cache response not working reliably

[catmando]

intermittently I am not getting data back from the cache... if I move the expected response into a stub, it "seems" to work fine, although things are so intermittent its hard to tell.

I did catch one "event" in selenium - firefox, and saw that the response was 0 length, and firefox debugger said:

Reload the page to get source for: https://iw3.catprint.com/v1/files/ad57c716a68847a6c23e19db2f97fec0
?callback=jQuery11200941301673271774_1457388635205&_=1457388635207

[catmando]

So the only way I have found to reliably work around this is to keep reloading the page like this:

before(:each) do
    login(@user, then_visit: '/drafts/new/pro/1/job_type')
    iw_loaded = nil  # once this is loaded we are good to go
    retry_count = 4
    until iw_loaded || retry_count == 0 do
      retry_count -= 1
      begin
        iw_loaded = find('.tp-filename', text: 'circle_die_line.pdf', wait: 6)  # find something that should have been loaded by puffing billing
      rescue
        puts "iw files did not load due to puffing-billing issue #142 reloading page"
        wait_for_ajax
        evaluate_script('window.onbeforeunload=null')
        visit '/drafts/new/pro/1/job_type'  # try again
      end
    end
    wait_for_ajax  # make sure we don't have any other loads hanging before moving on.
end

[catmando]

and so running this gives something like this:

a pro
  standard job
    thumbnails
      can move a file up
iw files did not load due to puffing-billing issue #142 reloading page
      can move a file down
iw files did not load due to puffing-billing issue #142 reloading page
iw files did not load due to puffing-billing issue #142 reloading page
iw files did not load due to puffing-billing issue #142 reloading page
iw files did not load due to puffing-billing issue #142 reloading page
      can not move the first file up
iw files did not load due to puffing-billing issue #142 reloading page
      can not move the last file down
  label job
iw files did not load due to puffing-billing issue #142 reloading page
iw files did not load due to puffing-billing issue #142 reloading page
    can be created and added to the cart
iw files did not load due to puffing-billing issue #142 reloading page
    can change the die line
  Printed Envelope job
iw files did not load due to puffing-billing issue #142 reloading page
iw files did not load due to puffing-billing issue #142 reloading page
iw files did not load due to puffing-billing issue #142 reloading page
    has back flap imaging option
iw files did not load due to puffing-billing issue #142 reloading page
    can not set Turns in File Setup

Finished in 6 minutes 14 seconds (files took 15.88 seconds to load)
8 examples, 0 failures

where the appearance of the "issue" is quite random. Never seems to happen on the first test.

Happens much less with Selenium / FF, happens more with Poltergeist, happens even more with Poltergeist, if network is disconnected. (the above print out was from poltergeist / no network)

[catmando]

I have tried putting sleep(10) in lots of places, but it doesn't make a lot of difference. The page being loaded very early on (even before a lot of assets are loaded) try to make this call to "IW" and I think that has something to do with it. When it "works" IW is called a little later in the load of the page.

[catmando]

I tried delaying the HTTP call that is having the problem, but this shifts things around, and actually seems to make things worse.

The other clue possibly is that when it "doesn't works" the http response does not make it back to jquery, and on the firefox debugger it says "200 connection established", 0 B returned, and the ip address seems correct (127.0.0.1:56746)

[ronwsmith]

Please include your puffing-billy config and the Billy log output.

[catmando]

How do I get the log output?

[ronwsmith]

You should just be able to tail your log directory: tail -f log/* from app root.

[catmando]

Posted a gist here with the successful log and failed log... search for the "*************" to see the point where the failure does (or doesn't happen)... its with the get from something called JSONPservices.aspx (boy that is an old API...) You will notice slight differences with the timing of other requests between the failed and success cases, which I have to believe is the cause.

Here are screen shots from the firebug net log... notice the difference between the JSONPservices.aspx requests! Any help greatly appreciated...

[catmando]

FYI... I tracked this down to what I believe must be a problem in EM or the EM server. eventmachine/evma_httpserver#34

[ronwsmith]

Great, let's see if anyone can assist there. In the meantime, can you post your puffing-billy config?

[catmando]

Apologize for the delay I thought I put this in the gist:

Billy.configure do |c|
  c.cache = true
  # c.cache_request_headers = false
  c.ignore_params = [
    "https://stats.g.doubleclick.net/r/collect",
    "https://www.google-analytics.com/r/collect",
    "https://www.google.com/ads/ga-audiences"
  ]
  # c.path_blacklist = []
  # c.merge_cached_responses_whitelist = []
  c.persist_cache = true
  # c.non_successful_cache_disabled = false
  # c.non_successful_error_level = :warn
  # c.non_whitelisted_requests_disabled = false
  c.cache_path = 'spec/req_cache/'
  #c.proxy_host = 'example.com' # defaults to localhost
  #c.proxy_port = 12345 # defaults to random
  #c.proxied_request_host = nil
  #c.proxied_request_port = 80
  c.dynamic_jsonp = true
  c.dynamic_jsonp_keys = ["callback", "_"]
end

[catmando]

Closed in favor of #144