Closed Bug 1483561 Opened 6 years ago Closed 4 years ago

Intermittent devtools/client/webreplay/mochitest/browser_dbg_rr_stepping-03.js | Test timed out -

Categories

(Core Graveyard :: Web Replay, defect, P5)

defect

Tracking

(firefox-esr52 unaffected, firefox-esr60 unaffected, firefox61 unaffected, firefox62 unaffected, firefox63 fixed)

RESOLVED WORKSFORME
mozilla63
Tracking Status
firefox-esr52 --- unaffected
firefox-esr60 --- unaffected
firefox61 --- unaffected
firefox62 --- unaffected
firefox63 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: bhackett1024)

References

Details

(Keywords: crash, intermittent-failure)

Crash Data

Attachments

(1 file)

Filed by: cbrindusan [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=194089178&repo=autoland

https://queue.taskcluster.net/v1/task/fNi5EhmKRf--qG4PXa-Qhg/runs/0/artifacts/public/logs/live_backing.log

06:31:16     INFO - mozcrash Downloading symbols from: https://queue.taskcluster.net/v1/task/CFIuPLG4TSytEoLzUtyRTg/artifacts/public/build/target.crashreporter-symbols.zip
06:31:24     INFO - mozcrash Copy/paste: /Users/cltbld/tasks/task_1534338643/build/macosx64-minidump_stackwalk /var/folders/h_/pk3znxv51dlb80110bbfgsb000000w/T/tmp31nVtn.mozrunner/minidumps/7E09A690-C9F8-4E2B-9DBB-00ADAD7143B1.dmp /var/folders/h_/pk3znxv51dlb80110bbfgsb000000w/T/tmprS7cpZ
06:31:37     INFO - mozcrash Saved minidump as /Users/cltbld/tasks/task_1534338643/build/blobber_upload_dir/7E09A690-C9F8-4E2B-9DBB-00ADAD7143B1.dmp
06:31:37     INFO - mozcrash Saved app info as /Users/cltbld/tasks/task_1534338643/build/blobber_upload_dir/7E09A690-C9F8-4E2B-9DBB-00ADAD7143B1.extra
06:31:38     INFO - PROCESS-CRASH | Main app process exited normally | application crashed [@ mozilla::recordreplay::child::ChannelMessageHandler(mozilla::recordreplay::Message*)]
06:31:38     INFO - Crash dump filename: /var/folders/h_/pk3znxv51dlb80110bbfgsb000000w/T/tmp31nVtn.mozrunner/minidumps/7E09A690-C9F8-4E2B-9DBB-00ADAD7143B1.dmp
06:31:38     INFO - Operating system: Mac OS X
06:31:38     INFO -                   10.10.5 14F27
06:31:38     INFO - CPU: amd64
06:31:38     INFO -      family 6 model 69 stepping 1
06:31:38     INFO -      4 CPUs
06:31:38     INFO - 
06:31:38     INFO - GPU: UNKNOWN
06:31:38     INFO - 
06:31:38     INFO - Crash reason:  EXC_BAD_ACCESS / KERN_INVALID_ADDRESS
06:31:38     INFO - Crash address: 0x0
06:31:38     INFO - Process uptime: 540 seconds
06:31:38     INFO - 
06:31:38     INFO - Thread 75 (crashed)
06:31:38     INFO -  0  XUL!mozilla::recordreplay::child::ChannelMessageHandler(mozilla::recordreplay::Message*) [ChildIPC.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 98 + 0x0]
06:31:38     INFO -     rax = 0x00000001077049a7   rdx = 0x000000011eee8458
06:31:38     INFO -     rcx = 0x000000010c42d558   rbx = 0x0000000115e96110
06:31:38     INFO -     rsi = 0x0000000119b64e98   rdi = 0x000000011eee8458
06:31:38     INFO -     rbp = 0x0000000119b64e80   rsp = 0x0000000119b64df0
06:31:38     INFO -      r8 = 0x0000000800000001    r9 = 0x000000000000016e
06:31:38     INFO -     r10 = 0x0000000000000000   r11 = 0x0000000012aa1458
06:31:38     INFO -     r12 = 0x000000011eee8458   r13 = 0x0000000106230100
06:31:38     INFO -     r14 = 0x0000000119b64e98   r15 = 0x000000010c696ab0
06:31:38     INFO -     rip = 0x0000000106239497
06:31:38     INFO -     Found by: given as instruction pointer in context
06:31:38     INFO -  1  XUL!mozilla::recordreplay::Channel::ThreadMain(void*) [functional:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 1916 + 0x9]
06:31:38     INFO -     rbp = 0x0000000119b64eb0   rsp = 0x0000000119b64e90
06:31:38     INFO -     rip = 0x00000001062302a6
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO -  2  XUL!mozilla::recordreplay::Thread::ThreadMain(void*) [Thread.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 174 + 0x4]
06:31:38     INFO -     rbp = 0x0000000119b64ef0   rsp = 0x0000000119b64ec0
06:31:38     INFO -     rip = 0x000000010622d7e3
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO -  3  libsystem_pthread.dylib + 0x405a
06:31:38     INFO -     rbp = 0x0000000119b64f10   rsp = 0x0000000119b64f00
06:31:38     INFO -     rip = 0x00007fff8dd1f05a
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO -  4  libsystem_pthread.dylib + 0x3fd7
06:31:38     INFO -     rbp = 0x0000000119b64f50   rsp = 0x0000000119b64f20
06:31:38     INFO -     rip = 0x00007fff8dd1efd7
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO -  5  libsystem_pthread.dylib + 0x13ed
06:31:38     INFO -     rbp = 0x0000000119b64f78   rsp = 0x0000000119b64f60
06:31:38     INFO -     rip = 0x00007fff8dd1c3ed
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO -  6  XUL + 0x3814770
06:31:38     INFO -     rsp = 0x0000000119b65030   rip = 0x000000010622d770
06:31:38     INFO -     Found by: stack scanning
06:31:38     INFO - 
06:31:38     INFO - Thread 0
06:31:38     INFO -  0  0x10c6330d1
06:31:38     INFO -     rax = 0x0000000002000003   rdx = 0x0000000000000001
06:31:38     INFO -     rcx = 0x00007fff5d50dad8   rbx = 0x0000000000000006
06:31:38     INFO -     rsi = 0x00007fff5d50daf7   rdi = 0x0000000000000006
06:31:38     INFO -     rbp = 0x00007fff5d50db20   rsp = 0x00007fff5d50dad8
06:31:38     INFO -      r8 = 0x00007fff5d50da70    r9 = 0x00007fff5d50daa1
06:31:38     INFO -     r10 = 0x000000010c66f8e0   r11 = 0x0000000000000202
06:31:38     INFO -     r12 = 0x00007fff5d50daf7   r13 = 0x000000010c42d582
06:31:38     INFO -     r14 = 0x000000010c42d580   r15 = 0x000000010c662100
06:31:38     INFO -     rip = 0x000000010c6330d1
06:31:38     INFO -     Found by: given as instruction pointer in context
06:31:38     INFO -  1  XUL!mozilla::recordreplay::NewCheckpoint(bool) [ProcessRewind.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 142 + 0x5]
06:31:38     INFO -     rbp = 0x00007fff5d50db70   rsp = 0x00007fff5d50db30
06:31:38     INFO -     rip = 0x000000010622be1f
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO -  2  XUL!mozilla::recordreplay::child::NotifyPaintStart() [ChildIPC.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 441 + 0x7]
06:31:38     INFO -     rbp = 0x00007fff5d50db80   rsp = 0x00007fff5d50db80
06:31:38     INFO -     rip = 0x0000000106239bc4
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO -  3  XUL!mozilla::layers::ShadowLayerForwarder::EndTransaction(mozilla::gfx::IntRegionTyped<mozilla::gfx::UnknownUnits> const&, mozilla::layers::TransactionId, bool, unsigned int, bool, mozilla::TimeStamp const&, mozilla::TimeStamp const&, bool*) [ShadowLayers.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 775 + 0x5]
06:31:38     INFO -     rbp = 0x00007fff5d50df30   rsp = 0x00007fff5d50db90
06:31:38     INFO -     rip = 0x00000001037bd685
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO -  4  XUL!mozilla::layers::ClientLayerManager::ForwardTransaction(bool) [ClientLayerManager.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 741 + 0xd]
06:31:38     INFO -     rbp = 0x00007fff5d50dfb0   rsp = 0x00007fff5d50df40
06:31:38     INFO -     rip = 0x0000000103738d56
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO -  5  XUL!mozilla::layers::ClientLayerManager::EndTransaction(void (*)(mozilla::layers::PaintedLayer*, gfxContext*, mozilla::gfx::IntRegionTyped<mozilla::gfx::UnknownUnits> const&, mozilla::gfx::IntRegionTyped<mozilla::gfx::UnknownUnits> const&, mozilla::layers::DrawRegionClip, mozilla::gfx::IntRegionTyped<mozilla::gfx::UnknownUnits> const&, void*), void*, mozilla::layers::LayerManager::EndTransactionFlags) [ClientLayerManager.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 399 + 0x8]
06:31:38     INFO -     rbp = 0x00007fff5d50dff0   rsp = 0x00007fff5d50dfc0
06:31:38     INFO -     rip = 0x0000000103738b3f
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO -  6  XUL!nsDisplayList::PaintRoot(nsDisplayListBuilder*, gfxContext*, unsigned int) [nsDisplayList.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 2759 + 0x12]
06:31:38     INFO -     rbp = 0x00007fff5d50e120   rsp = 0x00007fff5d50e000
06:31:38     INFO -     rip = 0x00000001053a6787
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO -  7  XUL!nsLayoutUtils::PaintFrame(gfxContext*, nsIFrame*, nsRegion const&, unsigned int, nsDisplayListBuilderMode, nsLayoutUtils::PaintFrameFlags) [nsLayoutUtils.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 3842 + 0x14]
06:31:38     INFO -     rbp = 0x00007fff5d510ac0   rsp = 0x00007fff5d50e130
06:31:38     INFO -     rip = 0x000000010511edf8
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO -  8  XUL!mozilla::PresShell::Paint(nsView*, nsRegion const&, unsigned int) [PresShell.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 6349 + 0x17]
06:31:38     INFO -     rbp = 0x00007fff5d510c40   rsp = 0x00007fff5d510ad0
06:31:38     INFO -     rip = 0x00000001050cd8f0
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO -  9  XUL!nsViewManager::ProcessPendingUpdatesPaint(nsIWidget*) [nsViewManager.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 480 + 0xa]
06:31:38     INFO -     rbp = 0x00007fff5d510c90   rsp = 0x00007fff5d510c50
06:31:38     INFO -     rip = 0x0000000104e9abd2
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO - 10  XUL!nsViewManager::ProcessPendingUpdatesForView(nsView*, bool) [nsViewManager.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 412 + 0x8]
06:31:38     INFO -     rbp = 0x00007fff5d510d00   rsp = 0x00007fff5d510ca0
06:31:38     INFO -     rip = 0x0000000104e9a745
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO - 11  XUL!nsViewManager::ProcessPendingUpdates() [nsViewManager.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 1102 + 0xd]
06:31:38     INFO -     rbp = 0x00007fff5d510d20   rsp = 0x00007fff5d510d10
06:31:38     INFO -     rip = 0x0000000104e9b988
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO - 12  XUL!nsRefreshDriver::Tick(mozilla::TimeStamp) [nsRefreshDriver.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 2042 + 0x5]
06:31:38     INFO -     rbp = 0x00007fff5d510fd0   rsp = 0x00007fff5d510d30
06:31:38     INFO -     rip = 0x00000001050a5bdc
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO - 13  XUL!mozilla::RefreshDriverTimer::TickRefreshDrivers(mozilla::TimeStamp, nsTArray<RefPtr<nsRefreshDriver> >&) [nsRefreshDriver.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 324 + 0x9]
06:31:38     INFO -     rbp = 0x00007fff5d511020   rsp = 0x00007fff5d510fe0
06:31:38     INFO -     rip = 0x00000001050a9783
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO - 14  XUL!mozilla::RefreshDriverTimer::Tick(mozilla::TimeStamp) [nsRefreshDriver.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 317 + 0xb]
06:31:38     INFO -     rbp = 0x00007fff5d511040   rsp = 0x00007fff5d511030
06:31:38     INFO -     rip = 0x00000001050a95f2
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO - 15  XUL!mozilla::VsyncRefreshDriverTimer::RefreshDriverVsyncObserver::TickRefreshDriver(mozilla::TimeStamp) [nsRefreshDriver.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 755 + 0x8]
06:31:38     INFO -     rbp = 0x00007fff5d511070   rsp = 0x00007fff5d511050
06:31:38     INFO -     rip = 0x00000001050aa4a3
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO - 16  XUL!mozilla::VsyncRefreshDriverTimer::RefreshDriverVsyncObserver::NotifyVsync(mozilla::TimeStamp) [nsRefreshDriver.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 571 + 0xb]
06:31:38     INFO -     rbp = 0x00007fff5d5110b0   rsp = 0x00007fff5d511080
06:31:38     INFO -     rip = 0x00000001050aa348
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO - 17  XUL!mozilla::recordreplay::child::NotifyVsyncObserver() [ChildIPC.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 389 + 0x9]
06:31:38     INFO -     rbp = 0x00007fff5d5110d0   rsp = 0x00007fff5d5110c0
06:31:38     INFO -     rip = 0x00000001062399ac
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO - 18  XUL!nsThread::ProcessNextEvent(bool, bool*) [nsThread.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 1118 + 0x5]
06:31:38     INFO -     rbp = 0x00007fff5d511610   rsp = 0x00007fff5d5110e0
06:31:38     INFO -     rip = 0x0000000102ad96ae
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO - 19  XUL!NS_ProcessNextEvent(nsIThread*, bool) [nsThreadUtils.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 519 + 0xd]
06:31:38     INFO -     rbp = 0x00007fff5d511630   rsp = 0x00007fff5d511620
06:31:38     INFO -     rip = 0x0000000102adc567
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO - 20  XUL!mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) [MessagePump.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 97 + 0xa]
06:31:38     INFO -     rbp = 0x00007fff5d511680   rsp = 0x00007fff5d511640
06:31:38     INFO -     rip = 0x0000000102fcd8a9
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO - 21  XUL!MessageLoop::Run() [message_loop.cc:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 325 + 0x8]
06:31:38     INFO -     rbp = 0x00007fff5d5116b0   rsp = 0x00007fff5d511690
06:31:38     INFO -     rip = 0x0000000102f9262b
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO - 22  XUL!nsBaseAppShell::Run() [nsBaseAppShell.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 158 + 0x8]
06:31:38     INFO -     rbp = 0x00007fff5d5116d0   rsp = 0x00007fff5d5116c0
06:31:38     INFO -     rip = 0x0000000104ec6179
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO - 23  XUL!nsAppShell::Run() [nsAppShell.mm:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 737 + 0x8]
06:31:38     INFO -     rbp = 0x00007fff5d511700   rsp = 0x00007fff5d5116e0
06:31:38     INFO -     rip = 0x0000000104f2e03f
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO - 24  XUL!XRE_RunAppShell() [nsEmbedFunctions.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 937 + 0x6]
06:31:38     INFO -     rbp = 0x00007fff5d511740   rsp = 0x00007fff5d511710
06:31:38     INFO -     rip = 0x000000010625c215
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO - 25  XUL!MessageLoop::Run() [message_loop.cc:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 325 + 0x8]
06:31:38     INFO -     rbp = 0x00007fff5d511770   rsp = 0x00007fff5d511750
06:31:38     INFO -     rip = 0x0000000102f9262b
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO - 26  XUL!XRE_InitChildProcess(int, char**, XREChildData const*) [nsEmbedFunctions.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 763 + 0x5]
06:31:38     INFO -     rbp = 0x00007fff5d511a40   rsp = 0x00007fff5d511780
06:31:38     INFO -     rip = 0x000000010625bfb2
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO - 27  plugin-container!main [plugin-container.cpp:581fb40d63fb10e1ea8b29ca2b52deb12b914bc3 : 50 + 0x13]
06:31:38     INFO -     rbp = 0x00007fff5d511a80   rsp = 0x00007fff5d511a50
06:31:38     INFO -     rip = 0x00000001026edf39
06:31:38     INFO -     Found by: previous frame's frame pointer
06:31:38     INFO - 28  libdyld.dylib + 0x35c9
06:31:38     INFO -     rbp = 0x00007fff5d511a90   rsp = 0x00007fff5d511a90
06:31:38     INFO -     rip = 0x00007fff8f7155c9
06:31:38     INFO -     Found by: previous frame's frame pointer
Blocks: 1465491
Component: Debugger → Web Replay
Product: DevTools → Core
Attached patch patchSplinter Review
This crash is happening because a replaying process hanged and the middleman told it to crash and generate a minidump with stacks.  All that is working, and from the stacks it looks like the main thread is waiting for all other threads to enter the right idle state so it can save or restore a checkpoint, but one of those threads is blocked inside the system's pthread_mutex_lock.

What I think is happening is that immediately after thread A acquires a lock, it notifies the next owner in the recording, thread B, that it is now able to attempt to acquire it.  Thread B blocks inside the system's pthread_mutex_lock, but thread A enters the idle state before releasing the lock, and we deadlock.

The attached patch should fix this by not doing the above notification until thread A is about to release the lock --- no idles should be able to happen between the call to Lock::Exit and the actual release of the system lock.

This also rolls in another fix to allow the pthread_mutex_lock redirection to return an error code --- some threads intentionally trigger an EDEADLK in order to test that they already own the lock.
Assignee: nobody → bhackett1024
Attachment #9002883 - Flags: review?(nfroyd)
Summary: Intermittent PROCESS-CRASH | Main app process exited normally | application crashed [@ mozilla::recordreplay::child::ChannelMessageHandler(mozilla::recordreplay::Message*)] → Intermittent devtools/client/debugger/new/test/mochitest/browser_dbg_rr_stepping-03.js | Test timed out -
Attachment #9002883 - Flags: review?(nfroyd) → review+
Pushed by bhackett@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/85e1ddee9e8f
Notify the next lock owner only when the last owner is about to release it, r=froydnj.
https://hg.mozilla.org/mozilla-central/rev/85e1ddee9e8f
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla63
Fail reappeared on autoland

Log link: https://treeherder.mozilla.org/logviewer.html#?job_id=212042705&repo=autoland&lineNumber=28448
Status: RESOLVED → REOPENED
Resolution: FIXED → ---

Moving these bugs (intermittent test failures with crashes) out of P5.

Priority: P5 → --
Priority: -- → P5
Summary: Intermittent devtools/client/debugger/new/test/mochitest/browser_dbg_rr_stepping-03.js | Test timed out - → Intermittent devtools/client/webreplay/mochitest/browser_dbg_rr_stepping-03.js | Test timed out -
Status: REOPENED → RESOLVED
Closed: 6 years ago4 years ago
Resolution: --- → WORKSFORME
Product: Core → Core Graveyard
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: