Adding client.setup_logging() duplicate abseil log messages (stdout+sterr)

[tarrade]

Environment details

• OS type and version: MacOS 10.14.6 (18G4032)
• Python version: 3.7.6
• pip version: 20.0.2
• google-cloud-logging version: 1.15.0

Steps to reproduce

1. without the line client.setup_logging()

>>python test_logging_3.py   > out

>>more out
 0 print --- 
[INFO 2020-05-22 12:50:59,650 test_logging_3.py:30]  1 logging:
[INFO 2020-05-22 12:50:59,650 test_logging_3.py:31]  2 logging:
 3 print --- 
[DEBUG 2020-05-22 12:50:59,650 test_logging_3.py:34]  4 logging-test-debug
[INFO 2020-05-22 12:50:59,650 test_logging_3.py:35]  5 logging-test-info
[WARNING 2020-05-22 12:50:59,650 test_logging_3.py:36]  6 logging-test-warning
[ERROR 2020-05-22 12:50:59,650 test_logging_3.py:37]  7 logging test-error
 8 print --- 
 9 print ---

For this test I redirect all messages to the stdout stream. This is what we see since all logs messages are only the out file

2. now with the line client.setup_logging()

 >>python test_logging_3.py   > out
  1 logging:
  2 logging:
  4 logging-test-debug
  5 logging-test-info
  6 logging-test-warning
  7 logging test-error
 Program shutting down, attempting to send 5 queued log entries to Stackdriver Logging...
 Waiting up to 5 seconds.
 Making request: POST https://oauth2.googleapis.com/token
 Starting new HTTPS connection (1): oauth2.googleapis.com:443
 https://oauth2.googleapis.com:443 "POST /token HTTP/1.1" 200 None
 Submitted 1 logs
 Submitted 7 logs
 Background thread exited gracefully.
 Sent all pending logs.
 
 >>more out
  0 print --- 
 [INFO 2020-05-22 12:54:28,833 test_logging_3.py:30]  1 logging:
 [INFO 2020-05-22 12:54:28,833 test_logging_3.py:31]  2 logging:
  3 print --- 
 [DEBUG 2020-05-22 12:54:28,834 test_logging_3.py:34]  4 logging-test-debug
 [INFO 2020-05-22 12:54:28,834 test_logging_3.py:35]  5 logging-test-info
 [WARNING 2020-05-22 12:54:28,834 test_logging_3.py:36]  6 logging-test-warning
 [ERROR 2020-05-22 12:54:28,834 test_logging_3.py:37]  7 logging test-error
  8 print --- 
  9 print --- 
 [DEBUG 2020-05-22 12:54:28,982 connectionpool.py:959] Starting new HTTPS connection (1): oauth2.googleapis.com:443
 [DEBUG 2020-05-22 12:54:29,130 connectionpool.py:437] https://oauth2.googleapis.com:443 "POST /token HTTP/1.1" 200 None

We can see that on the stdout stream we have few more messages on top of the orginal output which is expected when adding new service. Now on the stderr stream we see messages (before we had nothing)

1. ALL messages from abseil are now duplicated i.e:

1 logging: (--> in stderr)
 [INFO 2020-05-22 12:54:28,833 test_logging_3.py:30]  1 logging: (--> in stdout)

2. some new messages appear (probably from the new service and direct to the stderr stream) i.e:

 Submitted 1 logs
 Submitted 7 logs
 Background thread exited gracefully.
 Sent all pending logs

I tried to look in more details to the logger:

    for handler in loggers:
        print("handler ", handler)
        print("       handler.level-->  ", handler.level)
        print("       handler.name-->  ", handler.name)
        print("       handler.propagate-->  ", handler.propagate)
        print("       handler.parent-->  ", handler.parent )
        print(dir(handler))

but in both cases I see:

handler  <RootLogger root (DEBUG)>
       handler.level-->   10
       handler.name-->   root
       handler.propagate-->   True
       handler.parent-->   None

In the documentation it is just mentioned that we should add 2 lines to use google.cloud.logging. It seems that something else need to be setup to avoid duplicate. I didn't run the exact simple code on GCP but similar code show also duplicate in Stackdriver one time with the label "INFO" (from stdout stream) and one time with the label "ERROR" (from stderr stream). Here what I see on Stackdriver. Abseil messages are duplicated. WARNING and ERROR are shown 3 times:

)

How can we log messages from abseil only one time ? On Stackoverflow people suggested me to open a ticket.

Code example

Here my test_logging_3.py file:

from absl import logging
from absl import flags
from absl import app
import logging as logger
import google.cloud.logging

import sys

FLAGS = flags.FLAGS

def main(argv):

    logging.get_absl_handler().python_handler.stream = sys.stdout

    # Instantiates a client
    client = google.cloud.logging.Client()

    # Connects the logger to the root logging handler; by default this captures
    # all logs at INFO level and higher
    client.setup_logging()

    fmt = "[%(levelname)s %(asctime)s %(filename)s:%(lineno)s] %(message)s"
    formatter = logger.Formatter(fmt)
    logging.get_absl_handler().setFormatter(formatter)

    # set level of verbosity
    logging.set_verbosity(logging.DEBUG)

    print(' 0 print --- ')
    logging.info(' 1 logging:')
    logging.info(' 2 logging:')

    print(' 3 print --- ')
    logging.debug(' 4 logging-test-debug')
    logging.info(' 5 logging-test-info')
    logging.warning(' 6 logging-test-warning')
    logging.error(' 7 logging test-error')
    print(' 8 print --- ')
    print(' 9 print --- ')

if __name__ == '__main__':
    app.run(main)

[gregorth]

any update on that?

[daniel-sanche]

This seems to be a duplicate of #38, right? If so, it should be fixed by this PR: #106