Use with logging module

[jnjaeschke]

In my module, I use the python logging module to print out messages.

During the operation which I want to monitor using alive-progress it may happen that messages are sent out using the logging module. Then, artifacts of the bar remain in the console:

Loading the fmu took 0.34800148010253906 s.

Starting simulation at t=0.0 s.          | ▁▃▅ 0/1000 [0%] in 0s (0.0/s, eta: ?)
Simulation took 0.7570006847381592 s.███▌| ▅▇▇ 990/1000 [99%] in 0s (1126.2/s, eta: 0s)
Simulation finished at t=1000.0 s.
|████████████████████████████████████████| 1000/1000 [100%] in 0.9s (1096.43/s)

The first message ("loading ... took ...") was logged before i instantiated the alive bar. The other messages were emitted while the bar was active. I am using a vanilla StreamHandler that sends everything to stdout.

By the way - dunno if that's possible - is it possible to have the alive bar redirected to a logging module, too? Might be interesting to have the complete (or not, in case of an error!) progress bar in a log file. Gives structure...

By the way 2: it's pretty awesome :)

Cheers, Jan

[rsalmei]

Hey @jnjaeschke,

This is because the StreamHandler saves internally the stream it should log to, it is a constructor argument. If it is created before the alive_bar context manager, it got the actual stdout, not my print_hook, which knows how to clear the bar artifacts appropriately.

I've made this example:

$ ipython
Python 3.7.3 (default, May 20 2019, 22:39:32)
Type 'copyright', 'credits' or 'license' for more information
IPython 7.5.0 -- An enhanced Interactive Python. Type '?' for help.

In [1]: from alive_progress import alive_bar

In [2]: import logging, sys, time

In [3]: logging.basicConfig(stream=sys.stdout)
   ...: logger = logging.getLogger(__name__)
   ...: with alive_bar(100) as bar:
   ...:     alive_handler = logging.StreamHandler(sys.stdout)
   ...:     logger.addHandler(alive_handler)
   ...:     for i in range(100):
   ...:         time.sleep(.01)
   ...:         if i % 80 == 0: logger.warning('hey %s', i)
   ...:         bar()
   ...:
WARNING:__main__:hey 0                   | ▁▃▅ 0/100 [0%] in 0s (0.0/s, eta: ?)
on 0: hey 0

WARNING:__main__:hey 80████████▍         | ▃▅▇ 76/100 [76%] in 0s (87.5/s, eta: 0s)
on 80: hey 80

|████████████████████████████████████████| 100/100 [100%] in 1.2s (85.22/s)

In [4]:

Note the "WARNING" lines got garbage, because they came from the original StreamHandler that basicConfig created, which sends directly to stdout. But there's now cool "on XX:" lines, which came from the new StreamHandler I've created inside the alive_bar context manager... This one got the modifed stdout, the alive_bar print_hook, and all work as expected!

So, what you could do is, disable temporarily the outer handler, for example setting its log level to 100 like this:

In [4]: root = logging.getLogger()

In [5]: root.handlers[0].setLevel(100)

In [6]: with alive_bar(100) as bar:
    ...:     alive_handler = logging.StreamHandler(sys.stdout)
    ...:     logger.addHandler(alive_handler)
    ...:     for i in range(100):
    ...:         time.sleep(.01)
    ...:         if i % 80 == 0: logger.warning('hey %s', i)
    ...:         bar()
    ...:
on 0: hey 0

on 80: hey 80

|████████████████████████████████████████| 100/100 [100%] in 1.2s (85.48/s)

In [7]:

And after that, you could return its previous level 👍

[rsalmei]

I just didn't understand where did those newlines come from... 🤔

[rsalmei]

Regarding the by the ways, actually the alive_progress already does that! It will only refresh itself several times per second if the terminal reports itself as a tty. If it doesn't, I'll print only the final "receipt":

|████████████████████████████████████████| 100/100 [100%] in 1.2s (85.48/s)

So the log nicely receives only this milestone, so you know how fast your processing was.

And thank you man! I think it came out pretty awesome too 😃

[jnjaeschke]

Thanks for the quick response! I tried the following:

logger = logging.getLogger("test")
logger.addHandler(logging.StreamHandler(sys.stdout))
logger.warning("Message before progress bar")
sh = [h for h in logger.handlers] 
for h in sh:
    h.setLevel(100)
    logger.removeHandler(h)
with alive_progress.alive_bar(100) as bar:
    new_h = logging.StreamHandler(sys.stdout)
    logger.addHandler(new_h)
    for i in range(100):
        if i % 80 == 0:
            logger.warning("Message in progress bar at %s", i)
        sleep(.1)
        bar()
    logger.removeHandler(new_h)

for h in sh:
    h.setLevel(logger.level)
    logger.addHandler(h)
logger.warning("Message after progress bar")

But the output looks like this:

Message before progress bar
on 0: Message in progress bar at 0       | ▁▃▅ 0/100 [0%] in 0s (0.0/s, eta: ?)

on 80: Message in progress bar at 80     | ▅▃▁ 80/100 [80%] in 8s (9.9/s, eta: 2s)

|████████████████████████████████████████| 100/100 [100%] in 10.1s (9.91/s) ta: 0s)
Message after progress bar

Could this be a windows-specific issue? I tried this in cmd.exe, powershell and the Pycharm Terminal...

[rsalmei]

Yes, unfortunately it seems to be windows specific... In my macOS, I got the expected:

Message before progress bar
on 0: Message in progress bar at 0

on 80: Message in progress bar at 80

|████████████████████████████████████████| 100/100 [100%] in 10.3s (9.73/s)
Message after progress bar

[rsalmei]

Well, I'm going to close this one. Feel free to reopen if you have any more concerns!

[lschmelzeisen]

Hey, I'd like to reopen this. I like alive-progress a lot, but it's current interaction with logging is keeping me from using it.

The workaround you posted of disabling the outer logging handler and adding our own works:

In [4]: root = logging.getLogger()
In [5]: root.handlers[0].setLevel(100)
In [6]: with alive_bar(100) as bar:
   ...:     alive_handler = logging.StreamHandler(sys.stdout)
   ...:     logger.addHandler(alive_handler)
   ...:     for i in range(100):
   ...:         time.sleep(.01)
   ...:         if i % 80 == 0: logger.warning('hey %s', i)
   ...:         bar()
   ...:

However, I think this is a very ugly hack and it's certainly cumbersome to always have to remember to reset/reattach a logging handler whenever you want to use a progress bar. Could something like this either be added to alive_bar() (possible with a parameter), or be configured only once when setting up the root logging handler and not with every progress bar usage?

Additionally, the current code only prints the final progress bar receipt to the log file.

It will only refresh itself several times per second if the terminal reports itself as a tty. If it doesn't, I'll print only the final "receipt":

|████████████████████████████████████████| 100/100 [100%] in 1.2s (85.48/s)

So the log nicely receives only this milestone, so you know how fast your processing was.

However, I also like to have progress bars in my log files. One reason for that would be so that I can retrace at which exact point a log event occurred. Obviously, having a spinner spams the log file. Could options be added to:

• log the current progress bar state every time an item has been complete (i.e., bar() is called) without the terminal escape codes
• log the current progress bar state on every n-th completed item
• log the current progress bar state on every n-th completed item and additionally before any other log message is sent (such that context of the log message is visible)

[rsalmei]

Hello again @lschmelzeisen.

Yes, you're right, I should properly support logging. Actually, in spite of my workaround "working", now I see it looses the log level, which is very weird. Instead of this:

on 0: hey 0

I would like to see this:

on 0: WARNING:__main__:hey 0

Or this, I'm not so sure:

WARNING:__main__:on 0: hey 0

But what my workaround did is for sure flawed. I need to better study the source code of logging, and figure out a way to properly support this.

[rsalmei]

Regarding the progress bar in log files, I don't think you or anyone would like to see that in a log, would you?

|                                        | ▆█▆ 0/10 [0%] in 0s (0.0/s, eta: 10s)
|████                                    | ▅▃▁ 1/10 [10%] in 1s (1.0/s, eta: 9s)
|████████                                | ▂▂▄ 2/10 [20%] in 2s (0.9/s, eta: 8s)
|████████████                            | ▃▅▇ 3/10 [30%] in 3s (0.9/s, eta: 7s)
|████████████████                        | ▆█▆ 4/10 [40%] in 4s (0.9/s, eta: 6s)
|████████████████████                    | ▇▅▃ 5/10 [50%] in 5s (0.9/s, eta: 5s)
|████████████████████████                | ▄▂▂ 6/10 [60%] in 6s (0.9/s, eta: 4s)
|████████████████████████████            | ▂▄▆ 7/10 [70%] in 7s (0.9/s, eta: 3s)
|████████████████████████████████        | ▅▇▇ 8/10 [80%] in 8s (0.9/s, eta: 2s)
|████████████████████████████████████    | █▆▄ 9/10 [90%] in 9s (0.9/s, eta: 1s)
|████████████████████████████████████████| 10/10 [100%] in 10.2s (0.99/s)

To retrace the exact point a log event has occurred -> that's exactly the motivation I've implemented the print hooking system. If you print anything inside an alive_bar context, that line will output enriched with the exact position that context were. So the log would nicely be:

on 8: found corrupted sector.
|████████████████████████████████████████| 10/10 [100%] in 10.2s (0.99/s)

Don't you think that's way nicer than output several progress bar's lines to the log? Possibly hundreds or even thousands...

[lschmelzeisen]

To be honest, I wouldn't mind having the complete bars in my log. The on 8: found corrupted sector. solution would of course also work but not sure how this would work with nested bars.

[rsalmei]

Hey, I'm glad to report I've finally mastered this! 🎉 The proper logging support will be included in the next major version!

on 0: WARNING:__main__:hey 0
on 80: WARNING:__main__:hey 80
|████████████████████████████████████████| 100/100 [100%] in 1.2s (85.97/s)

Now it is all automatically setup! The code to generate the above output is only:

from alive_progress import alive_bar
import time, logging

logging.basicConfig()
logger = logging.getLogger(__name__)

with alive_bar(100) as bar:
    for i in range(100):
        time.sleep(.01)
        if i % 80 == 0:
            logger.warning('hey %s', i)
        bar()

[rsalmei]

It's gonna be released in https://github.com/rsalmei/alive-progress/pull/46 🎉

[rsalmei]

It's released!! 🥳 Care to test it and share, please?

[lschmelzeisen]

Sadly, upon quick inspection, I noticed two bugs:

• Trying to run the code you posted above fails in Python 3.6:

  from alive_progress import alive_bar
  import time, logging
  
  logging.basicConfig()
  logger = logging.getLogger(__name__)
  
  with alive_bar(100) as bar:
      for i in range(100):
          time.sleep(.01)
          if i % 80 == 0:
              logger.warning('hey %s', i)
          bar()

  $ python test.py 
  Traceback (most recent call last):
  File "test.py", line 7, in <module>
    with alive_bar(100) as bar:
  File "/usr/lib/python3.6/contextlib.py", line 81, in __enter__
    return next(self.gen)
  File "/home/lukas/test-alive-progress/.venv/lib/python3.6/site-packages/alive_progress/core/progress.py", line 274, in alive_bar
    start_monitoring()
  File "/home/lukas/test-alive-progress/.venv/lib/python3.6/site-packages/alive_progress/core/progress.py", line 185, in start_monitoring
    run.before_handlers = install_logging_hook()
  File "/home/lukas/test-alive-progress/.venv/lib/python3.6/site-packages/alive_progress/core/logging_hook.py", line 7, in install_logging_hook
    return {h: h.setStream(sys.stdout) for h in root.handlers
  File "/home/lukas/test-alive-progress/.venv/lib/python3.6/site-packages/alive_progress/core/logging_hook.py", line 8, in <dictcomp>
    if isinstance(h, logging.StreamHandler)}
  AttributeError: 'FileHandler' object has no attribute 'setStream'

• When running in Python 3.7+ the above script seemingly works as expected. However, trying to log somewhere else but to stdout fails. Take the following snippet which is supposed to log to a file test.log:

  from alive_progress import alive_bar
  import time, logging
  
  logging.basicConfig(filename="test.log")
  logger = logging.getLogger(__name__)
  
  with alive_bar(100) as bar:
    for i in range(100):
        time.sleep(.01)
        if i % 80 == 0:
            logger.warning('hey %s', i)
        bar()

  The file is indeed created, but the logging output is still all printed to console and the file remains empty:

  $ python test.py 
  on 0: WARNING:__main__:hey 0
  
  on 80: WARNING:__main__:hey 80
  
  |████████████████████████████████████████| 100/100 [100%] in 1.1s (94.88/s)

[rsalmei]

Hey @lschmelzeisen, thank you for finding those. This new release ended up way bigger than I initially intended, and those bugs have slipped. But it's ok, I'm going to fix both of them today.

[rsalmei]

Hey man, both problems are fixed! 👍 I'm gonna release it soon, just trying to sort out another weird thing with wrapping in #19.

[rsalmei]

It automatically closed when I merged the PR... Anyway, it is released! Can you test it again?

[rsalmei]

Hey @lschmelzeisen, please report back when you can.

[lschmelzeisen]

Sorry, that it took me a while to get back to this.

First of, the Python 3.6 bug seems to be fixed 👍

And it is now logging successfully to the file test.log:

WARNING:__main__:hey 0
WARNING:__main__:hey 80

However, when we compare this to the console output, the on 0: and on 80: are missing. Is this intended?

[rsalmei]

Hey, no problem. Yeah, unfortunately it is intended. I've realized it would be way harder to get the header into files also, as it would require to instantiate multiple simultaneous print hooks instead of a global one, each one tracking a different stream. It is possible, but I've decided not to adventure myself in it yet. At least it is all working now...

[rsalmei]

I've just included in the future version:

    # FIXME the header is not showing up in files used by logging.StreamHandler.
    # need to control multiple print hooks here, one for each stream.

[rsalmei]

Hey @lschmelzeisen, great news, I've made it!

While working on the v2, I could not create tests for the print_hook function, and after hard working I realized it needed to receive the stream externally, which was half way implementing this! So, I took the extra mile and worked on this!

So this code correctly prints to the console:

While simultaneously writing to file AND WITH THE HEADER:

How cool is that? 👍

[rsalmei]

Well @lschmelzeisen, I'm going to close this, if you find anything more when I release the 2.0 you can reopen this. Thank you man.

[rsalmei]

Hey, I'm going to keep this open for now, to see what will enter in the next milestone.

[rsalmei]

Less tickets is better than more.

[MoHoseinHabibi]

hello i have same problem here i tried below code:

import sys
import logging
from alive_progress import alive_bar
import time

logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)

fh = logging.FileHandler('log.txt', 'a', 'utf-8')
fh.setLevel(logging.DEBUG)
formatter = logging.Formatter('fh %(asctime)s  %(name)s:%(lineno)d %(levelname)s: %(message)s')
fh.setFormatter(formatter)
logger.addHandler(fh)

sh = logging.StreamHandler(sys.stdout)
sh.setLevel(logging.INFO)
formatter = logging.Formatter('sh %(asctime)s  %(name)s:%(lineno)d %(levelname)s: %(message)s')
sh.setFormatter(formatter)
logger.addHandler(sh)

with alive_bar(100) as bar:
    for i in range(100):
        time.sleep(.01)
        if i % 80 == 0:
            logger.warning('hey %s', i)
        bar()

and it did not work as it should be:

I'm using Python 3.8.5 on windows 10

[TheTechRobo]

Wasn't that the bug found with Windows?

[AlphonsG]

@mohammadof313 same issue as well

[rsalmei]

It works perfectly here, it seems it is related to Windows.

Unfortunately, I can't do much about it since I do not have a windows dev machine. Please look for other issues related to windows here, since this you reported has nothing to do with logging.