$upstream_addr returning "-" only on requests with "del" in them
Ruslan Ermilov
ru at nginx.com
Thu Apr 27 09:38:53 UTC 2017
On Wed, Apr 26, 2017 at 07:58:08PM -0400, ywarnier wrote:
> Sometimes writing your thought helps...
> Apparently something wasn't reporting correctly so far, but using the debug
> level, I finally end up getting some information. I should mention that the
> word that seems to provoke this issue is ' del ' (with two spaces around
> it). If those 3 letters are included in another word, nothing weird
> happens.
>
> When the word is there on its own, though, this is my debug log (I have
> surrounded the most obvious issue with two blank lines):
>
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http keepalive handler
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 malloc: 000055B18C6ADF30:1024
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 recv: fd:16 978 of 1024
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 reusable connection: 0
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 posix_memalign:
> 000055B18C6C0F10:4096 @16
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http header: "Host:
> dev.www.myorg.edu"
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http header: "Connection:
> keep-alive"
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http header: "Content-Length:
> 16639"
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http header: "Pragma: no-cache"
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http header: "Cache-Control:
> no-cache"
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http header: "Origin:
> http://dev.www.myorg.edu"
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http header:
> "Upgrade-Insecure-Requests: 1"
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http header: "User-Agent:
> Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko)
> Ubuntu Chromium/57.0.2987.98 Chrome/57.0.2987.98 Safari/537.36"
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http header: "Content-Type:
> multipart/form-data; boundary=----WebKitFormBoundaryfufPzGfQx0XTvHjM"
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http header: "Accept:
> text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8"
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http header: "Referer:
> http://dev.www.myorg.edu/en/node/734/edit"
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http header: "Accept-Encoding:
> gzip, deflate"
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http header: "Accept-Language:
> en-US,en;q=0.8,es;q=0.6,fr-FR;q=0.4,fr;q=0.2"
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http header: "Cookie:
> DrupalModuleFilter=activeTab%3Dall;
> SESSb62f82f041805dbb55d5167522aaa24e=y-yFLoyVXBRCGSmicYphWW-OCVYIGphmDhmx9k9wubQ;
> SESSd452cfca8c0eccb9b5e4447bc1fa95dc=ENsFfcPE5jv4sTxlDxc40kg09aFMu7S-ZXJHPn0osb4;
> has_js=1; Drupal.tableDrag.showWeight=0"
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http header: "DNT: 1"
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http header done
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 generic phase: 0
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 rewrite phase: 1
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 test location: "/"
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 using configuration "/"
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http cl:16639 max:52428800
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 rewrite phase: 3
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 post rewrite phase: 4
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 generic phase: 5
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 generic phase: 6
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 generic phase: 7
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 access phase: 8
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 access phase: 9
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 access phase: 10
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 access phase: 11
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 post access phase: 12
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 try files phase: 13
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http request body content length
> filter
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 malloc: 000055B18C6F4100:8192
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http read client request body
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 recv: fd:16 -1 of 8192
>
> 2017/04/26 18:38:52 [info] 6496#6496: *350 recv() failed (104: Connection
> reset by peer), client: 190.117.233.77, server: dev.www.myorg.edu, request:
> "POST /en/node/734/edit HTTP/1.1", host: "dev.www.myorg.edu", referrer:
> "http://dev.www.myorg.edu/en/node/734/edit"
>
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http client request body recv
> -1
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http finalize request: 400,
> "/en/node/734/edit?" a:1, c:1
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http terminate request count:1
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http terminate cleanup count:1
> blk:0
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http posted request:
> "/en/node/734/edit?"
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http terminate handler count:1
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http request count:1 blk:0
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http close request
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 http log handler
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 free: 000055B18C6F4100
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 free: 000055B18C6C0F10, unused:
> 128
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 free: 000055B18C6F30F0, unused:
> 1648
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 close http connection: 16
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 reusable connection: 0
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 free: 000055B18C6ADF30
> 2017/04/26 18:38:52 [debug] 6496#6496: *350 free: 000055B18C6AF150, unused:
> 112
>
>
> So in my case I got a 104: Connection reset by peer. Usually, this error
> message is followed by "while reading response header from upstream", but
> that's not my case. It looks like the issue is only the connection between
> my browser and Nginx, and nothing more. This is confirmed by the fact that I
> don't get anything in my backend's access logs.
>
> Is there anything else in this error log that should point me to a
> particular type of issue?
On Wed, Apr 26, 2017 at 08:25:31PM -0400, ywarnier wrote:
> And the usual debug information I just found on
> https://www.nginx.com/resources/wiki/start/topics/tutorials/debugging/ that
> I should provide (very sorry for doing that in 3 parts, won't happen
> again):
>
> #### nginx -V
> nginx version: nginx/1.10.0 (Ubuntu)
> built with OpenSSL 1.0.2g 1 Mar 2016
> TLS SNI support enabled
> configure arguments: --with-cc-opt='-g -O2 -fPIE -fstack-protector-strong
> -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2'
> --with-ld-opt='-Wl,-Bsymbolic-functions -fPIE -pie -Wl,-z,relro -Wl,-z,now'
> --prefix=/usr/share/nginx --conf-path=/etc/nginx/nginx.conf
> --http-log-path=/var/log/nginx/access.log
> --error-log-path=/var/log/nginx/error.log --lock-path=/var/lock/nginx.lock
> --pid-path=/run/nginx.pid --http-client-body-temp-path=/var/lib/nginx/body
> --http-fastcgi-temp-path=/var/lib/nginx/fastcgi
> --http-proxy-temp-path=/var/lib/nginx/proxy
> --http-scgi-temp-path=/var/lib/nginx/scgi
> --http-uwsgi-temp-path=/var/lib/nginx/uwsgi --with-debug --with-pcre-jit
> --with-ipv6 --with-http_ssl_module --with-http_stub_status_module
> --with-http_realip_module --with-http_auth_request_module
> --with-http_addition_module --with-http_dav_module --with-http_geoip_module
> --with-http_gunzip_module --with-http_gzip_static_module
> --with-http_image_filter_module --with-http_v2_module --with-http_sub_module
> --with-http_xslt_module --with-stream --with-stream_ssl_module --with-mail
> --with-mail_ssl_module --with-threads
> --add-module=/build/nginx-pzhfc2/nginx-1.10.0/debian/modules/nginx-auth-pam
> --add-module=/build/nginx-pzhfc2/nginx-1.10.0/debian/modules/nginx-dav-ext-module
> --add-module=/build/nginx-pzhfc2/nginx-1.10.0/debian/modules/nginx-echo
> --add-module=/build/nginx-pzhfc2/nginx-1.10.0/debian/modules/nginx-upstream-fair
> --add-module=/build/nginx-pzhfc2/nginx-1.10.0/debian/modules/ngx_http_substitutions_filter_module
>
> #### cat /etc/nginx/nginx.conf
>
> user www-data;
> worker_processes auto;
> pid /run/nginx.pid;
>
> events {
> worker_connections 768;
> }
>
> http {
> sendfile on;
> tcp_nopush on
> tcp_nodelay on;
> keepalive_timeout 65;
> types_hash_max_size 2048;
> client_max_body_size 50m;
> # Avoid timeouts
> send_timeout 600;
> proxy_send_timeout 600;
> proxy_read_timeout 600;
>
> include /etc/nginx/mime.types;
> default_type application/octet-stream;
>
> access_log /var/log/nginx/access.log;
> error_log /var/log/nginx/error.log;
> log_format compression '$remote_addr - $remote_user [$time_local] '
> '"$request" $status $body_bytes_sent '
> '"$http_referer" "$http_user_agent"
> "$gzip_ratio"'
> '[$upstream_addr: $request
> |$upstream_connect_time|$upstream_header_time|$upstream_response_time|$request_time|$bytes_sent|$pipe|$upstream_status]';
>
> gzip on;
> gzip_disable "msie6";
> include /etc/nginx/conf.d/*.conf;
> include /etc/nginx/sites-enabled/*;
> }
>
>
> #### cat sites-enabled/load-balancer
>
> upstream apache {
> server webdevw1.myorg.edu;
> }
>
> #### cat sites-enabled/dev.www.myorg.edu
>
> server {
> listen 80;
> listen [::]:80;
> server_name dev.www.myorg.edu;
> error_log /var/log/nginx/www.myorg.edu-error.log debug;
> access_log /var/log/nginx/www.myorg.edu-access.log compression;
> location / {
> proxy_buffers 64 128k;
> proxy_buffer_size 2k;
> proxy_http_version 1.1;
> proxy_set_header Connection "";
> proxy_set_header Host $host;
> proxy_set_header X-Forwarded-For $remote_addr;
> proxy_pass http://apache;
> }
> }
>From the log it follows that client closed a connection before
the entire request body was sent. From the config it follows
that http://nginx.org/r/proxy_request_buffering is "on" (which
is the default setting). It means that no upstream server was
ever contacted, so it's perfectly okay that $upstream_addr is
undefined (this is output as `-' in access_log).
More information about the nginx
mailing list