Add queue logging and fix indications buglet
authorMark Spencer <markster@digium.com>
Thu, 12 Feb 2004 22:11:02 +0000 (22:11 +0000)
committerMark Spencer <markster@digium.com>
Thu, 12 Feb 2004 22:11:02 +0000 (22:11 +0000)
git-svn-id: https://origsvn.digium.com/svn/asterisk/trunk@2159 65c4cc65-6c06-0410-ace0-fbb531ad65f3

apps/app_queue.c
doc/queuelog.txt [new file with mode: 0755]
include/asterisk/logger.h
indications.c
logger.c

index e5e4841..1f28aa6 100755 (executable)
@@ -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;
                                }
diff --git a/doc/queuelog.txt b/doc/queuelog.txt
new file mode 100755 (executable)
index 0000000..fc93d24
--- /dev/null
@@ -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.
+
index c2598b4..e0d3f5a 100755 (executable)
@@ -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.
index 4632f69..fefec91 100755 (executable)
@@ -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);
 }
 
index a4f2bd3..af3bf50 100755 (executable)
--- a/logger.c
+++ b/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;
 }