Incorrect pattern matching in Appsignal.Phoenix.EventHandler.phoenix_router_dispatch_exception/4

[benonymus]

Describe the bug

I am seeing an error log that says:

06:28:36.600 request_id=F0w1QXoRfbBLuO0AAAwB [error] Handler {Appsignal.Phoenix.EventHandler, [:phoenix, :router_dispatch, :exception]} has failed and has been detached. Class=:error
Reason=:function_clause
Stacktrace=[
  {Appsignal.Phoenix.EventHandler, :phoenix_router_dispatch_exception,
   [
     [:phoenix, :router_dispatch, :exception],
     %{duration: 160732125},
     %{
       conn: %Plug.Conn{

I dug into it a bit and it seems the pattern matching expects the stack key to be present but in the data that comes I see stacktrace.

To Reproduce

Steps to reproduce the behavior:

I don't think we are doing anything in particular, I see the behavior on a regular delete endpoint.

• Using AppSignal for Elixir package version 2.5.2

[jeffkreeftmeijer]

Hey @benonymus,

Thanks for reporting this, I’m looking into it. Could you send me the full stack trace? Also, reverting your :appsignal_elixir version to 2.2.1 should resolve the issue while we’re working on this.

[benonymus]

The full stacktrace is not more useful than this, because it just prints the conn, and cuts it off because it is too long.

I added another function clause to print the whole thing, here is that (from our tests, but saw it on prod too):

%{
  conn: %Plug.Conn{
    adapter: {Plug.Adapters.Test.Conn,
     %{
       chunks: nil,
       http_protocol: :"HTTP/1.1",
       method: "GET",
       owner: #PID<0.1119.0>,
       params: nil,
       peer_data: %{address: {127, 0, 0, 1}, port: 111317, ssl_cert: nil},
       ref: #Reference<0.1197830853.1585709057.88103>,
       req_body: ""
     }},
    assigns: %{
      current_user: #app.Users.User<
        __meta__: #Ecto.Schema.Metadata<:loaded, "users">,
        id: "u_bj5pe",
        invited_by_id: nil,
        invited_by: #Ecto.Association.NotLoaded<association :invited_by is not loaded>,
        invited_users: #Ecto.Association.NotLoaded<association :invited_users is not loaded>,
        user_identities: #Ecto.Association.NotLoaded<association :user_identities is not loaded>,
        invitation_accepted_at: nil,
        invitation_token: nil,
        unconfirmed_email: nil,
        email_confirmed_at: nil,
        email_confirmation_token: nil,
        email: "test-0@example.com",
        name: nil,
        role: :owner,
        role_in_selected_team: nil,
        status_in_selected_team: nil,
        default_timezone: "Etc/UTC",
        referral_source: nil,
        photo_url: nil,
        signed_photo_url: nil,
        hosted_domain: nil,
        is_fake: false,
        default_user_team: %app.UsersTeams.UserTeam{
          __meta__: #Ecto.Schema.Metadata<:loaded, "users_teams">,
          id: 3890,
          role: :owner,
          status: :active,
          is_default: true,
          user_id: "u_bj5pe",
          user: #Ecto.Association.NotLoaded<association :user is not loaded>,
          team_id: "w_zpeyj",
          team: %app.Teams.Team{
            __meta__: #Ecto.Schema.Metadata<:loaded, "teams">,
            id: "w_zpeyj",
            name: "test-team-0",
            owner_user_team: #Ecto.Association.NotLoaded<association :owner_user_team is not loaded>,
            owner: #Ecto.Association.NotLoaded<association :owner is not loaded>,
            owner_id: nil,
            default_timezone: "Etc/UTC",
            default_transcription_language: "en-US",
            color: "#008C2C",
            hosted_domain: nil,
            allow_auto_join: false,
            photo_url: nil,
            active_users_teams: #Ecto.Association.NotLoaded<association :active_users_teams is not loaded>,
            active_users: #Ecto.Association.NotLoaded<association :active_users is not loaded>,
            active_member_count: nil,
            pending_users_teams: #Ecto.Association.NotLoaded<association :pending_users_teams is not loaded>,
            pending_member_count: nil,
            users_teams: #Ecto.Association.NotLoaded<association :users_teams is not loaded>,
            user_team_id: nil,
            inserted_at: ~N[2023-03-14 06:56:55],
            updated_at: ~N[2023-03-14 06:56:55]
          },
          inserted_at: ~N[2023-03-14 06:56:55],
          updated_at: ~N[2023-03-14 06:56:55]
        },
        team: %app.Teams.Team{
          __meta__: #Ecto.Schema.Metadata<:loaded, "teams">,
          id: "w_zpeyj",
          name: "test-team-0",
          owner_user_team: #Ecto.Association.NotLoaded<association :owner_user_team is not loaded>,
          owner: #Ecto.Association.NotLoaded<association :owner is not loaded>,
          owner_id: nil,
          default_timezone: "Etc/UTC",
          default_transcription_language: "en-US",
          color: "#008C2C",
          hosted_domain: nil,
          allow_auto_join: false,
          photo_url: nil,
          active_users_teams: #Ecto.Association.NotLoaded<association :active_users_teams is not loaded>,
          active_users: #Ecto.Association.NotLoaded<association :active_users is not loaded>,
          active_member_count: nil,
          pending_users_teams: #Ecto.Association.NotLoaded<association :pending_users_teams is not loaded>,
          pending_member_count: nil,
          users_teams: #Ecto.Association.NotLoaded<association :users_teams is not loaded>,
          user_team_id: nil,
          inserted_at: ~N[2023-03-14 06:56:55],
          updated_at: ~N[2023-03-14 06:56:55]
        },
        team_id: "w_zpeyj",
        pending_user_teams: [],
        pending_teams: [],
        users_teams: [
          %app.UsersTeams.UserTeam{
            __meta__: #Ecto.Schema.Metadata<:loaded, "users_teams">,
            id: 3890,
            role: :owner,
            status: :active,
            is_default: true,
            user_id: "u_bj5pe",
            user: #Ecto.Association.NotLoaded<association :user is not loaded>,
            team_id: "w_zpeyj",
            team: %app.Teams.Team{
              __meta__: #Ecto.Schema.Metadata<:loaded, "teams">,
              id: "w_zpeyj",
              name: "test-team-0",
              owner_user_team: %app.UsersTeams.UserTeam{
                __meta__: #Ecto.Schema.Metadata<:loaded, "users_teams">,
                id: 3890,
                role: :owner,
                status: :active,
                is_default: true,
                user_id: "u_bj5pe",
                user: #app.Users.User<
                  __meta__: #Ecto.Schema.Metadata<:loaded, "users">,
                  id: "u_bj5pe",
                  invited_by_id: nil,
                  invited_by: #Ecto.Association.NotLoaded<association :invited_by is not loaded>,
                  invited_users: #Ecto.Association.NotLoaded<association :invited_users is not loaded>,
                  user_identities: #Ecto.Association.NotLoaded<association :user_identities is not loaded>,
                  invitation_accepted_at: nil,
                  invitation_token: nil,
                  unconfirmed_email: nil,
                  email_confirmed_at: nil,
                  email_confirmation_token: nil,
                  email: "test-0@example.com",
                  name: nil,
                  role: nil,
                  role_in_selected_team: nil,
                  status_in_selected_team: nil,
                  default_timezone: "Etc/UTC",
                  referral_source: nil,
                  photo_url: nil,
                  signed_photo_url: nil,
                  hosted_domain: nil,
                  is_fake: false,
                  default_user_team: #Ecto.Association.NotLoaded<association :default_user_team is not loaded>,
                  team: #Ecto.Association.NotLoaded<association :team is not loaded>,
                  team_id: nil,
                  pending_user_teams: #Ecto.Association.NotLoaded<association :pending_user_teams is not loaded>,
                  pending_teams: #Ecto.Association.NotLoaded<association :pending_teams is not loaded>,
                  users_teams: #Ecto.Association.NotLoaded<association :users_teams is not loaded>,
                  settings: #Ecto.Association.NotLoaded<association :settings is not loaded>,
                  user_session_balance: #Ecto.Association.NotLoaded<association :user_session_balance is not loaded>,
                  session_balance_ms: nil,
                  stripe_customer_id: nil,
                  active_stripe_subscription_id: nil,
                  intercom_contact_id: nil,
                  onboarding_step: nil,
                  subscribe_to_product_updates: true,
                  color_set: %{bg_hex_color: "#000000", bg_tw_color: "#000000"},
                  inserted_at: ~N[2023-03-14 06:56:55],
                  updated_at: ~N[2023-03-14 06:56:55],
                  ...
                >,
                team_id: "w_zpeyj",
                team: #Ecto.Association.NotLoaded<association :team is not loaded>,
                inserted_at: ~N[2023-03-14 06:56:55],
                updated_at: ~N[2023-03-14 06:56:55]
              },
              owner: #app.Users.User<
                __meta__: #Ecto.Schema.Metadata<:loaded, "users">,
                id: "u_bj5pe",
                invited_by_id: nil,
                invited_by: #Ecto.Association.NotLoaded<association :invited_by is not loaded>,
                invited_users: #Ecto.Association.NotLoaded<association :invited_users is not loaded>,
                user_identities: #Ecto.Association.NotLoaded<association :user_identities is not loaded>,
                invitation_accepted_at: nil,
                invitation_token: nil,
                unconfirmed_email: nil,
                email_confirmed_at: nil,
                email_confirmation_token: nil,
                email: "test-0@example.com",
                name: nil,
                role: nil,
                role_in_selected_team: nil,
                status_in_selected_team: nil,
                default_timezone: "Etc/UTC",
                referral_source: nil,
                photo_url: nil,
                signed_photo_url: nil,
                hosted_domain: nil,
                is_fake: false,
                default_user_team: #Ecto.Association.NotLoaded<association :default_user_team is not loaded>,
                team: #Ecto.Association.NotLoaded<association :team is not loaded>,
                team_id: nil,
                pending_user_teams: #Ecto.Association.NotLoaded<association :pending_user_teams is not loaded>,
                pending_teams: #Ecto.Association.NotLoaded<association :pending_teams is not loaded>,
                users_teams: #Ecto.Association.NotLoaded<association :users_teams is not loaded>,
                settings: #Ecto.Association.NotLoaded<association :settings is not loaded>,
                user_session_balance: #Ecto.Association.NotLoaded<association :user_session_balance is not loaded>,
                session_balance_ms: nil,
                stripe_customer_id: nil,
                active_stripe_subscription_id: nil,
                intercom_contact_id: nil,
                onboarding_step: nil,
                subscribe_to_product_updates: true,
                color_set: %{bg_hex_color: "#000000", bg_tw_color: "#000000"},
                inserted_at: ~N[2023-03-14 06:56:55],
                updated_at: ~N[2023-03-14 06:56:55],
                ...
              >,
              owner_id: nil,
              default_timezone: "Etc/UTC",
              default_transcription_language: "en-US",
              color: "#008C2C",
              hosted_domain: nil,
              allow_auto_join: false,
              photo_url: nil,
              active_users_teams: #Ecto.Association.NotLoaded<association :active_users_teams is not loaded>,
              active_users: #Ecto.Association.NotLoaded<association :active_users is not loaded>,
              active_member_count: 1,
              pending_users_teams: #Ecto.Association.NotLoaded<association :pending_users_teams is not loaded>,
              pending_member_count: 0,
              users_teams: #Ecto.Association.NotLoaded<association :users_teams is not loaded>,
              user_team_id: nil,
              inserted_at: ~N[2023-03-14 06:56:55],
              updated_at: ~N[2023-03-14 06:56:55]
            },
            inserted_at: ~N[2023-03-14 06:56:55],
            updated_at: ~N[2023-03-14 06:56:55]
          }
        ],
        settings: #Ecto.Association.NotLoaded<association :settings is not loaded>,
        user_session_balance: %app.Users.UserSessionBalance{
          __meta__: #Ecto.Schema.Metadata<:loaded, "user_session_balances">,
          id: 3620,
          balance_ms: 0,
          user_id: "u_bj5pe",
          user: #Ecto.Association.NotLoaded<association :user is not loaded>,
          user_session_balance_txs: #Ecto.Association.NotLoaded<association :user_session_balance_txs is not loaded>,
          inserted_at: ~N[2023-03-14 06:56:55],
          updated_at: ~N[2023-03-14 06:56:55]
        },
        session_balance_ms: 0,
        stripe_customer_id: nil,
        active_stripe_subscription_id: nil,
        intercom_contact_id: nil,
        onboarding_step: nil,
        subscribe_to_product_updates: true,
        color_set: %{bg_hex_color: "#A16207", bg_tw_color: "bg-yellow-700"},
        inserted_at: ~N[2023-03-14 06:56:55],
        updated_at: ~N[2023-03-14 06:56:55],
        ...
      >,
      user_token: "SFMyNTY.g2gDbQAAAAd1X2JqNXBlbgYAl2Po3oYBYgABUYA.7ELV26McFiE3wFxYdVdqQBTD7oUNwdCE19LtYHYiT3w",
      zoom_pkce_code_challenge: "qsjegExxRGIWTFAL3DuXeu064Ari_ejs7KglmSgs8mw=",
      zoom_pkce_code_verifier: "TQlEvEfN5tMNCwe3Ybx83Znr3t3ReKGn6u4xNozWRQM"
    },
    body_params: %{},
    cookies: %{
      "_app_key" => "SFMyNTY.g3QAAAABbQAAAA1waG9lbml4X2ZsYXNodAAAAAFtAAAABGluZm9tAAAAHVByb2plY3QgZGVsZXRlZCBzdWNjZXNzZnVsbHku.9ig0oHaa9xdzAc1QK6Sf6zHQcVUtiqxFEY4qG1rlR8M"
    },
    halted: false,
    host: "www.example.com",
    method: "GET",
    owner: #PID<0.1119.0>,
    params: %{"project_id" => "p_yn4xr"},
    path_info: ["studies", "p_yn4xr"],
    path_params: %{"project_id" => "p_yn4xr"},
    port: 80,
    private: %{
      appWeb.Router => {[],
       %{
         appWeb.Router.FigmaApiImagesProxy => ["figma-api-images"],
         appWeb.Router.FigmaApiImgProxy => ["figma-api-img"],
         appWeb.Router.GoogleFontProxy => ["css2"],
         appWeb.Router.ProductHuntProxy => ["widgets", "embed-image"],
         FunWithFlags.UI.Router => []
       }},
      :before_send => [#Function<2.69371438/1 in PowPersistentSession.Plug.Cookie.call/2>,
       #Function<2.28238432/1 in Pow.Plug.Session.call/2>,
       #Function<0.11807388/1 in Plug.Telemetry.call/2>,
       #Function<2.28238432/1 in Pow.Plug.Session.call/2>],
      :phoenix_endpoint => appWeb.Endpoint,
      :phoenix_live_view => {appWeb.ProjectParentLive,
       [action: nil, router: appWeb.Router],
       %{
         extra: %{
           on_mount: [
             %{
               function: &appWeb.UserLiveAuth.on_mount/4,
               id: {appWeb.UserLiveAuth, :default},
               stage: :mount
             }
           ],
           session: %{}
         },
         name: :app_app,
         vsn: 1678776933891268404
       }},
      :phoenix_recycled => true,
      :phoenix_request_logger => {"request_logger", "request_logger"},
      :phoenix_router => appWeb.Router,
      :plug_session => %{
        "app_auth" => "SFMyNTY.c2Vzc2lvbl9pZA.e097dM30uuhQ2fglOiU5khbRSxJQmtSOeRHpkgtianc"
      },
      :plug_session_fetch => #Function<1.84243074/1 in Plug.Session.fetch_session/1>,
      :plug_session_info => :write,
      :plug_skip_csrf_protection => true,
      :"pow/plug/session/before_send" => [#Function<1.28238432/1 in Pow.Plug.Session.before_send_delete/2>,
       #Function<0.28238432/1 in Pow.Plug.Session.before_send_create/3>],
      :pow_config => [
        mod: Pow.Plug.Session,
        plug: Pow.Plug.Session,
        otp_app: :app
      ],
      :pow_persistent_session => {PowPersistentSession.Plug.Cookie,
       [
         mod: Pow.Plug.Session,
         plug: Pow.Plug.Session,
         otp_app: :app,
         persistent_session_cookie_opts: [same_site: "None", secure: true]
       ]},
      :pow_session_metadata => [
        inserted_at: 1678777017455,
        fingerprint: "1bbe1a28-ff8e-47b3-a8d3-88e59af8157e"
      ]
    },
    query_params: %{},
    query_string: "",
    remote_ip: {127, 0, 0, 1},
    req_cookies: %{
      "_app_key" => "SFMyNTY.g3QAAAABbQAAAA1waG9lbml4X2ZsYXNodAAAAAFtAAAABGluZm9tAAAAHVByb2plY3QgZGVsZXRlZCBzdWNjZXNzZnVsbHku.9ig0oHaa9xdzAc1QK6Sf6zHQcVUtiqxFEY4qG1rlR8M"
    },
    req_headers: [
      {"cookie",
       "_app_key=SFMyNTY.g3QAAAABbQAAAA1waG9lbml4X2ZsYXNodAAAAAFtAAAABGluZm9tAAAAHVByb2plY3QgZGVsZXRlZCBzdWNjZXNzZnVsbHku.9ig0oHaa9xdzAc1QK6Sf6zHQcVUtiqxFEY4qG1rlR8M"}
    ],
    request_path: "/studies/p_yn4xr",
    resp_body: nil,
    resp_cookies: %{},
    resp_headers: [
      {"cache-control", "max-age=0, private, must-revalidate"},
      {"x-request-id", "F0w2zYa5lDZLuO0AAAtB"}
    ],
    scheme: :http,
    script_name: [],
    secret_key_base: :...,
    state: :unset,
    status: nil
  },
  kind: :error,
  log: :debug,
  log_function: :mount,
  log_module: appWeb.ProjectParentLive,
  path_params: %{"project_id" => "p_yn4xr"},
  phoenix_live_view: {appWeb.ProjectParentLive, nil,
   [action: nil, router: appWeb.Router],
   %{
     extra: %{
       on_mount: [
         %{
           function: &appWeb.UserLiveAuth.on_mount/4,
           id: {appWeb.UserLiveAuth, :default},
           stage: :mount
         }
       ],
       session: %{}
     },
     name: :app_app,
     vsn: 1678776933891268404
   }},
  pipe_through: [:browser, :protected, :pow_auth_links],
  plug: Phoenix.LiveView.Plug,
  plug_opts: appWeb.ProjectParentLive,
  reason: %Ecto.NoResultsError{
    message: "expected at least one result but got none in query:\n\nfrom s0 in app.Studies.Study,\n  left_join: s1 in assoc(s0, :sessions),\n  left_join: c2 in assoc(s0, :completed_sessions),\n  where: s0.id == ^\"p_yn4xr\",\n  group_by: [s0.id],\n  select: merge(s0, %{\n  session_count: count(s1.id, :distinct),\n  completed_session_count: count(c2.id, :distinct)\n})\n"
  },
  route: "/studies/:project_id",
  stacktrace: [
    {Ecto.Repo.Queryable, :one!, 3,
     [file: 'lib/ecto/repo/queryable.ex', line: 161]},
    {app.Repo, :get!, 3, [file: 'lib/app/repo.ex', line: 6]},
    {app.Studies, :get_study!, 1,
     [file: 'lib/app/studies/studies.ex', line: 55]},
    {appWeb.ProjectParentLive, :mount, 3,
     [file: 'lib/app_web/live/project_parent_live.ex', line: 23]},
    {Phoenix.LiveView.Utils, :"-maybe_call_live_view_mount!/5-fun-0-", 6,
     [file: 'lib/phoenix_live_view/utils.ex', line: 335]},
    {:telemetry, :span, 3,
     [file: '/app/deps/telemetry/src/telemetry.erl', line: 321]},
    {Phoenix.LiveView.Static, :call_mount_and_handle_params!, 5,
     [file: 'lib/phoenix_live_view/static.ex', line: 278]},
    {Phoenix.LiveView.Static, :render, 3,
     [file: 'lib/phoenix_live_view/static.ex', line: 111]},
    {Phoenix.LiveView.Controller, :live_render, 3,
     [file: 'lib/phoenix_live_view/controller.ex', line: 39]},
    {Phoenix.Router, :__call__, 2, [file: 'lib/phoenix/router.ex', line: 354]},
    {appWeb.Endpoint, :plug_builder_call, 2,
     [file: 'lib/app_web/endpoint.ex', line: 1]},
    {appWeb.Endpoint, :"call (overridable 3)", 2,
     [file: 'lib/app_web/endpoint.ex', line: 1]},
    {appWeb.Endpoint, :call, 2,
     [file: 'lib/app_web/endpoint.ex', line: 1]},
    {Phoenix.ConnTest, :dispatch, 5,
     [file: 'lib/phoenix/test/conn_test.ex', line: 225]},
    {Phoenix.ConnTest, :wrap_request, 1,
     [file: 'lib/phoenix/test/conn_test.ex', line: 696]},
    {Phoenix.ConnTest, :assert_error_sent, 2,
     [file: 'lib/phoenix/test/conn_test.ex', line: 650]},
    {appWeb.StudyControllerTest,
     :"test delete study deletes chosen study with an associated session", 1,
     [file: 'test/app_web/controllers/study_controller_test.exs', line: 122]},
    {ExUnit.Runner, :exec_test, 1, [file: 'lib/ex_unit/runner.ex', line: 512]},
    {:timer, :tc, 1, [file: 'timer.erl', line: 235]},
    {ExUnit.Runner, :"-spawn_test_monitor/4-fun-1-", 4,
     [file: 'lib/ex_unit/runner.ex', line: 463]}
  ]
}

[jeffkreeftmeijer]

You're right, that's been a bit confusing in the past, but I think the current implementation matches the error we're seeing here. In fact, there are two ways we get an error, either through the Plug.Conn, or through Plug's Plug.Conn.WrapperError. The latter is used to wrap errors, and includes an updated :conn and :stack, because there's no way to get the latest conn when an error is raised otherwise.

Now, Plug.Conn has a :stacktrace key, while Plug.Conn.WrapperError has a :stack key. I did some testing with this, and we seem to handle both options, so there should be some other way we're failing to handle this event.

So, outside of the conn, it would be interesting to know what's sent to the event handler here, especially the stack trace, which should be in the telemetry metadata:

[:phoenix, :router_dispatch, :exception],
%{duration: 160732125},
%{conn: _, reason: _, stack: _}
_

That said, I understand if those logs are gone by now.

I'll try to reproduce this in my example app. If you have any more information about the action that's called, that might also be helpful.

[jeffkreeftmeijer]

Alright, firstly, we shouldn't crash the event handler even if we fail to extract data from an error. I'be pushed a fix to the error-catch-all branch that prints a warning to the console instead. This should give us some more information in cases like this.

If you have time, could you run that branch in your app locally, and see if you can trigger the error once more? You should be able to switch to the branch by updating the dependency in your mix.exs file:

{:appsignal_phoenix, github: "appsignal/appsignal-elixir-phoenix", branch: "error-catch-all"}

[benonymus]

Hey Jeff,

I tried the branch, the error is gone now!

Just to reply to the previous message, I am not sure if I understand correctly, but if you wrap the log I sent, the stacktrace key is outside of conn. That log I got by adding a new catch all clause to phoenix_router_dispatch_exception (recompiled the dep), and this is the whole map that it gets.

[jeffkreeftmeijer]

I'm sorry for the confusion here. You're right, the stack trace isn't inside the conn, it's a key in the metadata map we're getting.

Good to hear that the updated patch prevents the event handler in your app from crashing. It should throw a warning if it happens again with the information we need to get to the bottom of this. Sould you please keep an eye on those logs to look out for long warnings from AppSignal?

[benonymus]

Oh our app never crashed due to this, just this big error would pop up in the logs sometimes. It does not have an effect on the running app.

[benonymus]

Resolved on :appsignal_phoenix, "~> 2.3.1"}. Thanks!