Skip to content
This repository has been archived by the owner on Nov 23, 2023. It is now read-only.

Add pending logging #5

Open
wants to merge 2 commits into
base: freeagent-logging-branch
Choose a base branch
from

Conversation

dmorgan-fa
Copy link

What

After reverting this fork back to the upstream 0.13.0 tag, we want to explicitly emit pending connections when we raise a TimeoutError from wait_for_idle.
There are three places that TimeoutError gets raised, each has it's own context, and so will need custom error handling if we want to get specific useful information out:

./lib/ferrum/page.rb
285:          raise TimeoutError.new() unless set

./lib/ferrum/browser/client.rb
46:        raise TimeoutError.new() unless data

./lib/ferrum/network.rb
71:          raise TimeoutError.new(pending_urls = pending_urls)

How

Deliberately triggering a failure in a spec:

wait_for_network_idle(connections:-1, timeout: 0)

Example output:

Failures:

  1) Bills UK Limited Company allows the user to create a new foreign currency bill
     Failure/Error: page.driver.wait_for_network_idle(**options)
     
     Ferrum::TimeoutError:
       Timed out waiting for response. It's possible that this happened because something took a very long time (for example a page load was slow). If so, setting the :timeout option to a higher value might help.
        Connections still pending:
        http://subdomain000001.lvh.me:9887/bills/inline_bill_item
     # /Users/dalemorgan/dev/ferrum/lib/ferrum/network.rb:71:in `wait_for_idle'
     # /Users/dalemorgan/.gem/ruby/3.1.3/bundler/gems/cuprite-2fe6236fe66e/lib/capybara/cuprite/driver.rb:262:in `wait_for_network_idle'
     # ./spec/support/helpers/feature_spec_helper.rb:212:in `wait_for_network_idle'
     # ./spec/features/bills/create_spec.rb:125:in `block (3 levels) in <top (required)>'
     # ./spec/support/capybara.rb:59:in `block (2 levels) in <main>'
     # ./spec/support/example_index.rb:22:in `block (2 levels) in <main>'
     # ./engines/radar_todos/spec/support/helper.rb:28:in `block (2 levels) in <main>'

Finished in 8.59 seconds (files took 11.77 seconds to load)
1 example, 1 failure
We're also dumping as much of the pending context as possible:
rsp spec/features/bills/create_spec.rb:122
WARNING: `sqreen` gem not installed, using a class stub instead.
Run options:
  include {:locations=>{"./spec/features/bills/create_spec.rb"=>[122]}}
  exclude {:"known-failure"=>true, :factorybot_lint=>true, :visual_regression=>true}

Bills
  UK Limited Company
Capybara starting Puma...
* Version 6.0.0 , codename: Sunflower
* Min threads: 0, max threads: 4
* Listening on http://0.0.0.0:9887
[DEBUG] 'wait_for_idle' pending connections:
["#<Ferrum::Network::Exchange @id=\"59581.66\" @intercepted_request=#<Ferrum::Network::InterceptedRequest @request_id=\"interception-job-34.0\" @frame_id=\"64B7201DA2424E9FD64676000455BE78\" @resource_type=\"XHR\" @request={\"url\"=>\"http://subdomain000001.lvh.me:9887/bills/inline_bill_item\", \"method\"=>\"POST\", \"headers\"=>{\"Accept\"=>\"text/vnd.turbo-stream.html, text/html\", \"Content-Type\"=>\"multipart/form-data; boundary=----WebKitFormBoundary2bjByxPLNhwS1B29\", \"Cookie\"=>\"fa_user_session_key=eyJfcmFpbHMiOnsibWVzc2FnZSI6IklrOXJWVUZLWldVMlRXZGtlVEJYV0hRMWJscEVhVTEwU3pocGVtMXBTbGd5YzJkM1pVRmZlVk5tZEZFaSIsImV4cCI6bnVsbCwicHVyIjoiY29va2llLmZhX3VzZXJfc2Vzc2lvbl9rZXkifX0%3D--b3f76b2b656f73c1fb0da60566eaaffaba35f4b0; _fa_session_2=%2BQ9Gwe1bVWqEdl6rOxXAmDABr7rW%2FUU1LT%2FVEYF3s9oE%2B%2FAzCXGhjzZY7oG1SNUzAJc3xLJ4My4sDsjG9TCYlgURjxlFGYilvecpQgYrmxUgcpFYNC7S5dyO1W3fkLYEwh8MXF7HvlX%2F8ZfLJ5VeIRmGfgOaFht6i6rwFvtRB6fti7EItz3AK9ghwiKtsI0uohdWlNjYDVap9oKNV5QhTqKa%2FPq0L9%2Fyzj71eRoaDXq51nMWe%2Fqx%2FfBu8%2FhLCkvcjDZMpovs%2BnkjbK3YeOrh%2F5ddBoSy2FBh53kMZ2E41gV5zpWUUR2vrnVCo%2BbnLHhmMpKOd1oqtpP27y02JyHwzoyip%2FtaTYzD0pNJ8qLF%2BLTV68aoFy19mxrr%2B5dyPbdeVxRbEETkRf%2BhxkDmVV0nbR9jVXsQupumol9Q3iN7sQcos%2Btk%2F4FPc49tzUJyTO1BraX7%2ByQ%3D--ys2LouRQBzpTmfrG--%2By6LhuqzMHYHvHYDVMNRUQ%3D%3D\ 
[...]
This is to try and make sense of what's happening with these pending connections. It's ugly and difficult to read, but the longer we take to output this, the longer the connections have to resolve and mask the issue (i.e. end up reporting that they have resolved).

@dmorgan-fa dmorgan-fa marked this pull request as ready for review December 19, 2022 14:43
"because something took a very long time (for example a page load " \
"was slow). If so, setting the :timeout option to a higher value might " \
"help."
message = "#{message}\n Connections still pending:\n #{pending_urls.join(', ')}" unless pending_urls.empty?

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This isn't a critique of your code here (because I use unless a lot) - but I read this the other day:
Read This Post 'Unless' You're Not A Ruby Developer

https://news.ycombinator.com/item?id=33965933

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do you want to override the whole message string, or just append to it if there are pending urls? (it's replacing it atm)

Copy link

@singhprd singhprd Dec 19, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Maybe something like: (I think that's how you add to a string.. )

Suggested change
message = "#{message}\n Connections still pending:\n #{pending_urls.join(', ')}" unless pending_urls.empty?
if !pending_urls.empty?
message =+ "#{message}\n Connections still pending:\n #{pending_urls.join(', ')}" unless pending_urls.empty?
end

if Utils::ElapsedTime.timeout?(start, timeout)
if @page.browser.options.pending_connection_errors
pendings = traffic.select(&:pending?)
pending_urls = pendings.map(&:url).compact

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Does the pending connection always have a url here? I thought we saw that sometimes it was empty, because the pendings are a collection of Network Exchange objects, from which the url method is request&.url. I could be wrong here - and it could also be that when we tested last time the exchange didn't have a request (and therefore no url) but when it's run normally they do.

if @page.browser.options.pending_connection_errors
pendings = traffic.select(&:pending?)
pending_urls = pendings.map(&:url).compact
puts("[DEBUG] 'wait_for_idle' pending connections:\n#{pendings.map(&:inspect)}")

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice idea 👌

Copy link

@singhprd singhprd left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

A few nitpicky comments and things to chat about, but I'm also very happy to ship this and iterate if there are future improvements to be made ?

@singhprd
Copy link

In terms of shipping this PR though - would recommend just keeping it on a branch, then referencing that branch in freeagent, keeping the main/master branch the same as upstream 👍

@dmorgan-fa dmorgan-fa changed the base branch from main to freeagent-logging-branch December 19, 2022 17:10
@dmorgan-fa
Copy link
Author

Pointing this to freeagent-logging-branch instead. We can merge subsequent changes there as we need.

@dmorgan-fa
Copy link
Author

dmorgan-fa commented Dec 20, 2022

Example of this being triggered (stress test run):
Debug log dumping all the info we have about the pending connection:

Switch to a client company
[DEBUG] 'wait_for_idle' pending connections:
["#<Ferrum::Network::Exchange @id=\"1997.163\" @intercepted_request=#<Ferrum::Network::InterceptedRequest @request_id=\"interception-job-59.0\" @frame_id=\"2555154DD8323609A4E0068CF38FC391\" @resource_type=\"XHR\" @request={\"url\"=>\"http://subdomain000001.lvh.me:9907/assets/application/setup-illustrations-1-ffa28978d62225e2e17eb6656e54ec46ab48fad94c95a8b6c86e84bdaa53d5c7.png?_=1671472022216\", \"method\"=>\"GET\", \"headers\"=>{\"Accept\"=>\"*/*\", \"Cookie\"=>\"_fa_dev_id=PcLpCpsCMtDIPMU9pMY50zb1qpobJSeKVlR3AyKC4UA%3D; fa_user_session_key=eyJfcmFpbHMiOnsibWVzc2FnZSI6IklucEhaRlZuUVc1ek9FaG1TWGw1U2xWNFJIQnNhRWwwWmpkUmIwaHhiM0E1ZFhkNldWaEdTRkJqU1UwaSIsImV4cCI6bnVsbCwicHVyIjoiY29va2llLmZhX3VzZXJfc2Vzc2lvbl9rZXkifX0%3D--8a9b272b14c56244a0078513c609a94ce74d1a19; setup_started=2022-12-19T17%3A47%3A01%2B00%3A00; _fa_session_2=tNvp4pvvyiIN2t5Tk%2B8s%2Bogfku5kM6SAksgay8uCMGwJrs%2FYUyyixBp0glV%2FbP1Llw3P%2BjomTQISHP3Qii8zBU6jdYsoIcnpIs2yMQm4MnlMlWTGDRjS%2BU7YenOzdZ%2BOo7ZurjPvLxPYaH0vu1jlM2OPHK51hY7PiPS6DnGW%2FJRK71HpUNacovxbG8Lz5ApoNRz5sdfiuTgZCDUVhvhjwA6cgyTc9zTqtPvvYto2kQ3n9iEyT3eWNbTdtWJHfB%2BxeApxoRGyqifSWrrri0HRg261lxkeNFQ8sDbuFtc%3D--GKmHS0Fc39j7nbyi--seEBLuvFl%2BOeblP6mRtEug%3D%3D\", \"Referer\"=>\"[http://subdomain000001.lvh.me:9907/setup\](http://subdomain000001.lvh.me:9907/setup/)", \"User-Agent\"=>\"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/108.0.5359.124 Safari/537.36\", \"X-Requested-With\"=>\"XMLHttpRequest\"}, \"initialPriority\"=>\"High\", \"referrerPolicy\"=>\"strict-origin-when-cross-origin\"}> @request=nil @response=nil @error=nil>"]

Backtrace doesn't show the Connections still pending: list though:

Ferrum::TimeoutError:
         Timed out waiting for response. It's possible that this happened because something took a very long time (for example a page load was slow). If so, setting the :timeout option to a higher value might help.
       Shared Example Group: "can complete setup" called from ./spec/features/getting_started_spec.rb:380
       # /usr/local/bundle/bundler/gems/ferrum-212d5eaecd97/lib/ferrum/network.rb:71:in `wait_for_idle'
       # /usr/local/bundle/bundler/gems/cuprite-2fe6236fe66e/lib/capybara/cuprite/driver.rb:262:in `wait_for_network_idle'
       # ./spec/support/helpers/feature_spec_helper.rb:212:in `wait_for_network_idle'
       # ./spec/features/getting_started_spec.rb:[81](https://github.com/fac/freeagent/actions/runs/3733825019/jobs/6335214748#step:8:84)6:in `fill_in_vat_details'
       # ./spec/features/getting_started_spec.rb:358:in `block (5 levels) in <main>'

In this example the failure comes down to http://subdomain000001.lvh.me:9907/assets/application/setup-illustrations-1-ffa28978d62225e2e17eb6656e54ec46ab48fad94c95a8b6c86e84bdaa53d5c7.png taking too long to load (and can be confirmed with the failure screenshot). Likely resource starvation, causing the fetch to take too long.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants