open-telemetry/opentelemetry-erlang

opentelemetry_finch handler is failing and detaching

AndrewDryga opened this issue · 2 comments

AndrewDryga commented

We have such logs seen both in test suite and production:

Error: :13:59.244 line=172 pid=<0.1372.0> file=/home/runner/work/firezone/firezone/elixir/deps/telemetry/src/telemetry.erl mfa=:telemetry.execute/3 [error] Handler {OpentelemetryFinch, :request_stop} has failed and has been detached. Class=:error
     Reason={:badkey, :status,
      {%Finch.Response{
         status: 200,
         body: ["" |
          "{\"authorization_endpoint\":\"http://localhost:41537/authorize\",\"claims_supported\":[\"aud\",\"auth_time\",\"created_at\",\"email\",\"email_verified\",\"exp\",\"family_name\",\"given_name\",\"iat\",\"identities\",\"iss\",\"name\",\"nickname\",\"phone_number\",\"picture\",\"sub\"],\"client_authorization_endpoint\":\"http://localhost:41537/oauth/client/code\",\"code_challenge_methods_supported\":[\"S256\",\"plain\"],\"end_session_endpoint\":\"https://example.com\",\"id_token_signing_alg_values_supported\":[\"HS256\",\"RS256\"],\"issuer\":\"http://localhost:41537/\",\"jwks_uri\":\"http://localhost:41537/.well-known/jwks.json\",\"mfa_challenge_endpoint\":\"http://localhost:41537/mfa/challenge\",\"registration_endpoint\":\"http://localhost:41537/oidc/register\",\"request_parameter_supported\":false,\"request_uri_parameter_supported\":false,\"response_modes_supported\":[\"query\",\"fragment\",\"form_post\"],\"response_types_supported\":[\"code\",\"token\",\"id_token\",\"code token\",\"code id_token\",\"token id_token\",\"code token id_token\"],\"revocation_endpoint\":\"http://localhost:41537/oauth/revoke\",\"scopes_supported\":[\"openid\",\"profile\",\"offline_access\",\"name\",\"given_name\",\"family_name\",\"nickname\",\"email\",\"email_verified\",\"picture\",\"created_at\",\"identities\",\"phone\",\"address\"],\"subject_types_supported\":[\"public\"],\"token_endpoint\":\"http://localhost:41537/oauth/token\",\"token_endpoint_auth_methods_supported\":[\"client_secret_basic\",\"client_secret_post\"],\"userinfo_endpoint\":\"http://localhost:41537/userinfo\"}"],
         headers: [
           {"cache-control", "max-age=0, private, must-revalidate"},
           {"content-length", "1425"},
           {"date", "Sun, 12 May 2024 16:13:59 GMT"},
           {"server", "Cowboy"}
         ],
         trailers: []
       }, 1425}}
     Stacktrace=[
       {OpentelemetryFinch, :handle_request_stop, 4,
        [file: ~c"lib/opentelemetry_finch.ex", line: 44]},
       {:telemetry, :"-execute/3-fun-0-", 4,
        [
          file: ~c"/home/runner/work/firezone/firezone/elixir/deps/telemetry/src/telemetry.erl",
          line: 160
        ]},
       {:lists, :foreach_1, 2, [file: ~c"lists.erl", line: [168](https://github.com/firezone/firezone/actions/runs/9052663558/job/24870602094?pr=4962#step:7:169)6]},
       {:telemetry, :span, 3,
        [
          file: ~c"/home/runner/work/firezone/firezone/elixir/deps/telemetry/src/telemetry.erl",
          line: 324
        ]},
       {OpenIDConnect.Document, :read_finch_response, 1,
        [file: ~c"lib/openid_connect/document.ex", line: 83]},
       {OpenIDConnect.Document, :fetch_remote_resource, 1,
        [file: ~c"lib/openid_connect/document.ex", line: 64]},
       {OpenIDConnect.Document, :fetch_document, 1,
        [file: ~c"lib/openid_connect/document.ex", line: 31]},
       {Domain.Auth.Adapters.OpenIDConnect.Settings.Changeset,
        :"-validate_discovery_document_uri/1-fun-0-", 2,
        [
          file: ~c"lib/domain/auth/adapters/openid_connect/settings/changeset.ex",
          line: 23
        ]},
       {Ecto.Changeset, :validate_change, 3,
        [file: ~c"lib/ecto/changeset.ex", line: 2427]},
       {Domain.Auth.Adapters.OpenIDConnect.Settings.Changeset, :changeset, 2,
        [
          file: ~c"lib/domain/auth/adapters/openid_connect/settings/changeset.ex",
          line: 13
        ]},
       {Domain.Repo.Changeset, :cast_polymorphic_embed, 3,
        [file: ~c"lib/domain/repo/changeset.ex", line: 423]},
       {Domain.Auth.Adapters, :provider_changeset, 1,
        [file: ~c"lib/domain/auth/adapters.ex", line: 52]},
       {Domain.Auth, :create_provider, 2, [file: ~c"lib/domain/auth.ex", line: 224]},
       {Domain.Fixtures.Auth, :create_openid_connect_provider, 1,
        [file: ~c"test/support/fixtures/auth.ex", line: 156]},
       {Domain.Fixtures.Auth, :start_and_create_openid_connect_provider, 1,
        [file: ~c"test/support/fixtures/auth.ex", line: 81]},
       {Domain.Fixtures.Auth, :"-create_identity/1-fun-1-", 2,
        [file: ~c"test/support/fixtures/auth.ex", line: 317]},
       {Domain.Fixture, :pop_assoc_fixture, 3,
        [file: ~c"test/support/fixture.ex", line: 29]},
       {Domain.Fixtures.Auth, :create_identity, 1,
        [file: ~c"test/support/fixtures/auth.ex", line: 313]},
       {Domain.Auth.Adapters.EmailTest,
        :"test request_sign_in_token/1 deletes previous sign in tokens", 1,
        [file: ~c"test/domain/auth/adapters/email_test.exs", line: 118]},
       {ExUnit.Runner, :exec_test, 2, [file: ~c"lib/ex_unit/runner.ex", line: 472]}
     ]

My theory is that it fails when Finch.stream_while/3 is used: https://github.com/firezone/openid_connect/blob/master/lib/openid_connect/document.ex#L83.

tsloughter commented

Hey, can you open this in, https://github.com/open-telemetry/opentelemetry-erlang-contrib, where that project lives.