1091297 - Assertion failure: now >= requestTime (bogus request time), at netwerk/protocol/http/nsHttpResponseHead.cpp:391

Status: RESOLVED FIXED

(Core :: Networking: HTTP, defect)

Description

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

I just hit this assertion, which seems bogus, given that it's not using monotonic clock times (the times match the output of "date +%s").  I had just unsuspended my laptop, so it seems believable that NTP was adjusting the clock right around when I hit it.

nsDocShell(0x80643420)::LoadURI(http://example.com/)
Assertion failure: now >= requestTime (bogus request time), at /home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/protocol/http/nsHttpResponseHead.cpp:391


(gdb) bt
#0  0x00007fd8d14cc9bd in nanosleep () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007fd8d14cc854 in __sleep (seconds=0)
    at ../sysdeps/unix/sysv/linux/sleep.c:137
#2  0x00007fd8cca9b881 in ah_crap_handler (signum=11)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/toolkit/xre/nsSigHandlers.cpp:92
#3  0x00007fd8cca90011 in nsProfileLock::FatalSignalHandler (signo=11, 
    info=0x7fff02a3fbf0, context=0x7fff02a3fac0)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/profile/dirserviceprovider/nsProfileLock.cpp:190
#4  0x00007fd8ccfc077f in AsmJSFaultHandler (signum=11, info=0x7fff02a3fbf0, 
    context=0x7fff02a3fac0)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/js/src/asmjs/AsmJSSignalHandlers.cpp:978
#5  <signal handler called>
#6  0x00007fd8cafb09e0 in mozilla::net::nsHttpResponseHead::ComputeCurrentAge (
    this=0x7fd8ac6a7150, now=now@entry=1414626385, 
    requestTime=requestTime@entry=1414626386, 
    result=result@entry=0x7fff02a400cc)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/protocol/http/nsHttpResponseHead.cpp:391
#7  0x00007fd8caf85381 in mozilla::net::nsHttpChannel::UpdateExpirationTime (
    this=this@entry=0xb9a03cc0)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/protocol/http/nsHttpChannel.cpp:3496
#8  0x00007fd8caf8f371 in mozilla::net::nsHttpChannel::InitCacheEntry (
    this=0xb9a03cc0)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/protocol/http/nsHttpChannel.cpp:3943
#9  0x00007fd8cafa28ea in mozilla::net::nsHttpChannel::ContinueProcessNormal (
    this=0xb9a03cc0, rv=NS_OK)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/protocol/http/nsHttpChannel.cpp:1643
#10 0x00007fd8cafa2ac8 in mozilla::net::nsHttpChannel::ProcessNormal (
    this=this@entry=0xb9a03cc0)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/protocol/http/nsHttpChannel.cpp:1610
#11 0x00007fd8cafa3978 in mozilla::net::nsHttpChannel::ProcessResponse (
    this=this@entry=0xb9a03cc0)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/protocol/http/nsHttpChannel.cpp:1520
#12 0x00007fd8cafa3cb6 in mozilla::net::nsHttpChannel::OnStartRequest (
    this=0xb9a03cc0, request=0xa14ea8b0, ctxt=<optimized out>)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/protocol/http/nsHttpChannel.cpp:5224
#13 0x00007fd8cae523d8 in nsInputStreamPump::OnStateStart (
---Type <return> to continue, or q <return> to quit---
    this=this@entry=0xa14ea8b0)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/base/src/nsInputStreamPump.cpp:531
#14 0x00007fd8cae5afc2 in nsInputStreamPump::OnInputStreamReady (
    this=0xa14ea8b0, stream=<optimized out>)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/base/src/nsInputStreamPump.cpp:433
#15 0x00007fd8cadc5e11 in nsInputStreamReadyEvent::Run (this=0xbed61370)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/xpcom/io/nsStreamUtils.cpp:88
#16 0x00007fd8cadd71ff in nsThread::ProcessNextEvent (this=0x247e2f0, 
    aMayWait=<optimized out>, aResult=0x7fff02a4043f)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/xpcom/threads/nsThread.cpp:830
#17 0x00007fd8cadf7899 in NS_ProcessNextEvent (aThread=<optimized out>, 
    aMayWait=<optimized out>)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/xpcom/glue/nsThreadUtils.cpp:265
#18 0x00007fd8cb086b77 in mozilla::ipc::MessagePump::Run (this=0x247c290, 
    aDelegate=0x247d920)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/ipc/glue/MessagePump.cpp:140
#19 0x00007fd8cb06a483 in MessageLoop::RunInternal (this=this@entry=0x247d920)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/ipc/chromium/src/base/message_loop.cc:233
#20 0x00007fd8cb06a4b4 in RunHandler (this=0x247d920)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/ipc/chromium/src/base/message_loop.cc:226
#21 MessageLoop::Run (this=0x247d920)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/ipc/chromium/src/base/message_loop.cc:200
#22 0x00007fd8cc02e899 in nsBaseAppShell::Run (this=0x282a9e0)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/widget/nsBaseAppShell.cpp:164
#23 0x00007fd8cca53c20 in nsAppStartup::Run (this=0x2827a80)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/toolkit/components/startup/nsAppStartup.cpp:280
#24 0x00007fd8cca990d2 in XREMain::XRE_mainRun (this=this@entry=0x7fff02a40768)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/toolkit/xre/nsAppRunner.cpp:4093
#25 0x00007fd8cca99483 in XREMain::XRE_main (this=this@entry=0x7fff02a40768, 
    argc=argc@entry=5, argv=argv@entry=0x7fff02a41c88, 
    aAppData=aAppData@entry=0x7fff02a40978)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/toolkit/xre/nsAppRunner.cpp:4169
#26 0x00007fd8cca996d1 in XRE_main (argc=5, argv=0x7fff02a41c88, 
---Type <return> to continue, or q <return> to quit---
    aAppData=0x7fff02a40978, aFlags=<optimized out>)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/toolkit/xre/nsAppRunner.cpp:4385
#27 0x0000000000403884 in do_main (argc=argc@entry=5, 
    argv=argv@entry=0x7fff02a41c88, xreDirectory=0x237e010)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/browser/app/nsBrowserApp.cpp:287
#28 0x00000000004031d1 in main (argc=5, argv=0x7fff02a41c88)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/browser/app/nsBrowserApp.cpp:656
(gdb) f 6
#6  0x00007fd8cafb09e0 in mozilla::net::nsHttpResponseHead::ComputeCurrentAge (
    this=0x7fd8ac6a7150, now=now@entry=1414626385, 
    requestTime=requestTime@entry=1414626386, 
    result=result@entry=0x7fff02a400cc)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/protocol/http/nsHttpResponseHead.cpp:391
391         MOZ_ASSERT(now >= requestTime, "bogus request time");
(gdb) p now
$1 = 1414626385
(gdb) p requestTime
$2 = 1414626386
(gdb) p now - requestTime
$3 = 4294967295
(gdb) p requestTime - now
$4 = 1

Comment 1

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

https://hg.mozilla.org/mozilla-central/rev/7400723d23bc made this a fatal assertion, when it previously wasn't.

Comment 2

[Patrick McManus [:mcmanus]]

Attachment: http age calculation wrongly assumed monotonic time

Comment 3

[Patrick McManus [:mcmanus]]

https://tbpl.mozilla.org/?tree=Try&rev=56844373ec31

Comment 4

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/7e3219a7986a

Comment 5

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/7e3219a7986a