Protocols getting unloaded during tests?

Questions / Help
, ,
1

I am having trouble with Elixir tests failing on CI only (passing on other machines, but failing pretty reliably in CI environment) - it looks like some protocol modules are getting unloaded from the BEAM? This project doesn’t do any changes to protocols in general doing tests (no defprotocol or defimpl in test .exs files), and it doesn’t set consolidate_protocols flag in mix.exs.

Happens on both Elixir 1.12.3 + OTP 24.0.6, and Elixir 1.12.2 + OTP 24.0.5, even when CI build cache is disabled

In setup blocks I added code to inspect the state of the two modules I saw in errors, and weirdly, indeed their loaded and protocol consolidation state changes. Here are the logs from CI:

# ... other umbrella apps 

==> ui
Enum.find(:erlang.loaded(), & &1 == Timex.Protocol) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Timex.Protocol)) != nil: false
function_exported?(Timex.Protocol, :to_gregorian_microseconds, 1): false
Protocol.consolidated?(Timex.Protocol): true
Enum.find(:erlang.loaded(), & &1 == Appsignal.Metadata) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Appsignal.Metadata)) != nil: true
function_exported?(Appsignal.Metadata, :metadata, 1): true
Protocol.consolidated?(Appsignal.Metadata): true
...Enum.find(:erlang.loaded(), & &1 == Timex.Protocol) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Timex.Protocol)) != nil: true
function_exported?(Timex.Protocol, :to_gregorian_microseconds, 1): true
Protocol.consolidated?(Timex.Protocol): true
Enum.find(:erlang.loaded(), & &1 == Appsignal.Metadata) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Appsignal.Metadata)) != nil: true
function_exported?(Appsignal.Metadata, :metadata, 1): true
Protocol.consolidated?(Appsignal.Metadata): true

# ... lots of passing tests and no difference with the modules, then around where integration tests start running:

.Enum.find(:erlang.loaded(), & &1 == Timex.Protocol) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Timex.Protocol)) != nil: false
function_exported?(Timex.Protocol, :to_gregorian_microseconds, 1): false
Protocol.consolidated?(Timex.Protocol): false
Enum.find(:erlang.loaded(), & &1 == Appsignal.Metadata) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Appsignal.Metadata)) != nil: false
function_exported?(Appsignal.Metadata, :metadata, 1): false
Protocol.consolidated?(Appsignal.Metadata): false
.Enum.find(:erlang.loaded(), & &1 == Timex.Protocol) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Timex.Protocol)) != nil: true
function_exported?(Timex.Protocol, :to_gregorian_microseconds, 1): true
Protocol.consolidated?(Timex.Protocol): true
Enum.find(:erlang.loaded(), & &1 == Appsignal.Metadata) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Appsignal.Metadata)) != nil: true
function_exported?(Appsignal.Metadata, :metadata, 1): true
Protocol.consolidated?(Appsignal.Metadata): true
.Enum.find(:erlang.loaded(), & &1 == Timex.Protocol) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Timex.Protocol)) != nil: true
function_exported?(Timex.Protocol, :to_gregorian_microseconds, 1): true
Protocol.consolidated?(Timex.Protocol): true
Enum.find(:erlang.loaded(), & &1 == Appsignal.Metadata) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Appsignal.Metadata)) != nil: true
function_exported?(Appsignal.Metadata, :metadata, 1): true
Protocol.consolidated?(Appsignal.Metadata): true
Network error: 500 u003C!DOCTYPE html>nu003Chtml>nu003Chead>n    u003Cmeta charset="utf-8">n    u003Ctitle>UndefinedFunctionError at POST / #[...] long html snippet
Warning: Network error: ServerParseError: Unexpected token u003C in JSON at position 0
Enum.find(:erlang.loaded(), & &1 == Timex.Protocol) != nil: true

  1) feature has some text (UI.SomeIntegrationTest)
Error:      apps/ui/test/ui/integration/some_test.exs:510
     ** (Wallaby.ExpectationNotMetError) Text 'Some text' was not found.
     code: |> assert_text("Some text")
     stacktrace:
       (wallaby 0.28.0) lib/wallaby/browser.ex:931: Wallaby.Browser.assert_text/2
Warning:        test/ui/integration/some_test.exs:532: (test)

     The following output was logged:
#[...] lots of unrelated logs
     11:33:39.484 http_method=POST http_path=/some_app/graphql request_id=FqVKMjSzJOo9n9gAAOLC remote_ip=127.0.0.1 pid=<0.20637.1> [info] POST /some_app/graphql
Error: :33:39.452 pid=<0.20117.1> [error] #PID<0.20635.1> running UI.Endpoint (connection #PID<0.20117.1>, stream id 17) terminated
     Server: localhost:5000 (http)
     Request: POST /some_app/graphql
     ** (exit) an exception was raised:
         ** (UndefinedFunctionError) function Timex.Protocol.to_gregorian_microseconds/1 is undefined or private
             (timex 3.7.5) Timex.Protocol.to_gregorian_microseconds(~U[2021-10-17 11:33:34Z])
Warning:              (timex 3.7.5) lib/comparable/diff.ex:15: Timex.Comparable.Diff.diff/3
             (some_app 0.1.0) lib/some_app/token_authenticate.ex:51: SomeApp.TokenAuthenticate.maybe_extend_token_expiry_date/1
Warning:              (some_app 0.1.0) lib/some_app/plugs/token_authenticate.ex:16: SomeApp.Plugs.TokenAuthenticate.call/2
             (some_app 0.1.0) SomeApp.Router.api_auth/2
             (some_app 0.1.0) lib/some_app/router.ex:1: SomeApp.Router.__pipe_through0__/1
Warning:              (phoenix 1.5.9) lib/phoenix/router.ex:347: Phoenix.Router.__call__/2
             (some_app 0.1.0) lib/some_app/endpoint.ex:1: SomeApp.Endpoint.plug_builder_call/2
Warning:              (some_app 0.1.0) lib/some_app/endpoint.ex:8: anonymous fn/3 in SomeApp.Endpoint."call (overridable 3)"/2
             (appsignal 2.2.2) lib/appsignal/instrumentation.ex:10: Appsignal.Instrumentation.instrument/1
Warning:              (some_app 0.1.0) lib/plug/debugger.ex:136: SomeApp.Endpoint."call (overridable 4)"/2
             (some_app 0.1.0) lib/some_app/endpoint.ex:1: SomeApp.Endpoint."call (overridable 5)"/2
Warning:              (some_app 0.1.0) lib/plug/error_handler.ex:65: SomeApp.Endpoint.call/2
             (ui 0.1.0) lib/plug/debugger.ex:136: UI.Endpoint."call (overridable 5)"/2
Warning:              (ui 0.1.0) lib/ui/endpoint.ex:1: UI.Endpoint."call (overridable 6)"/2
             (ui 0.1.0) lib/plug/error_handler.ex:65: UI.Endpoint.call/2
Warning:              (phoenix 1.5.9) lib/phoenix/endpoint/cowboy2_handler.ex:65: Phoenix.Endpoint.Cowboy2Handler.init/4
             (cowboy 2.9.0) /home/runner/work/myapp/myapp/deps/cowboy/src/cowboy_handler.erl:37: :cowboy_handler.execute/2
Warning:              (cowboy 2.9.0) /home/runner/work/myapp/myapp/deps/cowboy/src/cowboy_stream_h.erl:306: :cowboy_stream_h.execute/3
             (cowboy 2.9.0) /home/runner/work/myapp/myapp/deps/cowboy/src/cowboy_stream_h.erl:295: :cowboy_stream_h.request_process/3
     
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Timex.Protocol)) != nil: true
function_exported?(Timex.Protocol, :to_gregorian_microseconds, 1): true
Protocol.consolidated?(Timex.Protocol): true
Enum.find(:erlang.loaded(), & &1 == Appsignal.Metadata) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Appsignal.Metadata)) != nil: true
function_exported?(Appsignal.Metadata, :metadata, 1): true
Protocol.consolidated?(Appsignal.Metadata): true
.Enum.find(:erlang.loaded(), & &1 == Timex.Protocol) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Timex.Protocol)) != nil: true
function_exported?(Timex.Protocol, :to_gregorian_microseconds, 1): true
Protocol.consolidated?(Timex.Protocol): true
Enum.find(:erlang.loaded(), & &1 == Appsignal.Metadata) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Appsignal.Metadata)) != nil: true
function_exported?(Appsignal.Metadata, :metadata, 1): true
Protocol.consolidated?(Appsignal.Metadata): true
Network error: 500 u003C!DOCTYPE html>nu003Chtml>nu003Chead>n    u003Cmeta charset="utf-8">n    u003Ctitle>UndefinedFunctionError at POST /some_app/graphql #[...] long html snippet
Network error: ServerParseError: Unexpected token u003C in JSON at position 0

Enum.find(:erlang.loaded(), & &1 == Timex.Protocol) != nil: true

  2) feature renders and has some other text (UI.SomeIntegrationTest)
Error:      apps/ui/test/ui/integration/some_test.exs:209
     ** (Wallaby.ExpectationNotMetError) Expected to find 1, visible element with the text 'Some other text' but 0, visible elements with the text were found.
     
     code: |> assert_has(@some_other_text)
     stacktrace:
       test/ui/integration/some_test.exs:223: (test)

     The following output was logged:
#[...] lots of unrelated logs
     0.0.1 pid=<0.22902.1> [info] Sent 200 in 36ms
     11:33:52.857 request_id=FqVKNVHAsKbbPCQAAOcy remote_ip=127.0.0.1 pid=<0.22952.1> [info] POST /some_app/graphql
     11:33:52.857 http_method=POST http_path=/some_app/graphql request_id=FqVKNVHAsKbbPCQAAOcy remote_ip=127.0.0.1 pid=<0.22952.1> [info] POST /some_app/graphql
     11:33:52.864 http_method=POST http_path=/some_app/graphql request_id=FqVKNVHAsKbbPCQAAOcy remote_ip=127.0.0.1 pid=<0.22952.1> [info] Executing GraphQL query: SomeGraphqlQuery
Error: :33:53.109 pid=<0.22690.1> [error] #PID<0.22952.1> running UI.Endpoint (connection #PID<0.22690.1>, stream id 7) terminated
     Server: localhost:5000 (http)
     Request: POST /some_app/graphql
     ** (exit) an exception was raised:
         ** (UndefinedFunctionError) function Appsignal.Metadata.metadata/1 is undefined or private
             (appsignal 2.2.2) Appsignal.Metadata.metadata(%Plug.Conn{adapter: {Plug.Cowboy.Conn, :...}, assigns: %{phoenix_ecto_sandbox: "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/41.0.2228.0 Safari/537.36/BeamMetadata  #[...] lots of unrelated details
             (appsignal_plug 2.0.8) lib/appsignal_plug.ex:180: Appsignal.Plug.set_sample_data/2
Warning:              (appsignal_plug 2.0.8) lib/appsignal_plug.ex:111: Appsignal.Plug.set_conn_data/2
             (some_app 0.1.0) lib/some_app/endpoint.ex:8: anonymous fn/3 in SomeApp.Endpoint."call (overridable 3)"/2
Warning:              (appsignal 2.2.2) lib/appsignal/instrumentation.ex:10: Appsignal.Instrumentation.instrument/1
             (some_app 0.1.0) lib/plug/debugger.ex:136: SomeApp.Endpoint."call (overridable 4)"/2
Warning:              (some_app 0.1.0) lib/some_app/endpoint.ex:1: SomeApp.Endpoint."call (overridable 5)"/2
             (some_app 0.1.0) lib/plug/error_handler.ex:65: SomeApp.Endpoint.call/2
Warning:              (ui 0.1.0) lib/plug/debugger.ex:136: UI.Endpoint."call (overridable 5)"/2
             (ui 0.1.0) lib/ui/endpoint.ex:1: UI.Endpoint."call (overridable 6)"/2
Warning:              (ui 0.1.0) lib/plug/error_handler.ex:65: UI.Endpoint.call/2
             (phoenix 1.5.9) lib/phoenix/endpoint/cowboy2_handler.ex:65: Phoenix.Endpoint.Cowboy2Handler.init/4
Warning:              (cowboy 2.9.0) /home/runner/work/myapp/myapp/deps/cowboy/src/cowboy_handler.erl:37: :cowboy_handler.execute/2
             (cowboy 2.9.0) /home/runner/work/myapp/myapp/deps/cowboy/src/cowboy_stream_h.erl:306: :cowboy_stream_h.execute/3
Warning:              (cowboy 2.9.0) /home/runner/work/myapp/myapp/deps/cowboy/src/cowboy_stream_h.erl:295: :cowboy_stream_h.request_process/3
             (stdlib 3.15.2) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
     
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Timex.Protocol)) != nil: true
function_exported?(Timex.Protocol, :to_gregorian_microseconds, 1): true
Protocol.consolidated?(Timex.Protocol): true
Enum.find(:erlang.loaded(), & &1 == Appsignal.Metadata) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Appsignal.Metadata)) != nil: true
function_exported?(Appsignal.Metadata, :metadata, 1): true
Protocol.consolidated?(Appsignal.Metadata): true
.Enum.find(:erlang.loaded(), & &1 == Timex.Protocol) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Timex.Protocol)) != nil: false
function_exported?(Timex.Protocol, :to_gregorian_microseconds, 1): false
Protocol.consolidated?(Timex.Protocol): true
Enum.find(:erlang.loaded(), & &1 == Appsignal.Metadata) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Appsignal.Metadata)) != nil: false
function_exported?(Appsignal.Metadata, :metadata, 1): false
Protocol.consolidated?(Appsignal.Metadata): false
.Enum.find(:erlang.loaded(), & &1 == Timex.Protocol) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Timex.Protocol)) != nil: true
function_exported?(Timex.Protocol, :to_gregorian_microseconds, 1): true
Protocol.consolidated?(Timex.Protocol): true
Enum.find(:erlang.loaded(), & &1 == Appsignal.Metadata) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Appsignal.Metadata)) != nil: true
function_exported?(Appsignal.Metadata, :metadata, 1): true
Protocol.consolidated?(Appsignal.Metadata): true
.Enum.find(:erlang.loaded(), & &1 == Timex.Protocol) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Timex.Protocol)) != nil: true
function_exported?(Timex.Protocol, :to_gregorian_microseconds, 1): true
Protocol.consolidated?(Timex.Protocol): true
Enum.find(:erlang.loaded(), & &1 == Appsignal.Metadata) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Appsignal.Metadata)) != nil: true
function_exported?(Appsignal.Metadata, :metadata, 1): true
Protocol.consolidated?(Appsignal.Metadata): true
.Enum.find(:erlang.loaded(), & &1 == Timex.Protocol) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Timex.Protocol)) != nil: true
function_exported?(Timex.Protocol, :to_gregorian_microseconds, 1): true
Protocol.consolidated?(Timex.Protocol): true
Enum.find(:erlang.loaded(), & &1 == Appsignal.Metadata) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Appsignal.Metadata)) != nil: true
function_exported?(Appsignal.Metadata, :metadata, 1): true
Protocol.consolidated?(Appsignal.Metadata): true
Network error: 500 u003C!DOCTYPE html>nu003Chtml>nu003Chead>n    u003Cmeta charset="utf-8">n    u003Ctitle>UndefinedFunctionError at POST /some_app/graphql #[...] long html snippet
Warning: Network error: ServerParseError: Unexpected token u003C in JSON at position 0

Enum.find(:erlang.loaded(), & &1 == Timex.Protocol) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Timex.Protocol)) != nil: false
function_exported?(Timex.Protocol, :to_gregorian_microseconds, 1): false

  3) feature has something else (UI.SomeIntegrationTest)
Error:      apps/ui/test/ui/integration/some_test.exs:372
     ** (Wallaby.JSError) There was an uncaught JavaScript error:
     
     http://localhost:5000/js/app.js 1:79756 Uncaught Error: Unexpected token < in JSON at position 0
     
     code: |> assert_has(some_thing(1))
     stacktrace:
       (wallaby 0.28.0) lib/wallaby/chrome/logger.ex:8: Wallaby.Chrome.Logger.parse_log/1
Warning:        (elixir 1.12.3) lib/enum.ex:930: Enum."-each/2-lists^foreach/1-0-"/2
       (wallaby 0.28.0) lib/wallaby/driver/log_checker.ex:12: Wallaby.Driver.LogChecker.check_logs!/2
Warning:        (wallaby 0.28.0) lib/wallaby/element.ex:211: Wallaby.Element.visible?/1
       (elixir 1.12.3) lib/enum.ex:3848: Enum.filter_list/2
Warning:        (wallaby 0.28.0) lib/wallaby/browser.ex:1215: Wallaby.Browser.validate_visibility/2
       (wallaby 0.28.0) lib/wallaby/browser.ex:1282: anonymous fn/3 in Wallaby.Browser.execute_query/2
Warning:        (wallaby 0.28.0) lib/wallaby/browser.ex:147: Wallaby.Browser.retry/2
       test/ui/integration/some_test.exs:407: (test)

     The following output was logged:
#[...] lots of unrelated logs
     Executing GraphQL query: OtherGraphqlQuery
     11:34:24.566 http_method=POST http_path=/some_app/graphql request_id=FqVKPKPuLFpTjocAAYhB remote_ip=127.0.0.1 pid=<0.28598.1> [info] Sent 500 in 265ms
     11:34:24.566 http_method=POST http_path=/some_app/graphql request_id=FqVKPKPuLFpTjocAAYhB remote_ip=127.0.0.1 pid=<0.28598.1> [info] Sent 500 in 266ms
Error: :34:24.615 pid=<0.28595.1> [error] #PID<0.28598.1> running UI.Endpoint (connection #PID<0.28595.1>, stream id 3) terminated
     Server: localhost:5000 (http)
     Request: POST /some_app/graphql
     ** (exit) an exception was raised:
         ** (UndefinedFunctionError) function Timex.Protocol.to_gregorian_microseconds/1 is undefined or private
             (timex 3.7.5) Timex.Protocol.to_gregorian_microseconds(~U[2021-10-17 11:34:18Z])
Warning:              (timex 3.7.5) lib/comparable/diff.ex:15: Timex.Comparable.Diff.diff/3
             (some_app 0.1.0) lib/some_app/token_authenticate.ex:51: SomeApp.TokenAuthenticate.maybe_extend_token_expiry_date/1
Warning:              (some_app 0.1.0) lib/some_app/plugs/token_authenticate.ex:16: SomeApp.Plugs.TokenAuthenticate.call/2
             (some_app 0.1.0) SomeApp.Router.api_auth/2
             (some_app 0.1.0) lib/some_app/router.ex:1: SomeApp.Router.__pipe_through0__/1
Warning:              (phoenix 1.5.9) lib/phoenix/router.ex:347: Phoenix.Router.__call__/2
             (some_app 0.1.0) lib/some_app/endpoint.ex:1: SomeApp.Endpoint.plug_builder_call/2
Warning:              (some_app 0.1.0) lib/some_app/endpoint.ex:8: anonymous fn/3 in SomeApp.Endpoint."call (overridable 3)"/2
             (appsignal 2.2.2) lib/appsignal/instrumentation.ex:10: Appsignal.Instrumentation.instrument/1
Warning:              (some_app 0.1.0) lib/plug/debugger.ex:136: SomeApp.Endpoint."call (overridable 4)"/2
             (some_app 0.1.0) lib/some_app/endpoint.ex:1: SomeApp.Endpoint."call (overridable 5)"/2
Warning:              (some_app 0.1.0) lib/plug/error_handler.ex:65: SomeApp.Endpoint.call/2
             (ui 0.1.0) lib/plug/debugger.ex:136: UI.Endpoint."call (overridable 5)"/2
Warning:              (ui 0.1.0) lib/ui/endpoint.ex:1: UI.Endpoint."call (overridable 6)"/2
             (ui 0.1.0) lib/plug/error_handler.ex:65: UI.Endpoint.call/2
Warning:              (phoenix 1.5.9) lib/phoenix/endpoint/cowboy2_handler.ex:65: Phoenix.Endpoint.Cowboy2Handler.init/4
             (cowboy 2.9.0) /home/runner/work/myapp/myapp/deps/cowboy/src/cowboy_handler.erl:37: :cowboy_handler.execute/2
Warning:              (cowboy 2.9.0) /home/runner/work/myapp/myapp/deps/cowboy/src/cowboy_stream_h.erl:306: :cowboy_stream_h.execute/3
             (cowboy 2.9.0) /home/runner/work/myapp/myapp/deps/cowboy/src/cowboy_stream_h.erl:295: :cowboy_stream_h.request_process/3

#[...] lots of unrelated logs

Protocol.consolidated?(Timex.Protocol): true
Enum.find(:erlang.loaded(), & &1 == Appsignal.Metadata) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Appsignal.Metadata)) != nil: false
function_exported?(Appsignal.Metadata, :metadata, 1): false
Protocol.consolidated?(Appsignal.Metadata): true
.Enum.find(:erlang.loaded(), & &1 == Timex.Protocol) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Timex.Protocol)) != nil: true
function_exported?(Timex.Protocol, :to_gregorian_microseconds, 1): true
Protocol.consolidated?(Timex.Protocol): true
Enum.find(:erlang.loaded(), & &1 == Appsignal.Metadata) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Appsignal.Metadata)) != nil: true
function_exported?(Appsignal.Metadata, :metadata, 1): true
Protocol.consolidated?(Appsignal.Metadata): true
.Enum.find(:erlang.loaded(), & &1 == Timex.Protocol) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Timex.Protocol)) != nil: false
function_exported?(Timex.Protocol, :to_gregorian_microseconds, 1): false
Protocol.consolidated?(Timex.Protocol): true
Enum.find(:erlang.loaded(), & &1 == Appsignal.Metadata) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Appsignal.Metadata)) != nil: false
function_exported?(Appsignal.Metadata, :metadata, 1): false
Protocol.consolidated?(Appsignal.Metadata): false
.Enum.find(:erlang.loaded(), & &1 == Timex.Protocol) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Timex.Protocol)) != nil: false
function_exported?(Timex.Protocol, :to_gregorian_microseconds, 1): false
Protocol.consolidated?(Timex.Protocol): true
Enum.find(:erlang.loaded(), & &1 == Appsignal.Metadata) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Appsignal.Metadata)) != nil: false
function_exported?(Appsignal.Metadata, :metadata, 1): false
Protocol.consolidated?(Appsignal.Metadata): true

Network error: 500 u003C!DOCTYPE html>nu003Chtml>nu003Chead>n    u003Cmeta charset="utf-8">n    u003Ctitle>UndefinedFunctionError at POST /some_app/graphql #[...] long html snippet
Network error: ServerParseError: Unexpected token u003C in JSON at position 0
Enum.find(:erlang.loaded(), & &1 == Timex.Protocol) != nil: true

  4) feature does something (UI.SomeIntegrationTest)
Error:      apps/ui/test/ui/integration/some_test.exs:299
     ** (Wallaby.JSError) There was an uncaught JavaScript error:
     
     http://localhost:5000/js/app.js 1:79756 Uncaught Error: Unexpected token < in JSON at position 0
     
     code: |> assert_has(@a_thing)
     stacktrace:
       (wallaby 0.28.0) lib/wallaby/chrome/logger.ex:8: Wallaby.Chrome.Logger.parse_log/1
Warning:        (elixir 1.12.3) lib/enum.ex:930: Enum."-each/2-lists^foreach/1-0-"/2
       (wallaby 0.28.0) lib/wallaby/driver/log_checker.ex:12: Wallaby.Driver.LogChecker.check_logs!/2
Warning:        (wallaby 0.28.0) lib/wallaby/browser.ex:1281: anonymous fn/3 in Wallaby.Browser.execute_query/2
       (wallaby 0.28.0) lib/wallaby/browser.ex:147: Wallaby.Browser.retry/2
Warning:        test/ui/integration/some_test.exs:327: (test)

     The following output was logged:
#[...] lots of unrelated logs
     11:34:39.729 request_id=FqVKQDuVPIhWlzgAAQQi remote_ip=127.0.0.1 pid=<0.30432.1> [info] POST /some_app/graphql
     11:34:39.729 http_method=POST http_path=/some_app/graphql request_id=FqVKQDuVPIhWlzgAAQQi remote_ip=127.0.0.1 pid=<0.30432.1> [info] POST /some_app/graphql
     11:34:39.736 http_method=POST http_path=/some_app/graphql request_id=FqVKQDuVPIhWlzgAAQQi remote_ip=127.0.0.1 pid=<0.30432.1> [info] Executing GraphQL query: AnotherGraphqlQuery
Error: :34:39.976 pid=<0.30312.1> [error] #PID<0.30432.1> running UI.Endpoint (connection #PID<0.30312.1>, stream id 10) terminated
     Server: localhost:5000 (http)
     Request: POST /some_app/graphql
     ** (exit) an exception was raised:
         ** (UndefinedFunctionError) function Appsignal.Metadata.metadata/1 is undefined or private
             (appsignal 2.2.2) Appsignal.Metadata.metadata(%Plug.Conn{adapter: {Plug.Cowboy.Conn, :...}, assigns: %{phoenix_ecto_sandbox: "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/41.0.2228.0 Safari/537.36/BeamMetadata #[...] lots of unrelated details
             (appsignal_plug 2.0.8) lib/appsignal_plug.ex:180: Appsignal.Plug.set_sample_data/2
Warning:              (appsignal_plug 2.0.8) lib/appsignal_plug.ex:111: Appsignal.Plug.set_conn_data/2
             (some_app 0.1.0) lib/some_app/endpoint.ex:8: anonymous fn/3 in SomeApp.Endpoint."call (overridable 3)"/2
Warning:              (appsignal 2.2.2) lib/appsignal/instrumentation.ex:10: Appsignal.Instrumentation.instrument/1
             (some_app 0.1.0) lib/plug/debugger.ex:136: SomeApp.Endpoint."call (overridable 4)"/2
Warning:              (some_app 0.1.0) lib/some_app/endpoint.ex:1: SomeApp.Endpoint."call (overridable 5)"/2
             (some_app 0.1.0) lib/plug/error_handler.ex:65: SomeApp.Endpoint.call/2
Warning:              (ui 0.1.0) lib/plug/debugger.ex:136: UI.Endpoint."call (overridable 5)"/2
             (ui 0.1.0) lib/ui/endpoint.ex:1: UI.Endpoint."call (overridable 6)"/2
Warning:              (ui 0.1.0) lib/plug/error_handler.ex:65: UI.Endpoint.call/2
             (phoenix 1.5.9) lib/phoenix/endpoint/cowboy2_handler.ex:65: Phoenix.Endpoint.Cowboy2Handler.init/4
Warning:              (cowboy 2.9.0) /home/runner/work/myapp/myapp/deps/cowboy/src/cowboy_handler.erl:37: :cowboy_handler.execute/2
             (cowboy 2.9.0) /home/runner/work/myapp/myapp/deps/cowboy/src/cowboy_stream_h.erl:306: :cowboy_stream_h.execute/3
Warning:              (cowboy 2.9.0) /home/runner/work/myapp/myapp/deps/cowboy/src/cowboy_stream_h.erl:295: :cowboy_stream_h.request_process/3
             (stdlib 3.15.2) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
     
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Timex.Protocol)) != nil: false
function_exported?(Timex.Protocol, :to_gregorian_microseconds, 1): false
Protocol.consolidated?(Timex.Protocol): false
Enum.find(:erlang.loaded(), & &1 == Appsignal.Metadata) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Appsignal.Metadata)) != nil: false
function_exported?(Appsignal.Metadata, :metadata, 1): false
Protocol.consolidated?(Appsignal.Metadata): true
.Enum.find(:erlang.loaded(), & &1 == Timex.Protocol) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Timex.Protocol)) != nil: true
function_exported?(Timex.Protocol, :to_gregorian_microseconds, 1): true
Protocol.consolidated?(Timex.Protocol): false

#[...] many tests passing and no change

.Enum.find(:erlang.loaded(), & &1 == Timex.Protocol) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Timex.Protocol)) != nil: false
function_exported?(Timex.Protocol, :to_gregorian_microseconds, 1): false
Protocol.consolidated?(Timex.Protocol): true
Enum.find(:erlang.loaded(), & &1 == Appsignal.Metadata) != nil: true
Enum.find(:code.all_loaded(), &(elem(&1, 0) == Appsignal.Metadata)) != nil: true
function_exported?(Appsignal.Metadata, :metadata, 1): true
Protocol.consolidated?(Appsignal.Metadata): true

#[...] many tests passing

Does anyone know what could cause this behavior?

2

It may have been a rogue code_reloader: true setting in config/test.exs for one of the endpoints that we just found :crossed_fingers: