Logging module ignored when progressbar not used

[NicoHood]

#!/usr/bin/env python3

import progressbar
import logging

progressbar.streams.wrap_stderr()

logger = logging.getLogger(__name__)
logging.basicConfig(level=logging.DEBUG)
logger.info('test')
logger.info('test')
logger.info('test')

# count = 50000
# with progressbar.ProgressBar(max_value=count) as bar:
#     for i in range(count):
#         #logger.info('test')
#         bar.update(i)

ref #129
If you do not use the progressbar module, all logger traces are ignored when used with progressbar.streams.wrap_stderr()

Using 0.32.0

[wolph]

Guess I'll have to create some sort of global semaphore to actually start capturing the logs after wrapping. Didn't consider issues like these when I implemented the wrapping.

[NicoHood]

This is really annoying as I first thought i was coding wrong. But just the traces (logg info) disappeared. And when I hit ctrl+c all showed up instantly. Luckily we have a simple testcase.

[wolph]

Yes... I can imagine.

Originally the feature was intended to only be used on-demand, but the global stream wrapping changes the scenario quite a bit. Issues like these can be a pain to debug.... sorry about that

[pbeza]

Any idea for hotfix?

[wolph]

Manually flushing is always an option, so you could add a "flush" filter or handler to your logger:

progressbar.streams.flush()

I'm hoping to get a new release out today featuring a semaphore to fix the issue.

[wolph]

I"ve pushed an update to the develop branch which appears to solve the issue. I'm still testing it to make sure that takes care of everything but it looks good for the time being :)

[wolph]

The new version has been released :)

[NicoHood]

New version in testing. I will give devs one more week to respond to the package upgrade on archlinux.

[pbeza]

I tested it with the following example:

#!/usr/bin/env python3
import time
import logging
import progressbar

progressbar.streams.wrap_stderr()
logging.basicConfig()

bar = progressbar.ProgressBar()
for i in bar(range(10)):
    logging.error('Got %d', i)
    time.sleep(0.2)

and I got this output (click to see screenshot). I expected that there will be one progress bar that will be updated – just like here (click to see screenshot):

#!/usr/bin/env python3
import time
import progressbar

bar = progressbar.ProgressBar(redirect_stdout=True)
for i in range(10):
    print('Some text {}'.format(i))
    time.sleep(0.1)
    bar.update(i)

Also note that first character of ERROR:root:Got X (E character ) is printed as a last character in line instead of first one. Why is that?

(I'm not sure if this those issues are strictly related to your recent fix.)

[wolph]

It's related to the print order, unfortunately these are hard to properly test automatically :(
At least part of the issue is related to this fix but at the moment I'm completely unsure why or how...

I must be overlooking something obvious but I'm not seeing it yet.

[wolph]

Ah... I found the issue. It's specific to the logger.

Obviously flush() is a pretty common mnemonic for a io object, and the logger calls the flush method internally therefore breaking the output...