Added logging instrumentation to enable log - trace correlation #345

owais · 2021-02-19T08:22:52Z

Description

Added logging instrumentation to enable log - trace correlation

This commit adds a new logging instrumentation. The instrumentation
patches standard library logging module to inject tracing context
variables (otelSpanID, otelTraceID, otelServiceName) into log record
objects. It also optionally calls logging.basicConfig() and sets a
logging format that makes use of these vars if instructed by the user.

Type of change

Please delete options that are not relevant.

Bug fix (non-breaking change which fixes an issue)
New feature (non-breaking change which adds functionality)
Breaking change (fix or feature that would cause existing functionality to not work as expected)
This change requires a documentation update

How Has This Been Tested?

Please describe the tests that you ran to verify your changes. Provide instructions so we can reproduce. Please also list any relevant details for your test configuration

Added unit tests

Does This PR Require a Core Repo Change?

Yes. - Link to PR:
No.

Checklist:

See contributing.md for styleguide, changelog guidelines, and more.

Followed the style guidelines of this project
Changelogs have been updated
Unit tests have been added
Documentation has been updated

toumorokoshi

Thanks! I think the environment variables and basicConfig should be re-thought, but the correlation looks good!

toumorokoshi · 2021-02-22T07:00:13Z

.../opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/__init__.py

+- ``debug``
+- ``warning``
+
+Manually calling logging.basicConfig


I think the need for implicit ordering like this is a good argument why opentelemetry shouldn't provide a basicConfig configuration via environment variables.

If the user has to remember to call opentelemetry instrumentation first to get the opentelemetry call, why not just expose useful constants (e.g. log format) and document how to use them?

We have a constant defined and can document it. We can also update documentation to show how users can do this completely with custom code (manually calling basicConfig) without dealing with environment variables.

The environment variables solve an important use case though which is 100% auto-instrumented apps where users cannot or don't want to add manual code to enable tracing. We support this with the opentelemetry-bootstrap command and the pattern so far to allow customization of behavior has been to use env vars. So we really do need to support this through env vars.

This can still be totally used manually by adding a bit of code. I'll update the documentation to cover that use case as well.

The environment variables solve an important use case though which is 100% auto-instrumented apps where users cannot or don't want to add manual code to enable tracing. We support this with the opentelemetry-bootstrap command and the pattern so far to allow customization of behavior has been to use env vars. So we really do need to support this through env vars.

A part of me feels like no one would want opentelemetry to expose such an opinionated standard log, but I see your point that the idea is to make it really easy for even beginners to python / application development to get observability.

SGTM to leave the env vars.

toumorokoshi · 2021-02-22T07:05:40Z

.../opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/__init__.py

+
+            logging.setLogRecordFactory(record_factory)
+
+        if environ.get(OTEL_PYTHON_LOG_CORRELATION, "false").lower() == "true":


I would argue for the following:

remove these environment variables and the basicConfig porcelain altogether.

If 1 is not acceptable I would argue factoring this out into a separate method, since this is complecting two different behaviors (attaching custom fields to the log record, modifying logging) without a way to use them separately.

Porcelain functions like these typically help the user by orchestrating a complex process that they may not be completely familiar with. In this case, I could achieve the same result as these environment variables by a single call to logging.basicConfig, and I believe it would be pretty common for a python opentelemetry user to be familiar with the logging API.

Sure, we can split them into multiple methods or we can add an argument to the instrument() function that controls whether to call basicConfig or not in addition to the env var. I think the later would be preferable as all other instrumentations only export instrument() and uninstrument() functions so adding a 3rd method to this one would need a lot of justification.

So how about something like instrument(setup_logging_format=False). This would only call basicConfig if the user explicitly passed setup_logging_fromat=True.

WDYT?

Added arguments to the instrument method to allow users to configure the instrumentation manually through code while keeping env var support to allow opentelemetry-instrument command users to configure without having to add any custom code.

toumorokoshi

LGTM, thanks!

toumorokoshi · 2021-02-24T07:25:48Z

.../opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/__init__.py

+
+.. code-block::
+
+    %(asctime)s %(levelname)s [%(name)s] [%(filename)s:%(lineno)d] [trace_id=%(otelTraceID)s span_id=%(otelSpanID)s service.name=%(otelServiceName)s] - %(message)s


can this just link to the above default format? copy-paste can make it difficult to maintain code.

Not sure how linking will work in docs. Do you mean link to variable definition directly to source/github or define this string only once in docs with an anchor and link to that from everywhere else?

I tried a different solution. I'm assigning docstrings explicitly by setting __doc__ = "....".format(DEFAULT_LOGGING_FORMAT). This way the docs will always be up to date and logging format will have a single source of truth for both code and docs. It feels a bit weird but technically it's not inferior in any way. I can't think of a downside but may be I didn't think hard enough.

What do you think about this approach?

https://github.com/open-telemetry/opentelemetry-python-contrib/pull/345/files#diff-b3cc41cf4c57f13f0ac89e4d3edec4ce0156b65ed65e94fbd95660d1f763ae22R37
and
https://github.com/open-telemetry/opentelemetry-python-contrib/pull/345/files#diff-b3cc41cf4c57f13f0ac89e4d3edec4ce0156b65ed65e94fbd95660d1f763ae22R48

seemk

Just a potential nitpick regarding service.name 🙂

seemk · 2021-02-25T21:05:02Z

...opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/constants.py

+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+DEFAULT_LOGGING_FORMAT = "%(asctime)s %(levelname)s [%(name)s] [%(filename)s:%(lineno)d] [trace_id=%(otelTraceID)s span_id=%(otelSpanID)s service.name=%(otelServiceName)s] - %(message)s"


Should service.name be changed to resource.service.name?

There's an OTEP with a few approvals for log correlation conventions (open-telemetry/oteps#114) which goes over resource correlation as well.

Personally I like the shorter version, but if it is merged to the spec

Thanks! I've updated it.

owais · 2021-03-01T18:20:01Z

@aabmass PTAL when you can. Thanks.

aabmass

LGTM

aabmass · 2021-03-04T17:01:08Z

.../opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/__init__.py

+                record.otelSpanID = ""
+                record.otelTraceID = ""


If it is invalid span, it will log trace_id= span_id=? Would leaving the zeroes be better i.e. trace_id=0 span_id=0?

aabmass · 2021-03-04T17:05:08Z

...opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/constants.py

+The integration patches the standard library logging module to automatically inject tracing context into log record objects
+and optionally calls ``logging.basicConfig()`` to set a logging format with placeholders for span ID, trace ID and service name.
+
+The following keys are injected into the patched log record objects:


The "patch" terminology sounds like we are actually monkey patching, but since you updated it to just set it with logging.setLogRecordFactory() I think we should rephrase throughout

aabmass · 2021-03-04T17:15:59Z

.../opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/__init__.py

+            logging.basicConfig(format=log_format, level=log_level)
+
+    def _uninstrument(self, **kwargs):
+        LoggingInstrumentor._is_instrumented = False


Would keeping the old_factory and resetting it here be easier than tracking the _is_instrumented and _factory_registered booleans?

aabmass · 2021-03-04T17:18:36Z

...opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/constants.py

+Environment variables
+---------------------
+
+OTEL_PYTHON_LOG_CORRELATION


.. envvar directive?

aabmass · 2021-03-04T17:20:19Z

...opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/constants.py

+OTEL_PYTHON_LOG_CORRELATION
+^^^^^^^^^^^^^^^^^^^^^^^^^^^
+
+This env var must be set to ``true`` in order to enable trace context injection into logs by calling ``logging.basicConfig()`` and


nit they can also set it in LoggingInstrumentor constructor which I think you mention elsewhere, but this is misleading

owais · 2021-03-04T17:33:28Z

Thanks @aabmass. Will address the comments soon.

@codeboten please hold off on merging for now. I'll let you know once this is ready. Thanks!

codeboten

Blocking merge until comments are addressed as per your request @owais

owais · 2021-03-05T00:54:51Z

@codeboten This should be good to go now. Thanks.

This commit adds a new logging instrumentation. The instrumentation patches standard library logging module to inject tracing context variables (otelSpanID, otelTraceID, otelServiceName) into log record objects. It also optionally calls `logging.basicConfig()` and sets a logging format that makes use of these vars if instructed by the user.

srikanthccv · 2021-03-14T04:08:34Z

.../opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/__init__.py

+        resource = provider.resource if provider else None
+        if resource:
+            service_name = resource.attributes.get("service.name")
+


@owais I have been going through the codebase to see places we are relying on the current global tracer provider and in particularly where it doesn't fit with the multiple tracer providers usecase. This part of code is getting service name from the global tracer provider. Is this still something we want to do here?

Side question: Does this log-trace correlation also apply to logs emitted by opentemetry python packages?

Is this still something we want to do here?

No, I think we should update this to extract it from span (resource) just like the span and trace ID.

Side question: Does this log-trace correlation also apply to logs emitted by opentemetry python packages?
Yes. As it stands today, once enabled, this feature will apply to all logs produced by the python process.

owais force-pushed the logging-correlation branch from 63a4437 to 4628626 Compare February 19, 2021 08:25

owais changed the title ~~wip~~ Added logging instrumentation to enable log - trace correlation Feb 19, 2021

owais force-pushed the logging-correlation branch 9 times, most recently from 13edebb to f61b1f7 Compare February 19, 2021 10:45

owais marked this pull request as ready for review February 19, 2021 10:45

owais requested review from a team, toumorokoshi and ocelotl and removed request for a team February 19, 2021 10:45

owais force-pushed the logging-correlation branch 2 times, most recently from 7896720 to 2c7ce4f Compare February 20, 2021 21:05

toumorokoshi suggested changes Feb 22, 2021

View reviewed changes

owais force-pushed the logging-correlation branch 3 times, most recently from a475908 to b5911de Compare February 23, 2021 18:05

toumorokoshi approved these changes Feb 24, 2021

View reviewed changes

owais force-pushed the logging-correlation branch 3 times, most recently from bf7326c to 620a9ce Compare February 25, 2021 09:49

lzchen assigned aabmass Feb 25, 2021

seemk approved these changes Feb 25, 2021

View reviewed changes

owais force-pushed the logging-correlation branch 2 times, most recently from 6dff13d to 27c341e Compare February 27, 2021 15:39

aabmass approved these changes Mar 4, 2021

View reviewed changes

codeboten suggested changes Mar 4, 2021

View reviewed changes

owais force-pushed the logging-correlation branch 4 times, most recently from 14bbcb3 to 379ab65 Compare March 5, 2021 00:46

codeboten approved these changes Mar 9, 2021

View reviewed changes

owais force-pushed the logging-correlation branch from ef671cf to 34a96bb Compare March 10, 2021 00:10

Merge branch 'main' into logging-correlation

20e0168

codeboten merged commit 9ef4410 into open-telemetry:main Mar 10, 2021

owais deleted the logging-correlation branch March 10, 2021 13:12

srikanthccv reviewed Mar 14, 2021

View reviewed changes

owais mentioned this pull request Apr 9, 2021

Auto instrumentation: Inject trace IDs in logs open-telemetry/opentelemetry-python#1562

Closed

srikanthccv mentioned this pull request Apr 13, 2021

Update instrumentations to use tracer_provider for creating tracer if given, otherwise use global tracer provider #402

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Added logging instrumentation to enable log - trace correlation #345

Added logging instrumentation to enable log - trace correlation #345

owais commented Feb 19, 2021 •

edited

Loading

toumorokoshi left a comment

toumorokoshi Feb 22, 2021

owais Feb 22, 2021

toumorokoshi Feb 24, 2021

toumorokoshi Feb 22, 2021

owais Feb 22, 2021

owais Feb 23, 2021

toumorokoshi left a comment

toumorokoshi Feb 24, 2021

owais Feb 25, 2021

seemk left a comment

seemk Feb 25, 2021

owais Feb 25, 2021

owais commented Mar 1, 2021

aabmass left a comment

aabmass Mar 4, 2021

aabmass Mar 4, 2021

aabmass Mar 4, 2021

aabmass Mar 4, 2021

aabmass Mar 4, 2021

owais commented Mar 4, 2021

codeboten left a comment

owais commented Mar 5, 2021

srikanthccv Mar 14, 2021

owais Mar 14, 2021


		logging.setLogRecordFactory(record_factory)

		if environ.get(OTEL_PYTHON_LOG_CORRELATION, "false").lower() == "true":


		.. code-block::

		%(asctime)s %(levelname)s [%(name)s] [%(filename)s:%(lineno)d] [trace_id=%(otelTraceID)s span_id=%(otelSpanID)s service.name=%(otelServiceName)s] - %(message)s

Added logging instrumentation to enable log - trace correlation #345

Added logging instrumentation to enable log - trace correlation #345

Conversation

owais commented Feb 19, 2021 • edited Loading

Description

Type of change

How Has This Been Tested?

Does This PR Require a Core Repo Change?

Checklist:

toumorokoshi left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

toumorokoshi left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

seemk left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

owais commented Mar 1, 2021

aabmass left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

owais commented Mar 4, 2021

codeboten left a comment

Choose a reason for hiding this comment

owais commented Mar 5, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

owais commented Feb 19, 2021 •

edited

Loading