Inconsistent behavior when using ExVCR to test logic that makes HTTP requests in spawned processes

myronmarston commented 8 years ago

We've been using ExVCR for a while and for the most part it's working well for us. However, I've spent a few hours using it in a certain situation where it's not working correctly at all and is producing inconsistent results. Here's our setup:

We have an umbrella app with multiple child applications including barbosa_client (a simple HTTP client for an internal service using httpoison) and api (a phoenix app).
ExVCR works just fine in the tests in barbosa_client
In api, we have a phoenix channel that:
- Receives a get_data event
- Spawns 4 linked processes that each get part of the data from a different backend data source (although only one of these uses HTTP: the one that uses barbosa_client. The others read data off the file system or from a SQL DB)
- The 4 linked processes send the fetched data back to the phoenix channel process, which then sends the data over a socket back to the client

I've tried to use ExVCR in the test of the phoenix channel in api and it's not working right at all. Specifically, the results are inconsistent -- I ran it a bunch of times to get it to record the interaction and I got several different results. Eventually, I got it to record, but now it plays back inconsistently. Occasionally (less than 10%) of the time, but the rest of the time it gets one of a few different failures.

Here are the different failures I see (both when recording and when trying to play back). Most common is this:

  1) test sends the expected responses (and only the expected responses) when it receives params (DeloreanAPI.KeywordAnalysisChannelAcceptanceTest)
     apps/api/test/acceptance/keyword_analysis_channel_test.exs:27
     ** (EXIT from #PID<0.14215.0>) killed

Some process exited, but it provides no detail to understand what happen, unfortunately. I occasionally see this:

     ** (EXIT from #PID<0.1154.0>) an exception was raised:
         ** (RuntimeError) {:error, "BarbosaClient.difficulty_for(\"rspec before\", \"google.en-US\") post error (reason: %HTTPoison.Error{id: nil, reason: :req_not_found}); url: http://[REDACTED]/barbosa-internal-api/0.0.1/keyword/difficulty, request_body: %{engine: \"google\", keyword: \"rspec before\", locale: \"en-US\"}, headers: [{\"Content-type\", \"application/json\"}]"}
             (rankings_endpoint_models) lib/keyword_analysis/keyword_difficulty.ex:12: Delorean.RankingsEndpointModels.KeywordAnalysis.KeywordDifficulty.get/1
             (api) web/channels/keyword_analysis_channel.ex:120: anonymous fn/5 in DeloreanAPI.KeywordAnalysisChannel.announce_and_start_with_params/3

Once I get this head-scratcher:

         ** (ExVCR.RequestNotMatchError) Request did not match with any one in the current cassette: /Users/myron/moz/delorean/vcr_cassettes/recorded/link_opportunities_acceptance_test.json.
     Delete the current cassette with [mix vcr.delete] and re-record.

             lib/exvcr/handler.ex:127: ExVCR.Handler.raise_error_if_cassette_already_exists/1
             lib/exvcr/handler.ex:111: ExVCR.Handler.get_response_from_server/2
             (hackney) :hackney.request(:post, "http://staging.roger.dal.moz.com/barbosa-internal-api/0.0.1/keyword/difficulty", [{"Content-type", "application/json"}], "{\"locale\":\"en-US\",\"keyword\":\"rspec before\",\"engine\":\"google\"}", [])
             (httpoison) lib/httpoison/base.ex:396: HTTPoison.Base.request/9
             (rest_client) lib/rest_client.ex:33: anonymous fn/5 in Delorean.RestClient.post/5
             (stdlib) timer.erl:166: :timer.tc/1
             (util) lib/monitor.ex:42: Delorean.Util.Monitor.track/1
             (util) lib/monitor.ex:32: Delorean.Util.Monitor.perform_action_and_log/2
             (barbosa_client) lib/barbosa_client.ex:25: Delorean.BarbosaClient.difficulty_for/3
             (rankings_endpoint_models) lib/keyword_analysis/keyword_difficulty.ex:8: Delorean.RankingsEndpointModels.KeywordAnalysis.KeywordDifficulty.get/1
             (api) web/channels/keyword_analysis_channel.ex:120: anonymous fn/5 in DeloreanAPI.KeywordAnalysisChannel.announce_and_start_with_params/3

What's odd about this is that link_opportunities_acceptance_test.json is not used in this test -- it's used in a completely different test in a completely different file.

I've confirmed that we have async: false in all of our tests that use ExVCR so it can't be async tests at fault (also, adding --max-cases 1 to prevent any async tests resulted in the same inconsistent weirdness).

I've tried isolating this to a simple reproducible example I can provide for you but haven't yet gotten that (sorry), but I could perhaps spend more time on that if you really need it.

I've been assuming the parallel spawned processes in the channel are at fault but (a) only one of them makes an HTTP request so there are no parallel requests happening and (b) when I move the request into a spawned process in other tests where ExVCR is working it keep working just fine...so that may be a red herring.

I did a bit of looking around the ExVCR source and noticed some places where I'd expect there to be race conditions if ExVCR was used for a test of code that makes parallel requests. I'm not sure if these are related or not, but thought I'd mention them all the same:

ExVCR.Actor.Responses.pop/1: between the get and the set call the GenServer could respond to another message, right? I think this could be fixed by moving the logic behind a defcall so that it all happens within the GenServer, ensuring it happens synchronously.
ExVCR.Checker.add_count/2: Ditto here: the genserver state could change between get and append and I think this logic should happen within the GenServer instead of in the client process.
ExVCR.Recorder.update/3: There are multiple get gen sever calls in the map followed by a set at the end and again, the genserver state could change in the meantime. (Also, if the updater or finder functions use any GenServers they could lead to race conditions as well).

To prevent race conditions, I'd expect any operation that needs to be treated atomically to happen within a single GenServer.

Thanks!

parroty commented 8 years ago

Thanks for the extensive report and analysis, the 3 points you mentioned makes sense. Is there any ways you can try (or provide sample code?). If you can provide PR, that would be great too, though.

myronmarston commented 8 years ago

I tried extracting something isolated and failed, sadly, so there's something going on I don't understand and I can't really provide you with our entire codebase. I'll keep an eye out to see if it happens again and can extract something at that time.

nicocharlery commented 8 years ago

Hi there,

@myronmarston Have you found a workaround to this issue ?

On my project, it's happening when I have a GenServer handle_call or handle_cast spawning a process that will have to to an HTTP request to HTTPoison, faked by ExVCR. And same as @myronmarston it's happening randomly.

For now, I do a try catch on that error to having it removed to the tests. But that's not a solution :

    spawn(fn ->
      try do
        function_using_http_poison
      rescue
        e in HTTPoison.Error ->
          nil
      end

myronmarston commented 8 years ago

@myronmarston Have you found a workaround to this issue ?

Nope.

Ch4s3 commented 7 years ago

I'm having the same problem when using HTTPoison.

manjufy commented 7 years ago

Something similar to https://github.com/parroty/exvcr/issues/53 it happens when we have multiple requests in the test suite. Using HTTPoison and same issue.

sescobb27 commented 6 years ago

i have a similar issue with parallel requests being made https://github.com/parroty/exvcr/issues/127 (sorry i just found this issue), i think both are related. i also added a minimum code sample of what i'm doing.

RyanSept commented 1 year ago

It seems that network calls from spawned processes are not mocked at all. Upon switching off my wifi and running this test when a cassette is already populated, I receive an error which indicates the cassette was ignored and that it tried to make a network request.

The behaviour was the same even after turning on the global_mock config

defmodule Api.SomeTest.Test do
  use ExUnit.Case, async: false
  use ExVCR.Mock, adapter: ExVCR.Adapter.Hackney

  test "can get" do
    parent_pid = self()

    use_cassette "get_example_dotcom" do
      Process.spawn(
        fn ->
          res = HTTPoison.get("https://example.com")
          send(parent_pid, res)
        end,
        [:link]
      )
    end

    assert_receive {:ok, %{status_code: 200}}, 5000
  end
end


  1) test can get (Api.SomeTest.Test)
     test/api/get_example_test.exs:5
     Assertion failed, no matching message after 5000ms
     Showing 1 of 1 message in the mailbox
     code: assert_receive {:ok, %{status_code: 200}}
     mailbox:
       pattern: {:ok, %{status_code: 200}}
       value:   {:error, %HTTPoison.Error{__exception__: true, id: nil, reason: :nxdomain}}
     stacktrace:
       test/api/get_example_test.exs:18: (test)

Finished in 5.1 seconds (0.00s async, 5.1s sync)
1 test, 1 failure

parroty / exvcr

Inconsistent behavior when using ExVCR to test logic that makes HTTP requests in spawned processes #58