Prevent apps from crashing when sys.stderr is None (pythonw and pyinstaller 5.7)

[ElliotGarbus]

Kivy apps will crash if run from pythonw or if they are built with pyinstaller 5.7. The reason is that these runtimes set sys.stderr to None, causing a recursion error in the python logger. This fix will not load the ConsoleHandler if sys.stderr is None. This preserves the behavior prior to pyinstaller 5.7, and allows correct operation under pythonw.exe

Edit: Updated comment to reflect the solution.

This will fix this issue: #8074

Here is a small test I used developing the fix. The design of the logger redirects messages written to stderr to the logfile. That behavior is retained. If this code is executed with pythonw (or is built with pyinstaller 5.7) on a version of kivy without the fix - it will fail to run.

import sys

initial_stderror = sys.stderr  # at startup sys.stderror == None

from kivy.app import App
from kivy.uix.label import Label
from kivy.logger import Logger
from kivy.lang.builder import Builder
import itertools

kv = """
BoxLayout:
    orientation: 'vertical'
    AnchorLayout
        Button:
            size_hint: None, None
            size: dp(200), dp(48)
            text: 'Say Hello'
            on_release: label.say_hello()
    HelloLabel:
        id: label
        size_hint_y: None
        height: dp(48)
        text: 'Nice to meet you'
"""


class HelloLabel(Label):
    def __init__(self, **kwargs):
        super().__init__(**kwargs)
        self.hellos = itertools.cycle(['Hello to you!', 'Hey There!', "What's up?"])

    def say_hello(self):
        self.text = next(self.hellos)
        Logger.info(f'{self.text=}')
        # writes to stderr should be logged under pythonw or pyinstaller, but not written to the console
        print('print to stderr', file=sys.stderr)
        sys.stderr.write('write to stderr\n')


class ExampleWithPyinstallerApp(App):
    def build(self):
        return Builder.load_string(kv)

    def on_stop(self):
        Logger.info(f'sys.stderr before kivy loads: {initial_stderror}; sys.stderr at on_stop: {sys.stderr}')


ExampleWithPyinstallerApp().run()

Maintainer merge checklist

• Title is descriptive/clear for inclusion in release notes.
• Applied a Component: xxx label.
• Applied the api-deprecation or api-break label.
• Applied the release-highlight label to be highlighted in release notes.
• Added to the milestone version it was merged into.
• Unittests are included in PR.
• Properly documented, including versionadded, versionchanged as needed.

[pythonic64]

Why not test if stderr exist at line 598 and change it to if sys.stderr and 'KIVY_NO_CONSOLELOG' not in os.environ:?

I don't think Kivy should set environment variables as that should be left to users.

[ElliotGarbus]

Why not test if stderr exist at line 598 and change it to if sys.stderr and 'KIVY_NO_CONSOLELOG' not in os.environ:?

I don't think Kivy should set environment variables as that should be left to users.

Fair enough -that was my original implementation. I changed it for 2 reasons.

1. I thought setting the environment variable was more explicit
2. There is an ordering dependency between line 629

   kivy/kivy/logger.py

   Line 629 in d696932

   sys.stderr = ProcessingStream("stderr", Logger.warning)

   
   where stderr is redefined, and line 620 where the call to add_kivy_handlers(logging.root) would be using stderr in the if statement. It felt more 'defensive' to check stderr earlier in the flow.

This is not a strongly held opinion. If you would like me to do in the other way, I'm happy to update the PR. Let me know your thoughts.

[ElliotGarbus]

@pythonic64

Here is an idea to capture the "benefits" of my approach, without setting the environment variable. Create a new global variable that mirrors the name of the environment variable and use this in the add_kivy_handlers() function.
At around line 616:

KIVY_NO_CONSOLE_LOG =  not sys.stderr or 'KIVY_NO_CONSOLELOG' in os.environ

and then in add_kivy_handler(), at line 598

 if not KIVY_NO_CONSOLELOG:
    # load console log handler

What do you think?

[Julian-O]

I think it is a bit of overkill to use os.environ to signal a parameter to a piece of code 20 lines higher.

Why not move the check up into add_kivy_handlers instead.

i.e. change line 597-598 to say:

# Don't output to stderr if it doesn't exist (e.g. no console window) or if overridden
if (sys.stderr is not None) and ('KIVY_NO_CONSOLELOG' not in os.environ):

(Other than that, looks good.)

[ElliotGarbus]

Requested change completed

[Julian-O]

I am not an approved reviewer, but I was the last to spend much time in this area of the code, and it LGTM.

[pythonic64]

@ElliotGarbus Parenthesis are redundant and and you could have used my suggestion #8345 (comment) which is shorter.

[ElliotGarbus]

@ElliotGarbus Parenthesis are redundant and and you could have used my suggestion #8345 (comment) which is shorter.

Thanks for the feedback.
I used the suggestion from @Julian-O. I think testing for None is more precises and the parenthesis improve readability.
If you're an approving reviewer, and would like the change I would be happy to do it. Otherwise, I'll let it stand until the code is reviewed by an approver.

[misl6]

I like the shorter version from pythonic64 as it looks cleaner, but more importantly, can we add a test that covers this case so it does not happen again?

[ElliotGarbus]

I'll make the change and figure out the testing...

[ElliotGarbus]

@Julian-O I can see you have done some work with the kivy logger. I don't quite see how to test this fix.
I'm a logging novice, and have not used pytest before (but I'm willing to learn).

UPDATED: I have a clue.

Here is my WIP:

import sys


def test_logger_fix_8345():
    """
    The test checks that the ConsoleHandler is not in the Logger
    handlers list if stderr is None.  Test sets stderr to None.
    If the Console handler is found, the test fails.
    Pythonw and Pyinstaller 5.7+ (with console set to false) set stderr
    to None.
    :return:
    """
    from kivy.logger import Logger, add_kivy_handlers, ConsoleHandler
    sys.stderr = None
    console_handler_found = False
    add_kivy_handlers(Logger)
    for handler in Logger.handlers:
        if isinstance(handler, ConsoleHandler):
            console_handler_found = True
    assert console_handler_found is False

Still need to integrate the test. I assume I need to save and restore the state of sys.stderr - is that correct?

[Julian-O]

@ElliotGarbus:

• This function should be included in test_logger.py (which already imports sys).
• I know pytest fiddles with sys.stderr before calling your test method, function, but I don't know if it gets upset it you fiddle with it too. I would play it safe and record the old value (original_stderr = sys.stderr' before sys.stderr = Noneand thensys.stderr = original_stderr` at the end.
• I think you need to set stderror to None before the import of logger, because that is when the check is done, isn't it?
• The test scripts are executed three different times , with three different values for KIVY_LOG_MODE. [This is done in the action scripts that call the test code.] You may need to put a @pytest.mark.skipif check on your test - there are examples in the file - so it only runs in some modes, not others.
• In KIVY mode (the default) and MIXED, the handlers should be added automatically, so you don't need to call add_kivy_handlers. In PYTHON mode, the handlers aren't added, so you will need to call it yourself.
• Purely a style issue: I would make the search for a console handler into one line:

console_handler_found  = any(isinstance(handler, ConsoleHandler) for handler in Logger.handlers)

• Generally, avoid using is for values apart from None. The last line should read:

assert not console_handler_found

or even better, make the assert self-commenting if it fails.

assert not console_handler_found, "Console handler added, despite sys.stderr being None"

[ElliotGarbus]

@Julian-O
Thanks for the detailed feedback. I appreciate it!

You mentioned: "I think you need to set stderr to None before the import of logger, because that is when the check is done, isn't it?"

There are 2 actions on import. sys.stderr is reassigned, then add_kivy_handlers() is called. For the test, I will need to do the import then set sys,.stderr to None, then call add_kivy_handlers(). I may need to remove the handlers prior to calling add_kivy_handlers(), I'll know better when I put this test into test_logger.py and see the behavior.

Thanks again for your help!

[Julian-O]

I am worried we might be talking about different things, and confusing each other.

I see three different levels that you could test at.

You could do an integration test. This would be to call the code with pythonw.exe or pyinstaller, and show it works now where it didn't before. That would be a solid test, and would test your understanding of the cause of the problem, but will be tricky to produce in pytest.

You could do a low-level unit test. This would be to test just the code in kivy_add_handlers() without any of the surrounding code. That would be a reasonable approach. I think that is what you were aiming to do. The best way to do that would be to only run the test when in PYTHON mode. (i.e. decorate the test to skipif it is not python mode). In that case, the implicit steps (stderr being redirected to a class and add_kivy_handlers being called) are not performed, so you don't need to do the work to "undo" them. You can redirect stderr and call add_kivy_handlers() yourself, and check that the console handlers are not added.

I thought you were doing a mid-level unit-test, where you test the way the whole module behaves. In that case, you would test it in Kivy and Mixed modes. You would redirect sys.stderr to None first, before the import, and then immediately after the import check that the implicit call to add_kivy_handlers worked correctly, without calling it again. If you were being thorough, you would repeat the test in Python mode, but this time explicitly call add_kivy_handlers(), because even though I don't think many people will use this feature [i.e. manually add the Kivy loggers] it is advertised as possible.

I think I would prefer a mid-level test, but I would accept a low-level one. Doing both a low-level and mid-level test is a bit "belt-and-braces" - I would suggest only doing one, unless you really want to be sure.

Finally: The order of the code (except in PYTHON mode) is add the handlers first and then redirect stderr (so any output to stderr is captured by the logging systems). I don't think this is very important for this discussion.

[ElliotGarbus]

@Julian-O
Thanks for the additional feedback. I don't think we were talking past each other at all. I will admit to only narrowly thinking about the KIVY mode of the logger. Using PYTHON mode for the low-level test makes lots of sense. It had not even occurred to me.

And looking back at the logger.py source code I see I misspoke about the order of event 😞. Thanks for catching that. I'll get back to this later today.

[ElliotGarbus]

@Julian-O
How should I invoke pytest? I think I have a configuration issue or an simply calling pytest incorrectly. Do I need to set the env vars?

I'm using a pip installed kivy, and jumping into the venv, and editing the test file.

I'm current invoking:
(venv) PS C:\Users\ellio\PycharmProjects\ExampleWithPyinstaller\venv\Lib\site-packages\kivy\tests> pytest test_logger.py::test_logger_fix_8345

Here is my test, with some added logging output:

def test_logger_fix_8345():
    """
    The test checks that the ConsoleHandler is not in the Logger
    handlers list if stderr is None.  Test sets stderr to None,
    if the Console handler is found, the test fails.
    Pythonw and Pyinstaller 5.7+ (with console set to false) set stderr
    to None.
    """
    from kivy.logger import Logger, add_kivy_handlers, ConsoleHandler
    Logger.info(f'Initial state: {Logger.handlers=} {LOG_MODE=} {os.environ.get("KIVY_LOG_MODE")=}')
    original_sys_stderr = sys.stderr
    sys.stderr = None
    add_kivy_handlers(Logger)
    Logger.info(f'{Logger.handlers=} {LOG_MODE=}')
    sys.stderr = original_sys_stderr  # restore sys.stderr
    console_handler_found = any(isinstance(handler, ConsoleHandler) for handler in Logger.handlers)
    assert not console_handler_found, "Console handler added, despite sys.stderr being None"

Here is the relevant log outputs:

[INFO   ] Initial state: Logger.handlers=[] LOG_MODE='KIVY' os.environ.get("KIVY_LOG_MODE")=None
[INFO   ] Logger.handlers=[<LoggerHistory (NOTSET)>, <FileHandler (NOTSET)>] LOG_MODE='KIVY'

I'm surprised to see KIVY_LOG_MODE is None,
Thanks again!

[Julian-O]

I'm surprised to see KIVY_LOG_MODE is None,

That's working as designed. You haven't set the environment variable, so it is None. There is a line in test_logger.py that says:

LOG_MODE = os.environ.get("KIVY_LOG_MODE", "KIVY")

i.e. if no environment variable is set, default to KIVY mode. [Defaulting to KIVY mode was to make sure existing Kivy apps still worked like they used to.]

How should I invoke pytest?

The automated tests (which run when you push to GitHub or do a pull request) runs the test three times. (Look at windows_ci.ps1 for an example of where that is specified.)

First it leaves KIVY_LOG_MODE unset and runs all the tests (except those covered with a skip)
Then it sets KIVY_LOG_MODE to PYTHON, and runs only the tests marked as "logmodepython".
Then it sets KIVY_LOG_MODE to MIXED, and runs only the tests marked as "logmodemixed".

Because you don't want to run the test in KIVY mode, you should add a decorator:

@pytest.mark.skipif(
    LOG_MODE != "PYTHON",
    reason="Requires KIVY_LOG_MODE==PYTHON to run.",
)

You can run pytest test_logger.py::test_logger_fix_8345 and confirm that the test is skipped.

Because you do want to the test to be run in the second pass, you should add another decorator:

@pytest.mark.logmodepython

Now, to invoke it, you need to first set the environment variable. I see you are on Windows so the command should be SET KIVY_LOGGING_MODE=PYTHON.

Running the tests now with pytest test_logger.py::test_logger_fix_8345 should work.
If you run pytest -m logmodepython test_logger.py it should run a small suite of tests, including your test.

I am happy with what I am seeing, but one thing confuses me. Because you ran your existing test in KIVY mode, add_kivy_handlers() was presumably called twice - once implicitly on import (including a Console Log), and once explicitly by your test (without adding another ConsoleLog). I would have expected the test to fail, but you don't mention that it did.

[ElliotGarbus]

I am happy with what I am seeing, but one thing confuses me. Because you ran your existing test in KIVY mode, add_kivy_handlers() was presumably called twice - once implicitly on import (including a Console Log), and once explicitly by your test (without adding another ConsoleLog). I would have expected the test to fail, but you don't mention that it did.

The environment variable is not set to 'KIVY', it is None. Note the message from the logger, this is after kivy.logger is imported:

[INFO ] Initial state: Logger.handlers=[] LOG_MODE='KIVY' os.environ.get("KIVY_LOG_MODE")=None

The Logger evaluates the environment variable - and in this case effectively defaults to PYTHON. We can see none of the handlers are loaded. How/where does pyinstaller set the environment variable?

Thanks again for your guidance.

[Julian-O]

The environment variable is not set to 'KIVY', it is None.

Yes. (Well, pedantically it is not set at all, and the os.environ.get call defaults to None, but yes.)

The Logger evaluates the environment variable - and in this case effectively defaults to PYTHON.

It shouldn't be the case that it defaults to PYTHON. There is a line in logger.py:

KIVY_LOG_MODE = os.environ.get("KIVY_LOG_MODE", "KIVY")

i.e. if the environment variable is not set, default to KIVY.

We can see none of the handlers are loaded.

That has me flustered. I wonder why not.

How/where does pyinstaller set the environment variable?

I have almost no knowledge about pyinstaller. I doubt it sets the KIVY_LOG_MODE environment variable. Does it set NO_CONSOLE_LOG one?

[Julian-O]

Slaps forehead Of course! I see the problem!

In KIVY mode (the default), a logger called "Kivy" is created, but the handlers are added to the root logger. Kivy sends log messages to the Kivy logger, but it has no handlers, so the event escalate up the tree to the root logger, and is handled there. Any custom logger that a client creates will also be handled by root logger, and go through the Kivy handlers.

In MIXED mode, a logger called "Kivy" is created and the handlers are added directly to that. So now, the events raised by Kivy are handled by the Kivy loggers, and events send to other loggers can be handled however the user wants.

In PYTHON mode, a logger called "Kivy" is created, but no handlers are added. A user may choose to add Kivy handlers, or not, wherever they like.

So, in the case of this test:

• No environment variable is set, so it defaults to KIVY mode.
• A logger called Kivy is created, and no handlers are implicitly added.
• The root logger has kivy handlers implicitly added.
• The test checks if the kivy logger has handlers, and finds it doesn't. It doesn't notice that the root logger DOES have handlers!
• It adds more handlers to the kivy logger (so now there are two sets of handlers at different points in the logger tree).

This explains why it is running now.
I think limiting it to PYTHON mode, as described earlier, is still the right direction.

[ElliotGarbus]

Agreed!
(And looking at windows_c1.ps1 I see how the tests are run.)

[ElliotGarbus]

@misl6 Requested changes have been made, and a test has been added.
@Julian-O Thanks for the assistance!

[misl6]

PEP8 checks are failing with:

./kivy/tests/test_logger.py:511:81: E501 line too long (99 > 80 characters)

Can you please rebase on top of latest master and make sure it passes the PEP8 checks?

[misl6]

LGTM. Thank you!