HTTP connection closed seemingly related to ioctl(0, TIOCGWINSZ)

[nigoroll]

I did this

Only for context, feel free to skip

I am using curl for regression testing of SLASH/ with a delivery filter (VDP) on the varnish-cache end which deliberately panics when the written http body length does not match the expected value. The testing goal is to ensure that the storage engine always delivers the right amount of data, so for this testing scenario errors which are otherwise completely normal (like a short body write due to a connection closure from the client side) can not safely be ignored, as doing so would hide actual errors. In other words, for this testing regime I need a client which always does the right thing.

Calling curl

The main part of the test script executes 30 parallel instances of curl with 50001 urls in the argument list:

"${CURL_ARGS[@]}" -sSo /dev/null 127.0.0.1:8081/${p}{{5500..50000},{1..5500}}${l} 2>${p}${pp}2.curlerr &

The details regarding the p, l and pp variables should not matter, but feel free to look at the full script.

I expected the following

I expected curl to always read the full response body and not close the connection prematurely.

Sometimes and seemingly random, the curl invocation triggers a short write on the server side:

-   ReqStart       127.0.0.1 46424 a0
-   ReqMethod      GET
-   ReqURL         /I5690
-   ReqProtocol    HTTP/1.1
-   ReqHeader      Host: 127.0.0.1:8081
-   ReqHeader      User-Agent: curl/8.13.1-DEV
...
-   VCL_return     deliver
-   Timestamp      Process: 1744713049.557025 0.017923 0.000031
-   Filters         debug.chklen
-   RespHeader     Connection: keep-alive
-   Debug          "Write error, retval = -1, len = 36544, errno = Broken pipe%00"
-   VSL            flush
-   End            synth

Originally, I would see client returned ERROR on write of ... with curl.

To better understand the issue, I patched it slightly:

diff --git a/lib/cw-out.c b/lib/cw-out.c
index af8f1b9e5..30d079732 100644
--- a/lib/cw-out.c
+++ b/lib/cw-out.c
@@ -241,7 +241,8 @@ static CURLcode cw_out_ptr_flush(struct cw_out_ctx *ctx,
       break;
     }
     else if(CURL_WRITEFUNC_ERROR == nwritten) {
-      failf(data, "client returned ERROR on write of %zu bytes", wlen);
+      failf(data, "client returned ERROR %d on write of %zu/%zu bytes",
+            errno, nwritten, wlen);
       return CURLE_WRITE_ERROR;
     }
     else if(nwritten != wlen) {

With this, the error message is:

I22.curlerr:> GET /I5690 HTTP/1.1
I22.curlerr-> Host: 127.0.0.1:8081
I22.curlerr-> User-Agent: curl/8.13.1-DEV
I22.curlerr-> Accept: */*
I22.curlerr-> ttl: 1s
I22.curlerr-> 
I22.curlerr-* Request completely sent off
I22.curlerr-< HTTP/1.1 200 OK
I22.curlerr-< Date: Tue, 15 Apr 2025 10:30:49 GMT
I22.curlerr-< Server: Varnish
I22.curlerr-< len: 126824
I22.curlerr-< Cache-Control: public, max-age=1
I22.curlerr-< X-Varnish: 329919
I22.curlerr-< Content-Length: 126824
I22.curlerr-< storage: storage.fellow
I22.curlerr-< filters: 
I22.curlerr-< X-Varnish: 2097973
I22.curlerr-< Age: 0
I22.curlerr-< Via: 1.1 haggis21 (Varnish/trunk), 1.1 haggis21 (Varnish/trunk)
I22.curlerr-< Accept-Ranges: bytes
I22.curlerr-< Connection: keep-alive
I22.curlerr-< 
I22.curlerr-* client returned ERROR 25 on write of 4294967295/16384 bytes
I22.curlerr-* closing connection #16176 

So errno=ENOTTY with a signed return value of -1.

To be sure about the error, I also ran curl in strace:

poll([{fd=4, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
write(2, "* ", 2)                       = 2
write(2, "Re-using existing http: connecti"..., 55) = 55
sendto(4, "GET /I5501 HTTP/1.1\r\nHost: 127.0"..., 96, MSG_NOSIGNAL, NULL, 0) = 96
write(2, "> ", 2)                       = 2
write(2, "GET /I5501 HTTP/1.1\r\n", 21) = 21
write(2, "> ", 2)                       = 2
...
write(2, "> ", 2)                       = 2
write(2, "\r\n", 2)                     = 2
recvfrom(4, "HTTP/1.1 200 OK\r\nDate: Tue, 15 A"..., 102400, 0, NULL, NULL) = 65536
write(2, "< ", 2)                       = 2
write(2, "HTTP/1.1 200 OK\r\n", 17)     = 17
write(2, "< ", 2)                       = 2
...
write(2, "Connection: keep-alive\r\n", 24) = 24
write(2, "< ", 2)                       = 2
write(2, "\r\n", 2)                     = 2
ioctl(0, TIOCGWINSZ, 0x7ffe1d09cf48)    = -1 ENOTTY (Inappropriate ioctl for device)
write(2, "* ", 2)                       = 2
write(2, "client returned ERROR 25 on writ"..., 60) = 60
write(2, "* ", 2)                       = 2
write(2, "closing connection #0\n", 22) = 22
close(4)                                = 0

So it really looks like the issue would indeed be caused by ioctl(0, TIOCGWINSZ) seemingly called at random.

I see where this is happening in the code base, but I do not understand why apparently out of nowhere and at random points in time.

curl/libcurl version

Originally seen with stock-debian:

curl 7.88.1 (x86_64-pc-linux-gnu) libcurl/7.88.1 OpenSSL/3.0.15 zlib/1.2.13 brotli/1.0.9 zstd/1.5.4 libidn2/2.3.3 libpsl/0.21.2 (+libidn2/2.3.3) libssh2/1.10.0 nghttp2/1.52.0 librtmp/2.3 OpenLDAP/2.5.13
Release-Date: 2023-02-20, security patched: 7.88.1-10+deb12u8
Protocols: dict file ftp ftps gopher gophers http https imap imaps ldap ldaps mqtt pop3 pop3s rtmp rtsp scp sftp smb smbs smtp smtps telnet tftp
Features: alt-svc AsynchDNS brotli GSS-API HSTS HTTP2 HTTPS-proxy IDN IPv6 Kerberos Largefile libz NTLM NTLM_WB PSL SPNEGO SSL threadsafe TLS-SRP UnixSockets zstd

Then reproduced with current HEAD 3fbabec:

curl 8.13.1-DEV (x86_64-pc-linux-gnu) libcurl/7.88.1 OpenSSL/3.0.15 zlib/1.2.13 brotli/1.0.9 zstd/1.5.4 libidn2/2.3.3 libpsl/0.21.2 (+libidn2/2.3.3) libssh2/1.10.0 nghttp2/1.52.0 librtmp/2.3 OpenLDAP/2.5.13
Release-Date: [unreleased]
Protocols: dict file ftp ftps gopher gophers http https imap imaps ipfs ipns ldap ldaps mqtt pop3 pop3s rtmp rtsp scp sftp smb smbs smtp smtps telnet tftp
Features: alt-svc AsynchDNS brotli GSS-API HSTS HTTP2 HTTPS-proxy IDN IPv6 Kerberos Largefile libz NTLM NTLM_WB PSL SPNEGO SSL threadsafe TLS-SRP UnixSockets zstd
WARNING: curl and libcurl versions do not match. Functionality may be affected.

operating system

$ cat /etc/debian_version 
12.9

[nigoroll]

With this additional patch ...

diff --git a/src/terminal.c b/src/terminal.c
index 30d902e95..0f54ee23a 100644
--- a/src/terminal.c
+++ b/src/terminal.c
@@ -26,6 +26,7 @@
 #ifdef HAVE_SYS_IOCTL_H
 #include <sys/ioctl.h>
 #endif
+#include <errno.h>
 
 #include "terminal.h"
 #include "curlx.h"
@@ -47,6 +48,7 @@ unsigned int get_terminal_columns(void)
 {
   unsigned int width = 0;
   char *colp = curl_getenv("COLUMNS");
+  int saved = errno;
   if(colp) {
     curl_off_t num;
     const char *p = colp;
@@ -85,6 +87,7 @@ unsigned int get_terminal_columns(void)
     if(cols >= 0 && cols < 10000)
       width = (unsigned int)cols;
   }
+  errno = saved;
   if(!width)
     width = 79;
   return width; /* 79 for unknown, might also be tiny or enormous */

I get:

* client returned ERROR 11 on write of 4294967295/16384 bytes
* closing connection #15890 

which makes more sense in that maybe the failing ioctl() just covered the original error (11 would be EAGAIN)

[icing]

Yeah, I was looking for a "leftover" errno when the terminal width is checked. But I did not see why this is checked since your curl invocation suppresses the progress bar who would need it.

Maybe @bagder has an idea...

[nigoroll]

This patch avoids the issue:

diff --git a/src/tool_cb_wrt.c b/src/tool_cb_wrt.c
index 7a575c98f..2dc5aed86 100644
--- a/src/tool_cb_wrt.c
+++ b/src/tool_cb_wrt.c
@@ -364,7 +364,10 @@ size_t tool_write_cb(char *buffer, size_t sz, size_t nmemb, void *userdata)
 
   if(config->nobuffer) {
     /* output buffering disabled */
-    int res = fflush(outs->stream);
+    int res;
+    do {
+      res = fflush(outs->stream);
+    } while (res && errno == EINTR);
     if(res)
       return CURL_WRITEFUNC_ERROR;
   }

[icing]

Thanks! Converted into #17063.