Custom logger with time stamp in python
Question: I have lots of code on a project with print statements and wanted to make a
quick a dirty logger of these print statements and decided to go the custom
route. I managed to put together a logger that prints both to the terminal and
to a file (with the help of this site), but now I want to add a simple time
stamp to each statement and I am running into a weird issue.

Here is my logging class.

    
    
    class Logger(object):
        def __init__(self, stream):
            self.terminal = stream
            self.log = open("test.log", 'a')
    
        def write(self, message):
            self.terminal.flush()
            self.terminal.write(self.stamp() + message)
            self.log.write(self.stamp() + message)
    
        def stamp(self):
            d = datetime.today()
            string = d.strftime("[%H:%M:%S] ")
            return string
    

Notice the stamp method that I then attempt to use in the write method.

When running the following two lines I get an unexpected output:

    
    
    sys.stdout = Logger(sys.stdout)
    print("Hello World!")
    

Output:

    
    
    [11:10:47] Hello World![11:10:47]
    

This what the output also looks in the log file, however, I see no reason why
the string that I am adding appends to the end. Can someone help me here?

**UPDATE** See answer below. However, for quicker reference the issue is using
"print()" in general; replace it with sys.stdout.write after assigning the
variable.

Also use "logging" for long-term/larger projects right off the bat.


Answer: It calls the `.write()` method of your stream twice because in cpython `print`
calls the stream `.write()` method twice. The first time is with the object,
and the second time it writes a newline character. For example look at [line
138 in the `pprint` module in cpython
v3.5.2](https://hg.python.org/cpython/file/v3.5.2/Lib/pprint.py#l138)

    
    
    def pprint(self, object):
        self._format(object, self._stream, 0, 0, {}, 0)
        self._stream.write("\n")  # <- write() called again!
    

You can test this out:

    
    
    >>> from my_logger import Logger  # my_logger.py has your Logger class
    >>> import sys
    >>> sys.stdout = Logger(stream=sys.stdout)
    >>> sys.stdout.write('hi\n')
    [14:05:32] hi
    

You can replace `print(<blah>)` everywhere in your code using
[`sed`](https://www.gnu.org/software/sed/manual/sed.html).

    
    
    $ for mymodule in *.py; do
    > sed -i -E "s/print\((.+)\)/LOGGER.debug(\1)/" $mymodule
    > done
    

Check out [Python's Logging builtin
module](https://docs.python.org/2/library/logging.html). It has pretty
comprehensive logging including inclusion of a timestamp in all messages
format.

    
    
    import logging
    FORMAT = '%(asctime)-15s %(message)s'
    DATEFMT = '%Y-%m-%d %H:%M:%S'
    logging.basicConfig(format=FORMAT, datefmt=DATEFMT)
    logger = logging.getLogger(__name__)
    logger.setLevel(logging.DEBUG)
    
    logger.debug('message: %s', 'message')
    

This outputs `2016-07-29 11:44:20 message: message` to `stdout`. There are
also handlers to send output to files. There is a [basic
tutorial](https://docs.python.org/2/howto/logging.html#logging-basic-
tutorial), an [advanced
tutorial](https://docs.python.org/2/howto/logging.html#logging-advanced-
tutorial) and a [cookbook of common logging
recipes](https://docs.python.org/2/howto/logging-cookbook.html#logging-
cookbook).

There is an example of using [simultaneous file and console
loggers](https://docs.python.org/2.7/howto/logging-cookbook.html#using-
logging-in-multiple-modules) in the cookbook.

    
    
    import logging
    
    LOGGER = logging.getLogger(__name__)  # get logger named for this module
    LOGGER.setLevel(logging.DEBUG)  # set logger level to debug
    
    # create formatter
    LOG_DATEFMT = '%Y-%m-%d %H:%M:%S'
    LOG_FORMAT = ('\n[%(levelname)s/%(name)s:%(lineno)d] %(asctime)s ' +
                  '(%(processName)s/%(threadName)s)\n> %(message)s')
    FORMATTER = logging.Formatter(LOG_FORMAT, datefmt=LOG_DATEFMT)
    
    CH = logging.StreamHandler()  # create console handler
    CH.setLevel(logging.DEBUG)  # set handler level to debug
    CH.setFormatter(FORMATTER)  # add formatter to ch
    LOGGER.addHandler(CH)  # add console handler to logger
    
    FH = logging.FileHandler('myapp.log')  # create file handler
    FH.setLevel(logging.DEBUG)  # set handler level to debug
    FH.setFormatter(FORMATTER)  # add formatter to fh
    LOGGER.addHandler(FH)  # add file handler to logger
    
    LOGGER.debug('test: %s', 'hi')
    

This outputs:

    
    
    [DEBUG/__main__:22] 2016-07-29 12:20:45 (MainProcess/MainThread)
    > test: hi
    

to both console and file `myapp.log` simultaneously.

