1527038 - fix_stack_using_bpsyms.py failing on ESR60 after recent windows 10 update to 1803

Status: RESOLVED FIXED

(Core :: XPCOM, defect)

Description

[Joel Maher ( :jmaher ) (UTC -8)]

here is a log that shows the problem:
https://taskcluster-artifacts.net/GlArNieSSO6ylCFCsRLiVg/0/public/logs/live_backing.log

and some related info from the log:
17:39:29 INFO - GECKO(3688) | #26: mozilla::ipc::MessageChannel::MessageTask::Run() [ipc/glue/MessageChannel.cpp:1833]
17:39:29 INFO - GECKO(3688) | #27: mozilla::SchedulerGroup::Runnable::Run() [xpcom/threads/SchedulerGroup.cpp:375]
17:39:29 INFO - Couldn't open file: Child 920, Main Thread] ###!!! AS669\build\applSication\firefox\xul.dlEl
17:39:29 INFO - Exception in thread ProcessReader:
17:39:29 INFO - Traceback (most recent call last):
17:39:29 INFO - File "c:\mozilla-build\python\Lib\threading.py", line 801, in __bootstrap_inner
17:39:29 INFO - self.run()
17:39:29 INFO - File "c:\mozilla-build\python\Lib\threading.py", line 754, in run
17:39:29 INFO - self.__target(*self.__args, **self.__kwargs)
17:39:29 INFO - File "Z:\task_1549905669\build\venv\lib\site-packages\mozprocess\processhandler.py", line 1028, in _read
17:39:29 INFO - callback(line.rstrip())
17:39:29 INFO - File "Z:\task_1549905669\build\venv\lib\site-packages\mozprocess\processhandler.py", line 944, in call
17:39:29 INFO - e(*args, **kwargs)
17:39:29 INFO - File "Z:\task_1549905669\build\tests\mochitest\runtests.py", line 2931, in processOutputLine
17:39:29 INFO - message = handler(message)
17:39:29 INFO - File "Z:\task_1549905669\build\tests\mochitest\runtests.py", line 3018, in fix_stack
17:39:29 INFO - message['data'] = self.stackFixerFunction(message['data'])
17:39:29 INFO - File "Z:\task_1549905669\build\venv\lib\site-packages\mozrunner\utils.py", line 268, in stack_fixer_function
17:39:29 INFO - return stack_fixer_module.fixSymbols(line, symbolsPath)
17:39:29 INFO - File "Z:\task_1549905669\build\tests\bin\fix_stack_using_bpsyms.py", line 153, in fixSymbols
17:39:29 INFO - symbol = addressToSymbol(file, address, symbolsDir)
17:39:29 INFO - File "Z:\task_1549905669\build\tests\bin\fix_stack_using_bpsyms.py", line 139, in addressToSymbol
17:39:29 INFO - p = getSymbolFile(file, symbolsDir)
17:39:29 INFO - File "Z:\task_1549905669\build\tests\bin\fix_stack_using_bpsyms.py", line 128, in getSymbolFile
17:39:29 INFO - symfile = guessSymbolFile(file, symbolsDir)
17:39:29 INFO - File "Z:\task_1549905669\build\tests\bin\fix_stack_using_bpsyms.py", line 119, in guessSymbolFile
17:39:29 INFO - uuid = findIdForPath(full_path)
17:39:29 INFO - File "Z:\task_1549905669\build\tests\bin\fix_stack_using_bpsyms.py", line 103, in findIdForPath
17:39:29 INFO - (path, e.output))
17:39:29 INFO - Exception: Error getting fileid for Child 920, Main Thread] ###!!! AS669\build\applSication\firefox\xul.dlEl:
17:39:36 INFO - TEST-INFO | Main app process: exit 0
17:39:36 ERROR - 803 ERROR TEST-UNEXPECTED-FAIL | ShutdownLeaks | process() called before end of test suite
17:39:36 INFO - runtests.py | Application ran for: 0:00:18.171000
17:39:36 INFO - zombiecheck | Reading PID log: c:\users\task_1549905669\appdata\local\temp\tmpnmxn6upidlog
17:39:36 INFO - ==> process 3688 launched child process 920 ("Z:\task_1549905669\build\application\firefox\firefox.exe" -contentproc --channel="3688.0.1815779917\1441585815" -childID 1 -isForBrowser -intPrefs 43:0|45:0|64:0|69:0|75:0|172:1000|181:0|183:0|197:32|198:256|248:2| -boolPrefs 5:1|28:1|37:1|60:1|61:0|123:1|132:1|136:1|146:1|151:1|158:1|184:1|196:1|213:0|303:0| -stringPrefs 218:4;0.01|289:38;{0ace4094-842e-4c49-a153-dd114e22a9fe}| -schedulerPrefs 0001,2 -greomni "Z:\task_1549905669\build\application\firefox\omni.ja" -appomni "Z:\task_1549905669\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1549905669\build\application\firefox\browser" 3688 "\.\pipe\gecko-crash-server-pipe.3688" 2184 tab)

Comment 1

[Joel Maher ( :jmaher ) (UTC -8)]

Ted is this something you could add some context to? This seems to be showing up on ESR, I don't see it on trunk if that helps.

Comment 2

[(not currently active) Ted Mielczarek]

Ugh:

17:39:29 INFO - Exception: Error getting fileid for Child 920, Main Thread] ###!!! AS669\build\applSication\firefox\xul.dlEl:

This seems to be another instance of stdout/stderr getting intermingled and causing issues (bug 798300). I'm not sure why this would manifest only on ESR--perhaps some aspect of logging changed between there and trunk?

We seem to be in the middle of spewing the same assertion for every content process:

17:39:28 INFO - GECKO(3688) | [Child 6468, Main Thread] ###!!! ASSERTION: does it make sense to Show()/Hide() a disabled widget?: 'mEnabled', file z:/build/build/src/widget/PuppetWidget.cpp, line 185

Comment 3

[(not currently active) Ted Mielczarek]

That same assertion exists on both trunk and ESR60, FWIW:
https://searchfox.org/mozilla-central/rev/00c0d068ece99717bea7475f7dc07e61f7f35984/widget/PuppetWidget.cpp#184
https://dxr.mozilla.org/mozilla-esr60/rev/a610a1557958dd97593f15a85969a2b5e1f15d10/widget/PuppetWidget.cpp#185

...but it's possible that the code that causes it to get called has changed, or we're running different tests or something.

Comment 4

[(not currently active) Ted Mielczarek]

aha!

Compare:
https://dxr.mozilla.org/mozilla-esr60/rev/a610a1557958dd97593f15a85969a2b5e1f15d10/xpcom/base/nsTraceRefcnt.cpp#790-800
vs.
https://searchfox.org/mozilla-central/rev/00c0d068ece99717bea7475f7dc07e61f7f35984/xpcom/base/nsTraceRefcnt.cpp#741-755

bug 1485224 changed the output behavior of stack traces to be more atomic:
https://hg.mozilla.org/mozilla-central/rev/131188fb2361caf66b023dd24b72d21d7cb70d19

That change isn't in ESR60. We could uplift that change to improve things there.

Comment 6

[Masatoshi Kimura [:emk]]

It is very likely that updating 1803 caused the problem because it would change the system UCRT to the same version as SDK 17134's one.
I submitted an ESR60 uplift request.

Comment 7

[Intermittent Failures Robot]

14 failures in 2832 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-esr60: 14

Platform breakdown:

• windows10-64: 14

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

Comment 8

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-esr60: 2

Platform breakdown:

• windows10-64: 2

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

Comment 10

[Ryan VanderMeulen [:RyanVM]]

Fixed by uplifting the "Make best efforts to write a stack frame atomically" patch from bug 1485224.

https://hg.mozilla.org/releases/mozilla-esr60/rev/afe14f79474a

Comment 11

[Intermittent Failures Robot]

5 failures in 2981 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-esr60: 5

Platform breakdown:

• windows10-64: 5

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