add trace ctx to logger metadata when attached to pdict context

[tsloughter]

No description provided.

[codecov]

Codecov Report

Merging #394 (1ec99c9) into main (2964d0b) will increase coverage by 0.16%.
The diff coverage is 100.00%.

❗ Current head 1ec99c9 differs from pull request most recent head a6b8976. Consider uploading reports for the commit a6b8976 to get more accurate results

@@            Coverage Diff             @@
##             main     #394      +/-   ##
==========================================
+ Coverage   73.18%   73.34%   +0.16%     
==========================================
  Files          53       53              
  Lines        1656     1666      +10     
==========================================
+ Hits         1212     1222      +10     
  Misses        444      444              

Flag	Coverage Δ
api	69.10% <100.00%> (+0.51%)	⬆️
elixir	18.86% <100.00%> (+1.34%)	⬆️
erlang	74.76% <100.00%> (+0.15%)	⬆️
exporter	73.59% <ø> (ø)
sdk	78.09% <ø> (ø)
zipkin	53.84% <ø> (ø)

Flags with carried forward coverage won't be shown. Click here to find out more.

Impacted Files	Coverage Δ
apps/opentelemetry_api/src/otel_ctx.erl	59.37% <100.00%> (+4.20%)	⬆️
apps/opentelemetry_api/src/otel_span.erl	76.54% <100.00%> (+0.90%)	⬆️
apps/opentelemetry_api/src/otel_tracer.erl	69.56% <100.00%> (+6.40%)	⬆️

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 2964d0b...a6b8976. Read the comment docs.

[tsloughter]

Still needs to show an example to at least make clear that you use a list of atoms to access the subkeys in logger formatter: [otel_span_ctx, trace_id].

But maybe this is good enough aside from stuff like that I'll do before we merge.

[bryannaegele]

@tsloughter we also need to clear it from metadata on detach

[tsloughter]

@bryannaegele woop, good catch, I made sure setting to undefined worked but forgot about detach :)

[tsloughter]

Updated. Also updated the changelog.

[btkostner]

Coming back from the original discussion, I have deployed this to a staging Elixir project and can confirm trace metadata lines up with logs.

[tsloughter]

@btkostner thanks! Would you be willing to give a simple example of your logger config for adding the metadata to your logs?

[btkostner]

@tsloughter So this is an Elixir project sending data to Datadog. For the logger backend, we've been using https://github.com/Nebo15/logger_json with the DatadogLogger formatter. Configuration looks like so:

# config.exs
config :logger,
  backends: [LoggerJSON],
  level: :info

config :logger_json, :backend,
  formatter: LoggerJSON.Formatters.DatadogLogger,
  metadata: :all

And then we use a custom plug to log Phoenix requests in a single output like so:

# endpoint.ex
plug Plug.RequestId
plug Plug.Telemetry, event_prefix: [:phoenix, :endpoint]

plug LoggerJSON.Plug, metadata_formatter: LoggerJSON.Plug.MetadataFormatters.DatadogLogger

The plug needs to come after Plug.Telemetry for the correct trace data, else it will be empty. And outputs logs like so:

{
  "domain": ["elixir"],
  "duration": 5597270,
  "erl_level": "info",
  "http": {
    "url": "http://localhost/_health",
    "status_code": 200,
    "method": "GET",
    "referer": null,
    "request_id": "FvLDEr8jXx2K9E8AAAAB",
    "useragent": "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/102.0.0.0 Safari/537.36",
    "url_details": {
      "host": "localhost",
      "port": 4000,
      "path": "/_health",
      "queryString": "",
      "scheme": "http"
    }
  },
  "logger": {
    "thread_name": "#PID<0.616.0>",
    "method_name": "Elixir.LoggerJSON.Plug.call/2",
    "file_name": "lib/logger_json/plug.ex",
    "line": 44
  },
  "message": "",
  "network": {
    "client": {
      "ip": "127.0.0.1"
    }
  },
  "otel_span_ctx": {
    "span_id": "cd0375b7305d668e",
    "trace_flags": "01",
    "trace_id": "228ad09ba553e60b365a7485f107d9bb"
  },
  "phoenix": {
    "controller": "Elixir.HealthcheckAggregatorWeb.HealthController",
    "action": "index"
  },
  "request_id": "FvLDEr8jXx2K9E8AAAAB",
  "syslog": {
    "hostname": "Caprica",
    "severity": "info",
    "timestamp": "2022-05-26T14:54:58.495Z"
  }
}

Datadog has a weird formatting issue between otel and internal datadog ids (https://docs.datadoghq.com/tracing/connect_logs_and_traces/opentelemetry/) but I don't consider that an issue here. It's a Datadog feature / support issue.

Fighting a bit with a more native setup (standard Phoenix project, console logger config, and plugs), and I wasn't actually able to get it to appear. This is from a log function in the controller and Logger metadata to :all:

erl_level=info application=healthcheck_aggregator domain=elixir file=lib/healthcheck_aggregator_web/controllers/health_controller.ex function=index/2 line=7 mfa=HealthcheckAggregatorWeb.HealthController.index/2 module=HealthcheckAggregatorWeb.HealthController pid=<0.630.0> request_id=FvLDcZ_fnCVyocYAAAAU [info] testing trace data!

Tracking it down, seems that it gets ignored because it doesn't have a string implementation: https://github.com/elixir-lang/elixir/blob/main/lib/logger/lib/logger/formatter.ex#L227

[ikavgo]

would be great to see it merged. Will it work with opentelemetry_cowboy out of the box provided I will set up logger format accordingly?

[tsloughter]

Tracking it down, seems that it gets ignored because it doesn't have a string implementation: https://github.com/elixir-lang/elixir/blob/main/lib/logger/lib/logger/formatter.ex#L227

Ah, it is because the metadata is nested. Elixir's Logger must support nested metadata and it just need to be patched to work even with :all...?

[btkostner]

Sweet. Thank you @tsloughter! 🎊