Packet timestamp for 2.1.13 release - #4
Conversation
jimwwalker
left a comment
There was a problem hiding this comment.
These were from a broader review so hopefully the end of these staggeringly hard to follow flows 😆
f7d2fcf to
863dc91
Compare
|
I'm not familiar with libevent so I asked Claude for a review: Review: top 2 commits on
|
| Repo | /Users/pavlos.georgiou/Couchbase/libevent |
| Branch | packet_timestamp-for-2.1.13 |
| Commits | 863dc91f Add kernel socket receive timestamp supporte363491e 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_addrandomdeprecation and a-Wdeclaration-after-statementinregress_main.c). - Built a second tree with
-DEVENT__DISABLE_OPENSSL=ON. - Built
HEAD~2in a scratch worktree for an A/B comparison of test results. - Ran:
evbuffer/get_timestamp,bufferevent/bufferevent_recv_timestamps, the wholessl/group, the wholehttp/group — on both HEAD and base.
Test results
- New tests pass:
evbuffer/get_timestamp,bufferevent/bufferevent_recv_timestamps, and all three newssl/*_recv_timestampscases. Fullssl/group: 29 ok, 0 skipped. http/at HEAD:terminate_chunkedandterminate_chunked_oneshotfail. Both also fail atHEAD~2— pre-existing, not caused by these commits. (bad_requestadditionally failed on one base run only; flaky.)http/https_incompleteandhttp/https_incomplete_timeoutpass both before and aftere363491eon 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_SSL → BEV_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_TIMESTAMPNSstays armed on the kernel socket for the life of the connection;bufferevent_openssl_new_impl()still setsbev.recv_timestamps_enabled = 1(it only re-checksoptions & 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— theEVENT__HAVE_GETRANDOM#cmakedefineblock is duplicated (copy/paste artifact from inserting the twoSO_TIMESTAMP*defines). Harmless (identical redefinition) but should go.bufferevent_openssl.c:516—BIO_C_GET_FDwrites*(evutil_socket_t *)ptr, but OpenSSL'sBIO_get_fd(b, c)contract isint *c. Harmless today:evutil_socket_tisinton POSIX, and the BIO is never created on Windows because bothSO_TIMESTAMP*checks resolve to 0 there. It is an 8-byte write through anint *the moment either of those changes.include/event2/buffer.h:754-766—evbuffer_read_with_timestamp()is declaredEVENT2_EXPORT_SYMBOLin a public header while the commit message calls it "internal". Its doc block is a verbatim copy ofevbuffer_read()'s: no mention of timestamps, of theSO_TIMESTAMP/SO_TIMESTAMPNSprerequisite, or that it silently degrades to a plainreadv()on Windows and on non-USE_IOVEC_IMPLbuilds. Three new public symbols plus a new option flag, with no ChangeLog orwhatsnewentry.buffer.c:2523-2545— the failure path now frees a chain (plus an O(chain-count) list walk) betweenrecvmsg()failing and returning, so callers that inspecterrno— astest/regress_buffer.c:527does — depend onmm_free()not clobbering it. A save/restore around the cleanup is cheap insurance.evbuffer-internal.h:207-215—struct evbuffer_chaingrows by 24 bytes (struct timespec+int valid+ padding) for every chain in every program, whether or not the feature is used. Sinceevbuffer_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 theevbuffer/get_timestamptest exercises the drain-across-chain-boundary behaviour properly (including the EAGAIN cleanup leavingbuf->first == NULL). - The error-path chain unlink in
evbuffer_read_impl_is sound:new_chain->off == 0, soevbuffer_chain_insert()leaveslast_with_datapuntouched, 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, andbufferevent/bufferevent_recv_timestampscovers thebufferevent_setfd()swap explicitly. evbuffer_get_timestamp()'s doc comment is honest about the partial-drain and pullup caveats.
863dc91 to
fa0c91e
Compare
|
I addressed all comments except for number 2. Both versions are no longer supported |
|
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 (
|
| Repo | /Users/pavlos.georgiou/Couchbase/libevent |
| Branch | packet_timestamp-for-2.1.13 |
| Commits reviewed | fa0c91ec Add kernel socket receive timestamp support5b241415 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:
- Part 1 — status of each finding from the first review round (validating the claim "I addressed all comments except for number 2").
- Part 2 — a new build break introduced by one of the fixes.
- 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=ON → compiles 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.hunchanged, so the +24 bytes per chain stands. I called this "probably acceptable", so this one is fair to leave — measuredsizeof(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.cthe onlyevbuffer_get_timestampassertion is== -1at line 1078. - Root cause, macOS:
SO_TIMESTAMPsucceeds on anAF_UNIXsocketpair butrecvmsgreturnsmsg_controllen=0— no cmsg, for eitherSOCK_STREAMorSOCK_DGRAM. - Root cause, Linux: same.
AF_UNIX/STREAM + SO_TIMESTAMPNSover 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
recvmsgcalls collect timestamps (bio_data->bev_ssland 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_readhandles them internally and returnsWANT_READwithn_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:
CRYPTO_THREAD_run_oncewas 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.- 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< 0x20700000Lrange. Those users now get a confusing compile error instead of a clear one. Deleting the block or adding an explicit#errorversion 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 | fails — regress_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#5 — no 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_timestamp—AF_INET, SOCK_DGRAMbufferevent/bufferevent_recv_timestamps—AF_INET, SOCK_DGRAM- all three
ssl/*_recv_timestamps—AF_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
- 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. - Add a TCP test. It will fail on macOS — that is the point. Without it the platform gap is undetectable.
- Stop inferring capability from
setsockoptsuccess. ProbeSO_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. - 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. - 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.
- Clear
last_recv_ts_validwhenSSL_readreturns without application data, so handshake and TLS 1.3 post-handshake records don't leak stale timestamps into the first payload read. - Resolve # 2 explicitly — delete the
openssl-compat.hshim block or add an#error, so the supported range is stated once and enforced. - 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_UNIXyields no cmsg on either OS. - Observed once, did not reproduce: the post-drain anomaly noted in §3.4. Explicitly not claimed as a defect.
fa0c91e to
6af1a59
Compare
| 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; |
There was a problem hiding this comment.
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
e132af0 to
38dcc91
Compare
Review: kernel socket receive timestamps + UDP datagram truncation fixCommits reviewed:
Verified by building and running the suite on macOS 14 arm64 (AppleClang, OpenSSL 3.6.0) and (1) Blocking —
|
| 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_TYPEprobe correctly refusesSOCK_STREAMon BSD, whereSO_TIMESTAMPon 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
assertsts2 > ts1across consecutive records and passes, so records are not mis-attributed to
an earlier segment's timestamp. evbuffer/get_timestamp_unstamped_then_stampedis a good regression test: it covers both the
fresh-chain-on-unstamped-tail path and theevbuffer_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.
|
Fixed the issues reported by @pavlosg yesterday |
38dcc91 to
ae53187
Compare
|
Validation performed
Runtime evidence below comes from purpose-built repro programs and Blocking(1)
|
| 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:2473 — MSG_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:1084 — do_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:2509 — continue lets SCM_TIMESTAMP clobber SCM_TIMESTAMPNS — CONFIRMED, 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:1284 — fd_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.
ae53187 to
d2a2d48
Compare
|
Addressed all comments by @pavlosg yesterday |
|
Branch force-updated Validation performed
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)
|
| 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
EMSGSIZEis fatal to a bufferevent.bufferevent_readcb()maps a non-retriable-1toBEV_EVENT_ERROR, so a truncated datagram tears the bufferevent down. Normally unreachable — the dgram path sizeshowmuchfrom FIONREAD first — butbe_socket_get_n_bytes_readable_()returns −1 where FIONREAD is unavailable, and then any datagram overmax_single_readkills the connection where it used to be silently truncated. Also asymmetric: the non-timestamped path still truncates silently. Worth an explicitEMSGSIZEcase inbufferevent_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.
39df73b5addstest_bufferevent_ratelim_udp,test_bufferevent_wm_udpandtest_bufferevent_udp_large_datagrambut registers them only ind2a2d48f, so the intermediate commit builds with three-Wunused-functionwarnings. - Two SSL tests self-skip intermittently.
ssl/bufferevent_openssl_recv_ts_interleaved_writeand..._recv_ts_multiple_recordsskip 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.
d2a2d48 to
d8acab9
Compare
|
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) |
Correctness findings(1)
|
|
Fixed 1, 3, 4, 6, 7, 8, 9, 11, 12 and 13. |
d8acab9 to
f261673
Compare
|
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 |
f261673 to
07ee71d
Compare
|
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:
|
|
07ee71d to
cf3859d
Compare
jimwwalker
left a comment
There was a problem hiding this comment.
I think only the comment is worth changing to remove the UDP mention - other than that looks good
| * 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 |
There was a problem hiding this comment.
Since UDP is not enabled comment block is incorrect?
|
|
||
| New features (evbuffer, bufferevent): | ||
| - Add kernel socket receive timestamp support via BEV_OPT_RECV_TIMESTAMPS | ||
| and evbuffer_get_timestamp(), for TCP socket bufferevents. |
There was a problem hiding this comment.
state the platforms? (no windows etc...?)
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.
cf3859d to
6f9f83b
Compare
5f581c5
into
couchbasedeps:release-2.1.13-stable-couchbase
Added support for packet timestamp