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). _______________________________________________ nginx mailing list [email protected] http://mailman.nginx.org/mailman/listinfo/nginx
