search

apache / incubator-pagespeed-ngx

Automatic PageSpeed optimization module for Nginx
http://ngxpagespeed.com/
Apache License 2.0
4.37k stars 362 forks source link

DCHECK-fail in css summarizer: canceled_summaries_.empty() #891

Closed episage closed 7 years ago

episage commented 9 years ago

Hi

error.log 

2015/01/29 13:11:27 [alert] 26659#0: [ngx_pagespeed 1.9.32.3-4448] [0129/131127:FATAL:css_summarizer_base.cc(327)] Check failed: canceled_summaries_.empty().
2015/01/29 13:11:27 [alert] 20655#0: worker process 26659 exited on signal 6 (core dumped)

gdb backtrace full

root@install:~# gdb /usr/sbin/nginx /var/log/nginx/core_dumps/core
GNU gdb (GDB) 7.4.1-debian
Copyright (C) 2012 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /usr/sbin/nginx...Reading symbols from /usr/lib/debug/.build-id/a1/81e8592cc329844222bf46b12683985433f4f6.debug.                                   ..done.
done.
[New LWP 26662]
[New LWP 26779]
[New LWP 26780]
[New LWP 26660]
[New LWP 26661]
[New LWP 26659]

warning: Can't read pathname for load map: Input/output error.
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `nginx: worker pr'.
Program terminated with signal 6, Aborted.
#0  0x00007f2cc67ae165 in raise () from /lib/x86_64-linux-gnu/libc.so.6
(gdb) backtrace full
#0  0x00007f2cc67ae165 in raise () from /lib/x86_64-linux-gnu/libc.so.6
No symbol table info available.
#1  0x00007f2cc67b13e0 in abort () from /lib/x86_64-linux-gnu/libc.so.6
No symbol table info available.
#2  0x00000000004f7c6d in base::debug::(anonymous namespace)::DebugBreak ()
    at third_party/chromium/src/base/debug/debugger_posix.cc:235
No locals.
#3  0x00000000004f7c79 in base::debug::BreakDebugger () at third_party/chromium/src/base/debug/debugger_posix.cc:259
No locals.
#4  0x00000000004b38ad in (anonymous namespace)::LogMessageHandler (severity=4, file=<optimized out>, line=<optimized out>,
    message_start=<optimized out>, str=...) at /root/cl2/ngx_pagespeed-release-1.9.32.3-beta/src/log_message_handler.cc:87
        this_log_level = 2
        message = {static npos = <optimized out>,
          _M_dataplus = {<std::allocator<char>> = {<__gnu_cxx::new_allocator<char>> = {<No data fields>}, <No data fields>},
            _M_p = 0x7f2cb801c5f8 "[0129/131127:FATAL:css_summarizer_base.cc(327)] Check failed: canceled_summaries_.empty(). \nnginx: worker process() [0x4fc049]\nnginx: worker process() [0x4f9062]\nnginx: worker process() [0x5f863d]\nngi"...}}
        last_msg_character_index = 1567
#5  0x00000000004f9144 in logging::LogMessage::~LogMessage (this=0x7f2cbfb4f400, __in_chrg=<optimized out>)
    at third_party/chromium/src/base/logging.cc:570
        str_newline = {static npos = 18446744073709551615,
          _M_dataplus = {<std::allocator<char>> = {<__gnu_cxx::new_allocator<char>> = {<No data fields>}, <No data fields>},
            _M_p = 0x7f2cb80210e8 "[0129/131127:FATAL:css_summarizer_base.cc(327)] Check failed: canceled_summaries_.empty(). \nnginx: worker process() [0x4fc049]\nnginx: worker process() [0x4f9062]\nnginx: worker process() [0x5f863d]\nngi"...}}
#6  0x00000000005f863d in net_instaweb::CssSummarizerBase::StartDocumentImpl (this=0x153ec00)
    at net/instaweb/rewriter/css_summarizer_base.cc:327
No locals.
#7  0x0000000000972542 in net_instaweb::CommonFilter::StartDocument (this=0x153ec00) at net/instaweb/rewriter/common_filter.cc:70
No locals.
#8  0x00000000006f5cda in net_instaweb::HtmlStartDocumentEvent::Run (this=0x16effc0, filter=0x153ec00)
    at ./pagespeed/kernel/html/html_event.h:63
No locals.
#9  0x00000000006f28d5 in net_instaweb::HtmlParse::ApplyFilter (this=0x17841e0, filter=0x153ec00)
    at pagespeed/kernel/html/html_parse.cc:346
        event = 0x16effc0
        p = {_M_node = 0x17843c8}
#10 0x0000000000541cac in net_instaweb::RewriteDriver::FlushAsync (this=0x17841e0, callback=0x7f2cb8004330)
    at net/instaweb/rewriter/rewrite_driver.cc:648
        filter = 0x153ec00
---Type <return> to continue, or q <return> to quit---
        it = {_M_node = 0x1740fe0}
        num_rewrites = 0
#11 0x000000000054218f in net_instaweb::RewriteDriver::FinishParseAsync (this=0x17841e0, callback=0x7f2cb8004210)
    at net/instaweb/rewriter/rewrite_driver.cc:2686
No locals.
#12 0x00000000004eb165 in net_instaweb::ProxyFetch::Finish (this=0x170d350, success=true)
    at net/instaweb/automatic/proxy_fetch.cc:1148
        detach_callback = 0x0
        sync = 0x0
#13 0x00000000004eb800 in net_instaweb::ProxyFetch::ExecuteQueued (this=0x170d350) at net/instaweb/automatic/proxy_fetch.cc:1108
        do_flush = false
        do_finish = true
        done_result = true
        force_flush = false
        buffer_limit = 102400
        v = {<std::_Vector_base<std::basic_string<char, std::char_traits<char>, std::allocator<char> >*, std::allocator<std::basic_string<char, std::char_traits<char>, std::allocator<char> >*> >> = {
            _M_impl = {<std::allocator<std::basic_string<char, std::char_traits<char>, std::allocator<char> >*>> = {<__gnu_cxx::new_allocator<std::basic_string<char, std::char_traits<char>, std::allocator<char> >*>> = {<No data fields>}, <No data fields>},
              _M_start = 0x0, _M_finish = 0x0, _M_end_of_storage = 0x0}}, <No data fields>}
#14 0x00000000004f2372 in net_instaweb::MemberFunction0<net_instaweb::ProxyFetch>::Run (this=0x175c400)
    at ./pagespeed/kernel/base/function.h:143
No locals.
#15 0x00000000006945c6 in net_instaweb::Function::CallRun (this=0x175c400) at pagespeed/kernel/base/function.cc:51
        should_delete = true
#16 0x000000000075e3e3 in net_instaweb::QueuedWorkerPool::Run (this=0x1615210, sequence=0x168ba60, worker=0x16b3f90)
    at pagespeed/kernel/thread/queued_worker_pool.cc:157
        function = 0x175c400
#17 0x0000000000760cdb in net_instaweb::MemberFunction2<net_instaweb::QueuedWorkerPool, net_instaweb::QueuedWorkerPool::Sequence*, net_instaweb::QueuedWorker*>::Run (this=0x16cf6e0) at ./pagespeed/kernel/base/function.h:202
No locals.
#18 0x00000000006945c6 in net_instaweb::Function::CallRun (this=0x16cf6e0) at pagespeed/kernel/base/function.cc:51
        should_delete = true
#19 0x0000000000769b43 in net_instaweb::Worker::WorkThread::Run (this=0x168bb40) at pagespeed/kernel/thread/worker.cc:84
        task = 0x16cf6e0
#20 0x000000000076c2e0 in net_instaweb::PthreadThreadImpl::InvokeRun (self_ptr=0x16b4280)
    at pagespeed/kernel/thread/pthread_thread_system.cc:122
        self = 0x16b4280
---Type <return> to continue, or q <return> to quit---
#21 0x00007f2cc9403b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
No symbol table info available.
#22 0x00007f2cc68587bd in clone () from /lib/x86_64-linux-gnu/libc.so.6
No symbol table info available.
#23 0x0000000000000000 in ?? ()
No symbol table info available.

I did

rm -r /var/nginx/proxy_cache/*

before the error occured. Where proxy_cache is proxy cache directory I wanted to purge.

ModPagespeed config, nginx config available at https://www.dropbox.com/s/nij5m1hbkl0v2v3/PSM_CONF.zip?dl=0

Can provide more details on request

episage

jeffkaufman commented 9 years ago

Thanks for the backtrace!

@morlovich, this looks like a check you added?

episage commented 9 years ago

Detailed debug.log

2015/01/29 13:11:27 [debug] 26659#0: *1953 spdy keepalive handler
2015/01/29 13:11:27 [debug] 26659#0: *1953 reusable connection: 0
2015/01/29 13:11:27 [debug] 26659#0: *1953 posix_memalign: 0000000001C76B50:4096 @16
2015/01/29 13:11:27 [debug] 26659#0: *1953 spdy read handler
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL_read: 396
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL_read: -1
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL_get_error: 2
2015/01/29 13:11:27 [debug] 26659#0: *1953 spdy process frame head:80030001 f:1 l:388
2015/01/29 13:11:27 [debug] 26659#0: *1953 spdy SYN_STREAM frame sid:25 prio:0
2015/01/29 13:11:27 [debug] 26659#0: *1953 posix_memalign: 0000000002007830:4096 @16
2015/01/29 13:11:27 [debug] 26659#0: *1953 posix_memalign: 0000000001722420:4096 @16
2015/01/29 13:11:27 [debug] 26659#0: *1953 spdy process HEADERS 378 of 378
2015/01/29 13:11:27 [debug] 26659#0: *1953 spdy inflate out: ni:0000000001797BF1 no:000000000172283F ai:27 ao:0 rc:0
2015/01/29 13:11:27 [debug] 26659#0: *1953 spdy HEADERS block consists of 13 entries
2015/01/29 13:11:27 [debug] 26659#0: *1953 http uri: "/"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http args: ""
2015/01/29 13:11:27 [debug] 26659#0: *1953 http exten: ""
2015/01/29 13:11:27 [debug] 26659#0: *1953 spdy alloc large header buffer
2015/01/29 13:11:27 [debug] 26659#0: *1953 malloc: 0000000001BA2B10:8192
2015/01/29 13:11:27 [debug] 26659#0: *1953 spdy large header alloc: 0000000001BA2B10 8192
2015/01/29 13:11:27 [debug] 26659#0: *1953 spdy http request line: "GET / HTTP/1.1"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http header: "host: santelab.pl"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http header: "accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http header: "accept-encoding: gzip, deflate, sdch"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http header: "accept-language: en-GB,en;q=0.8,en-US;q=0.6,pl;q=0.4"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http header: "authorization: Basic --CUT OUT--"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http header: "cache-control: no-cache"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http header: "cookie: --CUT OUT--"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http header: "pragma: no-cache"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http header: "user-agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/40.0.2214.93 Safari/537.36"
2015/01/29 13:11:27 [debug] 26659#0: *1953 generic phase: 0
2015/01/29 13:11:27 [debug] 26659#0: *1953 rewrite phase: 1
2015/01/29 13:11:27 [debug] 26659#0: *1953 test location: "/"
2015/01/29 13:11:27 [debug] 26659#0: *1953 test location: ~ "^/pagespeed_static/"
2015/01/29 13:11:27 [debug] 26659#0: *1953 test location: ~ "^/ngx_pagespeed_beacon$"
2015/01/29 13:11:27 [debug] 26659#0: *1953 test location: ~ "\.pagespeed\.([a-z]\.)?[a-z]{2}\.[^.]{10}\.[^.]+"
2015/01/29 13:11:27 [debug] 26659#0: *1953 test location: ~ "^/pagespeed_admin"
2015/01/29 13:11:27 [debug] 26659#0: *1953 using configuration "/"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http cl:-1 max:134217728
2015/01/29 13:11:27 [debug] 26659#0: *1953 rewrite phase: 3
2015/01/29 13:11:27 [debug] 26659#0: *1953 post rewrite phase: 4
2015/01/29 13:11:27 [debug] 26659#0: *1953 generic phase: 5
2015/01/29 13:11:27 [debug] 26659#0: *1953 generic phase: 6
2015/01/29 13:11:27 [debug] 26659#0: *1953 generic phase: 7
2015/01/29 13:11:27 [debug] 26659#0: *1953 access phase: 8
2015/01/29 13:11:27 [debug] 26659#0: *1953 access phase: 9
2015/01/29 13:11:27 [debug] 26659#0: *1953 access phase: 10
2015/01/29 13:11:27 [debug] 26659#0: *1953 access phase: 11
2015/01/29 13:11:27 [debug] 26659#0: *1953 post access phase: 12
2015/01/29 13:11:27 [debug] 26659#0: *1953 pagespeed phase: 13
2015/01/29 13:11:27 [debug] 26659#0: *1953 http pagespeed handler "/"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http cleanup add: 00000000020086C8
2015/01/29 13:11:27 [debug] 26659#0: epoll add event: fd:14 op:1 ev:00002001
2015/01/29 13:11:27 [info] 26659#0: [ngx_pagespeed 1.9.32.3-4448] Trying to serve rewritten resource in-place: https://santelab.pl/
2015/01/29 13:11:27 [debug] 26659#0: *1953 http finalize request: -4, "/?" a:1, c:2
2015/01/29 13:11:27 [debug] 26659#0: *1953 http request count:2 blk:0
2015/01/29 13:11:27 [debug] 26659#0: *1953 event timer del: 3: 1422537261032
2015/01/29 13:11:27 [debug] 26659#0: reusable connection: 0
2015/01/29 13:11:27 [debug] 26659#0: *1953 ps fetch handler: /
2015/01/29 13:11:27 [debug] 26659#0: *1953 ps in place check header filter initial: /
2015/01/29 13:11:27 [info] 26659#0: [ngx_pagespeed 1.9.32.3-4448] Could not rewrite resource in-place because URL is not in cache: https://santelab.pl/
2015/01/29 13:11:27 [debug] 26659#0: *1953 try files phase: 14
2015/01/29 13:11:27 [debug] 26659#0: *1953 spdy read request body
2015/01/29 13:11:27 [debug] 26659#0: *1953 http init upstream, client timer: 0
2015/01/29 13:11:27 [debug] 26659#0: *1953 http cache key: "https://91.219.122.41"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http cache key: "/"
2015/01/29 13:11:27 [debug] 26659#0: *1953 add cleanup: 0000000002008808
2015/01/29 13:11:27 [debug] 26659#0: *1953 http file cache exists: 0 e:1
2015/01/29 13:11:27 [debug] 26659#0: *1953 cache file: "/var/nginx/proxy_cache/9/78/03d76d56294b499e72ad580eace08789"
2015/01/29 13:11:27 [debug] 26659#0: *1953 add cleanup: 00000000017232E0
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream cache: -5
2015/01/29 13:11:27 [debug] 26659#0: *1953 posix_memalign: 00000000018660C0:4096 @16
2015/01/29 13:11:27 [debug] 26659#0: *1953 http script copy: "Host: santelab.pl
"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http script copy: "Connection: close
"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http script copy: ""
2015/01/29 13:11:27 [debug] 26659#0: *1953 http script copy: ""
2015/01/29 13:11:27 [debug] 26659#0: *1953 http script copy: ""
2015/01/29 13:11:27 [debug] 26659#0: *1953 http script copy: ""
2015/01/29 13:11:27 [debug] 26659#0: *1953 http proxy header: "accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http proxy header: "accept-encoding: gzip, deflate, sdch"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http proxy header: "accept-language: en-GB,en;q=0.8,en-US;q=0.6,pl;q=0.4"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http proxy header: "authorization: Basic --CUT OUT--"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http proxy header: "cache-control: no-cache"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http proxy header: "--CUT OUT--"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http proxy header: "pragma: no-cache"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http proxy header: "user-agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/40.0.2214.93 Safari/537.36"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http proxy header:
"GET / HTTP/1.0
Host: santelab.pl
Connection: close
accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
accept-encoding: gzip, deflate, sdch
accept-language: en-GB,en;q=0.8,en-US;q=0.6,pl;q=0.4
authorization: Basic --CUT OUT--
cache-control: no-cache
cookie: --CUT OUT--
pragma: no-cache
user-agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/40.0.2214.93 Safari/537.36

"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http cleanup add: 00000000017233C0
2015/01/29 13:11:27 [debug] 26659#0: *1953 get rr peer, try: 1
2015/01/29 13:11:27 [debug] 26659#0: *1953 socket 14
2015/01/29 13:11:27 [debug] 26659#0: *1953 epoll add connection: fd:14 ev:80002005
2015/01/29 13:11:27 [debug] 26659#0: *1953 connect to 91.219.122.41:443, fd:14 #2049
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream connect: -2
2015/01/29 13:11:27 [debug] 26659#0: *1953 posix_memalign: 00000000016DFF00:128 @16
2015/01/29 13:11:27 [debug] 26659#0: *1953 event timer add: 14: 60000:1422537147255
2015/01/29 13:11:27 [debug] 26659#0: *1953 http finalize request: -4, "/?" a:1, c:3
2015/01/29 13:11:27 [debug] 26659#0: *1953 http request count:3 blk:0
2015/01/29 13:11:27 [debug] 26659#0: *1953 http finalize request: -4, "/?" a:1, c:2
2015/01/29 13:11:27 [debug] 26659#0: *1953 http request count:2 blk:0
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream request: "/?"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream send request handler
2015/01/29 13:11:27 [debug] 26659#0: *1953 malloc: 000000000175C400:64
2015/01/29 13:11:27 [debug] 26659#0: *1953 set session: 00000000016CE230:2
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL_do_handshake: -1
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL_get_error: 2
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL handshake handler: 0
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL_do_handshake: 1
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL: TLSv1.2, cipher: "RC4-SHA SSLv3 Kx=RSA Au=RSA Enc=RC4(128) Mac=SHA1"
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL reused session
2015/01/29 13:11:27 [debug] 26659#0: *1953 save session: 00000000016CE230:3
2015/01/29 13:11:27 [debug] 26659#0: *1953 old session: 00000000016CE230:3
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream send request
2015/01/29 13:11:27 [debug] 26659#0: *1953 chain writer buf fl:1 s:1109
2015/01/29 13:11:27 [debug] 26659#0: *1953 chain writer in: 00000000017233F8
2015/01/29 13:11:27 [debug] 26659#0: *1953 malloc: 00000000016CF6E0:80
2015/01/29 13:11:27 [debug] 26659#0: *1953 malloc: 0000000001817290:16384
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL buf copy: 1109
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL to write: 1109
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL_write: 1109
2015/01/29 13:11:27 [debug] 26659#0: *1953 chain writer out: 0000000000000000
2015/01/29 13:11:27 [debug] 26659#0: *1953 event timer del: 14: 1422537147255
2015/01/29 13:11:27 [debug] 26659#0: *1953 event timer add: 14: 1200000:1422538287321
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream process header
2015/01/29 13:11:27 [debug] 26659#0: *1953 malloc: 000000000189BC00:4096
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL_read: -1
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL_get_error: 2
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream request: "/?"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream send request handler
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream send request
2015/01/29 13:11:27 [debug] 26659#0: *1953 chain writer in: 0000000000000000
2015/01/29 13:11:27 [debug] 26659#0: *1953 event timer: 14, old: 1422538287321, new: 1422538287321
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream request: "/?"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream process header
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL_read: -1
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL_get_error: 2
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream request: "/?"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream dummy handler
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream request: "/?"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream process header
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL_read: -1
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL_get_error: 2
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream request: "/?"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream dummy handler
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream request: "/?"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream process header
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL_read: -1
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL_get_error: 2
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream request: "/?"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream dummy handler
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream request: "/?"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream process header
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL_read: -1
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL_get_error: 2
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream request: "/?"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream dummy handler
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream request: "/?"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream process header
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL_read: 4027
2015/01/29 13:11:27 [debug] 26659#0: *1953 http proxy status 200 "200 OK"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http proxy header: "Cache-Control: public, max-age=85641"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http proxy header: "Content-Type: text/html; charset=utf-8"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http proxy header: "Expires: Fri, 30 Jan 2015 12:58:50 GMT"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http proxy header: "Last-Modified: Thu, 29 Jan 2015 12:58:50 GMT"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http proxy header: "Vary: *"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http proxy header: "Server: Microsoft-IIS/8.5"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http proxy header: "X-AspNetMvc-Version: 4.0"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http proxy header: "X-AspNet-Version: 4.0.30319"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http proxy header: "Date: Thu, 29 Jan 2015 13:11:27 GMT"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http proxy header: "Connection: close"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http proxy header: "Content-Length: 9173"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http proxy header done
2015/01/29 13:11:27 [debug] 26659#0: *1953 http script var: "MISS"
2015/01/29 13:11:27 [debug] 26659#0: *1953 xslt filter header
2015/01/29 13:11:27 [debug] 26659#0: *1953 http pagespeed html rewrite header filter "/"
2015/01/29 13:11:27 [debug] 26659#0: epoll add event: fd:18 op:1 ev:00002001
2015/01/29 13:11:27 [debug] 26659#0: *1953 http file cache set header
2015/01/29 13:11:27 [debug] 26659#0: *1953 http cacheable: 1
2015/01/29 13:11:27 [debug] 26659#0: *1953 http proxy filter init s:200 h:0 c:0 l:9173
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream process upstream
2015/01/29 13:11:27 [debug] 26659#0: *1953 pipe read upstream: 1
2015/01/29 13:11:27 [debug] 26659#0: *1953 pipe preread: 3675
2015/01/29 13:11:27 [debug] 26659#0: *1953 input buf #0
2015/01/29 13:11:27 [debug] 26659#0: *1953 malloc: 0000000001C07910:4096
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL_read: 4096
2015/01/29 13:11:27 [debug] 26659#0: *1953 pipe recv chain: 4096
2015/01/29 13:11:27 [debug] 26659#0: *1953 input buf #1
2015/01/29 13:11:27 [debug] 26659#0: *1953 malloc: 000000000171E860:4096
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL_read: 1402
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL_read: 0
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL_get_error: 5
2015/01/29 13:11:27 [debug] 26659#0: *1953 peer shutdown SSL cleanly
2015/01/29 13:11:27 [debug] 26659#0: *1953 pipe recv chain: 1402
2015/01/29 13:11:27 [debug] 26659#0: *1953 pipe recv chain: 0
2015/01/29 13:11:27 [debug] 26659#0: *1953 pipe buf in   s:1 t:1 f:0 000000000189BC00, pos 000000000189BDA5, size: 3675 file: 0, size: 0
2015/01/29 13:11:27 [debug] 26659#0: *1953 pipe buf in   s:1 t:1 f:0 0000000001C07910, pos 0000000001C07910, size: 4096 file: 0, size: 0
2015/01/29 13:11:27 [debug] 26659#0: *1953 pipe buf free s:0 t:1 f:0 000000000171E860, pos 000000000171E860, size: 1402 file: 0, size: 0
2015/01/29 13:11:27 [debug] 26659#0: *1953 pipe length: 1402
2015/01/29 13:11:27 [debug] 26659#0: *1953 input buf #2
2015/01/29 13:11:27 [debug] 26659#0: *1953 add cleanup: 0000000001866DB8
2015/01/29 13:11:27 [debug] 26659#0: *1953 hashed path: /var/lib/nginx/proxy/2/13/0000000132
2015/01/29 13:11:27 [debug] 26659#0: *1953 temp fd:20
2015/01/29 13:11:27 [debug] 26659#0: *1953 writev: 20, 9594
2015/01/29 13:11:27 [debug] 26659#0: *1953 pipe write downstream: 1
2015/01/29 13:11:27 [debug] 26659#0: *1953 pipe write downstream flush out
2015/01/29 13:11:27 [debug] 26659#0: *1953 http output filter "/?"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http copy filter: "/?"
2015/01/29 13:11:27 [debug] 26659#0: *1953 malloc: 000000000208BC20:32768
2015/01/29 13:11:27 [debug] 26659#0: *1953 read: 20, 000000000208BC20, 9173, 421
2015/01/29 13:11:27 [debug] 26659#0: *1953 image filter
2015/01/29 13:11:27 [debug] 26659#0: *1953 xslt filter body
2015/01/29 13:11:27 [debug] 26659#0: *1953 http postpone filter "/?" 0000000001866F40
2015/01/29 13:11:27 [debug] 26659#0: *1953 http pagespeed html rewrite body filter "/"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http pagespeed write filter "/"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http copy filter: -2 "/?"
2015/01/29 13:11:27 [debug] 26659#0: *1953 pipe write downstream done
2015/01/29 13:11:27 [debug] 26659#0: *1953 event timer: 14, old: 1422538287321, new: 1422538287449
2015/01/29 13:11:27 [debug] 26659#0: *1953 http file cache update
2015/01/29 13:11:27 [debug] 26659#0: *1953 http file cache rename: "/var/lib/nginx/proxy/2/13/0000000132" to "/var/nginx/proxy_cache/9/78/03d76d56294b499e72ad580eace08789"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream exit: 0000000000000000
2015/01/29 13:11:27 [debug] 26659#0: *1953 finalize http upstream request: 0
2015/01/29 13:11:27 [debug] 26659#0: *1953 finalize http proxy request
2015/01/29 13:11:27 [debug] 26659#0: *1953 free rr peer 1 0
2015/01/29 13:11:27 [debug] 26659#0: *1953 SSL_shutdown: 1
2015/01/29 13:11:27 [debug] 26659#0: *1953 close http upstream connection: 14
2015/01/29 13:11:27 [debug] 26659#0: *1953 free: 0000000001817290
2015/01/29 13:11:27 [debug] 26659#0: *1953 free: 00000000016CF6E0
2015/01/29 13:11:27 [debug] 26659#0: *1953 free: 000000000175C400
2015/01/29 13:11:27 [debug] 26659#0: *1953 free: 00000000016DFF00, unused: 0
2015/01/29 13:11:27 [debug] 26659#0: *1953 event timer del: 14: 1422538287321
2015/01/29 13:11:27 [debug] 26659#0: *1953 reusable connection: 0
2015/01/29 13:11:27 [debug] 26659#0: *1953 http upstream temp fd: 20
2015/01/29 13:11:27 [debug] 26659#0: *1953 http output filter "/?"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http copy filter: "/?"
2015/01/29 13:11:27 [debug] 26659#0: *1953 image filter
2015/01/29 13:11:27 [debug] 26659#0: *1953 xslt filter body
2015/01/29 13:11:27 [debug] 26659#0: *1953 http postpone filter "/?" 00007FFF269130A0
2015/01/29 13:11:27 [debug] 26659#0: *1953 http pagespeed html rewrite body filter "/"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http pagespeed write filter "/"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http copy filter: -2 "/?"
2015/01/29 13:11:27 [debug] 26659#0: *1953 http finalize request: -2, "/?" a:1, c:1
2015/01/29 13:11:27 [alert] 26659#0: [ngx_pagespeed 1.9.32.3-4448] [0129/131127:FATAL:css_summarizer_base.cc(327)] Check failed: canceled_summaries_.empty().
nginx: worker process() [0x4fc049]
nginx: worker process() [0x4f9062]
nginx: worker process() [0x5f863d]
nginx: worker process() [0x972542]
nginx: worker process() [0x6f5cda]
nginx: worker process() [0x6f28d5]
nginx: worker process() [0x541cac]
nginx: worker process() [0x54218f]
nginx: worker process() [0x4eb165]
nginx: worker process() [0x4eb800]
nginx: worker process() [0x4f2372]
nginx: worker process() [0x6945c6]
nginx: worker process() [0x75e3e3]
nginx: worker process() [0x760cdb]
nginx: worker process() [0x6945c6]
nginx: worker process() [0x769b43]
nginx: worker process() [0x76c2e0]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x6b50) [0x7f2cc9403b50]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f2cc68587bd]

nginx: worker process() [0x4fc049]
nginx: worker process() [0x4b359d]
nginx: worker process() [0x4f9144]
nginx: worker process() [0x5f863d]
nginx: worker process() [0x972542]
nginx: worker process() [0x6f5cda]
nginx: worker process() [0x6f28d5]
nginx: worker process() [0x541cac]
nginx: worker process() [0x54218f]
nginx: worker process() [0x4eb165]
nginx: worker process() [0x4eb800]
nginx: worker process() [0x4f2372]
nginx: worker process() [0x6945c6]
nginx: worker process() [0x75e3e3]
nginx: worker process() [0x760cdb]
nginx: worker process() [0x6945c6]
nginx: worker process() [0x769b43]
nginx: worker process() [0x76c2e0]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x6b50) [0x7f2cc9403b50]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f2cc68587bd]
2015/01/29 13:11:27 [alert] 20655#0: worker process 26659 exited on signal 6 (core dumped)
bharadwaj6 commented 8 years ago

This issue comes up for me too! Any solutions/workarounds for this?

oschaaf commented 8 years ago

@bharadwaj6 This issue only occurs in debug builds, so one thing you could try is running a release build.

deweydb commented 8 years ago

I'm using the master branch and experiancing this issue. I reviewed the 6 commits between master and .11 and i don't see how any of those commits could impact this. I would like to stay on master because i need on of the recent commits because it fixes an issue we experienced. Is there any way to stay on master but not have this issue? 

nginx: worker process() [0x4f2e29] 
nginx: worker process() [0x4a7217] 
nginx: worker process() [0x4eff28] 
nginx: worker process() [0x5ef727] 
nginx: worker process() [0x971afc] 
nginx: worker process() [0x6ee014] 
nginx: worker process() [0x6eac0f] 
nginx: worker process() [0x538a7a] 
nginx: worker process() [0x539066] 
nginx: worker process() [0x4e260e] 
nginx: worker process() [0x4e9158] 
nginx: worker process() [0x68c478] 
nginx: worker process() [0x756703] 
nginx: worker process() [0x758ffb] 
nginx: worker process() [0x68c478] 
nginx: worker process() [0x761e5f] 
nginx: worker process() [0x7645f6] 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8182) [0x7f9027df9182] 
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f902643447d] 
2015/12/11 16:33:45 [alert] 6381#0: worker process 11319 exited on signal 6 
2015/12/11 16:34:43 [alert] 6384#0: [ngx_pagespeed 1.9.32.10-7423] [1211/163443:FATAL:css_summarizer_base.cc(327)] Check failed: canceled_summaries_.
empty().
oschaaf commented 8 years ago

@deweydb in a release build, this doesn't happen.

deweydb commented 8 years ago

Sorry if this is a dumb question, by release build do you mean using this source: https://github.com/pagespeed/ngx_pagespeed/archive/release-1.9.32.11-beta.zip ?? Or where do i get the release build from?

oschaaf commented 8 years ago

@deweydb leaving out --with-debug when you ./configure nginx will make ngx_pagespeed link against the release build.

deweydb commented 8 years ago

Thanks!

JourneyToSilius commented 8 years ago

I just updated to nginx 1.9.9 and compiled the beta version of ngx_pagespeed to test out the latest implementations, should I just use the stable release or there is a workaround for this ?

I have compiled without --with-debug and I am getting this issue too.

jeffkaufman commented 8 years ago

I can repro this very simply:

make nginx_debug_start
touch ~/ngx_pagespeed/debug-webp/ngx_pagespeed/test/tmp/
file-cache/cache.flush
http_proxy=localhost:8051 curl -sS issue-1215.example.com/mod_pagespeed_example/issue-1215/a.html
sleep 1
http_proxy=localhost:8051 curl -sS issue-1215.example.com/mod_pagespeed_example/issue-1215/a.html

This was with configuration:

server {
    listen @@SECONDARY_PORT@@;
    listen [::]:@@SECONDARY_PORT@@;
    server_name issue-1215.example.com;
    pagespeed FileCachePath "@@FILE_CACHE@@";

    pagespeed RewriteLevel OptimizeForBandwidth;
    pagespeed EnableFilters lazyload_images,convert_to_webp_lossless,combine_css,trim_urls,remove_comments,collapse_whitespace,prioritize_critical_css,insert_dns_prefetch,combine_javascript,defer_javascript;
    pagespeed CssInlineMaxBytes 10240;
  }

And with the files in issue-1215.zip

Still debugging.

(As you can see, I hit this when trying to repro https://github.com/pagespeed/mod_pagespeed/issues/1215 )

jeffkaufman commented 8 years ago

@morlovich is looking at this now as I build 1.10.33.1

oschaaf commented 8 years ago

Getting the pagespeed configuration more minimal, it seems there's an unwanted interaction between OptimizeForBandwidth and combine_css

        pagespeed RewriteLevel PassThrough;
        pagespeed EnableFilters combine_css;

Gives the following after a refresh or two: 

<link rel=stylesheet href=b.css+c.css+d.css+e.css+f.css+g.css.pagespeed.cc.L5ESabEI1o.css>
...

Adding this in configuration:

        # uncommenting the line below triggers the bug reliably for me.
        pagespeed RewriteLevel OptimizeForBandwidth;

Gives the following after a refresh or two:

<link rel=stylesheet href=b.css>
.....
JourneyToSilius commented 8 years ago

Is there a way I can help debugging ?

jmarantz commented 7 years ago

Although end-users shouldn't be seeing this with release builds, we should track it and fix it.

oschaaf commented 7 years ago

Created https://github.com/pagespeed/mod_pagespeed/pull/1377, proposing to remove the DCHECK and instead file an issue for the intended memory lifetime optimization I think the DCHECK was added for

oschaaf commented 7 years ago

Testing, I can actually no longer cause the DCHECK to fire, at least not with the setup described by @jeffkaufman in https://github.com/pagespeed/ngx_pagespeed/issues/891#issuecomment-164833952

gnif commented 7 years ago

I am seeing this fire still on a build from dotdeb, here are the configuration options.

nginx version: nginx/1.10.3
built with OpenSSL 1.0.2k  26 Jan 2017
TLS SNI support enabled
configure arguments: --add-module=/usr/src/builddir/debian/modules/naxsi/naxsi_src --with-cc-opt='-g -O2 -fstack-protector-strong -Wformat -Werror=format-security -D_FORTIFY_SOURCE=2' --with-ld-opt='-Wl,-z,relro -Wl,-z,now' --prefix=/usr/share/nginx --conf-path=/etc/nginx/nginx.conf --http-log-path=/var/log/nginx/access.log --error-log-path=/var/log/nginx/error.log --lock-path=/var/lock/nginx.lock --pid-path=/run/nginx.pid --modules-path=/usr/lib/nginx/modules --http-client-body-temp-path=/var/lib/nginx/body --http-fastcgi-temp-path=/var/lib/nginx/fastcgi --http-proxy-temp-path=/var/lib/nginx/proxy --http-scgi-temp-path=/var/lib/nginx/scgi --http-uwsgi-temp-path=/var/lib/nginx/uwsgi --with-debug --with-pcre-jit --with-ipv6 --with-http_ssl_module --with-http_stub_status_module --with-http_realip_module --with-http_auth_request_module --with-http_v2_module --with-http_dav_module --with-file-aio --with-threads --with-http_addition_module --with-http_flv_module --with-http_geoip_module=dynamic --with-http_gunzip_module --with-http_gzip_static_module --with-http_image_filter_module=dynamic --with-http_mp4_module --with-http_perl_module=dynamic --with-http_random_index_module --with-http_secure_link_module --with-http_sub_module --with-http_xslt_module=dynamic --with-mail=dynamic --with-mail_ssl_module --with-stream=dynamic --with-stream_ssl_module --add-module=/usr/src/builddir/debian/modules/headers-more-nginx-module --add-dynamic-module=/usr/src/builddir/debian/modules/nginx-auth-pam --add-module=/usr/src/builddir/debian/modules/nginx-cache-purge --add-module=/usr/src/builddir/debian/modules/nginx-dav-ext-module --add-dynamic-module=/usr/src/builddir/debian/modules/nginx-development-kit --add-module=/usr/src/builddir/debian/modules/nginx-echo --add-module=/usr/src/builddir/debian/modules/ngx-fancyindex --add-module=/usr/src/builddir/debian/modules/nginx-push-stream-module --add-dynamic-module=/usr/src/builddir/debian/modules/nginx-lua --add-module=/usr/src/builddir/debian/modules/nginx-upload-progress --add-module=/usr/src/builddir/debian/modules/nginx-upstream-fair --add-module=/usr/src/builddir/debian/modules/ngx_http_substitutions_filter_module --add-module=/usr/src/builddir/debian/modules/nginx-auth-ldap --add-module=/usr/src/builddir/debian/modules/ngx_pagespeed --add-module=/usr/src/builddir/debian/modules/nginx-x-rid-header --add-module=/usr/src/builddir/debian/modules/nginx-rtmp-module --with-ld-opt=-lossp-uuid

Here is the crash output

2017/05/30 13:20:42 [alert] 12354#12860: [ngx_pagespeed 1.11.33.2-0] [0530/132042:FATAL:css_summarizer_base.cc(306)] Check failed: canceled_summaries_.empty(). 
nginx: worker process() [0x5a2d33]
nginx: worker process() [0x59fdfa]
nginx: worker process() [0x6ba643]
nginx: worker process() [0xa1dd1e]
nginx: worker process() [0x7adb40]
nginx: worker process() [0x7aa528]
nginx: worker process() [0x5f180b]
nginx: worker process() [0x5f1df6]
nginx: worker process() [0x5920fc]
nginx: worker process() [0x59903e]
nginx: worker process() [0x74c280]
nginx: worker process() [0x82b45b]
nginx: worker process() [0x82dd53]
nginx: worker process() [0x74c280]
nginx: worker process() [0x836c85]
nginx: worker process() [0x839448]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8064) [0x7fd0e5562064]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7fd0e345062d]
jmarantz commented 7 years ago

I think this might be fixed in https://github.com/pagespeed/mod_pagespeed/commit/69a40de8840d8405bff76666c7c303f4fb94acf5 which is not in 1.11, but I think is in 1.12.

Also note that this is a DCHECK and should not be in production builds.