1

While debugging a queue example below, I found a weird (to me) behavior related to the print function in Python 3.6. The below code works as expected however, if I change the "logger.info" with "print" function in the consumer function below, the consumer function hangs. Why is that so?

from queue import Queue
from threading import Thread
import logging

logging.basicConfig(format='%(asctime)s; %(name)s; %(levelname)s; %(message)s', level=logging.DEBUG)
logger = logging.getLogger(__name__)
logger.info('Starting...')


def consumer(q):
    while True:
        item = q.get()
        logger.info ("Working on item: {}".format(item))


def main():
    q = Queue()

    t = Thread(target=consumer, args=(q,))
    t.start()

    for i in range(3):
        q.put(i)

if __name__ == '__main__':
    main()

Output 1:

2018-02-20 09:24:29,630; __main__; INFO; Starting...
2018-02-20 09:24:29,631; __main__; INFO; Working on item: 0
2018-02-20 09:24:29,631; __main__; INFO; Working on item: 1
2018-02-20 09:24:29,631; __main__; INFO; Working on item: 2

Output 2:

2018-02-20 09:26:14,497; __main__; INFO; Starting...
Matej
  • 932
  • 4
  • 14
  • 22
  • Maybe its output buffering. In Python 3.x you have extra argument `flush` for `print` function. It's `False` by default. Maybe setting it to `True` will flush output buffer. – Ilija Feb 20 '18 at 15:35

1 Answers1

2

It is probably because of stdout buffering.

In Python 3.x you have extra argument flush for print function. It's False by default. Maybe setting it to True will flush output buffer.

However, what I wanted to point out is:

logger.info ("Working on item: {}".format(item))

You should not format string and form a logging message this way.

Proper way of doing it is:

logger.info("Working on item: %s", item)

or maybe

logger.info("Working on item: {item}", item=item)

Reason: Its better to delay logging message creation until it is really needed, and if it is needed.

You can find more about it here.

Ilija
  • 1,556
  • 1
  • 9
  • 12