Filed by: abutkovits [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=359015615&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/XGlztNEHSOaf2Ocsktxe6g/runs/0/artifacts/public/logs/live_backing.log

 [task 2021-11-23T20:58:24.651Z] 20:58:24     INFO - TEST-PASS | browser/base/content/test/captivePortal/browser_CaptivePortalWatcher.js | There should be no captive portal notification in the window. - 
[task 2021-11-23T20:58:24.652Z] 20:58:24     INFO - TEST-PASS | browser/base/content/test/captivePortal/browser_CaptivePortalWatcher.js | There should be no captive portal notification in the window. - 
[task 2021-11-23T20:58:24.653Z] 20:58:24     INFO - Buffered messages finished
[task 2021-11-23T20:58:24.654Z] 20:58:24    ERROR - TEST-UNEXPECTED-FAIL | browser/base/content/test/captivePortal/browser_CaptivePortalWatcher.js | application terminated with exit code 11
[task 2021-11-23T20:58:24.654Z] 20:58:24     INFO - runtests.py | Application ran for: 0:00:11.773268
[task 2021-11-23T20:58:24.655Z] 20:58:24     INFO - zombiecheck | Reading PID log: /tmp/tmpdj4chxq7pidlog
[task 2021-11-23T20:58:24.655Z] 20:58:24     INFO - ==> process 2289 launched child process 2309
[task 2021-11-23T20:58:24.656Z] 20:58:24     INFO - ==> process 2289 launched child process 2359
[task 2021-11-23T20:58:24.656Z] 20:58:24     INFO - ==> process 2289 launched child process 2380
[task 2021-11-23T20:58:24.657Z] 20:58:24     INFO - ==> process 2289 launched child process 2437
[task 2021-11-23T20:58:24.658Z] 20:58:24     INFO - ==> process 2289 launched child process 2490
[task 2021-11-23T20:58:24.658Z] 20:58:24     INFO - ==> process 2289 launched child process 2519
[task 2021-11-23T20:58:24.659Z] 20:58:24     INFO - ==> process 2289 launched child process 2554
[task 2021-11-23T20:58:24.659Z] 20:58:24     INFO - ==> process 2289 launched child process 2601
[task 2021-11-23T20:58:24.660Z] 20:58:24     INFO - zombiecheck | Checking for orphan process with PID: 2519
[task 2021-11-23T20:58:24.660Z] 20:58:24     INFO - zombiecheck | Checking for orphan process with PID: 2309
[task 2021-11-23T20:58:24.661Z] 20:58:24     INFO - zombiecheck | Checking for orphan process with PID: 2437
[task 2021-11-23T20:58:24.661Z] 20:58:24     INFO - zombiecheck | Checking for orphan process with PID: 2601
[task 2021-11-23T20:58:24.662Z] 20:58:24     INFO - zombiecheck | Checking for orphan process with PID: 2380
[task 2021-11-23T20:58:24.662Z] 20:58:24     INFO - zombiecheck | Checking for orphan process with PID: 2554
[task 2021-11-23T20:58:24.663Z] 20:58:24     INFO - zombiecheck | Checking for orphan process with PID: 2359
[task 2021-11-23T20:58:24.663Z] 20:58:24     INFO - zombiecheck | Checking for orphan process with PID: 2490
[task 2021-11-23T20:58:24.664Z] 20:58:24     INFO - mozcrash Downloading symbols from: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/PZCA_30IQEmHu9Mv1-2HIw/artifacts/public/build/target.crashreporter-symbols.zip
[task 2021-11-23T20:58:27.384Z] 20:58:27     INFO - mozcrash Copy/paste: /builds/worker/fetches/minidump_stackwalk/minidump_stackwalk --human /tmp/tmpfgol6nho.mozrunner/minidumps/154b3bcf-0f60-2dd4-a523-fa6d1013b94e.dmp /tmp/tmp23rhwr_s --symbols-url=https://symbols.mozilla.org/
[task 2021-11-23T20:58:29.315Z] 20:58:29     INFO - mozcrash Saved minidump as /builds/worker/workspace/build/blobber_upload_dir/154b3bcf-0f60-2dd4-a523-fa6d1013b94e.dmp
[task 2021-11-23T20:58:29.316Z] 20:58:29     INFO - mozcrash Saved app info as /builds/worker/workspace/build/blobber_upload_dir/154b3bcf-0f60-2dd4-a523-fa6d1013b94e.extra
[task 2021-11-23T20:58:29.604Z] 20:58:29     INFO - PROCESS-CRASH | browser/base/content/test/captivePortal/browser_CaptivePortalWatcher.js | application crashed [@ __memmove_avx_unaligned_erms + 0x1d2]
[task 2021-11-23T20:58:29.604Z] 20:58:29     INFO - Crash dump filename: /tmp/tmpfgol6nho.mozrunner/minidumps/154b3bcf-0f60-2dd4-a523-fa6d1013b94e.dmp
[task 2021-11-23T20:58:29.604Z] 20:58:29     INFO - Operating system: Linux
[task 2021-11-23T20:58:29.605Z] 20:58:29     INFO -                   0.0.0 Linux 4.4.0-1014-aws #14taskcluster1-Ubuntu SMP Tue Apr 3 10:27:00 UTC 2018 x86_64
[task 2021-11-23T20:58:29.605Z] 20:58:29     INFO - CPU: amd64
[task 2021-11-23T20:58:29.605Z] 20:58:29     INFO -      family 6 model 85 stepping 7
[task 2021-11-23T20:58:29.605Z] 20:58:29     INFO -      2 CPUs
[task 2021-11-23T20:58:29.606Z] 20:58:29     INFO - Linux Ubuntu 18.04 - bionic (Ubuntu 18.04.6 LTS)
[task 2021-11-23T20:58:29.607Z] 20:58:29     INFO - 
[task 2021-11-23T20:58:29.607Z] 20:58:29     INFO - Crash reason:  SIGSEGV / SEGV_MAPERR
[task 2021-11-23T20:58:29.607Z] 20:58:29     INFO - Crash address: 0x7f7c6536d020
[task 2021-11-23T20:58:29.608Z] 20:58:29     INFO - Process uptime: not available
[task 2021-11-23T20:58:29.609Z] 20:58:29     INFO - 
[task 2021-11-23T20:58:29.609Z] 20:58:29     INFO - Thread 93  (crashed)
[task 2021-11-23T20:58:29.609Z] 20:58:29     INFO -  0  libc.so.6!__memmove_avx_unaligned_erms + 0x1d2
[task 2021-11-23T20:58:29.610Z] 20:58:29     INFO -     rax = 0x00007f7c6536d000   rdx = 0x0000000000000360
[task 2021-11-23T20:58:29.610Z] 20:58:29     INFO -     rcx = 0x00007f7c6536d3e0   rbx = 0x0000000000000000
[task 2021-11-23T20:58:29.610Z] 20:58:29     INFO -     rsi = 0x00007f7c706000a0   rdi = 0x00007f7c6536d020
[task 2021-11-23T20:58:29.610Z] 20:58:29     INFO -     rbp = 0x00007f7c86e59c60   rsp = 0x00007f7c86e59bc8
[task 2021-11-23T20:58:29.611Z] 20:58:29     INFO -      r8 = 0xffffffffffffffe0    r9 = 0x0000000000000001
[task 2021-11-23T20:58:29.611Z] 20:58:29     INFO -     r10 = 0x0000000000000100   r11 = 0x00007f7c6536d000
[task 2021-11-23T20:58:29.611Z] 20:58:29     INFO -     r12 = 0x0000000000000200   r13 = 0x0000000000000400
[task 2021-11-23T20:58:29.611Z] 20:58:29     INFO -     r14 = 0x00007f7c6536d000   r15 = 0x00007f7c70600000
[task 2021-11-23T20:58:29.611Z] 20:58:29     INFO -     rip = 0x00007f7cac9a4f12
[task 2021-11-23T20:58:29.611Z] 20:58:29     INFO -     Found by: given as instruction pointer in context
[task 2021-11-23T20:58:29.611Z] 20:58:29     INFO -  1  libxul.so!void scale_blit<false>(Texture&, IntRect const&, Texture&, IntRect const&, bool, IntRect const&) [composite.h:853874dee29b2a068a74b2a550151afaffd939ce : 162 + 0xa]
[task 2021-11-23T20:58:29.611Z] 20:58:29     INFO -     rbx = 0x0000000000000000   rbp = 0x00007f7c86e59c60
[task 2021-11-23T20:58:29.611Z] 20:58:29     INFO -     rsp = 0x00007f7c86e59bd0   r12 = 0x0000000000000200
[task 2021-11-23T20:58:29.611Z] 20:58:29     INFO -     r13 = 0x0000000000000400   r14 = 0x00007f7c6536d000
[task 2021-11-23T20:58:29.611Z] 20:58:29     INFO -     r15 = 0x00007f7c70600000   rip = 0x00007f7c9fbfc373
[task 2021-11-23T20:58:29.611Z] 20:58:29     INFO -     Found by: call frame info
[task 2021-11-23T20:58:29.611Z] 20:58:29     INFO -  2  libxul.so!Composite [composite.h:853874dee29b2a068a74b2a550151afaffd939ce : 442 + 0x22]
[task 2021-11-23T20:58:29.611Z] 20:58:29     INFO -     rbx = 0x0000000000000100   rbp = 0x00007f7c86e59cd0
[task 2021-11-23T20:58:29.611Z] 20:58:29     INFO -     rsp = 0x00007f7c86e59c70   r12 = 0x0000000000000000
[task 2021-11-23T20:58:29.611Z] 20:58:29     INFO -     r13 = 0x0000000000000200   r14 = 0x0000000000000200
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     r15 = 0x0000000000000100   rip = 0x00007f7c9fbfc840
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     Found by: call frame info
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -  3  libxul.so!webrender::compositor::sw_compositor::SwCompositeThread::process_job [sw_compositor.rs:853874dee29b2a068a74b2a550151afaffd939ce : 514 + 0xd9]
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     rbx = 0x00007f7c7539c320   rbp = 0x00007f7c86e59df0
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     rsp = 0x00007f7c86e59ce0   r12 = 0x0000000000000080
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     r13 = 0x0000000000000200   r14 = 0x0000000000000200
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     r15 = 0x0000000000002601   rip = 0x00007f7c9f7bee55
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     Found by: call frame info
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -  4  libxul.so!std::sys_common::backtrace::__rust_begin_short_backtrace [backtrace.rs:09c42c45858d5f3aedfa670698275303a3d19afa : 125 + 0x51]
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     rbx = 0x00007f7c753be890   rbp = 0x00007f7c86e59e30
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     rsp = 0x00007f7c86e59e00   r12 = 0x00007f7c7b8962f0
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     r13 = 0x0000000000000000   r14 = 0x00007f7c753be880
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     r15 = 0x00007f7c87719370   rip = 0x00007f7c9f79ab8d
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     Found by: call frame info
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -  5  libxul.so!core::ops::function::FnOnce::call_once{{vtable.shim}} [function.rs:09c42c45858d5f3aedfa670698275303a3d19afa : 227 + 0x74]
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     rbx = 0x00007f7c87719370   rbp = 0x00007f7c86e59e70
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     rsp = 0x00007f7c86e59e40   r12 = 0x00007f7c7b8962f0
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     r13 = 0x0000000000000000   r14 = 0x00007f7c86e59e40
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     r15 = 0x00007f7c87719370   rip = 0x00007f7c9f79fd65
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     Found by: call frame info
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -  6  libxul.so!std::sys::unix::thread::Thread::new::thread_start [thread.rs:09c42c45858d5f3aedfa670698275303a3d19afa : 106 + 0xe]
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     rbx = 0x00007f7ca2b13790   rbp = 0x0000000000000000
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     rsp = 0x00007f7c86e59e80   r12 = 0x00007f7c7b8962f0
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     r13 = 0x0000000000000000   r14 = 0x0000000000000000
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     r15 = 0x00007f7c87719370   rip = 0x00007f7c9fa99ad5
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     Found by: call frame info
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -  7  libpthread.so.0!start_thread [pthread_create.c : 463 + 0xc]
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     rbx = 0x0000000000000000   rbp = 0x0000000000000000
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     rsp = 0x00007f7c86e59ec0   r12 = 0x00007f7c86e59f80
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     r13 = 0x0000000000000000   r14 = 0x00007f7c7b8962f0
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     r15 = 0x00007f7c8c8a6eb0   rip = 0x00007f7cad7516db
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -     Found by: call frame info
[task 2021-11-23T20:58:29.612Z] 20:58:29     INFO -  8  libc.so.6!__GI___clone + 0x3e
[task 2021-11-23T20:58:29.613Z] 20:58:29     INFO -     rbx = 0x00007f7c86e5a700   rbp = 0x0000000000000000
[task 2021-11-23T20:58:29.613Z] 20:58:29     INFO -     rsp = 0x00007f7c86e59f80   r12 = 0x00007f7c86e59f80
[task 2021-11-23T20:58:29.613Z] 20:58:29     INFO -     r13 = 0x0000000000000000   r14 = 0x00007f7c7b8962f0
[task 2021-11-23T20:58:29.613Z] 20:58:29     INFO -     r15 = 0x00007f7c8c8a6eb0   rip = 0x00007f7cac937a3f
[task 2021-11-23T20:58:29.613Z] 20:58:29     INFO -     Found by: call frame info

Is the signature change expected?

The signature changed because mozcrash.py uses this heuristic to parse the crash records: https://searchfox.org/mozilla-central/rev/7fe9421af35256a95acc4620e9e0b76df7867287/testing/mozbase/mozcrash/mozcrash/mozcrash.py#369-376

It looks for "Thread N (crashed)" and then after that line searches for a line starting with a digit like

0  libc.so.6!__memmove_avx_unaligned_erms + 0x1d2

But for whatever reason in Bug 1737720 we see that breakpad squishes the two lines together:

 Thread 89 tid 14515 (crashed) 0  libc.so.6!__memmove_avx_unaligned_erms + 0x1d2

So mozcrash's scan misses the top frame and actually finds frame 1:

1  libxul.so!void scale_blit<false>(Texture&, IntRect const&, Texture&, IntRect const&, bool, IntRect const&) [composite.h:6c01444e17210e96f5fb322c7b55a2e9f87ec0b0 : 162 + 0xb]

So, at least as far as mozcrash's comments suggest intended behaviour, the new implementation is doing a "better job". Although in this case the frame it picks out is not as good. Unless there's some janky heuristic in breakpad to mess up the first line in some cases so mozcrash.py sees the second frame on purpose?

If that's the case (doubtful), I would just move that logic to mozcrash where it belongs.

Needinfo'ing Kris in case they have any historical context on if this weird behaviour from breakpad was expected/desired. (totally fine if not)

Thanks, the new behavior looks sane.

Looking at this and poking around Breakpad, I'm not really sure how we're getting these signatures. In theory there should be a newline between the crashing thread and the trace, but it's possible something is eating the end of the line. Not really sure what since I've never seen this before but I don't think it's intended behavior and if we're running into it frequently I can add an exception to mozcrash to check for stack traces beginning at the thread name.

The old code is removed now, so we don't need to "fix" it. Was just curious if this was somehow a really jank feature (seems not).