Ticket #2163: debug_499_error_log.txt

File debug_499_error_log.txt, 15.1 KB (added by vijaysridhar03@…, 5 years ago)
Line 
12021/04/13 13:30:38 [debug] 6938#0: accept on 0.0.0.0:9876, ready: 0
22021/04/13 13:30:38 [debug] 6938#0: posix_memalign: 0000556C850BB8D0:512 @16
32021/04/13 13:30:38 [debug] 6938#0: *64939 accept: 192.168.200.9:58032 fd:26
42021/04/13 13:30:38 [debug] 6938#0: *64939 event timer add: 26: 60000:4129392299
52021/04/13 13:30:38 [debug] 6938#0: *64939 reusable connection: 1
62021/04/13 13:30:38 [debug] 6938#0: *64939 epoll add event: fd:26 op:1 ev:80002001
72021/04/13 13:30:38 [debug] 6938#0: timer delta: 1782
82021/04/13 13:30:38 [debug] 6938#0: worker cycle
92021/04/13 13:30:38 [debug] 6938#0: epoll timer: 3647
102021/04/13 13:30:38 [debug] 6938#0: epoll: fd:26 ev:0001 d:00007F723E376871
112021/04/13 13:30:38 [debug] 6938#0: *64939 http wait request handler
122021/04/13 13:30:38 [debug] 6938#0: *64939 malloc: 0000556C85041AE0:1024
132021/04/13 13:30:38 [debug] 6938#0: *64939 recv: eof:0, avail:1
142021/04/13 13:30:38 [debug] 6938#0: *64939 recv: fd:26 1024 of 1024
152021/04/13 13:30:38 [debug] 6938#0: *64939 reusable connection: 0
162021/04/13 13:30:38 [debug] 6938#0: *64939 posix_memalign: 0000556C850B9B20:4096 @16
172021/04/13 13:30:38 [debug] 6938#0: *64939 http process request line
182021/04/13 13:30:38 [debug] 6938#0: *64939 http request line: "POST / HTTP/1.1"
192021/04/13 13:30:38 [debug] 6938#0: *64939 http uri: "/"
202021/04/13 13:30:38 [debug] 6938#0: *64939 http args: ""
212021/04/13 13:30:38 [debug] 6938#0: *64939 http exten: ""
222021/04/13 13:30:38 [debug] 6938#0: *64939 posix_memalign: 0000556C850B29F0:4096 @16
232021/04/13 13:30:38 [debug] 6938#0: *64939 http process request header line
242021/04/13 13:30:38 [debug] 6938#0: *64939 http header: "Content-Type: application/json"
252021/04/13 13:30:38 [debug] 6938#0: *64939 http header: "Authorization: Basic aHJ1zXVsE7SerT2we3512SCDEdrpsjP2qadrfbgTRESsjieAQ1LmnQWDxsFGY=="
262021/04/13 13:30:38 [debug] 6938#0: *64939 http header: "User-Agent: Java/1.8.0_191"
272021/04/13 13:30:38 [debug] 6938#0: *64939 http header: "Host: 192.168.100.123:9876"
282021/04/13 13:30:38 [debug] 6938#0: *64939 http header: "Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2"
292021/04/13 13:30:38 [debug] 6938#0: *64939 http header: "Connection: keep-alive"
302021/04/13 13:30:38 [debug] 6938#0: *64939 http header: "Content-Length: 4139"
312021/04/13 13:30:38 [debug] 6938#0: *64939 http header done
322021/04/13 13:30:38 [debug] 6938#0: *64939 event timer del: 26: 4129392299
332021/04/13 13:30:38 [debug] 6938#0: *64939 generic phase: 0
342021/04/13 13:30:38 [debug] 6938#0: *64939 rewrite phase: 1
352021/04/13 13:30:38 [debug] 6938#0: *64939 test location: "/"
362021/04/13 13:30:38 [debug] 6938#0: *64939 using configuration "/"
372021/04/13 13:30:38 [debug] 6938#0: *64939 http cl:4139 max:26214400
382021/04/13 13:30:38 [debug] 6938#0: *64939 rewrite phase: 3
392021/04/13 13:30:38 [debug] 6938#0: *64939 post rewrite phase: 4
402021/04/13 13:30:38 [debug] 6938#0: *64939 generic phase: 5
412021/04/13 13:30:38 [debug] 6938#0: *64939 generic phase: 6
422021/04/13 13:30:38 [debug] 6938#0: *64939 generic phase: 7
432021/04/13 13:30:38 [debug] 6938#0: *64939 generic phase: 8
442021/04/13 13:30:38 [debug] 6938#0: *64939 access phase: 9
452021/04/13 13:30:38 [debug] 6938#0: *64939 access phase: 10
462021/04/13 13:30:38 [debug] 6938#0: *64939 access phase: 11
472021/04/13 13:30:38 [debug] 6938#0: *64939 post access phase: 12
482021/04/13 13:30:38 [debug] 6938#0: *64939 generic phase: 13
492021/04/13 13:30:38 [debug] 6938#0: *64939 generic phase: 14
502021/04/13 13:30:38 [debug] 6938#0: *64939 http client request body preread 600
512021/04/13 13:30:38 [debug] 6938#0: *64939 http request body content length filter
522021/04/13 13:30:38 [debug] 6938#0: *64939 http body new buf t:1 f:0 0000556C85041C88, pos 0000556C85041C88, size: 600 file: 0, size: 0
532021/04/13 13:30:38 [debug] 6938#0: *64939 posix_memalign: 0000556C850B3A00:4096 @16
542021/04/13 13:30:38 [debug] 6938#0: *64939 http read client request body
552021/04/13 13:30:38 [debug] 6938#0: *64939 recv: eof:0, avail:1
562021/04/13 13:30:38 [debug] 6938#0: *64939 recv: fd:26 3539 of 3539
572021/04/13 13:30:38 [debug] 6938#0: *64939 http client request body recv 3539
582021/04/13 13:30:38 [debug] 6938#0: *64939 http body new buf t:1 f:0 0000556C850B3A20, pos 0000556C850B3A20, size: 3539 file: 0, size: 0
592021/04/13 13:30:38 [debug] 6938#0: *64939 http client request body rest 0
602021/04/13 13:30:38 [debug] 6938#0: *64939 http init upstream, client timer: 0
612021/04/13 13:30:38 [debug] 6938#0: *64939 epoll add event: fd:26 op:3 ev:80002005
622021/04/13 13:30:38 [debug] 6938#0: *64939 http script copy: "Host"
632021/04/13 13:30:38 [debug] 6938#0: *64939 http script var: "mysite.api.prod.vijay.com"
642021/04/13 13:30:38 [debug] 6938#0: *64939 http script copy: "Connection"
652021/04/13 13:30:38 [debug] 6938#0: *64939 http script copy: "close"
662021/04/13 13:30:38 [debug] 6938#0: *64939 http script copy: "Content-Length"
672021/04/13 13:30:38 [debug] 6938#0: *64939 http script var: "4139"
682021/04/13 13:30:38 [debug] 6938#0: *64939 http script copy: ""
692021/04/13 13:30:38 [debug] 6938#0: *64939 http proxy header: "Content-Type: application/json"
702021/04/13 13:30:38 [debug] 6938#0: *64939 http proxy header: "Authorization: Basic aHJ1zXVsE7SerT2we3512SCDEdrpsjP2qadrfbgTRESsjieAQ1LmnQWDxsFGY=="
712021/04/13 13:30:38 [debug] 6938#0: *64939 http proxy header: "User-Agent: Java/1.8.0_191"
722021/04/13 13:30:38 [debug] 6938#0: *64939 http proxy header: "Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2"
732021/04/13 13:30:38 [debug] 6938#0: *64939 http proxy header:
742021/04/13 13:30:38 [debug] 6938#0: *64939 http cleanup add: 0000556C850B3708
752021/04/13 13:30:38 [debug] 6938#0: *64939 get rr peer, try: 4
762021/04/13 13:30:38 [debug] 6938#0: *64939 get rr peer, current: 0000556C85071AA0 -2
772021/04/13 13:30:38 [debug] 6938#0: *64939 stream socket 27
782021/04/13 13:30:38 [debug] 6938#0: *64939 epoll add connection: fd:27 ev:80002005
792021/04/13 13:30:38 [debug] 6938#0: *64939 connect to 99.86.116.51:443, fd:27 #64940
802021/04/13 13:30:38 [debug] 6938#0: *64939 http upstream connect: -2
812021/04/13 13:30:38 [debug] 6938#0: *64939 posix_memalign: 0000556C85042D90:128 @16
822021/04/13 13:30:38 [debug] 6938#0: *64939 event timer add: 27: 60000:4129392300
832021/04/13 13:30:38 [debug] 6938#0: *64939 http finalize request: -4, "/?" a:1, c:2
842021/04/13 13:30:38 [debug] 6938#0: *64939 http request count:2 blk:0
852021/04/13 13:30:38 [debug] 6938#0: timer delta: 1
862021/04/13 13:30:38 [debug] 6938#0: worker cycle
872021/04/13 13:30:38 [debug] 6938#0: epoll timer: 3646
882021/04/13 13:30:38 [debug] 6938#0: epoll: fd:26 ev:0004 d:00007F723E376871
892021/04/13 13:30:38 [debug] 6938#0: *64939 http run request: "/?"
902021/04/13 13:30:38 [debug] 6938#0: *64939 http upstream check client, write event:1, "/"
912021/04/13 13:30:38 [debug] 6938#0: timer delta: 0
922021/04/13 13:30:38 [debug] 6938#0: worker cycle
932021/04/13 13:30:38 [debug] 6938#0: epoll timer: 3646
942021/04/13 13:30:38 [debug] 6938#0: epoll: fd:27 ev:0004 d:00007F723E375880
952021/04/13 13:30:38 [debug] 6938#0: *64939 http upstream request: "/?"
962021/04/13 13:30:38 [debug] 6938#0: *64939 http upstream send request handler
972021/04/13 13:30:38 [debug] 6938#0: *64939 malloc: 0000556C850B9120:88
982021/04/13 13:30:38 [debug] 6938#0: *64939 upstream SSL server name: "mysite.api.prod.vijay.com"
992021/04/13 13:30:38 [debug] 6938#0: *64939 set session: 0000556C85020940
1002021/04/13 13:30:38 [debug] 6938#0: *64939 tcp_nodelay
1012021/04/13 13:30:38 [debug] 6938#0: *64939 SSL_do_handshake: -1
1022021/04/13 13:30:38 [debug] 6938#0: *64939 SSL_get_error: 2
1032021/04/13 13:30:38 [debug] 6938#0: timer delta: 1
1042021/04/13 13:30:38 [debug] 6938#0: worker cycle
1052021/04/13 13:30:38 [debug] 6938#0: epoll timer: 3645
1062021/04/13 13:30:38 [debug] 6938#0: epoll: fd:27 ev:0005 d:00007F723E375880
1072021/04/13 13:30:38 [debug] 6938#0: *64939 SSL handshake handler: 0
1082021/04/13 13:30:38 [debug] 6938#0: *64939 SSL_do_handshake: 1
1092021/04/13 13:30:38 [debug] 6938#0: *64939 SSL: TLSv1.2, cipher: "ECDHE-RSA-AES128-GCM-SHA256 TLSv1.2 Kx=ECDH Au=RSA Enc=AESGCM(128) Mac=AEAD"
1102021/04/13 13:30:38 [debug] 6938#0: *64939 SSL reused session
1112021/04/13 13:30:38 [debug] 6938#0: *64939 http upstream ssl handshake: "/?"
1122021/04/13 13:30:38 [debug] 6938#0: *64939 http upstream send request
1132021/04/13 13:30:38 [debug] 6938#0: *64939 http upstream send request body
1142021/04/13 13:30:38 [debug] 6938#0: *64939 chain writer buf fl:0 s:454
1152021/04/13 13:30:38 [debug] 6938#0: *64939 chain writer buf fl:0 s:600
1162021/04/13 13:30:38 [debug] 6938#0: *64939 chain writer buf fl:1 s:3539
1172021/04/13 13:30:38 [debug] 6938#0: *64939 chain writer in: 0000556C850B37A0
1182021/04/13 13:30:38 [debug] 6938#0: *64939 malloc: 0000556C8503A6B0:80
1192021/04/13 13:30:38 [debug] 6938#0: *64939 malloc: 0000556C850BBE50:16384
1202021/04/13 13:30:38 [debug] 6938#0: *64939 SSL buf copy: 454
1212021/04/13 13:30:38 [debug] 6938#0: *64939 SSL buf copy: 600
1222021/04/13 13:30:38 [debug] 6938#0: *64939 SSL buf copy: 3539
1232021/04/13 13:30:38 [debug] 6938#0: *64939 SSL to write: 4593
1242021/04/13 13:30:38 [debug] 6938#0: *64939 SSL_write: 4593
1252021/04/13 13:30:38 [debug] 6938#0: *64939 chain writer out: 0000000000000000
1262021/04/13 13:30:38 [debug] 6938#0: *64939 event timer del: 27: 4129392300
1272021/04/13 13:30:38 [debug] 6938#0: *64939 event timer add: 27: 60000:4129392303
1282021/04/13 13:30:38 [debug] 6938#0: *64939 http upstream process header
1292021/04/13 13:30:38 [debug] 6938#0: *64939 malloc: 0000556C850B62A0:4096
1302021/04/13 13:30:38 [debug] 6938#0: *64939 SSL_read: -1
1312021/04/13 13:30:38 [debug] 6938#0: *64939 SSL_get_error: 2
1322021/04/13 13:30:38 [debug] 6938#0: *64939 http upstream request: "/?"
1332021/04/13 13:30:38 [debug] 6938#0: *64939 http upstream dummy handler
1342021/04/13 13:30:38 [debug] 6938#0: timer delta: 2
1352021/04/13 13:30:38 [debug] 6938#0: worker cycle
1362021/04/13 13:30:38 [debug] 6938#0: epoll timer: 3643
1372021/04/13 13:30:38 [debug] 6938#0: epoll: fd:3 ev:2005 d:00007F723E376F01
1382021/04/13 13:30:38 [debug] 6938#0: *64929 http run request: "/?"
1392021/04/13 13:30:38 [debug] 6938#0: *64929 http upstream check client, write event:0, "/"
1402021/04/13 13:30:38 [info] 6938#0: *64929 epoll_wait() reported that client prematurely closed connection, so upstream connection is closed too while reading response header from upstream, client: 192.168.200.9, server: 192.168.100.123, request: "POST / HTTP/1.1", upstream: "https://192.6.136.18:443/speed/send", host: "192.168.100.123:9876"
1412021/04/13 13:30:38 [debug] 6938#0: *64929 finalize http upstream request: 499
1422021/04/13 13:30:38 [debug] 6938#0: *64929 finalize http proxy request
1432021/04/13 13:30:38 [debug] 6938#0: *64929 free rr peer 4 0
1442021/04/13 13:30:38 [debug] 6938#0: *64929 SSL_shutdown: 1
1452021/04/13 13:30:38 [debug] 6938#0: *64929 close http upstream connection: 9
1462021/04/13 13:30:38 [debug] 6938#0: *64929 free: 0000556C8501C7F0
1472021/04/13 13:30:38 [debug] 6938#0: *64929 free: 0000556C850355D0
1482021/04/13 13:30:38 [debug] 6938#0: *64929 free: 0000556C85037FB0
1492021/04/13 13:30:38 [debug] 6938#0: *64929 free: 0000556C8501A200, unused: 0
1502021/04/13 13:30:38 [debug] 6938#0: *64929 event timer del: 9: 4129385076
1512021/04/13 13:30:38 [debug] 6938#0: *64929 reusable connection: 0
1522021/04/13 13:30:38 [debug] 6938#0: *64929 http finalize request: 499, "/?" a:1, c:1
1532021/04/13 13:30:38 [debug] 6938#0: *64929 http terminate request count:1
1542021/04/13 13:30:38 [debug] 6938#0: *64929 http terminate cleanup count:1 blk:0
1552021/04/13 13:30:38 [debug] 6938#0: *64929 http posted request: "/?"
1562021/04/13 13:30:38 [debug] 6938#0: *64929 http terminate handler count:1
1572021/04/13 13:30:38 [debug] 6938#0: *64929 http request count:1 blk:0
1582021/04/13 13:30:38 [debug] 6938#0: *64929 http close request
1592021/04/13 13:30:38 [debug] 6938#0: *64929 http log handler
1602021/04/13 13:30:38 [debug] 6938#0: *64929 free: 0000556C84FED250
1612021/04/13 13:30:38 [debug] 6938#0: *64929 free: 0000556C85038680, unused: 0
1622021/04/13 13:30:38 [debug] 6938#0: *64929 free: 0000556C85021830, unused: 22
1632021/04/13 13:30:38 [debug] 6938#0: *64929 free: 0000556C84FE5230, unused: 255
1642021/04/13 13:30:38 [debug] 6938#0: *64929 close http connection: 3
1652021/04/13 13:30:38 [debug] 6938#0: *64929 reusable connection: 0
1662021/04/13 13:30:38 [debug] 6938#0: *64929 free: 0000556C850340D0
1672021/04/13 13:30:38 [debug] 6938#0: *64929 free: 0000556C84FF23F0, unused: 136
1682021/04/13 13:30:38 [debug] 6938#0: timer delta: 776
1692021/04/13 13:30:38 [debug] 6938#0: worker cycle
1702021/04/13 13:30:38 [debug] 6938#0: epoll timer: 2867
1712021/04/13 13:30:39 [debug] 6938#0: epoll: fd:17 ev:2005 d:00007F723E376C31
1722021/04/13 13:30:39 [debug] 6938#0: *64931 http run request: "/?"
1732021/04/13 13:30:39 [debug] 6938#0: *64931 http upstream check client, write event:0, "/"
1742021/04/13 13:30:39 [info] 6938#0: *64931 epoll_wait() reported that client prematurely closed connection, so upstream connection is closed too while reading response header from upstream, client: 192.168.200.9, server: 192.168.100.123, request: "POST / HTTP/1.1", upstream: "https://192.6.136.18:443/speed/send", host: "192.168.100.123:9876"
1752021/04/13 13:30:39 [debug] 6938#0: *64931 finalize http upstream request: 499
1762021/04/13 13:30:39 [debug] 6938#0: *64931 finalize http proxy request
1772021/04/13 13:30:39 [debug] 6938#0: *64931 free rr peer 4 0
1782021/04/13 13:30:39 [debug] 6938#0: *64931 SSL_shutdown: 1
1792021/04/13 13:30:39 [debug] 6938#0: *64931 close http upstream connection: 20
1802021/04/13 13:30:39 [debug] 6938#0: *64931 free: 0000556C850AE9E0
1812021/04/13 13:30:39 [debug] 6938#0: *64931 free: 0000556C85035420
1822021/04/13 13:30:39 [debug] 6938#0: *64931 free: 0000556C8503C7A0
1832021/04/13 13:30:39 [debug] 6938#0: *64931 free: 0000556C84FF18E0, unused: 0
1842021/04/13 13:30:39 [debug] 6938#0: *64931 event timer del: 20: 4129385215
1852021/04/13 13:30:39 [debug] 6938#0: *64931 reusable connection: 0
1862021/04/13 13:30:39 [debug] 6938#0: *64931 http finalize request: 499, "/?" a:1, c:1
1872021/04/13 13:30:39 [debug] 6938#0: *64931 http terminate request count:1
1882021/04/13 13:30:39 [debug] 6938#0: *64931 http terminate cleanup count:1 blk:0
1892021/04/13 13:30:39 [debug] 6938#0: *64931 http posted request: "/?"
1902021/04/13 13:30:39 [debug] 6938#0: *64931 http terminate handler count:1
1912021/04/13 13:30:39 [debug] 6938#0: *64931 http request count:1 blk:0
1922021/04/13 13:30:39 [debug] 6938#0: *64931 http close request
1932021/04/13 13:30:39 [debug] 6938#0: *64931 http log handler
1942021/04/13 13:30:39 [debug] 6938#0: *64931 free: 0000556C850AA120
1952021/04/13 13:30:39 [debug] 6938#0: *64931 free: 0000556C84FF7060, unused: 0
1962021/04/13 13:30:39 [debug] 6938#0: *64931 free: 0000556C850436B0, unused: 22
1972021/04/13 13:30:39 [debug] 6938#0: *64931 free: 0000556C84FF2CE0, unused: 493
1982021/04/13 13:30:39 [debug] 6938#0: *64931 close http connection: 17
1992021/04/13 13:30:39 [debug] 6938#0: *64931 reusable connection: 0
2002021/04/13 13:30:39 [debug] 6938#0: *64931 free: 0000556C84FF6810
2012021/04/13 13:30:39 [debug] 6938#0: *64931 free: 0000556C84FF6030, unused: 136
2022021/04/13 13:30:39 [debug] 6938#0: timer delta: 139
2032021/04/13 13:30:39 [debug] 6938#0: worker cycle
2042021/04/13 13:30:39 [debug] 6938#0: epoll timer: 2728
2052021/04/13 13:30:39 [debug] 6938#0: epoll: fd:8 ev:0001 d:00007F723E3751F0