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

HEAD requests receive a response which includes an entity body in the html rewriting path #1375

Closed
Zewy opened this Issue Feb 3, 2017 · 21 comments

Comments

Projects
None yet
2 participants
@Zewy
Copy link

Zewy commented Feb 3, 2017

When I run curl -sv1IH 'accept-encoding: gzip, deflate, lzma, sdch, br' http://127.0.0.1/

* About to connect() to 127.0.0.1 port 80 (#0)
*   Trying 127.0.0.1...
* Connected to 127.0.0.1 (127.0.0.1) port 80 (#0)
> HEAD / HTTP/1.1
> User-Agent: curl/7.29.0
> Host: 127.0.0.1
> Accept: */*
> accept-encoding: gzip, deflate, lzma, sdch, br
>
< HTTP/1.1 200 OK
HTTP/1.1 200 OK
< Server: nginx/1.11.9
Server: nginx/1.11.9
< Content-Type: text/html
Content-Type: text/html
< Connection: keep-alive
Connection: keep-alive
< Vary: Accept-Encoding
Vary: Accept-Encoding
< Date: Fri, 03 Feb 2017 13:05:36 GMT
Date: Fri, 03 Feb 2017 13:05:36 GMT
< X-Page-Speed: 1.11.33.4-0
X-Page-Speed: 1.11.33.4-0
< Cache-Control: max-age=0, no-cache
Cache-Control: max-age=0, no-cache
< Content-Encoding: gzip
Content-Encoding: gzip

<
* Excess found in a non pipelined read: excess = 4090 url = / (zero-length body)
* Connection #0 to host 127.0.0.1 left intact

If I turn off pagespeed I don't get any Excess found in a non pipelined read: excess = 4090 url = / (zero-length body) I got the same problem with 1.12.34.2

@oschaaf

This comment has been minimized.

Copy link
Member

oschaaf commented Feb 3, 2017

Does the problem go away when you configure the following?:

pagespeed HttpCacheCompressionLevel 0;
@Zewy

This comment has been minimized.

Copy link

Zewy commented Feb 3, 2017

Did just try it same problem.

@oschaaf

This comment has been minimized.

Copy link
Member

oschaaf commented Feb 3, 2017

Thanks for checking, I didn't really expect that to fix it as you are querying the index which probably serves html (which should not be affected by the setting), but it was worth checking because there have been earlier reports of trouble with that setting. A couple of questions:

  • What does the output of nginx -V look like
  • What does the configuration look like
  • Would it be possible to provide a log trace of the request with nginx configured --with-debug and the log level set tot debug?
@Zewy

This comment has been minimized.

Copy link

Zewy commented Feb 3, 2017

Can you point me to how I do that with debug?

I did my install from this script on centos 7

https://gist.github.com/Zewy/a7dea63d72b6c9abaa1d0e3be08ac8ee

nginx version: nginx/1.11.9
built by gcc 4.8.5 20150623 (Red Hat 4.8.5-11) (GCC)
built with OpenSSL 1.1.0d  26 Jan 2017
TLS SNI support enabled
configure arguments: --prefix=/usr/local/nginx --sbin-path=/usr/sbin/nginx --conf-path=/etc/nginx/nginx.conf --pid-path=/var/run/nginx.pid --error-log-path=/var/log/nginx/error.log --http-log-path=/var/log/nginx/access.log --user=nginx --group=nginx --lock-path=/var/run/nginx.lock --modules-path=/usr/lib64/nginx/modules --http-client-body-temp-path=/var/cache/nginx/client_temp --http-proxy-temp-path=/var/cache/nginx/proxy_temp --http-fastcgi-temp-path=/var/cache/nginx/fastcgi_temp --http-uwsgi-temp-path=/var/cache/nginx/uwsgi_temp --http-scgi-temp-path=/var/cache/nginx/scgi_temp --with-compat --with-file-aio --with-threads --with-http_addition_module --with-http_auth_request_module --with-http_dav_module --with-http_flv_module --with-http_gunzip_module --with-http_gzip_static_module --with-http_mp4_module --with-http_random_index_module --with-http_realip_module --with-http_secure_link_module --with-http_slice_module --with-http_ssl_module --with-http_stub_status_module --with-http_sub_module --with-http_v2_module --with-mail --with-mail_ssl_module --with-openssl=/usr/local/src/openssl-1.1.0d --with-pcre=/usr/local/src/pcre-8.39 --with-pcre-jit --with-stream --with-stream_realip_module --with-stream_ssl_module --with-stream_ssl_preread_module --with-zlib=/usr/local/src/zlib-1.2.11 --with-cc-opt='-O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector-strong --param=ssp-buffer-size=4 -grecord-gcc-switches -m64 -mtune=generic' --add-module=/usr/local/src/ngx_pagespeed-1.11.33.4-beta

worker_processes  2;
pid /var/run/nginx.pid;

events {
    worker_connections  1024;
}
http {
    include       mime.types;
    default_type  application/octet-stream;

    sendfile        on;
    #tcp_nopush     on;

    keepalive_timeout  65;
    pagespeed off;
    pagespeed FileCachePath /var/ngx_pagespeed_cache;
    
    ## gzip
    #chunked_transfer_encoding off;
    gzip on;
    gzip_disable "msie6";

    gzip_vary on;
    gzip_proxied any;
    gzip_comp_level 6;
    gzip_buffers 16 8k;
    gzip_types text/plain text/css application/json application/x-javascript text/xml application/xml application/xml+rss text/javascript application/vnd.ms-fontobject application/x-font-ttf font/opentype image/svg+xml image/x-icon;

    
    include /etc/nginx/conf.d/*.conf;
}
server {
    listen       80;
    server_name  localhost;

  	pagespeed on;
    pagespeed RewriteLevel PassThrough;
  	pagespeed FileCachePath /var/ngx_pagespeed_cache;
    pagespeed HttpCacheCompressionLevel 0;

  	location ~ "\.pagespeed\.([a-z]\.)?[a-z]{2}\.[^.]{10}\.[^.]+" { add_header "" ""; }
  	location ~ "^/ngx_pagespeed_static/" { }
  	location ~ "^/ngx_pagespeed_beacon" { }

    location / {
        root   /usr/local/nginx/html;
        index  index.html index.htm;
    }
    error_page   500 502 503 504  /50x.html;
    location = /50x.html {
        root   /usr/local/nginx/html;
    }
}
@oschaaf

This comment has been minimized.

Copy link
Member

oschaaf commented Feb 3, 2017

For nginx debug logging, see http://nginx.org/en/docs/debugging_log.html

@Zewy

This comment has been minimized.

Copy link

Zewy commented Feb 3, 2017

tail /var/log/nginx/debug.log


2017/02/03 14:56:59 [debug] 3071#3071: epoll: fd:6 ev:0001 d:0000000003022C90
2017/02/03 14:56:59 [debug] 3071#3071: accept on 0.0.0.0:80, ready: 0
2017/02/03 14:56:59 [debug] 3071#3071: posix_memalign: 0000000003196330:512 @16
2017/02/03 14:56:59 [debug] 3071#3071: *1 accept: 127.0.0.1:60454 fd:17
2017/02/03 14:56:59 [debug] 3071#3071: *1 event timer add: 17: 60000:1486130279382
2017/02/03 14:56:59 [debug] 3071#3071: *1 reusable connection: 1
2017/02/03 14:56:59 [debug] 3071#3071: *1 epoll add event: fd:17 op:1 ev:80002001
2017/02/03 14:56:59 [debug] 3071#3071: timer delta: 13919
2017/02/03 14:56:59 [debug] 3071#3071: worker cycle
2017/02/03 14:56:59 [debug] 3071#3071: epoll timer: 60000
2017/02/03 14:56:59 [debug] 3071#3071: epoll: fd:17 ev:0001 d:0000000003023050
2017/02/03 14:56:59 [debug] 3071#3071: *1 http wait request handler
2017/02/03 14:56:59 [debug] 3071#3071: *1 malloc: 0000000003196540:1024
2017/02/03 14:56:59 [debug] 3071#3071: *1 recv: eof:0, avail:1
2017/02/03 14:56:59 [debug] 3071#3071: *1 recv: fd:17 122 of 1024
2017/02/03 14:56:59 [debug] 3071#3071: *1 reusable connection: 0
2017/02/03 14:56:59 [debug] 3071#3071: *1 posix_memalign: 00000000031976A0:4096 @16
2017/02/03 14:56:59 [debug] 3071#3071: *1 http process request line
2017/02/03 14:56:59 [debug] 3071#3071: *1 http request line: "HEAD / HTTP/1.1"
2017/02/03 14:56:59 [debug] 3071#3071: *1 http uri: "/"
2017/02/03 14:56:59 [debug] 3071#3071: *1 http args: ""
2017/02/03 14:56:59 [debug] 3071#3071: *1 http exten: ""
2017/02/03 14:56:59 [debug] 3071#3071: *1 posix_memalign: 00000000031986B0:4096 @16
2017/02/03 14:56:59 [debug] 3071#3071: *1 http process request header line
2017/02/03 14:56:59 [debug] 3071#3071: *1 http header: "User-Agent: curl/7.29.0"
2017/02/03 14:56:59 [debug] 3071#3071: *1 http header: "Host: 127.0.0.1"
2017/02/03 14:56:59 [debug] 3071#3071: *1 http header: "Accept: */*"
2017/02/03 14:56:59 [debug] 3071#3071: *1 http header: "accept-encoding: gzip, deflate, lzma, sdch, br"
2017/02/03 14:56:59 [debug] 3071#3071: *1 http header done
2017/02/03 14:56:59 [debug] 3071#3071: *1 event timer del: 17: 1486130279382
2017/02/03 14:56:59 [debug] 3071#3071: *1 generic phase: 0
2017/02/03 14:56:59 [debug] 3071#3071: *1 rewrite phase: 1
2017/02/03 14:56:59 [debug] 3071#3071: *1 test location: "/"
2017/02/03 14:56:59 [debug] 3071#3071: *1 test location: ~ "\.pagespeed\.([a-z]\.)?[a-z]{2}\.[^.]{10}\.[^.]+"
2017/02/03 14:56:59 [debug] 3071#3071: *1 test location: ~ "^/ngx_pagespeed_static/"
2017/02/03 14:56:59 [debug] 3071#3071: *1 test location: ~ "^/ngx_pagespeed_beacon"
2017/02/03 14:56:59 [debug] 3071#3071: *1 using configuration "/"
2017/02/03 14:56:59 [debug] 3071#3071: *1 http cl:-1 max:1048576
2017/02/03 14:56:59 [debug] 3071#3071: *1 rewrite phase: 3
2017/02/03 14:56:59 [debug] 3071#3071: *1 post rewrite phase: 4
2017/02/03 14:56:59 [debug] 3071#3071: *1 generic phase: 5
2017/02/03 14:56:59 [debug] 3071#3071: *1 generic phase: 5
2017/02/03 14:56:59 [debug] 3071#3071: *1 generic phase: 6
2017/02/03 14:56:59 [debug] 3071#3071: *1 generic phase: 7
2017/02/03 14:56:59 [debug] 3071#3071: *1 access phase: 8
2017/02/03 14:56:59 [debug] 3071#3071: *1 access phase: 9
2017/02/03 14:56:59 [debug] 3071#3071: *1 access phase: 10
2017/02/03 14:56:59 [debug] 3071#3071: *1 post access phase: 11
2017/02/03 14:56:59 [debug] 3071#3071: *1 pagespeed phase: 12
2017/02/03 14:56:59 [debug] 3071#3071: *1 http pagespeed handler "/"
2017/02/03 14:56:59 [debug] 3071#3071: *1 http cleanup add: 0000000003198488
2017/02/03 14:56:59 [info] 3071#3071: [ngx_pagespeed 1.11.33.4-0] Trying to serve rewritten resource in-place: http://127.0.0.1/
2017/02/03 14:56:59 [debug] 3071#3071: *1 http finalize request: -4, "/?" a:1, c:2
2017/02/03 14:56:59 [debug] 3071#3071: *1 http request count:2 blk:0
2017/02/03 14:56:59 [debug] 3071#3071: timer delta: 0
2017/02/03 14:56:59 [debug] 3071#3071: worker cycle
2017/02/03 14:56:59 [debug] 3071#3071: epoll timer: -1
2017/02/03 14:56:59 [info] 3071#3076: [ngx_pagespeed 1.11.33.4-0] Cache entry is expired: http://127.0.0.1/ (fragment=127.0.0.1)
2017/02/03 14:56:59 [debug] 3071#3076: [ngx_pagespeed 1.11.33.4-0] [0203/145659:VERBOSE1:cache_url_async_fetcher.cc(353)] Did not find in cache: http://127.0.0.1/ (127.0.0.1)
2017/02/03 14:56:59 [debug] 3071#3071: epoll: fd:12 ev:0001 d:0000000003022E70
2017/02/03 14:56:59 [debug] 3071#3071: pagespeed [00000000031976F0] event: H. bf:0000000003199B58 (ipro lookup) - refcnt:1 - det: N
2017/02/03 14:56:59 [debug] 3071#3071: *1 ps fetch handler: /
2017/02/03 14:56:59 [debug] 3071#3071: *1 ps in place check header filter initial: /
2017/02/03 14:56:59 [info] 3071#3071: [ngx_pagespeed 1.11.33.4-0] Could not rewrite resource in-place because URL is not in cache: http://127.0.0.1/
2017/02/03 14:56:59 [debug] 3071#3071: *1 try files phase: 13
2017/02/03 14:56:59 [debug] 3071#3071: *1 content phase: 14
2017/02/03 14:56:59 [debug] 3071#3071: *1 content phase: 15
2017/02/03 14:56:59 [debug] 3071#3071: *1 open index "/usr/local/nginx/html/index.html"
2017/02/03 14:56:59 [debug] 3071#3071: *1 internal redirect: "/index.html?"
2017/02/03 14:56:59 [debug] 3071#3071: *1 rewrite phase: 1
2017/02/03 14:56:59 [debug] 3071#3071: *1 test location: "/"
2017/02/03 14:56:59 [debug] 3071#3071: *1 test location: "50x.html"
2017/02/03 14:56:59 [debug] 3071#3071: *1 test location: ~ "\.pagespeed\.([a-z]\.)?[a-z]{2}\.[^.]{10}\.[^.]+"
2017/02/03 14:56:59 [debug] 3071#3071: *1 test location: ~ "^/ngx_pagespeed_static/"
2017/02/03 14:56:59 [debug] 3071#3071: *1 test location: ~ "^/ngx_pagespeed_beacon"
2017/02/03 14:56:59 [debug] 3071#3071: *1 using configuration "/"
2017/02/03 14:56:59 [debug] 3071#3071: *1 http cl:-1 max:1048576
2017/02/03 14:56:59 [debug] 3071#3071: *1 rewrite phase: 3
2017/02/03 14:56:59 [debug] 3071#3071: *1 post rewrite phase: 4
2017/02/03 14:56:59 [debug] 3071#3071: *1 generic phase: 5
2017/02/03 14:56:59 [debug] 3071#3071: *1 generic phase: 6
2017/02/03 14:56:59 [debug] 3071#3071: *1 generic phase: 7
2017/02/03 14:56:59 [debug] 3071#3071: *1 access phase: 8
2017/02/03 14:56:59 [debug] 3071#3071: *1 access phase: 9
2017/02/03 14:56:59 [debug] 3071#3071: *1 access phase: 10
2017/02/03 14:56:59 [debug] 3071#3071: *1 post access phase: 11
2017/02/03 14:56:59 [debug] 3071#3071: *1 pagespeed phase: 12
2017/02/03 14:56:59 [debug] 3071#3071: *1 http pagespeed handler "/index.html"
2017/02/03 14:56:59 [debug] 3071#3071: *1 http cleanup add: 00000000031984C8
2017/02/03 14:56:59 [info] 3071#3071: [ngx_pagespeed 1.11.33.4-0] Trying to serve rewritten resource in-place: http://127.0.0.1/
2017/02/03 14:56:59 [debug] 3071#3071: *1 http finalize request: -4, "/index.html?" a:1, c:4
2017/02/03 14:56:59 [debug] 3071#3071: *1 http request count:4 blk:0
2017/02/03 14:56:59 [debug] 3071#3071: *1 http finalize request: -4, "/index.html?" a:1, c:3
2017/02/03 14:56:59 [debug] 3071#3071: *1 http request count:3 blk:0
2017/02/03 14:56:59 [debug] 3071#3071: pagespeed [00000000031976F0] ps_base_fetch_handler() returned -4 for H
2017/02/03 14:56:59 [debug] 3071#3071: *1 http finalize request: -4, "/index.html?" a:1, c:2
2017/02/03 14:56:59 [debug] 3071#3071: *1 http request count:2 blk:0
2017/02/03 14:56:59 [debug] 3071#3071: timer delta: 3
2017/02/03 14:56:59 [debug] 3071#3071: worker cycle
2017/02/03 14:56:59 [debug] 3071#3071: epoll timer: -1
2017/02/03 14:56:59 [info] 3071#3076: [ngx_pagespeed 1.11.33.4-0] Cache entry is expired: http://127.0.0.1/ (fragment=127.0.0.1)
2017/02/03 14:56:59 [debug] 3071#3076: [ngx_pagespeed 1.11.33.4-0] [0203/145659:VERBOSE1:cache_url_async_fetcher.cc(353)] Did not find in cache: http://127.0.0.1/ (127.0.0.1)
2017/02/03 14:56:59 [debug] 3071#3071: epoll: fd:12 ev:0001 d:0000000003022E70
2017/02/03 14:56:59 [debug] 3071#3071: pagespeed [00000000031976F0] event: H. bf:0000000003199B58 (ipro lookup) - refcnt:1 - det: N
2017/02/03 14:56:59 [debug] 3071#3071: *1 ps fetch handler: /index.html
2017/02/03 14:56:59 [debug] 3071#3071: *1 ps in place check header filter initial: /index.html
2017/02/03 14:56:59 [info] 3071#3071: [ngx_pagespeed 1.11.33.4-0] Could not rewrite resource in-place because URL is not in cache: http://127.0.0.1/
2017/02/03 14:56:59 [debug] 3071#3071: *1 try files phase: 13
2017/02/03 14:56:59 [debug] 3071#3071: *1 content phase: 14
2017/02/03 14:56:59 [debug] 3071#3071: *1 content phase: 15
2017/02/03 14:56:59 [debug] 3071#3071: *1 content phase: 16
2017/02/03 14:56:59 [debug] 3071#3071: *1 content phase: 17
2017/02/03 14:56:59 [debug] 3071#3071: *1 content phase: 18
2017/02/03 14:56:59 [debug] 3071#3071: *1 content phase: 19
2017/02/03 14:56:59 [debug] 3071#3071: *1 http filename: "/usr/local/nginx/html/index.html"
2017/02/03 14:56:59 [debug] 3071#3071: *1 add cleanup: 0000000003198508
2017/02/03 14:56:59 [debug] 3071#3071: *1 http static fd: 18
2017/02/03 14:56:59 [debug] 3071#3071: *1 http set discard body
2017/02/03 14:56:59 [debug] 3071#3071: *1 http pagespeed html rewrite header filter "/index.html"
2017/02/03 14:56:59 [debug] 3071#3071: [ngx_pagespeed 1.11.33.4-0] [0203/145659:VERBOSE1:proxy_fetch.cc(544)] Attaching RewriteDriver 0x319bf38 to HtmlRewriter 0x31a2ad8
2017/02/03 14:56:59 [debug] 3071#3071: *1 http output filter "/index.html?"
2017/02/03 14:56:59 [debug] 3071#3071: *1 http copy filter: "/index.html?"
2017/02/03 14:56:59 [debug] 3071#3071: *1 malloc: 00000000031A2D50:4090
2017/02/03 14:56:59 [debug] 3071#3071: *1 read: 18, 00000000031A2D50, 4090, 0
2017/02/03 14:56:59 [debug] 3071#3071: *1 http postpone filter "/index.html?" 0000000003198B88
2017/02/03 14:56:59 [debug] 3071#3071: *1 http pagespeed html rewrite body filter "/index.html"
2017/02/03 14:56:59 [debug] 3071#3071: [ngx_pagespeed 1.11.33.4-0] [0203/145659:VERBOSE1:proxy_fetch.cc(589)] Parse successfully started.
2017/02/03 14:56:59 [debug] 3071#3071: [ngx_pagespeed 1.11.33.4-0] [0203/145659:VERBOSE1:proxy_fetch.cc(1006)] Fetch result:1 http://127.0.0.1/ : 200
2017/02/03 14:56:59 [debug] 3071#3071: *1 http pagespeed write filter "/index.html"
2017/02/03 14:56:59 [debug] 3071#3071: *1 http copy filter: -2 "/index.html?"
2017/02/03 14:56:59 [debug] 3071#3071: *1 http finalize request: -2, "/index.html?" a:1, c:2
2017/02/03 14:56:59 [debug] 3071#3071: *1 event timer add: 17: 60000:1486130279385
2017/02/03 14:56:59 [debug] 3071#3071: pagespeed [00000000031976F0] ps_base_fetch_handler() returned -4 for H
2017/02/03 14:56:59 [debug] 3071#3071: *1 http finalize request: -4, "/index.html?" a:1, c:2
2017/02/03 14:56:59 [debug] 3071#3071: *1 http request count:2 blk:0
2017/02/03 14:56:59 [debug] 3071#3071: timer delta: 0
2017/02/03 14:56:59 [debug] 3071#3071: worker cycle
2017/02/03 14:56:59 [debug] 3071#3071: epoll timer: 60000
2017/02/03 14:56:59 [debug] 3071#3071: epoll: fd:12 ev:0001 d:0000000003022E70
2017/02/03 14:56:59 [debug] 3071#3071: pagespeed [00000000031976F0] event: H. bf:0000000003197358 (html transform) - refcnt:3 - det: N
2017/02/03 14:56:59 [debug] 3071#3071: *1 ps fetch handler: /index.html
2017/02/03 14:56:59 [debug] 3071#3071: *1 ps in place check header filter recording: /index.html
2017/02/03 14:56:59 [debug] 3071#3071: *1 HTTP/1.1 200 OK
Server: nginx/1.11.9
Content-Type: text/html
Connection: keep-alive
Vary: Accept-Encoding
Date: Fri, 03 Feb 2017 13:56:59 GMT
X-Page-Speed: 1.11.33.4-0
Cache-Control: max-age=0, no-cache
Content-Encoding: gzip

2017/02/03 14:56:59 [debug] 3071#3071: *1 write new buf t:1 f:0 0000000003198DE8, pos 0000000003198DE8, size: 237 file: 0, size: 0
2017/02/03 14:56:59 [debug] 3071#3071: *1 http write filter: l:1 f:0 s:237
2017/02/03 14:56:59 [debug] 3071#3071: *1 http write filter limit 0
2017/02/03 14:56:59 [debug] 3071#3071: *1 writev: 237 of 237
2017/02/03 14:56:59 [debug] 3071#3071: *1 http write filter 0000000000000000
2017/02/03 14:56:59 [debug] 3071#3071: *1 malloc: 00000000031A4120:4090
2017/02/03 14:56:59 [debug] 3071#3071: *1 CollectAccumulatedWrites, 0
2017/02/03 14:56:59 [debug] 3071#3071: *1 ps in place body filter: /index.html
2017/02/03 14:56:59 [debug] 3071#3071: *1 write new buf t:1 f:0 00000000031A4120, pos 00000000031A4120, size: 4090 file: 0, size: 0
2017/02/03 14:56:59 [debug] 3071#3071: *1 http write filter: l:1 f:0 s:4090
2017/02/03 14:56:59 [debug] 3071#3071: *1 http write filter limit 0
2017/02/03 14:56:59 [debug] 3071#3071: *1 writev: 4090 of 4090
2017/02/03 14:56:59 [debug] 3071#3071: *1 http write filter 0000000000000000
2017/02/03 14:56:59 [debug] 3071#3071: pagespeed [00000000031976F0] ps_base_fetch_handler() returned 0 for H
2017/02/03 14:56:59 [debug] 3071#3071: *1 http finalize request: 0, "/index.html?" a:1, c:1
2017/02/03 14:56:59 [debug] 3071#3071: *1 event timer del: 17: 1486130279385
2017/02/03 14:56:59 [debug] 3071#3071: *1 set http keepalive handler
2017/02/03 14:56:59 [debug] 3071#3071: *1 http close request
2017/02/03 14:56:59 [debug] 3071#3071: *1 http log handler
2017/02/03 14:56:59 [debug] 3071#3071: *1 run cleanup: 0000000003198508
2017/02/03 14:56:59 [debug] 3071#3071: *1 file cleanup: fd:18
2017/02/03 14:56:59 [debug] 3071#3071: *1 free: 00000000031A4120
2017/02/03 14:56:59 [debug] 3071#3071: *1 free: 00000000031A2D50
2017/02/03 14:56:59 [debug] 3071#3071: *1 free: 00000000031976A0, unused: 0
2017/02/03 14:56:59 [debug] 3071#3071: *1 free: 00000000031986B0, unused: 1759
2017/02/03 14:56:59 [debug] 3071#3071: *1 free: 0000000003196540
2017/02/03 14:56:59 [debug] 3071#3071: *1 hc free: 0000000000000000 0
2017/02/03 14:56:59 [debug] 3071#3071: *1 hc busy: 0000000000000000 0
2017/02/03 14:56:59 [debug] 3071#3071: *1 tcp_nodelay
2017/02/03 14:56:59 [debug] 3071#3071: *1 reusable connection: 1
2017/02/03 14:56:59 [debug] 3071#3071: *1 event timer add: 17: 65000:1486130284387
2017/02/03 14:56:59 [debug] 3071#3071: timer delta: 2
2017/02/03 14:56:59 [debug] 3071#3071: worker cycle
2017/02/03 14:56:59 [debug] 3071#3071: epoll timer: 65000
2017/02/03 14:56:59 [debug] 3071#3071: epoll: fd:12 ev:0001 d:0000000003022E70
2017/02/03 14:56:59 [debug] 3071#3071: pagespeed [00000000031976F0] event: F. bf:0000000003197358 (html transform) - refcnt:1 - det: Y
2017/02/03 14:56:59 [debug] 3071#3071: timer delta: 0
2017/02/03 14:56:59 [debug] 3071#3071: worker cycle
2017/02/03 14:56:59 [debug] 3071#3071: epoll timer: 65000
2017/02/03 14:56:59 [debug] 3071#3071: epoll: fd:12 ev:0001 d:0000000003022E70
2017/02/03 14:56:59 [debug] 3071#3071: pagespeed [00000000031976F0] event: D. bf:0000000003197358 (html transform) - refcnt:0 - det: Y
2017/02/03 14:56:59 [debug] 3071#3071: timer delta: 0
2017/02/03 14:56:59 [debug] 3071#3071: worker cycle
2017/02/03 14:56:59 [debug] 3071#3071: epoll timer: 65000
2017/02/03 14:56:59 [debug] 3071#3071: epoll: fd:17 ev:2001 d:0000000003023050
2017/02/03 14:56:59 [debug] 3071#3071: *1 http keepalive handler
2017/02/03 14:56:59 [debug] 3071#3071: *1 malloc: 000000000319FC70:1024
2017/02/03 14:56:59 [debug] 3071#3071: *1 recv: eof:1, avail:1
2017/02/03 14:56:59 [debug] 3071#3071: *1 recv: fd:17 0 of 1024
2017/02/03 14:56:59 [info] 3071#3071: *1 client 127.0.0.1 closed keepalive connection
2017/02/03 14:56:59 [debug] 3071#3071: *1 close http connection: 17
2017/02/03 14:56:59 [debug] 3071#3071: *1 event timer del: 17: 1486130284387
2017/02/03 14:56:59 [debug] 3071#3071: *1 reusable connection: 0
2017/02/03 14:56:59 [debug] 3071#3071: *1 free: 000000000319FC70
2017/02/03 14:56:59 [debug] 3071#3071: *1 free: 0000000003196330, unused: 112
2017/02/03 14:56:59 [debug] 3071#3071: timer delta: 1
2017/02/03 14:56:59 [debug] 3071#3071: worker cycle
2017/02/03 14:56:59 [debug] 3071#3071: epoll timer: -1


@oschaaf

This comment has been minimized.

Copy link
Member

oschaaf commented Feb 3, 2017

@Zewy thanks a bunch, but could you post the full contents? (or perhaps better, email it to oschaaf@we-amp.com)

@Zewy

This comment has been minimized.

Copy link

Zewy commented Feb 3, 2017

with out pagespeed

2017/02/03 14:55:13 [debug] 3002#3002: epoll: fd:6 ev:0001 d:00000000028F9C90
2017/02/03 14:55:13 [debug] 3002#3002: accept on 0.0.0.0:80, ready: 0
2017/02/03 14:55:13 [debug] 3002#3002: posix_memalign: 0000000002A6D330:512 @16
2017/02/03 14:55:13 [debug] 3002#3002: *2 accept: 127.0.0.1:60452 fd:17
2017/02/03 14:55:13 [debug] 3002#3002: *2 event timer add: 17: 60000:1486130173798
2017/02/03 14:55:13 [debug] 3002#3002: *2 reusable connection: 1
2017/02/03 14:55:13 [debug] 3002#3002: *2 epoll add event: fd:17 op:1 ev:80002001
2017/02/03 14:55:13 [debug] 3002#3002: timer delta: 149786
2017/02/03 14:55:13 [debug] 3002#3002: worker cycle
2017/02/03 14:55:13 [debug] 3002#3002: epoll timer: 60000
2017/02/03 14:55:13 [debug] 3002#3002: epoll: fd:17 ev:0001 d:00000000028FA051
2017/02/03 14:55:13 [debug] 3002#3002: *2 http wait request handler
2017/02/03 14:55:13 [debug] 3002#3002: *2 malloc: 0000000002A6D540:1024
2017/02/03 14:55:13 [debug] 3002#3002: *2 recv: eof:0, avail:1
2017/02/03 14:55:13 [debug] 3002#3002: *2 recv: fd:17 122 of 1024
2017/02/03 14:55:13 [debug] 3002#3002: *2 reusable connection: 0
2017/02/03 14:55:13 [debug] 3002#3002: *2 posix_memalign: 0000000002A6E6A0:4096 @16
2017/02/03 14:55:13 [debug] 3002#3002: *2 http process request line
2017/02/03 14:55:13 [debug] 3002#3002: *2 http request line: "HEAD / HTTP/1.1"
2017/02/03 14:55:13 [debug] 3002#3002: *2 http uri: "/"
2017/02/03 14:55:13 [debug] 3002#3002: *2 http args: ""
2017/02/03 14:55:13 [debug] 3002#3002: *2 http exten: ""
2017/02/03 14:55:13 [debug] 3002#3002: *2 posix_memalign: 0000000002A6F6B0:4096 @16
2017/02/03 14:55:13 [debug] 3002#3002: *2 http process request header line
2017/02/03 14:55:13 [debug] 3002#3002: *2 http header: "User-Agent: curl/7.29.0"
2017/02/03 14:55:13 [debug] 3002#3002: *2 http header: "Host: 127.0.0.1"
2017/02/03 14:55:13 [debug] 3002#3002: *2 http header: "Accept: */*"
2017/02/03 14:55:13 [debug] 3002#3002: *2 http header: "accept-encoding: gzip, deflate, lzma, sdch, br"
2017/02/03 14:55:13 [debug] 3002#3002: *2 http header done
2017/02/03 14:55:13 [debug] 3002#3002: *2 event timer del: 17: 1486130173798
2017/02/03 14:55:13 [debug] 3002#3002: *2 generic phase: 0
2017/02/03 14:55:13 [debug] 3002#3002: *2 rewrite phase: 1
2017/02/03 14:55:13 [debug] 3002#3002: *2 test location: "/"
2017/02/03 14:55:13 [debug] 3002#3002: *2 test location: ~ "\.pagespeed\.([a-z]\.)?[a-z]{2}\.[^.]{10}\.[^.]+"
2017/02/03 14:55:13 [debug] 3002#3002: *2 test location: ~ "^/ngx_pagespeed_static/"
2017/02/03 14:55:13 [debug] 3002#3002: *2 test location: ~ "^/ngx_pagespeed_beacon"
2017/02/03 14:55:13 [debug] 3002#3002: *2 using configuration "/"
2017/02/03 14:55:13 [debug] 3002#3002: *2 http cl:-1 max:1048576
2017/02/03 14:55:13 [debug] 3002#3002: *2 rewrite phase: 3
2017/02/03 14:55:13 [debug] 3002#3002: *2 post rewrite phase: 4
2017/02/03 14:55:13 [debug] 3002#3002: *2 generic phase: 5
2017/02/03 14:55:13 [debug] 3002#3002: *2 generic phase: 6
2017/02/03 14:55:13 [debug] 3002#3002: *2 generic phase: 7
2017/02/03 14:55:13 [debug] 3002#3002: *2 access phase: 8
2017/02/03 14:55:13 [debug] 3002#3002: *2 access phase: 9
2017/02/03 14:55:13 [debug] 3002#3002: *2 access phase: 10
2017/02/03 14:55:13 [debug] 3002#3002: *2 post access phase: 11
2017/02/03 14:55:13 [debug] 3002#3002: *2 pagespeed phase: 12
2017/02/03 14:55:13 [debug] 3002#3002: *2 http pagespeed handler "/"
2017/02/03 14:55:13 [debug] 3002#3002: *2 try files phase: 13
2017/02/03 14:55:13 [debug] 3002#3002: *2 content phase: 14
2017/02/03 14:55:13 [debug] 3002#3002: *2 content phase: 15
2017/02/03 14:55:13 [debug] 3002#3002: *2 open index "/usr/local/nginx/html/index.html"
2017/02/03 14:55:13 [debug] 3002#3002: *2 internal redirect: "/index.html?"
2017/02/03 14:55:13 [debug] 3002#3002: *2 rewrite phase: 1
2017/02/03 14:55:13 [debug] 3002#3002: *2 test location: "/"
2017/02/03 14:55:13 [debug] 3002#3002: *2 test location: "50x.html"
2017/02/03 14:55:13 [debug] 3002#3002: *2 test location: ~ "\.pagespeed\.([a-z]\.)?[a-z]{2}\.[^.]{10}\.[^.]+"
2017/02/03 14:55:13 [debug] 3002#3002: *2 test location: ~ "^/ngx_pagespeed_static/"
2017/02/03 14:55:13 [debug] 3002#3002: *2 test location: ~ "^/ngx_pagespeed_beacon"
2017/02/03 14:55:13 [debug] 3002#3002: *2 using configuration "/"
2017/02/03 14:55:13 [debug] 3002#3002: *2 http cl:-1 max:1048576
2017/02/03 14:55:13 [debug] 3002#3002: *2 rewrite phase: 3
2017/02/03 14:55:13 [debug] 3002#3002: *2 post rewrite phase: 4
2017/02/03 14:55:13 [debug] 3002#3002: *2 generic phase: 5
2017/02/03 14:55:13 [debug] 3002#3002: *2 generic phase: 6
2017/02/03 14:55:13 [debug] 3002#3002: *2 generic phase: 7
2017/02/03 14:55:13 [debug] 3002#3002: *2 access phase: 8
2017/02/03 14:55:13 [debug] 3002#3002: *2 access phase: 9
2017/02/03 14:55:13 [debug] 3002#3002: *2 access phase: 10
2017/02/03 14:55:13 [debug] 3002#3002: *2 post access phase: 11
2017/02/03 14:55:13 [debug] 3002#3002: *2 pagespeed phase: 12
2017/02/03 14:55:13 [debug] 3002#3002: *2 http pagespeed handler "/index.html"
2017/02/03 14:55:13 [debug] 3002#3002: *2 try files phase: 13
2017/02/03 14:55:13 [debug] 3002#3002: *2 content phase: 14
2017/02/03 14:55:13 [debug] 3002#3002: *2 content phase: 15
2017/02/03 14:55:13 [debug] 3002#3002: *2 content phase: 16
2017/02/03 14:55:13 [debug] 3002#3002: *2 content phase: 17
2017/02/03 14:55:13 [debug] 3002#3002: *2 content phase: 18
2017/02/03 14:55:13 [debug] 3002#3002: *2 content phase: 19
2017/02/03 14:55:13 [debug] 3002#3002: *2 http filename: "/usr/local/nginx/html/index.html"
2017/02/03 14:55:13 [debug] 3002#3002: *2 add cleanup: 0000000002A6F4C8
2017/02/03 14:55:13 [debug] 3002#3002: *2 http static fd: 18
2017/02/03 14:55:13 [debug] 3002#3002: *2 http set discard body
2017/02/03 14:55:13 [debug] 3002#3002: *2 HTTP/1.1 200 OK
Server: nginx/1.11.9
Date: Fri, 03 Feb 2017 13:55:13 GMT
Content-Type: text/html
Last-Modified: Mon, 30 Jan 2017 13:15:58 GMT
Connection: keep-alive
Vary: Accept-Encoding
ETag: W/"588f3c8e-ffa"
Content-Encoding: gzip

2017/02/03 14:55:13 [debug] 3002#3002: *2 write new buf t:1 f:0 0000000002A6FBE8, pos 0000000002A6FBE8, size: 244 file: 0, size: 0
2017/02/03 14:55:13 [debug] 3002#3002: *2 http write filter: l:1 f:0 s:244
2017/02/03 14:55:13 [debug] 3002#3002: *2 http write filter limit 0
2017/02/03 14:55:13 [debug] 3002#3002: *2 writev: 244 of 244
2017/02/03 14:55:13 [debug] 3002#3002: *2 http write filter 0000000000000000
2017/02/03 14:55:13 [debug] 3002#3002: *2 http finalize request: 0, "/index.html?" a:1, c:2
2017/02/03 14:55:13 [debug] 3002#3002: *2 http request count:2 blk:0
2017/02/03 14:55:13 [debug] 3002#3002: *2 http finalize request: -4, "/index.html?" a:1, c:1
2017/02/03 14:55:13 [debug] 3002#3002: *2 set http keepalive handler
2017/02/03 14:55:13 [debug] 3002#3002: *2 http close request
2017/02/03 14:55:13 [debug] 3002#3002: *2 http log handler
2017/02/03 14:55:13 [debug] 3002#3002: *2 run cleanup: 0000000002A6F4C8
2017/02/03 14:55:13 [debug] 3002#3002: *2 file cleanup: fd:18
2017/02/03 14:55:13 [debug] 3002#3002: *2 free: 0000000002A6E6A0, unused: 16
2017/02/03 14:55:13 [debug] 3002#3002: *2 free: 0000000002A6F6B0, unused: 2395
2017/02/03 14:55:13 [debug] 3002#3002: *2 free: 0000000002A6D540
2017/02/03 14:55:13 [debug] 3002#3002: *2 hc free: 0000000000000000 0
2017/02/03 14:55:13 [debug] 3002#3002: *2 hc busy: 0000000000000000 0
2017/02/03 14:55:13 [debug] 3002#3002: *2 tcp_nodelay
2017/02/03 14:55:13 [debug] 3002#3002: *2 reusable connection: 1
2017/02/03 14:55:13 [debug] 3002#3002: *2 event timer add: 17: 65000:1486130178798
2017/02/03 14:55:13 [debug] 3002#3002: timer delta: 0
2017/02/03 14:55:13 [debug] 3002#3002: worker cycle
2017/02/03 14:55:13 [debug] 3002#3002: epoll timer: 65000
2017/02/03 14:55:13 [debug] 3002#3002: epoll: fd:17 ev:2001 d:00000000028FA051
2017/02/03 14:55:13 [debug] 3002#3002: *2 http keepalive handler
2017/02/03 14:55:13 [debug] 3002#3002: *2 malloc: 0000000002A6D540:1024
2017/02/03 14:55:13 [debug] 3002#3002: *2 recv: eof:1, avail:1
2017/02/03 14:55:13 [debug] 3002#3002: *2 recv: fd:17 0 of 1024
2017/02/03 14:55:13 [info] 3002#3002: *2 client 127.0.0.1 closed keepalive connection
2017/02/03 14:55:13 [debug] 3002#3002: *2 close http connection: 17
2017/02/03 14:55:13 [debug] 3002#3002: *2 event timer del: 17: 1486130178798
2017/02/03 14:55:13 [debug] 3002#3002: *2 reusable connection: 0
2017/02/03 14:55:13 [debug] 3002#3002: *2 free: 0000000002A6D540
2017/02/03 14:55:13 [debug] 3002#3002: *2 free: 0000000002A6D330, unused: 128
2017/02/03 14:55:13 [debug] 3002#3002: timer delta: 0
2017/02/03 14:55:13 [debug] 3002#3002: worker cycle
2017/02/03 14:55:13 [debug] 3002#3002: epoll timer: -1
@oschaaf

This comment has been minimized.

Copy link
Member

oschaaf commented Feb 3, 2017

It's odd that a HEAD request responds with a body. It looks like nginx attempts to discard the response body in both cases, but it looks like that with ngx_pagespeed it fails to do so, which I suspect results in the excess data curl complains about.
I need to look into this some more, it isn't immediately obvious to me why that happens, and on master with the test configuration (and different ./configure flags) it won't reproduce on my machine.
I'll try to set things up to be more like your system setup and configuration.

@Zewy

This comment has been minimized.

Copy link

Zewy commented Feb 3, 2017

I did edit my /usr/local/nginx/html/index.html so it looks like this

<!DOCTYPE html>
<html>
<head>
<title>Welcome to nginx!</title>
<style>
    body {
        width: 35em;
        margin: 0 auto;
        font-family: Tahoma, Verdana, Arial, sans-serif;
    }
</style>
</head>
<body>
<h1>Welcome to nginx!</h1>
<p>If you see this page, the nginx web server is successfully installed and
working. Further configuration is required.</p>

<p>For online documentation and support please refer to
<a href="http://nginx.org/">nginx.org</a>.<br/>
Commercial support is available at
<a href="http://nginx.com/">nginx.com</a>.</p>

<p><em>Thank you for using nginx.</em></p>
<p>Lorem ipsum dolor sit amet, consectetuer adipiscing elit. Aenean commodo ligula eget dolor. Aenean massa. Cum sociis natoque penatibus et magnis dis parturient montes, nascetur ridiculus mus. Donec quam felis, ultricies nec, pellentesque eu, pretium quis, sem. Nulla consequat massa quis enim. Donec pede justo, fringilla vel, aliquet nec, vulputate eget, arcu. In enim justo, rhoncus ut, imperdiet a, venenatis vitae, justo. Nullam dictum felis eu pede mollis pretium. Integer tincidunt. Cras dapibus. Vivamus elementum semper nisi. Aenean vulputate eleifend tellus. Aenean leo ligula, porttitor eu, consequat vitae, eleifend ac, enim. Aliquam lorem ante, dapibus in, viverra quis, feugiat a, tellus. Phasellus viverra nulla ut metus varius laoreet. Quisque rutrum. Aenean imperdiet. Etiam ultricies nisi vel augue. Curabitur ullamcorper ultricies nisi. Nam eget dui. Etiam rhoncus. Maecenas tempus, tellus eget condimentum rhoncus, sem quam semper libero, sit amet adipiscing sem neque sed ipsum. Nam quam nunc, blandit vel, luctus pulvinar, hendrerit id, lorem. Maecenas nec odio et ante tincidunt tempus. Donec vitae sapien ut libero venenatis faucibus. Nullam quis ante. Etiam sit amet orci eget eros faucibus tincidunt. Duis leo. Sed fringilla mauris sit amet nibh. Donec sodales sagittis magna. Sed consequat, leo eget bibendum sodales, augue velit cursus nunc, quis gravida magna mi a libero. Fusce vulputate eleifend sapien. Vestibulum purus quam, scelerisque ut, mollis sed, nonummy id, metus. Nullam accumsan lorem in dui. Cras ultricies mi eu turpis hendrerit fringilla. Vestibulum ante ipsum primis in faucibus orci luctus et ultrices posuere cubilia Curae; In ac dui quis mi consectetuer lacinia. Nam pretium turpis et arcu. Duis arcu tortor, suscipit eget, imperdiet nec, imperdiet iaculis, ipsum. Sed aliquam ultrices mauris. Integer ante arcu, accumsan a, consectetuer eget, posuere ut, mauris. Praesent adipiscing. Phasellus ullamcorper ipsum rutrum nunc. Nunc nonummy metus. Vestibulum volutpat pretium libero. Cras id dui. Aenean ut eros et nisl sagittis vestibulum. Nullam nulla eros, ultricies sit amet, nonummy id, imperdiet feugiat, pede. Sed lectus. Donec mollis hendrerit risus. Phasellus nec sem in justo pellentesque facilisis. Etiam imperdiet imperdiet orci. Nunc nec neque. Phasellus leo dolor, tempus non, auctor et, hendrerit quis, nisi. Curabitur ligula sapien, tincidunt non, euismod vitae, posuere imperdiet, leo. Maecenas malesuada. Praesent congue erat at massa. Sed cursus turpis vitae tortor. Donec posuere vulputate arcu. Phasellus accumsan cursus velit. Vestibulum ante ipsum primis in faucibus orci luctus et ultrices posuere cubilia Curae; Sed aliquam, nisi quis porttitor congue, elit erat euismod orci, ac placerat dolor lectus quis orci. Phasellus consectetuer vestibulum elit. Aenean tellus metus, bibendum sed, posuere ac, mattis non, nunc. Vestibulum fringilla pede sit amet augue. In turpis. Pellentesque posuere. Praesent turpis. Aenean posuere, tortor sed cursus feugiat, nunc augue blandit nunc, eu sollicitudin urna dolor sagittis lacus. Donec elit libero, sodales nec, volutpat a, suscipit non, turpis. Nullam sagittis. Suspendisse pulvinar, augue ac venenatis condimentum, sem libero volutpat nibh, nec pellentesque velit pede quis nunc. Vestibulum ante ipsum primis in faucibus orci luctus et ultrices posuere cubilia Curae; Fusce id purus. Ut varius tincidunt libero. Phasellus dolor. Maecenas vestibulum mollis </p>
</body>
</html>
@Zewy

This comment has been minimized.

Copy link

Zewy commented Feb 3, 2017

How do it look when you run that curl string? in curl and debug? Do you have a guide how you setup your system?

@oschaaf

This comment has been minimized.

Copy link
Member

oschaaf commented Feb 3, 2017

Running the curl command looks like the following on my system:

oschaaf@ubuntu:~/code/google/nps-issue-1375-gzip/ngx_pagespeed/testing-dependencies/nginx⟫ curl -sv1IH 'accept-encoding: gzi
p, deflate, lzma, sdch, br' http://127.0.0.1:8050/mod_pagespeed_example/
* Hostname was NOT found in DNS cache
*   Trying 127.0.0.1...
* Connected to 127.0.0.1 (127.0.0.1) port 8050 (#0)
> HEAD /mod_pagespeed_example/ HTTP/1.1
> User-Agent: curl/7.35.0
> Host: 127.0.0.1:8050
> Accept: */*
> accept-encoding: gzip, deflate, lzma, sdch, br
> 
< HTTP/1.1 200 OK
HTTP/1.1 200 OK
* Server nginx/1.11.9 is not blacklisted
< Server: nginx/1.11.9
Server: nginx/1.11.9
< Content-Type: text/html
Content-Type: text/html
< Connection: keep-alive
Connection: keep-alive
< Vary: Accept-Encoding
Vary: Accept-Encoding
< X-Extra-Header: 1
X-Extra-Header: 1
< Date: Thu, 02 Feb 2017 02:09:56 GMT
Date: Thu, 02 Feb 2017 02:09:56 GMT
< X-Page-Speed: 1.13.0.0-8389
X-Page-Speed: 1.13.0.0-8389
< Cache-Control: max-age=0, no-cache
Cache-Control: max-age=0, no-cache
< Content-Encoding: gzip
Content-Encoding: gzip

< 
* Connection #0 to host 127.0.0.1 left intact

On ubuntu 14.04 I created a directory, cd'd to it and went:

$git clone git@github.com:pagespeed/ngx_pagespeed.git
$cd ngx_pagespeed
$scripts/build_ngx_pagespeed.sh --devel
[Answered 'Y' to the questions the script asks]

This builds nginx with ngx_pagespeed from source in debug mode. When it finishes you can do this to start the system tests:

test/run_tests.sh 

I did that and aborted that with ^C, which keeps the freshly build nginx server processes (from nginx/sbin/nginx) running with the configuration from the system tests. Subsequently I ran your curl command against another page (see above).

Then I ran nginx with the stock configuration modified to enable mod_pagespeed, and tested that with you exact curl command (on the nginx stock index page), same results.

@oschaaf

This comment has been minimized.

Copy link
Member

oschaaf commented Feb 3, 2017

Just reproduced the issue. It seems to only happen sometimes, and it also happens on master.

@oschaaf

This comment has been minimized.

Copy link
Member

oschaaf commented Feb 3, 2017

To reproduce reliably:

130 oschaaf@ubuntu:~/code/google/nps-issue-1375-gzip/ngx_pagespeed⟫ curl -vv --raw  -X HEAD http://127.0.0.1:10000/
* Hostname was NOT found in DNS cache
*   Trying 127.0.0.1...
* Connected to 127.0.0.1 (127.0.0.1) port 10000 (#0)
> HEAD / HTTP/1.1
> User-Agent: curl/7.35.0
> Host: 127.0.0.1:10000
> Accept: */*
> 
< HTTP/1.1 200 OK
* Server nginx/1.11.6 is not blacklisted
< Server: nginx/1.11.6
< Content-Type: text/html
< Connection: keep-alive
< Vary: Accept-Encoding
< Date: Thu, 02 Feb 2017 03:01:20 GMT
< X-Page-Speed: 1.13.0.0-8389
< Cache-Control: max-age=0, no-cache
* no chunk, no close, no size. Assume close to signal end
< 
<!DOCTYPE html>
<html>
<head>
<title>Welcome to nginx!</title>
<style>body{width:35em;margin:0 auto;font-family:Tahoma,Verdana,Arial,sans-serif}</style>
</head>
<body>
<h1>Welcome to nginx!</h1>
<p>If you see this page, the nginx web server is successfully installed and
working. Further configuration is required.</p>

<p>For online documentation and support please refer to
<a href="http://nginx.org/">nginx.org</a>.<br/>
Commercial support is available at
<a href="http://nginx.com/">nginx.com</a>.</p>

<p><em>Thank you for using nginx.</em></p>
</body>
</html>
[hangs]

This response should not have had a body.

@Zewy

This comment has been minimized.

Copy link

Zewy commented Feb 3, 2017

Great that you where able to reproduce it. only difference is it happens all the time for me on my centos 7 setup

@oschaaf oschaaf changed the title Testing with curl I get non pipelined read HEAD requests receive a response which includes an entity body in the html rewriting path Feb 3, 2017

@oschaaf

This comment has been minimized.

Copy link
Member

oschaaf commented Feb 3, 2017

This rough patch solves the problem and passes the system tests:

diff --git a/src/ngx_pagespeed.cc b/src/ngx_pagespeed.cc
index 7bef853..8487f8a 100644
--- a/src/ngx_pagespeed.cc
+++ b/src/ngx_pagespeed.cc
@@ -239,6 +239,9 @@ ngx_http_output_body_filter_pt ngx_http_next_body_filter;
 ngx_int_t ps_base_fetch_filter(ngx_http_request_t* r, ngx_chain_t* in) {
   ps_request_ctx_t* ctx = ps_get_request_context(r);
 
+  if (r->header_only) {
+    return NGX_OK;
+  }
   if (ctx == NULL || ctx->base_fetch == NULL) {
     return ngx_http_next_body_filter(r, in);
   }

Would you be willing to try it to see if we can confirm the fix?

oschaaf added a commit that referenced this issue Feb 3, 2017

Don't respond with an entitybody to HEAD requests for html
Mind r->header_only when processing the response body.

Fixes #1375
@oschaaf

This comment has been minimized.

Copy link
Member

oschaaf commented Feb 3, 2017

PR with the proposed fix: #1375

@Zewy

This comment has been minimized.

Copy link

Zewy commented Feb 4, 2017

How do I wget this or get this change with git command?

Now I use
wget -q https://github.com/pagespeed/ngx_pagespeed/archive/latest-beta.zip

How do I get your version with git ?

@Zewy

This comment has been minimized.

Copy link

Zewy commented Feb 4, 2017

PAGESPEED="021b85b53824805cba574904077db6e396e72641"
NPS_VERSION="1.12.34.2" # 2016-12-15 (Beta)

wget -q https://github.com/pagespeed/ngx_pagespeed/archive/${PAGESPEED}.zip

unzip ${PAGESPEED}.zip

cd ngx_pagespeed-${PAGESPEED}/
psol_url=https://dl.google.com/dl/page-speed/psol/${NPS_VERSION}.tar.gz
[ -e scripts/format_binary_url.sh ] && psol_url=$(scripts/format_binary_url.sh PSOL_BINARY_URL)
wget ${psol_url}
tar -xzf $(basename ${psol_url})  # extracts to psol/

I get a error to build PSOL from source but I don't understand how
the instructions on https://github.com/pagespeed/ngx_pagespeed/wiki/Building-PSOL-From-Source is a bit unclear to me

@oschaaf

This comment has been minimized.

Copy link
Member

oschaaf commented Feb 4, 2017

To get a version based on the branch with the fix, you may be able to do the following:

$git clone git@github.com:pagespeed/ngx_pagespeed.git
$cd ngx_pagespeed
$git checkout oschaaf-nps-1375
$scripts/build_ngx_pagespeed.sh --devel

This would switch you to the bleeding edge though.

You can probably also patch in the change cleanly into your current version:
https://patch-diff.githubusercontent.com/raw/pagespeed/ngx_pagespeed/pull/1376.diff

@Zewy

This comment has been minimized.

Copy link

Zewy commented Feb 6, 2017

Did just try your patch on the current version and it works! great work thanks a lot!

@oschaaf oschaaf closed this in #1376 Feb 7, 2017

oschaaf added a commit that referenced this issue Feb 7, 2017

Don't respond with an entitybody to HEAD requests for html (#1376)
Mind r->header_only when processing the response body.

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