Closed
Bug 1050170
Opened 10 years ago
Closed 6 years ago
"test_end for X logged while not in progress" shown after a TimeoutException
Categories
(Testing :: Mozbase, defect)
Tracking
(Not tracked)
RESOLVED
INCOMPLETE
People
(Reporter: emorley, Unassigned)
References
(Blocks 1 open bug)
Details
In this log: https://tbpl.mozilla.org/php/getParsedLog.php?id=45402772&tree=Mozilla-Inbound b2g_emulator_vm mozilla-inbound opt test marionette-webapi on 2014-08-07 00:42:35 PDT for push 73e945ea5a4c slave: tst-linux64-spot-108 We appear to have a case of marionette not responding, which causes a TimeoutException, and thus a failed test - however we finally do get a response and then complain that a test_end was logged while a test was not in progress. We then also get a "AttributeError: 'NoneType' object has no attribute 'exc_info'" later. Could we handle this case any better? :-)
Flags: needinfo?(dburns)
Reporter | ||
Comment 1•10 years ago
|
||
01:07:01 INFO - 08-07 04:00:58.991 I/Gecko ( 44): 1407398458991 Marionette DEBUG Got request: setTestName, data: {"to":"0","sessionId":{"rotatable":true,"browserVersion":"34.0a1","takesScreenshot":true,"appBuildId":"20140807002215","XULappId":"{3c2e2abc-06d4-11e1-ac3b-374f68613e61}","secureSsl":false,"platform":"ANDROID","browserName":"B2G","version":"34.0a1","device":"qemu","b2g":true,"nativeEvents":false,"platformVersion":"34.0a1","takesElementScreenshot":true,"platformName":"ANDROID","handlesAlerts":false},"name":"setTestName","parameters":{"value":"test_implicit_waits.py TestImplicitWaits.testShouldStillFailToFindAnElementWhenImplicitWaitsAreEnabled"}}, id: {2d1df248-b8b0-4117-b41e-98a385bbfb55} 01:07:01 INFO - 08-07 04:00:59.002 I/Gecko ( 44): 1407398459003 Marionette INFO sendToClient: {"from":"0","ok":true}, {2d1df248-b8b0-4117-b41e-98a385bbfb55}, {2d1df248-b8b0-4117-b41e-98a385bbfb55} 01:07:01 INFO - 08-07 04:00:59.032 I/Gecko ( 44): 1407398459038 Marionette DEBUG Got request: execute, data: {"to":"0","sessionId":{"rotatable":true,"browserVersion":"34.0a1","takesScreenshot":true,"appBuildId":"20140807002215","XULappId":"{3c2e2abc-06d4-11e1-ac3b-374f68613e61}","secureSsl":false,"platform":"ANDROID","browserName":"B2G","version":"34.0a1","device":"qemu","b2g":true,"nativeEvents":false,"platformVersion":"34.0a1","takesElementScreenshot":true,"platformName":"ANDROID","handlesAlerts":false},"name":"executeScript","parameters":{"scriptTimeout":null,"specialPowers":false,"script":"log('TEST-START: /builds/slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_implicit_waits.py:testShouldStillFailToFindAnElementWhenImplicitWaitsAreEnabled')","newSandbox":true,"args":[],"filename":"marionette_test.py","line":350}}, id: {3ea2d3ba-0382-4194-a6dd-4bd918daf72e} 01:07:01 INFO - 08-07 04:00:59.072 I/Gecko ( 44): MARIONETTE LOG: INFO: TEST-START: /builds/slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_implicit_waits.py:testShouldStillFailToFindAnElementWhenImplicitWaitsAreEnabled 01:07:01 INFO - 08-07 04:00:59.132 I/Gecko ( 44): 1407398459139 Marionette INFO sendToClient: {"from":"0","value":null}, {3ea2d3ba-0382-4194-a6dd-4bd918daf72e}, {3ea2d3ba-0382-4194-a6dd-4bd918daf72e} 01:07:01 INFO - B2G is still running but Marionette can't respond due to either a Gecko, Gaia or Marionette error. Above, the 5 most recent errors are listed. Check logcat for all errors if these errors are not the cause of the failure. 01:07:01 ERROR - TEST-UNEXPECTED-ERROR | test_implicit_waits.py TestImplicitWaits.testShouldStillFailToFindAnElementWhenImplicitWaitsAreEnabled | TimeoutException: TimeoutException: Connection timed out 01:07:01 INFO - Traceback (most recent call last): 01:07:01 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette_test.py", line 171, in run 01:07:01 INFO - testMethod() 01:07:01 INFO - File "/builds/slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_implicit_waits.py", line 20, in testShouldStillFailToFindAnElementWhenImplicitWaitsAreEnabled 01:07:01 INFO - self.marionette.navigate(test_html) 01:07:01 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 1040, in navigate 01:07:01 INFO - response = self._send_message("get", "ok", url=url) 01:07:01 INFO - File "/builds/slave/test/build/tests/marionette/marionette/decorators.py", line 35, in _ 01:07:01 INFO - return func(*args, **kwargs) 01:07:01 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 617, in _send_message 01:07:01 INFO - "Connection timed out", status=errors.ErrorCodes.TIMEOUT) 01:07:01 INFO - TEST-INFO expected PASS | took 362216ms 01:07:01 INFO - mozdevice _runCmd - command: /builds/slave/test/build/emulator/b2g-distro/out/host/linux-x86/bin/adb -s emulator-5554 pull /data/local/tests/profile/minidumps /tmp/tmp0HC3ti 01:07:01 INFO - mozdevice remote object '/data/local/tests/profile/minidumps' does not exist 01:07:01 INFO - mozdevice _runCmd - command: /builds/slave/test/build/emulator/b2g-distro/out/host/linux-x86/bin/adb -s emulator-5554 shell ls -a /data/local/tests/profile/minidumps/ 01:07:01 INFO - mozdevice /data/local/tests/profile/minidumps/: No such file or directory 01:07:01 INFO - mozdevice _runCmd - command: /builds/slave/test/build/emulator/b2g-distro/out/host/linux-x86/bin/adb -s emulator-5554 shell ls -a /data/local/tests/profile/minidumps 01:07:01 INFO - mozdevice /data/local/tests/profile/minidumps: No such file or directory 01:07:01 INFO - mozdevice _runCmd - command: /builds/slave/test/build/emulator/b2g-distro/out/host/linux-x86/bin/adb -s emulator-5554 pull /data/local/tests/profile/minidumps /tmp/tmpGFka0n 01:07:01 INFO - mozdevice remote object '/data/local/tests/profile/minidumps' does not exist 01:07:01 INFO - mozdevice _runCmd - command: /builds/slave/test/build/emulator/b2g-distro/out/host/linux-x86/bin/adb -s emulator-5554 shell ls -a /data/local/tests/profile/minidumps/ 01:07:01 INFO - mozdevice /data/local/tests/profile/minidumps/: No such file or directory 01:07:01 INFO - mozdevice _runCmd - command: /builds/slave/test/build/emulator/b2g-distro/out/host/linux-x86/bin/adb -s emulator-5554 shell ls -a /data/local/tests/profile/minidumps 01:07:01 INFO - mozdevice /data/local/tests/profile/minidumps: No such file or directory 01:07:01 ERROR - test_end for test_implicit_waits.py TestImplicitWaits.testShouldStillFailToFindAnElementWhenImplicitWaitsAreEnabled logged while not in progress. Logged with data: {"status": "ERROR", "test": "test_implicit_waits.py TestImplicitWaits.testShouldStillFailToFindAnElementWhenImplicitWaitsAreEnabled", "message": "Traceback (most recent call last):\n File \"/builds/slave/test/build/tests/marionette/marionette/marionette_test.py\", line 199, in run\n self.tearDown()\n File \"/builds/slave/test/build/tests/marionette/marionette/marionette_test.py\", line 354, in tearDown\n self.marionette.set_context(\"content\")\n File \"/builds/slave/test/build/tests/marionette/marionette/marionette.py\", line 945, in set_context\n return self._send_message('setContext', 'ok', value=context)\n File \"/builds/slave/test/build/tests/marionette/marionette/decorators.py\", line 35, in _\n return func(*args, **kwargs)\n File \"/builds/slave/test/build/tests/marionette/marionette/marionette.py\", line 602, in _send_message\n raise errors.MarionetteException(\"Please start a session\")\nMarionetteException: MarionetteException: Please start a session\n\n", "expected": "PASS", "extra": {}} ... 01:42:00 INFO - mozdevice _runCmd - command: /builds/slave/test/build/emulator/b2g-distro/out/host/linux-x86/bin/adb -s emulator-5554 shell ls -a /data/local/tests/profile/settings.json 01:42:00 INFO - mozdevice /data/local/tests/profile/settings.json: No such file or directory 01:42:00 INFO - mozdevice _runCmd - command: /builds/slave/test/build/emulator/b2g-distro/out/host/linux-x86/bin/adb -s emulator-5554 shell ls -a /data/local/tests/profile/ 01:42:00 INFO - mozdevice /data/local/tests/profile/: No such file or directory 01:42:00 INFO - mozdevice _runCmd - command: /builds/slave/test/build/emulator/b2g-distro/out/host/linux-x86/bin/adb -s emulator-5554 shell ls -a /data/local/tests/profile 01:42:00 INFO - mozdevice /data/local/tests/profile: No such file or directory 01:42:00 INFO - SUITE-END | took 3296s 01:42:00 INFO - Unhandled exception in thread started by <bound method Thread.__bootstrap of <Thread(Thread-18, stopped daemon 140524458338048)>> 01:42:00 INFO - Traceback (most recent call last): 01:42:00 INFO - File "/usr/lib/python2.7/threading.py", line 524, in __bootstrap 01:42:00 INFO - self.__bootstrap_inner() 01:42:00 INFO - File "/usr/lib/python2.7/threading.py", line 564, in __bootstrap_inner 01:42:00 INFO - (self.name, _format_exc())) 01:42:00 INFO - File "/usr/lib/python2.7/traceback.py", line 240, in format_exc 01:42:00 INFO - etype, value, tb = sys.exc_info() 01:42:00 INFO - AttributeError: 'NoneType' object has no attribute 'exc_info' 01:42:00 ERROR - Return code: 10
Comment 2•10 years ago
|
||
(In reply to Ed Morley [:edmorley] from comment #0) > In this log: > https://tbpl.mozilla.org/php/getParsedLog.php?id=45402772&tree=Mozilla- > Inbound > b2g_emulator_vm mozilla-inbound opt test marionette-webapi on 2014-08-07 > 00:42:35 PDT for push 73e945ea5a4c > slave: tst-linux64-spot-108 > > We appear to have a case of marionette not responding, which causes a > TimeoutException, and thus a failed test - however we finally do get a > response and then complain that a test_end was logged while a test was not > in progress. We then also get a "AttributeError: 'NoneType' object has no > attribute 'exc_info'" later. > > Could we handle this case any better? :-) Looking at this error I think that mozdevice has some race condition, or at least with the logging. The NoneType error from the stack and logging appear to be from MozDevice So can we handle this better, I dont think we can from marionette but probably from Mozbase
Flags: needinfo?(dburns)
Reporter | ||
Comment 3•10 years ago
|
||
And another: https://tbpl.mozilla.org/php/getParsedLog.php?id=45386484&tree=B2g-Inbound#error0 I'm guessing this is a regression from bug 956739.
Comment 4•10 years ago
|
||
(In reply to Ed Morley [:edmorley] from comment #3) > And another: > https://tbpl.mozilla.org/php/getParsedLog.php?id=45386484&tree=B2g- > Inbound#error0 > > I'm guessing this is a regression from bug 956739. This looks quite a bit like bug 1036565. I think the error message is pretty informative, but if it's irrelevant in context maybe we should change it.
Reporter | ||
Comment 5•6 years ago
|
||
Mass-closing old bugs I filed that have not had recent activity/no longer affect me.
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE
You need to log in
before you can comment on or make changes to this bug.
Description
•