incomplete javascript downloading

[jeffkaufman]

I've prepared a CentOS 5 VM running 1.5.27.3-rc1 as part of preparing the next release. When I run the system tests I get:

TEST: Fetch the deferJs url with hash.
run_wget_with_args js_defer_debug.fxi6kLpaRF.js
wget -H -p -S -o /tmp/mod_pagespeed_test.jefftk/fetched_directory/wget_output.txt -nd -P /tmp/mod_pagespeed_test.jefftk/fetched_directory -e robots=off --header=ModPagespeedFilters:defer_javascript,debug http://localhost:8050/ngx_pagespeed_static/js_defer_debug.fxi6kLpaRF.js
[hangs]

This is with wget 1.14 (CentOS ships with 1.11, which is too old for the test.)

Looking in /tmp/mod_pagespeed_test.jefftk/fetched_directory/ I see both js_defer_debug.fxi6kLpaRF.js and js_defer_debug.fxi6kLpaRF.js.1. Which makes sense: wget downloads a page that references js_defer_debug... recursively giving us the first one, and the hang is when it's getting the second one. But the second one doesn't download completely. It's 48902 bytes instead of 53109.

[jeffkaufman]

Testing with telnet:

$ telnet localhost 8050
GET /ngx_pagespeed_static/js_defer_debug.fxi6kLpaRF.js HTTP/1.1
Host: localhost
ModPagespeedFilters:defer_javascript,debug 

...
pagespeed['addHandler'] = deferJsNs.addHandler;

/**
 * @return {boolean}

This cuts off partway through even on a freshly restarted ngx_pagespeed.

[jeffkaufman]

The ModPagespeedFilters isn't the problem; this fails for me too:

$ telnet localhost 8050
GET /ngx_pagespeed_static/js_defer_debug.fxi6kLpaRF.js HTTP/1.1
Host: localhost

[jeffkaufman]

The testing above was with Release, but it also happens with Debug. Error log:

2013/05/14 13:00:32 [debug] 11916#0: bind() 0.0.0.0:8051 #6 
2013/05/14 13:00:32 [debug] 11916#0: bind() 0.0.0.0:8050 #7 
2013/05/14 13:00:32 [notice] 11916#0: using the "epoll" event method
2013/05/14 13:00:32 [debug] 11916#0: counter: 00002AB7D8B8B080, 1
2013/05/14 13:00:32 [info] 11916#0: [ngx_pagespeed 1.5.27.3-3005] SharedMemCache: /home/jefftk/ngx_pagespeed/test/tmp/file-cache/with_shm///metadata_cache, sectors = 128, entries/sector = 356,  64-byte blocks/sector = 712, total footprint: 8404992
2013/05/14 13:00:32 [info] 11916#0: [ngx_pagespeed 1.5.27.3-3005] Initializing shared memory for path: /home/jefftk/ngx_pagespeed/test/tmp/file-cache//.
2013/05/14 13:00:32 [info] 11916#0: [ngx_pagespeed 1.5.27.3-3005] Initializing shared memory for path: /home/jefftk/ngx_pagespeed/test/tmp/file-cache/secondary//.
2013/05/14 13:00:32 [info] 11916#0: [ngx_pagespeed 1.5.27.3-3005] Initializing shared memory for path: /home/jefftk/ngx_pagespeed/test/tmp/file-cache/with_shm//.
2013/05/14 13:00:32 [notice] 11916#0: nginx/1.4.1
2013/05/14 13:00:32 [notice] 11916#0: built by gcc 4.1.2 20080704 (Red Hat 4.1.2-54)
2013/05/14 13:00:32 [notice] 11916#0: OS: Linux 2.6.18-348.el5
2013/05/14 13:00:32 [notice] 11916#0: getrlimit(RLIMIT_NOFILE): 1024:1024
2013/05/14 13:00:32 [debug] 11917#0: write: 8, 00007FFF9D385740, 6, 0
2013/05/14 13:00:32 [debug] 11917#0: setproctitle: "nginx: master process /home/jefftk/nginx-debug/sbin/nginx -c /home/jefftk/ngx_pagespeed/test/tmp/pagespeed_test.conf"
2013/05/14 13:00:32 [notice] 11917#0: start worker processes
2013/05/14 13:00:32 [debug] 11917#0: channel 3:8
2013/05/14 13:00:32 [debug] 11918#0: malloc: 00000000107E0040:6144
2013/05/14 13:00:32 [debug] 11918#0: malloc: 0000000010C2E820:188416
2013/05/14 13:00:32 [debug] 11918#0: malloc: 0000000010C5C830:106496
2013/05/14 13:00:32 [debug] 11918#0: malloc: 0000000010C76840:106496
2013/05/14 13:00:32 [debug] 11918#0: epoll add event: fd:6 op:1 ev:00000001
2013/05/14 13:00:32 [debug] 11918#0: epoll add event: fd:7 op:1 ev:00000001
2013/05/14 13:00:32 [info] 11918#0: [ngx_pagespeed 1.5.27.3-3005] Reusing shared memory for path: /home/jefftk/ngx_pagespeed/test/tmp/file-cache//.
2013/05/14 13:00:32 [info] 11918#0: [ngx_pagespeed 1.5.27.3-3005] Reusing shared memory for path: /home/jefftk/ngx_pagespeed/test/tmp/file-cache/secondary//.
2013/05/14 13:00:32 [info] 11918#0: [ngx_pagespeed 1.5.27.3-3005] Reusing shared memory for path: /home/jefftk/ngx_pagespeed/test/tmp/file-cache/with_shm//.
2013/05/14 13:00:32 [notice] 11917#0: start worker process 11918
2013/05/14 13:00:32 [debug] 11917#0: sigsuspend
2013/05/14 13:00:32 [debug] 11918#0: epoll add event: fd:8 op:1 ev:00000001
2013/05/14 13:00:32 [debug] 11918#0: setproctitle: "nginx: worker process"
2013/05/14 13:00:32 [debug] 11918#0: worker cycle
2013/05/14 13:00:32 [debug] 11918#0: epoll timer: -1
2013/05/14 13:00:37 [debug] 11918#0: epoll: fd:7 ev:0001 d:0000000010C2E8D8
2013/05/14 13:00:37 [debug] 11918#0: accept on 0.0.0.0:8050, ready: 0
2013/05/14 13:00:37 [debug] 11918#0: posix_memalign: 0000000010D6B370:256 @16
2013/05/14 13:00:37 [debug] 11918#0: *1 accept: 127.0.0.1 fd:3
2013/05/14 13:00:37 [debug] 11918#0: *1 event timer add: 3: 60000:1368550897940
2013/05/14 13:00:37 [debug] 11918#0: *1 reusable connection: 1
2013/05/14 13:00:37 [debug] 11918#0: *1 epoll add event: fd:3 op:1 ev:80000001
2013/05/14 13:00:37 [debug] 11918#0: timer delta: 5136
2013/05/14 13:00:37 [debug] 11918#0: posted events 0000000000000000
2013/05/14 13:00:37 [debug] 11918#0: worker cycle
2013/05/14 13:00:37 [debug] 11918#0: epoll timer: 60000
2013/05/14 13:00:51 [debug] 11918#0: epoll: fd:3 ev:0001 d:0000000010C2EA48
2013/05/14 13:00:51 [debug] 11918#0: *1 http wait request handler
2013/05/14 13:00:51 [debug] 11918#0: *1 posix_memalign: 0000000010D6B480:256 @16
2013/05/14 13:00:51 [debug] 11918#0: *1 malloc: 0000000010D6B590:1024
2013/05/14 13:00:51 [debug] 11918#0: *1 recv: fd:3 65 of 1024
2013/05/14 13:00:51 [debug] 11918#0: *1 reusable connection: 0
2013/05/14 13:00:51 [debug] 11918#0: *1 posix_memalign: 0000000010D6B9A0:4096 @16
2013/05/14 13:00:51 [debug] 11918#0: *1 http process request line
2013/05/14 13:00:51 [debug] 11918#0: *1 http request line: "GET /ngx_pagespeed_static/js_defer_debug.fxi6kLpaRF.js HTTP/1.1"
2013/05/14 13:00:51 [debug] 11918#0: *1 http uri: "/ngx_pagespeed_static/js_defer_debug.fxi6kLpaRF.js"
2013/05/14 13:00:51 [debug] 11918#0: *1 http args: ""
2013/05/14 13:00:51 [debug] 11918#0: *1 http exten: "js"
2013/05/14 13:00:51 [debug] 11918#0: *1 http process request header line
2013/05/14 13:00:51 [debug] 11918#0: *1 recv: fd:3 -1 of 959
2013/05/14 13:00:51 [debug] 11918#0: *1 recv() not ready (11: Resource temporarily unavailable)
2013/05/14 13:00:51 [debug] 11918#0: timer delta: 13877
2013/05/14 13:00:51 [debug] 11918#0: posted events 0000000000000000
2013/05/14 13:00:51 [debug] 11918#0: worker cycle
2013/05/14 13:00:51 [debug] 11918#0: epoll timer: 46123
2013/05/14 13:00:52 [debug] 11918#0: epoll: fd:3 ev:0001 d:0000000010C2EA48
2013/05/14 13:00:52 [debug] 11918#0: *1 http process request header line
2013/05/14 13:00:52 [debug] 11918#0: *1 recv: fd:3 17 of 959
2013/05/14 13:00:52 [debug] 11918#0: *1 http header: "Host: localhost"
2013/05/14 13:00:52 [debug] 11918#0: *1 recv: fd:3 -1 of 942
2013/05/14 13:00:52 [debug] 11918#0: *1 recv() not ready (11: Resource temporarily unavailable)
2013/05/14 13:00:52 [debug] 11918#0: timer delta: 537
2013/05/14 13:00:52 [debug] 11918#0: posted events 0000000000000000
2013/05/14 13:00:52 [debug] 11918#0: worker cycle
2013/05/14 13:00:52 [debug] 11918#0: epoll timer: 45586
2013/05/14 13:00:52 [debug] 11918#0: epoll: fd:3 ev:0001 d:0000000010C2EA48
2013/05/14 13:00:52 [debug] 11918#0: *1 http process request header line
2013/05/14 13:00:52 [debug] 11918#0: *1 recv: fd:3 2 of 942
2013/05/14 13:00:52 [debug] 11918#0: *1 http header done
2013/05/14 13:00:52 [debug] 11918#0: *1 event timer del: 3: 1368550897940
2013/05/14 13:00:52 [debug] 11918#0: *1 rewrite phase: 0
2013/05/14 13:00:52 [debug] 11918#0: *1 test location: "/mod_pagespeed_test/forbid_all_disabled/disabled"
2013/05/14 13:00:52 [debug] 11918#0: *1 test location: "/mod_pagespeed_test/ssi/"
2013/05/14 13:00:52 [debug] 11918#0: *1 test location: "/ngx_pagespeed_statistics"
2013/05/14 13:00:52 [debug] 11918#0: *1 test location: "/ngx_pagespeed_message"
2013/05/14 13:00:52 [debug] 11918#0: *1 test location: ~ "\.pagespeed\.([a-z]\.)?[a-z]{2}\.[^.]{10}\.[^.]+"
2013/05/14 13:00:52 [debug] 11918#0: *1 test location: ~ "\.php$"
2013/05/14 13:00:52 [debug] 11918#0: *1 using configuration ""
2013/05/14 13:00:52 [debug] 11918#0: *1 http cl:-1 max:1048576
2013/05/14 13:00:52 [debug] 11918#0: *1 rewrite phase: 2
2013/05/14 13:00:52 [debug] 11918#0: *1 post rewrite phase: 3
2013/05/14 13:00:52 [debug] 11918#0: *1 generic phase: 4
2013/05/14 13:00:52 [debug] 11918#0: *1 generic phase: 4
2013/05/14 13:00:52 [debug] 11918#0: *1 generic phase: 5
2013/05/14 13:00:52 [debug] 11918#0: *1 access phase: 6
2013/05/14 13:00:52 [debug] 11918#0: *1 access phase: 7
2013/05/14 13:00:52 [debug] 11918#0: *1 post access phase: 8
2013/05/14 13:00:52 [debug] 11918#0: *1 pagespeed phase: 9
2013/05/14 13:00:52 [debug] 11918#0: *1 http pagespeed handler "/ngx_pagespeed_static/js_defer_debug.fxi6kLpaRF.js"
2013/05/14 13:00:52 [debug] 11918#0: *1 posix_memalign: 0000000010D6C9B0:4096 @16
2013/05/14 13:00:52 [debug] 11918#0: *1 HTTP/1.1 200 OK
Server: nginx/1.4.1
Date: Tue, 14 May 2013 17:00:52 GMT
Content-Type: application/javascript
Content-Length: 53109
Connection: keep-alive
Vary: Accept-Encoding
Cache-Control: max-age=31536000
ETag: W/"0"
X-Extra-Header: 1

2013/05/14 13:00:52 [debug] 11918#0: *1 write new buf t:1 f:0 0000000010D6C9D0, pos 0000000010D6C9D0, size: 250 file: 0, size: 0
2013/05/14 13:00:52 [debug] 11918#0: *1 http write filter: l:0 f:0 s:250
2013/05/14 13:00:52 [debug] 11918#0: *1 malloc: 0000000010D6D9C0:8192
2013/05/14 13:00:52 [debug] 11918#0: *1 malloc: 0000000010D6F9D0:8192
2013/05/14 13:00:52 [debug] 11918#0: *1 malloc: 0000000010D719E0:8192
2013/05/14 13:00:52 [debug] 11918#0: *1 malloc: 0000000010D739F0:8192
2013/05/14 13:00:52 [debug] 11918#0: *1 malloc: 0000000010D75A00:8192
2013/05/14 13:00:52 [debug] 11918#0: *1 malloc: 0000000010D77A10:8192
2013/05/14 13:00:52 [debug] 11918#0: *1 posix_memalign: 0000000010D79A20:4096 @16
2013/05/14 13:00:52 [debug] 11918#0: *1 http output filter "/ngx_pagespeed_static/js_defer_debug.fxi6kLpaRF.js?"
2013/05/14 13:00:52 [debug] 11918#0: *1 http copy filter: "/ngx_pagespeed_static/js_defer_debug.fxi6kLpaRF.js?"
2013/05/14 13:00:52 [debug] 11918#0: *1 http postpone filter "/ngx_pagespeed_static/js_defer_debug.fxi6kLpaRF.js?" 0000000010D6CE28
2013/05/14 13:00:52 [debug] 11918#0: *1 write old buf t:1 f:0 0000000010D6C9D0, pos 0000000010D6C9D0, size: 250 file: 0, size: 0
2013/05/14 13:00:52 [debug] 11918#0: *1 write new buf t:1 f:0 0000000010D6D9C0, pos 0000000010D6D9C0, size: 8192 file: 0, size: 0
2013/05/14 13:00:52 [debug] 11918#0: *1 write new buf t:1 f:0 0000000010D6F9D0, pos 0000000010D6F9D0, size: 8192 file: 0, size: 0
2013/05/14 13:00:52 [debug] 11918#0: *1 write new buf t:1 f:0 0000000010D719E0, pos 0000000010D719E0, size: 8192 file: 0, size: 0
2013/05/14 13:00:52 [debug] 11918#0: *1 write new buf t:1 f:0 0000000010D739F0, pos 0000000010D739F0, size: 8192 file: 0, size: 0
2013/05/14 13:00:52 [debug] 11918#0: *1 write new buf t:1 f:0 0000000010D75A00, pos 0000000010D75A00, size: 8192 file: 0, size: 0
2013/05/14 13:00:52 [debug] 11918#0: *1 write new buf t:1 f:0 0000000010D77A10, pos 0000000010D77A10, size: 8192 file: 0, size: 0
2013/05/14 13:00:52 [debug] 11918#0: *1 write new buf t:1 f:0 0000000010D79A40, pos 0000000010D79A40, size: 3957 file: 0, size: 0
2013/05/14 13:00:52 [debug] 11918#0: *1 http write filter: l:1 f:0 s:53359
2013/05/14 13:00:52 [debug] 11918#0: *1 http write filter limit 0
2013/05/14 13:00:52 [debug] 11918#0: *1 writev: 49152
2013/05/14 13:00:52 [debug] 11918#0: *1 http write filter 0000000010D6CEE8
2013/05/14 13:00:52 [debug] 11918#0: *1 http copy filter: -2 "/ngx_pagespeed_static/js_defer_debug.fxi6kLpaRF.js?"
2013/05/14 13:00:52 [debug] 11918#0: timer delta: 599
2013/05/14 13:00:52 [debug] 11918#0: posted events 0000000000000000
2013/05/14 13:00:52 [debug] 11918#0: worker cycle
2013/05/14 13:00:52 [debug] 11918#0: epoll timer: -1

[jeffkaufman]

I would like to test with the 1.5.27.2 binaries, but they don't support CentOS.

[jeffkaufman]

This seemed like it might have been caused by 9c09f92, so I reverted that to test, but the problem persists.

[jeffkaufman]

bisecting

[jeffkaufman]

bad even back to commit e079640

[jeffkaufman]

Going back before then is hard because we depend on a different version of psol.

[jeffkaufman]

I've switched from 8196 byte buffers in the buffer chain to 256 byte ones to make it easier to see what's going on.

In telnet I still see us cutting off at the same place, after the "@return {boolean}". Interestingly, this isn't on a chain link boundary, though it is close to one. I see the previous link ending with {bo and the next one starting with olean}.

The chain we're creating has all the links it should, and I see them all dumped to the log looking correct. With 256 byte buffers it fails partway through buffer 191 of 207.

[jeffkaufman]

I think the problem is that ngx_http_output_filter is returning NGX_AGAIN to ps_static_handler. In ps_connection_read_handler we have "If we still have data to write, set a write handler so we can get called back to make our write" and I think we might need that here.

[jeffkaufman]

Calling ngx_http_set_pagespeed_write_handler(r) if ngx_http_output_filter gives NGX_AGAIN does the trick. Preparing pull request.

[jeffkaufman]

Released in 1.5.27.3