Added more logging, and fixed bug when ACK is responded!

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

8 files changed, 148 insertions, 26 deletions

diff --git a/pjsip/include/pjsip-ua/sip_inv.h b/pjsip/include/pjsip-ua/sip_inv.h
index a8276bb5..013687a7 100644
--- a/pjsip/include/pjsip-ua/sip_inv.h
+++ b/pjsip/include/pjsip-ua/sip_inv.h
@@ -166,14 +166,15 @@ enum pjsip_inv_option
  */
 struct pjsip_inv_session
 {
-    pj_pool_t		*pool;
-    pjsip_inv_state	 state;
-    pjsip_dialog	*dlg;
-    pjsip_role_e	 role;
-    unsigned		 options;
-    pjmedia_sdp_neg	*neg;
-    pjsip_transaction	*invite_tsx;
-    void		*mod_data[PJSIP_MAX_MODULE];
+    char		 obj_name[PJ_MAX_OBJ_NAME]; /**< Log identification. */
+    pj_pool_t		*pool;			    /**< Dialog's pool.	    */
+    pjsip_inv_state	 state;			    /**< Invite sess state. */
+    pjsip_dialog	*dlg;			    /**< Underlying dialog. */
+    pjsip_role_e	 role;			    /**< Invite role.	    */
+    unsigned		 options;		    /**< Options in use.    */
+    pjmedia_sdp_neg	*neg;			    /**< Negotiator.	    */
+    pjsip_transaction	*invite_tsx;		    /**< 1st invite tsx.    */
+    void		*mod_data[PJSIP_MAX_MODULE];/**< Modules data.	    */
 };
 
 
diff --git a/pjsip/include/pjsip/sip_dialog.h b/pjsip/include/pjsip/sip_dialog.h
index ede79b26..38f01c79 100644
--- a/pjsip/include/pjsip/sip_dialog.h
+++ b/pjsip/include/pjsip/sip_dialog.h
@@ -183,7 +183,8 @@ PJ_DECL(pj_status_t) pjsip_dlg_set_route_set( pjsip_dialog *dlg,
  * Increment the number of sessions in the dialog. Note that initially 
  * (after created) the dialog has the session counter set to zero.
  */
-PJ_DECL(pj_status_t) pjsip_dlg_inc_session( pjsip_dialog *dlg );
+PJ_DECL(pj_status_t) pjsip_dlg_inc_session( pjsip_dialog *dlg,
+					    pjsip_module *mod);
 
 
 /**
@@ -192,7 +193,8 @@ PJ_DECL(pj_status_t) pjsip_dlg_inc_session( pjsip_dialog *dlg );
  * destroyed. Note that this function may destroy the dialog immediately 
  * if there is no pending transaction when this function is called.
  */
-PJ_DECL(pj_status_t) pjsip_dlg_dec_session( pjsip_dialog *dlg );
+PJ_DECL(pj_status_t) pjsip_dlg_dec_session( pjsip_dialog *dlg,
+					    pjsip_module *mod);
 
 /**
  * Add a module as dialog usage, and optionally set the module specific data.
diff --git a/pjsip/src/pjsip-ua/sip_inv.c b/pjsip/src/pjsip-ua/sip_inv.c
index fede7da6..652f81c4 100644
--- a/pjsip/src/pjsip-ua/sip_inv.c
+++ b/pjsip/src/pjsip-ua/sip_inv.c
@@ -130,7 +130,7 @@ void inv_set_state(pjsip_inv_session *inv, pjsip_inv_state state,
 	(*mod_inv.cb.on_state_changed)(inv, e);
 
     if (inv->state == PJSIP_INV_STATE_DISCONNECTED)
-	pjsip_dlg_dec_session(inv->dlg);
+	pjsip_dlg_dec_session(inv->dlg, &mod_inv.mod);
 }
 
 
@@ -142,6 +142,9 @@ static pj_status_t inv_send_ack(pjsip_inv_session *inv, pjsip_rx_data *rdata)
     pjsip_tx_data *tdata;
     pj_status_t status;
 
+    PJ_LOG(5,(inv->obj_name, "Received %s, sending ACK",
+	      pjsip_rx_data_get_info(rdata)));
+
     status = pjsip_dlg_create_request(inv->dlg, &pjsip_ack_method, 
 				      rdata->msg_info.cseq->cseq, &tdata);
     if (status != PJ_SUCCESS) {
@@ -370,6 +373,9 @@ PJ_DEF(pj_status_t) pjsip_inv_create_uac( pjsip_dialog *dlg,
     inv->dlg = dlg;
     inv->options = options;
 
+    /* Object name will use the same dialog pointer. */
+    pj_snprintf(inv->obj_name, PJ_MAX_OBJ_NAME, "inv%p", dlg);
+
     /* Create negotiator if local_sdp is specified. */
     if (local_sdp) {
 	status = pjmedia_sdp_neg_create_w_local_offer(dlg->pool, local_sdp,
@@ -384,10 +390,14 @@ PJ_DEF(pj_status_t) pjsip_inv_create_uac( pjsip_dialog *dlg,
 	return status;
 
     /* Increment dialog session */
-    pjsip_dlg_inc_session(dlg);
+    pjsip_dlg_inc_session(dlg, &mod_inv.mod);
 
     /* Done */
     *p_inv = inv;
+
+    PJ_LOG(5,(inv->obj_name, "UAC invite session created for dialog %s",
+	      dlg->obj_name));
+
     return PJ_SUCCESS;
 }
 
@@ -759,6 +769,9 @@ PJ_DEF(pj_status_t) pjsip_inv_create_uas( pjsip_dialog *dlg,
     inv->dlg = dlg;
     inv->options = options;
 
+    /* Object name will use the same dialog pointer. */
+    pj_snprintf(inv->obj_name, PJ_MAX_OBJ_NAME, "inv%p", dlg);
+
     /* Parse SDP in message body, if present. */
     if (msg->body) {
 	pjsip_msg_body *body = msg->body;
@@ -794,7 +807,7 @@ PJ_DEF(pj_status_t) pjsip_inv_create_uas( pjsip_dialog *dlg,
 	return status;
 
     /* Increment session in the dialog. */
-    pjsip_dlg_inc_session(dlg);
+    pjsip_dlg_inc_session(dlg, &mod_inv.mod);
 
     /* Save the invite transaction. */
     inv->invite_tsx = pjsip_rdata_get_tsx(rdata);
@@ -807,6 +820,10 @@ PJ_DEF(pj_status_t) pjsip_inv_create_uas( pjsip_dialog *dlg,
 
     /* Done */
     *p_inv = inv;
+
+    PJ_LOG(5,(inv->obj_name, "UAS invite session created for dialog %s",
+	      dlg->obj_name));
+
     return PJ_SUCCESS;
 }
 
@@ -912,6 +929,8 @@ static pj_status_t inv_negotiate_sdp( pjsip_inv_session *inv )
 
     status = pjmedia_sdp_neg_negotiate(inv->pool, inv->neg, 0);
 
+    PJ_LOG(5,(inv->obj_name, "SDP negotiation done, status=%d", status));
+
     if (mod_inv.cb.on_media_update)
 	(*mod_inv.cb.on_media_update)(inv, status);
 
@@ -981,6 +1000,9 @@ static void inv_check_sdp_in_incoming_msg( pjsip_inv_session *inv,
 
 	/* This is an offer. */
 
+	PJ_LOG(5,(inv->obj_name, "Got SDP offer in %s", 
+		  pjsip_rx_data_get_info(rdata)));
+
 	if (inv->neg == NULL) {
 	    status=pjmedia_sdp_neg_create_w_remote_offer(inv->pool, NULL, 
 							 sdp, &inv->neg);
@@ -1009,6 +1031,9 @@ static void inv_check_sdp_in_incoming_msg( pjsip_inv_session *inv,
 	 * Process and negotiate remote answer.
 	 */
 
+	PJ_LOG(5,(inv->obj_name, "Got SDP answer in %s", 
+		  pjsip_rx_data_get_info(rdata)));
+
 	status = pjmedia_sdp_neg_set_remote_answer(inv->pool, inv->neg, sdp);
 
 	if (status != PJ_SUCCESS) {
@@ -1260,6 +1285,9 @@ PJ_DEF(pj_status_t) pjsip_inv_send_msg( pjsip_inv_session *inv,
     /* Verify arguments. */
     PJ_ASSERT_RETURN(inv && tdata, PJ_EINVAL);
 
+    PJ_LOG(5,(inv->obj_name, "Sending %s", 
+	      pjsip_tx_data_get_info(tdata)));
+
     if (tdata->msg->type == PJSIP_REQUEST_MSG) {
 	pjsip_transaction *tsx;
 	struct tsx_inv_data *tsx_inv_data;
@@ -1581,6 +1609,23 @@ static void inv_on_state_calling( pjsip_inv_session *inv, pjsip_event *e)
 	default:
 	    break;
 	}
+
+    } else if (inv->role == PJSIP_ROLE_UAC &&
+	       tsx->role == PJSIP_ROLE_UAC &&
+	       tsx->method.id == PJSIP_CANCEL_METHOD)
+    {
+	/*
+	 * Handle case when outgoing CANCEL is answered with 481 (Call/
+	 * Transaction Does Not Exist), 408, or when it's timed out. In these
+	 * cases, disconnect session (i.e. dialog usage only).
+	 */
+	if (tsx->status_code == PJSIP_SC_CALL_TSX_DOES_NOT_EXIST ||
+	    tsx->status_code == PJSIP_SC_REQUEST_TIMEOUT ||
+	    tsx->status_code == PJSIP_SC_TSX_TIMEOUT ||
+	    PJSIP_SC_TSX_TRANSPORT_ERROR)
+	{
+	    inv_set_state(inv, PJSIP_INV_STATE_DISCONNECTED, e);
+	}
     }
 }
 
@@ -1737,6 +1782,22 @@ static void inv_on_state_early( pjsip_inv_session *inv, pjsip_event *e)
 
 	inv_respond_incoming_cancel(inv, tsx, e->body.tsx_state.src.rdata);
 
+    } else if (inv->role == PJSIP_ROLE_UAC &&
+	       tsx->role == PJSIP_ROLE_UAC &&
+	       tsx->method.id == PJSIP_CANCEL_METHOD)
+    {
+	/*
+	 * Handle case when outgoing CANCEL is answered with 481 (Call/
+	 * Transaction Does Not Exist), 408, or when it's timed out. In these
+	 * cases, disconnect session (i.e. dialog usage only).
+	 */
+	if (tsx->status_code == PJSIP_SC_CALL_TSX_DOES_NOT_EXIST ||
+	    tsx->status_code == PJSIP_SC_REQUEST_TIMEOUT ||
+	    tsx->status_code == PJSIP_SC_TSX_TIMEOUT ||
+	    PJSIP_SC_TSX_TRANSPORT_ERROR)
+	{
+	    inv_set_state(inv, PJSIP_INV_STATE_DISCONNECTED, e);
+	}
     }
 }
 
diff --git a/pjsip/src/pjsip/sip_dialog.c b/pjsip/src/pjsip/sip_dialog.c
index 9f0434a4..6afbb2ab 100644
--- a/pjsip/src/pjsip/sip_dialog.c
+++ b/pjsip/src/pjsip/sip_dialog.c
@@ -200,6 +200,9 @@ PJ_DEF(pj_status_t) pjsip_dlg_create_uac( pjsip_user_agent *ua,
     /* Done! */
     *p_dlg = dlg;
 
+
+    PJ_LOG(5,(dlg->obj_name, "UAC dialog created"));
+
     return PJ_SUCCESS;
 
 on_error:
@@ -380,6 +383,7 @@ PJ_DEF(pj_status_t) pjsip_dlg_create_uas(   pjsip_user_agent *ua,
 
     /* Done. */
     *p_dlg = dlg;
+    PJ_LOG(5,(dlg->obj_name, "UAS dialog created"));
     return PJ_SUCCESS;
 
 on_error:
@@ -495,6 +499,7 @@ PJ_DEF(pj_status_t) pjsip_dlg_fork( const pjsip_dialog *first_dlg,
     /* Done! */
     *new_dlg = dlg;
 
+    PJ_LOG(5,(dlg->obj_name, "Forked dialog created"));
     return PJ_SUCCESS;
 
 on_error:
@@ -576,26 +581,34 @@ PJ_DEF(pj_status_t) pjsip_dlg_set_route_set( pjsip_dialog *dlg,
 /*
  * Increment session counter.
  */
-PJ_DEF(pj_status_t) pjsip_dlg_inc_session( pjsip_dialog *dlg )
+PJ_DEF(pj_status_t) pjsip_dlg_inc_session( pjsip_dialog *dlg,
+					   pjsip_module *mod )
 {
-    PJ_ASSERT_RETURN(dlg, PJ_EINVAL);
+    PJ_ASSERT_RETURN(dlg && mod, PJ_EINVAL);
 
     pj_mutex_lock(dlg->mutex);
     ++dlg->sess_count;
     pj_mutex_unlock(dlg->mutex);
 
+    PJ_LOG(5,(dlg->obj_name, "Session count inc to %d by %.*s",
+	      dlg->sess_count, (int)mod->name.slen, mod->name.ptr));
+
     return PJ_SUCCESS;
 }
 
 /*
  * Decrement session counter.
  */
-PJ_DEF(pj_status_t) pjsip_dlg_dec_session( pjsip_dialog *dlg )
+PJ_DEF(pj_status_t) pjsip_dlg_dec_session( pjsip_dialog *dlg,
+					   pjsip_module *mod)
 {
     pj_status_t status;
 
     PJ_ASSERT_RETURN(dlg, PJ_EINVAL);
 
+    PJ_LOG(5,(dlg->obj_name, "Session count dec to %d by %.*s",
+	      dlg->sess_count-1, (int)mod->name.slen, mod->name.ptr));
+
     pj_mutex_lock(dlg->mutex);
 
     pj_assert(dlg->sess_count > 0);
@@ -626,6 +639,9 @@ PJ_DEF(pj_status_t) pjsip_dlg_add_usage( pjsip_dialog *dlg,
 		     PJ_EINVAL);
     PJ_ASSERT_RETURN(dlg->usage_cnt < PJSIP_MAX_MODULE, PJ_EBUG);
 
+    PJ_LOG(5,(dlg->obj_name, "Module %.*s added as dialog usage",
+	      (int)mod->name.slen, mod->name.ptr));
+
     pj_mutex_lock(dlg->mutex);
 
     /* Usages are sorted on priority, lowest number first.
@@ -794,6 +810,9 @@ PJ_DEF(pj_status_t) pjsip_dlg_send_request( pjsip_dialog *dlg,
     PJ_ASSERT_RETURN(tdata->msg->type == PJSIP_REQUEST_MSG,
 		     PJSIP_ENOTREQUESTMSG);
 
+    PJ_LOG(5,(dlg->obj_name, "Sending %s",
+	      pjsip_tx_data_get_info(tdata)));
+
     /* Update CSeq */
     pj_mutex_lock(dlg->mutex);
 
@@ -1023,6 +1042,9 @@ PJ_DEF(pj_status_t) pjsip_dlg_send_response( pjsip_dialog *dlg,
     /* The transaction must belong to this dialog.  */
     PJ_ASSERT_RETURN(tsx->mod_data[dlg->ua->id] == dlg, PJ_EINVALIDOP);
 
+    PJ_LOG(5,(dlg->obj_name, "Sending %s",
+	      pjsip_tx_data_get_info(tdata)));
+
     /* Check that transaction method and cseq match the response. 
      * This operation is sloooww (search CSeq header twice), that's why
      * we only do it in debug mode.
@@ -1078,6 +1100,9 @@ void pjsip_dlg_on_rx_request( pjsip_dialog *dlg, pjsip_rx_data *rdata )
     pjsip_transaction *tsx = NULL;
     unsigned i;
 
+    PJ_LOG(5,(dlg->obj_name, "Received %s",
+	      pjsip_rx_data_get_info(rdata)));
+
     /* Lock the dialog. */
     pj_mutex_lock(dlg->mutex);
 
@@ -1143,6 +1168,9 @@ void pjsip_dlg_on_rx_response( pjsip_dialog *dlg, pjsip_rx_data *rdata )
     unsigned i;
     int res_code;
 
+    PJ_LOG(5,(dlg->obj_name, "Received %s",
+	      pjsip_rx_data_get_info(rdata)));
+
     /* Lock the dialog. */
     pj_mutex_lock(dlg->mutex);
 
@@ -1249,6 +1277,9 @@ void pjsip_dlg_on_tsx_state( pjsip_dialog *dlg,
 {
     unsigned i;
 
+    PJ_LOG(5,(dlg->obj_name, "Transaction %s state changed to %s",
+	      tsx->obj_name, pjsip_tsx_state_str(tsx->state)));
+
     /* Lock the dialog. */
     pj_mutex_lock(dlg->mutex);
 
diff --git a/pjsip/src/pjsip/sip_transaction.c b/pjsip/src/pjsip/sip_transaction.c
index dcb09131..cc18eac9 100644
--- a/pjsip/src/pjsip/sip_transaction.c
+++ b/pjsip/src/pjsip/sip_transaction.c
@@ -881,7 +881,7 @@ static void tsx_destroy( pjsip_transaction *tsx )
     /* Refuse to destroy transaction if it has pending resolving. */
     if (tsx->transport_flag & TSX_HAS_PENDING_TRANSPORT) {
 	tsx->transport_flag |= TSX_HAS_PENDING_DESTROY;
-	PJ_LOG(5,(tsx->obj_name, "Will destroy later because transport is "
+	PJ_LOG(4,(tsx->obj_name, "Will destroy later because transport is "
 				 "in progress"));
 	return;
     }
@@ -914,7 +914,7 @@ static void tsx_timer_callback( pj_timer_heap_t *theap, pj_timer_entry *entry)
 
     PJ_UNUSED_ARG(theap);
 
-    PJ_LOG(6,(tsx->obj_name, "%s timer event", 
+    PJ_LOG(5,(tsx->obj_name, "%s timer event", 
 	     (entry->id==TSX_TIMER_RETRANSMISSION ? "Retransmit":"Timeout")));
 
 
@@ -1286,6 +1286,8 @@ PJ_DEF(pj_status_t) pjsip_tsx_terminate( pjsip_transaction *tsx, int code )
 {
     struct tsx_lock_data lck;
 
+    PJ_LOG(5,(tsx->obj_name, "Request to terminate transaction"));
+
     PJ_ASSERT_RETURN(tsx != NULL, PJ_EINVAL);
     PJ_ASSERT_RETURN(code >= 200, PJ_EINVAL);
 
diff --git a/pjsip/src/pjsip/sip_ua_layer.c b/pjsip/src/pjsip/sip_ua_layer.c
index c1fd6332..6886f70a 100644
--- a/pjsip/src/pjsip/sip_ua_layer.c
+++ b/pjsip/src/pjsip/sip_ua_layer.c
@@ -496,9 +496,15 @@ static pj_bool_t mod_ua_on_rx_request(pjsip_rx_data *rdata)
 	/* Unable to find dialog. */
 	pj_mutex_unlock(mod_ua.mutex);
 
-	/* Respond with 481 . */
-	pjsip_endpt_respond_stateless( mod_ua.endpt, rdata, 481, NULL, NULL,
-				       NULL );
+	if (rdata->msg_info.msg->line.req.method.id != PJSIP_ACK_METHOD) {
+	    PJ_LOG(5,(THIS_FILE, 
+		      "Unable to find dialogset for %s, answering with 481",
+		      pjsip_rx_data_get_info(rdata)));
+
+	    /* Respond with 481 . */
+	    pjsip_endpt_respond_stateless( mod_ua.endpt, rdata, 481, NULL, 
+					   NULL, NULL );
+	}
 	return PJ_TRUE;
     }
 
@@ -517,8 +523,14 @@ static pj_bool_t mod_ua_on_rx_request(pjsip_rx_data *rdata)
 
     /* Dialog MUST be found! */
     if (dlg == (pjsip_dialog*)&dlg_set->dlg_list) {
+
 	/* Not found. Mulfunction UAC? */
 	pj_mutex_unlock(mod_ua.mutex);
+
+	PJ_LOG(5,(THIS_FILE, 
+	          "Unable to find dialog for %s, answering with 481",
+		  pjsip_rx_data_get_info(rdata)));
+
 	pjsip_endpt_respond_stateless(mod_ua.endpt, rdata,
 				      PJSIP_SC_CALL_TSX_DOES_NOT_EXIST, 
 				      NULL, NULL, NULL);
@@ -661,6 +673,12 @@ static pj_bool_t mod_ua_on_rx_response(pjsip_rx_data *rdata)
 	if (dlg == (pjsip_dialog*)&dlg_set->dlg_list &&
 	    ((st_code/100==1 && st_code!=100) || st_code/100==2)) 
 	{
+
+	    PJ_LOG(5,(THIS_FILE, 
+		      "Received forked %s for existing dialog %s",
+		      pjsip_rx_data_get_info(rdata), 
+		      dlg_set->dlg_list.next->obj_name));
+
 	    /* Report to application about forked condition.
 	     * Application can either create a dialog or ignore the response.
 	     */
diff --git a/pjsip/src/pjsip/sip_util.c b/pjsip/src/pjsip/sip_util.c
index 696302f9..bb928b73 100644
--- a/pjsip/src/pjsip/sip_util.c
+++ b/pjsip/src/pjsip/sip_util.c
@@ -357,6 +357,10 @@ PJ_DEF(pj_status_t) pjsip_endpt_create_response( pjsip_endpoint *endpt,
     req_msg = rdata->msg_info.msg;
     pj_assert(req_msg->type == PJSIP_REQUEST_MSG);
 
+    /* Request MUST NOT be ACK request! */
+    PJ_ASSERT_RETURN(req_msg->line.req.method.id != PJSIP_ACK_METHOD,
+		     PJ_EINVALIDOP);
+
     /* Create a new transmit buffer. */
     status = pjsip_endpt_create_tdata( endpt, &tdata);
     if (status != PJ_SUCCESS)
diff --git a/pjsip/src/pjsua/pjsua_core.c b/pjsip/src/pjsua/pjsua_core.c
index fc110409..5e344301 100644
--- a/pjsip/src/pjsua/pjsua_core.c
+++ b/pjsip/src/pjsua/pjsua_core.c
@@ -486,7 +486,6 @@ pj_status_t pjsua_start(void)
 
     status = init_sockets();
     if (status != PJ_SUCCESS) {
-	pj_caching_pool_destroy(&pjsua.cp);
 	pjsua_perror("init_sockets() has returned error", status);
 	return status;
     }
@@ -620,7 +619,6 @@ pj_status_t pjsua_start(void)
 		pj_thread_join(pjsua.threads[i]);
 		pj_thread_destroy(pjsua.threads[i]);
 	    }
-	    pj_caching_pool_destroy(&pjsua.cp);
 	    return status;
 	}
     }
@@ -665,15 +663,20 @@ pj_status_t pjsua_destroy(void)
 
     pjsua.quit_flag = 1;
 
-    /* Destroy sound framework: */
+    /* Destroy sound framework: 
+     * (this should be done in pjmedia_shutdown())
+     */
     pj_snd_deinit();
 
     /* Wait worker threads to quit: */
 
     for (i=0; i<pjsua.thread_cnt; ++i) {
 	
-	pj_thread_join(pjsua.threads[i]);
-	pj_thread_destroy(pjsua.threads[i]);
+	if (pjsua.threads[i]) {
+	    pj_thread_join(pjsua.threads[i]);
+	    pj_thread_destroy(pjsua.threads[i]);
+	    pjsua.threads[i] = NULL;
+	}
     }
 
     /* Destroy endpoint. */