Oban.TimeoutError are not reported to AppSignal

[jozuas]

Describe the bug

When Oban jobs are configured with an execution timeout (see docs):

@impl Oban.Worker
def timeout(_job), do: :timer.seconds(1)

And the jobs fail due to a timeout with an Oban.TimeoutError, the discarded jobs are not reported to AppSignal.

To Reproduce

deps:

• :appsignal version 2.15.9
• :oban version 2.19.4

config:

config :appsignal, :config,
  otp_app: :tp,
  name: "Tp",
  push_api_key: env."TP_APPSIGNAL_API_KEY",
  # Report errors when the job is discarded due to the error. Not for every attempt.
  report_oban_errors: :discard,
  ignore_errors: [
    # Should be ignored, as this is an internal error type for Bandit
    # https://github.com/mtrudel/bandit/issues/456#issuecomment-2740929245
    "Bandit.TransportError"
  ],
  env: config_env(),
  active: true

code:

defmodule TpData.ObanWorkers.DiscardTest do
  use Oban.Worker, queue: :default, max_attempts: 2

  @impl Oban.Worker
  def perform(_oban_job) do
    Process.sleep(2000)
  end

  @impl Oban.Worker
  def timeout(_job), do: :timer.seconds(1)
end

defmodule TpData.ObanWorkers.DiscardTest2 do
  use Oban.Worker, queue: :default, max_attempts: 2

  @impl Oban.Worker
  def perform(_oban_job) do
    raise "DiscardTest2"
  end
end

In the shell, inserting both jobs:

iex(tp@127.0.0.1)1> ObanWorkers.DiscardTest.new(%{}) |> Oban.insert()
{:ok,
 %Oban.Job{
 ...
}
iex(tp@127.0.0.1)1> ObanWorkers.DiscardTest2.new(%{}) |> Oban.insert()
{:ok,
 %Oban.Job{
 ...
}

Logs for 2nd attempt of both jobs:

10:54:12.114 [info] {"args":{},"id":3660,"meta":{"orig_scheduled_at":1758279233948088},"system_time":1758279252113866667,"max_attempts":2,"queue":"default","worker":"TpData.ObanWorkers.DiscardTest","source":"oban","tags":[],"attempt":2,"event":"job:start"}
10:54:13.125 [error] {"error":"** (Oban.TimeoutError) TpData.ObanWorkers.DiscardTest timed out after 1000ms","args":{},"id":3660,"meta":{"orig_scheduled_at":1758279233948088},"state":"discard","max_attempts":2,"queue":"default","worker":"TpData.ObanWorkers.DiscardTest","source":"oban","tags":[],"duration":1002374,"attempt":2,"event":"job:exception","queue_time":122020}

10:54:15.139 [info] {"args":{},"id":3661,"meta":{"orig_scheduled_at":1758279236611976},"system_time":1758279255139528750,"max_attempts":2,"queue":"default","worker":"TpData.ObanWorkers.DiscardTest2","source":"oban","tags":[],"attempt":2,"event":"job:start"}
10:54:15.143 [error] {"error":"** (RuntimeError) DiscardTest2","args":{},"id":3661,"meta":{"orig_scheduled_at":1758279236611976},"state":"discard","max_attempts":2,"queue":"default","worker":"TpData.ObanWorkers.DiscardTest2","source":"oban","tags":[],"duration":565,"attempt":2,"event":"job:exception","queue_time":506112}

Meanwhile in the AppSignal dashboard there's only a report for TpData.ObanWorkers.DiscardTest2:

EDIT: changed from Oban.Pro.Worker to Oban.Worker with the same results

[unflxw]

Hi @jozuas, thank you for reporting this. We'll look into this issue and get back to you.

[jeffkreeftmeijer]

Hey @jozuas, thanks again for letting us know about this. I'm able to reproduce this using your instructions, and looked into this to find what's happening.

Oban starts a process for each job, and sends an event about that to the telemetry backend. We catch that event, and start our span, linked to the pid of the job. Future telemetry events, like the one that indicates that a job has raised an error, all refer to the pid, so we can look up the span in our ets table.

However, timeouts are different in that the error doesn't come from the job's process, but from the main Oban process, which prevents us from linking the event to the correct span. From what I've seen, there's no way for us to get a reference to the process again, as it's not included in the event, making us lose the context.

That leaves creating a new event with the data we do have, for which I've pushed an example implementation to the oban-timeout branch. It'd be great if you could give that a shot to see how that works while we continue testing if this is something we'd want to ship ourselves.

[jozuas]

Thanks, it sounds promising, however the oban-timeout branch does not compile:

== Compilation error in file lib/appsignal/oban.ex ==
** (MismatchedDelimiterError) mismatched delimiter found on lib/appsignal/oban.ex:164:3:
     error: unexpected reserved word: end
     │
 156 │     (@tracer.current_span() || do_oban_job_start(metadata)
     │     └ unclosed delimiter
 ...
 164 │   end
     │   └ mismatched closing delimiter (expected ")")
     │
     └─ lib/appsignal/oban.ex:164:3
    (elixir 1.18.4) lib/kernel/parallel_compiler.ex:423: anonymous fn/5 in Kernel.ParallelCompiler.spawn_workers/8

[jeffkreeftmeijer]

Sorry about that, I pushed a fix just now.

[jozuas]

I tried your branch, and it looks fixed. Are you guys planning to PR this fix to main?

[jeffkreeftmeijer]

@jozuas thanks for getting back to me on this. I've just published a new version of the integration that includes #1018, so you should be able to switch back to the releases version and have Oban timeouts reported. Please let me know if you run into any issues.