Hello, I stuck in rather strange situation: if I run nginx under debugger, and request zero-length file it gives me correct reply on first connection. But on second connection it reply it output part of debug log (what supposed to be written to debug log, but wasn't). At the same time if nginx runs normally (without debugger attached) - everything works as it should.
Is is normal situation when nginx runs under debugger? I run everything on Debian 8.5 # uname -a Linux ng18 3.16.0-4-amd64 #1 SMP Debian 3.16.7-ckt25-2 (2016-04-08) x86_64 GNU/Linux # nginx -V nginx version: nginx/1.10.1 built by gcc 4.9.2 (Debian 4.9.2-10) configure arguments: --with-debug My nginx.conf file: =========================== worker_processes 1; daemon on; master_process off; error_log /root/devel/ngx_module/url-rewrite-nginx-module/t/servroot/logs/error.log debug; pid /root/devel/ngx_module/url-rewrite-nginx-module/t/servroot/logs/nginx.pid; http { access_log /root/devel/ngx_module/url-rewrite-nginx-module/t/servroot/logs/access.log; default_type text/plain; keepalive_timeout 68; server { listen 1984; server_name 'localhost'; client_max_body_size 30M; default_type text/html; client_body_buffer_size 1; client_header_buffer_size 1; proxy_buffer_size 1; chunked_transfer_encoding off; location /t { root /root/devel/ngx_module/url-rewrite-nginx-module/t/servroot/html; } location / { root /root/devel/ngx_module/url-rewrite-nginx-module/t/servroot/html; index index.html index.htm; } } } events { accept_mutex off; worker_connections 64; } =========================== Debug log: =========================== 2016/06/27 12:24:28 [debug] 32736#0: bind() 0.0.0.0:1984 #6 2016/06/27 12:24:28 [notice] 32736#0: using the "epoll" event method 2016/06/27 12:24:28 [notice] 32736#0: nginx/1.10.1 2016/06/27 12:24:28 [notice] 32736#0: built by gcc 4.9.2 (Debian 4.9.2-10) 2016/06/27 12:24:28 [notice] 32736#0: OS: Linux 3.16.0-4-amd64 2016/06/27 12:24:28 [notice] 32736#0: getrlimit(RLIMIT_NOFILE): 65536:65536 2016/06/27 12:24:30 [notice] 32736#0: signal 1 (SIGHUP) received, reconfiguring 2016/06/27 12:24:30 [debug] 32743#0: write: 7, 00007FFFFFFFE060, 6, 0 2016/06/27 12:24:30 [debug] 32743#0: notify eventfd: 7 2016/06/27 12:24:30 [debug] 32743#0: malloc: 00000000006E3340:6144 2016/06/27 12:24:30 [debug] 32743#0: malloc: 00000000006DA310:13824 2016/06/27 12:24:30 [debug] 32743#0: malloc: 00000000006E4B50:6144 2016/06/27 12:24:30 [debug] 32743#0: malloc: 00000000006F5600:6144 2016/06/27 12:24:30 [debug] 32743#0: epoll add event: fd:6 op:1 ev:00002001 2016/06/27 12:24:30 [debug] 32743#0: worker cycle 2016/06/27 12:24:30 [debug] 32743#0: epoll timer: -1 2016/06/27 12:24:45 [debug] 32743#0: epoll: fd:6 ev:0001 d:00000000006DA310 2016/06/27 12:24:45 [debug] 32743#0: accept on 0.0.0.0:1984, ready: 0 2016/06/27 12:24:45 [debug] 32743#0: posix_memalign: 00000000006E6360:512 @16 2016/06/27 12:24:45 [debug] 32743#0: *1 accept: 127.0.0.1:34417 fd:8 2016/06/27 12:24:45 [debug] 32743#0: *1 event timer add: 8: 60000:1467019545151 2016/06/27 12:24:45 [debug] 32743#0: *1 reusable connection: 1 2016/06/27 12:24:45 [debug] 32743#0: *1 epoll add event: fd:8 op:1 ev:80002001 2016/06/27 12:24:45 [debug] 32743#0: timer delta: 16289 2016/06/27 12:24:45 [notice] 32743#0: reconfiguring 2016/06/27 12:24:45 [debug] 32743#0: posix_memalign: 00000000006F6E10:16384 @16 2016/06/27 12:24:45 [debug] 32743#0: posix_memalign: 00000000006FAE20:16384 @16 2016/06/27 12:24:45 [debug] 32743#0: malloc: 00000000006FEE30:4096 2016/06/27 12:24:45 [debug] 32743#0: read: 9, 00000000006FEE30, 985, 0 2016/06/27 12:24:45 [debug] 32743#0: malloc: 00000000006FFE40:4280 2016/06/27 12:24:45 [debug] 32743#0: malloc: 0000000000700F00:4280 2016/06/27 12:24:45 [debug] 32743#0: malloc: 0000000000701FC0:4280 2016/06/27 12:24:45 [debug] 32743#0: malloc: 0000000000703080:4280 2016/06/27 12:24:45 [debug] 32743#0: malloc: 0000000000704140:4280 2016/06/27 12:24:45 [debug] 32743#0: malloc: 0000000000705200:4280 2016/06/27 12:24:45 [debug] 32743#0: posix_memalign: 00000000007062C0:16384 @16 2016/06/27 12:24:45 [debug] 32743#0: malloc: 000000000070A2D0:4096 2016/06/27 12:24:45 [debug] 32743#0: posix_memalign: 000000000070B2E0:16384 @16 2016/06/27 12:24:45 [debug] 32743#0: malloc: 00000000006DD920:2048 2016/06/27 12:24:45 [debug] 32743#0: add cleanup: 000000000070E000 2016/06/27 12:24:45 [debug] 32743#0: malloc: 00000000006D5730:408 2016/06/27 12:24:45 [debug] 32743#0: malloc: 00000000006D58D0:96 2016/06/27 12:24:45 [debug] 32743#0: malloc: 00000000006DD920:1024 2016/06/27 12:24:45 [debug] 32743#0: malloc: 00000000006DD920:1024 2016/06/27 12:24:45 [debug] 32743#0: malloc: 00000000006DD920:1024 2016/06/27 12:24:45 [debug] 32743#0: malloc: 00000000006DD920:1024 2016/06/27 12:24:45 [debug] 32743#0: posix_memalign: 000000000070F2F0:16384 @16 2016/06/27 12:24:45 [debug] 32743#0: malloc: 00000000006DD920:1024 2016/06/27 12:24:45 [debug] 32743#0: malloc: 00000000006DD920:1024 2016/06/27 12:24:45 [debug] 32743#0: malloc: 0000000000713300:4096 2016/06/27 12:24:45 [debug] 32743#0: malloc: 00000000006DD920:2048 2016/06/27 12:24:45 [debug] 32743#0: malloc: 0000000000713300:4096 2016/06/27 12:24:45 [debug] 32743#0: malloc: 0000000000713300:4096 2016/06/27 12:24:45 [debug] 32743#0: malloc: 00000000006DD920:1024 2016/06/27 12:24:45 [debug] 32743#0: malloc: 00000000006DD920:2048 2016/06/27 12:24:45 [debug] 32743#0: malloc: 0000000000713300:4160 2016/06/27 12:24:45 [debug] 32743#0: malloc: 00000000006D5940:376 2016/06/27 12:24:45 [debug] 32743#0: log: 00000000006F7190 9 "/root/devel/ngx_module/url-rewrite-nginx-module/t/servroot/logs/error.log" 2016/06/27 12:24:45 [debug] 32743#0: log: 00000000006F71B8 10 "/root/devel/ngx_module/url-rewrite-nginx-module/t/servroot/logs/access.log" 2016/06/27 12:24:45 [notice] 32743#0: using the "epoll" event method 2016/06/27 12:24:45 [debug] 32743#0: posix_memalign: 00000000006D5940:128 @16 2016/06/27 12:24:45 [debug] 32743#0: malloc: 00000000006D59D0:80 2016/06/27 12:24:45 [debug] 32743#0: event timer add: -1: 30000:1467019515151 2016/06/27 12:24:45 [debug] 32743#0: worker cycle 2016/06/27 12:24:45 [debug] 32743#0: epoll timer: 30000 2016/06/27 12:24:45 [debug] 32743#0: epoll: fd:8 ev:0001 d:00000000006DA3E8 2016/06/27 12:24:45 [debug] 32743#0: timer delta: 1 2016/06/27 12:24:45 [debug] 32743#0: posted event 00000000006E4BB0 2016/06/27 12:24:45 [debug] 32743#0: worker cycle 2016/06/27 12:24:45 [debug] 32743#0: epoll timer: 29999 2016/06/27 12:24:47 [debug] 32743#0: epoll: fd:6 ev:0001 d:00000000006DA310 2016/06/27 12:24:47 [debug] 32743#0: timer delta: 2054 2016/06/27 12:24:47 [debug] 32743#0: worker cycle 2016/06/27 12:24:47 [debug] 32743#0: epoll timer: 27945 2016/06/27 12:24:47 [debug] 32743#0: epoll: fd:4 ev:0001 d:00000000006DA3E9 2016/06/27 12:24:47 [debug] 32743#0: timer delta: 0 2016/06/27 12:24:47 [debug] 32743#0: posted event 00000000006E4BB0 2016/06/27 12:24:47 [debug] 32743#0: worker cycle 2016/06/27 12:24:47 [debug] 32743#0: epoll timer: 27945 2016/06/27 12:25:15 [debug] 32743#0: timer delta: 27974 2016/06/27 12:25:15 [debug] 32743#0: event timer del: -1: 1467019515151 2016/06/27 12:25:15 [debug] 32743#0: clean old cycles 2016/06/27 12:25:15 [debug] 32743#0: live fd:0 2016/06/27 12:25:15 [debug] 32743#0: old cycles status: 1 2016/06/27 12:25:15 [debug] 32743#0: event timer add: -1: 30000:1467019545180 2016/06/27 12:25:15 [debug] 32743#0: worker cycle 2016/06/27 12:25:15 [debug] 32743#0: epoll timer: 30000 2016/06/27 12:25:44 [debug] 32743#0: epoll: fd:4 ev:2001 d:00000000006DA3E9 =========================== Conversation: =========================== # curl -v -t 1 http://localhost:1984/t/zero.html * Hostname was NOT found in DNS cache * Trying ::1... * connect to ::1 port 1984 failed: Connection refused * Trying 127.0.0.1... * Connected to localhost (127.0.0.1) port 1984 (#0) > GET /t/zero.html HTTP/1.1 > User-Agent: curl/7.38.0 > Host: localhost:1984 > Accept: */* > < HTTP/1.1 200 OK * Server nginx/1.10.1 is not blacklisted < Server: nginx/1.10.1 < Date: Mon, 27 Jun 2016 09:24:45 GMT < Content-Type: text/html < Content-Length: 0 < Last-Modified: Mon, 27 Jun 2016 08:41:59 GMT < Connection: keep-alive < ETag: "5770e6d7-0" < Accept-Ranges: bytes < * Connection #0 to host localhost left intact # curl -v -t 1 http://localhost:1984/t/zero.html * Hostname was NOT found in DNS cache * Trying ::1... * connect to ::1 port 1984 failed: Connection refused * Trying 127.0.0.1... * Connected to localhost (127.0.0.1) port 1984 (#0) > GET /t/zero.html HTTP/1.1 > User-Agent: curl/7.38.0 > Host: localhost:1984 > Accept: */* > 2016/06/27 12:24:47 [debug] 32743#0: posix_memalign: 00000000006E6360:512 @16 2016/06/27 12:24:47 [debug] 32743#0: *2 accept: 127.0.0.1:34419 fd:4 2016/06/27 12:24:47 [debug] 32743#0: *2 event timer add: 4: 60000:1467019547206 2016/06/27 12:24:47 [debug] 32743#0: *2 reusable connection: 1 2016/06/27 12:24:47 [debug] 32743#0: *2 epoll add event: fd:4 op:1 ev:80002001 2016/06/27 12:24:47 [debug] 32743#0: *2 http wait request handler 2016/06/27 12:24:47 [debug] 32743#0: *2 recv: fd:4 1 of 1 2016/06/27 12:24:47 [debug] 32743#0: *2 reusable connection: 0 2016/06/27 12:24:47 [debug] 32743#0: *2 posix_memalign: 00000000006FAE20:4096 @16 2016/06/27 12:24:47 [debug] 32743#0: *2 http process request line 2016/06/27 12:24:47 [debug] 32743#0: *2 http alloc large header buffer 2016/06/27 12:24:47 [debug] 32743#0: *2 malloc: 00000000006FBE30:8192 2016/06/27 12:24:47 [debug] 32743#0: *2 http large header alloc: 00000000006FBE30 8192 2016/06/27 12:24:47 [debug] 32743#0: *2 http large header copy: 1 2016/06/27 12:24:47 [debug] 32743#0: *2 recv: fd:4 88 of 8191 2016/06/27 12:24:47 [debug] 32743#0: *2 http request line: "GET /t/zero.html HTTP/1.1" 2016/06/27 12:24:47 [debug] 32743#0: *2 http uri: "/t/zero.html" 2016/06/27 12:24:47 [debug] 32743#0: *2 http args: "" 2016/06/27 12:24:47 [debug] 32743#0: *2 http exten: "html" 2016/06/27 12:24:47 [debug] 32743#0: *2 http process request header line 2016/06/27 12:24:47 [debug] 32743#0: *2 http header: "User-Agent: curl/7.38.0" 2016/06/27 12:24:47 [debug] 32743#0: *2 http header: "Host: localhost:1984" 2016/06/27 12:24:47 [debug] 32743#0: *2 http header: "Accept: */*" 2016/06/27 12:24:47 [debug] 32743#0: *2 http header done 2016/06/27 12:24:47 [debug] 32743#0: *2 event timer del: 4: 1467019547206 2016/06/27 12:24:47 [debug] 32743#0: *2 rewrite phase: 0 2016/06/27 12:24:47 [debug] 32743#0: *2 test location: "/" 2016/06/27 12:24:47 [debug] 32743#0: *2 test location: "t" 2016/06/27 12:24:47 [debug] 32743#0: *2 using configuration "/t" 2016/06/27 12:24:47 [debug] 32743#0: *2 http cl:-1 max:31457280 2016/06/27 12:24:47 [debug] 32743#0: *2 rewrite phase: 2 2016/06/27 12:24:47 [debug] 32743#0: *2 post rewrite phase: 3 2016/06/27 12:24:47 [debug] 32743#0: *2 generic phase: 4 2016/06/27 12:24:47 [debug] 32743#0: *2 generic phase: 5 2016/06/27 12:24:47 [debug] 32743#0: *2 access phase: 6 2016/06/27 12:24:47 [debug] 32743#0: *2 access phase: 7 2016/06/27 12:24:47 [debug] 32743#0: *2 post access phase: 8 2016/06/27 12:24:47 [debug] 32743#0: *2 content phase: 9 2016/06/27 12:24:47 [debug] 32743#0: *2 content phase: 10 2016/06/27 12:24:47 [debug] 32743#0: *2 content phase: 11 2016/06/27 12:24:47 [debug] 32743#0: *2 http filename: "/root/devel/ngx_module/url-rewrite-nginx-module/t/servroot/html/t/zero.html" 2016/06/27 12:24:47 [debug] 32743#0: *2 add cleanup: 00000000006FBD48 2016/06/27 12:24:47 [debug] 32743#0: *2 http static fd: 5 2016/06/27 12:24:47 [debug] 32743#0: *2 http set discard body 2016/06/27 12:24:47 [debug] 32743#0: *2 posix_memalign: 00000000006FDE40:4096 @16 2016/06/27 12:24:47 [debug] 32743#0: *2 HTTP/1.1 200 OK Server: nginx/1.10.1 Date: Mon, 27 Jun 2016 09:24:47 GMT Content-Type: text/html Content-Length: 0 Last-Modified: Mon, 27 Jun 2016 08:41:59 GMT Connection: keep-alive ETag: "5770e6d7-0" Accept-Ranges: bytes 2016/06/27 12:24:47 [debug] 32743#0: *2 write new buf t:1 f:0 00000000006FDF78, pos 00000000006FDF78, size: 234 file: 0, size: 0 2016/06/27 12:24:47 [debug] 32743#0: *2 http write filter: l:0 f:0 s:234 2016/06/27 12:24:47 [debug] 32743#0: *2 http output filter "/t/zero.html?" 2016/06/27 12:24:47 [debug] 32743#0: *2 http copy filter: "/t/zero.html?" 2016/06/27 12:24:47 [debug] 32743#0: *2 http postpone filter "/t/zero.html?" 00007FFFFFFFDF20 2016/06/27 12:24:47 [debug] 32743#0: *2 write old buf t:1 f:0 00000000006FDF78, pos 00000000006FDF78, size: 234 file: 0, size: 0 2016/06/27 12:24:47 [debug] 32743#0: *2 write new buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0 2016/06/27 12:24:47 [debug] 32743#0: *2 http write filter: l:1 f:0 s:234 2016/06/27 12:24:47 [debug] 32743#0: *2 http write filter limit 0 HTTP/1.1 200 OK Server: nginx/1.10.1 Date: Mon, 27 Jun 2016 09:24:47 GMT Content-Type: text/html Content-Length: 0 Last-Modified: Mon, 27 Jun 2016 08:41:59 GMT Connection: keep-alive ETag: "5770e6d7-0" Accept-Ranges: bytes 2016/06/27 12:24:47 [debug] 32743#0: *2 writev: 234 of 234 2016/06/27 12:24:47 [debug] 32743#0: *2 http write filter 0000000000000000 2016/06/27 12:24:47 [debug] 32743#0: *2 http copy filter: 0 "/t/zero.html?" 2016/06/27 12:24:47 [debug] 32743#0: *2 http finalize request: 0, "/t/zero.html?" a:1, c:1 2016/06/27 12:24:47 [debug] 32743#0: *2 set http keepalive handler 2016/06/27 12:24:47 [debug] 32743#0: *2 http close request 2016/06/27 12:24:47 [debug] 32743#0: *2 http log handler 2016/06/27 12:24:47 [debug] 32743#0: *2 run cleanup: 00000000006FBD48 2016/06/27 12:24:47 [debug] 32743#0: *2 file cleanup: fd:5 2016/06/27 12:24:47 [debug] 32743#0: *2 free: 00000000006FAE20, unused: 8 2016/06/27 12:24:47 [debug] 32743#0: *2 free: 00000000006FDE40, unused: 3293 2016/06/27 12:24:47 [debug] 32743#0: *2 hc free: 0000000000000000 0 2016/06/27 12:24:47 [debug] 32743#0: *2 hc busy: 00000000006E64C8 1 2016/06/27 12:24:47 [debug] 32743#0: *2 free: 00000000006FBE30 2016/06/27 12:24:47 [debug] 32743#0: *2 tcp_nodelay 2016/06/27 12:24:47 [debug] 32743#0: *2 reusable connection: 1 2016/06/27 12:24:47 [debug] 32743#0: *2 event timer add: 4: 68000:1467019555206 2016/06/27 12:24:47 [debug] 32743#0: *2 post event 00000000006E4BB0 2016/06/27 12:24:47 [debug] 32743#0: *2 delete posted event 00000000006E4BB0 2016/06/27 12:24:47 [debug] 32743#0: *2 http keepalive handler 2016/06/27 12:24:47 [debug] 32743#0: *2 recv: fd:4 -1 of 1 2016/06/27 12:24:47 [debug] 32743#0: *2 recv() not ready (11: Resource temporarily unavailable) =========================== /t/zero.html is essentially empty file under /root/devel/ngx_module/url-rewrite-nginx-module/t/servroot/html/t/zero.html Traffic capture (attached) looks like this: =========================== GET /t/zero.html HTTP/1.1 User-Agent: curl/7.38.0 Host: localhost:1984 Accept: */* 2016/06/27 11:50:46 [debug] 27659#0: posix_memalign: 00000000006E6360:512 @16 2016/06/27 11:50:46 [debug] 27659#0: *2 accept: 127.0.0.1:34397 fd:4 2016/06/27 11:50:46 [debug] 27659#0: *2 event timer add: 4: 60000:1467017506450 2016/06/27 11:50:46 [debug] 27659#0: *2 reusable connection: 1 2016/06/27 11:50:46 [debug] 27659#0: *2 epoll add event: fd:4 op:1 ev:80002001 2016/06/27 11:50:46 [debug] 27659#0: *2 http wait request handler ......... =========================== I.e. no headers sent. Will be grateful for any information about this issue. If it it not a bug but feature - is there a way to disable this behavior?
debug_log_in_reply.pcap
Description: Binary data
_______________________________________________ nginx-devel mailing list nginx-devel@nginx.org http://mailman.nginx.org/mailman/listinfo/nginx-devel