Nodebb: Lots of "upstream timed out (110: Connection timed out)" errors logged by nginx

[joolswills]

Please include the following information when submitting a bug report/issue:

• NodeBB version and git hash: v1.4.1 - 3309f2910d2aa56f06d92a1912dc10ce30da10e2
• Database (mongo or redis) and it's version. Mongodb 3.2.11
• Nginx nginx version: nginx/1.10.2 (from dotdeb.org)

I am getting a lot of errors logged by nginx which is proxying to nodebb. I am not sure when this started but I noticed this a month or two ago, but have not had a chance to look into it until now. Despite the errors, the forum seems to be running fine, and I'm not sure what the problem is - if it's a configuration issue in nginx, or something wrong with the way nodebb is configured. Any pointers would be appreciated

example log snippet (ips removed)

2016/12/19 23:53:04 [error] 6410#6410: *15910264 upstream timed out (110: Connection timed out) while reading response header from upstream, client: ::ffff:REMOVED, server: retropie.org.uk, request: "GET /forum/socket.io/?EIO=3&transport=polling&t=LaPVxYL&sid=qenKXroKp82L_hWeAAuZ HTTP/1.1", upstream: "http://127.0.0.1:4570/forum/socket.io/?EIO=3&transport=polling&t=LaPVxYL&sid=qenKXroKp82L_hWeAAuZ", host: "retropie.org.uk", referrer: "https://retropie.org.uk/forum/topic/2859/how-to-use-mame-with-retropie-help-guide"
2016/12/19 23:53:06 [error] 5297#5297: *15887186 upstream timed out (110: Connection timed out) while reading response header from upstream, client: ::ffff:REMOVED, server: retropie.org.uk, request: "GET /forum/socket.io/?EIO=3&transport=polling&t=LaPVzT8&sid=5OnFzlIEqFBWVo14AA_T HTTP/2.0", upstream: "http://127.0.0.1:4567/forum/socket.io/?EIO=3&transport=polling&t=LaPVzT8&sid=5OnFzlIEqFBWVo14AA_T", host: "retropie.org.uk", referrer: "https://retropie.org.uk/forum/topic/2870/running-roms-from-a-network-share/20"
2016/12/19 23:53:06 [error] 6411#6411: *15905722 upstream timed out (110: Connection timed out) while reading response header from upstream, client: ::ffff:REMOVED, server: retropie.org.uk, request: "GET /forum/socket.io/?EIO=3&transport=polling&t=LaPVzlr&sid=zg40-Ov_vtmh_MpdAAhh HTTP/1.1", upstream: "http://127.0.0.1:4569/forum/socket.io/?EIO=3&transport=polling&t=LaPVzlr&sid=zg40-Ov_vtmh_MpdAAhh", host: "retropie.org.uk", referrer: "https://retropie.org.uk/forum/topic/3271/retropie-not-finding-roms-on-external-hard-drive/3"
2016/12/19 23:53:06 [error] 5297#5297: *15887186 upstream timed out (110: Connection timed out) while reading response header from upstream, client: ::ffff:REMOVED, server: retropie.org.uk, request: "GET /forum/socket.io/?EIO=3&transport=polling&t=LaPVzWZ&sid=tWwS5qZvwc8RmCGoAA_U HTTP/2.0", upstream: "http://127.0.0.1:4567/forum/socket.io/?EIO=3&transport=polling&t=LaPVzWZ&sid=tWwS5qZvwc8RmCGoAA_U", host: "retropie.org.uk", referrer: "https://retropie.org.uk/forum/topic/288/ps2-emu-on-pi3-possible"
2016/12/19 23:53:06 [error] 6410#6410: *15906869 upstream timed out (110: Connection timed out) while reading response header from upstream, client: ::ffff:REMOVED, server: retropie.org.uk, request: "GET /forum/socket.io/?EIO=3&transport=polling&t=LaPVzqO.0&sid=jfF20L2xkRLqHvWuAAuv HTTP/2.0", upstream: "http://127.0.0.1:4570/forum/socket.io/?EIO=3&transport=polling&t=LaPVzqO.0&sid=jfF20L2xkRLqHvWuAAuv", host: "retropie.org.uk", referrer: "https://retropie.org.uk/forum/topic/4837/retropie-will-not-recognize-mouse-or-trackball-at-all/7"

Despite the errors the forum seems to be running ok. It doesn't seem to be slow, but perhaps a backend is stalling for some reason to cause the timeout? System is not under heavy load.

nginx config:

upstream io_nodes {
  ip_hash;
  server 127.0.0.1:4567;
  server 127.0.0.1:4568;
  server 127.0.0.1:4569;
  server 127.0.0.1:4570;
  server 127.0.0.1:4571;
  server 127.0.0.1:4572;
}

server {
  listen [::]:443 default_server ipv6only=off ssl http2;
  server_name retropie.org.uk;

[unrelated configs]

  location ^~ /forum {
    error_page 502 =503 @maintenance;

    proxy_set_header X-Real-IP $remote_addr;
    proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
    proxy_set_header X-Forwarded-Proto $scheme;
    proxy_set_header Host $http_host;
    proxy_set_header X-NginX-Proxy true;

    proxy_pass http://io_nodes/forum;
    proxy_redirect off;

    # Socket.IO Support
    proxy_http_version 1.1;
    proxy_set_header Upgrade $http_upgrade;
    proxy_set_header Connection "upgrade";
  }
}

nodebb config

{
    "url": "https://retropie.org.uk/forum",
    "bind_address": "127.0.0.1",
    "secret": "REMOVED",
    "database": "mongo",
    "port": [4567, 4568, 4569, 4570, 4571, 4572],
    "mongo": {
        "host": "127.0.0.1",
        "port": "27017",
        "username": "REMOVED",
        "database": "nodebb",
        "password": "REMOVED"
    },
    "redis": {
        "host":"127.0.0.1",
        "port":"6379",
        "database": 0
    }
}

I'm not getting any errors from nodebb / mongodb.

[joolswills]

I am also seeing these

2016/12/20 00:13:23 [error] 1819#1819: *46402 upstream prematurely closed connection while reading response header from upstream, client: REMOVED, server: retropie.org.uk, request: "GET /forum/socket.io/?EIO=3&transport=websocket&sid=zFh1FVdGKh8L54mkAAGP HTTP/1.1", upstream: "http://127.0.0.1:4571/forum/socket.io/?EIO=3&transport=websocket&sid=zFh1FVdGKh8L54mkAAGP", host: "retropie.org.uk"
2016/12/20 00:13:25 [error] 1822#1822: *46575 upstream prematurely closed connection while reading response header from upstream, client: REMOVED, server: retropie.org.uk, request: "GET /forum/socket.io/?EIO=3&transport=websocket&sid=ijRkihHjmiq99IpfAAHD HTTP/1.1", upstream: "http://127.0.0.1:4571/forum/socket.io/?EIO=3&transport=websocket&sid=ijRkihHjmiq99IpfAAHD", host: "retropie.org.uk"

[julianlam]

Fixed upstream, thanks. https://github.com/socketio/engine.io/pull/458#issuecomment-265611569

It will be merged in in time, for now we wait.

[joolswills]

Thanks for the reference.

[joolswills]

@julianlam that fix is upstream in 1.8.2 - can nodebb be updated to use it ? I don't know if there is a reason nodebb is on the older 1.7.x socket.io etc

[julianlam]

@barisusakli can you double-check?

[barisusakli]

I think they haven't updated the npm package https://www.npmjs.com/package/socket.io

[barisusakli]

@joolswills try after https://github.com/NodeBB/NodeBB/commit/b08acd197c2fb18becf5a05010fcdd8e82fc5107

[joolswills]

aha. socket.io 1.7.2 includes engine.io 1.8.2. thanks. is it safe to update nodebb to that commit now on a production forum?

[barisusakli]

It is safe when you make a backup 👼

[joolswills]

:-) thanks.

[joolswills]

I can confirm this resolves the upstream prematurely closed connection errors, but I am still getting plenty of the errors in the original post

2017/02/03 16:36:10 [error] 7588#7588: *3345968 upstream timed out (110: Connection timed out) while reading response header from upstream, client: REMOVED, server: retropie.org.uk, request: "GET /forum/socket.io/?EIO=3&transport=polling&t=Le4r2Ks&sid=Q9z39iYh---Ky3BzAAAh HTTP/1.1", upstream: "http://127.0.0.1:4567/forum/socket.io/?EIO=3&transport=polling&t=Le4r2Ks&sid=Q9z39iYh---Ky3BzAAAh", host: "retropie.org.uk", referrer: "https://retropie.org.uk/forum/topic/5792/c64-roms"

the forum seems to function fine (as it did before), just a lot of log files with these errors.

[joolswills]

I think I may have resolved this now with some nginx config changes - will report back after more testing.

[barisusakli]

Please share your changes if it's resolved :)

[joolswills]

It sounds obvious as I just increased the timeouts - but I'm a little unsure as to why this was needed

testing with

    proxy_read_timeout 120s;
    proxy_send_timeout 120s;

the default is 60s - which should be plenty. With 6 nodebb processes, and with my current config of nginx serving up static content, I have no idea why anything would take longer than 60s to complete, and certainly when browsing the forum I don't see that. I will start logging the request times I think, to see if there is a pattern, or whether it's something odd about the way nginx is calculating the timeouts.

(On another system recently with nginx proxying to another piece of software, I had set a proxy timeout much higher, and it still timed out much before the timeout was reached, so I wonder if there is some nginx issue here).

[barisusakli]

Well if they are all from socket.io polling requests it might make sense.

[Rakin061]

@joolswills

I have been getting exactly the same errors as your's.

Could you please give me any light about how you resolve this issue ?

[joolswills]

@Rakin061 - upgraded I think, but without any information about your set-up, no-one can really advise.

[joolswills]

I mention above btw how i resolved it.

[Saptarshi510]

Facing similar issue , can anyone help in resolving it.

2020/02/18 17:44:06 [error] 120#120: *19 upstream timed out (110: Connection timed out) while connecting to upstream, client: 10.32.0.1, server: jenkins, request: "HEAD / HTTP/1.1", upstream: "http://xx.xx.xx.xx:8080/", host: "jenkins"
10.32.0.1 - - [18/Feb/2020:17:44:06 +0000] "HEAD / HTTP/1.1" 504 0 "-" "curl/7.29.0" "-"

Trying to run nginx-ingress on k8 and trying to run jenkins with nginx-ingress controller, to be more specific , able to access the jenkins with ip and port