LoggingExporter conflicts with logging trace_integrations

[jeffhentschel]

Describe your environment.

• Python 3.7.4
• opencensus 0.7.5

Steps to reproduce.

import logging

from opencensus.trace import config_integration
from opencensus.trace.tracer import Tracer
from opencensus.trace.samplers import AlwaysOnSampler
from opencensus.trace.logging_exporter import LoggingExporter
from opencensus.trace.print_exporter import PrintExporter

_format = '%(asctime)s %(traceId)s %(spanId)s %(name)s %(levelname)s %(message)s'

config_integration.trace_integrations(['logging'])

def getFormattedLoggingExporter():
    """
    Produces error:

    2019-10-14 12:59:09,263 a7f42704058d0eb10f3c17ae3f69c4ae 0000000000000000 __main__ DEBUG Before span
    2019-10-14 12:59:09,265 a7f42704058d0eb10f3c17ae3f69c4ae 8a8d3f5272f3a4c2 __main__ DEBUG Inside of span
    --- Logging error ---
    Traceback (most recent call last):
    File "/usr/local/Cellar/python/3.7.4/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1025, in emit
        msg = self.format(record)
    File "/usr/local/Cellar/python/3.7.4/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 869, in format
      return fmt.format(record)
    File "/usr/local/Cellar/python/3.7.4/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 611, in format
        s = self.formatMessage(record)
    File "/usr/local/Cellar/python/3.7.4/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 580, in formatMessage
        return self._style.format(record)
    File "/usr/local/Cellar/python/3.7.4/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 422, in format
        return self._fmt % record.__dict__
    KeyError: 'traceId'
    """
    handler = logging.StreamHandler()
    formatter = logging.Formatter(_format)
    handler.setFormatter(formatter)
    return LoggingExporter(handler)

def getDefaultLoggingExporter():
    """
    Produces unexpected output

    Before span
    Inside of span
    {'traceId': 'd6732caa558dc453ccd7e150ab50c347', 'spans': [{'displayName': {'value': 'span1', 'truncated_byte_count': 0}, 'spanId': '8480f6c4376300c2', 'startTime': '2019-10-14T17:00:32.974544Z', 'endTime': '2019-10-14T17:00:32.974808Z', 'childSpanCount': 0, 'kind': 0, 'status': {'code': 0}}]}
    After span
    """
    return LoggingExporter()

def getPrintLoggingExporter():
    """
    Produces following output

    2019-10-14 13:02:36,276 12446e050004f280ce2396b0f713a44c 0000000000000000 __main__ DEBUG Before span
    2019-10-14 13:02:36,278 12446e050004f280ce2396b0f713a44c 185318773e0608b0 __main__ DEBUG Inside of span
    [SpanData(name='span1', context=SpanContext(trace_id=12446e050004f280ce2396b0f713a44c, span_id=None, trace_options=TraceOptions(enabled=True), tracestate=None), span_id='185318773e0608b0', parent_span_id=None, attributes=BoundedDict({}, maxlen=32), start_time='2019-10-14T17:02:36.278290Z', end_time='2019-10-14T17:02:36.278567Z', child_span_count=0, stack_trace=None, annotations=BoundedList([], maxlen=32), message_events=BoundedList([], maxlen=128), links=BoundedList([], maxlen=32), status=<opencensus.trace.status.Status object at 0x110797f50>, same_process_as_parent_span=None, span_kind=0)]
    2019-10-14 13:02:36,279 12446e050004f280ce2396b0f713a44c 0000000000000000 __main__ DEBUG After span
    """
    return PrintExporter()

exporter = getPrintLoggingExporter()
sampler = AlwaysOnSampler()

tracer = Tracer(exporter=exporter, sampler=sampler)

logging.getLogger().setLevel(logging.DEBUG)
logging.basicConfig(format=_format)

log = logging.getLogger(__name__)
log.debug('Before span')
with tracer.span('span1'):
    log.debug('Inside of span')
log.debug('After span')

What is the expected behavior?

I'm trying to format log messages that are used in conjunction with the LoggingExporter and it looks like the exporter either overwrites my basicConfig formatter string or is unable to utilize the logging trace integrations. Thank you for the help.

What is the actual behavior?

See above code for 3 examples.

[h2floh]

Hey @jeffaudio , had a same issue today and stumbled on your post here.

I could resolve my problem with installing the logging extension package, it is only referenced by a string in the code: https://github.com/census-instrumentation/opencensus-python/tree/master/contrib/opencensus-ext-logging

And I had another mistake where config_integration.trace_integrations(['logging']) was called after the logger was retrieved log = logging.getLogger(__name__) after fixing both it worked just fine.