Part of debug log in reply instead of reply if nginx runs under debugger.
Andrey Kulikov
amdeich at gmail.com
Mon Jun 27 09:30:19 UTC 2016
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?
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.nginx.org/pipermail/nginx-devel/attachments/20160627/e6773c15/attachment.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: debug_log_in_reply.pcap
Type: application/octet-stream
Size: 13468 bytes
Desc: not available
URL: <http://mailman.nginx.org/pipermail/nginx-devel/attachments/20160627/e6773c15/attachment.obj>
More information about the nginx-devel
mailing list