Issue with spdy and proxy_pass

Detlef_R · February 18, 2014, 3:16pm

Hello,
I compiled nginx 1.5.10 on Centos 6.5 and try to use it as frontend for
Tomcat.
If I use pure SSL everything works fine. But as soon as I enable SPDY, I
only get a blank page.
And Content-Length Header is 0, but HTTP status code is 200.
But, the blank page only affects request which are handled by Tomcat.
Static
files, served by nginx, work with SPDY.

Here my vhost conf:

Redirect everything to ssl

server {
listen 192.168.89.175:80;
server_name example.org www.example.org;
return 301 https://www.example.org$request_uri;
}

Redirect to www

server {
listen 192.168.89.175:443 ssl spdy;
server_name example.org
return 301 https://www.example.org$request_uri;
}
server {
listen 192.168.89.175:443 ssl spdy;
server_name www.example.org;
ssl on;
ssl_certificate /usr/share/nginx/ssl/example.org.crt;
ssl_certificate_key /usr/share/nginx/ssl/example.org.key;

    ssl_protocols TLSv1 TLSv1.1 TLSv1.2;
    ssl_prefer_server_ciphers on;
    ssl_ciphers "EECDH+AESGCM EDH+AESGCM EECDH -RC4 EDH -CAMELLIA

-SEED
!aNULL !eNULL !LOW !3DES !MD5 !EXP !PSK !SRP !DSS !kEDH";
ssl_session_cache builtin:1000 shared:SSL:10m;

    root /usr/share/nginx/html/example.org;

    location / {
    try_files $uri $uri/ /index.cfm?q=$uri&$args;

    }

Proxy CFML to Tomcat/Railo

location ~ .(cfm|cfml|cfc|jsp|cfr)(.*)$ {
proxy_pass http://127.0.0.1:8888;
proxy_pass_request_headers on;
proxy_redirect default;
proxy_set_header Host $host;
proxy_read_timeout 900;
proxy_set_header X-Forwarded-Host $host;
proxy_set_header X-Forwarded-Server $host;
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
proxy_set_header X-Real-IP $remote_addr;
}

Posted at Nginx Forum:

p.heppler · February 18, 2014, 3:25pm

On Tuesday 18 February 2014 09:15:25 p.heppler wrote:

Hello,
I compiled nginx 1.5.10 on Centos 6.5 and try to use it as frontend for
Tomcat.
If I use pure SSL everything works fine. But as soon as I enable SPDY, I
only get a blank page.
And Content-Length Header is 0, but HTTP status code is 200.
But, the blank page only affects request which are handled by Tomcat. Static
files, served by nginx, work with SPDY.

[…]

Could you provide a debug log?
http://nginx.org/en/docs/debugging_log.html

wbr, Valentin V. Bartenev

p.heppler · February 18, 2014, 3:50pm

I meanwhile replaced Tomcat with Jetty, because Jetty also supports
SPDY.
But same result.

Posted at Nginx Forum:

p.heppler · February 18, 2014, 6:49pm

On Tuesday 18 February 2014 09:54:40 p.heppler wrote:

Another run with Tomcat, fresh log:
[…]

In both cases your backend returned a “200 OK” response
with empty body:

2014/02/18 15:46:13 [debug] 12839#0: *2 http proxy status 200 “200 OK”
2014/02/18 15:46:13 [debug] 12839#0: *2 http proxy header:
“Content-Type: text/html; charset=UTF-8”
2014/02/18 15:46:13 [debug] 12839#0: *2 http proxy header:
“Content-Length: 0”
2014/02/18 15:46:13 [debug] 12839#0: *2 http proxy header: “Server:
Jetty(9.0.6.v20130930)”
2014/02/18 15:46:13 [debug] 12839#0: *2 http proxy header done

wbr, Valentin V. Bartenev

p.heppler · February 19, 2014, 9:04am

Strange. As said with pure ssl it works, it’s just the spdy part. I’ll
check
Tomcat logs.

Posted at Nginx Forum:

p.heppler · February 19, 2014, 12:24pm

Hmm, just tried adding
proxy_set_header If-none-Match $http_if_none_match;
to my config and now it works with spdy to.

Why do I need to set this manually when using spdy, but not on “normal”
http/https?
Weird…

Posted at Nginx Forum:

p.heppler · February 19, 2014, 11:06am

I checked Tomcat logs. No errors, just status 200 and zero length. I
appended %v - Local server name to the log to see if $host is passed
thru
correct. It is.

And now it’s getting weird. I replcaed my complex website (which runs
fine
with pure ssl!) with a simple “Hello World” and it works!
Seems the issue was ETag / If-none-match Headers

In my website I set ETag for dynamic pages which don’t change
frequently, so
there was no need to hit database on every request.
As soon I turn this off, my site works.

Posted at Nginx Forum:

p.heppler · February 19, 2014, 3:25pm

On Wednesday 19 February 2014 06:24:41 p.heppler wrote:

Hmm, just tried adding
proxy_set_header If-none-Match $http_if_none_match;
to my config and now it works with spdy to.

Probably it works in this case because browser just shows to you cached
page,
that was retrieved earlier over http or https.

Why do I need to set this manually when using spdy, but not on “normal”
http/https?
Weird…

There’s no difference between SPDY and HTTP/HTTPS. In debug logs, that
you have provided, the client didn’t send “If-none-Match” and it’s
normal.

Anyway, missing or presence “If-none-Match” header shouldn’t result in
empty responses from your backend.

wbr, Valentin V. Bartenev

p.heppler · February 19, 2014, 4:45pm

Damn, seems Firefox didn’t clear the cache even if I told him to do so.
Worked a while, but now blank page again.
But it has to be the Tomcat backend 'cause PHP passed thru to fastcgi
works.

Posted at Nginx Forum:

p.heppler · February 24, 2014, 3:05pm

I got it!
SPDY breaks as soon as my Upstream uses GZip! I turned GZip off in Railo
and
voila it works. Turn it on and get blank page again.

Posted at Nginx Forum:

p.heppler · February 21, 2014, 3:41pm

In Railo you can access some environment and client vars within a struct
called cgi.
If I hit my site with plain ssl it shows cgi.server_port = 80. Should be
443, shouldn’t it?
Hitting Tomcat directly shows cgi.server_port=8888 which is fine.

Posted at Nginx Forum:

p.heppler · February 18, 2014, 3:43pm

I just created a new log. This is from nginx restart to first request:

2014/02/18 15:45:56 [debug] 12839#0: epoll add event: fd:9 op:1
ev:00002001
2014/02/18 15:46:12 [debug] 12839#0: post event 00007F29CC9D1078
2014/02/18 15:46:12 [debug] 12839#0: delete posted event
00007F29CC9D1078
2014/02/18 15:46:12 [debug] 12839#0: accept on 192.168.89.175:443,
ready: 1
2014/02/18 15:46:12 [debug] 12839#0: posix_memalign:
0000000002547890:256
@16
2014/02/18 15:46:12 [debug] 12839#0: *1 accept: 192.168.76.46 fd:15
2014/02/18 15:46:12 [debug] 12839#0: posix_memalign:
0000000002547330:256
@16
2014/02/18 15:46:12 [debug] 12839#0: *1 event timer add: 15:
60000:1392734832664
2014/02/18 15:46:12 [debug] 12839#0: *1 reusable connection: 1
2014/02/18 15:46:12 [debug] 12839#0: *1 epoll add event: fd:15 op:1
ev:80002001
2014/02/18 15:46:12 [debug] 12839#0: accept() not ready (11: Resource
temporarily unavailable)
2014/02/18 15:46:12 [debug] 12839#0: *1 post event 00007F29CC9D1148
2014/02/18 15:46:12 [debug] 12839#0: *1 delete posted event
00007F29CC9D1148
2014/02/18 15:46:12 [debug] 12839#0: *1 http check ssl handshake
2014/02/18 15:46:12 [debug] 12839#0: *1 http recv(): 1
2014/02/18 15:46:12 [debug] 12839#0: *1 https ssl handshake: 0x16
2014/02/18 15:46:12 [debug] 12839#0: *1 SSL server name:
“www.example.org”
2014/02/18 15:46:12 [debug] 12839#0: *1 SSL_do_handshake: 0
2014/02/18 15:46:12 [debug] 12839#0: *1 SSL_get_error: 5
2014/02/18 15:46:12 [info] 12839#0: *1 peer closed connection in SSL
handshake while SSL handshaking, client: 192.168.76.46, server:
192.168.89.175:443
2014/02/18 15:46:12 [debug] 12839#0: *1 close http connection: 15
2014/02/18 15:46:12 [debug] 12839#0: *1 SSL_shutdown: 1
2014/02/18 15:46:12 [debug] 12839#0: *1 event timer del: 15:
1392734832664
2014/02/18 15:46:12 [debug] 12839#0: *1 reusable connection: 0
2014/02/18 15:46:12 [debug] 12839#0: *1 free: 0000000002547890, unused:
16
2014/02/18 15:46:12 [debug] 12839#0: *1 free: 0000000002547330, unused:
114
2014/02/18 15:46:12 [debug] 12839#0: post event 00007F29CC9D1078
2014/02/18 15:46:12 [debug] 12839#0: delete posted event
00007F29CC9D1078
2014/02/18 15:46:12 [debug] 12839#0: accept on 192.168.89.175:443,
ready: 1
2014/02/18 15:46:12 [debug] 12839#0: posix_memalign:
000000000252BF80:256
@16
2014/02/18 15:46:12 [debug] 12839#0: *2 accept: 192.168.76.46 fd:15
2014/02/18 15:46:12 [debug] 12839#0: posix_memalign:
0000000002547890:256
@16
2014/02/18 15:46:12 [debug] 12839#0: *2 event timer add: 15:
60000:1392734832672
2014/02/18 15:46:12 [debug] 12839#0: *2 reusable connection: 1
2014/02/18 15:46:12 [debug] 12839#0: *2 epoll add event: fd:15 op:1
ev:80002001
2014/02/18 15:46:12 [debug] 12839#0: accept() not ready (11: Resource
temporarily unavailable)
2014/02/18 15:46:12 [debug] 12839#0: *2 post event 00007F29CC9D1148
2014/02/18 15:46:12 [debug] 12839#0: *2 delete posted event
00007F29CC9D1148
2014/02/18 15:46:12 [debug] 12839#0: *2 http check ssl handshake
2014/02/18 15:46:12 [debug] 12839#0: *2 http recv(): 1
2014/02/18 15:46:12 [debug] 12839#0: *2 https ssl handshake: 0x16
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL server name:
“www.example.org”
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL NPN advertised
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL_do_handshake: -1
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL_get_error: 2
2014/02/18 15:46:12 [debug] 12839#0: *2 reusable connection: 0
2014/02/18 15:46:12 [debug] 12839#0: *2 post event 00007F29CC9D1148
2014/02/18 15:46:12 [debug] 12839#0: *2 delete posted event
00007F29CC9D1148
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL handshake handler: 0
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL_do_handshake: 1
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL: TLSv1.2, cipher:
“ECDHE-RSA-AES128-GCM-SHA256 TLSv1.2 Kx=ECDH Au=RSA Enc=AESGCM(128)
Mac=AEAD”
2014/02/18 15:46:12 [debug] 12839#0: *2 init spdy request
2014/02/18 15:46:12 [debug] 12839#0: *2 malloc: 00000000024B1AA0:424
2014/02/18 15:46:12 [debug] 12839#0: *2 malloc: 00000000025981A0:9552
2014/02/18 15:46:12 [debug] 12839#0: *2 malloc: 00000000024B5940:5928
2014/02/18 15:46:12 [debug] 12839#0: *2 malloc: 000000000252C290:4096
2014/02/18 15:46:12 [debug] 12839#0: *2 malloc: 000000000259A700:4096
2014/02/18 15:46:12 [debug] 12839#0: *2 malloc: 00000000025A1AD0:4096
2014/02/18 15:46:12 [debug] 12839#0: *2 malloc: 00000000025A2AE0:4096
2014/02/18 15:46:12 [debug] 12839#0: *2 posix_memalign:
00000000025A3AF0:4096 @16
2014/02/18 15:46:12 [debug] 12839#0: *2 posix_memalign:
000000000252D2A0:256
@16
2014/02/18 15:46:12 [debug] 12839#0: *2 add cleanup: 000000000252D2C0
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy create SETTINGS frame
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy write WINDOW_UPDATE sid:0
delta:2147418111
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy read handler
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL_read: -1
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL_get_error: 2
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy frame out: 00000000025A3D00
sid:0 prio:0 bl:0 len:8
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy frame out: 00000000025A3C40
sid:0 prio:0 bl:0 len:20
2014/02/18 15:46:12 [debug] 12839#0: *2 malloc: 00000000025AF180:16384
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL buf copy: 28
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL buf copy: 16
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL to write: 44
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL_write: 44
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy frame sent:
00000000025A3C40
sid:0 bl:0 len:20
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy frame sent:
00000000025A3D00
sid:0 bl:0 len:8
2014/02/18 15:46:12 [debug] 12839#0: *2 free: 00000000025A3AF0, unused:
3392
2014/02/18 15:46:12 [debug] 12839#0: *2 free: 00000000025AF180
2014/02/18 15:46:12 [debug] 12839#0: *2 reusable connection: 1
2014/02/18 15:46:12 [debug] 12839#0: *2 event timer del: 15:
1392734832672
2014/02/18 15:46:12 [debug] 12839#0: *2 event timer add: 15:
180000:1392734952688
2014/02/18 15:46:12 [debug] 12839#0: *2 post event 00007F29CC9D1148
2014/02/18 15:46:12 [debug] 12839#0: *2 delete posted event
00007F29CC9D1148
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy keepalive handler
2014/02/18 15:46:12 [debug] 12839#0: *2 reusable connection: 0
2014/02/18 15:46:12 [debug] 12839#0: *2 posix_memalign:
00000000025A3AF0:4096 @16
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy read handler
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL_read: 36
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL_read: -1
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL_get_error: 2
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy process frame head:80030004
f:0
l:12
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy SETTINGS frame consists of
1
entries
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy SETTINGS entry fl:0 id:7
val:65536
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy process frame head:80030009
f:0
l:8
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy WINDOW_UPDATE sid:0
delta:268369920
2014/02/18 15:46:12 [debug] 12839#0: *2 free: 00000000025A3AF0, unused:
3760
2014/02/18 15:46:12 [debug] 12839#0: *2 reusable connection: 1
2014/02/18 15:46:12 [debug] 12839#0: *2 event timer: 15, old:
1392734952688,
new: 1392734952690
2014/02/18 15:46:12 [debug] 12839#0: *2 post event 00007F29CC9D1148
2014/02/18 15:46:12 [debug] 12839#0: *2 delete posted event
00007F29CC9D1148
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy keepalive handler
2014/02/18 15:46:12 [debug] 12839#0: *2 reusable connection: 0
2014/02/18 15:46:12 [debug] 12839#0: *2 posix_memalign:
00000000025A3AF0:4096 @16
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy read handler
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL_read: 568
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL_read: -1
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL_get_error: 2
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy process frame head:80030001
f:1
l:544
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy SYN_STREAM frame sid:1
prio:2
2014/02/18 15:46:12 [debug] 12839#0: *2 posix_memalign:
00000000025A4B00:4096 @16
2014/02/18 15:46:12 [debug] 12839#0: *2 posix_memalign:
00000000025A5B10:4096 @16
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy process HEADERS 534 of 534
2014/02/18 15:46:12 [debug] 12839#0: *2 malloc: 00000000025AF180:32768
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy inflateSetDictionary(): 0
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy inflate out:
ni:00007F29CC64F238 no:00000000025A5D36 ai:0 ao:505 rc:0
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy HEADERS block consists of
11
entries
2014/02/18 15:46:12 [debug] 12839#0: *2 http uri: “/”
2014/02/18 15:46:12 [debug] 12839#0: *2 http args: “”
2014/02/18 15:46:12 [debug] 12839#0: *2 http exten: “”
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy http request line: “GET /
HTTP/1.1”
2014/02/18 15:46:12 [debug] 12839#0: *2 http header: “host:
www.example.org”
2014/02/18 15:46:12 [debug] 12839#0: *2 http header: “user-agent:
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:27.0) Gecko/20100101
Firefox/27.0”
2014/02/18 15:46:12 [debug] 12839#0: 2 http header: “cache-control:
max-age=0”
2014/02/18 15:46:12 [debug] 12839#0: 2 http header: "accept:
text/html,application/xhtml+xml,application/xml;q=0.9,/;q=0.8"
2014/02/18 15:46:12 [debug] 12839#0: *2 http header: “accept-language:
de-de,de;q=0.8,en-us;q=0.5,en;q=0.3”
2014/02/18 15:46:12 [debug] 12839#0: *2 http header: “cookie:
cfid=b0fc4a14-0812-48b6-aea7-077c7b61cca7; cftoken=0;
_ga=GA1.2.982493482.1392732645; JSESSIONID=5ln6ihdqossy18j3j9ouz680c”
2014/02/18 15:46:12 [debug] 12839#0: *2 http header: “dnt: 1”
2014/02/18 15:46:12 [debug] 12839#0: *2 generic phase: 0
2014/02/18 15:46:12 [debug] 12839#0: *2 rewrite phase: 1
2014/02/18 15:46:12 [debug] 12839#0: *2 http script regex: “^/+”
2014/02/18 15:46:12 [notice] 12839#0: *2 “^/+” does not match “/”,
client:
192.168.76.46, server: www.example.org, request: “GET / HTTP/1.1”, host:
“www.example.org”
2014/02/18 15:46:12 [debug] 12839#0: *2 http script var
2014/02/18 15:46:12 [debug] 12839#0: *2 http script var: “GET”
2014/02/18 15:46:12 [debug] 12839#0: *2 http script regex:
“^(GET|HEAD|POST)$”
2014/02/18 15:46:12 [notice] 12839#0: *2 “^(GET|HEAD|POST)$” matches
“GET”,
client: 192.168.76.46, server: www.example.org, request: “GET /
HTTP/1.1”,
host: “www.example.org”
2014/02/18 15:46:12 [debug] 12839#0: *2 http script if
2014/02/18 15:46:12 [debug] 12839#0: *2 http script if: false
2014/02/18 15:46:12 [debug] 12839#0: *2 test location: “/”
2014/02/18 15:46:12 [debug] 12839#0: *2 test location: ~
“.(?:png|jpe?g)$”
2014/02/18 15:46:12 [debug] 12839#0: *2 test location: ~ “.php$”
2014/02/18 15:46:12 [debug] 12839#0: 2 test location: ~
".(cfm|cfml|cfc|jsp|cfr)(.)$"
2014/02/18 15:46:12 [debug] 12839#0: *2 test location: ~ “/.”
2014/02/18 15:46:12 [debug] 12839#0: *2 test location: ~
“.(?:eot|ttf|woff|otf|svg)$”
2014/02/18 15:46:12 [debug] 12839#0: *2 test location: ~
“.(?:css|js|png|jpe?g|ico|gif)$”
2014/02/18 15:46:12 [debug] 12839#0: *2 test location: ~
“.(aspx|asp|jsp|cgi)$”
2014/02/18 15:46:12 [debug] 12839#0: *2 using configuration “/”
2014/02/18 15:46:12 [debug] 12839#0: *2 http cl:-1 max:1048576
2014/02/18 15:46:12 [debug] 12839#0: *2 rewrite phase: 3
2014/02/18 15:46:12 [debug] 12839#0: *2 post rewrite phase: 4
2014/02/18 15:46:12 [debug] 12839#0: *2 generic phase: 5
2014/02/18 15:46:12 [debug] 12839#0: *2 generic phase: 6
2014/02/18 15:46:12 [debug] 12839#0: *2 generic phase: 7
2014/02/18 15:46:12 [debug] 12839#0: *2 generic phase: 8
2014/02/18 15:46:12 [debug] 12839#0: *2 access phase: 9
2014/02/18 15:46:12 [debug] 12839#0: *2 access phase: 10
2014/02/18 15:46:12 [debug] 12839#0: *2 post access phase: 11
2014/02/18 15:46:12 [debug] 12839#0: *2 try files phase: 12
2014/02/18 15:46:12 [debug] 12839#0: *2 http script var: “/”
2014/02/18 15:46:12 [debug] 12839#0: *2 trying to use file: “/”
“/usr/share/nginx/html/example.org/”
2014/02/18 15:46:12 [debug] 12839#0: *2 add cleanup: 00000000025A5A58
2014/02/18 15:46:12 [debug] 12839#0: *2 malloc: 0000000002547440:144
2014/02/18 15:46:12 [debug] 12839#0: *2 malloc: 000000000252BDD0:42
2014/02/18 15:46:12 [debug] 12839#0: *2 cached open file:
/usr/share/nginx/html/example.org/, fd:-1, c:0, e:0, u:1
2014/02/18 15:46:12 [debug] 12839#0: *2 http script var: “/”
2014/02/18 15:46:12 [debug] 12839#0: *2 trying to use dir: “/”
“/usr/share/nginx/html/example.org/”
2014/02/18 15:46:12 [debug] 12839#0: *2 add cleanup: 00000000025A5A90
2014/02/18 15:46:12 [debug] 12839#0: *2 cached open file:
/usr/share/nginx/html/example.org/, fd:-1, c:0, e:0, u:2
2014/02/18 15:46:12 [debug] 12839#0: *2 try file uri: “/”
2014/02/18 15:46:12 [debug] 12839#0: *2 content phase: 13
2014/02/18 15:46:12 [debug] 12839#0: *2 content phase: 14
2014/02/18 15:46:12 [debug] 12839#0: *2 open index
“/usr/share/nginx/html/example.org/index.cfm”
2014/02/18 15:46:12 [debug] 12839#0: *2 add cleanup: 00000000025A61D0
2014/02/18 15:46:12 [debug] 12839#0: *2 malloc: 0000000002547C30:144
2014/02/18 15:46:12 [debug] 12839#0: *2 malloc: 00000000025476D0:51
2014/02/18 15:46:12 [debug] 12839#0: *2 cached open file:
/usr/share/nginx/html/example.org/index.cfm, fd:16, c:1, e:0, u:1
2014/02/18 15:46:12 [debug] 12839#0: *2 internal redirect: “/index.cfm?”
2014/02/18 15:46:12 [debug] 12839#0: *2 rewrite phase: 1
2014/02/18 15:46:12 [debug] 12839#0: *2 http script regex: “^/+”
2014/02/18 15:46:12 [notice] 12839#0: *2 “^/+” does not match
“/index.cfm”,
client: 192.168.76.46, server: www.example.org, request: “GET /
HTTP/1.1”,
host: “www.example.org”
2014/02/18 15:46:12 [debug] 12839#0: *2 http script var
2014/02/18 15:46:12 [debug] 12839#0: *2 http script var: “GET”
2014/02/18 15:46:12 [debug] 12839#0: *2 http script regex:
“^(GET|HEAD|POST)$”
2014/02/18 15:46:12 [notice] 12839#0: *2 “^(GET|HEAD|POST)$” matches
“GET”,
client: 192.168.76.46, server: www.example.org, request: “GET /
HTTP/1.1”,
host: “www.example.org”
2014/02/18 15:46:12 [debug] 12839#0: *2 http script if
2014/02/18 15:46:12 [debug] 12839#0: *2 http script if: false
2014/02/18 15:46:12 [debug] 12839#0: *2 test location: “/”
2014/02/18 15:46:12 [debug] 12839#0: *2 test location: “core/”
2014/02/18 15:46:12 [debug] 12839#0: *2 test location: “includes/”
2014/02/18 15:46:12 [debug] 12839#0: *2 test location: “templates/”
2014/02/18 15:46:12 [debug] 12839#0: *2 test location: “robots.txt”
2014/02/18 15:46:12 [debug] 12839#0: *2 test location: ~
“.(?:png|jpe?g)$”
2014/02/18 15:46:12 [debug] 12839#0: *2 test location: ~ “.php$”
2014/02/18 15:46:12 [debug] 12839#0: 2 test location: ~
".(cfm|cfml|cfc|jsp|cfr)(.)$"
2014/02/18 15:46:12 [debug] 12839#0: 2 using configuration
".(cfm|cfml|cfc|jsp|cfr)(.)$"
2014/02/18 15:46:12 [debug] 12839#0: *2 http cl:-1 max:1048576
2014/02/18 15:46:12 [debug] 12839#0: *2 rewrite phase: 3
2014/02/18 15:46:12 [debug] 12839#0: *2 post rewrite phase: 4
2014/02/18 15:46:12 [debug] 12839#0: *2 generic phase: 5
2014/02/18 15:46:12 [debug] 12839#0: *2 generic phase: 6
2014/02/18 15:46:12 [debug] 12839#0: *2 generic phase: 7
2014/02/18 15:46:12 [debug] 12839#0: *2 generic phase: 8
2014/02/18 15:46:12 [debug] 12839#0: *2 access phase: 9
2014/02/18 15:46:12 [debug] 12839#0: *2 access phase: 10
2014/02/18 15:46:12 [debug] 12839#0: *2 post access phase: 11
2014/02/18 15:46:12 [debug] 12839#0: *2 try files phase: 12
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy read request body
2014/02/18 15:46:12 [debug] 12839#0: *2 http init upstream, client
timer: 0
2014/02/18 15:46:12 [debug] 12839#0: *2 posix_memalign:
00000000025B7190:4096 @16
2014/02/18 15:46:12 [debug] 12839#0: *2 http script copy: "Host: "
2014/02/18 15:46:12 [debug] 12839#0: *2 http script var:
“www.example.org”
2014/02/18 15:46:12 [debug] 12839#0: *2 http script copy: "
"
2014/02/18 15:46:12 [debug] 12839#0: *2 http script copy:
"X-Forwarded-Host:
"
2014/02/18 15:46:12 [debug] 12839#0: *2 http script var:
“www.example.org”
2014/02/18 15:46:12 [debug] 12839#0: *2 http script copy: "
"
2014/02/18 15:46:12 [debug] 12839#0: *2 http script copy:
"X-Forwarded-Server: "
2014/02/18 15:46:12 [debug] 12839#0: *2 http script var:
“www.example.org”
2014/02/18 15:46:12 [debug] 12839#0: *2 http script copy: "
"
2014/02/18 15:46:12 [debug] 12839#0: *2 http script copy:
"X-Forwarded-For:
"
2014/02/18 15:46:12 [debug] 12839#0: *2 http script var: “192.168.76.46”
2014/02/18 15:46:12 [debug] 12839#0: *2 http script copy: "
"
2014/02/18 15:46:12 [debug] 12839#0: *2 http script copy: "X-Real-IP: "
2014/02/18 15:46:12 [debug] 12839#0: *2 http script var: “192.168.76.46”
2014/02/18 15:46:12 [debug] 12839#0: *2 http script copy: "
"
2014/02/18 15:46:12 [debug] 12839#0: *2 http script copy: “Connection:
close
"
2014/02/18 15:46:12 [debug] 12839#0: *2 http script copy: “”
2014/02/18 15:46:12 [debug] 12839#0: *2 http script copy: “”
2014/02/18 15:46:12 [debug] 12839#0: *2 http proxy header: “user-agent:
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:27.0) Gecko/20100101
Firefox/27.0”
2014/02/18 15:46:12 [debug] 12839#0: 2 http proxy header:
“cache-control:
max-age=0”
2014/02/18 15:46:12 [debug] 12839#0: 2 http proxy header: "accept:
text/html,application/xhtml+xml,application/xml;q=0.9,/;q=0.8”
2014/02/18 15:46:12 [debug] 12839#0: *2 http proxy header:
“accept-language:
de-de,de;q=0.8,en-us;q=0.5,en;q=0.3”
2014/02/18 15:46:12 [debug] 12839#0: *2 http proxy header: “cookie:
cfid=b0fc4a14-0812-48b6-aea7-077c7b61cca7; cftoken=0;
_ga=GA1.2.982493482.1392732645; JSESSIONID=5ln6ihdqossy18j3j9ouz680c”
2014/02/18 15:46:12 [debug] 12839#0: 2 http proxy header: “dnt: 1”
2014/02/18 15:46:12 [debug] 12839#0: 2 http proxy header:
"GET /index.cfm HTTP/1.0
Host: www.example.org
X-Forwarded-Host: www.example.org
X-Forwarded-Server: www.example.org
X-Forwarded-For: 192.168.76.46
X-Real-IP: 192.168.76.46
Connection: close
user-agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:27.0) Gecko/20100101
Firefox/27.0
cache-control: max-age=0
accept: text/html,application/xhtml+xml,application/xml;q=0.9,/;q=0.8
accept-language: de-de,de;q=0.8,en-us;q=0.5,en;q=0.3
cookie: cfid=b0fc4a14-0812-48b6-aea7-077c7b61cca7; cftoken=0;
_ga=GA1.2.982493482.1392732645; JSESSIONID=5ln6ihdqossy18j3j9ouz680c
dnt: 1

"
2014/02/18 15:46:12 [debug] 12839#0: *2 http cleanup add:
00000000025A6950
2014/02/18 15:46:12 [debug] 12839#0: *2 get rr peer, try: 1
2014/02/18 15:46:12 [debug] 12839#0: *2 socket 17
2014/02/18 15:46:12 [debug] 12839#0: *2 epoll add connection: fd:17
ev:80002005
2014/02/18 15:46:12 [debug] 12839#0: *2 connect to 127.0.0.1:8443, fd:17
#3
2014/02/18 15:46:12 [debug] 12839#0: *2 http upstream connect: -2
2014/02/18 15:46:12 [debug] 12839#0: *2 posix_memalign:
000000000252BB20:128
@16
2014/02/18 15:46:12 [debug] 12839#0: *2 event timer add: 17:
60000:1392734832690
2014/02/18 15:46:12 [debug] 12839#0: *2 http finalize request: -4,
“/index.cfm?” a:1, c:3
2014/02/18 15:46:12 [debug] 12839#0: *2 http request count:3 blk:0
2014/02/18 15:46:12 [debug] 12839#0: *2 http finalize request: -4,
“/index.cfm?” a:1, c:2
2014/02/18 15:46:12 [debug] 12839#0: *2 http request count:2 blk:0
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy process frame head:80030009
f:0
l:8
2014/02/18 15:46:12 [debug] 12839#0: *2 spdy WINDOW_UPDATE sid:1
delta:268369920
2014/02/18 15:46:12 [debug] 12839#0: *2 event timer del: 15:
1392734952688
2014/02/18 15:46:12 [debug] 12839#0: *2 post event 00007F29CC6901B0
2014/02/18 15:46:12 [debug] 12839#0: *2 delete posted event
00007F29CC6901B0
2014/02/18 15:46:12 [debug] 12839#0: *2 http upstream request:
“/index.cfm?”
2014/02/18 15:46:12 [debug] 12839#0: *2 http upstream send request
handler
2014/02/18 15:46:12 [debug] 12839#0: *2 malloc: 00000000025328D0:64
2014/02/18 15:46:12 [debug] 12839#0: *2 set session: 0000000000000000:0
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL_do_handshake: -1
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL_get_error: 2
2014/02/18 15:46:12 [debug] 12839#0: *2 post event 00007F29CC9D11B0
2014/02/18 15:46:12 [debug] 12839#0: *2 post event 00007F29CC6901B0
2014/02/18 15:46:12 [debug] 12839#0: *2 delete posted event
00007F29CC6901B0
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL handshake handler: 1
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL_do_handshake: -1
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL_get_error: 2
2014/02/18 15:46:12 [debug] 12839#0: *2 delete posted event
00007F29CC9D11B0
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL handshake handler: 0
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL_do_handshake: -1
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL_get_error: 2
2014/02/18 15:46:12 [debug] 12839#0: *2 post event 00007F29CC9D11B0
2014/02/18 15:46:12 [debug] 12839#0: *2 post event 00007F29CC6901B0
2014/02/18 15:46:12 [debug] 12839#0: *2 delete posted event
00007F29CC6901B0
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL handshake handler: 1
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL_do_handshake: 1
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL: TLSv1.2, cipher:
“ECDHE-RSA-DES-CBC3-SHA SSLv3 Kx=ECDH Au=RSA Enc=3DES(168) Mac=SHA1”
2014/02/18 15:46:12 [debug] 12839#0: *2 save session: 000000000252D4A0:2
2014/02/18 15:46:12 [debug] 12839#0: *2 http upstream send request
2014/02/18 15:46:12 [debug] 12839#0: *2 chain writer buf fl:1 s:597
2014/02/18 15:46:12 [debug] 12839#0: *2 chain writer in:
00000000025A6988
2014/02/18 15:46:12 [debug] 12839#0: *2 malloc: 00000000025CBB30:80
2014/02/18 15:46:12 [debug] 12839#0: *2 malloc: 00000000025B81A0:16384
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL buf copy: 597
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL to write: 597
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL_write: 597
2014/02/18 15:46:12 [debug] 12839#0: *2 chain writer out:
0000000000000000
2014/02/18 15:46:12 [debug] 12839#0: *2 event timer del: 17:
1392734832690
2014/02/18 15:46:12 [debug] 12839#0: *2 event timer add: 17:
900000:1392735672713
2014/02/18 15:46:12 [debug] 12839#0: *2 http upstream process header
2014/02/18 15:46:12 [debug] 12839#0: *2 malloc: 00000000025BC1B0:4096
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL_read: -1
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL_get_error: 2
2014/02/18 15:46:12 [debug] 12839#0: *2 delete posted event
00007F29CC9D11B0
2014/02/18 15:46:12 [debug] 12839#0: *2 http upstream request:
“/index.cfm?”
2014/02/18 15:46:12 [debug] 12839#0: *2 http upstream process header
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL_read: -1
2014/02/18 15:46:12 [debug] 12839#0: *2 SSL_get_error: 2
2014/02/18 15:46:12 [debug] 12839#0: *2 post event 00007F29CC6901B0
2014/02/18 15:46:12 [debug] 12839#0: *2 delete posted event
00007F29CC6901B0
2014/02/18 15:46:12 [debug] 12839#0: *2 http upstream request:
“/index.cfm?”
2014/02/18 15:46:12 [debug] 12839#0: *2 http upstream send request
handler
2014/02/18 15:46:12 [debug] 12839#0: *2 http upstream send request
2014/02/18 15:46:12 [debug] 12839#0: *2 chain writer in:
0000000000000000
2014/02/18 15:46:12 [debug] 12839#0: *2 event timer: 17, old:
1392735672713,
new: 1392735672713
2014/02/18 15:46:13 [debug] 12839#0: *2 post event 00007F29CC9D11B0
2014/02/18 15:46:13 [debug] 12839#0: *2 post event 00007F29CC6901B0
2014/02/18 15:46:13 [debug] 12839#0: *2 delete posted event
00007F29CC6901B0
2014/02/18 15:46:13 [debug] 12839#0: *2 http upstream request:
“/index.cfm?”
2014/02/18 15:46:13 [debug] 12839#0: *2 http upstream dummy handler
2014/02/18 15:46:13 [debug] 12839#0: *2 delete posted event
00007F29CC9D11B0
2014/02/18 15:46:13 [debug] 12839#0: *2 http upstream request:
“/index.cfm?”
2014/02/18 15:46:13 [debug] 12839#0: *2 http upstream process header
2014/02/18 15:46:13 [debug] 12839#0: *2 SSL_read: 110
2014/02/18 15:46:13 [debug] 12839#0: *2 SSL_read: 0
2014/02/18 15:46:13 [debug] 12839#0: *2 SSL_get_error: 6
2014/02/18 15:46:13 [debug] 12839#0: *2 peer shutdown SSL cleanly
2014/02/18 15:46:13 [debug] 12839#0: *2 http proxy status 200 “200 OK”
2014/02/18 15:46:13 [debug] 12839#0: *2 http proxy header:
“Content-Type:
text/html; charset=UTF-8”
2014/02/18 15:46:13 [debug] 12839#0: *2 http proxy header:
“Content-Length:
0”
2014/02/18 15:46:13 [debug] 12839#0: *2 http proxy header: “Server:
Jetty(9.0.6.v20130930)”
2014/02/18 15:46:13 [debug] 12839#0: *2 http proxy header done
2014/02/18 15:46:13 [debug] 12839#0: *2 xslt filter header
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy header filter
2014/02/18 15:46:13 [debug] 12839#0: *2 malloc: 00000000025CC7E0:228
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy deflate out:
ni:00000000025CC8B1 no:00000000025B7685 ai:0 ao:26 rc:0
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy:1 create SYN_REPLY frame
00000000025A6A88: len:229
2014/02/18 15:46:13 [debug] 12839#0: *2 http cleanup add:
00000000025A6AC8
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy frame out: 00000000025A6A88
sid:1 prio:2 bl:1 len:229
2014/02/18 15:46:13 [debug] 12839#0: *2 malloc: 00000000025CE6C0:16384
2014/02/18 15:46:13 [debug] 12839#0: *2 SSL buf copy: 237
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy:1 SYN_REPLY frame
00000000025A6A88 was sent
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy frame sent:
00000000025A6A88
sid:1 bl:1 len:229
2014/02/18 15:46:13 [debug] 12839#0: *2 http cacheable: 0
2014/02/18 15:46:13 [debug] 12839#0: *2 http proxy filter init s:200 h:0
c:0
l:0
2014/02/18 15:46:13 [debug] 12839#0: *2 http upstream process upstream
2014/02/18 15:46:13 [debug] 12839#0: *2 pipe read upstream: 1
2014/02/18 15:46:13 [debug] 12839#0: *2 pipe preread: 0
2014/02/18 15:46:13 [debug] 12839#0: *2 pipe recv chain: 0
2014/02/18 15:46:13 [debug] 12839#0: *2 pipe buf free s:0 t:1 f:0
00000000025BC1B0, pos 00000000025BC21E, size: 0 file: 0, size: 0
2014/02/18 15:46:13 [debug] 12839#0: *2 pipe length: 0
2014/02/18 15:46:13 [debug] 12839#0: *2 pipe write downstream: 1
2014/02/18 15:46:13 [debug] 12839#0: *2 pipe write downstream done
2014/02/18 15:46:13 [debug] 12839#0: *2 event timer del: 17:
1392735672713
2014/02/18 15:46:13 [debug] 12839#0: *2 event timer add: 17:
900000:1392735673435
2014/02/18 15:46:13 [debug] 12839#0: *2 http upstream exit:
0000000000000000
2014/02/18 15:46:13 [debug] 12839#0: *2 finalize http upstream request:
0
2014/02/18 15:46:13 [debug] 12839#0: *2 finalize http proxy request
2014/02/18 15:46:13 [debug] 12839#0: *2 free rr peer 1 0
2014/02/18 15:46:13 [debug] 12839#0: *2 SSL_shutdown: 1
2014/02/18 15:46:13 [debug] 12839#0: *2 close http upstream connection:
17
2014/02/18 15:46:13 [debug] 12839#0: *2 free: 00000000025B81A0
2014/02/18 15:46:13 [debug] 12839#0: *2 free: 00000000025CBB30
2014/02/18 15:46:13 [debug] 12839#0: *2 free: 00000000025328D0
2014/02/18 15:46:13 [debug] 12839#0: *2 free: 000000000252BB20, unused:
0
2014/02/18 15:46:13 [debug] 12839#0: *2 event timer del: 17:
1392735673435
2014/02/18 15:46:13 [debug] 12839#0: *2 reusable connection: 0
2014/02/18 15:46:13 [debug] 12839#0: *2 http upstream temp fd: -1
2014/02/18 15:46:13 [debug] 12839#0: *2 http output filter “/index.cfm?”
2014/02/18 15:46:13 [debug] 12839#0: *2 http copy filter: “/index.cfm?”
2014/02/18 15:46:13 [debug] 12839#0: *2 image filter
2014/02/18 15:46:13 [debug] 12839#0: *2 xslt filter body
2014/02/18 15:46:13 [debug] 12839#0: *2 http postpone filter
“/index.cfm?”
00007FFF05E55010
2014/02/18 15:46:13 [debug] 12839#0: *2 write new buf t:0 f:0
0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2014/02/18 15:46:13 [debug] 12839#0: *2 http write filter: l:1 f:0 s:0
2014/02/18 15:46:13 [debug] 12839#0: *2 http write filter limit 0
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy:1 create DATA frame
00000000025A6A88: len:0 flags:1
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy frame out: 00000000025A6A88
sid:1 prio:2 bl:0 len:0
2014/02/18 15:46:13 [debug] 12839#0: *2 SSL buf copy: 8
2014/02/18 15:46:13 [debug] 12839#0: *2 SSL to write: 245
2014/02/18 15:46:13 [debug] 12839#0: *2 SSL_write: 245
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy:1 DATA frame
00000000025A6A88
was sent
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy frame sent:
00000000025A6A88
sid:1 bl:0 len:0
2014/02/18 15:46:13 [debug] 12839#0: *2 http write filter
0000000000000000
2014/02/18 15:46:13 [debug] 12839#0: *2 http copy filter: 0
“/index.cfm?”
2014/02/18 15:46:13 [debug] 12839#0: *2 http finalize request: 0,
“/index.cfm?” a:1, c:1
2014/02/18 15:46:13 [debug] 12839#0: *2 http request count:1 blk:0
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy close stream 1, queued 0,
processing 1
2014/02/18 15:46:13 [debug] 12839#0: *2 http close request
2014/02/18 15:46:13 [debug] 12839#0: *2 http log handler
2014/02/18 15:46:13 [debug] 12839#0: *2 run cleanup: 00000000025A61D0
2014/02/18 15:46:13 [debug] 12839#0: *2 close cached open file:
/usr/share/nginx/html/example.org/index.cfm, fd:16, c:0, u:1, 0
2014/02/18 15:46:13 [debug] 12839#0: *2 free: 00000000025BC1B0
2014/02/18 15:46:13 [debug] 12839#0: *2 free: 00000000025A4B00, unused:
4
2014/02/18 15:46:13 [debug] 12839#0: *2 free: 00000000025A5B10, unused:
8
2014/02/18 15:46:13 [debug] 12839#0: *2 free: 00000000025B7190, unused:
2272
2014/02/18 15:46:13 [debug] 12839#0: *2 post event 00007F29CC9D1148
2014/02/18 15:46:13 [debug] 12839#0: *2 delete posted event
00007F29CC9D1148
2014/02/18 15:46:13 [debug] 12839#0: *2 free: 00000000025A3AF0, unused:
3272
2014/02/18 15:46:13 [debug] 12839#0: *2 free: 00000000025CE6C0
2014/02/18 15:46:13 [debug] 12839#0: *2 reusable connection: 1
2014/02/18 15:46:13 [debug] 12839#0: *2 event timer add: 15:
180000:1392734953435
2014/02/18 15:46:13 [debug] 12839#0: *2 post event 00007F29CC9D1148
2014/02/18 15:46:13 [debug] 12839#0: *2 delete posted event
00007F29CC9D1148
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy keepalive handler
2014/02/18 15:46:13 [debug] 12839#0: *2 reusable connection: 0
2014/02/18 15:46:13 [debug] 12839#0: *2 posix_memalign:
00000000025C98B0:4096 @16
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy read handler
2014/02/18 15:46:13 [debug] 12839#0: *2 SSL_read: 543
2014/02/18 15:46:13 [debug] 12839#0: *2 SSL_read: -1
2014/02/18 15:46:13 [debug] 12839#0: *2 SSL_get_error: 2
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy process frame head:80030001
f:1
l:519
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy SYN_STREAM frame sid:3
prio:3
2014/02/18 15:46:13 [debug] 12839#0: *2 posix_memalign:
00000000025CA8C0:4096 @16
2014/02/18 15:46:13 [debug] 12839#0: *2 posix_memalign:
00000000025A3AF0:4096 @16
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy process HEADERS 509 of 509
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy inflate out:
ni:00007F29CC64F21F no:00000000025A3D03 ai:0 ao:524 rc:0
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy HEADERS block consists of
10
entries
2014/02/18 15:46:13 [debug] 12839#0: *2 http uri: “/favicon.ico”
2014/02/18 15:46:13 [debug] 12839#0: *2 http args: “”
2014/02/18 15:46:13 [debug] 12839#0: *2 http exten: “ico”
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy http request line: “GET
/favicon.ico HTTP/1.1”
2014/02/18 15:46:13 [debug] 12839#0: *2 http header: “host:
www.example.org”
2014/02/18 15:46:13 [debug] 12839#0: 2 http header: “user-agent:
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:27.0) Gecko/20100101
Firefox/27.0”
2014/02/18 15:46:13 [debug] 12839#0: 2 http header: "accept:
text/html,application/xhtml+xml,application/xml;q=0.9,/;q=0.8"
2014/02/18 15:46:13 [debug] 12839#0: *2 http header: “accept-language:
de-de,de;q=0.8,en-us;q=0.5,en;q=0.3”
2014/02/18 15:46:13 [debug] 12839#0: *2 http header: “cookie:
cfid=b0fc4a14-0812-48b6-aea7-077c7b61cca7; cftoken=0;
_ga=GA1.2.982493482.1392732645; JSESSIONID=5ln6ihdqossy18j3j9ouz680c”
2014/02/18 15:46:13 [debug] 12839#0: *2 http header: “dnt: 1”
2014/02/18 15:46:13 [debug] 12839#0: *2 generic phase: 0
2014/02/18 15:46:13 [debug] 12839#0: *2 rewrite phase: 1
2014/02/18 15:46:13 [debug] 12839#0: *2 http script regex: “^/+”
2014/02/18 15:46:13 [notice] 12839#0: *2 “^/+” does not match
“/favicon.ico”, client: 192.168.76.46, server: www.example.org, request:
“GET /favicon.ico HTTP/1.1”, host: “www.example.org”
2014/02/18 15:46:13 [debug] 12839#0: *2 http script var
2014/02/18 15:46:13 [debug] 12839#0: *2 http script var: “GET”
2014/02/18 15:46:13 [debug] 12839#0: *2 http script regex:
“^(GET|HEAD|POST)$”
2014/02/18 15:46:13 [notice] 12839#0: *2 “^(GET|HEAD|POST)$” matches
“GET”,
client: 192.168.76.46, server: www.example.org, request: “GET
/favicon.ico
HTTP/1.1”, host: “www.example.org”
2014/02/18 15:46:13 [debug] 12839#0: *2 http script if
2014/02/18 15:46:13 [debug] 12839#0: *2 http script if: false
2014/02/18 15:46:13 [debug] 12839#0: *2 test location: “/”
2014/02/18 15:46:13 [debug] 12839#0: *2 test location: “core/”
2014/02/18 15:46:13 [debug] 12839#0: *2 test location: “includes/”
2014/02/18 15:46:13 [debug] 12839#0: *2 test location: “favicon.ico”
2014/02/18 15:46:13 [debug] 12839#0: *2 using configuration
“=/favicon.ico”
2014/02/18 15:46:13 [debug] 12839#0: *2 http cl:-1 max:1048576
2014/02/18 15:46:13 [debug] 12839#0: *2 rewrite phase: 3
2014/02/18 15:46:13 [debug] 12839#0: *2 post rewrite phase: 4
2014/02/18 15:46:13 [debug] 12839#0: *2 generic phase: 5
2014/02/18 15:46:13 [debug] 12839#0: *2 generic phase: 6
2014/02/18 15:46:13 [debug] 12839#0: *2 generic phase: 7
2014/02/18 15:46:13 [debug] 12839#0: *2 generic phase: 8
2014/02/18 15:46:13 [debug] 12839#0: *2 access phase: 9
2014/02/18 15:46:13 [debug] 12839#0: *2 access phase: 10
2014/02/18 15:46:13 [debug] 12839#0: *2 post access phase: 11
2014/02/18 15:46:13 [debug] 12839#0: *2 try files phase: 12
2014/02/18 15:46:13 [debug] 12839#0: *2 content phase: 13
2014/02/18 15:46:13 [debug] 12839#0: *2 content phase: 14
2014/02/18 15:46:13 [debug] 12839#0: *2 content phase: 15
2014/02/18 15:46:13 [debug] 12839#0: *2 content phase: 16
2014/02/18 15:46:13 [debug] 12839#0: *2 content phase: 17
2014/02/18 15:46:13 [debug] 12839#0: *2 content phase: 18
2014/02/18 15:46:13 [debug] 12839#0: *2 http filename:
“/usr/share/nginx/html/example.org/favicon.ico”
2014/02/18 15:46:13 [debug] 12839#0: *2 add cleanup: 00000000025CB828
2014/02/18 15:46:13 [debug] 12839#0: *2 malloc: 00000000024A8F00:144
2014/02/18 15:46:13 [debug] 12839#0: *2 malloc: 00000000024B2120:53
2014/02/18 15:46:13 [debug] 12839#0: *2 cached open file:
/usr/share/nginx/html/example.org/favicon.ico, fd:16, c:1, e:0, u:1
2014/02/18 15:46:13 [debug] 12839#0: *2 http static fd: 16
2014/02/18 15:46:13 [debug] 12839#0: *2 xslt filter header
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy header filter
2014/02/18 15:46:13 [debug] 12839#0: *2 malloc: 000000000252AE40:315
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy deflate out:
ni:000000000252AF6B no:00000000025A4431 ai:0 ao:44 rc:0
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy:3 create SYN_REPLY frame
00000000025A4460: len:313
2014/02/18 15:46:13 [debug] 12839#0: *2 http cleanup add:
00000000025CB8A8
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy frame out: 00000000025A4460
sid:3 prio:3 bl:1 len:313
2014/02/18 15:46:13 [debug] 12839#0: *2 malloc: 00000000025B7190:16384
2014/02/18 15:46:13 [debug] 12839#0: *2 SSL buf copy: 321
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy:3 SYN_REPLY frame
00000000025A4460 was sent
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy frame sent:
00000000025A4460
sid:3 bl:1 len:313
2014/02/18 15:46:13 [debug] 12839#0: *2 http output filter
“/favicon.ico?”
2014/02/18 15:46:13 [debug] 12839#0: *2 http copy filter:
“/favicon.ico?”
2014/02/18 15:46:13 [debug] 12839#0: *2 posix_memalign:
00000000025A4B00:4096 @16
2014/02/18 15:46:13 [debug] 12839#0: *2 read: 16, 00000000025A4B20,
3262, 0
2014/02/18 15:46:13 [debug] 12839#0: *2 image filter
2014/02/18 15:46:13 [debug] 12839#0: *2 xslt filter body
2014/02/18 15:46:13 [debug] 12839#0: *2 http postpone filter
“/favicon.ico?”
00000000025A4560
2014/02/18 15:46:13 [debug] 12839#0: *2 write new buf t:1 f:1
00000000025A4B20, pos 00000000025A4B20, size: 3262 file: 0, size: 3262
2014/02/18 15:46:13 [debug] 12839#0: *2 http write filter: l:1 f:0
s:3262
2014/02/18 15:46:13 [debug] 12839#0: *2 http write filter limit 0
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy:3 create DATA frame
00000000025A4460: len:3262 flags:1
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy frame out: 00000000025A4460
sid:3 prio:3 bl:0 len:3262
2014/02/18 15:46:13 [debug] 12839#0: *2 SSL buf copy: 8
2014/02/18 15:46:13 [debug] 12839#0: *2 SSL buf copy: 3262
2014/02/18 15:46:13 [debug] 12839#0: *2 SSL to write: 3591
2014/02/18 15:46:13 [debug] 12839#0: *2 SSL_write: 3591
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy:3 DATA frame
00000000025A4460
was sent
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy frame sent:
00000000025A4460
sid:3 bl:0 len:3262
2014/02/18 15:46:13 [debug] 12839#0: *2 http write filter
0000000000000000
2014/02/18 15:46:13 [debug] 12839#0: *2 http copy filter: 0
“/favicon.ico?”
2014/02/18 15:46:13 [debug] 12839#0: *2 http finalize request: 0,
“/favicon.ico?” a:1, c:1
2014/02/18 15:46:13 [debug] 12839#0: *2 http request count:1 blk:0
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy close stream 3, queued 0,
processing 1
2014/02/18 15:46:13 [debug] 12839#0: *2 http close request
2014/02/18 15:46:13 [debug] 12839#0: *2 http log handler
2014/02/18 15:46:13 [debug] 12839#0: *2 run cleanup: 00000000025CB828
2014/02/18 15:46:13 [debug] 12839#0: *2 close cached open file:
/usr/share/nginx/html/example.org/favicon.ico, fd:16, c:0, u:1, 0
2014/02/18 15:46:13 [debug] 12839#0: *2 free: 00000000025CA8C0, unused:
0
2014/02/18 15:46:13 [debug] 12839#0: *2 free: 00000000025A3AF0, unused:
1272
2014/02/18 15:46:13 [debug] 12839#0: *2 free: 00000000025A4B00, unused:
802
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy process frame head:80030009
f:0
l:8
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy WINDOW_UPDATE sid:3
delta:268369920
2014/02/18 15:46:13 [info] 12839#0: *2 client sent WINDOW_UPDATE frame
for
unknown stream 3 while processing SPDY, client: 192.168.76.46, server:
192.168.89.175:443
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy write RST_STREAM sid:3 st:2
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy frame out: 00000000025C9BE8
sid:0 prio:7 bl:0 len:8
2014/02/18 15:46:13 [debug] 12839#0: *2 SSL buf copy: 16
2014/02/18 15:46:13 [debug] 12839#0: *2 SSL to write: 16
2014/02/18 15:46:13 [debug] 12839#0: *2 SSL_write: 16
2014/02/18 15:46:13 [debug] 12839#0: *2 spdy frame sent:
00000000025C9BE8
sid:0 bl:0 len:8
2014/02/18 15:46:13 [debug] 12839#0: *2 free: 00000000025C98B0, unused:
3096
2014/02/18 15:46:13 [debug] 12839#0: *2 free: 00000000025B7190
2014/02/18 15:46:13 [debug] 12839#0: *2 reusable connection: 1
2014/02/18 15:46:13 [debug] 12839#0: *2 event timer: 15, old:
1392734953435,
new: 1392734953471

Posted at Nginx Forum:

p.heppler · February 18, 2014, 3:54pm

Another run with Tomcat, fresh log:

2014/02/18 15:58:53 [debug] 12993#0: epoll add event: fd:9 op:1
ev:00002001
2014/02/18 15:58:57 [debug] 12993#0: post event 00007F19759D4078
2014/02/18 15:58:57 [debug] 12993#0: delete posted event
00007F19759D4078
2014/02/18 15:58:57 [debug] 12993#0: accept on 192.168.89.175:443,
ready: 1
2014/02/18 15:58:57 [debug] 12993#0: posix_memalign:
0000000001CF4860:256
@16
2014/02/18 15:58:57 [debug] 12993#0: *1 accept: 192.168.76.46 fd:15
2014/02/18 15:58:57 [debug] 12993#0: posix_memalign:
0000000001CF4300:256
@16
2014/02/18 15:58:57 [debug] 12993#0: *1 event timer add: 15:
60000:1392735597357
2014/02/18 15:58:57 [debug] 12993#0: *1 reusable connection: 1
2014/02/18 15:58:57 [debug] 12993#0: *1 epoll add event: fd:15 op:1
ev:80002001
2014/02/18 15:58:57 [debug] 12993#0: accept() not ready (11: Resource
temporarily unavailable)
2014/02/18 15:58:57 [debug] 12993#0: *1 post event 00007F19759D4148
2014/02/18 15:58:57 [debug] 12993#0: *1 delete posted event
00007F19759D4148
2014/02/18 15:58:57 [debug] 12993#0: *1 http check ssl handshake
2014/02/18 15:58:57 [debug] 12993#0: *1 http recv(): 1
2014/02/18 15:58:57 [debug] 12993#0: *1 https ssl handshake: 0x16
2014/02/18 15:58:57 [debug] 12993#0: *1 ssl get session: C26B2FD1:32
2014/02/18 15:58:57 [debug] 12993#0: *1 SSL server name:
“www.example.org”
2014/02/18 15:58:57 [debug] 12993#0: *1 SSL_do_handshake: 0
2014/02/18 15:58:57 [debug] 12993#0: *1 SSL_get_error: 5
2014/02/18 15:58:57 [info] 12993#0: *1 peer closed connection in SSL
handshake while SSL handshaking, client: 192.168.76.46, server:
192.168.89.175:443
2014/02/18 15:58:57 [debug] 12993#0: *1 close http connection: 15
2014/02/18 15:58:57 [debug] 12993#0: *1 SSL_shutdown: 1
2014/02/18 15:58:57 [debug] 12993#0: *1 event timer del: 15:
1392735597357
2014/02/18 15:58:57 [debug] 12993#0: *1 reusable connection: 0
2014/02/18 15:58:57 [debug] 12993#0: *1 free: 0000000001CF4860, unused:
16
2014/02/18 15:58:57 [debug] 12993#0: *1 free: 0000000001CF4300, unused:
114
2014/02/18 15:58:57 [debug] 12993#0: post event 00007F19759D4078
2014/02/18 15:58:57 [debug] 12993#0: delete posted event
00007F19759D4078
2014/02/18 15:58:57 [debug] 12993#0: accept on 192.168.89.175:443,
ready: 1
2014/02/18 15:58:57 [debug] 12993#0: posix_memalign:
0000000001C56F00:256
@16
2014/02/18 15:58:57 [debug] 12993#0: *2 accept: 192.168.76.46 fd:15
2014/02/18 15:58:57 [debug] 12993#0: posix_memalign:
0000000001CD8F70:256
@16
2014/02/18 15:58:57 [debug] 12993#0: *2 event timer add: 15:
60000:1392735597365
2014/02/18 15:58:57 [debug] 12993#0: *2 reusable connection: 1
2014/02/18 15:58:57 [debug] 12993#0: *2 epoll add event: fd:15 op:1
ev:80002001
2014/02/18 15:58:57 [debug] 12993#0: accept() not ready (11: Resource
temporarily unavailable)
2014/02/18 15:58:57 [debug] 12993#0: *2 post event 00007F19759D4148
2014/02/18 15:58:57 [debug] 12993#0: *2 delete posted event
00007F19759D4148
2014/02/18 15:58:57 [debug] 12993#0: *2 http check ssl handshake
2014/02/18 15:58:57 [debug] 12993#0: *2 http recv(): 1
2014/02/18 15:58:57 [debug] 12993#0: *2 https ssl handshake: 0x16
2014/02/18 15:58:57 [debug] 12993#0: *2 ssl get session: C26B2FD1:32
2014/02/18 15:58:57 [debug] 12993#0: *2 SSL server name:
“www.example.org”
2014/02/18 15:58:57 [debug] 12993#0: *2 SSL NPN advertised
2014/02/18 15:58:57 [debug] 12993#0: *2 SSL_do_handshake: -1
2014/02/18 15:58:57 [debug] 12993#0: *2 SSL_get_error: 2
2014/02/18 15:58:57 [debug] 12993#0: *2 reusable connection: 0
2014/02/18 15:58:57 [debug] 12993#0: *2 post event 00007F19759D4148
2014/02/18 15:58:57 [debug] 12993#0: *2 delete posted event
00007F19759D4148
2014/02/18 15:58:57 [debug] 12993#0: *2 SSL handshake handler: 0
2014/02/18 15:58:57 [debug] 12993#0: *2 SSL_do_handshake: 1
2014/02/18 15:58:57 [debug] 12993#0: *2 SSL: TLSv1.2, cipher:
“ECDHE-RSA-AES128-GCM-SHA256 TLSv1.2 Kx=ECDH Au=RSA Enc=AESGCM(128)
Mac=AEAD”
2014/02/18 15:58:57 [debug] 12993#0: *2 init spdy request
2014/02/18 15:58:57 [debug] 12993#0: *2 malloc: 0000000001C5FB10:424
2014/02/18 15:58:57 [debug] 12993#0: *2 malloc: 0000000001D451A0:9552
2014/02/18 15:58:57 [debug] 12993#0: *2 malloc: 0000000001C63930:5928
2014/02/18 15:58:57 [debug] 12993#0: *2 malloc: 0000000001CD9260:4096
2014/02/18 15:58:57 [debug] 12993#0: *2 malloc: 0000000001D47700:4096
2014/02/18 15:58:57 [debug] 12993#0: *2 malloc: 0000000001D4EAD0:4096
2014/02/18 15:58:57 [debug] 12993#0: *2 malloc: 0000000001D4FAE0:4096
2014/02/18 15:58:57 [debug] 12993#0: *2 posix_memalign:
0000000001D50AF0:4096 @16
2014/02/18 15:58:57 [debug] 12993#0: *2 posix_memalign:
0000000001CF4300:256
@16
2014/02/18 15:58:57 [debug] 12993#0: *2 add cleanup: 0000000001CF4320
2014/02/18 15:58:57 [debug] 12993#0: *2 spdy create SETTINGS frame
2014/02/18 15:58:57 [debug] 12993#0: *2 spdy write WINDOW_UPDATE sid:0
delta:2147418111
2014/02/18 15:58:57 [debug] 12993#0: *2 spdy read handler
2014/02/18 15:58:57 [debug] 12993#0: *2 SSL_read: -1
2014/02/18 15:58:57 [debug] 12993#0: *2 SSL_get_error: 2
2014/02/18 15:58:57 [debug] 12993#0: *2 spdy frame out: 0000000001D50D00
sid:0 prio:0 bl:0 len:8
2014/02/18 15:58:57 [debug] 12993#0: *2 spdy frame out: 0000000001D50C40
sid:0 prio:0 bl:0 len:20
2014/02/18 15:58:57 [debug] 12993#0: *2 malloc: 0000000001D5C180:16384
2014/02/18 15:58:57 [debug] 12993#0: *2 SSL buf copy: 28
2014/02/18 15:58:57 [debug] 12993#0: *2 SSL buf copy: 16
2014/02/18 15:58:57 [debug] 12993#0: *2 SSL to write: 44
2014/02/18 15:58:57 [debug] 12993#0: *2 SSL_write: 44
2014/02/18 15:58:57 [debug] 12993#0: *2 spdy frame sent:
0000000001D50C40
sid:0 bl:0 len:20
2014/02/18 15:58:57 [debug] 12993#0: *2 spdy frame sent:
0000000001D50D00
sid:0 bl:0 len:8
2014/02/18 15:58:57 [debug] 12993#0: *2 free: 0000000001D50AF0, unused:
3392
2014/02/18 15:58:57 [debug] 12993#0: *2 free: 0000000001D5C180
2014/02/18 15:58:57 [debug] 12993#0: *2 reusable connection: 1
2014/02/18 15:58:57 [debug] 12993#0: *2 event timer del: 15:
1392735597365
2014/02/18 15:58:57 [debug] 12993#0: *2 event timer add: 15:
180000:1392735717380
2014/02/18 15:58:57 [debug] 12993#0: *2 post event 00007F19759D4148
2014/02/18 15:58:57 [debug] 12993#0: *2 delete posted event
00007F19759D4148
2014/02/18 15:58:57 [debug] 12993#0: *2 spdy keepalive handler
2014/02/18 15:58:57 [debug] 12993#0: *2 reusable connection: 0
2014/02/18 15:58:57 [debug] 12993#0: *2 posix_memalign:
0000000001D50AF0:4096 @16
2014/02/18 15:58:57 [debug] 12993#0: *2 spdy read handler
2014/02/18 15:58:57 [debug] 12993#0: *2 SSL_read: 36
2014/02/18 15:58:57 [debug] 12993#0: *2 SSL_read: 568
2014/02/18 15:58:57 [debug] 12993#0: *2 SSL_read: -1
2014/02/18 15:58:57 [debug] 12993#0: *2 SSL_get_error: 2
2014/02/18 15:58:57 [debug] 12993#0: *2 spdy process frame head:80030004
f:0
l:12
2014/02/18 15:58:57 [debug] 12993#0: *2 spdy SETTINGS frame consists of
1
entries
2014/02/18 15:58:57 [debug] 12993#0: *2 spdy SETTINGS entry fl:0 id:7
val:65536
2014/02/18 15:58:57 [debug] 12993#0: *2 spdy process frame head:80030009
f:0
l:8
2014/02/18 15:58:57 [debug] 12993#0: *2 spdy WINDOW_UPDATE sid:0
delta:268369920
2014/02/18 15:58:57 [debug] 12993#0: *2 spdy process frame head:80030001
f:1
l:544
2014/02/18 15:58:57 [debug] 12993#0: *2 spdy SYN_STREAM frame sid:1
prio:2
2014/02/18 15:58:57 [debug] 12993#0: *2 posix_memalign:
0000000001D51B00:4096 @16
2014/02/18 15:58:57 [debug] 12993#0: *2 posix_memalign:
0000000001D52B10:4096 @16
2014/02/18 15:58:57 [debug] 12993#0: *2 spdy process HEADERS 534 of 534
2014/02/18 15:58:57 [debug] 12993#0: *2 malloc: 0000000001D5C180:32768
2014/02/18 15:58:57 [debug] 12993#0: *2 spdy inflateSetDictionary(): 0
2014/02/18 15:58:57 [debug] 12993#0: *2 spdy inflate out:
ni:00007F197565225C no:0000000001D52D36 ai:0 ao:505 rc:0
2014/02/18 15:58:57 [debug] 12993#0: *2 spdy HEADERS block consists of
11
entries
2014/02/18 15:58:57 [debug] 12993#0: *2 http uri: “/”
2014/02/18 15:58:57 [debug] 12993#0: *2 http args: “”
2014/02/18 15:58:57 [debug] 12993#0: *2 http exten: “”
2014/02/18 15:58:57 [debug] 12993#0: *2 spdy http request line: “GET /
HTTP/1.1”
2014/02/18 15:58:57 [debug] 12993#0: *2 http header: “host:
www.example.org”
2014/02/18 15:58:57 [debug] 12993#0: *2 http header: “user-agent:
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:27.0) Gecko/20100101
Firefox/27.0”
2014/02/18 15:58:57 [debug] 12993#0: 2 http header: “cache-control:
max-age=0”
2014/02/18 15:58:57 [debug] 12993#0: 2 http header: "accept:
text/html,application/xhtml+xml,application/xml;q=0.9,/;q=0.8"
2014/02/18 15:58:57 [debug] 12993#0: *2 http header: “accept-language:
de-de,de;q=0.8,en-us;q=0.5,en;q=0.3”
2014/02/18 15:58:57 [debug] 12993#0: *2 http header: “cookie:
cfid=b0fc4a14-0812-48b6-aea7-077c7b61cca7; cftoken=0;
_ga=GA1.2.982493482.1392732645; JSESSIONID=5ln6ihdqossy18j3j9ouz680c”
2014/02/18 15:58:57 [debug] 12993#0: *2 http header: “dnt: 1”
2014/02/18 15:58:57 [debug] 12993#0: *2 generic phase: 0
2014/02/18 15:58:57 [debug] 12993#0: *2 rewrite phase: 1
2014/02/18 15:58:57 [debug] 12993#0: *2 http script regex: “^/+”
2014/02/18 15:58:57 [notice] 12993#0: *2 “^/+” does not match “/”,
client:
192.168.76.46, server: www.example.org, request: “GET / HTTP/1.1”, host:
“www.example.org”
2014/02/18 15:58:57 [debug] 12993#0: *2 http script var
2014/02/18 15:58:57 [debug] 12993#0: *2 http script var: “GET”
2014/02/18 15:58:57 [debug] 12993#0: *2 http script regex:
“^(GET|HEAD|POST)$”
2014/02/18 15:58:57 [notice] 12993#0: *2 “^(GET|HEAD|POST)$” matches
“GET”,
client: 192.168.76.46, server: www.example.org, request: “GET /
HTTP/1.1”,
host: “www.example.org”
2014/02/18 15:58:57 [debug] 12993#0: *2 http script if
2014/02/18 15:58:57 [debug] 12993#0: *2 http script if: false
2014/02/18 15:58:57 [debug] 12993#0: *2 test location: “/”
2014/02/18 15:58:57 [debug] 12993#0: *2 test location: ~
“.(?:png|jpe?g)$”
2014/02/18 15:58:57 [debug] 12993#0: *2 test location: ~ “.php$”
2014/02/18 15:58:57 [debug] 12993#0: 2 test location: ~
".(cfm|cfml|cfc|jsp|cfr)(.)$"
2014/02/18 15:58:57 [debug] 12993#0: *2 test location: ~ “/.”
2014/02/18 15:58:57 [debug] 12993#0: *2 test location: ~
“.(?:eot|ttf|woff|otf|svg)$”
2014/02/18 15:58:57 [debug] 12993#0: *2 test location: ~
“.(?:css|js|png|jpe?g|ico|gif)$”
2014/02/18 15:58:57 [debug] 12993#0: *2 test location: ~
“.(aspx|asp|jsp|cgi)$”
2014/02/18 15:58:57 [debug] 12993#0: *2 using configuration “/”
2014/02/18 15:58:57 [debug] 12993#0: *2 http cl:-1 max:1048576
2014/02/18 15:58:57 [debug] 12993#0: *2 rewrite phase: 3
2014/02/18 15:58:57 [debug] 12993#0: *2 post rewrite phase: 4
2014/02/18 15:58:57 [debug] 12993#0: *2 generic phase: 5
2014/02/18 15:58:57 [debug] 12993#0: *2 generic phase: 6
2014/02/18 15:58:57 [debug] 12993#0: *2 generic phase: 7
2014/02/18 15:58:57 [debug] 12993#0: *2 generic phase: 8
2014/02/18 15:58:57 [debug] 12993#0: *2 access phase: 9
2014/02/18 15:58:57 [debug] 12993#0: *2 access phase: 10
2014/02/18 15:58:57 [debug] 12993#0: *2 post access phase: 11
2014/02/18 15:58:57 [debug] 12993#0: *2 try files phase: 12
2014/02/18 15:58:57 [debug] 12993#0: *2 http script var: “/”
2014/02/18 15:58:57 [debug] 12993#0: *2 trying to use file: “/”
“/usr/share/nginx/html/example.org/”
2014/02/18 15:58:57 [debug] 12993#0: *2 add cleanup: 0000000001D52A58
2014/02/18 15:58:57 [debug] 12993#0: *2 malloc: 0000000001CF4A60:144
2014/02/18 15:58:57 [debug] 12993#0: *2 malloc: 0000000001CDA7D0:42
2014/02/18 15:58:57 [debug] 12993#0: *2 cached open file:
/usr/share/nginx/html/example.org/, fd:-1, c:0, e:0, u:1
2014/02/18 15:58:57 [debug] 12993#0: *2 http script var: “/”
2014/02/18 15:58:57 [debug] 12993#0: *2 trying to use dir: “/”
“/usr/share/nginx/html/example.org/”
2014/02/18 15:58:57 [debug] 12993#0: *2 add cleanup: 0000000001D52A90
2014/02/18 15:58:57 [debug] 12993#0: *2 cached open file:
/usr/share/nginx/html/example.org/, fd:-1, c:0, e:0, u:2
2014/02/18 15:58:57 [debug] 12993#0: *2 try file uri: “/”
2014/02/18 15:58:57 [debug] 12993#0: *2 content phase: 13
2014/02/18 15:58:57 [debug] 12993#0: *2 content phase: 14
2014/02/18 15:58:57 [debug] 12993#0: *2 open index
“/usr/share/nginx/html/example.org/index.cfm”
2014/02/18 15:58:57 [debug] 12993#0: *2 add cleanup: 0000000001D531D0
2014/02/18 15:58:57 [debug] 12993#0: *2 malloc: 0000000001CDF7F0:144
2014/02/18 15:58:57 [debug] 12993#0: *2 malloc: 0000000001CF4CA0:51
2014/02/18 15:58:57 [debug] 12993#0: *2 cached open file:
/usr/share/nginx/html/example.org/index.cfm, fd:16, c:1, e:0, u:1
2014/02/18 15:58:57 [debug] 12993#0: *2 internal redirect: “/index.cfm?”
2014/02/18 15:58:57 [debug] 12993#0: *2 rewrite phase: 1
2014/02/18 15:58:57 [debug] 12993#0: *2 http script regex: “^/+”
2014/02/18 15:58:57 [notice] 12993#0: *2 “^/+” does not match
“/index.cfm”,
client: 192.168.76.46, server: www.example.org, request: “GET /
HTTP/1.1”,
host: “www.example.org”
2014/02/18 15:58:57 [debug] 12993#0: *2 http script var
2014/02/18 15:58:57 [debug] 12993#0: *2 http script var: “GET”
2014/02/18 15:58:57 [debug] 12993#0: *2 http script regex:
“^(GET|HEAD|POST)$”
2014/02/18 15:58:57 [notice] 12993#0: *2 “^(GET|HEAD|POST)$” matches
“GET”,
client: 192.168.76.46, server: www.example.org, request: “GET /
HTTP/1.1”,
host: “www.example.org”
2014/02/18 15:58:57 [debug] 12993#0: *2 http script if
2014/02/18 15:58:57 [debug] 12993#0: *2 http script if: false
2014/02/18 15:58:57 [debug] 12993#0: *2 test location: “/”
2014/02/18 15:58:57 [debug] 12993#0: *2 test location: “core/”
2014/02/18 15:58:57 [debug] 12993#0: *2 test location: “includes/”
2014/02/18 15:58:57 [debug] 12993#0: *2 test location: “templates/”
2014/02/18 15:58:57 [debug] 12993#0: *2 test location: “robots.txt”
2014/02/18 15:58:57 [debug] 12993#0: *2 test location: ~
“.(?:png|jpe?g)$”
2014/02/18 15:58:57 [debug] 12993#0: *2 test location: ~ “.php$”
2014/02/18 15:58:57 [debug] 12993#0: 2 test location: ~
".(cfm|cfml|cfc|jsp|cfr)(.)$"
2014/02/18 15:58:57 [debug] 12993#0: 2 using configuration
".(cfm|cfml|cfc|jsp|cfr)(.)$"
2014/02/18 15:58:57 [debug] 12993#0: *2 http cl:-1 max:1048576
2014/02/18 15:58:57 [debug] 12993#0: *2 rewrite phase: 3
2014/02/18 15:58:57 [debug] 12993#0: *2 post rewrite phase: 4
2014/02/18 15:58:57 [debug] 12993#0: *2 generic phase: 5
2014/02/18 15:58:57 [debug] 12993#0: *2 generic phase: 6
2014/02/18 15:58:57 [debug] 12993#0: *2 generic phase: 7
2014/02/18 15:58:57 [debug] 12993#0: *2 generic phase: 8
2014/02/18 15:58:57 [debug] 12993#0: *2 access phase: 9
2014/02/18 15:58:57 [debug] 12993#0: *2 access phase: 10
2014/02/18 15:58:57 [debug] 12993#0: *2 post access phase: 11
2014/02/18 15:58:57 [debug] 12993#0: *2 try files phase: 12
2014/02/18 15:58:57 [debug] 12993#0: *2 spdy read request body
2014/02/18 15:58:57 [debug] 12993#0: *2 http init upstream, client
timer: 0
2014/02/18 15:58:57 [debug] 12993#0: *2 posix_memalign:
0000000001D64190:4096 @16
2014/02/18 15:58:57 [debug] 12993#0: *2 http script copy: "Host: "
2014/02/18 15:58:57 [debug] 12993#0: *2 http script var:
“www.example.org”
2014/02/18 15:58:57 [debug] 12993#0: *2 http script copy: "
"
2014/02/18 15:58:57 [debug] 12993#0: *2 http script copy:
"X-Forwarded-Host:
"
2014/02/18 15:58:57 [debug] 12993#0: *2 http script var:
“www.example.org”
2014/02/18 15:58:57 [debug] 12993#0: *2 http script copy: "
"
2014/02/18 15:58:57 [debug] 12993#0: *2 http script copy:
"X-Forwarded-Server: "
2014/02/18 15:58:57 [debug] 12993#0: *2 http script var:
“www.example.org”
2014/02/18 15:58:57 [debug] 12993#0: *2 http script copy: "
"
2014/02/18 15:58:57 [debug] 12993#0: *2 http script copy:
"X-Forwarded-For:
"
2014/02/18 15:58:57 [debug] 12993#0: *2 http script var: “192.168.76.46”
2014/02/18 15:58:57 [debug] 12993#0: *2 http script copy: "
"
2014/02/18 15:58:57 [debug] 12993#0: *2 http script copy: "X-Real-IP: "
2014/02/18 15:58:57 [debug] 12993#0: *2 http script var: “192.168.76.46”
2014/02/18 15:58:57 [debug] 12993#0: *2 http script copy: "
"
2014/02/18 15:58:57 [debug] 12993#0: *2 http script copy: “Connection:
close
"
2014/02/18 15:58:57 [debug] 12993#0: *2 http script copy: “”
2014/02/18 15:58:57 [debug] 12993#0: *2 http script copy: “”
2014/02/18 15:58:57 [debug] 12993#0: *2 http proxy header: “user-agent:
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:27.0) Gecko/20100101
Firefox/27.0”
2014/02/18 15:58:57 [debug] 12993#0: 2 http proxy header:
“cache-control:
max-age=0”
2014/02/18 15:58:57 [debug] 12993#0: 2 http proxy header: "accept:
text/html,application/xhtml+xml,application/xml;q=0.9,/;q=0.8”
2014/02/18 15:58:57 [debug] 12993#0: *2 http proxy header:
“accept-language:
de-de,de;q=0.8,en-us;q=0.5,en;q=0.3”
2014/02/18 15:58:57 [debug] 12993#0: *2 http proxy header: “cookie:
cfid=b0fc4a14-0812-48b6-aea7-077c7b61cca7; cftoken=0;
_ga=GA1.2.982493482.1392732645; JSESSIONID=5ln6ihdqossy18j3j9ouz680c”
2014/02/18 15:58:57 [debug] 12993#0: 2 http proxy header: “dnt: 1”
2014/02/18 15:58:57 [debug] 12993#0: 2 http proxy header:
"GET /index.cfm HTTP/1.0
Host: www.example.org
X-Forwarded-Host: www.example.org
X-Forwarded-Server: www.example.org
X-Forwarded-For: 192.168.76.46
X-Real-IP: 192.168.76.46
Connection: close
user-agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:27.0) Gecko/20100101
Firefox/27.0
cache-control: max-age=0
accept: text/html,application/xhtml+xml,application/xml;q=0.9,/;q=0.8
accept-language: de-de,de;q=0.8,en-us;q=0.5,en;q=0.3
cookie: cfid=b0fc4a14-0812-48b6-aea7-077c7b61cca7; cftoken=0;
_ga=GA1.2.982493482.1392732645; JSESSIONID=5ln6ihdqossy18j3j9ouz680c
dnt: 1

"
2014/02/18 15:58:57 [debug] 12993#0: *2 http cleanup add:
0000000001D53950
2014/02/18 15:58:57 [debug] 12993#0: *2 get rr peer, try: 1
2014/02/18 15:58:57 [debug] 12993#0: *2 socket 17
2014/02/18 15:58:57 [debug] 12993#0: *2 epoll add connection: fd:17
ev:80002005
2014/02/18 15:58:57 [debug] 12993#0: *2 connect to 127.0.0.1:8888, fd:17
#3
2014/02/18 15:58:57 [debug] 12993#0: *2 http upstream connect: -2
2014/02/18 15:58:57 [debug] 12993#0: *2 posix_memalign:
0000000001CD8B00:128
@16
2014/02/18 15:58:57 [debug] 12993#0: *2 event timer add: 17:
60000:1392735597388
2014/02/18 15:58:57 [debug] 12993#0: *2 http finalize request: -4,
“/index.cfm?” a:1, c:3
2014/02/18 15:58:57 [debug] 12993#0: *2 http request count:3 blk:0
2014/02/18 15:58:57 [debug] 12993#0: *2 http finalize request: -4,
“/index.cfm?” a:1, c:2
2014/02/18 15:58:57 [debug] 12993#0: *2 http request count:2 blk:0
2014/02/18 15:58:57 [debug] 12993#0: *2 spdy process frame head:80030009
f:0
l:8
2014/02/18 15:58:57 [debug] 12993#0: *2 spdy WINDOW_UPDATE sid:1
delta:268369920
2014/02/18 15:58:57 [debug] 12993#0: *2 event timer del: 15:
1392735717380
2014/02/18 15:58:57 [debug] 12993#0: *2 post event 00007F19756931B0
2014/02/18 15:58:57 [debug] 12993#0: *2 delete posted event
00007F19756931B0
2014/02/18 15:58:57 [debug] 12993#0: *2 http upstream request:
“/index.cfm?”
2014/02/18 15:58:57 [debug] 12993#0: *2 http upstream send request
handler
2014/02/18 15:58:57 [debug] 12993#0: *2 http upstream send request
2014/02/18 15:58:57 [debug] 12993#0: *2 chain writer buf fl:1 s:597
2014/02/18 15:58:57 [debug] 12993#0: *2 chain writer in:
0000000001D53988
2014/02/18 15:58:57 [debug] 12993#0: *2 writev: 597
2014/02/18 15:58:57 [debug] 12993#0: *2 chain writer out:
0000000000000000
2014/02/18 15:58:57 [debug] 12993#0: *2 event timer del: 17:
1392735597388
2014/02/18 15:58:57 [debug] 12993#0: *2 event timer add: 17:
900000:1392736437394
2014/02/18 15:59:01 [debug] 12993#0: *2 post event 00007F19759D41B0
2014/02/18 15:59:01 [debug] 12993#0: *2 post event 00007F19756931B0
2014/02/18 15:59:01 [debug] 12993#0: *2 delete posted event
00007F19756931B0
2014/02/18 15:59:01 [debug] 12993#0: *2 http upstream request:
“/index.cfm?”
2014/02/18 15:59:01 [debug] 12993#0: *2 http upstream dummy handler
2014/02/18 15:59:01 [debug] 12993#0: *2 delete posted event
00007F19759D41B0
2014/02/18 15:59:01 [debug] 12993#0: *2 http upstream request:
“/index.cfm?”
2014/02/18 15:59:01 [debug] 12993#0: *2 http upstream process header
2014/02/18 15:59:01 [debug] 12993#0: *2 malloc: 0000000001D651A0:4096
2014/02/18 15:59:01 [debug] 12993#0: *2 recv: fd:17 235 of 4096
2014/02/18 15:59:01 [debug] 12993#0: *2 http proxy status 200 “200 OK”
2014/02/18 15:59:01 [debug] 12993#0: *2 http proxy header: “Server:
Apache-Coyote/1.1”
2014/02/18 15:59:01 [debug] 12993#0: *2 http proxy header: “Set-Cookie:
JSESSIONID=396DC49FA6AF6BE7BDB1B46A00612E34; Path=/; HttpOnly”
2014/02/18 15:59:01 [debug] 12993#0: *2 http proxy header:
“Content-Type:
text/html;charset=UTF-8”
2014/02/18 15:59:01 [debug] 12993#0: *2 http proxy header:
“Content-Length:
0”
2014/02/18 15:59:01 [debug] 12993#0: *2 http proxy header: “Date: Tue,
18
Feb 2014 14:59:01 GMT”
2014/02/18 15:59:01 [debug] 12993#0: *2 http proxy header: “Connection:
close”
2014/02/18 15:59:01 [debug] 12993#0: *2 http proxy header done
2014/02/18 15:59:01 [debug] 12993#0: *2 xslt filter header
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy header filter
2014/02/18 15:59:01 [debug] 12993#0: *2 malloc: 0000000001CDA270:306
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy deflate out:
ni:0000000001CDA38F no:0000000001D646D3 ai:0 ao:36 rc:0
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy:1 create SYN_REPLY frame
0000000001D64708: len:307
2014/02/18 15:59:01 [debug] 12993#0: *2 http cleanup add:
0000000001D64748
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy frame out: 0000000001D64708
sid:1 prio:2 bl:1 len:307
2014/02/18 15:59:01 [debug] 12993#0: *2 malloc: 0000000001D661B0:16384
2014/02/18 15:59:01 [debug] 12993#0: *2 SSL buf copy: 315
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy:1 SYN_REPLY frame
0000000001D64708 was sent
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy frame sent:
0000000001D64708
sid:1 bl:1 len:307
2014/02/18 15:59:01 [debug] 12993#0: *2 http cacheable: 0
2014/02/18 15:59:01 [debug] 12993#0: *2 http proxy filter init s:200 h:0
c:0
l:0
2014/02/18 15:59:01 [debug] 12993#0: *2 http upstream process upstream
2014/02/18 15:59:01 [debug] 12993#0: *2 pipe read upstream: 1
2014/02/18 15:59:01 [debug] 12993#0: *2 pipe preread: 0
2014/02/18 15:59:01 [debug] 12993#0: *2 readv: 1:3861
2014/02/18 15:59:01 [debug] 12993#0: *2 readv() not ready (11: Resource
temporarily unavailable)
2014/02/18 15:59:01 [debug] 12993#0: *2 pipe recv chain: -2
2014/02/18 15:59:01 [debug] 12993#0: *2 pipe buf free s:0 t:1 f:0
0000000001D651A0, pos 0000000001D6528B, size: 0 file: 0, size: 0
2014/02/18 15:59:01 [debug] 12993#0: *2 pipe length: 0
2014/02/18 15:59:01 [debug] 12993#0: *2 pipe write downstream: 1
2014/02/18 15:59:01 [debug] 12993#0: *2 pipe write downstream done
2014/02/18 15:59:01 [debug] 12993#0: *2 event timer del: 17:
1392736437394
2014/02/18 15:59:01 [debug] 12993#0: *2 event timer add: 17:
900000:1392736441385
2014/02/18 15:59:01 [debug] 12993#0: *2 http upstream exit:
0000000000000000
2014/02/18 15:59:01 [debug] 12993#0: *2 finalize http upstream request:
0
2014/02/18 15:59:01 [debug] 12993#0: *2 finalize http proxy request
2014/02/18 15:59:01 [debug] 12993#0: *2 free rr peer 1 0
2014/02/18 15:59:01 [debug] 12993#0: *2 close http upstream connection:
17
2014/02/18 15:59:01 [debug] 12993#0: *2 free: 0000000001CD8B00, unused:
48
2014/02/18 15:59:01 [debug] 12993#0: *2 event timer del: 17:
1392736441385
2014/02/18 15:59:01 [debug] 12993#0: *2 reusable connection: 0
2014/02/18 15:59:01 [debug] 12993#0: *2 http upstream temp fd: -1
2014/02/18 15:59:01 [debug] 12993#0: *2 http output filter “/index.cfm?”
2014/02/18 15:59:01 [debug] 12993#0: *2 http copy filter: “/index.cfm?”
2014/02/18 15:59:01 [debug] 12993#0: *2 image filter
2014/02/18 15:59:01 [debug] 12993#0: *2 xslt filter body
2014/02/18 15:59:01 [debug] 12993#0: *2 http postpone filter
“/index.cfm?”
00007FFF0EE2CD10
2014/02/18 15:59:01 [debug] 12993#0: *2 write new buf t:0 f:0
0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2014/02/18 15:59:01 [debug] 12993#0: *2 http write filter: l:1 f:0 s:0
2014/02/18 15:59:01 [debug] 12993#0: *2 http write filter limit 0
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy:1 create DATA frame
0000000001D64708: len:0 flags:1
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy frame out: 0000000001D64708
sid:1 prio:2 bl:0 len:0
2014/02/18 15:59:01 [debug] 12993#0: *2 SSL buf copy: 8
2014/02/18 15:59:01 [debug] 12993#0: *2 SSL to write: 323
2014/02/18 15:59:01 [debug] 12993#0: *2 SSL_write: 323
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy:1 DATA frame
0000000001D64708
was sent
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy frame sent:
0000000001D64708
sid:1 bl:0 len:0
2014/02/18 15:59:01 [debug] 12993#0: *2 http write filter
0000000000000000
2014/02/18 15:59:01 [debug] 12993#0: *2 http copy filter: 0
“/index.cfm?”
2014/02/18 15:59:01 [debug] 12993#0: *2 http finalize request: 0,
“/index.cfm?” a:1, c:1
2014/02/18 15:59:01 [debug] 12993#0: *2 http request count:1 blk:0
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy close stream 1, queued 0,
processing 1
2014/02/18 15:59:01 [debug] 12993#0: *2 http close request
2014/02/18 15:59:01 [debug] 12993#0: *2 http log handler
2014/02/18 15:59:01 [debug] 12993#0: *2 run cleanup: 0000000001D531D0
2014/02/18 15:59:01 [debug] 12993#0: *2 close cached open file:
/usr/share/nginx/html/example.org/index.cfm, fd:16, c:0, u:1, 0
2014/02/18 15:59:01 [debug] 12993#0: *2 free: 0000000001D651A0
2014/02/18 15:59:01 [debug] 12993#0: *2 free: 0000000001D51B00, unused:
4
2014/02/18 15:59:01 [debug] 12993#0: *2 free: 0000000001D52B10, unused:
0
2014/02/18 15:59:01 [debug] 12993#0: *2 free: 0000000001D64190, unused:
2048
2014/02/18 15:59:01 [debug] 12993#0: *2 post event 00007F19759D4148
2014/02/18 15:59:01 [debug] 12993#0: *2 delete posted event
00007F19759D4148
2014/02/18 15:59:01 [debug] 12993#0: *2 free: 0000000001D50AF0, unused:
3272
2014/02/18 15:59:01 [debug] 12993#0: *2 free: 0000000001D661B0
2014/02/18 15:59:01 [debug] 12993#0: *2 reusable connection: 1
2014/02/18 15:59:01 [debug] 12993#0: *2 event timer add: 15:
180000:1392735721385
2014/02/18 15:59:01 [debug] 12993#0: *2 post event 00007F19759D4148
2014/02/18 15:59:01 [debug] 12993#0: *2 delete posted event
00007F19759D4148
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy keepalive handler
2014/02/18 15:59:01 [debug] 12993#0: *2 reusable connection: 0
2014/02/18 15:59:01 [debug] 12993#0: *2 posix_memalign:
0000000001D50AF0:4096 @16
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy read handler
2014/02/18 15:59:01 [debug] 12993#0: *2 SSL_read: 550
2014/02/18 15:59:01 [debug] 12993#0: *2 SSL_read: -1
2014/02/18 15:59:01 [debug] 12993#0: *2 SSL_get_error: 2
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy process frame head:80030001
f:1
l:526
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy SYN_STREAM frame sid:3
prio:3
2014/02/18 15:59:01 [debug] 12993#0: *2 posix_memalign:
0000000001D51B00:4096 @16
2014/02/18 15:59:01 [debug] 12993#0: *2 posix_memalign:
0000000001D52B10:4096 @16
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy process HEADERS 516 of 516
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy inflate out:
ni:00007F1975652226 no:0000000001D52D2A ai:0 ao:517 rc:0
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy HEADERS block consists of
10
entries
2014/02/18 15:59:01 [debug] 12993#0: *2 http uri: “/favicon.ico”
2014/02/18 15:59:01 [debug] 12993#0: *2 http args: “”
2014/02/18 15:59:01 [debug] 12993#0: *2 http exten: “ico”
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy http request line: “GET
/favicon.ico HTTP/1.1”
2014/02/18 15:59:01 [debug] 12993#0: *2 http header: “host:
www.example.org”
2014/02/18 15:59:01 [debug] 12993#0: 2 http header: “user-agent:
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:27.0) Gecko/20100101
Firefox/27.0”
2014/02/18 15:59:01 [debug] 12993#0: 2 http header: "accept:
text/html,application/xhtml+xml,application/xml;q=0.9,/;q=0.8"
2014/02/18 15:59:01 [debug] 12993#0: *2 http header: “accept-language:
de-de,de;q=0.8,en-us;q=0.5,en;q=0.3”
2014/02/18 15:59:01 [debug] 12993#0: *2 http header: “cookie:
cfid=b0fc4a14-0812-48b6-aea7-077c7b61cca7; cftoken=0;
_ga=GA1.2.982493482.1392732645;
JSESSIONID=396DC49FA6AF6BE7BDB1B46A00612E34”
2014/02/18 15:59:01 [debug] 12993#0: *2 http header: “dnt: 1”
2014/02/18 15:59:01 [debug] 12993#0: *2 generic phase: 0
2014/02/18 15:59:01 [debug] 12993#0: *2 rewrite phase: 1
2014/02/18 15:59:01 [debug] 12993#0: *2 http script regex: “^/+”
2014/02/18 15:59:01 [notice] 12993#0: *2 “^/+” does not match
“/favicon.ico”, client: 192.168.76.46, server: www.example.org, request:
“GET /favicon.ico HTTP/1.1”, host: “www.example.org”
2014/02/18 15:59:01 [debug] 12993#0: *2 http script var
2014/02/18 15:59:01 [debug] 12993#0: *2 http script var: “GET”
2014/02/18 15:59:01 [debug] 12993#0: *2 http script regex:
“^(GET|HEAD|POST)$”
2014/02/18 15:59:01 [notice] 12993#0: *2 “^(GET|HEAD|POST)$” matches
“GET”,
client: 192.168.76.46, server: www.example.org, request: “GET
/favicon.ico
HTTP/1.1”, host: “www.example.org”
2014/02/18 15:59:01 [debug] 12993#0: *2 http script if
2014/02/18 15:59:01 [debug] 12993#0: *2 http script if: false
2014/02/18 15:59:01 [debug] 12993#0: *2 test location: “/”
2014/02/18 15:59:01 [debug] 12993#0: *2 test location: “core/”
2014/02/18 15:59:01 [debug] 12993#0: *2 test location: “includes/”
2014/02/18 15:59:01 [debug] 12993#0: *2 test location: “favicon.ico”
2014/02/18 15:59:01 [debug] 12993#0: *2 using configuration
“=/favicon.ico”
2014/02/18 15:59:01 [debug] 12993#0: *2 http cl:-1 max:1048576
2014/02/18 15:59:01 [debug] 12993#0: *2 rewrite phase: 3
2014/02/18 15:59:01 [debug] 12993#0: *2 post rewrite phase: 4
2014/02/18 15:59:01 [debug] 12993#0: *2 generic phase: 5
2014/02/18 15:59:01 [debug] 12993#0: *2 generic phase: 6
2014/02/18 15:59:01 [debug] 12993#0: *2 generic phase: 7
2014/02/18 15:59:01 [debug] 12993#0: *2 generic phase: 8
2014/02/18 15:59:01 [debug] 12993#0: *2 access phase: 9
2014/02/18 15:59:01 [debug] 12993#0: *2 access phase: 10
2014/02/18 15:59:01 [debug] 12993#0: *2 post access phase: 11
2014/02/18 15:59:01 [debug] 12993#0: *2 try files phase: 12
2014/02/18 15:59:01 [debug] 12993#0: *2 content phase: 13
2014/02/18 15:59:01 [debug] 12993#0: *2 content phase: 14
2014/02/18 15:59:01 [debug] 12993#0: *2 content phase: 15
2014/02/18 15:59:01 [debug] 12993#0: *2 content phase: 16
2014/02/18 15:59:01 [debug] 12993#0: *2 content phase: 17
2014/02/18 15:59:01 [debug] 12993#0: *2 content phase: 18
2014/02/18 15:59:01 [debug] 12993#0: *2 http filename:
“/usr/share/nginx/html/example.org/favicon.ico”
2014/02/18 15:59:01 [debug] 12993#0: *2 add cleanup: 0000000001D52A68
2014/02/18 15:59:01 [debug] 12993#0: *2 malloc: 0000000001CDC1D0:144
2014/02/18 15:59:01 [debug] 12993#0: *2 malloc: 0000000001CBBE20:53
2014/02/18 15:59:01 [debug] 12993#0: *2 cached open file:
/usr/share/nginx/html/example.org/favicon.ico, fd:16, c:1, e:0, u:1
2014/02/18 15:59:01 [debug] 12993#0: *2 http static fd: 16
2014/02/18 15:59:01 [debug] 12993#0: *2 xslt filter header
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy header filter
2014/02/18 15:59:01 [debug] 12993#0: *2 malloc: 0000000001CDA270:315
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy deflate out:
ni:0000000001CDA39B no:0000000001D53451 ai:0 ao:44 rc:0
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy:3 create SYN_REPLY frame
0000000001D53480: len:313
2014/02/18 15:59:01 [debug] 12993#0: *2 http cleanup add:
0000000001D52AE8
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy frame out: 0000000001D53480
sid:3 prio:3 bl:1 len:313
2014/02/18 15:59:01 [debug] 12993#0: *2 malloc: 0000000001D64190:16384
2014/02/18 15:59:01 [debug] 12993#0: *2 SSL buf copy: 321
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy:3 SYN_REPLY frame
0000000001D53480 was sent
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy frame sent:
0000000001D53480
sid:3 bl:1 len:313
2014/02/18 15:59:01 [debug] 12993#0: *2 http output filter
“/favicon.ico?”
2014/02/18 15:59:01 [debug] 12993#0: *2 http copy filter:
“/favicon.ico?”
2014/02/18 15:59:01 [debug] 12993#0: *2 posix_memalign:
0000000001D681A0:4096 @16
2014/02/18 15:59:01 [debug] 12993#0: *2 read: 16, 0000000001D681C0,
3262, 0
2014/02/18 15:59:01 [debug] 12993#0: *2 image filter
2014/02/18 15:59:01 [debug] 12993#0: *2 xslt filter body
2014/02/18 15:59:01 [debug] 12993#0: *2 http postpone filter
“/favicon.ico?”
0000000001D53580
2014/02/18 15:59:01 [debug] 12993#0: *2 write new buf t:1 f:1
0000000001D681C0, pos 0000000001D681C0, size: 3262 file: 0, size: 3262
2014/02/18 15:59:01 [debug] 12993#0: *2 http write filter: l:1 f:0
s:3262
2014/02/18 15:59:01 [debug] 12993#0: *2 http write filter limit 0
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy:3 create DATA frame
0000000001D53480: len:3262 flags:1
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy frame out: 0000000001D53480
sid:3 prio:3 bl:0 len:3262
2014/02/18 15:59:01 [debug] 12993#0: *2 SSL buf copy: 8
2014/02/18 15:59:01 [debug] 12993#0: *2 SSL buf copy: 3262
2014/02/18 15:59:01 [debug] 12993#0: *2 SSL to write: 3591
2014/02/18 15:59:01 [debug] 12993#0: *2 SSL_write: 3591
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy:3 DATA frame
0000000001D53480
was sent
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy frame sent:
0000000001D53480
sid:3 bl:0 len:3262
2014/02/18 15:59:01 [debug] 12993#0: *2 http write filter
0000000000000000
2014/02/18 15:59:01 [debug] 12993#0: *2 http copy filter: 0
“/favicon.ico?”
2014/02/18 15:59:01 [debug] 12993#0: *2 http finalize request: 0,
“/favicon.ico?” a:1, c:1
2014/02/18 15:59:01 [debug] 12993#0: *2 http request count:1 blk:0
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy close stream 3, queued 0,
processing 1
2014/02/18 15:59:01 [debug] 12993#0: *2 http close request
2014/02/18 15:59:01 [debug] 12993#0: *2 http log handler
2014/02/18 15:59:01 [debug] 12993#0: *2 run cleanup: 0000000001D52A68
2014/02/18 15:59:01 [debug] 12993#0: *2 close cached open file:
/usr/share/nginx/html/example.org/favicon.ico, fd:16, c:0, u:1, 0
2014/02/18 15:59:01 [debug] 12993#0: *2 free: 0000000001D51B00, unused:
0
2014/02/18 15:59:01 [debug] 12993#0: *2 free: 0000000001D52B10, unused:
1272
2014/02/18 15:59:01 [debug] 12993#0: *2 free: 0000000001D681A0, unused:
802
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy process frame head:80030009
f:0
l:8
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy WINDOW_UPDATE sid:3
delta:268369920
2014/02/18 15:59:01 [info] 12993#0: *2 client sent WINDOW_UPDATE frame
for
unknown stream 3 while processing SPDY, client: 192.168.76.46, server:
192.168.89.175:443
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy write RST_STREAM sid:3 st:2
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy frame out: 0000000001D50E28
sid:0 prio:7 bl:0 len:8
2014/02/18 15:59:01 [debug] 12993#0: *2 SSL buf copy: 16
2014/02/18 15:59:01 [debug] 12993#0: *2 SSL to write: 16
2014/02/18 15:59:01 [debug] 12993#0: *2 SSL_write: 16
2014/02/18 15:59:01 [debug] 12993#0: *2 spdy frame sent:
0000000001D50E28
sid:0 bl:0 len:8
2014/02/18 15:59:01 [debug] 12993#0: *2 free: 0000000001D50AF0, unused:
3096
2014/02/18 15:59:01 [debug] 12993#0: *2 free: 0000000001D64190
2014/02/18 15:59:01 [debug] 12993#0: *2 reusable connection: 1
2014/02/18 15:59:01 [debug] 12993#0: *2 event timer: 15, old:
1392735721385,
new: 1392735721410

Posted at Nginx Forum: