Modified the libraries to use the new log indentation feature re #1372

git-svn-id: http://svn.pjsip.org/repos/pjproject/trunk@3753 74dad513-b988-da41-8d7b-12977e46ad98

4 files changed, 72 insertions, 10 deletions

diff --git a/pjnath/src/pjnath/ice_session.c b/pjnath/src/pjnath/ice_session.c
index d6fae822..c77f7928 100644
--- a/pjnath/src/pjnath/ice_session.c
+++ b/pjnath/src/pjnath/ice_session.c
@@ -1748,6 +1748,7 @@ static pj_status_t perform_check(pj_ice_sess *ice,
     LOG5((ice->obj_name, 
 	 "Sending connectivity check for check %s", 
 	 dump_check(ice->tmp.txt, sizeof(ice->tmp.txt), clist, check)));
+    pj_log_push_indent();
 
     /* Create request */
     status = pj_stun_session_create_req(comp->stun_sess, 
@@ -1755,6 +1756,7 @@ static pj_status_t perform_check(pj_ice_sess *ice,
 					NULL, &check->tdata);
     if (status != PJ_SUCCESS) {
 	pjnath_perror(ice->obj_name, "Error creating STUN request", status);
+	pj_log_pop_indent();
 	return status;
     }
 
@@ -1811,11 +1813,13 @@ static pj_status_t perform_check(pj_ice_sess *ice,
     if (status != PJ_SUCCESS) {
 	check->tdata = NULL;
 	pjnath_perror(ice->obj_name, "Error sending STUN request", status);
+	pj_log_pop_indent();
 	return status;
     }
 
     check_set_state(ice, check, PJ_ICE_SESS_CHECK_STATE_IN_PROGRESS, 
 	            PJ_SUCCESS);
+    pj_log_pop_indent();
     return PJ_SUCCESS;
 }
 
@@ -1845,6 +1849,7 @@ static pj_status_t start_periodic_check(pj_timer_heap_t *th,
     clist_set_state(ice, clist, PJ_ICE_SESS_CHECKLIST_ST_RUNNING);
 
     LOG5((ice->obj_name, "Starting checklist periodic check"));
+    pj_log_push_indent();
 
     /* Send STUN Binding request for check with highest priority on
      * Waiting state.
@@ -1856,6 +1861,7 @@ static pj_status_t start_periodic_check(pj_timer_heap_t *th,
 	    status = perform_check(ice, clist, i, ice->is_nominating);
 	    if (status != PJ_SUCCESS) {
 		pj_mutex_unlock(ice->mutex);
+		pj_log_pop_indent();
 		return status;
 	    }
 
@@ -1875,6 +1881,7 @@ static pj_status_t start_periodic_check(pj_timer_heap_t *th,
 		status = perform_check(ice, clist, i, ice->is_nominating);
 		if (status != PJ_SUCCESS) {
 		    pj_mutex_unlock(ice->mutex);
+		    pj_log_pop_indent();
 		    return status;
 		}
 
@@ -1896,6 +1903,7 @@ static pj_status_t start_periodic_check(pj_timer_heap_t *th,
     }
 
     pj_mutex_unlock(ice->mutex);
+    pj_log_pop_indent();
     return PJ_SUCCESS;
 }
 
@@ -1908,6 +1916,7 @@ static void start_nominated_check(pj_ice_sess *ice)
     pj_status_t status;
 
     LOG4((ice->obj_name, "Starting nominated check.."));
+    pj_log_push_indent();
 
     pj_assert(ice->is_nominating == PJ_FALSE);
 
@@ -1958,6 +1967,7 @@ static void start_nominated_check(pj_ice_sess *ice)
     }
 
     ice->is_nominating = PJ_TRUE;
+    pj_log_pop_indent();
 }
 
 /* Timer callback to perform periodic check */
@@ -2005,6 +2015,7 @@ PJ_DEF(pj_status_t) pj_ice_sess_start_check(pj_ice_sess *ice)
     pj_mutex_lock(ice->mutex);
 
     LOG4((ice->obj_name, "Starting ICE check.."));
+    pj_log_push_indent();
 
     /* If we are using aggressive nomination, set the is_nominating state */
     if (ice->opt.aggressive)
@@ -2032,6 +2043,7 @@ PJ_DEF(pj_status_t) pj_ice_sess_start_check(pj_ice_sess *ice)
     if (i == clist->count) {
 	pj_assert(!"Unable to find checklist for component 1");
 	pj_mutex_unlock(ice->mutex);
+	pj_log_pop_indent();
 	return PJNATH_EICEINCOMPID;
     }
 
@@ -2072,8 +2084,10 @@ PJ_DEF(pj_status_t) pj_ice_sess_start_check(pj_ice_sess *ice)
 	LOG4((ice->obj_name, 
 	      "Performing delayed triggerred check for component %d",
 	      rcheck->comp_id));
+	pj_log_push_indent();
 	handle_incoming_check(ice, rcheck);
 	rcheck = rcheck->next;
+	pj_log_pop_indent();
     }
     pj_list_init(&ice->early_check);
 
@@ -2091,6 +2105,7 @@ PJ_DEF(pj_status_t) pj_ice_sess_start_check(pj_ice_sess *ice)
     }
 
     pj_mutex_unlock(ice->mutex);
+    pj_log_pop_indent();
     return status;
 }
 
@@ -2193,9 +2208,11 @@ static void on_stun_request_complete(pj_stun_session *stun_sess,
 
 	    /* Resend request */
 	    LOG4((ice->obj_name, "Resending check because of role conflict"));
+	    pj_log_push_indent();
 	    check_set_state(ice, check, PJ_ICE_SESS_CHECK_STATE_WAITING, 0);
 	    perform_check(ice, clist, msg_data->data.req.ckid, 
 			  check->nominated || ice->is_nominating);
+	    pj_log_pop_indent();
 	    pj_mutex_unlock(ice->mutex);
 	    return;
 	}
@@ -2207,9 +2224,10 @@ static void on_stun_request_complete(pj_stun_session *stun_sess,
 			&ice->clist, check),
 	     (check->nominated ? " (nominated)" : " (not nominated)"),
 	     errmsg));
-
+	pj_log_push_indent();
 	check_set_state(ice, check, PJ_ICE_SESS_CHECK_STATE_FAILED, status);
 	on_check_complete(ice, check);
+	pj_log_pop_indent();
 	pj_mutex_unlock(ice->mutex);
 	return;
     }
@@ -2230,8 +2248,10 @@ static void on_stun_request_complete(pj_stun_session *stun_sess,
 	     dump_check(ice->tmp.txt, sizeof(ice->tmp.txt), 
 			&ice->clist, check),
 	     (check->nominated ? " (nominated)" : " (not nominated)")));
+	pj_log_push_indent();
 	check_set_state(ice, check, PJ_ICE_SESS_CHECK_STATE_FAILED, status);
 	on_check_complete(ice, check);
+	pj_log_pop_indent();
 	pj_mutex_unlock(ice->mutex);
 	return;
     }
@@ -2702,14 +2722,18 @@ static void handle_incoming_check(pj_ice_sess *ice,
 	    pj_bool_t nominate = (c->nominated || ice->is_nominating);
 
 	    LOG5((ice->obj_name, "Performing triggered check for check %d",i));
+	    pj_log_push_indent();
 	    perform_check(ice, &ice->clist, i, nominate);
+	    pj_log_pop_indent();
 
 	} else if (c->state == PJ_ICE_SESS_CHECK_STATE_IN_PROGRESS) {
 	    /* Should retransmit immediately
 	     */
 	    LOG5((ice->obj_name, "Triggered check for check %d not performed "
 		  "because it's in progress. Retransmitting", i));
+	    pj_log_push_indent();
 	    pj_stun_session_retransmit_req(comp->stun_sess, c->tdata);
+	    pj_log_pop_indent();
 
 	} else if (c->state == PJ_ICE_SESS_CHECK_STATE_SUCCEEDED) {
 	    /* Check complete for this component.
@@ -2743,8 +2767,9 @@ static void handle_incoming_check(pj_ice_sess *ice,
 
 	    LOG5((ice->obj_name, "Triggered check for check %d not performed "
 				"because it's completed", i));
-
+	    pj_log_push_indent();
 	    complete = on_check_complete(ice, c);
+	    pj_log_pop_indent();
 	    if (complete) {
 		return;
 	    }
@@ -2773,7 +2798,9 @@ static void handle_incoming_check(pj_ice_sess *ice,
 
 	LOG4((ice->obj_name, "New triggered check added: %d", 
 	     ice->clist.count));
+	pj_log_push_indent();
 	perform_check(ice, &ice->clist, ice->clist.count++, nominate);
+	pj_log_pop_indent();
 
     } else {
 	LOG4((ice->obj_name, "Error: unable to perform triggered check: "
@@ -2802,6 +2829,8 @@ static pj_status_t on_stun_rx_indication(pj_stun_session *sess,
 
     sd = (struct stun_data*) pj_stun_session_get_user_data(sess);
 
+    pj_log_push_indent();
+
     if (msg->hdr.type == PJ_STUN_BINDING_INDICATION) {
 	LOG5((sd->ice->obj_name, "Received Binding Indication keep-alive "
 	      "for component %d", sd->comp_id));
@@ -2811,6 +2840,8 @@ static pj_status_t on_stun_rx_indication(pj_stun_session *sess,
 	      sd->comp_id));
     }
 
+    pj_log_pop_indent();
+
     return PJ_SUCCESS;
 }
 
diff --git a/pjnath/src/pjnath/ice_strans.c b/pjnath/src/pjnath/ice_strans.c
index eb3d00ba..906f2683 100644
--- a/pjnath/src/pjnath/ice_strans.c
+++ b/pjnath/src/pjnath/ice_strans.c
@@ -405,6 +405,8 @@ static pj_status_t create_comp(pj_ice_strans *ice_st, unsigned comp_id)
 		      "Comp %d: srflx candidate starts Binding discovery",
 		      comp_id));
 
+	    pj_log_push_indent();
+
 	    /* Start Binding resolution */
 	    status = pj_stun_sock_start(comp->stun_sock, 
 					&ice_st->cfg.stun.server,
@@ -412,6 +414,7 @@ static pj_status_t create_comp(pj_ice_strans *ice_st, unsigned comp_id)
 					ice_st->cfg.resolver);
 	    if (status != PJ_SUCCESS) {
 		///sess_dec_ref(ice_st);
+		pj_log_pop_indent();
 		return status;
 	    }
 
@@ -419,6 +422,7 @@ static pj_status_t create_comp(pj_ice_strans *ice_st, unsigned comp_id)
 	    status = pj_stun_sock_get_info(comp->stun_sock, &stun_sock_info);
 	    if (status != PJ_SUCCESS) {
 		///sess_dec_ref(ice_st);
+		pj_log_pop_indent();
 		return status;
 	    }
 
@@ -437,6 +441,7 @@ static pj_status_t create_comp(pj_ice_strans *ice_st, unsigned comp_id)
 	    /* Set default candidate to srflx */
 	    comp->default_cand = cand - comp->cand_list;
 
+	    pj_log_pop_indent();
 	}
 
 	/* Add local addresses to host candidates, unless max_host_cands
@@ -536,6 +541,7 @@ PJ_DEF(pj_status_t) pj_ice_strans_create( const char *name,
     PJ_LOG(4,(ice_st->obj_name, 
 	      "Creating ICE stream transport with %d component(s)",
 	      comp_cnt));
+    pj_log_push_indent();
 
     pj_ice_strans_cfg_copy(pool, &ice_st->cfg, cfg);
     pj_memcpy(&ice_st->cb, cb, sizeof(*cb));
@@ -550,6 +556,7 @@ PJ_DEF(pj_status_t) pj_ice_strans_create( const char *name,
 					    &ice_st->init_lock);
     if (status != PJ_SUCCESS) {
 	destroy_ice_st(ice_st);
+	pj_log_pop_indent();
 	return status;
     }
 
@@ -570,6 +577,7 @@ PJ_DEF(pj_status_t) pj_ice_strans_create( const char *name,
 	if (status != PJ_SUCCESS) {
 	    pj_lock_release(ice_st->init_lock);
 	    destroy_ice_st(ice_st);
+	    pj_log_pop_indent();
 	    return status;
 	}
     }
@@ -583,6 +591,8 @@ PJ_DEF(pj_status_t) pj_ice_strans_create( const char *name,
     PJ_LOG(4,(ice_st->obj_name, "ICE stream transport created"));
 
     *p_ice_st = ice_st;
+    pj_log_pop_indent();
+
     return PJ_SUCCESS;
 }
 
@@ -591,6 +601,9 @@ static void destroy_ice_st(pj_ice_strans *ice_st)
 {
     unsigned i;
 
+    PJ_LOG(5,(ice_st->obj_name, "ICE stream transport destroying.."));
+    pj_log_push_indent();
+
     /* Destroy ICE if we have ICE */
     if (ice_st->ice) {
 	pj_ice_sess_destroy(ice_st->ice);
@@ -629,8 +642,11 @@ static void destroy_ice_st(pj_ice_strans *ice_st)
 	ice_st->busy_cnt = NULL;
     }
 
+    PJ_LOG(4,(ice_st->obj_name, "ICE stream transport destroyed"));
+
     /* Done */
     pj_pool_release(ice_st->pool);
+    pj_log_pop_indent();
 }
 
 /* Get ICE session state. */
@@ -664,14 +680,19 @@ static void sess_fail(pj_ice_strans *ice_st, pj_ice_strans_op op,
 
     pj_strerror(status, errmsg, sizeof(errmsg));
     PJ_LOG(4,(ice_st->obj_name, "%s: %s", title, errmsg));
+    pj_log_push_indent();
 
-    if (op==PJ_ICE_STRANS_OP_INIT && ice_st->cb_called)
+    if (op==PJ_ICE_STRANS_OP_INIT && ice_st->cb_called) {
+	pj_log_pop_indent();
 	return;
+    }
 
     ice_st->cb_called = PJ_TRUE;
 
     if (ice_st->cb.on_ice_complete)
 	(*ice_st->cb.on_ice_complete)(ice_st, op, status);
+
+    pj_log_pop_indent();
 }
 
 /* Update initialization status */
@@ -709,8 +730,6 @@ static void sess_init_update(pj_ice_strans *ice_st)
  */
 PJ_DEF(pj_status_t) pj_ice_strans_destroy(pj_ice_strans *ice_st)
 {
-    char obj_name[PJ_MAX_OBJ_NAME];
-
     PJ_ASSERT_RETURN(ice_st, PJ_EINVAL);
 
     ice_st->destroy_req = PJ_TRUE;
@@ -720,10 +739,7 @@ PJ_DEF(pj_status_t) pj_ice_strans_destroy(pj_ice_strans *ice_st)
 	return PJ_EPENDING;
     }
     
-    pj_memcpy(obj_name, ice_st->obj_name, PJ_MAX_OBJ_NAME);
     destroy_ice_st(ice_st);
-
-    PJ_LOG(4,(obj_name, "ICE stream transport destroyed"));
     return PJ_SUCCESS;
 }
 
@@ -1294,9 +1310,10 @@ static void on_ice_complete(pj_ice_sess *ice, pj_status_t status)
 	ice_st->state = (status==PJ_SUCCESS) ? PJ_ICE_STRANS_STATE_RUNNING :
 					       PJ_ICE_STRANS_STATE_FAILED;
 
+	pj_log_push_indent();
 	(*ice_st->cb.on_ice_complete)(ice_st, PJ_ICE_STRANS_OP_NEGOTIATION, 
 				      status);
-
+	pj_log_pop_indent();
 	
     }
 
@@ -1615,6 +1632,7 @@ static void turn_on_state(pj_turn_sock *turn_sock, pj_turn_state_t old_state,
 
     PJ_LOG(5,(comp->ice_st->obj_name, "TURN client state changed %s --> %s",
 	      pj_turn_state_name(old_state), pj_turn_state_name(new_state)));
+    pj_log_push_indent();
 
     sess_add_ref(comp->ice_st);
 
@@ -1690,5 +1708,7 @@ static void turn_on_state(pj_turn_sock *turn_sock, pj_turn_state_t old_state,
     }
 
     sess_dec_ref(comp->ice_st);
+
+    pj_log_pop_indent();
 }
 
diff --git a/pjnath/src/pjnath/stun_session.c b/pjnath/src/pjnath/stun_session.c
index 0613bd2a..7d858463 100644
--- a/pjnath/src/pjnath/stun_session.c
+++ b/pjnath/src/pjnath/stun_session.c
@@ -864,6 +864,8 @@ PJ_DEF(pj_status_t) pj_stun_session_send_msg( pj_stun_session *sess,
 
     PJ_ASSERT_RETURN(sess && addr_len && server && tdata, PJ_EINVAL);
 
+    pj_log_push_indent();
+
     /* Allocate packet */
     tdata->max_len = PJ_STUN_MAX_PKT_LEN;
     tdata->pkt = pj_pool_alloc(tdata->pool, tdata->max_len);
@@ -972,6 +974,8 @@ PJ_DEF(pj_status_t) pj_stun_session_send_msg( pj_stun_session *sess,
 on_return:
     pj_lock_release(sess->lock);
 
+    pj_log_pop_indent();
+
     /* Check if application has called destroy() in the callback */
     if (pj_atomic_dec_and_get(sess->busy)==0 && sess->destroy_request) {
 	pj_stun_session_destroy(sess);
@@ -1353,6 +1357,8 @@ PJ_DEF(pj_status_t) pj_stun_session_on_rx_pkt(pj_stun_session *sess,
 
     PJ_ASSERT_RETURN(sess && packet && pkt_size, PJ_EINVAL);
 
+    pj_log_push_indent();
+
     /* Lock the session and prevent user from destroying us in the callback */
     pj_atomic_inc(sess->busy);
     pj_lock_acquire(sess->lock);
@@ -1410,6 +1416,8 @@ PJ_DEF(pj_status_t) pj_stun_session_on_rx_pkt(pj_stun_session *sess,
 on_return:
     pj_lock_release(sess->lock);
 
+    pj_log_pop_indent();
+
     /* If we've received destroy request while we're on the callback,
      * destroy the session now.
      */
diff --git a/pjnath/src/pjnath/stun_transaction.c b/pjnath/src/pjnath/stun_transaction.c
index 991f8487..ab16b32c 100644
--- a/pjnath/src/pjnath/stun_transaction.c
+++ b/pjnath/src/pjnath/stun_transaction.c
@@ -225,6 +225,7 @@ static pj_status_t tsx_transmit_msg(pj_stun_client_tsx *tsx)
 
     PJ_LOG(5,(tsx->obj_name, "STUN sending message (transmit count=%d)",
 	      tsx->transmit_count));
+    pj_log_push_indent();
 
     /* Send message */
     status = tsx->cb.on_send_msg(tsx, tsx->last_pkt, tsx->last_pkt_size);
@@ -238,9 +239,9 @@ static pj_status_t tsx_transmit_msg(pj_stun_client_tsx *tsx)
 	    tsx->retransmit_timer.id = 0;
 	}
 	stun_perror(tsx, "STUN error sending message", status);
-	return status;
     }
 
+    pj_log_pop_indent();
     return status;
 }
 
@@ -321,6 +322,7 @@ static void retransmit_timer_callback(pj_timer_heap_t *timer_heap,
 	/* Retransmission count exceeded. Transaction has failed */
 	tsx->retransmit_timer.id = 0;
 	PJ_LOG(4,(tsx->obj_name, "STUN timeout waiting for response"));
+	pj_log_push_indent();
 	if (!tsx->complete) {
 	    tsx->complete = PJ_TRUE;
 	    if (tsx->cb.on_complete) {
@@ -328,6 +330,7 @@ static void retransmit_timer_callback(pj_timer_heap_t *timer_heap,
 	    }
 	}
 	/* We might have been destroyed, don't try to access the object */
+	pj_log_pop_indent();
 	return;
     }