Intermittant SSL Problems

Thu Nov 21 02:03:11 UTC 2013

Hi folks,

We are using Nginx for SSL termination, and then it proxies to an ATS or
Haproxy server depending on our environment.

We're running into a problem where every now and then, Nginx closes a
connection due to a timeout.  When investigating, it looks like the
connections that are being timed-out are not being forwarded to the backend
service.  The scenario when we were able to best reproduce this is one
where one of our Java client was running about 100 REST requests that were
fairly similar.  I've attached files that contain both the tcpdump from the
client side as well as the debug log on the nginx side.

I tried comparing a successful and unsuccessful request next to each
other.  From the client side, it looks like the messages back and forth
look very consistent.  On the nginx side, the first difference seems to
happen when reading in the Http Request.  The requests that fail, all seem
to do a partial read:

==SNIPPET FROM FAILING REQUEST==

2013/11/20 01:58:05 [debug] 52611#0: *621 http wait request handler
2013/11/20 01:58:05 [debug] 52611#0: *621 malloc: 0000000000F1BE20:1024
2013/11/20 01:58:05 [debug] 52611#0: *621 SSL_read: 335
2013/11/20 01:58:05 [debug] 52611#0: *621 SSL_read: 1
2013/11/20 01:58:05 [debug] 52611#0: *621 SSL_read: -1
2013/11/20 01:58:05 [debug] 52611#0: *621 SSL_get_error: 2
2013/11/20 01:58:05 [debug] 52611#0: *621 reusable connection: 0
2013/11/20 01:58:05 [debug] 52611#0: *621 posix_memalign:
0000000000EFB600:4096 @16
2013/11/20 01:58:05 [debug] 52611#0: *621 http process request line

==SNIPPET FROM SUCCEEDING REQUEST==
2013/11/20 01:58:04 [debug] 52611#0: *619 http wait request handler
2013/11/20 01:58:04 [debug] 52611#0: *619 malloc: 0000000000F1BE20:1024
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_read: 335
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_read: 1
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_read: 167
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_read: 1
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_read: 2
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_read: 1
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_read: 1
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_read: -1
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_get_error: 2
2013/11/20 01:58:04 [debug] 52611#0: *619 reusable connection: 0
2013/11/20 01:58:04 [debug] 52611#0: *619 posix_memalign:
0000000000EFB600:4096 @16
2013/11/20 01:58:04 [debug] 52611#0: *619 http process request line

This difference seems to be consistent with errors.  Later on, the request
that ends up failing attempts to load the request body, but only gets about
16 bytes, and looks like it keeps waiting for the rest of the data.
However, looking at a tcpdump from the client, it looks like all the data
is sent up and ack-ed.  Then the client sees nothing for a minute until the
connection is closed by the server.

==TCP DUMP FROM FAILING REQUEST==
...
17:58:05.259451 IP x.x.x.145.53167 > y.y.y.209.https: Flags [.], ack 2996,
win 8023, options [nop,nop,TS val 145724966 ecr 155421032], length 0
17:58:05.261592 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq
221:296, ack 2996, win 8192, options [nop,nop,TS val 145724968 ecr
155421032], length 75
17:58:05.262989 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq
296:302, ack 2996, win 8192, options [nop,nop,TS val 145724969 ecr
155421032], length 6
17:58:05.263196 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq
302:355, ack 2996, win 8192, options [nop,nop,TS val 145724969 ecr
155421032], length 53
17:58:05.295347 IP y.y.y.209.https > x.x.x.145.53167: Flags [.], ack 355,
win 122, options [nop,nop,TS val 155421041 ecr 145724968], length 0
17:58:05.295387 IP y.y.y.209.https > x.x.x.145.53167: Flags [P.], seq
2996:3055, ack 355, win 122, options [nop,nop,TS val 155421042 ecr
145724968], length 59
17:58:05.295481 IP x.x.x.145.53167 > y.y.y.209.https: Flags [.], ack 3055,
win 8188, options [nop,nop,TS val 145725000 ecr 155421042], length 0
17:58:05.300058 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq
355:728, ack 3055, win 8192, options [nop,nop,TS val 145725004 ecr
155421042], length 373
17:58:05.300253 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq
728:765, ack 3055, win 8192, options [nop,nop,TS val 145725004 ecr
155421042], length 37
17:58:05.300254 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq
765:962, ack 3055, win 8192, options [nop,nop,TS val 145725004 ecr
155421042], length 197
17:58:05.300282 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq
962:999, ack 3055, win 8192, options [nop,nop,TS val 145725004 ecr
155421042], length 37
17:58:05.300307 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq
999:1036, ack 3055, win 8192, options [nop,nop,TS val 145725004 ecr
155421042], length 37
17:58:05.300342 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq
1036:1073, ack 3055, win 8192, options [nop,nop,TS val 145725004 ecr
155421042], length 37
17:58:05.300365 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq
1073:1110, ack 3055, win 8192, options [nop,nop,TS val 145725004 ecr
155421042], length 37
17:58:05.332040 IP y.y.y.209.https > x.x.x.145.53167: Flags [.], ack 765,
win 130, options [nop,nop,TS val 155421051 ecr 145725004], length 0
17:58:05.332247 IP y.y.y.209.https > x.x.x.145.53167: Flags [.], ack 1110,
win 139, options [nop,nop,TS val 155421051 ecr 145725004], length 0
*17:59:05.338429 IP y.y.y.209.https > x.x.x.145.53167: Flags [F.], seq
3055, ack 1110, win 139, options [nop,nop,TS val 155436119 ecr 145725004],
length 0*
17:59:05.338581 IP x.x.x.145.53167 > y.y.y.209.https: Flags [.], ack 3056,
win 8192, options [nop,nop,TS val 145784751 ecr 155436119], length 0
17:59:05.338932 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq
1110:1147, ack 3056, win 8192, options [nop,nop,TS val 145784751 ecr
155436119], length 37
17:59:05.338933 IP x.x.x.145.53167 > y.y.y.209.https: Flags [F.], seq 1147,
ack 3056, win 8192, options [nop,nop,TS val 145784751 ecr 155436119],
length 0
17:59:05.370400 IP y.y.y.209.https > x.x.x.145.53167: Flags [R], seq
325468762, win 0, length 0

==TCP DUMP FROM SUCCESSFUL REQUEST==
...
17:58:04.481722 IP x.x.x.145.53166 > y.y.y.209.https: Flags [.], ack 2996,
win 8023, options [nop,nop,TS val 145724196 ecr 155420837], length 0
17:58:04.484108 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq
221:296, ack 2996, win 8192, options [nop,nop,TS val 145724198 ecr
155420837], length 75
17:58:04.485569 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq
296:302, ack 2996, win 8192, options [nop,nop,TS val 145724199 ecr
155420837], length 6
17:58:04.485767 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq
302:355, ack 2996, win 8192, options [nop,nop,TS val 145724199 ecr
155420837], length 53
17:58:04.531685 IP y.y.y.209.https > x.x.x.145.53166: Flags [.], ack 355,
win 122, options [nop,nop,TS val 155420850 ecr 145724198], length 0
17:58:04.531689 IP y.y.y.209.https > x.x.x.145.53166: Flags [P.], seq
2996:3055, ack 355, win 122, options [nop,nop,TS val 155420850 ecr
145724198], length 59
17:58:04.531827 IP x.x.x.145.53166 > y.y.y.209.https: Flags [.], ack 3055,
win 8188, options [nop,nop,TS val 145724244 ecr 155420850], length 0
17:58:04.532709 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq
355:728, ack 3055, win 8192, options [nop,nop,TS val 145724244 ecr
155420850], length 373
17:58:04.532906 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq
728:765, ack 3055, win 8192, options [nop,nop,TS val 145724245 ecr
155420850], length 37
17:58:04.532954 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq
765:962, ack 3055, win 8192, options [nop,nop,TS val 145724245 ecr
155420850], length 197
17:58:04.532983 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq
962:999, ack 3055, win 8192, options [nop,nop,TS val 145724245 ecr
155420850], length 37
17:58:04.533012 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq
999:1036, ack 3055, win 8192, options [nop,nop,TS val 145724245 ecr
155420850], length 37
17:58:04.533045 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq
1036:1073, ack 3055, win 8192, options [nop,nop,TS val 145724245 ecr
155420850], length 37
17:58:04.533143 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq
1073:1110, ack 3055, win 8192, options [nop,nop,TS val 145724245 ecr
155420850], length 37
17:58:04.565176 IP y.y.y.209.https > x.x.x.145.53166: Flags [.], ack 962,
win 139, options [nop,nop,TS val 155420858 ecr 145724244], length 0
17:58:04.565184 IP y.y.y.209.https > x.x.x.145.53166: Flags [.], ack 1110,
win 139, options [nop,nop,TS val 155420858 ecr 145724245], length 0
*17:58:05.184331 IP y.y.y.209.https > x.x.x.145.53166: Flags [P.], seq
3055:3540, ack 1110, win 139, options [nop,nop,TS val 155421011 ecr
145724245], length 485*
17:58:05.184442 IP x.x.x.145.53166 > y.y.y.209.https: Flags [.], ack 3540,
win 8161, options [nop,nop,TS val 145724894 ecr 155421011], length 0
17:58:05.184592 IP y.y.y.209.https > x.x.x.145.53166: Flags [F.], seq 3540,
ack 1110, win 139, options [nop,nop,TS val 155421011 ecr 145724245], length
0
17:58:05.184658 IP x.x.x.145.53166 > y.y.y.209.https: Flags [.], ack 3541,
win 8192, options [nop,nop,TS val 145724894 ecr 155421011], length 0
17:58:05.184863 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq
1110:1147, ack 3541, win 8192, options [nop,nop,TS val 145724894 ecr
155421011], length 37
17:58:05.184863 IP x.x.x.145.53166 > y.y.y.209.https: Flags [F.], seq 1147,
ack 3541, win 8192, options [nop,nop,TS val 145724894 ecr 155421011],
length 0

When I look at the TCP dumps, it looks like the client sends up all the
data, and it looks like the server receives and acks it.  At this point,
I'm sorta stuck.  Does anyone have any insight here?  Is there a know bug
that has been fixed that we may be missing?  I've attached files that have
more complete dumps of the requests.

We are running Ubuntu 12.04.3 LTS, with:
    nginx version: nginx/1.4.1
    openssl version: OpenSSL 1.0.1 14 Mar 2012

    Thanks,
    --Will
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.nginx.org/pipermail/nginx/attachments/20131120/e9853087/attachment-0001.html>
-------------- next part --------------
2013/11/20 01:58:05 [debug] 52611#0: *621 SSL handshake handler: 0
2013/11/20 01:58:05 [debug] 52611#0: *621 SSL_do_handshake: 1
2013/11/20 01:58:05 [debug] 52611#0: *621 SSL: TLSv1, cipher: "ECDHE-RSA-AES128-SHA SSLv3 Kx=ECDH Au=RSA Enc=AES(128) Mac=SHA1"
2013/11/20 01:58:05 [debug] 52611#0: *621 reusable connection: 1
2013/11/20 01:58:05 [debug] 52611#0: *621 http wait request handler
2013/11/20 01:58:05 [debug] 52611#0: *621 malloc: 0000000000F1BE20:1024
2013/11/20 01:58:05 [debug] 52611#0: *621 SSL_read: -1
2013/11/20 01:58:05 [debug] 52611#0: *621 SSL_get_error: 2
2013/11/20 01:58:05 [debug] 52611#0: *621 free: 0000000000F1BE20
2013/11/20 01:58:05 [debug] 52611#0: *621 post event 0000000000E8F5A8
2013/11/20 01:58:05 [debug] 52611#0: *621 delete posted event 0000000000E8F5A8
2013/11/20 01:58:05 [debug] 52611#0: *621 http wait request handler
2013/11/20 01:58:05 [debug] 52611#0: *621 malloc: 0000000000F1BE20:1024
2013/11/20 01:58:05 [debug] 52611#0: *621 SSL_read: 335
2013/11/20 01:58:05 [debug] 52611#0: *621 SSL_read: 1
2013/11/20 01:58:05 [debug] 52611#0: *621 SSL_read: -1
2013/11/20 01:58:05 [debug] 52611#0: *621 SSL_get_error: 2
2013/11/20 01:58:05 [debug] 52611#0: *621 reusable connection: 0
2013/11/20 01:58:05 [debug] 52611#0: *621 posix_memalign: 0000000000EFB600:4096 @16
2013/11/20 01:58:05 [debug] 52611#0: *621 http process request line
2013/11/20 01:58:05 [debug] 52611#0: *621 http request line: "POST /api/views/uv4d-it6e/columns?$$version=2.0 HTTP/1.1"
2013/11/20 01:58:05 [debug] 52611#0: *621 http uri: "/api/views/uv4d-it6e/columns"
2013/11/20 01:58:05 [debug] 52611#0: *621 http args: "$$version=2.0"
2013/11/20 01:58:05 [debug] 52611#0: *621 http exten: ""
2013/11/20 01:58:05 [debug] 52611#0: *621 http process request header line
2013/11/20 01:58:05 [debug] 52611#0: *621 http header: "Accept: application/json"
2013/11/20 01:58:05 [debug] 52611#0: *621 http header: "Content-Type: application/json"
2013/11/20 01:58:05 [debug] 52611#0: *621 http header: "X-App-Token: Ya8CU9HKxeh0ytjHJttm2FhaW"
2013/11/20 01:58:05 [debug] 52611#0: *621 http header: "Authorization: Basic d2lsbC5wdWdoQHNvY3JhdGEuY29tOlNzbjEyMzQ1Ng=="
2013/11/20 01:58:05 [debug] 52611#0: *621 http header: "User-Agent: Java/1.7.0_12-ea"
2013/11/20 01:58:05 [debug] 52611#0: *621 http header: "Host: opendata.test-socrata.com"
2013/11/20 01:58:05 [debug] 52611#0: *621 http header: "Connection: close"
2013/11/20 01:58:05 [debug] 52611#0: *621 http header: "Transfer-Encoding: chunked"
2013/11/20 01:58:05 [debug] 52611#0: *621 http header done
2013/11/20 01:58:05 [debug] 52611#0: *621 event timer del: 11: 1384912745204
2013/11/20 01:58:05 [debug] 52611#0: *621 generic phase: 0
2013/11/20 01:58:05 [debug] 52611#0: *621 rewrite phase: 1
2013/11/20 01:58:05 [debug] 52611#0: *621 test location: "/"
2013/11/20 01:58:05 [debug] 52611#0: *621 test location: "socket.io"
2013/11/20 01:58:05 [debug] 52611#0: *621 using configuration "/"
2013/11/20 01:58:05 [debug] 52611#0: *621 http cl:-1 max:25769803776
2013/11/20 01:58:05 [debug] 52611#0: *621 rewrite phase: 3
2013/11/20 01:58:05 [debug] 52611#0: *621 posix_memalign: 0000000000EFB600:4096 @16
2013/11/20 01:58:05 [debug] 52611#0: *621 http process request line
2013/11/20 01:58:05 [debug] 52611#0: *621 http request line: "POST /api/views/uv4d-it6e/columns?$$version=2.0 HTTP/1.1"
2013/11/20 01:58:05 [debug] 52611#0: *621 http uri: "/api/views/uv4d-it6e/columns"
2013/11/20 01:58:05 [debug] 52611#0: *621 http args: "$$version=2.0"
2013/11/20 01:58:05 [debug] 52611#0: *621 http exten: ""
2013/11/20 01:58:05 [debug] 52611#0: *621 http process request header line
2013/11/20 01:58:05 [debug] 52611#0: *621 http header: "Accept: application/json"
2013/11/20 01:58:05 [debug] 52611#0: *621 http header: "Content-Type: application/json"
2013/11/20 01:58:05 [debug] 52611#0: *621 http header: "X-App-Token: Ya8CU9HKxeh0ytjHJttm2FhaW"
2013/11/20 01:58:05 [debug] 52611#0: *621 http header: "Authorization: Basic d2lsbC5wdWdoQHNvY3JhdGEuY29tOlNzbjEyMzQ1Ng=="
2013/11/20 01:58:05 [debug] 52611#0: *621 http header: "User-Agent: Java/1.7.0_12-ea"
2013/11/20 01:58:05 [debug] 52611#0: *621 http header: "Host: opendata.test-socrata.com"
2013/11/20 01:58:05 [debug] 52611#0: *621 http header: "Connection: close"
2013/11/20 01:58:05 [debug] 52611#0: *621 http header: "Transfer-Encoding: chunked"
2013/11/20 01:58:05 [debug] 52611#0: *621 http header done
2013/11/20 01:58:05 [debug] 52611#0: *621 event timer del: 11: 1384912745204
2013/11/20 01:58:05 [debug] 52611#0: *621 generic phase: 0
2013/11/20 01:58:05 [debug] 52611#0: *621 rewrite phase: 1
2013/11/20 01:58:05 [debug] 52611#0: *621 test location: "/"
2013/11/20 01:58:05 [debug] 52611#0: *621 test location: "socket.io"
2013/11/20 01:58:05 [debug] 52611#0: *621 using configuration "/"
2013/11/20 01:58:05 [debug] 52611#0: *621 http cl:-1 max:25769803776
2013/11/20 01:58:05 [debug] 52611#0: *621 rewrite phase: 3
2013/11/20 01:58:05 [debug] 52611#0: *621 posix_memalign: 0000000000F18E70:4096 @16
2013/11/20 01:58:05 [debug] 52611#0: *621 http script complex value
2013/11/20 01:58:05 [debug] 52611#0: *621 http script var: "/var/www/nginx-default"
2013/11/20 01:58:05 [debug] 52611#0: *621 http script copy: "/maintenance.html^@"
2013/11/20 01:58:05 [debug] 52611#0: *621 http script file op 0000000000000000 "/var/www/nginx-default/maintenance.html"
2013/11/20 01:58:05 [debug] 52611#0: *621 http script file op false
2013/11/20 01:58:05 [debug] 52611#0: *621 http script if
2013/11/20 01:58:05 [debug] 52611#0: *621 http script if: false
2013/11/20 01:58:05 [debug] 52611#0: *621 post rewrite phase: 4
2013/11/20 01:58:05 [debug] 52611#0: *621 generic phase: 5
2013/11/20 01:58:05 [debug] 52611#0: *621 generic phase: 6
2013/11/20 01:58:05 [debug] 52611#0: *621 generic phase: 7
2013/11/20 01:58:05 [debug] 52611#0: *621 access phase: 8
2013/11/20 01:58:05 [debug] 52611#0: *621 access phase: 9
2013/11/20 01:58:05 [debug] 52611#0: *621 post access phase: 10
2013/11/20 01:58:05 [debug] 52611#0: *621 http client request body preread 1
2013/11/20 01:58:05 [debug] 52611#0: *621 http request body chunked filter
2013/11/20 01:58:05 [debug] 52611#0: *621 http body chunked buf t:1 f:0 0000000000F1BE20, pos 0000000000F1BF6F, size: 1 file: 0, size: 0
2013/11/20 01:58:05 [debug] 52611#0: *621 http chunked byte: 61 s:0
2013/11/20 01:58:05 [debug] 52611#0: *621 malloc: 0000000000F0EAE0:8192
2013/11/20 01:58:05 [debug] 52611#0: *621 http read client request body
2013/11/20 01:58:05 [debug] 52611#0: *621 SSL_read: 16
2013/11/20 01:58:05 [debug] 52611#0: *621 http client request body recv 16
2013/11/20 01:58:05 [debug] 52611#0: *621 http body chunked buf t:1 f:0 0000000000F0EAE0, pos 0000000000F0EAE0, size: 16 file: 0, size: 0
2013/11/20 01:58:05 [debug] 52611#0: *621 http chunked byte: 30 s:1
2013/11/20 01:58:05 [debug] 52611#0: *621 http chunked byte: 0D s:1
2013/11/20 01:58:05 [debug] 52611#0: *621 http chunked byte: 0A s:3
2013/11/20 01:58:05 [debug] 52611#0: *621 http chunked byte: 7B s:4
2013/11/20 01:58:05 [debug] 52611#0: *621 http body chunked buf t:1 f:0 0000000000F0EAE0, pos 0000000000F0EAF0, size: 0 file: 0, size: 0
2013/11/20 01:58:05 [debug] 52611#0: *621 http body new buf t:1 f:0 0000000000F0EAE3, pos 0000000000F0EAE3, size: 13 file: 0, size: 0
2013/11/20 01:58:05 [debug] 52611#0: *621 http client request body rest 151
2013/11/20 01:58:05 [debug] 52611#0: *621 event timer add: 11: 60000:1384912745281
2013/11/20 01:58:05 [debug] 52611#0: *621 http finalize request: -4, "/api/views/uv4d-it6e/columns?$$version=2.0" a:1, c:2
2013/11/20 01:58:05 [debug] 52611#0: *621 http request count:2 blk:0
2013/11/20 01:59:05 [debug] 52611#0: *621 event timer del: 11: 1384912745281
2013/11/20 01:59:05 [debug] 52611#0: *621 http run request: "/api/views/uv4d-it6e/columns?$$version=2.0"
2013/11/20 01:59:05 [debug] 52611#0: *621 http finalize request: 408, "/api/views/uv4d-it6e/columns?$$version=2.0" a:1, c:1
2013/11/20 01:59:05 [debug] 52611#0: *621 http terminate request count:1
2013/11/20 01:59:05 [debug] 52611#0: *621 http terminate cleanup count:1 blk:0
2013/11/20 01:59:05 [debug] 52611#0: *621 http posted request: "/api/views/uv4d-it6e/columns?$$version=2.0"
2013/11/20 01:59:05 [debug] 52611#0: *621 http terminate handler count:1
2013/11/20 01:59:05 [debug] 52611#0: *621 http request count:1 blk:0
2013/11/20 01:59:05 [debug] 52611#0: *621 http close request
2013/11/20 01:59:05 [debug] 52611#0: *621 http log handler
2013/11/20 01:59:05 [debug] 52611#0: *621 free: 0000000000F0EAE0
2013/11/20 01:59:05 [debug] 52611#0: *621 free: 0000000000EFB600, unused: 0
2013/11/20 01:59:05 [debug] 52611#0: *621 free: 0000000000F18E70, unused: 2006
2013/11/20 01:59:05 [debug] 52611#0: *621 close http connection: 11
2013/11/20 01:59:05 [debug] 52611#0: *621 SSL_shutdown: 1
2013/11/20 01:59:05 [debug] 52611#0: *621 reusable connection: 0
2013/11/20 01:59:05 [debug] 52611#0: *621 free: 0000000000F1BE20
2013/11/20 01:59:05 [debug] 52611#0: *621 free: 0000000000E1F1A0, unused: 0
2013/11/20 01:59:05 [debug] 52611#0: *621 free: 0000000000F0C650, unused: 40
-------------- next part --------------
17:58:05.186256 IP x.x.x.145.53167 > y.y.y.209.https: Flags [S], seq 1022305023, win 65535, options [mss 1460,nop,wscale 4,nop,nop,TS val 145724895 ecr 0,sackOK,eol], length 0
17:58:05.216148 IP y.y.y.209.https > x.x.x.145.53166: Flags [.], ack 1148, win 139, options [nop,nop,TS val 155421022 ecr 145724894], length 0
17:58:05.218560 IP y.y.y.209.https > x.x.x.145.53167: Flags [S.], seq 325465706, ack 1022305024, win 14480, options [mss 1440,sackOK,TS val 155421022 ecr 145724895,nop,wscale 7], length 0
17:58:05.218705 IP x.x.x.145.53167 > y.y.y.209.https: Flags [.], ack 1, win 8211, options [nop,nop,TS val 145724927 ecr 155421022], length 0
17:58:05.220137 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq 1:221, ack 1, win 8211, options [nop,nop,TS val 145724928 ecr 155421022], length 220
17:58:05.254098 IP y.y.y.209.https > x.x.x.145.53167: Flags [.], ack 221, win 122, options [nop,nop,TS val 155421031 ecr 145724928], length 0
17:58:05.259022 IP y.y.y.209.https > x.x.x.145.53167: Flags [.], seq 1:1449, ack 221, win 122, options [nop,nop,TS val 155421032 ecr 145724928], length 1448
17:58:05.259263 IP y.y.y.209.https > x.x.x.145.53167: Flags [.], seq 1449:2897, ack 221, win 122, options [nop,nop,TS val 155421032 ecr 145724928], length 1448
17:58:05.259335 IP x.x.x.145.53167 > y.y.y.209.https: Flags [.], ack 2897, win 8030, options [nop,nop,TS val 145724966 ecr 155421032], length 0
17:58:05.259425 IP y.y.y.209.https > x.x.x.145.53167: Flags [P.], seq 2897:2996, ack 221, win 122, options [nop,nop,TS val 155421032 ecr 145724928], length 99
17:58:05.259451 IP x.x.x.145.53167 > y.y.y.209.https: Flags [.], ack 2996, win 8023, options [nop,nop,TS val 145724966 ecr 155421032], length 0
17:58:05.261592 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq 221:296, ack 2996, win 8192, options [nop,nop,TS val 145724968 ecr 155421032], length 75
17:58:05.262989 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq 296:302, ack 2996, win 8192, options [nop,nop,TS val 145724969 ecr 155421032], length 6
17:58:05.263196 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq 302:355, ack 2996, win 8192, options [nop,nop,TS val 145724969 ecr 155421032], length 53
17:58:05.295347 IP y.y.y.209.https > x.x.x.145.53167: Flags [.], ack 355, win 122, options [nop,nop,TS val 155421041 ecr 145724968], length 0
17:58:05.295387 IP y.y.y.209.https > x.x.x.145.53167: Flags [P.], seq 2996:3055, ack 355, win 122, options [nop,nop,TS val 155421042 ecr 145724968], length 59
17:58:05.295481 IP x.x.x.145.53167 > y.y.y.209.https: Flags [.], ack 3055, win 8188, options [nop,nop,TS val 145725000 ecr 155421042], length 0
17:58:05.300058 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq 355:728, ack 3055, win 8192, options [nop,nop,TS val 145725004 ecr 155421042], length 373
17:58:05.300253 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq 728:765, ack 3055, win 8192, options [nop,nop,TS val 145725004 ecr 155421042], length 37
17:58:05.300254 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq 765:962, ack 3055, win 8192, options [nop,nop,TS val 145725004 ecr 155421042], length 197
17:58:05.300282 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq 962:999, ack 3055, win 8192, options [nop,nop,TS val 145725004 ecr 155421042], length 37
17:58:05.300307 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq 999:1036, ack 3055, win 8192, options [nop,nop,TS val 145725004 ecr 155421042], length 37
17:58:05.300342 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq 1036:1073, ack 3055, win 8192, options [nop,nop,TS val 145725004 ecr 155421042], length 37
17:58:05.300365 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq 1073:1110, ack 3055, win 8192, options [nop,nop,TS val 145725004 ecr 155421042], length 37
17:58:05.332040 IP y.y.y.209.https > x.x.x.145.53167: Flags [.], ack 765, win 130, options [nop,nop,TS val 155421051 ecr 145725004], length 0
17:58:05.332247 IP y.y.y.209.https > x.x.x.145.53167: Flags [.], ack 1110, win 139, options [nop,nop,TS val 155421051 ecr 145725004], length 0
17:59:05.338429 IP y.y.y.209.https > x.x.x.145.53167: Flags [F.], seq 3055, ack 1110, win 139, options [nop,nop,TS val 155436119 ecr 145725004], length 0
17:59:05.338581 IP x.x.x.145.53167 > y.y.y.209.https: Flags [.], ack 3056, win 8192, options [nop,nop,TS val 145784751 ecr 155436119], length 0
17:59:05.338932 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq 1110:1147, ack 3056, win 8192, options [nop,nop,TS val 145784751 ecr 155436119], length 37
17:59:05.338933 IP x.x.x.145.53167 > y.y.y.209.https: Flags [F.], seq 1147, ack 3056, win 8192, options [nop,nop,TS val 145784751 ecr 155436119], length 0
17:59:05.370400 IP y.y.y.209.https > x.x.x.145.53167: Flags [R], seq 325468762, win 0, length 0
-------------- next part --------------
2013/11/20 01:58:04 [debug] 52611#0: *619 http check ssl handshake
2013/11/20 01:58:04 [debug] 52611#0: *619 http recv(): 1
2013/11/20 01:58:04 [debug] 52611#0: *619 https ssl handshake: 0x16
2013/11/20 01:58:04 [debug] 52611#0: *619 posix_memalign: 0000000000F0C650:256 @16
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL server name: "opendata.test-socrata.com"
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_do_handshake: -1
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_get_error: 2
2013/11/20 01:58:04 [debug] 52611#0: *619 reusable connection: 0
2013/11/20 01:58:04 [debug] 52611#0: *619 post event 0000000000E8F5A8
2013/11/20 01:58:04 [debug] 52611#0: *619 delete posted event 0000000000E8F5A8
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL handshake handler: 0
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_do_handshake: 1
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL: TLSv1, cipher: "ECDHE-RSA-AES128-SHA SSLv3 Kx=ECDH Au=RSA Enc=AES(128) Mac=SHA1"
2013/11/20 01:58:04 [debug] 52611#0: *619 reusable connection: 1
2013/11/20 01:58:04 [debug] 52611#0: *619 http wait request handler
2013/11/20 01:58:04 [debug] 52611#0: *619 malloc: 0000000000F1BE20:1024
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_read: -1
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_get_error: 2
2013/11/20 01:58:04 [debug] 52611#0: *619 free: 0000000000F1BE20
2013/11/20 01:58:04 [debug] 52611#0: *619 post event 0000000000E8F5A8
2013/11/20 01:58:04 [debug] 52611#0: *619 delete posted event 0000000000E8F5A8
2013/11/20 01:58:04 [debug] 52611#0: *619 http wait request handler
2013/11/20 01:58:04 [debug] 52611#0: *619 malloc: 0000000000F1BE20:1024
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_read: 335
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_read: 1
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_read: 167
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_read: 1
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_read: 2
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_read: 1
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_read: 1
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_read: -1
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_get_error: 2
2013/11/20 01:58:04 [debug] 52611#0: *619 reusable connection: 0
2013/11/20 01:58:04 [debug] 52611#0: *619 posix_memalign: 0000000000EFB600:4096 @16
2013/11/20 01:58:04 [debug] 52611#0: *619 http process request line
2013/11/20 01:58:04 [debug] 52611#0: *619 http request line: "POST /api/views/uv4d-it6e/columns?$$version=2.0 HTTP/1.1"
2013/11/20 01:58:04 [debug] 52611#0: *619 http uri: "/api/views/uv4d-it6e/columns"
2013/11/20 01:58:04 [debug] 52611#0: *619 http args: "$$version=2.0"
2013/11/20 01:58:04 [debug] 52611#0: *619 http exten: ""
2013/11/20 01:58:04 [debug] 52611#0: *619 http process request header line
2013/11/20 01:58:04 [debug] 52611#0: *619 http header: "Accept: application/json"
2013/11/20 01:58:04 [debug] 52611#0: *619 http header: "Content-Type: application/json"
2013/11/20 01:58:04 [debug] 52611#0: *619 http header: "X-App-Token: Ya8CU9HKxeh0ytjHJttm2FhaW"
2013/11/20 01:58:04 [debug] 52611#0: *619 http header: "Authorization: Basic d2lsbC5wdWdoQHNvY3JhdGEuY29tOlNzbjEyMzQ1Ng=="
2013/11/20 01:58:04 [debug] 52611#0: *619 http header: "User-Agent: Java/1.7.0_12-ea"
2013/11/20 01:58:04 [debug] 52611#0: *619 http header: "Host: opendata.test-socrata.com"
2013/11/20 01:58:04 [debug] 52611#0: *619 http header: "Connection: close"
2013/11/20 01:58:04 [debug] 52611#0: *619 http header: "Transfer-Encoding: chunked"
2013/11/20 01:58:04 [debug] 52611#0: *619 http header done
2013/11/20 01:58:04 [debug] 52611#0: *619 event timer del: 11: 1384912744424
2013/11/20 01:58:04 [debug] 52611#0: *619 generic phase: 0
2013/11/20 01:58:04 [debug] 52611#0: *619 rewrite phase: 1
2013/11/20 01:58:04 [debug] 52611#0: *619 test location: "/"
2013/11/20 01:58:04 [debug] 52611#0: *619 test location: "socket.io"
2013/11/20 01:58:04 [debug] 52611#0: *619 using configuration "/"
2013/11/20 01:58:04 [debug] 52611#0: *619 http cl:-1 max:25769803776
2013/11/20 01:58:04 [debug] 52611#0: *619 rewrite phase: 3
2013/11/20 01:58:04 [debug] 52611#0: *619 posix_memalign: 0000000000F18E70:4096 @16
2013/11/20 01:58:04 [debug] 52611#0: *619 http script complex value
2013/11/20 01:58:04 [debug] 52611#0: *619 http script var: "/var/www/nginx-default"
2013/11/20 01:58:04 [debug] 52611#0: *619 http script copy: "/maintenance.html^@"
2013/11/20 01:58:04 [debug] 52611#0: *619 http script file op 0000000000000000 "/var/www/nginx-default/maintenance.html"
2013/11/20 01:58:04 [debug] 52611#0: *619 http script file op false
2013/11/20 01:58:04 [debug] 52611#0: *619 http script if
2013/11/20 01:58:04 [debug] 52611#0: *619 http script if: false
2013/11/20 01:58:04 [debug] 52611#0: *619 post rewrite phase: 4
2013/11/20 01:58:04 [debug] 52611#0: *619 generic phase: 5
2013/11/20 01:58:04 [debug] 52611#0: *619 generic phase: 6
2013/11/20 01:58:04 [debug] 52611#0: *619 generic phase: 7
2013/11/20 01:58:04 [debug] 52611#0: *619 access phase: 8
2013/11/20 01:58:04 [debug] 52611#0: *619 access phase: 9
2013/11/20 01:58:04 [debug] 52611#0: *619 post access phase: 10
2013/11/20 01:58:04 [debug] 52611#0: *619 http client request body preread 173
2013/11/20 01:58:04 [debug] 52611#0: *619 http request body chunked filter
2013/11/20 01:58:04 [debug] 52611#0: *619 http body chunked buf t:1 f:0 0000000000F1BE20, pos 0000000000F1BF6F, size: 173 file: 0, size: 0
2013/11/20 01:58:04 [debug] 52611#0: *619 http chunked byte: 61 s:0
2013/11/20 01:58:04 [debug] 52611#0: *619 http chunked byte: 32 s:1
2013/11/20 01:58:04 [debug] 52611#0: *619 http chunked byte: 0D s:1
2013/11/20 01:58:04 [debug] 52611#0: *619 http chunked byte: 0A s:3
2013/11/20 01:58:04 [debug] 52611#0: *619 http chunked byte: 7B s:4
2013/11/20 01:58:04 [debug] 52611#0: *619 http body chunked buf t:1 f:0 0000000000F1BE20, pos 0000000000F1C015, size: 7 file: 0, size: 0
2013/11/20 01:58:04 [debug] 52611#0: *619 http chunked byte: 0D s:5
2013/11/20 01:58:04 [debug] 52611#0: *619 http chunked byte: 0A s:6
2013/11/20 01:58:04 [debug] 52611#0: *619 http chunked byte: 30 s:0
2013/11/20 01:58:04 [debug] 52611#0: *619 http chunked byte: 0D s:1
2013/11/20 01:58:04 [debug] 52611#0: *619 http chunked byte: 0A s:8
2013/11/20 01:58:04 [debug] 52611#0: *619 http chunked byte: 0D s:9
2013/11/20 01:58:04 [debug] 52611#0: *619 http chunked byte: 0A s:10
2013/11/20 01:58:04 [debug] 52611#0: *619 http body new buf t:1 f:0 0000000000F1BF73, pos 0000000000F1BF73, size: 162 file: 0, size: 0
2013/11/20 01:58:04 [debug] 52611#0: *619 http body new buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2013/11/20 01:58:04 [debug] 52611#0: *619 http init upstream, client timer: 0
2013/11/20 01:58:04 [debug] 52611#0: *619 epoll add event: fd:11 op:3 ev:80000005
2013/11/20 01:58:04 [debug] 52611#0: *619 http script copy: "X-Forwarded-For: "
2013/11/20 01:58:04 [debug] 52611#0: *619 http script var: "66.171.190.186"
2013/11/20 01:58:04 [debug] 52611#0: *619 http script copy: "^M
"
2013/11/20 01:58:04 [debug] 52611#0: *619 http script copy: "X-Forwarded-Proto: "
2013/11/20 01:58:04 [debug] 52611#0: *619 http script var: "https"
2013/11/20 01:58:04 [debug] 52611#0: *619 http script copy: "^M
"
2013/11/20 01:58:04 [debug] 52611#0: *619 http script copy: "Host: "
2013/11/20 01:58:04 [debug] 52611#0: *619 http script var: "opendata.test-socrata.com"
2013/11/20 01:58:04 [debug] 52611#0: *619 http script copy: "^M
"
2013/11/20 01:58:04 [debug] 52611#0: *619 http script copy: "Connection: close^M
"
2013/11/20 01:58:04 [debug] 52611#0: *619 http script copy: "Content-Length: "
2013/11/20 01:58:04 [debug] 52611#0: *619 http script var: "162"
2013/11/20 01:58:04 [debug] 52611#0: *619 http script copy: "^M
"
2013/11/20 01:58:04 [debug] 52611#0: *619 http proxy header: "Accept: application/json"
2013/11/20 01:58:04 [debug] 52611#0: *619 http proxy header: "Content-Type: application/json"
2013/11/20 01:58:04 [debug] 52611#0: *619 http proxy header: "X-App-Token: Ya8CU9HKxeh0ytjHJttm2FhaW"
2013/11/20 01:58:04 [debug] 52611#0: *619 http proxy header: "Authorization: Basic d2lsbC5wdWdoQHNvY3JhdGEuY29tOlNzbjEyMzQ1Ng=="
2013/11/20 01:58:04 [debug] 52611#0: *619 http proxy header: "User-Agent: Java/1.7.0_12-ea"
2013/11/20 01:58:04 [debug] 52611#0: *619 http proxy header:
"POST /api/views/uv4d-it6e/columns?$$version=2.0 HTTP/1.0^M
X-Forwarded-For: 66.171.190.186^M
X-Forwarded-Proto: https^M
Host: opendata.test-socrata.com^M
Connection: close^M
Content-Length: 162^M
Accept: application/json^M
Content-Type: application/json^M
X-App-Token: Ya8CU9HKxeh0ytjHJttm2FhaW^M
Authorization: Basic d2lsbC5wdWdoQHNvY3JhdGEuY29tOlNzbjEyMzQ1Ng==^M
User-Agent: Java/1.7.0_12-ea^M
^M
"
2013/11/20 01:58:04 [debug] 52611#0: *619 http cleanup add: 0000000000F198D0
2013/11/20 01:58:04 [debug] 52611#0: *619 get rr peer, try: 1
2013/11/20 01:58:04 [debug] 52611#0: *619 socket 13
2013/11/20 01:58:04 [debug] 52611#0: *619 epoll add connection: fd:13 ev:80000005
2013/11/20 01:58:04 [debug] 52611#0: *619 connect to 0.0.0.0:8080, fd:13 #620
2013/11/20 01:58:04 [debug] 52611#0: *619 http upstream connect: -2
2013/11/20 01:58:04 [debug] 52611#0: *619 posix_memalign: 0000000000F09100:128 @16
2013/11/20 01:58:04 [debug] 52611#0: *619 event timer add: 13: 60000:1384912744514
2013/11/20 01:58:04 [debug] 52611#0: *619 http finalize request: -4, "/api/views/uv4d-it6e/columns?$$version=2.0" a:1, c:2
2013/11/20 01:58:04 [debug] 52611#0: *619 http request count:2 blk:0
2013/11/20 01:58:04 [debug] 52611#0: *619 post event 0000000000EC35B8
2013/11/20 01:58:04 [debug] 52611#0: *619 post event 0000000000EC3620
2013/11/20 01:58:04 [debug] 52611#0: *619 delete posted event 0000000000EC3620
2013/11/20 01:58:04 [debug] 52611#0: *619 http upstream request: "/api/views/uv4d-it6e/columns?$$version=2.0"
2013/11/20 01:58:04 [debug] 52611#0: *619 http upstream send request handler
2013/11/20 01:58:04 [debug] 52611#0: *619 http upstream send request
2013/11/20 01:58:04 [debug] 52611#0: *619 chain writer buf fl:0 s:387
2013/11/20 01:58:04 [debug] 52611#0: *619 chain writer buf fl:0 s:162
2013/11/20 01:58:04 [debug] 52611#0: *619 chain writer buf fl:1 s:0
2013/11/20 01:58:04 [debug] 52611#0: *619 chain writer in: 0000000000F19938
2013/11/20 01:58:04 [debug] 52611#0: *619 writev: 549
2013/11/20 01:58:04 [debug] 52611#0: *619 chain writer out: 0000000000000000
2013/11/20 01:58:04 [debug] 52611#0: *619 event timer del: 13: 1384912744514
2013/11/20 01:58:04 [debug] 52611#0: *619 event timer add: 13: 10800000:1384923484515
2013/11/20 01:58:04 [debug] 52611#0: *619 delete posted event 0000000000EC35B8
2013/11/20 01:58:04 [debug] 52611#0: *619 http run request: "/api/views/uv4d-it6e/columns?$$version=2.0"
2013/11/20 01:58:04 [debug] 52611#0: *619 http upstream check client, write event:1, "/api/views/uv4d-it6e/columns"
2013/11/20 01:58:04 [debug] 52611#0: *619 http upstream recv(): -1 (11: Resource temporarily unavailable)
2013/11/20 01:58:05 [debug] 52611#0: *619 post event 0000000000E8F610
2013/11/20 01:58:05 [debug] 52611#0: *619 post event 0000000000EC3620
2013/11/20 01:58:05 [debug] 52611#0: *619 delete posted event 0000000000EC3620
2013/11/20 01:58:05 [debug] 52611#0: *619 http upstream request: "/api/views/uv4d-it6e/columns?$$version=2.0"
2013/11/20 01:58:05 [debug] 52611#0: *619 http upstream dummy handler
2013/11/20 01:58:05 [debug] 52611#0: *619 delete posted event 0000000000E8F610
2013/11/20 01:58:05 [debug] 52611#0: *619 http upstream request: "/api/views/uv4d-it6e/columns?$$version=2.0"
2013/11/20 01:58:05 [debug] 52611#0: *619 http upstream process header
2013/11/20 01:58:05 [debug] 52611#0: *619 malloc: 0000000000F0EAE0:8192
2013/11/20 01:58:05 [debug] 52611#0: *619 recv: fd:13 397 of 8192
2013/11/20 01:58:05 [debug] 52611#0: *619 http proxy status 200 "200 OK"
2013/11/20 01:58:05 [debug] 52611#0: *619 http proxy header: "Date: Wed, 20 Nov 2013 01:58:04 GMT"
2013/11/20 01:58:05 [debug] 52611#0: *619 http proxy header: "Access-Control-Allow-Origin: *"
2013/11/20 01:58:05 [debug] 52611#0: *619 http proxy header: "Content-Type: application/json; charset=utf-8"
2013/11/20 01:58:05 [debug] 52611#0: *619 http proxy header: "Server: ATS/4.0.2"
2013/11/20 01:58:05 [debug] 52611#0: *619 http proxy header: "Age: 2"
2013/11/20 01:58:05 [debug] 52611#0: *619 http proxy header done
2013/11/20 01:58:05 [debug] 52611#0: *619 HTTP/1.1 200 OK^M
Server: nginx^M
Date: Wed, 20 Nov 2013 01:58:05 GMT^M
Content-Type: application/json; charset=utf-8^M
Transfer-Encoding: chunked^M
Connection: close^M
Access-Control-Allow-Origin: *^M
Age: 2^M

2013/11/20 01:58:05 [debug] 52611#0: *619 write new buf t:1 f:0 0000000000F19C28, pos 0000000000F19C28, size: 205 file: 0, size: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 http write filter: l:0 f:0 s:205
2013/11/20 01:58:05 [debug] 52611#0: *619 http cacheable: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 http proxy filter init s:200 h:0 c:0 l:-1
2013/11/20 01:58:05 [debug] 52611#0: *619 http upstream process upstream
2013/11/20 01:58:05 [debug] 52611#0: *619 pipe read upstream: 1
2013/11/20 01:58:05 [debug] 52611#0: *619 pipe preread: 235
2013/11/20 01:58:05 [debug] 52611#0: *619 readv: 1:7795
2013/11/20 01:58:05 [debug] 52611#0: *619 readv() not ready (11: Resource temporarily unavailable)
2013/11/20 01:58:05 [debug] 52611#0: *619 pipe recv chain: -2
2013/11/20 01:58:05 [debug] 52611#0: *619 pipe buf free s:0 t:1 f:0 0000000000F0EAE0, pos 0000000000F0EB82, size: 235 file: 0, size: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 pipe length: -1
2013/11/20 01:58:05 [debug] 52611#0: *619 pipe write downstream: 1
2013/11/20 01:58:05 [debug] 52611#0: *619 pipe write busy: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 pipe write: out:0000000000000000, f:0
2013/11/20 01:58:05 [debug] 52611#0: *619 pipe read upstream: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 pipe buf free s:0 t:1 f:0 0000000000F0EAE0, pos 0000000000F0EB82, size: 235 file: 0, size: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 pipe length: -1
2013/11/20 01:58:05 [debug] 52611#0: *619 event timer del: 13: 1384923484515
2013/11/20 01:58:05 [debug] 52611#0: *619 event timer add: 13: 10800000:1384923485118
2013/11/20 01:58:05 [debug] 52611#0: *619 post event 0000000000E8F610
2013/11/20 01:58:05 [debug] 52611#0: *619 post event 0000000000EC3620
2013/11/20 01:58:05 [debug] 52611#0: *619 delete posted event 0000000000EC3620
2013/11/20 01:58:05 [debug] 52611#0: *619 http upstream request: "/api/views/uv4d-it6e/columns?$$version=2.0"
2013/11/20 01:58:05 [debug] 52611#0: *619 http upstream dummy handler
2013/11/20 01:58:05 [debug] 52611#0: *619 delete posted event 0000000000E8F610
2013/11/20 01:58:05 [debug] 52611#0: *619 http upstream request: "/api/views/uv4d-it6e/columns?$$version=2.0"
2013/11/20 01:58:05 [debug] 52611#0: *619 http upstream process upstream
2013/11/20 01:58:05 [debug] 52611#0: *619 pipe read upstream: 1
2013/11/20 01:58:05 [debug] 52611#0: *619 readv: 1:7795
2013/11/20 01:58:05 [debug] 52611#0: *619 pipe recv chain: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 pipe buf free s:0 t:1 f:0 0000000000F0EAE0, pos 0000000000F0EB82, size: 235 file: 0, size: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 pipe length: -1
2013/11/20 01:58:05 [debug] 52611#0: *619 input buf #0
2013/11/20 01:58:05 [debug] 52611#0: *619 pipe write downstream: 1
2013/11/20 01:58:05 [debug] 52611#0: *619 pipe write downstream flush in
2013/11/20 01:58:05 [debug] 52611#0: *619 http output filter "/api/views/uv4d-it6e/columns?$$version=2.0"
2013/11/20 01:58:05 [debug] 52611#0: *619 http copy filter: "/api/views/uv4d-it6e/columns?$$version=2.0"
2013/11/20 01:58:05 [debug] 52611#0: *619 posix_memalign: 0000000000F19FD0:4096 @16
2013/11/20 01:58:05 [debug] 52611#0: *619 http postpone filter "/api/views/uv4d-it6e/columns?$$version=2.0" 0000000000F19908
2013/11/20 01:58:05 [debug] 52611#0: *619 http chunk: 235
2013/11/20 01:58:05 [debug] 52611#0: *619 write old buf t:1 f:0 0000000000F19C28, pos 0000000000F19C28, size: 205 file: 0, size: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 write new buf t:1 f:0 0000000000F1A0A8, pos 0000000000F1A0A8, size: 4 file: 0, size: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 write new buf t:1 f:0 0000000000F0EAE0, pos 0000000000F0EB82, size: 235 file: 0, size: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 write new buf t:0 f:0 0000000000000000, pos 0000000000493E1D, size: 2 file: 0, size: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 http write filter: l:0 f:0 s:446
2013/11/20 01:58:05 [debug] 52611#0: *619 http copy filter: 0 "/api/views/uv4d-it6e/columns?$$version=2.0"
2013/11/20 01:58:05 [debug] 52611#0: *619 pipe write downstream done
2013/11/20 01:58:05 [debug] 52611#0: *619 event timer: 13, old: 1384923485118, new: 1384923485121
2013/11/20 01:58:05 [debug] 52611#0: *619 http upstream exit: 0000000000000000
2013/11/20 01:58:05 [debug] 52611#0: *619 finalize http upstream request: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 finalize http proxy request
2013/11/20 01:58:05 [debug] 52611#0: *619 free rr peer 1 0
2013/11/20 01:58:05 [debug] 52611#0: *619 close http upstream connection: 13
2013/11/20 01:58:05 [debug] 52611#0: *619 free: 0000000000F09100, unused: 48
2013/11/20 01:58:05 [debug] 52611#0: *619 event timer del: 13: 1384923485118
2013/11/20 01:58:05 [debug] 52611#0: *619 reusable connection: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 http upstream temp fd: -1
2013/11/20 01:58:05 [debug] 52611#0: *619 http output filter "/api/views/uv4d-it6e/columns?$$version=2.0"
2013/11/20 01:58:05 [debug] 52611#0: *619 http copy filter: "/api/views/uv4d-it6e/columns?$$version=2.0"
2013/11/20 01:58:05 [debug] 52611#0: *619 http postpone filter "/api/views/uv4d-it6e/columns?$$version=2.0" 00007FFF96EB3030
2013/11/20 01:58:05 [debug] 52611#0: *619 http chunk: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 write old buf t:1 f:0 0000000000F19C28, pos 0000000000F19C28, size: 205 file: 0, size: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 write old buf t:1 f:0 0000000000F1A0A8, pos 0000000000F1A0A8, size: 4 file: 0, size: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 write old buf t:1 f:0 0000000000F0EAE0, pos 0000000000F0EB82, size: 235 file: 0, size: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 write old buf t:0 f:0 0000000000000000, pos 0000000000493E1D, size: 2 file: 0, size: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 write new buf t:0 f:0 0000000000000000, pos 0000000000493E1A, size: 5 file: 0, size: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 http write filter: l:1 f:0 s:451
2013/11/20 01:58:05 [debug] 52611#0: *619 http write filter limit 0
2013/11/20 01:58:05 [debug] 52611#0: *619 posix_memalign: 0000000000F099A0:256 @16
2013/11/20 01:58:05 [debug] 52611#0: *619 malloc: 0000000000EF7490:16384
2013/11/20 01:58:05 [debug] 52611#0: *619 SSL buf copy: 205
2013/11/20 01:58:05 [debug] 52611#0: *619 SSL buf copy: 4
2013/11/20 01:58:05 [debug] 52611#0: *619 SSL buf copy: 235
2013/11/20 01:58:05 [debug] 52611#0: *619 SSL buf copy: 2
2013/11/20 01:58:05 [debug] 52611#0: *619 SSL buf copy: 5
2013/11/20 01:58:05 [debug] 52611#0: *619 SSL to write: 451
2013/11/20 01:58:05 [debug] 52611#0: *619 SSL_write: 451
2013/11/20 01:58:05 [debug] 52611#0: *619 http write filter 0000000000000000
2013/11/20 01:58:05 [debug] 52611#0: *619 http copy filter: 0 "/api/views/uv4d-it6e/columns?$$version=2.0"
2013/11/20 01:58:05 [debug] 52611#0: *619 http finalize request: 0, "/api/views/uv4d-it6e/columns?$$version=2.0" a:1, c:1
2013/11/20 01:58:05 [debug] 52611#0: *619 event timer add: 11: 5000:1384912690121
2013/11/20 01:58:05 [debug] 52611#0: *619 post event 0000000000EC35B8
2013/11/20 01:58:05 [debug] 52611#0: *619 delete posted event 0000000000EC35B8
2013/11/20 01:58:05 [debug] 52611#0: *619 http empty handler
2013/11/20 01:58:05 [debug] 52611#0: *619 post event 0000000000E8F5A8
2013/11/20 01:58:05 [debug] 52611#0: *619 post event 0000000000EC35B8
2013/11/20 01:58:05 [debug] 52611#0: *619 delete posted event 0000000000EC35B8
2013/11/20 01:58:05 [debug] 52611#0: *619 http empty handler
2013/11/20 01:58:05 [debug] 52611#0: *619 delete posted event 0000000000E8F5A8
2013/11/20 01:58:05 [debug] 52611#0: *619 http lingering close handler
2013/11/20 01:58:05 [debug] 52611#0: *619 SSL_read: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 SSL_get_error: 6
2013/11/20 01:58:05 [debug] 52611#0: *619 peer shutdown SSL cleanly
2013/11/20 01:58:05 [debug] 52611#0: *619 lingering read: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 http request count:1 blk:0
2013/11/20 01:58:05 [debug] 52611#0: *619 http close request
2013/11/20 01:58:05 [debug] 52611#0: *619 http log handler
2013/11/20 01:58:05 [debug] 52611#0: *619 free: 0000000000F0EAE0
2013/11/20 01:58:05 [debug] 52611#0: *619 free: 0000000000EFB600, unused: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 free: 0000000000F18E70, unused: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 free: 0000000000F19FD0, unused: 3310
2013/11/20 01:58:05 [debug] 52611#0: *619 close http connection: 11
2013/11/20 01:58:05 [debug] 52611#0: *619 SSL_shutdown: 1
2013/11/20 01:58:05 [debug] 52611#0: *619 event timer del: 11: 1384912690121
2013/11/20 01:58:05 [debug] 52611#0: *619 reusable connection: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 free: 0000000000EF7490
2013/11/20 01:58:05 [debug] 52611#0: *619 free: 0000000000F1BE20
2013/11/20 01:58:05 [debug] 52611#0: *619 free: 0000000000E1F1A0, unused: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 free: 0000000000F0C650, unused: 0
2013/11/20 01:58:05 [debug] 52611#0: *619 free: 0000000000F099A0, unused: 144
2013/11/20 01:58:05 [debug] 52611#0: *621 accept: 66.171.190.186 fd:11
2013/11/20 01:58:05 [debug] 52611#0: *621 event timer add: 11: 60000:1384912745204
2013/11/20 01:58:05 [debug] 52611#0: *621 reusable connection: 1
2013/11/20 01:58:05 [debug] 52611#0: *621 epoll add event: fd:11 op:1 ev:80000001
2013/11/20 01:58:05 [debug] 52611#0: *621 post event 0000000000E8F5A8
2013/11/20 01:58:05 [debug] 52611#0: *621 delete posted event 0000000000E8F5A8
2013/11/20 01:58:05 [debug] 52611#0: *621 http check ssl handshake
2013/11/20 01:58:05 [debug] 52611#0: *621 http recv(): 1
2013/11/20 01:58:05 [debug] 52611#0: *621 https ssl handshake: 0x16
2013/11/20 01:58:05 [debug] 52611#0: *621 posix_memalign: 0000000000F0C650:256 @16
2013/11/20 01:58:05 [debug] 52611#0: *621 SSL server name: "opendata.test-socrata.com"
2013/11/20 01:58:05 [debug] 52611#0: *621 SSL_do_handshake: -1
2013/11/20 01:58:05 [debug] 52611#0: *621 SSL_get_error: 2
2013/11/20 01:58:05 [debug] 52611#0: *621 reusable connection: 0
2013/11/20 01:58:05 [debug] 52611#0: *621 post event 0000000000E8F5A8
2013/11/20 01:58:05 [debug] 52611#0: *621 delete posted event 0000000000E8F5A8
2013/11/20 01:58:05 [debug] 52611#0: *621 SSL handshake handler: 0
2013/11/20 01:58:05 [debug] 52611#0: *621 SSL_do_handshake: -1
2013/11/20 01:58:05 [debug] 52611#0: *621 SSL_get_error: 2
2013/11/20 01:58:05 [debug] 52611#0: *621 post event 0000000000E8F5A8
2013/11/20 01:58:05 [debug] 52611#0: *621 delete posted event 0000000000E8F5A8
-------------- next part --------------
17:58:04.412927 IP x.x.x.145.53166 > y.y.y.209.https: Flags [S], seq 3988579492, win 65535, options [mss 1460,nop,wscale 4,nop,nop,TS val 145724129 ecr 0,sackOK,eol], length 0
17:58:04.444282 IP y.y.y.209.https > x.x.x.145.53166: Flags [S.], seq 3152825397, ack 3988579493, win 14480, options [mss 1440,sackOK,TS val 155420828 ecr 145724129,nop,wscale 7], length 0
17:58:04.444324 IP y.y.y.209.https > x.x.x.145.53165: Flags [.], ack 1148, win 139, options [nop,nop,TS val 155420828 ecr 145724128], length 0
17:58:04.444344 IP x.x.x.145.53166 > y.y.y.209.https: Flags [.], ack 1, win 8211, options [nop,nop,TS val 145724160 ecr 155420828], length 0
17:58:04.445103 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq 1:221, ack 1, win 8211, options [nop,nop,TS val 145724160 ecr 155420828], length 220
17:58:04.476946 IP y.y.y.209.https > x.x.x.145.53166: Flags [.], ack 221, win 122, options [nop,nop,TS val 155420836 ecr 145724160], length 0
17:58:04.481414 IP y.y.y.209.https > x.x.x.145.53166: Flags [.], seq 1:1449, ack 221, win 122, options [nop,nop,TS val 155420837 ecr 145724160], length 1448
17:58:04.481502 IP y.y.y.209.https > x.x.x.145.53166: Flags [.], seq 1449:2897, ack 221, win 122, options [nop,nop,TS val 155420837 ecr 145724160], length 1448
17:58:04.481582 IP x.x.x.145.53166 > y.y.y.209.https: Flags [.], ack 2897, win 8030, options [nop,nop,TS val 145724196 ecr 155420837], length 0
17:58:04.481657 IP y.y.y.209.https > x.x.x.145.53166: Flags [P.], seq 2897:2996, ack 221, win 122, options [nop,nop,TS val 155420837 ecr 145724160], length 99
17:58:04.481722 IP x.x.x.145.53166 > y.y.y.209.https: Flags [.], ack 2996, win 8023, options [nop,nop,TS val 145724196 ecr 155420837], length 0
17:58:04.484108 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq 221:296, ack 2996, win 8192, options [nop,nop,TS val 145724198 ecr 155420837], length 75
17:58:04.485569 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq 296:302, ack 2996, win 8192, options [nop,nop,TS val 145724199 ecr 155420837], length 6
17:58:04.485767 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq 302:355, ack 2996, win 8192, options [nop,nop,TS val 145724199 ecr 155420837], length 53
17:58:04.531685 IP y.y.y.209.https > x.x.x.145.53166: Flags [.], ack 355, win 122, options [nop,nop,TS val 155420850 ecr 145724198], length 0
17:58:04.531689 IP y.y.y.209.https > x.x.x.145.53166: Flags [P.], seq 2996:3055, ack 355, win 122, options [nop,nop,TS val 155420850 ecr 145724198], length 59
17:58:04.531827 IP x.x.x.145.53166 > y.y.y.209.https: Flags [.], ack 3055, win 8188, options [nop,nop,TS val 145724244 ecr 155420850], length 0
17:58:04.532709 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq 355:728, ack 3055, win 8192, options [nop,nop,TS val 145724244 ecr 155420850], length 373
17:58:04.532906 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq 728:765, ack 3055, win 8192, options [nop,nop,TS val 145724245 ecr 155420850], length 37
17:58:04.532954 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq 765:962, ack 3055, win 8192, options [nop,nop,TS val 145724245 ecr 155420850], length 197
17:58:04.532983 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq 962:999, ack 3055, win 8192, options [nop,nop,TS val 145724245 ecr 155420850], length 37
17:58:04.533012 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq 999:1036, ack 3055, win 8192, options [nop,nop,TS val 145724245 ecr 155420850], length 37
17:58:04.533045 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq 1036:1073, ack 3055, win 8192, options [nop,nop,TS val 145724245 ecr 155420850], length 37
17:58:04.533143 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq 1073:1110, ack 3055, win 8192, options [nop,nop,TS val 145724245 ecr 155420850], length 37
17:58:04.565176 IP y.y.y.209.https > x.x.x.145.53166: Flags [.], ack 962, win 139, options [nop,nop,TS val 155420858 ecr 145724244], length 0
17:58:04.565184 IP y.y.y.209.https > x.x.x.145.53166: Flags [.], ack 1110, win 139, options [nop,nop,TS val 155420858 ecr 145724245], length 0
17:58:05.184331 IP y.y.y.209.https > x.x.x.145.53166: Flags [P.], seq 3055:3540, ack 1110, win 139, options [nop,nop,TS val 155421011 ecr 145724245], length 485
17:58:05.184442 IP x.x.x.145.53166 > y.y.y.209.https: Flags [.], ack 3540, win 8161, options [nop,nop,TS val 145724894 ecr 155421011], length 0
17:58:05.184592 IP y.y.y.209.https > x.x.x.145.53166: Flags [F.], seq 3540, ack 1110, win 139, options [nop,nop,TS val 155421011 ecr 145724245], length 0
17:58:05.184658 IP x.x.x.145.53166 > y.y.y.209.https: Flags [.], ack 3541, win 8192, options [nop,nop,TS val 145724894 ecr 155421011], length 0
17:58:05.184863 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq 1110:1147, ack 3541, win 8192, options [nop,nop,TS val 145724894 ecr 155421011], length 37
17:58:05.184863 IP x.x.x.145.53166 > y.y.y.209.https: Flags [F.], seq 1147, ack 3541, win 8192, options [nop,nop,TS val 145724894 ecr 155421011], length 0