Default configuration does not look great for Windows users

[wimglenn]

It prints escape sequences to terminal.

Python 3.8.0
colorama v0.4.1
structlog v19.2.0

(in foreground is powershell, background is cmd.exe, Windows 10)

[hynek]

Is this a regression? I.e. does 19.1.0 look fine everything else being equal?

[wimglenn]

Yes, this is a regression. Maybe 3b534af 👀

[hynek]

Yeah, me too! Could you double-check if colorama.init() is called at all please?

[wimglenn]

>>> import colorama
>>> colorama.init = lambda: print("yep!")
>>> structlog.get_logger().msg("hello")
yep!
�[2m2019-11-05 14:49.13�[0m �[1mhello�[0m

[hynek]

Oof. WTF then?

[wimglenn]

It might be the print logger needs to reacquire sys.stdout after colorama init. But I'm not a Windows user personally, so not too sure - just guessing here. When I get back on a windows box I can bisect it ..

[hynek]

OK just to be sure and before I start pulling people into this – could you please:

• try with Python 3.7
• double-check it doesn't happen with structlog 19.1?

thanks!

[wimglenn]

                    +--------------+--------------+
                    | Python-3.7.5 | Python-3.8.0 |
+-------------------+--------------+--------------+
| structlog==19.1.0 | ok           | ok           |
+-------------------+--------------+--------------+
| structlog==19.2.0 | bug          | bug          |
+-------------------+--------------+--------------+ 

[ahtik]

Confirming @wimglenn observation, after moving to the colorama lazy init, PrintLogger _file assignment from sys.stdout comes earlier than the lazy ConsoleRenderer colorama.init(), so the colorama StreamWrapper is never used for write.

The issue is only with Windows, all good with Linux, but can't debug the Linux process right now to understand the init difference.

Could it be that currently there is simply no rewriting by colorama required for Linux and that's why it also works fine without wrapped colorama stream for any terminal accepting a TTY?

According to https://github.com/tartley/colorama On other platforms, calling init() has no effect.

[MarkusH]

I did some debugging, and can confirm that 3b534af is in fact the commit that broke the behavior. Here's why:

• Running import structlog imports structlog._config which imports structlog.dev.ConsoleRenderer and instantiates the latter with colors=_has_colorama on module level, as part of _BUILTIN_DEFAULT_PROCESSORS. Before said commit, that instantiation would've called colorama.init(). However, this call is now delayed.
• Importing structlog will also have imported get_logger(). Calling get_logger() will effectively return an instance of BoundLoggerLazyProxy.
• Calling msg() on the BoundLoggerLazyProxy instance, will cause a call to BoundLoggerLazyProxy.__getattr__() since msg isn't an attribute on that class, which will call BoundLoggerLazyProxy.bind()
• In BoundLoggerLazyProxy.bind(), PrintLoggerFactory.__call__() is run, instantiating a PrintLogger with file=None, causing it to store self._file=sys.stdout.
• The BoundLoggerLazyProxy.bind() returns an instance of BoundLogger with _logger being said PrintLogger instance. The BoundLogger instance doesn't have a msg attribute either. Thus, BoundLoggerBase._proxy_to_logger will be called, which in turn eventually executes ConsoleRenderer.__call__ which will now wrap sys.stdout through colorama.init().
• But since the PrintLogger instance already cached sys.stdout, the wrapped sys.stdout stream is not used, but the original one.

I see two ways forward:

1. Revert said commit
2. Make the PrintLogger lazily use sys.stdout when needed.

To me, reverting 3b534af seems to be the more appropriate and efficient approach.

[hynek]

Ugh but both are terrible. :( One looks bad on Windows, the other has an unavoidable import side-effect :(