python when is logging.Handler flush-method called?

Question

This is my custom loggging handler

import logging
import datetime

from my_app.models import MyModel


class DbLogHandler(logging.Handler): # Inherit from logging.Handler
    def __init__(self):
        # run the regular Handler __init__
        logging.Handler.__init__(self)
        self.entries = []
        print("*****************[DB] INIT db handler")

    def emit(self, record):
        # instantiate the model
        print("@@@@@@@@@@@@@@@@@@@@", self.__hash__())
        print("*****************[DB] called emit on db handler")
        print("*****************[DB] entries has {0:d} entries "
                     "now".format(len(self.entries)))
        # print("*****************[DB] current record is {}".format(record.__dict__))
        try:
            revision_instance = getattr(record, 'revision', None)
            logEntry = MyModel(name=record.name,
                                  log_level_name=record.levelname,
                                  message = record.msg,
                                  module = record.module,
                                  func_name = record.funcName,
                                  line_no = record.lineno,
                                  exception = record.exc_text,
                                  revision = revision_instance
                                  )
            if revision_instance is None:
                return
            self.entries.append(logEntry)
            print("[+] entries has {0:d} entries "
                         "now".format(len(self.entries)))

        except Exception as ex:
            print(ex)
        return

    def flush(self):
        print("************************[*] Flushing {0:d} entries".format(len(self.entries)))
        if self.entries:
            MyModel.objects.bulk_create(self.entries)
            print("************************[+] Successfully flushed {0:d} log entries to "
                         "the DB".format(len(self.entries)))
        else:
            print("************************[*] No log entries for DB logger")

My log file tells me this

[2015-09-18 15:12:51,367: WARNING/Worker-2] [+] entries has 3 entries now
[2015-09-18 15:12:51,366: DEBUG/Worker-2] threedi_inpy.tasks.generate_inp_files[None]: {}
[2015-09-18 15:12:51,367: WARNING/Worker-2] @@@@@@@@@@@@@@@@@@@@
[2015-09-18 15:12:51,367: WARNING/Worker-2] 6865789
[2015-09-18 15:12:51,367: WARNING/Worker-2] *****************[DB] called emit on db handler
[2015-09-18 15:12:51,367: WARNING/Worker-2] *****************[DB] entries has 3 entries now
[2015-09-18 15:12:51,367: WARNING/Worker-2] [+] entries has 4 entries now
[2015-09-18 15:12:51,367: INFO/Worker-2] threedi_inpy.tasks.generate_inp_files[None]: [*] Trying to make_sqlite_models_entry for now
[2015-09-18 15:12:51,368: WARNING/Worker-2] @@@@@@@@@@@@@@@@@@@@
[2015-09-18 15:12:51,368: WARNING/Worker-2] 5511201
[2015-09-18 15:12:51,368: WARNING/Worker-2] *****************[DB] called emit on db handler
[2015-09-18 15:12:51,368: WARNING/Worker-2] *****************[DB] entries has 0 entries now
[2015-09-18 15:12:51,368: INFO/Worker-2] threedi_inpy.tasks.generate_inp_files[None]: Skipped directory /srv/var/models/lars_test/test9967b6-52ee-11e5-940c-0050569e25test92/.hg
[2015-09-18 15:12:51,368: WARNING/Worker-2] @@@@@@@@@@@@@@@@@@@@
[2015-09-18 15:12:51,369: WARNING/Worker-2] 5511201
[2015-09-18 15:12:51,369: WARNING/Worker-2] *****************[DB] called emit on db handler
[2015-09-18 15:12:51,369: WARNING/Worker-2] *****************[DB] entries has 0 entries now

The flush method is never called thus my entries will get lost. Thus, my fist question is: when is flush() called? Alternatively, how I could I write to the DB in bulk and not on every emit?

Answer 1

You are basically trying to write MemoryHandler

It is a handler that will store records in memory and calls flush whenever the maximum capacity is reached or when a certain level is logged. flush will then send the records to a target handler, which could be your database handler.

flush is indeed not called in the base handler, it's just defined in the API, it's up to the child classes to decide how and if to call it. The only case where it gets called is when logging.shutdown is called.

For example, MemoryHandler does this in emit (inherited from BufferingHandler):

    def emit(self, record):
    """
    Emit a record.

    Append the record. If shouldFlush() tells us to, call flush() to process
    the buffer.
    """
    self.buffer.append(record)
    if self.shouldFlush(record):
        self.flush()