Capybara::Webkit::Browser.command becomes out of sync reading @connection responses, causing JSON::ParserError

[markwpiper]

The Capybara::Webkit::Browser command method used to send commands and read responses over the socket to the Webkit process can become out-of-sync. When this happens, read_response returns a prior response, which does not match up to the most recent command.

This often manifests to the user as errors such as JSON::ParserError: 757: unexpected token at 'true' or JSON::ParserError: A JSON text must at least contain two octets! or possibly issues such as #957. There may be other errors possible since it depends on what the code does with response message.

I'm not sure what conditions this occurs under, but can almost 100% reliably reproduce it locally by calling page.evaluate_script followed by a call to page.driver.console_messages, on a page that is performing AJAX requests. The response for the first Evaluate command is accidentally read by the subsequent ConsoleMessages command, which attempts to parse the evaluate response as JSON.

Here is an example with logging I added. Note how the 'CHECK COMMAND Evaluate' never finishes reading a response and READ COMMAND ConsoleMessages reads the evaluate response string '1':

STARTING COMMAND Evaluate@1541370685
CHECK COMMAND Evaluate@1541370685
12:54:09.300 Received 200 from "http://127.0.0.1:56578/catering/menu_packages?max_budget=10002&menu_date=2018-11-07&min_budget=0&page=6"
12:54:09.302 Started request to "http://127.0.0.1:56578/catering/menu_packages?max_budget=10002&menu_date=2018-11-07&min_budget=0&page=7"
12:54:09.432 Received 200 from "http://127.0.0.1:56578/catering/menu_packages?max_budget=10002&menu_date=2018-11-07&min_budget=0&page=7"
12:54:09.433 Started request to "http://127.0.0.1:56578/catering/menu_packages?max_budget=10002&menu_date=2018-11-07&min_budget=0&page=8"
Page is Capybara::Session
Page driver is Capybara::Webkit::Driver
[DEPRECATION] Capybara::Webkit::Driver#browser is deprecated.
STARTING COMMAND ConsoleMessages@1541370685
CHECK COMMAND ConsoleMessages@1541370685
12:54:09.666 Received 200 from "http://127.0.0.1:56578/catering/menu_packages?max_budget=10002&menu_date=2018-11-07&min_budget=0&page=8"
12:54:09.669 Started request to "http://127.0.0.1:56578/catering/menu_packages?max_budget=10002&menu_date=2018-11-07&min_budget=0&page=9"
12:54:09.787 Received "Evaluate(angular.element(document.querySelector('[ng-app]')).injector().get('$http').pendingRequests.length, [])"
12:54:09.838 Started "Evaluate(angular.element(document.querySelector('[ng-app]')).injector().get('$http').pendingRequests.length, [])"
12:54:09.838 Finished "Evaluate(angular.element(document.querySelector('[ng-app]')).injector().get('$http').pendingRequests.length, [])" with response "Success(1)"
12:54:09.838 Wrote response true "1"
12:54:09.838 Received "ConsoleMessages()"
12:54:09.839 Received 200 from "http://127.0.0.1:56578/catering/menu_packages?max_budget=10002&menu_date=2018-11-07&min_budget=0&page=9"
12:54:09.840 Started request to "http://127.0.0.1:56578/catering/menu_packages?max_budget=10002&menu_date=2018-11-07&min_budget=0&page=10"
12:54:10.006 Started "ConsoleMessages()"
12:54:10.006 Finished "ConsoleMessages()" with response "Success([{\"line_number\":34,\"message\":\"This page does not have a Lish metrics_page_name or page_identity_js set and will not be enabled for UTM attribution tracking.\",\"source\":\"http://127.0.0.1:56578/catering/orders/C517346447/checkout\"}])"
12:54:10.007 Wrote response true "[{\"line_number\":34,\"message\":\"This page does not have a Lish metrics_page_name or page_identity_js set and will not be enabled for UTM attribution tracking.\",\"source\":\"http://127.0.0.1:56578/catering/orders/C517346447/checkout\"}]"
12:54:10.008 Received 200 from "http://127.0.0.1:56578/catering/menu_packages?max_budget=10002&menu_date=2018-11-07&min_budget=0&page=10"
12:54:10.010 Started request to "http://127.0.0.1:56578/catering/menu_packages?max_budget=10002&menu_date=2018-11-07&min_budget=0&page=11"
check=<ok>
READ COMMAND ConsoleMessages@1541370685
response_length=<1>
response=<1>
FINISHED COMMAND ConsoleMessages@1541370685 with response <1>

This appears to happen because the rescue IO::WaitReadable in connection.read never triggers for the Evaluate command.

When I remove the evaluate_script call everything works as expected.

I'm using ruby 2.2.4p230 (2015-12-16 revision 53155) [x86_64-darwin15] with page.driver.version

Capybara: 2.13.0
capybara-webkit: 1.15.0
Qt: 5.5.1
WebKit: 538.1
QtWebKit: 5.5.1

[twalpole]

What does the evaluate_script call return?