From f97e6767bbda21d25eaeb77f69148085c282b557 Mon Sep 17 00:00:00 2001 From: Krisztian Litkey Date: Mon, 26 May 2014 01:16:55 +0300 Subject: [PATCH] sphinx: better logging and verbosity handling 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 | 5 +- src/plugins/speech-to-text/sphinx/decoder-set.c | 16 +- src/plugins/speech-to-text/sphinx/logger.c | 191 ++++++++++++++++++++++ src/plugins/speech-to-text/sphinx/logger.h | 8 + src/plugins/speech-to-text/sphinx/options.c | 25 +++ src/plugins/speech-to-text/sphinx/sphinx-plugin.c | 6 + src/plugins/speech-to-text/sphinx/sphinx-plugin.h | 2 +- 7 files changed, 245 insertions(+), 8 deletions(-) create mode 100644 src/plugins/speech-to-text/sphinx/logger.c create mode 100644 src/plugins/speech-to-text/sphinx/logger.h diff --git a/src/Makefile.am b/src/Makefile.am index ed95c0b..fdf45f5 100644 --- a/src/Makefile.am +++ b/src/Makefile.am @@ -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) \ diff --git a/src/plugins/speech-to-text/sphinx/decoder-set.c b/src/plugins/speech-to-text/sphinx/decoder-set.c index 4ccc458..26a64a9 100644 --- a/src/plugins/speech-to-text/sphinx/decoder-set.c +++ b/src/plugins/speech-to-text/sphinx/decoder-set.c @@ -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 index 0000000..094a122 --- /dev/null +++ b/src/plugins/speech-to-text/sphinx/logger.c @@ -0,0 +1,191 @@ +#include +#include +#define __USE_GNU /* F_SETPIPE_SZ */ +#include +#include +#include + +#include +#include + +#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 = ""; + } + + 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 index 0000000..d6a7b15 --- /dev/null +++ b/src/plugins/speech-to-text/sphinx/logger.h @@ -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__ */ diff --git a/src/plugins/speech-to-text/sphinx/options.c b/src/plugins/speech-to-text/sphinx/options.c index e1bf358..327e3f7 100644 --- a/src/plugins/speech-to-text/sphinx/options.c +++ b/src/plugins/speech-to-text/sphinx/options.c @@ -4,9 +4,12 @@ #include #include +#include + #include #include +#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; diff --git a/src/plugins/speech-to-text/sphinx/sphinx-plugin.c b/src/plugins/speech-to-text/sphinx/sphinx-plugin.c index df69730..50bc0e7 100644 --- a/src/plugins/speech-to-text/sphinx/sphinx-plugin.c +++ b/src/plugins/speech-to-text/sphinx/sphinx-plugin.c @@ -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; diff --git a/src/plugins/speech-to-text/sphinx/sphinx-plugin.h b/src/plugins/speech-to-text/sphinx/sphinx-plugin.h index 93ffe6f..426247e 100644 --- a/src/plugins/speech-to-text/sphinx/sphinx-plugin.h +++ b/src/plugins/speech-to-text/sphinx/sphinx-plugin.h @@ -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__ */ -- 2.7.4