emit time

Author: kazuho

include/picotls.h

@@ -1397,13 +1397,13 @@ uint64_t ptls_decode_quicint(const uint8_t **src, const uint8_t *end);
         ptls_decode_assert_block_close((src), end);                                                                                \
     } while (0)
 
-#define PTLS_LOG__DO_LOG(module, name, conn_state, get_sni, get_sni_arg, block)                                                    \
+#define PTLS_LOG__DO_LOG(module, name, conn_state, get_sni, get_sni_arg, add_time, block)                                          \
     do {                                                                                                                           \
         int ptlslog_skip = 0, ptlslog_include_appdata = 0;                                                                         \
         do {                                                                                                                       \
             char smallbuf[128];                                                                                                    \
             ptls_buffer_t ptlslogbuf;                                                                                              \
-            ptls_log__do_write_start(&logpoint, &ptlslogbuf, smallbuf, sizeof(smallbuf));                                          \
+            ptls_log__do_write_start(&logpoint, &ptlslogbuf, smallbuf, sizeof(smallbuf), (add_time));                              \
             do {                                                                                                                   \
                 block                                                                                                              \
             } while (0);                                                                                                           \
@@ -1420,7 +1420,7 @@ uint64_t ptls_decode_quicint(const uint8_t **src, const uint8_t *end);
         PTLS_LOG_DEFINE_POINT(module, name, logpoint);                                                                             \
         if (ptls_log_point_maybe_active(&logpoint) == 0)                                                                           \
             break;                                                                                                                 \
-        PTLS_LOG__DO_LOG(module, name, NULL, NULL, NULL, {block});                                                                 \
+        PTLS_LOG__DO_LOG(module, name, NULL, NULL, NULL, 1, {block});                                                              \
     } while (0)
 
 #define PTLS_LOG_CONN(name, tls, block)                                                                                            \
@@ -1434,7 +1434,7 @@ uint64_t ptls_decode_quicint(const uint8_t **src, const uint8_t *end);
         active &= ptls_log_conn_maybe_active(conn_state, (const char *(*)(void *))ptls_get_server_name, _tls);                     \
         if (active == 0)                                                                                                           \
             break;                                                                                                                 \
-        PTLS_LOG__DO_LOG(picotls, name, conn_state, (const char *(*)(void *))ptls_get_server_name, _tls, {                         \
+        PTLS_LOG__DO_LOG(picotls, name, conn_state, (const char *(*)(void *))ptls_get_server_name, _tls, 1, {                      \
             PTLS_LOG_ELEMENT_PTR(tls, _tls);                                                                                       \
             do {                                                                                                                   \
                 block                                                                                                              \
@@ -1636,7 +1636,8 @@ int ptls_log__do_push_signed32(ptls_buffer_t *buf, int32_t v);
 int ptls_log__do_push_signed64(ptls_buffer_t *buf, int64_t v);
 int ptls_log__do_push_unsigned32(ptls_buffer_t *buf, uint32_t v);
 int ptls_log__do_push_unsigned64(ptls_buffer_t *buf, uint64_t v);
-void ptls_log__do_write_start(struct st_ptls_log_point_t *point, ptls_buffer_t *buf, void *smallbuf, size_t smallbufsize);
+void ptls_log__do_write_start(struct st_ptls_log_point_t *point, ptls_buffer_t *buf, void *smallbuf, size_t smallbufsize,
+                              int add_time);
 int ptls_log__do_write_end(struct st_ptls_log_point_t *point, struct st_ptls_log_conn_state_t *conn, const char *(*get_sni)(void *),
                            void *get_sni_arg, ptls_buffer_t *buf, int includes_appdata);
 

lib/picotls.c

@@ -7105,39 +7105,53 @@ int ptls_log_add_fd(int fd, float sample_ratio, const char *_points, const char
 #endif
 }
 
-void ptls_log__do_write_start(struct st_ptls_log_point_t *point, ptls_buffer_t *buf, void *smallbuf, size_t smallbufsize)
+void ptls_log__do_write_start(struct st_ptls_log_point_t *point, ptls_buffer_t *buf, void *smallbuf, size_t smallbufsize,
+                              int add_time)
 {
 #if defined(__linux__) || defined(__APPLE__)
     static PTLS_THREADLOCAL char tid[sizeof(",\"tid\":-9223372036854775808")];
-    static PTLS_THREADLOCAL int tid_ready;
-    if (!tid_ready) {
+    static PTLS_THREADLOCAL size_t tid_len;
+    if (tid_len == 0) {
         static pthread_mutex_t mutex = PTHREAD_MUTEX_INITIALIZER;
         pthread_mutex_lock(&mutex);
-        if (!tid_ready) {
+        if (tid_len == 0) {
 #if defined(__linux__)
             sprintf(tid, ",\"tid\":%" PRId64, (int64_t)syscall(SYS_gettid));
 #elif defined(__APPLE__)
             uint64_t t = 0;
             (void)pthread_threadid_np(NULL, &t);
-            sprintf(tid, ",\"tid\":%" PRIu64, t);
+            int l = sprintf(tid, ",\"tid\":%" PRIu64, t);
 #else
 #error "unexpected platform"
 #endif
             __sync_synchronize();
-            tid_ready = 1;
+            tid_len = (size_t)l;
         }
         pthread_mutex_unlock(&mutex);
     }
 #else
-    const char *tid = "";
+    const char *tid = NULL;
+    const size_t tid_len = 0;
 #endif
     const char *colon_at = strchr(point->name, ':');
 
     ptls_buffer_init(buf, smallbuf, smallbufsize);
 
-    int written = snprintf((char *)buf->base, buf->capacity, "{\"module\":\"%.*s\",\"type\":\"%s\"%s",
-                           (int)(colon_at - point->name), point->name, colon_at + 1, tid);
+    int written = snprintf((char *)buf->base, buf->capacity, "{\"module\":\"%.*s\",\"type\":\"%s\"", (int)(colon_at - point->name),
+                           point->name, colon_at + 1);
+    if (tid != NULL) {
+        assert(written > 0 && written + tid_len < buf->capacity);
+        memcpy((char *)buf->base + written, tid, tid_len + 1);
+        written += tid_len;
+    }
+    if (add_time != 0) {
+        struct timeval tv;
+        gettimeofday(&tv, NULL);
+        written += snprintf((char *)buf->base + written, buf->capacity - written, ",\"time\":%" PRIu64,
+                            (uint64_t)tv.tv_sec * 1000 + tv.tv_usec / 1000);
+    }
     assert(written > 0 && written < buf->capacity && "caller MUST provide smallbuf suffient to emit the prefix");
+
     buf->off = (size_t)written;
 }