How can I see log metadata in dev?

Questions / Help
,
1

EDIT: There has been back and forth and I was impatient, operating under the assumption that I am missing something obvious and small. Turns out it wasn’t exactly that. I accepted @LostKobrakai’s comment because it showed me how exactly to configure Logger metadata at runtime, but it was @ibarch’s comment near the end that finally made it work (because apparently Logger ignores “complex” metadata so you have to either do Jason.encode!(metadata) or inspect(metadata).

I have failed the 5-minute test of finding what I need. :grimacing:

So I have this code somewhere in my app:

Logger.error("Invalid payload", payload: message)

I copied my default Logger config to config/dev.exs:

config :logger, :console,
  format: "$time $level $metadata $message\n",
  metadata: [:request_id]

So I call the function with an invalid parameter and all I see is this:

15:54:12.439 error  Invalid payload

No metadata. Tried with info just in case, same result. What should be changed?

2

The issue might be that you only including the request_id in the metadata, Logger — Logger v1.16.2 I believe thats why the payload is excluded and was one of the reason that I scraped including capturing logger in https://dbvisor.com that is leveraging telemetry and storing them in a timeseries table in your DB for easy debugging.

3

Removed the metadata part of the config, nothing changed sadly.

Also migrated the config to this:

config :logger, :default_handler, level: :all
config :logger, :default_formatter, format: "$time $level $message $metadata\n"

And again, no metadata. :confused:

To respond to the second half of your message, production logging and telemetry is yet to be decided but in the meantime I just want to see the metadata on my machine while testing.

4

I feel there must be a place that is overriding this. Did you try to print out the config like IO.inspect Application.get_env(:logger)

5

Aren’t you missing the :payload value under the metadata config option?

6

Didn’t realize metadata was strictly opt-in, OK, included it:

config :logger, :default_handler, level: :all

config :logger, :default_formatter,
  format: "$time $level $message $metadata\n",
  metadata: [:payload]

Still nothing. :confused:

7

If anybody wants to play with this before we solve it, here’s a self-contained script that demonstrates my problem (mine is called logging_playground.exs):

Mix.install(
  [],
  config: [
    logger: [
      # console: [format: "$time $level $message $metadata\n"]
      default_handler: [level: :all],
      default_formatter: [format: "$time $level $message $metadata\n", metadata: [:payload]]
    ]
  ]
)

require Logger

Logger.info("Nothing", payload: "metadata")

Then just elixir logging_playground.exs and you should see no metadata, only this:

16:33:09.216 [info] Nothing
8

It doesn’t honor the format either (it still adds the square brackets), so it doesn’t pick up on the whole config.

9

Yep, now that you mention it, quite interesting actually.

10

Weird, might be easier to just use telemetry and setup your own handler to print to the console on dev. Then you also gain way more control then Logger could give you.

11

Maybe, but I’d be hugely surprised if Elixir doesn’t cover this use case trivially. I must be having a Saturday afternoon moment here and missing something extremely obvious.

12

FWIW, I think your original problem is solved by adding :payload to the list of metadata values. I tried in a new mix project (with mix new), and the log output contained the payload as expected.

I think the Mix.install/2 version doesn’t work, because the Logger config you’re trying to set is part of the boot configuration (which is different from the compile configuration). Both can be set in config/config.exs, but I don’t know how that works with the Mix.install/2 way of configuring things. Maybe that’s just too late to influence the Logger’s boot configuration.

I’ve actually never thought about this “boot configuration” aspect of an Elixir app. So if anyone can chime in… Please do!

PS: just to be clear, this is the config that works, defined in config/config.exs:

# config/config.exs (or config/dev.exs)
config :logger, :console, # :default_handler also works
  format: "[$level] $message $metadata\n",
  metadata: [:payload]

# iex
require Logger
Logger.info("some message", payload: "some payload")

# > [info] some message payload=some payload
13

What you described is exatly the reason. The issue here is simply the chick-egg dance of starting a beam VM:

Basically all code on the beam kinda wants the the logger to be running. Therefore it is started as soon as possible by the :kernel application, which is always the first application to start on an the beam (even directly bootstrapped by the vm iirc, see https://www.youtube.com/watch?v=_AqmxltiV9I). So at that point where :kernel is starting the logger it needs to setup the default handler and its formatting. Essentially no custom code has run yet. I’m not even sure config/runtime.exs is executed early enough in an release startup to configure the logger.

Therefore setting configuration with Mix.install doesn’t help. At that point the default handler is already running and configured from the app env. One would need to use the runtime APIs to adjust the formatter config, as there’s no code watching the app env for changes.

:logger.update_formatter_config(:default, %{metadata: [:payload, :application]})

(use :livebook_gl_handler instead of :default in livebook)

3 Likes
14

Alright, the mystery is not entirely solved.

This is my config/dev.exs (I swapped the place of $message and $metadata btw):

config :logger, :default_handler, level: :all

config :logger, :default_formatter,
  format: "$time $level $metadata $message\n",
  metadata: [:payload]

Indeed I can just do this in iex now:

iex(1)> require Logger
Logger
iex(2)> Logger.error("play", payload: "stuff")
22:15:33.804 error payload=stuff  play
:ok

But from within one of my modules I still can’t make it work (the format is respected btw, no more square brackets etc. but no metadata). Any suggestions? I should probably start by IO.inspect-ing Logger.metadata(), I suppose.

15

Logger.metadata() is an empty list btw – [].

16

There is not much to inspect, I’m afraid. Whatever you pass in as a keyword list with the Logger call will be in your metadata.

Is this a Phoenix app? Are you running with mix, and is your mix-env set to dev?

Does it behave differently when you call that module function from iex, as opposed to from within your application?

Running :logger.get_config() reveals the current config. Somewhere in that datastructure I find the metadata and format keys, which should reflect your config.

17

That’s to be expected. You can add metadata that is associated with the current process, using Logger.metadata/1. Whatever you pass in with Logger.error/2 as a second parameter will add to that metadata. But that “base” metadata can be anything, and by default is probably rightfully so an empty list.

1 Like
18

Hrm, I just used @LostKobrakai’s recommendation and put this in my application.ex after loading config. We have a bespoke mechanism of loading stuff and it’s heavily dependent on the way we deploy apps so that was probably the reason. And one I admit I don’t care much to pursue.

So for posterity for both of you and future readers, do this if you have my problem:

defmodule YourApp.Application do
  use Application
  require Logger

  @impl Application
  def start(_type, _args) do
    config = load_config() # our custom stuff.

+    :logger.update_formatter_config(:default, %{metadata: [:payload, :application]})

    children = [
      # The app's children go here.
    ]

    opts = [strategy: :one_for_one, name: Facteur.Supervisor]
    Supervisor.start_link(children, opts)
  end
end

And you are on your merry way. (Obviously replace [:payload, :application] with whatever metadata you want to be able to pass to your Logger and for it to be visible.)

EDIT: spoke too soon, read below.

19

Yes and yes.

Yeah, I was just wondering if some of the app’s dependencies doesn’t do something under the hood is all. Turns out they don’t.

20

OK I am definitely having a Saturday moment and spoke too soon without scanning properly. The application key got printed, the payload thing didn’t. :003:

Still leaving @LostKobrakai’s comment as the solution since it achieved partial success but the search goes on.

1 Like