Introducing the log message unique call identifiers feature

Log messages will now display a call number that they are tied to (ordered for calls
based on when they started). This feature is made to be minimally invasive without
requiring changes to many of the existing log messages. These IDs  won't show up for
verbose messages on CLI (but they will in log files) This is currently in phase II
of production, see more about this feature on the wiki --
https://wiki.asterisk.org/wiki/display/AST/Unique+Call-ID+Logging

Review: https://reviewboard.asterisk.org/r/1823/


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

9 files changed, 265 insertions, 14 deletions

diff --git a/CHANGES b/CHANGES
index d42be61de..75a7e87ae 100644
--- a/CHANGES
+++ b/CHANGES
@@ -23,6 +23,10 @@ Core
    modules that are loaded into Asterisk, since they should only be called once
    in any single process. If desired, this feature can be disabled by supplying
    the "--disable-asteriskssl" option to the configure script.
+ * Threads belonging to a particular call are now linked with callids which get
+   added to any log messages produced by those threads. Log messages can now be
+   easily identified as involved with a certain call by looking at their call id.
+   This feature can be disabled in logger.conf with the display_callids option.
 
 CLI Changes
 -------------------
diff --git a/apps/app_mixmonitor.c b/apps/app_mixmonitor.c
index a89b6cc5d..c1f5ada72 100644
--- a/apps/app_mixmonitor.c
+++ b/apps/app_mixmonitor.c
@@ -240,6 +240,7 @@ static const char * const mixmonitor_spy_type = "MixMonitor";
 
 struct mixmonitor {
 	struct ast_audiohook audiohook;
+	struct ast_callid *callid;
 	char *filename;
 	char *filename_read;
 	char *filename_write;
@@ -395,6 +396,10 @@ static void mixmonitor_free(struct mixmonitor *mixmonitor)
 			ast_free(mixmonitor->name);
 			ast_free(mixmonitor->post_process);
 		}
+
+		if (mixmonitor->callid) {
+			ast_callid_unref(mixmonitor->callid);
+		}
 		ast_free(mixmonitor);
 	}
 }
@@ -440,6 +445,11 @@ static void *mixmonitor_thread(void *obj)
 	int errflag = 0;
 	struct ast_format format_slin;
 
+	/* Keep callid association before any log messages */
+	if (mixmonitor->callid) {
+		ast_callid_threadassoc_add(mixmonitor->callid);
+	}
+
 	ast_verb(2, "Begin MixMonitor Recording %s\n", mixmonitor->name);
 
 	fs = &mixmonitor->mixmonitor_ds->fs;
@@ -674,6 +684,9 @@ static void launch_monitor_thread(struct ast_channel *chan, const char *filename
 		return;
 	}
 
+	/* reference be released at mixmonitor destruction */
+	mixmonitor->callid = ast_read_threadstorage_callid();
+
 	ast_pthread_create_detached_background(&thread, NULL, mixmonitor_thread, mixmonitor);
 }
 
diff --git a/configs/logger.conf.sample b/configs/logger.conf.sample
index 3f4850788..1fdac7030 100644
--- a/configs/logger.conf.sample
+++ b/configs/logger.conf.sample
@@ -19,6 +19,11 @@
 ;dateformat=%F %T       ; ISO 8601 date format
 ;dateformat=%F %T.%3q   ; with milliseconds
 ;
+;
+; This makes Asterisk write callids to log messages
+; (defaults to yes)
+;use_callids = no
+;
 ; This appends the hostname to the name of the log files.
 ;appendhostname = yes
 ;
diff --git a/include/asterisk/bridging.h b/include/asterisk/bridging.h
index 3c117b7cd..831f340c8 100644
--- a/include/asterisk/bridging.h
+++ b/include/asterisk/bridging.h
@@ -165,6 +165,8 @@ struct ast_bridge_channel {
 	struct ast_bridge_tech_optimizations tech_args;
 	/*! Queue of DTMF digits used for DTMF streaming */
 	char dtmf_stream_q[8];
+	/*! Call ID associated with bridge channel */
+	struct ast_callid *callid;
 	/*! Linked list information */
 	AST_LIST_ENTRY(ast_bridge_channel) entry;
 };
@@ -243,9 +245,11 @@ struct ast_bridge {
 	size_t array_num;
 	/*! Number of channels the array can handle */
 	size_t array_size;
+	/*! Call ID associated with the bridge */
+	struct ast_callid *callid;
 	/*! Linked list of channels participating in the bridge */
 	AST_LIST_HEAD_NOLOCK(, ast_bridge_channel) channels;
-};
+	};
 
 /*! \brief Create a new bridge
  *
diff --git a/include/asterisk/logger.h b/include/asterisk/logger.h
index c7f260c49..a49544963 100644
--- a/include/asterisk/logger.h
+++ b/include/asterisk/logger.h
@@ -60,6 +60,24 @@ extern "C" {
 void ast_log(int level, const char *file, int line, const char *function, const char *fmt, ...)
 	__attribute__((format(printf, 5, 6)));
 
+/* XXX needs documentation */
+struct ast_callid;
+
+/*! \brief Used for sending a log message with a known call_id
+	This is a modified logger function which is functionally identical to the above logger function,
+	it just include a call_id argument as well. If NULL is specified here, no attempt will be made to
+	join the log message with a call_id.
+
+	\param level	Type of log event
+	\param file	Will be provided by the AST_LOG_* macro
+	\param line	Will be provided by the AST_LOG_* macro
+	\param function	Will be provided by the AST_LOG_* macro
+	\param callid	This is the ast_callid that is associated with the log message. May be NULL.
+	\param fmt	This is what is important.  The format is the same as your favorite breed of printf.  You know how that works, right? :-)
+*/
+void ast_log_callid(int level, const char *file, int line, const char *function, struct ast_callid *callid, const char *fmt, ...)
+	__attribute__((format(printf, 6, 7)));
+
 void ast_backtrace(void);
 
 /*! \brief Reload logger without rotating log files */
@@ -216,6 +234,56 @@ int ast_logger_register_level(const char *name);
 void ast_logger_unregister_level(const char *name);
 
 /*!
+ * \brief factory function to create a new uniquely identifying callid.
+ *
+ * \retval ast_callid struct pointer containing the call id
+ *
+ * \note The newly created callid will be referenced upon creation and this function should be
+ * paired with a call to ast_callid_unref()
+ */
+struct ast_callid *ast_create_callid(void);
+
+/*!
+ * \brief extracts the callerid from the thread
+ *
+ * \retval ast_callid reference to call_id related to the thread
+ * \retval NULL if no call_id is present in the thread
+ *
+ * This reference must be unreffed before it loses scope to prevent memory leaks.
+ */
+struct ast_callid *ast_read_threadstorage_callid(void);
+
+/*!
+ * \brief Increase callid reference count
+ *
+ * \param c the ast_callid
+ *
+ * \retval c always
+ */
+#define ast_callid_ref(c) ({ ao2_ref(c, +1); (c); })
+
+/*!
+ * \brief Decrease callid reference count
+ *
+ * \param c the ast_callid
+ *
+ * \retval NULL always
+ */
+#define ast_callid_unref(c) ({ ao2_ref(c, -1); (NULL); })
+
+/*!
+ * \brief Adds a known callid to thread storage of the calling thread
+ *
+ * \retval 0 - success
+ * \retval non-zero - failure
+ */
+int ast_callid_threadassoc_add(struct ast_callid *callid);
+
+/*
+ * May need a function to clean the threadstorage if we want to repurpose a thread.
+ */
+
+/*!
  * \brief Send a log message to a dynamically registered log level
  * \param level The log level to send the message to
  *
diff --git a/main/dial.c b/main/dial.c
index d65cb8a65..251eab9ba 100644
--- a/main/dial.c
+++ b/main/dial.c
@@ -50,6 +50,7 @@ struct ast_dial {
 	void *user_data;                                   /*!< Attached user data */
 	AST_LIST_HEAD(, ast_dial_channel) channels; /*!< Channels being dialed */
 	pthread_t thread;                                  /*!< Thread (if running in async) */
+	struct ast_callid *callid;                         /*!< callid pointer (if running in async) */
 	ast_mutex_t lock;                                  /*! Lock to protect the thread information above */
 };
 
@@ -705,6 +706,9 @@ static enum ast_dial_result monitor_dial(struct ast_dial *dial, struct ast_chann
 static void *async_dial(void *data)
 {
 	struct ast_dial *dial = data;
+	if (dial->callid) {
+		ast_callid_threadassoc_add(dial->callid);
+	}
 
 	/* This is really really simple... we basically pass monitor_dial a NULL owner and it changes it's behavior */
 	monitor_dial(dial, NULL);
@@ -738,6 +742,8 @@ enum ast_dial_result ast_dial_run(struct ast_dial *dial, struct ast_channel *cha
 
 	/* If we are running async spawn a thread and send it away... otherwise block here */
 	if (async) {
+		/* reference be released at dial destruction if it isn't NULL */
+		dial->callid = ast_read_threadstorage_callid();
 		dial->state = AST_DIAL_RESULT_TRYING;
 		/* Try to create a thread */
 		if (ast_pthread_create(&dial->thread, NULL, async_dial, dial)) {
@@ -913,6 +919,11 @@ int ast_dial_destroy(struct ast_dial *dial)
 	/* Lock be gone! */
 	ast_mutex_destroy(&dial->lock);
 
+	/* Get rid of the reference to the ast_callid */
+	if (dial->callid) {
+		ast_callid_unref(dial->callid);
+	}
+
 	/* Free structure */
 	ast_free(dial);
 
diff --git a/main/features.c b/main/features.c
index 71be7d3f7..d23bda4a1 100644
--- a/main/features.c
+++ b/main/features.c
@@ -844,6 +844,7 @@ struct ast_bridge_thread_obj
 	struct ast_bridge_config bconfig;
 	struct ast_channel *chan;
 	struct ast_channel *peer;
+	struct ast_callid *callid;                             /*<! callid pointer (Only used to bind thread) */
 	unsigned int return_to_pbx:1;
 };
 
@@ -949,6 +950,12 @@ static void *bridge_call_thread(void *data)
 	struct ast_bridge_thread_obj *tobj = data;
 	int res;
 
+	if (tobj->callid) {
+		ast_callid_threadassoc_add(tobj->callid);
+		/* Need to deref and set to null since ast_bridge_thread_obj has no common destructor */
+		tobj->callid = ast_callid_unref(tobj->callid);
+	}
+
 	ast_channel_appl_set(tobj->chan, !tobj->return_to_pbx ? "Transferred Call" : "ManagerBridge");
 	ast_channel_data_set(tobj->chan, ast_channel_name(tobj->peer));
 	ast_channel_appl_set(tobj->peer, !tobj->return_to_pbx ? "Transferred Call" : "ManagerBridge");
@@ -987,15 +994,23 @@ static void *bridge_call_thread(void *data)
  *
  * Create thread and attributes, call bridge_call_thread
  */
-static void bridge_call_thread_launch(void *data)
+static void bridge_call_thread_launch(struct ast_bridge_thread_obj *data)
 {
 	pthread_t thread;
 	pthread_attr_t attr;
 	struct sched_param sched;
 
+	/* This needs to be unreffed once it has been associated with the new thread. */
+	data->callid = ast_read_threadstorage_callid();
+
 	pthread_attr_init(&attr);
 	pthread_attr_setdetachstate(&attr, PTHREAD_CREATE_DETACHED);
-	ast_pthread_create(&thread, &attr, bridge_call_thread, data);
+	if (ast_pthread_create(&thread, &attr, bridge_call_thread, data)) {
+		/* Failed to create thread. Ditch the reference to callid. */
+		ast_callid_unref(data->callid);
+		ast_log(LOG_ERROR, "Failed to create bridge_call_thread.\n");
+		return;
+	}
 	pthread_attr_destroy(&attr);
 	memset(&sched, 0, sizeof(sched));
 	pthread_setschedparam(thread, SCHED_RR, &sched);
@@ -8263,3 +8278,4 @@ int ast_features_init(void)
 
 	return res;
 }
+
diff --git a/main/logger.c b/main/logger.c
index 37f13cea6..5891e8709 100644
--- a/main/logger.c
+++ b/main/logger.c
@@ -43,6 +43,7 @@ ASTERISK_FILE_VERSION(__FILE__, "$Revision$")
 #include "asterisk/cli.h"
 #include "asterisk/utils.h"
 #include "asterisk/manager.h"
+#include "asterisk/astobj2.h"
 #include "asterisk/threadstorage.h"
 #include "asterisk/strings.h"
 #include "asterisk/pbx.h"
@@ -73,6 +74,15 @@ static int filesize_reload_needed;
 static unsigned int global_logmask = 0xFFFF;
 static int queuelog_init;
 static int logger_initialized;
+static volatile int next_unique_callid; /* Used to assign unique call_ids to calls */
+static int display_callids;
+static void unique_callid_cleanup(void *data);
+
+struct ast_callid {
+    int call_identifier; /* Numerical value of the call displayed in the logs */
+};
+
+AST_THREADSTORAGE_CUSTOM(unique_callid, NULL, unique_callid_cleanup);
 
 static enum rotatestrategy {
 	SEQUENTIAL = 1 << 0,     /* Original method - create a new file, in order */
@@ -129,6 +139,7 @@ struct logmsg {
 	int level;
 	int line;
 	int lwp;
+	struct ast_callid *callid;
 	AST_DECLARE_STRING_FIELDS(
 		AST_STRING_FIELD(date);
 		AST_STRING_FIELD(file);
@@ -139,6 +150,14 @@ struct logmsg {
 	AST_LIST_ENTRY(logmsg) list;
 };
 
+static void logmsg_free(struct logmsg *msg)
+{
+	if (msg->callid) {
+		ast_callid_unref(msg->callid);
+	}
+	ast_free(msg);
+}
+
 static AST_LIST_HEAD_STATIC(logmsgs, logmsg);
 static pthread_t logthread = AST_PTHREADT_NULL;
 static ast_cond_t logcond;
@@ -320,6 +339,8 @@ static void init_logger_chain(int locked, const char *altconf)
 	const char *s;
 	struct ast_flags config_flags = { 0 };
 
+	display_callids = 1;
+
 	if (!(cfg = ast_config_load2(S_OR(altconf, "logger.conf"), "logger", config_flags)) || cfg == CONFIG_STATUS_FILEINVALID) {
 		return;
 	}
@@ -373,6 +394,9 @@ static void init_logger_chain(int locked, const char *altconf)
 			hostname[0] = '\0';
 	} else
 		hostname[0] = '\0';
+	if ((s = ast_variable_retrieve(cfg, "general", "display_callids"))) {
+		display_callids = ast_true(s);
+	}
 	if ((s = ast_variable_retrieve(cfg, "general", "dateformat")))
 		ast_copy_string(dateformat, s, sizeof(dateformat));
 	else
@@ -999,6 +1023,14 @@ static void logger_print_normal(struct logmsg *logmsg)
 
 	if (!AST_RWLIST_EMPTY(&logchannels)) {
 		AST_RWLIST_TRAVERSE(&logchannels, chan, list) {
+			/* XXX May need to grow larger later in order to accomodate call counts higher than 999999. */
+			char call_identifier_str[13] = "";
+
+			if (logmsg->callid) {
+				snprintf(call_identifier_str, sizeof(call_identifier_str), "[C-%08x]", logmsg->callid->call_identifier);
+			}
+
+
 			/* If the channel is disabled, then move on to the next one */
 			if (chan->disabled) {
 				continue;
@@ -1022,10 +1054,11 @@ static void logger_print_normal(struct logmsg *logmsg)
 				/* Turn the numerical line number into a string */
 				snprintf(linestr, sizeof(linestr), "%d", logmsg->line);
 				/* Build string to print out */
-				snprintf(buf, sizeof(buf), "[%s] %s[%d]: %s:%s %s: %s",
+				snprintf(buf, sizeof(buf), "[%s] %s[%d]%s: %s:%s %s: %s",
 					 logmsg->date,
 					 term_color(tmp1, logmsg->level_name, colors[logmsg->level], 0, sizeof(tmp1)),
 					 logmsg->lwp,
+					 call_identifier_str,
 					 term_color(tmp2, logmsg->file, COLOR_BRWHITE, 0, sizeof(tmp2)),
 					 term_color(tmp3, linestr, COLOR_BRWHITE, 0, sizeof(tmp3)),
 					 term_color(tmp4, logmsg->function, COLOR_BRWHITE, 0, sizeof(tmp4)),
@@ -1042,8 +1075,9 @@ static void logger_print_normal(struct logmsg *logmsg)
 				}
 
 				/* Print out to the file */
-				res = fprintf(chan->fileptr, "[%s] %s[%d] %s: %s",
-					      logmsg->date, logmsg->level_name, logmsg->lwp, logmsg->file, term_strip(buf, logmsg->message, BUFSIZ));
+				res = fprintf(chan->fileptr, "[%s] %s[%d]%s %s: %s",
+					      logmsg->date, logmsg->level_name, logmsg->lwp, call_identifier_str,
+					      logmsg->file, term_strip(buf, logmsg->message, BUFSIZ));
 				if (res <= 0 && !ast_strlen_zero(logmsg->message)) {
 					fprintf(stderr, "**** Asterisk Logging Error: ***********\n");
 					if (errno == ENOMEM || errno == ENOSPC)
@@ -1100,7 +1134,7 @@ static void *logger_thread(void *data)
 			logger_print_normal(msg);
 
 			/* Free the data since we are done */
-			ast_free(msg);
+			logmsg_free(msg);
 		}
 
 		/* If we should stop, then stop */
@@ -1203,17 +1237,83 @@ void close_logger(void)
 	return;
 }
 
+struct ast_callid *ast_create_callid(void)
+{
+	struct ast_callid *call;
+	int using;
+
+	if (!(call = ao2_alloc(sizeof(struct ast_callid), NULL))) {
+		ast_log(LOG_ERROR, "Could not allocate callid struct.\n");
+		return NULL;
+	}
+
+	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);
+	return call;
+}
+
+struct ast_callid *ast_read_threadstorage_callid(void)
+{
+	struct ast_callid **callid;
+	callid = ast_threadstorage_get(&unique_callid, sizeof(struct ast_callid **));
+	if (callid && *callid) {
+		ast_callid_ref(*callid);
+		return *callid;
+	}
+
+	return NULL;
+
+}
+
+int ast_callid_threadassoc_add(struct ast_callid *callid)
+{
+	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)) {
+		/* 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);
+	} else {
+		ast_log(LOG_WARNING, "Attempted to ast_callid_threadassoc_add on thread already associated with a callid.\n");
+		return 1;
+	}
+
+	return 0;
+}
+
+/*!
+ * \internal
+ * \brief thread storage cleanup function for unique_callid
+ */
+static void unique_callid_cleanup(void *data)
+{
+	struct ast_callid **callid = data;
+
+	if (*callid) {
+		ast_callid_unref(*callid);
+	}
+
+	ast_free(data);
+}
+
 /*!
  * \brief send log messages to syslog and/or the console
  */
-void ast_log(int level, const char *file, int line, const char *function, const char *fmt, ...)
+static void __attribute__((format(printf, 6, 0))) ast_log_full(int level, const char *file, int line, const char *function, struct ast_callid *callid, const char *fmt, va_list ap)
 {
 	struct logmsg *logmsg = NULL;
 	struct ast_str *buf = NULL;
 	struct ast_tm tm;
 	struct timeval now = ast_tvnow();
 	int res = 0;
-	va_list ap;
 	char datestring[256];
 
 	if (!(buf = ast_str_thread_get(&log_buf, LOG_BUF_INIT_SIZE)))
@@ -1225,9 +1325,7 @@ void ast_log(int level, const char *file, int line, const char *function, const
 		 * so just log to stdout
 		 */
 		int result;
-		va_start(ap, fmt);
 		result = ast_str_set_va(&buf, BUFSIZ, fmt, ap); /* XXX BUFSIZ ? */
-		va_end(ap);
 		if (result != AST_DYNSTR_BUILD_FAILED) {
 			term_filter_escapes(ast_str_buffer(buf));
 			fputs(ast_str_buffer(buf), stdout);
@@ -1240,9 +1338,7 @@ void ast_log(int level, const char *file, int line, const char *function, const
 		return;
 
 	/* Build string */
-	va_start(ap, fmt);
 	res = ast_str_set_va(&buf, BUFSIZ, fmt, ap);
-	va_end(ap);
 
 	/* If the build failed, then abort and free this structure */
 	if (res == AST_DYNSTR_BUILD_FAILED)
@@ -1262,6 +1358,11 @@ void ast_log(int level, const char *file, int line, const char *function, const
 		logmsg->type = LOGMSG_NORMAL;
 	}
 
+	if (display_callids && callid) {
+		logmsg->callid = ast_callid_ref(callid);
+		/* callid will be unreffed at logmsg destruction */
+	}
+
 	/* Create our date/time */
 	ast_localtime(&now, &tm, NULL);
 	ast_strftime(datestring, sizeof(datestring), dateformat, &tm);
@@ -1283,12 +1384,36 @@ void ast_log(int level, const char *file, int line, const char *function, const
 		AST_LIST_UNLOCK(&logmsgs);
 	} else {
 		logger_print_normal(logmsg);
-		ast_free(logmsg);
+		logmsg_free(logmsg);
 	}
 
 	return;
 }
 
+void ast_log(int level, const char *file, int line, const char *function, const char *fmt, ...)
+{
+	struct ast_callid *callid;
+	va_list ap;
+
+	callid = ast_read_threadstorage_callid();
+
+	va_start(ap, fmt);
+	ast_log_full(level, file, line, function, callid, fmt, ap);
+	va_end(ap);
+
+	if (callid) {
+		ast_callid_unref(callid);
+	}
+}
+
+void ast_log_callid(int level, const char *file, int line, const char *function, struct ast_callid *callid, const char *fmt, ...)
+{
+	va_list ap;
+	va_start(ap, fmt);
+	ast_log_full(level, file, line, function, callid, fmt, ap);
+	va_end(ap);
+}
+
 #ifdef HAVE_BKTR
 
 struct ast_bt *ast_bt_create(void)
diff --git a/main/pbx.c b/main/pbx.c
index 17d941fa2..cdeccaf9d 100644
--- a/main/pbx.c
+++ b/main/pbx.c
@@ -5486,6 +5486,11 @@ 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();