Seek support in logging hooks

[johanjeppsson]

First of all; I really like this project. It makes creating nice looking progress bars a breeze compared to other solutions that I've tried in the past. Nice work!

Today I ran into an issue related to loggers after upgrading to 2.0.0. I'm using a RotatingFileHandler and don't disable existing loggers, which seems to cause issues with the internal logging in alive-progress. The following small example can be used to reproduce the issue that I'm seeing

from alive_progress import alive_bar
import logging
from logging.config import dictConfig

config = {
    "version": 1,
    "disable_existing_loggers": False,    # This causes the error
    "handlers": {"logfile": {
       "class": "logging.handlers.RotatingFileHandler",
        "filename": f"test.log",
        "maxBytes": 1000
        }
    },
    "root": {"level": "DEBUG", "handlers": ["logfile"]},
}

dictConfig(config)
logger = logging.getLogger('simple_example')

n = 1
with alive_bar(total=n) as bar:
    for i in range(n):
        logger.info(f"Currently at {i}")
        bar()

which results in the following error

on 0: --- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.7/logging/handlers.py", line 68, in emit
          if self.shouldRollover(record):
  File "/usr/lib/python3.7/logging/handlers.py", line 185, in shouldRollover
          self.stream.seek(0, 2)  #due to non-posix-compliant Windows feature
AttributeError: 'types.SimpleNamespace' object has no attribute 'seek'
Call stack:
  File "test_bar.py", line 23, in <module>
          logger.info(f"Currently at {i}")
Message: 'Currently at 0'
      Arguments: ()

[rsalmei]

Hey @johanjeppsson, thank you man!

Humm, I didn't know some internal logging used seek... I'm going to fix it asap!

[rsalmei]

Humm, I've analyzed the RotatingFileHandler code, and unfortunately it's not possible to support it in full. Of course I'll fix the error, but the auto-hook I've made works by exchanging all known handlers' streams at alive_bar start, for other ones that will enrich and correctly clear the lines of garbage when printing.

But in this rotating handler, when it detects a file rollover is due, it will close that file stream (the instrumented one by alive_bar) and assign another, which would not be instrumented... I don't really know what to do in this case.

[rsalmei]

Well, I'm also thinking about a kinda radical idea, I could maybe up one level, and instrument the handler itself, in addition of its stream... That way I could include a setter there, and detect any assignments. This would completely change my hook manager implementation, and break all tests...... argh But maybe it's worth it. I'm going to think about this in the next days.

[johanjeppsson]

Sounds good! Thanks for the quick response!

[rsalmei]

Hey @Miladiouss, The error you report is not the same as in this thread, maybe you posted in the wrong issue? Here is an AttributeError about 'seek', yours is a TypeError about an unhashable type...

Anyway, I've handled that exact error you mention in #107, but yours seems simple enough: alive-progress does not support nested bars. There's an issue open for that (#20) for a long time, but it's very hard and I don't have enough free time (or incentive) to implement that.

[rjkowalski]

Hi @rsalmei - I just upgraded from 1.6.1 to 2.3.1. I did not see the issue described above in 1.6.1 but now I have the same error as listed above.

[rsalmei]

Hello @rjkowalski. I think 1.6.1 didn't have any support for logging, did it? Anyway, unfortunately, I couldn't really act on this one. As I explained above, when the rotating handler does its thing, it removes the handler I had prepared with another one, so it breaks... It's not easy to support that.

[jfthuong]

Maybe we could add a Test for RotatingFileHandler?

https://github.com/rsalmei/alive-progress/blob/a3a940e9924c3ef45fe61f73f1979be3059da389/tests/core/test_hook_manager.py#L108

And maybe there could be a check of active loggers and raise some warning or exception to notify you that RotatingFileHandler is not supported: at least, the user will know that fails :)

[rsalmei]

Hey @jfthuong, I like my alive-progress bar to transparently show whenever it is asked, keeping all previous terminal content untouched. blessed uses curses, which enters a new terminal mode that clears the screen, it is MUCH MUCH easier that way...

Regarding the warning, it is perhaps a good idea. I'll try to think about that, or even implement the actual support if I can.

[rsalmei]

This is fixed! Should be available in the next release... 👍

[alexisteleco]

Hi, I agree with @johanjeppsson, this project is great!

I've been having this exact same problem too (I'm using RotatingFileHandler) and when I searched for it I discovered that it is solved! 🥳

So my only question is when the next release will be released, I'm using 2.4.1 at the moment (which pip says it's the newer one) and it is not fixed there. I do not want to put pressure or anything, just wanted to know an approximate date if possible.

Thanks again for this incredible piece of software!

[rsalmei]

Hi folks! Thanks, @alexisteleco!

I'm committing it at this exact moment!! I should release it very soon!

[rsalmei]

I'd just like to leave here a known issue: I could not implement that radical idea I was thinking about, so my previous comment remains correct:

But in this rotating handler, when it detects a file rollover is due, it will close that file stream (the instrumented one by alive_bar) and assign another, which would not be instrumented...

So, although this new version loses the enriched text when the rotation occurs, at least it does work!! Using the code from the OP, but with n=10 and maxBytes=100, this is what happens:

on 0: Currently at 0
on 1: Currently at 1
on 2: Currently at 2
on 3: Currently at 3
on 4: Currently at 4
Currently at 5
Currently at 6
Currently at 7
Currently at 8
Currently at 9