Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Ferrum::Network::Response#loaded? fails on 302 redirects after #309 #321

Closed
dmorgan-fa opened this issue Dec 22, 2022 · 4 comments · Fixed by #338
Closed

Ferrum::Network::Response#loaded? fails on 302 redirects after #309 #321

dmorgan-fa opened this issue Dec 22, 2022 · 4 comments · Fixed by #338

Comments

@dmorgan-fa
Copy link

Hi,
Firstly, thanks for the excellent work on this gem and Cuprite!

We've been looking into some reliability issues lately and trying different things. One thing that I've noticed, is a recent change:

now causes redirect requests to be considered still pending even though they've completed:

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:
          {:status=>302, :status_text=>"Found", :url=>"http://practice1.lvh.me:9888/practice_dashboard/companies/895397944/notes/1"}
Full Ferrum::Network::Exchange object here
#<Ferrum::Network::Exchange
  @id="E711BF6D793E1D3EC660F87242702CEF"
  @intercepted_request=#<Ferrum::Network::InterceptedRequest
    @request_id="interception-job-32.1"
    @frame_id="E80A9391E528438362D111598AAB1C2B"
    @resource_type="Document"
    @request={
      "url"=>"http://subdomain000001.lvh.me:9887/overview",
      "method"=>"GET",
      "headers"=>{
        "Accept"=>"text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9",
        "Cookie"=>"[REDACTED]",
        "Referer"=>"http://subdomain000001.lvh.me:9887/",
        "Upgrade-Insecure-Requests"=>"1",
        "User-Agent"=>"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/108.0.5359.124 Safari/537.36"
      },
      "initialPriority"=>"VeryHigh",
      "referrerPolicy"=>"origin"
    }
  >
  @request= #<Ferrum::Network::Request:0x000000011c7e0b90
    @params={
      "requestId"=>"E711BF6D793E1D3EC660F87242702CEF",
      "loaderId"=>"E711BF6D793E1D3EC660F87242702CEF",
      "documentURL"=>"http://subdomain000001.lvh.me:9887/overview",
      "request"=>{
        "url"=>"http://subdomain000001.lvh.me:9887/overview",
        "method"=>"GET",
        "headers"=>{
          "Content-Type"=>"application/x-www-form-urlencoded",
          "Origin"=>"http://subdomain000001.lvh.me:9887",
          "Referer"=>"http://subdomain000001.lvh.me:9887/",
          "Upgrade-Insecure-Requests"=>"1",
          "User-Agent"=>"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/108.0.5359.124 Safari/537.36"
        },
        "mixedContentType"=>"none",
        "initialPriority"=>"VeryHigh",
        "referrerPolicy"=>"origin",
        "isSameSite"=>true
      },
      "timestamp"=>122384.896241,
      "wallTime"=>1671721817.864675,
      "initiator"=>{
        "type"=>"other"
      },
      "redirectHasExtraInfo"=>true,
      "redirectResponse"=>{
        "url"=>"http://subdomain000001.lvh.me:9887/sessions",
        "status"=>302,
        "statusText"=>"Found",
        "headers"=>{
          "Cache-Control"=>"no-store",
          "Content-Length"=>"206",
          "Content-Type"=>"text/html; charset=utf-8",
          "Feature-Policy"=>"accelerometer 'none'; autoplay 'none'; ambient-light-sensor 'none'; camera 'none'; encrypted-media 'none'; fullscreen 'self'; geolocation 'none'; gyroscope 'none'; magnetometer 'none'; microphone 'none'; midi 'none'; payment 'none'; picture-in-picture 'none'; speaker 'none'; usb 'none'; vibrate 'none'; vr 'none'",
          "Location"=>"http://subdomain000001.lvh.me:9887/overview",
          "Pragma"=>"no-cache",
          "X-Frame-Options"=>"SAMEORIGIN",
          "X-Host"=>"mac",
          "X-Request-Id"=>"7fe4438c-e2da-4846-b9e1-57bbfa40344d",
          "X-Rev"=>"2aad5e7960c77fe0e405880b0974b0cda2c3a57c",
          "X-Runtime"=>"0.373335",
          "X-XSS-Protection"=>"1; mode=block"
        },
        "mimeType"=>"text/html",
        "connectionReused"=>true,
        "connectionId"=>36,
        "remoteIPAddress"=>"127.0.0.1",
        "remotePort"=>9887,
        "fromDiskCache"=>false,
        "fromServiceWorker"=>false,
        "fromPrefetchCache"=>false,
        "encodedDataLength"=>1630,
        "timing"=>{
          "requestTime"=>122384.433822,
          "proxyStart"=>-1,
          "proxyEnd"=>-1,
          "dnsStart"=>-1,
          "dnsEnd"=>-1,
          "connectStart"=>-1,
          "connectEnd"=>-1,
          "sslStart"=>-1,
          "sslEnd"=>-1,
          "workerStart"=>-1,
          "workerReady"=>-1,
          "workerFetchStart"=>-1,
          "workerRespondWithSettled"=>-1,
          "sendStart"=>0.197,
          "sendEnd"=>0.256,
          "pushStart"=>0,
          "pushEnd"=>0,
          "receiveHeadersEnd"=>461.364
        },
        "responseTime"=>1671721817863.499,
        "protocol"=>"http/1.1",
        "alternateProtocolUsage"=>"unspecifiedReason",
        "securityState"=>"insecure"
      },
      "type"=>"Document",
      "frameId"=>"E80A9391E528438362D111598AAB1C2B",
      "hasUserGesture"=>true
    },
    @request={
      "url"=>"http://subdomain000001.lvh.me:9887/overview",
      "method"=>"GET",
      "headers"=>{
        "Content-Type"=>"application/x-www-form-urlencoded",
        "Origin"=>"http://subdomain000001.lvh.me:9887",
        "Referer"=>"http://subdomain000001.lvh.me:9887/",
        "Upgrade-Insecure-Requests"=>"1",
        "User-Agent"=>"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/108.0.5359.124 Safari/537.36"
      },
      "mixedContentType"=>"none",
      "initialPriority"=>"VeryHigh",
      "referrerPolicy"=>"origin",
      "isSameSite"=>true
    }
  >
  @response= #<Ferrum::Network::Response
    @params={
      "requestId"=>"E711BF6D793E1D3EC660F87242702CEF",
      "loaderId"=>"E711BF6D793E1D3EC660F87242702CEF",
      "documentURL"=>"http://subdomain000001.lvh.me:9887/setup",
      "request"=>{
        "url"=>"http://subdomain000001.lvh.me:9887/setup",
        "method"=>"GET",
        "headers"=>{"Content-Type"=>"application/x-www-form-urlencoded",
        "Origin"=>"http://subdomain000001.lvh.me:9887",
        "Referer"=>"http://subdomain000001.lvh.me:9887/",
        "Upgrade-Insecure-Requests"=>"1",
        "User-Agent"=>"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML,like Gecko) HeadlessChrome/108.0.5359.124 Safari/537.36"},
        "mixedContentType"=>"none",
        "initialPriority"=>"VeryHigh",
        "referrerPolicy"=>"origin",
        "isSameSite"=>true
      },
      "timestamp"=>122385.173023,
      "wallTime"=>1671721818.141461,
      "initiator"=>{
        "type"=>"other"
      },
      "redirectHasExtraInfo"=>true,
      "redirectResponse"=>{
        "url"=>"http://subdomain000001.lvh.me:9887/overview",
        "status"=>302,
        "statusText"=>"Found",
        "headers"=>{
          "Cache-Control"=>"no-store",
          "Content-Length"=>"203",
          "Content-Type"=>"text/html; charset=utf-8",
          "Feature-Policy"=>"accelerometer 'none'; autoplay 'none'; ambient-light-sensor 'none'; camera 'none'; encrypted-media 'none'; fullscreen 'self'; geolocation 'none'; gyroscope 'none'; magnetometer 'none'; microphone 'none'; midi 'none'; payment 'none'; picture-in-picture 'none'; speaker 'none'; usb 'none'; vibrate 'none'; vr 'none'",
          "Location"=>"http://subdomain000001.lvh.me:9887/setup",
          "Pragma"=>"no-cache",
          "X-Frame-Options"=>"SAMEORIGIN",
          "X-Host"=>"mac",
          "X-Request-Id"=>"fc59edb4-4158-48bc-b64e-761dc432ef25",
          "X-Rev"=>"2aad5e7960c77fe0e405880b0974b0cda2c3a57c",
          "X-Runtime"=>"0.189034",
          "X-XSS-Protection"=>"1; mode=block"
        },
        "mimeType"=>"text/html",
        "connectionReused"=>true,
        "connectionId"=>36,
        "remoteIPAddress"=>"127.0.0.1",
        "remotePort"=>9887,
        "fromDiskCache"=>false,
        "fromServiceWorker"=>false,
        "fromPrefetchCache"=>false,
        "encodedDataLength"=>1761,
        "timing"=>{
          "requestTime"=>122384.896961,
          "proxyStart"=>-1,
          "proxyEnd"=>-1,
          "dnsStart"=>-1,
          "dnsEnd"=>-1,
          "connectStart"=>-1,
          "connectEnd"=>-1,
          "sslStart"=>-1,
          "sslEnd"=>-1,
          "workerStart"=>-1,
          "workerReady"=>-1,
          "workerFetchStart"=>-1,
          "workerRespondWithSettled"=>-1,
          "sendStart"=>0.146,
          "sendEnd"=>0.185,
          "pushStart"=>0,
          "pushEnd"=>0,
          "receiveHeadersEnd"=>275.388
        },
        "responseTime"=>1671721818140.693,
        "protocol"=>"http/1.1",
        "alternateProtocolUsage"=>"unspecifiedReason",
        "securityState"=>"insecure"
      },
      "type"=>"Document",
      "frameId"=>"E80A9391E528438362D111598AAB1C2B",
      "hasUserGesture"=>true
    }
    @response={
      "url"=>"http://subdomain000001.lvh.me:9887/overview",
      "status"=>302,
      "statusText"=>"Found",
      "headers"=>{
        "Cache-Control"=>"no-store",
        "Content-Length"=>"203",
        "Content-Type"=>"text/html; charset=utf-8",
        "Feature-Policy"=>"accelerometer 'none'; autoplay 'none'; ambient-light-sensor 'none'; camera 'none'; encrypted-media 'none'; fullscreen 'self'; geolocation 'none'; gyroscope 'none'; magnetometer 'none'; microphone 'none'; midi 'none'; payment 'none'; picture-in-picture 'none'; speaker 'none'; usb 'none'; vibrate 'none'; vr 'none'",
        "Location"=>"http://subdomain000001.lvh.me:9887/setup",
        "Pragma"=>"no-cache",
        "X-Frame-Options"=>"SAMEORIGIN",
        "X-Host"=>"mac",
        "X-Request-Id"=>"fc59edb4-4158-48bc-b64e-761dc432ef25",
        "X-Rev"=>"2aad5e7960c77fe0e405880b0974b0cda2c3a57c",
        "X-Runtime"=>"0.189034",
        "X-XSS-Protection"=>"1; mode=block"
      },
      "mimeType"=>"text/html",
      "connectionReused"=>true,
      "connectionId"=>36,
      "remoteIPAddress"=>"127.0.0.1",
      "remotePort"=>9887,
      "fromDiskCache"=>false,
      "fromServiceWorker"=>false,
      "fromPrefetchCache"=>false,
      "encodedDataLength"=>1761,
      "timing"=>{
        "requestTime"=>122384.896961,
        "proxyStart"=>-1,
        "proxyEnd"=>-1,
        "dnsStart"=>-1,
        "dnsEnd"=>-1,
        "connectStart"=>-1,
        "connectEnd"=>-1,
        "sslStart"=>-1,
        "sslEnd"=>-1,
        "workerStart"=>-1,
        "workerReady"=>-1,
        "workerFetchStart"=>-1,
        "workerRespondWithSettled"=>-1,
        "sendStart"=>0.146,
        "sendEnd"=>0.185,
        "pushStart"=>0,
        "pushEnd"=>0,
        "receiveHeadersEnd"=>275.388
      },
      "responseTime"=>1671721818140.693,
      "protocol"=>"http/1.1",
      "alternateProtocolUsage"=>"unspecifiedReason",
      "securityState"=>"insecure"
    }
  >
  @error=nil
>

This output was from a forked branch with some extra logging:

Admittedly this is only seen when we're calling Cuprite's wait_for_network_idle directly within a spec (something we're looking to remove), but it looks like something that will trip Ferrum up if wait_for_idle gets called and there's been a redirect.

@route
Copy link
Member

route commented Dec 22, 2022

Oh I see, could you please try to add check for a redirect status here, something like:

    def subscribe_response_received
      @page.on("Network.responseReceived") do |params|
        exchange = select(params["requestId"]).last

        if exchange
          response = Network::Response.new(@page, params)
          exchange.response = response
          response.loaded = true if response.status is redirect # <<< HERE
        end
      end
    end

and tell me if it works?

@dmorgan-fa
Copy link
Author

Thanks for the quick reply!
Unfortunately that doesn't seem to resolve it. Looks like we're stuck checking loaded?:

def loaded?
  if @loaded.nil?
    puts params['request']['url'] if params['request']
    puts params['redirectResponse']['status'] if params['redirectResponse']
  end
  @loaded
end
Output
Capybara starting Puma...
* Version 6.0.0 , codename: Sunflower
* Min threads: 0, max threads: 4
* Listening on http://0.0.0.0:9887
http://subdomain000001.lvh.me:9887/overview
302
http://subdomain000001.lvh.me:9887/setup
302
http://subdomain000001.lvh.me:9887/setup/accounting_dates
302
http://subdomain000001.lvh.me:9887/setup/vat_details
302
http://subdomain000001.lvh.me:9887/overview
302
http://subdomain000001.lvh.me:9887/setup
302
http://subdomain000001.lvh.me:9887/setup/accounting_dates
302
http://subdomain000001.lvh.me:9887/setup/vat_details
302
http://subdomain000001.lvh.me:9887/overview
302
http://subdomain000001.lvh.me:9887/setup
302
[...] # And on until it hits the timeout

A little more debugging:

def subscribe_response_received
  @page.on("Network.responseReceived") do |params|
    exchange = select(params["requestId"]).last

    if exchange
      response = Network::Response.new(@page, params)
      exchange.response = response
      puts "#{response.status} - #{response.url}"
      binding.pry if response.status != 200
      binding.pry if params['redirectResponse']['status'] == 302
      response.loaded = true if response.status is redirect
    end
  end
end
Output
[...]
200 - http://subdomain000001.lvh.me:9887/assets/talaria/source_sans/WOFF/OTF/SourceSansPro-Semibold.otf-e925383d18cb0ed94addee8444adf985ca8556fa4f3a0952088b57ab97c74d1f.woff
200 - http://subdomain000001.lvh.me:9887/assets/application/setup-clouds-1dfc5d93caf668f1ab11ada5ec2c2319d24475530d5b43480e53d5579d5b12d0.gif
200 - http://subdomain000001.lvh.me:9887/assets/application/setup-illustrations-1-ffa28978d62225e2e17eb6656e54ec46ab48fad94c95a8b6c86e84bdaa53d5c7.png
200 - http://subdomain000001.lvh.me:9887/assets/application/setup-illustrations-2-940cf4b3edf82e13955652ab0bb4a7a16e4936a899815d626ef4141c18fa873e.png
200 - http://subdomain000001.lvh.me:9887/assets/application/setup-illustrations-4-22726e5e0bca7e7901c55fb8897e34facffca81341456c8578bd58fa7bd952d8.png
200 - http://subdomain000001.lvh.me:9887/assets/application/setup-illustrations-5-89e61798f93d1a98e03132e94a9598db1e9847908be87dbdd31993b10f116059.png
200 - http://subdomain000001.lvh.me:9887/assets/talaria/components/icons/selectArrow-3fe18e3b8316bd20f03a1b32bc39a2bdda901fce760b51700316f5ccc60e0f91.svg
200 - http://subdomain000001.lvh.me:9887/assets/talaria/components/icons/cal-ecb2f5f5c59aab84c061122adbcc6f72d394397eb5cf816561fcbbb075832092.svg
200 - http://subdomain000001.lvh.me:9887/assets/talaria/components/icons/dot-42ac9b055cfef7d81dd982c462e5fc611e30f6b4248a47a1ab03832192e3b812.svg
http://subdomain000001.lvh.me:9887/overview
302
http://subdomain000001.lvh.me:9887/setup
302
http://subdomain000001.lvh.me:9887/setup/accounting_dates
302
http://subdomain000001.lvh.me:9887/setup/vat_details
302
http://subdomain000001.lvh.me:9887/overview
[...] # And on until it hits the timeout

@francisbeaudoin
Copy link
Contributor

francisbeaudoin commented Jan 19, 2023

@dmorgan-fa As you already worked on this, is the proposed fix in #328 making sense?

@dmorgan-fa
Copy link
Author

@francisbeaudoin, sorry for the delayed response.
I've just tested this and it does resolve the issue we were seeing, thanks!
We've since moved away from explicitly calling Cuprite's wait_for_network_idle, but it's a good addition to fix the Ferrum library 👍

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
3 participants