-1

What I want to Achieve ?

I want to dump all logs in a single line which got collected during a request.

Why I am doing this?

  • General approach, i.e. logger.info(), dumps log in file at same time when you call function. Due to this, Logs get mixed up and can't read them sequentially as multiple threads are using same file.

    By my approach, all logs will get collected in memory during request, will dump once just before we are returning response. Now I can read log easily as all logs belong to the request are in single line.

    Isn't it good approach, what are the problems can occur?

  • Less IO, I am storing all logs in memory and dumping at once.

    What I believe IO contribute some part of response time, also IO is more costly then Memory. My approach somehow contributing to improve performance.

    Am I wrong?

How am I trying to do ?

Creating a custom logging class which will be singleton (per request) on basis of log filename. It has it's own methods just like logger have i.e. info, error etc. But it will only store logs in the memory (collecting logs in list). We need to call dump method to log actually (calling actual .info, .error methods when whole request complete).

Is it wrong approach ?

Code Snippets

Assumptions: To achieve, We will only open multiprocesses in uwsgi not the multi threaded.

file: customlogging.py

import logging

class MyLogging(object):
    """This will return singleton object as per filename."""
    _instance = {}
    def __new__(cls, file_name):
        if not cls._instance.get(file_name):
            cls._instance = super(MyLogging, cls).__new__(cls, file_name)
        return cls._instance

    def __init__(self, file_name):
        self.logger = logging.getLogger(file_name')
        self.info_log = []
        self.error_log = []

    def log_append(self, logtype, msg):
        """
        Appending into log .
        """
        d = getattr(self, '%s_log' % logtype)
        d.append(msg)

    def info(self, msg):
        self.log_append('info', msg)

    def error(self, msg):
        self.log_append('error', msg)

    def dump(self):
        self.logger.info(",".join(self.info_log))
        self.logger.info(",".join(self.error_log))

file: app/abc.py

mylogger = MyLogging('app.abc')

def abc(request):
    mylogging.info(request.data)
    # doing something.
    mylogging.error("something")
    return httpresponse

file: utils.py

mylogger = MyLogging('app.abc')

def abc_util(arg):
    mylogging.info(arg)

file: middleware/dump_log.py

mylogger = MyLogging('app.abc')

class LogDumpMiddleware(object):
    def process_response(self, request, response):
        mylogger.dump()
        # Assumption: Multi Processes not multi threaded.
        mylogger._instance = None
        return response
  • 12factor.net/logs – jonrsharpe Dec 11 '16 at 20:09
  • It'd be good, if you could provide a bit more context to the problem. Furthermore it'd be helpful, if you described your approach, rather than posting your code. You might as well post some code, but don't just give a filename and the contents. – Paul Kertscher Dec 12 '16 at 9:09
  • @PaulK, I tried to add more details, Please check and let me know if you got the problem statement. – Anurag Dec 20 '16 at 10:26
2

Sure, something like that will work. I'd still advise against it.

You don't need logs when everything works as expected. You need logs to figure out why something went wrong. Any solution that defers writing to a log file needs to think about how the log will be saved in case something unexpected happens – like forgetting to call logger.dump(), or encountering an exception before you can call logger.dump(), or worst of all a bug within the logging system.

Deferring the log writes also means that the log file is no longer in exactly chronological order. In fact, your design sketch would only store the time stamp when the log was dumped, not for each individual log item. That makes it impossible to reconstruct the actual sequence and timing of events.

A good logging system has the following properties:

  • The log is machine readable. I can then write scripts to analyse a log file, e.g. extract all log entries that originated from a given request, extract all log entries from a specific module, convert the log file to another format, ….

  • If a log file is shared among processes/threads: Writes to the log are atomic. This ensures two log entries are never interleaved but are written one after another to the log file. Without this property, you might see corrupted and therefore potentially useless log files under high load.

  • Each log entry contains enough metadata to reconstruct the sequence of events in the program, and to help with debugging. In addition to the log message, these fields might be a timestamp with at least millisecond resolution, the log level (error/warning/info/debug), file+line of the log statement, process-/thread-/request-ID, name of enclosing class and method, ….

  • The log file will still be useful in case the program suddenly crashes. You'll want to know what events lead up to that failure. This means any output buffers should be flushed after each log entry (in C: fflush() function). If you are concerned about complete system crashes or power failures, you'll also want to make sure the data has been written to disk (under Posix systems: fsync() system call).

  • Logging should have very little overhead if that log level is deactivated. This is actually fairly difficult to pull of elegantly in Python. The largest source of logging-related slowness I've seen wasn't from IO, it was from unnecessary string formatting for log entries that would never be written.

If IO is currently your limiting factor, you'll have to analyse that a bit more before reaching the conclusion that you should mutilate the logging system. For example, I'd expect to see performance problems due to long seek times if you use hard disk drives, and store the log and a database on the same physical drive. I recommend that you profile your application to figure out where most time is spent. You can also benchmark your application under different log levels – how much faster is the program when any logging is disabled, compared to your normal settings? You can then calculate how much time at most you can save by deferring log writes.

  • 1
    The program-crash issue is usually addressed by having the log-writer in a separate OS process, which communicates with the application process via shared-memory. – rwong Dec 11 '16 at 11:58

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.