pagespeed/ngx_pagespeed — pull request #276 by jeffkaufman (2013-04-22 17:58:32+00:00)
Title: beacon-handler: don't screw up the connection

This fixes issue (1) from #275 , but I'm not at all confident that it's fixing it in the right way. While I've done a little refactoring, the real change is just:

ps_beacon_handler_helper(r, request_body);
+ r->count--;
ngx_http_finalize_request(r, NGX_HTTP_NO_CONTENT);

I don't really understand what I'm doing here. @yaoweibin or @chaizhenhua could you take a look? I'm also not sure whether this should be `r->main->count--`. Though I don't think beacon handling would ever be combined with subrequests.

What this fixes is that if I run:

```
$ telnet localhost 8050
POST /ngx_pagespeed_beacon HTTP/1.1
Host: localhost:8050
Content-Length: 127

url=http%3A%2F%2Flocalhost%3A8050%2Fmod_pagespeed_example%2Fprioritize_critical_css.html&oh=e87c7hWk3p&cs=.big,.blue,.bold,.foo

HTTP/1.1 204 No Content
Server: nginx/1.3.15
Date: Mon, 22 Apr 2013 17:54:55 GMT
Connection: keep-alive
X-Extra-Header: 1

POST /ngx_pagespeed_beacon HTTP/1.1
Host: localhost:8050
Content-Length: 127

url=http%3A%2F%2Flocalhost%3A8050%2Fmod_pagespeed_example%2Fprioritize_critical_css.html&oh=e87c7hWk3p&cs=.big,.blue,.bold,.foo
```

then the second POST would just sit there with no response. Now the second post also gets a proper `204 No Content` response.

Logs from running those two posts on master:

```
2013/04/22 13:57:06 [debug] 29226#0: bind() 0.0.0.0:8051 #6
2013/04/22 13:57:06 [debug] 29226#0: bind() 0.0.0.0:8050 #7
2013/04/22 13:57:06 [notice] 29226#0: using the "epoll" event method
2013/04/22 13:57:06 [debug] 29226#0: counter: 00007F159FDDD080, 1
2013/04/22 13:57:06 [info] 29226#0: [ngx_pagespeed 1.5.27.1-2857] SharedMemCache: /usr/local/google/home/jefftk/h/ngx_ps/ngx_pagespeed/test/tmp/file-cache/with_shm///metadata_cache, sectors = 128, entries/sector = 356, 64-byte blocks/sector = 712, total footprint: 8404992
2013/04/22 13:57:06 [info] 29226#0: [ngx_pagespeed 1.5.27.1-2857] Initializing shared memory for path: /usr/local/google/home/jefftk/h/ngx_ps/ngx_pagespeed/test/tmp/file-cache//.
2013/04/22 13:57:06 [info] 29226#0: [ngx_pagespeed 1.5.27.1-2857] Initializing shared memory for path: /usr/local/google/home/jefftk/h/ngx_ps/ngx_pagespeed/test/tmp/file-cache/secondary//.
2013/04/22 13:57:06 [info] 29226#0: [ngx_pagespeed 1.5.27.1-2857] Initializing shared memory for path: /usr/local/google/home/jefftk/h/ngx_ps/ngx_pagespeed/test/tmp/file-cache/with_shm//.
2013/04/22 13:57:06 [notice] 29226#0: nginx/1.3.15
2013/04/22 13:57:06 [notice] 29226#0: built by gcc 4.6.3 (Ubuntu/Linaro 4.6.3-1ubuntu5)
2013/04/22 13:57:06 [notice] 29226#0: OS: Linux 3.2.5-gg1130
2013/04/22 13:57:06 [notice] 29226#0: getrlimit(RLIMIT_NOFILE): 32768:32768
2013/04/22 13:57:06 [debug] 29227#0: write: 8, 00007FFF63FFCEA0, 6, 0
2013/04/22 13:57:06 [debug] 29227#0: setproctitle: "nginx: master process /home/jefftk/nginx/sbin/nginx -c /usr/local/google/home/jefftk/h/ngx_ps/ngx_pagespeed/test/tmp/pagespeed_test.conf"
2013/04/22 13:57:06 [notice] 29227#0: start worker processes
2013/04/22 13:57:06 [debug] 29227#0: channel 3:8
2013/04/22 13:57:06 [notice] 29227#0: start worker process 29228
2013/04/22 13:57:06 [debug] 29227#0: sigsuspend
2013/04/22 13:57:06 [debug] 29228#0: malloc: 00000000022C6F50:6144
2013/04/22 13:57:06 [debug] 29228#0: malloc: 000000000277C890:188416
2013/04/22 13:57:06 [debug] 29228#0: malloc: 00000000027AA8A0:106496
2013/04/22 13:57:06 [debug] 29228#0: malloc: 00000000027C48B0:106496
2013/04/22 13:57:06 [debug] 29228#0: epoll add event: fd:6 op:1 ev:00000001
2013/04/22 13:57:06 [debug] 29228#0: epoll add event: fd:7 op:1 ev:00000001
2013/04/22 13:57:06 [info] 29228#0: [ngx_pagespeed 1.5.27.1-2857] Reusing shared memory for path: /usr/local/google/home/jefftk/h/ngx_ps/ngx_pagespeed/test/tmp/file-cache//.
2013/04/22 13:57:06 [info] 29228#0: [ngx_pagespeed 1.5.27.1-2857] Reusing shared memory for path: /usr/local/google/home/jefftk/h/ngx_ps/ngx_pagespeed/test/tmp/file-cache/secondary//.
2013/04/22 13:57:06 [info] 29228#0: [ngx_pagespeed 1.5.27.1-2857] Reusing shared memory for path: /usr/local/google/home/jefftk/h/ngx_ps/ngx_pagespeed/test/tmp/file-cache/with_shm//.
2013/04/22 13:57:06 [debug] 29228#0: epoll add event: fd:8 op:1 ev:00000001
2013/04/22 13:57:06 [debug] 29228#0: setproctitle: "nginx: worker process"
2013/04/22 13:57:06 [debug] 29228#0: worker cycle
2013/04/22 13:57:06 [debug] 29228#0: epoll timer: -1
2013/04/22 13:57:25 [debug] 29228#0: epoll: fd:7 ev:0001 d:000000000277C948
2013/04/22 13:57:25 [debug] 29228#0: accept on 0.0.0.0:8050, ready: 0
2013/04/22 13:57:25 [debug] 29228#0: posix_memalign: 00000000028AAAC0:256 @16
2013/04/22 13:57:25 [debug] 29228#0: *1 accept: 127.0.0.1 fd:3
2013/04/22 13:57:25 [debug] 29228#0: *1 event timer add: 3: 60000:1366653505038
2013/04/22 13:57:25 [debug] 29228#0: *1 reusable connection: 1
2013/04/22 13:57:25 [debug] 29228#0: *1 epoll add event: fd:3 op:1 ev:80000001
2013/04/22 13:57:25 [debug] 29228#0: timer delta: 18957
2013/04/22 13:57:25 [debug] 29228#0: posted events 0000000000000000
2013/04/22 13:57:25 [debug] 29228#0: worker cycle
2013/04/22 13:57:25 [debug] 29228#0: epoll timer: 60000
2013/04/22 13:57:28 [debug] 29228#0: epoll: fd:3 ev:0001 d:000000000277CAB8
2013/04/22 13:57:28 [debug] 29228#0: *1 http wait request handler
2013/04/22 13:57:28 [debug] 29228#0: *1 posix_memalign: 00000000028AABD0:256 @16
2013/04/22 13:57:28 [debug] 29228#0: *1 malloc: 00000000028AACE0:1024
2013/04/22 13:57:28 [debug] 29228#0: *1 recv: fd:3 211 of 1024
2013/04/22 13:57:28 [debug] 29228#0: *1 reusable connection: 0
2013/04/22 13:57:28 [debug] 29228#0: *1 posix_memalign: 00000000028AB0F0:4096 @16
2013/04/22 13:57:28 [debug] 29228#0: *1 http process request line
2013/04/22 13:57:28 [debug] 29228#0: *1 http request line: "POST /ngx_pagespeed_beacon HTTP/1.1"
2013/04/22 13:57:28 [debug] 29228#0: *1 http uri: "/ngx_pagespeed_beacon"
2013/04/22 13:57:28 [debug] 29228#0: *1 http args: ""
2013/04/22 13:57:28 [debug] 29228#0: *1 http exten: ""
2013/04/22 13:57:28 [debug] 29228#0: *1 http process request header line
2013/04/22 13:57:28 [debug] 29228#0: *1 http header: "Host: localhost:8050"
2013/04/22 13:57:28 [debug] 29228#0: *1 http header: "Content-Length: 127"
2013/04/22 13:57:28 [debug] 29228#0: *1 http header done
2013/04/22 13:57:28 [debug] 29228#0: *1 event timer del: 3: 1366653505038
2013/04/22 13:57:28 [debug] 29228#0: *1 rewrite phase: 0
2013/04/22 13:57:28 [debug] 29228#0: *1 test location: "/mod_pagespeed_test/forbid_all_disabled/disabled"
2013/04/22 13:57:28 [debug] 29228#0: *1 test location: "/mod_pagespeed_test/ssi/"
2013/04/22 13:57:28 [debug] 29228#0: *1 test location: "/ngx_pagespeed_statistics"
2013/04/22 13:57:28 [debug] 29228#0: *1 test location: "/ngx_pagespeed_message"
2013/04/22 13:57:28 [debug] 29228#0: *1 test location: ~ "\.pagespeed\.([a-z]\.)?[a-z]{2}\.[^.]{10}\.[^.]+"
2013/04/22 13:57:28 [debug] 29228#0: *1 test location: ~ "\.php$"
2013/04/22 13:57:28 [debug] 29228#0: *1 using configuration ""
2013/04/22 13:57:28 [debug] 29228#0: *1 http cl:127 max:1048576
2013/04/22 13:57:28 [debug] 29228#0: *1 rewrite phase: 2
2013/04/22 13:57:28 [debug] 29228#0: *1 post rewrite phase: 3
2013/04/22 13:57:28 [debug] 29228#0: *1 generic phase: 4
2013/04/22 13:57:28 [debug] 29228#0: *1 generic phase: 4
2013/04/22 13:57:28 [debug] 29228#0: *1 generic phase: 5
2013/04/22 13:57:28 [debug] 29228#0: *1 access phase: 6
2013/04/22 13:57:28 [debug] 29228#0: *1 access phase: 7
2013/04/22 13:57:28 [debug] 29228#0: *1 post access phase: 8
2013/04/22 13:57:28 [debug] 29228#0: *1 generic phase: 9
2013/04/22 13:57:28 [debug] 29228#0: *1 http pagespeed handler "/ngx_pagespeed_beacon"
2013/04/22 13:57:28 [debug] 29228#0: *1 http client request body preread 129
2013/04/22 13:57:28 [debug] 29228#0: *1 http request body content length filter
2013/04/22 13:57:28 [debug] 29228#0: *1 http body new buf t:1 f:0 00000000028AAD32, pos 00000000028AAD32, size: 127 file: 0, size: 0
2013/04/22 13:57:28 [debug] 29228#0: *1 ngx_pagespeed beacon: single buffer of 127
2013/04/22 13:57:28 [debug] 29228#0: *1 ps_beacon_handler_helper: beacon[127] url=http%3A%2F%2Flocalhost%3A8050%2Fmod_pagespeed_example%2Fprioritize_critical_css.html&oh=e87c7hWk3p&cs=.big,.blue,.bold,.foo
2013/04/22 13:57:28 [debug] 29228#0: *1 http finalize request: 204, "/ngx_pagespeed_beacon?" a:1, c:2
2013/04/22 13:57:28 [debug] 29228#0: *1 http special response: 204, "/ngx_pagespeed_beacon?"
2013/04/22 13:57:28 [debug] 29228#0: *1 posix_memalign: 00000000028AD3F0:4096 @16
2013/04/22 13:57:28 [debug] 29228#0: *1 HTTP/1.1 204 No Content
Server: nginx/1.3.15
Date: Mon, 22 Apr 2013 17:57:28 GMT
Connection: keep-alive
X-Extra-Header: 1

2013/04/22 13:57:28 [debug] 29228#0: *1 write new buf t:1 f:0 00000000028AD460, pos 00000000028AD460, size: 129 file: 0, size: 0
2013/04/22 13:57:28 [debug] 29228#0: *1 http write filter: l:1 f:0 s:129
2013/04/22 13:57:28 [debug] 29228#0: *1 http write filter limit 0
2013/04/22 13:57:28 [debug] 29228#0: *1 writev: 129
2013/04/22 13:57:28 [debug] 29228#0: *1 http write filter 0000000000000000
2013/04/22 13:57:28 [debug] 29228#0: *1 http finalize request: 0, "/ngx_pagespeed_beacon?" a:1, c:2
2013/04/22 13:57:28 [debug] 29228#0: *1 http request count:2 blk:0
2013/04/22 13:57:28 [debug] 29228#0: timer delta: 3788
2013/04/22 13:57:28 [debug] 29228#0: posted events 0000000000000000
2013/04/22 13:57:28 [debug] 29228#0: worker cycle
2013/04/22 13:57:28 [debug] 29228#0: epoll timer: -1
2013/04/22 13:57:29 [debug] 29228#0: epoll: fd:3 ev:0001 d:000000000277CAB8
2013/04/22 13:57:29 [debug] 29228#0: *1 http run request: "/ngx_pagespeed_beacon?"
2013/04/22 13:57:29 [debug] 29228#0: *1 http reading blocked
2013/04/22 13:57:29 [debug] 29228#0: timer delta: 664
2013/04/22 13:57:29 [debug] 29228#0: posted events 0000000000000000
2013/04/22 13:57:29 [debug] 29228#0: worker cycle
2013/04/22 13:57:29 [debug] 29228#0: epoll timer: -1
2013/04/22 13:57:29 [debug] 29228#0: epoll: fd:3 ev:0001 d:000000000277CAB8
2013/04/22 13:57:29 [debug] 29228#0: *1 http run request: "/ngx_pagespeed_beacon?"
2013/04/22 13:57:29 [debug] 29228#0: *1 http reading blocked
2013/04/22 13:57:29 [debug] 29228#0: timer delta: 32
2013/04/22 13:57:29 [debug] 29228#0: posted events 0000000000000000
2013/04/22 13:57:29 [debug] 29228#0: worker cycle
2013/04/22 13:57:29 [debug] 29228#0: epoll timer: -1
```

Logs from running those two posts with the `count--`:

```
2013/04/22 13:58:13 [debug] 29521#0: bind() 0.0.0.0:8051 #6
2013/04/22 13:58:13 [debug] 29521#0: bind() 0.0.0.0:8050 #7
2013/04/22 13:58:13 [notice] 29521#0: using the "epoll" event method
2013/04/22 13:58:13 [debug] 29521#0: counter: 00007FB64BABE080, 1
2013/04/22 13:58:13 [info] 29521#0: [ngx_pagespeed 1.5.27.1-2857] SharedMemCache: /usr/local/google/home/jefftk/h/ngx_ps/ngx_pagespeed/test/tmp/file-cache/with_shm///metadata_cache, sectors = 128, entries/sector = 356, 64-byte blocks/sector = 712, total footprint: 8404992
2013/04/22 13:58:13 [info] 29521#0: [ngx_pagespeed 1.5.27.1-2857] Initializing shared memory for path: /usr/local/google/home/jefftk/h/ngx_ps/ngx_pagespeed/test/tmp/file-cache//.
2013/04/22 13:58:13 [info] 29521#0: [ngx_pagespeed 1.5.27.1-2857] Initializing shared memory for path: /usr/local/google/home/jefftk/h/ngx_ps/ngx_pagespeed/test/tmp/file-cache/secondary//.
2013/04/22 13:58:13 [info] 29521#0: [ngx_pagespeed 1.5.27.1-2857] Initializing shared memory for path: /usr/local/google/home/jefftk/h/ngx_ps/ngx_pagespeed/test/tmp/file-cache/with_shm//.
2013/04/22 13:58:13 [notice] 29521#0: nginx/1.3.15
2013/04/22 13:58:13 [notice] 29521#0: built by gcc 4.6.3 (Ubuntu/Linaro 4.6.3-1ubuntu5)
2013/04/22 13:58:13 [notice] 29521#0: OS: Linux 3.2.5-gg1130
2013/04/22 13:58:13 [notice] 29521#0: getrlimit(RLIMIT_NOFILE): 32768:32768
2013/04/22 13:58:13 [debug] 29522#0: write: 8, 00007FFFF2A2AA20, 6, 0
2013/04/22 13:58:13 [debug] 29522#0: setproctitle: "nginx: master process /home/jefftk/nginx/sbin/nginx -c /usr/local/google/home/jefftk/h/ngx_ps/ngx_pagespeed/test/tmp/pagespeed_test.conf"
2013/04/22 13:58:13 [notice] 29522#0: start worker processes
2013/04/22 13:58:13 [debug] 29522#0: channel 3:8
2013/04/22 13:58:13 [notice] 29522#0: start worker process 29523
2013/04/22 13:58:13 [debug] 29522#0: sigsuspend
2013/04/22 13:58:13 [debug] 29523#0: malloc: 0000000001996F50:6144
2013/04/22 13:58:13 [debug] 29523#0: malloc: 0000000001E4C890:188416
2013/04/22 13:58:13 [debug] 29523#0: malloc: 0000000001E7A8A0:106496
2013/04/22 13:58:13 [debug] 29523#0: malloc: 0000000001E948B0:106496
2013/04/22 13:58:13 [debug] 29523#0: epoll add event: fd:6 op:1 ev:00000001
2013/04/22 13:58:13 [debug] 29523#0: epoll add event: fd:7 op:1 ev:00000001
2013/04/22 13:58:13 [info] 29523#0: [ngx_pagespeed 1.5.27.1-2857] Reusing shared memory for path: /usr/local/google/home/jefftk/h/ngx_ps/ngx_pagespeed/test/tmp/file-cache//.
2013/04/22 13:58:13 [info] 29523#0: [ngx_pagespeed 1.5.27.1-2857] Reusing shared memory for path: /usr/local/google/home/jefftk/h/ngx_ps/ngx_pagespeed/test/tmp/file-cache/secondary//.
2013/04/22 13:58:13 [info] 29523#0: [ngx_pagespeed 1.5.27.1-2857] Reusing shared memory for path: /usr/local/google/home/jefftk/h/ngx_ps/ngx_pagespeed/test/tmp/file-cache/with_shm//.
2013/04/22 13:58:13 [debug] 29523#0: epoll add event: fd:8 op:1 ev:00000001
2013/04/22 13:58:13 [debug] 29523#0: setproctitle: "nginx: worker process"
2013/04/22 13:58:13 [debug] 29523#0: worker cycle
2013/04/22 13:58:13 [debug] 29523#0: epoll timer: -1
2013/04/22 13:58:15 [debug] 29523#0: epoll: fd:7 ev:0001 d:0000000001E4C948
2013/04/22 13:58:15 [debug] 29523#0: accept on 0.0.0.0:8050, ready: 0
2013/04/22 13:58:15 [debug] 29523#0: posix_memalign: 0000000001F7AAC0:256 @16
2013/04/22 13:58:15 [debug] 29523#0: *1 accept: 127.0.0.1 fd:3
2013/04/22 13:58:15 [debug] 29523#0: *1 event timer add: 3: 60000:1366653555630
2013/04/22 13:58:15 [debug] 29523#0: *1 reusable connection: 1
2013/04/22 13:58:15 [debug] 29523#0: *1 epoll add event: fd:3 op:1 ev:80000001
2013/04/22 13:58:15 [debug] 29523#0: timer delta: 2052
2013/04/22 13:58:15 [debug] 29523#0: posted events 0000000000000000
2013/04/22 13:58:15 [debug] 29523#0: worker cycle
2013/04/22 13:58:15 [debug] 29523#0: epoll timer: 60000
2013/04/22 13:58:20 [debug] 29523#0: epoll: fd:3 ev:0001 d:0000000001E4CAB8
2013/04/22 13:58:20 [debug] 29523#0: *1 http wait request handler
2013/04/22 13:58:20 [debug] 29523#0: *1 posix_memalign: 0000000001F7ABD0:256 @16
2013/04/22 13:58:20 [debug] 29523#0: *1 malloc: 0000000001F7ACE0:1024
2013/04/22 13:58:20 [debug] 29523#0: *1 recv: fd:3 211 of 1024
2013/04/22 13:58:20 [debug] 29523#0: *1 reusable connection: 0
2013/04/22 13:58:20 [debug] 29523#0: *1 posix_memalign: 0000000001F7B0F0:4096 @16
2013/04/22 13:58:20 [debug] 29523#0: *1 http process request line
2013/04/22 13:58:20 [debug] 29523#0: *1 http request line: "POST /ngx_pagespeed_beacon HTTP/1.1"
2013/04/22 13:58:20 [debug] 29523#0: *1 http uri: "/ngx_pagespeed_beacon"
2013/04/22 13:58:20 [debug] 29523#0: *1 http args: ""
2013/04/22 13:58:20 [debug] 29523#0: *1 http exten: ""
2013/04/22 13:58:20 [debug] 29523#0: *1 http process request header line
2013/04/22 13:58:20 [debug] 29523#0: *1 http header: "Host: localhost:8050"
2013/04/22 13:58:20 [debug] 29523#0: *1 http header: "Content-Length: 127"
2013/04/22 13:58:20 [debug] 29523#0: *1 http header done
2013/04/22 13:58:20 [debug] 29523#0: *1 event timer del: 3: 1366653555630
2013/04/22 13:58:20 [debug] 29523#0: *1 rewrite phase: 0
2013/04/22 13:58:20 [debug] 29523#0: *1 test location: "/mod_pagespeed_test/forbid_all_disabled/disabled"
2013/04/22 13:58:20 [debug] 29523#0: *1 test location: "/mod_pagespeed_test/ssi/"
2013/04/22 13:58:20 [debug] 29523#0: *1 test location: "/ngx_pagespeed_statistics"
2013/04/22 13:58:20 [debug] 29523#0: *1 test location: "/ngx_pagespeed_message"
2013/04/22 13:58:20 [debug] 29523#0: *1 test location: ~ "\.pagespeed\.([a-z]\.)?[a-z]{2}\.[^.]{10}\.[^.]+"
2013/04/22 13:58:20 [debug] 29523#0: *1 test location: ~ "\.php$"
2013/04/22 13:58:20 [debug] 29523#0: *1 using configuration ""
2013/04/22 13:58:20 [debug] 29523#0: *1 http cl:127 max:1048576
2013/04/22 13:58:20 [debug] 29523#0: *1 rewrite phase: 2
2013/04/22 13:58:20 [debug] 29523#0: *1 post rewrite phase: 3
2013/04/22 13:58:20 [debug] 29523#0: *1 generic phase: 4
2013/04/22 13:58:20 [debug] 29523#0: *1 generic phase: 4
2013/04/22 13:58:20 [debug] 29523#0: *1 generic phase: 5
2013/04/22 13:58:20 [debug] 29523#0: *1 access phase: 6
2013/04/22 13:58:20 [debug] 29523#0: *1 access phase: 7
2013/04/22 13:58:20 [debug] 29523#0: *1 post access phase: 8
2013/04/22 13:58:20 [debug] 29523#0: *1 generic phase: 9
2013/04/22 13:58:20 [debug] 29523#0: *1 http pagespeed handler "/ngx_pagespeed_beacon"
2013/04/22 13:58:20 [debug] 29523#0: *1 http client request body preread 129
2013/04/22 13:58:20 [debug] 29523#0: *1 http request body content length filter
2013/04/22 13:58:20 [debug] 29523#0: *1 http body new buf t:1 f:0 0000000001F7AD32, pos 0000000001F7AD32, size: 127 file: 0, size: 0
2013/04/22 13:58:20 [debug] 29523#0: *1 ngx_pagespeed beacon: single buffer of 127
2013/04/22 13:58:20 [debug] 29523#0: *1 ps_beacon_handler_helper: beacon[127] url=http%3A%2F%2Flocalhost%3A8050%2Fmod_pagespeed_example%2Fprioritize_critical_css.html&oh=e87c7hWk3p&cs=.big,.blue,.bold,.foo
2013/04/22 13:58:20 [debug] 29523#0: *1 http finalize request: 204, "/ngx_pagespeed_beacon?" a:1, c:1
2013/04/22 13:58:20 [debug] 29523#0: *1 http special response: 204, "/ngx_pagespeed_beacon?"
2013/04/22 13:58:20 [debug] 29523#0: *1 posix_memalign: 0000000001F7D3F0:4096 @16
2013/04/22 13:58:20 [debug] 29523#0: *1 HTTP/1.1 204 No Content
Server: nginx/1.3.15
Date: Mon, 22 Apr 2013 17:58:20 GMT
Connection: keep-alive
X-Extra-Header: 1

2013/04/22 13:58:20 [debug] 29523#0: *1 write new buf t:1 f:0 0000000001F7D460, pos 0000000001F7D460, size: 129 file: 0, size: 0
2013/04/22 13:58:20 [debug] 29523#0: *1 http write filter: l:1 f:0 s:129
2013/04/22 13:58:20 [debug] 29523#0: *1 http write filter limit 0
2013/04/22 13:58:20 [debug] 29523#0: *1 writev: 129
2013/04/22 13:58:20 [debug] 29523#0: *1 http write filter 0000000000000000
2013/04/22 13:58:20 [debug] 29523#0: *1 http finalize request: 0, "/ngx_pagespeed_beacon?" a:1, c:1
2013/04/22 13:58:20 [debug] 29523#0: *1 set http keepalive handler
2013/04/22 13:58:20 [debug] 29523#0: *1 http close request
2013/04/22 13:58:20 [debug] 29523#0: *1 http log handler
2013/04/22 13:58:20 [debug] 29523#0: *1 free: 0000000001F7B0F0, unused: 16
2013/04/22 13:58:20 [debug] 29523#0: *1 free: 0000000001F7D3F0, unused: 3724
2013/04/22 13:58:20 [debug] 29523#0: *1 pipelined request
2013/04/22 13:58:20 [debug] 29523#0: *1 posix_memalign: 0000000001F7B0F0:4096 @16
2013/04/22 13:58:20 [debug] 29523#0: *1 post event 0000000001E7A9D8
2013/04/22 13:58:20 [debug] 29523#0: timer delta: 4709
2013/04/22 13:58:20 [debug] 29523#0: posted events 0000000001E7A9D8
2013/04/22 13:58:20 [debug] 29523#0: posted event 0000000001E7A9D8
2013/04/22 13:58:20 [debug] 29523#0: *1 delete posted event 0000000001E7A9D8
2013/04/22 13:58:20 [debug] 29523#0: *1 http process request line
2013/04/22 13:58:20 [debug] 29523#0: *1 recv: fd:3 -1 of 813
2013/04/22 13:58:20 [debug] 29523#0: *1 recv() not ready (11: Resource temporarily unavailable)
2013/04/22 13:58:20 [debug] 29523#0: *1 event timer add: 3: 60000:1366653560339
2013/04/22 13:58:20 [debug] 29523#0: posted event 0000000000000000
2013/04/22 13:58:20 [debug] 29523#0: worker cycle
2013/04/22 13:58:20 [debug] 29523#0: epoll timer: 60000
2013/04/22 13:58:20 [debug] 29523#0: epoll: fd:3 ev:0001 d:0000000001E4CAB8
2013/04/22 13:58:20 [debug] 29523#0: *1 http process request line
2013/04/22 13:58:20 [debug] 29523#0: *1 recv: fd:3 37 of 813
2013/04/22 13:58:20 [debug] 29523#0: *1 http request line: "POST /ngx_pagespeed_beacon HTTP/1.1"
2013/04/22 13:58:20 [debug] 29523#0: *1 http uri: "/ngx_pagespeed_beacon"
2013/04/22 13:58:20 [debug] 29523#0: *1 http args: ""
2013/04/22 13:58:20 [debug] 29523#0: *1 http exten: ""
2013/04/22 13:58:20 [debug] 29523#0: *1 http process request header line
2013/04/22 13:58:20 [debug] 29523#0: *1 recv: fd:3 -1 of 776
2013/04/22 13:58:20 [debug] 29523#0: *1 recv() not ready (11: Resource temporarily unavailable)
2013/04/22 13:58:20 [debug] 29523#0: timer delta: 625
2013/04/22 13:58:20 [debug] 29523#0: posted events 0000000000000000
2013/04/22 13:58:20 [debug] 29523#0: worker cycle
2013/04/22 13:58:20 [debug] 29523#0: epoll timer: 59375
2013/04/22 13:58:21 [debug] 29523#0: epoll: fd:3 ev:0001 d:0000000001E4CAB8
2013/04/22 13:58:21 [debug] 29523#0: *1 http process request header line
2013/04/22 13:58:21 [debug] 29523#0: *1 recv: fd:3 174 of 776
2013/04/22 13:58:21 [debug] 29523#0: *1 http header: "Host: localhost:8050"
2013/04/22 13:58:21 [debug] 29523#0: *1 http header: "Content-Length: 127"
2013/04/22 13:58:21 [debug] 29523#0: *1 http header done
2013/04/22 13:58:21 [debug] 29523#0: *1 event timer del: 3: 1366653560339
2013/04/22 13:58:21 [debug] 29523#0: *1 rewrite phase: 0
2013/04/22 13:58:21 [debug] 29523#0: *1 test location: "/mod_pagespeed_test/forbid_all_disabled/disabled"
2013/04/22 13:58:21 [debug] 29523#0: *1 test location: "/mod_pagespeed_test/ssi/"
2013/04/22 13:58:21 [debug] 29523#0: *1 test location: "/ngx_pagespeed_statistics"
2013/04/22 13:58:21 [debug] 29523#0: *1 test location: "/ngx_pagespeed_message"
2013/04/22 13:58:21 [debug] 29523#0: *1 test location: ~ "\.pagespeed\.([a-z]\.)?[a-z]{2}\.[^.]{10}\.[^.]+"
2013/04/22 13:58:21 [debug] 29523#0: *1 test location: ~ "\.php$"
2013/04/22 13:58:21 [debug] 29523#0: *1 using configuration ""
2013/04/22 13:58:21 [debug] 29523#0: *1 http cl:127 max:1048576
2013/04/22 13:58:21 [debug] 29523#0: *1 rewrite phase: 2
2013/04/22 13:58:21 [debug] 29523#0: *1 post rewrite phase: 3
2013/04/22 13:58:21 [debug] 29523#0: *1 generic phase: 4
2013/04/22 13:58:21 [debug] 29523#0: *1 generic phase: 5
2013/04/22 13:58:21 [debug] 29523#0: *1 access phase: 6
2013/04/22 13:58:21 [debug] 29523#0: *1 access phase: 7
2013/04/22 13:58:21 [debug] 29523#0: *1 post access phase: 8
2013/04/22 13:58:21 [debug] 29523#0: *1 generic phase: 9
2013/04/22 13:58:21 [debug] 29523#0: *1 http pagespeed handler "/ngx_pagespeed_beacon"
2013/04/22 13:58:21 [debug] 29523#0: *1 http client request body preread 129
2013/04/22 13:58:21 [debug] 29523#0: *1 http request body content length filter
2013/04/22 13:58:21 [debug] 29523#0: *1 http body new buf t:1 f:0 0000000001F7AE05, pos 0000000001F7AE05, size: 127 file: 0, size: 0
2013/04/22 13:58:21 [debug] 29523#0: *1 ngx_pagespeed beacon: single buffer of 127
2013/04/22 13:58:21 [debug] 29523#0: *1 ps_beacon_handler_helper: beacon[127] url=http%3A%2F%2Flocalhost%3A8050%2Fmod_pagespeed_example%2Fprioritize_critical_css.html&oh=e87c7hWk3p&cs=.big,.blue,.bold,.foo
2013/04/22 13:58:21 [debug] 29523#0: *1 http finalize request: 204, "/ngx_pagespeed_beacon?" a:1, c:1
2013/04/22 13:58:21 [debug] 29523#0: *1 http special response: 204, "/ngx_pagespeed_beacon?"
2013/04/22 13:58:21 [debug] 29523#0: *1 posix_memalign: 0000000001F7D3F0:4096 @16
2013/04/22 13:58:21 [debug] 29523#0: *1 HTTP/1.1 204 No Content
Server: nginx/1.3.15
Date: Mon, 22 Apr 2013 17:58:21 GMT
Connection: keep-alive
X-Extra-Header: 1

2013/04/22 13:58:21 [debug] 29523#0: *1 write new buf t:1 f:0 0000000001F7D460, pos 0000000001F7D460, size: 129 file: 0, size: 0
2013/04/22 13:58:21 [debug] 29523#0: *1 http write filter: l:1 f:0 s:129
2013/04/22 13:58:21 [debug] 29523#0: *1 http write filter limit 0
2013/04/22 13:58:21 [debug] 29523#0: *1 writev: 129
2013/04/22 13:58:21 [debug] 29523#0: *1 http write filter 0000000000000000
2013/04/22 13:58:21 [debug] 29523#0: *1 http finalize request: 0, "/ngx_pagespeed_beacon?" a:1, c:1
2013/04/22 13:58:21 [debug] 29523#0: *1 set http keepalive handler
2013/04/22 13:58:21 [debug] 29523#0: *1 http close request
2013/04/22 13:58:21 [debug] 29523#0: *1 http log handler
2013/04/22 13:58:21 [debug] 29523#0: *1 free: 0000000001F7B0F0, unused: 16
2013/04/22 13:58:21 [debug] 29523#0: *1 free: 0000000001F7D3F0, unused: 3724
2013/04/22 13:58:21 [debug] 29523#0: *1 pipelined request
2013/04/22 13:58:21 [debug] 29523#0: *1 posix_memalign: 0000000001F7B0F0:4096 @16
2013/04/22 13:58:21 [debug] 29523#0: *1 post event 0000000001E7A9D8
2013/04/22 13:58:21 [debug] 29523#0: timer delta: 38
2013/04/22 13:58:21 [debug] 29523#0: posted events 0000000001E7A9D8
2013/04/22 13:58:21 [debug] 29523#0: posted event 0000000001E7A9D8
2013/04/22 13:58:21 [debug] 29523#0: *1 delete posted event 0000000001E7A9D8
2013/04/22 13:58:21 [debug] 29523#0: *1 http process request line
2013/04/22 13:58:21 [debug] 29523#0: *1 recv: fd:3 -1 of 602
2013/04/22 13:58:21 [debug] 29523#0: *1 recv() not ready (11: Resource temporarily unavailable)
2013/04/22 13:58:21 [debug] 29523#0: *1 event timer add: 3: 60000:1366653561002
2013/04/22 13:58:21 [debug] 29523#0: posted event 0000000000000000
2013/04/22 13:58:21 [debug] 29523#0: worker cycle
2013/04/22 13:58:21 [debug] 29523#0: epoll timer: 60000
```