Python Logging Module Output To Screen Lag

Question

In my python script, I am using the logging module with INFO going to a file and the screen:

fh_info = logging.FileHandler(info)
fh_info.setLevel(logging.INFO)
fh_info.setFormatter(formatter)

std_out_info = logging.StreamHandler()
std_out_info.setLevel(logging.INFO)

logger.addHandler(fh_info)
logger.addHandler(std_out_info)

But the issue I am having is that the messages got to the screen after the function is completed. For instance, in:

def getToken(self):
    msg = ("Initializing token....")
    logger.info(msg)
    sys.stdout.flush()
    try:
        jsonreq = ( {"auth": {"KEY:apiKeyCredentials": {
            "username": self.username,
            "apiKey": self.apikey}}})
        auth_headers = {'content-type': 'application/json'}
        r = requests.post(self.url, data=json.dumps(jsonreq), headers=auth_headers)
        self.jsonresp = json.loads(r.text)
        self.token = str(self.jsonresp['access']['token']['id'])
        msg = ("done!")
        logger.info(msg)
    except:
        msg = ("Bad name or apikey!")
        logger.error(msg)
        sys.exit()

The message "Initializing token...." will go to the screen after the operations in the function are completed. The makes for a long pause while authentication is going on with no output...then after authentication completes I see "Initializing token....done".

How can I make the logger.info(msg) stay in sync with the flow of the script and output to the screen in it's timely manner?

Most likely your output on STDOUT gets line buffered (which usually is a good thing). Try 1) Doing an explicit `sys.stdout.flush()` whenever you want to flush STDOUT and 2) running python in unbuffered mode using `python -u yourscript.py` — Lukas Graf, Nov 25 '13 at 18:06
Just noticed you're already doing `sys.stdout.flush()` - so disregard that please, and try unbuffered mode (`-u`). — Lukas Graf, Nov 25 '13 at 18:07
Try to use sleep to see any different: logger.info('start ...'); time.sleep(2); logger.info('done'); if it still not sync, then I guess the problem is from other part. Because I tried you init logger code with sleep part, it works in sync way. BTW, logging go to sys.stderr in linux. — PasteBT, Nov 25 '13 at 18:45
@PasteBT brought up a good point: If you register your own [`StreamHandler`](http://docs.python.org/2/library/logging.handlers.html#logging.StreamHandler) without specifying `StreamHandler(stream=sys.stdout)`, it will log to STDERR by default - which means you're currently flushing the wrong stream in your code. — Lukas Graf, Nov 25 '13 at 18:55

score 4 · Answer 1 · answered Nov 26 '13 at 01:14

4

You are not initialising the StreamHandler with sys.stdout, so it will use the documented default - sys.stderr. That's why your flushing of sys.stdout isn't having any effect - there's nothing the the code you posted which is causing writes to sys.stdout!

answered Nov 26 '13 at 01:14

Vinay Sajip

95,872
14
179
191

Wouldn't it be nicer if the Logger had a flush method? – sureshvv Feb 06 '16 at 09:03
@sureshw Loggers don't do I/O, they just route it. Handlers, which do I/O, *do* have a flush method. – Vinay Sajip Feb 06 '16 at 19:36
i meant as a shortcut for [x.flush() for x in logger.handlers] – sureshvv Feb 08 '16 at 09:48
@VinaySajip According to [this answer](http://stackoverflow.com/questions/16633911/does-python-logging-flush-every-log) there is no need to explicitly flush a `StreamHandler` object. – akhan Dec 22 '16 at 08:28
@akhan - that's correct. I didn't say a flush was needed, I merely answered why the flush in OP's code was having no effect. – Vinay Sajip Dec 22 '16 at 09:16
@VinaySajip In other words, since the flush to stderr is happening regardless, then why is the op observing lag? – akhan Dec 23 '16 at 07:36
@akhan Not enough information in the question to give a definitive answer. – Vinay Sajip Dec 23 '16 at 15:20

Python Logging Module Output To Screen Lag

1 Answers1