Benign osiris_replica_reader crash: getprotocol badmatch in file:sendfile on peer socket close #230

Describe the bug

An osiris_replica_reader crashes with {badmatch,undefined} raised from inside file:sendfile/8 when the peer replication socket closes while the reader is in its do_sendfile0/1 send loop. In effect the crash appears benign (the replica re-establishes its reader on reconnect, and the run's aggregate replay check found no message loss), but it logs a full gen_server/crasher report at [error] on every occurrence, which is noisy and indistinguishable from a real fault to any log-based monitoring.

Root cause

This is a TOCTOU race in OTP's prim_inet:sendfile/4. It guards on erlang:port_info(S, connected), and on success calls sendfile_maybe_cork/1 -> getprotocol/1, which does a second, unguarded {name,Drv} = erlang:port_info(S, name). If the peer closes the port between those two port_info/2 calls, the second returns undefined and the match raises {badmatch,undefined}. (A fully-closed socket instead fails the connected guard and returns {error, einval}; only the race raises.) Verified against OTP source at tag OTP-27.3.4.14; prim_inet.erl is byte-identical to the deployed OTP-27.3.4.13.

There are two independent fixes, and both are worth doing:

• osiris side (Catch file:sendfile badmatch to keep replica reader alive #231): osiris_log:sendfile/6 calls file:sendfile/8 inside a plain case that only handles a returned {ok,_}/{error,_}, so the thrown exception is uncaught and propagates through send_file/3 to do_sendfile0/1, terminating the reader. Catching the badmatch and returning {error,_} (which do_sendfile0/1 already handles) fixes it on current OTP releases.
• OTP side (erlang/otp#11438): getprotocol/1 should tolerate the undefined a closed port returns rather than badmatch on it (the caller already treats a gone port as {error, einval}).

Stack trace

[error] <0.259721.0>     initial call: osiris_replica_reader:init/1
[error] <0.259721.0>     exception error: no match of right hand side value undefined
[error] <0.259721.0>       in function  prim_inet:getprotocol/1
[error] <0.259721.0>       in call from prim_inet:sendfile_maybe_cork/1
[error] <0.259721.0>       in call from prim_inet:sendfile/4
[error] <0.259721.0>       in call from prim_file:sendfile/8
[error] <0.259721.0>       in call from file:sendfile/8 (file.erl, line 2778)
[error] <0.259721.0>       in call from osiris_log:sendfile/6 (src/osiris_log.erl, line 2722)
[error] <0.259721.0>       in call from osiris_log:send_file/3 (src/osiris_log.erl, line 1872)
[error] <0.259721.0>       in call from osiris_replica_reader:do_sendfile0/1 (src/osiris_replica_reader.erl, line 340)
[error] <0.259721.0>     message_queue_len: 3
[error] <0.259721.0>     messages: [{osiris_offset,
[error] <0.259721.0>                       {resource,<<"/">>,queue,<<"...">>},
[error] <0.259721.0>                       464047132},
[error] <0.259721.0>                   {tcp_closed,#Port<0.42033>},
[error] <0.259721.0>                   {'EXIT',<36809.261294.0>,normal}]

The mailbox is the key detail: at the moment of the crash the reader had a queued {tcp_closed, ...} and an {'EXIT', <remote_pid>, normal} waiting behind the {osiris_offset, ...} it was processing. The peer closed the connection normally, but the reader entered its next file:sendfile/8 before draining those messages, so the send raced the close.

Environment

• osiris 1.13.0
• Erlang/OTP 27.3.4.13 (erts 15.2.7.9)
• RabbitMQ 3.13.0+2510.g0a1c4ad
• Linux (x86_64), TCP replication (not TLS)
• 3-node cluster, 12 streams, sustained high-throughput publish + replication over a 24-hour run
• No node restarts occurred during the run; all three nodes had continuous uptime throughout

Frequency

3 occurrences in a 24-hour sustained-load run, all within the first ~75 minutes (2 on one node, 1 on another), then none for the remaining ~22.5 hours. It is intermittent and correlates with normal replication connection churn, not with any operator action.

Relationship to current code

On main (verified at 492bee9), osiris_log:sendfile/6 still calls file:sendfile/8 inside a bare case, so this code path is unchanged and unguarded there.

The recently merged crash fixes (#228 softening ok = setopts matches, #229 best-effort erlang:send for committed_offset) and the open #221 (guarding setopts and checking for pending supervisor EXIT in the send loop) all harden adjacent points in osiris_replica_reader, but none of them wraps the file:sendfile/8 call in osiris_log:sendfile/6, which is where this specific exception is thrown. #149 reports a same-class benign teardown crash (a stack trace logged when a TLS peer connection closes) but via a different path (inet:tcp_close/1 in osiris_replica:terminate/2).

Note that osiris_replica_reader children are started restart => temporary, so the supervisor does not restart a crashed reader by design; recovery relies on the replica re-establishing the reader on reconnect, which is why the crash is benign in effect but still logged loudly.

Expected behavior

A peer closing its replication socket during a send is a normal, expected event and should not produce an [error]-level crash report. See the two fixes under Root cause.

Reproduction

Not deterministic. Observed under sustained high-throughput publishing to a multi-stream 3-node cluster over TCP replication; it surfaces during ordinary replication connection churn. It has not been tied to a minimal reproduction.