opentelemetry-ruby icon indicating copy to clipboard operation
opentelemetry-ruby copied to clipboard

Unexpected behavior for log record attributes with symbols for keys

Open kaylareopelle opened this issue 11 months ago • 6 comments

When a log record attribute has a Symbol for a key, the following OpenTelemetry error log message is output: ERROR -- : OpenTelemetry error: invalid log record attribute key type Symbol on record: 'Thuja plicata with symbol attribute key' Where Thuja plicata is the log body, and :cedar is the attribute key.

The expectation is that all attribute keys are Strings. This is the same as the expectation for attributes on stable Ruby OTel signals, like Spans/SpanEvents for Traces.

Despite this warning, the attribute is passed along to the exporter anyway, and it is successfully sent over OTLP.

For example (source):

OpenTelemetry Ruby logger SDK

# Use your Logger to  emit a log record
logger.on_emit(
  timestamp: Time.now,
  severity_text: 'INFO',
  body: 'Thuja plicata with symbol attribute key',
  attributes: { cedar: true },
)

Shell output from running the code above

[4:10](https://cloud-native.slack.com/archives/C01NWKKMKMY/p1734307839893059?thread_ts=1734228402.085199&cid=C01NWKKMKMY)
$ pwd
/Users/wsmoak/Projects/opentelemetry-ruby/examples/logs_sdk
wsmoak logs_sdk $ ruby logs_otlp.rb
Resolving dependencies...
Fetching gem metadata from https://rubygems.org/..
E, [2024-12-15T19:10:02.812695 #81798] ERROR -- : OpenTelemetry error: invalid log record attribute key type Symbol on record: 'Thuja plicata with symbol attribute key'

Collector output from running the code above

$ cat collector-output.txt | grep -3 Thuja
--
Timestamp: 2024-12-16 00:10:02.81267 +0000 UTC
SeverityText: INFO
SeverityNumber: Unspecified(0)
Body: Str(Thuja plicata with symbol attribute key)
Attributes:
     -> cedar: Bool(true)
Trace ID:

Questions / Next Steps

  1. Why are symbols forbidden as keys on trace-related attributes?
  2. Should this reasoning extend to logs?
  3. If the reasoning should extend to logs, update the code to reject attributes with symbols as keys and update the error message to state that strings are required
  4. If the reasoning should not extend to logs, remove the error message

kaylareopelle avatar Dec 16 '24 19:12 kaylareopelle

Notes from SIG:

  1. Symbols for keys: A lot of this has to do with the spec, ultimately, using a frozen string as a key ends up being more efficient; converting a symbol to a string will create garbage for all those conversions, whereas if you have a frozen string to begin with, you don't need to convert; so no garbage is created.

If that can be disproven, then we could have a discussion around allowing Symbols; this is already working and could be more natural for Rubyists.

By allowing Symbols, we may be enabling users to make OpenTelemetry less efficient

kaylareopelle avatar Dec 17 '24 17:12 kaylareopelle

👋 This issue has been marked as stale because it has been open with no activity. You can: comment on the issue or remove the stale label to hold stale off for a while, add the keep label to hold stale off permanently, or do nothing. If you do nothing this issue will be closed eventually by the stale bot.

github-actions[bot] avatar Jan 17 '25 01:01 github-actions[bot]

👋 This issue has been marked as stale because it has been open with no activity. You can: comment on the issue or remove the stale label to hold stale off for a while, add the keep label to hold stale off permanently, or do nothing. If you do nothing this issue will be closed eventually by the stale bot.

github-actions[bot] avatar Feb 16 '25 02:02 github-actions[bot]

Comparing behavior on other signals, spans will have attributes with invalid names or values removed from the attribute collection during finish(). The span is still exported, but without the attributes that didn't conform to spec.

We could opt to match that behavior in LogRecord, maybe in trim_attributes().

The ERROR message generated currently could be a WARN about how the invalid attribute was removed from the log record (or span) before sending and tell the reader—at least for keys—that they should provide a string instead. The ERROR message is currently generated with a call to OpenTelemetry.handle_error() which only logs an ERROR. We might be able to call OpenTelemetry.logger.warn() more directly.

robbkidd avatar Mar 11 '25 21:03 robbkidd

Hi @robbkidd, I think those are great suggestions. I made some changes in #1825 to use a WARN log instead of handle_error. This would make the logs behavior different from span behavior, but if it's more helpful to users, I'm all for making the change.

kaylareopelle avatar Mar 11 '25 22:03 kaylareopelle

👋 This issue has been marked as stale because it has been open with no activity. You can: comment on the issue or remove the stale label to hold stale off for a while, add the keep label to hold stale off permanently, or do nothing. If you do nothing this issue will be closed eventually by the stale bot.

github-actions[bot] avatar Apr 11 '25 02:04 github-actions[bot]

After https://github.com/reidmorrison/semantic_logger/pull/292 was added, I was trying to resolve the remaining issue in https://github.com/reidmorrison/semantic_logger/pull/319. Maybe you can use this as an idea.

viktorianer avatar Aug 27 '25 12:08 viktorianer

I ran into this again today, the log says error, invalid, dropping ... but it does not actually drop the attribute. If the behavior is staying the same, then it should only be a warning.

But it looks like in #1825 the decision was to keep it as an error.

Was there a decision on actually dropping the attributes, or is the current behavior going to stay? (In which case it can be documented somewhere and this can be closed.)

wsmoak avatar Oct 04 '25 16:10 wsmoak