Multiple exchanges are created for the same request when network intercept is enabled

[rzane]

Describe the bug

Normally, build_exchange is called upon Network.requestWillBeSent:

ferrum/lib/ferrum/network.rb

Lines 387 to 388 in 5ca5e9e

	exchange = select(request.id).last
	exchange = build_exchange(request.id) unless exchange&.blank?

When a whitelist is registered, a Fetch.requestPaused event is also registered and causes build_exchange to be called again for the same request:

ferrum/lib/ferrum/page.rb

Lines 367 to 368 in ac52ce9

	exchange = network.select(request.network_id).last
	exchange ||= network.build_exchange(request.network_id)

As a result, Network#traffic will have two exchanges referencing the same request. One of these exchanges will not be #finished?. As a result, calling wait_for_idle will raise Ferrum::TimeoutError.

To Reproduce
I'm not sure if I'll be able to produce a minimal reproduction. This happens pretty infrequently.

I added some logging to network.rb and here's what I found in my application:

D, [2020-08-11T00:00:10.967036 #93432] DEBUG -- : Network.requestWillBeSent: GET http://127.0.0.1:52464/redacted (94044.261)
D, [2020-08-11T00:00:10.967094 #93432] DEBUG -- : Fetch.requestPaused: GET http://127.0.0.1:52464/redacted (94044.261)
D, [2020-08-11T00:00:10.967123 #93432] DEBUG -- : build_exchange: exchange 19883500 (94044.261)
D, [2020-08-11T00:00:10.967165 #93432] DEBUG -- : build_exchange: exchange 19883520 (94044.261)
D, [2020-08-11T00:00:10.967144 #93432] DEBUG -- : Fetch.requestPaused: exchange 19883500 (94044.261)
D, [2020-08-11T00:00:10.967187 #93432] DEBUG -- : Network.requestWillBeSent: exchange 19883520 (94044.261)

In the logs above, 94044.261 is the request ID. 19883500 and 19883520 are Exchange#object_id. As you can see, two exchanges were created for this request.

Expected behavior

Changing this line appears to fix the issue:

-exchange = build_exchange(request.id) unless exchange&.blank?
+exchange ||= build_exchange(request.id)

That being said, I'm sure there's a good reason why this .blank? check exists.

Screenshots
None

Desktop (please complete the following information):

• OS: macOS
• Browser: Chrome 127.0.6533.74 (Official Build) (arm64)
• Version: v0.15

Additional context
None.

[rzane]

I managed to make a script that occasionally reproduces the issue.

https://gist.github.com/rzane/a4efe24db7ce44491f0ec6056ac16401

[rzane]

Note: The reason these pending requests aren't marked as #finished? is because the subscriptions that handle responses only assign properties to select(request_id).last

ferrum/lib/ferrum/network.rb

Lines 395 to 445 in 5ca5e9e

	def subscribe_response_received
	@page.on("Network.responseReceived") do |params|
	exchange = select(params["requestId"]).last
	next unless exchange
	response = Network::Response.new(@page, params)
	exchange.response = response
	end
	end
	def subscribe_loading_finished
	@page.on("Network.loadingFinished") do |params|
	exchange = select(params["requestId"]).last
	next unless exchange
	if (response = exchange.response)
	response.loaded = true
	response.body_size = params["encodedDataLength"]
	end
	end
	end
	def subscribe_loading_failed
	@page.on("Network.loadingFailed") do |params|
	exchange = select(params["requestId"]).last
	next unless exchange
	exchange.error ||= Network::Error.new
	exchange.error.id = params["requestId"]
	exchange.error.type = params["type"]
	exchange.error.error_text = params["errorText"]
	exchange.error.monotonic_time = params["timestamp"]
	exchange.error.canceled = params["canceled"]
	end
	end
	def subscribe_log_entry_added
	@page.on("Log.entryAdded") do |params|
	entry = params["entry"] || {}
	if entry["source"] == "network" && entry["level"] == "error"
	exchange = select(entry["networkRequestId"]).last
	next unless exchange
	exchange.error ||= Network::Error.new
	exchange.error.id = entry["networkRequestId"]
	exchange.error.url = entry["url"]
	exchange.error.description = entry["text"]
	exchange.error.timestamp = entry["timestamp"]
	end
	end
	end