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)

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.