NGINX 408 timeout (reading client request headers)

Question

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.

NGINX access log

[11/Sep/2018:13:41:11 +0000] "HEAD / HTTP/1.1" 408 0 "-" "-" --- "-" "-"

The log format is as follows

log_format custom '[$time_local] "$request" $status $body_bytes_sent '
                  '"$http_referer" "$http_user_agent" ---'
                  '"$content_type" "$content_length"';

NGINX error log

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

Tcpdump sudo tcpdump -n -S -s 0 -A 'src SRCIP and port 80' shows

13:55:32.846408 IP SRCIP.39761 > 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 > DSTIP.80: Flags [.], ack 3538300854, win 2920, length 0
E..(....p..^E......h.Q.P....../.P..hqK........
13:55:33.314206 IP SRCIP.39761 > DSTIP.80: Flags [P.], seq 1846788:1846859, ack 3538300854, win 2920, length 71: HTTP: HEAD / HTTP/1.1
E..o&...p..CE......h.Q.P....../.P..hg...HEAD / HTTP/1.1
Host: MYHOST
Content-Length:
13:56:33.363048 IP SRCIP.39761 > DSTIP.80: Flags [F.], seq 1846859, ack 3538300855, win 2919, length 0
E..(....p...E......h.Q.P...K../.P..gq.........

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.

EDIT: I'm not adding the server config because I've tried too many and I'm not sure what to paste here.

EDIT 2: tcpdump at first logs

13:55:32.846408 IP SRCIP.39761 > 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 > DSTIP.80: Flags [.], ack 3538300854, win 2920, length 0
E..(....p..^E......h.Q.P....../.P..hqK........
13:55:33.314206 IP SRCIP.39761 > DSTIP.80: Flags [P.], seq 1846788:1846859, ack 3538300854, win 2920, length 71: HTTP: HEAD / HTTP/1.1
E..o&...p..CE......h.Q.P....../.P..hg...HEAD / HTTP/1.1
Host: MYHOST
Content-Length:

And then the rest after some time. I assume it's after NGINX times out.

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.

As I've said above, the IoT devices on boot are performing a HEAD request. They expect a response with a Date: header so that they can parse it.

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 Date: header.

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. (https://httpd.apache.org/docs/2.4/mod/mod_reqtimeout.html)

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.

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. (http://nginx.org/en/docs/http/ngx_http_core_module.html#client_header_timeout)

There's been a discussion on this behaviour already https://trac.nginx.org/nginx/ticket/1005.

In other words, the HEAD request from the IoT devices has always being wrong. It just works with Apache because a 408 response with Date: is sent back whenever a timeout while waiting for headers is triggered.

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.

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.

The version of NGINX is 1.14.0.

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->timedout) {
         ngx_log_error(NGX_LOG_INFO, c->log, NGX_ETIMEDOUT, "client timed out");
         c->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;
     }

To validate the code is working I used Telnet:

This is what NGINX normally would do

Request

$ telnet HOST 80
Trying IP...
Connected to HOST.
Escape character is '^]'.
HEAD / HTTP/1.1
Content-Length:

Response

Connection closed by foreign host.

This is what NGINX does with the modified code

Request

$ telnet HOST 80
Trying IP...
Connected to HOST.
Escape character is '^]'.
HEAD / HTTP/1.1
Content-Length:

Response

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

Notice that I could use another header in place of Content-Length: (e.g. Accept: 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 Content-Length:).

It looks like they never send value for the Content-Length header, and they don't send the "blank line" after the headers either... How is the server supposed to know that the client has finished sending the headers? — Attie, Commented Sep 11, 2018 at 14:26
Do you have control of the Content-Length value or the content? If so, is it expected to include a newline, but is currently empty? — Attie, Commented Sep 11, 2018 at 14:27
Sensors with a custom firmware. Unfortunately, there's no way for me to change the code in the sensors. I need to find a workaround in NGINX. — 3v0k4, Commented Sep 11, 2018 at 14:35
I'm not totally sure what's going on. One thing I forgot to mention is that tcpdump stops at Content-Length: for some time. I assume it's because NGINX is waiting for data but the sensor does not send anything. — 3v0k4, Commented Sep 11, 2018 at 14:38

3v0k4 · Accepted Answer · 2018-10-04 14:29:31Z

-1

I ended up using Apache. In fact, it seems like there's no way to configure NGINX to send back the 408 to the client (and not just closing the connection). Patching the source is risky and makes updating the server painful.

edited Oct 4, 2018 at 14:29

answered Sep 29, 2018 at 8:19

3v0k4

1611 gold badge4 silver badges10 bronze badges

Add a comment |

Charles Brandt · Accepted Answer · 2022-02-18 18:55:37Z

I was running into this with a proxy_pass. Originally I had the following configuration:

    location / {
        proxy_read_timeout 300s;
        proxy_connect_timeout 75s;
        proxy_pass https://internal:3210/;

        add_header Access-Control-Allow-Origin *;
        proxy_http_version 1.1;
        proxy_set_header Upgrade $http_upgrade;
        proxy_set_header Connection "upgrade";
        proxy_buffering off;
    }

Then I commented out the proxy settings and it started to work for me:

    location / {
        proxy_read_timeout 300s;
        proxy_connect_timeout 75s;
        proxy_pass https://internal:3210/;

        # add_header Access-Control-Allow-Origin *;
        # proxy_http_version 1.1;
        # proxy_set_header Upgrade $http_upgrade;
        # proxy_set_header Connection "upgrade";
        # proxy_buffering off;
    }

NGINX 408 timeout (reading client request headers)

2 Answers 2

Your Answer

Not the answer you're looking for? Browse other questions tagged
nginx
or ask your own question.

Hot Network Questions

NGINX 408 timeout (reading client request headers)

2 Answers 2

Your Answer

Sign up or log in

Post as a guest

Not the answer you're looking for? Browse other questions tagged nginx or ask your own question.

Related

Hot Network Questions

Not the answer you're looking for? Browse other questions tagged
nginx
or ask your own question.