Closed Bug 1525152 Opened 5 years ago Closed 3 years ago

Intermittent Automation Error: Received unexpected exception while running application | after AttributeError: function 'GetProcessImageFileNameA' not found

Categories

(Core :: General, defect, P5)

defect

Tracking

()

RESOLVED FIXED
91 Branch
Tracking Status
firefox-esr78 --- wontfix
firefox89 --- wontfix
firefox90 --- wontfix
firefox91 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [retriggered])

Attachments

(1 file)

#[markdown(off)]
Filed by: dvarga [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=225980007&repo=mozilla-inbound

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

20:55:53 INFO - Traceback (most recent call last):
20:55:53 INFO - File "Z:\task_1549312793\build\tests\mochitest\runtests.py", line 2791, in doTests
20:55:53 INFO - e10s=options.e10s
20:55:53 INFO - File "Z:\task_1549312793\build\tests\mochitest\runtests.py", line 2297, in runApp
20:55:53 INFO - debuggerInfo)
20:55:53 INFO - File "Z:\task_1549312793\build\tests\mochitest\runtests.py", line 2048, in checkForZombies
20:55:53 INFO - if isPidAlive(processPID):
20:55:53 INFO - File "Z:\task_1549312793\build\tests\mochitest\runtests.py", line 382, in isPidAlive
20:55:53 INFO - namelen = ctypes.windll.kernel32.GetProcessImageFileNameA(pHandle,
20:55:53 INFO - File "c:\mozilla-build\python\Lib\ctypes\__init__.py", line 379, in __getattr__
20:55:53 INFO - func = self.__getitem__(name)
20:55:53 INFO - File "c:\mozilla-build\python\Lib\ctypes\__init__.py", line 384, in __getitem__
20:55:53 INFO - func = self._FuncPtr((name_or_ordinal, self))
20:55:53 INFO - AttributeError: function 'GetProcessImageFileNameA' not found
20:55:53 ERROR - Automation Error: Received unexpected exception while running application
20:55:53 ERROR -
20:55:53 INFO - Stopping web server
20:55:53 INFO - Stopping web socket server
20:55:53 INFO - Stopping ssltunnel
20:55:53 INFO - leakcheck | Processing log file c:\users\task_1549312793\appdata\local\temp\tmpksurwe.mozrunner\runtests_leaks.log
20:55:53 INFO - TEST-INFO | leakcheck | default process: leak threshold set at 0 bytes
20:55:53 INFO - TEST-INFO | leakcheck | plugin process: leak threshold set at 0 bytes
20:55:53 INFO - TEST-INFO | leakcheck | tab process: leak threshold set at 1000 bytes
20:55:53 INFO - TEST-INFO | leakcheck | gmplugin process: leak threshold set at 20000 bytes
20:55:53 INFO - TEST-INFO | leakcheck | gpu process: leak threshold set at 0 bytes
20:55:53 INFO - TEST-INFO | leakcheck | rdd process: leak threshold set at 400 bytes
20:55:53 INFO - TEST-INFO | leakcheck | vr process: leak threshold set at 0 bytes
20:55:53 INFO - TEST-INFO | leakcheck | socket process: leak threshold set at 0 bytes
20:55:53 INFO - leakcheck | Processing leak log file c:\users\task_1549312793\appdata\local\temp\tmpksurwe.mozrunner\runtests_leaks.log

last successful test run: devtools/client/aboutdebugging-new/test/browser/browser_aboutdebugging_workers_remote_runtime.js

Component: about:debugging → Worker
Product: DevTools → Taskcluster
QA Contact: pmoore

Rob, has anything changes with Windows 10 machines on Monday which would explain the error message?

Flags: needinfo?(rthijssen)

Joel has pointed out the calling code is new (from bug 1247453).

Nathan, please take a look at why this fails on Windows 10 64-bit.

Blocks: 1247453
Flags: needinfo?(rthijssen) → needinfo?(nfroyd)

I guess I misread the documentation:

https://docs.microsoft.com/en-us/windows/desktop/api/psapi/nf-psapi-getprocessimagefilenamea

it looks like this should be using psapi.dll and possibly a different file name.

Assignee: nobody → nfroyd
Flags: needinfo?(nfroyd)
Component: Worker → Workers
No longer blocks: 1247453
Regressed by: 1247453

Hi Nathan, looks like this is still a pretty regular occurrence. Can you please take a look when you get a chance? Thanks!

Flags: needinfo?(nfroyd)
Component: Workers → General
Product: Taskcluster → Core

There are 7 failures in the last 7 days on windows10-64, windows10-64-shippable, windows7-32 and windows7-32-shippable all opt builds.

https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-12-02&endday=2019-12-09&tree=trunk&bug=1525152

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=280116081&repo=mozilla-central&lineNumber=5096

[task 2019-12-07T11:02:47.266Z] 11:02:47 INFO - TEST-START | devtools/client/webconsole/test/browser/browser_webconsole_worklet_error.js
[task 2019-12-07T11:02:47.425Z] 11:02:47 INFO - GECKO(3832) | JavaScript error: https://example.com/browser/devtools/client/webconsole/test/browser/test-syntaxerror-worklet.js, line 6: SyntaxError: duplicate formal argument a
[task 2019-12-07T11:02:47.504Z] 11:02:47 INFO - GECKO(3832) | JavaScript error: https://example.com/browser/devtools/client/webconsole/test/browser/test-error-worklet.js, line 18: Error: addModule
[task 2019-12-07T11:02:47.519Z] 11:02:47 INFO - GECKO(3832) | JavaScript error: , line 0: uncaught exception: process
[task 2019-12-07T11:02:49.586Z] 11:02:49 INFO - GECKO(3832) | console.warn: "IGNORED REDUX ACTION:" ({type:"AUTOCOMPLETE_CLEAR"})
[task 2019-12-07T11:02:49.641Z] 11:02:49 INFO - GECKO(3832) | MEMORY STAT | vsize 1605MB | vsizeMaxContiguous 129MB | residentFast 811MB | heapAllocated 455MB
[task 2019-12-07T11:02:49.641Z] 11:02:49 INFO - TEST-OK | devtools/client/webconsole/test/browser/browser_webconsole_worklet_error.js | took 2370ms
[task 2019-12-07T11:02:49.656Z] 11:02:49 INFO - checking window state
[task 2019-12-07T11:02:55.158Z] 11:02:55 INFO - GECKO(3832) | Completed ShutdownLeaks collections in process 4524
[task 2019-12-07T11:02:55.173Z] 11:02:55 INFO - GECKO(3832) | Completed ShutdownLeaks collections in process 5360
[task 2019-12-07T11:02:55.193Z] 11:02:55 INFO - GECKO(3832) | Completed ShutdownLeaks collections in process 3712
[task 2019-12-07T11:02:55.280Z] 11:02:55 INFO - GECKO(3832) | Completed ShutdownLeaks collections in process 4848
[task 2019-12-07T11:02:55.327Z] 11:02:55 INFO - GECKO(3832) | Completed ShutdownLeaks collections in process 4036
[task 2019-12-07T11:02:55.342Z] 11:02:55 INFO - GECKO(3832) | Completed ShutdownLeaks collections in process 5124
[task 2019-12-07T11:02:55.389Z] 11:02:55 INFO - GECKO(3832) | Completed ShutdownLeaks collections in process 4192
[task 2019-12-07T11:02:55.428Z] 11:02:55 INFO - GECKO(3832) | Completed ShutdownLeaks collections in process 2244
[task 2019-12-07T11:02:55.455Z] 11:02:55 INFO - GECKO(3832) | Completed ShutdownLeaks collections in process 532
[task 2019-12-07T11:02:59.042Z] 11:02:59 INFO - GECKO(3832) | Completed ShutdownLeaks collections in process 1044
[task 2019-12-07T11:02:59.042Z] 11:02:59 INFO - TEST-START | Shutdown
[task 2019-12-07T11:02:59.042Z] 11:02:59 INFO - Browser Chrome Test Summary
[task 2019-12-07T11:02:59.042Z] 11:02:59 INFO - Passed: 4515
[task 2019-12-07T11:02:59.043Z] 11:02:59 INFO - Failed: 0
[task 2019-12-07T11:02:59.043Z] 11:02:59 INFO - Todo: 1
[task 2019-12-07T11:02:59.043Z] 11:02:59 INFO - Mode: e10s
[task 2019-12-07T11:02:59.043Z] 11:02:59 INFO - *** End BrowserChrome Test Results ***
[task 2019-12-07T11:02:59.183Z] 11:02:59 INFO - GECKO(3832) | JavaScript error: , line 0: uncaught exception: undefined
[task 2019-12-07T11:02:59.458Z] 11:02:59 INFO - GECKO(3832) | 1575716579443 Marionette TRACE Received observer notification xpcom-will-shutdown
[task 2019-12-07T11:02:59.458Z] 11:02:59 INFO - GECKO(3832) | 1575716579443 Marionette INFO Stopped listening on port 2828
[task 2019-12-07T11:02:59.458Z] 11:02:59 INFO - GECKO(3832) | 1575716579444 Marionette DEBUG Marionette stopped listening
[task 2019-12-07T11:03:00.478Z] 11:03:00 INFO - TEST-INFO | Main app process: exit 0
[task 2019-12-07T11:03:00.478Z] 11:03:00 INFO - runtests.py | Application ran for: 0:12:22.481000
[task 2019-12-07T11:03:00.478Z] 11:03:00 INFO - zombiecheck | Reading PID log: c:\users\task_1575714955\appdata\local\temp\tmprjv1tgpidlog
[task 2019-12-07T11:03:00.479Z] 11:03:00 INFO - ==> process 1044 launched child process 5124 ("Z:\task_1575714955\build\application\firefox\firefox.exe" -contentproc --channel="1044.0.1663982441\1153127058" -childID 1 -isForBrowser -prefsHandle 2152 -prefMapHandle 1580 -prefsLen 1 -prefMapSize 225005 -parentBuildID 20191207092617 -greomni "Z:\task_1575714955\build\application\firefox\omni.ja" -appomni "Z:\task_1575714955\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1575714955\build\application\firefox\browser" - 1044 "\.\pipe\gecko-crash-server-pipe.1044" 2196 tab)
[task 2019-12-07T11:03:00.480Z] 11:03:00 INFO - ==> process 1044 launched child process 4524 ("Z:\task_1575714955\build\application\firefox\firefox.exe" -contentproc --channel="1044.6.75176873\565891366" -childID 2 -isForBrowser -prefsHandle 2400 -prefMapHandle 2396 -prefsLen 463 -prefMapSize 225005 -parentBuildID 20191207092617 -greomni "Z:\task_1575714955\build\application\firefox\omni.ja" -appomni "Z:\task_1575714955\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1575714955\build\application\firefox\browser" - 1044 "\.\pipe\gecko-crash-server-pipe.1044" 2412 tab)
[task 2019-12-07T11:03:00.480Z] 11:03:00 INFO - ==> process 1044 launched child process 532 ("Z:\task_1575714955\build\application\firefox\firefox.exe" -contentproc --channel="1044.12.1269180804\1529631450" -childID 3 -isForBrowser -prefsHandle 2580 -prefMapHandle 2576 -prefsLen 524 -prefMapSize 225005 -parentBuildID 20191207092617 -greomni "Z:\task_1575714955\build\application\firefox\omni.ja" -appomni "Z:\task_1575714955\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1575714955\build\application\firefox\browser" - 1044 "\.\pipe\gecko-crash-server-pipe.1044" 2592 tab)
[task 2019-12-07T11:03:00.480Z] 11:03:00 INFO - ==> process 1044 launched child process 5360 ("Z:\task_1575714955\build\application\firefox\firefox.exe" -contentproc --channel="1044.18.988137254\197155058" -childID 4 -isForBrowser -prefsHandle 3356 -prefMapHandle 3428 -prefsLen 9926 -prefMapSize 225005 -parentBuildID 20191207092617 -greomni "Z:\task_1575714955\build\application\firefox\omni.ja" -appomni "Z:\task_1575714955\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1575714955\build\application\firefox\browser" - 1044 "\.\pipe\gecko-crash-server-pipe.1044" 3512 tab)
[task 2019-12-07T11:03:00.481Z] 11:03:00 INFO - ==> process 1044 launched child process 4036 ("Z:\task_1575714955\build\application\firefox\firefox.exe" -contentproc --channel="1044.24.582435334\417845902" -childID 5 -isForBrowser -prefsHandle 3780 -prefMapHandle 3736 -prefsLen 10009 -prefMapSize 225005 -parentBuildID 20191207092617 -greomni "Z:\task_1575714955\build\application\firefox\omni.ja" -appomni "Z:\task_1575714955\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1575714955\build\application\firefox\browser" - 1044 "\.\pipe\gecko-crash-server-pipe.1044" 3848 tab)
[task 2019-12-07T11:03:00.482Z] 11:03:00 INFO - ==> process 1044 launched child process 2244 ("Z:\task_1575714955\build\application\firefox\firefox.exe" -contentproc --channel="1044.30.379705982\320687360" -childID 6 -isForBrowser -prefsHandle 3968 -prefMapHandle 3964 -prefsLen 10011 -prefMapSize 225005 -parentBuildID 20191207092617 -greomni "Z:\task_1575714955\build\application\firefox\omni.ja" -appomni "Z:\task_1575714955\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1575714955\build\application\firefox\browser" - 1044 "\.\pipe\gecko-crash-server-pipe.1044" 3980 tab)
[task 2019-12-07T11:03:00.482Z] 11:03:00 INFO - ==> process 1044 launched child process 4192 ("Z:\task_1575714955\build\application\firefox\firefox.exe" -contentproc --channel="1044.36.416526336\124518283" -childID 7 -isForBrowser -prefsHandle 3984 -prefMapHandle 4160 -prefsLen 10160 -prefMapSize 225005 -parentBuildID 20191207092617 -greomni "Z:\task_1575714955\build\application\firefox\omni.ja" -appomni "Z:\task_1575714955\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1575714955\build\application\firefox\browser" - 1044 "\.\pipe\gecko-crash-server-pipe.1044" 4224 tab)
[task 2019-12-07T11:03:00.482Z] 11:03:00 INFO - ==> process 1044 launched child process 4848 ("Z:\task_1575714955\build\application\firefox\firefox.exe" -contentproc --channel="1044.42.872786024\1103185775" -childID 8 -isForBrowser -prefsHandle 4256 -prefMapHandle 3900 -prefsLen 10161 -prefMapSize 225005 -parentBuildID 20191207092617 -greomni "Z:\task_1575714955\build\application\firefox\omni.ja" -appomni "Z:\task_1575714955\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1575714955\build\application\firefox\browser" - 1044 "\.\pipe\gecko-crash-server-pipe.1044" 1616 tab)
[task 2019-12-07T11:03:00.483Z] 11:03:00 INFO - ==> process 1044 launched child process 3712 ("Z:\task_1575714955\build\application\firefox\firefox.exe" -contentproc --channel="1044.48.136762681\1684326398" -childID 9 -isForBrowser -prefsHandle 4452 -prefMapHandle 4464 -prefsLen 10160 -prefMapSize 225005 -parentBuildID 20191207092617 -greomni "Z:\task_1575714955\build\application\firefox\omni.ja" -appomni "Z:\task_1575714955\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1575714955\build\application\firefox\browser" - 1044 "\.\pipe\gecko-crash-server-pipe.1044" 4600 tab)
[task 2019-12-07T11:03:00.484Z] 11:03:00 INFO - ==> process 4100 launched child process 3476 ("Z:\task_1575714955\build\application\firefox\firefox.exe" -contentproc --channel="4100.0.944204604\269869001" -childID 1 -isForBrowser -prefsHandle 2132 -prefMapHandle 2124 -prefsLen 1 -prefMapSize 228924 -parentBuildID 20191207092617 -greomni "Z:\task_1575714955\build\application\firefox\omni.ja" -appomni "Z:\task_1575714955\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1575714955\build\application\firefox\browser" - 4100 "\.\pipe\gecko-crash-server-pipe.4100" 2176 tab)
[task 2019-12-07T11:03:00.485Z] 11:03:00 INFO - ==> process 4100 launched child process 4332 ("Z:\task_1575714955\build\application\firefox\firefox.exe" -contentproc --channel="4100.6.1327449260\271224009" -childID 2 -isForBrowser -prefsHandle 2528 -prefMapHandle 2524 -prefsLen 453 -prefMapSize 228924 -parentBuildID 20191207092617 -greomni "Z:\task_1575714955\build\application\firefox\omni.ja" -appomni "Z:\task_1575714955\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1575714955\build\application\firefox\browser" - 4100 "\.\pipe\gecko-crash-server-pipe.4100" 2540 tab)
[task 2019-12-07T11:03:00.485Z] 11:03:00 INFO - zombiecheck | Checking for orphan process with PID: 4192
[task 2019-12-07T11:03:00.485Z] 11:03:00 INFO - zombiecheck | Checking for orphan process with PID: 4848
[task 2019-12-07T11:03:00.486Z] 11:03:00 INFO - zombiecheck | Checking for orphan process with PID: 5124
[task 2019-12-07T11:03:00.486Z] 11:03:00 INFO - zombiecheck | Checking for orphan process with PID: 4332
[task 2019-12-07T11:03:00.486Z] 11:03:00 INFO - Traceback (most recent call last):
[task 2019-12-07T11:03:00.486Z] 11:03:00 INFO - File "Z:\task_1575714955\build\tests\mochitest\runtests.py", line 2850, in doTests
[task 2019-12-07T11:03:00.486Z] 11:03:00 INFO - e10s=options.e10s
[task 2019-12-07T11:03:00.486Z] 11:03:00 INFO - File "Z:\task_1575714955\build\tests\mochitest\runtests.py", line 2349, in runApp
[task 2019-12-07T11:03:00.486Z] 11:03:00 INFO - debuggerInfo)
[task 2019-12-07T11:03:00.486Z] 11:03:00 INFO - File "Z:\task_1575714955\build\tests\mochitest\runtests.py", line 2098, in checkForZombies
[task 2019-12-07T11:03:00.487Z] 11:03:00 INFO - if isPidAlive(processPID):
[task 2019-12-07T11:03:00.487Z] 11:03:00 INFO - File "Z:\task_1575714955\build\tests\mochitest\runtests.py", line 394, in isPidAlive
[task 2019-12-07T11:03:00.487Z] 11:03:00 INFO - namelen = ctypes.windll.kernel32.GetProcessImageFileNameA(pHandle,
[task 2019-12-07T11:03:00.487Z] 11:03:00 INFO - File "c:\mozilla-build\python\Lib\ctypes_init_.py", line 378, in getattr
[task 2019-12-07T11:03:00.487Z] 11:03:00 INFO - func = self.getitem(name)
[task 2019-12-07T11:03:00.487Z] 11:03:00 INFO - File "c:\mozilla-build\python\Lib\ctypes_init_.py", line 383, in getitem
[task 2019-12-07T11:03:00.487Z] 11:03:00 INFO - func = self._FuncPtr((name_or_ordinal, self))
[task 2019-12-07T11:03:00.487Z] 11:03:00 INFO - AttributeError: function 'GetProcessImageFileNameA' not found
[task 2019-12-07T11:03:00.487Z] 11:03:00 ERROR - Automation Error: Received unexpected exception while running application
[task 2019-12-07T11:03:00.487Z] 11:03:00 ERROR -
[task 2019-12-07T11:03:00.487Z] 11:03:00 INFO - Stopping web server
[task 2019-12-07T11:03:00.490Z] 11:03:00 INFO - Stopping web socket server
[task 2019-12-07T11:03:00.509Z] 11:03:00 INFO - Stopping ssltunnel
[task 2019-12-07T11:03:00.544Z] 11:03:00 WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2019-12-07T11:03:00.544Z] 11:03:00 INFO - runtests.py | Running tests: end.
[task 2019-12-07T11:03:00.651Z] 11:03:00 INFO - Buffered messages finished

Flags: needinfo?(nfroyd)
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → INCOMPLETE
Status: REOPENED → RESOLVED
Closed: 4 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: VERIFIED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

(In reply to Nathan Froyd [:froydnj] from comment #3)

I guess I misread the documentation:

https://docs.microsoft.com/en-us/windows/desktop/api/psapi/nf-psapi-getprocessimagefilenamea

it looks like this should be using psapi.dll and possibly a different file name.

Yes, I think psapi is the way to go.

Taking, since failures are on-going and the assignee appears inactive.

Assignee: froydnj+bz → whole.grains

Also, it might be useful to catch this error and fallback to the older behaviour when the new way doesn't work.

https://hg.mozilla.org/mozilla-central/rev/9fb802aba6b9167ce4ecc0bd3a30704aeb3fb7ae

This is only an infrequent intermittent failure. Is that because this code is only called infrequently, or does it sometimes succeed and sometimes fail? If isPidAlive is called consistently, we see that it always fails:

https://treeherder.mozilla.org/jobs?repo=try&revision=1ffaf933bfab1e54f2e241975d4314d041edaeca

This code is infrequently used, but has always failed because it references
the wrong dll name - corrected here.

Pushed by whole.grains@protonmail.com:
https://hg.mozilla.org/integration/autoland/rev/ac46852a23b8
Use correct dll name for GetProcessImageFileName; r=ahal
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → FIXED
Target Milestone: --- → 91 Branch
Has Regression Range: --- → yes
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: