CHECK failure on DNS timeout

[melong007]

the bt info are as follow:
#0 base::debug::BreakDebugger () at third_party/chromium/src/base/debug/debugger_posix.cc:243
#1 0x00000000004b6370 in (anonymous namespace)::LogMessageHandler (severity=4,

file=0xa422b8 "/data/cache9/pagespeed/ngx_pagespeed-master/src/ngx_fetch.cc", line=208, message_start=38, 
str=...) at /data/cache9/pagespeed/ngx_pagespeed-master/src/log_message_handler.cc:87

#2 0x00000000004d83d5 in logging::LogMessage::~LogMessage (this=0x7ffff2f41a50, __in_chrg=)

at third_party/chromium/src/base/logging.cc:574

#3 0x00000000004b7b8f in net_instaweb::NgxFetch::CallbackDone (this=0x2b1590005f00, success=false)

at /data/cache9/pagespeed/ngx_pagespeed-master/src/ngx_fetch.cc:208

#4 0x00000000004b7fc7 in net_instaweb::NgxFetch::NgxFetchResolveDone (resolver_ctx=0x2b159006b0f0)

at /data/cache9/pagespeed/ngx_pagespeed-master/src/ngx_fetch.cc:289

#5 0x000000000042e182 in ngx_resolver_timeout_handler (ev=0x2b159004ef70) at src/core/ngx_resolver.c:2043
#6 0x0000000000434007 in ngx_event_expire_timers () at src/event/ngx_event_timer.c:149
#7 0x0000000000431df3 in ngx_process_events_and_timers (cycle=0xd1dc9b0) at src/event/ngx_event.c:265
#8 0x000000000043f0a1 in ngx_worker_process_cycle (cycle=0xd1dc9b0, data=0x6)

at src/os/unix/ngx_process_cycle.c:807

#9 0x000000000043ba13 in ngx_spawn_process (cycle=0xd1dc9b0, proc=0x43eef1 <ngx_worker_process_cycle>, data=0x6,

name=0xa354d3 "worker process", respawn=6) at src/os/unix/ngx_process.c:198

#10 0x000000000043eafb in ngx_reap_children (cycle=0xd1dc9b0) at src/os/unix/ngx_process_cycle.c:619
#11 0x000000000043d7af in ngx_master_process_cycle (cycle=0xd1dc9b0) at src/os/unix/ngx_process_cycle.c:180
#12 0x000000000040d916 in main (argc=1, argv=0x7ffff2f42248) at src/core/nginx.c:412

[melong007]

207 if (async_fetch_ == NULL) {
208 LOG(FATAL)
209 << "BUG: NgxFetch callback called more than once on same fetch"
210 << str_url_.c_str() << "(" << this << ").Please report this at"
211 << "https://groups.google.com/forum/#!forum/ngx-pagespeed-discuss";
212 return;

[melong007]

oh, the bug was generated by the command "UseNativeFetcher on";

[oschaaf]

@melong007
Can you post or email the contents of the lines around this crash in error.log?
Starting about 2 minutes before the crasher would be ideal.
It would be especially interesting to know it this message was emitted before crashing:
NgxFetch: ngx_resolve_name failed, as that would confirm a suspicion about where this
originates from.

[jeffkaufman]

@dinic

[melong007]

@oschaaf , I have send the nginx error.log file to your "we-amp.com email address";

[oschaaf]

@melong007 I received it - thanks!
@dinic I will forward the log so you can have a look as well

[oschaaf]

It seems to me that two timers get armed in NgxFetch::Init():
NgxFetch::timeout_event_ and resolver_ctx_->timeout
Next to NgxFetch::timeout_event_, shouldn't we also clear resolver_ctx_->timeout if it is still armed in NgxFetch::CallbackDone()?

@dinic Any thoughts?

[oschaaf]

I'm able to reproduce this when I add this to nginx.conf:

    pagespeed UseNativeFetcher on;
    pagespeed MapProxyDomain mpd.example.com/gstatic_images http://www.gstatic.com/;   
    # point the resolver to google.com:81
    # the firewall will drop tcp SYN packets, which  is useful 
    # here to simulate a timeout for the dns lookup
    resolver 173.194.65.106:81;
    resolver_timeout 5s; # make it happen a little sooner

Subsequently, requesting
/mod_pagespeed_example/proxy_external_resource.html?PageSpeed=on&PageSpeedFilters=rewrite_images
will trigger the fetch, the dns timeout, and the check failure for the second call to NgxFetch::CallbackDone()

[jeffkaufman]

@yaoweibin would you or @dinic have some time to look at how the native fetcher handles dns timeouts? @oschaaf has figured out how to reproduce this consistently with #625 (comment)

[jeffkaufman]

This is fixed in #655 right?

[oschaaf]

@jeffkaufman: "This is fixed in #655 right?"
Yes