1211001 - constant ASSERTION: nsITimer->SetDelay() called when the one-shot timer is not set up.

Status: RESOLVED FIXED

(Core :: Networking: WebSockets, defect)

Description

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

I have a long-running Firefox session in which I'm seeing pretty much constant flow of:

[Parent 21509] ###!!! ASSERTION: nsITimer->SetDelay() called when the one-shot timer is not set up.: 'Error', file /home/dbaron/builds/ssd/mozilla-central/mozilla/xpcom/threads/nsTimerImpl.cpp, line 379
#01: mozilla::net::WebSocketChannel::ProcessInput(unsigned char*, unsigned int) (/home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/protocol/websocket/WebSocketChannel.cpp:1489)
#02: mozilla::net::WebSocketChannel::OnInputStreamReady(nsIAsyncInputStream*) (/home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/protocol/websocket/WebSocketChannel.cpp:3716)
#03: nsInputStreamReadyEvent::Run() (/home/dbaron/builds/ssd/mozilla-central/mozilla/xpcom/io/nsStreamUtils.cpp:93)
#04: nsThread::ProcessNextEvent(bool, bool*) (/home/dbaron/builds/ssd/mozilla-central/mozilla/xpcom/threads/nsThread.cpp:930)
#05: NS_ProcessNextEvent(nsIThread*, bool) (/home/dbaron/builds/ssd/mozilla-central/mozilla/xpcom/glue/nsThreadUtils.cpp:277)
#06: nsSocketTransportService::Run() (/home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/base/nsSocketTransportService2.cpp:909)
#07: nsThread::ProcessNextEvent(bool, bool*) (/home/dbaron/builds/ssd/mozilla-central/mozilla/xpcom/threads/nsThread.cpp:930)
#08: NS_ProcessNextEvent(nsIThread*, bool) (/home/dbaron/builds/ssd/mozilla-central/mozilla/xpcom/glue/nsThreadUtils.cpp:277)
#09: mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) (/home/dbaron/builds/ssd/mozilla-central/mozilla/ipc/glue/MessagePump.cpp:355)
#10: MessageLoop::RunInternal() (/home/dbaron/builds/ssd/mozilla-central/mozilla/ipc/chromium/src/base/message_loop.cc:235)
#11: MessageLoop::Run() (/home/dbaron/builds/ssd/mozilla-central/mozilla/ipc/chromium/src/base/message_loop.cc:520)
#12: nsThread::ThreadFunc(void*) (/home/dbaron/builds/ssd/mozilla-central/mozilla/xpcom/threads/nsThread.cpp:381)
#13: _pt_root (/home/dbaron/builds/ssd/mozilla-central/mozilla/nsprpub/pr/src/pthreads/ptthread.c:215)
#14: start_thread (/build/buildd/glibc-2.21/nptl/pthread_create.c:333)
#15: __clone (/build/buildd/glibc-2.21/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:111)

Comment 1

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

The gdb backtrace is:

(gdb) bt 8
#0  0x00007ff8eafcbf03 in NS_DebugBreak(uint32_t, char const*, char const*, char const*, int32_t) (aSeverity=1, aStr=0x7ff8edec49fe "nsITimer->SetDelay() called when the one-shot timer is not set up.", aExpr=0x7ff8edea4a56 "Error", aFile=0x7ff8edec4997 "/home/dbaron/builds/ssd/mozilla-central/mozilla/xpcom/threads/nsTimerImpl.cpp", aLine=379)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/xpcom/base/nsDebugImpl.cpp:319
#1  0x00007ff8eb03cda2 in nsTimerImpl::SetDelay(unsigned int) (this=0x7ff8dae445f0, aDelay=<optimized out>)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/xpcom/threads/nsTimerImpl.cpp:378
#2  0x00007ff8eb257164 in mozilla::net::WebSocketChannel::ProcessInput(unsigned char*, unsigned int) (this=0x9000580)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/protocol/websocket/WebSocketChannel.h:181
#3  0x00007ff8eb257164 in mozilla::net::WebSocketChannel::ProcessInput(unsigned char*, unsigned int) (this=this@entry=0x9000580, buffer=buffer@entry=0x7ff8e2b62258 "\211", count=<optimized out>)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/protocol/websocket/WebSocketChannel.cpp:1485
#4  0x00007ff8eb258019 in mozilla::net::WebSocketChannel::OnInputStreamReady(nsIAsyncInputStream*) (this=0x9000580, aStream=<optimized out>)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/protocol/websocket/WebSocketChannel.cpp:3716
#5  0x00007ff8eb01c559 in nsInputStreamReadyEvent::Run() (this=0x7ff8d878cfd0)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/xpcom/io/nsStreamUtils.cpp:91
#6  0x00007ff8eb031449 in nsThread::ProcessNextEvent(bool, bool*) (this=0x1735780, aMayWait=<optimized out>, aResult=0x7ff8e2b62b77)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/xpcom/threads/nsThread.cpp:950
#7  0x00007ff8eb06035e in NS_ProcessNextEvent(nsIThread*, bool) (aThread=<optimized out>, aMayWait=<optimized out>)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/xpcom/glue/nsThreadUtils.cpp:277
#8  0x00007ff8eb0fd9f9 in nsSocketTransportService::Run() (this=0x1738c30)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/base/nsSocketTransportService2.cpp:907

and:

(gdb) f 2
#2  0x00007ff8eb257164 in ResetPingTimer (this=0x9000580)
    at /home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/protocol/websocket/WebSocketChannel.h:181
181	      mPingTimer->SetDelay(mPingInterval);
...
(gdb) p mURI.mRawPtr->mSpec.mData
$4 = (nsACString_internal::char_type *) 0x114e9ca8 "wss://live.github.com/_sockets/<removed lots of characters>"...
(gdb) p mOrigin
$5 = {
  <nsACString_internal> = {
    mData = 0x3e2dfa8 "https://github.com", 
    mLength = 18, 
    mFlags = 5
  }, <No data fields>}

Comment 2

[Michal Novotny [:michal]]

Attachment: fix

This can happen when pinging is disabled and ping is forced due to network change:

WebSocketChannel::OnNetworkChange -> mPingForced = 1
WebSocketChannel::Notify          -> mPingForced = 0, mPingOutstanding = 1
WebSocketChannel::ResetPingTimer  -> mPingOutstanding = 0
WebSocketChannel::Notify          -> no-op (mPingOutstanding == 0, mPingForced == 0, mPingInterval == 0)
WebSocketChannel::ResetPingTimer  -> asserts since previous Notify didn't initialize the timer


https://treeherder.mozilla.org/#/jobs?repo=try&revision=93e76692c3cb

Comment 3

[Patrick McManus [:mcmanus]]

heh - I didn't realize wss://live.github.com/_sockets/.. was a thing

Comment 4

[Pulsebot]

https://hg.mozilla.org/mozilla-central/rev/3c1f5c76e1ee

Comment 5

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/3c1f5c76e1ee