Release 1.21.0

[FEATURE] Add qlog log module.

CHANGELOG

@@ -1,3 +1,7 @@
+2019-04-12
+    - 1.21.0
+    - [FEATURE] Add qlog log module.
+
 2019-04-01
     - 1.20.0
     - [FEATURE] Add support for Q046.

include/lsquic.h

@@ -24,7 +24,7 @@ extern "C" {
 #endif
 
 #define LSQUIC_MAJOR_VERSION 1
-#define LSQUIC_MINOR_VERSION 20
+#define LSQUIC_MINOR_VERSION 21
 #define LSQUIC_PATCH_VERSION 0
 
 /**

src/liblsquic/CMakeLists.txt

@@ -39,6 +39,7 @@ SET(lsquic_STAT_SRCS
     lsquic_di_error.c
     lsquic_global.c
     lsquic_packet_common.c
+    lsquic_qlog.c
     lsquic_ev_log.c
     lsquic_frame_common.c
     lsquic_packints.c

src/liblsquic/lsquic_engine.c

@@ -553,6 +553,8 @@ process_packet_in (lsquic_engine_t *engine, lsquic_packet_in_t *packet_in,
        const struct sockaddr *sa_peer, void *peer_ctx)
 {
     lsquic_conn_t *conn;
+    const unsigned char *packet_in_data;
+    size_t packet_in_size;
 
     if (lsquic_packet_in_is_gquic_prst(packet_in)
                                 && !engine->pub.enp_settings.es_honor_prst)
@@ -577,8 +579,27 @@ process_packet_in (lsquic_engine_t *engine, lsquic_packet_in_t *packet_in,
     }
     lsquic_conn_record_sockaddr(conn, sa_local, sa_peer);
     lsquic_packet_in_upref(packet_in);
+    /* Note on QLog:
+     * For the PACKET_RX QLog event, we are interested in logging these things:
+     *  - raw packet (however it comes in, encrypted or not)
+     *  - frames (list of frame names)
+     *  - packet type and number
+     *  - packet rx timestamp
+     *
+     * Since only some of these items are available at this code
+     * juncture, we will wait until after the packet has been
+     * decrypted (if necessary) and parsed to call the log functions.
+     *
+     * Once the PACKET_RX event is finally logged, the timestamp
+     * will come from packet_in->pi_received. For correct sequential
+     * ordering of QLog events, be sure to process the QLogs downstream.
+     * (Hint: Use the qlog_parser.py tool in tools/ for full QLog processing.)
+     */
     conn->cn_peer_ctx = peer_ctx;
+    packet_in_data = packet_in->pi_data;
+    packet_in_size = packet_in->pi_data_sz;
     conn->cn_if->ci_packet_in(conn, packet_in);
+    QLOG_PACKET_RX(conn->cn_cid, packet_in, packet_in_data, packet_in_size);
     lsquic_packet_in_put(&engine->pub.enp_mm, packet_in);
     return 0;
 }
@@ -700,6 +721,8 @@ lsquic_engine_connect (lsquic_engine_t *engine, const struct sockaddr *local_sa,
                                                     zero_rtt, zero_rtt_len);
     if (!conn)
         goto err;
+    EV_LOG_CREATE_CONN(conn->cn_cid, local_sa, peer_sa);
+    EV_LOG_VER_NEG(conn->cn_cid, "proposed", lsquic_ver2str[conn->cn_version]);
     lsquic_conn_record_sockaddr(conn, local_sa, peer_sa);
     if (0 != conn_hash_add(&engine->conns_hash, conn))
     {

src/liblsquic/lsquic_ev_log.c

@@ -345,3 +345,42 @@ lsquic_ev_log_generated_http_push_promise (lsquic_cid_t cid,
                 (int)    extra_headers->headers[i].value.iov_len,
                 (char *) extra_headers->headers[i].value.iov_base);
 }
+
+
+void
+lsquic_ev_log_create_connection (lsquic_cid_t cid,
+                                    const struct sockaddr *local_sa,
+                                    const struct sockaddr *peer_sa)
+{
+    LCID("connection created");
+}
+
+
+void
+lsquic_ev_log_hsk_completed (lsquic_cid_t cid)
+{
+    LCID("handshake completed");
+}
+
+
+void
+lsquic_ev_log_zero_rtt (lsquic_cid_t cid)
+{
+    LCID("zero_rtt successful");
+}
+
+
+void
+lsquic_ev_log_check_certs (lsquic_cid_t cid, const lsquic_str_t **certs,
+                                                                size_t count)
+{
+    LCID("check certs");
+}
+
+
+void
+lsquic_ev_log_version_negotiation (lsquic_cid_t cid,
+                                        const char *action, const char *ver)
+{
+    LCID("version negotiation: %s version %s", action, ver);
+}

src/liblsquic/lsquic_ev_log.h

@@ -7,6 +7,7 @@
 #define LSQUIC_EV_LOG_H 1
 
 #include "lsquic_int_types.h"
+#include "lsquic_qlog.h"
 
 struct ack_info;
 struct http_prio_frame;
@@ -208,4 +209,56 @@ lsquic_ev_log_generated_http_push_promise (lsquic_cid_t, uint32_t stream_id,
         lsquic_ev_log_generated_http_push_promise(__VA_ARGS__);             \
 } while (0)
 
+void
+lsquic_ev_log_create_connection (lsquic_cid_t, const struct sockaddr *,
+                                                    const struct sockaddr *);
+
+#define EV_LOG_CREATE_CONN(...) do {                                        \
+    if (LSQ_LOG_ENABLED_EXT(LSQ_LOG_DEBUG, LSQLM_EVENT))                    \
+        lsquic_ev_log_create_connection(__VA_ARGS__);                       \
+    if (LSQ_LOG_ENABLED_EXT(LSQ_LOG_DEBUG, LSQLM_QLOG))                     \
+        lsquic_qlog_create_connection(__VA_ARGS__);                         \
+} while (0)
+
+void
+lsquic_ev_log_hsk_completed (lsquic_cid_t);
+
+#define EV_LOG_HSK_COMPLETED(...) do {                                      \
+    if (LSQ_LOG_ENABLED_EXT(LSQ_LOG_DEBUG, LSQLM_EVENT))                    \
+        lsquic_ev_log_hsk_completed(__VA_ARGS__);                           \
+    if (LSQ_LOG_ENABLED_EXT(LSQ_LOG_DEBUG, LSQLM_QLOG))                     \
+        lsquic_qlog_hsk_completed(__VA_ARGS__);                             \
+} while (0)
+
+
+void
+lsquic_ev_log_zero_rtt (lsquic_cid_t);
+
+#define EV_LOG_ZERO_RTT(...) do {                                           \
+    if (LSQ_LOG_ENABLED_EXT(LSQ_LOG_DEBUG, LSQLM_EVENT))                    \
+        lsquic_ev_log_zero_rtt(__VA_ARGS__);                                \
+    if (LSQ_LOG_ENABLED_EXT(LSQ_LOG_DEBUG, LSQLM_QLOG))                     \
+        lsquic_qlog_zero_rtt(__VA_ARGS__);                                  \
+} while (0)
+
+void
+lsquic_ev_log_check_certs (lsquic_cid_t, const lsquic_str_t **, size_t);
+
+#define EV_LOG_CHECK_CERTS(...) do {                                        \
+    if (LSQ_LOG_ENABLED_EXT(LSQ_LOG_DEBUG, LSQLM_EVENT))                    \
+        lsquic_ev_log_check_certs(__VA_ARGS__);                             \
+    if (LSQ_LOG_ENABLED_EXT(LSQ_LOG_DEBUG, LSQLM_QLOG))                     \
+        lsquic_qlog_check_certs(__VA_ARGS__);                               \
+} while (0)
+
+void
+lsquic_ev_log_version_negotiation (lsquic_cid_t, const char *, const char *);
+
+#define EV_LOG_VER_NEG(...) do {                                            \
+    if (LSQ_LOG_ENABLED_EXT(LSQ_LOG_DEBUG, LSQLM_EVENT))                    \
+        lsquic_ev_log_version_negotiation(__VA_ARGS__);                     \
+    if (LSQ_LOG_ENABLED_EXT(LSQ_LOG_DEBUG, LSQLM_QLOG))                     \
+        lsquic_qlog_version_negotiation(__VA_ARGS__);                       \
+} while (0)
+
 #endif

src/liblsquic/lsquic_full_conn.c

@@ -1920,6 +1920,8 @@ process_ver_neg_packet (struct full_conn *conn, lsquic_packet_in_t *packet_in)
         {
             versions |= 1 << version;
             LSQ_DEBUG("server supports version %s", lsquic_ver2str[version]);
+            EV_LOG_VER_NEG(conn->fc_conn.cn_cid,
+                                        "supports", lsquic_ver2str[version]);
         }
     }
 
@@ -2111,6 +2113,8 @@ process_incoming_packet (struct full_conn *conn, lsquic_packet_in_t *packet_in)
             LSQ_DEBUG("end of version negotiation: agreed upon %s",
                                     lsquic_ver2str[conn->fc_ver_neg.vn_ver]);
             lsquic_send_ctl_verneg_done(&conn->fc_send_ctl);
+            EV_LOG_VER_NEG(conn->fc_conn.cn_cid,
+                            "agreed", lsquic_ver2str[conn->fc_ver_neg.vn_ver]);
         }
         return process_regular_packet(conn, packet_in);
     }

src/liblsquic/lsquic_handshake.c

@@ -1185,6 +1185,7 @@ static int handle_chlo_reply_verify_prof(lsquic_enc_session_t *enc_session,
         LSQ_INFO("server certificate verification %ssuccessful",
                                                     ret == 0 ? "" : "not ");
     }
+    EV_LOG_CHECK_CERTS(enc_session->cid, (const lsquic_str_t **)out_certs, *out_certs_count);
 
   cleanup:
     if (chain)
@@ -1423,6 +1424,9 @@ lsquic_enc_session_handle_chlo_reply (lsquic_enc_session_t *enc_session,
     else if(head_tag == QTAG_SHLO)
     {
         enc_session->hsk_state = HSK_COMPLETED;
+        EV_LOG_HSK_COMPLETED(enc_session->cid);
+        if (!(enc_session->es_flags & ES_RECV_REJ))
+            EV_LOG_ZERO_RTT(enc_session->cid);
     }
 
     if (info->scfg_flag == 1)

src/liblsquic/lsquic_logger.c

@@ -85,6 +85,7 @@ enum lsq_log_level lsq_log_levels[N_LSQUIC_LOGGER_MODULES] = {
     [LSQLM_PACER]       = LSQ_LOG_WARN,
     [LSQLM_MIN_HEAP]    = LSQ_LOG_WARN,
     [LSQLM_HTTP1X]      = LSQ_LOG_WARN,
+    [LSQLM_QLOG]        = LSQ_LOG_WARN,
 };
 
 const char *const lsqlm_to_str[N_LSQUIC_LOGGER_MODULES] = {
@@ -114,6 +115,7 @@ const char *const lsqlm_to_str[N_LSQUIC_LOGGER_MODULES] = {
     [LSQLM_PACER]       = "pacer",
     [LSQLM_MIN_HEAP]    = "min-heap",
     [LSQLM_HTTP1X]      = "http1x",
+    [LSQLM_QLOG]        = "qlog",
 };
 
 const char *const lsq_loglevel2str[N_LSQUIC_LOG_LEVELS] = {

src/liblsquic/lsquic_logger.h

@@ -72,6 +72,7 @@ enum lsquic_logger_module {
     LSQLM_PACER,
     LSQLM_MIN_HEAP,
     LSQLM_HTTP1X,
+    LSQLM_QLOG,
     N_LSQUIC_LOGGER_MODULES
 };
 

src/liblsquic/lsquic_packet_common.h

@@ -64,8 +64,9 @@ static const char * const frame_type_2_str[N_QUIC_FRAMES] = {
     [QUIC_FRAME_PING]              =  "QUIC_FRAME_PING",
 };
 
-
+#define QUIC_FRAME_PRELEN   (sizeof("QUIC_FRAME_"))
-#define QUIC_FRAME_SLEN(x) (sizeof(#x) - sizeof("QUIC_FRAME_"))
+#define QUIC_FRAME_SLEN(x)  (sizeof(#x) - QUIC_FRAME_PRELEN)
+#define QUIC_FRAME_NAME(i)  (frame_type_2_str[i] + QUIC_FRAME_PRELEN - 1)
 
 
     /* We don't need to include INVALID frame in this list because it is

src/liblsquic/lsquic_parse_Q046.c

@@ -72,10 +72,13 @@ write_packno (unsigned char *p, lsquic_packno_t packno, enum packno_bits bits)
     {
     case IQUIC_PACKNO_LEN_4:
         *p++ = packno >> 24;
+        /* fall-through */
     case IQUIC_PACKNO_LEN_3:
         *p++ = packno >> 16;
+        /* fall-through */
     case IQUIC_PACKNO_LEN_2:
         *p++ = packno >> 8;
+        /* fall-through */
     default:
         *p++ = packno;
     }

src/liblsquic/lsquic_parse_iquic_common.c

@@ -75,13 +75,7 @@ lsquic_iquic_parse_packet_in_long_begin (lsquic_packet_in_t *packet_in,
             header_type = bits2ht[ (first_byte >> 4) & 3 ];
     }
     else
-    {
         header_type = HETY_VERNEG;
-#ifdef WIN32
-        /* Useless initialization */
-        version = -1;
-#endif
-    }
 
     packet_in->pi_header_type = header_type;
 
@@ -131,10 +125,6 @@ lsquic_iquic_parse_packet_in_long_begin (lsquic_packet_in_t *packet_in,
         /* Need at least one version in the version array: add 4 */
         if (end - p < (ptrdiff_t) (dcil + scil + 4))
             return -1;
-#ifdef WIN32
-        /* Useless initialization */
-        packet_len = 0;
-#endif
     }
 
     memcpy(&packet_in->pi_conn_id, p, cid_len);

src/liblsquic/lsquic_qlog.c

@@ -0,0 +1,208 @@
+/* Copyright (c) 2017 - 2019 LiteSpeed Technologies Inc.  See LICENSE. */
+#include <stdlib.h>
+#include <stdio.h>
+#include <errno.h>
+#include <inttypes.h>
+#include <string.h>
+#include <sys/queue.h>
+#include <netinet/in.h>
+#include <arpa/inet.h>
+
+#include "lsquic.h"
+#include "lsquic_types.h"
+#include "lsquic_int_types.h"
+#include "lsquic_packet_common.h"
+#include "lsquic_packet_in.h"
+#include "lsquic_packet_out.h"
+#include "lsquic_util.h"
+#include "lsquic_qlog.h"
+
+#define LSQUIC_LOGGER_MODULE LSQLM_QLOG
+#include "lsquic_logger.h"
+
+#define LSQUIC_LOG_CONN_ID cid
+#define LCID(...) LSQ_LOG2(LSQ_LOG_DEBUG, __VA_ARGS__)
+
+#define MAX_IP_LEN INET6_ADDRSTRLEN
+#define QLOG_PACKET_RAW_SZ 64
+
+
+void
+lsquic_qlog_create_connection (lsquic_cid_t cid,
+                                const struct sockaddr *local_sa,
+                                const struct sockaddr *peer_sa)
+{
+    uint32_t ip_version, srcport, dstport;
+    struct sockaddr_in *local4, *peer4;
+    struct sockaddr_in6 *local6, *peer6;
+    char srcip[MAX_IP_LEN], dstip[MAX_IP_LEN];
+
+    if (!local_sa || !peer_sa)
+        return;
+
+    if (local_sa->sa_family == AF_INET)
+    {
+        ip_version = 4;
+        local4 = (struct sockaddr_in *)local_sa;
+        peer4 = (struct sockaddr_in *)peer_sa;
+        srcport = ntohs(local4->sin_port);
+        dstport = ntohs(peer4->sin_port);
+        inet_ntop(local4->sin_family, &local4->sin_addr, srcip, MAX_IP_LEN);
+        inet_ntop(peer4->sin_family, &peer4->sin_addr, dstip, MAX_IP_LEN);
+    }
+    else if (local_sa->sa_family == AF_INET6)
+    {
+        ip_version = 6;
+        local6 = (struct sockaddr_in6 *)local_sa;
+        peer6 = (struct sockaddr_in6 *)peer_sa;
+        srcport = ntohs(local6->sin6_port);
+        dstport = ntohs(peer6->sin6_port);
+        inet_ntop(local6->sin6_family, &local6->sin6_addr, srcip, MAX_IP_LEN);
+        inet_ntop(peer6->sin6_family, &peer6->sin6_addr, dstip, MAX_IP_LEN);
+    }
+    else
+        return;
+
+    LCID("[%" PRIu64 ",\"CONNECTIVITY\",\"NEW_CONNECTION\",\"LINE\","
+            "{"
+                "\"ip_version\":\"%u\","
+                "\"srcip\":\"%s\","
+                "\"dstip\":\"%s\","
+                "\"srcport\":\"%u\","
+                "\"dstport\":\"%u\""
+            "}]",
+            lsquic_time_now(), ip_version, srcip, dstip, srcport, dstport);
+}
+
+#define QLOG_FRAME_DICT_PREFIX ",{\"frame_type\":\""
+#define QLOG_FRAME_DICT_SUFFIX "\"}"
+#define QLOG_FRAME_LIST_PREFIX ",\"frames\":["
+#define QLOG_FRAME_LIST_SUFFIX "]"
+#define QLOG_FRAME_LIST_MAX \
+    sizeof(QLOG_FRAME_LIST_PREFIX) + \
+    sizeof(QLOG_FRAME_LIST_SUFFIX) + \
+    lsquic_frame_types_str_sz + \
+    (N_QUIC_FRAMES * \
+    (sizeof(QLOG_FRAME_DICT_PREFIX) + \
+     sizeof(QLOG_FRAME_DICT_SUFFIX)))
+
+void
+lsquic_qlog_packet_rx (lsquic_cid_t cid,
+                        const struct lsquic_packet_in *packet_in,
+                        const unsigned char *packet_in_data,
+                        size_t packet_in_size)
+{
+    int i, cur = 0, first = 0, ret = 0;
+    size_t raw_bytes_written;
+    char data[QLOG_PACKET_RAW_SZ];
+    char frame_list[QLOG_FRAME_LIST_MAX + 1];
+
+    if (!packet_in || !packet_in_data)
+        return;
+
+    frame_list[cur] = '\0';
+    if (packet_in->pi_frame_types)
+    {
+        cur = sprintf(frame_list, "%s", QLOG_FRAME_LIST_PREFIX);
+        for (i = 0; i < N_QUIC_FRAMES; i++)
+            if (packet_in->pi_frame_types & (1 << i))
+            {
+                ret = snprintf(frame_list + cur,
+                                QLOG_FRAME_LIST_MAX - cur,
+                                /* prefix + FRAME_NAME + suffix */
+                                "%s%s%s",
+                                /* skip comma in prefix if first frame */
+                                QLOG_FRAME_DICT_PREFIX + (first++ ? 0 : 1),
+                                QUIC_FRAME_NAME(i),
+                                QLOG_FRAME_DICT_SUFFIX);
+                if ((unsigned)ret > QLOG_FRAME_LIST_MAX - cur)
+                    break;
+                cur += ret;
+            }
+        if ((unsigned)cur <= QLOG_FRAME_LIST_MAX)
+            sprintf(frame_list + cur, "%s", QLOG_FRAME_LIST_SUFFIX);
+    }
+
+    raw_bytes_written = lsquic_hex_encode(packet_in_data, packet_in_size,
+                                                    data, QLOG_PACKET_RAW_SZ);
+
+    LCID("[%" PRIu64 ",\"TRANSPORT\",\"PACKET_RX\",\"LINE\","
+            "{"
+                "\"raw\":\"%s%s\","
+                "\"header\":{"
+                    "\"type\":\"%s\","
+                    "\"payload_length\":\"%d\","
+                    "\"packet_number\":\"%ld\""
+                "}%s"
+            "}]",
+            packet_in->pi_received,
+            data, (raw_bytes_written < packet_in_size) ? "..." : "",
+            lsquic_hety2str[packet_in->pi_header_type],
+            packet_in->pi_data_sz,
+            packet_in->pi_packno,
+            frame_list);
+}
+
+
+void
+lsquic_qlog_hsk_completed (lsquic_cid_t cid)
+{
+    LCID("[%" PRIu64 ",\"CONNECTIVITY\",\"HANDSHAKE\",\"PACKET_RX\","
+            "{\"status\":\"complete\"}]", lsquic_time_now());
+}
+
+
+void
+lsquic_qlog_zero_rtt (lsquic_cid_t cid)
+{
+    LCID("[%" PRIu64 ",\"RECOVERY\",\"RTT_UPDATE\",\"PACKET_RX\","
+            "{\"zero_rtt\":\"successful\"}]", lsquic_time_now());
+}
+
+
+void
+lsquic_qlog_check_certs (lsquic_cid_t cid, const lsquic_str_t **certs,
+                                                                size_t count)
+{
+    size_t i;
+    size_t buf_sz = 0;
+    char *buf = NULL;
+    char *new_buf;
+
+    for (i = 0; i < count; i++)
+    {
+        if (buf_sz < (lsquic_str_len(certs[i]) * 2) + 1)
+        {
+            buf_sz = (lsquic_str_len(certs[i]) * 2) + 1;
+            new_buf = realloc(buf, buf_sz);
+            if (!new_buf)
+                break;
+            buf = new_buf;
+        }
+        lsquic_hex_encode(lsquic_str_cstr(certs[i]), lsquic_str_len(certs[i]),
+                                                                buf, buf_sz);
+        LCID("[%" PRIu64 ",\"SECURITY\",\"CHECK_CERT\",\"CERTLOG\","
+                "{\"certificate\":\"%s\"}]", lsquic_time_now(), buf);
+    }
+    if (buf)
+        free(buf);
+}
+
+
+void
+lsquic_qlog_version_negotiation (lsquic_cid_t cid,
+                                        const char *action, const char *ver)
+{
+    char *trig;
+
+    if (!action || !ver)
+        return;
+    if (strcmp(action, "proposed") == 0)
+        trig = "LINE";
+    else if (strcmp(action, "agreed") == 0)
+        trig = "PACKET_RX";
+    else
+        return;
+    LCID("[%" PRIu64 ",\"CONNECTIVITY\",\"VERNEG\",\"%s\","
+            "{\"%s_version\":\"%s\"}]", lsquic_time_now(), trig, action, ver);
+}

src/liblsquic/lsquic_qlog.h

@@ -0,0 +1,89 @@
+/* Copyright (c) 2017 - 2019 LiteSpeed Technologies Inc.  See LICENSE. */
+/*
+ * lsquic_qlog.h -- QLOG Event logger
+ */
+
+#ifndef LSQUIC_QLOG_H
+#define LSQUIC_QLOG_H 1
+
+#include "lsquic_int_types.h"
+#include "lsquic_packet_common.h"
+#include "lsquic_str.h"
+
+/*
+EventCategory
+    CONNECTIVITY
+    SECURITY
+    TRANSPORT
+    RECOVERY
+
+EventType
+  CONNECTIVITY
+    NEW_CONNECTION
++   VERNEG
++   HANDSHAKE
+  SECURITY
++   CHECK_CERT
+    KEY_UPDATE
+  TRANSPORT
++   PACKET_RX
+    STREAM_NEW
+    ACK_NEW
+    MAXDATA_NEW
+    MAXSTREAMDATA_NEW
+  RECOVERY
+    LOSS_DETECTION_ARMED
+    LOSS_DETECTION_POSTPONED
+    LOSS_DETECTION_TRIGGERED
+    BYTES_IN_FLIGHT_UPDATE
+    CWND_UPDATE
+    RTT_UPDATE
+
+EventTrigger
+  CONNECTIVITY
+    LINE
++   PACKET_RX
+  SECURITY
++   CERTLOG
+    KEYLOG
+  TRANSPORT
+    LINE
+    PACKET_TX
+    PACKET_RX
+  RECOVERY
+    ACK_RX
+    PACKET_RX
+    UNKNOWN
+
+EventData
+  EventNewConnection
+  EventKeyUpdate
+  EventPacketRX
+*/
+
+void
+lsquic_qlog_create_connection (lsquic_cid_t, const struct sockaddr *,
+                                                    const struct sockaddr *);
+
+void
+lsquic_qlog_packet_rx (lsquic_cid_t cid, const struct lsquic_packet_in *,
+                                                const unsigned char *, size_t);
+
+#define QLOG_PACKET_RX(...) do {                                            \
+    if (LSQ_LOG_ENABLED_EXT(LSQ_LOG_DEBUG, LSQLM_QLOG))                     \
+        lsquic_qlog_packet_rx(__VA_ARGS__);                                 \
+} while (0)
+
+void
+lsquic_qlog_hsk_completed (lsquic_cid_t);
+
+void
+lsquic_qlog_zero_rtt (lsquic_cid_t);
+
+void
+lsquic_qlog_check_certs (lsquic_cid_t, const lsquic_str_t **, size_t);
+
+void
+lsquic_qlog_version_negotiation (lsquic_cid_t, const char *, const char *);
+
+#endif

src/liblsquic/lsquic_util.c

@@ -128,6 +128,34 @@ char *get_bin_str(const void *s, size_t len, size_t max_display_len)
 }
 
 
+static char
+hex_digit(uint8_t n)
+{
+    return (n < 10) ? (n + '0') : ((n - 10) + 'a');
+}
+
+
+size_t
+lsquic_hex_encode (const void *src, size_t src_sz, void *dst, size_t dst_sz)
+{
+    size_t src_cur, dst_cur;
+    const uint8_t *src_hex;
+    char *dst_char;
+
+    src_hex = (const uint8_t *)src;
+    dst_char = (char *)dst;
+    src_cur = dst_cur = 0;
+
+    while (src_cur < src_sz && dst_cur < (dst_sz - 2))
+    {
+        dst_char[dst_cur++] = hex_digit((src_hex[src_cur] & 0xf0) >> 4);
+        dst_char[dst_cur++] = hex_digit(src_hex[src_cur++] & 0x0f);
+    }
+    dst_char[dst_cur++] = '\0';
+    return dst_cur;
+}
+
+
 size_t
 hexdump (const void *src_void, size_t src_sz, char *out, size_t out_sz)
 {

src/liblsquic/lsquic_util.h

@@ -25,6 +25,8 @@ lsquic_is_zero (const void *buf, size_t bufsz);
 
 char * get_bin_str(const void *s, size_t len, size_t max_display_len);
 
+size_t
+lsquic_hex_encode (const void *src, size_t src_sz, void *dst, size_t dst_sz);
 
 /* `out_sz' is assumed to be at least 1.  `out' is always NUL-terminated. */
 size_t

test/unittests/CMakeLists.txt

@@ -38,6 +38,7 @@ SET(TESTS
     hkdf
     lsquic_hash
     malo
+    qlog
     packet_out
     packno_len
     parse_packet_in

test/unittests/test_qlog.c

@@ -0,0 +1,54 @@
+/* Copyright (c) 2017 - 2019 LiteSpeed Technologies Inc.  See LICENSE. */
+#include <assert.h>
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+
+#include "lsquic.h"
+#include "lsquic_int_types.h"
+#include "lsquic_conn.h"
+
+#include "lsquic_qlog.h"
+
+#define LSQUIC_LOGGER_MODULE LSQLM_NOMODULE
+#include "lsquic_logger.h"
+
+
+int
+main (void)
+{
+    lsquic_log_to_fstream(stderr, LLTS_HHMMSSMS);
+    lsquic_set_log_level("debug");
+
+    lsquic_qlog_create_connection(0, NULL, NULL);
+    struct in_addr local_addr = {.s_addr = htonl(0x0a000001),};
+    struct sockaddr_in local =
+    {
+        .sin_family = AF_INET,
+        .sin_port = htons(12345),
+        .sin_addr = local_addr,
+    };
+    struct in_addr peer_addr = {.s_addr = htonl(0x0a000002),};
+    struct sockaddr_in peer =
+    {
+        .sin_family = AF_INET,
+        .sin_port = htons(443),
+        .sin_addr = peer_addr,
+    };
+    lsquic_qlog_create_connection(0, (const struct sockaddr *)&local,
+                                        (const struct sockaddr *)&peer);
+
+    lsquic_qlog_packet_rx(0, NULL, NULL, 0);
+    lsquic_qlog_hsk_completed(0);
+    lsquic_qlog_zero_rtt(0);
+    lsquic_qlog_check_certs(0, NULL, 0);
+
+    lsquic_qlog_version_negotiation(0, NULL, NULL);
+    lsquic_qlog_version_negotiation(0, "proposed", NULL);
+    lsquic_qlog_version_negotiation(0, "proposed", "Q035");
+    lsquic_qlog_version_negotiation(0, "proposed", "Q046");
+    lsquic_qlog_version_negotiation(0, "agreed", "Q044");
+    lsquic_qlog_version_negotiation(0, "agreed", "Q098");
+    lsquic_qlog_version_negotiation(0, "something else", "Q098");
+    return 0;
+}

tools/qlog-parser.py

@@ -0,0 +1,83 @@
+import time
+import json
+import re
+import argparse
+
+_ev_time = 0
+_ev_cate = 1
+_ev_type = 2
+_ev_trig = 3
+_ev_data = 4
+_conn_base = {
+    'qlog_version': '0.1',
+    'vantagepoint': 'NETWORK',
+    'connectionid': '0',
+    'starttime': '0',
+    'fields': [
+        'time',
+        'category',
+        'type',
+        'trigger',
+        'data',
+    ],
+    'events': [],
+}
+
+arg_parser = argparse.ArgumentParser(description='Test the ExploreParser.')
+arg_parser.add_argument('qlog_path', type=str, help='path to QLog file')
+args = arg_parser.parse_args()
+
+try:
+    with open(args.qlog_path, 'r') as file:
+        text = file.read()
+except IOError:
+    print('ERROR: QLog not found at given path.')
+
+events = {}
+event_times = {}
+start_time = {}
+
+qlog = {
+    'qlog_version': '0.1',
+    'description': 'test with local log file',
+    'connections': [],
+}
+
+lines = text.split('\n')
+for line in lines:
+    if 'qlog' in line:
+        i = line.find('[QUIC:')
+        j = line.find(']', i)
+        k = line.find('qlog: ')
+
+        cid = line[i+6:j]
+        try:
+            event = json.loads(line[k+6:])
+        except json.JSONDecodeError:
+            continue
+
+        if not cid in events:
+            events[cid] = [event]
+            event_times[cid] = [event[_ev_time]]
+        else:
+            events[cid].append(event)
+            event_times[cid].append(event[_ev_time])
+
+for cid, times in event_times.items():
+    new_events = []
+    start_time[cid] = min(times)
+    times = [t - min(times) for t in times]
+    for t, i in sorted(((t, i) for i, t in enumerate(times))):
+        events[cid][i][0] = t
+        new_events.append(events[cid][i])
+    events[cid] = new_events
+
+for cid, event_list in events.items():
+    conn = _conn_base.copy()
+    conn['connectionid'] = cid
+    conn['starttime'] = start_time[cid]
+    conn['events'] = event_list
+    qlog['connections'].append(conn)
+
+print(json.dumps(qlog, indent=2))
+