1604719 - Intermittent dom/serviceworkers/test/test_file_upload.html | application crashed [@ PR_MD_LSEEK64(PRFileDesc*, long long, PRSeekWhence)]

Status: RESOLVED FIXED

(Core :: DOM: Service Workers, defect, P1)

Description

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

---

[task 2019-12-18T06:30:49.161Z] 06:30:49     INFO - TEST-START | dom/serviceworkers/test/test_file_upload.html
[task 2019-12-18T06:30:49.544Z] 06:30:49     INFO - GECKO(6892) | Exiting due to channel error.
[task 2019-12-18T06:30:49.603Z] 06:30:49     INFO - TEST-INFO | Main app process: exit 1
[task 2019-12-18T06:30:49.603Z] 06:30:49     INFO - Buffered messages finished
[task 2019-12-18T06:30:49.603Z] 06:30:49    ERROR - TEST-UNEXPECTED-FAIL | dom/serviceworkers/test/test_file_upload.html | application terminated with exit code 1
[task 2019-12-18T06:30:49.603Z] 06:30:49     INFO - runtests.py | Application ran for: 0:00:16.333000
[task 2019-12-18T06:30:49.603Z] 06:30:49     INFO - zombiecheck | Reading PID log: c:\users\task_1576647597\appdata\local\temp\tmpzhveefpidlog
[task 2019-12-18T06:30:49.603Z] 06:30:49     INFO - ==> process 6268 launched child process 10544 ("Z:\task_1576647597\build\application\firefox\firefox.exe" -contentproc --channel="6268.0.703318828\765123766" -parentBuildID 20191218041155 -prefsHandle 2260 -prefMapHandle 2252 -prefsLen 1 -prefMapSize 224052 -greomni "Z:\task_1576647597\build\application\firefox\omni.ja" -appomni "Z:\task_1576647597\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1576647597\build\application\firefox\browser" - 6268 "\\.\pipe\gecko-crash-server-pipe.6268" 2332 gpu)
[task 2019-12-18T06:30:49.604Z] 06:30:49     INFO - ==> process 6268 launched child process 10668 ("Z:\task_1576647597\build\application\firefox\firefox.exe" -contentproc --channel="6268.6.1798182724\1297706831" -childID 1 -isForBrowser -prefsHandle 2948 -prefMapHandle 2944 -prefsLen 2195 -prefMapSize 224052 -parentBuildID 20191218041155 -greomni "Z:\task_1576647597\build\application\firefox\omni.ja" -appomni "Z:\task_1576647597\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1576647597\build\application\firefox\browser" - 6268 "\\.\pipe\gecko-crash-server-pipe.6268" 2964 tab)
[task 2019-12-18T06:30:49.604Z] 06:30:49     INFO - ==> process 6268 launched child process 6236 ("Z:\task_1576647597\build\application\firefox\firefox.exe" -contentproc --channel="6268.13.1963880540\1951959075" -childID 2 -isForBrowser -prefsHandle 3132 -prefMapHandle 3076 -prefsLen 2292 -prefMapSize 224052 -parentBuildID 20191218041155 -greomni "Z:\task_1576647597\build\application\firefox\omni.ja" -appomni "Z:\task_1576647597\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1576647597\build\application\firefox\browser" - 6268 "\\.\pipe\gecko-crash-server-pipe.6268" 3180 tab)
[task 2019-12-18T06:30:49.604Z] 06:30:49     INFO - ==> process 6268 launched child process 5820 ("Z:\task_1576647597\build\application\firefox\firefox.exe" -contentproc --channel="6268.20.1533643083\1399162574" -childID 3 -isForBrowser -prefsHandle 3164 -prefMapHandle 3156 -prefsLen 2353 -prefMapSize 224052 -parentBuildID 20191218041155 -greomni "Z:\task_1576647597\build\application\firefox\omni.ja" -appomni "Z:\task_1576647597\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1576647597\build\application\firefox\browser" - 6268 "\\.\pipe\gecko-crash-server-pipe.6268" 3376 tab)
[task 2019-12-18T06:30:49.604Z] 06:30:49     INFO - zombiecheck | Checking for orphan process with PID: 10544
[task 2019-12-18T06:30:49.604Z] 06:30:49     INFO - zombiecheck | Checking for orphan process with PID: 6236
[task 2019-12-18T06:30:49.604Z] 06:30:49     INFO - zombiecheck | Checking for orphan process with PID: 5820
[task 2019-12-18T06:30:49.604Z] 06:30:49     INFO - zombiecheck | Checking for orphan process with PID: 10668
[task 2019-12-18T06:30:49.604Z] 06:30:49     INFO - mozcrash Downloading symbols from: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/VY68Bu5PRRik8AzDDNrAsw/artifacts/public/build/target.crashreporter-symbols.zip
[task 2019-12-18T06:30:54.157Z] 06:30:54     INFO - mozcrash Copy/paste: Z:\task_1576647597\build\win32-minidump_stackwalk.exe c:\users\task_1576647597\appdata\local\temp\tmpdp5pmn.mozrunner\minidumps\d3173da6-9b72-4f68-923b-d5cbc3898c3e.dmp c:\users\task_1576647597\appdata\local\temp\tmp5xyhhd
[task 2019-12-18T06:31:03.115Z] 06:31:03     INFO - mozcrash Saved minidump as Z:\task_1576647597\build\blobber_upload_dir\d3173da6-9b72-4f68-923b-d5cbc3898c3e.dmp
[task 2019-12-18T06:31:03.115Z] 06:31:03     INFO - mozcrash Saved app info as Z:\task_1576647597\build\blobber_upload_dir\d3173da6-9b72-4f68-923b-d5cbc3898c3e.extra
[task 2019-12-18T06:31:03.189Z] 06:31:03     INFO - PROCESS-CRASH | dom/serviceworkers/test/test_file_upload.html | application crashed [@ PR_MD_LSEEK64(PRFileDesc*, long long, PRSeekWhence)]
[task 2019-12-18T06:31:03.189Z] 06:31:03     INFO - Crash dump filename: c:\users\task_1576647597\appdata\local\temp\tmpdp5pmn.mozrunner\minidumps\d3173da6-9b72-4f68-923b-d5cbc3898c3e.dmp
[task 2019-12-18T06:31:03.189Z] 06:31:03     INFO - Operating system: Windows NT
[task 2019-12-18T06:31:03.189Z] 06:31:03     INFO -                   10.0.17134 
[task 2019-12-18T06:31:03.189Z] 06:31:03     INFO - CPU: amd64
[task 2019-12-18T06:31:03.189Z] 06:31:03     INFO -      family 6 model 85 stepping 4
[task 2019-12-18T06:31:03.189Z] 06:31:03     INFO -      8 CPUs
[task 2019-12-18T06:31:03.189Z] 06:31:03     INFO - 
[task 2019-12-18T06:31:03.189Z] 06:31:03     INFO - GPU: UNKNOWN
[task 2019-12-18T06:31:03.189Z] 06:31:03     INFO - 
[task 2019-12-18T06:31:03.189Z] 06:31:03     INFO - Crash reason:  EXCEPTION_ACCESS_VIOLATION_READ
[task 2019-12-18T06:31:03.189Z] 06:31:03     INFO - Crash address: 0xffffffffffffffff
[task 2019-12-18T06:31:03.189Z] 06:31:03     INFO - Process uptime: 16 seconds
[task 2019-12-18T06:31:03.189Z] 06:31:03     INFO - 
[task 2019-12-18T06:31:03.189Z] 06:31:03     INFO - Thread 70 (crashed)
[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -  0  nss3.dll!PR_MD_LSEEK64(PRFileDesc*, long long, PRSeekWhence) [w95io.c:e928d60013446484acd63757ac883626b722f85d : 371 + 0x9]
[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -     rax = 0xe5e5e5e5e5e5e5e5   rdx = 0x0000000000000000
[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -     rcx = 0x0000019cbd8adaf0   rbx = 0x00000036ea4fef68
[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -     rsi = 0x0000019cbd8adaf0   rdi = 0x0000000000002000[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -     rbp = 0x0000000000000000   rsp = 0x00000036ea4fed70
[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -      r8 = 0x00000036ea4fed94    r9 = 0x0000000000000002
[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -     r10 = 0x0000000000000000   r11 = 0x0000000000000246
[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -     r12 = 0x00007ffe43a3bb20   r13 = 0x0000019caa01f680
[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -     r14 = 0x0000019cbff29180   r15 = 0x0000000000000000
[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -     rip = 0x00007ffe43bbf7fb
[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -     Found by: given as instruction pointer in context
[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -  1  nss3.dll!FileAvailable64(PRFileDesc*) [prfile.c:e928d60013446484acd63757ac883626b722f85d : 140 + 0x10]
[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -     rbx = 0x00000036ea4fef68   rbp = 0x0000000000000000
[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -     rsp = 0x00000036ea4fedb0   r12 = 0x00007ffe43a3bb20
[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -     r13 = 0x0000019caa01f680   r14 = 0x0000019cbff29180
[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -     r15 = 0x0000000000000000   rip = 0x00007ffe43bb95ff
[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -     Found by: call frame info
[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -  2  xul.dll!nsFileStreamBase::Available(unsigned long long*) [nsFileStreams.cpp:e928d60013446484acd63757ac883626b722f85d : 183 + 0x6]
[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -     rbx = 0x00000036ea4fef68   rbp = 0x0000000000000000
[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -     rsp = 0x00000036ea4fedf0   r12 = 0x00007ffe43a3bb20
[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -     r13 = 0x0000019caa01f680   r14 = 0x0000019cbff29180
[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -     r15 = 0x0000000000000000   rip = 0x00007ffe0d99f943
[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -     Found by: call frame info
[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -  3  xul.dll!mozilla::`anonymous namespace'::AvailableEvent::Run() [InputStreamLengthHelper.cpp:e928d60013446484acd63757ac883626b722f85d : 35 + 0xb]
[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -     rbx = 0x00000036ea4fef68   rbp = 0x0000000000000000
[task 2019-12-18T06:31:03.190Z] 06:31:03     INFO -     rsp = 0x00000036ea4fee30   r12 = 0x00007ffe43a3bb20
[task 2019-12-18T06:31:03.191Z] 06:31:03     INFO -     r13 = 0x0000019caa01f680   r14 = 0x0000019cbff29180
[task 2019-12-18T06:31:03.191Z] 06:31:03     INFO -     r15 = 0x0000000000000000   rip = 0x00007ffe0dceee80
[task 2019-12-18T06:31:03.191Z] 06:31:03     INFO -     Found by: call frame info
[task 2019-12-18T06:31:03.191Z] 06:31:03     INFO -  4  xul.dll!nsThreadPool::Run() [nsThreadPool.cpp:e928d60013446484acd63757ac883626b722f85d : 300 + 0x5]
[task 2019-12-18T06:31:03.191Z] 06:31:03     INFO -     rbx = 0x00000036ea4fef68   rbp = 0x0000000000000000
[task 2019-12-18T06:31:03.191Z] 06:31:03     INFO -     rsp = 0x00000036ea4feec0   r12 = 0x00007ffe43a3bb20
[task 2019-12-18T06:31:03.191Z] 06:31:03     INFO -     r13 = 0x0000019caa01f680   r14 = 0x0000019cbff29180
[task 2019-12-18T06:31:03.191Z] 06:31:03     INFO -     r15 = 0x0000000000000000   rip = 0x00007ffe0d596c9d
[task 2019-12-18T06:31:03.191Z] 06:31:03     INFO -     Found by: call frame info
[task 2019-12-18T06:31:03.191Z] 06:31:03     INFO -  5  xul.dll!nsThread::ProcessNextEvent(bool, bool*) [nsThread.cpp:e928d60013446484acd63757ac883626b722f85d : 1241 + 0x29]
[task 2019-12-18T06:31:03.191Z] 06:31:03     INFO -     rbx = 0x00000036ea4fef68   rbp = 0x0000000000000000
[task 2019-12-18T06:31:03.191Z] 06:31:03     INFO -     rsp = 0x00000036ea4ff050   r12 = 0x00007ffe43a3bb20
[task 2019-12-18T06:31:03.191Z] 06:31:03     INFO -     r13 = 0x0000019caa01f680   r14 = 0x0000019cbff29180
[task 2019-12-18T06:31:03.191Z] 06:31:03     INFO -     r15 = 0x0000000000000000   rip = 0x00007ffe0d4fbe17
[task 2019-12-18T06:31:03.191Z] 06:31:03     INFO -     Found by: call frame info
[task 2019-12-18T06:31:03.191Z] 06:31:03     INFO -  6  xul.dll!NS_ProcessNextEvent(nsIThread*, bool) [nsThreadUtils.cpp:e928d60013446484acd63757ac883626b722f85d : 486 + 0x26]
[task 2019-12-18T06:31:03.191Z] 06:31:03     INFO -     rbx = 0x00000036ea4fef68   rbp = 0x0000000000000000
[task 2019-12-18T06:31:03.191Z] 06:31:03     INFO -     rsp = 0x00000036ea4ff5f0   r12 = 0x00007ffe43a3bb20[task 2019-12-18T06:31:03.191Z] 06:31:03     INFO -     r13 = 0x0000019caa01f680   r14 = 0x0000019cbff29180
[task 2019-12-18T06:31:03.191Z] 06:31:03     INFO -     r15 = 0x0000000000000000   rip = 0x00007ffe0d4fa855
[task 2019-12-18T06:31:03.191Z] 06:31:03     INFO -     Found by: call frame info
[task 2019-12-18T06:31:03.191Z] 06:31:03     INFO -  7  xul.dll!mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) [MessagePump.cpp:e928d60013446484acd63757ac883626b722f85d : 332 + 0xa]
[task 2019-12-18T06:31:03.191Z] 06:31:03     INFO -     rbx = 0x00000036ea4fef68   rbp = 0x0000000000000000
[task 2019-12-18T06:31:03.191Z] 06:31:03     INFO -     rsp = 0x00000036ea4ff640   r12 = 0x00007ffe43a3bb20
[task 2019-12-18T06:31:03.191Z] 06:31:03     INFO -     r13 = 0x0000019caa01f680   r14 = 0x0000019cbff29180
[task 2019-12-18T06:31:03.192Z] 06:31:03     INFO -     r15 = 0x0000000000000000   rip = 0x00007ffe0d4fa64f
[task 2019-12-18T06:31:03.192Z] 06:31:03     INFO -     Found by: call frame info
[task 2019-12-18T06:31:03.192Z] 06:31:03     INFO -  8  xul.dll!MessageLoop::RunHandler() [message_loop.cc:e928d60013446484acd63757ac883626b722f85d : 308 + 0xf]
[task 2019-12-18T06:31:03.192Z] 06:31:03     INFO -     rbx = 0x00000036ea4fef68   rbp = 0x0000000000000000
[task 2019-12-18T06:31:03.192Z] 06:31:03     INFO -     rsp = 0x00000036ea4ff6b0   r12 = 0x00007ffe43a3bb20
[task 2019-12-18T06:31:03.192Z] 06:31:03     INFO -     r13 = 0x0000019caa01f680   r14 = 0x0000019cbff29180
[task 2019-12-18T06:31:03.192Z] 06:31:03     INFO -     r15 = 0x0000000000000000   rip = 0x00007ffe0d4df968
[task 2019-12-18T06:31:03.192Z] 06:31:03     INFO -     Found by: call frame info
[task 2019-12-18T06:31:03.192Z] 06:31:03     INFO -  9  xul.dll!MessageLoop::Run() [message_loop.cc:e928d60013446484acd63757ac883626b722f85d : 290 + 0x5]
[task 2019-12-18T06:31:03.192Z] 06:31:03     INFO -     rbx = 0x00000036ea4fef68   rbp = 0x0000000000000000
[task 2019-12-18T06:31:03.192Z] 06:31:03     INFO -     rsp = 0x00000036ea4ff700   r12 = 0x00007ffe43a3bb20
[task 2019-12-18T06:31:03.192Z] 06:31:03     INFO -     r13 = 0x0000019caa01f680   r14 = 0x0000019cbff29180
[task 2019-12-18T06:31:03.192Z] 06:31:03     INFO -     r15 = 0x0000000000000000   rip = 0x00007ffe0d4fa4a1
[task 2019-12-18T06:31:03.192Z] 06:31:03     INFO -     Found by: call frame info
[task 2019-12-18T06:31:03.192Z] 06:31:03     INFO - 10  xul.dll!static nsThread::ThreadFunc(void*) [nsThread.cpp:e928d60013446484acd63757ac883626b722f85d : 459 + 0x8]
[task 2019-12-18T06:31:03.192Z] 06:31:03     INFO -     rbx = 0x00000036ea4fef68   rbp = 0x0000000000000000
[task 2019-12-18T06:31:03.192Z] 06:31:03     INFO -     rsp = 0x00000036ea4ff750   r12 = 0x00007ffe43a3bb20
[task 2019-12-18T06:31:03.192Z] 06:31:03     INFO -     r13 = 0x0000019caa01f680   r14 = 0x0000019cbff29180
[task 2019-12-18T06:31:03.192Z] 06:31:03     INFO -     r15 = 0x0000000000000000   rip = 0x00007ffe0d4fa150
[task 2019-12-18T06:31:03.192Z] 06:31:03     INFO -     Found by: call frame info
[task 2019-12-18T06:31:03.192Z] 06:31:03     INFO - 11  nss3.dll!_PR_NativeRunThread(void*) [pruthr.c:e928d60013446484acd63757ac883626b722f85d : 399 + 0xa]
[task 2019-12-18T06:31:03.192Z] 06:31:03     INFO -     rbx = 0x00000036ea4fef68   rbp = 0x0000000000000000
[task 2019-12-18T06:31:03.192Z] 06:31:03     INFO -     rsp = 0x00000036ea4ff7c0   r12 = 0x00007ffe43a3bb20
[task 2019-12-18T06:31:03.192Z] 06:31:03     INFO -     r13 = 0x0000019caa01f680   r14 = 0x0000019cbff29180
[task 2019-12-18T06:31:03.192Z] 06:31:03     INFO -     r15 = 0x0000000000000000   rip = 0x00007ffe43bd423c
[task 2019-12-18T06:31:03.193Z] 06:31:03     INFO -     Found by: call frame info
[task 2019-12-18T06:31:03.193Z] 06:31:03     INFO - 12  nss3.dll!pr_root(void*) [w95thred.c:e928d60013446484acd63757ac883626b722f85d : 139 + 0x6]
[task 2019-12-18T06:31:03.193Z] 06:31:03     INFO -     rbx = 0x00000036ea4fef68   rbp = 0x0000000000000000
[task 2019-12-18T06:31:03.193Z] 06:31:03     INFO -     rsp = 0x00000036ea4ff840   r12 = 0x00007ffe43a3bb20
[task 2019-12-18T06:31:03.193Z] 06:31:03     INFO -     r13 = 0x0000019caa01f680   r14 = 0x0000019cbff29180
[task 2019-12-18T06:31:03.193Z] 06:31:03     INFO -     r15 = 0x0000000000000000   rip = 0x00007ffe43bc1a3a
[task 2019-12-18T06:31:03.193Z] 06:31:03     INFO -     Found by: call frame info[task 2019-12-18T06:31:03.193Z] 06:31:03     INFO - 13  ucrtbase.dll!guard_dispatch_icall_nop + 0x11b5e
[task 2019-12-18T06:31:03.193Z] 06:31:03     INFO -     rbx = 0x00000036ea4fef68   rbp = 0x0000000000000000
[task 2019-12-18T06:31:03.193Z] 06:31:03     INFO -     rsp = 0x00000036ea4ff870   r12 = 0x00007ffe43a3bb20
[task 2019-12-18T06:31:03.193Z] 06:31:03     INFO -     r13 = 0x0000019caa01f680   r14 = 0x0000019cbff29180
[task 2019-12-18T06:31:03.193Z] 06:31:03     INFO -     r15 = 0x0000000000000000   rip = 0x00007ffe4e6bc4be
[task 2019-12-18T06:31:03.193Z] 06:31:03     INFO -     Found by: call frame info
[task 2019-12-18T06:31:03.193Z] 06:31:03     INFO - 14  kernel32.dll!guard_dispatch_icall_nop + 0x86d4
[task 2019-12-18T06:31:03.193Z] 06:31:03     INFO -     rsp = 0x00000036ea4ff8a0   rip = 0x00007ffe503f3034
[task 2019-12-18T06:31:03.193Z] 06:31:03     INFO -     Found by: stack scanning
[task 2019-12-18T06:31:03.193Z] 06:31:03     INFO - 15  ntdll.dll!guard_dispatch_icall_nop + 0x66b01
[task 2019-12-18T06:31:03.193Z] 06:31:03     INFO -     rsp = 0x00000036ea4ff8d0   rip = 0x00007ffe513a1461
[task 2019-12-18T06:31:03.193Z] 06:31:03     INFO -     Found by: stack scanning
[task 2019-12-18T06:31:03.193Z] 06:31:03     INFO - 16  KERNELBASE.dll!guard_dispatch_icall_nop + 0xe15b0
[task 2019-12-18T06:31:03.193Z] 06:31:03     INFO -     rsp = 0x00000036ea4ff900   rip = 0x00007ffe4e40bf10
[task 2019-12-18T06:31:03.193Z] 06:31:03     INFO -     Found by: stack scanning

Comment 1

[Intermittent Failures Robot]

1 failures in 4582 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows10-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1604719&startday=2019-12-16&endday=2019-12-22&tree=all

Comment 2

[Intermittent Failures Robot]

1 failures in 1862 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows10-64-shippable-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1604719&startday=2019-12-30&endday=2020-01-05&tree=all

Comment 3

[Intermittent Failures Robot]

1 failures in 3773 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1

Platform breakdown:

• windows7-32-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1604719&startday=2020-01-13&endday=2020-01-19&tree=all

Comment 4

[Jens Stutte [:jstutte]]

Looking at the call stack of the crash, it seems that mFD is nullptr in the call to nsresult nsFileStreamBase::Available(uint64_t* aResult).

As mFD is set to nullptr when the file is closed AND we seem to be in an asynchronous AvailableEvent::Run() event handler, I assume, there is an order problem. This might be mitigated through a check in nsresult nsFileStreamBase::Available(uint64_t* aResult) - if the file is closed, it's not available.

:ttung, as you are looking at different issues with file handling, maybe this makes ring something in your head for other issues?

Comment 5

[Jens Stutte [:jstutte]]

So nsresult nsFileStreamBase::Available(uint64_t* aResult) uses nsresult nsFileStreamBase::DoPendingOpen() to check, if we have a valid mFD, it seems (and we have a shippable non-debug build, so the assertions in there won't happen). Still I must assume, that mFD is nullptr later in the call.

I have no evidence, but as nsFileStreamBase seems not to be thread-safe, a possible explanation could be a race condition on the nsFileStreamBase instance (something happens on a different thread between the DoPendingOpen() and the PR_Available64(mFD)). The very rare occurrences kind of second that.

Comment 6

[Tom Tung [:tt, :ttung]]

It does look like mFD is a nullptr, but I wasn't able to read the mini dump from the try.

I suspect Firefox gets crash or fail on other places earlier when it's a debug build since there is no fail/crash on the non-opt build.

I'll look into the code around to see if I can get more evidence to verify our guess and thus provide a fix/mitigation.

Comment 7

[Intermittent Failures Robot]

1 failures in 2190 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1

Platform breakdown:

• windows7-32-devedition: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1604719&startday=2020-01-27&endday=2020-02-02&tree=all

Comment 8

[Intermittent Failures Robot]

1 failures in 3364 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows10-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1604719&startday=2020-02-03&endday=2020-02-09&tree=all

Comment 9

[Jens Stutte [:jstutte]]

The occurrence in comment 8 seems to be in a totally different place.

Comment 10

[Intermittent Failures Robot]

1 failures in 4690 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows10-64-shippable-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1604719&startday=2020-02-10&endday=2020-02-16&tree=all

Comment 11

[Intermittent Failures Robot]

1 failures in 4045 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1

Platform breakdown:

• windows7-32-devedition: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1604719&startday=2020-02-17&endday=2020-02-23&tree=all

Comment 15

[Tom Tung [:tt, :ttung]]

I will check if there is only one caller to dispatch an AvailableEvent. If there is only one, then we might be able to narrow down the possible call pathes.

Comment 16

[Tom Tung [:tt, :ttung]]

(In reply to Tom Tung [:tt, :ttung] from comment #15)

I will check if there is only one caller to dispatch an AvailableEvent. If there is only one, then we might be able to narrow down the possible call pathes.

It is called twice and both of them are from here.

Comment 17

[Tom Tung [:tt, :ttung]]

(In reply to Tom Tung [:tt, :ttung] from comment #16)

(In reply to Tom Tung [:tt, :ttung] from comment #15)

I will check if there is only one caller to dispatch an AvailableEvent. If there is only one, then we might be able to narrow down the possible call pathes.

It is called twice and both of them are from here.

Below is the log I added for these two calls in the test (I print ${this} ${threadName} ${functionName}):

 0:21.20 GECKO(50875) [TT] 0x60d00033d600 StreamTrans #13 nsresult nsFileStreamBase::Available(uint64_t *)
 0:21.20 GECKO(50875) [TT] 0x60d00033d600 StreamTrans #13 nsresult nsFileStreamBase::DoPendingOpen()
 0:21.20 GECKO(50875) [TT] 0x60d00033d600 StreamTrans #13 virtual nsresult nsFileStreamBase::DoOpen()
 0:21.20 GECKO(50875) [TT] 0x60d00033d600 Main Thread nsresult nsFileInputStream::SeekInternal(int32_t, int64_t, bool)
 0:21.20 GECKO(50875) [TT] 0x60d00033d600 Main Thread nsresult nsFileStreamBase::DoPendingOpen()
 0:21.20 GECKO(50875) [TT] 0x60d00033d600 Main Thread virtual nsresult nsFileStreamBase::Seek(int32_t, int64_t)
 0:21.20 GECKO(50875) [TT] 0x60d00033d600 Main Thread nsresult nsFileStreamBase::DoPendingOpen()

 0:21.21 GECKO(50875) [TT] 0x60d000220b20 StreamTrans #17 nsresult nsFileStreamBase::Available(uint64_t *)
 0:21.21 GECKO(50875) [TT] 0x60d000220b20 StreamTrans #17 nsresult nsFileStreamBase::DoPendingOpen()
 0:21.21 GECKO(50875) [TT] 0x60d000220b20 StreamTrans #4 nsresult nsFileStreamBase::Read(char *, uint32_t, uint32_t *)
 0:21.21 GECKO(50875) [TT] 0x60d000220b20 StreamTrans #4 nsresult nsFileStreamBase::DoPendingOpen()
 0:21.21 GECKO(50875) [TT] 0x60d000220b20 StreamTrans #4 nsresult nsFileStreamBase::Read(char *, uint32_t, uint32_t *)
 0:21.21 GECKO(50875) [TT] 0x60d000220b20 StreamTrans #4 nsresult nsFileStreamBase::DoPendingOpen()
 0:21.21 GECKO(50875) [TT] 0x60d000220b20 StreamTrans #4 nsresult nsFileStreamBase::Read(char *, uint32_t, uint32_t *)
 0:21.21 GECKO(50875) [TT] 0x60d000220b20 StreamTrans #4 nsresult nsFileStreamBase::DoPendingOpen()
 0:21.21 GECKO(50875) [TT] 0x60d000220b20 StreamTrans #4 nsresult nsFileStreamBase::Read(char *, uint32_t, uint32_t *)
 0:21.21 GECKO(50875) [TT] 0x60d000220b20 StreamTrans #4 nsresult nsFileStreamBase::DoPendingOpen()
 0:21.21 GECKO(50875) [TT] 0x60d000220b20 StreamTrans #4 nsresult nsFileStreamBase::Read(char *, uint32_t, uint32_t *)
 0:21.21 GECKO(50875) [TT] 0x60d000220b20 StreamTrans #4 nsresult nsFileStreamBase::DoPendingOpen()
 0:21.21 GECKO(50875) [TT] 0x60d000220b20 StreamTrans #4 nsresult nsFileStreamBase::Read(char *, uint32_t, uint32_t *)
 0:21.21 GECKO(50875) [TT] 0x60d000220b20 StreamTrans #4 nsresult nsFileStreamBase::DoPendingOpen()
 0:21.21 GECKO(50875) [TT] 0x60d000220b20 StreamTrans #4 nsresult nsFileStreamBase::Read(char *, uint32_t, uint32_t *)
 0:21.21 GECKO(50875) [TT] 0x60d000220b20 StreamTrans #4 nsresult nsFileStreamBase::DoPendingOpen()
 0:21.21 GECKO(50875) [TT] 0x60d000220b20 StreamTrans #4 nsresult nsFileStreamBase::Read(char *, uint32_t, uint32_t *)
 0:21.21 GECKO(50875) [TT] 0x60d000220b20 StreamTrans #4 nsresult nsFileStreamBase::DoPendingOpen()
 0:21.21 GECKO(50875) [TT] 0x60d000220b20 StreamTrans #4 nsresult nsFileStreamBase::Close()
 0:21.21 GECKO(50875) [TT] 0x60d000220b20 StreamTrans #4 nsresult nsFileStreamBase::Close()

It looks like two threads access the same instance in a short time for both calls.
The next step is to check if we guarantee the order of them.

Comment 18

[Tom Tung [:tt, :ttung]]

(In reply to Tom Tung [:tt, :ttung] from comment #17)

 0:21.21 GECKO(50875) [TT] 0x60d000220b20 StreamTrans #17 nsresult nsFileStreamBase::Available(uint64_t *)
 0:21.21 GECKO(50875) [TT] 0x60d000220b20 StreamTrans #17 nsresult nsFileStreamBase::DoPendingOpen()

I wonder if the Read below is triggered by https://searchfox.org/mozilla-central/rev/96f1457323cc598a36f5701f8e67aedaf97acfcf/netwerk/protocol/http/HttpChannelParent.cpp#680
If it's, then it looks like it's possible to close the Stream during checking Available

0:21.21 GECKO(50875) [TT] 0x60d000220b20 StreamTrans #4 nsresult nsFileStreamBase::Read(char *, uint32_t, uint32_t *)

Comment 19

[Tom Tung [:tt, :ttung]]

In HttpChannelParent::DoAsyncOpen (Main thread)

1. AsyncGetLength (which dispatchs a task to call nsFileStreamBase::Available via StreamTransportService)
2. mChannel->EnsureUploadStreamIsCloneable(r) (which will call NS_AsyncCopy and consequently call nsFileStreamBase::Read and nsFileStreamBase::Close)

This is probably because nsFileStreamBase::Close is called after https://searchfox.org/mozilla-central/rev/96f1457323cc598a36f5701f8e67aedaf97acfcf/netwerk/base/nsFileStreams.cpp#179 but before https://searchfox.org/mozilla-central/rev/96f1457323cc598a36f5701f8e67aedaf97acfcf/netwerk/base/nsFileStreams.cpp#183

I'm considering if adding mutex in nsFileStreams would help or not.

Comment 20

[Tom Tung [:tt, :ttung]]

Hmm, I couldn't reproduce this with rr choas mode. Given the test failure/crash rate is rather low. I'm not so sure if I should keep looking into htis or not.

Comment 21

[Tom Tung [:tt, :ttung]]

Unassign myself since the crash rate is rather low. Will revisit it if it goes higher or if we get requests from others.

Comment 22

[Intermittent Failures Robot]

4 failures in 5233 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 1
• try: 3

Platform breakdown:

• windows7-32-shippable: 1
• windows7-32-devedition: 1
• linux1804-64-shippable: 1
• windows10-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1604719&startday=2020-02-24&endday=2020-03-01&tree=all

Comment 23

[Intermittent Failures Robot]

2 failures in 5483 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1
• autoland: 1

Platform breakdown:

• windows7-32-shippable: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1604719&startday=2020-03-02&endday=2020-03-08&tree=all

Comment 24

[Intermittent Failures Robot]

1 failures in 5336 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1

Platform breakdown:

• windows10-64-shippable-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1604719&startday=2020-03-09&endday=2020-03-15&tree=all

Comment 25

[Intermittent Failures Robot]

2 failures in 4955 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1
• try: 1

Platform breakdown:

• windows7-32-shippable: 1
• windows10-64-shippable-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1604719&startday=2020-03-16&endday=2020-03-22&tree=all

Comment 26

[Intermittent Failures Robot]

2 failures in 4773 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1
• autoland: 1

Platform breakdown:

• windows10-64-devedition: 1
• windows10-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1604719&startday=2020-03-23&endday=2020-03-29&tree=all

Comment 27

[Intermittent Failures Robot]

4 failures in 5015 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 3
• try: 1

Platform breakdown:

• linux1804-64-shippable: 1
• windows7-32-shippable: 1
• windows10-64-qr: 1
• windows10-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1604719&startday=2020-03-30&endday=2020-04-05&tree=all

Comment 28

[Intermittent Failures Robot]

1 failures in 4823 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows7-32-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1604719&startday=2020-04-06&endday=2020-04-12&tree=all

Comment 29

[Intermittent Failures Robot]

2 failures in 4528 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1
• autoland: 1

Platform breakdown:

• windows7-32-shippable: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1604719&startday=2020-04-13&endday=2020-04-19&tree=all

Comment 30

[Intermittent Failures Robot]

1 failures in 5582 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1

Platform breakdown:

• windows7-32-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1604719&startday=2020-04-20&endday=2020-04-26&tree=all

Comment 31

[Intermittent Failures Robot]

1 failures in 5423 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows10-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1604719&startday=2020-04-27&endday=2020-05-03&tree=all

Comment 32

[Jens Stutte [:jstutte]]

We acquire a strong reference to the stream which we then pass as a raw pointer to an async function. If (for some order problem in the event loop or even parallel execution) the last strong reference on the stream gets lost, before this event is fetched, we are screwed.

I assume, there is a way to avoid this order and/or parallelism problem, but probably first we should ensure, our object is not freed if we can know that we still need it in that async event. The easiest way might be to pass a strong/weak reference instead of the raw pointer?

Comment 33

[Jens Stutte [:jstutte]]

Daniel, I suspect a UAF here. Relevant?

Comment 34

[Daniel Veditz [:dveditz]]

In the handful of logs I looked at here rax = 0xe5e5e5e5e5e5e5e5 -- clearly a UAF. Given the async calls maybe also a race?

There are very few crashes in the wild, but those also look like UAF:
https://crash-stats.mozilla.org/report/index/df824716-d773-4e2d-9299-492cd0200212#tab-rawdump

Comment 35

[Daniel Veditz [:dveditz]]

The crashing test here is dom/serviceworkers/test/test_file_upload.html -- does that mean it likely requires user interaction uploading a file to trigger? That would lower the severity to sec-moderate. Or is it just coincidence that's the action involved here and it could be triggered with other actions?

Comment 36

[Jens Stutte [:jstutte]]

(In reply to Jens Stutte [:jstutte] from comment #32)

I assume, there is a way to avoid this order and/or parallelism problem, but probably first we should ensure, our object is not freed if we can know that we still need it in that async event. The easiest way might be to pass a strong/weak reference instead of the raw pointer?

(In reply to Daniel Veditz [:dveditz] from comment #34)

Given the async calls maybe also a race?

Given the (short) lifetime of the stream raw pointer while passing it into AvailableEvent(nsIInputStream* stream, … I suspect a rare race here (AvailableEvent stores the passed raw pointer then into a nsComPtr).

Comment 38

[Ryan VanderMeulen [:RyanVM]]

Hi Andrew, any updates on this bug?

Comment 39

[Andrew Sutherland [:asuth] (he/him)]

I believe this was a null deref of mFD on nsFileStreamBase which is fixed by Bug 1622451 and am currently verifying this.

• Assuming true, this wants an extra mFD guard as a separate bug (may involve ordering-related fixes), and the bug can be duped.
• Crashes for this started in Firefox 74 and ended in Firefox 77 which is consistent with parent-intercept enabling (74) and the fix only landing in 78.

Comment 40

[Jens Stutte [:jstutte]]

(In reply to Andrew Sutherland [:asuth] (he/him) from comment #39)

I believe this was a null deref of mFD on nsFileStreamBase which is fixed by Bug 1622451 and am currently verifying this.

• Assuming true, this wants an extra mFD guard as a separate bug (may involve ordering-related fixes), and the bug can be duped.
• Crashes for this started in Firefox 74 and ended in Firefox 77 which is consistent with parent-intercept enabling (74) and the fix only landing in 78.

Hi Andrew, do we have more confidence now that bug 1622451 fixed this? Which would mean also, it is fixed in ESR 78, too? Then I would probably just want to close this bug, as it looks too rare to be really exploitable and thus an uplift to ESR 68 is not really needed (tbc by :dveditz, of course)? Can you please file the follow up one?

Comment 41

[Jens Stutte [:jstutte]]

The three crashes I see now are different, it seems.

They all point to nsZipHandle::Init. This could happen, if OpenNSPRFileDesc returned NS_OK but did not create a valid FD for some reason. There seems to be the theoretic possibility that ConvertWinError returns NS_OK, though it sounds unlikely that GetLastError did return 0. But a ConvertWinErrorfunction that may return NS_OK seems odd.

In any case these are most likely no UAF and thus less scary. Daniel, should we move the component and re-triage this bug or create a follow up one?

Comment 42

[Daniel Veditz [:dveditz]]

The crashes in the wild reported to crash-stats were never all that common, but yes, the 3 reported in the last month against Fx79.0 are different from the earlier ones. The new ones are start-up crashes on the main thread opening omni.ja. I think it's fair to call the original bug (intermittent filed against a specific Service Worker testcase) FIXED or WORKSFORME.

I don't know if it's worth opening a new bug for comment 41 but I would NOT morph this bug to cover that case. If you do open a new bug it doesn't look like it needs to be a security bug.

Comment 43

[Jens Stutte [:jstutte]]

I filed bug 1663854 for comment 41.

And I resolved WORKSFORME bug 1617463, making point bug 1617464 and bug 1617465 as DUPLICATES there.

Thus I would close this one as FIXED through bug 1622451 without marking it as duplicate here.

Comment 44

[Jens Stutte [:jstutte]]

(In reply to Andrew Sutherland [:asuth] (he/him) from comment #39)

• Assuming true, this wants an extra mFD guard as a separate bug (may involve ordering-related fixes), and the bug can be duped.

Hi Andrew, can you file this bug, please? I am unsure what to say there exactly (without pointing here).

Comment 45

[Andrew Sutherland [:asuth] (he/him)]

(In reply to Jens Stutte [:jstutte] (REO for FF 81) from comment #44)

(In reply to Andrew Sutherland [:asuth] (he/him) from comment #39)

• Assuming true, this wants an extra mFD guard as a separate bug (may involve ordering-related fixes), and the bug can be duped.

Hi Andrew, can you file this bug, please? I am unsure what to say there exactly (without pointing here).

I filed bug 1664112. Note that I believe I mis-characterized the problem in that comment and your and Tom's analysis better captured the problem and potential solutions, so I've filed along those lines and the current callers which might want to address the problem at a higher level.