1731576 - [wdspec] Log pollution for "UnsupportedCommandError: test.test not supported for destination ROOT" when command is not supported

Status: RESOLVED FIXED

(Testing :: geckodriver, defect, P2)

Description

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Over on bug 1730234 we have seen log pollution for expected failing tests when the specified command is not supported:

https://treeherder.mozilla.org/logviewer?job_id=351178075&repo=autoland&lineNumber=8910-8928

[task 2021-09-10T18:25:59.571Z] 18:25:59     INFO - STDERR: Future exception was never retrieved
[task 2021-09-10T18:25:59.571Z] 18:25:59     INFO - future: <Future finished exception=UnknownErrorException(unknown error, Error: Cannot forward command to "ROOT" from "ROOT"., forwardCommand@chrome://remote/content/shared/messagehandler/RootMessageHandler.jsm:80:15
[task 2021-09-10T18:25:59.571Z] 18:25:59     INFO - handleCommand@chrome://remote/content/shared/messagehandler/MessageHandler.jsm:155:17
[task 2021-09-10T18:25:59.571Z] 18:25:59     INFO - execute@chrome://remote/content/shared/webdriver/Session.jsm:219:32
[task 2021-09-10T18:25:59.571Z] 18:25:59     INFO - onPacket@chrome://remote/content/webdriver-bidi/WebDriverBiDiConnection.jsm:156:37
[task 2021-09-10T18:25:59.571Z] 18:25:59     INFO - onMessage@chrome://remote/content/server/WebSocketTransport.jsm:89:18
[task 2021-09-10T18:25:59.571Z] 18:25:59     INFO - handleEvent@chrome://remote/content/server/WebSocketTransport.jsm:71:14
[task 2021-09-10T18:25:59.571Z] 18:25:59     INFO - )>
[task 2021-09-10T18:25:59.571Z] 18:25:59     INFO - webdriver.bidi.error.UnknownErrorException: unknown error (Error: Cannot forward command to "ROOT" from "ROOT".)
[task 2021-09-10T18:25:59.571Z] 18:25:59     INFO - 
[task 2021-09-10T18:25:59.571Z] 18:25:59     INFO - Remote-end stacktrace:
[task 2021-09-10T18:25:59.571Z] 18:25:59     INFO - 
[task 2021-09-10T18:25:59.571Z] 18:25:59     INFO - forwardCommand@chrome://remote/content/shared/messagehandler/RootMessageHandler.jsm:80:15
[task 2021-09-10T18:25:59.571Z] 18:25:59     INFO - handleCommand@chrome://remote/content/shared/messagehandler/MessageHandler.jsm:155:17
[task 2021-09-10T18:25:59.571Z] 18:25:59     INFO - execute@chrome://remote/content/shared/webdriver/Session.jsm:219:32
[task 2021-09-10T18:25:59.571Z] 18:25:59     INFO - onPacket@chrome://remote/content/webdriver-bidi/WebDriverBiDiConnection.jsm:156:37
[task 2021-09-10T18:25:59.571Z] 18:25:59     INFO - onMessage@chrome://remote/content/server/WebSocketTransport.jsm:89:18
[task 2021-09-10T18:25:59.571Z] 18:25:59     INFO - handleEvent@chrome://remote/content/server/WebSocketTransport.jsm:71:14

Comment 1

[BugBot [:suhaib / :marco/ :calixte]]

The severity field is not set for this bug.
:whimboo, could you have a look please?

For more information, please visit auto_nag documentation.

Comment 3

[Julian Descottes [:jdescottes]]

Updating the title to reflect the new error message.

Comment 4

[Henrik Skupin [:whimboo][⌚️UTC+2]]

The error handling happens here:
https://searchfox.org/mozilla-central/source/testing/web-platform/tests/tools/wptrunner/wptrunner/executors/pytestrunner/runner.py#106-116

The error is actually raised here:
https://searchfox.org/mozilla-central/rev/3c9369510cb883b9f08d5f9641e1233d2142f025/remote/shared/messagehandler/RootMessageHandler.jsm#133

I wonder if we should instead just log a warning or have to wait until bug 1723592 is fixed so that we do not try to forward to a module which doesn't have the method implemented. Julian, what do you think?

Comment 5

[Julian Descottes [:jdescottes]]

In my opinion throwing an error is the good thing to do here.
Even when Bug 1723592 is implemented, I still think that we should throw if you try to call an invalid command.
If we only log a warning, consumers have no way to detect that something went wrong.

The error is actually raised here:
https://searchfox.org/mozilla-central/rev/3c9369510cb883b9f08d5f9641e1233d2142f025/remote/shared/messagehandler/RootMessageHandler.jsm#133

This is not the error we see in those tests anymore. This runtime error is here in case we start adding support for a new MessageHandler type but don't handle it yet in RootMessageHandler.

The error we see in the wdspec tests is from https://searchfox.org/mozilla-central/rev/3c9369510cb883b9f08d5f9641e1233d2142f025/remote/shared/messagehandler/MessageHandler.jsm#124-128

so that we do not try to forward to a module which doesn't have the method implemented

Note that this is already the case, we do not forward anything if the method is not implemented. Here we detect that the command is not implemented by looking at the methods available on the module.
Bug 1723592 is about changing the logic to detect this.

Comment 6

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Oh, I see. So the method where the error gets raised is called checkCommand and I would more expect that it returns a boolean instead. Given that we are not trying to actually run a command here, what is the benefit of having it here? Maybe we could change it so that the callee is handling that situation?

In the above case we are really trying to run an invalid command, and we also return the appropriate BiDi response with the failure. What makes me wonder is the following output:

future: <Future finished exception=UnknownErrorException

Isn't that Python? Aren't we correctly handling the failure in the test so that the Javascript stack gets printed to the log?

Comment 7

[Julian Descottes [:jdescottes]]

Oh, I see. So the method where the error gets raised is called checkCommand and I would more expect that it returns a boolean instead. Given that we are not trying to actually run a command here, what is the benefit of having it here? Maybe we could change it so that the callee is handling that situation?

checkCommand is called from handleCommand at https://searchfox.org/mozilla-central/rev/3407e72ceb5039da514c03ae61bd279b1725c3b2/remote/shared/messagehandler/MessageHandler.jsm#202. We can change the signature of checkCommand so that it returns a boolean, but then handleCommand should throw the error instead.

Comment 8

[Julian Descottes [:jdescottes]]

Isn't that Python? Aren't we correctly handling the failure in the test so that the Javascript stack gets printed to the log?

Yes this is referring to a Python Future. We are expecting a specific error in the test InvalidArgumentException, which is why those tests are expected to fail.

@pytest.mark.asyncio
@pytest.mark.parametrize("value", ["", "foo", "foo.bar"])
async def test_params_events_value_invalid_event_name(send_blocking_command, value):
    with pytest.raises(InvalidArgumentException):
        response = await send_blocking_command("session.subscribe", {"events": [value]})

Session.subscribe is currently not checking if the module or event exists, as long as the argument looks like ${moduleName}.${eventName}. We could make session.subscribe already check for this.messageHandler.checkCommand(moduleName, "_subscribeEvent"); (or try catch around the the this.messageHandler.handleCommand call?) and emit the right exception?

We would add this check in the Promise.allSettled at https://searchfox.org/mozilla-central/rev/3407e72ceb5039da514c03ae61bd279b1725c3b2/remote/webdriver-bidi/modules/root/session.jsm#59

Comment 9

[Julian Descottes [:jdescottes]]

add a POC

Comment 10

[Julian Descottes [:jdescottes]]

Attachment: Bug 1731576 - [remote] Throw InvalidArgumentException when passing events with invalid modules to session subscribe/unsubscribe

Comment 11

[Intermittent Failures Robot]

3 failures in 3319 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1
• mozilla-central: 2

Platform and build breakdown:

• linux1804-64-asan-qr: 1
  • opt: 1
• linux1804-64-ccov-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1731576&startday=2021-12-06&endday=2021-12-12&tree=all

Comment 12

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Julian. Thank you for the PoC. From my view I would be fine to get some code landed that will actually cause us to pass the tests. Even when it misses exact checks for valid event names. Do you think that you can finish this patch? Would it then prevent the log pollution?

Comment 13

[Julian Descottes [:jdescottes]]

My bad, I missed that the log pollution was actually from connect.py and not from subscribe.py.
While the patch attached here is valid, it is not enough to fix the log pollution.

connect.py looks as follows:

# test bidi_session send
# using bidi_session is the recommended way to test bidi
@pytest.mark.asyncio
async def test_bidi_session_send(bidi_session):
    await bidi_session.send_command("test.test", {})

# bidi session following a bidi session with a different capabilities
# to test session recreation
@pytest.mark.asyncio
@pytest.mark.capabilities({"acceptInsecureCerts": True})
async def test_bidi_session_with_different_capability(bidi_session):
    await bidi_session.send_command("test.test", {})

So it tries to send a command to a missing module. I'm not sure what is expected in this case?
In the webdriver spec, I can see we have the unknown command and unknown method errors https://w3c.github.io/webdriver/#dfn-unknown-command.

Or we can silence this error in https://searchfox.org/mozilla-central/source/remote/shared/webdriver/Session.jsm#223 . Either catch UnsupportedCommand errors, or pre-emptively check this.messageHandler.supportsCommand.

James: from a spec perspective, what should happen when sending such a command?

Comment 14

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Oh! I didn't even notice that it came from connect.py! Thanks for the pointer.

So AFAICS we should not send an invalid test.test command in connect.py to verify a communication via the WebSocket channel works as expected. Instead an existing command should be used. Maybe session.status, but that we don't have implemented yet and it might also go away.

Also this test is wrong because it only sends the command but doesn't wait for the response. So similar to other BiDi tests it would have to use the send_blocking_command fixture.

Then the test should no longer fail and as such the error shouldn't pollute the log. Julian, could you maybe try if that works by using the session.subscribe command here? If that's the case we should be able to quickly get this command implemented if it will stay around - which I hope for.

Comment 15

[James Graham [:jgraham]]

From a spec perspective this will respond with an unknown command error, see https://w3c.github.io/webdriver-bidi/#handle-an-incoming-message.

I think we want to be able to write tests that check that we handle unknown commands correctly without always having logspam, so it might make sense to change the way we log in this case.

Comment 16

[Julian Descottes [:jdescottes]]

Thank you both for the feedback.

From what I understand, we should switch to a valid command for the existing connect tests, but we also want to add another test which covers the unknown command scenario. As long as we expect the error in the test, I don't think it should be picked up by the parser. I can try to do both.

(but let me know if I misunderstood something)

Comment 17

[Henrik Skupin [:whimboo][⌚️UTC+2]]

I filed bug 1746216 to get the session.status command implemented. Should be trivial to do, and I would suggest that we wait with the fix here.

I wonder if we really have this log output when we expect an unknown command error.

Comment 18

[Julian Descottes [:jdescottes]]

Attachment: Bug 1731576 - [wdspec] Use session.status in connect.py

Depends on D133942

Comment 19

[Phabricator Automation]

Comment on attachment 9253922 [details]
Bug 1731576 - [remote] Throw InvalidArgumentException when passing events with invalid modules to session subscribe/unsubscribe

Revision D132972 was moved to bug 1723592. Setting attachment 9253922 [details] to obsolete.

Comment 20

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/c0adf9120b10
[wdspec] Use session.status in connect.py r=webdriver-reviewers,whimboo

Comment 21

[Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)]

Created web-platform-tests PR https://github.com/web-platform-tests/wpt/pull/32115 for changes under testing/web-platform/tests

Comment 22

[Cristian Tuns]

https://hg.mozilla.org/mozilla-central/rev/c0adf9120b10

Comment 23

[Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)]

Upstream PR merged by moz-wptsync-bot