-
Notifications
You must be signed in to change notification settings - Fork 657
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
Add OTLPHandler for standard library logging module #1903
Changes from all commits
43c79ae
b88bb2a
8a071fe
a10ccb8
c31d36a
c1d3eb6
0f6f3b4
3756f2d
287719c
0dc7318
ef20aee
ff0f491
3806614
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
Original file line number | Diff line number | Diff line change |
---|---|---|
|
@@ -21,9 +21,10 @@ | |
from opentelemetry.sdk.environment_variables import ( | ||
OTEL_PYTHON_LOG_EMITTER_PROVIDER, | ||
) | ||
from opentelemetry.sdk.logs.severity import SeverityNumber | ||
from opentelemetry.sdk.logs.severity import SeverityNumber, std_to_otlp | ||
from opentelemetry.sdk.resources import Resource | ||
from opentelemetry.sdk.util.instrumentation import InstrumentationInfo | ||
from opentelemetry.trace import get_current_span | ||
from opentelemetry.trace.span import TraceFlags | ||
from opentelemetry.util._providers import _load_provider | ||
from opentelemetry.util.types import Attributes | ||
|
@@ -111,6 +112,48 @@ def force_flush(self, timeout_millis: int = 30000): | |
""" | ||
|
||
|
||
class OTLPHandler(logging.Handler): | ||
"""A handler class which writes logging records, in OTLP format, to | ||
a network destination or file. | ||
""" | ||
|
||
def __init__(self, level=logging.NOTSET, log_emitter=None) -> None: | ||
super().__init__(level=level) | ||
self._log_emitter = log_emitter or get_log_emitter(__name__) | ||
|
||
def _translate(self, record: logging.LogRecord) -> LogRecord: | ||
timestamp = int(record.created * 1e9) | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Just for your information, this PEP may be relevant here. |
||
span_context = get_current_span().get_span_context() | ||
# TODO: attributes (or resource attributes?) from record metadata | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. FYI, I believe attributes can be populated from both custom and resources. There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. So There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. For When I was saying "custom" attributes, I meant the ability for users to add custom attributes to the Not any concern for now, just something to be mindful of. There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
From a users perspective, it looks like this: logging.debug("msg", extra={...}) Would it be possible to map this to OTLP log record attributes? You could take the top-level attributes of |
||
attributes: Attributes = {} | ||
severity_number = std_to_otlp(record.levelno) | ||
return LogRecord( | ||
timestamp=timestamp, | ||
trace_id=span_context.trace_id, | ||
span_id=span_context.span_id, | ||
trace_flags=span_context.trace_flags, | ||
severity_text=record.levelname, | ||
severity_number=severity_number, | ||
body=record.getMessage(), | ||
resource=self._log_emitter.resource, | ||
attributes=attributes, | ||
) | ||
|
||
def emit(self, record: logging.LogRecord) -> None: | ||
""" | ||
Emit a record. | ||
|
||
The record is translated to OTLP format, and then sent across the pipeline. | ||
""" | ||
self._log_emitter.emit(self._translate(record)) | ||
|
||
def flush(self) -> None: | ||
""" | ||
Flushes the logging output. | ||
""" | ||
self._log_emitter.flush() | ||
|
||
|
||
class LogEmitter: | ||
# TODO: Add multi_log_processor | ||
def __init__( | ||
|
@@ -121,6 +164,10 @@ def __init__( | |
self._resource = resource | ||
self._instrumentation_info = instrumentation_info | ||
|
||
@property | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Good catch! There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Shouldn't this be on the There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Yes, this should be on provider as well. |
||
def resource(self): | ||
return self._resource | ||
|
||
def emit(self, record: LogRecord): | ||
# TODO: multi_log_processor.emit | ||
pass | ||
|
@@ -142,6 +189,10 @@ def __init__( | |
if shutdown_on_exit: | ||
self._at_exit_handler = atexit.register(self.shutdown) | ||
|
||
@property | ||
def resource(self): | ||
return self._resource | ||
|
||
def get_log_emitter( | ||
self, | ||
instrumenting_module_name: str, | ||
|
Original file line number | Diff line number | Diff line change |
---|---|---|
|
@@ -54,3 +54,63 @@ class SeverityNumber(enum.Enum): | |
FATAL2 = 22 | ||
FATAL3 = 23 | ||
FATAL4 = 24 | ||
|
||
|
||
_STD_TO_OTLP = { | ||
10: SeverityNumber.DEBUG, | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. How come the interim levels defined like this? (11-19, 21-29, etc.) There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Curious will numbers in "std" ever be anything other than 0, 10, 20, 30, 40, 50? There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. This follows the log data model specification for mapping source format https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/logs/data-model.md#mapping-of-severitynumber. The step value from one level to another level in logging module is 10 but the it is 5 in log data model, so it is clearly many-to-one mapping for some levels. Higher the value, higher the severity. In general these intermediary levels don't come into play but logging library allows programmers to define the custom log levels if they need, so this addresses that case. For example I would define some >>> import logging
>>> SCARY = 45
>>> logging.addLevelName(SCARY, "SCARY")
>>> def scary(self, message, *args, **kws):
... self._log(SCARY, message, args, **kws)
...
>>> logging.Logger.scary = scary
>>> logger = logging.getLogger(__name__)
>>> logger.scary("Boo")
Boo |
||
11: SeverityNumber.DEBUG2, | ||
12: SeverityNumber.DEBUG3, | ||
13: SeverityNumber.DEBUG4, | ||
14: SeverityNumber.DEBUG4, | ||
15: SeverityNumber.DEBUG4, | ||
16: SeverityNumber.DEBUG4, | ||
17: SeverityNumber.DEBUG4, | ||
18: SeverityNumber.DEBUG4, | ||
19: SeverityNumber.DEBUG4, | ||
20: SeverityNumber.INFO, | ||
21: SeverityNumber.INFO2, | ||
22: SeverityNumber.INFO3, | ||
23: SeverityNumber.INFO4, | ||
24: SeverityNumber.INFO4, | ||
25: SeverityNumber.INFO4, | ||
26: SeverityNumber.INFO4, | ||
27: SeverityNumber.INFO4, | ||
28: SeverityNumber.INFO4, | ||
29: SeverityNumber.INFO4, | ||
30: SeverityNumber.WARN, | ||
31: SeverityNumber.WARN2, | ||
32: SeverityNumber.WARN3, | ||
33: SeverityNumber.WARN4, | ||
34: SeverityNumber.WARN4, | ||
35: SeverityNumber.WARN4, | ||
36: SeverityNumber.WARN4, | ||
37: SeverityNumber.WARN4, | ||
38: SeverityNumber.WARN4, | ||
39: SeverityNumber.WARN4, | ||
40: SeverityNumber.ERROR, | ||
41: SeverityNumber.ERROR2, | ||
42: SeverityNumber.ERROR3, | ||
43: SeverityNumber.ERROR4, | ||
44: SeverityNumber.ERROR4, | ||
45: SeverityNumber.ERROR4, | ||
46: SeverityNumber.ERROR4, | ||
47: SeverityNumber.ERROR4, | ||
48: SeverityNumber.ERROR4, | ||
49: SeverityNumber.ERROR4, | ||
50: SeverityNumber.FATAL, | ||
51: SeverityNumber.FATAL2, | ||
52: SeverityNumber.FATAL3, | ||
53: SeverityNumber.FATAL4, | ||
} | ||
|
||
|
||
def std_to_otlp(levelno: int) -> SeverityNumber: | ||
""" | ||
Map python log levelno as defined in https://docs.python.org/3/library/logging.html#logging-levels | ||
to OTLP log severity number. | ||
""" | ||
if levelno < 10: | ||
return SeverityNumber.UNSPECIFIED | ||
if levelno > 53: | ||
return SeverityNumber.FATAL4 | ||
return _STD_TO_OTLP[levelno] |
Original file line number | Diff line number | Diff line change |
---|---|---|
@@ -0,0 +1,84 @@ | ||
# Copyright The OpenTelemetry Authors | ||
# | ||
# Licensed under the Apache License, Version 2.0 (the "License"); | ||
# you may not use this file except in compliance with the License. | ||
# You may obtain a copy of the License at | ||
# | ||
# http://www.apache.org/licenses/LICENSE-2.0 | ||
# | ||
# Unless required by applicable law or agreed to in writing, software | ||
# distributed under the License is distributed on an "AS IS" BASIS, | ||
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. | ||
# See the License for the specific language governing permissions and | ||
# limitations under the License. | ||
|
||
import logging | ||
import unittest | ||
from unittest.mock import Mock | ||
|
||
from opentelemetry.sdk import trace | ||
from opentelemetry.sdk.logs import LogEmitter, OTLPHandler | ||
from opentelemetry.sdk.logs.severity import SeverityNumber | ||
from opentelemetry.trace import INVALID_SPAN_CONTEXT | ||
|
||
|
||
def get_logger(level=logging.NOTSET, log_emitter=None): | ||
logger = logging.getLogger(__name__) | ||
handler = OTLPHandler(level=level, log_emitter=log_emitter) | ||
logger.addHandler(handler) | ||
return logger | ||
|
||
|
||
class TestOTLPHandler(unittest.TestCase): | ||
def test_handler_default_log_level(self): | ||
emitter_mock = Mock(spec=LogEmitter) | ||
logger = get_logger(log_emitter=emitter_mock) | ||
# Make sure debug messages are ignored by default | ||
logger.debug("Debug message") | ||
self.assertEqual(emitter_mock.emit.call_count, 0) | ||
# Assert emit gets called for warning message | ||
logger.warning("Wanrning message") | ||
self.assertEqual(emitter_mock.emit.call_count, 1) | ||
|
||
def test_handler_custom_log_level(self): | ||
emitter_mock = Mock(spec=LogEmitter) | ||
logger = get_logger(level=logging.ERROR, log_emitter=emitter_mock) | ||
logger.warning("Warning message test custom log level") | ||
# Make sure any log with level < ERROR is ignored | ||
self.assertEqual(emitter_mock.emit.call_count, 0) | ||
logger.error("Mumbai, we have a major problem") | ||
logger.critical("No Time For Caution") | ||
self.assertEqual(emitter_mock.emit.call_count, 2) | ||
|
||
def test_log_record_no_span_context(self): | ||
emitter_mock = Mock(spec=LogEmitter) | ||
logger = get_logger(log_emitter=emitter_mock) | ||
# Assert emit gets called for warning message | ||
logger.warning("Wanrning message") | ||
args, _ = emitter_mock.emit.call_args_list[0] | ||
log_record = args[0] | ||
|
||
self.assertIsNotNone(log_record) | ||
self.assertEqual(log_record.trace_id, INVALID_SPAN_CONTEXT.trace_id) | ||
self.assertEqual(log_record.span_id, INVALID_SPAN_CONTEXT.span_id) | ||
self.assertEqual( | ||
log_record.trace_flags, INVALID_SPAN_CONTEXT.trace_flags | ||
) | ||
|
||
def test_log_record_trace_correlation(self): | ||
emitter_mock = Mock(spec=LogEmitter) | ||
logger = get_logger(log_emitter=emitter_mock) | ||
|
||
tracer = trace.TracerProvider().get_tracer(__name__) | ||
with tracer.start_as_current_span("test") as span: | ||
logger.critical("Critical message within span") | ||
|
||
args, _ = emitter_mock.emit.call_args_list[0] | ||
log_record = args[0] | ||
self.assertEqual(log_record.body, "Critical message within span") | ||
self.assertEqual(log_record.severity_text, "CRITICAL") | ||
self.assertEqual(log_record.severity_number, SeverityNumber.FATAL) | ||
span_context = span.get_span_context() | ||
self.assertEqual(log_record.trace_id, span_context.trace_id) | ||
self.assertEqual(log_record.span_id, span_context.span_id) | ||
self.assertEqual(log_record.trace_flags, span_context.trace_flags) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Should this be called an emitter rather than a handler? Or is this a convenience handler to allow users to add this handler to their python root handler?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Yes, this is one of the the handlers users can attach to root logger. I believe the name Handler makes more sense here.