Closed Bug 1665209 Opened 5 years ago Closed 5 years ago

Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_click.py TestClick.test_input_file | AssertionError: InvalidArgumentException not raised

Categories

(Testing :: Marionette Client and Harness, defect, P5)

Product:
Testing
Component:
Marionette Client and Harness
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED WORKSFORME

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: assertion, intermittent-failure)

Filed by: nbeleuzu [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=315779328&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/GDVmVMhQTcyaCuErqBB0Hw/runs/0/artifacts/public/logs/live_backing.log

[task 2020-09-15T20:34:29.372Z] 20:34:29     INFO -  DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-09-15T20:34:29.374Z] 20:34:29     INFO -  1600202069372	Marionette	DEBUG	184 -> [0,9,"Marionette:GetContext",{}]
[task 2020-09-15T20:34:29.374Z] 20:34:29     INFO -  1600202069373	Marionette	DEBUG	184 <- [1,9,null,{"value":"content"}]
[task 2020-09-15T20:34:29.376Z] 20:34:29     INFO -  1600202069374	Marionette	DEBUG	184 -> [0,10,"Marionette:SetContext",{"value":"content"}]
[task 2020-09-15T20:34:29.376Z] 20:34:29     INFO -  1600202069374	Marionette	DEBUG	184 <- [1,10,null,{"value":null}]
[task 2020-09-15T20:34:29.377Z] 20:34:29     INFO -  1600202069376	Marionette	DEBUG	184 -> [0,11,"WebDriver:GetPageSource",{}]
[task 2020-09-15T20:34:29.379Z] 20:34:29     INFO -  1600202069378	Marionette	DEBUG	184 <- [1,11,null,{"value":"<html><head></head><body><input type=\"file\"></body></html>"}]
[task 2020-09-15T20:34:29.384Z] 20:34:29     INFO -  DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-09-15T20:34:29.384Z] 20:34:29     INFO -  1600202069383	Marionette	DEBUG	184 -> [0,12,"Marionette:SetContext",{"value":"content"}]
[task 2020-09-15T20:34:29.384Z] 20:34:29     INFO -  1600202069383	Marionette	DEBUG	184 <- [1,12,null,{"value":null}]
[task 2020-09-15T20:34:29.386Z] 20:34:29    ERROR -  TEST-UNEXPECTED-FAIL | testing/marionette/harness/marionette_harness/tests/unit/test_click.py TestClick.test_input_file | AssertionError: InvalidArgumentException not raised
[task 2020-09-15T20:34:29.386Z] 20:34:29     INFO -  Traceback (most recent call last):
[task 2020-09-15T20:34:29.386Z] 20:34:29     INFO -    File "Z:\task_1600199416\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 196, in run
[task 2020-09-15T20:34:29.386Z] 20:34:29     INFO -      testMethod()
[task 2020-09-15T20:34:29.386Z] 20:34:29     INFO -    File "Z:\task_1600199416\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_click.py", line 307, in test_input_file
[task 2020-09-15T20:34:29.386Z] 20:34:29     INFO -      self.marionette.find_element(By.TAG_NAME, "input").click()
[task 2020-09-15T20:34:29.386Z] 20:34:29     INFO -  TEST-INFO took 519ms```

Here the real failure lines:

[task 2020-09-15T20:34:29.000Z] 20:34:29     INFO -  1600202068998	Marionette	TRACE	Received message pageshow for data:text/html;charset=utf-8,%3Cinput%20type%3Dfile%3E
[task 2020-09-15T20:34:29.000Z] 20:34:29     INFO -  1600202068999	Marionette	DEBUG	184 <- [1,2,null,{"value":null}]
[task 2020-09-15T20:34:29.022Z] 20:34:29     INFO -  DEBUG: Completed blocker Transaction (16) for phase content-prefs.sqlite#0: waiting for clients
[task 2020-09-15T20:34:29.032Z] 20:34:29     INFO -  1600202069025	Marionette	DEBUG	184 -> [0,3,"WebDriver:FindElement",{"using":"tag name","value":"input"}]
[task 2020-09-15T20:34:29.032Z] 20:34:29     INFO -  1600202069030	Marionette	DEBUG	184 <- [1,3,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"bc1ac4b0-2507-4b70-8145-c9b26166849b"}}]
[task 2020-09-15T20:34:29.037Z] 20:34:29     INFO -  1600202069032	Marionette	DEBUG	184 -> [0,4,"WebDriver:ElementClick",{"id":"bc1ac4b0-2507-4b70-8145-c9b26166849b"}]
[task 2020-09-15T20:34:29.263Z] 20:34:29     INFO -  1600202069259	Marionette	TRACE	Canceled page load listener because no navigation has been detected

This should basically throw the InvalidArgumentError:
https://searchfox.org/mozilla-release/rev/7ac70cbbbe2f44d1140535d2909458d04212b32f/testing/marionette/interaction.js#141-143

The only situation where this could happen is that the code actually uses the seleniumClickElement code path here. But that is true by default, and it's not getting overridden when starting the new session.

So far it only failed from 15th to 17th of September. Since then no more failures. Lets observe if it happens again or not.

Checking the log again this is most likely a problem with a delayed click due to the synchronous capabilities update with the parent process. This has been removed with the patch on bug 1394354, and as such this failure should no longer happen.

Depends on: 1394354

Probably fixed by bug 1394354. Marking as WFM.

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → WORKSFORME
Product: Testing → Remote Protocol
Moving bug to Testing::Marionette Client and Harness component per bug 1815831.
Component: Marionette → Marionette Client and Harness
Product: Remote Protocol → Testing
You need to log in before you can comment on or make changes to this bug.