Ticket #801: debuglog.txt

File debuglog.txt, 9.9 KB (added by Florin Asăvoaie, 11 years ago)
Line 
12015/09/29 12:13:21 [debug] 8892#0: *4 http cl:686 max:26214400
22015/09/29 12:13:21 [debug] 8892#0: *4 rewrite phase: 3
32015/09/29 12:13:21 [debug] 8892#0: *4 http client request body preread 486
42015/09/29 12:13:21 [debug] 8892#0: *4 http request body content length filter
52015/09/29 12:13:21 [debug] 8892#0: *4 http body new buf t:1 f:0 0000000001EF9D0A, pos 0000000001EF9D0A, size: 486 file: 0, size: 0
62015/09/29 12:13:21 [debug] 8892#0: *4 http read client request body
72015/09/29 12:13:21 [debug] 8892#0: *4 SSL_read: 200
82015/09/29 12:13:21 [debug] 8892#0: *4 http client request body recv 200
92015/09/29 12:13:21 [debug] 8892#0: *4 http body old buf t:1 f:0 0000000001EF9D0A, pos 0000000001EF9D0A, size: 486 file: 0, size: 0
102015/09/29 12:13:21 [debug] 8892#0: *4 http body new buf t:1 f:0 0000000001EFAD90, pos 0000000001EFAD90, size: 200 file: 0, size: 0
112015/09/29 12:13:21 [debug] 8892#0: *4 http client request body rest 0
122015/09/29 12:13:21 [debug] 8892#0: *4 rewrite phase: 4
132015/09/29 12:13:21 [debug] 8892#0: *4 post rewrite phase: 5
142015/09/29 12:13:21 [debug] 8892#0: *4 generic phase: 6
152015/09/29 12:13:21 [debug] 8892#0: *4 generic phase: 7
162015/09/29 12:13:21 [debug] 8892#0: *4 generic phase: 8
172015/09/29 12:13:21 [debug] 8892#0: *4 access phase: 9
182015/09/29 12:13:21 [debug] 8892#0: *4 access: 040A160A 00000000 00000000
192015/09/29 12:13:21 [debug] 8892#0: *4 access phase: 10
202015/09/29 12:13:21 [debug] 8892#0: *4 access phase: 11
212015/09/29 12:13:21 [debug] 8892#0: *4 auth request handler
222015/09/29 12:13:21 [debug] 8892#0: *4 posix_memalign: 0000000001EFBBB0:4096 @16
232015/09/29 12:13:21 [debug] 8892#0: *4 http subrequest "/auth?"
242015/09/29 12:13:21 [debug] 8892#0: *4 http posted request: "/auth?"
252015/09/29 12:13:21 [debug] 8892#0: *4 rewrite phase: 1
262015/09/29 12:13:21 [debug] 8892#0: *4 test location: "/permission-denied"
272015/09/29 12:13:21 [debug] 8892#0: *4 test location: "/auth"
282015/09/29 12:13:21 [debug] 8892#0: *4 using configuration "=/auth"
292015/09/29 12:13:21 [debug] 8892#0: *4 http cl:686 max:26214400
302015/09/29 12:13:21 [debug] 8892#0: *4 rewrite phase: 3
312015/09/29 12:13:21 [debug] 8892#0: *4 rewrite phase: 4
322015/09/29 12:13:21 [debug] 8892#0: *4 http script var
332015/09/29 12:13:21 [debug] 8892#0: *4 http script if
342015/09/29 12:13:21 [debug] 8892#0: *4 http script if: false
352015/09/29 12:13:21 [debug] 8892#0: *4 http script var
362015/09/29 12:13:21 [debug] 8892#0: *4 http script var: "Token RANDOMSESSIONID"
372015/09/29 12:13:21 [debug] 8892#0: *4 http script if
382015/09/29 12:13:21 [debug] 8892#0: *4 http script complex value
392015/09/29 12:13:21 [debug] 8892#0: *4 http script var: "Token RANDOMSESSIONID"
402015/09/29 12:13:21 [debug] 8892#0: *4 http script set $app_auth
412015/09/29 12:13:21 [debug] 8892#0: *4 post rewrite phase: 5
422015/09/29 12:13:21 [debug] 8892#0: *4 generic phase: 6
432015/09/29 12:13:21 [debug] 8892#0: *4 generic phase: 7
442015/09/29 12:13:21 [debug] 8892#0: *4 generic phase: 8
452015/09/29 12:13:21 [debug] 8892#0: *4 try files phase: 13
462015/09/29 12:13:21 [debug] 8892#0: *4 http init upstream, client timer: 0
472015/09/29 12:13:21 [debug] 8892#0: *4 epoll add event: fd:147 op:3 ev:80002005
482015/09/29 12:13:21 [debug] 8892#0: *4 http script var: "127.0.0.1"
492015/09/29 12:13:21 [debug] 8892#0: *4 http script var: "mylocalhostname"
502015/09/29 12:13:21 [debug] 8892#0: *4 http script var: "Token RANDOMSESSIONID"
512015/09/29 12:13:21 [debug] 8892#0: *4 http cache key: "127.0.0.1mylocalhostnameToken RANDOMSESSIONID"
522015/09/29 12:13:21 [debug] 8892#0: *4 add cleanup: 0000000001EFC6F8
532015/09/29 12:13:21 [debug] 8892#0: *4 http file cache exists: -5 e:0
542015/09/29 12:13:21 [debug] 8892#0: *4 cache file: "/var/cache/nginx/proxyCacheAuth/RANDOMCACHEFILENAME"
552015/09/29 12:13:21 [debug] 8892#0: *4 add cleanup: 0000000001EFC758
562015/09/29 12:13:21 [debug] 8892#0: *4 http upstream cache: -5
572015/09/29 12:13:21 [debug] 8892#0: *4 http script copy: "Authorize: "
582015/09/29 12:13:21 [debug] 8892#0: *4 http script var: "Token RANDOMSESSIONID"
592015/09/29 12:13:21 [debug] 8892#0: *4 http script copy: "
60"
612015/09/29 12:13:21 [debug] 8892#0: *4 http script copy: "Host: "
622015/09/29 12:13:21 [debug] 8892#0: *4 http script var: "mylocalhostname"
632015/09/29 12:13:21 [debug] 8892#0: *4 http script copy: "
64"
652015/09/29 12:13:21 [debug] 8892#0: *4 http script copy: "Connection: close
66"
672015/09/29 12:13:21 [debug] 8892#0: *4 http script copy: ""
682015/09/29 12:13:21 [debug] 8892#0: *4 http script copy: ""
692015/09/29 12:13:21 [debug] 8892#0: *4 http script copy: ""
702015/09/29 12:13:21 [debug] 8892#0: *4 http script copy: ""
712015/09/29 12:13:21 [debug] 8892#0: *4 http script copy: ""
722015/09/29 12:13:21 [debug] 8892#0: *4 http script copy: ""
732015/09/29 12:13:21 [debug] 8892#0: *4 http proxy header:
74"GET /random/url HTTP/1.1
75Authorize: Token RANDOMSESSIONID
76Host: mylocalhostname
77Connection: close
78
79"
802015/09/29 12:13:21 [debug] 8892#0: *4 http cleanup add: 0000000001EFC920
812015/09/29 12:13:21 [debug] 8892#0: *4 get rr peer, try: 2
822015/09/29 12:13:21 [debug] 8892#0: *4 get rr peer, current: 0 -1
832015/09/29 12:13:21 [debug] 8892#0: *4 socket 148
842015/09/29 12:13:21 [debug] 8892#0: *4 epoll add connection: fd:148 ev:80002005
852015/09/29 12:13:21 [debug] 8892#0: *4 connect to 127.0.0.1:8080, fd:148 #5
862015/09/29 12:13:21 [debug] 8892#0: *4 http upstream connect: -2
872015/09/29 12:13:21 [debug] 8892#0: *4 posix_memalign: 0000000001A5A8D0:128 @16
882015/09/29 12:13:21 [debug] 8892#0: *4 event timer add: 148: 60000:1443521661601
892015/09/29 12:13:21 [debug] 8892#0: *4 http finalize request: -4, "/auth?" a:1, c:3
902015/09/29 12:13:21 [debug] 8892#0: *4 http request count:3 blk:0
912015/09/29 12:13:21 [debug] 8892#0: *4 http run request: "/auth?"
922015/09/29 12:13:21 [debug] 8892#0: *4 http upstream check client, write event:1, "/auth"
932015/09/29 12:13:21 [debug] 8892#0: *4 http upstream recv(): -1 (11: Resource temporarily unavailable)
942015/09/29 12:13:21 [debug] 8892#0: *4 http upstream request: "/auth?"
952015/09/29 12:13:21 [debug] 8892#0: *4 http upstream send request handler
962015/09/29 12:13:21 [debug] 8892#0: *4 http upstream send request
972015/09/29 12:13:21 [debug] 8892#0: *4 http upstream send request body
982015/09/29 12:13:21 [debug] 8892#0: *4 chain writer buf fl:1 s:156
992015/09/29 12:13:21 [debug] 8892#0: *4 chain writer in: 0000000001EFC958
1002015/09/29 12:13:21 [debug] 8892#0: *4 writev: 156 of 156
1012015/09/29 12:13:21 [debug] 8892#0: *4 chain writer out: 0000000000000000
1022015/09/29 12:13:21 [debug] 8892#0: *4 event timer del: 148: 1443521661601
1032015/09/29 12:13:21 [debug] 8892#0: *4 event timer add: 148: 60000:1443521661602
1042015/09/29 12:13:21 [debug] 8892#0: *4 http upstream request: "/auth?"
1052015/09/29 12:13:21 [debug] 8892#0: *4 http upstream process header
1062015/09/29 12:13:21 [debug] 8892#0: *4 malloc: 0000000001F01410:4096
1072015/09/29 12:13:21 [debug] 8892#0: *4 recv: fd:148 131 of 3871
1082015/09/29 12:13:21 [debug] 8892#0: *4 http proxy status 401 "401 Unauthorized"
1092015/09/29 12:13:21 [debug] 8892#0: *4 http proxy header: "Server: XXX"
1102015/09/29 12:13:21 [debug] 8892#0: *4 http proxy header: "Date: Tue, 29 Sep 2015 10:13:21 GMT"
1112015/09/29 12:13:21 [debug] 8892#0: *4 http proxy header: "Content-Length: 0"
1122015/09/29 12:13:21 [debug] 8892#0: *4 http proxy header: "Connection: close"
1132015/09/29 12:13:21 [debug] 8892#0: *4 http proxy header done
1142015/09/29 12:13:21 [debug] 8892#0: *4 http file cache set header
1152015/09/29 12:13:21 [debug] 8892#0: *4 http cacheable: 1
1162015/09/29 12:13:21 [debug] 8892#0: *4 posix_memalign: 0000000001F02420:4096 @16
1172015/09/29 12:13:21 [debug] 8892#0: *4 http proxy filter init s:401 h:0 c:0 l:0
1182015/09/29 12:13:21 [debug] 8892#0: *4 http upstream process upstream
1192015/09/29 12:13:21 [debug] 8892#0: *4 pipe read upstream: 1
1202015/09/29 12:13:21 [debug] 8892#0: *4 pipe preread: 0
1212015/09/29 12:13:21 [debug] 8892#0: *4 readv: 1, last:3740
1222015/09/29 12:13:21 [debug] 8892#0: *4 pipe recv chain: 0
1232015/09/29 12:13:21 [debug] 8892#0: *4 pipe buf free s:0 t:1 f:0 0000000001F01410, pos 0000000001F01574, size: 0 file: 0, size: 0
1242015/09/29 12:13:21 [debug] 8892#0: *4 pipe length: 0
1252015/09/29 12:13:21 [debug] 8892#0: *4 pipe write chain
1262015/09/29 12:13:21 [debug] 8892#0: *4 add cleanup: 0000000001EFCB88
1272015/09/29 12:13:21 [debug] 8892#0: *4 hashed path: /var/cache/nginx/proxy_temp/1/00/0000000001
1282015/09/29 12:13:21 [debug] 8892#0: *4 temp fd:149
1292015/09/29 12:13:21 [debug] 8892#0: *4 write: 149, 0000000001F01410, 356, 0
1302015/09/29 12:13:21 [debug] 8892#0: *4 pipe write downstream: 1
1312015/09/29 12:13:21 [debug] 8892#0: *4 event timer del: 148: 1443521661602
1322015/09/29 12:13:21 [debug] 8892#0: *4 http file cache update
1332015/09/29 12:13:21 [debug] 8892#0: *4 http file cache rename: "/var/cache/nginx/proxy_temp/1/00/0000000001" to "/var/cache/nginx/proxyCacheAuth/RANDOMCACHEFILENAME"
1342015/09/29 12:13:21 [debug] 8892#0: *4 http upstream exit: 0000000000000000
1352015/09/29 12:13:21 [debug] 8892#0: *4 finalize http upstream request: 0
1362015/09/29 12:13:21 [debug] 8892#0: *4 finalize http proxy request
1372015/09/29 12:13:21 [debug] 8892#0: *4 free rr peer 2 0
1382015/09/29 12:13:21 [debug] 8892#0: *4 close http upstream connection: 148
1392015/09/29 12:13:21 [debug] 8892#0: *4 free: 0000000001A5A8D0, unused: 48
1402015/09/29 12:13:21 [debug] 8892#0: *4 reusable connection: 0
1412015/09/29 12:13:21 [debug] 8892#0: *4 http upstream temp fd: 149
1422015/09/29 12:13:21 [debug] 8892#0: *4 http finalize request: 0, "/auth?" a:1, c:2
1432015/09/29 12:13:21 [debug] 8892#0: *4 auth request done s:401
1442015/09/29 12:13:21 [debug] 8892#0: *4 http wake parent request: "/myapp?"
1452015/09/29 12:13:21 [debug] 8892#0: *4 http posted request: "/myapp?"
1462015/09/29 12:13:21 [debug] 8892#0: *4 http request empty handler
1472015/09/29 12:13:25 [debug] 8892#0: *4 http run request: "/myapp?"
1482015/09/29 12:13:25 [debug] 8892#0: *4 http reading blocked
1492015/09/29 12:13:25 [debug] 8892#0: *4 http run request: "/myapp?"
1502015/09/29 12:13:25 [debug] 8892#0: *4 http request empty handler