trace_id is not logged

[samsondav]

I have the correct config for my logger:

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

But the trace_id is not being logged:

Oct 23 15:51:51 dc1-live-appserver2 eggl[30255]: 15:51:51.298 request_id=iahoj1li85bhul2kf16m54lqsd11000p viewer_id=788210 span_id=4174
988920911713992 [info] QUERY OK source="valuations" db=1.5ms queue=0.1ms

[zachdaniel]

I think this is missing in the documentation

  config :my_app, MyApp.Repo,
    loggers: [{Ecto.LogEntry, :log, [:info]}, {Spandex.Ecto.Trace, :trace, []}]

[zachdaniel]

Have you configured your ecto repo like so?

[samsondav]

I have that in my config already. It's nothing to do with Ecto-specific logging, this occurs on all trace logging. For example:

Oct 26 06:13:30 dc1-live-appserver1 eggl[26638]: 06:13:30.463 request_id=vrm4nlsve7oj89tmt0itge96p9g1cjjh viewer_id=1290838 span_id=8168473195267214966 [debug
] ABSINTHE schema=nil variables=%{}

[zachdaniel]

Interesting. I look at your format configuration and I'm surprised to see even the span_id showing up in logs. Try removing the format configuration.

[samsondav]

@zachdaniel I removed the format string, same result.

All the rest of the metadata is working fine - it's only the trace_id that is missing.

[zachdaniel]

Okay, I think I may need more information to properly debug this then. Can I see your spandex configuration? Also, are your traces being sent to datadog correctly?

[samsondav]

Traces are being sent to datadog correctly. Here is my spandex configuration:

config :spandex,
  service: :elixir, # required, default service name
  adapter: Spandex.Adapters.Datadog, # required
  disabled?: {:system, "DISABLE_SPANDEX", false},
  env: {:system, "RELEASE_LEVEL", "mix:#{Mix.env}"},
  # application: :core,
  ignored_methods: ["OPTIONS"],
  ignored_routes: [~r|\A/status\z|],
  log_traces?: false # You probably don't want this to be on. This is helpful for debugging though.

config :spandex, :datadog,
  api_adapter: Spandex.Datadog.ApiServer, # Traces will get sent in background
  host: {:system, "DATADOG_HOST", "localhost"},
  port: {:system, "DATADOG_PORT", 8126},
  services: [ # for defaults mapping in spans service => type
    ecto: :db,
    elixir: :web,
    closeio: :http,
    rested: :web,
    data_service: :http,
    auth: :http,
    postcode_anywhere: :http,
    geocoder: :http
  ]

[zachdaniel]

I think your config for logger must be getting overriden somewhere. The way your format is set to "$time $metadata[$level] $message\n" means you shouldn't be seeing even span_id. Are you perhaps overriding your log format in an environment specific config?

[samsondav]

Nope, nothing is being overridden. Here is the current configuration:

> Application.get_env(:logger, :console)
[metadata: [:request_id, :viewer_id, :trace_id, :span_id]]

Incidentally the default message format is: \n$time $metadata[$level] $levelpad$message\n"

See: https://github.com/elixir-lang/elixir/blob/master/lib/logger/lib/logger.ex#L206

Here is my repo config:

config :properties_db, PropertiesDB.Repo,
  migration_source: "ecto_schema_migrations",
  loggers: [{Ecto.LogEntry, :log, [:info]}, {Spandex.Ecto.Trace, :trace, []}] # Trace with spandex

Here is an example output from ecto:

Oct 31 06:25:23 dc1-live-appserver2 eggl[17996]: 06:25:23.939 request_id=m834kd3ug1q03rupejr2bdnnl1vd76un viewer_id=1321076 span_id=4793383928018839571 [info] QUERY OK source="valuations" db=5.5ms

Here is an example output from Absinthe (inside Phoenix with plug Spandex.Plug.StartTrace).

Oct 31 06:25:30 dc1-live-appserver2 eggl[17996]: 06:25:30.245 request_id=o1g2u8vk59c6iehhtv38aneo5vfti5ta viewer_id=1321077 span_id=1112471628734059966 [debug] ABSINTHE schema=nil variables=%{}

Note that trace_id is the only metadata absent from both.

[zachdaniel]

This is very confusing :/. Have you tried altering the format? For instance adding $metadata[trace_id] somewhere in the format string? I'm really not sure what's going on otherwise.

[samsondav]

I think you are misunderstanding how the logger format string works. $metadata always logs all metadata regardless of what follows. It is not an access lookup. $metadata[$level] for example logs the metadata and then a space and then the level.

[samsondav]

So here all the metadata is being logged. But the trace_id has not been set even though the span_id has.

[zachdaniel]

Ah, yeah I definitely was misunderstanding the logger formatting. We use a custom JSON formatter so I haven't thought about it for a while. I also just realized that were not on the most recent version of spandex ourselves, so I've been looking for an issue in your implementation when it may just as well be an issue in some of the newer code. I'll take a look at the new stuff soon.

[asummers]

Is plug Spandex.Plug.StartTrace in your endpoint.ex or routes file somewhere? This calls Spandex.start_trace("request") which sets the trace_id in the metadata. If so, something down that path is failing for some reason.

[samsondav]

The trace_id IS being correctly set, since I can see it in the DataDog panel.

It simply isn't being added to the logger metadata.

[zachdaniel]

I have just been so busy lately, I'm sorry I haven't looked at this. It's still on my radar, along with various other improvements. I really need to sit down with it. Need to do some load testing as well. I will definitely address this this week.

[zachdaniel]

@samphilipd If you upgrade to 1.1.2 the trace_id should be present. Apologies for the long turnaround time.

[samsondav]

Hooray! Thank you @zachdaniel