Add nanoseconds to JSON realtime timestamps

Change-Id: Ic8d60d148bd88514f9342bac82c1477383bb0f6e

diff --git a/src/logutil/logutil_doc.h b/src/logutil/logutil_doc.h
index 1b6c3e1..1c0179f 100644 (file)
--- a/src/logutil/logutil_doc.h
+++ b/src/logutil/logutil_doc.h
@@ -106,10 +106,7 @@ static void show_help(const char *cmd, bool requested_by_user)
                "                    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"
+               "                    various fields describing the log. 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"

diff --git a/src/shared/logprint.c b/src/shared/logprint.c
index 81fb8f4..ba9e393 100644 (file)
--- a/src/shared/logprint.c
+++ b/src/shared/logprint.c
@@ -744,28 +744,34 @@ char *log_format_json(
                return NULL;
 
        char recv_real[64], recv_mono[64], sent_real[64], sent_mono[64];
+       char recv_real_ns[sizeof("\"recv_real_ns\":,") + 9];
+       char sent_real_ns[sizeof("\"sent_real_ns\":,") + 9];
        struct tm tmBuf;
        struct tm *ptm;
        time_t time_t_temp;
 
-       if (entry->nsec_recv_real == INVALID_NSEC)
+       if (entry->nsec_recv_real == INVALID_NSEC) {
                recv_real[0] = '\0';
-       else {
+               recv_real_ns[0] = '\0';
+       } else {
                time_t_temp = entry->sec_recv_real;
                ptm = localtime_r(&time_t_temp, &tmBuf);
                if (!ptm)
                        return NULL;
                strftime(recv_real, sizeof recv_real, "\"recv_real\":\"%FT%T%z\",", ptm);
+               snprintf(recv_real_ns, sizeof recv_real_ns, "\"recv_real_ns\":%d,", entry->nsec_recv_real);
        }
 
-       if (entry->nsec_sent_real == INVALID_NSEC)
+       if (entry->nsec_sent_real == INVALID_NSEC) {
                sent_real[0] = '\0';
-       else {
+               sent_real_ns[0] = '\0';
+       } else {
                time_t_temp = entry->sec_sent_real;
                ptm = localtime_r(&time_t_temp, &tmBuf);
                if (!ptm)
                        return NULL;
                strftime(sent_real, sizeof sent_real, "\"sent_real\":\"%FT%T%z\",", ptm);
+               snprintf(sent_real_ns, sizeof sent_real_ns, "\"sent_real_ns\":%d,", entry->nsec_sent_real);
        }
 
        if (entry->nsec_recv_mono == INVALID_NSEC)
@@ -782,11 +788,11 @@ char *log_format_json(
                "\"priority\":\"%s\"," \
                "\"pid\":%d," \
                "\"tid\":%d," \
-               "%s%s%s%s" \
+               "%s%s%s%s%s%s" \
                "\"tag\":\"%s\"," \
                "\"msg\":\"%s\"" \
                "}\n", prio_name, entry->pid, entry->tid, \
-               recv_real, recv_mono, sent_real, sent_mono, \
+               recv_real, recv_real_ns, recv_mono, sent_real, sent_real_ns, sent_mono, \
                tag_esc, msg_esc
 
        int len = snprintf(NULL, 0, ARGS);

diff --git a/src/tests/logprint.c b/src/tests/logprint.c
index 2e843cb..9ce54a0 100644 (file)
--- a/src/tests/logprint.c
+++ b/src/tests/logprint.c
@@ -214,8 +214,10 @@ void check_log_print_log_line(void)
                        "\"pid\":4228,"
                        "\"tid\":4567,"
                        "\"recv_real\":\"1970-02-01T00:05:17+0000\","
+                       "\"recv_real_ns\":734543254,"
                        "\"recv_mono\":365467.346253662,"
                        "\"sent_real\":\"1970-03-14T23:22:51+0000\","
+                       "\"sent_real_ns\":451435135,"
                        "\"sent_mono\":3205048.235123213,"
                        "\"tag\":\"BASIC TAG\","
                        "\"msg\":\"Basic message.\""
@@ -307,8 +309,10 @@ void check_log_print_log_line(void)
                        "\"pid\":4228,"
                        "\"tid\":4567,"
                        "\"recv_real\":\"1970-02-01T00:05:17+0000\","
+                       "\"recv_real_ns\":734543254,"
                        "\"recv_mono\":365467.346253662,"
                        "\"sent_real\":\"1970-03-14T23:22:51+0000\","
+                       "\"sent_real_ns\":451435135,"
                        "\"sent_mono\":3205048.235123213,"
                        "\"tag\":\"DLOG_ERROR_NOTAG\","
                        "\"msg\":\"Tagless\""
@@ -425,8 +429,10 @@ void check_log_print_log_line(void)
                        "\"pid\":4228,"
                        "\"tid\":4567,"
                        "\"recv_real\":\"1970-02-01T00:05:17+0000\","
+                       "\"recv_real_ns\":734543254,"
                        "\"recv_mono\":365467.346253662,"
                        "\"sent_real\":\"1970-03-14T23:22:51+0000\","
+                       "\"sent_real_ns\":451435135,"
                        "\"sent_mono\":3205048.235123213,"
                        "\"tag\":\"SOME_TAG\","
                        "\"msg\":\" \""
@@ -539,8 +545,10 @@ void check_log_print_log_line(void)
                        "\"pid\":0,"
                        "\"tid\":0,"
                        "\"recv_real\":\"1970-02-01T00:05:17+0000\","
+                       "\"recv_real_ns\":734543254,"
                        "\"recv_mono\":365467.346253662,"
                        "\"sent_real\":\"1970-02-01T00:05:17+0000\","
+                       "\"sent_real_ns\":734543254,"
                        "\"sent_mono\":365467.346253662,"
                        "\"tag\":\"BASIC TAG\","
                        "\"msg\":\"Basic message.\\n"
@@ -721,8 +729,10 @@ void check_json(void)
                "\"pid\":17,"\
                "\"tid\":18,"\
                "\"recv_real\":\"1970-11-24T11:10:31+0000\","\
+               "\"recv_real_ns\":28293031,"\
                "\"recv_mono\":22.000000022,"\
                "\"sent_real\":\"1970-09-27T00:15:27+0000\","\
+               "\"sent_real_ns\":23242527,"\
                "\"sent_mono\":21.000000021,"\
                "\"tag\":\"tag\","\
                "\"msg\":\"message\""\
@@ -738,8 +748,10 @@ void check_json(void)
                "\"pid\":17,"\
                "\"tid\":18,"\
                "\"recv_real\":\"1970-11-24T11:10:31+0000\","\
+               "\"recv_real_ns\":28293031,"\
                "\"recv_mono\":22.000000022,"\
                "\"sent_real\":\"1970-09-27T00:15:27+0000\","\
+               "\"sent_real_ns\":23242527,"\
                "\"sent_mono\":21.000000021,"\
                "\"tag\":\"∫\","\
                "\"msg\":\"\\u0001\\u0002\\u0003\\u0014\\u0015\\u0016\\\"\\\\\\b\\f\\n\\r\\t🤔\""\

diff --git a/tests/dlog_test.in b/tests/dlog_test.in
index d21db00..1229717 100644 (file)
--- a/tests/dlog_test.in
+++ b/tests/dlog_test.in
@@ -697,9 +697,9 @@ line=$($cmd_prefix $format)
 
 format="json"
 if [ "$type" = "pipe" ]; then
-       REGEX="s/^\{\"priority\":\"(verbose|debug|info|warning|error|fatal|silent)\",\"pid\":[1-9][0-9]*,\"tid\":[1-9][0-9]*,\"recv_real\":\"[0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9]{2}:[0-9]{2}:[0-9]{2}$regex_timezone\",\"recv_mono\":[1-9][0-9]+\.[0-9]{9},\"sent_real\":\"[0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9]{2}:[0-9]{2}:[0-9]{2}$regex_timezone\",\"sent_mono\":[1-9][0-9]+\.[0-9]{9},\"tag\":\"[[:print:]]*\",\"msg\":\"[[:print:]]*\"\}$/1/g"
+       REGEX="s/^\{\"priority\":\"(verbose|debug|info|warning|error|fatal|silent)\",\"pid\":[1-9][0-9]*,\"tid\":[1-9][0-9]*,\"recv_real\":\"[0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9]{2}:[0-9]{2}:[0-9]{2}$regex_timezone\",\"recv_real_ns\":[1-9][0-9]*,\"recv_mono\":[1-9][0-9]+\.[0-9]{9},\"sent_real\":\"[0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9]{2}:[0-9]{2}:[0-9]{2}$regex_timezone\",\"sent_real_ns\":[1-9][0-9]*,\"sent_mono\":[1-9][0-9]+\.[0-9]{9},\"tag\":\"[[:print:]]*\",\"msg\":\"[[:print:]]*\"\}$/1/g"
 elif [ "$type" = "logger" ]; then
-       REGEX="s/^\{\"priority\":\"(verbose|debug|info|warning|error|fatal|silent)\",\"pid\":[1-9][0-9]*,\"tid\":[1-9][0-9]*,\"sent_real\":\"[0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9]{2}:[0-9]{2}:[0-9]{2}$regex_timezone\",\"tag\":\"[[:print:]]*\",\"msg\":\"[[:print:]]*\"\}$/1/g"
+       REGEX="s/^\{\"priority\":\"(verbose|debug|info|warning|error|fatal|silent)\",\"pid\":[1-9][0-9]*,\"tid\":[1-9][0-9]*,\"sent_real\":\"[0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9]{2}:[0-9]{2}:[0-9]{2}$regex_timezone\",\"sent_real_ns\":[1-9][0-9]*,\"tag\":\"[[:print:]]*\",\"msg\":\"[[:print:]]*\"\}$/1/g"
 else # zero-copy
        REGEX="s/^\{\"priority\":\"(verbose|debug|info|warning|error|fatal|silent)\",\"pid\":[1-9][0-9]*,\"tid\":[1-9][0-9]*,\"sent_mono\":[1-9][0-9]+\.[0-9]{9},\"tag\":\"[[:print:]]*\",\"msg\":\"[[:print:]]*\"\}$/1/g"
 fi
@@ -1338,7 +1338,7 @@ if [ "$quick" -ne 1 ]; then
                        LOG_DETAILS="testing if dlogutil --sort-by sorts correctly (${P}_mono)"
                        dlogutil -db main --sort-by "${P}_mono" -v json | sed -Ee "s/^.*\"${P}_mono\":([^,}]*).*\$/\\1/" | sort -c && ok || fail
                        LOG_DETAILS="testing if dlogutil --sort-by sorts correctly (${P}_real)"
-                       dlogutil -db main --sort-by "${P}_real" -v json | sed -Ee "s/^.*\"${P}_real\":\"([^\"]*)\".*\$/\\1/" | sort -c && ok || fail
+                       dlogutil -db main --sort-by "${P}_real" -v json | sed -Ee "s/^.*\"${P}_real\":\"([^\"]*)\",\"${P}_real_ns\":([^,}]*).*\$/\\1 \2/" | sort -c -k1,1 -k2,2g && ok || fail
                done
        fi