When logging, metadata related to span is missing

[gmile]

Hi!

What's the current recommended approach to set the Logger metadata in a way that it actually shows up on calls to Logger macros, such as Logger.info/2?

Today, when calling Logger.info/2 or other macros from the Logger module in Elixir, the keys :otel_span_id, :otel_trace_flags, and :otel_trace_id are missing. However, these keys and respective values are present in the output of Logger.metadata/0. I suspect this is due to:

1. :otel_span_id, :otel_trace_flags, and :otel_trace_id - all pointing to values that are character lists,
2. list of allowed types of values in Logger's metadata does not contain characters lists.

Here's a script to reproduce what I am talking about

Mix.install([:opentelemetry],
  config: [
    logger: [
      default_formatter: [
        format: "$time $metadata[$level] $message\n",
        metadata: [:user_id, :otel_span_id, :otel_trace_flags, :otel_trace_id]
      ]
    ],
  ],
  start_applications: false
)

Application.stop(:logger)
Application.start(:logger)

defmodule Reproduce do
  require Logger
  require OpenTelemetry.Tracer

  def run do
    IO.inspect(Logger.metadata(), label: "Initial logger metadata")

    Logger.metadata(%{user_id: "some-user-id"})
    IO.inspect(Logger.metadata(), label: "Logger metadata after setting user_id")

    OpenTelemetry.Tracer.with_span("my-span") do; :ok end
    IO.inspect(Logger.metadata(), label: "Logger metadata after calling OpenTelemetry.Tracer.with_span/2")

    Logger.info("No otel_* metadata shows up here")

    # Fix/workaround: converting charlists to strings, manually
    #
    metadata = Logger.metadata()
    Logger.metadata(%{
      otel_span_id: to_string(metadata[:otel_span_id]),
      otel_trace_flags: to_string(metadata[:otel_trace_flags]),
      otel_trace_id: to_string(metadata[:otel_trace_id])
    })

    Logger.info("Finally, metadata shows up here")
  end
end

Reproduce.run()

The output:

Initial logger metadata: []
Logger metadata after setting user_id: [user_id: "some-user-id"]
Logger metadata after calling OpenTelemetry.Tracer.with_span/2: [
  user_id: "some-user-id",
  otel_span_id: ~c"0000000000000000",
  otel_trace_flags: ~c"00",
  otel_trace_id: ~c"00000000000000000000000000000000"
]
20:54:14.050 user_id=some-user-id [info] No otel_* metadata shows up here
20:54:14.052 user_id=some-user-id otel_span_id=0000000000000000 otel_trace_flags=00 otel_trace_id=00000000000000000000000000000000 [info] Finally, metadata shows up here

I doubt my approach with merely overriding the keys is a correct one 🤔 For context, the application I am working on is a web server. While I could, in principle, add a code like this - I just doubt that's the right way to do it:

defmodule MyApp.Endpoint do
  use Phoenix.Endpoint, otp_app: :myapp

  plug :fix_opentelemetry_metadata

  # ...various other plugs

  plug MyApp.Router

  defp fix_opentelemetry_metadata(conn, _opts) do
    metadata = Logger.metadata()

    # This should work, because the span metadata was already set some time earlier when processing the request
    Logger.metadata(%{
      otel_span_id: to_string(metadata[:otel_span_id]),
      otel_trace_flags: to_string(metadata[:otel_trace_flags]),
      otel_trace_id: to_string(metadata[:otel_trace_id])
    })

    conn
  end
end

[gmile]

I doubt my approach with merely overriding the keys is a correct one

I think I could do a less risky workaround here, and instead of overriding values of existing keys - introduce new keys. Doing so reduces the risk of breaking some code elsewhere that expects the values to be charlists:

Logger.metadata(%{
  my_otel_span_id: to_string(metadata[:otel_span_id]),
  my_otel_trace_flags: to_string(metadata[:otel_trace_flags]),
  my_otel_trace_id: to_string(metadata[:otel_trace_id])
})

Still not 100% sure if this is the right way, and judging by popularity of opentelemetry-erlang - if there shouldn't be some way where library could assist with rendering of span context info in a better way 🙈

[gmile]

Forgot to mention - I am merely interested in having the span context info in the logs, so that later I could "manually link" it to a span in Grafana like this:

datasources:
  # ...
  - name: Loki
    type: loki
    access: proxy
    url: http://loki:3100
    version: 1
    editable: false
    jsonData:
      derivedFields:
        - datasourceUid: tempo
          matcherRegex: "trace_id=(\\w+)"
          name: TraceID
          url: "$${__value.raw}"

So, this is not to be confused with opentelemetry-erlang's native support of logs in any way, which I understand is currently under development.

[tsloughter]

Oh no... if that is the case with Elixir then we need to just change to using a binary string.

[gmile]

@tsloughter btw, this is now also clarified in the Elixir documentation: elixir-lang/elixir#13977.

change to using a binary string

I'll submit a PR.