Nginx 408 error

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:).

#1005

closed


defect


(fixed)

A customer of mine is trying to upload a file to our remote nginx webserver via a form POST using XHR2 form data (and a cross-domain request with CORS). During mid-upload, the webserver returns a 408 and the ajax error handler halts processing as a result. The files are in the 20-120MB range. The access logs for some of the file uploads are as follows (he has tried on Chrome 31 and IE11):

[24/Dec/2013:16:44:18 -0500] "OPTIONS / HTTP/1.1" 200 0 "http://www.example.com/files/upload" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/31.0.1650.63 Safari/537.36"
[24/Dec/2013:16:47:50 -0500] "POST / HTTP/1.1" 408 0 "http://www.example.com/files/upload" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/31.0.1650.63 Safari/537.36"
...
[27/Dec/2013:01:23:51 -0500] "OPTIONS / HTTP/1.1" 200 0 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; Trident/7.0; rv:11.0) like Gecko"
[27/Dec/2013:01:33:11 -0500] "POST / HTTP/1.1" 408 0 "http://www.example.com/files/upload" "Mozilla/5.0 (Windows NT 6.1; WOW64; Trident/7.0; rv:11.0) like Gecko"

Sometimes files will upload perfectly fine for him with Chrome instead of IE, and sometimes vice versa, but most of the time neither browser will work for him.

I’ve been reading the nginx wiki and the only two settings that correlate with 408 errors are client_body_timeout and client_header_timeout. I’m having a hard time understanding the meaning of these two directives. I increased both to 180 seconds but the issue persists. I asked him if he had a slow connection, and he said that he has 2.5 mbps up, which should be fast enough to fully receive the request header (but again, we are unsure of what these 2 directives mean according to the wiki, such as what a «readstep» is). We have successfully received 1GB uploads to our server before from other customers, which usually take around an hour to finish.

For the problematic files that we have eventually successfully received from our customer, we tried uploading the same file in various browsers and it worked perfectly.

I have read that using SSL could cause the timeouts, but the server doesn’t have SSL enabled and we are only using http.

Our nginx.conf:

user www-data;
worker_processes auto;
pid /run/nginx.pid;

events {
    worker_connections 5000;
    # multi_accept on;
}

http {
    ##
    # Basic Settings
    ##

    sendfile on;
    tcp_nopush on;
    tcp_nodelay off;
    keepalive_timeout 25;

    # Increase client/head body_timeout to prevent 408's for slow Internet connections??
    client_header_timeout 180;
    client_body_timeout 180;


    types_hash_max_size 2048;

    server_tokens off;

    # server_names_hash_bucket_size 64;
    # server_name_in_redirect off;

    include /etc/nginx/mime.types;
    default_type application/octet-stream;

    ##
    # Logging Settings
    ##

    access_log /var/log/nginx/access.log;
    error_log /var/log/nginx/error.log;

        log_format  main  '$remote_addr - $remote_user [$time_local] "$request" '
                    '$status $body_bytes_sent "$http_referer" '
                    '"$http_user_agent" "$http_x_forwarded_for"';

    ##
    # Gzip Settings
    ##

    gzip on;
    gzip_disable "msie6";

    gzip_vary on;
    gzip_proxied any;
    gzip_comp_level 5;
        gzip_min_length 256;

        gzip_types
        application/atom+xml
        text/javascript
        application/javascript
        application/json
        application/rss+xml
        application/vnd.ms-fontobject
        application/x-font-ttf
        application/x-web-app-manifest+json
        application/xhtml+xml
        application/xml
        font/opentype
        image/svg+xml
        image/x-icon
        text/css
        text/plain
        text/x-component; 

        # Increase FastCGI buffers
        fastcgi_read_timeout 1500;
        fastcgi_buffers 8 16K;
        fastcgi_buffer_size 32K;

    ##
    # Virtual Host Configs
    ##
    include /etc/nginx/conf.d/*.conf;
    include /etc/nginx/sites-enabled/*;


}

Our upload server config:

server {
    listen 80;
    server_name upload.example.com;

    root /var/www/releases/latest/_UPLOAD/public;

    # remove trailing slash, that throws ZF router
    if (!-d $request_filename) {
        rewrite ^/(.*)/$ /$1 permanent;
    }

    # 1.2G upload limit + 10M for post data (which is extremely liberal)
    client_max_body_size 1210M;
    client_body_buffer_size 4M;    

    proxy_max_temp_file_size 0;    

    location = /favicon.ico {
        access_log     off;
        log_not_found  off;
    }

    location = /apple-touch-icon.png {
        access_log off;
        log_not_found off;
    }

    location / {
        # This is for AJAX file uploads... need to set CORS headers
        if ($request_method = OPTIONS ) {
            add_header Access-Control-Allow-Origin '$scheme://www.example.com';
            add_header Access-Control-Allow-Methods 'POST, OPTIONS';
            add_header Access-Control-Allow-Headers 'X-Requested-With, Content-Type, Content-Range, Content-Disposition';
            return 200;
        }

        try_files $uri $uri/ /index.php?$args;
        index index.php index.html index.htm;
    }

    location ~ .php$ {
        try_files $uri $uri/ /index.php?$args;
        index index.php index.html index.htm;

        fastcgi_pass   unix:/var/run/php5-fpm.sock;
        fastcgi_index  index.php;
        fastcgi_param  SCRIPT_FILENAME  /var/www/releases/latest/_UPLOAD/public$fastcgi_script_name;
        fastcgi_param  APPLICATION_ENV production;
        fastcgi_param  PATH /usr/bin:/bin:/usr/sbin:/sbin;
        fastcgi_intercept_errors on;
        include        fastcgi_params;
    }

    error_page 403 =404 /404.html;
    error_page 404 /404.html;
    location = /404.html {
        root /var/www/releases/latest/_UPLOAD/public;
        internal;
    }

    error_page 500 502 503 504 = /50x.html;
    location = /50x.html {
        root /var/www/releases/latest/_UPLOAD/public;
        internal;
    }
}

Is there anything in the config that might impede successful uploads and be causing these pesky 408 errors? Nothing is mentioned in the error logs about this issue.

NOTE: We have only used reload when we make changes to the nginx configuration. We are trying to avoid a restart but if that is required for our configuration changes to take full effect then we will do it.

I’m sorry, but this is going to be one of those long rants of mine.

The problem with 408

This is (sadly) a typical scenario: A client, or other luser of the interwebs, notices that a website shows HTTP error 408 instead of their favorite content. Oh no! “the remote server returned an error: (408) request timeout!” He or she then asks the web developer to make the bad error go away.

The “seasoned” web developer looks at the error logs, and notices an error: something to do with timeouts. Having no idea what it means, he or she googles the error, and voila! an article gives “the” solution for this type of error. It looks something like this:

Locate your nginx config file, or your php.ini file, and increase max_execution_time (or some variation thereof).

— some random “technical” article on the web

Usually the article will also include some helpful info on how to locate these files, and how to restart the server after you’re done editing them (as if you shouldn’t know this already).

Let’s think for a moment about what has happened here

Web servers (usually Apache, Nginx, etc) are configured by default to wait for the back-end (usually PHP) for about 15 or 30 seconds. If the script doesn’t respond in that time, the web server kills the script and sends the user on their merry way with an HTTP status code of 408.

When you increase that timeout limit, what you tell the server is that you’re OK with HTTP requests taking more than 30 seconds. Really? Are you really OK with this?

Do this right now: Count slowly from 1 to 30, to get a feel of what half a minute is like. Would you wait that long for a website to load? Unless you’re working for a government website, I’m guessing you probably care about SEO at least a tiny bit.

So please, next time you see a web script timing out, don’t just blindly increase timeout limits. Dig a little deeper in your log files, do some tests, debug a little. Does the issue occur with all scripts or just with some? What do the PHP-FPM logs say? Are the worker threads up and running? What’s the memory situation like on your server? Maybe add a few debug prints in your script, or do some profiling?

If you’re on a CMS like WordPress, try disabling some plugins. Switch to another theme. Tinker with your caches. Try to isolate the component that causes the issue.

Conclusion

I don’t know what’s wrong with your server. But I know it shouldn’t be taking over half a minute to respond to an HTTP request. So please, do your job as an engineer, and look for the root cause of the issue.

Same goes for maximum memory, worker threads count etc. Don’t just increase numbers at random. Look at your traffic first. What amount of worker threads do you need? What do your scripts need in terms of resources? You know that these things use CPU and memory, right?