1080165 - Intermittent test_encryptedMediaExtensions.html | Failed to initialise MediaKeySession (with "Sandbox: seccomp sandbox violation, … syscall 141")

Reporter

Description

•

10 years ago

https://treeherder.mozilla.org/ui/logviewer.html#?job_id=2857362&repo=mozilla-inbound builder Ubuntu ASAN VM 12.04 x64 mozilla-inbound opt test mochitest-1 buildid 20141008095906 builduid 617796d675db477aa26ddf275941b0d3 results warnings (1) revision 0097b4ffaf33 slave tst-linux64-spot-318 starttime Wed Oct 08 2014 13:42:47 GMT-0400 (Eastern Standard Time) 11:03:09 INFO - 1781 INFO TEST-START | /tests/content/media/test/test_encryptedMediaExtensions.html 11:03:09 INFO - I/SampleTable( 2183): There are reordered frames present. 11:03:10 INFO - Sandbox: seccomp sandbox violation: pid 2993, syscall 141, args 0 2995 1 140443920623904 983040 9447184. Killing process. 11:03:10 INFO - 1782 INFO Started Wed Oct 08 2014 11:03:09 GMT-0700 (PDT) (1412791389.329s) 11:03:10 INFO - 1783 INFO TEST-PASS | /tests/content/media/test/test_encryptedMediaExtensions.html | [started short-cenc.mp4-0] Length of array should match number of running tests 11:03:10 INFO - 1784 INFO got encrypted event 11:03:10 INFO - 1785 INFO TEST-PASS | /tests/content/media/test/test_encryptedMediaExtensions.html | MediaKeys should support this keysystem 11:03:10 INFO - 1786 INFO created MediaKeys object ok 11:03:10 INFO - 1787 INFO set MediaKeys on <video> element ok 11:03:10 INFO - 1788 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_encryptedMediaExtensions.html | Failed to initialise MediaKeySession - expected PASS 11:03:10 INFO - 1789 INFO TEST-OK | /tests/content/media/test/test_encryptedMediaExtensions.html | took 1248ms The sandbox error looks possibly-relevant?

Comment hidden (Legacy TBPL/Treeherder Robot)

submit_timestamp: 2014-10-08T14:17:49 log: https://treeherder.mozilla.org/ui/logviewer.html#?repo=mozilla-inbound&job_id=2857362 repository: mozilla-inbound who: rvandermeulen[at]mozilla[dot]com machine: tst-linux64-spot-318 buildname: Ubuntu ASAN VM 12.04 x64 mozilla-inbound opt test mochitest-1 revision: 0097b4ffaf33 1788 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_encryptedMediaExtensions.html | Failed to initialise MediaKeySession - expected PASS 1793 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_error_in_video_document.html | Network state - got 1, expected 0 1794 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_error_in_video_document.html | Error object - didn't expect null, but got it 1804 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_fastSeek-forwards.html | Test timed out. - expected PASS 1812 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_fastSeek.html | Test timed out. - expected PASS 1818 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_fragment_noplay.html | Test timed out. - expected PASS 1824 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_fragment_play.html | Test timed out. - expected PASS 1825 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | 4 test timeouts, giving up. - expected PASS 1826 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | Skipping 467 remaining tests. - expected PASS 1829 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | /tests/content/media/test/test_fragment_play.html - finished in a non-clean fashion, probably because it didn't call SimpleTest.finish() 1831 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | undefined assertion name - Result logged after SimpleTest.finish() 1840 ERROR TEST-UNEXPECTED-TIMEOUT | /tests/content/media/test/test_fragment_play.html | application timed out after 330 seconds with no output 1841 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_fragment_play.html | application terminated with exit code -9 Return code: 247

Jed Davis [:jld] ⟨⏰|UTC-8⟩ ⟦he/him⟧

Assignee

Comment 2

•

10 years ago

I filed bug 1080077 about getting a call stack for these crashes (normally we would, via the crash reporter, but ASAN disables it), so that I can find out what is calling setpriority() after we're sandboxed rather than just guessing. My guess, for what it's worth, is that the NSPR thread creation stuff that does getpriority followed by setpriority (and skips the latter if the former fails) is racing with the sandbox startup. I don't know why that would start happening now. (I also don't like that it's even possible to have that kind of race condition, but there are larger windmills to tilt at.)

Jed Davis [:jld] ⟨⏰|UTC-8⟩ ⟦he/him⟧

Assignee

Updated

•

10 years ago

Comment 6

•

10 years ago

Comment #5 is a timeout that seems to be unrelated; there's no sandbox failure. (Bug 1082112: mozharness doesn't highlight the relevant log lines, even though it's seriously bad if they ever appear, so their presence/absence isn't obvious.) Comment #4 *is* a repro, with a stack trace thanks to bug 1080077: 15:33:48 INFO - Sandbox: seccomp sandbox violation: pid 2689, syscall 141, args 0 2691 1 139757464054048 983040 9447184. Killing process. 15:33:48 INFO - Sandbox: crash reporter is disabled (or failed); trying stack trace: 15:33:48 INFO - Sandbox: frame #01: setpriority[/lib/x86_64-linux-gnu/libc.so.6 +0xec407] 15:33:48 INFO - Sandbox: frame #02: ???[/builds/slave/test/build/application/firefox/libnspr4.so +0x681c5] 15:33:48 INFO - Sandbox: frame #03: ???[/lib/x86_64-linux-gnu/libpthread.so.0 +0x7e9a] 15:33:48 INFO - Sandbox: frame #04: clone[/lib/x86_64-linux-gnu/libc.so.6 +0xf3dbd] 15:33:48 INFO - Sandbox: end of stack. So, 0x681c5. Clear the Thumb bit, subtract 1, and ask addr2line: _pt_root /builds/slave/m-in-l64-asan-0000000000000000/build/nsprpub/pr/src/pthreads/ptthread.c:142 Which is this: 137 rv = getpriority(PRIO_PROCESS, 0); 138 139 /* If we cannot read the main thread's nice value don't try to change the 140 * new thread's nice value. */ 141 if (errno == 0) { => 142 setpriority(PRIO_PROCESS, tid, 143 pt_RelativePriority(rv, thred->priority)); 144 } So my guess in comment #2 was right, and this isn't actually ASAN-specific.

Assignee: nobody → jld

Blocks: 1021232

Summary: Intermittent test_encryptedMediaExtensions.html | Failed to initialise MediaKeySession → Intermittent test_encryptedMediaExtensions.html | Failed to initialise MediaKeySession (with "Sandbox: seccomp sandbox violation, … syscall 141")

Ryan VanderMeulen [:RyanVM]

Reporter

Comment 7

•

10 years ago

I filed bug 1083924 for comment 5 (and others like it).

Jed Davis [:jld] ⟨⏰|UTC-8⟩ ⟦he/him⟧

Assignee

Comment 8

•

10 years ago

(In reply to Jed Davis [:jld] from comment #6) > So, 0x681c5. Clear the Thumb bit, subtract 1, and ask addr2line: …and we can see here that it was too early in the morning when I wrote that, because this is amd64, not ARM. But it's still valid: 0x681c3 is inside the 5-byte call instruction at 0x681c0, so the debug info thusly indexed is correct. The important part, really, is that the caller doesn't care if the setpriority fails.

Jed Davis [:jld] ⟨⏰|UTC-8⟩ ⟦he/him⟧

Assignee

Comment 9

•

10 years ago

Attached patch bug1080165-setpriority-hg0.diff — Details — Splinter Review

Tested locally, and trying: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=f37fb87db34e

Attachment #8506350 - Flags: review?(gdestuynder)

Guillaume Destuynder [:kang] [this account is no longer active]

Updated

•

10 years ago

Attachment #8506350 - Flags: review?(gdestuynder) → review+

Jed Davis [:jld] ⟨⏰|UTC-8⟩ ⟦he/him⟧

Assignee

Comment 10

•

10 years ago

The try run in comment #9 is green.

Keywords: checkin-needed

Carsten Book [:Tomcat]

Comment 11

•

10 years ago

https://hg.mozilla.org/integration/mozilla-inbound/rev/11f1649bd31a

Keywords: checkin-needed

Carsten Book [:Tomcat]

Comment 12

•

10 years ago

https://hg.mozilla.org/mozilla-central/rev/11f1649bd31a

Status: NEW → RESOLVED

Closed: 10 years ago

Resolution: --- → FIXED

Target Milestone: --- → mozilla36

Ryan VanderMeulen [:RyanVM]

Reporter

Comment 13

•

10 years ago

Please request Aurora and Beta approval on this when you get a chance.

status-firefox34: --- → affected

status-firefox35: --- → affected

status-firefox36: --- → fixed

status-firefox-esr31: --- → unaffected

Flags: needinfo?(jld)

Jed Davis [:jld] ⟨⏰|UTC-8⟩ ⟦he/him⟧

Assignee

Comment 14

•

10 years ago

Comment on attachment 8506350 [details] [diff] [review] bug1080165-setpriority-hg0.diff Approval Request Comment [Feature/regressing bug #]: Bug 1012951 [User impact if declined]: Intermittent failure to start a media plugin. We've only seen this on automated ASAN runs, and not very often (see above), but in theory it could occur on regular builds. [Describe test coverage new/current, TBPL]: There are mochitests that run media plugins, including the one named in this bug's summary. [Risks and why]: Very little; this changes setpriority() from crashing to simply failing, for media plugins (OpenH264, EME) on Linux. The set of allowed system calls is unaffected. [String/UUID change made/needed]: None. Aurora try: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=168163563792 Beta try: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=fbaf4f1d5e75

Flags: needinfo?(jld)

Attachment #8506350 - Flags: approval-mozilla-beta?

Attachment #8506350 - Flags: approval-mozilla-aurora?

Lawrence Mandel [:lmandel] (use needinfo)

Updated

•

10 years ago

status-firefox33: --- → wontfix

Lawrence Mandel [:lmandel] (use needinfo)

Comment 15

•

10 years ago

Comment on attachment 8506350 [details] [diff] [review] bug1080165-setpriority-hg0.diff Beta+ Aurora+

Attachment #8506350 - Flags: approval-mozilla-beta?

Attachment #8506350 - Flags: approval-mozilla-beta+

Attachment #8506350 - Flags: approval-mozilla-aurora?

Attachment #8506350 - Flags: approval-mozilla-aurora+

Ryan VanderMeulen [:RyanVM]

Reporter

Comment 16

•

10 years ago

https://hg.mozilla.org/releases/mozilla-aurora/rev/67e21c3c700f https://hg.mozilla.org/releases/mozilla-beta/rev/5c014e511661

status-firefox34: affected → fixed

status-firefox35: affected → fixed