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

[dmorgan-fa]

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:

• fix: finished? should return true only when response is fully loaded #309

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:

• Testing upstream fac/ferrum#6

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]

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]

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]

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

[dmorgan-fa]

@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 👍