logger: Adds additional support for call id logging and chan_sip specific stuff

This patch improves the handling of call id logging significantly with regard
to transfers and adding APIs to better handle specific aspects of logging.
Also, changes have been made to chan_sip in order to better handle the creation
of callids and to enable the monitor thread to bind itself to a particular
call id when a dialog is determined to be related to a callid. It then unbinds
itself before returning to normal monitoring.

review: https://reviewboard.asterisk.org/r/1886/


git-svn-id: https://origsvn.digium.com/svn/asterisk/trunk@366842 65c4cc65-6c06-0410-ace0-fbb531ad65f3

5 files changed, 197 insertions, 11 deletions

diff --git a/main/channel.c b/main/channel.c
index e46aa3a79..e7bfa1d33 100644
--- a/main/channel.c
+++ b/main/channel.c
@@ -2177,6 +2177,7 @@ static void ast_channel_destructor(void *obj)
 	struct varshead *headp;
 	struct ast_datastore *datastore;
 	char device_name[AST_CHANNEL_NAME];
+	struct ast_callid *callid;
 
 	if (ast_channel_internal_is_finalized(chan)) {
 		ast_cel_report_event(chan, AST_CEL_CHANNEL_END, NULL, NULL, NULL);
@@ -2188,6 +2189,11 @@ static void ast_channel_destructor(void *obj)
 	while ((datastore = AST_LIST_REMOVE_HEAD(ast_channel_datastores(chan), entry)))
 		/* Free the data store */
 		ast_datastore_free(datastore);
+
+	/* While the channel is locked, take the reference to its callid while we tear down the call. */
+	callid = ast_channel_callid(chan);
+	ast_channel_callid_cleanup(chan);
+
 	ast_channel_unlock(chan);
 
 	/* Lock and unlock the channel just to be sure nobody has it locked still
@@ -2196,7 +2202,7 @@ static void ast_channel_destructor(void *obj)
 	ast_channel_unlock(chan);
 
 	if (ast_channel_tech_pvt(chan)) {
-		ast_log(LOG_WARNING, "Channel '%s' may not have been hung up properly\n", ast_channel_name(chan));
+		ast_log_callid(LOG_WARNING, callid, "Channel '%s' may not have been hung up properly\n", ast_channel_name(chan));
 		ast_free(ast_channel_tech_pvt(chan));
 	}
 
@@ -2229,7 +2235,7 @@ static void ast_channel_destructor(void *obj)
 	if (ast_channel_writetrans(chan))
 		ast_translator_free_path(ast_channel_writetrans(chan));
 	if (ast_channel_pbx(chan))
-		ast_log(LOG_WARNING, "PBX may not have been terminated properly on '%s'\n", ast_channel_name(chan));
+		ast_log_callid(LOG_WARNING, callid, "PBX may not have been terminated properly on '%s'\n", ast_channel_name(chan));
 
 	ast_party_dialed_free(ast_channel_dialed(chan));
 	ast_party_caller_free(ast_channel_caller(chan));
@@ -2286,6 +2292,9 @@ static void ast_channel_destructor(void *obj)
 	}
 
 	ast_channel_nativeformats_set(chan, ast_format_cap_destroy(ast_channel_nativeformats(chan)));
+	if (callid) {
+		ast_callid_unref(callid);
+	}
 }
 
 /*! \brief Free a dummy channel structure */
@@ -5669,6 +5678,16 @@ struct ast_channel *ast_request(const char *type, struct ast_format_cap *request
 			ast_format_cap_destroy(joint_cap);
 			return NULL;
 		}
+
+		/* Set newly created channel callid to same as the requestor */
+		if (requestor) {
+			struct ast_callid *callid = ast_channel_callid(requestor);
+			if (callid) {
+				ast_channel_callid_set(c, callid);
+				callid = ast_callid_unref(callid);
+			}
+		}
+
 		joint_cap = ast_format_cap_destroy(joint_cap);
 
 		if (set_security_requirements(requestor, c)) {
diff --git a/main/channel_internal_api.c b/main/channel_internal_api.c
index 4f89ca788..5125c6f59 100644
--- a/main/channel_internal_api.c
+++ b/main/channel_internal_api.c
@@ -82,6 +82,7 @@ struct ast_channel {
 	struct ast_tone_zone *zone;			/*!< Tone zone as set in indications.conf or
 							 *   in the CHANNEL dialplan function */
 	struct ast_channel_monitor *monitor;		/*!< Channel monitoring */
+	struct ast_callid *callid;			/*!< Bound call identifier pointer */
 #ifdef HAVE_EPOLL
 	struct ast_epoll_data *epfd_data[AST_MAX_FDS];
 #endif
@@ -829,6 +830,31 @@ enum ast_channel_state ast_channel_state(const struct ast_channel *chan)
 {
 	return chan->state;
 }
+struct ast_callid *ast_channel_callid(const struct ast_channel *chan)
+{
+	if (chan->callid) {
+		ast_callid_ref(chan->callid);
+		return chan->callid;
+	}
+	return NULL;
+}
+void ast_channel_callid_set(struct ast_channel *chan, struct ast_callid *callid)
+{
+	if (chan->callid) {
+
+		if ((option_debug >= 3) || (ast_opt_dbg_module && ast_debug_get_by_module(AST_MODULE) >= 3)) {
+			char call_identifier_from[13];
+			char call_identifier_to[13];
+			ast_callid_strnprint(call_identifier_from, sizeof(call_identifier_from), chan->callid);
+			ast_callid_strnprint(call_identifier_to, sizeof(call_identifier_to), callid);
+			ast_log(LOG_DEBUG, "Channel Call ID changing from %s to %s\n", call_identifier_from, call_identifier_to);
+		}
+
+		/* unbind if already set */
+		ast_callid_unref(chan->callid);
+	}
+	chan->callid = ast_callid_ref(callid);
+}
 void ast_channel_state_set(struct ast_channel *chan, enum ast_channel_state value)
 {
 	chan->state = value;
@@ -956,6 +982,13 @@ void ast_channel_softhangup_internal_flag_clear(struct ast_channel *chan, int va
 	chan ->softhangup &= ~value;
 }
 
+void ast_channel_callid_cleanup(struct ast_channel *chan)
+{
+	if (chan->callid) {
+		chan->callid = ast_callid_unref(chan->callid);
+	}
+}
+
 /* Typedef accessors */
 ast_group_t ast_channel_callgroup(const struct ast_channel *chan)
 {
diff --git a/main/cli.c b/main/cli.c
index 89bef8023..6c79c7bb2 100644
--- a/main/cli.c
+++ b/main/cli.c
@@ -1393,6 +1393,8 @@ static char *handle_showchan(struct ast_cli_entry *e, int cmd, struct ast_cli_ar
 	struct ast_str *output;/*!< Accumulation buffer for all output. */
 	long elapsed_seconds=0;
 	int hour=0, min=0, sec=0;
+	struct ast_callid *callid;
+	char call_identifier_str[13] = "";
 #ifdef CHANNEL_TRACE
 	int trace_enabled;
 #endif
@@ -1440,6 +1442,12 @@ static char *handle_showchan(struct ast_cli_entry *e, int cmd, struct ast_cli_ar
 		strcpy(cdrtime, "N/A");
 	}
 
+	/* Construct the call identifier string based on the status of the channel's call identifier */
+	if ((callid = ast_channel_callid(c))) {
+		ast_callid_strnprint(call_identifier_str, sizeof(call_identifier_str), callid);
+		ast_callid_unref(callid);
+	}
+
 	ast_str_append(&output, 0,
 		" -- General --\n"
 		"           Name: %s\n"
@@ -1474,7 +1482,8 @@ static char *handle_showchan(struct ast_cli_entry *e, int cmd, struct ast_cli_ar
 		"   Pickup Group: %llu\n"
 		"    Application: %s\n"
 		"           Data: %s\n"
-		"    Blocking in: %s\n",
+		"    Blocking in: %s\n"
+		" Call Identifer: %s\n",
 		ast_channel_name(c), ast_channel_tech(c)->type, ast_channel_uniqueid(c), ast_channel_linkedid(c),
 		S_COR(ast_channel_caller(c)->id.number.valid, ast_channel_caller(c)->id.number.str, "(N/A)"),
 		S_COR(ast_channel_caller(c)->id.name.valid, ast_channel_caller(c)->id.name.str, "(N/A)"),
@@ -1497,7 +1506,8 @@ static char *handle_showchan(struct ast_cli_entry *e, int cmd, struct ast_cli_ar
 		cdrtime, ast_channel_internal_bridged_channel(c) ? ast_channel_name(ast_channel_internal_bridged_channel(c)) : "<none>", ast_bridged_channel(c) ? ast_channel_name(ast_bridged_channel(c)) : "<none>",
 		ast_channel_context(c), ast_channel_exten(c), ast_channel_priority(c), ast_channel_callgroup(c), ast_channel_pickupgroup(c), (ast_channel_appl(c) ? ast_channel_appl(c) : "(N/A)" ),
 		(ast_channel_data(c) ? S_OR(ast_channel_data(c), "(Empty)") : "(None)"),
-		(ast_test_flag(ast_channel_flags(c), AST_FLAG_BLOCKING) ? ast_channel_blockproc(c) : "(Not Blocking)"));
+		(ast_test_flag(ast_channel_flags(c), AST_FLAG_BLOCKING) ? ast_channel_blockproc(c) : "(Not Blocking)"),
+		S_OR(call_identifier_str, "(None)"));
 
 	if (pbx_builtin_serialize_variables(c, &obuf)) {
 		ast_str_append(&output, 0, "      Variables:\n%s\n", ast_str_buffer(obuf));
diff --git a/main/logger.c b/main/logger.c
index dcef76218..cdced2701 100644
--- a/main/logger.c
+++ b/main/logger.c
@@ -1236,6 +1236,11 @@ void close_logger(void)
 	AST_RWLIST_UNLOCK(&logchannels);
 }
 
+void ast_callid_strnprint(char *buffer, size_t buffer_size, struct ast_callid *callid)
+{
+	snprintf(buffer, buffer_size, "[C-%08x]", callid->call_identifier);
+}
+
 struct ast_callid *ast_create_callid(void)
 {
 	struct ast_callid *call;
@@ -1249,7 +1254,7 @@ struct ast_callid *ast_create_callid(void)
 	using = ast_atomic_fetchadd_int(&next_unique_callid, +1);
 
 	call->call_identifier = using;
-	ast_log(LOG_DEBUG, "CALL_ID [C-%08x] created by thread.\n", call->call_identifier);
+	ast_debug(3, "CALL_ID [C-%08x] created by thread.\n", call->call_identifier);
 	return call;
 }
 
@@ -1279,7 +1284,7 @@ int ast_callid_threadassoc_add(struct ast_callid *callid)
 		/* callid will be unreffed at thread destruction */
 		ast_callid_ref(callid);
 		*pointing = callid;
-		ast_log(LOG_DEBUG, "CALL_ID [C-%08x] bound to thread.\n", callid->call_identifier);
+		ast_debug(3, "CALL_ID [C-%08x] bound to thread.\n", callid->call_identifier);
 	} else {
 		ast_log(LOG_WARNING, "Attempted to ast_callid_threadassoc_add on thread already associated with a callid.\n");
 		return 1;
@@ -1288,6 +1293,59 @@ int ast_callid_threadassoc_add(struct ast_callid *callid)
 	return 0;
 }
 
+int ast_callid_threadassoc_remove()
+{
+	struct ast_callid **pointing;
+	pointing = ast_threadstorage_get(&unique_callid, sizeof(struct ast_callid **));
+	if (!(pointing)) {
+		ast_log(LOG_ERROR, "Failed to allocate thread storage.\n");
+		return -1;
+	}
+
+	if (!(*pointing)) {
+		ast_log(LOG_ERROR, "Tried to clean callid thread storage with no callid in thread storage.\n");
+		return -1;
+	} else {
+		ast_debug(3, "Call_ID [C-%08x] being removed from thread.\n", (*pointing)->call_identifier);
+		*pointing = ast_callid_unref(*pointing);
+		return 0;
+	}
+}
+
+int ast_callid_threadstorage_auto(struct ast_callid **callid)
+{
+	struct ast_callid *tmp;
+
+	/* Start by trying to see if a callid is available from thread storage */
+	tmp = ast_read_threadstorage_callid();
+	if (tmp) {
+		*callid = tmp;
+		return 0;
+	}
+
+	/* If that failed, try to create a new one and bind it. */
+	tmp = ast_create_callid();
+	if (tmp) {
+		ast_callid_threadassoc_add(tmp);
+		*callid = tmp;
+		return 1;
+	}
+
+	/* If neither worked, then something must have gone wrong. */
+	return -1;
+}
+
+void ast_callid_threadstorage_auto_clean(struct ast_callid *callid, int callid_created)
+{
+	if (callid) {
+		/* If the callid was created rather than simply grabbed from the thread storage, we need to unbind here. */
+		if (callid_created == 1) {
+			ast_callid_threadassoc_remove();
+		}
+		callid = ast_callid_unref(callid);
+	}
+}
+
 /*!
  * \internal
  * \brief thread storage cleanup function for unique_callid
diff --git a/main/pbx.c b/main/pbx.c
index 7ea360024..2860218af 100644
--- a/main/pbx.c
+++ b/main/pbx.c
@@ -5115,6 +5115,20 @@ static enum ast_pbx_result __ast_pbx_run(struct ast_channel *c,
 	if (!(pbx = ast_calloc(1, sizeof(*pbx)))) {
 		return -1;
 	}
+
+	if (!ast_read_threadstorage_callid()) {
+		/* Associate new PBX thread with the channel call id if it is availble.
+		 * If not, create a new one instead.
+		 */
+		struct ast_callid *callid;
+		if (!(callid = ast_channel_callid(c))) {
+			callid = ast_create_callid();
+		}
+		ast_callid_threadassoc_add(callid);
+		ast_channel_callid_set(c, callid);
+		callid = ast_callid_unref(callid);
+	}
+
 	ast_channel_pbx_set(c, pbx);
 	/* Set reasonable defaults */
 	ast_channel_pbx(c)->rtimeoutms = 10000;
@@ -5489,11 +5503,6 @@ static void *pbx_thread(void *data)
 	 */
 	struct ast_channel *c = data;
 
-	/* Associate new PBX thread with a call-id */
-	struct ast_callid *callid = ast_create_callid();
-	ast_callid_threadassoc_add(callid);
-	callid = ast_callid_unref(callid);
-
 	__ast_pbx_run(c, NULL);
 	decrease_call_count();
 
@@ -8953,9 +8962,13 @@ int ast_pbx_outgoing_exten(const char *type, struct ast_format_cap *cap, const c
 {
 	struct ast_channel *chan;
 	struct async_stat *as;
+	struct ast_callid *callid;
+	int callid_created = 0;
 	int res = -1, cdr_res = -1;
 	struct outgoing_helper oh;
 
+	callid_created = ast_callid_threadstorage_auto(&callid);
+
 	if (synchronous) {
 		oh.context = context;
 		oh.exten = exten;
@@ -8973,6 +8986,16 @@ int ast_pbx_outgoing_exten(const char *type, struct ast_format_cap *cap, const c
 				ast_channel_lock(chan);
 		}
 		if (chan) {
+			/* Bind the callid to the channel if it doesn't already have one on creation */
+			struct ast_callid *channel_callid = ast_channel_callid(chan);
+			if (channel_callid) {
+				ast_callid_unref(channel_callid);
+			} else {
+				if (callid) {
+					ast_channel_callid_set(chan, callid);
+				}
+			}
+
 			if (ast_channel_state(chan) == AST_STATE_UP) {
 					res = 0;
 				ast_verb(4, "Channel %s was answered.\n", ast_channel_name(chan));
@@ -9052,6 +9075,7 @@ int ast_pbx_outgoing_exten(const char *type, struct ast_format_cap *cap, const c
 			}
 		}
 	} else {
+		struct ast_callid *channel_callid;
 		if (!(as = ast_calloc(1, sizeof(*as)))) {
 			res = -1;
 			goto outgoing_exten_cleanup;
@@ -9067,6 +9091,17 @@ int ast_pbx_outgoing_exten(const char *type, struct ast_format_cap *cap, const c
 			res = -1;
 			goto outgoing_exten_cleanup;
 		}
+
+		/* Bind the newly created callid to the channel if it doesn't already have one on creation. */
+		channel_callid = ast_channel_callid(chan);
+		if (channel_callid) {
+			ast_callid_unref(channel_callid);
+		} else {
+			if (callid) {
+				ast_channel_callid_set(chan, callid);
+			}
+		}
+
 		as->chan = chan;
 		ast_copy_string(as->context, context, sizeof(as->context));
 		set_ext_pri(as->chan,  exten, priority);
@@ -9087,7 +9122,9 @@ int ast_pbx_outgoing_exten(const char *type, struct ast_format_cap *cap, const c
 		}
 		res = 0;
 	}
+
 outgoing_exten_cleanup:
+	ast_callid_threadstorage_auto_clean(callid, callid_created);
 	ast_variables_destroy(vars);
 	return res;
 }
@@ -9122,9 +9159,14 @@ int ast_pbx_outgoing_app(const char *type, struct ast_format_cap *cap, const cha
 {
 	struct ast_channel *chan;
 	struct app_tmp *tmp;
+	struct ast_callid *callid;
+	int callid_created;
 	int res = -1, cdr_res = -1;
 	struct outgoing_helper oh;
 
+	/* Start by checking for a callid in threadstorage, and if none is found, bind one. */
+	callid_created = ast_callid_threadstorage_auto(&callid);
+
 	memset(&oh, 0, sizeof(oh));
 	oh.vars = vars;
 	oh.account = account;
@@ -9138,6 +9180,16 @@ int ast_pbx_outgoing_app(const char *type, struct ast_format_cap *cap, const cha
 	if (synchronous) {
 		chan = __ast_request_and_dial(type, cap, NULL, addr, timeout, reason, cid_num, cid_name, &oh);
 		if (chan) {
+			/* Bind the newly created callid to the channel if it doesn't already have one on creation */
+			struct ast_callid *channel_callid = ast_channel_callid(chan);
+			if (channel_callid) {
+				ast_callid_unref(channel_callid);
+			} else {
+				if (callid) {
+					ast_channel_callid_set(chan, callid);
+				}
+			}
+
 			ast_set_variables(chan, vars);
 			if (account)
 				ast_cdr_setaccount(chan, account);
@@ -9200,6 +9252,7 @@ int ast_pbx_outgoing_app(const char *type, struct ast_format_cap *cap, const cha
 
 	} else {
 		struct async_stat *as;
+		struct ast_callid *channel_callid;
 		if (!(as = ast_calloc(1, sizeof(*as)))) {
 			res = -1;
 			goto outgoing_app_cleanup;
@@ -9210,6 +9263,17 @@ int ast_pbx_outgoing_app(const char *type, struct ast_format_cap *cap, const cha
 			res = -1;
 			goto outgoing_app_cleanup;
 		}
+
+		/* Bind the newly created callid to the channel if it doesn't already have one on creation. */
+		channel_callid = ast_channel_callid(chan);
+		if (channel_callid) {
+			ast_callid_unref(channel_callid);
+		} else {
+			if (callid) {
+				ast_channel_callid_set(chan, callid);
+			}
+		}
+
 		as->chan = chan;
 		ast_copy_string(as->app, app, sizeof(as->app));
 		if (appdata)
@@ -9235,7 +9299,9 @@ int ast_pbx_outgoing_app(const char *type, struct ast_format_cap *cap, const cha
 		}
 		res = 0;
 	}
+
 outgoing_app_cleanup:
+	ast_callid_threadstorage_auto_clean(callid, callid_created);
 	ast_variables_destroy(vars);
 	return res;
 }