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
48 changes: 48 additions & 0 deletions opentelemetry-sdk/src/opentelemetry/sdk/logs/__init__.py
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,8 @@
from opentelemetry.sdk.logs.severity import SeverityNumber
from opentelemetry.sdk.resources import Resource
from opentelemetry.sdk.util.instrumentation import InstrumentationInfo
from opentelemetry.sdk.util.severity import std_to_otlp
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 +113,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

@srikanthccv srikanthccv Jun 16, 2021

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 calss which writes logging records, in OTLP format, to
srikanthccv marked this conversation as resolved.
Show resolved Hide resolved
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 +165,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 Down
71 changes: 71 additions & 0 deletions opentelemetry-sdk/src/opentelemetry/sdk/util/severity.py
Original file line number Diff line number Diff line change
@@ -0,0 +1,71 @@
# Copyright The OpenTelemetry Authors
srikanthccv marked this conversation as resolved.
Show resolved Hide resolved
#
# 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.

from opentelemetry.sdk.logs.severity import SeverityNumber

srikanthccv marked this conversation as resolved.
Show resolved Hide resolved
_STD_TO_OTLP = {
10: SeverityNumber.DEBUG,
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:
srikanthccv marked this conversation as resolved.
Show resolved Hide resolved
"""Map python log levelno 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)