Connection timed out errors

[jlyonsmith]

I'm getting:

2019/01/17 21:38:32 [error] 4213#4213: *12683 upstream timed out (110: Connection timed out) while connecting to upstream(proxy_connect), client: 192.168.0.138, server: , request: "CONNECT registry.npmjs.org:443 HTTP/1.1", host: "registry.npmjs.org"

When trying to do an npm install through the proxy. What happens is, I will get may a hundred or so successful upstream connections, and then this error will start to appear and npm will never recover.

Both my systems are on AWS EC2. My nginx.conf file looks like this:

worker_processes 1;

error_log /var/log/nginx/error.log info;

pid /run/nginx.pid;

events {
  worker_connections 1024;
}

http {
  include mime.types;
  default_type application/octet-stream;
  sendfile on;
  keepalive_timeout 65;

  server {
    listen 3128;
    resolver 127.0.0.53 ipv6=off;
    resolver_timeout 30s;

    # Forward proxy for CONNECT requests
    proxy_connect;
    proxy_connect_allow 443;
    proxy_connect_connect_timeout 30s;
    proxy_connect_read_timeout 30s;
    proxy_connect_send_timeout 30s;

    # Forward proxy for non-CONNECT request
    location / {
      proxy_pass http://$host;
      proxy_set_header Host $host;
    }
  }
}

I found I had to add the ipv6=off or the I'd get this error almost constantly. Apparently there is a race condition with the DNS server sometimes returning an IPv6 record before the IPv4 one.

[chobits]

Let me check

[chobits]

2019/01/17 21:38:32 [error] 4213#4213: *12683 upstream timed out (110: Connection timed out) while connecting to upstream(proxy_connect), client: 192.168.0.138, server: , request: "CONNECT registry.npmjs.org:443 HTTP/1.1", host: "registry.npmjs.org"

This means proxy_connect module tried to connect backend peer and it timed out finally. The backend peer is returned by DNS server for resolving registry.npmjs.org.

Based on what you said about IPv6 resolving, I guess your proxy server cannot connect to the IPv6 peer address.

But it is hard to fixed in proxy_connect module, proxy_connect module just calls standard nginx-core DNS API.

BTW, I'll optimize the error log to show timedout IP address.

[chobits]

• TODO: optimize error log to show connect-timedout IP address

edit fixed in #121.

[bigboyq]

I have solved similar problem by adding

proxy_connect_timeout 600;
proxy_send_timeout 600;
proxy_read_timeout 600;
send_timeout 600;

in nginx.conf, just have a try

[jrgp]

Hi @chobits do you have an update on this?

I'm seeing something similar: I see a bunch of these upstream timeout errors in logs, but in the access log they don't always show up as 504s. Do you have any ideas as to the disparity between the error logs and the access logs for these timeouts? I'm wondering if the proxy module tries to reconnect a few times before giving up.

[chobits]

Hi @chobits do you have an update on this?

I'm seeing something similar: I see a bunch of these upstream timeout errors in logs, but in the access log they don't always show up as 504s. Do you have any ideas as to the disparity between the error logs and the access logs for these timeouts? I'm wondering if the proxy module tries to reconnect a few times before giving up.

Response status will be 200 not 504 if CONNECT tunnel has been established with backend server and then the timedout error occurs.

Will modify some error message to show these details.

[chobits]

hi @jrgp

Im wondering if the proxy module tries to reconnect a few times before giving up.

No, proxy_connect modules does not reconnect a few times.
And note that only error message including proxy_connect string is generated by proxy_connect, other error messages may be generated by nginx upstream(http proxy).

[chobits]

Error log messages has been updated in #121 and #124.

For doc of error log message, see readme/error log

• fixed TODO: optimize error log to show connect-timedout IP address

[jlyonsmith]

Just as an additional data point, we switched to using Tengine instead of vanilla nginx and have not seen this issue. @chobits It is my understanding that you merged this module into Tengine. Is there something different about it in the Tengine code base? With this module and nginx we would see this timeout error downloading npm modules regularly. We have never seen with Tengine.

[chobits]

hi @jlyonsmith

It is my understanding that you merged this module into Tengine.

Yes

Is there something different about it in the Tengine code base?

Tengine core base has something different about nginx. However, proxy_connect module code base has nothing diffrerent with them. Hard to explain your testing result.

Maybe new error log messages can help to locate this problem. It shows backend address and differentiates between connect() and read() syscall.

[jrgp]

Hi @chobits thanks for adding the additional debugging messages. I just upgraded to the latest master rev and I'm now seeing the additional information, with the error classified as a read timeout:

2019/08/08 19:10:05 [error] 11765#0: *471838 proxy_connect: upstream read timed out (peer:[REDACTED]:443) while connecting to upstream, client: REDACTED, server: , request: "CONNECT REDACTED:443 HTTP/1.1", host: "REDACTED:443"

I'm using nginx 1.12.2. Do you think there are improvements in the nginx core between 1.12.2 and 1.16.0 which could help this problem, or is it more likely to be a networking/config problem on my end?

Also, are the proxy timeout config options in vanilla nginx relevant here or do only the proxy_connect_* options this module provides matter?

[chobits]

Also, are the proxy timeout config options in vanilla nginx relevant here or do only the proxy_connect_* options this module provides matter?

For backend timeout, proxy_connect_* works.

[chobits]

hi @jrgp

2019/08/08 19:10:05 [error] 11765#0: *471838 proxy_connect: upstream read timed out ...

It means proxy_connect tries to read data from backend server, but the backend server does not send data back during timeout set by proxy_connect_read_timeout occurs. Try to increase the value of timeout.

[jrgp]

Hi @chobits. Thanks for the info. Bumping that setting much higher (30s to 60s) made most of the error messages go away. Now I need to determine why the timeout needs to be set so high :)