Merge 443677ab1b into 9c877a4177

After some time without activity (only keepalive), the ping frame was send in loop.

.cirrus.yml

@@ -1,5 +1,5 @@
 freebsd_instance:
-    image: freebsd-12-1-release-amd64
+    image: freebsd-13-2-release-amd64
 
 task:
     install_script:

.readthedocs.yaml

@@ -0,0 +1,35 @@
+# Read the Docs configuration file for Sphinx projects
+# See https://docs.readthedocs.io/en/stable/config-file/v2.html for details
+
+# Required
+version: 2
+
+# Set the OS, Python version and other tools you might need
+build:
+  os: ubuntu-22.04
+  tools:
+    python: "3.12"
+    # You can also specify other tool versions:
+    # nodejs: "20"
+    # rust: "1.70"
+    # golang: "1.20"
+
+# Build documentation in the "docs/" directory with Sphinx
+sphinx:
+  configuration: docs/conf.py
+  # You can configure Sphinx to use a different builder, for instance use the dirhtml builder for simpler URLs
+  # builder: "dirhtml"
+  # Fail on all warnings to avoid broken references
+  # fail_on_warning: true
+
+# Optionally build your docs in additional formats such as PDF and ePub
+# formats:
+#   - pdf
+#   - epub
+
+# Optional but recommended, declare the Python requirements required
+# to build your documentation
+# See https://docs.readthedocs.io/en/stable/guides/reproducible-builds.html
+python:
+  install:
+    - requirements: docs/requirements.txt

CHANGELOG

@@ -1,3 +1,23 @@
+2024-02-07
+    - 4.0.5
+    - Fix CPU spinning due to STREAM_BLOCKED frame.
+
+2024-01-08
+    - 4.0.4
+    - Fix DCID validation.
+    - Fix CPU spinning due to pending STREAM_BLOCKED frame.
+
+2023-12-25
+    - 4.0.3
+    - Fix session resumption bug introduced in 4.0.2.
+
+2023-12-19
+    - 4.0.2
+    - More strict RFC compliance.
+    - Minimize packet generated when send STREAM_BLOCKED frame
+    - Fix memory management bugs.
+    - Fix memory leak in unit tests.
+
 2023-05-14
     - 4.0.1
     - Fix send_ctl bug.

CMakeLists.txt

@@ -272,7 +272,8 @@ ENDIF()
 SET(LIBS lsquic ${BORINGSSL_LIB_ssl} ${BORINGSSL_LIB_crypto} ${ZLIB_LIB} ${LIBS})
 
 IF (LSQUIC_BIN)
-    FIND_PATH(EVENT_INCLUDE_DIR NAMES event2/event.h)
+    FIND_PATH(EVENT_INCLUDE_DIR NAMES event2/event.h
+              PATHS ${PROJECT_SOURCE_DIR}/../third-party/include)
     IF (EVENT_INCLUDE_DIR)
         INCLUDE_DIRECTORIES(${EVENT_INCLUDE_DIR})
     ELSE()
@@ -285,7 +286,8 @@ IF (LSQUIC_BIN)
     IF (CMAKE_SYSTEM_NAME STREQUAL Windows)
         FIND_LIBRARY(EVENT_LIB event)
     ELSE()
-        FIND_LIBRARY(EVENT_LIB libevent${LIB_SUFFIX})
+        FIND_LIBRARY(EVENT_LIB libevent${LIB_SUFFIX}
+                    PATHS ${PROJECT_SOURCE_DIR}/../third-party/lib)
         IF(NOT EVENT_LIB)
             FIND_LIBRARY(EVENT_LIB libevent.so)
         ENDIF()

bin/http_client.c

@@ -348,7 +348,10 @@ http_client_on_conn_closed (lsquic_conn_t *conn)
     if (conn_h->client_ctx->hcc_flags & HCC_ABORT_ON_INCOMPLETE)
     {
         if (!(conn_h->client_ctx->hcc_flags & HCC_SEEN_FIN))
-            abort();
+        {
+            LSQ_INFO("abort incomplete connection");
+            exit(1);
+        }
     }
     --conn_h->client_ctx->hcc_n_open_conns;
 
@@ -1011,6 +1014,7 @@ usage (const char *prog)
 "                 content-type: application/octet-stream and\n"
 "                 content-length\n"
 "   -K          Discard server response\n"
+"   -B          Header bypass\n"
 "   -I          Abort on incomplete reponse from server\n"
 "   -4          Prefer IPv4 when resolving hostname\n"
 "   -6          Prefer IPv6 when resolving hostname\n"

bin/prog.c

@@ -171,6 +171,11 @@ prog_print_common_options (const struct prog *prog, FILE *out)
 "                   sndbuf=12345    # Sets SO_SNDBUF\n"
 "                   rcvbuf=12345    # Sets SO_RCVBUF\n"
 "   -W          Use stock PMI (malloc & free)\n"
+"   -A CC_ALGO  Congestion control algorithm.  The following algorithms are\n"
+"                 supported.\n"
+"                   1: Cubic\n"
+"                   2: BBRv1\n"
+"                   3: Adaptive congestion control (this is the default).\n"
     );
 
 #if HAVE_SENDMMSG
@@ -266,6 +271,9 @@ prog_set_opt (struct prog *prog, int opt, const char *arg)
     case 'W':
         prog->prog_use_stock_pmi = 1;
         return 0;
+    case 'A':
+        prog->prog_settings.es_cc_algo = atoi(optarg);
+        return 0;
     case 'c':
         if (prog->prog_engine_flags & LSENG_SERVER)
         {

bin/prog.h

@@ -74,7 +74,7 @@ prog_init (struct prog *, unsigned lsquic_engine_flags, struct sport_head *,
 #   define IP_DONTFRAG_FLAG ""
 #endif
 
-#define PROG_OPTS "i:km:c:y:L:l:o:H:s:S:Y:z:G:W" RECVMMSG_FLAG SENDMMSG_FLAG \
+#define PROG_OPTS "i:km:c:y:L:l:o:H:s:S:Y:z:G:WA:" RECVMMSG_FLAG SENDMMSG_FLAG \
                                                             IP_DONTFRAG_FLAG
 
 /* Returns:

docs/conf.py

@@ -26,7 +26,7 @@ author = u'LiteSpeed Technologies'
 # The short X.Y version
 version = u'4.0'
 # The full version, including alpha/beta/rc tags
-release = u'4.0.1'
+release = u'4.0.5'
 
 
 # -- General configuration ---------------------------------------------------
@@ -41,6 +41,7 @@ release = u'4.0.1'
 extensions = [
 # To make ours look like readthedocs.io, change theme to "sphinx_rtd_theme",
 # pip install sphinx_rtd_theme, and uncomment extensions:
+    "sphinx_rtd_theme",
 #    "sphinx.ext.intersphinx",
 #    "sphinx.ext.autodoc",
 #    "sphinx.ext.mathjax",
@@ -83,8 +84,8 @@ primary_domain = 'c'
 # The theme to use for HTML and HTML Help pages.  See the documentation for
 # a list of builtin themes.
 #
-#html_theme = 'alabaster'
-html_style = '/default.css'
+html_theme = "sphinx_rtd_theme"
+#html_style = '/default.css'
 
 # Theme options are theme-specific and customize the look and feel of a theme
 # further.  For a list of options available for each theme, see the

docs/requirements.txt

@@ -0,0 +1 @@
+sphinx-rtd-theme

include/lsquic.h

@@ -27,7 +27,7 @@ extern "C" {
 
 #define LSQUIC_MAJOR_VERSION 4
 #define LSQUIC_MINOR_VERSION 0
-#define LSQUIC_PATCH_VERSION 1
+#define LSQUIC_PATCH_VERSION 5
 
 /**
  * Engine flags:
@@ -318,7 +318,7 @@ typedef struct ssl_ctx_st * (*lsquic_lookup_cert_f)(
 #define LSQUIC_DF_STTL               86400
 #define LSQUIC_DF_MAX_INCHOATE     (1 * 1000 * 1000)
 
-#define LSQUIC_DF_SUPPORT_SREJ_SERVER  0
+#define LSQUIC_DF_SUPPORT_SREJ_SERVER  1
 #define LSQUIC_DF_SUPPORT_SREJ_CLIENT  0
 
 /** Do not use NSTP by default */

src/liblsquic/ls-qpack

@@ -1 +1 @@
-Subproject commit 19863c2ed8bf28d648213460093d1991def4e643
+Subproject commit 521792711f2839f05565fd3dd617708cfb5b80ee

src/liblsquic/lsquic_bbr.c

@@ -733,8 +733,8 @@ maybe_exit_startup_or_drain (struct lsquic_bbr *bbr, lsquic_time_t now,
     if (bbr->bbr_mode == BBR_MODE_DRAIN)
     {
         target_cwnd = get_target_cwnd(bbr, 1);
-        LSQ_DEBUG("%s: bytes in flight: %"PRIu64"; target cwnd: %"PRIu64,
-                                    __func__, bytes_in_flight, target_cwnd);
+        LSQ_DEBUG("bytes in flight: %"PRIu64"; target cwnd: %"PRIu64,
+                                    bytes_in_flight, target_cwnd);
         if (bytes_in_flight <= target_cwnd)
             enter_probe_bw_mode(bbr, now);
     }
@@ -799,9 +799,9 @@ maybe_enter_or_exit_probe_rtt (struct lsquic_bbr *bbr, lsquic_time_t now,
     if (bbr->bbr_mode == BBR_MODE_PROBE_RTT)
     {
         lsquic_bw_sampler_app_limited(&bbr->bbr_bw_sampler);
-        LSQ_DEBUG("%s: exit probe at: %"PRIu64"; now: %"PRIu64
+        LSQ_DEBUG("exit probe at: %"PRIu64"; now: %"PRIu64
             "; round start: %d; round passed: %d; rtt: %"PRIu64" usec",
-            __func__, bbr->bbr_exit_probe_rtt_at, now, is_round_start,
+            bbr->bbr_exit_probe_rtt_at, now, is_round_start,
             !!(bbr->bbr_flags & BBR_FLAG_PROBE_RTT_ROUND_PASSED),
             lsquic_rtt_stats_get_min_rtt(bbr->bbr_rtt_stats));
         if (bbr->bbr_exit_probe_rtt_at == 0)

src/liblsquic/lsquic_cubic.c

@@ -109,7 +109,7 @@ cubic_update (struct lsquic_cubic *cubic, lsquic_time_t now, unsigned n_bytes)
 void
 lsquic_cubic_set_flags (struct lsquic_cubic *cubic, enum cubic_flags flags)
 {
-    LSQ_DEBUG("%s(cubic, 0x%X)", __func__, flags);
+    LSQ_DEBUG("(cubic, 0x%X)", flags);
     cubic->cu_flags = flags;
 }
 
@@ -132,7 +132,7 @@ lsquic_cubic_init (void *cong_ctl, const struct lsquic_conn_public *conn_pub,
     else
 #endif
         cubic->cu_sampling_rate = 100000;
-    LSQ_DEBUG("%s(cubic, $conn)", __func__);
+    LSQ_DEBUG("(cubic, $conn)");
     LSQ_INFO("initialized");
 }
 
@@ -163,7 +163,7 @@ static void
 lsquic_cubic_was_quiet (void *cong_ctl, lsquic_time_t now, uint64_t in_flight)
 {
     struct lsquic_cubic *const cubic = cong_ctl;
-    LSQ_DEBUG("%s(cubic, %"PRIu64")", __func__, now);
+    LSQ_DEBUG("(cubic, %"PRIu64")", now);
     cubic->cu_epoch_start = 0;
 }
 
@@ -176,7 +176,7 @@ lsquic_cubic_ack (void *cong_ctl, struct lsquic_packet_out *packet_out,
     lsquic_time_t rtt;
 
     rtt = now_time - packet_out->po_sent;
-    LSQ_DEBUG("%s(cubic, %"PRIu64", %"PRIu64", %d, %u)", __func__, now_time, rtt,
+    LSQ_DEBUG("(cubic, %"PRIu64", %"PRIu64", %d, %u)", now_time, rtt,
                                                         app_limited, n_bytes);
     if (0 == cubic->cu_min_delay || rtt < cubic->cu_min_delay)
     {
@@ -203,7 +203,7 @@ static void
 lsquic_cubic_loss (void *cong_ctl)
 {
     struct lsquic_cubic *const cubic = cong_ctl;
-    LSQ_DEBUG("%s(cubic)", __func__);
+    LSQ_DEBUG("(cubic)");
     cubic->cu_epoch_start = 0;
     if (FAST_CONVERGENCE && cubic->cu_cwnd < cubic->cu_last_max_cwnd)
         cubic->cu_last_max_cwnd = cubic->cu_cwnd * TWO_MINUS_BETA_OVER_TWO / 1024;
@@ -225,7 +225,7 @@ lsquic_cubic_timeout (void *cong_ctl)
     unsigned long cwnd;
 
     cwnd = cubic->cu_cwnd;
-    LSQ_DEBUG("%s(cubic)", __func__);
+    LSQ_DEBUG("(cubic)");
     cubic_reset(cubic);
     cubic->cu_ssthresh = cwnd / 2;
     cubic->cu_tcp_cwnd = 2 * TCP_MSS;

src/liblsquic/lsquic_di_hash.c

@@ -443,7 +443,6 @@ hash_di_insert_frame (struct data_in *data_in,
     if (ins == INS_FRAME_OK)
     {
         lsquic_packet_in_put(hdi->hdi_conn_pub->mm, new_frame->packet_in);
-        lsquic_malo_put(new_frame);
     }
     return ins;
 }

src/liblsquic/lsquic_di_nocopy.c

@@ -386,7 +386,7 @@ nocopy_di_insert_frame (struct data_in *data_in,
     ins_case = insert_frame(ncdi, new_frame, read_offset, &count);
     ins = ins_case & 0xFF;
     ins_case >>= 8;
-    LSQ_DEBUG("%s: ins: %d (case '%c')", __func__, ins, (char) ins_case);
+    LSQ_DEBUG("ins: %d (case '%c')", ins, (char) ins_case);
     switch (ins)
     {
     case INS_FRAME_OK:

src/liblsquic/lsquic_enc_sess_ietf.c

@@ -1243,7 +1243,7 @@ setup_handshake_keys (struct enc_sess_iquic *enc_sess, const lsquic_cid_t *cid)
             hp->hp_flags |= 1 << i;
         else
         {
-            LSQ_ERROR("%s: cannot initialize cipher %u", __func__, i);
+            LSQ_ERROR("cannot initialize cipher %u", i);
             goto err;
         }
     }
@@ -1569,7 +1569,7 @@ iquic_ssl_sess_to_resume_info (struct enc_sess_iquic *enc_sess, SSL *ssl,
     if (!buf)
     {
         OPENSSL_free(ticket_buf);
-        LSQ_INFO("%s: malloc failed", __func__);
+        LSQ_INFO("malloc failed");
         return -1;
     }
 
@@ -2604,7 +2604,7 @@ iquic_esf_global_init (int flags)
     }
     else
     {
-        LSQ_LOG1(LSQ_LOG_ERROR, "%s: could not select index", __func__);
+        LSQ_LOG1(LSQ_LOG_ERROR, "could not select index");
         return -1;
     }
 }
@@ -3625,7 +3625,7 @@ lsquic_ssl_sess_to_resume_info (SSL *ssl, SSL_SESSION *session,
     status = iquic_ssl_sess_to_resume_info(enc_sess, ssl, session, buf, buf_sz);
     if (status == 0)
     {
-        LSQ_DEBUG("%s called successfully, unset WANT_TICKET flag", __func__);
+        LSQ_DEBUG("called successfully, unset WANT_TICKET flag");
         enc_sess->esi_flags &= ~ESI_WANT_TICKET;
         lsquic_alarmset_unset(enc_sess->esi_alset, AL_SESS_TICKET);
     }

src/liblsquic/lsquic_engine.c

@@ -963,7 +963,7 @@ destroy_conn (struct lsquic_engine *engine, struct lsquic_conn *conn,
     if (engine->busy.current == conn)
     {
         char cidstr[MAX_CID_LEN * 2 + 1];
-        lsquic_logger_log1(LSQ_LOG_NOTICE, LSQLM_CONN_STATS,
+        lsquic_logger_log1(LSQ_LOG_NOTICE, LSQLM_CONN_STATS, __func__,
             "busy connection %s is destroyed",
             (lsquic_cid2str(lsquic_conn_log_cid(conn), cidstr), cidstr));
         engine->busy.current = NULL;
@@ -1040,7 +1040,7 @@ maybe_grow_conn_heaps (struct lsquic_engine *engine)
     els = malloc(sizeof(els[0]) * count);
     if (!els)
     {
-        LSQ_ERROR("%s: malloc failed", __func__);
+        LSQ_ERROR("malloc failed");
         return -1;
     }
 
@@ -1942,7 +1942,7 @@ lsquic_engine_connect (lsquic_engine_t *engine, enum lsquic_version version,
 
     if (engine->flags & ENG_SERVER)
     {
-        LSQ_ERROR("`%s' must only be called in client mode", __func__);
+        LSQ_ERROR("must only be called in client mode");
         goto err;
     }
 
@@ -2894,7 +2894,7 @@ send_packets_out (struct lsquic_engine *engine,
 
     coi_reheap(&conns_iter, engine);
 
-    LSQ_DEBUG("%s: sent %u packet%.*s", __func__, n_sent, n_sent != 1, "s");
+    LSQ_DEBUG("sent %u packet%.*s", n_sent, n_sent != 1, "s");
 }
 
 
@@ -3008,7 +3008,7 @@ maybe_log_conn_stats (struct lsquic_engine *engine, struct lsquic_conn *conn,
     }
     else
     {
-        lsquic_logger_log1(LSQ_LOG_NOTICE, LSQLM_CONN_STATS,
+        lsquic_logger_log1(LSQ_LOG_NOTICE, LSQLM_CONN_STATS, __func__,
             "stop logging status for connection %s: no longer busy",
             (lsquic_cid2str(lsquic_conn_log_cid(conn), cidstr), cidstr));
         engine->busy.current = NULL;
@@ -3232,6 +3232,7 @@ lsquic_engine_packet_in (lsquic_engine_t *engine,
          * by PI_OWN_DATA flag.
          */
         packet_in->pi_data = (unsigned char *) packet_in_data;
+        packet_in->pi_pkt_size = packet_in_size;
         if (0 != parse_packet_in_begin(packet_in, packet_end - packet_in_data,
                                 engine->flags & ENG_SERVER,
                                 engine->pub.enp_settings.es_scid_len, &ppstate))
@@ -3332,7 +3333,7 @@ update_busy_detector (struct lsquic_engine *engine, struct lsquic_conn *conn,
         if (MAX_IMMED_TICKS == engine->busy.immed_ticks)
         {
             if (engine->busy.current != conn)
-                lsquic_logger_log1(LSQ_LOG_NOTICE, LSQLM_CONN_STATS,
+                lsquic_logger_log1(LSQ_LOG_NOTICE, LSQLM_CONN_STATS, __func__,
                     "connection %s marked busy: it's had %u immediate ticks "
                     "in a row",
                     (lsquic_cid2str(lsquic_conn_log_cid(conn), cidstr), cidstr),
@@ -3368,6 +3369,8 @@ lsquic_engine_earliest_adv_tick (lsquic_engine_t *engine, int *diff)
                                     && lsquic_mh_count(&engine->conns_out))
     {
 #if LSQUIC_DEBUG_NEXT_ADV_TICK
+    if (LSQ_LOG_ENABLED(L))
+    {
         conn = lsquic_mh_peek(&engine->conns_out);
         engine->last_logged_conn = 0;
         LSQ_LOGC(L, "next advisory tick is now: went past deadline last time "
@@ -3375,6 +3378,7 @@ lsquic_engine_earliest_adv_tick (lsquic_engine_t *engine, int *diff)
             lsquic_mh_count(&engine->conns_out),
             lsquic_mh_count(&engine->conns_out) != 1, "s",
             CID_BITS(lsquic_conn_log_cid(conn)));
+    }
 #endif
 #if LSQUIC_CONN_STATS
         conn = lsquic_mh_peek(&engine->conns_out);
@@ -3388,8 +3392,11 @@ lsquic_engine_earliest_adv_tick (lsquic_engine_t *engine, int *diff)
         && engine->pr_queue && lsquic_prq_have_pending(engine->pr_queue))
     {
 #if LSQUIC_DEBUG_NEXT_ADV_TICK
+    if (LSQ_LOG_ENABLED(L))
+    {
         engine->last_logged_conn = 0;
         LSQ_LOG(L, "next advisory tick is now: have pending PRQ elements");
+    }
 #endif
         *diff = 0;
         return 1;
@@ -3398,6 +3405,8 @@ lsquic_engine_earliest_adv_tick (lsquic_engine_t *engine, int *diff)
     if (lsquic_mh_count(&engine->conns_tickable))
     {
 #if LSQUIC_DEBUG_NEXT_ADV_TICK
+    if (LSQ_LOG_ENABLED(L))
+    {
         conn = lsquic_mh_peek(&engine->conns_tickable);
         engine->last_logged_conn = 0;
         LSQ_LOGC(L, "next advisory tick is now: have %u tickable "
@@ -3405,6 +3414,7 @@ lsquic_engine_earliest_adv_tick (lsquic_engine_t *engine, int *diff)
             lsquic_mh_count(&engine->conns_tickable),
             lsquic_mh_count(&engine->conns_tickable) != 1, "s",
             CID_BITS(lsquic_conn_log_cid(conn)));
+    }
 #endif
 #if LSQUIC_CONN_STATS
         conn = lsquic_mh_peek(&engine->conns_tickable);
@@ -3440,28 +3450,31 @@ lsquic_engine_earliest_adv_tick (lsquic_engine_t *engine, int *diff)
     now = lsquic_time_now();
     *diff = (int) ((int64_t) next_time - (int64_t) now);
 #if LSQUIC_DEBUG_NEXT_ADV_TICK
-    if (next_attq)
+    if (LSQ_LOG_ENABLED(L))
     {
-        /* Deduplicate consecutive log messages about the same reason for the
-         * same connection.
-         * If diff is always zero or diff reset to a higher value, event is
-         * still logged.
-         */
-        if (!((unsigned) next_attq->ae_why == engine->last_logged_ae_why
-                    && (uintptr_t) next_attq->ae_conn
-                                            == engine->last_logged_conn
-                    && *diff < engine->last_tick_diff))
+        if (next_attq)
         {
-            engine->last_logged_conn = (uintptr_t) next_attq->ae_conn;
-            engine->last_logged_ae_why = (unsigned) next_attq->ae_why;
-            engine->last_tick_diff = *diff;
-            LSQ_LOGC(L, "next advisory tick is %d usec away: conn %"CID_FMT
-                ": %s", *diff, CID_BITS(lsquic_conn_log_cid(next_attq->ae_conn)),
-                lsquic_attq_why2str(next_attq->ae_why));
+            /* Deduplicate consecutive log messages about the same reason for the
+             * same connection.
+             * If diff is always zero or diff reset to a higher value, event is
+             * still logged.
+             */
+            if (!((unsigned) next_attq->ae_why == engine->last_logged_ae_why
+                        && (uintptr_t) next_attq->ae_conn
+                                                == engine->last_logged_conn
+                        && *diff < engine->last_tick_diff))
+            {
+                engine->last_logged_conn = (uintptr_t) next_attq->ae_conn;
+                engine->last_logged_ae_why = (unsigned) next_attq->ae_why;
+                engine->last_tick_diff = *diff;
+                LSQ_LOGC(L, "next advisory tick is %d usec away: conn %"CID_FMT
+                    ": %s", *diff, CID_BITS(lsquic_conn_log_cid(next_attq->ae_conn)),
+                    lsquic_attq_why2str(next_attq->ae_why));
+            }
         }
+        else
+            LSQ_LOG(L, "next advisory tick is %d usec away: resume sending", *diff);
     }
-    else
-        LSQ_LOG(L, "next advisory tick is %d usec away: resume sending", *diff);
 #endif
 
 #if LSQUIC_CONN_STATS

src/liblsquic/lsquic_ev_log.h

@@ -23,13 +23,15 @@ struct stack_st_X509;
 /* Log a generic event not tied to any particular connection */
 #define EV_LOG_GENERIC_EVENT(...) do {                                      \
     if (LSQ_LOG_ENABLED_EXT(LSQ_LOG_DEBUG, LSQLM_EVENT))                    \
-        lsquic_logger_log1(LSQ_LOG_DEBUG, LSQLM_EVENT, __VA_ARGS__);        \
+        lsquic_logger_log1(LSQ_LOG_DEBUG, LSQLM_EVENT, 						\
+        					__func__, __VA_ARGS__);        					\
 } while (0)
 
 /* Log a generic event associated with connection `cid' */
 #define EV_LOG_CONN_EVENT(cid, ...) do {                                    \
     if (LSQ_LOG_ENABLED_EXT(LSQ_LOG_DEBUG, LSQLM_EVENT))                    \
-        lsquic_logger_log2(LSQ_LOG_DEBUG, LSQLM_EVENT, cid, __VA_ARGS__);   \
+        lsquic_logger_log2(LSQ_LOG_DEBUG, LSQLM_EVENT, cid, 				\
+        					__func__, __VA_ARGS__);   						\
 } while (0)
 
 void

src/liblsquic/lsquic_frame_reader.c

@@ -230,12 +230,12 @@ lsquic_frame_reader_destroy (struct lsquic_frame_reader *fr)
     assert(nread <= 0);                                                 \
     if (0 == nread)                                                     \
     {                                                                   \
-        LSQ_INFO("%s: unexpected EOF", __func__);                        \
+        LSQ_INFO("unexpected EOF");                                     \
         return -1;                                                      \
     }                                                                   \
     else                                                                \
     {                                                                   \
-        LSQ_WARN("%s: error reading from stream: %s", __func__,          \
+        LSQ_WARN("error reading from stream: %s",                   \
             strerror(errno));                                           \
         return -1;                                                      \
     }                                                                   \
@@ -690,7 +690,7 @@ decode_and_pass_payload (struct lsquic_frame_reader *fr)
     return;
 
   stream_error:
-    LSQ_INFO("%s: stream error %u", __func__, err);
+    LSQ_INFO("stream error %u", err);
     if (hset)
         fr->fr_hsi_if->hsi_discard_header_set(hset);
     fr->fr_callbacks->frc_on_error(fr->fr_cb_ctx, fr_get_stream_id(fr), err);

src/liblsquic/lsquic_full_conn.c

@@ -904,12 +904,12 @@ lsquic_gquic_full_conn_server_new (struct lsquic_engine_public *enpub,
 
     for (n = 0; received; ++n)
     {
-        if (received & (1U << n))
+        if (received & (1ULL << n))
             /* Setting `now' to zero is OK here, as we should have had at
              * least one other packet above.
              */
             lsquic_rechist_received(&conn->fc_rechist, n + 1, 0);
-        received &= ~(1U << n);
+        received &= ~(1ULL << n);
     }
 
     /* Mini connection sends out packets 1, 2, 3... and so on.  It deletes
@@ -2951,7 +2951,7 @@ create_delayed_streams (struct full_conn *conn)
     new_streams = malloc(sizeof(new_streams[0]) * avail);
     if (!new_streams)
     {
-        ABORT_WARN("%s: malloc failed", __func__);
+        ABORT_WARN("malloc failed");
         return;
     }
 
@@ -2964,8 +2964,7 @@ create_delayed_streams (struct full_conn *conn)
         new_streams[i] = new_stream(conn, generate_stream_id(conn), 0);
         if (!new_streams[i])
         {
-            ABORT_ERROR("%s: cannot create new stream: %s", __func__,
-                                                        strerror(errno));
+            ABORT_ERROR("cannot create new stream: %s", strerror(errno));
             goto cleanup;
         }
     }
@@ -3262,7 +3261,7 @@ immediate_close (struct full_conn *conn)
                      lsquic_packet_out_avail(packet_out), 0, error_code,
                      error_reason, error_reason ? strlen(error_reason) : 0);
     if (sz < 0) {
-        LSQ_WARN("%s failed", __func__);
+        LSQ_WARN("failed");
         return TICK_CLOSE;
     }
     lsquic_send_ctl_incr_pack_sz(&conn->fc_send_ctl, packet_out, sz);
@@ -4365,8 +4364,7 @@ full_conn_ci_next_tick_time (lsquic_conn_t *lconn, unsigned *why)
     {
         now = lsquic_time_now();
         if (pacer_time < now)
-            LSQ_DEBUG("%s: pacer is %"PRIu64" usec in the past", __func__,
-                                                            now - pacer_time);
+            LSQ_DEBUG("pacer is %"PRIu64" usec in the past", now - pacer_time);
     }
 
     if (alarm_time && pacer_time)
@@ -4500,7 +4498,7 @@ full_conn_ci_log_stats (struct lsquic_conn *lconn)
     cwnd = conn->fc_send_ctl.sc_ci->cci_get_cwnd(
                                             conn->fc_send_ctl.sc_cong_ctl);
     lsquic_conn_stats_diff(&conn->fc_stats, conn->fc_last_stats, &diff_stats);
-    lsquic_logger_log1(LSQ_LOG_NOTICE, LSQLM_CONN_STATS,
+    lsquic_logger_log1(LSQ_LOG_NOTICE, LSQLM_CONN_STATS, __func__,
         "%s: ticks: %lu; cwnd: %"PRIu64"; conn flow: max: %"PRIu64
         ", avail: %"PRIu64"; packets: sent: %lu, lost: %lu, retx: %lu, rcvd: %lu"
         "; batch: count: %u; min: %u; max: %u; avg: %.2f",

src/liblsquic/lsquic_full_conn_ietf.c

@@ -453,6 +453,7 @@ struct ietf_full_conn
     unsigned                    ifc_n_slack_akbl[N_PNS];
     unsigned                    ifc_n_slack_all;    /* App PNS only */
     unsigned                    ifc_max_retx_since_last_ack;
+    unsigned short              ifc_max_udp_payload;    /* Cached TP */
     lsquic_time_t               ifc_max_ack_delay;
     uint64_t                    ifc_ecn_counts_in[N_PNS][4];
     lsquic_stream_id_t          ifc_max_req_id;
@@ -491,7 +492,8 @@ struct ietf_full_conn
     unsigned                    ifc_max_pack_tol_sent;
 #endif
     unsigned                    ifc_max_ack_freq_seqno; /* Incoming */
-    unsigned short              ifc_max_udp_payload;    /* Cached TP */
+    unsigned short              ifc_min_dg_sz,
+                                ifc_max_dg_sz;
     lsquic_time_t               ifc_last_live_update;
     struct conn_path            ifc_paths[N_PATHS];
     union {
@@ -520,8 +522,6 @@ struct ietf_full_conn
     lsquic_time_t               ifc_ping_period;
     struct lsquic_hash         *ifc_bpus;
     uint64_t                    ifc_last_max_data_off_sent;
-    unsigned short              ifc_min_dg_sz,
-                                ifc_max_dg_sz;
     struct packet_tolerance_stats
                                 ifc_pts;
 #if LSQUIC_CONN_STATS
@@ -695,7 +695,7 @@ cid_throt_alarm_expired (enum alarm_id al_id, void *ctx,
                                     lsquic_time_t expiry, lsquic_time_t now)
 {
     struct ietf_full_conn *const conn = (struct ietf_full_conn *) ctx;
-    LSQ_DEBUG("%s", __func__);
+    LSQ_DEBUG("called");
     conn->ifc_send_flags |= SF_SEND_NEW_CID;
     return;
 }
@@ -755,6 +755,7 @@ blocked_ka_alarm_expired (enum alarm_id al_id, void *ctx,
     struct ietf_full_conn *const conn = (struct ietf_full_conn *) ctx;
     struct lsquic_stream *stream;
     struct lsquic_hash_elem *el;
+    int has_send_flag;
 
     if (lsquic_conn_cap_avail(&conn->ifc_pub.conn_cap) == 0)
     {
@@ -767,13 +768,21 @@ blocked_ka_alarm_expired (enum alarm_id al_id, void *ctx,
                          el = lsquic_hash_next(conn->ifc_pub.all_streams))
     {
         stream = lsquic_hashelem_getdata(el);
-        if (lsquic_stream_is_blocked(stream))
+        if (lsquic_stream_is_blocked(stream)
+            && !lsquic_stream_is_write_reset(stream))
         {
-            if (!(stream->sm_qflags & SMQF_SENDING_FLAGS))
-                TAILQ_INSERT_TAIL(&conn->ifc_pub.sending_streams, stream,
-                                                            next_send_stream);
+            has_send_flag = (stream->sm_qflags & SMQF_SENDING_FLAGS);
             stream->sm_qflags |= SMQF_SEND_BLOCKED;
             LSQ_DEBUG("set SEND_BLOCKED flag on stream %"PRIu64, stream->id);
+            if (!lsquic_sendctl_gen_stream_blocked_frame(
+                        stream->conn_pub->send_ctl, stream))
+            {
+                LSQ_DEBUG("failed to send STREAM_BLOCKED frame for"
+                        " stream %"PRIu64 " immedately, postpone.", stream->id);
+                if (!has_send_flag)
+                    TAILQ_INSERT_TAIL(&conn->ifc_pub.sending_streams, stream,
+                                                            next_send_stream);
+            }
             return;
         }
     }
@@ -1794,7 +1803,7 @@ generate_timestamp_frame (struct ietf_full_conn *conn,
     if (0 != lsquic_packet_out_add_frame(packet_out, conn->ifc_pub.mm, 0,
                             QUIC_FRAME_TIMESTAMP, packet_out->po_data_sz, w))
     {
-        LSQ_DEBUG("%s: adding frame to packet failed: %d", __func__, errno);
+        LSQ_DEBUG("adding frame to packet failed: %d", errno);
         return;
     }
     packet_out->po_frame_types |= 1 << QUIC_FRAME_TIMESTAMP;
@@ -2491,46 +2500,6 @@ generate_max_stream_data_frame (struct ietf_full_conn *conn,
 }
 
 
-/* Return true if generated, false otherwise */
-static int
-generate_stream_blocked_frame (struct ietf_full_conn *conn,
-                                                struct lsquic_stream *stream)
-{
-    struct lsquic_packet_out *packet_out;
-    unsigned need;
-    uint64_t off;
-    int sz;
-
-    off = lsquic_stream_combined_send_off(stream);
-    need = conn->ifc_conn.cn_pf->pf_stream_blocked_frame_size(stream->id, off);
-    packet_out = get_writeable_packet(conn, need);
-    if (!packet_out)
-        return 0;
-    sz = conn->ifc_conn.cn_pf->pf_gen_stream_blocked_frame(
-                         packet_out->po_data + packet_out->po_data_sz,
-                         lsquic_packet_out_avail(packet_out), stream->id, off);
-    if (sz < 0)
-    {
-        ABORT_ERROR("Generating STREAM_BLOCKED frame failed");
-        return 0;
-    }
-    LSQ_DEBUG("generated %d-byte STREAM_BLOCKED "
-        "frame; stream_id: %"PRIu64"; offset: %"PRIu64, sz, stream->id, off);
-    EV_LOG_CONN_EVENT(LSQUIC_LOG_CONN_ID, "generated %d-byte STREAM_BLOCKED "
-        "frame; stream_id: %"PRIu64"; offset: %"PRIu64, sz, stream->id, off);
-    if (0 != lsquic_packet_out_add_frame(packet_out, conn->ifc_pub.mm, 0,
-                        QUIC_FRAME_STREAM_BLOCKED, packet_out->po_data_sz, sz))
-    {
-        ABORT_ERROR("adding frame to packet failed: %d", errno);
-        return 0;
-    }
-    lsquic_send_ctl_incr_pack_sz(&conn->ifc_send_ctl, packet_out, sz);
-    packet_out->po_frame_types |= 1 << QUIC_FRAME_STREAM_BLOCKED;
-    lsquic_stream_blocked_frame_sent(stream);
-    return 1;
-}
-
-
 static int
 generate_stop_sending_frame_by_id (struct ietf_full_conn *conn,
                 lsquic_stream_id_t stream_id, enum http_error_code error_code)
@@ -2915,10 +2884,26 @@ process_stream_ready_to_send (struct ietf_full_conn *conn,
                                             struct lsquic_stream *stream)
 {
     int r = 1;
+
+    LSQ_DEBUG("process_stream_ready_to_send: stream: %"PRIu64", "
+              "sm_qflags: %d. stream_flags: %d, sm_bflags: %d, ", stream->id,
+              stream->sm_qflags, stream->stream_flags, stream->sm_bflags);
+
     if (stream->sm_qflags & SMQF_SEND_MAX_STREAM_DATA)
         r &= generate_max_stream_data_frame(conn, stream);
     if (stream->sm_qflags & SMQF_SEND_BLOCKED)
-        r &= generate_stream_blocked_frame(conn, stream);
+    {
+        if (lsquic_stream_is_write_reset(stream))
+        {
+            stream->sm_qflags &= ~SMQF_SEND_BLOCKED;
+            if (!(stream->sm_qflags & SMQF_SENDING_FLAGS))
+                TAILQ_REMOVE(&stream->conn_pub->sending_streams, stream,
+                             next_send_stream);
+        }
+        else
+            r &= lsquic_sendctl_gen_stream_blocked_frame(&conn->ifc_send_ctl,
+                                                         stream);
+    }
     if (stream->sm_qflags & SMQF_SEND_RST)
         r &= generate_rst_stream_frame(conn, stream);
     if (stream->sm_qflags & SMQF_SEND_STOP_SENDING)
@@ -3062,7 +3047,7 @@ retire_seqno (struct ietf_full_conn *conn, unsigned seqno)
         conn->ifc_send_flags |= SF_SEND_RETIRE_CID;
     }
     else
-        LSQ_INFO("%s: cannot allocate dce", __func__);
+        LSQ_INFO("cannot allocate dce");
 }
 
 
@@ -3097,7 +3082,7 @@ ietf_full_conn_ci_retire_cid (struct lsquic_conn *lconn)
         }
     if (!dces[1])
     {
-        ABORT_WARN("%s: cannot find own DCID", __func__);
+        ABORT_WARN("cannot find own DCID");
         return;
     }
     if (!dces[0])
@@ -4322,13 +4307,13 @@ immediate_close (struct ietf_full_conn *conn)
                      conn_err.u.err, error_reason,
                      error_reason ? strlen(error_reason) : 0);
     if (sz < 0) {
-        LSQ_WARN("%s failed", __func__);
+        LSQ_WARN("failed");
         return TICK_CLOSE;
     }
     if (0 != lsquic_packet_out_add_frame(packet_out, conn->ifc_pub.mm, 0,
                     QUIC_FRAME_CONNECTION_CLOSE, packet_out->po_data_sz, sz))
     {
-        LSQ_WARN("%s: adding frame to packet failed: %d", __func__, errno);
+        LSQ_WARN("adding frame to packet failed: %d", errno);
         return TICK_CLOSE;
     }
     lsquic_send_ctl_incr_pack_sz(&conn->ifc_send_ctl, packet_out, sz);
@@ -4898,8 +4883,7 @@ ietf_full_conn_ci_next_tick_time (struct lsquic_conn *lconn, unsigned *why)
     {
         now = lsquic_time_now();
         if (pacer_time < now)
-            LSQ_DEBUG("%s: pacer is %"PRIu64" usec in the past", __func__,
-                                                            now - pacer_time);
+            LSQ_DEBUG("pacer is %"PRIu64" usec in the past", now - pacer_time);
     }
 
     if (alarm_time && pacer_time)
@@ -7188,15 +7172,14 @@ verify_retry_packet (struct ietf_full_conn *conn,
         /* Cover the theoretical possibility that we cannot fit the pseudo-
          * packet and 16-byte decrypted output into 4 KB:
          */
-        LSQ_INFO("%s: Retry packet is too long: %hu bytes", __func__,
-                                                        packet_in->pi_data_sz);
+        LSQ_INFO("Retry packet is too long: %hu bytes", packet_in->pi_data_sz);
         return -1;
     }
 
     pseudo_packet = lsquic_mm_get_4k(conn->ifc_pub.mm);
     if (!pseudo_packet)
     {
-        LSQ_INFO("%s: cannot allocate memory", __func__);
+        LSQ_INFO("cannot allocate memory");
         return -1;
     }
 
@@ -7316,7 +7299,8 @@ on_dcid_change (struct ietf_full_conn *conn, const lsquic_cid_t *dcid_in)
     struct lsquic_conn *const lconn = &conn->ifc_conn;  /* Shorthand */
     struct conn_cid_elem *cce;
 
-    LSQ_DEBUG("peer switched its DCID, attempt to switch own SCID");
+    LSQ_DEBUGC("peer switched its DCID to %"CID_FMT
+              ", attempt to switch own SCID", CID_BITS(dcid_in));
 
     for (cce = lconn->cn_cces; cce < END_OF_CCES(lconn); ++cce)
         if (cce - lconn->cn_cces != lconn->cn_cur_cce_idx
@@ -7340,7 +7324,7 @@ on_dcid_change (struct ietf_full_conn *conn, const lsquic_cid_t *dcid_in)
 
     cce->cce_flags |= CCE_USED;
     lconn->cn_cur_cce_idx = cce - lconn->cn_cces;
-    LSQ_DEBUGC("%s: set SCID to %"CID_FMT, __func__, CID_BITS(CN_SCID(lconn)));
+    LSQ_DEBUGC("set SCID to %"CID_FMT, CID_BITS(CN_SCID(lconn)));
     LOG_SCIDS(conn);
 
     return 0;
@@ -7427,6 +7411,7 @@ process_regular_packet (struct ietf_full_conn *conn,
     enum was_missing was_missing;
     int is_rechist_empty;
     unsigned char saved_path_id;
+    int is_dcid_changed;
 
     if (HETY_RETRY == packet_in->pi_header_type)
         return process_retry_packet(conn, packet_in);
@@ -7529,12 +7514,31 @@ process_regular_packet (struct ietf_full_conn *conn,
         }
     }
 
+    is_dcid_changed = !LSQUIC_CIDS_EQ(CN_SCID(&conn->ifc_conn),
+                                        &packet_in->pi_dcid);
     if (pns == PNS_INIT)
         conn->ifc_conn.cn_esf.i->esfi_set_iscid(conn->ifc_conn.cn_enc_session,
                                                                     packet_in);
-    else if (pns == PNS_HSK)
-        lsquic_send_ctl_maybe_calc_rough_rtt(&conn->ifc_send_ctl, pns - 1);
-
+    else
+    {
+        if (is_dcid_changed)
+        {
+            if (LSQUIC_CIDS_EQ(&conn->ifc_conn.cn_cces[0].cce_cid,
+                            &packet_in->pi_dcid)
+                && !(conn->ifc_conn.cn_cces[0].cce_flags & CCE_SEQNO))
+            {
+                ABORT_QUIETLY(0, TEC_PROTOCOL_VIOLATION,
+                            "protocol violation detected bad dcid");
+                return -1;
+            }
+        }
+        if (pns == PNS_HSK)
+        {
+            if ((conn->ifc_flags & (IFC_SERVER | IFC_IGNORE_INIT)) == IFC_SERVER)
+                ignore_init(conn);
+            lsquic_send_ctl_maybe_calc_rough_rtt(&conn->ifc_send_ctl, pns - 1);
+        }
+    }
     EV_LOG_PACKET_IN(LSQUIC_LOG_CONN_ID, packet_in);
 
     is_rechist_empty = lsquic_rechist_is_empty(&conn->ifc_rechist[pns]);
@@ -7558,8 +7562,9 @@ process_regular_packet (struct ietf_full_conn *conn,
                                                     << packet_in->pi_path_id);
                 }
             }
-            else if (!LSQUIC_CIDS_EQ(CN_SCID(&conn->ifc_conn),
-                                                    &packet_in->pi_dcid))
+            else if (is_dcid_changed
+                && !LSQUIC_CIDS_EQ(CN_SCID(&conn->ifc_conn),
+                                   &packet_in->pi_dcid))
             {
                 if (0 != on_dcid_change(conn, &packet_in->pi_dcid))
                     return -1;
@@ -7934,7 +7939,7 @@ ietf_full_conn_ci_packet_sent (struct lsquic_conn *lconn,
     struct ietf_full_conn *const conn = (struct ietf_full_conn *) lconn;
     int s;
 
-    if (packet_out->po_frame_types & IQUIC_FRAME_RETX_MASK)
+    if (packet_out->po_frame_types & (IQUIC_FRAME_RETX_MASK | QUIC_FTBIT_ACK))
         conn->ifc_n_cons_unretx = 0;
     else
         ++conn->ifc_n_cons_unretx;
@@ -8966,7 +8971,7 @@ ietf_full_conn_ci_log_stats (struct lsquic_conn *lconn)
     cwnd = conn->ifc_send_ctl.sc_ci->cci_get_cwnd(
                                             conn->ifc_send_ctl.sc_cong_ctl);
     lsquic_conn_stats_diff(&conn->ifc_stats, conn->ifc_last_stats, &diff_stats);
-    lsquic_logger_log1(LSQ_LOG_NOTICE, LSQLM_CONN_STATS,
+    lsquic_logger_log1(LSQ_LOG_NOTICE, LSQLM_CONN_STATS, __func__,
         "%s: ticks: %lu; cwnd: %"PRIu64"; conn flow: max: %"PRIu64
         ", avail: %"PRIu64"; packets: sent: %lu, lost: %lu, retx: %lu, rcvd: %lu"
         "; batch: count: %u; min: %u; max: %u; avg: %.2f",

src/liblsquic/lsquic_handshake.c

@@ -1880,7 +1880,7 @@ get_valid_scfg (const struct lsquic_enc_session *enc_session,
 
     temp_scfg->scfg_len = MSG_LEN_VAL(msg_len);
 
-    LSQ_DEBUG("%s called, return len %d.", __func__, temp_scfg->scfg_len);
+    LSQ_DEBUG("called, return len %d.", temp_scfg->scfg_len);
 
 //     /* TODO: will shi_delete call free to release the buffer? */
 //     shi->shi_delete(shi_ctx, SERVER_SCFG_KEY, SERVER_SCFG_KEY_SIZE);
@@ -2870,8 +2870,7 @@ lsquic_enc_session_handle_chlo_reply (enc_session_t *enc_session_p,
 
   end:
     LSQ_DEBUG("lsquic_enc_session_handle_chlo_reply called, buf in %d, return %d.", len, ret);
-    EV_LOG_CONN_EVENT(&enc_session->cid, "%s returning %s", __func__,
-                                                                he2str(ret));
+    EV_LOG_CONN_EVENT(&enc_session->cid, "returning %s", he2str(ret));
     return ret;
 }
 
@@ -3226,9 +3225,9 @@ gquic_encrypt_buf (struct lsquic_enc_session *enc_session,
     EVP_AEAD_CTX *key;
 
     if (enc_session)
-        LSQ_DEBUG("%s: hsk_state: %d", __func__, enc_session->hsk_state);
+        LSQ_DEBUG("hsk_state: %d", enc_session->hsk_state);
     else
-        LSQ_DEBUG("%s: enc_session is not set", __func__);
+        LSQ_DEBUG("enc_session is not set");
 
     if (!enc_session || enc_session->have_key == 0 || is_chlo)
     {
@@ -3361,8 +3360,7 @@ lsquic_enc_session_handle_chlo(enc_session_t *enc_session_p,
     }
 
   end:
-    EV_LOG_CONN_EVENT(&enc_session->cid, "%s returning %s", __func__,
-                                                            he2str(rtt));
+    EV_LOG_CONN_EVENT(&enc_session->cid, "returning %s", he2str(rtt));
     return rtt;
 }
 

src/liblsquic/lsquic_hpi.c

@@ -327,8 +327,7 @@ lsquic_hpi_next (void *iter_p)
         stream = next_nonincr(iter, prio);
 
     if (LSQ_LOG_ENABLED(LSQ_LOG_DEBUG))
-        HPI_DEBUG("%s: return stream %"PRIu64", incr: %u, priority %u",
-                                            __func__, stream->id, incr, prio);
+        HPI_DEBUG("return stream %"PRIu64", incr: %u, priority %u", stream->id, incr, prio);
     return stream;
 }
 

src/liblsquic/lsquic_logger.c

@@ -245,7 +245,7 @@ void
 lsquic_logger_log3 (enum lsq_log_level log_level,
                     enum lsquic_logger_module module,
                     const lsquic_cid_t *conn_id, lsquic_stream_id_t stream_id,
-                    const char *fmt, ...)
+                    const char *caller, const char *fmt, ...)
 {
     const int saved_errno = errno;
     char cidbuf_[MAX_CID_LEN * 2 + 1];
@@ -261,9 +261,9 @@ lsquic_logger_log3 (enum lsq_log_level log_level,
             goto end;
         len += lb;
     }
-    lb = snprintf(buf + len, max - len, "[%s] [QUIC:%"CID_FMT"-%"PRIu64"] %s: ",
+    lb = snprintf(buf + len, max - len, "[%s] [QUIC:%"CID_FMT"-%"PRIu64"] %s::%s: ",
         lsq_loglevel2str[log_level], CID_BITS(conn_id),
-        stream_id, lsqlm_to_str[module]);
+        stream_id, lsqlm_to_str[module], caller);
     if (FORMAT_PROBLEM(lb, len, max))
         goto end;
     len += lb;
@@ -292,7 +292,8 @@ end:
 void
 lsquic_logger_log2 (enum lsq_log_level log_level,
                     enum lsquic_logger_module module,
-                    const struct lsquic_cid *conn_id, const char *fmt, ...)
+                    const struct lsquic_cid *conn_id, const char *caller,
+                    const char *fmt, ...)
 {
     const int saved_errno = errno;
     char cidbuf_[MAX_CID_LEN * 2 + 1];
@@ -309,8 +310,8 @@ lsquic_logger_log2 (enum lsq_log_level log_level,
         len += lb;
     }
 
-    lb = snprintf(buf + len, max - len, "[%s] [QUIC:%"CID_FMT"] %s: ",
-        lsq_loglevel2str[log_level], CID_BITS(conn_id), lsqlm_to_str[module]);
+    lb = snprintf(buf + len, max - len, "[%s] [QUIC:%"CID_FMT"] %s::%s: ",
+        lsq_loglevel2str[log_level], CID_BITS(conn_id), lsqlm_to_str[module], caller);
     if (FORMAT_PROBLEM(lb, len, max))
         goto end;
     len += lb;
@@ -339,7 +340,7 @@ end:
 void
 lsquic_logger_log1 (enum lsq_log_level log_level,
                     enum lsquic_logger_module module,
-                    const char *fmt, ...)
+                    const char *caller, const char *fmt, ...)
 {
     const int saved_errno = errno;
     size_t len = 0;
@@ -354,8 +355,8 @@ lsquic_logger_log1 (enum lsq_log_level log_level,
             goto end;
         len += lb;
     }
-    lb = snprintf(buf + len, max - len, "[%s] %s: ", lsq_loglevel2str[log_level],
-                                                lsqlm_to_str[module]);
+    lb = snprintf(buf + len, max - len, "[%s] %s::%s: ", lsq_loglevel2str[log_level],
+                                                lsqlm_to_str[module], caller);
     if (FORMAT_PROBLEM(lb, len, max))
         goto end;
     len += lb;
@@ -382,7 +383,8 @@ end:
 
 
 void
-lsquic_logger_log0 (enum lsq_log_level log_level, const char *fmt, ...)
+lsquic_logger_log0 (enum lsq_log_level log_level, const char *caller,
+					const char *fmt, ...)
 {
     const int saved_errno = errno;
     size_t len = 0;
@@ -398,7 +400,7 @@ lsquic_logger_log0 (enum lsq_log_level log_level, const char *fmt, ...)
         len += lb;
     }
 
-    lb = snprintf(buf + len, max - len, "[%s] ", lsq_loglevel2str[log_level]);
+    lb = snprintf(buf + len, max - len, "[%s] %s: ", lsq_loglevel2str[log_level], caller);
     if (FORMAT_PROBLEM(lb, len, max))
         goto end;
     len += lb;
@@ -432,7 +434,7 @@ lsquic_logger_init (const struct lsquic_logger_if *lif, void *lctx,
     logger_ctx = lctx;
     if (llts < N_LLTS)
         g_llts = llts;
-    LSQ_DEBUG("%s called", __func__);
+    LSQ_DEBUG("called");
 }
 
 

src/liblsquic/lsquic_logger.h

@@ -129,73 +129,81 @@ struct lsquic_cid;
 void
 lsquic_logger_log3 (enum lsq_log_level, enum lsquic_logger_module,
                     const struct lsquic_cid *conn_id,
-                    lsquic_stream_id_t stream_id, const char *format, ...)
+                    lsquic_stream_id_t stream_id, const char *caller,
+                    const char *format, ...)
 #if __GNUC__
-            __attribute__((format(printf, 5, 6)))
+            __attribute__((format(printf, 6, 7)))
 #endif
 ;
 #   define LSQ_LOG3(level, ...) do {                                         \
         if (LSQ_LOG_ENABLED(level))                                          \
             lsquic_logger_log3(level, LSQUIC_LOGGER_MODULE,                  \
-                    LSQUIC_LOG_CONN_ID, LSQUIC_LOG_STREAM_ID, __VA_ARGS__);  \
+                    LSQUIC_LOG_CONN_ID, LSQUIC_LOG_STREAM_ID, __func__,		 \
+                    __VA_ARGS__);											 \
     } while (0)
 
 
 void
 lsquic_logger_log2 (enum lsq_log_level, enum lsquic_logger_module,
-                    const struct lsquic_cid *conn_id, const char *format, ...)
+                    const struct lsquic_cid *conn_id, const char *caller,
+                    const char *format, ...)
 #if __GNUC__
-            __attribute__((format(printf, 4, 5)))
+            __attribute__((format(printf, 5, 6)))
 #endif
 ;
 #   define LSQ_LOG2(level, ...) do {                                         \
         if (LSQ_LOG_ENABLED(level))                                          \
             lsquic_logger_log2(level, LSQUIC_LOGGER_MODULE,                  \
-                                       LSQUIC_LOG_CONN_ID, __VA_ARGS__);     \
+                                       LSQUIC_LOG_CONN_ID, __func__,		 \
+                                       __VA_ARGS__);					     \
     } while (0)
 #   define LSQ_LOG2C(level, ...) do {                                        \
         if (LSQ_LOG_ENABLED(level))                                          \
         {                                                                    \
             char cidbuf_[MAX_CID_LEN * 2 + 1];                               \
             lsquic_logger_log2(level, LSQUIC_LOGGER_MODULE,                  \
-                                       LSQUIC_LOG_CONN_ID, __VA_ARGS__);     \
+                                       LSQUIC_LOG_CONN_ID, __func__,		 \
+                                       __VA_ARGS__);					     \
         }                                                                    \
     } while (0)
 
 void
 lsquic_logger_log1 (enum lsq_log_level, enum lsquic_logger_module,
-                    const char *format, ...)
+                    const char *caller, const char *format, ...)
 #if __GNUC__
-            __attribute__((format(printf, 3, 4)))
+            __attribute__((format(printf, 4, 5)))
 #endif
 ;
 #   define LSQ_LOG1(level, ...) do {                                         \
         if (LSQ_LOG_ENABLED(level))                                          \
-            lsquic_logger_log1(level, LSQUIC_LOGGER_MODULE, __VA_ARGS__);    \
+            lsquic_logger_log1(level, LSQUIC_LOGGER_MODULE,					 \
+            __func__, __VA_ARGS__);										     \
     } while (0)
 #   define LSQ_LOG1C(level, ...) do {                                        \
         if (LSQ_LOG_ENABLED(level))                                          \
         {                                                                    \
             char cidbuf_[MAX_CID_LEN * 2 + 1];                               \
-            lsquic_logger_log1(level, LSQUIC_LOGGER_MODULE, __VA_ARGS__);    \
+            lsquic_logger_log1(level, LSQUIC_LOGGER_MODULE,					 \
+            __func__, __VA_ARGS__);										     \
         }                                                                    \
     } while (0)
 
 void
-lsquic_logger_log0 (enum lsq_log_level, const char *format, ...)
+lsquic_logger_log0 (enum lsq_log_level, const char *caller,
+					const char *format, ...)
 #if __GNUC__
-            __attribute__((format(printf, 2, 3)))
+            __attribute__((format(printf, 3, 4)))
 #endif
 ;
 #   define LSQ_LOG0(level, ...) do {                                         \
         if (LSQ_LOG_ENABLED(level))                                          \
-            lsquic_logger_log0(level, __VA_ARGS__);                          \
+            lsquic_logger_log0(level, __func__, __VA_ARGS__);                \
     } while (0)
 #   define LSQ_LOG0C(level, ...) do {                                        \
         if (LSQ_LOG_ENABLED(level))                                          \
         {                                                                    \
             char cidbuf_[MAX_CID_LEN * 2 + 1];                               \
-            lsquic_logger_log0(level, __VA_ARGS__);                          \
+            lsquic_logger_log0(level, __func__, __VA_ARGS__);                \
         }                                                                    \
     } while (0)
 

src/liblsquic/lsquic_mini_conn.c

@@ -1055,7 +1055,11 @@ continue_handshake (struct mini_conn *mc)
      */
     TAILQ_FOREACH(packet_in, &mc->mc_packets_in, pi_next)
     {
-        assert(n_hsk_chunks < sizeof(hsk_chunks) / sizeof(hsk_chunks[0]));
+        if (n_hsk_chunks >= sizeof(hsk_chunks) / sizeof(hsk_chunks[0])) {
+            LSQ_WARN("too many handshake packets");
+            return -1;
+        }
+
         if (0 == (packet_in->pi_flags & PI_HSK_STREAM))
             continue;
         s = parse_frame(packet_in->pi_data + packet_in->pi_hsk_stream,
@@ -1285,8 +1289,7 @@ mini_rechist_largest_recv (void *rechist_ctx)
     lsquic_time_t delta =  mc->mc_largest_recv[0]
                         + (mc->mc_largest_recv[1] << 8)
                         + (mc->mc_largest_recv[2] << 16);
-    LSQ_DEBUG("%s: largest received: %"PRIu64" usec since creation",
-                                                            __func__, delta);
+    LSQ_DEBUG("largest received: %"PRIu64" usec since creation", delta);
     return mc->mc_created + delta;
 }
 
@@ -1324,7 +1327,7 @@ mini_rechist_next (void *rechist_ctx)
     }
     else
         rechist->cur_set = 0;
-    LSQ_DEBUG("%s: return [%"PRIu64", %"PRIu64"]", __func__,
+    LSQ_DEBUG("return [%"PRIu64", %"PRIu64"]",
                                 rechist->range.low, rechist->range.high);
     return &rechist->range;
 }
@@ -1350,7 +1353,7 @@ least_unacked (const struct mini_conn *mc)
         packno = lowest_bit_set(unacked) + 1;
     else
         packno = highest_bit_set(mc->mc_sent_packnos) + 2;
-    LSQ_DEBUG("%s: least unacked: %"PRIu64, __func__, packno);
+    LSQ_DEBUG("least unacked: %"PRIu64, packno);
     return packno;
 }
 
@@ -1954,7 +1957,7 @@ mini_conn_ci_packet_sent (struct lsquic_conn *lconn,
         assert(mc->mc_flags & MC_UNSENT_ACK);
         mc->mc_flags &= ~MC_UNSENT_ACK;
     }
-    LSQ_DEBUG("%s: packet %"PRIu64" sent", __func__, packet_out->po_packno);
+    LSQ_DEBUG("packet %"PRIu64" sent", packet_out->po_packno);
     MCHIST_APPEND(mc, MCHE_PACKET_SENT);
 }
 
@@ -1965,7 +1968,7 @@ mini_conn_ci_packet_not_sent (struct lsquic_conn *lconn,
 {
     struct mini_conn *mc = (struct mini_conn *) lconn;
     packet_out->po_flags &= ~PO_SENT;
-    LSQ_DEBUG("%s: packet %"PRIu64" not sent", __func__, packet_out->po_packno);
+    LSQ_DEBUG("packet %"PRIu64" not sent", packet_out->po_packno);
     MCHIST_APPEND(mc, MCHE_PACKET_DELAYED);
 }
 
@@ -2058,7 +2061,7 @@ mini_conn_ci_destroy (struct lsquic_conn *lconn)
 #else
     if (LSQ_LOG_ENABLED(log_level))
         lsquic_logger_log2(log_level, LSQUIC_LOGGER_MODULE,
-                                   LSQUIC_LOG_CONN_ID,
+                                   LSQUIC_LOG_CONN_ID, __func__,
         "destroyed.  Diagnostics: conn flags: 0x%X, "
         "mc flags: 0x%X, "
 #if LSQUIC_RECORD_INORD_HIST

src/liblsquic/lsquic_mini_conn_ietf.c

@@ -1436,6 +1436,14 @@ imico_parse_regular_packet (struct ietf_mini_conn *conn,
     p = packet_in->pi_data + packet_in->pi_header_sz;
     pend = packet_in->pi_data + packet_in->pi_data_sz;
 
+    if (p >= pend)
+    {
+        ietf_mini_conn_ci_abort_error(&conn->imc_conn, 0,
+                                      TEC_PROTOCOL_VIOLATION,
+                                      "packet %"PRIu64" has no frames",
+                                      packet_in->pi_packno);
+        return -1;
+    }
     while (p < pend)
     {
         len = imico_process_packet_frame(conn, packet_in, p, pend - p);
@@ -1677,10 +1685,20 @@ ietf_mini_conn_ci_packet_in (struct lsquic_conn *lconn,
         imico_maybe_validate_by_dcid(conn, &packet_in->pi_dcid);
 
     pns = lsquic_hety2pns[ packet_in->pi_header_type ];
-    if (pns == PNS_INIT && (conn->imc_flags & IMC_IGNORE_INIT))
+    if (pns == PNS_INIT)
     {
-        LSQ_DEBUG("ignore init packet");    /* Don't bother decrypting */
-        return;
+        if (conn->imc_flags & IMC_IGNORE_INIT)
+        {
+            LSQ_DEBUG("ignore init packet");    /* Don't bother decrypting */
+            return;
+        }
+        if (packet_in->pi_pkt_size
+            && packet_in->pi_pkt_size < IQUIC_MIN_INIT_PACKET_SZ)
+        {
+            LSQ_DEBUG("ignore init packet smaller than minimum size required");
+            /* Don't bother decrypting */
+            return;
+        }
     }
 
     dec_packin = lconn->cn_esf_c->esf_decrypt_packet(lconn->cn_enc_session,
@@ -1718,7 +1736,15 @@ ietf_mini_conn_ci_packet_in (struct lsquic_conn *lconn,
         return;
     }
     else if (pns == PNS_HSK)
+    {
+        if (!LSQUIC_CIDS_EQ(CN_SCID(&conn->imc_conn), &packet_in->pi_dcid))
+        {
+            ietf_mini_conn_ci_abort_error(lconn, 0, TEC_PROTOCOL_VIOLATION,
+                    "protocol violation detected bad dcid for HSK pns");
+            return;
+        }
         imico_peer_addr_validated(conn, "handshake PNS");
+    }
 
     if (((conn->imc_flags >> IMCBIT_PNS_BIT_SHIFT) & 3) < pns)
     {
@@ -1792,7 +1818,7 @@ ietf_mini_conn_ci_packet_sent (struct lsquic_conn *lconn,
 #endif
     if (packet_out->po_header_type == HETY_HANDSHAKE)
         conn->imc_flags |= IMC_HSK_PACKET_SENT;
-    LSQ_DEBUG("%s: packet %"PRIu64" sent", __func__, packet_out->po_packno);
+    LSQ_DEBUG("packet %"PRIu64" sent", packet_out->po_packno);
 }
 
 
@@ -1806,7 +1832,7 @@ ietf_mini_conn_ci_packet_not_sent (struct lsquic_conn *lconn,
     packet_out->po_flags &= ~PO_SENT;
     packet_size = lsquic_packet_out_total_sz(lconn, packet_out);
     conn->imc_bytes_out -= packet_size;
-    LSQ_DEBUG("%s: packet %"PRIu64" not sent", __func__, packet_out->po_packno);
+    LSQ_DEBUG("packet %"PRIu64" not sent", packet_out->po_packno);
 }
 
 
@@ -1976,7 +2002,7 @@ imico_bitmask_rechist_next (struct ietf_mini_rechist *rechist)
     }
     else
         rechist->u.bitmask.cur_set = 0;
-    LSQ_DEBUG("%s: return [%"PRIu64", %"PRIu64"]", __func__,
+    LSQ_DEBUG("return [%"PRIu64", %"PRIu64"]",
                 rechist->u.bitmask.range.low, rechist->u.bitmask.range.high);
     return &rechist->u.bitmask.range;
 }

src/liblsquic/lsquic_mm.c

@@ -364,6 +364,7 @@ maybe_shrink_packet_out_bufs (struct lsquic_mm *mm, unsigned idx)
 #endif
 
 
+#if LSQUIC_USE_POOLS
 /* If average maximum falls under 1/4 of all objects allocated, release
  * half of the objects allocated.
  */
@@ -398,6 +399,7 @@ maybe_shrink_packet_in_bufs (struct lsquic_mm *mm, unsigned idx)
     }
 #endif
 }
+#endif
 
 
 void

src/liblsquic/lsquic_pacer.c

@@ -59,7 +59,7 @@ lsquic_pacer_packet_scheduled (struct pacer *pacer, unsigned n_in_flight,
     if (n_in_flight == 0 && !in_recovery)
     {
         pacer->pa_burst_tokens = 10;
-        LSQ_DEBUG("%s: replenish tokens: %u", __func__, pacer->pa_burst_tokens);
+        LSQ_DEBUG("replenish tokens: %u", pacer->pa_burst_tokens);
     }
 
     if (pacer->pa_burst_tokens > 0)
@@ -68,7 +68,7 @@ lsquic_pacer_packet_scheduled (struct pacer *pacer, unsigned n_in_flight,
         pacer->pa_flags &= ~PA_LAST_SCHED_DELAYED;
         pacer->pa_next_sched = 0;
         pacer->pa_last_delayed = 0;
-        LSQ_DEBUG("%s: tokens: %u", __func__, pacer->pa_burst_tokens);
+        LSQ_DEBUG("tokens: %u", pacer->pa_burst_tokens);
         return;
     }
 
@@ -101,7 +101,7 @@ void
 lsquic_pacer_loss_event (struct pacer *pacer)
 {
     pacer->pa_burst_tokens = 0;
-    LSQ_DEBUG("%s: tokens: %u", __func__, pacer->pa_burst_tokens);
+    LSQ_DEBUG("tokens: %u", pacer->pa_burst_tokens);
 }
 
 
@@ -120,7 +120,7 @@ lsquic_pacer_can_schedule (struct pacer *pacer, unsigned n_in_flight)
     else
         can = 1;
 
-    LSQ_DEBUG("%s: %d", __func__, can);
+    LSQ_DEBUG("%d", can);
     return can;
 }
 

src/liblsquic/lsquic_packet_common.h

@@ -148,28 +148,16 @@ lsquic_frame_types_to_str (char *buf, size_t bufsz, enum quic_ft_bit);
 enum packno_bits
 {
     PACKNO_BITS_0 = 0,
-    PACKNO_BITS_1 = 1,
-    PACKNO_BITS_2 = 2,
-    PACKNO_BITS_3 = 3,
-};
-
-
-/* GQUIC maps 0, 1, 2, 3 -> 1, 2, 4, 6 */
-enum
-{
     GQUIC_PACKNO_LEN_1 = PACKNO_BITS_0,
-    GQUIC_PACKNO_LEN_2 = PACKNO_BITS_1,
-    GQUIC_PACKNO_LEN_4 = PACKNO_BITS_2,
-    GQUIC_PACKNO_LEN_6 = PACKNO_BITS_3,
-};
-
-
-/* IQUIC maps 0, 1, 2, 3 -> 1, 2, 3, 4 (as of ID-17) */
-enum
-{
     IQUIC_PACKNO_LEN_1 = PACKNO_BITS_0,
+    PACKNO_BITS_1 = 1,
+    GQUIC_PACKNO_LEN_2 = PACKNO_BITS_1,
     IQUIC_PACKNO_LEN_2 = PACKNO_BITS_1,
+    PACKNO_BITS_2 = 2,
+    GQUIC_PACKNO_LEN_4 = PACKNO_BITS_2,
     IQUIC_PACKNO_LEN_3 = PACKNO_BITS_2,
+    PACKNO_BITS_3 = 3,
+    GQUIC_PACKNO_LEN_6 = PACKNO_BITS_3,
     IQUIC_PACKNO_LEN_4 = PACKNO_BITS_3,
 };
 

src/liblsquic/lsquic_packet_in.h

@@ -93,6 +93,7 @@ typedef struct lsquic_packet_in
     }                               pi_flags;
     /* pi_token and pi_token_size are set in Initial and Retry packets */
     unsigned short                  pi_token_size; /* Size of the token */
+    unsigned short                  pi_pkt_size;   /* Size of the whole packet */
     unsigned char                   pi_token;      /* Offset to token */
     /* pi_odcid and pi_odcid_len are only set in Retry packets for I-D < 25 */
     unsigned char                   pi_odcid;      /* Offset to Original DCID */

src/liblsquic/lsquic_parse_gquic_be.c

@@ -919,7 +919,7 @@ lsquic_gquic_be_gen_ack_frame (unsigned char *outbuf, size_t outbuf_sz,
     CHECKOUT(2);
     time_diff = now - rechist_largest_recv(rechist);
     lsquic_gquic_be_write_float_time16(time_diff, p);
-    LSQ_DEBUG("%s: diff: %"PRIu64"; encoded: 0x%04X", __func__, time_diff,
+    LSQ_DEBUG("diff: %"PRIu64"; encoded: 0x%04X", time_diff,
         *(uint16_t*)p);
     p += 2;
 

src/liblsquic/lsquic_qdec_hdl.c

@@ -143,7 +143,7 @@ qdh_begin_out (struct qpack_dec_hdl *qdh)
 {
     if (0 != qdh_write_type(qdh))
     {
-        LSQ_WARN("%s: could not write to decoder", __func__);
+        LSQ_WARN("could not write to decoder");
         qdh->qdh_conn->cn_if->ci_internal_error(qdh->qdh_conn,
                                         "cannot write to decoder stream");
     }
@@ -280,7 +280,7 @@ qdh_out_on_write (struct lsquic_stream *stream, lsquic_stream_ctx_t *ctx)
 
     if (lsquic_frab_list_empty(&qdh->qdh_fral))
     {
-        LSQ_DEBUG("%s: nothing to write", __func__);
+        LSQ_DEBUG("nothing to write");
         lsquic_stream_wantwrite(stream, 0);
         return;
     }

src/liblsquic/lsquic_send_ctl.c

@@ -1705,8 +1705,8 @@ static int
 send_ctl_can_send (struct lsquic_send_ctl *ctl)
 {
     const unsigned n_out = send_ctl_all_bytes_out(ctl);
-    LSQ_DEBUG("%s: n_out: %u (unacked_all: %u); cwnd: %"PRIu64
-        "; ccfc: %"PRIu64"/%"PRIu64, __func__,
+    LSQ_DEBUG("n_out: %u (unacked_all: %u); cwnd: %"PRIu64
+        "; ccfc: %"PRIu64"/%"PRIu64,
         n_out, ctl->sc_bytes_unacked_all,
         ctl->sc_ci->cci_get_cwnd(CGP(ctl)),
         ctl->sc_conn_pub->conn_cap.cc_sent,
@@ -1742,8 +1742,8 @@ send_ctl_can_send_pre_hsk (struct lsquic_send_ctl *ctl)
     if (bytes_out >= bytes_in * 2 + bytes_in / 2 /* This should work out
                                                 to around 3 on average */)
     {
-        LSQ_DEBUG("%s: amplification block: %u bytes in, %u bytes out",
-                                            __func__, bytes_in, bytes_out);
+        LSQ_DEBUG("amplification block: %u bytes in, %u bytes out",
+                                            bytes_in, bytes_out);
         return 0;
     }
     else
@@ -2132,7 +2132,7 @@ lsquic_send_ctl_next_packet_to_send (struct lsquic_send_ctl *ctl,
     else
         packet_out->po_lflags &= ~POL_LIMITED;
 
-    if (UNLIKELY(!(ctl->sc_conn_pub->lconn->cn_flags & LSCONN_HANDSHAKE_DONE))
+    if (UNLIKELY(packet_out->po_header_type == HETY_INITIAL)
                     && (!(ctl->sc_conn_pub->lconn->cn_flags & LSCONN_SERVER)
                         || (packet_out->po_frame_types
                                                 & IQUIC_FRAME_ACKABLE_MASK))
@@ -2601,7 +2601,7 @@ send_ctl_log_packet_q (const lsquic_send_ctl_t *ctl, const char *prefix,
     buf = malloc(bufsz);
     if (!buf)
     {
-        LSQ_ERROR("%s: malloc: %s", __func__, strerror(errno));
+        LSQ_ERROR("malloc: %s", strerror(errno));
         return;
     }
 
@@ -2966,6 +2966,52 @@ lsquic_send_ctl_get_packet_for_stream (lsquic_send_ctl_t *ctl,
 }
 
 
+/* Return true if generated, false otherwise */
+int
+lsquic_sendctl_gen_stream_blocked_frame (struct lsquic_send_ctl *ctl,
+                                         struct lsquic_stream *stream)
+{
+    struct lsquic_packet_out *packet_out;
+    const struct parse_funcs *const pf = stream->conn_pub->lconn->cn_pf;
+    unsigned need;
+    uint64_t off;
+    int sz;
+    int is_err;
+
+    off = lsquic_stream_combined_send_off(stream);
+    need = pf->pf_stream_blocked_frame_size(stream->id, off);
+    packet_out = lsquic_send_ctl_get_packet_for_stream(ctl, need,
+                       stream->conn_pub->path, stream);
+    if (!packet_out)
+    {
+        LSQ_DEBUG("failed to get packet_out with lsquic_send_ctl_get_packet_for_stream");
+        packet_out = lsquic_send_ctl_get_writeable_packet(ctl,
+                            PNS_APP, need, stream->conn_pub->path, 0, &is_err);
+        if (!packet_out)
+        {
+            LSQ_DEBUG("cannot get writeable packet for STREAM_BLOCKED frame");
+            return 0;
+        }
+    }
+    sz = pf->pf_gen_stream_blocked_frame(
+                         packet_out->po_data + packet_out->po_data_sz,
+                         lsquic_packet_out_avail(packet_out), stream->id, off);
+    if (sz < 0)
+        return 0;
+    LSQ_DEBUG("generated %d-byte STREAM_BLOCKED "
+        "frame; stream_id: %"PRIu64"; offset: %"PRIu64, sz, stream->id, off);
+    EV_LOG_CONN_EVENT(LSQUIC_LOG_CONN_ID, "generated %d-byte STREAM_BLOCKED "
+        "frame; stream_id: %"PRIu64"; offset: %"PRIu64, sz, stream->id, off);
+    if (0 != lsquic_packet_out_add_frame(packet_out, &ctl->sc_enpub->enp_mm, 0,
+                        QUIC_FRAME_STREAM_BLOCKED, packet_out->po_data_sz, sz))
+        return 0;
+    lsquic_send_ctl_incr_pack_sz(ctl, packet_out, sz);
+    packet_out->po_frame_types |= 1 << QUIC_FRAME_STREAM_BLOCKED;
+    lsquic_stream_blocked_frame_sent(stream);
+    return 1;
+}
+
+
 #ifdef NDEBUG
 static
 #elif __GNUC__
@@ -3775,9 +3821,9 @@ lsquic_send_ctl_resize (struct lsquic_send_ctl *ctl)
                 size = lsquic_packet_out_total_sz(lconn, packet_out);
                 if (size > packet_out->po_path->np_pack_size)
                 {
-                    send_ctl_resize_q(ctl, *q, packet_out->po_path);
                     path_ids |= 1 << packet_out->po_path->np_path_id;
                     q_idxs |= 1 << (q - queues);
+                    send_ctl_resize_q(ctl, *q, packet_out->po_path);
                     goto redo_q;
                 }
             }

src/liblsquic/lsquic_send_ctl.h

@@ -236,6 +236,10 @@ lsquic_send_ctl_get_packet_for_stream (lsquic_send_ctl_t *,
                     unsigned need_at_least, const struct network_path *,
                     const struct lsquic_stream *);
 
+int
+lsquic_sendctl_gen_stream_blocked_frame (struct lsquic_send_ctl *ctl,
+                                         struct lsquic_stream *stream);
+
 struct lsquic_packet_out *
 lsquic_send_ctl_get_packet_for_crypto (struct lsquic_send_ctl *ctl,
     unsigned need_at_least, enum packnum_space, const struct network_path *);

src/liblsquic/lsquic_spi.c

@@ -119,7 +119,7 @@ find_and_set_lowest_priority (struct stream_prio_iter *iter)
 
     if (set >= 4)
     {
-        //SPI_DEBUG("%s: cannot find any", __func__);
+        //SPI_DEBUG("cannot find any");
         return -1;
     }
 
@@ -138,7 +138,7 @@ find_and_set_lowest_priority (struct stream_prio_iter *iter)
     assert(iter->spi_set[ set ] & (1ULL << bit));
 #endif
 
-    SPI_DEBUG("%s: prio %u -> %u", __func__, iter->spi_cur_prio, prio);
+    SPI_DEBUG("prio %u -> %u", iter->spi_cur_prio, prio);
     iter->spi_cur_prio = (unsigned char) prio;
     return 0;
 }
@@ -171,7 +171,7 @@ find_and_set_next_priority (struct stream_prio_iter *iter)
 
     if (set >= 4)
     {
-        //SPI_DEBUG("%s: cannot find any", __func__);
+        //SPI_DEBUG("cannot find any");
         return -1;
     }
 
@@ -191,7 +191,7 @@ find_and_set_next_priority (struct stream_prio_iter *iter)
     assert(iter->spi_set[ set ] & (1ULL << bit));
 #endif
 
-    SPI_DEBUG("%s: prio %u -> %u", __func__, iter->spi_cur_prio, prio);
+    SPI_DEBUG("prio %u -> %u", iter->spi_cur_prio, prio);
     iter->spi_cur_prio = (unsigned char) prio;
     return 0;
 }
@@ -212,7 +212,7 @@ lsquic_spi_first (void *iter_p)
     {
         if (0 != find_and_set_lowest_priority(iter))
         {
-            SPI_DEBUG("%s: return NULL", __func__);
+            SPI_DEBUG("return NULL, iter_p=%p", iter_p);
             return NULL;
         }
     }
@@ -220,7 +220,7 @@ lsquic_spi_first (void *iter_p)
     stream = TAILQ_FIRST(&iter->spi_streams[ iter->spi_cur_prio ]);
     iter->spi_next_stream = TAILQ_NEXT(stream, next_prio_stream);
     if (LSQ_LOG_ENABLED(LSQ_LOG_DEBUG) && !lsquic_stream_is_critical(stream))
-        SPI_DEBUG("%s: return stream %"PRIu64", priority %u", __func__,
+        SPI_DEBUG("return stream %"PRIu64", priority %u",
                                             stream->id, iter->spi_cur_prio);
     return stream;
 }
@@ -237,14 +237,14 @@ lsquic_spi_next (void *iter_p)
     {
         iter->spi_next_stream = TAILQ_NEXT(stream, next_prio_stream);
         if (LSQ_LOG_ENABLED(LSQ_LOG_DEBUG) && !lsquic_stream_is_critical(stream))
-            SPI_DEBUG("%s: return stream %"PRIu64", priority %u", __func__,
+            SPI_DEBUG("return stream %"PRIu64", priority %u",
                                             stream->id, iter->spi_cur_prio);
         return stream;
     }
 
     if (0 != find_and_set_next_priority(iter))
     {
-        //SPI_DEBUG("%s: return NULL", __func__);
+        //SPI_DEBUG("return NULL");
         return NULL;
     }
 
@@ -252,7 +252,7 @@ lsquic_spi_next (void *iter_p)
     iter->spi_next_stream = TAILQ_NEXT(stream, next_prio_stream);
 
     if (LSQ_LOG_ENABLED(LSQ_LOG_DEBUG) && !lsquic_stream_is_critical(stream))
-        SPI_DEBUG("%s: return stream %"PRIu64", priority %u", __func__,
+        SPI_DEBUG("return stream %"PRIu64", priority %u",
                                             stream->id, iter->spi_cur_prio);
     return stream;
 }

src/liblsquic/lsquic_stream.c

@@ -1334,6 +1334,15 @@ lsquic_stream_stop_sending_in (struct lsquic_stream *stream,
                                     && !(stream->sm_qflags & SMQF_SEND_RST))
         stream_reset(stream, 0, 0);
 
+    if (stream->sm_qflags & (SMQF_SEND_WUF | SMQF_SEND_BLOCKED \
+                             | SMQF_SEND_STOP_SENDING))
+    {
+        stream->sm_qflags &= ~(SMQF_SEND_WUF | SMQF_SEND_BLOCKED \
+                               | SMQF_SEND_STOP_SENDING);
+        if (!(stream->sm_qflags & SMQF_SENDING_FLAGS))
+            TAILQ_REMOVE(&stream->conn_pub->sending_streams, stream, next_send_stream);
+    }
+
     maybe_finish_stream(stream);
     maybe_schedule_call_on_close(stream);
 }
@@ -1648,8 +1657,8 @@ stream_readf (struct lsquic_stream *stream,
         return nread;
     total_nread += (size_t) nread;
 
-    LSQ_DEBUG("%s: read %zd bytes, read offset %"PRIu64", reached fin: %d",
-        __func__, total_nread, stream->read_offset,
+    LSQ_DEBUG("read %zd bytes, read offset %"PRIu64", reached fin: %d",
+        total_nread, stream->read_offset,
         !!(stream->stream_flags & STREAM_FIN_REACHED));
 
     if (total_nread)
@@ -2408,7 +2417,10 @@ lsquic_stream_dispatch_write_events (lsquic_stream_t *stream)
     unsigned short n_buffered;
     enum stream_q_flags q_flags;
 
-    LSQ_DEBUG("dispatch_write_events");
+    LSQ_DEBUG("dispatch_write_events, sm_qflags: %d. stream_flags: %d, sm_bflags: %d, "
+                "max_send_off: %" PRIu64 ", tosend_off: %" PRIu64 ", sm_n_buffered: %u",
+              stream->sm_qflags, stream->stream_flags, stream->sm_bflags,
+              stream->max_send_off, stream->tosend_off, stream->sm_n_buffered);
 
     if (!(stream->sm_qflags & SMQF_WRITE_Q_FLAGS)
         || (stream->stream_flags & STREAM_FINISHED))
@@ -2434,6 +2446,12 @@ lsquic_stream_dispatch_write_events (lsquic_stream_t *stream)
     else
         stream_dispatch_write_events_loop(stream);
 
+    if ((stream->sm_qflags & SMQF_SEND_BLOCKED) &&
+        (stream->sm_bflags & SMBF_IETF))
+    {
+        lsquic_sendctl_gen_stream_blocked_frame(stream->conn_pub->send_ctl, stream);
+    }
+
     /* Progress means either flags or offsets changed: */
     progress = !((stream->sm_qflags & SMQF_WRITE_Q_FLAGS) == q_flags &&
                         stream->tosend_off == tosend_off &&
@@ -3104,7 +3122,7 @@ verify_conn_cap (const struct lsquic_conn_public *conn_pub)
 
     assert(n_buffered + conn_pub->stream_frame_bytes
                                             == conn_pub->conn_cap.cc_sent);
-    LSQ_DEBUG("%s: cc_sent: %"PRIu64, __func__, conn_pub->conn_cap.cc_sent);
+    LSQ_DEBUG("cc_sent: %"PRIu64, conn_pub->conn_cap.cc_sent);
 }
 
 
@@ -3695,10 +3713,15 @@ stream_write (lsquic_stream_t *stream, struct lsquic_reader *reader,
         }
         while (nwritten < len
                         && stream->sm_n_buffered < stream->sm_n_allocated);
-        return nwritten;
     }
     else
-        return stream_write_to_packets(stream, reader, thresh, swo);
+        nwritten = stream_write_to_packets(stream, reader, thresh, swo);
+    if ((stream->sm_qflags & SMQF_SEND_BLOCKED) &&
+        (stream->sm_bflags & SMBF_IETF))
+    {
+        lsquic_sendctl_gen_stream_blocked_frame(stream->conn_pub->send_ctl, stream);
+    }
+    return nwritten;
 }
 
 
@@ -4701,7 +4724,7 @@ lsquic_stream_get_hset (struct lsquic_stream *stream)
 
     if (stream_is_read_reset(stream))
     {
-        LSQ_INFO("%s: stream is reset, no headers returned", __func__);
+        LSQ_INFO("stream is reset, no headers returned");
         errno = ECONNRESET;
         return NULL;
     }
@@ -4709,14 +4732,14 @@ lsquic_stream_get_hset (struct lsquic_stream *stream)
     if (!((stream->sm_bflags & SMBF_USE_HEADERS)
                                 && (stream->stream_flags & STREAM_HAVE_UH)))
     {
-        LSQ_INFO("%s: unexpected call, flags: 0x%X", __func__,
+        LSQ_INFO("unexpected call, flags: 0x%X",
                                                         stream->stream_flags);
         return NULL;
     }
 
     if (!stream->uh)
     {
-        LSQ_INFO("%s: headers unavailable (already fetched?)", __func__);
+        LSQ_INFO("headers unavailable (already fetched?)");
         return NULL;
     }
 
@@ -5424,7 +5447,7 @@ lsquic_stream_push_promise (struct lsquic_stream *stream,
 #ifdef FIU_ENABLE
     if (fiu_fail("stream/fail_initial_pp_write"))
     {
-        LSQ_NOTICE("%s: failed to write push promise (fiu)", __func__);
+        LSQ_NOTICE("failed to write push promise (fiu)");
         nw = -1;
     }
     else
@@ -5505,7 +5528,7 @@ lsquic_stream_set_http_prio (struct lsquic_stream *stream,
     {
         if (ehp->urgency > LSQUIC_MAX_HTTP_URGENCY)
         {
-            LSQ_INFO("%s: invalid urgency: %hhu", __func__, ehp->urgency);
+            LSQ_INFO("invalid urgency: %hhu", ehp->urgency);
             return -1;
         }
         stream->sm_priority = ehp->urgency;

src/lshpack

@@ -1 +1 @@
-Subproject commit df068e6feec3268a32a1edbbec4a4636d200ee90
+Subproject commit 32e96f10593c7cb8553cd8c9c12721100ae9e924

tests/test_frame_reader.c

@@ -1134,8 +1134,9 @@ test_one_frt (const struct frame_reader_test *frt)
     stream.conn_pub = &conn_pub;
     conn_pub.lconn = &lconn;
 
-  top:
     lsquic_mm_init(&mm);
+
+  top:
     lshpack_dec_init(&hdec);
     memset(&input, 0, sizeof(input));
     memcpy(input.in_buf, frt->frt_buf, frt->frt_bufsz);

tests/test_h3_framing.c

@@ -376,7 +376,7 @@ init_test_objs (struct test_objs *tobjs, unsigned initial_conn_window,
     tobjs->stream_if = &stream_if;
     tobjs->stream_if_ctx = &test_ctx;
     tobjs->ctor_flags = stream_ctor_flags;
-    if ((1 << tobjs->lconn.cn_version) & LSQUIC_IETF_VERSIONS)
+    //if ((1 << tobjs->lconn.cn_version) & LSQUIC_IETF_VERSIONS)
     {
         lsquic_qeh_init(&tobjs->qeh, &tobjs->lconn);
         s = lsquic_qeh_settings(&tobjs->qeh, 0, 0, 0, 0);
@@ -395,7 +395,7 @@ deinit_test_objs (struct test_objs *tobjs)
     lsquic_send_ctl_cleanup(&tobjs->send_ctl);
     lsquic_malo_destroy(tobjs->conn_pub.packet_out_malo);
     lsquic_mm_cleanup(&tobjs->eng_pub.enp_mm);
-    if ((1 << tobjs->lconn.cn_version) & LSQUIC_IETF_VERSIONS)
+    //if ((1 << tobjs->lconn.cn_version) & LSQUIC_IETF_VERSIONS)
         lsquic_qeh_cleanup(&tobjs->qeh);
 }
 

tests/test_tokgen.c

@@ -35,6 +35,7 @@ main (int argc, char **argv)
     printf("\n");
 
     lsquic_tg_destroy(tg);
+    lsquic_stock_shared_hash_destroy(enpub.enp_shi_ctx);
 
     return 0;
 }