Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat: Update Logger#on_emit to create LogRecords #1611

Merged
merged 13 commits into from
Jul 25, 2024
Merged
Show file tree
Hide file tree
Changes from 6 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
37 changes: 23 additions & 14 deletions logs_api/lib/opentelemetry/logs/logger.rb
Original file line number Diff line number Diff line change
Expand Up @@ -12,36 +12,45 @@ class Logger

# Emit a {LogRecord} to the processing pipeline.
#
# @param timestamp [optional Float, Time] Time in nanoseconds since Unix
# @param [optional Float, Time] timestamp Time in nanoseconds since Unix
# epoch when the event occurred measured by the origin clock, i.e. the
# time at the source.
# @param observed_timestamp [optional Float, Time] Time in nanoseconds
# @param [optional Float, Time] observed_timestamp Time in nanoseconds
# since Unix epoch when the event was observed by the collection system.
# Intended default: Process.clock_gettime(Process::CLOCK_REALTIME)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The units are unclear here. If we accept nanoseconds, I'd expect that to be Integer rather than Float, and if we accept Time, then the units are not relevant. IMO we should only accept Time, and we should convert that to "Integer nanoseconds since Epoch" internally.

Related: documenting the Process.clock_gettime(Process::CLOCK_REALTIME) as the default increases confusion about the units (and precision).

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Great points, I agree. Addressed here: #1611 (comment)

# @param context [optional Context] The Context to associate with the
# LogRecord. Intended default: OpenTelemetry::Context.current
# @param severity_number [optional Integer] Numerical value of the
# @param [optional Integer] severity_number Numerical value of the
# severity. Smaller numerical values correspond to less severe events
# (such as debug events), larger numerical values correspond to more
# severe events (such as errors and critical events).
# @param severity_text [optional String] Original string representation of
# @param [optional String] severity_text Original string representation of
# the severity as it is known at the source. Also known as log level.
# @param body [optional String, Numeric, Boolean, Array<String, Numeric,
# @param [optional String, Numeric, Boolean, Array<String, Numeric,
# Boolean>, Hash{String => String, Numeric, Boolean, Array<String,
# Numeric, Boolean>}] A value containing the body of the log record.
# @param attributes [optional Hash{String => String, Numeric, Boolean,
# Array<String, Numeric, Boolean>}] Additional information about the
# event.
# Numeric, Boolean>}] body A value containing the body of the log record.
# @param [optional String] trace_id The trace ID associated with the
# current context.
# @param [optional String] span_id The span ID associated with the
# current context.
# @param [optional TraceFlags] trace_flags The trace flags associated
# with the current context.
# @param [optional Hash{String => String, Numeric, Boolean,
# Array<String, Numeric, Boolean>}] attributes Additional information
# about the event.
# @param [optional Context] context The Context to associate with the
# LogRecord. Intended default: OpenTelemetry::Context.current
#
# @api public
def emit(
def on_emit(
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

When we renamed the method in #1517, I forgot to go back and change the references in the API.

timestamp: nil,
observed_timestamp: nil,
context: nil,
severity_number: nil,
severity_text: nil,
body: nil,
attributes: nil
trace_id: nil,
span_id: nil,
trace_flags: nil,
attributes: nil,
context: nil
)
end
# rubocop:enable Style/EmptyMethod
Expand Down
2 changes: 1 addition & 1 deletion logs_api/test/opentelemetry/logs/logger_test.rb
Original file line number Diff line number Diff line change
Expand Up @@ -11,7 +11,7 @@

describe '#emit' do
it 'returns nil, as it is a no-op method' do
assert_nil(logger.emit)
assert_nil(logger.on_emit)
end
end
end
2 changes: 2 additions & 0 deletions logs_sdk/lib/opentelemetry/sdk/logs.rb
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,8 @@
require_relative 'logs/version'
require_relative 'logs/logger'
require_relative 'logs/logger_provider'
require_relative 'logs/log_record'
require_relative 'logs/log_record_data'
require_relative 'logs/log_record_processor'
require_relative 'logs/export'

Expand Down
99 changes: 99 additions & 0 deletions logs_sdk/lib/opentelemetry/sdk/logs/log_record.rb
Original file line number Diff line number Diff line change
@@ -0,0 +1,99 @@
# frozen_string_literal: true

# Copyright The OpenTelemetry Authors
#
# SPDX-License-Identifier: Apache-2.0

module OpenTelemetry
module SDK
module Logs
# Implementation of OpenTelemetry::Logs::LogRecord that records log events.
class LogRecord < OpenTelemetry::Logs::LogRecord
attr_accessor :timestamp,
:observed_timestamp,
:span_context,
:severity_text,
:severity_number,
:body,
:attributes,
:trace_id,
:span_id,
:trace_flags,
:resource,
:instrumentation_scope

# Creates a new {LogRecord}.
#
# @param [optional Float, Time] timestamp Time when the event occurred.
# @param [optional Float, Time] observed_timestamp Time when the event
# was observed by the collection system. If nil, will first attempt
# to set to `timestamp`. If `timestamp` is nil, will set to
# `Process.clock_gettime(Process::CLOCK_REALTIME, :nanosecond)`.
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why do these accept Float? They should only accept Time, like corresponding methods in the tracing API. This makes it easier to ensure the correctness of conversion to "Integer nanoseconds since Epoch" internally, and reduces confusion about the units.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I got a little too overzealous when trying to adhere to the spec. The datatype in the Logs Data Model was listed as "Type: Timestamp, uint64 nanoseconds since Unix epoch." Since the timestamp could be efficiently accessed using Process.clock_gettime(Process::CLOCK_REALTIME, :nanosecond), I decided to add it and make it the default.

Based on these questions, I decided to remove the Float option, go all in on the Time object and transform it into a nanosecond Integer in LogRecord#to_log_record_data.

Fixes across two commits:

# @param [optional String] severity_text The log severity, also known as
# log level.
# @param [optional Integer] severity_number The numerical value of the
# log severity.
# @param [optional String, Numeric, Boolean, Array<String, Numeric,
# Boolean>, Hash{String => String, Numeric, Boolean, Array<String,
# Numeric, Boolean>}] body The body of the {LogRecord}.
# @param [optional Hash{String => String, Numeric, Boolean,
# Array<String, Numeric, Boolean>}] attributes Attributes to associate
# with the {LogRecord}.
# @param [optional String] trace_id The trace ID associated with the
# current context.
# @param [optional String] span_id The span ID associated with the
# current context.
# @param [optional TraceFlags] trace_flags The trace flags associated
# with the current context.
# @param [optional OpenTelemetry::SDK::Logs::Logger] logger The logger that
# created the {LogRecord}. Used to set `resource` and
# `instrumentation_scope`.
#
# @return [LogRecord]
def initialize(
timestamp: nil,
observed_timestamp: nil,
severity_text: nil,
severity_number: nil,
body: nil,
attributes: nil,
trace_id: nil,
span_id: nil,
trace_flags: nil,
logger: nil
)
@timestamp = timestamp
@observed_timestamp = observed_timestamp || timestamp || Process.clock_gettime(Process::CLOCK_REALTIME, :nanosecond)
@span_context = span_context
robertlaurin marked this conversation as resolved.
Show resolved Hide resolved
@severity_text = severity_text
@severity_number = severity_number
@body = body
@attributes = attributes.nil? ? nil : Hash[attributes] # We need a mutable copy of attributes
@trace_id = trace_id
@span_id = span_id
@trace_flags = trace_flags
@resource = logger&.resource
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I know there's a method added to the sdk logger here to support this but it still reads like logger.logger_provider.resource to me.

I wonder if there's any merit in following the same pattern we did with the tracer https://github.com/open-telemetry/opentelemetry-ruby/blob/main/sdk/lib/opentelemetry/sdk/trace/tracer.rb#L35

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That's a great point, following that approach cleans up the code nicely. Fixed in ab57071

@instrumentation_scope = logger&.instrumentation_scope
kaylareopelle marked this conversation as resolved.
Show resolved Hide resolved
@total_recorded_attributes = @attributes&.size || 0
end

def to_log_record_data
LogRecordData.new(
@timestamp,
@observed_timestamp,
@severity_text,
@severity_number,
@body,
@attributes,
@trace_id,
@span_id,
@trace_flags,
@resource,
@instrumentation_scope,
@total_recorded_attributes
)
end
end
end
end
end
43 changes: 43 additions & 0 deletions logs_sdk/lib/opentelemetry/sdk/logs/log_record_data.rb
Original file line number Diff line number Diff line change
@@ -0,0 +1,43 @@
# frozen_string_literal: true

# Copyright The OpenTelemetry Authors
#
# SPDX-License-Identifier: Apache-2.0

module OpenTelemetry
module SDK
module Logs
# LogRecordData is a Struct containing {LogRecord} data for export.
LogRecordData = Struct.new(:timestamp, # optional Integer nanoseconds since Epoch
:observed_timestamp, # Integer nanoseconds since Epoch
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The timestamp and observed_timestamp are documented here to be "Integer nanoseconds since Epoch", so there should be no need for the unix_nano_timestamp and unix_nano_observed_timestamp methods below.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Great point. Fixed in 0fb4606

:severity_text, # optional String
:severity_number, # optional Integer
:body, # optional String, Numeric, Boolean, Array<String, Numeric,
# Boolean>, Hash{String => String, Numeric, Boolean,
# Array<String, Numeric, Boolean>}
:attributes, # optional Hash{String => String, Numeric, Boolean, Array<String, Numeric, Boolean>}
:trace_id, # optional String (16-byte binary)
:span_id, # optional String (8-byte binary)
:trace_flags, # optional Integer (8-bit byte of bit flags)
:resource, # optional OpenTelemetry::SDK::Resources::Resource
:instrumentation_scope, # OpenTelemetry::SDK::InstrumentationScope
:total_recorded_attributes) do # Integer
def unix_nano_timestamp
kaylareopelle marked this conversation as resolved.
Show resolved Hide resolved
if timestamp.is_a?(Time)
(timestamp.to_r * 1_000_000_000).to_i
else
timestamp
end
end

def unix_nano_observed_timestamp
if timestamp.is_a?(Time)
(timestamp.to_r * 1_000_000_000).to_i
else
timestamp
end
end
end
end
end
end
68 changes: 68 additions & 0 deletions logs_sdk/lib/opentelemetry/sdk/logs/logger.rb
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,8 @@ module SDK
module Logs
# The SDK implementation of OpenTelemetry::Logs::Logger
class Logger < OpenTelemetry::Logs::Logger
attr_reader :instrumentation_scope, :logger_provider

# @api private
#
# Returns a new {OpenTelemetry::SDK::Logs::Logger} instance. This should
Expand All @@ -25,6 +27,72 @@ def initialize(name, version, logger_provider)
@instrumentation_scope = InstrumentationScope.new(name, version)
@logger_provider = logger_provider
end

def resource
logger_provider.resource
end

# Emit a {LogRecord} to the processing pipeline.
#
# @param [optional Float, Time] timestamp Time in nanoseconds since Unix
# epoch when the event occurred measured by the origin clock, i.e. the
# time at the source.
# @param [optional Float, Time] observed_timestamp Time in nanoseconds
# since Unix epoch when the event was observed by the collection system.
# Intended default: Process.clock_gettime(Process::CLOCK_REALTIME, :nanosecond)
# @param [optional String] severity_text Original string representation of
# the severity as it is known at the source. Also known as log level.
# @param [optional Integer] severity_number Numerical value of the
# severity. Smaller numerical values correspond to less severe events
# (such as debug events), larger numerical values correspond to more
# severe events (such as errors and critical events).
# @param [optional String, Numeric, Boolean, Array<String, Numeric,
# Boolean>, Hash{String => String, Numeric, Boolean, Array<String,
# Numeric, Boolean>}] body A value containing the body of the log record.
# @param [optional Hash{String => String, Numeric, Boolean,
# Array<String, Numeric, Boolean>}] attributes Additional information
# about the event.
# @param [optional String (16-byte binary)] trace_id Request trace id as
# defined in {https://www.w3.org/TR/trace-context/#trace-id W3C Trace Context}.
# Can be set for logs that are part of request processing and have an
# assigned trace id.
# @param [optional String (8-byte binary)] span_id Span id. Can be set
# for logs that are part of a particular processing span. If span_id
# is present trace_id should also be present.
# @param [optional Integer (8-bit byte of bit flags)] trace_flags Trace
# flag as defined in {https://www.w3.org/TR/trace-context/#trace-flags W3C Trace Context}
# specification. At the time of writing the specification defines one
# flag - the SAMPLED flag.
# @param [optional OpenTelemetry::Context] context The OpenTelemetry::Context
# to associate with the {LogRecord}.
#
# @api public
def on_emit(timestamp: nil,
observed_timestamp: Process.clock_gettime(Process::CLOCK_REALTIME, :nanosecond),
severity_text: nil,
severity_number: nil,
body: nil,
attributes: nil,
trace_id: nil,
span_id: nil,
trace_flags: nil,
context: OpenTelemetry::Context.current)

current_span = OpenTelemetry::Trace.current_span(context)
span_context = current_span.context unless OpenTelemetry::Trace::Span::INVALID == current_span
log_record = LogRecord.new(timestamp: timestamp,
observed_timestamp: observed_timestamp,
severity_text: severity_text,
severity_number: severity_number,
body: body,
attributes: attributes,
trace_id: trace_id || span_context&.trace_id,
span_id: span_id || span_context&.span_id,
trace_flags: trace_flags || span_context&.trace_flags,
logger: self)

logger_provider.on_emit(log_record, context)
end
end
end
end
Expand Down
5 changes: 5 additions & 0 deletions logs_sdk/lib/opentelemetry/sdk/logs/logger_provider.rb
Original file line number Diff line number Diff line change
Expand Up @@ -120,6 +120,11 @@ def force_flush(timeout: nil)
results.max || Export::SUCCESS
end
end

# Call the on_emit methods for each log_record_processor
def on_emit(log_record, context)
@log_record_processors.each { |processor| processor.on_emit(log_record, context) }
end
end
end
end
Expand Down
Loading
Loading