1050170 - "test_end for X logged while not in progress" shown after a TimeoutException

Status: RESOLVED INCOMPLETE

(Testing :: Mozbase, defect)

Description

[Ed Morley [:emorley]]

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? :-)

Comment 1

[Ed Morley [:emorley]]

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

[David Burns :automatedtester]

(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

Comment 3

[Ed Morley [:emorley]]

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

[Chris Manchester (limited bugmail, email directly)]

(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.

Comment 5

[Ed Morley [:emorley]]

Mass-closing old bugs I filed that have not had recent activity/no longer affect me.