sca: added some additional debug statements

- Needed some additional debug statements to figure out the issues with
the SCA module.

modules/sca/sca_call_info.c

@@ -530,6 +530,11 @@ int sca_call_info_seize_held_call(sip_msg_t *msg, sca_call_info *call_info,
 	int slot_idx = -1;
 	int rc = -1;
 
+	LM_DBG( "From-AOR:%.*s To-AOR:%.*s From-URI:<%.*s> To-URI:<%.*s> "
+			"Contact: <%.*s> Call-Info: appearance-index=%d\n",
+			STR_FMT(from_aor), STR_FMT(to_aor),STR_FMT(&from->uri),
+			STR_FMT(&to->uri), STR_FMT(contact_uri), call_info->index);
+
 	slot_idx = sca_hash_table_index_for_key(sca->appearances, from_aor);
 	sca_hash_table_lock_index(sca->appearances, slot_idx);
 
@@ -803,6 +808,10 @@ static int sca_call_info_is_line_seize_reinvite(sip_msg_t *msg,
 	str ruri_aor;
 	int state;
 
+	LM_DBG("For From-AOR %.*s To-AOR: %.*s: From: <%.*s> To: <%.*s> "
+			"Call-Info: appearance-index=%d\n",
+			STR_FMT(from_aor), STR_FMT(to_aor), STR_FMT(&from->uri),
+			STR_FMT(&to->uri), call_info->index);
 
 	// a handset in an SCA group is attempting to seize a held line if:
 	//		the RURI, From URI and To URI are identical;
@@ -834,6 +843,8 @@ static int sca_call_info_is_line_seize_reinvite(sip_msg_t *msg,
 				STR_FMT(to_aor), STR_FMT(from_aor), call_info->index);
 		return (0);
 	}
+	LM_DBG("reINVITE to %.*s from %.*s appearance-index %d (seizing held line)\n",
+			STR_FMT(to_aor), STR_FMT(from_aor), call_info->index);
 
 	return (1);
 }
@@ -934,6 +945,11 @@ int sca_call_info_invite_request_handler(sip_msg_t *msg,
 	int state = SCA_APPEARANCE_STATE_UNKNOWN;
 	int rc = -1;
 
+	LM_DBG("For From-AOR %.*s To-AOR: %.*s: From: <%.*s> To: <%.*s> "
+			"Contact: <%.*s> Call-Info: appearance-index=%d\n",
+			STR_FMT(from_aor), STR_FMT(to_aor),STR_FMT(&from->uri), STR_FMT(&to->uri),
+			STR_FMT(contact_uri), call_info->index);
+
 	// if we get here, one of the legs is an SCA endpoint. we want to know
 	// when the e2e ACK comes in so we can notify other members of the group.
 	if (sca->tm_api->register_tmcb(msg, NULL, TMCB_E2EACK_IN,
@@ -1016,6 +1032,11 @@ int sca_call_info_invite_reply_18x_handler(sip_msg_t *msg,
 	int rc = -1;
 	int notify = 0;
 
+	LM_DBG("For From-AOR %.*s To-AOR: %.*s: From: <%.*s> To: <%.*s> "
+			"Contact: <%.*s> Call-Info: appearance-index=%d",
+			STR_FMT(from_aor), STR_FMT(to_aor),STR_FMT(&from->uri), STR_FMT(&to->uri),
+			STR_FMT(contact_uri), call_info->index);
+
 	switch (msg->REPLY_STATUS) {
 	case 180:
 	case 183:
@@ -1169,6 +1190,11 @@ static int sca_call_info_invite_reply_200_handler(sip_msg_t *msg,
 	int slot_idx = -1;
 	int rc = -1;
 
+	LM_DBG("For From-AOR %.*s To-AOR: %.*s: From: <%.*s> To: <%.*s> "
+			"Contact: <%.*s> Call-Info: appearance-index=%d\n",
+			STR_FMT(from_aor), STR_FMT(to_aor),STR_FMT(&from->uri), STR_FMT(&to->uri),
+			STR_FMT(contact_uri), call_info->index);
+
 	if (SCA_CALL_INFO_IS_SHARED_CALLEE(call_info)) {
 		rc = sca_call_info_uri_update(to_aor, call_info, from, to, contact_uri,
 				&msg->callid->body);
@@ -1940,6 +1966,11 @@ int sca_call_info_update(sip_msg_t *msg, char *p1, char *p2)
 		goto done;
 	}
 
+	LM_DBG( "Calling Dispatch Id: %d handler with From-AOR: %.*s To-AOR: %.*s "
+			"From-URI: <%.*s> To-URI: <%.*s> Contact-URI: <%.*s>\n",
+			i, STR_FMT(&from_aor), STR_FMT(&to_aor),STR_FMT(&from->uri),
+			STR_FMT(&to->uri), STR_FMT(&contact_uri));
+
 	rc = call_info_dispatch[i].handler(msg, &call_info, from, to, &from_aor,
 			&to_aor, &contact_uri);
 	if (rc < 0) {

modules/sca/sca_dialog.c

@@ -32,6 +32,9 @@ int sca_dialog_build_from_tags(sca_dialog *dialog, int maxlen, str *call_id,
 	assert(call_id != NULL);
 	assert(from_tag != NULL);
 
+	LM_DBG( "From-Tag: %.*s To-Tag: %.*s CallId: %.*s\n",
+			STR_FMT(from_tag), STR_FMT(to_tag), STR_FMT(call_id));
+
 	len = call_id->len + from_tag->len;
 	if (!SCA_STR_EMPTY(to_tag)) {
 		len += to_tag->len;
@@ -74,6 +77,8 @@ int sca_dialog_create_replaces_header(sca_dialog *dlg, str *replaces_hdr)
 
 	assert(replaces_hdr != NULL);
 
+	LM_DBG( "Called\n" );
+
 	if (SCA_STR_EMPTY(&dlg->call_id) || SCA_STR_EMPTY(&dlg->from_tag) ||
 	SCA_STR_EMPTY(&dlg->to_tag)) {
 		LM_ERR("sca_dialog_create_replaces_header: dialog %.*s is not a "

modules/sca/sca_notify.c

@@ -22,6 +22,7 @@
 #include <assert.h>
 
 #include "sca.h"
+#include "sca_appearance.h"
 #include "sca_call_info.h"
 #include "sca_event.h"
 #include "sca_notify.h"
@@ -261,8 +262,14 @@ static int sca_notify_subscriber_internal(sca_mod *scam, sca_subscription *sub,
 {
 	uac_req_t request;
 	dlg_t *dlg = NULL;
+	str state_str = STR_NULL;
 	int rc = -1;
 
+	sca_appearance_state_to_str(sub->state, &state_str);
+	LM_DBG("SCA: NOTIFYing subscriber '%.*s' of event '%s' with a state of '%.*s' to index '%d'\n",
+			STR_FMT(&sub->subscriber), sca_event_name_from_type(sub->event),
+			STR_FMT(&state_str), sub->index);
+
 	dlg = sca_notify_dlg_for_subscription(sub);
 	if (dlg == NULL) {
 		LM_ERR("Failed to create dlg_t for %s NOTIFY to %.*s\n",
@@ -298,8 +305,9 @@ int sca_notify_subscriber(sca_mod *scam, sca_subscription *sub, int app_idx)
 	str headers = STR_NULL;
 	char hdrbuf[SCA_HEADERS_MAX_LEN];
 
-	headers.s = hdrbuf;
+	LM_DBG("NOTIFYing subscriber because of a SUBSCRIPTION request\n");
 
+	headers.s = hdrbuf;
 	if (sca_notify_build_headers_from_info(&headers, sizeof(hdrbuf), scam, sub,
 			app_idx) < 0) {
 		LM_ERR("Failed to build NOTIFY headers\n");
@@ -328,8 +336,10 @@ int sca_notify_call_info_subscribers(sca_mod *scam, str *subscription_aor)
 	assert(scam->subscriptions != NULL);
 	assert(!SCA_STR_EMPTY(subscription_aor));
 
-	event_name = sca_event_name_from_type(SCA_EVENT_TYPE_CALL_INFO);
+	LM_DBG("Notifying ALL subscribers of AOR %.*s due to a SUBSCRIBTION request\n",
+			STR_FMT(subscription_aor));
 
+	event_name = sca_event_name_from_type(SCA_EVENT_TYPE_CALL_INFO);
 	if (subscription_aor->len + strlen(event_name) >= sizeof(keybuf)) {
 		LM_ERR("Hash key %.*s + %s is too long\n",
 				STR_FMT(subscription_aor), event_name);