title: NGINX 408 timeout (reading client request headers)
body: <p>I'm working on a server that is receiving requests from IoT devices. They perform a HEAD request on boot. Unfortunately, it seems there's something wrong with the headers.</p>
  
  <p>NGINX access log</p>
  
  <pre><code>[11/Sep/2018:13:41:11 +0000] "HEAD / HTTP/1.1" 408 0 "-" "-" --- "-" "-"
  </code></pre>
  
  <p>The log format is as follows</p>
  
  <pre><code>log_format custom '[$time_local] "$request" $status $body_bytes_sent '
                    '"$http_referer" "$http_user_agent" ---'
                    '"$content_type" "$content_length"';
  </code></pre>
  
  <p>NGINX error log</p>
  
  <pre><code>2018/09/11 13:40:11 [debug] 31368#31368: *1 accept: SRCIP:33930 fd:32
  2018/09/11 13:40:11 [debug] 31368#31368: *1 event timer add: 32: 60000:1536673271229
  2018/09/11 13:40:11 [debug] 31368#31368: *1 reusable connection: 1
  2018/09/11 13:40:11 [debug] 31368#31368: *1 epoll add event: fd:32 op:1 ev:80002001
  2018/09/11 13:40:11 [debug] 31368#31368: *1 post event 000056011DBAA2C0
  2018/09/11 13:40:11 [debug] 31368#31368: *1 delete posted event 000056011DBAA2C0
  2018/09/11 13:40:11 [debug] 31368#31368: *1 http wait request handler
  2018/09/11 13:40:11 [debug] 31368#31368: *1 malloc: 000056011DAAB650:1024
  2018/09/11 13:40:11 [debug] 31368#31368: *1 recv: fd:32 71 of 1024
  2018/09/11 13:40:11 [debug] 31368#31368: *1 reusable connection: 0
  2018/09/11 13:40:11 [debug] 31368#31368: *1 posix_memalign: 000056011DB0DCD0:4096 @16
  2018/09/11 13:40:11 [debug] 31368#31368: *1 http process request line
  2018/09/11 13:40:11 [debug] 31368#31368: *1 http request line: "HEAD / HTTP/1.1"
  2018/09/11 13:40:11 [debug] 31368#31368: *1 http uri: "/"
  2018/09/11 13:40:11 [debug] 31368#31368: *1 http args: ""
  2018/09/11 13:40:11 [debug] 31368#31368: *1 http exten: ""
  2018/09/11 13:40:11 [debug] 31368#31368: *1 posix_memalign: 000056011DB690C0:4096 @16
  2018/09/11 13:40:11 [debug] 31368#31368: *1 http process request header line
  2018/09/11 13:40:11 [debug] 31368#31368: *1 http header: "Host: MYHOST"
  2018/09/11 13:40:11 [debug] 31368#31368: *1 recv: fd:32 -1 of 953
  2018/09/11 13:40:11 [debug] 31368#31368: *1 recv() not ready (11: Resource temporarily unavailable)
  2018/09/11 13:41:11 [debug] 31368#31368: *1 event timer del: 32: 1536673271229
  2018/09/11 13:41:11 [debug] 31368#31368: *1 http process request header line
  2018/09/11 13:41:11 [info] 31368#31368: *1 client timed out (110: Connection timed out) while reading client request headers, client: SRCIP, server: MYHOST, request: "HEAD / HTTP/1.1", host: "MYHOST"
  2018/09/11 13:41:11 [debug] 31368#31368: *1 http request count:1 blk:0
  2018/09/11 13:41:11 [debug] 31368#31368: *1 http close request
  2018/09/11 13:41:11 [debug] 31368#31368: *1 http log handler
  2018/09/11 13:41:11 [debug] 31368#31368: *1 free: 000056011DB0DCD0, unused: 707
  2018/09/11 13:41:11 [debug] 31368#31368: *1 free: 000056011DB690C0, unused: 3104
  2018/09/11 13:41:11 [debug] 31368#31368: *1 close http connection: 32
  2018/09/11 13:41:11 [debug] 31368#31368: *1 reusable connection: 0
  2018/09/11 13:41:11 [debug] 31368#31368: *1 free: 000056011DAAB650
  2018/09/11 13:41:11 [debug] 31368#31368: *1 free: 000056011DAFF960, unused: 128
  </code></pre>
  
  <p>Tcpdump <code>sudo tcpdump -n -S -s 0 -A 'src SRCIP and port 80'</code> shows</p>
  
  <pre><code>13:55:32.846408 IP SRCIP.39761 &gt; DSTIP.80: Flags [S], seq 1846787, win 2920, options [mss 1460], length 0
  E..,....p. *E......h.Q.P........`..h\;........
  13:55:33.153456 IP SRCIP.39761 &gt; DSTIP.80: Flags [.], ack 3538300854, win 2920, length 0
  E..(....p..^E......h.Q.P....../.P..hqK........
  13:55:33.314206 IP SRCIP.39761 &gt; DSTIP.80: Flags [P.], seq 1846788:1846859, ack 3538300854, win 2920, length 71: HTTP: HEAD / HTTP/1.1
  E..o&amp;...p..CE......h.Q.P....../.P..hg...HEAD / HTTP/1.1
  Host: MYHOST
  Content-Length:
  13:56:33.363048 IP SRCIP.39761 &gt; DSTIP.80: Flags [F.], seq 1846859, ack 3538300855, win 2919, length 0
  E..(....p...E......h.Q.P...K../.P..gq.........
  </code></pre>
  
  <p>I cannot change the firmware in the devices so I'm looking for a workaround on the NGINX side. Please let me know if I can provide more info to help with the answer.</p>
  
  <p>EDIT: I'm not adding the server config because I've tried too many and I'm not sure what to paste here.</p>
  
  <p>EDIT 2: tcpdump at first logs  </p>
  
  <pre><code>13:55:32.846408 IP SRCIP.39761 &gt; DSTIP.80: Flags [S], seq 1846787, win 2920, options [mss 1460], length 0
  E..,....p. *E......h.Q.P........`..h\;........
  13:55:33.153456 IP SRCIP.39761 &gt; DSTIP.80: Flags [.], ack 3538300854, win 2920, length 0
  E..(....p..^E......h.Q.P....../.P..hqK........
  13:55:33.314206 IP SRCIP.39761 &gt; DSTIP.80: Flags [P.], seq 1846788:1846859, ack 3538300854, win 2920, length 71: HTTP: HEAD / HTTP/1.1
  E..o&amp;...p..CE......h.Q.P....../.P..hg...HEAD / HTTP/1.1
  Host: MYHOST
  Content-Length:
  </code></pre>
  
  <p>And then the rest after some time. I assume it's after NGINX times out.</p>
  
  <p>EDIT 3: I finally understand what's going on. This has been really confusing because there's one Apache server in production with which the devices work properly. While trying to switch to NGINX things stopped working.</p>
  
  <p>As I've said above, the IoT devices on boot are performing a HEAD request. They expect a response with a <code>Date:</code> header so that they can parse it.</p>
  
  <p>Currently, the device are working fine with Apache because when a timeout is triggered while waiting for headers from the client, Apache returns a 408 response to the client, including the <code>Date:</code> header.</p>
  
  <blockquote>
    <p>This directive can set various timeouts for receiving the request headers and the request body from the client. If the client fails to send headers or body within the configured time, a 408 REQUEST TIME OUT error is sent.
    (<a href="https://httpd.apache.org/docs/2.4/mod/mod_reqtimeout.html" rel="nofollow noreferrer">https://httpd.apache.org/docs/2.4/mod/mod_reqtimeout.html</a>)</p>
  </blockquote>
  
  <p>On the other hand, NGINX when a when a timeout is triggered while waiting for headers from the client, just closes the connection without returning anything to the client. Even if it logs 408 in the access log.</p>
  
  <blockquote>
    <p>Defines a timeout for reading client request header. If a client does not transmit the entire header within this time, the request is terminated with the 408 (Request Time-out) error.
    (<a href="http://nginx.org/en/docs/http/ngx_http_core_module.html#client_header_timeout" rel="nofollow noreferrer">http://nginx.org/en/docs/http/ngx_http_core_module.html#client_header_timeout</a>)</p>
  </blockquote>
  
  <p>There's been a discussion on this behaviour already <a href="https://trac.nginx.org/nginx/ticket/1005" rel="nofollow noreferrer">https://trac.nginx.org/nginx/ticket/1005</a>.</p>
  
  <p>In other words, the HEAD request from the IoT devices has always being wrong. It just works with Apache because a 408 response with <code>Date:</code> is sent back whenever a timeout while waiting for headers is triggered.</p>
  
  <p>As I said above, unfortunately there's no way for me to change how the devices work. Thus, I need to workaround in NGINX. The only way I found is to change the source and compile myself.</p>
  
  <p>This is what I came up with by copy / pasting from the internet. Unfortunately, I haven't had time to understand the code and prolly won't ever. It would be really great if somebody helped me understanding how bad that code is and what's a better way of writing it. </p>
  
  <p>The version of NGINX is 1.14.0.</p>
  
  <pre><code>diff --git a/src/http/ngx_http_request.c b/src/http/ngx_http_request.c
  index 2db7a62..086701b 100644
  --- a/src/http/ngx_http_request.c
  +++ b/src/http/ngx_http_request.c
  @@ -1236,7 +1236,7 @@ ngx_http_process_request_headers(ngx_event_t *rev)
       if (rev-&gt;timedout) {
           ngx_log_error(NGX_LOG_INFO, c-&gt;log, NGX_ETIMEDOUT, "client timed out");
           c-&gt;timedout = 1;
  -        ngx_http_close_request(r, NGX_HTTP_REQUEST_TIME_OUT);
  +        ngx_http_finalize_request(r, ngx_http_special_response_handler(r, NGX_HTTP_REQUEST_TIME_OUT));
           return;
       }
  </code></pre>
  
  <p>To validate the code is working I used Telnet:</p>
  
  <p>This is what NGINX normally would do</p>
  
  <p>Request</p>
  
  <pre><code>$ telnet HOST 80
  Trying IP...
  Connected to HOST.
  Escape character is '^]'.
  HEAD / HTTP/1.1
  Content-Length:
  </code></pre>
  
  <p>Response</p>
  
  <pre><code>Connection closed by foreign host.
  </code></pre>
  
  <p>This is what NGINX does with the modified code</p>
  
  <p>Request</p>
  
  <pre><code>$ telnet HOST 80
  Trying IP...
  Connected to HOST.
  Escape character is '^]'.
  HEAD / HTTP/1.1
  Content-Length:
  </code></pre>
  
  <p>Response</p>
  
  <pre><code>HTTP/1.1 408 Request Time-out
  Server: nginx
  Date: Tue, 25 Sep 2018 08:18:41 GMT
  Content-Type: text/html
  Content-Length: 176
  Connection: close
  </code></pre>
  
  <p>Notice that I could use another header in place of <code>Content-Length:</code> (e.g. <code>Accept:</code> and the result would be the same). If you are trying to reproduce just remember to press enter once (and only once) after the empty header (in the example <code>Content-Length:</code>).</p>