Last Comment Bug 740242 - runtests.py | Received unexpected exception while running application ''NoneType' object has no attribute 'group'' (mostly in windows debug test mochitests-1/5)
: runtests.py | Received unexpected exception while running application ''NoneT...
Status: RESOLVED FIXED
[cleanup]
: intermittent-failure
Product: Testing
Classification: Components
Component: Mochitest (show other bugs)
: Trunk
: x86 Windows Vista
: P3 normal (vote)
: mozilla15
Assigned To: Tim Taubert [:ttaubert]
:
Mentors:
Depends on: 758986
Blocks: 438871 683953
  Show dependency treegraph
 
Reported: 2012-03-28 20:16 PDT by Richard Newman [:rnewman]
Modified: 2012-11-25 19:31 PST (History)
8 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
fixed
fixed


Attachments
check winrm-0.1.exe into /build/tools (32.10 KB, text/plain)
2012-04-11 14:49 PDT, John Ford [:jhford]
coop: review+
Details
add some diagnostics to get more info about Python exceptions during Mochitest (3.13 KB, patch)
2012-05-01 08:34 PDT, Ted Mielczarek [:ted.mielczarek]
jmaher: review+
Details | Diff | Splinter Review
make regex parsing more tolerant towards corrupted log lines (1.70 KB, patch)
2012-05-04 05:34 PDT, Tim Taubert [:ttaubert]
ted: review+
lukasblakk+bugs: approval‑mozilla‑aurora+
lukasblakk+bugs: approval‑mozilla‑beta+
Details | Diff | Splinter Review

Description Richard Newman [:rnewman] 2012-03-28 20:16:27 PDT
I have no idea.

https://tbpl.mozilla.org/php/getParsedLog.php?id=10457230&full=1&branch=mozilla-central

xul!JSD_GetValueForObject+0x00000000000BDBE1
xul!JSD_GetValueForObject+0x000000000008CE76
xul!XRE_RunAppShell+0x0000000000000029
xul!JSD_GetValueForObject+0x0000000000182677
xul!StartupHooker+0x0000000000013835
xul!StartupHooker+0x0000000000013D72
xul!StartupHooker+0x000000000001423D
xul!XRE_InitChildProcess+0x00000000000003E8
0x000000000101140D
0x0000000001011571
0x00000000010118FF
0x000000000101172F
kernel32!BaseThreadInitThunk+0x0000000000000012
ntdll!RtlInitializeExceptionChain+0x0000000000000063
ntdll!RtlInitializeExceptionChain+0x0000000000000036
###!!! ASSERTION: Should have mContext in non-global/non-process manager!: 'mContext || (aChrome && !aParentManager) || aProcessManager', file e:\builds\moz2_slave\m-cen-w32-dbg\build\content\base\src\nsFrameMessageManager.h, line 101
--DOMWINDOW == 406 (19271830) [serial = 644] [outer = 00000000] [url = file:///c:/users/cltbld/appdata/local/temp/tmpmeya7q/mochikit-22.tmp/89419.html]
--DOMWINDOW == 405 (17B89878) [serial = 611] [outer = 00000000] [url = http://mochi.test:8888/tests/docshell/test/chrome/582176_xml.xml]
--DOMWINDOW == 404 (0D52A928) [serial = 609] [outer = 00000000] [url = chrome://mochitests/content/chrome/docshell/test/chrome/bug582176_window.xul]
--DOMWINDOW == 403 (0D52C390) [serial = 600] [outer = 00000000] [url = chrome://mochitests/content/chrome/docshell/test/chrome/bug113934_window.xul?chrome]
--DOMWINDOW == 402 (19272208) [serial = 665] [outer = 00000000] [url = javascript:'1';]
--DOMWINDOW == 401 (17D20940) [serial = 663] [outer = 00000000] [url = data:application/vnd.mozilla.xul+xml,<?xml%20version="1.0"?><window%20xmlns="http://www.mozilla.org/keymaster/gatekeeper/there.is.only.xul"/>]
--DOMWINDOW == 400 (19271A28) [serial = 653] [outer = 00000000] [url = http://mochi.test:8888/tests/docshell/test/chrome/92598_nostore.html]
--DOMWINDOW == 399 (19271E18) [serial = 626] [outer = 00000000] [url = file:///c:/users/cltbld/appdata/local/temp/tmpmeya7q/mochikit-21.tmp/662200b.html]
--DOMWINDOW == 398 (17D21778) [serial = 651] [outer = 00000000] [url = chrome://mochitests/content/chrome/docshell/test/chrome/bug92598_window.xul]
--DOMWINDOW == 397 (17B888B8) [serial = 636] [outer = 00000000] [url = data:text/html,<title>new%20load</title>]
--DOMWINDOW == 396 (0D52C598) [serial = 634] [outer = 00000000] [url = chrome://mochitests/content/chrome/docshell/test/chrome/bug690056_window.xul]
--DOMWINDOW == 395 (17D20530) [serial = 642] [outer = 00000000] [url = chrome://mochitests/content/chrome/docshell/test/chrome/bug89419_window.xul]
INFO | runtests.py | Received unexpected exception while running application ''NoneType' object has no attribute 'group''

WARNING: nsExceptionService ignoring thread destruction after shutdown: file e:/builds/moz2_slave/m-cen-w32-dbg/build/xpcom/base/nsExceptionService.cpp, line 199
nsStringStats
 => mAllocCount:           2905
 => mReallocCount:          223
 => mFreeCount:            2905
 => mShareCount:           8464
 => mAdoptCount:            127
 => mAdoptFreeCount:        127
ERROR: The process "1024" not found.
SUCCESS: The process with PID 2716 has been terminated.
TEST-UNEXPECTED-FAIL | automationutils.processLeakLog() | missing output line for total leaks!
TEST-UNEXPECTED-FAIL | plugin process 3076 | automationutils.processLeakLog() | missing output line for total leaks!
==> process 3376 will purposefully crash
INFO | automationutils.processLeakLog() | process 3376 was deliberately crashed and thus has no leak log

INFO | runtests.py | Running tests: end.
Traceback (most recent call last):
  File "mochitest/runtests.py", line 914, in <module>
  File "mochitest/runtests.py", line 911, in main
  File "mochitest/runtests.py", line 719, in runTests
  File "mochitest/runtests.py", line 610, in cleanup
  File "c:\mozilla-build\python25\Lib\shutil.py", line 174, in rmtree
    onerror(os.remove, fullname, sys.exc_info())
  File "c:\mozilla-build\python25\Lib\shutil.py", line 172, in rmtree
    os.remove(fullname)
WindowsError: [Error 13] The process cannot access the file because it is being used by another process: 'c:\\users\\cltbld\\appdata\\local\\temp\\tmpmeya7q\\animals.sqlite'

command timed out: 1200 seconds without output, attempting to kill
SIGKILL failed to kill process
using fake rc=-1
program finished with exit code -1
Comment 1 Chris Cooper [:coop] 2012-03-29 13:59:53 PDT
Oh, Windows. Not sure if deploying jhford's tool from bug 727551 will help here unless we also make runtests.py aware of it.
Comment 4 Phil Ringnalda (:philor, back in August) 2012-04-02 17:21:44 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10580764&tree=Mozilla-Inbound
Comment 5 Phil Ringnalda (:philor, back in August) 2012-04-02 21:20:15 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10586146&tree=Mozilla-Aurora
Comment 6 Phil Ringnalda (:philor, back in August) 2012-04-02 21:54:33 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10588385&tree=Mozilla-Inbound
Comment 7 Phil Ringnalda (:philor, back in August) 2012-04-03 12:55:05 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10604872&tree=Mozilla-Inbound
Comment 8 Phil Ringnalda (:philor, back in August) 2012-04-03 14:34:19 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10607923&tree=Build-System
Comment 9 Phil Ringnalda (:philor, back in August) 2012-04-04 08:08:47 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10635462&tree=Firefox
Comment 10 Phil Ringnalda (:philor, back in August) 2012-04-04 08:47:05 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10633310&tree=Mozilla-Inbound
Comment 11 Phil Ringnalda (:philor, back in August) 2012-04-04 21:12:15 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10651578&tree=Mozilla-Inbound
Comment 12 Phil Ringnalda (:philor, back in August) 2012-04-05 08:29:51 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10666380&tree=Mozilla-Inbound
Comment 13 Phil Ringnalda (:philor, back in August) 2012-04-06 10:40:55 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10691413&tree=Mozilla-Inbound
Comment 14 Phil Ringnalda (:philor, back in August) 2012-04-06 16:16:09 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10711376&tree=Mozilla-Inbound
Comment 15 Phil Ringnalda (:philor, back in August) 2012-04-07 09:36:32 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10723060&tree=Mozilla-Inbound
Comment 16 Phil Ringnalda (:philor, back in August) 2012-04-07 10:27:57 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10719345&tree=Mozilla-Inbound
Comment 17 Phil Ringnalda (:philor, back in August) 2012-04-07 11:01:28 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10717807&tree=Mozilla-Inbound
Comment 18 Phil Ringnalda (:philor, back in August) 2012-04-07 12:22:55 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10712098&tree=Mozilla-Aurora
Comment 19 Phil Ringnalda (:philor, back in August) 2012-04-07 12:23:27 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10708188&tree=Mozilla-Aurora
Comment 20 Phil Ringnalda (:philor, back in August) 2012-04-09 07:25:47 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10742018&tree=Mozilla-Inbound
Comment 21 Phil Ringnalda (:philor, back in August) 2012-04-09 08:11:00 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10745381&tree=Mozilla-Inbound
Comment 22 Phil Ringnalda (:philor, back in August) 2012-04-09 15:06:02 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10756995&tree=Mozilla-Inbound
Comment 23 Nick Thomas [:nthomas] 2012-04-09 15:58:41 PDT
Based on the log in comment #22 only, is there a problem with the tests failing, leaving runtests.py trying to delete a file locked by firefox still running, and then buildbot fails to delete all the processes ? The last is filed elsewhere.
Comment 24 Phil Ringnalda (:philor, back in August) 2012-04-09 16:03:55 PDT
No idea - my feeling was that it was a bug in runtests.py (or, really, something it includes) failing to properly check whether a regex matched before doing something to one of the groups from the NoneType match, since that's what we usually do when we "'NoneType' object has no attribute 'group'", but I couldn't find one that didn't check.
Comment 25 Phil Ringnalda (:philor, back in August) 2012-04-10 09:18:45 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10776053&tree=Mozilla-Inbound
Comment 26 Phil Ringnalda (:philor, back in August) 2012-04-10 15:20:30 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10787517&tree=Mozilla-Inbound
Comment 27 Phil Ringnalda (:philor, back in August) 2012-04-10 16:40:10 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10789842&tree=Mozilla-Inbound
Comment 28 Phil Ringnalda (:philor, back in August) 2012-04-11 12:08:19 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10818427&tree=Mozilla-Inbound
Comment 29 Phil Ringnalda (:philor, back in August) 2012-04-11 14:18:05 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10822190&tree=Mozilla-Inbound
Comment 30 Phil Ringnalda (:philor, back in August) 2012-04-11 14:33:40 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10822629&tree=Mozilla-Inbound
Comment 31 John Ford [:jhford] 2012-04-11 14:49:26 PDT
Created attachment 614180 [details]
check winrm-0.1.exe into /build/tools

binaries in hg is sub-optimal, but it's a tiny one and we already have the stackwalk ones in this repo.  Also opsi.
Comment 32 Phil Ringnalda (:philor, back in August) 2012-04-11 15:35:25 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10823206&tree=Mozilla-Inbound
Comment 33 Phil Ringnalda (:philor, back in August) 2012-04-11 16:26:35 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10825005&tree=Mozilla-Inbound
Comment 34 Phil Ringnalda (:philor, back in August) 2012-04-11 19:41:59 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10830303&tree=Mozilla-Inbound
Comment 35 Phil Ringnalda (:philor, back in August) 2012-04-11 19:42:39 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10830291&tree=Mozilla-Inbound
Comment 36 Phil Ringnalda (:philor, back in August) 2012-04-13 10:47:22 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10877943&tree=Mozilla-Inbound
Comment 37 Phil Ringnalda (:philor, back in August) 2012-04-13 11:13:35 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10865114&tree=Firefox
Comment 38 Phil Ringnalda (:philor, back in August) 2012-04-13 22:36:59 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10893698&tree=Firefox
Comment 40 Phil Ringnalda (:philor, back in August) 2012-04-15 17:15:48 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10904785&tree=Services-Central
Comment 41 Phil Ringnalda (:philor, back in August) 2012-04-16 19:47:37 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10958770&tree=Mozilla-Inbound
Comment 42 Phil Ringnalda (:philor, back in August) 2012-04-16 22:00:02 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10961553&tree=Mozilla-Inbound
Comment 43 Nick Thomas [:nthomas] 2012-04-16 22:09:04 PDT
jmaher, there seems to be multiple issues here so perhaps you can help untangle them. This seems to be typical (from the log in comment #42) but the tests running prior to the fail does vary:

88228 INFO TEST-PASS | /tests/content/media/test/test_fragment_noplay.html | big.wav#t=3-7 fragment test: mozFragmentEnd (9.287981) == end Time (9.287981)
88229 INFO TEST-PASS | /tests/content/media/test/test_fragment_noplay.html | [finished big.wav#t=3-7-4] Length of array should match number of running tests - 1 should equal 1
--DOMWINDOW == 42 (0B053AA8) [serial = 2631] [outer = 00000000] [url = about:blank]
--DOMWINDOW == 41 (1094F7F8) [serial = 2636] [outer = 00000000] [url = http://mochi.test:8888/tests/content/media/test/test_error_on_404.html]
--DOMWINDOW == 40 (07E5E800) [serial = 2635] [outer = 00000000] [url = http://mochi.test:8888/tests/content/media/test/bogus.ogv]
--DOMWINDOW == 39 (12169808) [serial = 2633] [outer = 00000000] [url = http://mochi.test:8888/tests/content/media/test/test_error_in_video_document.html]
--DOMWINDOW == 38 (118BCFB0) [serial = 2632] [outer = 00000000] [url = about:blank]
--DOMWINDOW == 37 (107D1348) [serial = 2622] [outer = 00000000] [url = http://mochi.test:8888/tests/content/media/test/test_delay_load.html]
--DOMWINDOW == 36 (130D3738) [serial = 2619] [outer = 00000000] [url = http://mochi.test:8888/tests/content/media/test/test_decode_error.html]
--DOMWINDOW == 35 (13A64298) [serial = 2618] [outer = 00000000] [url = http://mochi.test:8888/tests/content/media/test/test_currentTime.html]
--DOMWINDOW == 34 (11EAC178) [serial = 2617] [outer = 00000000] [url = http://mochi.test:8888/tests/content/media/test/test_controls.html]
--DOMWINDOW == 33 (11C8F5A8) [serial = 2616] [outer = 00000000] [url = http://mochi.test:8888/tests/content/media/test/test_contentDuration7.html]
--DOMWINDOW == 32 (11B6EFC0) [serial = 2615] [outer = 00000000] [url = http://mochi.test:8888/tests/content/media/test/test_contentDuration6.html]
--DOMWINDOW == 31 (11885158) [serial = 2614] [outer = 00000000] [url = http://mochi.test:8888/tests/content/media/test/test_contentDuration5.html]
--DOMWINDOW == 30 (11F59178) [serial = 2613] [outer = 00000000] [url = http://mochi.test:8888/tests/content/media/test/test_contentDuration4.html]
--DOMWINDOW == 29 (1240A0B0) [serial = 2612] [outer = 00000000] [url = http://mochi.test:8888/tests/content/media/test/test_contentDuration3.html]
--DOMWINDOW == 28 (10F97218) [serial = 2611] [outer = 00000000] [url = http://mochi.test:8888/tests/content/media/test/test_contentDuration2.html]
--DOMWINDOW == 27 (11C27D70) [serial = 2610] [outer = 00000000] [url = http://mochi.test:8888/tests/content/media/test/test_contentDuration1.html]
--DOMWINDOW == 26 (10F5C068) [serial = 2609] [outer = 00000000] [url = http://mochi.test:8888/tests/content/media/test/test_constants.html]
--DOMWINDOW == 25 (119830D8) [serial = 2608] [outer = 00000000] [url = http://mochi.test:8888/tests/content/media/test/test_closing_connections.html]
--DOMWINDOW == 24 (11858890) [serial = 2621] [outer = 00000000] [url = http://mochi.test:8888/tests/content/media/test/test_defaultMuted.html]
--DOMWINDOW == 23 (11EDC078) [serial = 2620] [outer = 00000000] [url = http://mochi.test:8888/tests/content/media/test/test_decoder_disable.html]
WARNING: Resource read failed: file e:/builds/moz2_slave/m-in-w32-dbg/build/content/media/wave/nsWaveReader.cpp, line 301
WARNING: NS_ENSURE_SUCCESS(res, -1) failed with result 0x80004005: file e:/builds/moz2_slave/m-in-w32-dbg/build/content/media/ogg/nsOggReader.cpp, line 705
WARNING: NS_ENSURE_SUCCESS(res, -1) failed with result 0x80004005: file e:/builds/moz2_slave/m-in-w32-dbg/build/content/media/ogg/nsOggReader.cpp, line 705
WARNING: NS_ENSURE_SUCCESS(res, -1) failed with result 0x80004005: file e:/builds/moz2_slave/m-in-w32-dbg/build/content/media/ogg/nsOggReader.cpp, line 705
WARNING: NS_ENSURE_SUCCESS(res, -1) failed with result 0x80004005: file e:/builds/moz2_slave/m-in-w32-dbg/build/content/media/ogg/nsOggReader.cpp, line 705
WARNING: NS_ENSURE_SUCCESS(res, -1) failed with result 0x80004005: file e:/builds/moz2_slave/m-in-w32-dbg/build/content/media/ogg/nsOggReader.cpp, line 705

### Firefox may have crashed here

INFO | runtests.py | Received unexpected exception while running application 
''NoneType' object has no attribute 'group''

### runtests.py doesn't deal with that very gracefully

WARNING: nsExceptionService ignoring thread destruction after shutdown: file e:/builds/moz2_slave/m-in-w32-dbg/build/xpcom/base/nsExceptionService.cpp, line 199
nsStringStats
 => mAllocCount:         115268
 => mReallocCount:         8310
 => mFreeCount:          115268
 => mShareCount:         136316
 => mAdoptCount:           3683
 => mAdoptFreeCount:       3683
ERROR: The process "1044" not found.
SUCCESS: The process with PID 3968 has been terminated.
TEST-UNEXPECTED-FAIL | automationutils.processLeakLog() | missing output line for total leaks!
TEST-UNEXPECTED-FAIL | plugin process 1112 | automationutils.processLeakLog() | missing output line for total leaks!

== BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, plugin process 1364

     |<----------------Class--------------->|<-----Bytes------>|<----------------Objects---------------->|<--------------References-------------->|
                                              Per-Inst   Leaked    Total      Rem      Mean       StdDev     Total      Rem      Mean       StdDev
   0 TOTAL                                          26        0      345        0 (   23.80 +/-    18.56)      248        0 (   53.05 +/-    42.14)

nsTraceRefcntImpl::DumpStatistics: 23 entries
TEST-PASS | plugin process 1364 | automationutils.processLeakLog() | no leaks detected!

INFO | runtests.py | Running tests: end.
Traceback (most recent call last):
  File "mochitest/runtests.py", line 914, in <module>
  File "mochitest/runtests.py", line 911, in main
  File "mochitest/runtests.py", line 719, in runTests
  File "mochitest/runtests.py", line 610, in cleanup
  File "c:\mozilla-build\python25\Lib\shutil.py", line 169, in rmtree
    rmtree(fullname, ignore_errors, onerror)
  File "c:\mozilla-build\python25\Lib\shutil.py", line 169, in rmtree
    rmtree(fullname, ignore_errors, onerror)
  File "c:\mozilla-build\python25\Lib\shutil.py", line 169, in rmtree
    rmtree(fullname, ignore_errors, onerror)
  File "c:\mozilla-build\python25\Lib\shutil.py", line 174, in rmtree
    onerror(os.remove, fullname, sys.exc_info())
  File "c:\mozilla-build\python25\Lib\shutil.py", line 172, in rmtree
    os.remove(fullname)
WindowsError: [Error 13] The process cannot access the file because it is being used by another process: 'c:\\docume~1\\cltbld\\locals~1\\temp\\tmpig9qs_\\Cache\\2\\55\\BC091d01'

### Something is still locking the file from the Firefox crash

command timed out: 1200 seconds without output, attempting to kill
SIGKILL failed to kill process
using fake rc=-1
program finished with exit code -1

### buildbot fails to kill some process too (known issue on windows)
Comment 44 Phil Ringnalda (:philor, back in August) 2012-04-17 07:21:22 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10974352&tree=Mozilla-Inbound
Comment 45 Phil Ringnalda (:philor, back in August) 2012-04-18 15:29:44 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11017523&tree=Mozilla-Inbound
Comment 46 Phil Ringnalda (:philor, back in August) 2012-04-19 15:15:14 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11049326&tree=Mozilla-Inbound
Comment 47 Phil Ringnalda (:philor, back in August) 2012-04-20 07:36:55 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11061546&tree=Mozilla-Inbound
Comment 48 Phil Ringnalda (:philor, back in August) 2012-04-20 08:03:01 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11059128&tree=Firefox
Comment 49 Ryan VanderMeulen [:RyanVM] 2012-04-20 19:28:44 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11081455&tree=Birch
Comment 50 Phil Ringnalda (:philor, back in August) 2012-04-22 01:39:20 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11103373&tree=Firefox
Comment 51 Phil Ringnalda (:philor, back in August) 2012-04-24 12:03:09 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11163918&tree=Firefox
Comment 52 Phil Ringnalda (:philor, back in August) 2012-04-24 18:40:37 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11176689&tree=Mozilla-Inbound
Comment 55 Phil Ringnalda (:philor, back in August) 2012-04-25 22:31:31 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11218170&tree=Mozilla-Inbound
Comment 56 Phil Ringnalda (:philor, back in August) 2012-04-26 08:02:38 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11226667&tree=Mozilla-Inbound
Comment 57 Phil Ringnalda (:philor, back in August) 2012-04-27 09:51:46 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11268200&tree=Firefox
Comment 58 Phil Ringnalda (:philor, back in August) 2012-04-27 12:54:00 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11274796&tree=Mozilla-Inbound
Comment 59 Phil Ringnalda (:philor, back in August) 2012-04-27 21:06:36 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11277411&tree=Mozilla-Inbound
Comment 60 Phil Ringnalda (:philor, back in August) 2012-04-27 21:09:16 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11278157&tree=Mozilla-Inbound
Comment 61 Phil Ringnalda (:philor, back in August) 2012-04-27 22:04:11 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11277565&tree=Mozilla-Inbound
Comment 62 Phil Ringnalda (:philor, back in August) 2012-04-27 22:08:20 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11284609&tree=Firefox
Comment 65 Phil Ringnalda (:philor, back in August) 2012-04-29 05:45:52 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11304932&tree=Firefox
Comment 66 Ryan VanderMeulen [:RyanVM] 2012-04-29 16:20:30 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11311925&tree=Firefox
Comment 67 Nick Thomas [:nthomas] 2012-04-29 16:49:35 PDT
Is there a clear action for RelEng here ? Should it go to Core:Testing for debugging ?
Comment 70 Phil Ringnalda (:philor, back in August) 2012-04-29 23:04:35 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11316654&tree=Mozilla-Inbound
Comment 74 Phil Ringnalda (:philor, back in August) 2012-04-30 23:08:13 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11350785&tree=Mozilla-Inbound
Comment 75 Phil Ringnalda (:philor, back in August) 2012-04-30 23:22:34 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11348659&tree=Mozilla-Aurora
Comment 76 Nick Thomas [:nthomas] 2012-05-01 00:43:56 PDT
Halp! Any insight what's going wrong here ?
Comment 77 Ted Mielczarek [:ted.mielczarek] 2012-05-01 07:22:57 PDT
My guess is that:
1) Something is failing a regex test and breaking some code, causing an exception to propagate outwards to runtests.py
2) runtests.py then tries to clean up the profile and fails because it hasn't waited for the app to exit, so profile files are still locked.

It's really hard to guess what regex is failing, my best guess is:
http://mxr.mozilla.org/mozilla-central/source/build/automationutils.py#533

We could change the log statement here to be .log.exception:
http://mxr.mozilla.org/mozilla-central/source/testing/mochitest/runtests.py#703

which would give us a traceback instead of just the exception info, which would help.
Comment 78 Ted Mielczarek [:ted.mielczarek] 2012-05-01 07:55:52 PDT
Probably fallout from bug 683953, it looks like.
Comment 79 Ted Mielczarek [:ted.mielczarek] 2012-05-01 08:34:30 PDT
Created attachment 619937 [details] [diff] [review]
add some diagnostics to get more info about Python exceptions during Mochitest

This patch does two things that should improve our diagnostics here:
1) use log.exception if we catch an exception, which will print a full traceback, so we can see where we're actually failing
2) log the output line before passing it off to the leak logger code, so if that code is what's failing, we can see what output it's choking on
Comment 80 Serge Gautherie (:sgautherie) 2012-05-01 08:45:46 PDT
Comment on attachment 619937 [details] [diff] [review]
add some diagnostics to get more info about Python exceptions during Mochitest

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

::: testing/mochitest/runtests.py
@@ +699,5 @@
>      except KeyboardInterrupt:
>        self.automation.log.info("INFO | runtests.py | Received keyboard interrupt.\n");
>        status = -1
>      except:
> +      self.automation.log.exception("INFO | runtests.py | Received unexpected exception while running application\n")

Nit: Should 'INFO' become 'WARNING' or the like too?
Comment 84 Joel Maher ( :jmaher ) 2012-05-02 06:04:53 PDT
Comment on attachment 619937 [details] [diff] [review]
add some diagnostics to get more info about Python exceptions during Mochitest

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

looks good to me.
Comment 85 Ted Mielczarek [:ted.mielczarek] 2012-05-02 07:09:19 PDT
Diagnostic patch landed on inbound:
http://hg.mozilla.org/integration/mozilla-inbound/rev/78e104d007e0
Comment 86 Ted Mielczarek [:ted.mielczarek] 2012-05-02 07:10:14 PDT
(In reply to Serge Gautherie (:sgautherie) from comment #80)
> Nit: Should 'INFO' become 'WARNING' or the like too?

Seems irrelevant, there's no real convention here, it's purely informational.
Comment 87 Phil Ringnalda (:philor, back in August) 2012-05-02 14:27:03 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11399068&tree=Mozilla-Inbound

--WARNING: Resource read failed: file e:/builds/moz2_slave/m-in-w32-dbg/build/content/media/wave/nsWaveReader.cpp, line 301
DOMWINDOW == 18 (10E935E0) [serial = 2713] [outer = 00000000] [url = chrome://browser/content/devtools/gcliblank.xhtml]
--DOMWINDOW == 17 (106044E8) [serial = 2712] [outer = 00000000] [url = chrome://browser/content/devtools/gcliblank.xhtml]
--DOMWINDOW == 16 (1WARNING: NS_ENSURE_SUCCESS(res, -1) failed with result 0x80004005: file e:/builds/moz2_slave/m-in-w32-dbg/build/content/media/ogg/nsOggReader.cpp, line 705
INFO | runtests.py | Received unexpected exception while running application
Traceback (most recent call last):
  File "mochitest/runtests.py", line 698, in runTests
    timeout = timeout)
  File "c:\talos-slave\test\build\mochitest\automation.py", line 900, in runApp
    status = self.waitForFinish(proc, utilityPath, timeout, maxTime, startTime, debuggerInfo, symbolsPath, logger)
  File "c:\talos-slave\test\build\mochitest\automation.py", line 749, in waitForFinish
    logger.log(line)
  File "c:\talos-slave\test\build\mochitest\automationutils.py", line 474, in log
    self._logWindow(line)
  File "c:\talos-slave\test\build\mochitest\automationutils.py", line 508, in _logWindow
    id = self._parseValue(line, "serial")
  File "c:\talos-slave\test\build\mochitest\automationutils.py", line 533, in _parseValue
    return re.search("\[%s = (.+?)\]" % name, line).group(1)
AttributeError: 'NoneType' object has no attribute 'group'
Comment 88 Ted Mielczarek [:ted.mielczarek] 2012-05-02 14:32:35 PDT
oh-HO! So my guess in comment 77 was correct. We can also see the log line it's choking on:
--DOMWINDOW == 16 (1WARNING: NS_ENSURE_SUCCESS(res, -1) failed with result 0x80004005: file e:/builds/moz2_slave/m-in-w32-dbg/build/content/media/ogg/nsOggReader.cpp, line 705

Why yes, this would totally make us choke! I'm not at all sure what's happening there to make it intermingle that output, that seems really bad. That should all be main-thread, I'd think. In any event, we should handle this more gracefully.
Comment 91 Ed Morley [:emorley] 2012-05-03 02:11:01 PDT
(Reopening since just diagnostic patch landed so far aiui)
Comment 96 Phil Ringnalda (:philor, back in August) 2012-05-03 11:56:59 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11434842&tree=Mozilla-Inbound
Comment 97 Phil Ringnalda (:philor, back in August) 2012-05-03 16:02:25 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11443009&tree=Mozilla-Inbound
Comment 98 Phil Ringnalda (:philor, back in August) 2012-05-03 18:05:45 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11446737&tree=Mozilla-Inbound
Comment 100 Phil Ringnalda (:philor, back in August) 2012-05-03 18:13:13 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11447192&tree=Firefox
Comment 103 Phil Ringnalda (:philor, back in August) 2012-05-03 20:33:13 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11451237&tree=Mozilla-Inbound
Comment 104 Phil Ringnalda (:philor, back in August) 2012-05-03 21:30:10 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11452614&tree=Mozilla-Inbound
Rev3 WINNT 5.1 mozilla-inbound debug test mochitests-3/5 on 2012-05-03 20:38:33 PDT for push a4c02dde700c

++DOMWINDOW == 105 (1156F940) [serial = WARNING: 1 sort operation has occurred for the SQL statement '0x10f5ebd0'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file e:/builds/moz2_slave/m-in-w32-dbg/build/storage/src/mozStoragePrivateHelpers.cpp, line 144
INFO | runtests.py | Received unexpected exception while running application
Traceback (most recent call last):
  File "mochitest/runtests.py", line 698, in runTests
    timeout = timeout)
  File "c:\talos-slave\test\build\mochitest\automation.py", line 900, in runApp
    status = self.waitForFinish(proc, utilityPath, timeout, maxTime, startTime, debuggerInfo, symbolsPath, logger)
  File "c:\talos-slave\test\build\mochitest\automation.py", line 749, in waitForFinish
    logger.log(line)
  File "c:\talos-slave\test\build\mochitest\automationutils.py", line 474, in log
    self._logWindow(line)
  File "c:\talos-slave\test\build\mochitest\automationutils.py", line 508, in _logWindow
    id = self._parseValue(line, "serial")
  File "c:\talos-slave\test\build\mochitest\automationutils.py", line 533, in _parseValue
    return re.search("\[%s = (.+?)\]" % name, line).group(1)
AttributeError: 'NoneType' object has no attribute 'group'
Comment 109 Tim Taubert [:ttaubert] 2012-05-04 05:34:41 PDT
Created attachment 621018 [details] [diff] [review]
make regex parsing more tolerant towards corrupted log lines
Comment 110 Ted Mielczarek [:ted.mielczarek] 2012-05-04 06:35:25 PDT
Comment on attachment 621018 [details] [diff] [review]
make regex parsing more tolerant towards corrupted log lines

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

::: build/automationutils.py
@@ +539,5 @@
>  
>    def _parseValue(self, line, name):
> +    match = re.search("\[%s = (.+?)\]" % name, line)
> +    if match:
> +      return match.group(1)

I think you should explicitly return None here if the regex match fails just to be very clear about what's happening.
Comment 111 Tim Taubert [:ttaubert] 2012-05-04 07:31:52 PDT
https://hg.mozilla.org/integration/fx-team/rev/b6e6a24c9e95
Comment 114 Phil Ringnalda (:philor, back in August) 2012-05-04 10:14:37 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11470934&tree=Mozilla-Inbound
Comment 116 Ed Morley [:emorley] 2012-05-04 12:04:42 PDT
(Pre fix landing)

https://tbpl.mozilla.org/php/getParsedLog.php?id=11447823&tree=Fx-Team
Comment 117 Phil Ringnalda (:philor, back in August) 2012-05-04 12:10:19 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11472498&tree=Firefox
Comment 118 Phil Ringnalda (:philor, back in August) 2012-05-04 15:12:30 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11479171&tree=Mozilla-Aurora
Comment 119 Phil Ringnalda (:philor, back in August) 2012-05-04 15:27:37 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11480152&tree=Mozilla-Inbound
Comment 120 Phil Ringnalda (:philor, back in August) 2012-05-04 15:33:29 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11475860&tree=Mozilla-Inbound
++DOMWINDOW == 18 (142Can't find symbol 'GetTexImage'
Comment 121 Tim Taubert [:ttaubert] 2012-05-04 15:38:03 PDT
https://hg.mozilla.org/mozilla-central/rev/b6e6a24c9e95
Comment 122 Phil Ringnalda (:philor, back in August) 2012-05-04 18:51:05 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11483451&tree=Mozilla-Inbound
Comment 123 Phil Ringnalda (:philor, back in August) 2012-05-04 18:52:31 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11482639&tree=Mozilla-Inbound
Comment 124 Phil Ringnalda (:philor, back in August) 2012-05-07 11:13:37 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11531444&tree=Mozilla-Aurora
Comment 125 Ted Mielczarek [:ted.mielczarek] 2012-05-07 11:17:26 PDT
This is a pretty trivial patch, should be easy enough to transplant to Aurora if desired.
Comment 127 Ted Mielczarek [:ted.mielczarek] 2012-05-07 12:17:03 PDT
Comment on attachment 621018 [details] [diff] [review]
make regex parsing more tolerant towards corrupted log lines

[Approval Request Comment]
Regression caused by (bug #): bug 683953
User impact if declined: Intermittent Mochitest orange
Testing completed (on m-c, etc.): Patch has been running without issue on mozilla-central for a few days.
Risk to taking this patch (and alternatives if risky): Very low-risk, test-harness only.
String changes made by this patch: None
Comment 129 Ted Mielczarek [:ted.mielczarek] 2012-05-08 06:07:06 PDT
Comment on attachment 621018 [details] [diff] [review]
make regex parsing more tolerant towards corrupted log lines

[Approval Request Comment]
See comment 127 for Aurora approval request.
Comment 130 Lukas Blakk [:lsblakk] use ?needinfo 2012-05-09 15:35:24 PDT
Comment on attachment 621018 [details] [diff] [review]
make regex parsing more tolerant towards corrupted log lines

test harness only, approved.
Comment 131 Phil Ringnalda (:philor, back in August) 2012-05-10 17:40:23 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11660591&tree=Mozilla-Aurora
Comment 132 Phil Ringnalda (:philor, back in August) 2012-05-18 15:47:50 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11873168&tree=Mozilla-Aurora
Comment 133 Phil Ringnalda (:philor, back in August) 2012-05-18 15:58:08 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11875246&tree=Mozilla-Aurora
Comment 134 Phil Ringnalda (:philor, back in August) 2012-05-21 20:51:46 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=11936178&tree=Mozilla-Aurora
Comment 135 Phil Ringnalda (:philor, back in August) 2012-05-21 20:57:26 PDT
https://hg.mozilla.org/releases/mozilla-aurora/rev/2275d7877dfc
Comment 136 Phil Ringnalda (:philor, back in August) 2012-05-21 21:01:12 PDT
https://hg.mozilla.org/releases/mozilla-beta/rev/9e63a64ef822

Note You need to log in before you can comment on or make changes to this bug.