fix against corrupted output in parallel logging
[osmocom-bb.git] / src / logging.c
index fe782a6..948b2a6 100644 (file)
@@ -26,6 +26,7 @@
 #include <stdlib.h>
 #include <stdio.h>
 #include <string.h>
+#include <ctype.h>
 
 #ifdef HAVE_STRINGS_H
 #include <strings.h>
 #include <time.h>
 #include <errno.h>
 
-#include <osmocore/talloc.h>
-#include <osmocore/utils.h>
-#include <osmocore/logging.h>
+#include <osmocom/core/talloc.h>
+#include <osmocom/core/utils.h>
+#include <osmocom/core/logging.h>
 
-const struct log_info *osmo_log_info;
+#include <osmocom/vty/logging.h>       /* for LOGGING_STR. */
+
+struct log_info *osmo_log_info;
 
 static struct log_context log_context;
 static void *tall_log_ctx = NULL;
-static LLIST_HEAD(target_list);
+LLIST_HEAD(osmo_log_target_list);
+
+#define LOGLEVEL_DEFS  6       /* Number of loglevels.*/
 
-static const struct value_string loglevel_strs[] = {
+static const struct value_string loglevel_strs[LOGLEVEL_DEFS+1] = {
        { 0,            "EVERYTHING" },
        { LOGL_DEBUG,   "DEBUG" },
        { LOGL_INFO,    "INFO" },
@@ -53,6 +58,39 @@ static const struct value_string loglevel_strs[] = {
        { 0, NULL },
 };
 
+#define INT2IDX(x)     (-1*(x)-1)
+static const struct log_info_cat internal_cat[OSMO_NUM_DLIB] = {
+       [INT2IDX(DLGLOBAL)] = { /* -1 becomes 0 */
+               .name = "DLGLOBAL",
+               .description = "Library-internal global log family",
+               .loglevel = LOGL_NOTICE,
+               .enabled = 1,
+       },
+       [INT2IDX(DLLAPDM)] = {  /* -2 becomes 1 */
+               .name = "DLLAPDM",
+               .description = "LAPDm in libosmogsm",
+               .loglevel = LOGL_NOTICE,
+               .enabled = 1,
+       },
+};
+
+/* You have to keep this in sync with the structure loglevel_strs. */
+const char *loglevel_descriptions[LOGLEVEL_DEFS+1] = {
+       "Log simply everything",
+       "Log debug messages and higher levels",
+       "Log informational messages and higher levels",
+       "Log noticable messages and higher levels",
+       "Log error messages and higher levels",
+       "Log only fatal messages",
+       NULL,
+};
+
+/* special magic for negative (library-internal) log subsystem numbers */
+static int subsys_lib2index(int subsys)
+{
+       return (subsys * -1) + (osmo_log_info->num_cat_user-1);
+}
+
 int log_parse_level(const char *lvl)
 {
        return get_string_value(loglevel_strs, lvl);
@@ -68,6 +106,8 @@ int log_parse_category(const char *category)
        int i;
 
        for (i = 0; i < osmo_log_info->num_cat; ++i) {
+               if (osmo_log_info->cat[i].name == NULL)
+                       continue;
                if (!strcasecmp(osmo_log_info->cat[i].name+1, category))
                        return i;
        }
@@ -87,7 +127,7 @@ void log_parse_category_mask(struct log_target* target, const char *_mask)
        char *category_token = NULL;
 
        /* Disable everything to enable it afterwards */
-       for (i = 0; i < ARRAY_SIZE(target->categories); ++i)
+       for (i = 0; i < osmo_log_info->num_cat; ++i)
                target->categories[i].enabled = 0;
 
        category_token = strtok(mask, ":");
@@ -96,6 +136,9 @@ void log_parse_category_mask(struct log_target* target, const char *_mask)
                        char* colon = strstr(category_token, ",");
                        int length = strlen(category_token);
 
+                       if (!osmo_log_info->cat[i].name)
+                               continue;
+
                        if (colon)
                            length = colon - category_token;
 
@@ -124,32 +167,22 @@ static const char* color(int subsys)
 }
 
 static void _output(struct log_target *target, unsigned int subsys,
-                   char *file, int line, int cont, const char *format,
-                   va_list ap)
+                   unsigned int level, char *file, int line, int cont,
+                   const char *format, va_list ap)
 {
-       char col[30];
-       char sub[30];
-       char tim[30];
        char buf[4096];
-       char final[4096];
-
-       /* prepare the data */
-       col[0] = '\0';
-       sub[0] = '\0';
-       tim[0] = '\0';
-       buf[0] = '\0';
+       int ret, len = 0, offset = 0, rem = sizeof(buf);
 
        /* are we using color */
        if (target->use_color) {
                const char *c = color(subsys);
                if (c) {
-                       snprintf(col, sizeof(col), "%s", color(subsys));
-                       col[sizeof(col)-1] = '\0';
+                       ret = snprintf(buf + offset, rem, "%s", color(subsys));
+                       if (ret < 0)
+                               goto err;
+                       OSMO_SNPRINTF_RET(ret, rem, offset, len);
                }
        }
-       vsnprintf(buf, sizeof(buf), format, ap);
-       buf[sizeof(buf)-1] = '\0';
-
        if (!cont) {
                if (target->print_timestamp) {
                        char *timestr;
@@ -157,28 +190,47 @@ static void _output(struct log_target *target, unsigned int subsys,
                        tm = time(NULL);
                        timestr = ctime(&tm);
                        timestr[strlen(timestr)-1] = '\0';
-                       snprintf(tim, sizeof(tim), "%s ", timestr);
-                       tim[sizeof(tim)-1] = '\0';
+                       ret = snprintf(buf + offset, rem, "%s ", timestr);
+                       if (ret < 0)
+                               goto err;
+                       OSMO_SNPRINTF_RET(ret, rem, offset, len);
                }
-               snprintf(sub, sizeof(sub), "<%4.4x> %s:%d ", subsys, file, line);
-               sub[sizeof(sub)-1] = '\0';
+               ret = snprintf(buf + offset, rem, "<%4.4x> %s:%d ",
+                               subsys, file, line);
+               if (ret < 0)
+                       goto err;
+               OSMO_SNPRINTF_RET(ret, rem, offset, len);
        }
-
-       snprintf(final, sizeof(final), "%s%s%s%s%s", col, tim, sub, buf,
-                target->use_color ? "\033[0;m" : "");
-       final[sizeof(final)-1] = '\0';
-       target->output(target, final);
+       ret = vsnprintf(buf + offset, rem, format, ap);
+       if (ret < 0)
+               goto err;
+       OSMO_SNPRINTF_RET(ret, rem, offset, len);
+
+       ret = snprintf(buf + offset, rem, "%s",
+                       target->use_color ? "\033[0;m" : "");
+       if (ret < 0)
+               goto err;
+       OSMO_SNPRINTF_RET(ret, rem, offset, len);
+err:
+       buf[sizeof(buf)-1] = '\0';
+       target->output(target, level, buf);
 }
 
-
-static void _logp(unsigned int subsys, int level, char *file, int line,
+static void _logp(int subsys, int level, char *file, int line,
                  int cont, const char *format, va_list ap)
 {
        struct log_target *tar;
 
-       llist_for_each_entry(tar, &target_list, entry) {
+       if (subsys < 0)
+               subsys = subsys_lib2index(subsys);
+
+       if (subsys > osmo_log_info->num_cat)
+               subsys = DLGLOBAL;
+
+       llist_for_each_entry(tar, &osmo_log_target_list, entry) {
                struct log_category *category;
                int output = 0;
+               va_list bp;
 
                category = &tar->categories[subsys];
                /* subsystem is not supposed to be logged */
@@ -202,23 +254,19 @@ static void _logp(unsigned int subsys, int level, char *file, int line,
                else if (osmo_log_info->filter_fn)
                        output = osmo_log_info->filter_fn(&log_context,
                                                       tar);
+               if (!output)
+                       continue;
 
-               if (output) {
-                       /* FIXME: copying the va_list is an ugly
-                        * workaround against a bug hidden somewhere in
-                        * _output.  If we do not copy here, the first
-                        * call to _output() will corrupt the va_list
-                        * contents, and any further _output() calls
-                        * with the same va_list will segfault */
-                       va_list bp;
-                       va_copy(bp, ap);
-                       _output(tar, subsys, file, line, cont, format, bp);
-                       va_end(bp);
-               }
+               /* According to the manpage, vsnprintf leaves the value of ap
+                * in undefined state. Since _output uses vsnprintf and it may
+                * be called several times, we have to pass a copy of ap. */
+               va_copy(bp, ap);
+               _output(tar, subsys, level, file, line, cont, format, bp);
+               va_end(bp);
        }
 }
 
-void logp(unsigned int subsys, char *file, int line, int cont,
+void logp(int subsys, char *file, int line, int cont,
          const char *format, ...)
 {
        va_list ap;
@@ -228,7 +276,7 @@ void logp(unsigned int subsys, char *file, int line, int cont,
        va_end(ap);
 }
 
-void logp2(unsigned int subsys, unsigned int level, char *file, int line, int cont, const char *format, ...)
+void logp2(int subsys, unsigned int level, char *file, int line, int cont, const char *format, ...)
 {
        va_list ap;
 
@@ -239,7 +287,7 @@ void logp2(unsigned int subsys, unsigned int level, char *file, int line, int co
 
 void log_add_target(struct log_target *target)
 {
-       llist_add_tail(&target->entry, &target_list);
+       llist_add_tail(&target->entry, &osmo_log_target_list);
 }
 
 void log_del_target(struct log_target *target)
@@ -294,14 +342,12 @@ void log_set_category_filter(struct log_target *target, int category,
        target->categories[category].loglevel = level;
 }
 
-/* since C89/C99 says stderr is a macro, we can safely do this! */
-#ifdef stderr
-static void _file_output(struct log_target *target, const char *log)
+static void _file_output(struct log_target *target, unsigned int level,
+                        const char *log)
 {
        fprintf(target->tgt_file.out, "%s", log);
        fflush(target->tgt_file.out);
 }
-#endif
 
 struct log_target *log_target_create(void)
 {
@@ -312,6 +358,14 @@ struct log_target *log_target_create(void)
        if (!target)
                return NULL;
 
+       target->categories = talloc_zero_array(target, 
+                                               struct log_category,
+                                               osmo_log_info->num_cat);
+       if (!target->categories) {
+               talloc_free(target);
+               return NULL;
+       }
+
        INIT_LLIST_HEAD(&target->entry);
 
        /* initialize the per-category enabled/loglevel from defaults */
@@ -340,6 +394,7 @@ struct log_target *log_target_create_stderr(void)
        if (!target)
                return NULL;
 
+       target->type = LOG_TGT_TYPE_STDERR;
        target->tgt_file.out = stderr;
        target->output = _file_output;
        return target;
@@ -348,54 +403,247 @@ struct log_target *log_target_create_stderr(void)
 #endif /* stderr */
 }
 
-const char *log_vty_level_string(struct log_info *info)
+struct log_target *log_target_create_file(const char *fname)
+{
+       struct log_target *target;
+
+       target = log_target_create();
+       if (!target)
+               return NULL;
+
+       target->type = LOG_TGT_TYPE_FILE;
+       target->tgt_file.out = fopen(fname, "a");
+       if (!target->tgt_file.out)
+               return NULL;
+
+       target->output = _file_output;
+
+       target->tgt_file.fname = talloc_strdup(target, fname);
+
+       return target;
+}
+
+struct log_target *log_target_find(int type, const char *fname)
 {
-       const struct value_string *vs;
-       unsigned int len = 3; /* ()\0 */
+       struct log_target *tgt;
+
+       llist_for_each_entry(tgt, &osmo_log_target_list, entry) {
+               if (tgt->type != type)
+                       continue;
+               if (tgt->type == LOG_TGT_TYPE_FILE) {
+                       if (!strcmp(fname, tgt->tgt_file.fname))
+                               return tgt;
+               } else
+                       return tgt;
+       }
+       return NULL;
+}
+
+void log_target_destroy(struct log_target *target)
+{
+
+       /* just in case, to make sure we don't have any references */
+       log_del_target(target);
+
+       if (target->output == &_file_output) {
+/* since C89/C99 says stderr is a macro, we can safely do this! */
+#ifdef stderr
+               /* don't close stderr */
+               if (target->tgt_file.out != stderr)
+#endif
+               {
+                       fclose(target->tgt_file.out);
+                       target->tgt_file.out = NULL;
+               }
+       }
+
+       talloc_free(target);
+}
+
+/* close and re-open a log file (for log file rotation) */
+int log_target_file_reopen(struct log_target *target)
+{
+       fclose(target->tgt_file.out);
+
+       target->tgt_file.out = fopen(target->tgt_file.fname, "a");
+       if (!target->tgt_file.out)
+               return -errno;
+
+       /* we assume target->output already to be set */
+
+       return 0;
+}
+
+/* This generates the logging command string for VTY. */
+const char *log_vty_command_string(const struct log_info *unused_info)
+{
+       struct log_info *info = osmo_log_info;
+       int len = 0, offset = 0, ret, i, rem;
+       int size = strlen("logging level () ()") + 1;
        char *str;
 
-       for (vs = loglevel_strs; vs->value || vs->str; vs++)
-               len += strlen(vs->str) + 1;
+       for (i = 0; i < info->num_cat; i++) {
+               if (info->cat[i].name == NULL)
+                       continue;
+               size += strlen(info->cat[i].name) + 1;
+       }
+
+       for (i = 0; i < LOGLEVEL_DEFS; i++)
+               size += strlen(loglevel_strs[i].str) + 1;
 
-       str = talloc_zero_size(NULL, len);
+       rem = size;
+       str = talloc_zero_size(tall_log_ctx, size);
        if (!str)
                return NULL;
 
-       str[0] = '(';
-       for (vs = loglevel_strs; vs->value || vs->str; vs++) {
-               strcat(str, vs->str);
-               strcat(str, "|");
-       }
-       str[strlen(str)-1] = ')';
+       ret = snprintf(str + offset, rem, "logging level (all|");
+       if (ret < 0)
+               goto err;
+       OSMO_SNPRINTF_RET(ret, rem, offset, len);
 
+       for (i = 0; i < info->num_cat; i++) {
+               if (info->cat[i].name) {
+                       int j, name_len = strlen(info->cat[i].name)+1;
+                       char name[name_len];
+
+                       for (j = 0; j < name_len; j++)
+                               name[j] = tolower(info->cat[i].name[j]);
+
+                       name[name_len-1] = '\0';
+                       ret = snprintf(str + offset, rem, "%s|", name+1);
+                       if (ret < 0)
+                               goto err;
+                       OSMO_SNPRINTF_RET(ret, rem, offset, len);
+               }
+       }
+       offset--;       /* to remove the trailing | */
+       rem++;
+
+       ret = snprintf(str + offset, rem, ") (");
+       if (ret < 0)
+               goto err;
+       OSMO_SNPRINTF_RET(ret, rem, offset, len);
+
+       for (i = 0; i < LOGLEVEL_DEFS; i++) {
+               int j, loglevel_str_len = strlen(loglevel_strs[i].str)+1;
+               char loglevel_str[loglevel_str_len];
+
+               for (j = 0; j < loglevel_str_len; j++)
+                       loglevel_str[j] = tolower(loglevel_strs[i].str[j]);
+
+               loglevel_str[loglevel_str_len-1] = '\0';
+               ret = snprintf(str + offset, rem, "%s|", loglevel_str);
+               if (ret < 0)
+                       goto err;
+               OSMO_SNPRINTF_RET(ret, rem, offset, len);
+       }
+       offset--;       /* to remove the trailing | */
+       rem++;
+
+       ret = snprintf(str + offset, rem, ")");
+       if (ret < 0)
+               goto err;
+       OSMO_SNPRINTF_RET(ret, rem, offset, len);
+err:
+       str[size-1] = '\0';
        return str;
 }
 
-const char *log_vty_category_string(struct log_info *info)
+/* This generates the logging command description for VTY. */
+const char *log_vty_command_description(const struct log_info *unused_info)
 {
-       unsigned int len = 3;   /* "()\0" */
-       unsigned int i;
+       struct log_info *info = osmo_log_info;
        char *str;
+       int i, ret, len = 0, offset = 0, rem;
+       unsigned int size =
+               strlen(LOGGING_STR
+                      "Set the log level for a specified category\n") + 1;
+
+       for (i = 0; i < info->num_cat; i++) {
+               if (info->cat[i].name == NULL)
+                       continue;
+               size += strlen(info->cat[i].description) + 1;
+       }
 
-       for (i = 0; i < info->num_cat; i++)
-               len += strlen(info->cat[i].name) + 1;
+       for (i = 0; i < LOGLEVEL_DEFS; i++)
+               size += strlen(loglevel_descriptions[i]) + 1;
 
-       str = talloc_zero_size(NULL, len);
+       size += strlen("Global setting for all subsystems") + 1;
+       rem = size;
+       str = talloc_zero_size(tall_log_ctx, size);
        if (!str)
                return NULL;
 
-       str[0] = '(';
+       ret = snprintf(str + offset, rem, LOGGING_STR
+                       "Set the log level for a specified category\n");
+       if (ret < 0)
+               goto err;
+       OSMO_SNPRINTF_RET(ret, rem, offset, len);
+
+       ret = snprintf(str + offset, rem,
+                       "Global setting for all subsystems\n");
+       if (ret < 0)
+               goto err;
+       OSMO_SNPRINTF_RET(ret, rem, offset, len);
+
        for (i = 0; i < info->num_cat; i++) {
-               strcat(str, info->cat[i].name+1);
-               strcat(str, "|");
+               if (info->cat[i].name == NULL)
+                       continue;
+               ret = snprintf(str + offset, rem, "%s\n",
+                               info->cat[i].description);
+               if (ret < 0)
+                       goto err;
+               OSMO_SNPRINTF_RET(ret, rem, offset, len);
        }
-       str[strlen(str)-1] = ')';
-
+       for (i = 0; i < LOGLEVEL_DEFS; i++) {
+               ret = snprintf(str + offset, rem, "%s\n",
+                               loglevel_descriptions[i]);
+               if (ret < 0)
+                       goto err;
+               OSMO_SNPRINTF_RET(ret, rem, offset, len);
+       }
+err:
+       str[size-1] = '\0';
        return str;
 }
 
-void log_init(const struct log_info *cat)
+int log_init(const struct log_info *inf, void *ctx)
 {
-       tall_log_ctx = talloc_named_const(NULL, 1, "logging");
-       osmo_log_info = cat;
+       int i;
+
+       tall_log_ctx = talloc_named_const(ctx, 1, "logging");
+       if (!tall_log_ctx)
+               return -ENOMEM;
+
+       osmo_log_info = talloc_zero(tall_log_ctx, struct log_info);
+       if (!osmo_log_info)
+               return -ENOMEM;
+
+       osmo_log_info->num_cat_user = inf->num_cat;
+       /* total number = number of user cat + library cat */
+       osmo_log_info->num_cat = inf->num_cat + ARRAY_SIZE(internal_cat);
+
+       osmo_log_info->cat = talloc_zero_array(osmo_log_info,
+                                       struct log_info_cat,
+                                       osmo_log_info->num_cat);
+       if (!osmo_log_info->cat) {
+               talloc_free(osmo_log_info);
+               osmo_log_info = NULL;
+               return -ENOMEM;
+       }
+
+       /* copy over the user part */
+       for (i = 0; i < inf->num_cat; i++) {
+               memcpy(&osmo_log_info->cat[i], &inf->cat[i],
+                       sizeof(struct log_info_cat));
+       }
+
+       /* copy over the library part */
+       for (i = 0; i < ARRAY_SIZE(internal_cat); i++) {
+               unsigned int cn = osmo_log_info->num_cat_user + i;
+               memcpy(&osmo_log_info->cat[cn],
+                       &internal_cat[i], sizeof(struct log_info_cat));
+       }
+
+       return 0;
 }