Closed Bug 1497029 Opened Last year Closed Last year

Perma failing ValueError: need more than 1 value to unpack after fix_stack_using_bpsyms.py

Categories

(Core :: XPCOM, defect, P1, critical)

defect

Tracking

()

RESOLVED FIXED
mozilla64
Tracking Status
firefox64 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: glandium)

References

Details

(Keywords: intermittent-failure)

Filed by: aiakab [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=203890898&repo=autoland

https://queue.taskcluster.net/v1/task/OLHGfYj4TRq4S439kWo7cw/runs/0/artifacts/public/logs/live_backing.log

TEST-START | accessible/tests/browser/events/browser_test_focus_urlbar.js
22:52:27     INFO - GECKO(5144) | Chrome file doesn't exist: Z:\task_1538865704\build\tests\mochitest\browser\accessible\tests\browser\layout.js
22:52:27     INFO - GECKO(5144) | ++DOCSHELL 0AF2D800 == 4 [pid = 4332] [id = {1f6770e0-1605-4011-9c0c-6e8e5bfec8e2}]
22:52:27     INFO - GECKO(5144) | ++DOMWINDOW == 11 (012C1A00) [pid = 4332] [serial = 11] [outer = 00000000]
22:52:27     INFO - GECKO(5144) | ++DOMWINDOW == 12 (0AFB6400) [pid = 4332] [serial = 12] [outer = 012C1A00]
22:52:27     INFO - GECKO(5144) | ++DOMWINDOW == 13 (0AFB7000) [pid = 4332] [serial = 13] [outer = 012C1A00]
22:52:27     INFO - GECKO(5144) | [Child 4332, Main Thread] WARNING: Resource acquired is being released in non-LIFO order; why?
22:52:27     INFO - GECKO(5144) | : file z:/build/build/src/xpcom/threads/BlockingResourceBase.cpp, line 356
22:52:27     INFO - GECKO(5144) | --- Mutex : mozilla::mscom::LiveSet::mMutex (currently acquired)
22:52:27     INFO - GECKO(5144) |  calling context
22:52:27     INFO - GECKO(5144) |   [stack trace unavailable]
22:52:29     INFO - GECKO(5144) | [Parent 5164, Main Thread] ###!!! ASSERTION: Wrong in offset: 'Error', file z:/build/build/src/accessible/generic/HyperTextAccessible.cpp, line 1236
22:52:48     INFO -  Exception in thread ProcessReader:
22:52:48     INFO -  Traceback (most recent call last):
22:52:48     INFO -    File "c:\mozilla-build\python\Lib\threading.py", line 801, in __bootstrap_inner
22:52:48     INFO -      self.run()
22:52:48     INFO -    File "c:\mozilla-build\python\Lib\threading.py", line 754, in run
22:52:48     INFO -      self.__target(*self.__args, **self.__kwargs)
22:52:48     INFO -    File "Z:\task_1538865704\build\venv\lib\site-packages\mozprocess\processhandler.py", line 1048, in _read
22:52:48     INFO -      callback(line.rstrip())
22:52:48     INFO -    File "Z:\task_1538865704\build\venv\lib\site-packages\mozprocess\processhandler.py", line 964, in __call__
22:52:48     INFO -      e(*args, **kwargs)
22:52:48     INFO -    File "Z:\task_1538865704\build\tests\mochitest\runtests.py", line 2962, in processOutputLine
22:52:48     INFO -      message = handler(message)
22:52:48     INFO -    File "Z:\task_1538865704\build\tests\mochitest\runtests.py", line 3049, in fix_stack
22:52:48     INFO -      message['data'] = self.stackFixerFunction(message['data'])
22:52:48     INFO -    File "Z:\task_1538865704\build\venv\lib\site-packages\mozrunner\utils.py", line 269, in stack_fixer_function
22:52:48     INFO -      return stack_fixer_module.fixSymbols(line, symbolsPath)
22:52:48     INFO -    File "Z:\task_1538865704\build\tests\bin\fix_stack_using_bpsyms.py", line 195, in fixSymbols
22:52:48     INFO -      symbol = addressToSymbol(file, address, symbolsDir)
22:52:48     INFO -    File "Z:\task_1538865704\build\tests\bin\fix_stack_using_bpsyms.py", line 179, in addressToSymbol
22:52:48     INFO -      p = getSymbolFile(file, symbolsDir)
22:52:48     INFO -    File "Z:\task_1538865704\build\tests\bin\fix_stack_using_bpsyms.py", line 169, in getSymbolFile
22:52:48     INFO -      p = SymbolFile(symfile)
22:52:48     INFO -    File "Z:\task_1538865704\build\tests\bin\fix_stack_using_bpsyms.py", line 76, in __init__
22:52:48     INFO -      (rva, size, line, filenum) = line.split(None)
22:52:48     INFO -  ValueError: need more than 1 value to unpack
22:52:49     INFO - TEST-INFO | Main app process: exit 0
22:52:49    ERROR - TEST-UNEXPECTED-FAIL | ShutdownLeaks | process() called before end of test suite
22:52:49     INFO - runtests.py | Application ran for: 0:00:28.575000
22:52:49     INFO - zombiecheck | Reading PID log: c:\users\task_1538865704\appdata\local\temp\tmplqydgzpidlog
22:52:49     INFO - ==> process 5164 launched child process 5560 ("Z:\task_1538865704\build\application\firefox\firefox.exe" -contentproc --channel="5164.0.1486111005\924026334" -childID 1 -isForBrowser -prefsHandle 2008 -prefMapHandle 2004 -prefsLen 1 -prefMapSize 188316 -schedulerPrefs 0001,2 -parentBuildID 20181006211422 -greomni "Z:\task_1538865704\build\application\firefox\omni.ja" -appomni "Z:\task_1538865704\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1538865704\build\application\firefox\browser" - 5164 "\\.\pipe\gecko-crash-server-pipe.5164" 2084 tab)
22:52:49     INFO - ==> process 5164 launched child process 5572 ("Z:\task_1538865704\build\application\firefox\firefox.exe" -contentproc --channel="5164.6.580687566\1775931526" -childID 2 -isForBrowser -prefsHandle 1944 -prefMapHandle 1912 -prefsLen 151 -prefMapSize 188316 -schedulerPrefs 0001,2 -parentBuildID 20181006211422 -greomni "Z:\task_1538865704\build\application\firefox\omni.ja" -appomni "Z:\task_1538865704\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1538865704\build\application\firefox\browser" - 5164 "\\.\pipe\gecko-crash-server-pipe.5164" 1952 tab)
22:52:49     INFO - ==> process 5164 launched child process 5864 ("Z:\task_1538865704\build\application\firefox\firefox.exe" -contentproc --channel="5164.12.213333767\154531457" -childID 3 -isForBrowser -prefsHandle 1912 -prefMapHandle 1616 -prefsLen 191 -prefMapSize 188316 -schedulerPrefs 0001,2 -parentBuildID 20181006211422 -greomni "Z:\task_1538865704\build\application\firefox\omni.ja" -appomni "Z:\task_1538865704\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1538865704\build\application\firefox\browser" - 5164 "\\.\pipe\gecko-crash-server-pipe.5164" 2308 tab)
22:52:49     INFO - ==> process 5164 launched child process 4332 ("Z:\task_1538865704\build\application\firefox\firefox.exe" -contentproc --channel="5164.18.907401476\1694430864" -childID 4 -isForBrowser -prefsHandle 3156 -prefMapHandle 3160 -prefsLen 6664 -prefMapSize 188316 -schedulerPrefs 0001,2 -parentBuildID 20181006211422 -greomni "Z:\task_1538865704\build\application\firefox\omni.ja" -appomni "Z:\task_1538865704\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1538865704\build\application\firefox\browser" - 5164 "\\.\pipe\gecko-crash-server-pipe.5164" 3172 tab)
22:52:49     INFO - ==> process 5164 launched child process 4124 ("Z:\task_1538865704\build\application\firefox\firefox.exe" -contentproc --channel="5164.24.1987404071\647555377" -childID 5 -isForBrowser -prefsHandle 3320 -prefMapHandle 3404 -prefsLen 6664 -prefMapSize 188316 -schedulerPrefs 0001,2 -parentBuildID 20181006211422 -greomni "Z:\task_1538865704\build\application\firefox\omni.ja" -appomni "Z:\task_1538865704\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1538865704\build\application\firefox\browser" - 5164 "\\.\pipe\gecko-crash-server-pipe.5164" 3360 tab)
22:52:49     INFO - zombiecheck | Checking for orphan process with PID: 5560
22:52:49     INFO - zombiecheck | Checking for orphan process with PID: 5864
22:52:49     INFO - zombiecheck | Checking for orphan process with PID: 5572
22:52:49     INFO - zombiecheck | Checking for orphan process with PID: 4332
22:52:49     INFO - zombiecheck | Checking for orphan process with PID: 4124
22:52:49     INFO - Stopping web server
22:52:49     INFO - Stopping web socket server
22:52:49     INFO - Stopping ssltunnel
22:52:49     INFO - TEST-INFO | leakcheck | default process: leak threshold set at 0 bytes
22:52:49     INFO - TEST-INFO | leakcheck | plugin process: leak threshold set at 0 bytes
22:52:49     INFO - TEST-INFO | leakcheck | tab process: leak threshold set at 1000 bytes
22:52:49     INFO - TEST-INFO | leakcheck | geckomediaplugin process: leak threshold set at 20000 bytes
22:52:49     INFO - TEST-INFO | leakcheck | gpu process: leak threshold set at 0 bytes
22:52:49     INFO - 
22:52:49     INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, default process 5164
22:52:49     INFO - 
22:52:49     INFO -      |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
22:52:49     INFO -      |                                      | Per-Inst   Leaked|   Total      Rem|
22:52:49     INFO -    0 |TOTAL                                 |       26        0|10233060        0|
22:52:49     INFO - 
22:52:49     INFO - nsTraceRefcnt::DumpStatistics: 2012 entries
22:52:49     INFO - 
22:52:49     INFO - TEST-PASS | leakcheck | default process: no leaks detected!
Component: Disability Access APIs → XPCOM
Summary: Perma failing Intermittent OSError: IO Completion Port failed to signal process shutdown → Perma failing ValueError: need more than 1 value to unpack after fix_stack_using_bpsyms.py
Conversation from IRC:

•Aryx> apavel|sheriffduty: this didn't fail after that. and because it is about using the stack, this looks like the symbols which translate machine code to human readable addresses were broken
12:36 PM later jobs are green
Whiteboard: [stockwell unknown]
Duplicate of this bug: 1497015
This is mass failed on the last 3 pushes on autoland, is intermittent in general and we can't see the output line which makes that fail and only on Windows 7 debug.

Mike, do you have any idea what could be going on here? Thank you.
Severity: normal → critical
Flags: needinfo?(mh+mozilla)
Whiteboard: [stockwell unknown]
Gabriele, is this something you can help with? This hits randomly on trunk trees and hampers the ability to do merges. Thank you.
Flags: needinfo?(gsvelto)
Sure, I'll look into it tonight, leaving the NI.
The .sym files are truncated for some reason. Investigating.
Flags: needinfo?(mh+mozilla)
The patch from bug 1497382 gives us the return code from dump_syms: -1073741819 on opt and -1073741676 on debug. The former is STATUS_ACCESS_VIOLATION, the latter is STATUS_INTEGER_DIVIDE_BY_ZERO.
All in all this is happening because of some 64-bits dll from the DIA SDK not being found because the 64-bits path is not in $PATH. Fixed by backing out bug 1414287.
Status: NEW → RESOLVED
Closed: Last year
Flags: needinfo?(gsvelto)
Resolution: --- → FIXED
(In reply to Mike Hommey [:glandium] from comment #12)
> All in all this is happening because of some 64-bits dll from the DIA SDK
> not being found because the 64-bits path is not in $PATH. Fixed by backing
> out bug 1414287.

Ah yeah, dump_syms.exe relies on msdia140.dll from the DIA SDK. If it's not registered as a COM component then there's code to fall back to creating it by explicitly loading the DLL:
https://dxr.mozilla.org/mozilla-central/rev/c291143e24019097d087f9307e59b49facaf90cb/toolkit/crashreporter/google-breakpad/src/common/windows/pdb_source_line_writer.cc#208

Unfortunately we apparently never fixed the issue where symbolstore.py doesn't error if dump_syms errors? We ignore the return code from dump_syms:
https://dxr.mozilla.org/mozilla-central/rev/c291143e24019097d087f9307e59b49facaf90cb/toolkit/crashreporter/tools/symbolstore.py#601
Assignee: nobody → mh+mozilla
Target Milestone: --- → mozilla64
You need to log in before you can comment on or make changes to this bug.