logging with CloudLoggingHandler from multiple processes

Question

Which is the preferred way to collect and send logs to google cloud logging when logs are produced by several processes ?

Here is my CloudLoggingHandler based proposal, would you care to criticize it ?

import google
from multiprocessing import Process
from logging import getLogger

class Worker(Process):
    def __init__(self):
        super(Worker, self).__init__()

    def __setup_logger(self):
        handler = CloudLoggingHandler(google.cloud.logging.Client(), name='log-name')                           
        logger = logging.getLogger()
        logger.setLevel(logging.DEBUG)
        google.cloud.logging.handlers.setup_logging(handler)

    def run(self):
        self.__setup_logger()
        for i in range(10):
            logging.warning("i=%d", i)

if __name__ == "__main__":
    for _ in range(2):
        w = Worker()
        w.start()

I read about queue based log handlers here, but CloudLoggingHandler uses a batch commit in an isolated thread, so queue based handlers would be overkill. Am I correct ?

Sources indicates that CloudLoggingHandler is thread safe, so it might be sufficient to have one instance of CloudLoggingHandler shared by all the processes. Would it work? if so isn't it to harsh ?

---

Edits below to answer @thomas-schultz.

I stuck to my proposal, mostly because I was prototyping, it worked "out of the box", and I did not check for performances issues. I'm reconsidering this choice.

Indeed, from what I understand the CloudLoggingHandler with BackgroundThreadTransport blocks the main thread until the log is sent to the logging endpoint. This would occur almost for each log line. Indeed, the batch is sent as soon as there is one log record (cf source).

In my dev environnement, when several processes log concurrently, it occurs that one processe waits up to 1s for the log to be sent. I guess that is mostly network cost, and it would shrink to "not so much" from within the google data centers.

I'm considering to define a StreamHandler which would push all the log record to a Queue. This queue would be read by a Process which would be in charge to sent the logs to the logging endpoint. This process might rely on CloudLoggingHandler to do that, if it is relevant.

Does this make sense ?

Answer 1

Here is how I plan to log to Google Cloud Logging from multiple processes. This solution uses only python 3 builtin logging handler (doc). In the example below I measure the time it take for the main process to log a message. The results shows that this solution allows to avoid for the main process to block while the log is sent to the logging endpoint. Of course it is useful only if your time consuming task is not done in the main process.

What do you think about this approach?

Queue: avg log call duration: 0.00004s
Queue: min log call duration: 0.00002s
Queue: max log call duration: 0.00018s

Cloud: avg log call duration: 0.03019s
Cloud: min log call duration: 0.00003s
Cloud: max log call duration: 0.16630s

Below a comprehensive example.

import sys
import os
import time
import google
import logging
import multiprocessing

from logging.handlers import QueueHandler, QueueListener
from google.cloud.logging.handlers import CloudLoggingHandler


def do(i):
    """
        Dummy function that times the log insertion.
    """
    t = time.time()
    logging.info('%dth message.' % i)
    return time.time() - t


if __name__ == '__main__':

    # The standard google cloud logging handler sends logs to the clooud logging endpoint.
    client = google.cloud.logging.Client()
    cloud_handler = CloudLoggingHandler(client=client, name="xyz")

    # A local handler is used to have feedbacks on what is going on.
    local_handler = logging.StreamHandler(sys.stdout)

    # Log records are put in the log queue.
    log_queue = multiprocessing.Queue()

    # The listener dequeues log records from the log queue. Each handler registered in the 
    # listener processes the log records.
    queue_listener = QueueListener(log_queue, local_handler, cloud_handler)
    queue_listener.start()

    # The queue handler pushes the log records to the log queue.
    queue_handler = QueueHandler(log_queue)

    # Setup the root loger to the handler we defined.
    root_logger = logging.getLogger()
    root_logger.setLevel(logging.INFO)
    root_logger.addHandler(queue_handler)

    n = 10

    # Emits logs and measure how fast it is with the 
    durations = [do(i) for i in range(n)]
    print('Queue: avg log call duration: %.5fs' % (sum(durations) / n))
    print('Queue: min log call duration: %.5fs' % min(durations))
    print('Queue: max log call duration: %.5fs' % max(durations))

    # Stop the queue listener.
    queue_listener.stop()

    # Remove the queue handler from the root logger.
    root_logger.removeHandler(queue_handler)

    # Setup the root loger to use CloudLoggingHandler.
    root_logger.setLevel(logging.INFO)
    root_logger.addHandler(local_handler)
    root_logger.addHandler(cloud_handler)

    # Emits logs and measure how fast it is with the 
    durations = [do(i) for i in range(n)]
    print('Queue: avg log call duration: %.5fs' % (sum(durations) / n))
    print('Queue: min log call duration: %.5fs' % min(durations))
    print('Queue: max log call duration: %.5fs' % max(durations))

Answer 2

I think it could be overkill unless you're running into connection issues or some kind of situation where queues would be required.

In that case, you could probably use the same instance of CloudLoggingHandler but there maybe some performance bottlenecks in doing so. I'm not entirely sure.

Here's more on integrating with Python's standard library logger. https://googlecloudplatform.github.io/google-cloud-python/stable/logging-usage.html#integration-with-python-logging-module

I'm curious if you arrived at a different answer?