Lines joined when running pyprind alongside the logging module

[fat-lobyte]

Hi!

I was trying to run both pyprind and the builtin python module logging at the same time. This, however did not handle particularly well:

import time
import pyprind
import logging

logging.basicConfig(level=logging.INFO)

n = 15

bar = pyprind.ProgPercent(n)
for i in range(n):
        time.sleep(1)
        bar.update()
        logging.info("Something happened.")

The output looks like this:

[  6 %] Time elapsed: 00:00:01 | ETA: 00:00:14INFO:root:Something happened.
[ 13 %] Time elapsed: 00:00:02 | ETA: 00:00:13INFO:root:Something happened.
[ 20 %] Time elapsed: 00:00:03 | ETA: 00:00:12INFO:root:Something happened.
[ 26 %] Time elapsed: 00:00:04 | ETA: 00:00:11INFO:root:Something happened.
[ 33 %] Time elapsed: 00:00:05 | ETA: 00:00:10INFO:root:Something happened.
[ 40 %] Time elapsed: 00:00:06 | ETA: 00:00:09INFO:root:Something happened.
[ 46 %] Time elapsed: 00:00:07 | ETA: 00:00:08INFO:root:Something happened.
[ 53 %] Time elapsed: 00:00:08 | ETA: 00:00:07INFO:root:Something happened.
[ 60 %] Time elapsed: 00:00:09 | ETA: 00:00:06INFO:root:Something happened.
[ 66 %] Time elapsed: 00:00:10 | ETA: 00:00:05INFO:root:Something happened.
[ 73 %] Time elapsed: 00:00:11 | ETA: 00:00:04INFO:root:Something happened.
[ 80 %] Time elapsed: 00:00:12 | ETA: 00:00:03INFO:root:Something happened.
[ 86 %] Time elapsed: 00:00:13 | ETA: 00:00:02INFO:root:Something happened.
[ 93 %] Time elapsed: 00:00:14 | ETA: 00:00:01INFO:root:Something happened.
[100 %] Time elapsed: 00:00:15 | ETA: 00:00:00
Total time elapsed: 00:00:15
INFO:root:Something happened.

As you see, the lines from pyprind and logging are joined. This is somewhat random in a real world scenario, but happens most of the time.

I have not yet found any fix or workaround. Any ideas?

[rasbt]

Sorry for the late response @fat-lobyte, somehow, I missed the notification about this issue!

One way to solve the problem is to add a newline character at the beginning of the logging string. E.g.,

E.g.,

import time
import pyprind
import logging

logging.basicConfig(format='\n%(message)s', level=logging.INFO)

n = 15

bar = pyprind.ProgPercent(n, stream=1)
for i in range(n):
        time.sleep(1)
        bar.update()
        logging.info("Something happened.")

Which then produces the following:

[  6 %] Time elapsed: 00:00:01 | ETA: 00:00:14
Something happened.
[ 13 %] Time elapsed: 00:00:02 | ETA: 00:00:13
Something happened.
[ 20 %] Time elapsed: 00:00:03 | ETA: 00:00:12
Something happened.
[ 26 %] Time elapsed: 00:00:04 | ETA: 00:00:11
Something happened.
[ 33 %] Time elapsed: 00:00:05 | ETA: 00:00:10
Something happened.
[ 40 %] Time elapsed: 00:00:06 | ETA: 00:00:09
Something happened.
...

Hope this is what you were looking for?

[akors]

Thanks for the reply.

That's not exactly what I was looking for, the problem is that outside the loop, all messages will have extra newlines. Also, the progress bar can be turned off and the output looks ugly then.

Do I infer correctly that there's not a way inside pyprind to fix this?

[rasbt]

Oh okay. Hm, I am not sure if there's a good way to avoid that; I think it's more like a limitation of the shell environment. The only way I could think of would be to print "PyPrind" to stdout and forward the logging to a log file. E.g.,

Initializing the bar as

bar = pyprind.ProgPercent(n, stream=1)

(note the stream=1, which is stdout; the default is stream=2, which is stderr)

Then in the shell, running it via:

python test.py * 2> pathToLogFile.log
[100 %] Time elapsed: 00:00:15 | ETA: 00:00:00
Total time elapsed: 00:00:15

The accompanying logfile will look like this then:

INFO:root:Something happened.
INFO:root:Something happened.
INFO:root:Something happened.
INFO:root:Something happened.
INFO:root:Something happened.
INFO:root:Something happened.
INFO:root:Something happened.
INFO:root:Something happened.
INFO:root:Something happened.
INFO:root:Something happened.
INFO:root:Something happened.
INFO:root:Something happened.
INFO:root:Something happened.
INFO:root:Something happened.
INFO:root:Something happened.