Skip to content

Assertion `!!(blocked & mask) == is_sig_blocked(sig)' failed to hold. SIGTRAP is not blocked #1879

Closed
Closed
Assertion `!!(blocked & mask) == is_sig_blocked(sig)' failed to hold. SIGTRAP is not blocked#1879
Assignees
rocallahan

Description

@mjfroman
mjfroman
opened on Nov 7, 2016

Using rr with mochitests seems to be broken now. I'm on Ubuntu 16.04 with latest updates. I have pulled the latest rr (0f36df5) and rebuilt. I have the latest version of ff code from central (060f80b690b8). This seems to be completely repeatable. As an example, if I run this command:

./mach mochitest dom/media/tests/mochitest/test_peerConnection_basicAudio.html --keep-open=false --debugger=rr

I see:

[FATAL /home/mfroman/rr/rr/src/RecordTask.cc:1110:verify_signal_states() errno: SUCCESS]
 (task 16128 (rec:16128) at time 285111)
 -> Assertion `!!(blocked & mask) == is_sig_blocked(sig)' failed to hold. SIGTRAP is not blocked
[FATAL /home/mfroman/rr/rr/src/log.cc:284:emergency_debug() errno: SUCCESS] (session doesn't look interactive, aborting emergency debugging)
TEST-INFO | Main app process: killed by SIGIOT
Buffered messages finished
1 ERROR TEST-UNEXPECTED-FAIL | automation.py | application terminated with exit code -6
runtests.py | Application ran for: 0:01:40.504514
zombiecheck | Reading PID log: /tmp/tmpfWkP9Wpidlog
==> process 15958 launched child process 15977
==> process 15958 launched child process 16047
zombiecheck | Checking for orphan process with PID: 15977
zombiecheck | Checking for orphan process with PID: 16047

After rerunning with:

./mach mochitest dom/media/tests/mochitest/test_peerConnection_basicAudio.html --keep-open=false --debugger=rr --debugger-args="record -F"

And attaching with gdb, "where" gives me:

#0  mozilla::SigSysHandler (nr=0, info=0x0, void_context=0x0) at /home/mfroman/mozilla/moz-central/security/sandbox/linux/Sandbox.cpp:120
#1  <signal handler called>
#2  0x000000007000000e in ?? ()
#3  0x00007fb31124d288 in _raw_syscall () at /home/mfroman/rr/rr/src/preload/raw_syscall.S:120
#4  0x00007fb31124a012 in untraced_syscall_base (syscallno=syscallno@entry=89, a0=a0@entry=140406479660152, a1=a1@entry=140406067028008, a2=a2@entry=99, a3=a3@entry=0,
    a4=a4@entry=0, a5=0, syscall_instruction=0x7000000c) at /home/mfroman/rr/rr/src/preload/preload.c:334
#5  0x00007fb31124bf5d in sys_readlink (call=0x7fb2d5ffdfb0) at /home/mfroman/rr/rr/src/preload/preload.c:1893
#6  syscall_hook_internal (call=0x7fb2d5ffdfb0) at /home/mfroman/rr/rr/src/preload/preload.c:2391
#7  syscall_hook (call=0x7fb2d5ffdfb0) at /home/mfroman/rr/rr/src/preload/preload.c:2443
#8  0x00007fb31124d2b2 in _syscall_hook_trampoline () at /home/mfroman/rr/rr/src/preload/syscall_hook.S:188
#9  0x00007fb31124d2d7 in _syscall_hook_trampoline_48_3d_01_f0_ff_ff () at /home/mfroman/rr/rr/src/preload/syscall_hook.S:249
#10 0x00007fb3055efe4d in readlink () at ../sysdeps/unix/syscall-template.S:84
#11 0x00007fb2ee551885 in pa_readlink () from /usr/lib/x86_64-linux-gnu/pulseaudio/libpulsecommon-8.0.so
#12 0x00007fb2ee545e1c in pa_get_binary_name () from /usr/lib/x86_64-linux-gnu/pulseaudio/libpulsecommon-8.0.so
#13 0x00007fb2ee54ffc2 in pa_get_binary_name_malloc () from /usr/lib/x86_64-linux-gnu/pulseaudio/libpulsecommon-8.0.so
#14 0x00007fb2ee567ca2 in pa_init_proplist () from /usr/lib/x86_64-linux-gnu/pulseaudio/libpulsecommon-8.0.so
#15 0x00007fb2ee9c25e2 in ?? () from /usr/lib/x86_64-linux-gnu/libpulse.so.0
#16 0x00007fb2ee565ae1 in ?? () from /usr/lib/x86_64-linux-gnu/pulseaudio/libpulsecommon-8.0.so
#17 0x00007fb2ee565e6b in pa_pdispatch_run () from /usr/lib/x86_64-linux-gnu/pulseaudio/libpulsecommon-8.0.so
#18 0x00007fb2ee9bff2e in ?? () from /usr/lib/x86_64-linux-gnu/libpulse.so.0
#19 0x00007fb2ee5686cf in ?? () from /usr/lib/x86_64-linux-gnu/pulseaudio/libpulsecommon-8.0.so
#20 0x00007fb2ee56ad84 in ?? () from /usr/lib/x86_64-linux-gnu/pulseaudio/libpulsecommon-8.0.so
#21 0x00007fb2ee9d4cb0 in pa_mainloop_dispatch () from /usr/lib/x86_64-linux-gnu/libpulse.so.0
#22 0x00007fb2ee9d50bc in pa_mainloop_iterate () from /usr/lib/x86_64-linux-gnu/libpulse.so.0
#23 0x00007fb2ee9d5160 in pa_mainloop_run () from /usr/lib/x86_64-linux-gnu/libpulse.so.0
#24 0x00007fb2ee9e3149 in ?? () from /usr/lib/x86_64-linux-gnu/libpulse.so.0
#25 0x00007fb2ee57b678 in ?? () from /usr/lib/x86_64-linux-gnu/pulseaudio/libpulsecommon-8.0.so
#26 0x00007fb31103370a in start_thread (arg=0x7fb2d67fe700) at pthread_create.c:333
#27 0x00007fb3055fe82d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

If there is additional info you'd like, please let me know!

Activity

  1. dminor commented on Nov 7, 2016

    @dminor
    dminor
    on Nov 7, 2016

    This reproduces for me on Ubuntu 16.04 with rr 4.4.0 (pulled and rebuilt this morning).

  2. mjfroman
    assigned
    khuey
    on Nov 7, 2016

  3. mjfroman commented on Nov 7, 2016

    @mjfroman
    mjfroman
    on Nov 7, 2016
    Author

    To add a small bit of additional info:
    dom/media/tests/mochitest/test_peerConnection_basicVideo.html records just fine.
    dom/media/tests/mochitest/test_peerConnection_basicAudioVideo.html does not.
    This is maybe specific to audio-related tests?

  4. khuey commented on Nov 7, 2016

    @khuey
    khuey
    on Nov 7, 2016
    Collaborator

    The relevant difference may be that we're on a PulseAudio thread here. Perhaps that causes Firefox's sandbox code to behave differently.

  5. mjfroman
    unassigned
    khuey
    on Nov 7, 2016

  6. khuey commented on Nov 7, 2016

    @khuey
    khuey
    on Nov 7, 2016
    Collaborator

    @rocallahan do you want to take a look at this one? I don't have any good ideas :/

  7. rocallahan
    self-assigned this
    on Nov 7, 2016

  8. rocallahan commented on Nov 7, 2016

    @rocallahan
    rocallahan
    on Nov 7, 2016
    Collaborator

    Looking. It reproduces in Fedora 24 so it looks like some Firefox change caused this.

  9. rocallahan commented on Nov 8, 2016

    @rocallahan
    rocallahan
    on Nov 8, 2016
    Collaborator

    It's something to do with the way signals are injected. Here's a log with some instrumentation. The "blocked signals = ..." lines report the kernel signal mask as reported by /proc/<pid>/status.

    [RecordSession] trace time 584458: Active task is 7719. Events:
[RecordSession] SIGSYS handled
[RecordSession] handled blocked signals = 0xfffffffe1ffb7eff

    This matches rr's mask.

    [RecordSession] trace time 584458: Active task is 7719. Events:
[RecordSession]   7719: SIGSYS has user handler
[RecordSession]     maybe not in signal-stop; tgkill(SIGSYS)

    We decide to send a SIGSYS because we think the task is not in a signal-stop. I'm not sure why in this case, since we should still be in the SIGSYS stop. This needs investigation.

    [RecordSession] before tgkill blocked signals = 0xfffffffe1ffb7eff
[RecordSession] after tgkill blocked signals = 0xfffffffe1ffb7eff

    Having sent the signal, we now resume-singlestep hoping to get the signal-delivery-stop.

    [RecordSession] after RESUME_SINGLESTEP blocked signals = 0xfffffffe1ffb7eef
[RecordSession] Unexpected SIGTRAP while processing seccomp SIGSYS

    We got it, but we're in the XXX khuey block where a SIGTRAP is being delivered for unknown reasons and the kernel has unblocked SIGTRAP!

    [RecordSession] after unexpected SIGTRAP blocked signals = 0xfffffffe1ffb7eef
[RecordSession] after RESUME_SINGLESTEP blocked signals = 0xfffffffe1ffb7eef
[RecordSession]     stopped with signal SIGSYS
[RecordSession]     injecting signal number {signo:SIGSYS,errno:ENOMEM,code:sicode(1)}
[RecordSession] Before inject_handled_signal blocked signals = 0xfffffffe1ffb7eef
[RecordSession] After inject_handled_signal blocked signals = 0xfffffffe1ffb7eef
[RecordTask] apply_sig_sa_mask for signal SIGSYS
[RecordTask] apply_sig_sa_mask 7719 mask is 0xfffffffe1fff7fff, handler mask is 0
[FATAL /home/roc/rr/rr/src/RecordTask.cc:1118:verify_signal_states() errno: SUCCESS]
 (task 7719 (rec:7719) at time 584460)
 -> Assertion `!!(blocked & mask) == is_sig_blocked(sig)' failed to hold. SIGTRAP is not blocked

  10. rocallahan commented on Nov 8, 2016

    @rocallahan
    rocallahan
    on Nov 8, 2016
    Collaborator

    So it's time to figure out why we're getting that SIGTRAP.

  11. rocallahan commented on Nov 8, 2016

    @rocallahan
    rocallahan
    on Nov 8, 2016
    Collaborator

    We decide to send a SIGSYS because we think the task is not in a signal-stop. I'm not sure why in this case, since we should still be in the SIGSYS stop. This needs investigation.

    That's because we synthesize the SIGSYS on behalf of a seccomp filter.

  12. khuey commented on Nov 8, 2016

    @khuey
    khuey
    on Nov 8, 2016
    Collaborator

    (IIRC) That SIGTRAP happens every time we synthesize the seccomp filter signal though. And this doesn't normally trip the signal mask assertion.

  13. rocallahan commented on Nov 8, 2016

    @rocallahan
    rocallahan
    on Nov 8, 2016
    Collaborator

    We certainly don't always get a SIGTRAP. A simple testcase shows us getting a SIGSYS when we inject a SIGSYS, as expected.

  14. rocallahan commented on Nov 8, 2016

    @rocallahan
    rocallahan
    on Nov 8, 2016
    Collaborator

    I'll need to do more work to confirm this, but I think the reason the assertion trips in this case and not others is that generally threads in the sandbox aren't trying to block SIGTRAP, so when they trigger the SIGTRAP that's harmless. But the Pulseaudio thread does block SIGTRAP (along with every other signal it can possibly block).

  15. khuey commented on Nov 8, 2016

    @khuey
    khuey
    on Nov 8, 2016
    Collaborator

    Yeah, that would make more sense.

  16. rocallahan commented on Nov 8, 2016

    @rocallahan
    rocallahan
    on Nov 8, 2016
    Collaborator

    We already know of cases where the kernel decides it really needs to deliver a signal and unblocks that signal if it's currently blocked, and I suspect that's what's happening here.

  17. rocallahan commented on Nov 8, 2016

    @rocallahan
    rocallahan
    on Nov 8, 2016
    Collaborator

    The siginfo for the SIGTRAP is {signo:SIGTRAP,errno:SUCCESS,code:TRAP_BRKPT,addr:0x7000000e}. That's amusing.

  18. rocallahan commented on Nov 8, 2016

    @rocallahan
    rocallahan
    on Nov 8, 2016
    Collaborator

    TRAP_BRKPT only occurs twice for x86 in the kernel sources. One of them is get_si_code called from do_debug for a hardware-triggered debug-register trap. My guess is we're not hitting this one, there's no reason to and hardware singlestepping would cause TRAP_TRACE instead. The other is user_single_step_siginfo called from tracehook_report_syscall_exitwhich is called from syscall_slow_exit_work when we singlestep out of a syscall --- this is the SIGTRAP you get when you singlestep-exit from a syscall. The latter seems more probably but I'm not sure...

  19. rocallahan commented on Nov 8, 2016

    @rocallahan
    rocallahan
    on Nov 8, 2016
    Collaborator

    What I would expect to happen in the kernel here is that we're in the PTRACE_EVENT_SECCOMP stop, we send a signal so that there's a SIGSYS queued for the tracee, then we do the PTRACE_SINGLESTEP which resumes execution along the skip-syscall path. This should lead to syscall_return_slowpath which (because we have TIF_SINGLESTEP) calls syscall_slow_exit_work which calls tracehook_report_syscall_exit which queues a SIGTRAP. Then in exit_to_usermode_loop we dequeue a signal, and next_signal should choose the lowest-numbered signal, in this case SIGTRAP. But obviously that's not normally what happens. Hmm...

  20. rocallahan commented on Nov 8, 2016

    @rocallahan
    rocallahan
    on Nov 8, 2016
    Collaborator

    Ah, I can reproduce this in a small testcase now --- it happens when we synthesize a SIGSYS for an untraced syscall.

    For traced syscalls the synthetic SIGSYS works because we exit the syscall via PTRACE_SYSCALL before trying to deliver the SIGSYS, so tracehook_report_syscall_exit is called with step=0. While in that syscall-exit ptrace-stop, rr sends the SIGSYS which is then reported via the ptrace signal-stop while the tracee is in exit_to_usermode_loop. When we PTRACE_SINGLESTEP from that signal-stop, no SIGTRAP is generated, we just transition to the signal handler. (I don't know exactly how that works but rr has depended on that forever.)

    For untraced syscalls we aren't exiting the syscall via PTRACE_SYSCALL (because we don't need to normally), so we're trying to deliver our synthetic SIGSYS directly in the seccomp ptrace-stop. We send the signal and do a PTRACE_SINGLESTEP and from the seccomp ptrace-stop that triggers a SIGTRAP.

    I'll get some sleep and look more into this tomorrow.

  21. rocallahan
    closed this as completedin dfb6237on Nov 8, 2016

  22. mjfroman commented on Nov 10, 2016

    @mjfroman
    mjfroman
    on Nov 10, 2016
    Author

    Thank you! Just verified it is fixed here.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

No labels
No labels

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions