python - logging stdout, but getting second blank line on each entry

Question

I'm on a Linux Ubuntu 12.04 system. I have been using this code to log all stdout and stderr + additional logging on INFO level to a file..

class LogFile(object):
    def __init__(self, name=None):
        self.logger = logging.getLogger(name)

    def write(self, msg, level=logging.INFO):
        self.logger.log(level, msg)

    def flush(self):
        for handler in self.logger.handlers:
            handler.flush()

logging.basicConfig(level=logging.INFO, 
                    format='%(asctime)s %(name)-12s %(levelname)-8s %(message)s',
                    datefmt='%m-%d-%y %H:%M:%S',
                    filename='logging.log')
sys.stdout = LogFile('stdout')
sys.stderr = LogFile('stderr')

For some reason whenever I get an entry it's always followed by a blank line, here is a small output of my log:

08-09-12 09:52:54 stdout       INFO     CheckCon: Checking Portal access.
08-09-12 09:52:54 stdout       INFO     

08-09-12 09:52:54 stdout       INFO     CheckCon: Portal ping successful.
08-09-12 09:52:54 stdout       INFO     

08-09-12 09:53:08 stderr       INFO     Bottle server starting up (using PasteServer())...

08-09-12 09:53:08 stderr       INFO     Listening on http://0.0.0.0:8654/

08-09-12 09:53:08 stderr       INFO     Hit Ctrl-C to quit.


08-09-12 09:53:08 stdout       INFO     URI: Generated https://*****
08-09-12 09:53:08 stdout       INFO     

08-09-12 09:53:08 stdout       INFO     CheckCon: Checking Portal access.
08-09-12 09:53:08 stdout       INFO     

08-09-12 09:53:08 stdout       INFO     serving on 0.0.0.0:8654 view at http://127.0.0.1:8654
08-09-12 09:53:08 stdout       INFO     

08-09-12 09:53:08 stdout       INFO     CheckCon: Google ping successful.
08-09-12 09:53:08 stdout       INFO     

This is how it looks in the file, with both an empty stdout line and then followed by an entire blank line. If you notice the output from the bottle server seems to not have the empty line but still a blank line between each line.

Anyone know what is causing this or how I can prevent it ?

EDIT:

From suggestions I have changed all my print to logging.info, I still have the problem that bottle and paste server is doing regular prints :\

so my log now with modified format format='%(asctime)s %(levelname)-4s: %(message)s':

08-09-12 12:44:40 INFO: URI: Generated https://****
08-09-12 12:44:40 INFO: CheckCon: Checking Portal access.
08-09-12 12:44:40 INFO: serving on 0.0.0.0:9002 view at http://127.0.0.1:9002
08-09-12 12:44:40 INFO: 

08-09-12 12:44:40 INFO: CheckCon: Google ping successful.
08-09-12 12:44:40 INFO: FullW: opening url: ****
08-09-12 12:44:40 INFO: FullW: showing.
08-09-12 12:44:40 INFO: LOOP: starting.

From what I can see the additional empty line is also because of the empty info line, so getting closer now..

Edit to clarify output: The interesting bit:

+++08-09-12 13:01:04 stdout       INFO     serving on 0.0.0.0:9002 view at     http://127.0.0.1:9002+++
+++08-09-12 13:01:04 stdout       INFO     
+++

Final Edit:

Changed my write to check if the length of the msg is under 2 chars, and that eliminated the blank lines.. still not 100% sure of the reason though.

def write(self, msg, level=logging.INFO):
    if len(msg) < 2:
        pass
    else:
        self.logger.log(level, msg)

Pillar

Besides, I would suggest to put the level= parameter to __init__(), not to write(). – Devotee

sorry glglgl I do not understand what you mean? – Pillar

Just for clarity, how does it look with a run where the format is set to +++%(asctime)s %(name)-12s %(levelname)-8s %(message)s+++? – Monomania

What I mean is to have def __init__(self, name=None, level=logging.INFO):, keeping the level inside the object and using it in write(). So you keep the flexibility to change it without having to adjust every call of write(). Or you can have both - provide a default on __init__() and use that if it is not overridden in write(). – Devotee

Answer 1

This is due to the way how print works.

I have modified your example so that I have a print (level, msg) in the write() method.

It shows me the following:

>>> x=LogFile("foo")
>>> print >>x, "123\n321\n444", "321", "222",
(20, '123\n321\n444')
(20, ' ')
(20, '321')
(20, ' ')
(20, '222')
>>> print >>x, "123\n321\n444", "321", "222"
(20, ' ')
(20, '123\n321\n444')
(20, ' ')
(20, '321')
(20, ' ')
(20, '222')
(20, '\n')

And if each of this calls is transferred into a logger call, you get an entry for each of them.

In order to cope with that, you could implement a kind of buffering which only calls logger.log() for complete lines and on closing.

Devotee

I can't figure out your answer. Is this happening to OP because of \n? I'm actually trying to recreate the behavior OP wanted to get rid of. – Retiarius

Answer 2

What I can think is that, since you overwrite sys.stdout, the actual command writing the logging lines will have a newline appended: sys.stdout.write("log text\n"). The logging module/methods will append a newline themselves, so you get two newlines.

That should, however, only show a completely blank line, not an empty line with just <date> <name> <level>. That might be caused by single sys.stdout.write("\n") statements elsewhere.

The simplest way I can think of to prevent this, is to strip the newline from msg, and check whether message is empty. Not the most beautiful, but if that works, the newline is probably the cause, and you could work from there:

def write(self, msg, level=logging.INFO):
    msg = msg.rstrip("\n")
    if msg:
        self.logger.log(level, msg)

Villager

You would be right if it was only that. But alas, print makes split calls for each component and for the separating ' ' and '\n'. – Devotee

It just seems odd that the application that's being used, doesn't use Python logging in the first place. Just using print statements doesn't feel right in this case. – Villager

I can change all my prints to logging but I still have the issue of a blank line between each log input. – Pillar