845283 - Intermittent dom/media/tests/crashtests/799419.html | Exited with code -1073741819 during test run | application crashed [@ msvcr100.dll + 0x7d101]

Status: RESOLVED FIXED

(Core :: WebRTC: Networking, defect, P1)

Description

[Ryan VanderMeulen [:RyanVM]]

https://tbpl.mozilla.org/php/getParsedLog.php?id=20094918&tree=Mozilla-Inbound

Rev3 WINNT 6.1 mozilla-inbound pgo test crashtest on 2013-02-26 00:50:52 PST for push 70814e7dbcb8
slave: talos-r3-w7-080

00:58:35     INFO -  REFTEST TEST-START | file:///C:/talos-slave/test/build/tests/reftest/tests/dom/media/tests/crashtests/799419.html | 534 / 2294 (23%)
00:58:36     INFO -  0[a11140]: CC_SIPCCCall Creating  CC_SIPCCCall 262148
00:58:36     INFO -  (ice/NOTICE) No STUN servers specified
00:58:36     INFO -  (ice/NOTICE) No TURN servers specified
00:58:36     INFO -  0[82fa4f0]: cpr SIPCC-CC_API: 4/4, cc_int_feature2: UI -> GSM: SETPEERCONNECTION
00:58:36     INFO -  0[82fd430]: cpr SIPCC-DCSM: dcsm_process_event: DCSM 22  :(DCSM_READY:SETPEERCONNECTION )
00:58:36     INFO -  0[82fd430]: cpr SIPCC-UI_API: ui_mnc_reached: line 4: Max number of calls reached =1
00:58:36     INFO -  0[82fd430]: cpr SIPCC-GSM: 4/4, sm_process_event: DEF   :(IDLE:SETPEERCONNECTION )
00:58:36     INFO -  0[82fa4f0]: CC_SIPCCService onLineEvent(CCAPI_LINE_EV_CAPSET_CHANGED, 4, [306837180|OOS]
00:58:36     INFO -  0[a11140]: CC_SIPCCCall Creating  CC_SIPCCCall 327685
00:58:38  WARNING -  TEST-UNEXPECTED-FAIL | file:///C:/talos-slave/test/build/tests/reftest/tests/dom/media/tests/crashtests/799419.html | Exited with code -1073741819 during test run
00:58:38  WARNING -  This is a harness error.
00:58:38     INFO -  INFO | automation.py | Application ran for: 0:02:24.434000
00:58:38     INFO -  INFO | automation.py | Reading PID log: c:\users\cltbld\appdata\local\temp\tmpy5g90gpidlog
00:58:38     INFO -  Downloading symbols from: http://ftp.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/mozilla-inbound-win32-pgo/1361855105/firefox-22.0a1.en-US.win32.crashreporter-symbols.zip
00:58:49     INFO -  PROCESS-CRASH | file:///C:/talos-slave/test/build/tests/reftest/tests/dom/media/tests/crashtests/799419.html | application crashed [@ msvcr100.dll + 0x7d101]
00:58:49     INFO -  Crash dump filename: c:\users\cltbld\appdata\local\temp\tmpva5dm7\minidumps\435ead2e-afb6-4123-b638-3cd09531d04b.dmp
00:58:49     INFO -  Operating system: Windows NT
00:58:49     INFO -                    6.1.7600
00:58:49     INFO -  CPU: x86
00:58:49     INFO -       GenuineIntel family 6 model 23 stepping 10
00:58:49     INFO -       2 CPUs
00:58:49     INFO -  Crash reason:  EXCEPTION_ACCESS_VIOLATION_READ
00:58:49     INFO -  Crash address: 0x5
00:58:49     INFO -  Thread 0 (crashed)
00:58:49     INFO -   0  msvcr100.dll + 0x7d101
00:58:49     INFO -      eip = 0x71a4d101   esp = 0x0021bd88   ebp = 0x0021c00c   ebx = 0x6c627013
00:58:49     INFO -      esi = 0x00000000   edi = 0x00000005   eax = 0x00000005   ecx = 0x7ffffffe
00:58:49     INFO -      edx = 0x00440173   efl = 0x00210202
00:58:49     INFO -      Found by: given as instruction pointer in context
00:58:49     INFO -   1  msvcr100.dll + 0x6710d
00:58:49     INFO -      eip = 0x71a3710e   esp = 0x0021c014   ebp = 0x0021c054
00:58:49     INFO -      Found by: previous frame's frame pointer
00:58:49     INFO -   2  msvcr100.dll + 0x671d5
00:58:49     INFO -      eip = 0x71a371d6   esp = 0x0021c05c   ebp = 0x0021c070
00:58:49     INFO -      Found by: previous frame's frame pointer
00:58:49     INFO -   3  xul.dll!stderr_vlog [r_log.c:70814e7dbcb8 : 377 + 0x17]
00:58:49     INFO -      eip = 0x6bbbc99a   esp = 0x0021c078   ebp = 0x0021c088
00:58:49     INFO -      Found by: previous frame's frame pointer
00:58:49     INFO -   4  xul.dll!r_vlog [r_log.c:70814e7dbcb8 : 357 + 0x9]
00:58:49     INFO -      eip = 0x6bced044   esp = 0x0021c090   ebp = 0x0021c0ac
00:58:49     INFO -      Found by: call frame info
00:58:49     INFO -   5  xul.dll!r_log [r_log.c:70814e7dbcb8 : 304 + 0x11]
00:58:49     INFO -      eip = 0x6bced071   esp = 0x0021c0b4   ebp = 0x0021c0c4
00:58:49     INFO -      Found by: call frame info
00:58:49     INFO -   6  xul.dll!nr_ice_ctx_create [ice_ctx.c:70814e7dbcb8 : 265 + 0x11]
00:58:49     INFO -      eip = 0x6be47889   esp = 0x0021c0cc   ebp = 0x0021c14c
00:58:49     INFO -      Found by: call frame info
00:58:49     INFO -   7  xul.dll!mozilla::NrIceCtx::Create(std::basic_string<char,std::char_traits<char>,std::allocator<char> > const &,bool,bool) [nricectx.cpp:70814e7dbcb8 : 290 + 0x23]
00:58:49     INFO -      eip = 0x6be49923   esp = 0x0021c154   ebp = 0x0021c1a4
00:58:49     INFO -      Found by: call frame info
00:58:49     INFO -   8  xul.dll!sipcc::PeerConnectionMedia::Init(std::vector<mozilla::NrIceStunServer,std::allocator<mozilla::NrIceStunServer> > const &) [PeerConnectionMedia.cpp:70814e7dbcb8 : 87 + 0x27]
00:58:49     INFO -      eip = 0x6b9323a1   esp = 0x0021c1ac   ebp = 0x0021c200
00:58:49     INFO -      Found by: call frame info

Comment 1

[Randell Jesup [:jesup] (needinfo me)]

Crashing here: (down in vfprintf())
      r_log(LOG_ICE,LOG_NOTICE,"No STUN servers specified");


There's a serious thread-safety issue in r_log(), though it may well be unrelated to this crash:

in r_vlog(), if r_log_env_verbose is set (and maybe it isn't in this case, but if it is) it does:

static char log_fmt_buf[MAX_ERROR_STRING_SIZE];
...
    if (r_log_env_verbose) {
      ...
      snprintf(log_fmt_buf, MAX_ERROR_STRING_SIZE, "(%s/%s) %s",
        facility_str,level_str,format);

      log_fmt_buf[MAX_ERROR_STRING_SIZE-1]=0;
      fmt_str=log_fmt_buf;
    }
    <effectively ends up calling vfprintf(stderr, fmt_str, ap)>

That's ok if it all happens from one thread.  It's not ok if used from different threads.  (Some other logging functions use different formats in that same static shared buffer.)

Probably the buffer should be on the stack...  Or if you prefer throw a lock around it.

Comment 2

[Adam Roach [:abr]]

Yes, verbose logging is turned on for the TBPL runs. It is realistic to think that the issue you describe is the root of this bug.

Comment 3

[Randell Jesup [:jesup] (needinfo me)]

s-s even though the reported crash is null-deref; in theory since it's a format-string thread-safety issue it could do more damage.

Comment 4

[Adam Roach [:abr]]

Attachment: Move formatting buffer onto the stack

Comment 5

[Eric Rescorla (:ekr)]

Comment on attachment 718473 [details] [diff] [review]
Move formatting buffer onto the stack

Review of attachment 718473 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good to me. You need to make sure you simultaneously uplift this to nrappkit.

Comment 6

[Adam Roach [:abr]]

Comment on attachment 718473 [details] [diff] [review]
Move formatting buffer onto the stack

> [Security approval request comment]
> How easily could an exploit be constructed based on the patch?

Determining the nature of the bug from the patch would be tricky. Going further to actually create an exploit would be very difficult, if it is even possible at all. This is a tricky race to evoke; actually controlling what gets written into the buffer would be even more difficult. On top of all of this, evoking the situation requires users to have manually set at least two environment variables, all of which are undocumented.

> Do comments in the patch, the check-in comment, or tests included in the patch paint a bulls-eye on the security problem?

No.

> Which older supported branches are affected by this flaw?

All WebRTC implementations to date, although the feature is preffed off except in Nightly and Aurora 21.

> If not all supported branches, which bug introduced the flaw?

The bug was introduced with the importation of the library

> Do you have backports for the affected branches? If not, how different, hard to create, and risky will they be?

The patch should work on all previous branches.

> How likely is this patch to cause regressions; how much testing does it need?

Chances of regression are virtually nonexistent. We're just moving a buffer from static memory to the stack.

Comment 7

[Adam Roach [:abr]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/6a225df3780e

Comment 8

[Adam Roach [:abr]]

Upstreamed to nrappkit:

Checking in src/log/r_log.c;
/cvsroot/nrappkit/nrappkit/src/log/r_log.c,v  <--  r_log.c
new revision: 1.11; previous revision: 1.10
done

Comment 9

[Adam Roach [:abr]]

Apparently moved into m-c without annotation in the bug; I'm marking as fixed:

https://hg.mozilla.org/mozilla-central/rev/6a225df3780e

Comment 10

[bhavana bajaj [:bajaj]]

(In reply to Adam Roach [:abr] from comment #7)
> https://hg.mozilla.org/integration/mozilla-inbound/rev/6a225df3780e

Can you please go ahead and request approval for aurora(fx21) uplift ?

Comment 11

[Randell Jesup [:jesup] (needinfo me)]

making sure it's on adams radar

Comment 12

[Adam Roach [:abr]]

Given that we're still preffed off for 21 beta and release (see Bug 853106), I'm marking this as disabled for 21.

Note: even when the pref is on, this bug requires a rather spectacular level of user complicity in order to present itself. The only way to trigger this bug is to have the user set an undocumented environment variable (not even a normal Mozilla logging variable, but something even more esoteric) and then evoke a race in the logging code. As far as I'm concerned, that's more bulletproof than a preffed-off feature, and we've been happy shipping "unsafe but preffed off" features.

Comment 14

[Alex Keybl [:akeybl]]

Not tracking given comment 12.