Silence debug logging from Oban?

[tomtaylor]

Is there an easy way to silence the debug logging from Oban when in dev mode? I can see a lot of lines of things like:

[debug] QUERY OK db=0.2ms queue=0.3ms
SELECT pg_notify($1, $2) ["oban_gossip", "{\"count\":0,\"limit\":1,\"node\":\"tetra\",\"paused\":false,\"queue\":\"slack\"}"]
[debug] QUERY OK db=0.2ms queue=0.1ms
SELECT pg_notify($1, $2) ["oban_gossip", "{\"count\":0,\"limit\":5,\"node\":\"tetra\",\"paused\":false,\"queue\":\"mailer\"}"]
[debug] QUERY OK source="oban_jobs" db=0.2ms
UPDATE "oban_jobs" AS o0 SET "state" = $1, "attempted_at" = $2, "attempt" = o0."attempt" + $3 FROM (SELECT o0."id" AS "id", pg_try_advisory_lock_shared('oban_jobs'::regclass::oid::int, oban_wrap_id(o0."id")) AS "lock" FROM "oban_jobs" AS o0 WHERE (o0."state" = 'available') AND (o0."queue" = $4) AND (o0."scheduled_at" <= $5) ORDER BY o0."scheduled_at", o0."id" LIMIT $6 FOR UPDATE SKIP LOCKED) AS s1 WHERE (o0."id" = s1."id") RETURNING o0."id", o0."state", o0."queue", o0."worker", o0."args", o0."errors", o0."attempt", o0."max_attempts", o0."attempted_at", o0."completed_at", o0."inserted_at", o0."scheduled_at" ["executing", ~U[2019-07-01 10:03:38.769207Z], 1, "mailer", ~U[2019-07-01 10:03:38.769196Z], 5]
[debug] QUERY OK source="oban_jobs" db=0.3ms
UPDATE "oban_jobs" AS o0 SET "state" = $1, "attempted_at" = $2, "attempt" = o0."attempt" + $3 FROM (SELECT o0."id" AS "id", pg_try_advisory_lock_shared('oban_jobs'::regclass::oid::int, oban_wrap_id(o0."id")) AS "lock" FROM "oban_jobs" AS o0 WHERE (o0."state" = 'available') AND (o0."queue" = $4) AND (o0."scheduled_at" <= $5) ORDER BY o0."scheduled_at", o0."id" LIMIT $6 FOR UPDATE SKIP LOCKED) AS s1 WHERE (o0."id" = s1."id") RETURNING o0."id", o0."state", o0."queue", o0."worker", o0."args", o0."errors", o0."attempt", o0."max_attempts", o0."attempted_at", o0."completed_at", o0."inserted_at", o0."scheduled_at" ["executing", ~U[2019-07-01 10:03:38.769157Z], 1, "slack", ~U[2019-07-01 10:03:38.769147Z], 1]
[debug] QUERY OK source="oban_jobs" db=0.3ms queue=0.1ms
UPDATE "oban_jobs" AS o0 SET "state" = $1 WHERE (o0."state" IN ('scheduled','retryable')) AND (o0."queue" = $2) AND (o0."scheduled_at" <= $3) ["available", "mailer", ~U[2019-07-01 10:03:38.814383Z]]
[debug] QUERY OK source="oban_jobs" db=0.4ms
UPDATE "oban_jobs" AS o0 SET "state" = $1 WHERE (o0."state" IN ('scheduled','retryable')) AND (o0."queue" = $2) AND (o0."scheduled_at" <= $3) ["available", "default", ~U[2019-07-01 10:03:38.814252Z]]
[debug] QUERY OK source="oban_jobs" db=0.7ms
UPDATE "oban_jobs" AS o0 SET "state" = $1 WHERE (o0."state" IN ('scheduled','retryable')) AND (o0."queue" = $2) AND (o0."scheduled_at" <= $3) ["available", "slack", ~U[2019-07-01 10:03:38.814226Z]]

It'd be really great to be able to silence this, so I can see the debug logging coming from my application, when in dev mode.

[sorentwo]

@tomtaylor Great suggestion. This is something that I've found annoying as well. Typically I would set the overall log level to :info, but that isn't always desirable during development.

With the changes in b127e73 you can now setverbose: false in your top level configuration and the queries won't be logged at all. Please give it a try and let me know how it goes for you 👍

[tomtaylor]

@sorentwo brilliant, thank you!

[andykent]

Just a quick note to say I just hit this too, was about to create an issue and noticed these changes on master. I just tried it out and it solved things for me 100% so thanks so much for all your hard work.

[sorentwo]

@andykent Glad you found this issue and that it is working out for you. Thank you so much for the kind words as well! 💛

[lpil]

Hi all! Just thought I'd share that Elixir's logger has the per-application log purging built in, so you can do this with any library without having to add additional logic to the library itself.

https://hexdocs.pm/logger/Logger.html#module-application-configuration

config :logger,
  compile_time_purge_matching: [
    [application: :foo, level_lower_than: :info]
  ]

[andykent]

Oh awesome! That’s really nice.

Thanks for taking the time to show that @lpil

[hisapy]

Hi @sorentwo

I'm having a similar issue here on 1.2.0, in my case every ~1 second in my dev console I'm getting the following

[debug] QUERY OK db=1.7ms
commit []
[debug] QUERY OK db=1.7ms
commit []
[debug] QUERY OK db=0.2ms
begin []
[debug] QUERY OK db=0.2ms
begin []
[debug] QUERY OK db=1.6ms
commit []

Tried verbose: false but didn't work ... Is there a way I can turn off those messages so I can keep on using my IEx?

Sorry if I had to create a new issue instead of replying in a closed one and thank you very much for his awesome lib.

[sorentwo]

Hi all! Just thought I'd share that Elixir's logger has the per-application log purging built in, so you can do this with any library without having to add additional logic to the library itself.

Somehow I never saw this comment before! I would have mentioned that Oban isn't the application doing the logging, it is all coming from Ecto itself.

Tried verbose: false but didn't work ... Is there a way I can turn off those messages so I can keep on using my IEx?

That's strange. There are only three uses of transactions in Oban and all three of them are setting the log option. Are you sure this is from Oban? Does it continue if you set queues: false?

[hisapy]

When I set queues: false it stops.

[sorentwo]

When I set queues: false it stops.

Interesting. I wonder if this is from the connection checkout. Can you try using master and see if it persists?

[hisapy]

Sorry for taking too long to respond. I just installed from master branch and when started my app got the following error:

[error] GenServer Oban.Queue.AchDebits.Producer terminating
** (UndefinedFunctionError) function Payments.Repo.default_options/1 is undefined or private
    (payments 0.1.0) Payments.Repo.default_options(:update_all)
    (ecto 3.4.2) lib/ecto/repo/queryable.ex:203: Ecto.Repo.Queryable.prepare_query/4
    (ecto 3.4.2) lib/ecto/repo/queryable.ex:174: Ecto.Repo.Queryable.execute/4
    (oban 1.2.0) lib/oban/query.ex:113: Oban.Query.rescue_orphaned_jobs/2
    (oban 1.2.0) lib/oban/queue/producer.ex:196: Oban.Queue.Producer.rescue_orphans/1
    (oban 1.2.0) lib/oban/queue/producer.ex:65: Oban.Queue.Producer.handle_continue/2
    (stdlib 3.11) gen_server.erl:637: :gen_server.try_dispatch/4
    (stdlib 3.11) gen_server.erl:388: :gen_server.loop/7
    (stdlib 3.11) proc_lib.erl:249: :proc_lib.init_p_do_apply/3

Going to look for that default_options function but let me know if you have a quick answer.

[sorentwo]

It seems like you have something in your app that is modifying queries before they are sent. Maybe a prepare_query callback? That may be overriding the log setting that Oban is passing.

[hisapy]

No, this app is very tiny yet. It's actually starting so there's not much going on.

EDIT: ExAudit is being used and in fact it replaces the Ecto.Repo so maybe the problem is coming from there. Let me see.

[hisapy]

I fixed the problem in ExAudit in this PR

Thx and stay safe devs.

[sorentwo]

Thanks @hisapy!

[LannyBose]

Just FYI in case someone ends up here via the Google, verbose: false is no longer current. Since July 2020, log: false is the correct config, based on this commit.