Hi,
I think I found a possible timer bookkeeping issue in OTP 24’s inet_drv.
The problem appears when a large TCP payload is followed by several smaller payloads, while the application uses:
erlang:port_command(Socket, Data, [force])
In my case, the first payload was around 200 KB, followed immediately by several smaller payloads.
The socket was configured with options similar to:
inet:setopts(Socket, [
binary,
{packet, 0},
{active, false},
{nodelay, true},
{delay_send, false},
{send_timeout, 15000},
{send_timeout_close, false},
{high_watermark, 32 * 1024},
{low_watermark, 24 * 1024}
]).
The surprising part was that the data had already been completely sent when the timeout was reported. The peer had received the data, and the driver’s output queue had already drained, but the owner process still received this message about 15 seconds later:
{inet_reply, Socket, {error, timeout}}
Relevant code path
In tcp_sendv(), when the output queue is already non-empty and the queue remains above the high watermark after another write, the driver does this:
sz = driver_sizeq(ix);
if ((desc->tcp_add_flags & TCP_ADDF_SENDFILE) || sz > 0) {
driver_enqv(ix, ev, 0);
if (sz + ev->size >= desc->high) {
desc->inet.state |= INET_F_BUSY;
desc->inet.busy_caller = desc->inet.caller;
set_busy_port(desc->inet.port, 1);
if (desc->send_timeout != INET_INFINITY) {
desc->busy_on_send = 1;
add_multi_timer(desc,
INETP(desc)->port,
0,
desc->send_timeout,
&tcp_inet_send_timeout);
}
return 1;
}
}
There does not appear to be a check to avoid adding another tcp_inet_send_timeout timer when one already exists for the current busy period.
This means that a large packet followed by several smaller packets can create multiple timers:
timer 1 -> tcp_inet_send_timeout
timer 2 -> tcp_inet_send_timeout
timer 3 -> tcp_inet_send_timeout
...
The timers are added by add_multi_timer(), which inserts every timer into the timer list.
When the output queue later falls below the low watermark, the driver tries to recover from the busy state:
if (driver_deq(ix, n) <= desc->low) {
if (IS_BUSY(INETP(desc))) {
desc->inet.caller = desc->inet.busy_caller;
desc->inet.state &= ~INET_F_BUSY;
set_busy_port(desc->inet.port, 0);
if (desc->busy_on_send) {
cancel_multi_timer(desc,
INETP(desc)->port,
&tcp_inet_send_timeout);
desc->busy_on_send = 0;
}
inet_reply_ok(INETP(desc));
}
}
However, cancel_multi_timer() removes only the first timer matching tcp_inet_send_timeout. It does not remove all timers with that callback.
Therefore, the following sequence seems possible:
-
A large packet leaves data in the driver’s output queue.
-
Several smaller packets are sent while the queue is still above the high watermark.
-
Each smaller packet adds another send-timeout timer.
-
All queued data is eventually sent.
-
The queue falls below the low watermark.
-
The busy state is cleared and only one timeout timer is cancelled.
-
One or more timeout timers remain in the timer list.
-
A remaining timer expires 15 seconds later.
-
The owner process receives:
{inet_reply, Socket, {error, timeout}}
At that point, the data has already been sent and the output queue is empty. The timeout appears to come from a stale timer left over from the previous busy period.
The relevant parts of the OTP source are:
tcp_sendv()and timer creationtcp_inet_output()and low-watermark handlingcancel_multi_timer()add_multi_timer()
I am not sure whether this is expected behavior or an existing OTP bug.
Should the driver only add one send-timeout timer while the port is busy? Or should the low-watermark recovery path cancel all timers associated with tcp_inet_send_timeout?
I am not using port_info/2 or any application-level workaround here. I am only trying to understand the timer behavior in inet_drv.
My English isn’t very good, so I used AI to help write this post. Please excuse any awkward wording.