Questions: How does Logger metadata works?

Metadata

Adds the given keyword list to the current process metadata.

  • How exactly does it work? Two examples in specific would be nice:
    • plug app: i.e. if I set metadata at the beginning of request in one of the plugs, and log something further on within the main app or lets say ecto, will I have this metadata there?
    • OTP app: I set metadata in core app, and ecto logs something, will it have this metadata as well?
    • when it wouldn’t work?
  • when it’s being cleaned up?

Logger.Backends.Console

You can set metadata via Logger.metadata() and add more of it with Logger.info("msg", [meta: :data]) - how does it behave in backend? Is it merged? or can I access them separately?

Why is there so much magic in log_event? wouldn’t it be enough to have IO.puts? If no then should I do exactly the same while building another logger backend?

node(gl) != node() what’s the purpose here?

Btw. it’s quite difficult to navigate through this “example” backend impelemntation, especially when it’s not documented. It would be way easier to have some kind of documented template why required and optional stuff in it.

Best,
Leszek

After digging more into git blame, issues, pull requests and code I found out that:

  • PR#4720 send msg directly to device to improve performance
  • PR#4728 batch IO and unicode error handling, this actually explains a lot the whole async/await/handle reply io stuff

Maybe it actually makes sense to extract this logic to a separate module, so other backends sending stuff to console (or actually any other IO device, i.e. files) could leverage as well?

This raises the question: what is :user process? I somehow can’t find anything in the elxir code aboout it, is it something from Erlang land and can’t we assume we always have it?

/cc @josevalim I assume You could be really helpful here, if you would find a sec :wink:

I am not sure how exactly to extract that. Because it requires passing state around, you would still need to receive the messages and put them in the buffer. Maybe a Buffer data structure is what we need but I doubt it would transparently solve the problem.

The other option is to have a process that does the batching for you. It wouldn’t be useful for the Logger, because in this case we already have the Logger process, but it could be used for general batching for any party interested. pobox provides such solution.

It comes from Erlang. It is the process responsible for doing IO. There is a very detailed explanation here.

Whenever you perform an IO operation, that operation is forwarded to the “group leader”. Every process has a group leader and that can be configured. For example, Phoenix Code Reloader uses the group leader to proxy all the output that happens during compilation so it can also show compilation errors in your browser.

By default, the group leader process is the user process:

$ elixir -e "IO.inspect {Process.group_leader, Process.whereis(:user)}"
{#PID<0.24.0>, #PID<0.24.0>}

However, when you start IEx, the group leader is no longer the user process. That’s because IEx wants to have full control when your sessions output to the shell. Let’s see it:

$ iex
Erlang/OTP 18 [erts-7.1] [source] [64-bit] [smp:4:4] [async-threads:10] [hipe] [kernel-poll:false] [dtrace]

Interactive Elixir (1.4.0-dev) - press Ctrl+C to exit (type h() ENTER for help)
iex(1)> {Process.group_leader, Process.whereis(:user)}
{#PID<0.26.0>, #PID<0.25.0>}

To see why this matters, let’s start another IEx session and have it print hello and over again:

iex(1)> Stream.interval(1000) |> Stream.each(fn _ -> IO.puts "hello" end) |> Stream.run
{:ok, #PID<0.58.0>}
hello
hello
hello
iex(2)>
User switch command (Ctrl+G)
 --> s 'Elixir.IEx'
 --> c
Interactive Elixir (1.4.0-dev) - press Ctrl+C to exit (type h() ENTER for help)
iex(1)> Process.group_leader
#PID<0.58.0>

Notice that, after we hit Ctrl+G, we started a new shell, connected to it and we no longer see “hello” printed. That’s because the previous shell is writing to its own group leader, which is now being silenced, and the new shell got a new one.

However, if you rewrite the previous example to write to IO.puts(:user, "hello"), then it will output to whatever shell you are connected to. Let’s try it:

iex(1)> Stream.interval(1000) |> Stream.each(fn _ -> IO.puts :user, "hello" end) |> Stream.run
hello
hello

User switch command (Ctrl+G)
 --> s 'Elixir.IEx'
 --> c
hello
Interactive Elixir (1.4.0-dev) - press Ctrl+C to exit (type h() ENTER for help)
iex(1)> hello
hello
hello
hello

In other words, the :user process allows you to always write to IO, bypassing the group leader. In most cases, the group leader is the user process though, and you don’t have to care about it.

99.9% of the times you don’t need to care about the examples or concepts above, but, since you asked, you got it. :slight_smile:

1 Like

Thanks, that makes way more sense! Will need to find couple minutes to dive into the article :thumbsup:

So if I’m correct then the logger console backend is basically using IO.write :user, msg?

Besides that any ideas about the metadata or some articles that would explain how it works?

Best,
Leszek

1 Like