Rename .closed property to avoid recursion

[bbayles]

Re: issue #196, this PR changes one aspect of #164 that was causing me problems.

When using autoreset=True, this check seems to happen over and over. This method is calling itself, since StreamWrapper can be the stream.

Adding a print statement here:

Checking closure...
Checking closure...
Checking closure...
Checking closure...
Checking closure...
Checking closure...
Checking closure...
Checking closure...
Checking closure...
Checking closure...
Checking closure...
Checking closure...
Checking closure...
Checking closure...
Checking closure...
Checking closure...
Checking closure...
Checking closure...
Checking closure...

So we basically have a name collision. In order to avoid that I've renamed the StreamWrapper.closed property to .is_closed. I'm happy to name it something else, or turn it back into a method instead of a property.

[Delgan]

Argh, I'm sorry to having introduced such regression with my commit... 😬

Thanks for having investigated this and quickly found a successful solution! 😃

I would like to examine this bug too, but I'm unable to reproduce the error. Basic example works fine:

from colorama import init, Fore
init(autoreset=True)
print(Fore.RED + 'some red text')
print('automatically back to default color again')

I can't figure out how to introduce the offending recursion. 😕

Basically, I would like to reproduce and understand the bug to:

• Try to add proper unit tests
• Ensure that this can't occur with isatty()
• See if an alternative implementation can avoid the duplication between .closed and .is_closed

@bbayles Do you have some code snippet I could use to trigger the bug please?

[bbayles]

The problem is that things stack up. If I add a debug statement to the closed property on the master branch:

    @property
    def closed(self):
        print('is closed?')
        stream = self.__wrapped
        return not hasattr(stream, 'closed') or stream.closed

Then do something like this will produce this output:

>>> import colorama
... import sys
... 
... colorama.init(autoreset=True)
is closed?
is closed?
is closed?
is closed?

Switching to an older version (or my branch here), you get this:

>>> import colorama
... import sys
... 
... colorama.init(autoreset=True)
is closed?
is closed?

So there are more checks after 2057f03.

Subsequent calls to init (on master) produce an explosion of checks - I found this when running unit tests, which exercise the same code over and over. The second call produces 12 checks. The third produces 28. The fourth 60... I think it's 2^n - 4 calls.

On an older verison (or my branch here), it's always two checks.

[Delgan]

@bbayles Thanks for the explanations!

So, there is no infinite recursion nor method calling itself (just method calling the same method, but the one of the wrapped stream), right? The issue is caused by too much nested calls, occuring while checking .closed in reset_all(), which is only called if autoreset=True.

To better vizualise what caused these excessive calls after 2057f03, I drew the call stack before and after your fix.

Before your fix, accessing stream.closed results in first calling hasattr(wrapped, 'closed') and then accessing wrapped.closed.

@property
def closed(self):
    stream = self.__wrapped
    return not hasattr(stream, 'closed') or stream.closed

But as hasattr(wrapped, 'closed') is implemented by calling getattr(wrapped, 'closed') (and checking if an error occurs), this causes exploding nested calls as this is equivalent to accessing wrapped.closed and hence double checking the nested stream, and this get worse as the number of nested streams increases. The same problem happens while calling .isatty().

For example if init() is called three times, the resulting stream is equivalent to StreamWrapper(StreamWrapper(StreamWrapper(sys.stderr))), let's rename it to A(B(C(sys.stderr))).

Before your fix, the call stack would look like this:

A.closed
  ├ hasattr(B, 'closed')
  │  └ getattr(B, 'closed')
  │       ├ hasattr(C, 'closed')
  │       │   └ getattr(C, 'closed')
  │       │       ├ hasattr(sys.stderr, 'closed')
  │       │       │   └ getattr(sys.stderr, 'closed')
  │       │       └ sys.stderr.closed
  │       └ C.closed
  │           ├ hasattr(sys.stderr, 'closed')
  │           │   └ getattr(sys.stderr, 'closed')
  │           └ sys.stderr.closed            
  └ B.closed
      ├ hasattr(C, 'closed')
      │   └ getattr(C, 'closed')
      │       ├ hasattr(sys.stderr, 'closed')
      │       │    └ getattr(sys.stderr, 'closed')
      │       └ sys.stderr.closed
      └ C.closed
          ├ hasattr(sys.stderr, 'closed')
          │   └ getattr(sys.stderr, 'closed')
          └ sys.stderr.closed  

As your fix removes the .closed property, trying to accessing it fallbacks to __getattr__.

def __getattr__(self, name):
    return getattr(self.__wrapped, name)

The calls stack looks like this while accessing .is_closed:

A.is_closed
  ├ hasattr(B, 'closed')
  │   └ getattr(B, 'closed')
  │       └ __getattr__(B, 'closed')
  │           └ getattr(C, 'closed')
  │               └ __getattr__(C, 'closed')
  │                   └ getattr(sys.stderr, 'closed')
  └ B.closed
      └ __getattr__(B, 'closed')
          └ getattr(C, 'closed')
              └ __getattr__(C, 'closed')
                  └ getattr(sys.stderr, 'closed')

Much shorter, and prevent the number of calls to exponentially grows!

I think we can have the best of both worlds, that is keep the linear number of calls while accessing .closed, by simply replacing the hasattr() call appropriately.

What do you think of re-implementing the property like this:

@property
def closed(self):
    stream = self.__wrapped
    try:
        return stream.closed
    except AttributeError:
        return True

The resulting call stack would be:

A.closed
  └ B.closed
      └ C.closed
          └ sys.stderr.closed

Even simpler!

The same fix should be done for .isatty(). That's way, the StreamWrapper() would stay transparently equivalent to the stream it wraps.

[bbayles]

The try/except looks nicer, but I still get exponential behavior when I test your method.

    @property
    def closed(self):
        print('is this closed?')
        stream = self.__wrapped
        try:
            return stream.closed
        except AttributeError:
            return True

>>> import colorama
... colorama.init(autoreset=True)
is this closed?
is this closed?
is this closed?
is this closed?
>>> colorama.init(autoreset=True)
is this closed?
is this closed?
is this closed?
is this closed?
is this closed?
is this closed?
is this closed?
is this closed?

[Delgan]

@bbayles It doesn't seem exponential on my computer, more like 2 6 12 20 30 42 56 72 90.

You should also tries to add the print() in the __getattr__() under the condition if name == "closed" to fully see all recursion calls on your branch.

By the way, this makes me wonder... As the print() is called from inside the colorama module, does not that risk to interfer?... Because as sys.stdout is wrapped by a StreamWrapper with autoreset=True, calling print() will trigger the .closed check in reset_all(), hence causing excessive calls. 🤔

I made my tests by adding a global n variable in ansitowin32.py that I increment within the .closed property, and I added a print_n() function that I call between two init().

[bbayles]

Re: whether it's exponential, I think the number shouldn't be growing at all.

Re: printing; we can reproduce the same issue printing to stderr instead of stdout; I don't think it matters.

My main thought is that the exponential behavior in the currently released version is significant, and will probably cause problems with downstream projects, at least in test suites. It's probably appropriate to apply my fix here (or revert 2057f03) and release 0.4.1?

[wiggin15]

By the way, this makes me wonder... As the print() is called from inside the colorama module, does not that risk to interfer?

It does. The reason you get this growing number of calls is because you are using "autoreset" and debug-printing from inside the "closed" property. When colorama auto-resets, it checks whether the stream is closed to print the reset sequence. So if every call to "closed" causes a print, it also causes a reset and causes another call to "closed". That would explain the recursion in the first case and the growing prints in after your changes.
In other words, it looks like your debug-printing is what is causing the trouble. There must be another issue in #196, but there isn't enough information there to investigate.

[Delgan]

Re: whether it's exponential, I think the number shouldn't be growing at all.

@bbayles The number has to grown, each subsequent call to init() wrap and replace the sys.stderr. So, if you wrap an already wrapped stream, accessing .closed will need two calls down to the original sys.stderr where the closed value is retrieved. If you call init() again, three calls will be needed, etc. The only reason you may think this number don't grow with your implementation is because you don't add print() in the __getattr__ function, but the nested calls are there.

My main thought is that the exponential behavior in the currently released version is significant, and will probably cause problems with downstream projects, at least in test suites. It's probably appropriate to apply my fix here (or revert 2057f03) and release 0.4.1?

I agree with you, the current code on master is prone to exponential calls. My thought is that we can fix it by re-implementing the .closed property properly rather than adding a new method.

There must be another issue in #196, but there isn't enough information there to investigate.

@wiggin15 I think I understood the issue, as explained in my second message, there is indeed a problem with excessive nested calls, even by omitting erroneous calls to print(). The callstacks should be quite straightforward to vizualise the issue (at least I thought 😁 ).

[bbayles]

Re: issue #196, the exponential calls were causing my hanging problem.

Re: a fix, you're welcome to close this PR and go with some other fix. I'm happy as long as PyPI gets updated promptly to remove the exponential behavior.

[Delgan]

@bbayles Yes, fixing this should be done as soon as possible, thanks again for having reported the issue I introduced... 😀

I implemented an alternative fix solution as discussed, see #198