Add queue logging and fix indications buglet

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

apps/app_queue.c

@@ -35,6 +35,8 @@
 #include <sys/signal.h>
 #include <netinet/in.h>
 
+#include "../astconf.h"
+
 #include <pthread.h>
 
 #define QUEUE_STRATEGY_RINGALL		0
@@ -128,6 +130,8 @@ struct queue_ent {
 	char announce[80];		/* Announcement to play */
 	char context[80];		/* Context when user exits queue */
 	int pos;					/* Where we are in the queue */
+	int opos;					/* Where we started in the queue */
+	int handled;				/* Whether our call was handled */
 	time_t start;				/* When we started holding */
 	struct ast_channel *chan;	/* Our channel */
 	struct queue_ent *next;		/* The next queue entry */
@@ -221,6 +225,7 @@ static int join_queue(char *queuename, struct queue_ent *qe)
 				qe->next = NULL;
 				qe->parent = q;
 				qe->pos = ++pos;
+				qe->opos = pos;
 				strncpy(qe->moh, q->moh, sizeof(qe->moh));
 				strncpy(qe->announce, q->announce, sizeof(qe->announce));
 				strncpy(qe->context, q->context, sizeof(qe->context));
@@ -699,6 +704,9 @@ static int try_calling(struct queue_ent *qe, char *options, char *announceoverri
 	int allowredir_out=0;
 	int allowdisconnect=0;
 	char restofit[AST_MAX_EXTENSION];
+	char oldexten[AST_MAX_EXTENSION]="";
+	char oldcontext[AST_MAX_EXTENSION]="";
+	char queuename[256]="";
 	char *newnum;
 	struct ast_channel *peer;
 	struct localuser *lpeer;
@@ -707,8 +715,10 @@ static int try_calling(struct queue_ent *qe, char *options, char *announceoverri
 	int x=0;
 	char *announce = NULL;
 	char digit = 0;
+	time_t callstart;
 	/* Hold the lock while we setup the outgoing calls */
 	ast_mutex_lock(&qe->parent->lock);
+	strncpy(queuename, qe->parent->name, sizeof(queuename) - 1);
 	cur = qe->parent->members;
 	if (strlen(qe->announce))
 		announce = qe->announce;
@@ -797,6 +807,7 @@ static int try_calling(struct queue_ent *qe, char *options, char *announceoverri
 		/* Ah ha!  Someone answered within the desired timeframe.  Of course after this
 		   we will always return with -1 so that it is hung up properly after the 
 		   conversation.  */
+		qe->handled++;
 		if (!strcmp(qe->chan->type,"Zap")) {
 			if (tmp->dataquality) zapx = 0;
 			ast_channel_setoption(qe->chan,AST_OPTION_TONE_VERIFY,&zapx,sizeof(char),0);
@@ -822,6 +833,7 @@ static int try_calling(struct queue_ent *qe, char *options, char *announceoverri
 			if (res2) {
 				/* Agent must have hung up */
 				ast_log(LOG_WARNING, "Agent on %s hungup on the customer.  They're going to be pissed.\n", peer->name);
+				ast_queue_log(queuename, qe->chan->uniqueid, peer->name, "AGENTDUMP", "");
 				ast_hangup(peer);
 				return -1;
 			}
@@ -832,6 +844,7 @@ static int try_calling(struct queue_ent *qe, char *options, char *announceoverri
 		/* Make sure channels are compatible */
 		res = ast_channel_make_compatible(qe->chan, peer);
 		if (res < 0) {
+			ast_queue_log(queuename, qe->chan->uniqueid, peer->name, "SYSCOMPAT", "");
 			ast_log(LOG_WARNING, "Had to drop call because I couldn't make %s compatible with %s\n", qe->chan->name, peer->name);
 			ast_hangup(peer);
 			return -1;
@@ -843,7 +856,18 @@ static int try_calling(struct queue_ent *qe, char *options, char *announceoverri
  			ast_log(LOG_DEBUG, "app_queue: sendurl=%s.\n", url);
  			ast_channel_sendurl( peer, url );
  		} /* /JDG */
+		ast_queue_log(queuename, qe->chan->uniqueid, peer->name, "CONNECT", "%ld", (long)time(NULL) - qe->start);
+		strncpy(oldcontext, qe->chan->context, sizeof(oldcontext) - 1);
+		strncpy(oldexten, qe->chan->exten, sizeof(oldexten) - 1);
+		time(&callstart);
 		bridge = ast_bridge_call(qe->chan, peer, allowredir_in, allowredir_out, allowdisconnect);
+		if (strcasecmp(oldcontext, qe->chan->context) || strcasecmp(oldexten, qe->chan->exten)) {
+			ast_queue_log(queuename, qe->chan->uniqueid, peer->name, "TRANSFER", "%s|%s", qe->chan->exten, qe->chan->context);
+		} else if (qe->chan->_softhangup) {
+			ast_queue_log(queuename, qe->chan->uniqueid, peer->name, "COMPLETECALLER", "%ld|%ld", (long)(callstart - qe->start), (long)(time(NULL) - callstart));
+		} else {
+			ast_queue_log(queuename, qe->chan->uniqueid, peer->name, "COMPLETEAGENT", "%ld|%ld", (long)(callstart - qe->start), (long)(time(NULL) - callstart));
+		}
 
 		if(bridge != AST_PBX_NO_HANGUP_PEER)
 			ast_hangup(peer);
@@ -1139,41 +1163,54 @@ static int queue_exec(struct ast_channel *chan, void *data)
 	qe.chan = chan;
 	qe.start = time(NULL);
 	if (!join_queue(queuename, &qe)) {
+		ast_queue_log(queuename, chan->uniqueid, "NONE", "ENTERQUEUE", "%s|%s", url ? url : "", chan->callerid ? chan->callerid : "");
 		/* Start music on hold */
 		ast_moh_start(chan, qe.moh);
 		for (;;) {
 			res = wait_our_turn(&qe);
 			/* If they hungup, return immediately */
 			if (res < 0) {
+				ast_queue_log(queuename, chan->uniqueid, "NONE", "ABANDON", "%d|%d|%ld", qe.pos, qe.opos, (long)time(NULL) - qe.start);
 				if (option_verbose > 2) {
 					ast_verbose(VERBOSE_PREFIX_3 "User disconnected while waiting their turn\n");
 					res = -1;
 				}
 				break;
 			}
-			if (!res)
+			if (!res) 
 				break;
-			if (valid_exit(&qe, res))
+			if (valid_exit(&qe, res)) {
+				ast_queue_log(queuename, chan->uniqueid, "NONE", "EXITWITHKEY", "%c|%d", res, qe.pos);
 				break;
+			}
 		}
 		if (!res) {
 			for (;;) {
 				res = try_calling(&qe, options, announceoverride, url, &go_on);
-				if (res)
+				if (res) {
+					if (res < 0) {
+						if (!qe.handled)
+							ast_queue_log(queuename, chan->uniqueid, "NONE", "ABANDON", "%d|%d|%ld", qe.pos, qe.opos, (long)time(NULL) - qe.start);
+					} else if (res > 0)
+						ast_queue_log(queuename, chan->uniqueid, "NONE", "EXITWITHKEY", "%c|%d", res, qe.pos);
 					break;
+				}
 				res = wait_a_bit(&qe);
 				if (res < 0) {
+					ast_queue_log(queuename, chan->uniqueid, "NONE", "ABANDON", "%d|%d|%ld", qe.pos, qe.opos, (long)time(NULL) - qe.start);
 					if (option_verbose > 2) {
 						ast_verbose(VERBOSE_PREFIX_3 "User disconnected when they almost made it\n");
 						res = -1;
 					}
 					break;
 				}
-				if (res && valid_exit(&qe, res))
+				if (res && valid_exit(&qe, res)) {
+					ast_queue_log(queuename, chan->uniqueid, "NONE", "EXITWITHKEY", "%c|%d", res, qe.pos);
 					break;
-
+				}
 				/* exit after a timeout if 'n' option enabled */
 				if (go_on) {
+					ast_queue_log(queuename, chan->uniqueid, "NONE", "EXITWITHTIMEOUT", "%d", qe.pos);
 					res = 0;
 					break;
 				}

doc/queuelog.txt

@@ -0,0 +1,62 @@
+Queue Log Information
+=====================
+
+In order to properly manage ACD queues, it is important to be able to
+keep track of details of call setups and teardowns in much greater detail
+than traditional call detail records provide.  In order to support this,
+extensive and detailed tracing of every queued call is stored in the
+queue log, located (by default) in /var/log/asterisk/queue_log.
+
+These are the events (and associated information) in the queue log:
+
+ABANDON(position|origposition|waittime)
+The caller abandoned their position in the queue.  The position is the
+caller's position in the queue when they hungup, the origposition is
+the original position the caller was when they first entered the
+queue, and the waittime is how long the call had been waiting in the 
+queue at the time of disconnect.
+
+AGENTDUMP
+The agent dumped the caller while listening to the queue announcement.
+
+COMPLETEAGENT(holdtime|calltime|origposition)
+The caller was connected to an agent, and the call was terminated normally
+by the *agent*.  The caller's hold time and the length of the call are both
+recorded.  The caller's original position in the queue is recorded in
+origposition.
+
+COMPLETECALLER(holdtime|calltime|origposition)
+The caller was connected to an agent, and the call was terminated normally
+by the *caller*.  The caller's hold time and the length of the call are both
+recorded.  The caller's original position in the queue is recorded in
+origposition.
+
+CONFIGRELOAD
+The configuration has been reloaded (e.g. with asterisk -rx reload)
+
+CONNECT(holdtime)
+The caller was connected to an agent.  Hold time represents the amount
+of time the caller was on hold.
+
+ENTERQUEUE(url|callerid)
+A call has entered the queue.  URL (if specified) and Caller*ID are placed
+in the log.
+
+EXITWITHKEY(key|position)
+The caller elected to use a menu key to exit the queue.  The key and
+the caller's position in the queue are recorded.
+
+EXITWITHTIMEOUT(position)
+The caller was on hold too long and the timeout expired.
+
+QUEUESTART
+The queueing system has been started for the first time this session.
+
+SYSCOMPAT
+A call was answered by an agent, but the call was dropped because the 
+channels were not compatible.
+
+TRANSFER(extension,context)
+Caller was transferred to a different extension.  Context and extension
+are recorded.
+

include/asterisk/logger.h

@@ -40,6 +40,9 @@ extern "C" {
 extern void ast_log(int level, const char *file, int line, const char *function, const char *fmt, ...)
 	__attribute__ ((format (printf, 5, 6)));
 
+extern void ast_queue_log(const char *queuename, const char *callid, const char *agent, const char *event, const char *fmt, ...)
+	__attribute__ ((format (printf, 5, 6)));
+
 //! Send a verbose message (based on verbose level)
 /*!
  * This works like ast_log, but prints verbose messages to the console depending on verbosity level set.

indications.c

@@ -318,11 +318,11 @@ static inline void free_zone(struct tone_zone* zone)
 		struct tone_zone_sound *tmp = zone->tones->next;
 		free((void*)zone->tones->name);
 		free((void*)zone->tones->data);
-		if (zone->ringcadance)
-			free((void*)zone->ringcadance);
 		free(zone->tones);
 		zone->tones = tmp;
 	}
+	if (zone->ringcadance)
+		free((void*)zone->ringcadance);
 	free(zone);
 }
 

logger.c

@@ -220,6 +220,43 @@ static void init_logger_chain(void)
 	ast_mutex_unlock(&loglock);
 }
 
+static FILE *qlog = NULL;
+static ast_mutex_t qloglock = AST_MUTEX_INITIALIZER;
+
+void ast_queue_log(const char *queuename, const char *callid, const char *agent, const char *event, const char *fmt, ...)
+{
+	va_list ap;
+	ast_mutex_lock(&qloglock);
+	if (qlog) {
+		va_start(ap, fmt);
+		fprintf(qlog, "%ld|%s|%s|%s|%s|", (long)time(NULL), callid, queuename, agent, event);
+		vfprintf(qlog, fmt, ap);
+		fprintf(qlog, "\n");
+		va_end(ap);
+		fflush(qlog);
+	}
+	ast_mutex_unlock(&qloglock);
+}
+
+static void queue_log_init(void)
+{
+	char filename[256];
+	int reloaded = 0;
+	ast_mutex_lock(&qloglock);
+	if (qlog) {
+		reloaded = 1;
+		fclose(qlog);
+		qlog = NULL;
+	}
+	snprintf(filename, sizeof(filename), "%s/%s", (char *)ast_config_AST_LOG_DIR, "queue_log");
+	qlog = fopen(filename, "a");
+	ast_mutex_unlock(&qloglock);
+	if (reloaded) 
+		ast_queue_log("NONE", "NONE", "NONE", "CONFIGRELOAD", "");
+	else
+		ast_queue_log("NONE", "NONE", "NONE", "QUEUESTART", "");
+}
+
 int reload_logger(int rotate)
 {
 	char old[AST_CONFIG_MAX_PATH];
@@ -294,6 +331,7 @@ int reload_logger(int rotate)
 		return 0;
 	} else 
 		ast_log(LOG_ERROR, "Unable to create event log: %s\n", strerror(errno));
+	queue_log_init();
 	init_logger_chain();
 	return -1;
 }