2015/09/29 12:13:21 [debug] 8892#0: *4 http cl:686 max:26214400
2015/09/29 12:13:21 [debug] 8892#0: *4 rewrite phase: 3
2015/09/29 12:13:21 [debug] 8892#0: *4 http client request body preread 486
2015/09/29 12:13:21 [debug] 8892#0: *4 http request body content length filter
2015/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
2015/09/29 12:13:21 [debug] 8892#0: *4 http read client request body
2015/09/29 12:13:21 [debug] 8892#0: *4 SSL_read: 200
2015/09/29 12:13:21 [debug] 8892#0: *4 http client request body recv 200
2015/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
2015/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
2015/09/29 12:13:21 [debug] 8892#0: *4 http client request body rest 0
2015/09/29 12:13:21 [debug] 8892#0: *4 rewrite phase: 4
2015/09/29 12:13:21 [debug] 8892#0: *4 post rewrite phase: 5
2015/09/29 12:13:21 [debug] 8892#0: *4 generic phase: 6
2015/09/29 12:13:21 [debug] 8892#0: *4 generic phase: 7
2015/09/29 12:13:21 [debug] 8892#0: *4 generic phase: 8
2015/09/29 12:13:21 [debug] 8892#0: *4 access phase: 9
2015/09/29 12:13:21 [debug] 8892#0: *4 access: 040A160A 00000000 00000000
2015/09/29 12:13:21 [debug] 8892#0: *4 access phase: 10
2015/09/29 12:13:21 [debug] 8892#0: *4 access phase: 11
2015/09/29 12:13:21 [debug] 8892#0: *4 auth request handler
2015/09/29 12:13:21 [debug] 8892#0: *4 posix_memalign: 0000000001EFBBB0:4096 @16
2015/09/29 12:13:21 [debug] 8892#0: *4 http subrequest "/auth?"
2015/09/29 12:13:21 [debug] 8892#0: *4 http posted request: "/auth?"
2015/09/29 12:13:21 [debug] 8892#0: *4 rewrite phase: 1
2015/09/29 12:13:21 [debug] 8892#0: *4 test location: "/permission-denied"
2015/09/29 12:13:21 [debug] 8892#0: *4 test location: "/auth"
2015/09/29 12:13:21 [debug] 8892#0: *4 using configuration "=/auth"
2015/09/29 12:13:21 [debug] 8892#0: *4 http cl:686 max:26214400
2015/09/29 12:13:21 [debug] 8892#0: *4 rewrite phase: 3
2015/09/29 12:13:21 [debug] 8892#0: *4 rewrite phase: 4
2015/09/29 12:13:21 [debug] 8892#0: *4 http script var
2015/09/29 12:13:21 [debug] 8892#0: *4 http script if
2015/09/29 12:13:21 [debug] 8892#0: *4 http script if: false
2015/09/29 12:13:21 [debug] 8892#0: *4 http script var
2015/09/29 12:13:21 [debug] 8892#0: *4 http script var: "Token RANDOMSESSIONID"
2015/09/29 12:13:21 [debug] 8892#0: *4 http script if
2015/09/29 12:13:21 [debug] 8892#0: *4 http script complex value
2015/09/29 12:13:21 [debug] 8892#0: *4 http script var: "Token RANDOMSESSIONID"
2015/09/29 12:13:21 [debug] 8892#0: *4 http script set $app_auth
2015/09/29 12:13:21 [debug] 8892#0: *4 post rewrite phase: 5
2015/09/29 12:13:21 [debug] 8892#0: *4 generic phase: 6
2015/09/29 12:13:21 [debug] 8892#0: *4 generic phase: 7
2015/09/29 12:13:21 [debug] 8892#0: *4 generic phase: 8
2015/09/29 12:13:21 [debug] 8892#0: *4 try files phase: 13
2015/09/29 12:13:21 [debug] 8892#0: *4 http init upstream, client timer: 0
2015/09/29 12:13:21 [debug] 8892#0: *4 epoll add event: fd:147 op:3 ev:80002005
2015/09/29 12:13:21 [debug] 8892#0: *4 http script var: "127.0.0.1"
2015/09/29 12:13:21 [debug] 8892#0: *4 http script var: "mylocalhostname"
2015/09/29 12:13:21 [debug] 8892#0: *4 http script var: "Token RANDOMSESSIONID"
2015/09/29 12:13:21 [debug] 8892#0: *4 http cache key: "127.0.0.1mylocalhostnameToken RANDOMSESSIONID"
2015/09/29 12:13:21 [debug] 8892#0: *4 add cleanup: 0000000001EFC6F8
2015/09/29 12:13:21 [debug] 8892#0: *4 http file cache exists: -5 e:0
2015/09/29 12:13:21 [debug] 8892#0: *4 cache file: "/var/cache/nginx/proxyCacheAuth/RANDOMCACHEFILENAME"
2015/09/29 12:13:21 [debug] 8892#0: *4 add cleanup: 0000000001EFC758
2015/09/29 12:13:21 [debug] 8892#0: *4 http upstream cache: -5
2015/09/29 12:13:21 [debug] 8892#0: *4 http script copy: "Authorize: "
2015/09/29 12:13:21 [debug] 8892#0: *4 http script var: "Token RANDOMSESSIONID"
2015/09/29 12:13:21 [debug] 8892#0: *4 http script copy: "
"
2015/09/29 12:13:21 [debug] 8892#0: *4 http script copy: "Host: "
2015/09/29 12:13:21 [debug] 8892#0: *4 http script var: "mylocalhostname"
2015/09/29 12:13:21 [debug] 8892#0: *4 http script copy: "
"
2015/09/29 12:13:21 [debug] 8892#0: *4 http script copy: "Connection: close
"
2015/09/29 12:13:21 [debug] 8892#0: *4 http script copy: ""
2015/09/29 12:13:21 [debug] 8892#0: *4 http script copy: ""
2015/09/29 12:13:21 [debug] 8892#0: *4 http script copy: ""
2015/09/29 12:13:21 [debug] 8892#0: *4 http script copy: ""
2015/09/29 12:13:21 [debug] 8892#0: *4 http script copy: ""
2015/09/29 12:13:21 [debug] 8892#0: *4 http script copy: ""
2015/09/29 12:13:21 [debug] 8892#0: *4 http proxy header:
"GET /random/url HTTP/1.1
Authorize: Token RANDOMSESSIONID
Host: mylocalhostname
Connection: close

"
2015/09/29 12:13:21 [debug] 8892#0: *4 http cleanup add: 0000000001EFC920
2015/09/29 12:13:21 [debug] 8892#0: *4 get rr peer, try: 2
2015/09/29 12:13:21 [debug] 8892#0: *4 get rr peer, current: 0 -1
2015/09/29 12:13:21 [debug] 8892#0: *4 socket 148
2015/09/29 12:13:21 [debug] 8892#0: *4 epoll add connection: fd:148 ev:80002005
2015/09/29 12:13:21 [debug] 8892#0: *4 connect to 127.0.0.1:8080, fd:148 #5
2015/09/29 12:13:21 [debug] 8892#0: *4 http upstream connect: -2
2015/09/29 12:13:21 [debug] 8892#0: *4 posix_memalign: 0000000001A5A8D0:128 @16
2015/09/29 12:13:21 [debug] 8892#0: *4 event timer add: 148: 60000:1443521661601
2015/09/29 12:13:21 [debug] 8892#0: *4 http finalize request: -4, "/auth?" a:1, c:3
2015/09/29 12:13:21 [debug] 8892#0: *4 http request count:3 blk:0
2015/09/29 12:13:21 [debug] 8892#0: *4 http run request: "/auth?"
2015/09/29 12:13:21 [debug] 8892#0: *4 http upstream check client, write event:1, "/auth"
2015/09/29 12:13:21 [debug] 8892#0: *4 http upstream recv(): -1 (11: Resource temporarily unavailable)
2015/09/29 12:13:21 [debug] 8892#0: *4 http upstream request: "/auth?"
2015/09/29 12:13:21 [debug] 8892#0: *4 http upstream send request handler
2015/09/29 12:13:21 [debug] 8892#0: *4 http upstream send request
2015/09/29 12:13:21 [debug] 8892#0: *4 http upstream send request body
2015/09/29 12:13:21 [debug] 8892#0: *4 chain writer buf fl:1 s:156
2015/09/29 12:13:21 [debug] 8892#0: *4 chain writer in: 0000000001EFC958
2015/09/29 12:13:21 [debug] 8892#0: *4 writev: 156 of 156
2015/09/29 12:13:21 [debug] 8892#0: *4 chain writer out: 0000000000000000
2015/09/29 12:13:21 [debug] 8892#0: *4 event timer del: 148: 1443521661601
2015/09/29 12:13:21 [debug] 8892#0: *4 event timer add: 148: 60000:1443521661602
2015/09/29 12:13:21 [debug] 8892#0: *4 http upstream request: "/auth?"
2015/09/29 12:13:21 [debug] 8892#0: *4 http upstream process header
2015/09/29 12:13:21 [debug] 8892#0: *4 malloc: 0000000001F01410:4096
2015/09/29 12:13:21 [debug] 8892#0: *4 recv: fd:148 131 of 3871
2015/09/29 12:13:21 [debug] 8892#0: *4 http proxy status 401 "401 Unauthorized"
2015/09/29 12:13:21 [debug] 8892#0: *4 http proxy header: "Server: XXX"
2015/09/29 12:13:21 [debug] 8892#0: *4 http proxy header: "Date: Tue, 29 Sep 2015 10:13:21 GMT"
2015/09/29 12:13:21 [debug] 8892#0: *4 http proxy header: "Content-Length: 0"
2015/09/29 12:13:21 [debug] 8892#0: *4 http proxy header: "Connection: close"
2015/09/29 12:13:21 [debug] 8892#0: *4 http proxy header done
2015/09/29 12:13:21 [debug] 8892#0: *4 http file cache set header
2015/09/29 12:13:21 [debug] 8892#0: *4 http cacheable: 1
2015/09/29 12:13:21 [debug] 8892#0: *4 posix_memalign: 0000000001F02420:4096 @16
2015/09/29 12:13:21 [debug] 8892#0: *4 http proxy filter init s:401 h:0 c:0 l:0
2015/09/29 12:13:21 [debug] 8892#0: *4 http upstream process upstream
2015/09/29 12:13:21 [debug] 8892#0: *4 pipe read upstream: 1
2015/09/29 12:13:21 [debug] 8892#0: *4 pipe preread: 0
2015/09/29 12:13:21 [debug] 8892#0: *4 readv: 1, last:3740
2015/09/29 12:13:21 [debug] 8892#0: *4 pipe recv chain: 0
2015/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
2015/09/29 12:13:21 [debug] 8892#0: *4 pipe length: 0
2015/09/29 12:13:21 [debug] 8892#0: *4 pipe write chain
2015/09/29 12:13:21 [debug] 8892#0: *4 add cleanup: 0000000001EFCB88
2015/09/29 12:13:21 [debug] 8892#0: *4 hashed path: /var/cache/nginx/proxy_temp/1/00/0000000001
2015/09/29 12:13:21 [debug] 8892#0: *4 temp fd:149
2015/09/29 12:13:21 [debug] 8892#0: *4 write: 149, 0000000001F01410, 356, 0
2015/09/29 12:13:21 [debug] 8892#0: *4 pipe write downstream: 1
2015/09/29 12:13:21 [debug] 8892#0: *4 event timer del: 148: 1443521661602
2015/09/29 12:13:21 [debug] 8892#0: *4 http file cache update
2015/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"
2015/09/29 12:13:21 [debug] 8892#0: *4 http upstream exit: 0000000000000000
2015/09/29 12:13:21 [debug] 8892#0: *4 finalize http upstream request: 0
2015/09/29 12:13:21 [debug] 8892#0: *4 finalize http proxy request
2015/09/29 12:13:21 [debug] 8892#0: *4 free rr peer 2 0
2015/09/29 12:13:21 [debug] 8892#0: *4 close http upstream connection: 148
2015/09/29 12:13:21 [debug] 8892#0: *4 free: 0000000001A5A8D0, unused: 48
2015/09/29 12:13:21 [debug] 8892#0: *4 reusable connection: 0
2015/09/29 12:13:21 [debug] 8892#0: *4 http upstream temp fd: 149
2015/09/29 12:13:21 [debug] 8892#0: *4 http finalize request: 0, "/auth?" a:1, c:2
2015/09/29 12:13:21 [debug] 8892#0: *4 auth request done s:401
2015/09/29 12:13:21 [debug] 8892#0: *4 http wake parent request: "/myapp?"
2015/09/29 12:13:21 [debug] 8892#0: *4 http posted request: "/myapp?"
2015/09/29 12:13:21 [debug] 8892#0: *4 http request empty handler
2015/09/29 12:13:25 [debug] 8892#0: *4 http run request: "/myapp?"
2015/09/29 12:13:25 [debug] 8892#0: *4 http reading blocked
2015/09/29 12:13:25 [debug] 8892#0: *4 http run request: "/myapp?"
2015/09/29 12:13:25 [debug] 8892#0: *4 http request empty handler