Intermittent "session is already started" error for bluetooth tests

[jdm]

Traceback (most recent call last):
  File "/Users/servo/buildbot/slave/mac-rel-wpt4/build/tests/wpt/web-platform-tests/tools/wptrunner/wptrunner/executors/protocol.py", line 48, in setup
    self.connect()
  File "/Users/servo/buildbot/slave/mac-rel-wpt4/build/tests/wpt/web-platform-tests/tools/wptrunner/wptrunner/executors/executorservodriver.py", line 100, in connect
    self.session.start()
  File "/Users/servo/buildbot/slave/mac-rel-wpt4/build/tests/wpt/web-platform-tests/tools/webdriver/webdriver/client.py", line 421, in start
    value = self.send_command("POST", "session", body=body)
  File "/Users/servo/buildbot/slave/mac-rel-wpt4/build/tests/wpt/web-platform-tests/tools/webdriver/webdriver/client.py", line 472, in send_command
    raise err
SessionNotCreatedException: session not created (500): Session is already started


  ▶ ERROR [expected OK] /bluetooth/characteristic/getDescriptors/gen-characteristic-is-removed.https.html
  └   → ''

I recall seeing this in #21370 as well.

[aditj]

Hey @jdm I was looking at the issue, have you figured out why this is being caused? Why is a new session being created when a session already exists?
Is this because this check is not working ? or some other issue perhaps?
Also is the webdriver ready for multiple sessions?

[jdm]

I have not figured out why yet. I believe it should be possible to add support for multiple sessions to the server, though.

[georgeroman]

I tried to replicate this error locally but instead of the SessionNotCreatedException here is what I've got:

[ERROR script::dom::bindings::error] Error at https://web-platform.test:8443/bluetooth/resources/bluetooth-helpers.js:177:10 Illegal constructor.
[ERROR script::dom::bindings::error] Error at https://web-platform.test:8443/bluetooth/characteristic/getDescriptors/gen-characteristic-is-removed.https.html:11:18 Illegal constructor.

[jdm]

It should be possible to reproduce by running ./mach test-wpt --processes 8 --headless --product=servodriver bluetooth. We should file a separate issue for the Illegal constructor exceptions triggered by https://github.com/web-platform-tests/wpt/blob/e45bda7edddd2cffb4169efe2f61812537b09abd/bluetooth/resources/bluetooth-helpers.js#L177.

[aditj]

@jdm , i couldnt reproduce this error all my tests ran as expected , can this error be system specific?

[georgeroman]

@aditj Try modifying the test's expectation to PASS in https://github.com/servo/servo/blob/master/tests/wpt/metadata/bluetooth/characteristic/getDescriptors/gen-characteristic-is-removed.https.html.ini.

[aditj]

@aditj Try modifying the test's expectation to PASS in https://github.com/servo/servo/blob/master/tests/wpt/metadata/bluetooth/characteristic/getDescriptors/gen-characteristic-is-removed.https.html.ini.

Oh !I am now getting the Illegal constructor error but not the SessionNotCreatedException

[jgraham]

I have not figured out why yet. I believe it should be possible to add support for multiple sessions to the server, though.

Adding multiple sessions to the server probably isn't that easy in the sense that the webdriver crate isn't designed to have multiple clients at a time, and ensuring the sessions are isolated on the servo side seems like it would be a lot of work since you need to maintain a map between session id and all the resources associated with that session.

Possibly this just means "shutting down a session and starting a new one without quitting servo", which I think is much more reasonable. However in this case I guess there's some race condition in shutting down the session which allows us to try to start a new one before the previous one is finished.

[hundredeir]

As I can see whenever any test function runs it calls a fixture which tries to create a new session and if gets SessionNotCreated error then it raises the exception. And between two test functions there isn't any cleanup/teardown happening.
So, when the next function is called the webdriver doesn't even let the message reach servo and itself returns an error.

[georgeroman]

I managed to reproduce the error locally and I noticed that two different processes attempted to start WebDriver on the same port:

A few lines down in the log there are two attempts to starting a WebDriver session on the same port:

Next, the error was raised. From what I investigated, the ports are chosen here and that code is vulnerable to race conditions.

[jdm]

That looks extremely suspicious!

[atouchet]

Is this issue fixed now?

[georgeroman]

The issue is fixed for the bluetooth tests, but it's still there in the new_session wdspec tests.

[georgeroman]

So, I further investigated what causes the Session is already started error in the new_session wdspec tests and I found out that the WebDriver instances that get assigned to each process each have a port of 4444. Here are some debug prints illustrating this:

Although the port retrieval in _find_next_free_port is protected with a lock, it must be the case that each process has a different copy of the WebDriverServer class and in this case the lock is irrelevant.

[georgeroman]

So, after lots of debugging, I finally managed to understand the real cause of the error in the wdspec new_session tests.

When running the wdspec tests in parallel, wpt starts new processes having as target the start_runner function. Here, the executor is ServoWdspecExecutor, which has an associated ServoDriverServer. So, the port initialization occurs for each instance of ServoDriverServer in a different process. Although _used_ports is a class variable and is protected by a lock from concurrent access, since we are in different processes, each process will have a different copy of it. In other words, _used_ports is not shared between the processes (the changes made by one process to it are not visible by the other processes) and the lock that protects it is useless since there is only one process that modifies a particular copy of _used_ports. Because the port initialization is not synchronized we have multiple processes trying to create new sessions on the same WebDriver port and so we get those Session is already started errors.

Why didn't this also happen in the other occurrences of get_free_port (here for example)? Because there the initialization occurs in threads, not processes, and each thread shares the same used_ports variable. (I've used multiprocessing.Lock for protecting used_ports, but threading.Lock would have also been good enough in this case).

I thought about several possible solutions:

• run the new_session tests in a single process
• find a way to share _used_ports between processes
• modify wptrunner to do the port initialization in threads instead of processes
• support multiple sessions in WebDriver

[georgeroman]

Good news! Once we update web-platform-tests to include this commit, this issue will be fixed! (As noted here there is still a small chance of getting this error, but the probability of it happening is quite low)

[georgeroman]

This can be closed now!