From b451470330fc334519bc30a240737bdc22ba9c21 Mon Sep 17 00:00:00 2001 From: Benny Prijono Date: Sun, 18 Sep 2011 14:59:56 +0000 Subject: 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 --- pjnath/src/pjnath/ice_session.c | 35 +++++++++++++++++++++++++++++++++-- pjnath/src/pjnath/ice_strans.c | 34 +++++++++++++++++++++++++++------- pjnath/src/pjnath/stun_session.c | 8 ++++++++ pjnath/src/pjnath/stun_transaction.c | 5 ++++- 4 files changed, 72 insertions(+), 10 deletions(-) (limited to 'pjnath') 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; } -- cgit v1.2.3