Add the JSON format to dlogutil 78/210478/9
authorMateusz Majewski <m.majewski2@samsung.com>
Wed, 10 Jul 2019 13:11:08 +0000 (15:11 +0200)
committerHyotaek Shim <hyotaek.shim@samsung.com>
Mon, 29 Jul 2019 02:43:17 +0000 (02:43 +0000)
Change-Id: I10600b919c73d4279f34721a0a3e0bf7efc425a5

include/logprint.h
src/logutil/logutil_doc.h
src/shared/logprint.c
src/tests/logprint.c

index b4e4e29..ec1d6d1 100644 (file)
@@ -43,6 +43,7 @@ typedef enum {
        FORMAT_RECV_REALTIME,
        FORMAT_RWTIME,
        FORMAT_LONG,
+       FORMAT_JSON,
 } log_print_format;
 
 typedef struct log_format_t log_format;
index add231d..5175d89 100644 (file)
@@ -93,6 +93,13 @@ static void show_help(const char *cmd, bool requested_by_user)
                "                    much sense (usually shows dates in January 1970).\n"
                "                    The most reliable choices are 'rwtime' and 'recv_realtime',\n"
                "                    but the default is 'brief' for legacy reasons.\n"
+               "                    Additionally, a 'json' format is supported, in which\n"
+               "                    each log becomes a line with a JSON object containing\n"
+               "                    the following fields: 'priority' (string), 'tid' (number),\n"
+               "                    'pid' (number), 'recv_real' (string), 'recv_mono' (number),\n"
+               "                    'sent_real' (string), 'sent_mono' (number), 'tag' (string)\n"
+               "                    and 'msg' (string). Note that some of the timestamps\n"
+               "                    can be missing, but at least one will be available.\n"
                "filterspecs are a series of\n<tag>[*][:priority]\n and \n<prefix>*[:=priority]\n"
                "where <tag> is a log component tag\n"
                "<prefix>* matches all log component tags starting with the prefix\n"
index dd411d5..efea3f2 100644 (file)
@@ -392,6 +392,7 @@ log_print_format log_format_from_string(const char *formatString)
                {"recv_realtime", FORMAT_RECV_REALTIME},
                {"rwtime"       , FORMAT_RWTIME       },
                {"long"         , FORMAT_LONG         },
+               {"json"         , FORMAT_JSON         },
        };
 
        for (size_t i = 0; i < NELEMS(formats); ++i)
@@ -615,7 +616,8 @@ enum sorting_order get_format_sorting(const log_format *format)
 #define COLOR_YELLOW "\033[33;1m"
 #define COLOR_RESET  "\033[0m"
 
-static const char *get_pre_color(log_priority pri, bool enabled) {
+static const char *get_pre_color(log_priority pri, bool enabled)
+{
        if (!enabled)
                return "";
        switch (pri) {
@@ -630,7 +632,8 @@ static const char *get_pre_color(log_priority pri, bool enabled) {
        }
 }
 
-static const char *get_post_color(log_priority pri, bool enabled) {
+static const char *get_post_color(log_priority pri, bool enabled)
+{
        if (!enabled)
                return "";
        switch (pri) {
@@ -643,6 +646,204 @@ static const char *get_post_color(log_priority pri, bool enabled) {
        }
 }
 
+static char to_hex_digit(int digit)
+{
+       assert(digit >= 0);
+       assert(digit < 16);
+       if (digit < 10)
+               return digit + '0';
+       else
+               return digit + 'A' - 10;
+}
+
+char *json_escape_string(char *in)
+{
+       assert(in);
+       size_t len = strlen(in);
+       /* One input string character will be encoded by max 6 characters in the output string.
+        * We use unsigned chars for easy comparisions. */
+       unsigned char *buf = malloc(6 * len + 1);
+       if (!buf)
+               return NULL;
+
+       /* So, RFC 7159 says that JSON output can be in one of three encodings: UTF-{8,16,32}.
+        * In particular, in UTF-8, the multibyte characters are allowed. This means that, assuming
+        * that our input is valid UTF-8, we can just write them directly, simplifying the implementation.
+        * Correctly encoding arbitrary binary data would require something like base64, this, however,
+        * would make it very difficult to read by humans. Almost all logs are UTF-8 anyway. */
+       int targ = 0;
+       for (int i = 0; i < len; ++i) {
+               unsigned char c = in[i];
+               switch (c) {
+               /* These cases can get nicer encodings than the usual "\uxxxx", even though we technically
+                * dont have to do so. Also, we don't encode '/', because there is no reason to. */
+               case '\"':
+                       buf[targ++] = '\\';
+                       buf[targ++] = '\"';
+                       break;
+               case '\\':
+                       buf[targ++] = '\\';
+                       buf[targ++] = '\\';
+                       break;
+               case '\b':
+                       buf[targ++] = '\\';
+                       buf[targ++] = 'b';
+                       break;
+               case '\f':
+                       buf[targ++] = '\\';
+                       buf[targ++] = 'f';
+                       break;
+               case '\n':
+                       buf[targ++] = '\\';
+                       buf[targ++] = 'n';
+                       break;
+               case '\r':
+                       buf[targ++] = '\\';
+                       buf[targ++] = 'r';
+                       break;
+               case '\t':
+                       buf[targ++] = '\\';
+                       buf[targ++] = 't';
+                       break;
+               default:
+                       /* We don't use a range case, because we would have to remove the already done characters from it.
+                        * We would end up with three distinct cases for the {0, ..., 31} interval. */
+                       if (c <= 31) {
+                               buf[targ++] = '\\';
+                               buf[targ++] = 'u';
+                               buf[targ++] = '0';
+                               buf[targ++] = '0';
+                               buf[targ++] = to_hex_digit(c / 16);
+                               buf[targ++] = to_hex_digit(c % 16);
+                       }
+                       else
+                               buf[targ++] = c;
+                       break;
+               }
+       }
+       buf[targ++] = '\0';
+
+       char *ret = realloc(buf, targ);
+       if (!ret)
+               free(buf);
+       return ret;
+}
+
+const char *json_priority_name(log_priority prio)
+{
+       static const char *const json_priorities_map[] = {
+               [DLOG_VERBOSE] = "verbose",
+               [DLOG_DEBUG]   = "debug",
+               [DLOG_INFO]    = "info",
+               [DLOG_WARN]    = "warning",
+               [DLOG_ERROR]   = "error",
+               [DLOG_FATAL]   = "fatal",
+               [DLOG_SILENT]  = "silent",
+       };
+
+       const char *ret = NULL;
+       if (prio < NELEMS(json_priorities_map))
+               ret = json_priorities_map[prio];
+       if (!ret) // Either out of the map, or in between its elements
+               ret = "unknown";
+       return ret;
+}
+
+static char *log_format_json(
+               char *default_buffer,
+               size_t default_buffer_size,
+               const struct logger_entry *entry,
+               size_t *p_outLength,
+               char *tag,
+               char *msg)
+{
+       const char *prio_name = json_priority_name(entry->priority);
+
+       __attribute__((cleanup(free_ptr))) char *tag_esc = json_escape_string(tag);
+       if (tag_esc == NULL)
+               return NULL;
+
+       __attribute__((cleanup(free_ptr))) char *msg_esc = json_escape_string(msg);
+       if (msg_esc == NULL)
+               return NULL;
+
+       char recv_real[64], recv_mono[64], sent_real[64], sent_mono[64];
+#if defined(HAVE_LOCALTIME_R)
+       struct tm tmBuf;
+#endif
+       struct tm* ptm;
+
+       if (entry->nsec_recv_real == INVALID_NSEC)
+               recv_real[0] = '\0';
+       else {
+#if defined(HAVE_LOCALTIME_R)
+               ptm = localtime_r((const time_t*)&entry->sec_recv_real, &tmBuf);
+#else
+               ptm = localtime((const time_t*)&entry->sec_recv_real);
+#endif
+               strftime(recv_real, sizeof recv_real, "\"recv_real\":\"%FT%T%z\",", ptm);
+       }
+
+       if (entry->nsec_sent_real == INVALID_NSEC)
+               sent_real[0] = '\0';
+       else {
+#if defined(HAVE_LOCALTIME_R)
+               ptm = localtime_r((const time_t*)&entry->sec_sent_real, &tmBuf);
+#else
+               ptm = localtime((const time_t*)&entry->sec_sent_real);
+#endif
+               strftime(sent_real, sizeof sent_real, "\"sent_real\":\"%FT%T%z\",", ptm);
+       }
+
+       if (entry->nsec_recv_mono == INVALID_NSEC)
+               recv_mono[0] = '\0';
+       else
+               snprintf(recv_mono, sizeof recv_mono, "\"recv_mono\":%d.%.9d,", entry->sec_recv_mono, entry->nsec_recv_mono);
+
+       if (entry->nsec_sent_mono == INVALID_NSEC)
+               sent_mono[0] = '\0';
+       else
+               snprintf(sent_mono, sizeof sent_mono, "\"sent_mono\":%d.%.9d,", entry->sec_sent_mono, entry->nsec_sent_mono);
+
+#define ARGS "{" \
+               "\"priority\":\"%s\"," \
+               "\"pid\":%d," \
+               "\"tid\":%d," \
+               "%s%s%s%s" \
+               "\"tag\":\"%s\"," \
+               "\"msg\":\"%s\"" \
+               "}\n", prio_name, entry->pid, entry->tid, \
+               recv_real, recv_mono, sent_real, sent_mono, \
+               tag_esc, msg_esc
+
+       int len = snprintf(NULL, 0, ARGS);
+
+       char *ret;
+       if (len < 0)
+               return NULL;
+       else if (default_buffer_size >= len + 1) {
+               ret = default_buffer;
+       } else {
+               ret = (char *)malloc(len + 1);
+
+               if (ret == NULL)
+                       return NULL;
+       }
+
+       int res = snprintf(ret, len + 1, ARGS);
+
+#undef ARGS
+
+       if (res <= 0) {
+               if (ret != default_buffer)
+                       free(ret);
+               return NULL;
+       }
+
+       *p_outLength = len;
+       return ret;
+}
+
 /**
  * @brief Format log line
  * @details Formats a log entry for direct printing
@@ -684,6 +885,15 @@ char *log_format_log_line(
        msg = log_buffer_get_message(entry) ?: "DLOG_ERROR_NOMSG";
 
        /*
+        * JSON is formatted separately. This is because it's so vastly different
+        * to the other formats, it even contains different data.
+        * Also, currently in other formats the data before and after the message
+        * is limited in length. This would make JSON impossible to implement in a good way.
+        */
+       if (p_format->format == FORMAT_JSON)
+               return log_format_json(defaultBuffer, defaultBufferSize, entry, p_outLength, tag, msg);
+
+       /*
         * Get the current date/time in pretty form
         *
         * It's often useful when examining a log with "less" to jump to
index 0b694ad..4afed4f 100644 (file)
@@ -329,6 +329,40 @@ void check_log_print_log_line()
        CHECK_LOGPRINT_TESTCASES("THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTH\0foo1\nfoo2", tests_long_metadata);
 }
 
+char *json_escape_string(char *in);
+void check_json_escape_string_testcase(char *in, char *correct)
+{
+       char *out = json_escape_string(in);
+       assert(out);
+       assert(!strcmp(out, correct));
+       free(out);
+}
+
+const char *json_priority_name(log_priority prio);
+void check_json()
+{
+       // TODO: Failure testing, JSON formatting testing (when the format is complete)
+       check_json_escape_string_testcase("abc/def", "abc/def");
+       check_json_escape_string_testcase("\x01\x02\x03", "\\u0001\\u0002\\u0003");
+       check_json_escape_string_testcase("\x1A\x1B\x1C", "\\u001A\\u001B\\u001C");
+       check_json_escape_string_testcase("\x1D\x1E\x1F", "\\u001D\\u001E\\u001F");
+       check_json_escape_string_testcase("\"\\\b\f\n\r\t", "\\\"\\\\\\b\\f\\n\\r\\t");
+       check_json_escape_string_testcase("zażółć gęślą jaźń", "zażółć gęślą jaźń");
+       check_json_escape_string_testcase("삼성", "삼성");
+       check_json_escape_string_testcase("タイゼン", "タイゼン");
+       check_json_escape_string_testcase("🏀", "🏀");
+
+       assert(!strcmp(json_priority_name(DLOG_VERBOSE), "verbose"));
+       assert(!strcmp(json_priority_name(DLOG_DEBUG),   "debug"));
+       assert(!strcmp(json_priority_name(DLOG_INFO),    "info"));
+       assert(!strcmp(json_priority_name(DLOG_WARN),    "warning"));
+       assert(!strcmp(json_priority_name(DLOG_ERROR),   "error"));
+       assert(!strcmp(json_priority_name(DLOG_FATAL),   "fatal"));
+       assert(!strcmp(json_priority_name(DLOG_SILENT),  "silent"));
+       assert(!strcmp(json_priority_name(DLOG_UNKNOWN), "unknown"));
+       assert(!strcmp(json_priority_name(123),          "unknown"));
+}
+
 void check_isatty_detection_testcase(bool enable_colors)
 {
        struct logger_entry_with_msg entry;
@@ -557,5 +591,6 @@ int main()
        check_invalid_input();
        check_syscall_failure_handling();
        check_isatty_detection();
+       check_json();
 }