Superfluous service name in console log output

[tigrannajaryan]

Describe your environment
Mac OS X
Python 3.9.6

Steps to reproduce
Run Getting Started, metrics example.

What is the expected behavior?
Service name present once in the log records.

What is the actual behavior?
Service name is present in two different places in the log records, once as a subkey of the "attributes", once as a subkey of "resource".

{
    "body": "Anonymous player is rolling the dice: 5",
    "severity_number": "<SeverityNumber.WARN: 13>",
    "severity_text": "WARNING",
    "attributes": {
        "otelSpanID": "7d0581e1f3f51bea",
        "otelTraceID": "8b346ee9af8718bf73a4318d073cbbb1",
        "otelTraceSampled": true,
        "otelServiceName": "dice-server"
    },
    "dropped_attributes": 0,
    "timestamp": "2023-11-22T17:01:36.027744Z",
    "trace_id": "0x8b346ee9af8718bf73a4318d073cbbb1",
    "span_id": "0x7d0581e1f3f51bea",
    "trace_flags": 1,
    "resource": "BoundedAttributes({'telemetry.sdk.language': 'python', 'telemetry.sdk.name': 'opentelemetry', 'telemetry.sdk.version': '1.21.0', 'service.name': 'dice-server', 'telemetry.auto.version': '0.42b0'}, maxlen=None)"
}

I think it is sufficient to have the service name in the "resource" field.

Additional context
Part of review open-telemetry/community#1751

[garry-cairns]

I'm not convinced this reproduces in a guaranteed way. Running an adapted version of the logging example script:

import logging

from opentelemetry import trace
from opentelemetry._logs import set_logger_provider
from opentelemetry.sdk._logs import LoggerProvider, LoggingHandler
from opentelemetry.sdk._logs.export import BatchLogRecordProcessor, ConsoleLogExporter
from opentelemetry.sdk.resources import Resource
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import (
    BatchSpanProcessor,
    ConsoleSpanExporter,
)

trace.set_tracer_provider(TracerProvider())
trace.get_tracer_provider().add_span_processor(
    BatchSpanProcessor(ConsoleSpanExporter())
)

logger_provider = LoggerProvider(
    resource=Resource.create(
        {
            "service.name": "shoppingcart",
            "service.instance.id": "instance-12",
        }
    ),
)
set_logger_provider(logger_provider)

exporter = ConsoleLogExporter()
logger_provider.add_log_record_processor(BatchLogRecordProcessor(exporter))
handler = LoggingHandler(level=logging.NOTSET, logger_provider=logger_provider)

# Attach OTLP handler to root logger
logging.getLogger().addHandler(handler)

# Log directly
logging.info("Jackdaws love my big sphinx of quartz.")

# Create different namespaced loggers
logger1 = logging.getLogger("myapp.area1")
logger2 = logging.getLogger("myapp.area2")

logger1.debug("Quick zephyrs blow, vexing daft Jim.")
logger1.info("How quickly daft jumping zebras vex.")
logger2.warning("Jail zesty vixen who grabbed pay from quack.")
logger2.error("The five boxing wizards jump quickly.")


# Trace context correlation
tracer = trace.get_tracer(__name__)
with tracer.start_as_current_span("foo"):
    # Do something
    logger2.error("Hyderabad, we have a major problem.")

Importing this at the shell runs pretty much everything because it's top-level and, omitting the output from the console trace exporter, you get:

>>> import sample
...
{
    "body": "Jail zesty vixen who grabbed pay from quack.",
    "severity_number": "<SeverityNumber.WARN: 13>",
    "severity_text": "WARNING",
    "attributes": null,
    "dropped_attributes": 0,
    "timestamp": "2023-12-08T23:11:51.278082Z",
    "trace_id": "0x00000000000000000000000000000000",
    "span_id": "0x0000000000000000",
    "trace_flags": 0,
    "resource": "BoundedAttributes({'telemetry.sdk.language': 'python', 'telemetry.sdk.name': 'opentelemetry', 'telemetry.sdk.version': '1.20.0', 'service.name': 'shoppingcart', 'service.instance.id': 'instance-12'}, maxlen=None)"
}
{
    "body": "The five boxing wizards jump quickly.",
    "severity_number": "<SeverityNumber.ERROR: 17>",
    "severity_text": "ERROR",
    "attributes": null,
    "dropped_attributes": 0,
    "timestamp": "2023-12-08T23:11:51.282972Z",
    "trace_id": "0x00000000000000000000000000000000",
    "span_id": "0x0000000000000000",
    "trace_flags": 0,
    "resource": "BoundedAttributes({'telemetry.sdk.language': 'python', 'telemetry.sdk.name': 'opentelemetry', 'telemetry.sdk.version': '1.20.0', 'service.name': 'shoppingcart', 'service.instance.id': 'instance-12'}, maxlen=None)"
}
{
    "body": "Hyderabad, we have a major problem.",
    "severity_number": "<SeverityNumber.ERROR: 17>",
    "severity_text": "ERROR",
    "attributes": null,
    "dropped_attributes": 0,
    "timestamp": "2023-12-08T23:11:51.283412Z",
    "trace_id": "0x6f8bb3b9b5afdda7232b909954e9fa2d",
    "span_id": "0x3dab9b33cffcba63",
    "trace_flags": 1,
    "resource": "BoundedAttributes({'telemetry.sdk.language': 'python', 'telemetry.sdk.name': 'opentelemetry', 'telemetry.sdk.version': '1.20.0', 'service.name': 'shoppingcart', 'service.instance.id': 'instance-12'}, maxlen=None)"
}

I suspected what you're seeing might have related to the logging integration but setting OTEL_PYTHON_LOG_CORRELATION in my env and calling logging.basicConfig() in the script didn't reproduce the behavior you saw either, but merely changed the logging behavior itself as we might expect.

[emdneto]

@tigrannajaryan @lzchen Since this is related to opentelemetry-instrumentation-logging is it still a blocker for the review? Is there something we can do? Maybe put those under _RESERVED_ATTRS?

[lzchen]

Was indeed able to replicate this with opentelemetry-instrumentation-logging. Since the instrumentation supplements the log records and it is experimental, I do not believe this should block the logging sdk rc.

Is there something we can do?

What we can do in regards to this feature is to improve the README of the logging instrumentation to outline what fields the instrumentation enriches the log records with. I will be closing the issue in favor of a doc change issue.

[lzchen]

open-telemetry/opentelemetry-python-contrib#2642