sphinx: better logging and verbosity handling
authorKrisztian Litkey <kli@iki.fi>
Sun, 25 May 2014 22:16:55 +0000 (01:16 +0300)
committerKrisztian Litkey <krisztian.litkey@intel.com>
Wed, 4 Jun 2014 12:57:34 +0000 (15:57 +0300)
Allow sphinx verbosity and logfile to be controlled by the
sphinx.verbose boolean and sphinx.log string keys. Also if
sphinx.log is set to 'srs', turn verbosity on and log sphinx
messages as murphy debug messages. sphinx warnings are turned
into murphy warnings and the rest (errors, critical errors
and fatal errors) are turned into murphy error messages.

Because we only get the originating file name and the line
number but not the function name where the message was
generated we have to cheat a bit and use 'sphinx' as the file
name and the file name as the originating function name. As a
consequence, you can see all sphinx INFO messages as murphy
debug messages by using the -d @sphinx command line option if
you have set sphinx.log to 'srs' in the config file (or have
passed -s 'sphinx.log=srs' to the daemon on the command line).

src/Makefile.am
src/plugins/speech-to-text/sphinx/decoder-set.c
src/plugins/speech-to-text/sphinx/logger.c [new file with mode: 0644]
src/plugins/speech-to-text/sphinx/logger.h [new file with mode: 0644]
src/plugins/speech-to-text/sphinx/options.c
src/plugins/speech-to-text/sphinx/sphinx-plugin.c
src/plugins/speech-to-text/sphinx/sphinx-plugin.h

index ed95c0b..fdf45f5 100644 (file)
@@ -186,9 +186,10 @@ plugin_sphinx_speech_la_SOURCES =                          \
                plugins/speech-to-text/sphinx/pulse-interface.c \
                plugins/speech-to-text/sphinx/input-buffer.c    \
                plugins/speech-to-text/sphinx/filter-buffer.c   \
-               plugins/speech-to-text/sphinx/utterance.c             \
+               plugins/speech-to-text/sphinx/utterance.c       \
                plugins/speech-to-text/sphinx/decoder-set.c     \
-               plugins/speech-to-text/sphinx/options.c
+               plugins/speech-to-text/sphinx/options.c         \
+               plugins/speech-to-text/sphinx/logger.c
 
 plugin_sphinx_speech_la_CFLAGS  =                      \
                $(AM_CFLAGS)                            \
index 4ccc458..26a64a9 100644 (file)
@@ -16,8 +16,7 @@
 #include "decoder-set.h"
 #include "options.h"
 #include "utterance.h"
-
-
+#include "logger.h"
 
 
 int decoder_set_create(context_t *ctx)
@@ -147,10 +146,17 @@ int decoder_set_add(context_t *ctx, const char *decoder_name,
     cmd_ln_set_str_r(cfg, "-dict", dict);
     cmd_ln_set_int_r(cfg, "-topn", topn);
     cmd_ln_set_float_r(cfg, "-samprate", (double)opts->rate);
-    cmd_ln_set_boolean_r(cfg, "-verbose", ctx->verbose);
+    cmd_ln_set_boolean_r(cfg, "-verbose",
+                         (ctx->verbose || opts->logfn != NULL) ? true : false);
 
-    if (opts->logfn)
-        cmd_ln_set_str_r(cfg, "-logfn", opts->logfn);
+    if (opts->logfn != NULL) {
+        if (strcmp(opts->logfn, "srs"))
+            cmd_ln_set_str_r(cfg, "-logfn", opts->logfn);
+    }
+    else {
+        if (ctx->verbose)
+            err_set_logfp(stdout);
+    }
 
     if (fsg)
         cmd_ln_set_str_r(cfg, "-fsg", fsg);
diff --git a/src/plugins/speech-to-text/sphinx/logger.c b/src/plugins/speech-to-text/sphinx/logger.c
new file mode 100644 (file)
index 0000000..094a122
--- /dev/null
@@ -0,0 +1,191 @@
+#include <stdio.h>
+#include <unistd.h>
+#define __USE_GNU                        /* F_SETPIPE_SZ */
+#include <fcntl.h>
+#include <string.h>
+#include <errno.h>
+
+#include <murphy/common/log.h>
+#include <murphy/common/mainloop.h>
+
+#include "sphinx-plugin.h"
+
+#define SPHINX_INFO   "INFO: "
+#define SPHINX_ERROR  "ERROR: "
+#define SPHINX_WARN   "WARNING: "
+#define SPHINX_SYSERR "SYSTEM_ERROR: "
+#define SPHINX_FATAL  "FATAL_ERROR: "
+
+#define RD 0
+#define WR 1
+
+typedef struct {
+    int             fd[2];               /* log message pipe */
+    FILE           *fp;                  /* log write stream */
+    mrp_io_watch_t *w;                   /* log I/O watch */
+    char            buf[4096];           /* log line buffer */
+    ssize_t         n;
+} logger_t;
+
+
+static ssize_t pull_log(logger_t *logger)
+{
+    char    *p;
+    ssize_t  n, l;
+
+    p = logger->buf + logger->n;
+    l = sizeof(logger->buf) - logger->n - 1;
+
+    n = read(logger->fd[RD], p, l);
+
+    if (n <= 0)
+        return n;
+
+    p[n] = '\0';
+    logger->n += n;
+
+    return logger->n;
+}
+
+
+static void push_log(logger_t *logger)
+{
+    char    *b, *e, *lb, *le, *file, lvl, name[1024];
+    int      line, len, nlen;
+    ssize_t  n;
+
+    name[sizeof(name) - 1] = '\0';
+
+    lvl  = 0;
+    file = NULL;
+
+    while (logger->n > 0) {
+        b = logger->buf;
+
+        if (!strncmp(b, SPHINX_INFO  , len = sizeof(SPHINX_INFO  ) - 1) ||
+            !strncmp(b, SPHINX_WARN  , len = sizeof(SPHINX_WARN  ) - 1) ||
+            !strncmp(b, SPHINX_ERROR , len = sizeof(SPHINX_ERROR ) - 1) ||
+            !strncmp(b, SPHINX_SYSERR, len = sizeof(SPHINX_SYSERR) - 1) ||
+            !strncmp(b, SPHINX_FATAL , len = sizeof(SPHINX_FATAL ) - 1)) {
+            lvl  = *b;
+            b   += len;
+            lb  = strchr(b, '(');
+        }
+        else
+            lvl = 0;
+
+        if ((e = strchr(b, '\n')) == NULL) {
+            if (logger->n >= sizeof(logger->buf) - 1) {
+                mrp_log_warning("Discarding too long sphinx log buffer.");
+                logger->n = 0;
+            }
+            return;
+        }
+
+        if (lb != NULL) {
+            line = (int)strtoul(lb + 1, &le, 10);
+
+            if (lb != NULL && *le == ')') {
+                nlen = lb - b;
+                snprintf(name, sizeof(name) - 1, "%*.*s", nlen, nlen, b);
+                file = name;
+                b = le + 1;
+                if (b[0] == ':' && b[1] == ' ')
+                    b += 2;
+            }
+        }
+        else {
+            if (file == NULL)
+                file = "<unknown-file>";
+        }
+
+        n = e - b;
+
+        switch (lvl) {
+        case 'I':
+        default:
+            mrp_debug_at("sphinx", line, file, "%*.*s", n, n, b);
+            break;
+        case 'W':
+            mrp_log_msg(MRP_LOG_WARNING, file, line, "sphinx", "%*.*s", n, n, b);
+            break;
+        case 'E':
+        case 'S':
+        case 'F':
+            mrp_log_msg(MRP_LOG_ERROR, file, line, "sphinx", "%*.*s", n, n, b);
+            break;
+        }
+
+        b = e + 1;
+        n = logger->n - (b - logger->buf);
+
+        if (n <= 0)
+            logger->n = 0;
+        else {
+            memmove(logger->buf, b, n);
+            logger->n = n;
+            logger->buf[n] = '\0';
+        }
+    }
+}
+
+
+static void log_cb(mrp_io_watch_t *w, int fd, mrp_io_event_t events,
+                   void *user_data)
+{
+    logger_t *logger = (logger_t *)user_data;
+
+    MRP_UNUSED(fd);
+
+    if (events & MRP_IO_EVENT_IN)
+        while (pull_log(logger) > 0)
+            push_log(logger);
+
+    if (events & MRP_IO_EVENT_HUP)
+        mrp_del_io_watch(w);
+}
+
+
+FILE *logger_create(context_t *ctx)
+{
+    static logger_t  logger = { { -1, -1 }, NULL, 0 };
+    mrp_mainloop_t  *ml     = plugin_get_mainloop(ctx->plugin);
+    mrp_io_event_t   events = MRP_IO_EVENT_IN | MRP_IO_EVENT_HUP;
+
+    if (logger.fp != NULL)
+        return logger.fp;
+
+    if (pipe(logger.fd) < 0) {
+        mrp_log_error("Failed to create sphinx logging pipe (error %d: %s).",
+                      errno, strerror(errno));
+        goto fail;
+    }
+
+    if ((logger.fp = fdopen(logger.fd[WR], "w")) == NULL)
+        goto fail;
+
+    setvbuf(logger.fp, NULL, _IOLBF, 0);
+
+    fcntl(logger.fd[WR], F_SETPIPE_SZ, 512 * 1024);
+    fcntl(logger.fd[WR], F_SETFL, O_NONBLOCK);
+    fcntl(logger.fd[RD], F_SETFL, O_NONBLOCK);
+
+    logger.w = mrp_add_io_watch(ml, logger.fd[RD], events, log_cb, &logger);
+
+    if (logger.w != NULL)
+        return logger.fp;
+
+    /* fallthru */
+
+ fail:
+    close(logger.fd[0]);
+    close(logger.fd[1]);
+    if (logger.fp != NULL)
+        fclose(logger.fp);
+
+    logger.fd[0] = -1;
+    logger.fd[1] = -1;
+    logger.fp = NULL;
+
+    return NULL;
+}
diff --git a/src/plugins/speech-to-text/sphinx/logger.h b/src/plugins/speech-to-text/sphinx/logger.h
new file mode 100644 (file)
index 0000000..d6a7b15
--- /dev/null
@@ -0,0 +1,8 @@
+#ifndef __SRS_POCKET_SPHINX_LOGGER_H__
+#define __SRS_POCKET_SPHINX_LOGGER_H__
+
+#include "sphinx-plugin.h"
+
+FILE *logger_create(context_t *ctx);
+
+#endif /* __SRS_POCKET_SPHINX_LOGGER_H__ */
index e1bf358..327e3f7 100644 (file)
@@ -4,9 +4,12 @@
 #include <string.h>
 #include <errno.h>
 
+#include <sphinxbase/err.h>
+
 #include <murphy/common/mm.h>
 #include <murphy/common/log.h>
 
+#include "logger.h"
 #include "options.h"
 
 #define DEFAULT_HMM  "/usr/share/pocketsphinx/model/hmm/en_US/hub4wsj_sc_8k"
@@ -99,6 +102,14 @@ int options_create(context_t *ctx, int ncfg, srs_cfg_t *cfgs)
                     mrp_free((void *)decs->lm);
                     decs->lm = mrp_strdup(value);
                 }
+                else if (!strcmp(key, "log")) {
+                    mrp_log_info("Redirecting sphinx logs to '%s'.", value);
+                    mrp_free((void *)opts->logfn);
+                    opts->logfn = mrp_strdup(value);
+
+                    if (!strcmp(opts->logfn, "srs"))
+                        err_set_logfp(logger_create(ctx));
+                }
                 break;
 
             case 'p':
@@ -139,6 +150,20 @@ int options_create(context_t *ctx, int ncfg, srs_cfg_t *cfgs)
                 }
                 break;
 
+            case 'v':
+                if (!strcmp(key, "verbose")) {
+                    if (!strcmp(value, "true") ||
+                        !strcmp(value, "on") ||
+                        !strcmp(value, "yes"))
+                        ctx->verbose = verbose = true;
+                    else
+                        ctx->verbose = verbose = false;
+
+                    mrp_log_info("Sphinx verbosity turned %s", verbose ?
+                                 "on" : "off");
+                }
+                break;
+
             default:
                 // cfg->used = FALSE;
                 break;
index df69730..50bc0e7 100644 (file)
@@ -55,6 +55,12 @@ struct plugin_s {
 };
 
 
+mrp_mainloop_t *plugin_get_mainloop(plugin_t *plugin)
+{
+    return plugin->self->srs->ml;
+}
+
+
 int32_t plugin_utterance_handler(context_t *ctx, srs_srec_utterance_t *utt)
 {
     plugin_t *pl;
index 93ffe6f..426247e 100644 (file)
@@ -41,7 +41,7 @@ struct context_s {
 
 
 int32_t plugin_utterance_handler(context_t *ctx, srs_srec_utterance_t *utt);
-
+mrp_mainloop_t *plugin_get_mainloop(plugin_t *plugin);
 
 #endif /* __SRS_POCKET_SPHINX_PLUGIN_H__ */