Closed Bug 1581360 Opened 7 years ago Closed 6 years ago

Intermittent test_navigation.py TestBackForwardNavigation.test_file_url | IOError: Process crashed (Exit code: 1) (Reason: No data received over socket) | application crashed [@ base::MessagePumpLibevent::OnLibeventSignalNotification(int, short, void*)]

Categories

(Core :: IPC, defect, P2)

Product:
Core
Component:
IPC
Type:
defect

Tracking

()

Status:
RESOLVED DUPLICATE of bug 1574037
Tracking Flags:
Tracking Status
firefox70 --- wontfix
firefox71 --- wontfix

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(4 keywords)

Filed by: rgurzau [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=266719109&repo=mozilla-inbound
Full log: https://queue.taskcluster.net/v1/task/fyCn8oJ_S4uK_ofIIcwEOQ/runs/0/artifacts/public/logs/live_backing.log

[task 2019-09-14T22:40:52.206Z] 22:40:52 INFO - [GFX1-]: Receive IPC close with reason=AbnormalShutdown
[task 2019-09-14T22:40:52.208Z] 22:40:52 INFO - Exiting due to channel error.
[task 2019-09-14T22:40:52.208Z] 22:40:52 INFO - Exiting due to channel error.
[task 2019-09-14T22:40:52.208Z] 22:40:52 INFO - Exiting due to channel error.
[task 2019-09-14T22:40:52.254Z] 22:40:52 INFO - mozcrash Downloading symbols from: https://queue.taskcluster.net/v1/task/ShEiVNYMSlyWaow15LtVag/artifacts/public/build/target.crashreporter-symbols.zip
[task 2019-09-14T22:40:56.062Z] 22:40:56 INFO - mozcrash Copy/paste: /Users/cltbld/tasks/task_1568500686/build/macosx64-minidump_stackwalk /var/folders//56y4sw851tv0348xrl89s9qh000017/T/tmpVuMVPM.mozrunner/minidumps/4B77D19E-0AB5-4CDE-A5E2-A74822B80D90.dmp /var/folders//56y4sw851tv0348xrl89s9qh000017/T/tmpLzQeWa
[task 2019-09-14T22:41:02.763Z] 22:41:02 INFO - mozcrash Saved minidump as /Users/cltbld/tasks/task_1568500686/build/blobber_upload_dir/4B77D19E-0AB5-4CDE-A5E2-A74822B80D90.dmp
[task 2019-09-14T22:41:02.763Z] 22:41:02 INFO - mozcrash Saved app info as /Users/cltbld/tasks/task_1568500686/build/blobber_upload_dir/4B77D19E-0AB5-4CDE-A5E2-A74822B80D90.extra
[task 2019-09-14T22:41:02.896Z] 22:41:02 INFO - PROCESS-CRASH | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestBackForwardNavigation.test_file_url | application crashed [@ base::MessagePumpLibevent::OnLibeventSignalNotification(int, short, void*)]
[task 2019-09-14T22:41:02.897Z] 22:41:02 INFO - Crash dump filename: /var/folders/__/56y4sw851tv0348xrl89s9qh000017/T/tmpVuMVPM.mozrunner/minidumps/4B77D19E-0AB5-4CDE-A5E2-A74822B80D90.dmp
[task 2019-09-14T22:41:02.897Z] 22:41:02 INFO - Operating system: Mac OS X
[task 2019-09-14T22:41:02.897Z] 22:41:02 INFO - 10.14.5 18F132
[task 2019-09-14T22:41:02.897Z] 22:41:02 INFO - CPU: amd64
[task 2019-09-14T22:41:02.897Z] 22:41:02 INFO - family 6 model 69 stepping 1
[task 2019-09-14T22:41:02.897Z] 22:41:02 INFO - 4 CPUs
[task 2019-09-14T22:41:02.897Z] 22:41:02 INFO -
[task 2019-09-14T22:41:02.897Z] 22:41:02 INFO - GPU: UNKNOWN
[task 2019-09-14T22:41:02.897Z] 22:41:02 INFO -
[task 2019-09-14T22:41:02.897Z] 22:41:02 INFO - Crash reason: EXC_BAD_ACCESS / KERN_INVALID_ADDRESS
[task 2019-09-14T22:41:02.897Z] 22:41:02 INFO - Crash address: 0x11
[task 2019-09-14T22:41:02.897Z] 22:41:02 INFO - Process uptime: 68 seconds
[task 2019-09-14T22:41:02.897Z] 22:41:02 INFO -
[task 2019-09-14T22:41:02.897Z] 22:41:02 INFO - Thread 2 (crashed)
[task 2019-09-14T22:41:02.897Z] 22:41:02 INFO - 0 XUL!base::MessagePumpLibevent::OnLibeventSignalNotification(int, short, void*) [message_pump_libevent.cc:6cbf1430a66ef5aa5f066ed77677f47ea44fc0e1 : 308 + 0x3]
[task 2019-09-14T22:41:02.897Z] 22:41:02 INFO - rax = 0x0000003400000001 rdx = 0x0000000117e04d00
[task 2019-09-14T22:41:02.897Z] 22:41:02 INFO - rcx = 0x00000001032fef14 rbx = 0x0000000000000001
[task 2019-09-14T22:41:02.897Z] 22:41:02 INFO - rsi = 0x0000000000000014 rdi = 0x0000000000000014
[task 2019-09-14T22:41:02.898Z] 22:41:02 INFO - rbp = 0x000070000eebab90 rsp = 0x000070000eebab90
[task 2019-09-14T22:41:02.898Z] 22:41:02 INFO - r8 = 0x0000000101900250 r9 = 0x000070000eebabe0
[task 2019-09-14T22:41:02.898Z] 22:41:02 INFO - r10 = 0x0000000000000000 r11 = 0x0000000000000246
[task 2019-09-14T22:41:02.898Z] 22:41:02 INFO - r12 = 0x0000000115c66800 r13 = 0x0000000000000001
[task 2019-09-14T22:41:02.898Z] 22:41:02 INFO - r14 = 0x00000001028a9800 r15 = 0x0000000115c66800
[task 2019-09-14T22:41:02.898Z] 22:41:02 INFO - rip = 0x00000001032e94e9
[task 2019-09-14T22:41:02.898Z] 22:41:02 INFO - Found by: given as instruction pointer in context
[task 2019-09-14T22:41:02.898Z] 22:41:02 INFO - 1 XUL!event_process_active_single_queue [event.c:6cbf1430a66ef5aa5f066ed77677f47ea44fc0e1 : 1635 + 0x71]
[task 2019-09-14T22:41:02.898Z] 22:41:02 INFO - rbp = 0x000070000eebac20 rsp = 0x000070000eebaba0
[task 2019-09-14T22:41:02.898Z] 22:41:02 INFO - rip = 0x00000001032fea6a
[task 2019-09-14T22:41:02.898Z] 22:41:02 INFO - Found by: previous frame's frame pointer
[task 2019-09-14T22:41:02.898Z] 22:41:02 INFO - 2 XUL!event_base_loop [event.c:6cbf1430a66ef5aa5f066ed77677f47ea44fc0e1 : 0 + 0x5]
[task 2019-09-14T22:41:02.898Z] 22:41:02 INFO - rbp = 0x000070000eebacc0 rsp = 0x000070000eebac30
[task 2019-09-14T22:41:02.898Z] 22:41:02 INFO - rip = 0x00000001032fd200
[task 2019-09-14T22:41:02.898Z] 22:41:02 INFO - Found by: previous frame's frame pointer
[task 2019-09-14T22:41:02.898Z] 22:41:02 INFO - 3 XUL!base::MessagePumpLibevent::Run(base::MessagePump::Delegate*) [message_pump_libevent.cc:6cbf1430a66ef5aa5f066ed77677f47ea44fc0e1 : 0 + 0xe]
[task 2019-09-14T22:41:02.898Z] 22:41:02 INFO - rbp = 0x000070000eebad20 rsp = 0x000070000eebacd0
[task 2019-09-14T22:41:02.898Z] 22:41:02 INFO - rip = 0x00000001032e9648
[task 2019-09-14T22:41:02.899Z] 22:41:02 INFO - Found by: previous frame's frame pointer
[task 2019-09-14T22:41:02.899Z] 22:41:02 INFO - 4 XUL!base::Thread::ThreadMain() [thread.cc:6cbf1430a66ef5aa5f066ed77677f47ea44fc0e1 : 192 + 0x4d]
[task 2019-09-14T22:41:02.899Z] 22:41:02 INFO - rbp = 0x000070000eebaf00 rsp = 0x000070000eebad30
[task 2019-09-14T22:41:02.899Z] 22:41:02 INFO - rip = 0x00000001032f131f
[task 2019-09-14T22:41:02.899Z] 22:41:02 INFO - Found by: previous frame's frame pointer
[task 2019-09-14T22:41:02.899Z] 22:41:02 INFO - 5 XUL!ThreadFunc(void*) [platform_thread_posix.cc:6cbf1430a66ef5aa5f066ed77677f47ea44fc0e1 : 40 + 0x6]
[task 2019-09-14T22:41:02.899Z] 22:41:02 INFO - rbp = 0x000070000eebaf10 rsp = 0x000070000eebaf10
[task 2019-09-14T22:41:02.899Z] 22:41:02 INFO - rip = 0x00000001032edada
[task 2019-09-14T22:41:02.899Z] 22:41:02 INFO - Found by: previous frame's frame pointer
[task 2019-09-14T22:41:02.899Z] 22:41:02 INFO - 6 libsystem_pthread.dylib!_pthread_body + 0x7e
[task 2019-09-14T22:41:02.899Z] 22:41:02 INFO - rbp = 0x000070000eebaf30 rsp = 0x000070000eebaf20
[task 2019-09-14T22:41:02.899Z] 22:41:02 INFO - rip = 0x00007fff7d8372eb
[task 2019-09-14T22:41:02.899Z] 22:41:02 INFO - Found by: previous frame's frame pointer
[task 2019-09-14T22:41:02.899Z] 22:41:02 INFO - 7 libsystem_pthread.dylib!_pthread_start + 0x42
[task 2019-09-14T22:41:02.899Z] 22:41:02 INFO - rbp = 0x000070000eebaf50 rsp = 0x000070000eebaf40
[task 2019-09-14T22:41:02.899Z] 22:41:02 INFO - rip = 0x00007fff7d83a249
[task 2019-09-14T22:41:02.899Z] 22:41:02 INFO - Found by: previous frame's frame pointer
[task 2019-09-14T22:41:02.899Z] 22:41:02 INFO - 8 libsystem_pthread.dylib!thread_start + 0xd
[task 2019-09-14T22:41:02.900Z] 22:41:02 INFO - rbp = 0x000070000eebaf78 rsp = 0x000070000eebaf60
[task 2019-09-14T22:41:02.900Z] 22:41:02 INFO - rip = 0x00007fff7d83640d
[task 2019-09-14T22:41:02.900Z] 22:41:02 INFO - Found by: previous frame's frame pointer
[task 2019-09-14T22:41:02.900Z] 22:41:02 INFO - 9 XUL!std::__1::__deque_base<MessageLoop::PendingTask, std::__1::allocator<MessageLoop::PendingTask> >::clear() [deque : 1196 + 0xf]
[task 2019-09-14T22:41:02.900Z] 22:41:02 INFO - rsp = 0x000070000eebb090 rip = 0x00000001032edad0
[task 2019-09-14T22:41:02.900Z] 22:41:02 INFO - Found by: stack scanning
[task 2019-09-14T22:41:02.900Z] 22:41:02 INFO -

[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - 0x7fff7d84e000 - 0x7fff7d863fff libsystem_trace.dylib ???
[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - 0x7fff7d865000 - 0x7fff7d86afff libunwind.dylib ???
[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - 0x7fff7d86b000 - 0x7fff7d89afff libxpc.dylib ???
[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestBackForwardNavigation.test_file_url | IOError: Process crashed (Exit code: 1) (Reason: No data received over socket)
[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - Traceback (most recent call last):
[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - File "/Users/cltbld/tasks/task_1568500686/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 190, in run
[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - self.tearDown()
[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - File "/Users/cltbld/tasks/task_1568500686/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py", line 69, in tearDown
[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - super(BaseNavigationTestCase, self).tearDown()
[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - File "/Users/cltbld/tasks/task_1568500686/build/venv/lib/python2.7/site-packages/marionette_harness/runner/mixins/window_manager.py", line 28, in tearDown
[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - if len(self.marionette.window_handles) > len(self.start_tabs):
[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - File "/Users/cltbld/tasks/task_1568500686/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1246, in window_handles
[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - return self._send_message("WebDriver:GetWindowHandles")
[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - File "/Users/cltbld/tasks/task_1568500686/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 36, in _
[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - m._handle_socket_failure()
[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - File "/Users/cltbld/tasks/task_1568500686/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 678, in _handle_socket_failure
[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - reraise(IOError, message.format(returncode=returncode, reason=val), tb)
[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - File "/Users/cltbld/tasks/task_1568500686/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - return func(*args, **kwargs)
[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - File "/Users/cltbld/tasks/task_1568500686/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 590, in _send_message
[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - msg = self.client.request(name, params)
[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - File "/Users/cltbld/tasks/task_1568500686/build/venv/lib/python2.7/site-packages/marionette_driver/transport.py", line 273, in request
[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - return self.receive()
[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - File "/Users/cltbld/tasks/task_1568500686/build/venv/lib/python2.7/site-packages/marionette_driver/transport.py", line 159, in receive
[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - raise socket.error("No data received over socket")
[task 2019-09-14T22:41:03.126Z] 22:41:03 INFO - TEST-INFO took 14502ms

Component: Marionette → IPC
Product: Testing → Core
Version: Version 3 → unspecified

Here's the compiled version of MessagePumpLibevent::OnLibeventSignalNotification (from the minidump and not the build, for reference, but it probably doesn't matter); the faulting instruction is at 1032e94e9:

   1032e94e0:   55                      push   %rbp
   1032e94e1:   48 89 e5                mov    %rsp,%rbp
   1032e94e4:   89 fe                   mov    %edi,%esi
   1032e94e6:   48 8b 02                mov    (%rdx),%rax
   1032e94e9:   48 8b 40 10             mov    0x10(%rax),%rax
   1032e94ed:   48 89 d7                mov    %rdx,%rdi
   1032e94f0:   5d                      pop    %rbp
   1032e94f1:   ff e0                   jmpq   *%rax

So the object pointer (rdx = 0x0000000117e04d00) is valid, but the vtable pointer (rax = 0x0000003400000001) is not, and looks like it was replaced with two ints. This might be a variant of bug 1574037 where the memory is reallocated at another type before it's accessed.

It's interesting that, if I'm interpteting this correctly, the reported crash address was truncated to 32 bits. That… ideally shouldn't happen.

Group: dom-core-security
See Also: → 1574037
status-firefox70: --- → fix-optional
status-firefox71: --- → affected
Priority: P5 → P1

This "intermittent" appears to have happened only once and it doesn't look like we have much progress on a potential cause. Time to mark INCOMPLETE or WORKSFORME?

Keywords: stalled

Or duplicate of bug 1574037 (which is stalled on someone doing an audit of all the code related to handling SIGCHLD).

As mentioned this is a likely duplicate of bug 1574037, which is P2 (and maybe should be P3) because of how little information we have and the difficulty of acquiring more. Also fixing priority so I'm not nagged to set “severity” (which we've defined in a way that isn't meaningful for security bugs).

Priority: P1 → P2
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → DUPLICATE

Since the bug is closed, the stalled keyword is now meaningless.
For more information, please visit auto_nag documentation.

Keywords: stalled
Group: dom-core-security
You need to log in before you can comment on or make changes to this bug.