ipro & https: Cannot fetch url 'https://192.168.185.100/mps/': as https is not supported

[oschaaf]

I have to double check this, but I'm putting it here so I don't forget to do so. I think I saw in-place rewriting for https pages being declined when the configured http fetcher did not support https.
As the resource has been recordedm instead of having to be fetched via http, I think that shouldn't be a problem.

[ghost]

Hi oschaaf, your post sounds like you know this problem. We've just built nginx (ver. 1.6) with ngx_pagespeed (ver. 1.9), the pages are https only and when the pagespeed is on the content is not served. Everything is fine when the pagespeed is off. I see the same message as you
"2014/09/24 09:49:29 [info] 28603#0: [ngx_pagespeed 1.9.32.1-4238] Cannot fetch url '...': as https is not supported" in the log.
Have you found how to solve this problem?

[oschaaf]

@nataluang At the time I noticed these messages, pages were being served OK (but the log messages made me suspect that in place rewriting was not being executed for https). Are you saying that with https your site is completely broken when pagespeed on; is configured?

To work around, you could try if pagespeed InPlaceResourceOptimization off; fixes the problem.

• edit: fixes the problem is not properly worded. That would disable in place resource optimization (which seems to not work for you on https-only anyway) and thereby get rid of the log messages.

[ghost]

@oschaaf Yes, the site is completely broken when pagespeed is on. Browser gives me this error "The connection to the server was reset while the page was loading.".

Setting the pagespeed InPlaceResourceOptimization off; didn't solve this problem, but the log message I mentioned before went away.
Now the log looks like this:

2014/09/24 11:38:26 [notice] 15361#0: start worker processes
2014/09/24 11:38:26 [info] 15362#0: [ngx_pagespeed 1.9.32.1-4238] Reusing shared memory for path: /var/cache/nginx/pagespeed.
2014/09/24 11:38:26 [notice] 15361#0: start worker process 15362
2014/09/24 11:38:26 [info] 15365#0: [ngx_pagespeed 1.9.32.1-4238] Reusing shared memory for path: /var/cache/nginx/pagespeed.
2014/09/24 11:38:26 [notice] 15361#0: start worker process 15365
2014/09/24 11:38:26 [info] 15367#0: [ngx_pagespeed 1.9.32.1-4238] Reusing shared memory for path: /var/cache/nginx/pagespeed.
2014/09/24 11:38:26 [notice] 15361#0: start worker process 15367
2014/09/24 11:38:26 [notice] 15361#0: start worker process 15368
2014/09/24 11:38:26 [info] 15368#0: [ngx_pagespeed 1.9.32.1-4238] Reusing shared memory for path: /var/cache/nginx/pagespeed.
2014/09/24 11:38:33 [notice] 15362#0: *1 "^/howItWorks/$" does not match "/", client: 192.168.1.118, server: qa-www.mydomain.com, request: "GET / HTTP/1.1", host: "qa-www.mydomain.com"
...
2014/09/24 11:38:33 [notice] 15362#0: *1 "^/public/forgotPassword.htm$" does not match "/", client: 192.168.1.118, server: qa-www.mydomain.com, request: "GET / HTTP/1.1", host: "qa-www.mydomain.com"
2014/09/24 11:38:33 [debug] 15362#0: *1 Passing on content handling for non-pagespeed resource 'https://qa-www.mydomain.com/'
2014/09/24 11:38:33 [debug] 15362#0: *1 [sticky/init_sticky_peer] got cookie route=c10c39ac8d2beb839fa41a31d9d504a7, let's try to find a matching peer
2014/09/24 11:38:33 [debug] 15362#0: *1 [sticky/init_sticky_peer] the route "c10c39ac8d2beb839fa41a31d9d504a7" matches peer at index 0
2014/09/24 11:38:33 [debug] 15362#0: *1 [sticky/get_sticky_peer] get sticky peer, try: 2, n_peers: 2, no_fallback: 0/0
2014/09/24 11:38:33 [debug] 15362#0: *1 [sticky/get_sticky_peer] let's try the selected peer (0)
2014/09/24 11:38:33 [debug] 15362#0: *1 [sticky/get_sticky_peer] peer found at index 0
2014/09/24 11:38:33 [debug] 15362#0: [ngx_pagespeed 1.9.32.1-4238] [0924/113833:VERBOSE1:proxy_fetch.cc(550)] Attaching RewriteDriver 0x158dfc40 to HtmlRewriter 0x158f8af0
2014/09/24 11:38:33 [notice] 15361#0: signal 17 (SIGCHLD) received
2014/09/24 11:38:33 [alert] 15361#0: worker process 15362 exited on signal 11
2014/09/24 11:38:33 [notice] 15361#0: start worker process 15383
2014/09/24 11:38:33 [notice] 15361#0: signal 29 (SIGIO) received
2014/09/24 11:38:33 [info] 15383#0: [ngx_pagespeed 1.9.32.1-4238] Reusing shared memory for path: /var/cache/nginx/pagespeed.

I would really appreciate any help or even hint where to look for the problem.

[oschaaf]

@nataluang Could you run nginx -V and post the output?
Would you be able to add pagespeed InstallCrashHandler on; to nginx.conf in the http{} block and post the contents of error.log after requesting another page? It looks like a segfault is occurring, and hopefully we can capture a backtrace to error.log, which could be helpful in figuring out where it originates.

[ghost]

@oschaaf
Here is the output of the nginx -V:
nginx version: nginx/1.6.1
built by gcc 4.1.2 20080704 (Red Hat 4.1.2-54)
TLS SNI support disabled
configure arguments: --prefix=/etc/nginx --sbin-path=/usr/local/sbin/nginx-ps --conf-path=/etc/nginx/nginx.conf --error-log-path=/var/log/nginx/error.log --http-log-path=/var/log/nginx/access.log --pid-path=/var/run/nginx.pid --lock-path=/var/run/nginx.lock --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 --user=nginx --group=nginx --with-http_ssl_module --with-http_realip_module --with-http_addition_module --with-http_sub_module --with-http_dav_module --with-http_flv_module --with-http_mp4_module --with-http_gunzip_module --with-http_gzip_static_module --with-http_random_index_module --with-http_secure_link_module --with-http_stub_status_module --with-mail --with-mail_ssl_module --with-cc-opt='-O2 -g -pipe -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector --param=ssp-buffer-size=4 -m64 -mtune=generic' --add-module=../nginx-goodies-nginx-sticky-module-ng-f2adff04b8e3 --add-module=../ngx_pagespeed-release-1.9.32.1-beta

The log with pagespeed InstallCrashHandler on;:
2014/09/24 12:43:02 [debug] 25611#0: *1 Passing on content handling for non-pagespeed resource 'https://qa-www.mydomain.com/'
2014/09/24 12:43:02 [debug] 25611#0: *1 [sticky/init_sticky_peer] got cookie route=c10c39ac8d2beb839fa41a31d9d504a7, let's try to find a matching peer
2014/09/24 12:43:02 [debug] 25611#0: *1 [sticky/init_sticky_peer] the route "c10c39ac8d2beb839fa41a31d9d504a7" matches peer at index 0
2014/09/24 12:43:02 [debug] 25611#0: *1 [sticky/get_sticky_peer] get sticky peer, try: 2, n_peers: 2, no_fallback: 0/0
2014/09/24 12:43:02 [debug] 25611#0: *1 [sticky/get_sticky_peer] let's try the selected peer (0)
2014/09/24 12:43:02 [debug] 25611#0: *1 [sticky/get_sticky_peer] peer found at index 0
2014/09/24 12:43:02 [debug] 25611#0: [ngx_pagespeed 1.9.32.1-4238] [0924/124302:VERBOSE1:proxy_fetch.cc(550)] Attaching RewriteDriver 0x72e2590 to HtmlRewriter 0x72fb900
2014/09/24 12:43:02 [alert] 25611#0: Trapped signal [11]
nginx: worker process [0x4c0b1a]
nginx: worker process [0x5e2911]
nginx: worker process [0x48f47c]
/lib64/libc.so.6 [0x2b0e3dff6330]
nginx: worker process [0x4a2296]
nginx: worker process [0x4907e9]
nginx: worker process [0x4585f3]
nginx: worker process [0x45af20]
nginx: worker process [0x45c84f]
nginx: worker process [0x45cc7c]
nginx: worker process [0x4108ef]
nginx: worker process [0x43f6f4]
nginx: worker process [0x4504aa]
nginx: worker process [0x430e2b]
nginx: worker process [0x424bfb]
nginx: worker process [0x449ebe]
nginx: worker process [0x44c9eb]
nginx: worker process [0x449a9b]
nginx: worker process [0x4231b6]
nginx: worker process [0x428d3f]
nginx: worker process [0x427460]
nginx: worker process [0x428361]
nginx: worker process [0x4292d7]
nginx: worker process [0x40d9f3]
/lib64/libc.so.6(__libc_start_main+0xf4) [0x2b0e3dfe39c4]
nginx: worker process [0x40c169]

2014/09/24 12:43:02 [notice] 25610#0: signal 17 (SIGCHLD) received
2014/09/24 12:43:02 [alert] 25610#0: worker process 25611 exited on signal 9
2014/09/24 12:43:02 [notice] 25610#0: start worker process 25636
2014/09/24 12:43:02 [notice] 25610#0: signal 29 (SIGIO) received
2014/09/24 12:43:02 [info] 25636#0: [ngx_pagespeed 1.9.32.1-4238] Reusing shared memory for path: /var/cache/nginx/pagespeed.

[oschaaf]

@nataluang thanks. the backtrace isn't as helpful as I hoped for, as it mentions addresses instead of function names. It is hard for me to translate those.

Could you post the output of this?:

addr2line -e /usr/local/nginx/sbin/nginx-ps 0x4c0b1a 0x5e2911 0x48f47c 0x2b0e3dff6330 0x4a2296 0x4907e9 0x4585f3 0x45af20 0x45c84f 0x45cc7c 0x4108ef 0x43f6f4 0x4504aa 0x430e2b 0x424bfb 0x449ebe 0x44c9eb 0x449a9b 0x4231b6 0x428d3f 0x427460 0x428361 0x4292d7 0x40d9f3

[ghost]

@oschaaf Here it is:
[webqa(root) /etc/nginx]# addr2line -e /usr/local/sbin/nginx-ps 0x4c0b1a 0x5e2911 0x48f47c 0x2b0e3dff6330 0x4a2296 0x4907e9 0x4585f3 0x45af20 0x45c84f 0x45cc7c 0x4108ef 0x43f6f4 0x4504aa 0x430e2b 0x424bfb 0x449ebe 0x44c9eb 0x449a9b 0x4231b6 0x428d3f 0x427460 0x428361 0x4292d7 0x40d9f3
??:0
??:0
/home/appbuild/compile/nginx/nginx-1.6.1/../ngx_pagespeed-release-1.9.32.1-beta/src/ngx_message_handler.cc:47
??:0
??:0
/home/appbuild/compile/nginx/nginx-1.6.1/../ngx_pagespeed-release-1.9.32.1-beta/src/ngx_pagespeed.cc:2080
/home/appbuild/compile/nginx/nginx-1.6.1/src/http/modules/ngx_http_ssi_filter_module.c:408
/home/appbuild/compile/nginx/nginx-1.6.1/src/http/modules/ngx_http_charset_filter_module.c:643
/home/appbuild/compile/nginx/nginx-1.6.1/src/http/modules/ngx_http_addition_filter_module.c:194
/home/appbuild/compile/nginx/nginx-1.6.1/src/http/modules/ngx_http_gunzip_filter_module.c:292
/home/appbuild/compile/nginx/nginx-1.6.1/src/core/ngx_output_chain.c:208
/home/appbuild/compile/nginx/nginx-1.6.1/src/http/ngx_http_copy_filter_module.c:145
/home/appbuild/compile/nginx/nginx-1.6.1/src/http/modules/ngx_http_range_filter_module.c:614
/home/appbuild/compile/nginx/nginx-1.6.1/src/http/ngx_http_core_module.c:1966
/home/appbuild/compile/nginx/nginx-1.6.1/src/event/ngx_event_pipe.c:640
/home/appbuild/compile/nginx/nginx-1.6.1/src/http/ngx_http_upstream.c:3084
/home/appbuild/compile/nginx/nginx-1.6.1/src/http/ngx_http_upstream.c:2493
/home/appbuild/compile/nginx/nginx-1.6.1/src/http/ngx_http_upstream.c:980
/home/appbuild/compile/nginx/nginx-1.6.1/src/event/ngx_event_posted.c:29
/home/appbuild/compile/nginx/nginx-1.6.1/src/os/unix/ngx_process_cycle.c:818
/home/appbuild/compile/nginx/nginx-1.6.1/src/os/unix/ngx_process.c:205
/home/appbuild/compile/nginx/nginx-1.6.1/src/os/unix/ngx_process_cycle.c:367
/home/appbuild/compile/nginx/nginx-1.6.1/src/os/unix/ngx_process_cycle.c:138
/home/appbuild/compile/nginx/nginx-1.6.1/src/core/nginx.c:407

[oschaaf]

@nataluang Are you actively using SSI includes?

The crash path seems to be that the SSI module calls ngx_pagespeed via [1], and subsequently the crasher occurs when ctx->inflater->SetInput() is called in ps_send_to_pagespeed(). [2]

It is also worth noting that earlier in the trace the gunzip module seems to be returning NGX_ERROR[3].

[1] https://github.com/nginx/nginx/blob/1fdff008eae31a85e7575079a43f1419aba9ba9b/src/http/modules/ngx_http_ssi_filter_module.c#L408
[2] https://github.com/pagespeed/ngx_pagespeed/blob/release-1.9.32.1-beta/src/ngx_pagespeed.cc#L2080
[3] https://github.com/nginx/nginx/blob/1fdff008eae31a85e7575079a43f1419aba9ba9b/src/http/modules/ngx_http_gunzip_filter_module.c#L292

[ghost]

@oschaaf From what I know we did use it (SSI) for something, but unclear if it's still necessary. I'm going to try to rebuild without it and see if that will help.
As for the second part, are you saying there is also a problem with gunzip? We do use that module and I could probably post our config here if that would help at all. But because it works with pagespeed off I wouldn't think there should be a problem with it.

[oschaaf]

@nataluang Sorry - I was more or less thinking aloud. I suspect there's a compatibility problem with one of the modules you are using. SSI / gunzip are candidates, but I can't be sure because of the way nginx works.

SSI is suspect because of earlier trouble. Gunzip is suspect because that would potentially be linked to the fact that we gunzip our inputs as well and the involved code is actually mentioned in the backtrace.

There's also the sticky module which I've never tested with.
I need to test with your setup to debug this, which I should be able to more or less rebuild with the output you posted for nginx -V. Having your nginx configuration files would be helpful too, if its possible, could you PM those?

[ghost]

@oschaaf emailed you my config.

[ghost]

@oschaaf The ngx_http_ssi_module was not included into the build, so that is confusing as it shouldn't be there.

[ghost]

@oschaaf I rebuilt nginx without ssi module and without gunzip (I don't think we've been using either).
Here is new "stacktrace":
[webqa(root) /etc/nginx]# addr2line -e /usr/local/sbin/nginx-ps 0x4bc82a 0x5de621 0x48b18c 0x2b4fbc216330 0x49dfa6 0x48c4f9 0x457520 0x458e4f 0x410c3c 0x43f5a4 0x45036a 0x430cdb 0x424abb 0x449d5e 0x44993b 0x423076 0x428bff 0x427320 0x428221 0x429197 0x40d8b3 0x2b4fbc2039c4 0x40c029
??:0
??:0
/home/appbuild/compile/nginx/nginx-1.6.1/../ngx_pagespeed-release-1.9.32.1-beta/src/ngx_message_handler.cc:47
??:0
??:0
/home/appbuild/compile/nginx/nginx-1.6.1/../ngx_pagespeed-release-1.9.32.1-beta/src/ngx_pagespeed.cc:2080
/home/appbuild/compile/nginx/nginx-1.6.1/src/http/modules/ngx_http_charset_filter_module.c:643
/home/appbuild/compile/nginx/nginx-1.6.1/src/http/modules/ngx_http_addition_filter_module.c:194
/home/appbuild/compile/nginx/nginx-1.6.1/src/core/ngx_output_chain.c:66
/home/appbuild/compile/nginx/nginx-1.6.1/src/http/ngx_http_copy_filter_module.c:145
/home/appbuild/compile/nginx/nginx-1.6.1/src/http/modules/ngx_http_range_filter_module.c:614
/home/appbuild/compile/nginx/nginx-1.6.1/src/http/ngx_http_core_module.c:1966
/home/appbuild/compile/nginx/nginx-1.6.1/src/event/ngx_event_pipe.c:640
/home/appbuild/compile/nginx/nginx-1.6.1/src/http/ngx_http_upstream.c:3084
/home/appbuild/compile/nginx/nginx-1.6.1/src/http/ngx_http_upstream.c:980
/home/appbuild/compile/nginx/nginx-1.6.1/src/event/ngx_event_posted.c:29
/home/appbuild/compile/nginx/nginx-1.6.1/src/os/unix/ngx_process_cycle.c:818
/home/appbuild/compile/nginx/nginx-1.6.1/src/os/unix/ngx_process.c:205
/home/appbuild/compile/nginx/nginx-1.6.1/src/os/unix/ngx_process_cycle.c:367
/home/appbuild/compile/nginx/nginx-1.6.1/src/os/unix/ngx_process_cycle.c:138
/home/appbuild/compile/nginx/nginx-1.6.1/src/core/nginx.c:407
??:0
??:0

And here is log output:
2014/09/24 17:27:55 [debug] 24277#0: *1 Passing on content handling for non-pagespeed resource 'https://qa-www.mydomain.com/'
2014/09/24 17:27:55 [debug] 24277#0: *1 [sticky/init_sticky_peer] got cookie route=c10c39ac8d2beb839fa41a31d9d504a7, let's try to find a matching peer
2014/09/24 17:27:55 [debug] 24277#0: *1 [sticky/init_sticky_peer] the route "c10c39ac8d2beb839fa41a31d9d504a7" matches peer at index 0
2014/09/24 17:27:55 [debug] 24277#0: *1 [sticky/get_sticky_peer] get sticky peer, try: 2, n_peers: 2, no_fallback: 0/0
2014/09/24 17:27:55 [debug] 24277#0: *1 [sticky/get_sticky_peer] let's try the selected peer (0)
2014/09/24 17:27:55 [debug] 24277#0: *1 [sticky/get_sticky_peer] peer found at index 0
2014/09/24 17:27:55 [debug] 24277#0: [ngx_pagespeed 1.9.32.1-4238] [0924/172755:VERBOSE1:proxy_fetch.cc(550)] Attaching RewriteDriver 0x157b7b50 to HtmlRewriter 0x157d0e20
2014/09/24 17:27:55 [alert] 24277#0: Trapped signal [11]
nginx: worker process [0x4bc82a]
nginx: worker process [0x5de621]
nginx: worker process [0x48b18c]
/lib64/libc.so.6 [0x2b4fbc216330]
nginx: worker process [0x49dfa6]
nginx: worker process [0x48c4f9]
nginx: worker process [0x457520]
nginx: worker process [0x458e4f]
nginx: worker process [0x410c3c]
nginx: worker process [0x43f5a4]
nginx: worker process [0x45036a]
nginx: worker process [0x430cdb]
nginx: worker process [0x424abb]
nginx: worker process [0x449d5e]
nginx: worker process [0x44993b]
nginx: worker process [0x423076]
nginx: worker process [0x428bff]
nginx: worker process [0x427320]
nginx: worker process [0x428221]
nginx: worker process [0x429197]
nginx: worker process [0x40d8b3]
/lib64/libc.so.6(__libc_start_main+0xf4) [0x2b4fbc2039c4]
nginx: worker process [0x40c029]

2014/09/24 17:27:55 [notice] 24276#0: signal 17 (SIGCHLD) received
2014/09/24 17:27:55 [alert] 24276#0: worker process 24277 exited on signal 9
2014/09/24 17:27:55 [notice] 24276#0: start worker process 24310
2014/09/24 17:27:55 [notice] 24276#0: signal 29 (SIGIO) received
2014/09/24 17:27:55 [info] 24310#0: [ngx_pagespeed 1.9.32.1-4238] Reusing shared memory for path: /var/cache/nginx/pagespeed

[oschaaf]

@nataluang I've made a first attempt at reproducing, which regrettably failed. I'm going to try again with redhat and gcc 4.1
The gcc version escaped my attention earlier, but I just noticed and it reminds me of this post at ngx-pagespeed-discuss: https://groups.google.com/forum/#!msg/ngx-pagespeed-discuss/zqYG8xbrNHY/aPWDfkJ7D_wJ

[ghost]

@oschaaf Thank you Otto! I rebuilt with the gcc 4.4.7 and now I don't have the problem anymore.

[oschaaf]

I moved the gcc 4.1.2 issue to a separate issue to track it: #813

[oschaaf]

The original issue was that I thought I saw IPRO requests being declined when the configured fetcher didn't support https. After specifically testing that, it looks like I was wrong and things are working fine.

Closing this issue.