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