Duplicate log entries with Google Cloud Stackdriver logging of Python code on Kubernetes Engine

Question

I have a simple Python app running in a container on Google Kubernetes Engine. I am trying to connect the standard Python logging to Google Stackdriver logging using this guide. I have almost succeeded, but I am getting duplicate log entries with one always at the 'error' level...

---

Screenshot of Stackdriver logs showing duplicate entries

This is my python code that set's up the logging according to the above guide:

import webapp2
from paste import httpserver
import rpc

# Imports the Google Cloud client library
import google.cloud.logging
# 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()

app = webapp2.WSGIApplication([('/rpc/([A-Za-z]+)', rpc.RpcHandler),], debug=True)
httpserver.serve(app, host='0.0.0.0', port='80')

Here's the code that triggers the logs from the screenshot:

import logging

logging.info("INFO Entering PostEchoPost...")
logging.warning("WARNING Entering PostEchoPost...")
logging.error("ERROR Entering PostEchoPost...")
logging.critical("CRITICAL Entering PostEchoPost...")

Here is the full Stackdriver log, expanded from the screenshot, with an incorrectly interpreted ERROR level:

{
 insertId:  "1mk4fkaga4m63w1"  
 labels: {
  compute.googleapis.com/resource_name:  "gke-alg-microservice-default-pool-xxxxxxxxxx-ttnz"   
  container.googleapis.com/namespace_name:  "default"   
  container.googleapis.com/pod_name:  "esp-alg-xxxxxxxxxx-xj2p2"   
  container.googleapis.com/stream:  "stderr"   
 }
 logName:  "projects/projectname/logs/algorithm"  
 receiveTimestamp:  "2018-01-03T12:18:22.479058645Z"  
 resource: {
  labels: {
   cluster_name:  "alg-microservice"    
   container_name:  "alg"    
   instance_id:  "703849119xxxxxxxxxx"   
   namespace_id:  "default"    
   pod_id:  "esp-alg-xxxxxxxxxx-xj2p2"    
   project_id:  "projectname"    
   zone:  "europe-west1-b"    
  }
  type:  "container"   
 }
 severity:  "ERROR"  
 textPayload:  "INFO Entering PostEchoPost...
"  
 timestamp:  "2018-01-03T12:18:20Z"  
}

Here is the the full Stackdriver log, expanded from the screenshot, with a correctly interpreted INFO level:

{
 insertId:  "1mk4fkaga4m63w0"  
 jsonPayload: {
  message:  "INFO Entering PostEchoPost..."   
  thread:  140348659595008   
 }
 labels: {
  compute.googleapis.com/resource_name:  "gke-alg-microservi-default-pool-xxxxxxxxxx-ttnz"   
  container.googleapis.com/namespace_name:  "default"   
  container.googleapis.com/pod_name:  "esp-alg-xxxxxxxxxx-xj2p2"   
  container.googleapis.com/stream:  "stderr"   
 }
 logName:  "projects/projectname/logs/algorithm"  
 receiveTimestamp:  "2018-01-03T12:18:22.479058645Z"  
 resource: {
  labels: {
   cluster_name:  "alg-microservice"    
   container_name:  "alg"    
   instance_id:  "703849119xxxxxxxxxx"    
   namespace_id:  "default"    
   pod_id:  "esp-alg-xxxxxxxxxx-xj2p2"    
   project_id:  "projectname"    
   zone:  "europe-west1-b"    
  }
  type:  "container"   
 }
 severity:  "INFO"  
 timestamp:  "2018-01-03T12:18:20.260099887Z"  
}

So, this entry might be the key:

container.googleapis.com/stream:  "stderr" 

It looks like in addition to my logging set-up working, all logs from the container are being send to stderr in the container, and I believe that by default, at least on Kubernetes Container Engine, all stdout/stderr are picked up by Google Stackdriver via FluentD... Having said that, I'm out of my depth at this point.

Any ideas why I am getting these duplicate entries?

Answer 1

[2024 answer]

This issue is still present as of September 2024 but only if you use the Python root logger (logging.getLogger()) in an application running on your local machine and launched from the command line. In this case, when the application gets reset, another handler attaches to the root logger (if you have LRU cache, this gets overwritten when resetting an application and a new handler is generated). So, multiple handlers might be attached to the root logger.

If you use a named logger, Cloud Logging will not reuse the root logger and logs will not be duplicated:

client = google.cloud.logging.Client()
client.setup_logging()

logger = logging.getLogger('your-logger-name')

Instead, when you run an application in a container, if the application gets reset, then it means the whole container has been reset, and so the underlying root logger. You should have no issues in this case.

Answer 2

Writing in 2022, shortly after v3.0.0 of google-cloud-logging was released, and this issue cropped up for me too (albeit almost certainly for a different reason).

Debugging

The most useful thing I did on the way to debugging it was stick the following in my code:

import logging
...
root_logger = logging.getLogger()  # no arguments = return the root logger
print(root_logger.handlers, flush=True)  # tell me what handlers are attached
...

If you're getting duplicate logs, it seems certain that it's because you've got multiple handlers attached to your logger, and Stackdriver is catching logs from both of them! To be fair, that is Stackdriver's job; it's just a pity that google-cloud-logging can't sort this out by default.

The good news is that Stackdriver will also catch the print statement (which goes to the STDOUT stream). In my case, the following list of handlers was logged: [<StreamHandler <stderr> (NOTSET)>, <StructuredLogHandler <stderr> (NOTSET)>]. So: two handlers were attached to the root logger.

Fixing it

You might be able to find that your code is attaching the handler somewhere else, and simply remove that part. But it may instead be the case that e.g. a dependency is setting up the extra handler, something I wrestled with.

I used a solution based on the answer written by Andy Carlson. Keeping it general/extensible:

import google.cloud.logging
import logging

def is_cloud_handler(handler: logging.Handler) -> bool:
    """
    is_cloud_handler

    Returns True or False depending on whether the input is a
    google-cloud-logging handler class

    """
    accepted_handlers = (
        google.cloud.logging.handlers.StructuredLogHandler,
        google.cloud.logging.handlers.CloudLoggingHandler,
        google.cloud.logging.handlers.ContainerEngineHandler,
        google.cloud.logging.handlers.AppEngineHandler,
    )
    return isinstance(handler, accepted_handlers)


def set_up_logging():
    # here we assume you'll be using the basic logging methods
    # logging.info, logging.warn etc. which invoke the root logger
    client = google.cloud.logging.Client()
    client.setup_logging()

    root_logger = logging.getLogger()
    root_logger.handlers = [h for h in root_logger.handlers if is_cloud_handler(h)]

More context

For those who find this solution confusing

In Python there is a separation between 'loggers' and 'handlers': loggers generate logs, and handlers decide what happens to them. Thus, you can attach multiple handlers to the same logger (in case you want multiple things to happen to the logs from that logger).

The google-cloud-logging library suggests that you run its setup_logging method and then just use the basic logging methods of the built in logging library to create your logs. These are: logging.debug, logging.info, logging.warning, logging.error, and logging.critical (in escalating order of urgency).

All logging.Logger instances have the same methods, including a special Logger instance called the root logger. If you look at the source code for the basic logging methods, they simply call these methods on this root logger.

It's possible to set up specific Loggers, which is standard practice to demarcate logs generated by different areas of an application (rather than sending everything via the root logger). This is done using logging.getLogger("name-of-logger"). However, logging.getLogger() with no argument returns the root logger.

Meanwhile, the purpose of the google.cloud.logging.Client.setup_logging method is to attach a special log handler to the root logger. Thus, logs created using logging.info etc. will be handled by a google-cloud-logging handler. But you have to make sure no other handlers are also attached to the root logger.

Fortunately, Loggers have a property, .handlers, which is a list of attached log handlers. In this solution we just edit that list to ensure we have just one handler.

Answer 3

I solved this problem by overwriting the handlers property on my root logger immediately after calling the setup_logging method

import logging
from google.cloud import logging as gcp_logging
from google.cloud.logging.handlers import CloudLoggingHandler, ContainerEngineHandler, AppEngineHandler

logging_client = gcp_logging.Client()
logging_client.setup_logging(log_level=logging.INFO)
root_logger = logging.getLogger()
# use the GCP handler ONLY in order to prevent logs from getting written to STDERR
root_logger.handlers = [handler
                        for handler in root_logger.handlers
                        if isinstance(handler, (CloudLoggingHandler, ContainerEngineHandler, AppEngineHandler))]

To elaborate on this a bit, the client.setup_logging method sets up 2 handlers, a normal logging.StreamHandler and also a GCP-specific handler. So, logs will go to both stderr and Cloud Logging. You need to remove the stream handler from the handlers list to prevent the duplication.

EDIT: I have filed an issue with Google to add an argument to to make this less hacky.

Answer 4

Problem is in the way how logging client initializes root logger

    logger = logging.getLogger()
    logger.setLevel(log_level)
    logger.addHandler(handler)
    logger.addHandler(logging.StreamHandler())

it adds default stream handler in addition to Stackdriver handler. My workaround for now is to initialize appropriate Stackdriver handler manually:

            # this basically manually sets logger compatible with GKE/fluentd
            # as LoggingClient automatically add another StreamHandler - so 
            # log records are duplicated
            from google.cloud.logging.handlers import ContainerEngineHandler
            formatter = logging.Formatter("%(message)s")
            handler = ContainerEngineHandler(stream=sys.stderr)
            handler.setFormatter(formatter)
            handler.setLevel(level)
            root = logging.getLogger()
            root.addHandler(handler)
            root.setLevel(level)