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

Add OTLPHandler for standard library logging module #1903

Merged
merged 13 commits into from
Jun 18, 2021
2 changes: 2 additions & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
### Added
- Add global LogEmitterProvider and convenience function get_log_emitter
([#1901](https://github.com/open-telemetry/opentelemetry-python/pull/1901))
- Add OTLPHandler for standard library logging module
([#1903](https://github.com/open-telemetry/opentelemetry-python/pull/1903))

### Changed
- Updated `opentelemetry-opencensus-exporter` to use `service_name` of spans instead of resource
Expand Down
53 changes: 52 additions & 1 deletion opentelemetry-sdk/src/opentelemetry/sdk/logs/__init__.py
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -111,6 +112,48 @@ def force_flush(self, timeout_millis: int = 30000):
"""


class OTLPHandler(logging.Handler):
Copy link
Contributor

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?

Copy link
Member Author

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.

"""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)
Copy link
Contributor

Choose a reason for hiding this comment

The 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
Copy link
Contributor

Choose a reason for hiding this comment

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

FYI, I believe attributes can be populated from both custom and resources.

Copy link
Member Author

Choose a reason for hiding this comment

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

So logging.LogRecord https://docs.python.org/3/library/logging.html#logrecord-attributes has a number of attributes like funcName, filename, and processName etc.. I was wondering if we should just make these as OTLP log record attributes https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/logs/data-model.md#field-attributes or log record resource attributes.

Copy link
Contributor

Choose a reason for hiding this comment

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

For logging.LogRecord attributes, it makes more sense to be part of the OTLP log record attributes.

When I was saying "custom" attributes, I meant the ability for users to add custom attributes to the LogRecord themselves (it is a feature in OpenCensus as well), but may not be defined yet in the specs.

Not any concern for now, just something to be mindful of.

Copy link
Contributor

Choose a reason for hiding this comment

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

logging.LogRecord has an (optional) extra attribute that holds arbitrary user-injected attributes.
This is not super well documented, but the docs can be found a couple paragraphs down from here.

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 extra (which would be my preference), or require them to be nested under a specific key (e.g. logging.debug("msg", extra={"oltp-attributes": {...}})).

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__(
Expand All @@ -121,6 +164,10 @@ def __init__(
self._resource = resource
self._instrumentation_info = instrumentation_info

@property
Copy link
Contributor

Choose a reason for hiding this comment

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

Good catch!

Copy link
Contributor

Choose a reason for hiding this comment

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

Shouldn't this be on the provider level?

Copy link
Member Author

Choose a reason for hiding this comment

The 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
Expand All @@ -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,
Expand Down
60 changes: 60 additions & 0 deletions opentelemetry-sdk/src/opentelemetry/sdk/logs/severity.py
Original file line number Diff line number Diff line change
Expand Up @@ -54,3 +54,63 @@ class SeverityNumber(enum.Enum):
FATAL2 = 22
FATAL3 = 23
FATAL4 = 24


_STD_TO_OTLP = {
10: SeverityNumber.DEBUG,
Copy link
Contributor

Choose a reason for hiding this comment

The 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.)

Copy link
Contributor

@lzchen lzchen Jun 16, 2021

Choose a reason for hiding this comment

The 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?

Copy link
Member Author

Choose a reason for hiding this comment

The 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 scary b/w error and critical level like below

>>> 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]
84 changes: 84 additions & 0 deletions opentelemetry-sdk/tests/logs/test_handler.py
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)