New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Client times out on (304) requests #537

Closed
saravsars opened this Issue Oct 7, 2013 · 40 comments

Comments

Projects
None yet
6 participants
@saravsars
Copy link

saravsars commented Oct 7, 2013

For 200 requests everything works fine

a200

For 304 requests , it takes 1 minute to complete

a304

In error log

error

What is the issue here??

OS: Ubuntu 12.04
Nginx version: 1.5.6
Pagespeed : 1.6.29.5

Thanks

@oschaaf

This comment has been minimized.

Copy link
Member

oschaaf commented Oct 7, 2013

@saravsars I fail to reproduce this with Ubuntu 12.04.3/nginx 1.5.6/Pagespeed 1.6.29.5.
Would you be able to crank up the logging level to debug, reproduce, and post the error log content?

I tried with chrome, but also with curl:

oschaaf@ubuntu:~$ curl -vv 'http://192.168.185.185/mod_pagespeed_example/images/xCuppa.png.pagespeed.ic.jf3PtqQ39N.png' 'http://192.168.185.185/mod_pagespeed_example/images/xCuppa.png.pagespeed.ic.jf3PtqQ39N.png' -H 'Pragma: no-cache' -H 'Accept-Encoding: gzip,deflate,sdch' -H 'Host: 192.168.185.185' -H 'Accept-Language: nl-NL,nl;q=0.8,en-US;q=0.6,en;q=0.4' -H 'User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/30.0.1599.69 Safari/537.36' -H 'Accept: image/webp,*/*;q=0.8' -H 'Cache-Control: max-age=0' -H 'If-None-Match: W/"0"' -H 'Connection: keep-alive' -H 'If-Modified-Since: Mon, 07 Oct 2013 08:04:06 GMT' -H 'Referer: http://192.168.185.185/mod_pagespeed_example/rewrite_css_images.html?PageSpeed=on&PageSpeedFilters=rewrite_css,rewrite_images,prioritize_critical_css' --compressed
* About to connect() to 192.168.185.185 port 80 (#0)
*   Trying 192.168.185.185... connected
> GET /mod_pagespeed_example/images/xCuppa.png.pagespeed.ic.jf3PtqQ39N.png HTTP/1.1
> Pragma: no-cache
> Accept-Encoding: gzip,deflate,sdch
> Host: 192.168.185.185
> Accept-Language: nl-NL,nl;q=0.8,en-US;q=0.6,en;q=0.4
> User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/30.0.1599.69 Safari/537.36
> Accept: image/webp,*/*;q=0.8
> Cache-Control: max-age=0
> If-None-Match: W/"0"
> Connection: keep-alive
> If-Modified-Since: Mon, 07 Oct 2013 08:04:06 GMT
> Referer: http://192.168.185.185/mod_pagespeed_example/rewrite_css_images.html?PageSpeed=on&PageSpeedFilters=rewrite_css,rewrite_images,prioritize_critical_css
> 
< HTTP/1.1 304 Not Modified
< Server: nginx/1.5.6
< Date: Mon, 07 Oct 2013 08:18:40 GMT
< Connection: keep-alive
< X-Page-Speed: 1.6.29.5-3346
< 
* Connection #0 to host 192.168.185.185 left intact
* Re-using existing connection! (#0) with host 192.168.185.185
* Connected to 192.168.185.185 (192.168.185.185) port 80 (#0)
> GET /mod_pagespeed_example/images/xCuppa.png.pagespeed.ic.jf3PtqQ39N.png HTTP/1.1
> Pragma: no-cache
> Accept-Encoding: gzip,deflate,sdch
> Host: 192.168.185.185
> Accept-Language: nl-NL,nl;q=0.8,en-US;q=0.6,en;q=0.4
> User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/30.0.1599.69 Safari/537.36
> Accept: image/webp,*/*;q=0.8
> Cache-Control: max-age=0
> If-None-Match: W/"0"
> Connection: keep-alive
> If-Modified-Since: Mon, 07 Oct 2013 08:04:06 GMT
> Referer: http://192.168.185.185/mod_pagespeed_example/rewrite_css_images.html?PageSpeed=on&PageSpeedFilters=rewrite_css,rewrite_images,prioritize_critical_css
> 
< HTTP/1.1 304 Not Modified
< Server: nginx/1.5.6
< Date: Mon, 07 Oct 2013 08:18:40 GMT
< Connection: keep-alive
< X-Page-Speed: 1.6.29.5-3346
< 
* Connection #0 to host 192.168.185.185 left intact
* Closing connection #0
oschaaf@ubuntu:~$ 

@saravsars

This comment has been minimized.

Copy link

saravsars commented Oct 7, 2013

@oschaaf error log content for 304 request : http://pastebin.com/HgXJB4Qk

Can you share your nginx configuration file ??

Thanks.

@oschaaf

This comment has been minimized.

Copy link
Member

oschaaf commented Oct 7, 2013

@saravsars thanks for the log, I'll have a look
My nginx configuration: http://pastebin.com/CJrwEMz9

@oschaaf

This comment has been minimized.

Copy link
Member

oschaaf commented Oct 7, 2013

@saravsars I would also be interested in your nginx.conf and ./configure.
Could ngx_pagespeed be doing something here that doesn't work well with another nginx module?

@saravsars

This comment has been minimized.

Copy link

saravsars commented Oct 7, 2013

@oschaaf I'm using your configuration now but the issue is not resolved.

nginx.conf : http://pastebin.com/xz8wrhYF

nginx configure :

nginx version: nginx/1.5.6
configure arguments: --prefix=/opt/nginx --user=nginx --group=nginx --add-module=/home/Downloads/ngx_pagespeed-master --add-module=/home/Downloads/ngx_cache_purge-master --with-debug

@saravsars

This comment has been minimized.

Copy link

saravsars commented Oct 7, 2013

@oschaaf strangely this configuration and your configuration works if I enable defer-javascript filter. When I disable defer-javascript client timed out error occurs.

Any reason for it ??

nginx.conf

worker_processes 1;

events {
worker_connections 1024;
}

http {

pagespeed on;

server {
listen 9071;
server_name localhost;
pagespeed FileCachePath "/opt/ngx_pagespeed/";
pagespeed RewriteLevel CoreFilters;
pagespeed EnableFilters defer_javascript;

location /
{
    root html/banner;
    index index.html;
}   

}

sendfile on;

keepalive_timeout 65;

set up gzip

gzip on;
gzip_vary on;
gzip_http_version 1.0;

default_type application/octet-stream;

}

@oschaaf

This comment has been minimized.

Copy link
Member

oschaaf commented Oct 7, 2013

The ./configure and nginx.conf you are using are really similar to mine.
One thing I noted in the error log you posted was this:

2013/10/07 14:02:35 [debug] 9340#0: *36 ps fetch handler: /index.html
2013/10/07 14:02:35 [debug] 9340#0: *36 HTTP/1.1 200 OK
Server: nginx/1.4.2

Did you perhaps switch testing to 1.4.2?

If defer_javascript makes the issue go away, the only thing I can come up with, is that you are hitting a corner case with either the timings or file sizes involved.
I suspect that disabling keepalives will resolve the problem, but I don't think that is a proper workaround.

[1] http://wiki.nginx.org/HttpCoreModule#keepalive_disable

@saravsars

This comment has been minimized.

Copy link

saravsars commented Oct 7, 2013

@oschaaf yeah I'm testing both 1.4.2 and 1.5.6.

Setting keepalive_timeout 0; solves the issue but I need some other solution.

Thanks for quick response 👍

@oschaaf

This comment has been minimized.

Copy link
Member

oschaaf commented Oct 7, 2013

@saravsars
Would you be able to post your website here? Or pm it if you don't want to post it public?
I feel it is like a long shot, but that way, we might be able to hit the same corner case and reproduce.

@saravsars

This comment has been minimized.

Copy link

saravsars commented Oct 7, 2013

@oschaaf I'll try to post it public asap.

BTW Im seeing this error many times in error.log
recv

It is usual one ??
Full error.log : https://docs.google.com/file/d/0B9HIahYpqDmdNmUzNnNsbVF2cFE/edit?usp=sharing

Thanks

@oschaaf

This comment has been minimized.

Copy link
Member

oschaaf commented Oct 8, 2013

@saravsars Would you be able to try the current master?
@jeffkaufman just opened and diagnosed #538, and I think that might be related - which would mean this should be fixed on the current master.

@adegtyarev

This comment has been minimized.

Copy link

adegtyarev commented Oct 12, 2013

You may want to set keepalive_timeout 0; to only on pagespeed-specific location to workaround the problem:

location ~ "\.pagespeed\.([a-z]\.)?[a-z]{2}\.[^.]{10}\.[^.]+" {
  keepalive_timeout 0;
}

By the way, I only have these options related to pagespeed:

pagespeed on;
pagespeed FileCachePath /var/cache/ngx_pagespeed;

nginx: 1.4.3
pagespeed: 1.6.29.5-3346

@saravsars

This comment has been minimized.

Copy link

saravsars commented Oct 14, 2013

@oschaaf @degtyarevalexey yeah using keepalive_timeout 0; for pagespeed specific resources.

Thanks 👍

@tuurbo

This comment has been minimized.

Copy link

tuurbo commented Oct 26, 2013

Having the same problem as saravsars. Using keepalive_timeout 0 fixed the problem for me as well, but is it safe to use keepalive_timeout 0 as described above without causing any problems?

ubuntu: 13.10
nginx: 1.4.3
pagespeed: 1.6.29.5

./configure --add-module=$HOME/ngx_pagespeed --with-http_ssl_module --with-openssl=/usr/bin/openssl

pagespeed on;
pagespeed FileCachePath /var/ngx_pagespeed_cache;

location ~ "\.pagespeed\.([a-z]\.)?[a-z]{2}\.[^.]{10}\.[^.]+" {
    add_header "" "";
    keepalive_timeout 0;
}
location ~ "^/ngx_pagespeed_static/" { }
location ~ "^/ngx_pagespeed_beacon$" { }
location /ngx_pagespeed_statistics { allow 127.0.0.1; deny all; }
location /ngx_pagespeed_message { allow 127.0.0.1; deny all; }
location /pagespeed_console { allow 127.0.0.1; deny all; }

Edit

For whatever reason putting keepalive_timeout 0 inside the pagespeed location regex stopped working for me. Has to be put outside of it.

@jeffkaufman

This comment has been minimized.

Copy link
Contributor

jeffkaufman commented Oct 28, 2013

keepalive_timeout 0 is safe but not efficient. We think this bug is fixed on master and the fix will be in the next release.

@tuurbo

This comment has been minimized.

Copy link

tuurbo commented Nov 5, 2013

I just compiled nginx with the pagespeed master today (1.6.29.7-3453) and I'm still getting the same problem.

ubuntu: 13.10
nginx: 1.4.3
pagespeed: 1.6.29.7-3453
./configure --add-module=$HOME/ngx_pagespeed --with-http_ssl_module --with-openssl=/usr/src/openssl-1.0.1e

@oschaaf

This comment has been minimized.

Copy link
Member

oschaaf commented Nov 5, 2013

@tuurbo
Looking back at a prior comment, I have a suspicion:
Could you try to add the keepalive setting to the beacon location?:

location ~ "^/ngx_pagespeed_beacon$" { keepalive_timeout 0; }

It would be good to know if disabling keepalive at only that location resolves the problem

@tuurbo

This comment has been minimized.

Copy link

tuurbo commented Nov 5, 2013

@oschaaf Just tried that and it didn't resolve the issue

@oschaaf

This comment has been minimized.

Copy link
Member

oschaaf commented Nov 5, 2013

@tuurbo The problem doesn't seem to reproduce for me, what browser are you testing with?

@tuurbo

This comment has been minimized.

Copy link

tuurbo commented Nov 5, 2013

chrome 30, firefox 25, IE 10

you should see the problem by refreshing the page a few times

@oschaaf

This comment has been minimized.

Copy link
Member

oschaaf commented Nov 5, 2013

@tuurbo
/cc @jeffkaufman

Thanks, I was able to reproduce it, and I can reproduce this when replaying chrome's request using curl now too:

curl 'http://162.243.66.244/A.test1.css+test2.css+normalize.css,Mcc.AGf1ZLA5YO.css.pagespeed.cf.jsqcE5eTy3.css' -H 'Pragma: no-cache' -H 'Accept-Encoding: gzip,deflate,sdch' -H 'Host: 162.243.66.244' -H 'Accept-Language: nl-NL,nl;q=0.8,en-US;q=0.6,en;q=0.4' -H 'User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/30.0.1599.101 Safari/537.36' -H 'Accept: text/css,*/*;q=0.1' -H 'Cache-Control: max-age=0' -H 'If-None-Match: W/"0"' -H 'Connection: keep-alive' -H 'If-Modified-Since: Tue, 05 Nov 2013 09:31:39 GMT' -H 'Referer: http://162.243.66.244/test.htm' --compressed http://162.243.66.244/test.htm

That should help us to figure this out.

The second request to http://162.243.66.244/test.htm seems to wait for a timeout to fire before it gets processed, so apparently, the 304 response seems to drop the ball.

While we figure this out, I can currently only suggest working around this for now with setting keepalive_timeout 0; as before.

@oschaaf

This comment has been minimized.

Copy link
Member

oschaaf commented Nov 5, 2013

@chaizhenhua Could you have a look at this? Does ps_connection_read_handler need extra handling for responses without an entity body?

@chaizhenhua

This comment has been minimized.

Copy link
Contributor

chaizhenhua commented Nov 5, 2013

@oschaaf It seems that we do not need extra handling if HandleDone is called for all response.

@jeffkaufman

This comment has been minimized.

Copy link
Contributor

jeffkaufman commented Nov 8, 2013

Testing on the 1.7.30.1 I was about to release, this is not actually fixed:

$ curl -vv 'http://localhost:8050/A.test1.css+test2.css+normalize.css,Mcc.AGf1ZLA5YO.css.pagespeed.cf.jsqcE5eTy3.css' -H 'Connection: keep-alive' -H 'If-Modified-Since: Tue, 05 Nov 2013 09:31:39 GMT' http://localhost:8050/test.htm
* About to connect() to localhost port 8050 (#0)
*   Trying 127.0.0.1... connected
> GET /A.test1.css+test2.css+normalize.css,Mcc.AGf1ZLA5YO.css.pagespeed.cf.jsqcE5eTy3.css HTTP/1.1
> User-Agent: curl/7.22.0 (x86_64-pc-linux-gnu) libcurl/7.22.0 OpenSSL/1.0.1 zlib/1.2.3.4 libidn/1.23 librtmp/2.3
> Host: localhost:8050
> Accept: */*
> Connection: keep-alive
> If-Modified-Since: Tue, 05 Nov 2013 09:31:39 GMT
> 
< HTTP/1.1 304 Not Modified
< Server: nginx/1.4.1
< Date: Fri, 08 Nov 2013 14:06:33 GMT
< Connection: keep-alive
< X-Page-Speed: 1.7.30.1-3609
< 
* Connection #0 to host localhost left intact
* Re-using existing connection! (#0) with host localhost
* Connected to localhost (127.0.0.1) port 8050 (#0)
> GET /test.htm HTTP/1.1
> User-Agent: curl/7.22.0 (x86_64-pc-linux-gnu) libcurl/7.22.0 OpenSSL/1.0.1 zlib/1.2.3.4 libidn/1.23 librtmp/2.3
> Host: localhost:8050
> Accept: */*
> Connection: keep-alive
> If-Modified-Since: Tue, 05 Nov 2013 09:31:39 GMT
> 
* Recv failure: Connection reset by peer
* Connection died, retrying a fresh connect
* Closing connection #0
* Issue another request to this URL: 'http://localhost:8050/test.htm'
* About to connect() to localhost port 8050 (#0)
*   Trying 127.0.0.1... connected
> GET /test.htm HTTP/1.1
> User-Agent: curl/7.22.0 (x86_64-pc-linux-gnu) libcurl/7.22.0 OpenSSL/1.0.1 zlib/1.2.3.4 libidn/1.23 librtmp/2.3
> Host: localhost:8050
> Accept: */*
> Connection: keep-alive
> If-Modified-Since: Tue, 05 Nov 2013 09:31:39 GMT
> 
[60s pause here]
< HTTP/1.1 404 Not Found
< Server: nginx/1.4.1
< Date: Fri, 08 Nov 2013 14:07:33 GMT
< Content-Type: text/html
< Content-Length: 168
< Connection: keep-alive
< Vary: Accept-Encoding
< 
<html>
<head><title>404 Not Found</title></head>
<body bgcolor="white">
<center><h1>404 Not Found</h1></center>
<hr><center>nginx/1.4.1</center>
</body>
</html>
* Connection #0 to host localhost left intact
* Closing connection #0
@jeffkaufman

This comment has been minimized.

Copy link
Contributor

jeffkaufman commented Nov 8, 2013

Slightly smaller test case:

$  curl -vv 'http://localhost:8050/foo.css.pagespeed.ce.0.css' -H 'If-Modified-Since: Z' http://localhost:8050/foo
* About to connect() to localhost port 8050 (#0)
*   Trying 127.0.0.1... connected
> GET /foo.css.pagespeed.ce.0.css HTTP/1.1
> User-Agent: curl/7.22.0 (x86_64-pc-linux-gnu) libcurl/7.22.0 OpenSSL/1.0.1 zlib/1.2.3.4 libidn/1.23 librtmp/2.3
> Host: localhost:8050
> Accept: */*
> If-Modified-Since: Z
> 
< HTTP/1.1 304 Not Modified
< Server: nginx/1.4.1
< Date: Fri, 08 Nov 2013 14:14:07 GMT
< Connection: keep-alive
< X-Page-Speed: 1.7.30.1-3609
< 
* Connection #0 to host localhost left intact
* Re-using existing connection! (#0) with host localhost
* Connected to localhost (127.0.0.1) port 8050 (#0)
> GET /foo HTTP/1.1
> User-Agent: curl/7.22.0 (x86_64-pc-linux-gnu) libcurl/7.22.0 OpenSSL/1.0.1 zlib/1.2.3.4 libidn/1.23 librtmp/2.3
> Host: localhost:8050
> Accept: */*
> If-Modified-Since: Z
> 
[60s pause here]
< HTTP/1.1 404 Not Found
< Server: nginx/1.4.1
< Date: Fri, 08 Nov 2013 14:15:07 GMT
< Content-Type: text/html
< Content-Length: 168
< Connection: keep-alive
< Vary: Accept-Encoding
< 
<html>
<head><title>404 Not Found</title></head>
<body bgcolor="white">
<center><h1>404 Not Found</h1></center>
<hr><center>nginx/1.4.1</center>
</body>
</html>
* Connection #0 to host localhost left intact
* Closing connection #0
@jeffkaufman

This comment has been minimized.

Copy link
Contributor

jeffkaufman commented Nov 8, 2013

Tracing execution I see:

request comes in for http://localhost:8050/foo.css.pagespeed.ce.0.css
psol will see that it's a .pagespeed. resources and respond 304
NgxBaseFetch::HandleDone(success=1)
NgxBaseFetch::DecrefAndDeleteIfUnreferenced -- no delete
[debug] http finalize request: -4 (NGX_DONE), "/foo.css.pagespeed.ce.0.css?" a:1, c:2
[debug] http request count:2 blk:0
[debug] reusable connection: 0
[debug] ps fetch handler: /foo.css.pagespeed.ce.0.css
304 headers sent out
[debug] http finalize request: 0 (NGX_OK), "/foo.css.pagespeed.ce.0.css?" a:1, c:1
[debug] http run request: "/foo.css.pagespeed.ce.0.css?"
... 60s pause ...
[debug] timer delta: 60018
[debug] http run request: "/foo.css.pagespeed.ce.0.css?"
[debug] http writer handler: "/foo.css.pagespeed.ce.0.css?"
[debug] client timed out (110: Connection timed out),
            client: 127.0.0.1, server: localhost,
            request: "GET /foo.css.pagespeed.ce.0.css HTTP/1.1",
            host: "localhost:8050"
[debug] http finalize request: 408 (REQUEST_TIME_OUT), "/foo.css.pagespeed.ce.0.css?" a:1, c:1
[debug] http terminate request count:1
[debug] NgxBaseFetch::DecrefAndDeleteIfUnreferenced -- actually delete
[debug] http terminate cleanup count:1 blk:0
[debug] http posted request: "/foo.css.pagespeed.ce.0.css?"
request for /foo is processed and response is sent out smoothly
@jeffkaufman

This comment has been minimized.

Copy link
Contributor

jeffkaufman commented Nov 8, 2013

Normal request flow, without If-Modified-Since header:

$ curl -vv 'http://localhost:8050/foo.css.pagespeed.ce.0.css' http://localhost:8050/foo
* About to connect() to localhost port 8050 (#0)
*   Trying 127.0.0.1... connected
> GET /foo.css.pagespeed.ce.0.css HTTP/1.1
> User-Agent: curl/7.22.0 (x86_64-pc-linux-gnu) libcurl/7.22.0 OpenSSL/1.0.1 zlib/1.2.3.4 libidn/1.23 librtmp/2.3
> Host: localhost:8050
> Accept: */*
> 
< HTTP/1.1 404 Not Found
< Server: nginx/1.4.1
< Date: Fri, 08 Nov 2013 14:41:16 GMT
< Transfer-Encoding: chunked
< Connection: keep-alive
< X-Page-Speed: 1.7.30.1-3609
< 
* Connection #0 to host localhost left intact
* Re-using existing connection! (#0) with host localhost
* Connected to localhost (127.0.0.1) port 8050 (#0)
> GET /foo HTTP/1.1
> User-Agent: curl/7.22.0 (x86_64-pc-linux-gnu) libcurl/7.22.0 OpenSSL/1.0.1 zlib/1.2.3.4 libidn/1.23 librtmp/2.3
> Host: localhost:8050
> Accept: */*
> 
< HTTP/1.1 404 Not Found
< Server: nginx/1.4.1
< Date: Fri, 08 Nov 2013 14:41:16 GMT
< Content-Type: text/html
< Content-Length: 168
< Connection: keep-alive
< Vary: Accept-Encoding
< 
<html>
<head><title>404 Not Found</title></head>
<body bgcolor="white">
<center><h1>404 Not Found</h1></center>
<hr><center>nginx/1.4.1</center>
</body>
</html>

No pauses, as expected.

@jeffkaufman

This comment has been minimized.

Copy link
Contributor

jeffkaufman commented Nov 8, 2013

request comes in for /foo.css.pagespeed.ce.0.css
loopback request for http://localhost:8050/foo.css gets 404
404 headers sent out
[debug] CollectAccumulatedWrites, -2 (NGX_AGAIN)
[debug] http finalize request: -2 (NGX_AGAIN), "/foo.css.pagespeed.ce.0.css?" a:1, c:1
NgxBaseFetch::HandleDone(success=0)
NgxBaseFetch::DecrefAndDeleteIfUnreferenced -- not deleting
[debug] reusable connection: 0
[debug] ps fetch handler: /foo.css.pagespeed.ce.0.css
[debug] CollectAccumulatedWrites, 0 (NGX_OK)
[debug] http pagespeed write filter "/foo.css.pagespeed.ce.0.css"
[debug] http finalize request: 0 (NGX_OK_, "/foo.css.pagespeed.ce.0.css?" a:1, c:1
[debug] http close request
[debug] NgxBaseFetch::DecrefAndDeleteIfUnreferenced -- deleting
request comes in for /foo, 404 response goes out smoothly
@jeffkaufman

This comment has been minimized.

Copy link
Contributor

jeffkaufman commented Nov 8, 2013

In the If-Modified-Since case CollectAccumulatedWrites isn't being called, and ngx_http_finalize_request(r, NGX_DONE) is being called from ps_phase_handler.

@jeffkaufman

This comment has been minimized.

Copy link
Contributor

jeffkaufman commented Nov 8, 2013

More details on the If-Modified-Since case:

ps_async_wait_response is returning NGX_DONE which gets back to ngx_http_finalize_request via ps_resource_handler and then ps_phase_handler.

This is not ok, and there's a comment to this effect in ps_phase_handler:

  // Warning: this requires ps_content_handler to always return NGX_DECLINED     
  // directly if it's not going to handle the request. It is not ok for          
  // ps_content_handler to asynchronously determine whether to handle the        
  // request, returning NGX_DONE here.   

I don't know why I didn't make that into at least a DCHECK(rc != NGX_DONE) failure, but I'm pretty sure ps_content_handler needs to never return NGX_DONE.

@jeffkaufman

This comment has been minimized.

Copy link
Contributor

jeffkaufman commented Nov 8, 2013

@chaizhenhua @oschaaf I'm not sure I understand what ps_async_wait_response is doing. What is it for, and why is it returning NGX_DONE?

@jeffkaufman

This comment has been minimized.

Copy link
Contributor

jeffkaufman commented Nov 8, 2013

Above I compared this to a 404, but maybe a 200 is a better comparison. When fetching http://localhost:8050/mod_pagespeed_example/styles/blue.css.pagespeed.ce.0.css I see"

request comes in for /mod_pagespeed_example/styles/blue.css.pagespeed.ce.0.css
ps_async_wait_response returns NGX_DONE
NGX_DONE bubbles up through ps_resource_handler, ps_content_handler and ps_phase_handler
ps_phase_handler calls ngx_http_finalize_request(NGX_DONE)
[debug] http finalize request: -4, "/mod_pagespeed_example/styles/blue.css.pagespeed.ce.0.css?" a:1, c:2
[debug] http request count:2 blk:0
loopback request comes in for /mod_pagespeed_example/styles/blue.css
respond to blue.css request properly
[debug] Resource http://localhost:8050/mod_pagespeed_example/styles/blue.css.pagespeed.ce.0.css : 200
[debug] ps fetch handler: /mod_pagespeed_example/styles/blue.css.pagespeed.ce.0.css
[debug] NgxBaseFetch::HandleDone(success=1)
sends out headers for blue.css.pagespeed.ce.0.css
[debug] DecrefAndDeleteIfUnreferenced -- doesn't delete
[debug] CollectAccumulatedWrites, 0 (NGX_OK)
[debug] http pagespeed write filter "/mod_pagespeed_example/styles/blue.css.pagespeed.ce.0.css"
[debug] http finalize request: 0 (NGX_OK), "/mod_pagespeed_example/styles/blue.css.pagespeed.ce.0.css?" a:1, c:1
[debug] NgxBaseFetch::DecrefAndDeleteIfUnreferenced deletes

@jeffkaufman jeffkaufman closed this Nov 8, 2013

@jeffkaufman jeffkaufman reopened this Nov 8, 2013

@jeffkaufman

This comment has been minimized.

Copy link
Contributor

jeffkaufman commented Nov 8, 2013

It looks like my sternly worded comment in ps_phase_handler is no longer valid: returning NGX_DONE is ok. In fact, ipro couldn't work without this. I think this NGX_DONE isn't the real problem, or in fact any problem at all.

I think the real problem is that we need CollectAccumulatedWrites() to get called at least once, and for requests with no body that doesn't happen.

@jeffkaufman

This comment has been minimized.

Copy link
Contributor

jeffkaufman commented Nov 8, 2013

Guess: HandleDone should call RequestCollection.

@oschaaf

This comment has been minimized.

Copy link
Member

oschaaf commented Nov 8, 2013

@jeffkaufman
"Guess: HandleDone should call RequestCollection."

That sounds like something that should work to me (when success=true in HandleDone), It seems to be only needed when no actual response bytes are written from the BaseFetch - eg. for responses without an entity body like 304)

@jeffkaufman

This comment has been minimized.

Copy link
Contributor

jeffkaufman commented Nov 8, 2013

Calling RequestCollection from HandleDone doesn't fix it, sadly.

I think the problem might be in how we handle the pipe closing. RequestCollection writes to the pipe, but HandleDone closes it. Then when we watch the pipe in the nginx thread we see the pipe is closed and think everything is done.

@jeffkaufman

This comment has been minimized.

Copy link
Contributor

jeffkaufman commented Nov 8, 2013

Actually, I think the problem isn't with RequestCollection but with our handling of r->header_only

@jeffkaufman

This comment has been minimized.

Copy link
Contributor

jeffkaufman commented Nov 8, 2013

Here's a hack that fixes this:

--- a/src/ngx_pagespeed.cc
+++ b/src/ngx_pagespeed.cc
@@ -1109,10 +1109,6 @@ ngx_int_t ps_base_fetch_handler(ngx_http_request_t* r) {

     ctx->write_pending = (rc == NGX_AGAIN);

-    if (r->header_only) {
-      ctx->fetch_done = true;
-      return rc;
-    }
     ps_set_buffered(r, true);
   }
@jeffkaufman

This comment has been minimized.

Copy link
Contributor

jeffkaufman commented Nov 8, 2013

Thinking more, removing the header_only special casing isn't a hack. We have general code that we want to run all the time, and simply doing ctx->fetch_done = true; return rc doesn't run that code. So let's stop special-casing here. Created #557 to do this.

@jeffkaufman

This comment has been minimized.

Copy link
Contributor

jeffkaufman commented Nov 8, 2013

Fixed by #557

@jeffkaufman jeffkaufman closed this Nov 8, 2013

@jmaessen jmaessen changed the title For new (200) requests pagespeed serving optimized resources but for subsequent (304) requests client timed out error occurs Client times out on (304) requests Apr 23, 2014

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment