Closed Bug 740242 Opened 12 years ago Closed 12 years ago

runtests.py | Received unexpected exception while running application ''NoneType' object has no attribute 'group'' (mostly in windows debug test mochitests-1/5)

Categories

(Testing :: Mochitest, defect, P3)

Product:
Testing
Component:
Mochitest
Platform:
x86
Windows Vista
Type:
defect

Tracking

(firefox13 fixed, firefox14 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla15
Tracking Flags:
Tracking Status
firefox13 --- fixed
firefox14 --- fixed

People

(Reporter: rnewman, Assigned: ttaubert)

References

Details

(Keywords: intermittent-failure, Whiteboard: [cleanup])

Attachments

(3 files)

check winrm-0.1.exe into /build/tools
32.10 KB, text/plain
coop
: review+
Details
add some diagnostics to get more info about Python exceptions during Mochitest
3.13 KB, patch
jmaher
: review+
Details | Diff | Splinter Review
make regex parsing more tolerant towards corrupted log lines
1.70 KB, patch
ted
: review+
lsblakk
: approval-mozilla-aurora+
lsblakk
: approval-mozilla-beta+
Details | Diff | Splinter Review 
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
Oh, Windows. Not sure if deploying jhford's tool from bug 727551 will help here unless we also make runtests.py aware of it.
Component: Release Engineering → Release Engineering: Platform Support
Priority: -- → P3
QA Contact: release → coop
Whiteboard: [cleanup]
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.
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.
binaries in hg is sub-optimal, but it's a tiny one and we already have the stackwalk ones in this repo.  Also opsi.
Attachment #614180 - Flags: review?(coop)
Attachment #614180 - Flags: review?(coop) → review+
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)
Summary: runtests.py | Received unexpected exception while running application ''NoneType' object has no attribute 'group'' → runtests.py | Received unexpected exception while running application ''NoneType' object has no attribute 'group'' (mostly in windows debug test mochitests-1/5)
Is there a clear action for RelEng here ? Should it go to Core:Testing for debugging ?
Halp! Any insight what's going wrong here ?
Component: Release Engineering: Platform Support → Mochitest
Product: mozilla.org → Testing
QA Contact: coop → mochitest
Version: other → Trunk
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.
Probably fallout from bug 683953, it looks like.
Blocks: 683953
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
Attachment #619937 - Flags: review?(jmaher)
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 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.
Attachment #619937 - Flags: review?(jmaher) → review+
(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.
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'
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.
https://hg.mozilla.org/mozilla-central/rev/78e104d007e0
Status: NEW → RESOLVED
Closed: 12 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla15
(Reopening since just diagnostic patch landed so far aiui)
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
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'
Assignee: nobody → ttaubert

        Attachment #621018 -
        Flags: review?(ted.mielczarek)

    
    

    
  
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.

        Attachment #621018 -
        Flags: review?(ted.mielczarek) → review+

    
    

    
  
https://hg.mozilla.org/integration/fx-team/rev/b6e6a24c9e95
Whiteboard: [cleanup][orange] → [cleanup][orange][fixed-in-fx-team]

    
    

    
  
https://hg.mozilla.org/mozilla-central/rev/b6e6a24c9e95
Status: REOPENED → RESOLVED
Closed: 12 years ago → 12 years ago
Resolution: --- → FIXED
Whiteboard: [cleanup][orange][fixed-in-fx-team] → [cleanup][orange]

    
    

    
  
This is a pretty trivial patch, should be easy enough to transplant to Aurora if desired.

    
    

    
  
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

        Attachment #621018 -
        Flags: approval-mozilla-aurora?

    
    

    
  
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.

        Attachment #621018 -
        Flags: approval-mozilla-beta?

    
    

    
  
Comment on attachment 621018 [details] [diff] [review]
make regex parsing more tolerant towards corrupted log lines

test harness only, approved.

        Attachment #621018 -
        Flags: approval-mozilla-beta?

        Attachment #621018 -
        Flags: approval-mozilla-beta+

        Attachment #621018 -
        Flags: approval-mozilla-aurora?

        Attachment #621018 -
        Flags: approval-mozilla-aurora+

    
  
Depends on: 758986
Whiteboard: [cleanup][orange] → [cleanup]

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