Update to Example 5 Python
It appears that I missed an interesting error when developing Example 5 for Python. It is a bit complex, so I’m relying on the advanced formatting of this webpage to help explain it better than I can via email or in a short post to the class. I’ll start with a short version, and then include a longer discussion of the problem and how I came to a solution that I feel is very helpful reading for anyone learning to program and solve these issues in their own work.
tl;dr - The Short Version
Currently pytest has a bug that causes errors when logging to sys.stderr
when running code inside of pytest
.
As best I can tell, pytest
tries to capture all output being printed to sys.stderr
by redirecting it to a buffer (a virtual file) when running the tests. Once it is done, it will close the buffer and redirect output back to sys.stderr
. Unfortunately, our logger does not realize this, and it may continue to try and write data to the buffer that is now closed, resulting in the ValueError: I/O operation on closed file
error message seen in the output.
There are several methods to determine if code is running under pytest
and disable logging in that case.
I recommend this method:
import sys
# get the root logger
logger = logging.getLogger()
# disable if pytest is running
if "pytest" in sys.modules:
logger.disabled = True
You will need to add this code to any file that you add logging to, in order to prevent errors from pytest
. Alternatively, you can disable the handler that prints to sys.stderr
and instead just use a file handler.
The Long Version
Since this is an advanced programming course, I figure that it is worth a bit of a “deep dive” into this situation so you can understand what I found, the efforts I went through to solve it, and how things are really working behind the scenes.
This is a bit of cognitive apprenticeship, where I attempt to show you my thought processes and how I go about solving a problem like this. My hope is that you’ll be able to learn from this process and possibly use this knowledge to help you solve your own problems in the future.
Unfortunately, in the world of higher education, we spend way too much time focusing on narrowly-scoped, previously-solved problems, to allow you to learn in an environment where we know a solution is possible in a set amount of time. In the real world, however, you’ll be constantly presented with broadly-scoped, open-ended problems like this one, where you’ll have to do some exploration to find possible causes and solutions, and then use your own background and knowledge to determine what solutions, if any, are available.
So, here goes.
The Error
When you run pytest
in Example 5 after adding some logging code as directed in the video, you will see many pages of errors printed to the terminal. In my testing, the terminal in Codio printed errors for several minutes before finally stopping. A screenshot of a small portion of those errors is below.
When this happens, you may be able to use CTRL + C to stop the output, but in many cases I simply had to close the terminal tab in Codio.
What Happened
When I developed this example, I focused on the debugging portion first, and then later added the logging code. However, I neglected to run pytest
after adding the logging code to my model solution, and did not encounter this error in my initial testing. That was an oversight on my part.
As you work on this project, you may end up adding the logging code first while still working on debugging the errors in the project. In that case, you will most likely run tox
or pytest
to run the unit tests contained in the project with the logging code in place. That will cause the error to appear. As soon as I ran tox
in my existing model solution, my code presented this error.
How I solved the problem
The process of finding a solution for this problem went in three phases.
Phase 1 - Searching
First, I attempted to Google some of the error message and a few things that I suspected were at play. I already had a hunch that the error itself was coming from the logging code, since I had added that to my model solution last. After reproducing the bug in my solution, I set out to solve it. Some Google search phrases I used:
pytest logging stderr write to closed file
- Including keywords pytest
and logging
as well as the stderr
stream and a bit of the error message.
pytest stream.write(msg) I/O operation on closed file
- adding more details such as the line of code causing the error and the exact error messages.
"pytest" stream.write(msg) I/O operation on closed file
- putting "pytest"
in quotes will find results that always include that keyword
There were others, but this was the most fruitful.
Phase 2 - Isolate the Error
In several of those searches, I came across a few bug reports on GitHub, specifically within the pytest
project’s repository. Bug reports and discussions on GitHub are usually very fruitful when looking for technical errors that include code and error messages, so I looked into a few of them.
- ValueError: I/O Operation on closed file (#14) - this was the first one I found. However, I quickly ruled it out, as it was first posted in 2010 and mainly seemed to use Python 2 instead of Python 3. After scrolling through the discussion, nothing really seemed to fit the situation I was in, so I ignored it and moved on. However, it did reference the next issue…
- Improve error message when tests use closed stdout/stderr (capture) (#5743) - this one felt like it was a bit closer. In this report, they discuss the fact that pytest will redirect and close system streams such as
sys.stderr
as part of the test. It was also much more recent, and some of the error messages they were running into were similar to what I was seeing.
- pytest 4.5 floods the output with logging errors when logging from atexit handlers (#5282) - similar to the one above, this one was getting closer to the issue I was seeing, though it wasn’t an exact match. By reading these three thread, I was starting to get a feel for the crux of the error - if our logger is trying to write to any of the output streams, like
sys.stderr
or sys.stdout
, then most likely pytest
would interfere with that and cause this error. Thankfully, the last two issues both referenced this issue…
- pytest capture logging error still happening (#5502) - this report had a lot of discussion on it, but pretty much sealed the deal for me. One of the core
pytest
developers posted a message that included this text:
What I believe is happening is:
- pytest changes
sys.stdout
and sys.stderr
to a buffer while importing test modules.
- If there’s user code setting up logging and/or creating a
logging.StreamHandler
at the import level, it will attach itself to pytest’s buffer.
- When pytest is about to finish the test session, it will restore
sys.stdout
and sys.stderr
to the original values, and close the “capture” buffer.
- Here the problem happens: if any message is emitted at this point, the
StreamHandler
will try to attach itself to the buffer, hence the error.
So, we’ve now found what we suspect is the error. All we have to do is figure out how to resolve it.
Phase 3 - The Fix
Unfortunately, issue #5502 is still open as of this writing, so we needed a way to get around this error. With some quick testing, I was able to confirm the error went away if I removed the StreamHandler
from the existing logging code. So, I decided that the best way to deal with this was to find some way to disable logging while the code is running as part of a unit test. This is a somewhat common, though discouraged, trick in programming. Ideally you don’t want to hide any code from the unit tests, but in some instances you want to make sure that the unit tests don’t actually change live data, such as the actual database used by this program. So, you can “protect” the code that connects to the database and make sure it cannot run as part of a unit test.
A quick Google search for determine if code is running under pytest python
quickly lead me to a StackOverflow post discussing this very issue. Great! I had quickly found a pretty good resource that might lead me to a solution.
Within the discussion, there are a few solutions suggested, and helpfully ranked by the upvotes from other users.
- Solution 1 - simply check
if "pytest" in sys.modules:
since the pytest
application will always be loaded when running a test. This solution seemed pretty simple and didn’t have many obvious side effects, provided your application didn’t load pytest
as part of its normal execution.
- Solution 2 - a solution that points to a section of the pytest Manual that shows the preferred way of doing this. In short, we place some code in the
conftest.py
file, which is only executed as part of a unit test, to update a value in our code, and then check that value where needed. This looks promising, and is probably the correct answer that would work in all cases, but also requires significantly more code and adds a structural dependency between our code and the conftest.py
file.
- Solution 3 - a third solution suggests checking for the existence of the
PYTEST_CURRENT_TEST
environment variable, which is set when pytest is running. This may also work, but has the side effect of being outside of our control - any other application on our system could also set that variable, including another instance of pytest
, so it may not work as reliably as the other two.
In the end, I chose Solution 1, and updated the code at the top of my main()
method in TicTacToe.py
to the following:
import sys
# get the root logger
logger = logging.getLogger()
# disable if pytest is running
if "pytest" in sys.modules:
logger.disabled = True
That code will simply load the logger, and immediately check if the "pytest"
module is loaded. If so, it will disable the logger globally in my program.
An alternative solution would be to just disable the StreamHandler
and allow the FileHandler
to remain enabled, but I felt that logging from unit tests is not helpful and chose to disable it entirely.
Summary
I hope this discussion is helpful - I’ve found that sometimes the best opportunities for cognitive apprenticeship happen directly as a result of the class, so I wanted to take this chance and share a bit of my own problem solving process here.
If you have any follow up questions about this, please let me know!
Codio Webpages
YouTube Video
Edited Transcript
Hi, everyone, I’m hoping I can break the record for quickest turnaround on responses to a question that I got. But I did get a question via the start-stop-continue survey about loading the milestone content on Codio, so that you can see it on a single monitor, especially if you’re using a laptop. So I’m going to show you a couple of things that you can do in Codio to to help out. First I have loaded, this is the Codio restaurant project. And I just added up here all of these options for the different milestones. And so in Codio, one of the things I can do is go to the View menu, and then click panels. And I’m going to split the main panel vertically so that it has two sides, then I can pick my milestone up here, and it will open that milestone in a web browser. And so now you can have your web browser encode do, you’ll be able to see all of the assignment requirements, and then over here, you can open up your files. This is adjustable, just like any other IDE that you’d be used to, you can split the panels. And if you’re done, you can close this. And then you can go to View panels and join with closest, and it will make it go away. So that will work on the milestones for the restaurant project. Hopefully that fixes that. And if you’re loading the restaurant project, I think the next time you reload it, it should show these new buttons up here at the top. If they don’t let me know.
For the examples, it will take me a little bit longer to go through because there are 14 of those. But you can do the same trick with an extra step. And so in any of the examples, I can go to View panels and split. And then over in this panel, I’m just going to click this project index button to load the web browser over here. And then I can go to the textbook and find that milestone or example project. So for example, if you’re on the example project for find the page that you need. And then up here at the top, there’s a button right here that says embed this page. What that will do is that will reopen the web page in this embed link by adding embed.html at the end of it. You can do this on any pages on our textbook. And so I’m just going to copy that URL. I’m going to go back to my Codio project. I’m going to paste that URL in the browser in Codio, and ta-da, I can load the page directly in Codio. Once again, I will go through and add these to the examples it will take me a little while because there are 14 of them. And it takes a little bit of time to do all that. But as a quick sidestep around that you can easily load any webpage inside of Codio, you can do anything in this web browser. It’s pretty easy to play around with. So for those of you that are working on a single monitor or on a laptop, hopefully this is a great workaround so that you can be more productive in Codio.
I have also gotten a couple other questions via the start stop continue survey that I’m going to work on answering. One of them is providing some additional instruction for people who would like to work outside of Codio, and so hopefully in the next week or so I’ll make a set of videos on installing local IDEs, using git to clone into those local IDEs and setting up a development environment outside of Codio in both Java and Python, so watch for those over the next couple of weeks as I get time to work on that. But this one is one I can solve really really quickly. As always, if you have any questions or feedback please let me know I’m more than happy to work with you to make this class is as painless as I possibly can while still being a four credit hour class. So good luck and I look forward to seeing you all again soon.