Strange issue after nginx update

Andrea Soracchi soracchi at multidialogo.it
Thu Jun 29 10:01:35 UTC 2017


Hi Payam, 

the problem is between Nginx and Php-fpm, but 

I have set the debug level log to nginx and php-fpm. 

Nginx: 

2017/06/29 10:05:14 [warn] 5252#5252: *1613 a client request body is buffered to a temporary file /var/lib/nginx/body/0000000044, client: 192.168.18.18, server: andrea.eoraptor3.netbuilder.it, request: "POST /index2.php HTTP/1.1", host: "andrea.eoraptor3.netbuilder.it" 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 write: 9, 0000560D636FBE70, 8192, 0 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 recv: fd:3 5488 of 8192 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 http client request body recv 5488 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 http client request body rest 54606013 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 recv: fd:3 -1 of 2704 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 recv() not ready (11: Resource temporarily unavailable) 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 http client request body recv -2 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 http client request body rest 54606013 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 event timer: 3, old: 1498723634292, new: 1498723634292 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 http run request: "/index2.php?" 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 http read client request body 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 recv: fd:3 1368 of 2704 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 http client request body recv 1368 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 http client request body rest 54606013 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 recv: fd:3 -1 of 1336 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 recv() not ready (11: Resource temporarily unavailable) 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 http client request body recv -2 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 http client request body rest 54606013 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 event timer: 3, old: 1498723634292, new: 1498723634293 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 http run request: "/index2.php?" 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 http read client request body 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 recv: fd:3 1336 of 1336 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 http client request body recv 1336 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 http body new buf t:1 f:0 0000560D636FBE70, pos 0000560D636FBE70, size: 8192 file: 0, size: 0 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 http write client request body, bufs 0000560D636F92C0 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 write: 9, 0000560D636FBE70, 8192, 8192 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 recv: fd:3 1400 of 8192 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 http client request body recv 1400 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 http client request body rest 54597821 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 recv: fd:3 -1 of 6792 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 recv() not ready (11: Resource temporarily unavailable) 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 http client request body recv -2 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 http client request body rest 54597821 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 event timer: 3, old: 1498723634292, new: 1498723634293 
2017/06/29 10:05:14 [debug] 5252#5252: *1613 http run request: "/index2.php?" 
... 
Repeated several times 
... 
... 
2017/06/29 10:05:15 [debug] 5252#5252: *1613 writev() not ready (11: Resource temporarily unavailable) 
2017/06/29 10:05:15 [debug] 5252#5252: *1613 chain writer out: 0000560D637FE780 
2017/06/29 10:05:15 [debug] 5252#5252: *1613 event timer: 10, old: 1498723575096, new: 1498723575151 
2017/06/29 10:05:15 [debug] 5252#5252: *1613 http upstream request: "/index2.php?" 
2017/06/29 10:05:15 [debug] 5252#5252: *1613 http upstream send request handler 
2017/06/29 10:05:15 [debug] 5252#5252: *1613 http upstream send request 
2017/06/29 10:05:15 [debug] 5252#5252: *1613 http upstream send request body 
2017/06/29 10:05:15 [debug] 5252#5252: *1613 chain writer in: 0000560D637FE780 
2017/06/29 10:05:15 [debug] 5252#5252: *1613 writev: 8 of 8 
2017/06/29 10:05:15 [debug] 5252#5252: *1613 sendfile: @54591488 22717 
2017/06/29 10:05:15 [debug] 5252#5252: *1613 sendfile: 22717 of 22717 @54591488 
2017/06/29 10:05:15 [debug] 5252#5252: *1613 writev: 11 of 11 
2017/06/29 10:05:15 [debug] 5252#5252: *1613 chain writer out: 0000000000000000 
2017/06/29 10:05:15 [debug] 5252#5252: *1613 event timer del: 10: 1498723575096 
2017/06/29 10:05:15 [debug] 5252#5252: *1613 event timer add: 10: 300000:1498723815151 
2017/06/29 10:05:15 [debug] 5252#5252: *1613 http upstream request: "/index2.php?" 
2017/06/29 10:05:15 [debug] 5252#5252: *1613 http upstream dummy handler 
2017/06/29 10:05:15 [debug] 5252#5252: *1613 http upstream request: "/index2.php?" 
2017/06/29 10:05:15 [debug] 5252#5252: *1613 http upstream dummy handler 
2017/06/29 10:05:40 [debug] 5252#5252: *1613 http upstream request: "/index2.php?" 
2017/06/29 10:05:40 [debug] 5252#5252: *1613 http upstream process header 
2017/06/29 10:05:40 [debug] 5252#5252: *1613 malloc: 0000560D637FF560:4096 
2017/06/29 10:05:40 [debug] 5252#5252: *1613 recv: fd:10 56 of 4096 
2017/06/29 10:05:40 [debug] 5252#5252: *1613 http fastcgi record byte: 01 
2017/06/29 10:05:40 [debug] 5252#5252: *1613 http fastcgi record byte: 06 
2017/06/29 10:05:40 [debug] 5252#5252: *1613 http fastcgi record byte: 00 
2017/06/29 10:05:40 [debug] 5252#5252: *1613 http fastcgi record byte: 01 
2017/06/29 10:05:40 [debug] 5252#5252: *1613 http fastcgi record byte: 00 
2017/06/29 10:05:40 [debug] 5252#5252: *1613 http fastcgi record byte: 1D 
2017/06/29 10:05:40 [debug] 5252#5252: *1613 http fastcgi record byte: 03 
2017/06/29 10:05:40 [debug] 5252#5252: *1613 http fastcgi record byte: 00 
2017/06/29 10:05:40 [debug] 5252#5252: *1613 http fastcgi record length: 29 
2017/06/29 10:05:40 [debug] 5252#5252: *1613 http fastcgi parser: 0 
2017/06/29 10:05:40 [debug] 5252#5252: *1613 http fastcgi header: "Content-type: text/html" 
2017/06/29 10:05:40 [debug] 5252#5252: *1613 http fastcgi parser: 1 
2017/06/29 10:05:40 [debug] 5252#5252: *1613 http fastcgi header done 
2017/06/29 10:05:40 [debug] 5252#5252: *1613 xslt filter header 
2017/06/29 10:05:40 [debug] 5252#5252: *1613 HTTP/1.1 200 OK^M 


Php-fpm: 

PHPFPM 

[29-Jun-2017 10:05:14.699514] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 0 active children, 3 spare children, 3 running children. Spawning rate 1 

[29-Jun-2017 10:05:16.700710] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 1 active children, 2 spare children, 3 running children. Spawning rate 1 
[29-Jun-2017 10:05:17.701773] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 1 active children, 2 spare children, 3 running children. Spawning rate 1 
[29-Jun-2017 10:05:18.702842] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 1 active children, 2 spare children, 3 running children. Spawning rate 1 
[29-Jun-2017 10:05:19.703778] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 1 active children, 2 spare children, 3 running children. Spawning rate 1 
[29-Jun-2017 10:05:20.705400] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 1 active children, 2 spare children, 3 running children. Spawning rate 1 
[29-Jun-2017 10:05:21.706471] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 1 active children, 2 spare children, 3 running children. Spawning rate 1 
[29-Jun-2017 10:05:22.707537] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 1 active children, 2 spare children, 3 running children. Spawning rate 1 
[29-Jun-2017 10:05:23.707779] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 1 active children, 2 spare children, 3 running children. Spawning rate 1 
[29-Jun-2017 10:05:24.708839] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 1 active children, 2 spare children, 3 running children. Spawning rate 1 
[29-Jun-2017 10:05:25.710378] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 1 active children, 2 spare children, 3 running children. Spawning rate 1 
[29-Jun-2017 10:05:26.710841] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 1 active children, 2 spare children, 3 running children. Spawning rate 1 
[29-Jun-2017 10:05:27.711798] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 1 active children, 2 spare children, 3 running children. Spawning rate 1 
[29-Jun-2017 10:05:28.712864] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 1 active children, 2 spare children, 3 running children. Spawning rate 1 
[29-Jun-2017 10:05:29.713932] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 1 active children, 2 spare children, 3 running children. Spawning rate 1 
[29-Jun-2017 10:05:30.715523] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 1 active children, 2 spare children, 3 running children. Spawning rate 1 
[29-Jun-2017 10:05:31.715785] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 1 active children, 2 spare children, 3 running children. Spawning rate 1 
[29-Jun-2017 10:05:32.716851] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 1 active children, 2 spare children, 3 running children. Spawning rate 1 
[29-Jun-2017 10:05:32.716851] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 1 active children, 2 spare children, 3 running children. Spawning rate 1 
[29-Jun-2017 10:05:33.717931] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 1 active children, 2 spare children, 3 running children. Spawning rate 1 
[29-Jun-2017 10:05:34.719001] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 1 active children, 2 spare children, 3 running children. Spawning rate 1 
[29-Jun-2017 10:05:35.720280] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 1 active children, 2 spare children, 3 running children. Spawning rate 1 
[29-Jun-2017 10:05:36.720662] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 1 active children, 2 spare children, 3 running children. Spawning rate 1 
[29-Jun-2017 10:05:37.721725] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 1 active children, 2 spare children, 3 running children. Spawning rate 1 
[29-Jun-2017 10:05:38.722791] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 1 active children, 2 spare children, 3 running children. Spawning rate 1 
[29-Jun-2017 10:05:39.723785] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 1 active children, 2 spare children, 3 running children. Spawning rate 1 

[29-Jun-2017 10:05:40.725342] DEBUG: pid 5135, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool mdbeta] currently 0 active children, 3 spare children, 3 running children. Spawning rate 1 


Any idea? 

Thanks a lot, 
Andrea 





ANDREA SORACCHI 
+39 329 0512704 
System Engineer 

+39 0521 24 77 91 
soracchi at netbuilder.it 
----- Original Message -----

From: "Payam Chychi" <pchychi at gmail.com> 
To: nginx at nginx.org 
Sent: Giovedì, 29 giugno 2017 6:38:09 
Subject: Re: Strange issue after nginx update 



Are you seeing any errors in your php log? 
are you connecting to the hostname or ip? 


Also, make sure your interface is connected at full duplex. whats the output of " ethtool eth0" replace eth0 with your nic in use. 


not sure what else really... 
id say to check dns but its all local to you 


- Payam 






On Wed, Jun 28, 2017 at 9:01 PM Anoop Alias < anoopalias01 at gmail.com > wrote: 



give a try changing the nameservers in /etc/resolv.conf 



On Thu, Jun 29, 2017 at 3:51 AM, Andrea Soracchi < soracchi at multidialogo.it > wrote: 

<blockquote>



Hi, 



I have attached part of the ettercap log . 



I have posted a test file of 40MB. 


The delay is 29 second: 


from the last file's chunk at 23:56:06 

to the response of index2.php at 23:56:35 


The nginx's log show: 


192.168.18.18 - - [28/Jun/2017:23:56:35 +0200] "POST /index2.php HTTP/1.1" 200 37 "-" "Generic Client" 


Nothing retransmits, SElinux isn't installed and apparmor is stopped. 



Nothing in dmesg... 



Thanks a lot, 








ANDREA SORACCHI 
+39 329 0512704 
System Engineer 

+39 0521 24 77 91 
soracchi at netbuilder.it 



Da: "Payam Chychi" < pchychi at gmail.com > 
A: "nginx" < nginx at nginx.org > 
Inviato: Mercoledì, 28 giugno 2017 19:56:04 
Oggetto: Re: Strange issue after nginx update 








On Wed, Jun 28, 2017 at 8:41 AM Andrea Soracchi < soracchi at multidialogo.it > wrote: 

<blockquote>




Hi, 
could you please help me solve this issue? I'm getting crazy! 

Before the nginx update my client worked perfectly: it posted files to my website without any delay. 

How, after nginx update (ubuntu 16.04 LTS) I've got this issue: 

- the client posts files successfully but the answer of the post is delayed. The more the file is bigger, the more the answer is delayed. 

I put a sniffer into the website' server and I noticed that the nginx receives the post but it waits to transfer the file to php-fpm process, so also the answer to the client is delayed 

The nginx server is: 

nginx/1.10.0 (Ubuntu) and its conf is: 

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

events { 
worker_connections 768; 
# multi_accept on; 
} 

http { 
sendfile on; 
tcp_nodelay on; 
keepalive_timeout 65; 
types_hash_max_size 2048; 
client_max_body_size 0; 
log_not_found off; 
server_name_in_redirect off; 
client_body_timeout 120s; 
autoindex off; 
include /etc/nginx/mime.types; 
default_type application/octet-stream; 
ssl_protocols TLSv1 TLSv1.1 TLSv1.2; # Dropping SSLv3, ref: POODLE 
ssl_prefer_server_ciphers on; 
access_log /var/log/nginx/access.log; 
error_log /var/log/nginx/error.log info; 
gzip on; 
gzip_disable "msie6"; 
gzip_types text/plain text/css application/json application/javascript text/xml application/xml application/xml+rss text/javascript; 
include /etc/nginx/conf.d/*.conf; 
include /etc/nginx/sites-enabled/*; 
--- 

and website's php-fpm conf is: 

server { 
listen 80; 
server_name test.it ; 
server_name_in_redirect off; 
autoindex off; 
client_max_body_size 500m; 
index index.html; 
root /home/test/test; 
location ~ \.(php|html|htm|php3)$ { 
try_files $uri 404; 
fastcgi_pass unix:/run/php/mdtest-fpm.sock; 
include fastcgi_params; 
} 
} 

fastcgi_params config: 

fastcgi_param QUERY_STRING $query_string; 
fastcgi_param REQUEST_METHOD $request_method; 
fastcgi_param CONTENT_TYPE $content_type; 
fastcgi_param CONTENT_LENGTH $content_length; 

fastcgi_param SCRIPT_NAME $fastcgi_script_name; 
fastcgi_param REQUEST_URI $request_uri; 
fastcgi_param DOCUMENT_URI $document_uri; 
fastcgi_param DOCUMENT_ROOT $document_root; 
fastcgi_param SERVER_PROTOCOL $server_protocol; 
fastcgi_param REQUEST_SCHEME $scheme; 
fastcgi_param HTTPS $https if_not_empty; 

fastcgi_param GATEWAY_INTERFACE CGI/1.1; 
fastcgi_param SERVER_SOFTWARE nginx/$nginx_version; 

fastcgi_param REMOTE_ADDR $remote_addr; 
fastcgi_param REMOTE_PORT $remote_port; 
fastcgi_param SERVER_ADDR $server_addr; 
fastcgi_param SERVER_PORT $server_port; 
#fastcgi_param SERVER_NAME $server_name; 
fastcgi_param SERVER_NAME $http_host; 

# PHP only, required if PHP was built with --enable-force-cgi-redirect 
fastcgi_param REDIRECT_STATUS 200; 

fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name; 


Thanks a lot, 
Andrea 







ANDREA SORACCHI 
+39 329 0512704 
System Engineer 

+39 0521 24 77 91 
soracchi at netbuilder.it 

_______________________________________________ 
nginx mailing list 
nginx at nginx.org 
http://mailman.nginx.org/mailman/listinfo/ nginx 




<blockquote>

</blockquote>


hi, 


can you show the related wireshark data, how long is the response delayed by? and anything else like retransmits or anything else? 


any SElinux security throtelling taking place? anything in dmesg? 
<blockquote>


</blockquote>

-- 

Payam Tarverdyan Chychi 
Network Security Specialist / Network Engineer 
_______________________________________________ 
nginx mailing list 
nginx at nginx.org 
http://mailman.nginx.org/mailman/listinfo/nginx 

_______________________________________________ 
nginx mailing list 
nginx at nginx.org 
http://mailman.nginx.org/mailman/listinfo/nginx 

</blockquote>





-- 



Anoop P Alias 

_______________________________________________ 
nginx mailing list 
nginx at nginx.org 
http://mailman.nginx.org/mailman/listinfo/nginx 
</blockquote>

-- 

Payam Tarverdyan Chychi 
Network Security Specialist / Network Engineer 
-- 
Questo messaggio e' stato analizzato ed e' risultato non infetto. 
This message was scanned and is believed to be clean. 
_______________________________________________ 
nginx mailing list 
nginx at nginx.org 
http://mailman.nginx.org/mailman/listinfo/nginx 
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.nginx.org/pipermail/nginx/attachments/20170629/ac04be67/attachment-0001.html>


More information about the nginx mailing list