Skip to content

Packet timestamp for 2.1.13 release - #4

Merged
trondn merged 2 commits into
couchbasedeps:release-2.1.13-stable-couchbasefrom
trondn:packet_timestamp-for-2.1.13
Sep 3, 2026
Merged

Packet timestamp for 2.1.13 release#4
trondn merged 2 commits into
couchbasedeps:release-2.1.13-stable-couchbasefrom
trondn:packet_timestamp-for-2.1.13

Conversation

@trondn

@trondn trondn commented Jul 7, 2026

Copy link
Copy Markdown

Added support for packet timestamp

Comment thread buffer.c Outdated
Comment thread buffer.c Outdated
Comment thread buffer.c Outdated

@jimwwalker jimwwalker left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

These were from a broader review so hopefully the end of these staggeringly hard to follow flows 😆

Comment thread include/event2/bufferevent.h Outdated
Comment thread bufferevent_openssl.c
Comment thread bufferevent_sock.c Outdated
Comment thread bufferevent_openssl.c
@trondn
trondn force-pushed the packet_timestamp-for-2.1.13 branch from f7d2fcf to 863dc91 Compare July 27, 2026 08:59
@pavlosg

pavlosg commented Jul 29, 2026

Copy link
Copy Markdown

I'm not familiar with libevent so I asked Claude for a review:

Review: top 2 commits on packet_timestamp-for-2.1.13

Repo /Users/pavlos.georgiou/Couchbase/libevent
Branch packet_timestamp-for-2.1.13
Commits 863dc91f Add kernel socket receive timestamp support
e363491e test: fix OpenSSL 3.0 test suite compatibility issues
Base 79ddfb46
Reviewed 2026-07-29

Verification performed

  • Read the full diffs of both commits.
  • Built the tree with CMake + Debug + Homebrew OpenSSL 3.6.0 on macOS arm64 (AppleClang): clean, no new warnings (only pre-existing arc4random_addrandom deprecation and a -Wdeclaration-after-statement in regress_main.c).
  • Built a second tree with -DEVENT__DISABLE_OPENSSL=ON.
  • Built HEAD~2 in a scratch worktree for an A/B comparison of test results.
  • Ran: evbuffer/get_timestamp, bufferevent/bufferevent_recv_timestamps, the whole ssl/ group, the whole http/ group — on both HEAD and base.

Test results

  • New tests pass: evbuffer/get_timestamp, bufferevent/bufferevent_recv_timestamps, and all three new ssl/*_recv_timestamps cases. Full ssl/ group: 29 ok, 0 skipped.
  • http/ at HEAD: terminate_chunked and terminate_chunked_oneshot fail. Both also fail at HEAD~2 — pre-existing, not caused by these commits. (bad_request additionally failed on one base run only; flaky.)
  • http/https_incomplete and http/https_incomplete_timeout pass both before and after e363491e on macOS + OpenSSL 3.6, so that commit's fix is not exercised on this platform. It is presumably specific to OpenSSL 3.0.x. Not disputed, just not verifiable here.

Blocking

1. --disable-openssl builds no longer compile

test/regress_http.c:3093

bufferevent_get_openssl_error(bev) is the only OpenSSL call in that file that is not wrapped in #ifdef EVENT__HAVE_OPENSSL — compare lines 119, 479, 1091, 3701, which all are. event2/bufferevent_ssl.h only declares the symbol when OpenSSL support is present.

Confirmed:

cmake -S . -B build-nossl -DEVENT__DISABLE_OPENSSL=ON -DEVENT__DISABLE_MBEDTLS=ON
cmake --build build-nossl
...
test/regress_http.c:3093:7: error: call to undeclared function
    'bufferevent_get_openssl_error'; ISO C99 and later do not support
    implicit function declarations [-Wimplicit-function-declaration]
1 error generated.

Fix: guard the whole BEV_EVENT_READING|BEV_EVENT_ERROR branch with #ifdef EVENT__HAVE_OPENSSL, falling back to test_ok = -2 otherwise.

(commit e363491e)

2. Build break on OpenSSL < 1.1.0 and LibreSSL < 2.7.0

bufferevent_openssl.c:262, bufferevent_openssl.c:561

static CRYPTO_ONCE once = CRYPTO_ONCE_STATIC_INIT;
CRYPTO_THREAD_run_once(&once, init_methods_bufferevent);

CRYPTO_ONCE, CRYPTO_ONCE_STATIC_INIT and CRYPTO_THREAD_run_once are OpenSSL 1.1.0+ APIs. But openssl-compat.h:7 still shims BIO_meth_new, BIO_meth_set_*, BIO_set_data, BIO_get_shutdown, … for exactly:

#if (OPENSSL_VERSION_NUMBER < 0x10100000L) || \
    (defined(LIBRESSL_VERSION_NUMBER) && LIBRESSL_VERSION_NUMBER < 0x20700000L)

so those configurations are nominally still supported and will now fail to compile.

Secondary: converting BIO_s_bufferevent() from lazy init to CRYPTO_THREAD_run_once is a real race fix, but it is unrelated to receive timestamps and would be better as its own commit.

(commit 863dc91f)


Correctness

3. The recvmsg BIO drops BIO_s_socket's EOF semantics

bufferevent_openssl.c:498-537 (bio_socket_recvmsg_ctrl), bufferevent_openssl.c:373-467 (bio_socket_recvmsg_read)

bio_socket_recvmsg_read() never sets BIO_FLAGS_IN_EOF when the read returns 0, and bio_socket_recvmsg_ctrl() has no BIO_CTRL_EOF case — it falls through to default: ret = 0. OpenSSL's own sock_read/sock_ctrl do implement both.

On OpenSSL 3.x, BIO_eof() is exactly what decides whether a FIN arriving before close_notify is classified as SSL_R_UNEXPECTED_EOF_WHILE_READING (→ SSL_ERROR_SSLBEV_EVENT_ERROR with a nonzero OpenSSL error) or as a bare SSL_ERROR_SYSCALL (→ conn_closed()'s dirty-shutdown path). Both SSL_R_UNEXPECTED_EOF_WHILE_READING and SSL_OP_IGNORE_UNEXPECTED_EOF are present in the installed 3.6 headers, and BIO_CTRL_EOF / BIO_FLAGS_IN_EOF are the mechanism — so the path is live.

Net effect: setting BEV_OPT_RECV_TIMESTAMPS silently changes how connection close is reported to the application.

The two commits collide here. e363491e teaches http_incomplete_errorcb to accept BEV_EVENT_ERROR only when bufferevent_get_openssl_error() != 0 — which is precisely the signal the custom BIO suppresses. If https_bev also set BEV_OPT_RECV_TIMESTAMPS, that workaround would take the test_ok = -2 branch.

Scope of verification: the code divergence and the OpenSSL-side mechanism are confirmed by inspection of the diff and the installed headers. I did not reproduce an end-to-end failure.

Also missing vs. the stock socket BIO: BIO_CTRL_PENDING / BIO_CTRL_WPENDING (both land on default: ret = 0).

4. Timestamp attributed to the oldest byte is actually the newest segment's

bufferevent_openssl.c:884-895

/* Store timestamp from first successful read (oldest data). ... */
if (n_used == 1) {
        if (bio_data && bio_data->last_recv_ts_valid) {
                first_ts = bio_data->last_recv_ts;

bio_data->last_recv_ts is read after SSL_read() returns. Any TLS record larger than the MSS requires multiple recvmsg() calls inside a single SSL_read(), and each one overwrites last_recv_ts. So the timestamp attributed to the oldest plaintext byte is the arrival time of the last segment. last_recv_ts_valid is also never cleared after use, so the reported value can be too new but never absent.

For a feature whose entire purpose is arrival-latency measurement, this is the accuracy bug that matters most. Capturing the BIO's timestamp before the first SSL_read() (or having the BIO record a "first ts since last consume" alongside the latest) would fix it.

5. Timestamps armed on the socket but never collected — and still reported as enabled

bufferevent_openssl.c:1803-1831, with bufferevent_openssl.c:1713-1717

In bufferevent_openssl_socket_new(), be_socket_enable_timestamps_(fd) runs before the guarded BIO swap. The guard itself is right — it correctly refuses to SSL_set_bio() over a split rbio/wbio pair, and the new ssl/bufferevent_openssl_split_bio_recv_timestamps test covers that. But when the swap is skipped (split BIOs, or any non-BIO_TYPE_SOCKET BIO):

  • SO_TIMESTAMP/SO_TIMESTAMPNS stays armed on the kernel socket for the life of the connection;
  • bufferevent_openssl_new_impl() still sets bev.recv_timestamps_enabled = 1 (it only re-checks options & BEV_OPT_RECV_TIMESTAMPS && fd >= 0);
  • reads go through the stock BIO, so no ancillary data is ever parsed;
  • evbuffer_get_timestamp() returns -1 forever.

There is no way for a caller to distinguish "not supported on this socket/BIO" from "no data received yet" — both are -1. A query accessor (or making bufferevent_openssl_socket_new fail loudly) would help.

Minor, same area: be_socket_enable_timestamps_() is invoked twice on the same fd — once in bufferevent_openssl_socket_new(), again in bufferevent_openssl_new_impl().

6. evbuffer_pullup() comments contradict the code

buffer.c:1412-1416, buffer.c:1428-1432, vs. buffer.c:1462 and buffer.c:1480

Both new comments state that timestamps from consolidated chains are "intentionally discarded; only this chain's timestamp is preserved". The loop at 1462 does the opposite — it adopts the first valid timestamp found among the consumed chains whenever tmp has none.

That behaviour also mis-attributes. If the first chain came from evbuffer_add/evbuffer_prepend (no timestamp) and a later chain has one, then after evbuffer_pullup() evbuffer_get_timestamp() reports that later timestamp as belonging to the oldest bytes, instead of returning -1. Leaving valid = 0 when the oldest chain has no timestamp would be more truthful.


Test gaps

7. The TLS timestamp path is never actually asserted

test/regress_ssl.c:1006, test/regress_ssl.c:1128, test/regress_ssl.c:1143-1208

Both new SSL tests guard the only meaningful assertion behind if (ts_result == 0). I ran them with --verbose and confirmed that assertion never executes: evbuffer_get_timestamp() returns -1 in both cases, so all that is checked is that the data round-trips.

SO_TIMESTAMP succeeds on an AF_UNIX socketpair on macOS (verified with a standalone setsockopt probe returning 0), so the custom recvmsg BIO is installed and exercised — but no SCM_TIMESTAMP cmsg is ever delivered for AF_UNIX. So the headline capability, timestamps over TLS, has no assertion that a timestamp was ever produced, on any platform likely to be in CI.

Worse, test_bufferevent_openssl_filter_recv_timestamps has no tt_int_op(done, ==, 1) after event_base_dispatch() at line 1206 — it falls straight to end: at 1208. If the read callback never fires, the test passes vacuously.

Suggestion: use a UDP socket pair (as evbuffer/get_timestamp and bufferevent/bufferevent_recv_timestamps already do) for at least one SSL case, so the assertion actually runs; and add the missing done check.

8. Assertion failure inside a read callback hangs the test

test/regress_bufferevent.c:1365, test/regress_ssl.c:989, test/regress_ssl.c:1113

All three read callbacks goto end on a failed tt_assert/tt_int_op without calling event_base_loopexit(). On failure, event_base_dispatch() stays blocked on an armed-but-idle read event instead of the test failing and returning. Call event_base_loopexit() on the failure path too.

9. e363491e weakens http_incomplete_errorcb

test/regress_http.c:3089-3097

Accepting any nonzero OpenSSL error as a successful termination means a genuine TLS failure is now indistinguishable from the expected server-side close. Narrowing to the specific expected reason code (e.g. SSL_R_UNEXPECTED_EOF_WHILE_READING) would keep the test meaningful.

The non-SSL variants (http/incomplete, http/incomplete_timeout) are unaffected: upcast() returns NULL for non-OpenSSL bufferevents, so bufferevent_get_openssl_error() yields 0 and the test still takes test_ok = -2 — same as the old else.


Minor / cleanup

  • event-config.h.cmake:78-88 — the EVENT__HAVE_GETRANDOM #cmakedefine block is duplicated (copy/paste artifact from inserting the two SO_TIMESTAMP* defines). Harmless (identical redefinition) but should go.
  • bufferevent_openssl.c:516BIO_C_GET_FD writes *(evutil_socket_t *)ptr, but OpenSSL's BIO_get_fd(b, c) contract is int *c. Harmless today: evutil_socket_t is int on POSIX, and the BIO is never created on Windows because both SO_TIMESTAMP* checks resolve to 0 there. It is an 8-byte write through an int * the moment either of those changes.
  • include/event2/buffer.h:754-766evbuffer_read_with_timestamp() is declared EVENT2_EXPORT_SYMBOL in a public header while the commit message calls it "internal". Its doc block is a verbatim copy of evbuffer_read()'s: no mention of timestamps, of the SO_TIMESTAMP/SO_TIMESTAMPNS prerequisite, or that it silently degrades to a plain readv() on Windows and on non-USE_IOVEC_IMPL builds. Three new public symbols plus a new option flag, with no ChangeLog or whatsnew entry.
  • buffer.c:2523-2545 — the failure path now frees a chain (plus an O(chain-count) list walk) between recvmsg() failing and returning, so callers that inspect errno — as test/regress_buffer.c:527 does — depend on mm_free() not clobbering it. A save/restore around the cleanup is cheap insurance.
  • evbuffer-internal.h:207-215struct evbuffer_chain grows by 24 bytes (struct timespec + int valid + padding) for every chain in every program, whether or not the feature is used. Since evbuffer_chain_new() rounds the total allocation up to a power of two, requests that previously landed exactly on a boundary now double. Probably acceptable, worth being deliberate about.

Things that are right and worth noting

  • The fresh-chain-per-recvmsg() design is the correct call — it is what makes per-packet timestamps survive, and the evbuffer/get_timestamp test exercises the drain-across-chain-boundary behaviour properly (including the EAGAIN cleanup leaving buf->first == NULL).
  • The error-path chain unlink in evbuffer_read_impl_ is sound: new_chain->off == 0, so evbuffer_chain_insert() leaves last_with_datap untouched, and every insert position (empty buffer, trailing empty chains, pinned trailing chain) restores consistently. I walked each case.
  • The split rbio/wbio guard in bufferevent_openssl_socket_new() is a genuinely subtle hazard caught and documented, with a dedicated test.
  • Re-arming timestamps in be_socket_setfd() (and clearing the flag first) is correct, and bufferevent/bufferevent_recv_timestamps covers the bufferevent_setfd() swap explicitly.
  • evbuffer_get_timestamp()'s doc comment is honest about the partial-drain and pullup caveats.

@trondn
trondn force-pushed the packet_timestamp-for-2.1.13 branch from 863dc91 to fa0c91e Compare July 29, 2026 14:47
@trondn

trondn commented Jul 29, 2026

Copy link
Copy Markdown
Author

I addressed all comments except for number 2. Both versions are no longer supported

@pavlosg

pavlosg commented Aug 3, 2026

Copy link
Copy Markdown

I did another pass. I focused on the previous claim made by the AI about UDP, which is not something KV cares about. It turns out there is some deficiency in the TCP case as well.

Review: kernel socket receive timestamp support (packet_timestamp-for-2.1.13)

Repo /Users/pavlos.georgiou/Couchbase/libevent
Branch packet_timestamp-for-2.1.13
Commits reviewed fa0c91ec Add kernel socket receive timestamp support
5b241415 Fix OpenSSL 3.0 test suite compatibility issues
Superseded revision 863dc91f / e363491e (original review round)
Base 79ddfb46
Date 2026-08-03

This document covers three things:

  1. Part 1 — status of each finding from the first review round (validating the claim "I addressed all comments except for number 2").
  2. Part 2 — a new build break introduced by one of the fixes.
  3. Part 3 — whether the patch achieves its actual goal: timestamps for TCP packets.

Part 3 is the most consequential section and was not covered by the first review round.


Verdict

The rework is real and mostly good: 7 of 9 numbered findings and 3 of 5 minor bullets are genuinely fixed, several with better fixes than I suggested. But:

  • Finding # 7 was not addressed (only its sub-point was), contrary to the claim.
  • The fix for # 9 introduced a build break on OpenSSL < 3.0 and all LibreSSL — a stricter version requirement than the # 2 being dismissed, which undercuts the reasoning used to dismiss it.
  • On macOS/BSD the feature is a silent no-op for TCP, the primary target transport. On Linux it works, but reports the last segment of each read while the API contract promises the oldest byte.
  • There is no TCP test anywhere, which is why the above stayed invisible.

Part 1 — Status of the first-round findings

Verified fixed

# Summary Evidence
1 --disable-openssl build break Built -DEVENT__DISABLE_OPENSSL=ON -DEVENT__DISABLE_MBEDTLS=ONcompiles clean. Guard is correct: regress_http.c contains zero mbedtls references, so EVENT__HAVE_OPENSSL is the right predicate.
3 recvmsg BIO dropped EOF semantics BIO_CTRL_EOF case at bufferevent_openssl.c:542; BIO_FLAGS_IN_EOF set at bufferevent_openssl.c:480, cleared at bufferevent_openssl.c:405. Matches stock sock_read/sock_ctrl.
4 Timestamp was newest, not oldest Sticky-first at bufferevent_openssl.c:464 (ts_found && !data->last_recv_ts_valid) plus clear-on-consume at bufferevent_openssl.c:906. Multi-segment TLS records now correctly report the first segment. See residual issue below.
5 Armed but never collected, still reported enabled new_impl now sets the flag only when the recvmsg BIO actually landed (bufferevent_openssl.c:1738). The double-arming sub-point is also gone.
6 pullup comments contradicted the code Code now matches the comments in all three branches; tmp genuinely inherits the oldest chain's stamp at buffer.c:1447, so the "set above" in the comment is accurate.
8 Assertion failure in readcb hung the test event_base_loopexit() moved to the end: label in all three callbacks.
9 http_incomplete_errorcb too permissive Narrowed to ERR_GET_REASON(...) == SSL_R_UNEXPECTED_EOF_WHILE_READING. But see Part 2.

Minor bullets fixed: duplicate EVENT__HAVE_GETRANDOM removed (one define remains, event-config.h.cmake:79); BIO_C_GET_FD now writes *(int *)ptr; errno save/restore at buffer.c:2524 / buffer.c:2540; the buffer.h doc block is now genuinely informative rather than copy-pasted.

Not addressed

  • # 2 — OpenSSL < 1.1.0 / LibreSSL < 2.7.0 build break. Acknowledged and consciously declined. See the caveats below.
  • # 7 — the TLS timestamp path is never asserted. Only its sub-point (the missing tt_int_op(done, ==, 1)) was fixed. Detail below.
  • Minor: no ChangeLog / whatsnew entry for three new public symbols plus a new option flag. Both files exist and are untouched by either commit.
  • Minor: evbuffer-internal.h unchanged, so the +24 bytes per chain stands. I called this "probably acceptable", so this one is fair to leave — measured sizeof(struct evbuffer_chain) is now 72 bytes.

Correction to my own first-round review

The BIO_CTRL_PENDING / BIO_CTRL_WPENDING aside in #3 was moot. OpenSSL's own socket BIO also falls through to default: ret = 0 for those, so the custom BIO already matches stock behaviour. Nothing to fix.

libevent#7 in detail — not addressed

The core recommendation was to use a UDP pair for at least one SSL case so the assertion actually runs. That was not taken; regress_ssl.c:1156 still uses AF_UNIX.

Verified on both platforms:

  • Ran all five new tests verbosely. Positive timestamp assertions appear only in the UDP-based tests (regress_buffer.c:546, regress_bufferevent.c:1373). In regress_ssl.c the only evbuffer_get_timestamp assertion is == -1 at line 1078.
  • Root cause, macOS: SO_TIMESTAMP succeeds on an AF_UNIX socketpair but recvmsg returns msg_controllen=0 — no cmsg, for either SOCK_STREAM or SOCK_DGRAM.
  • Root cause, Linux: same. AF_UNIX/STREAM + SO_TIMESTAMPNS over 6 reads → ...... (none stamped).

So the headline capability — timestamps over TLS — has no assertion that a timestamp was ever produced, on either OS. All 29 ssl/ tests pass on both; they pass without testing the feature.

Residual issue in the # 4 fix (inspection only, not reproduced)

last_recv_ts_valid is cleared only when n_used == 1, i.e. only when SSL_read yields application data. Bytes consumed by non-application records never clear it, so the sticky timestamp goes stale:

  • Handshake recvmsg calls collect timestamps (bio_data->bev_ssl and the flag are both set before the event loop dispatches, per :409 and :1738), so the first application read reports a handshake-era arrival time.
  • Same for TLS 1.3 NewSessionTicket, alerts and key updates: SSL_read handles them internally and returns WANT_READ with n_used == 0, leaving the stale value to be attributed to the next real payload.

This is the mirror image of the original bug — previously too new, now potentially far too old. Not reproduced: macOS delivers no cmsg on AF_UNIX, so the path can't be exercised by the existing tests. Clearing the flag whenever SSL_read returns without data would fix it.

On dismissing #2

The factual premise is correct — OpenSSL < 1.1.0 and LibreSSL < 2.7.0 are EOL upstream. Two caveats:

  1. CRYPTO_THREAD_run_once was never the binding constraint. Verified present in OpenSSL 1.1.1w. The Libevent http doesn't ignore spaces after field-content in headers libevent/libevent#9 fix has since raised the real floor to 3.0 and dropped LibreSSL entirely (Part 2). So the decision that actually needs ratifying is "OpenSSL 3.0+, no LibreSSL" — a much larger call than the one made.
  2. The tree still advertises the support it no longer has. openssl-compat.h:7 still shims BIO_meth_new, BIO_set_data, TLS_method, X509_getm_notBefore, … for exactly the < 0x10100000L / LibreSSL < 0x20700000L range. Those users now get a confusing compile error instead of a clear one. Deleting the block or adding an explicit #error version gate would make the decision self-documenting.

Part 2 — New build break introduced by the libevent#9 fix

SSL_R_UNEXPECTED_EOF_WHILE_READING was added in OpenSSL 3.0. Confirmed absent from the 1.1.1w headers, and an actual build against openssl@1.1 fails:

test/regress_http.c:3099: error: use of undeclared identifier
    'SSL_R_UNEXPECTED_EOF_WHILE_READING'

This also breaks LibreSSL at every version — it has no such reason code. The reference is inside #ifdef EVENT__HAVE_OPENSSL but is not version-gated. Needs an OPENSSL_VERSION_NUMBER >= 0x30000000L guard with a fallback, or an explicit project-wide minimum.

Build matrix as it stands:

Configuration Result
OpenSSL 3.6.0 (macOS arm64) builds clean, no new warnings
OpenSSL 3.0.20 (Linux aarch64) builds clean
-DEVENT__DISABLE_OPENSSL=ON builds clean (was the #1 break)
OpenSSL 1.1.1w failsregress_http.c:3099
OpenSSL < 1.1.0 / LibreSSL < 2.7.0 fails (#2, declined)

Part 3 — Does the patch achieve timestamps for TCP packets?

Yes on Linux, no on macOS/BSD — and where it works, the value does not mean what the API says it means.

Linux 6.10 macOS 14 (arm64)
TCP timestamps delivered yes, via SO_TIMESTAMPNS no — silent no-op
EVENT__HAVE_DECL_SO_TIMESTAMPNS 1 0
Meaning of the value last segment in the read n/a
Granularity per read, not per packet n/a
TCP test coverage none none

3.1 macOS/BSD: silent no-op on TCP

AF_INET/TCP   setsockopt=OK   recvmsg=5   controllen=0    SCM_TIMESTAMP=ABSENT
AF_INET/UDP   setsockopt=OK   recvmsg=5   controllen=28   SCM_TIMESTAMP=PRESENT

setsockopt(SO_TIMESTAMP) succeeds on a TCP socket but the kernel never attaches a cmsg — including after a warm-up sequence, so this is not a first-packet artifact. It is a BSD design property: the timestamp control message is attached by the datagram append path; sbappendstream has no per-segment cmsg mechanism.

Because bufferevent_sock.c treats setsockopt success as capability, the consequence end-to-end is:

TCP loopback, BEV_OPT_RECV_TIMESTAMPS on the reading end:
  readcb: 11 bytes buffered, evbuffer_get_timestamp() = -1

recv_timestamps_enabled becomes 1, every read is routed through evbuffer_read_with_timestamp(), the cost is paid (§3.5), and nothing is ever returned. This is finding libevent#5no way to distinguish "unsupported" from "no data yet" — but far more consequential than I originally framed it: on macOS the primary transport is permanently in the indistinguishable-failure state.

3.2 Linux: works, and SO_TIMESTAMPNS is what makes it work

read #1:  7 bytes, evbuffer_get_timestamp()= 0  ts=1785760475.740019211
read #2:  7 bytes, evbuffer_get_timestamp()= 0  ts=1785760475.822482753
read #3:  7 bytes, evbuffer_get_timestamp()= 0  ts=1785760475.904339628
...  all 6 stamped, ~82 ms apart as sent

Both SO_TIMESTAMP and SO_TIMESTAMPNS produce cmsgs on Linux TCP. The patch prefers SO_TIMESTAMPNS, which is the right choice.

3.3 The value is the last segment in the read, not the oldest byte

Two segments 400 ms apart, coalesced into a single recvmsg, with a warm-up first to rule out the first-packet effect:

single recvmsg returned 20 bytes: "AAAAAAAAAABBBBBBBBBB"
  reported SCM_TIMESTAMPNS = 1785760415.244642
  write(A)                 = 1785760414.843746   (ts - A = +400.9 ms)
  write(B)                 = 1785760415.244548   (ts - B =   +0.1 ms)
  ==> corresponds to the LAST (B) segment

tcp_recvmsg overwrites its timestamp slot per-skb as data is copied, so the cmsg carries the newest segment in that read.

The patch contracts the opposite throughout:

  • evbuffer_get_timestamp() is documented as the timestamp of the oldest data;
  • buffer.c:1447 propagates the oldest chain's stamp through pullup;
  • the sticky-first logic at bufferevent_openssl.c:464, added to fix # 4, exists specifically to prefer the earliest arrival.

On TCP all of that machinery is fed a last-segment value. For latency measurement it under-reports by the span of the read — 400 ms in this test. For TLS the two layers compose confusingly: first-recvmsg-of-the-record, where each recvmsg itself reports its own last segment.

"Per-packet" is not achievable for TCP by construction. One recvmsg on a stream socket returns bytes coalesced from arbitrarily many segments and carries at most one timestamp. The ceiling is one timestamp per read, and read boundaries are set by scheduling and FIONREAD, not by packet arrival. The fresh-chain-per-recvmsg() design is exactly right for UDP, where one read is one datagram; on TCP the chain boundary carries no packet meaning.

3.4 Data queued before arming is never stamped, and blinds the buffer while it sits

be_socket_enable_timestamps_() runs at bufferevent construction, so anything already in the socket receive buffer is unstamped. Reproducible 4/4 runs on Linux:

no pre-queued data:     YYYYYYYY      (Y = stamped)
WITH pre-queued data:   .YYYYYYYY

The kernel recovers immediately after arming (raw-syscall control: pre-queued read unstamped, then YYYYYYYY). But because evbuffer_get_timestamp() returns the oldest chain's stamp, while that unstamped chain remains buffered the whole buffer reports -1 even though newer data is stamped:

after reading 5 pre-queued bytes:    len= 5  get_timestamp()=-1
after 5 more bytes arrive (armed):   len=10  get_timestamp()=-1

This is the direct consequence of the # 6 change — discarding rather than adopting is more truthful, but one unstamped early read blinds the caller until it drains. That is the common server shape: accept(), eager client sends immediately, bufferevent constructed after.

Loose end, not a finding: in one run the timestamp was still absent after I drained the unstamped chain, which does not follow from the attach logic at buffer.c:2558-2570. It did not reproduce in the controlled test, so I am not reporting it as a defect — but it may be worth a look.

3.5 The cost is paid regardless, and it is a memory amplification vector

howmuch is clamped to FIONREAD at buffer.c:2370-2374, then buffer.c:2382 calls evbuffer_chain_new(howmuch), which rounds up to MIN_BUFFER_SIZE (1024). A stream arriving one byte per read therefore allocates a 1024-byte chain per byte, never refilled — whereas baseline evbuffer_expand_fast_() appends into existing chain space.

Measured, 20 000 single-byte TCP reads with the input left undrained (ru_maxrss, unit-corrected per platform — KB on Linux, bytes on macOS):

baseline with BEV_OPT_RECV_TIMESTAMPS ratio
Linux 6.10 aarch64 1.27 MB 21.16 MB ~17x
macOS 14 arm64 1.30 MB 20.97 MB ~16x

Consistent with 20 000 × 1024 ≈ 20.5 MB. For a server reading from an untrusted or merely chatty peer this is a memory-exhaustion vector — and on macOS it buys nothing at all.

Reference figures, sizeof(struct evbuffer_chain) = 72:

one read of     1 bytes -> fresh chain alloc  1024 bytes (1024x)
one read of    64 bytes -> fresh chain alloc  1024 bytes (  16x)
one read of  1024 bytes -> fresh chain alloc  2048 bytes (   2x)
one read of  4096 bytes -> fresh chain alloc  8192 bytes (   2x)

3.6 No TCP test exists

  • evbuffer/get_timestampAF_INET, SOCK_DGRAM
  • bufferevent/bufferevent_recv_timestampsAF_INET, SOCK_DGRAM
  • all three ssl/*_recv_timestampsAF_UNIX, SOCK_STREAM

The only two tests that assert a real timestamp are UDP. Nothing exercises TCP, which is why §3.1–§3.4 stayed invisible.


Recommendations, in priority order

  1. Version-gate SSL_R_UNEXPECTED_EOF_WHILE_READING (Part 2) or declare an explicit OpenSSL 3.0+ / no-LibreSSL minimum. This is a hard build break today.
  2. Add a TCP test. It will fail on macOS — that is the point. Without it the platform gap is undetectable.
  3. Stop inferring capability from setsockopt success. Probe SO_TYPE, or confirm a cmsg actually arrives, and surface the result so callers can distinguish "unsupported here" from "nothing yet". This is what makes the macOS case silent.
  4. Decide and document the TCP semantic. Either state plainly that the value is the arrival of the last segment in the read and drop the oldest-data framing, or move to SO_TIMESTAMPING, which gives per-skb control instead of one overwritten slot per read.
  5. Don't allocate a fresh chain when no timestamp was obtained. Removes both the amplification and nearly all the cost on platforms where the feature cannot work.
  6. Clear last_recv_ts_valid when SSL_read returns without application data, so handshake and TLS 1.3 post-handshake records don't leak stale timestamps into the first payload read.
  7. Resolve # 2 explicitly — delete the openssl-compat.h shim block or add an #error, so the supported range is stated once and enforced.
  8. Add a ChangeLog / whatsnew entry for the three new public symbols and BEV_OPT_RECV_TIMESTAMPS.

Verification performed

Environment. macOS 14 (Darwin 23.6.0) arm64, AppleClang, Homebrew OpenSSL 3.6.0 and 1.1.1w. Linux via Docker 27.4.0: kernel 6.10.14-linuxkit aarch64, gcc 12 (gcc:13 image), CMake 3.25.1, OpenSSL 3.0.20.

Builds. Four configurations: OpenSSL 3.6.0 (macOS), -DEVENT__DISABLE_OPENSSL=ON (macOS), OpenSSL 1.1.1w (macOS), OpenSSL 3.0.20 (Linux). All out-of-tree in a scratch directory; the working tree was not modified.

Tests. evbuffer/get_timestamp, bufferevent/bufferevent_recv_timestamps, all three ssl/*_recv_timestamps, the full ssl/ group and the full http/ group — on both platforms, with --verbose runs grepped to confirm which assertions actually execute.

Test results. ssl/ 29/29 ok on both platforms. Both new non-SSL tests pass on both. http/ failures across five macOS runs are confined to bad_request, terminate_chunked, terminate_chunked_oneshot — intermittent, and the same set that failed at base 79ddfb46 in the first review round, so not regressions. https_incomplete / https_incomplete_timeout passed every run.

Purpose-built probes (all in the scratch directory): raw SO_TIMESTAMP/SO_TIMESTAMPNS cmsg delivery across AF_INET/TCP, AF_INET/UDP, AF_UNIX/STREAM, AF_UNIX/DGRAM; first-vs-last segment attribution on a coalesced multi-segment read, with warm-up; per-read timestamp presence over sequential reads; pre-queued-data behaviour at both the syscall and libevent layers; end-to-end BEV_OPT_RECV_TIMESTAMPS over TCP through the public API; and the memory-amplification measurement.

Diff method. The superseded commits 863dc91f/e363491e were still reachable via reflog, so old→new was diffed directly rather than inferred.

Confidence scoping

  • Executed and reproduced: everything in Part 2, §3.1–§3.5, and all Part 1 "verified fixed" rows.
  • Reasoned from code, not reproduced: the residual # 4 issue (handshake / post-handshake stale timestamp) — the existing tests cannot exercise it because AF_UNIX yields no cmsg on either OS.
  • Observed once, did not reproduce: the post-drain anomaly noted in §3.4. Explicitly not claimed as a defect.

@trondn
trondn force-pushed the packet_timestamp-for-2.1.13 branch from fa0c91e to 6af1a59 Compare August 4, 2026 14:39
Comment thread bufferevent_openssl.c
first_ts_valid = 1;
bio_data->last_recv_ts_valid = 0;
} else if (bio_data && bio_data->has_recv_ts) {
first_ts = bio_data->last_recv_ts;

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

do_read clears last_recv_ts_valid but not has_recv_ts, so a later read with no new cmsg re-reports the prior timestamp as current

Comment thread buffer.c Outdated
@trondn
trondn force-pushed the packet_timestamp-for-2.1.13 branch 7 times, most recently from e132af0 to 38dcc91 Compare August 5, 2026 18:49
@pavlosg

pavlosg commented Aug 13, 2026

Copy link
Copy Markdown

Review: kernel socket receive timestamps + UDP datagram truncation fix

Commits reviewed:

  • 25f105b2 openssl: Fix 3.0+ test suite; enforce >= 3.4
  • dae45394 Add kernel socket receive timestamp support
  • 38dcc911 bufferevent: prevent UDP datagram truncation

Verified by building and running the suite on macOS 14 arm64 (AppleClang, OpenSSL 3.6.0) and
Linux 6.10 aarch64 (Debian trixie, gcc, OpenSSL 3.5.6). Both platforms build clean with no new
warnings. Two blocking issues below; each is invisible on the other platform, so neither shows up
in a single-platform CI run.


(1) Blocking — bufferevent/bufferevent_udp_large_datagram fails on macOS/BSD

Deterministic, 5/5 runs. The test reports [Lost connection!]; run in-process it dies on
signal 14 (SIGALRM) — it hangs and the tinytest watchdog kills it.

test/regress_bufferevent.c:1850 sends a 16000-byte UDP datagram. macOS caps datagrams at
net.inet.udp.maxdgram = 9216:

send( 4096) ->   4096   ok
send( 8192) ->   8192   ok
send( 9216) ->   9216   ok
send(16000) ->     -1   Message too long

It hangs rather than failing because bufferevent_write() only buffers and returns 0; the actual
send() fails asynchronously with EMSGSIZE, and bev1 has no event callback (bufferevent_setcb
is called only for bev2), so the error is swallowed. done stays 0 and event_base_dispatch()
never returns.

Passes 5/5 on Linux, where the datagram limit is far higher — which is why it isn't caught there.

Suggested fix, both parts:

  • Reduce the payload to ≤ 9216. 8192 still exercises the > 4096 path this test exists to prove.
  • Add an event callback on bev1 so a send failure fails the test loudly instead of hanging.

Repro:

./regress bufferevent/bufferevent_udp_large_datagram          # [Lost connection!]
./regress --no-fork bufferevent/bufferevent_udp_large_datagram; echo $?   # 142 = SIGALRM

(2) Blocking — TCP timestamp tests are order-dependent and flaky on Linux

FAIL test/regress_bufferevent.c:1519: assert(ts_result == 0): -1 vs 0
FAIL test/regress_ssl.c:1006:         assert(ts_result == 0): -1 vs 0

Measured on Linux:

Scenario Failures
bufferevent/bufferevent_recv_timestamps_tcp alone 26/30 (87%)
UDP timestamp test first, then the TCP test, same invocation 0/30
ssl/..._direct_recv_timestamps + ..._filter_recv_timestamps alone 4/40 (~10%)
bufferevent/bufferevent_recv_timestamps (UDP) alone 0/40

Cause: the first socket in a process to enable SO_TIMESTAMPNS does not get a timestamp on its
first packet. A direct probe shows the pattern clearly — first read unstamped, all subsequent reads
stamped:

per-read timestamp presence over 10 sequential reads:  .YYYYYYYYY     (Y = timestamp present)

These tests pass in a full-group run only because earlier tests happen to warm the kernel state
first. That is an accidental ordering dependency: running a single test to debug, sharding CI, or
reordering the suite will all produce spurious failures.

Suggested fix: warm up inside each timestamp test — send and consume one throwaway packet before
the measured one — or assert on the second read rather than the first.

There is a product-behaviour point underneath this worth addressing separately: on Linux
evbuffer_get_timestamp() can return -1 for early data even when timestamping is enabled and
working. Applications measuring arrival latency have to tolerate that, and it is not currently
documented in include/event2/buffer.h.

(3) evbuffer_read_impl_ raises the per-read size for all TCP bufferevents

The change in buffer.c removes the EVBUFFER_MAX_READ (4096) clamp for explicit read sizes, not
only for datagram sockets. Since MAX_SINGLE_READ_DEFAULT is 16384, every socket bufferevent now
reserves up to 16 KB per read instead of 4 KB.

This is plausibly a throughput win, and it makes max_single_read meaningful for the first time,
but it is a global change to memory profile and per-read behaviour landing in a commit titled
"prevent UDP datagram truncation". Worth an explicit ChangeLog entry so it is not a surprise.

Related edge case: when FIONREAD fails (returns -1), howmuch is no longer clamped at all,
where previously it fell back to 4096.

(4) AF_UNIX sockets on Linux report timestamping as enabled but never deliver it

be_socket_enable_timestamps_() in bufferevent_sock.c refuses SOCK_STREAM only on
Apple/FreeBSD/OpenBSD/NetBSD/DragonFly. On Linux, setsockopt(SO_TIMESTAMPNS) succeeds for
AF_UNIX but no control message is ever delivered:

AF_UNIX/STREAM + SO_TIMESTAMPNS, 6 reads:  ......     (none stamped)

So BEV_OPT_RECV_TIMESTAMPS on an AF_UNIX bufferevent reports success and then returns -1 from
evbuffer_get_timestamp() for the life of the connection, with no way for the caller to tell that
apart from "no data received yet". Extending the existing SO_TYPE probe to reject AF_UNIX
(via getsockname()/SO_DOMAIN) would make this honest.

(5) The OpenSSL floor is stricter than the code requires

openssl-compat.h, CMakeLists.txt:846 and m4/libevent_openssl.m4 all require >= 3.4.0.
The only version-sensitive symbol in the tree is SSL_R_UNEXPECTED_EOF_WHILE_READING, which is
available from 3.0. Requiring 3.4 excludes Debian 12, RHEL 9 and Ubuntu 24.04, which ship 3.0.x.

If 3.4 is deliberate policy this is fine as-is — the diagnostics are good, and the failure is a
clear configure-time error rather than a confusing compile error. Flagging only in case the
intended floor was 3.0.


Test results

Group macOS / OpenSSL 3.6.0 Linux / OpenSSL 3.5.6
evbuffer/ 62 ok 62 ok
bufferevent/ 1/40 failed — see (1) 39 ok, 2 skipped
ssl/ 29 ok, 2 skipped 1/31 failed — see (2), intermittent
http/ 74 ok, 16 skipped 72 ok, 18 skipped

Notes on what works well

  • The SO_TYPE probe correctly refuses SOCK_STREAM on BSD, where SO_TIMESTAMP on a stream
    socket is a silent kernel no-op. This removes both the false "enabled" signal and the per-read
    chain allocation cost on that path.
  • Timestamp lifetime across TLS records is handled carefully. ssl/..._recv_ts_multiple_records
    asserts ts2 > ts1 across consecutive records and passes, so records are not mis-attributed to
    an earlier segment's timestamp.
  • evbuffer/get_timestamp_unstamped_then_stamped is a good regression test: it covers both the
    fresh-chain-on-unstamped-tail path and the evbuffer_commit_space_with_timespec() guard against
    retroactively stamping pre-existing bytes, and it runs on both platforms rather than skipping.
  • Documenting the TCP semantics in include/event2/buffer.h — per-read, corresponding to the last
    segment in that read — matches the kernel behaviour I measured (a coalesced two-segment read
    reports the second segment's arrival time, +0.1 ms vs +400.9 ms).

Under OpenSSL 3.0+, unexpected socket closures before a clean SSL/TLS shutdown alert is exchanged are classified as protocol errors rather than clean EOFs, causing regression tests to fail.

- https_bev: enable allow_dirty_shutdown on server bufferevents to handle abrupt client socket closures cleanly

- http_incomplete_errorcb: accept BEV_EVENT_ERROR with an OpenSSL error as a successful termination (OpenSSL 3.0 treats raw socket shutdowns as TLS protocol errors)

- openssl-compat.h: require OpenSSL >= 3.0.0 and explicitly reject LibreSSL. OpenSSL older than 3.0 is EOL, and LibreSSL is not supported in this branch as LibreSSL is not available for testing its API.
@trondn

trondn commented Aug 14, 2026

Copy link
Copy Markdown
Author

Fixed the issues reported by @pavlosg yesterday

@trondn
trondn force-pushed the packet_timestamp-for-2.1.13 branch from 38dcc91 to ae53187 Compare August 14, 2026 09:54
@pavlosg

pavlosg commented Aug 18, 2026

Copy link
Copy Markdown

c21eece1 (OpenSSL 3.0+ enforcement), 5940a264 (kernel receive timestamps), ae53187b (UDP datagram truncation).

Validation performed

macOS build AppleClang 15, arm64, OpenSSL 3.6 — clean, 0 warnings
Linux build Debian bookworm, gcc 12, OpenSSL 3.0.17 — clean, 0 warnings
Full regress suite 2/366 fail (bufferevent_pair_release_lock, dns/getaddrinfo_cancel_stress) — both fail identically on the pre-series baseline 79ddfb46, so neither is a regression
New timestamp tests all 10 pass

Runtime evidence below comes from purpose-built repro programs and strace in the Linux container; each finding is tagged with how it was established.

Blocking

(1) bufferevent_openssl.c:1968 — fd double-close for non-socket BIOs — CONFIRMED, runtime, regression

BIO_set_close(bio, 0) used to run unconditionally on the have_fd >= 0 path; it is now gated on BIO_TYPE_SOCKET || BIO_TYPE_LIBEVENT_RECVMSG, so any other fd-bearing BIO keeps its close flag armed.

Repro: SSL_set_bio(ssl, bio, bio) + bufferevent_openssl_socket_new(base, -1, ssl, ..., BEV_OPT_CLOSE_ON_FREE), traced with strace -e trace=close.

BIO type close flag after bev create close(fd) at teardown
BIO_TYPE_SOCKET (BIO_new_socket) 0 1x
BIO_TYPE_FD (BIO_new_fd) 1 2x — second returns EBADF
BIO_TYPE_BUFFER (BIO_f_buffer over a socket BIO) 1 2x — second returns EBADF

Same program against baseline 79ddfb46: close flag 0 and exactly one close(3) for all three BIO types. The EBADF is benign only because nothing reopened the descriptor in between; in a threaded program the second close destroys an unrelated fd.

(2) bufferevent_openssl.c:505 — stale-timestamp guard is dead code — CONFIRMED, static

} else if (!data->last_recv_ts_valid && !data->has_recv_ts) {
        data->has_recv_ts = 0;   /* the guard already implies this */
}

The condition implies the assignment, so the protection documented at lines 362-367 never applies. Deleting the whole block leaves the generated code for bio_socket_recvmsg_read semantically identical (166 -> 163 instructions, difference is only the dead test and store; the rest differs solely in register allocation).

Consequence: recvmsg #1 records ts1; do_read() consumes it but SSL_pending() != 0 leaves has_recv_ts == 1; recvmsg #2 (seconds later) returns data with no cmsg timestamp; the reset is skipped and the next do_read() stamps unrelated data with ts1. I did not build an end-to-end repro for that sequence — the logic defect is unconditional either way.

Fix: else if (!data->last_recv_ts_valid).

(3) buffer.c:2473MSG_TRUNC never checked — CONFIRMED, runtime

The recvmsg path ignores msg.msg_flags & MSG_TRUNC. Sending one 40000-byte UDP datagram and calling evbuffer_read_with_timestamp(buf, fd, 16384):

  return value        : 16384
  evbuffer length     : 16384
  bytes silently lost : 23616

No error, no warning — the caller cannot distinguish this from a normal short read. Directly at odds with the goal of ae53187b.

(5) bufferevent_openssl.c:1084do_write() error paths skip the timestamp clear — CONFIRMED, static

Four early return OP_ERR | result; at lines 1084, 1105, 1117, 1125 bypass the sole clear_new_bio_recvmsg_ts() call at line 1147. If SSL_write() serviced a renegotiation read first, last_recv_ts_valid stays set and the next do_read() attributes a renegotiation-byte timestamp to an application record. Use a single goto out exit.

(6) buffer.c:2509continue lets SCM_TIMESTAMP clobber SCM_TIMESTAMPNSCONFIRMED, runtime

40 UDP datagrams, checking how often tv_nsec % 1000 != 0:

  SO_TIMESTAMPNS only (control)      timestamps=40  sub-microsecond precision=38
  SO_TIMESTAMPNS + SO_TIMESTAMP      timestamps=40  sub-microsecond precision= 0

Sample values go from tv_nsec=768285667 to tv_nsec=808397000 — the nanosecond value found at line 2502 is overwritten at 2515-2516 by the microsecond one. bufferevent_openssl.c:471 uses break on the same cmsg scan, so the two paths disagree for the same socket. Use break in both, or prefer TIMESTAMPNS explicitly. The MSG_CTRUNC test at line 2496 is loop-invariant and belongs outside the loop.

Should fix

(8) include/event2/buffer.h:775 — doc contradicts implementation — CONFIRMED, runtime

The header says howmuch above EVBUFFER_MAX_READ (4096) is clamped. buffer.c:2383-2389 only clamps when FIONREAD fails. Passing howmuch = 1000000 with data queued reads 60000 bytes. The matching relaxation of evbuffer_read() (lines 746-747) also changes behaviour for every existing caller (http, rpc) and should be documented.

(9) buffer.c:2399 — one fresh chain per timestamped read — CONFIRMED, runtime, but smaller than it looks

200 reads of 100 bytes with howmuch = 16384, buffer never drained, counted via event_set_mem_functions:

  evbuffer_read          mallocs=  23   >=4KiB mallocs=0   total malloc'd=  22664
  ..._with_timestamp     mallocs= 201   >=4KiB mallocs=0   total malloc'd= 204936

~9x memory and ~8.7x malloc count, one chain per read instead of packing into shared tail space. Correction to my earlier description: there is no 32 KB-per-read allocation and no 320x amplification — get_n_bytes_readable_on_socket() clamps howmuch down to the bytes actually available before the chain is sized, so each chain is MIN_BUFFER_SIZE (~1 KB), not max_single_read rounded up. The waste is the per-read chain header plus rounding, not an oversized buffer. Still worth fixing (allocate a fresh chain only when the tail already holds data), but it is an efficiency nit, not a memory blowup.

(4) buffer.c:2462, bufferevent_openssl.c:423 — unaligned cmsg buffer — NOT REPRODUCED; latent

unsigned char control[...] has declared alignment 1 while _Alignof(struct cmsghdr) is 8. On x86-64 and aarch64 the compiler places the local on a 16-byte boundary anyway, so this does not misbehave on any mainstream target, and I could not produce a fault. It remains a real portability defect (the placement is the compiler's choice, not a guarantee — inside a struct after a char the same array lands at offset 1), and the portable idiom costs nothing:

union { unsigned char buf[N]; struct cmsghdr align; } control;

Treat as cleanup rather than a bug.

(7) bufferevent_async.c:306 — FIONREAD sizing is a no-op on IOCP — UNVERIFIED (Windows-only)

Overlapped reads are pre-posted, so be_socket_get_n_bytes_readable_() should return 0 and at_most fall back to max_single_read, leaving the 20 KB datagram case the comment at lines 285-296 claims to prevent. This path is _WIN32-only and could not be exercised on Linux or macOS — reasoning only. Either raise the dgram floor or document the remaining limit.

Cleanups

(10) bufferevent_sock.c:115 — duplicated FIONREAD helper — CONFIRMED, runtime

strace of a UDP bufferevent read loop shows exactly two ioctls per read event:

ioctl(3, FIONREAD, [512])
ioctl(3, FIONREAD, [512])
recvmsg(3, {... cmsg_type=SO_TIMESTAMPNS_OLD ...}, 0) = 512

One from be_socket_get_n_bytes_readable_() (bufferevent_sock.c:316), one from get_n_bytes_readable_on_socket() (buffer.c:2376). Two copies of the same #ifdef ladder, and they differ — one seeds the ioctl argument with EVBUFFER_MAX_READ, the other with 0. Export the buffer.c helper and share it.

(11) bufferevent_sock.c:168 — dead SO_TYPE probe; missing fd < 0 guard — CONFIRMED, runtime + static

strace of bufferevent_socket_new(..., BEV_OPT_RECV_TIMESTAMPS):

getsockopt(3, SOL_SOCKET, SO_TYPE, [2], [4]) = 0     <- be_socket_is_dgram_()
getsockname(3, {AF_INET, ...})              = 0     <- AF_UNIX rejection (useful)
getsockopt(3, SOL_SOCKET, SO_TYPE, [2], [4]) = 0     <- dead: body is empty on Linux
setsockopt(3, SOL_SOCKET, SO_TIMESTAMPNS_OLD, [1], 4) = 0

On Linux EVENT__HAVE_DECL_SO_TIMESTAMPNS is 1, so the inner #if at line 172 is false and if (type == SOCK_STREAM) { } is an empty body — the second getsockopt is pure waste per create and per setfd. (Correction to my earlier note: the getsockname above it is functional, it rejects AF_UNIX. Only the SO_TYPE probe is dead.)

Separately, be_openssl_ctrl() (line 1745) passes data->fd to be_socket_enable_timestamps_() and that can be -1 when clearing the fd; unlike be_socket_is_dgram_() there is no early return, so three syscalls run on fd -1.

(12) bufferevent_openssl.c:962 — hoist evbuffer_get_timestamp() out of the iovec loop — static, not measured

Called per iteration, but only consumed when n_used == 1 (line 987). Each call locks/unlocks the underlying evbuffer. Skip it entirely when timestamps aren't armed.

(13) test/regress_ssl.c:1284fd_w leaked on error paths — CONFIRMED, static

rbio/wbio are both created BIO_NOCLOSE (lines 1241-1243). On the success path be_openssl_destruct() closes fd_w via BIO_get_fd(wbio), so the comment at 1279-1281 is accurate. But on any tt_assert failure before bev exists, or if bufferevent_openssl_socket_new() returns NULL, the else if (ssl) SSL_free(ssl); branch frees both BIOs without closing anything and the cleanup closes only fd_r. Error path only, so not runtime-triggerable without fault injection.

(14) test/regress_bufferevent.c:1476 — displaced fd leaked — CONFIRMED, runtime

strace of bufferevent/bufferevent_recv_timestamps, pairing each socket(AF_INET, SOCK_DGRAM) with its closes:

  fd 7  : closed 0 time(s)    <- original listener, displaced by bufferevent_setfd()
  fd 8  : closed 1 time(s)
  fd 9  : closed 1 time(s)
  fd 10 : closed 1 time(s)

bufferevent_setfd() does not close the previous fd, and fd_pair[1] was already set to -1 at line 1418, so the end: block skips it.

(15) buffer.c:1447 — redundant if (chain->timestamp.valid)CONFIRMED, static

tmp comes from evbuffer_chain_new(), which zeroes the header (buffer.c:181), so an unconditional copy is equivalent.

@trondn
trondn force-pushed the packet_timestamp-for-2.1.13 branch from ae53187 to d2a2d48 Compare August 19, 2026 09:01
@trondn

trondn commented Aug 19, 2026

Copy link
Copy Markdown
Author

Addressed all comments by @pavlosg yesterday

@pavlosg

pavlosg commented Aug 20, 2026

Copy link
Copy Markdown

Branch force-updated ae53187bd2a2d48f. c21eece1 is byte-identical; commits 2 and 3 were rewritten.

Validation performed

macOS build AppleClang 15, arm64, OpenSSL 3.6 — 2 warnings, both in files this series doesn't touch (evutil_rand.c, test/regress_main.c)
Linux build Debian bookworm, gcc 12, OpenSSL 3.0.20 — 0 warnings
Full regress suite 2/364 fail — same two pre-existing failures as baseline 79ddfb46 (bufferevent_pair_release_lock, dns/getaddrinfo_cancel_stress)
Timestamp tests 11 pass
Bisectability all three commits build; the stray >>>>>>> 0d1b954e conflict marker that made the old commit 2 unbuildable is gone

All 15 findings were addressed. 12 verified fixed, 2 are inert or partial, and 1 fix introduced a new bug. One of my original findings — (6) — was mis-diagnosed; correction below.

New — introduced by this rewrite

(16) buffer.c:2509break skips SCM_RIGHTS, leaking received descriptors — CONFIRMED, runtime, regression

The (6) fix turned continue into break after a timestamp cmsg. The SCM_RIGHTS handler sits earlier in the same loop body, and the kernel puts the timestamp cmsg first, so the scan now aborts before ever reaching the descriptors:

recvmsg -> 1 bytes; cmsg order as delivered:
  [0] level=1 type=35 (SCM_TIMESTAMPNS)
  [1] level=1 type=1  (SCM_RIGHTS)

10 AF_UNIX datagrams carrying 2 descriptors each, through evbuffer_read_with_timestamp():

open fds before after leaked
ae53187b (continue) 5 5 0
d2a2d48f (break) 5 25 20 / 20

bufferevent_openssl.c:471 has the same break and the same exposure; it predates this rewrite. Its comment — "Closing SCM_RIGHTS fds above must not be skipped … fds that fit within the control buffer have already been duplicated into this process and must still be closed" — states exactly the invariant the break violates.

Reachability: be_socket_enable_timestamps_() rejects AF_UNIX, so no bufferevent hits this. It is reachable through the public evbuffer_read_with_timestamp() on a socket the caller armed itself, which is what the repro does.

Fix: restore continue and prefer nanoseconds with a flag rather than by exiting the loop:

if (cmsg->cmsg_type == SCM_TIMESTAMP) {
        if (ts_found)      /* an SCM_TIMESTAMPNS already won */
                continue;
        ...
}

Correction: my original finding (6) was wrong

I attributed the lost nanosecond precision to a second cmsg clobbering the first inside libevent's loop. That is not what happens. The kernel emits exactly one timestamp cmsg, and setsockopt(SO_TIMESTAMP) clears SOCK_RCVTSTAMPNS, so the two options are mutually exclusive — last one set wins:

SO_TIMESTAMPNS only:  [0] type=35 SCM_TIMESTAMPNS  tv_nsec=402140136
SO_TIMESTAMP   only:  [0] type=29 SCM_TIMESTAMP    tv_usec=402176
both enabled:         [0] type=29 SCM_TIMESTAMP    tv_usec=402194

My repro enabled SO_TIMESTAMP after SO_TIMESTAMPNS and so disabled nanoseconds at the socket level — the precision loss was in my test setup, not in buffer.c. libevent's loop never sees two timestamp cmsgs. The pre-rewrite continue was harmless; the break that replaced it fixes nothing and costs the descriptors above. The only genuine part of (6) was cosmetic: buffer.c and bufferevent_openssl.c scanned differently.

Fixes that don't do anything

(9) tail-chain reuse never fires — CONFIRMED, runtime

The new guard is buf->last && off == 0 && CHAIN_SPACE_LEN >= howmuch. Five drain patterns, 100 timestamped reads each, all show one malloc per read — unchanged from ae53187b.

Counting which sub-condition rejects reuse, via a build with the guard instrumented:

  scenario                         |  !last   off!=0  immut  nospace | REUSED
  ---------------------------------+---------------------------------+-------
  never drained                    |      1       99      0        0 |      0
  fully drained each round         |    100        0      0        0 |      0
  drained to 10 bytes              |      1       99      0        0 |      0
  drained + evbuffer_expand        |      1        0      0        0 |     99
  fully drained, howmuch=128       |    100        0      0        0 |      0

The two rejection modes are exactly the ones the read loop alternates between: evbuffer_drain() of the whole buffer frees the chains and leaves buf->last == NULL (100/100), and anything short of a full drain leaves a tail with off > 0 (99/100, the odd one being the first read, when no chain exists yet). EVBUFFER_IMMUTABLE and the space check never reject.

The branch can fire — the evbuffer_expand() row reuses 99/100 — but only when something outside the read path leaves an empty tail chain with space, which the read path never does. Either drop it as dead weight or reuse the tail whenever CHAIN_SPACE_LEN(buf->last) >= howmuch and stamp only the bytes this read contributed.

(10) the helper was deduplicated, the syscall wasn't — CONFIRMED, runtime

get_n_bytes_readable_on_socket() is gone and buffer.c now calls be_socket_get_n_bytes_readable_(), so the two divergent #ifdef ladders are one. But both call sites remain — bufferevent_readcb() at bufferevent_sock.c:335 and evbuffer_read_impl_() at buffer.c:2356 — so it is still two ioctls per read event:

ioctl(3, FIONREAD, [512])
ioctl(3, FIONREAD, [512])
recvmsg(3, {... cmsg_type=SO_TIMESTAMPNS_OLD ...}, 0) = 512

Pass the value the caller already has down to evbuffer_read_impl_(), or let the dgram path in bufferevent_readcb() rely on the clamp inside evbuffer_read_impl_().

Verified fixed

evidence
(1) fd double-close BIO_TYPE_FD/BIO_TYPE_BUFFER close flag 1 → 0; close(3) count 6 → 5, EBADF 1 → 0. All three BIO types now match.
(2) dead stale-timestamp guard now else if (!data->last_recv_ts_valid)
(3) MSG_TRUNC 40000-byte datagram read with howmuch=16384 returns −1/EMSGSIZE, buffer length 0. 1000 truncated + 1000 normal reads interleaved: +0 bytes, +0 blocks live — the rollback that unlinks the chain after n = -1 is correct.
(4) cmsg alignment union { unsigned char buf[N]; struct cmsghdr align; } in both files
(5) do_write() early returns single out: label
(7) IOCP dgram sizing floors at_most at EVENT_MAX_UDP_DATAGRAM_ (65527). Windows-only, still unexercised here.
(8) header docs rewritten to describe actual behaviour, including the pre-2.1.13 note
(11) dead SO_TYPE probe gone from the trace — one SO_TYPE, one getsockname, one setsockopt per create. fd < 0 guard added.
(12) evbuffer_get_timestamp() in the iovec loop gated on the underlying bufferevent having timestamps armed
(13) fd_w leaked on test error paths closed in the else branch
(14) displaced fd leaked all four dgram fds now close exactly once (was: fd 7 never closed)
(15) redundant if (chain->timestamp.valid) unconditional copy

Notes

  • EMSGSIZE is fatal to a bufferevent. bufferevent_readcb() maps a non-retriable -1 to BEV_EVENT_ERROR, so a truncated datagram tears the bufferevent down. Normally unreachable — the dgram path sizes howmuch from FIONREAD first — but be_socket_get_n_bytes_readable_() returns −1 where FIONREAD is unavailable, and then any datagram over max_single_read kills the connection where it used to be silently truncated. Also asymmetric: the non-timestamped path still truncates silently. Worth an explicit EMSGSIZE case in bufferevent_readcb().
  • IOCP floor costs memory. Every pending overlapped dgram read now reserves ≥64 KiB regardless of max_single_read. Intended, but it is a per-bufferevent cost on Windows servers with many UDP sockets.
  • Squash artifact. 39df73b5 adds test_bufferevent_ratelim_udp, test_bufferevent_wm_udp and test_bufferevent_udp_large_datagram but registers them only in d2a2d48f, so the intermediate commit builds with three -Wunused-function warnings.
  • Two SSL tests self-skip intermittently. ssl/bufferevent_openssl_recv_ts_interleaved_write and ..._recv_ts_multiple_records skip when their kernel-timestamp probe doesn't fire — 1/20 and 3/20 over 20 runs, on the new and old tip alike. Pre-existing, but they don't reliably guard what they were written for.

@trondn
trondn force-pushed the packet_timestamp-for-2.1.13 branch from d2a2d48 to d8acab9 Compare August 21, 2026 05:43
@trondn

trondn commented Aug 21, 2026

Copy link
Copy Markdown
Author

Fixed comments given by @pavlosg yesterday. With respect to the notes for UDP; that code path is (currently) not being used in our use-case (it is currently all TCP)

@pavlosg

pavlosg commented Aug 27, 2026

Copy link
Copy Markdown

Correctness findings

(1) BIO_C_SET_FD reads the fd out of ptr as a value — bufferevent_openssl.c:615

Confirmed by repro.

bio_socket_recvmsg_ctrl() does:

case BIO_C_SET_FD:
        data->fd = (evutil_socket_t)(ev_intptr_t)ptr;
        BIO_set_shutdown(b, (int)num);

OpenSSL's public macro is #define BIO_set_fd(b,fd,c) BIO_int_ctrl(b,BIO_C_SET_FD,c,fd), and BIO_int_ctrl() does int i = iarg; return BIO_ctrl(b, cmd, larg, (char *)&i); — so ptr is a pointer to a stack int and the close flag arrives in num, not the other way round.

Repro on Linux/aarch64, UDP AF_INET socket with BEV_OPT_RECV_TIMESTAMPS so the recvmsg BIO is installed:

BIO method type = 1082 (recvmsg BIO; BIO_TYPE_SOCKET=1285)
initial  BIO_get_fd -> 6   (real fd 6)
after BIO_set_fd(7) -> BIO_get_fd = -1043134284  *** WRONG ***

The low 32 bits of &i become the descriptor; every later recvmsg()/send() targets it, and BIO_set_shutdown() takes the close flag from the wrong argument. The plain BIO_s_socket() libevent installs today handles the same call correctly, so this is a behavior regression for any app that calls BIO_set_fd() on the SSL's rbio.

Fix. Read *(int *)ptr, matching the BIO_C_GET_FD case immediately below it, and switch libevent's own call at bufferevent_openssl.c:684 to BIO_int_ctrl().


(2) readmax <= 0 returns with the level-triggered event still armed — bufferevent_sock.c:322

Confirmed by repro.

New code in bufferevent_readcb():

readmax = bufferevent_get_read_max_(bufev_p);
if (readmax <= 0) {
        goto done;
}

done: neither suspends reading nor deletes ev_read, which is EV_READ|EV_PERSIST and level-triggered, so the callback is re-entered immediately while the socket stays readable.

readmax == 0 is reachable with read_suspended clear. bufferevent_ratelim.c:247:

share = LIM(g->rate_limit) / g->n_members;
if (share < g->min_share)
        share = g->min_share;

With bufferevent_rate_limit_group_set_min_share(g, 0) — documented as disabling the floor — and a group limit below the member count, share is 0 while the group is not suspended (suspension only happens in decrement when the bucket goes ≤ 0).

Repro: 5 bytes/tick shared by 10 members, min_share 0, 10 readable sockets, measured over a 500 ms window:

wall 500 ms, cpu 500 ms  (100% busy)
readcb invocations: 0   BEV_EVENT_EOF: 0   BEV_EVENT_ERROR: 0

Nothing was ever read. Pre-change code read 0 bytes and mislabelled it EOF — also wrong, but it terminated.

Fix. Suspend reading (or event_del the read event) instead of a bare goto done, so the loop parks until the bucket refills.


(3) A public read API silently closes descriptors passed via SCM_RIGHTSbuffer.c:2476

Confirmed by repro.

evbuffer_read_with_timestamp() walks the control buffer and unconditionally closes every fd in an SCM_RIGHTS cmsg. No error, no indication in the return value, no mention in the header docs. Duplicated at bufferevent_openssl.c:452.

Repro: pass the write end of a pipe over an AF_UNIX SOCK_DGRAM socket, drop the sender's copy, then read the message two ways:

plain recvmsg (ctrl)   read= 5 bytes   passed fd still open afterwards: YES
evbuffer_read_with_ts  read= 5 bytes   passed fd still open afterwards: NO  <-- fd was closed

The payload arrives, the descriptor does not. If that fd number is later reused, a subsequent close of an unrelated fd becomes a double-close on the wrong object.

Fix. Either document it loudly in include/event2/buffer.h as a precondition (socket must not carry SCM_RIGHTS), or stop closing and let the caller own what the kernel installed. Silently closing a descriptor the application was sent is the one behavior that cannot be recovered from.


(4) do_read() early returns skip the has_recv_ts retirement block — bufferevent_openssl.c:996, :1029, :1036

Confirmed by fault injection. Scope is narrower than first reported.

Three return OP_ERR | result; paths inside do_read()'s loop bypass the retirement block at :1076:

if (bio_data && bio_data->has_recv_ts &&
    SSL_pending(bev_ssl->ssl) == 0) {
        bio_data->has_recv_ts = 0;
}

Leaving has_recv_ts == 1 with last_recv_ts_valid == 0 makes bio_socket_recvmsg_read()'s if (!last_recv_ts_valid && !has_recv_ts) guard refuse to record the next timestamp, so the next record inherits the previous record's kernel timestamp.

Verification: a copy of the tree with a one-shot early return injected at the equivalent point (after the n_used == 1 attribution, while has_recv_ts is still set), TLS server writing one 19-byte record every 150 ms, instrumented trace:

[ts] INJECT early return: leaving last_valid=0 has=1 ssl_pending=0
[ts] do_read enter: last_valid=0 has=1 ssl_pending=0
[ts] bio_read r=5  ts_found=1 pre(last_valid=0 has=1) -> KEEP old
[ts] bio_read r=36 ts_found=1 pre(last_valid=0 has=1) -> KEEP old
[ts] do_read attribute: last_valid=0 has=1 underlying=0
[ts] do_read retire has_recv_ts (ssl_pending=0)

read 1: kernel ts is   106.1 ms older than the callback  <-- handshake-tail artifact, also present clean
read 2: kernel ts is   148.7 ms older than the callback  <-- STALE, one record interval behind
read 3: kernel ts is     0.1 ms older than the callback
read 4: kernel ts is     0.1 ms older than the callback

Two things worth recording:

  • It self-heals. The next completed do_read() retires the flag, so this is one mis-timestamped record per occurrence, not permanent corruption of the connection as originally claimed.
  • The bufferevent survives to mis-attribute. consider_reading() merely breaks its loop on OP_ERR — no error event, no read disable — so reads continue afterwards.

The vulnerable state is the common one: the trace shows attribute: last_valid=1 has=1 on 4 of 5 attributions.

The uncommitted-iovec data loss on those same three paths is pre-existing upstream behavior (verified against HEAD~3), not introduced here.

Fix. Move the retirement block into a goto out epilogue, the way do_write() was already restructured in this commit, so all three exits run it.


(5) evbuffer_read() no longer caps a caller-supplied howmuchbuffer.c:2371

Confirmed by before/after run.

} else {
        if (n > 0 && n < howmuch) {
                howmuch = n;
        } else if (n < 0 && howmuch > EVBUFFER_MAX_READ) {
                howmuch = EVBUFFER_MAX_READ;
        }
}

For howmuch >= 0 with FIONREAD available, the 4096-byte ceiling is gone. The commit message states this is intentional for datagram sockets, but the change lands on the shared evbuffer primitive and therefore on every existing caller.

Same program linked against both trees, TCP loopback with 418920 bytes queued:

HEAD~3     : evbuffer_read(buf, fd, 1000000) -> 4096 bytes in ONE call
this tree  : evbuffer_read(buf, fd, 1000000) -> 418920 bytes in ONE call

An app using evbuffer_read(buf, tcp_fd, INT_MAX) as the "read whatever is there" idiom now drains the entire socket queue in a single event callback, allocating for all of it.

Fix. Scope the uncapped read to the datagram path, which bufferevent_readcb() already identifies via bufev_p->is_dgram, rather than changing the contract of a long-standing public function.


(6) MSG_CTRUNC discards timestamps that arrived intact — buffer.c:2470

Confirmed by repro.

int ctrunc = (msg.msg_flags & MSG_CTRUNC) != 0;
for (cmsg = CMSG_FIRSTHDR(&msg); cmsg; cmsg = CMSG_NXTHDR(&msg, cmsg)) {
        ...
        if (!ctrunc) {
                /* SCM_TIMESTAMPNS / SCM_TIMESTAMP handling */
        }
}

MSG_CTRUNC means the tail of the control buffer was dropped; it says nothing about cmsgs already delivered. The control buffer is CMSG_SPACE(timespec) + CMSG_SPACE(timeval) + 256 = 320 bytes here.

Repro on AF_UNIX SOCK_DGRAM with SO_TIMESTAMPNS armed and the sender passing 100 fds so the ancillary data overflows. Raw recvmsg() with an identically sized buffer shows exactly what libevent sees:

MSG_CTRUNC set: yes
cmsg type=SCM_TIMESTAMPNS len=32  <-- complete and usable
cmsg type=SCM_RIGHTS      len=288

Through libevent on the same socket, same option:

no SCM_RIGHTS (no MSG_CTRUNC):  evbuffer_get_timestamp -> 0  (timestamp recorded)
with SCM_RIGHTS (MSG_CTRUNC):   evbuffer_get_timestamp -> -1 (NO timestamp)

The kernel puts the timestamp first and truncates the tail — so the guard throws away a complete, usable timestamp.

Fix. Drop the ctrunc guard. The cmsg_len check two lines below is already the correct and sufficient test: only a cmsg whose own length is short is unsafe to read.


(7) recv_timestamps_enabled derived from BIO type, not from options — bufferevent_openssl.c:1897

Confirmed by repro.

In bufferevent_openssl_new_impl():

BIO *rbio = SSL_get_rbio(ssl);
if (rbio && BIO_method_type(rbio) == BIO_TYPE_LIBEVENT_RECVMSG) {
        struct bio_socket_recvmsg_data *bio_data = BIO_get_data(rbio);
        bev_ssl->bev.recv_timestamps_enabled = 1;
        if (bio_data) {
                bio_data->bev_ssl = bev_ssl;
        }
}

options is never consulted. be_openssl_destruct() only frees the SSL under BEV_OPT_CLOSE_ON_FREE, so a recvmsg BIO can outlive the bufferevent that asked for it and be inherited by the next one.

Repro with a real TLS handshake; first bufferevent created with BEV_OPT_RECV_TIMESTAMPS and no BEV_OPT_CLOSE_ON_FREE, then freed (destruct allowed to complete), second bufferevent created over the same SSL with plain options:

scenario=control        rbio type=1285 (plain socket BIO)   timestamp on input: no
   read syscalls: read=42
scenario=reuse          rbio type=1082 (libevent recvmsg BIO)  timestamp on input: YES
   read syscalls: read=18  recvmsg=24

The second bufferevent pays for recvmsg with a 320-byte control buffer on every read, gets full timestamp bookkeeping, and inherits the SCM_RIGHTS-closing behavior of (3) — without ever requesting any of it.

Fix. Gate the block on options & BEV_OPT_RECV_TIMESTAMPS, and swap the inherited recvmsg BIO back to a plain socket BIO when the option is absent.


(8) be_openssl_destruct() clears an owner pointer that belongs to another bufferevent — bufferevent_openssl.c:1698

Confirmed by repro. Not in the original review — found while building (7)'s repro.

if (!bev_ssl->underlying && bev_ssl->ssl) {
        BIO *rbio = SSL_get_rbio(bev_ssl->ssl);
        if (rbio && BIO_method_type(rbio) == BIO_TYPE_LIBEVENT_RECVMSG) {
                struct bio_socket_recvmsg_data *bio_data = BIO_get_data(rbio);
                if (bio_data) {
                        bio_data->bev_ssl = NULL;
                }
        }
}

No check that bio_data->bev_ssl still is this bufferevent. Since bufferevent destruction is deferred to the event loop, the sequence bufferevent_free(bev1); bev2 = bufferevent_openssl_socket_new(... same SSL ...) — an app recreating a bufferevent over a preserved SSL inside a callback — lets bev1's destruct run after bev2 claimed the BIO and null out bev2's owner pointer.

Repro is the (7) program with the loop not run between free and recreate:

scenario=reuse_nodrain  rbio type=1082 (libevent recvmsg BIO)  timestamp on input: no
   read syscalls: recvfrom=24  read=18

The recvmsg BIO is installed, but bio_socket_recvmsg_read()'s data->bev_ssl && data->bev_ssl->bev.recv_timestamps_enabled gate is false, so it takes the plain recv() branch and evbuffer_get_timestamp() returns −1 for the whole connection. Timestamps the caller explicitly requested are silently off.

Fix. if (bio_data && bio_data->bev_ssl == bev_ssl) bio_data->bev_ssl = NULL;


API-design findings

(9) BEV_OPT_RECV_TIMESTAMPS degrades silently, with no way to detect it — bufferevent_sock.c:559

Confirmed by repro on both platforms.

be_socket_enable_timestamps_() returns −1 for:

  • every AF_UNIX/AF_LOCAL socket, unconditionally (bufferevent_sock.c:174-187);
  • every SOCK_STREAM socket on Apple/BSD without SO_TIMESTAMPNS (bufferevent_sock.c:189-199, guarded by the macro defined at :142-146).

Callers see success either way. evbuffer_get_timestamp() then returns −1 forever, indistinguishable from "this data happened to carry no timestamp".

macOS, native build of this tree, TCP loopback:

bufferevent_socket_new(BEV_OPT_RECV_TIMESTAMPS) on TCP: SUCCEEDED (no error reported to the caller)
bytes read: 10   timestamp available: NO

Linux, AF_UNIX: an SSL bufferevent requesting timestamps gets a plain BIO_TYPE_SOCKET BIO (1285) instead of the recvmsg BIO — confirmed by repro. The same silent degradation applies in bufferevent_openssl_socket_new() whenever the existing BIO is not BIO_TYPE_SOCKET or rbio != wbio.

Fix. Add an accessor (e.g. bufferevent_get_recv_timestamps_enabled()), or fail bufferevent_socket_new() when the option was explicitly requested and cannot be honored. Document the platform matrix in include/event2/bufferevent.h next to the option.


Efficiency and quality findings

(10) Fresh chain per timestamped read, no reuse of trailing space — buffer.c:2386

Measured. The magnitude in the original review was wrong.

Originally reported as 32 KB per read. Measured via event_set_mem_functions() — three 10-byte reads on a TCP bufferevent, input never drained:

TIMESTAMPS OFF   chain allocations: 1   (1024 bytes, largest 1024)
TIMESTAMPS ON    chain allocations: 3   (3072 bytes, largest 1024)

FIONREAD clamps howmuch to the bytes actually pending (buffer.c:2371), so the chain is sized to the data, not to max_single_read. The 32768-byte chain would require howmuch to stay at 16384, which only happens where FIONREAD is unavailable.

What does hold: one malloc/free per read event and no reuse of the tail chain's remaining space, where the non-timestamped path reuses it and allocates nothing. A per-chain timestamp does need a fresh chain when the tail is already stamped — but not when the tail is unstamped and empty.

(11) Test reads errno instead of EVUTIL_SOCKET_ERROR()test/regress_buffer.c:529

Static only — Windows-only claim, not runnable here.

tt_assert(errno == EAGAIN || errno == EWOULDBLOCK);

On Windows the use_recvmsg block is compiled out (#ifndef _WIN32) and the read goes through WSARecv, which reports failure via WSAGetLastError() and leaves errno untouched — so the assertion tests whatever errno held from an earlier libc call. Every other socket-error check in the suite uses EVUTIL_SOCKET_ERROR().

(12) Hand-rolled chain unlink duplicates an existing helper — buffer.c:2571

Static only — quality.

The n <= 0 error path re-implements what evbuffer_free_trailing_empty_chains() already does, and walks from buf->first:

prev = buf->first;
while (prev->next != new_chain)
        prev = prev->next;

new_chain is always the chain immediately after *buf->last_with_datap, so with many chains queued this walks the whole list on every would-block wakeup. The last/last_with_datap invariants are handled correctly today; the risk is drift between the two copies.

(13) oldest_underlying_ts_valid reset from four sites — bufferevent_openssl.c:1018

Static only — quality.

Line 1018 clears it inside the n_used == 1 branch; line 1059 clears the same field unconditionally for any filter bufferevent that committed data; do_write() and do_handshake() clear it too. Four sites, no single owner. Deriving the value on demand from evbuffer_get_timestamp() on the underlying input — which is what the cache mirrors — removes all four.

@trondn

trondn commented Aug 27, 2026

Copy link
Copy Markdown
Author

Fixed 1, 3, 4, 6, 7, 8, 9, 11, 12 and 13.
2 and 5 fixed by dropping the UDP patch (we don't use UDP in our use)
Skipping 10 as I don't think it is worth fixing. The problem would (in my opinion) be rare in practice, and the performance win would be virtually unmeasurable.

@trondn
trondn force-pushed the packet_timestamp-for-2.1.13 branch from d8acab9 to f261673 Compare August 28, 2026 05:38
@trondn

trondn commented Aug 28, 2026

Copy link
Copy Markdown
Author

Updated the patch to only allow timestamp over TCP (which simplifies things). Just noticed a few things I forgot to fix.. will push a fix to them soon

@trondn
trondn force-pushed the packet_timestamp-for-2.1.13 branch from f261673 to 07ee71d Compare August 28, 2026 10:03
@pavlosg

pavlosg commented Sep 3, 2026

Copy link
Copy Markdown

It looks like the AI exhausted important findings... There are some minor things but I don't think we would be affected by them in our usage:

evbuffer_add() bypasses timestamp invalidation

buffer.c:1826, also evbuffer_prepend() and evbuffer_add_vprintf(). evbuffer_commit_space_with_timespec() invalidates a chain's timestamp whenever the chain holds bytes from more than one commit — that is its stated purpose. The public mutators append straight into chain->off and never run that guard, so anything written into a timestamped input buffer inherits a receive time it never had.

Reproduced: commit 10 bytes with a timestamp, append 5 unrelated bytes via evbuffer_add(), drain the original 10. evbuffer_get_timestamp() returns the drained bytes' timestamp for the 5 that remain.

No timestamp invalidation on OpenSSL fd swap

bufferevent_openssl.c:1767, BEV_CTRL_SET_FD. be_socket_setfd() calls evbuffer_invalidate_last_chain_timestamp_() on every fd rebind, precisely so a later read on the new fd cannot extend a chain still carrying the old fd's timestamp. The direct-fd OpenSSL path does the same rebind and never makes that call.

Reproduced on Linux over real TCP + TLS, deterministic across 6 runs: timestamp.valid stays 1 across bufferevent_setfd() to a fresh socket.

do_write() clears pending timestamps unconditionally

bufferevent_openssl.c:1162. do_handshake() guards the identical cleanup with if (SSL_pending(ssl) == 0) and explains why in a comment: an incidental read may have decrypted data that do_read() still needs the timestamp for. do_write() uses the same snapshot/restore pattern with no such guard. The asymmetry looks unintended.

SSL_pending()==0 is an imprecise retirement proxy

bufferevent_openssl.c:1056. SSL_pending() reports decrypted application data only, not raw ciphertext buffered from the same recvmsg(). When one read delivers a complete record plus the head of the next — ordinary TCP segmentation — the second record's earliest bytes lose their arrival time and get stamped later, contradicting the "oldest wins" rule implemented everywhere else.

Duplicated cmsg parsing has already diverged

buffer.c:2499,2517 vs bufferevent_openssl.c:458,476. The block is near-verbatim in both files, down to the comments, but buffer.c casts CMSG_DATA() through an intermediate (void *) and the OpenSSL copy does not. Correct at runtime — the union guarantees alignment — but confirmed with -Wcast-align=strict, where buffer.c is silent and the OpenSSL copy warns at both sites. The two copies drifted apart inside a single commit, which is the argument for a shared helper.

@trondn

trondn commented Sep 3, 2026

Copy link
Copy Markdown
Author

evbuffer_add() bypasses timestamp invalidation

buffer.c:1826, also evbuffer_prepend() and evbuffer_add_vprintf().
evbuffer_commit_space_with_timespec() invalidates a chain's
timestamp whenever the chain holds bytes from more than one
commit — that is its stated purpose. The public mutators append
straight into chain->off and never run that guard, so anything
written into a timestamped input buffer inherits a receive time
it never had.

Reproduced: commit 10 bytes with a timestamp, append 5 unrelated
bytes via evbuffer_add(), drain the original 10.
evbuffer_get_timestamp() returns the drained bytes' timestamp
for the 5 that remain.

Agreed this is real, but it's outside the usage pattern we care
about: timestamps only matter to us on buffers holding raw,
kernel-captured network data, and that path never goes through
evbuffer_add()/evbuffer_prepend()/evbuffer_add_vprintf(). Not
fixing for now; worth documenting as a limitation of the public
mutators if evbuffer timestamping ever becomes a general-purpose
API for arbitrary callers.

No timestamp invalidation on OpenSSL fd swap

bufferevent_openssl.c:1767, BEV_CTRL_SET_FD. be_socket_setfd()
calls evbuffer_invalidate_last_chain_timestamp_() on every fd
rebind, precisely so a later read on the new fd cannot extend
a chain still carrying the old fd's timestamp. The direct-fd
OpenSSL path does the same rebind and never makes that call.

Reproduced on Linux over real TCP + TLS, deterministic across 6
runs: timestamp.valid stays 1 across bufferevent_setfd() to
a fresh socket.

We don't rebind fds on our OpenSSL bufferevents, so this path is
dead code for us, and even if it weren't, an incorrect timestamp
here isn't a serious problem for our usage. Leaving as-is; the fix
is a one-line call to evbuffer_invalidate_last_chain_timestamp_()
if we ever start using BEV_CTRL_SET_FD for real.

do_write() clears pending timestamps unconditionally

bufferevent_openssl.c:1162. do_handshake() guards the identical
cleanup with if (SSL_pending(ssl) == 0) and explains why in
a comment: an incidental read may have decrypted data that
do_read() still needs the timestamp for. do_write() uses the
same snapshot/restore pattern with no such guard. The asymmetry
looks unintended.

Fixed — added the same SSL_pending(ssl) == 0 guard to do_write()
that do_handshake() already uses, so the two call sites are now
consistent. For what it's worth, even unfixed this was low
severity for us: on TCP the kernel and our own code already
coalesce segments and lose per-segment timestamp granularity, so a
mis-attributed timestamp here would land in the same "best effort,
not exact" bucket we already tolerate elsewhere. The guard was
cheap enough to apply anyway.

SSL_pending()==0 is an imprecise retirement proxy

bufferevent_openssl.c:1056. SSL_pending() reports decrypted
application data only, not raw ciphertext buffered from the same
recvmsg(). When one read delivers a complete record plus the
head of the next — ordinary TCP segmentation — the second record's
earliest bytes lose their arrival time and get stamped later,
contradicting the "oldest wins" rule implemented everywhere else.

Confirmed, and it's the same underlying phenomenon as the
do_write() item above and ordinary TCP segment coalescing:
coarser-than-ideal timestamp attribution on a stream socket, not
data loss or corruption of unrelated data. We only need solid
per-message timestamp guarantees in a UDP-style setup, and running
bufferevents over UDP isn't a sane use case to begin with (it's a
stream abstraction), so we're treating this as a documented
limitation of stream mode rather than fixing it.

Duplicated cmsg parsing has already diverged

buffer.c:2499,2517 vs bufferevent_openssl.c:458,476. The
block is near-verbatim in both files, down to the comments, but
buffer.c casts CMSG_DATA() through an intermediate (void *) and the OpenSSL copy does not. Correct at runtime — the union
guarantees alignment — but confirmed with -Wcast-align=strict,
where buffer.c is silent and the OpenSSL copy warns at both
sites. The two copies drifted apart inside a single commit, which
is the argument for a shared helper.

Fixed the immediate symptom: added the matching (void *)
intermediate cast to the bufferevent_openssl.c copy, so both are
now clean under -Wcast-align=strict. Agreed in principle that
factoring the shared cmsg-scanning loop into one helper would
prevent this kind of drift going forward; not doing that refactor
right now, but leaving it as a follow-up if this code gets touched
again.

@trondn
trondn force-pushed the packet_timestamp-for-2.1.13 branch from 07ee71d to cf3859d Compare September 3, 2026 11:54

@jimwwalker jimwwalker left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think only the comment is worth changing to remove the UDP mention - other than that looks good

Comment thread include/event2/buffer.h Outdated
* Get the timestamp stored for the oldest data chain in the buffer.
*
* Returns the kernel receive timestamp associated with the oldest chain
* currently in the buffer. For UDP sockets, this is the arrival timestamp of

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Since UDP is not enabled comment block is incorrect?

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done

Comment thread ChangeLog Outdated

New features (evbuffer, bufferevent):
- Add kernel socket receive timestamp support via BEV_OPT_RECV_TIMESTAMPS
and evbuffer_get_timestamp(), for TCP socket bufferevents.

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

state the platforms? (no windows etc...?)

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done

Implement kernel-measured socket receive timestamps with nanosecond
precision on supported platforms via the recvmsg() syscall. Each
timestamped recvmsg() call writes into a freshly allocated evbuffer
chain so that every read receives an independent timestamp and
timestamps are never silently overwritten or shared across reads.

Scope and Platform Details:
- Stream sockets only (SOCK_STREAM / TCP):
  This feature is scoped strictly to stream-oriented bufferevents.
  Bufferevent and evbuffer are continuous byte-stream abstractions;
  datagram sockets (SOCK_DGRAM / UDP) are susceptible to message
  truncation on partial reads and fragmentation on writes, and are
  best handled using raw event callbacks with direct recvmsg() calls.
  Non-stream sockets explicitly fail to arm timestamps.
- Platform matrix:
  - Linux: Full nanosecond support via SO_TIMESTAMPNS (and microsecond
    fallback via SO_TIMESTAMP) for TCP sockets.
  - BSD / macOS: SO_TIMESTAMP on SOCK_STREAM is a silent kernel no-op
    on kernels lacking SO_TIMESTAMPNS; this is detected and reported as
    unsupported (-1) rather than silently failing.
  - AF_UNIX: Explicitly unsupported.
  - Use bufferevent_get_recv_timestamps_enabled() to detect whether
    timestamping was successfully armed on the socket.
- Loopback (lo) test caveat:
  On Linux, virtual loopback transfers bypass the physical network
  ingress pipeline and NAPI timestamping hooks, and fast-path TCP
  segment coalescing (tcp_try_coalesce) may not attach timestamps to
  in-memory loopback skbs. Unit tests gracefully skip timestamp
  assertions when run over loopback interfaces if the kernel does not
  deliver timestamps. Physical network interfaces always populate
  skb->tstamp on ingress.

Infrastructure changes:
- evbuffer-internal.h: Add timestamp storage and validity flag to
  evbuffer_chain structure.
- buffer.c: Update evbuffer_read_impl_() to read data via recvmsg(),
  extract timestamps from SCM_TIMESTAMPNS / SCM_TIMESTAMP, and safely
  clean up empty trailing chains via evbuffer_free_trailing_empty_chains().
- bufferevent_sock.c: Check SO_TYPE for SOCK_STREAM in
  be_socket_enable_timestamps_(), arm socket timestamps, and swap
  standard reads with recvmsg() when requested.
- bufferevent_openssl.c: Add a custom socket BIO
  (BIO_TYPE_LIBEVENT_RECVMSG) to extract kernel timestamps during direct
  socket reads, and propagate timestamps from underlying bufferevents in
  filtered TLS mode across partial reads. Correctly handle BIO_C_SET_FD
  pointer arguments, preserve pending timestamps across multi-record reads,
  and safely swap back to standard socket BIOs on SSL reuse.
- Build system: Add CMake and Autotools socket timestamp checks for
  SO_TIMESTAMP and SO_TIMESTAMPNS option availability.

Public API additions:
- BEV_OPT_RECV_TIMESTAMPS option flag for stream socket bufferevents.
- bufferevent_get_recv_timestamps_enabled() to check whether receive
  timestamps were successfully armed.
- evbuffer_get_timestamp() to fetch the receipt timestamp of the oldest
  data currently in the buffer.
- evbuffer_commit_space_with_timespec() to commit reserved space and
  manually attach a timestamp to the committed chains.
@trondn
trondn force-pushed the packet_timestamp-for-2.1.13 branch from cf3859d to 6f9f83b Compare September 3, 2026 13:43
@trondn
trondn merged commit 5f581c5 into couchbasedeps:release-2.1.13-stable-couchbase Sep 3, 2026
0 of 53 checks passed
@trondn
trondn deleted the packet_timestamp-for-2.1.13 branch September 3, 2026 15:27
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants