Closed Bug 1597282 Opened 4 years ago Closed 4 years ago

Intermittent org.mozilla.geckoview.test.ZZAccessibilityTest#testAccessibilityFocus | application crashed [@ mozilla::Logger::~Logger()]

Categories

(Core :: IPC, defect, P2)

defect

Tracking

()

RESOLVED FIXED
mozilla73
Tracking Status
firefox-esr68 --- unaffected
firefox71 --- unaffected
firefox72 --- unaffected
firefox73 --- fixed

People

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

References

Details

(Keywords: crash, intermittent-failure)

Attachments

(1 file)

Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=276720168&repo=try
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/D3C14RL8SCyK2lStvao-ag/runs/0/artifacts/public/logs/live_backing.log


[task 2019-11-18T10:58:13.151Z] 10:58:13 INFO - TEST-START | org.mozilla.geckoview.test.ZZAccessibilityTest.testAccessibilityFocus
[task 2019-11-18T10:58:16.556Z] 10:58:16 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_RESULT: shortMsg=Process crashed.
[task 2019-11-18T10:58:16.556Z] 10:58:16 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_CODE: 0
[task 2019-11-18T10:58:16.657Z] 10:58:16 INFO - Passed: 464
[task 2019-11-18T10:58:16.657Z] 10:58:16 INFO - Failed: 0
[task 2019-11-18T10:58:16.657Z] 10:58:16 INFO - Todo: 71
[task 2019-11-18T10:58:16.657Z] 10:58:16 INFO - SUITE-END | took 341s
[task 2019-11-18T10:58:17.395Z] 10:58:17 INFO - mozcrash Copy/paste: /builds/worker/workspace/build/linux64-minidump_stackwalk /tmp/tmpWrfroj/625cc98a-de83-68e1-6d09-6c6322bbf067.dmp /builds/worker/workspace/build/symbols
[task 2019-11-18T10:58:22.132Z] 10:58:22 INFO - mozcrash Saved minidump as /builds/worker/workspace/build/blobber_upload_dir/625cc98a-de83-68e1-6d09-6c6322bbf067.dmp
[task 2019-11-18T10:58:22.132Z] 10:58:22 INFO - mozcrash Saved app info as /builds/worker/workspace/build/blobber_upload_dir/625cc98a-de83-68e1-6d09-6c6322bbf067.extra
[task 2019-11-18T10:58:22.139Z] 10:58:22 WARNING - PROCESS-CRASH | org.mozilla.geckoview.test.ZZAccessibilityTest.testAccessibilityFocus | application crashed [@ mozilla::Logger::~Logger()]
[task 2019-11-18T10:58:22.140Z] 10:58:22 INFO - Crash dump filename: /tmp/tmpWrfroj/625cc98a-de83-68e1-6d09-6c6322bbf067.dmp
[task 2019-11-18T10:58:22.140Z] 10:58:22 INFO - Operating system: Android
[task 2019-11-18T10:58:22.140Z] 10:58:22 INFO - 0.0.0 Linux 3.10.0+ #260 SMP PREEMPT Fri May 19 12:48:14 PDT 2017 x86_64
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - CPU: amd64
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - family 6 model 6 stepping 3
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - 4 CPUs
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - GPU: UNKNOWN
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - Crash reason: SIGSEGV /SEGV_MAPERR
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - Crash address: 0x0
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - Process uptime: not available
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - Thread 15 (crashed)
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - 0 libmozglue.so!mozalloc_abort [mozalloc_abort.cpp:bf9d4014a01474bd7d1b0a314e7b4ae767b54c16 : 33 + 0x16]
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - rax = 0x000076b0c520f3c8 rdx = 0x0000000000000004
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - rcx = 0x000076b0c54b7810 rbx = 0x000076b0d75737e0
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - rsi = 0x000076b0d75730b0 rdi = 0x000000000000001b
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - rbp = 0x000076b0d7573770 rsp = 0x000076b0d7573760
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - r8 = 0x0000000000000000 r9 = 0x000076b0e3a59090
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - r10 = 0x0000000000000022 r11 = 0x0000000000000246
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - r12 = 0x000076b0d75737c0 r13 = 0x0000000000000000
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - r14 = 0x000076b0d75737e0 r15 = 0x000076b0d75739e8
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - rip = 0x000076b0c5137e51
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - Found by: given as instruction pointer in context
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - 1 libxul.so!Abort(char const*) [nsDebugImpl.cpp:bf9d4014a01474bd7d1b0a314e7b4ae767b54c16 : 442 + 0x8]
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - rbp = 0x000076b0d7573790 rsp = 0x000076b0d7573780
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - rip = 0x000076b0bc491907
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - Found by: previous frame's frame pointer
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - 2 libxul.so!NS_DebugBreak [nsTSubstring.h:bf9d4014a01474bd7d1b0a314e7b4ae767b54c16 : 0 + 0x19]
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - rbp = 0x000076b0d7573c10 rsp = 0x000076b0d75737a0
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - rip = 0x000076b0bc4917a5
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - Found by: previous frame's frame pointer
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - 3 libxul.so!mozilla::Logger::~Logger() [logging.cc:bf9d4014a01474bd7d1b0a314e7b4ae767b54c16 : 48 + 0x13]
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - rbp = 0x000076b0d7573c30 rsp = 0x000076b0d7573c20
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - rip = 0x000076b0bc9f0f3b
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - Found by: previous frame's frame pointer
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - 4 libxul.so!IDMap<nsCOMPtr<nsIEventTarget> >::AddWithID(nsCOMPtr<nsIEventTarget> const&, int) [id_map.h:bf9d4014a01474bd7d1b0a314e7b4ae767b54c16 : 53 + 0x36]
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - rbp = 0x000076b0d7573c90 rsp = 0x000076b0d7573c40
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - rip = 0x000076b0bca409df
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - Found by: previous frame's frame pointer
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - 5 libxul.so!mozilla::ipc::IToplevelProtocol::GetMessageEventTarget(IPC::Message const&) [ProtocolUtils.cpp:bf9d4014a01474bd7d1b0a314e7b4ae767b54c16 : 836 + 0xf]
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - rbp = 0x000076b0d7573d40 rsp = 0x000076b0d7573ca0
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - rip = 0x000076b0bca3ac72
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - Found by: previous frame's frame pointer
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - 6 libxul.so!mozilla::ipc::MessageChannel::MessageTask::Post() [MessageChannel.cpp:bf9d4014a01474bd7d1b0a314e7b4ae767b54c16 : 2038 + 0x18]
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - rbp = 0x000076b0d7573d90 rsp = 0x000076b0d7573d50
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - rip = 0x000076b0bca37fd6
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - Found by: previous frame's frame pointer
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - 7 libxul.so!mozilla::ipc::MessageChannel::RepostAllMessages() [MessageChannel.cpp:bf9d4014a01474bd7d1b0a314e7b4ae767b54c16 : 2889 + 0x11]
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - rbp = 0x000076b0d7573e00 rsp = 0x000076b0d7573da0
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - rip = 0x000076b0bca3b6a6
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - Found by: previous frame's frame pointer
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - 8 libxul.so!mozilla::ipc::MessageChannel::OnMessageReceivedFromLink(IPC::Message&&) [MessageChannel.cpp:bf9d4014a01474bd7d1b0a314e7b4ae767b54c16 : 1239 + 0x8]
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - rbp = 0x000076b0d7573e50 rsp = 0x000076b0d7573e10
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - rip = 0x000076b0bca378b5
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - Found by: previous frame's frame pointer
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - 9 libxul.so!mozilla::ipc::ProcessLink::OnMessageReceived(IPC::Message&&) [MessageLink.cpp:bf9d4014a01474bd7d1b0a314e7b4ae767b54c16 : 252 + 0xc]
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - rbp = 0x000076b0d7573e80 rsp = 0x000076b0d7573e60
[task 2019-11-18T10:58:22.144Z] 10:58:22 INFO - rip = 0x000076b0bca3cfa2
[task 2019-11-18T10:58:22.145Z] 10:58:22 INFO - Found by: previous frame's frame pointer
[task 2019-11-18T10:58:22.145Z] 10:58:22 INFO - 10 libxul.so!IPC::Channel::ChannelImpl::ProcessIncomingMessages() [ipc_channel_posix.cc:bf9d4014a01474bd7d1b0a314e7b4ae767b54c16 : 583 + 0x10]
[task 2019-11-18T10:58:22.145Z] 10:58:22 INFO - rbp = 0x000076b0d7573fb0 rsp = 0x000076b0d7573e90
[task 2019-11-18T10:58:22.145Z] 10:58:22 INFO - rip = 0x000076b0bc9ffff8
[task 2019-11-18T10:58:22.145Z] 10:58:22 INFO - Found by: previous frame's frame pointer
[task 2019-11-18T10:58:22.145Z] 10:58:22 INFO - 11 libxul.so!IPC::Channel::ChannelImpl::OnFileCanReadWithoutBlocking(int) [ipc_channel_posix.cc:bf9d4014a01474bd7d1b0a314e7b4ae767b54c16 : 828 + 0x8]
[task 2019-11-18T10:58:22.145Z] 10:58:22 INFO - rbp = 0x000076b0d7573fd0 rsp = 0x000076b0d7573fc0
[task 2019-11-18T10:58:22.145Z] 10:58:22 INFO - rip = 0x000076b0bca00a13
[task 2019-11-18T10:58:22.146Z] 10:58:22 INFO - Found by: previous frame's frame pointer
[task 2019-11-18T10:58:22.146Z] 10:58:22 INFO - 12 libxul.so!event_process_active_single_queue [event.c:bf9d4014a01474bd7d1b0a314e7b4ae767b54c16 : 1639 + 0xea]
[task 2019-11-18T10:58:22.146Z] 10:58:22 INFO - rbp = 0x000076b0d7574070 rsp = 0x000076b0d7573fe0
[task 2019-11-18T10:58:22.146Z] 10:58:22 INFO - rip = 0x000076b0bca08f96
[task 2019-11-18T10:58:22.146Z] 10:58:22 INFO - Found by: previous frame's frame pointer
[task 2019-11-18T10:58:22.146Z] 10:58:22 INFO - 13 libxul.so!event_base_loop [event.c:bf9d4014a01474bd7d1b0a314e7b4ae767b54c16 : 1961 + 0xc5]
[task 2019-11-18T10:58:22.146Z] 10:58:22 INFO - rbp = 0x000076b0d7574100 rsp = 0x000076b0d7574080
[task 2019-11-18T10:58:22.146Z] 10:58:22 INFO - rip = 0x000076b0bca069af
[task 2019-11-18T10:58:22.146Z] 10:58:22 INFO - Found by: previous frame's frame pointer
[task 2019-11-18T10:58:22.147Z] 10:58:22 INFO - 14 libxul.so!base::MessagePumpLibevent::Run(base::MessagePump::Delegate*) [message_pump_libevent.cc:bf9d4014a01474bd7d1b0a314e7b4ae767b54c16 : 0 + 0xc]
[task 2019-11-18T10:58:22.147Z] 10:58:22 INFO - rbp = 0x000076b0d7574170 rsp = 0x000076b0d7574110
[task 2019-11-18T10:58:22.147Z] 10:58:22 INFO - rip = 0x000076b0bc9f3d7b
[task 2019-11-18T10:58:22.147Z] 10:58:22 INFO - Found by: previous frame's frame pointer
[task 2019-11-18T10:58:22.147Z] 10:58:22 INFO - 15 libxul.so!MessageLoop::RunInternal() [message_loop.cc:bf9d4014a01474bd7d1b0a314e7b4ae767b54c16 : 315 + 0x17]
[task 2019-11-18T10:58:22.147Z] 10:58:22 INFO - rbp = 0x000076b0d75741b0 rsp = 0x000076b0d7574180
[task 2019-11-18T10:58:22.147Z] 10:58:22 INFO - rip = 0x000076b0bc9f20e2
[task 2019-11-18T10:58:22.147Z] 10:58:22 INFO - Found by: previous frame's frame pointer
[task 2019-11-18T10:58:22.147Z] 10:58:22 INFO - 16 libxul.so!MessageLoop::Run() [message_loop.cc:bf9d4014a01474bd7d1b0a314e7b4ae767b54c16 : 290 + 0x8]
[task 2019-11-18T10:58:22.148Z] 10:58:22 INFO - rbp = 0x000076b0d75741f0 rsp = 0x000076b0d75741c0
[task 2019-11-18T10:58:22.148Z] 10:58:22 INFO - rip = 0x000076b0bc9f204b
[task 2019-11-18T10:58:22.148Z] 10:58:22 INFO - Found by: previous frame's frame pointer
[task 2019-11-18T10:58:22.148Z] 10:58:22 INFO - 17 libxul.so!base::Thread::ThreadMain() [thread.cc:bf9d4014a01474bd7d1b0a314e7b4ae767b54c16 : 192 + 0x8]
[task 2019-11-18T10:58:22.148Z] 10:58:22 INFO - rbp = 0x000076b0d75743d0 rsp = 0x000076b0d7574200
[task 2019-11-18T10:58:22.148Z] 10:58:22 INFO - rip = 0x000076b0bc9fd673
[task 2019-11-18T10:58:22.148Z] 10:58:22 INFO - Found by: previous frame's frame pointer
[task 2019-11-18T10:58:22.148Z] 10:58:22 INFO - 18 libxul.so!ThreadFunc(void*) [platform_thread_posix.cc:bf9d4014a01474bd7d1b0a314e7b4ae767b54c16 : 40 + 0x6]
[task 2019-11-18T10:58:22.148Z] 10:58:22 INFO - rbp = 0x000076b0d75743e0 rsp = 0x000076b0d75743e0
[task 2019-11-18T10:58:22.149Z] 10:58:22 INFO - rip = 0x000076b0bc9f79e2
[task 2019-11-18T10:58:22.149Z] 10:58:22 INFO - Found by: previous frame's frame pointer
[task 2019-11-18T10:58:22.149Z] 10:58:22 INFO - 19 libc.so + 0x89772
[task 2019-11-18T10:58:22.149Z] 10:58:22 INFO - rsp = 0x000076b0d75743f0 rip = 0x000076b0e2af6772
[task 2019-11-18T10:58:22.149Z] 10:58:22 INFO - Found by: stack scanning
[task 2019-11-18T10:58:22.149Z] 10:58:22 INFO - 20 libxul.so!std::__ndk1::__vector_base<MessageLoop::PendingTask, std::__ndk1::allocator<MessageLoop::PendingTask> >::__destruct_at_end(MessageLoop::PendingTask*) [vector : 429 + 0xb]
[task 2019-11-18T10:58:22.149Z] 10:58:22 INFO - rsp = 0x000076b0d7574428 rip = 0x000076b0bc9f79d8
[task 2019-11-18T10:58:22.149Z] 10:58:22 INFO - Found by: stack scanning
[task 2019-11-18T10:58:22.149Z] 10:58:22 INFO - 21 libc.so + 0x299ec
[task 2019-11-18T10:58:22.150Z] 10:58:22 INFO - rsp = 0x000076b0d7574440 rip = 0x000076b0e2a969ec
[task 2019-11-18T10:58:22.150Z] 10:58:22 INFO - Found by: stack scanning
[task 2019-11-18T10:58:22.150Z] 10:58:22 INFO - 22 libc.so + 0x896c0
[task 2019-11-18T10:58:22.150Z] 10:58:22 INFO - rsp = 0x000076b0d7574448 rip = 0x000076b0e2af66c0
[task 2019-11-18T10:58:22.150Z] 10:58:22 INFO - Found by: stack scanning
[task 2019-11-18T10:58:22.150Z] 10:58:22 INFO - 23 libc.so + 0x1ca66
[task 2019-11-18T10:58:22.150Z] 10:58:22 INFO - rsp = 0x000076b0d7574450 rip = 0x000076b0e2a89a66
[task 2019-11-18T10:58:22.150Z] 10:58:22 INFO - Found by: stack scanning
[task 2019-11-18T10:58:22.151Z] 10:58:22 INFO - 24 libxul.so!std::__ndk1::__vector_base<MessageLoop::PendingTask, std::__ndk1::allocator<MessageLoop::PendingTask> >::__destruct_at_end(MessageLoop::PendingTask*) [vector : 429 + 0xb]
[task 2019-11-18T10:58:22.151Z] 10:58:22 INFO - rsp = 0x000076b0d75744b8 rip = 0x000076b0bc9f79d8
[task 2019-11-18T10:58:22.151Z] 10:58:22 INFO - Found by: stack scanning
[task 2019-11-18T10:58:22.151Z] 10:58:22 INFO - Thread 0

Not the right signature, and this is a debug assertion so it wouldn't show up on crash-stats anyway. (And there should be an accompanying message, Inserting duplicate item, but it's not in the log anywhere, so that's also not helping. Are we failing to collect error messages on Android?)

The frame with MessageChannel::RepostAllMessages may be significant — if we're processing a constructor message twice, that might explain the assertion. But I don't think anyone who's still here knows anything about that code….

Crash Signature: [@ mozilla::Logger::~Logger()]
Assignee: nobody → haftandilian
Priority: -- → P1
Priority: P1 → P2

As a side effect of calling MessageChannel::MessageTask::Post() for a constructor message, the top-level protocol mEventTargetMap is populated by the mEventTargetMap.AddWithID(target, handle.mId) call in IToplevelProtocol::GetMessageEventTarget().

When we call EndTimeout() due to receiving a message that was previously timed out, we call RepostAllMessages() which ends up calling Post() and GetMessageEventTarget() again for all messages in MessageChannel::mPending. This results in trying to add the same pair to the target map which causes the crash in DEBUG builds. I am not 100% certain that is what is happening here and there aren’t other scenarios that could leave a mapping in mEventTargetMap, but from the stack and code inspection, this seems likely.

So it looks like we just need to account for this scenario by skipping adding the same (target, handle.mID) pair to the mEventTargetMap. When there’s an event target in the map already, we can ASSERT that it matches the new event target so that we would still crash for instances not caused by RepostAllMessages().

While RepostAllMessages() is definitely hit during try testing, this crash requires a constructor message to be in mPending and already Post()’d when the RepostAllMessages().

See Also: → 1445121

Avoid crashing in IToplevelProtocol::GetMessageEventTarget() in DEBUG builds for messages that have been re-posted.

Pushed by haftandilian@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/b97bacb338c9
Intermittent org.mozilla.geckoview.test.ZZAccessibilityTest.testAccessibilityFocus r=jld
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla73

(In reply to Pulsebot from comment #6)

Pushed by haftandilian@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/b97bacb338c9
Intermittent org.mozilla.geckoview.test.ZZAccessibilityTest.testAccessibilityFocus r=jld

If Phabricator's UI had made it clear that that was going to be the first line of the commit message I would have asked for it to be changed. Oh well.

(In reply to Jed Davis [:jld] ⟨⏰|UTC-6⟩ ⟦he/him⟧ from comment #8)

Intermittent org.mozilla.geckoview.test.ZZAccessibilityTest.testAccessibilityFocus r=jld

If Phabricator's UI had made it clear that that was going to be the first line of the commit message I would have asked for it to be changed. Oh well.

Sorry about that. I should have updated it. I assume you mean there was no reason to mention the test name because it was a generic IPC issue? And a debug only issue at that.

6c6f5da9-bf33-4082-a19d-7d99e8083d97 Mass rename intermittents due to Bug 1723034.

Summary: Intermittent org.mozilla.geckoview.test.ZZAccessibilityTest.testAccessibilityFocus | application crashed [@ mozilla::Logger::~Logger()] → Intermittent org.mozilla.geckoview.test.ZZAccessibilityTest#testAccessibilityFocus | application crashed [@ mozilla::Logger::~Logger()]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: