test_logging failure in WarningsTest on buildbots

[bitdancer]

BPO	18081
Nosy	@brettcannon, @terryjreedy, @kbkaiser, @vsajip, @vstinner, @serwy, @bitdancer
Dependencies	bpo-18242: IDLE should not be replacing warnings.formatwarning
Files	zdummy.diff changes.diff: Changes resulting in passing tests issue18081-warn.diff issue18081-warn3.diff

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = 'https://github.com/terryjreedy'
closed_at = <Date 2013-06-29.04:05:43.740>
created_at = <Date 2013-05-28.15:25:27.120>
labels = ['type-bug', 'tests']
title = 'test_logging failure in WarningsTest on buildbots'
updated_at = <Date 2013-06-29.04:05:43.739>
user = 'https://github.com/bitdancer'

bugs.python.org fields:

activity = <Date 2013-06-29.04:05:43.739>
actor = 'terry.reedy'
assignee = 'terry.reedy'
closed = True
closed_date = <Date 2013-06-29.04:05:43.740>
closer = 'terry.reedy'
components = ['Tests']
creation = <Date 2013-05-28.15:25:27.120>
creator = 'r.david.murray'
dependencies = ['18242']
files = ['30613', '30619', '30708', '30719']
hgrepos = []
issue_num = 18081
keywords = ['patch', 'buildbot']
message_count = 25.0
messages = ['190220', '191266', '191267', '191277', '191283', '191286', '191291', '191293', '191296', '191298', '191305', '191309', '191328', '191339', '191342', '191343', '191816', '191817', '191864', '191865', '191918', '191925', '191976', '192026', '192028']
nosy_count = 9.0
nosy_names = ['brett.cannon', 'terry.reedy', 'kbk', 'vinay.sajip', 'vstinner', 'roger.serwy', 'Arfrever', 'r.david.murray', 'python-dev']
pr_nums = []
priority = 'normal'
resolution = 'fixed'
stage = 'commit review'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue18081'
versions = ['Python 2.7', 'Python 3.3', 'Python 3.4']

[bitdancer]

The following failure is showing up frequently in the buildbots. I haven't checked closely enough to be sure if it is a heisenberg, but I suspect it is, since it doesn't seem to be related to any of the recent changesets that would have been included in the builds that just failed and that show the failure:

======================================================================
FAIL: test_warnings (test.test_logging.WarningsTest)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/usr/home/db3l/buildarea/3.3.bolen-freebsd/build/Lib/test/test_logging.py", line 1796, in test_warnings
    "dummy.py:42: UserWarning: Explicit\n  Dummy line\n")
AssertionError: '\nWarning (from warnings module):\n  File "dummy.py", line 42\n    Dummy line\n [truncated]... != 'dummy.py:42: UserWarning: Explicit\n  Dummy line\n'
+ dummy.py:42: UserWarning: Explicit
- 
- Warning (from warnings module):
-   File "dummy.py", line 42
-     Dummy line
? --
+   Dummy line
- UserWarning: Explicit
- >>>

[brettcannon]

Seems to be fairly consistent on Windows but more random on Linux. I have also triggered it on my OS X machine randomly.

Can't tell if it's a timing issue or some other test doing something bad. I'm worried solving it is going to require taking one of the failing instance's list of tests and then slowly pruning it down to find the trigger (if it's not a timing thing).

[brettcannon]

Found the test cases to cause this::

./python.exe -m test test_idle test_logging

Adding Roger and Terry to see if they happen to remember any of the IDLE tests using logging or warnings in a way that could cause this.

P.S.: I thought we had a script somewhere which helped do a binary search for what tests cause a failure but I can't find it. Am I imagining things?

[terryjreedy]

test_idle, which runs the tests in idlelib/idle_test, currently comprises 9 test methods and perhaps 100 lines that do not, as far as I know, use warnings or logging. However, perhaps this has an effect:

F:\Python\dev\cpython\PCbuild>python_d -m test test_idle
[1/1] test_idle
Warning -- os.environ was modified by test_idle
Warning -- locale was modified by test_idle
1 test altered the execution environment:
test_idle

Of course, the idle test code itself does no such modification. So I have no idea what the warning is about or how to stop it.

F:\Python\dev\cpython\PCbuild>python_d -m test.test_idle
which runs under unittest, does not produce the warning.

The other test files that use tcl/tk/tkinter, test_tcl, test_tk, test_ttk_guionly, and test_ttk_textonly, produce the os.environ warning but not the locale warning.

I duplicated the failure with the command you gave. Substituting _tcl or _tk for _idle removes the error. So perhaps the locale alteration, however it happens, is the problem.

[brettcannon]

I actually don't get the warnings when I run test_idle under regrtest. But what I did was followed a hunch and added a check for warnings.showwarning() and sure enough, it's been left modified by IDLE: PyShell replaces the function as a side-effect of import. Not sure how you want to fix it. Using warnings.catch_warnings() during import would solve it, but I don't know if that's how you want to go in case that showwarnings replacement is needed.

[terryjreedy]

I discovered the same thing a different way. Grepping Lib/*.py for
'Warning (from warnings module)' hits
F:\Python\dev\cpython\Lib\idlelib\PyShell.py: 67:
F:\Python\dev\cpython\Lib\idlelib\run.py: 34:
Both monkey-patch warnings, when imported, to show warnings 'the Idle way' ;-).

I am not sure which test file indirectly imports PyShell, but one must. Idle was written to be run from the command line. It was not written to be imported but not run, as in a test environment, or to be run as part of another script.

Roger, can the monkey patching be put in a function that is only called when Idle runs? Perhaps in PyShell.main and run.main? There is no need to reformat warning sent to the console (if there is one) during import, before Idle starts. Can the monkey-patching be undone when Python exits (in case it is being run from within a script)?

In the meanwhile, I will try using support.import_fresh_module('warnings') in test_logging, or better, saving and restoring warnings in test_idle.

[Although the alteration warnings are red-herrings for this issue, I am sure silencing them, including in tkinter tests, would be a good idea.]

[vsajip]

In the meanwhile, I will try using support.import_fresh_module('warnings') in test_logging, or better, saving and restoring warnings in test_idle.

I agree the second option (changing test_idle) is better. The failing logging test is checking to ensure that the original warnings implementation is used when an explicit file is passed to warnings.showwarning, but it assumes that original implementation is the one in warnings when comparing the output from that (supposed) original implementation.

+1 to restoring the environment and locale in test_idle, too.

[terryjreedy]

Vinay, please comment on this: on my Win7-64 system, as least, test_logging seems broken without running test_idle first.

F:\Python\dev\cpython\PCbuild>python_d -m test test_logging
[1/1] test_logging
dummy.py:42: UserWarning: Explicit
Warning -- warnings.filters was modified by test_logging
test test_logging failed -- Traceback (most recent call last):
  File "F:\Python\dev\cpython\lib\test\test_logging.py", line 1779, in test_warnings_no_handlers
    self.assertEqual(len(logger.handlers), 1)
AssertionError: 0 != 1

Relevant code:
with warnings.catch_warnings():
logging.captureWarnings(True)
self.addCleanup(logging.captureWarnings, False)

  # confirm our assumption: no loggers are set
  logger = logging.getLogger("py.warnings")
  self.assertEqual(logger.handlers, [])

  warnings.showwarning("Explicit", UserWarning, "dummy.py", 42)
  self.assertEqual(len(logger.handlers), 1)
  self.assertIsInstance(logger.handlers[0], logging.NullHandler)

Since the above lines have not been touched in 2 years, and presumably worked before, perhaps something changed in warnings.catchwarnings or logging.capturewarnings so that NullHandler is no longer added.

With import_fresh_module added to the test.support import (line 69) and warnings imported with "warnings = import_fresh_module('warnings')";
cpython\PCbuild>python_d -m test test_logging
produces the same error as above, so it works to eliminate the effect of Idle running first, and could be used as a temporary fix.

Side note: on Win7, should I see this?
test_basic (test.test_logging.NTEventLogHandlerTest) ... skipped 'win32evtlog/win32evtlogutil required for this test.'

[terryjreedy]

I reverted the change to test_logging, reran, and it runs fine, at least twice. Before the revert, I checked that the only two changes were the intentional ones.

I tried adding idle_test/test_zdummy.py with a tearDownModule that deletes sys.modules['warnings']. This 'works' in that the original failure passes, as with the change to test_logging, and
'dummy.py:42: UserWarning: Explicit' is printed. But with test_logging unchanged from when it ran and passed, I see the same 0 != 1 error as in the last message plus

Traceback (most recent call last):
  File "F:\Python\dev\cpython\lib\test\test_logging.py", line 1757, in test_warnings
    self.assertGreater(s.find("UserWarning: I'm warning you...\n"), 0)
AssertionError: -1 not greater than 0

[vsajip]

I would change the reverted test_logging to add "print(logging._warnings_showwarning)" before the failing assertions. If this is bound to the original warnings.showwarning implementation, all should be well. If it points to e.g. idle_showwarning, you would expect to get a failure, as idle_showwarning formats warning messages differently from what warnings.showwarning is originally bound to.

I think the right fix is to take the approach that logging does: have PyShell.py grow a captureWarnings(bool) function which either captures the old values before setting idle_showwarning/idle_formatwarning or restores them, according to the Boolean passed in. The PyShell.captureWarnings(True) could be called from PyShell module-level code if a side-effect free import is unavoidable, but test_idle could call PyShell.captureWarnings(False) to put things back as they were. I would have thought you could avoid side-effects by having the PyShell.captureWarnings(True) called from somewhere in the code path followed from "if __name__ == '__main__'", or from test_idle code.

Re. Your side note - IIRC that skip of the NTEventLogHandler is expected, unless you install some win32 components which aren't shipped with stock Python (Mark Hammond's pywin32 project, available on SourceForge). They are shipped with other Python distributions, e.g. ActivePython.

[bitdancer]

As a side note, the various warnings about the execution environment being modified do not appear when tests are run under unittest because those warnings are generated by regrtest itself.

[terryjreedy]

The only locale setting is IOBinding.py: 21
# Try setting the locale, so that we can find out what encoding to use
locale.setlocale(locale.LC_CTYPE, "")
This section, up to line 65, might be wrapped either by a function or if statement.

There are only 2 os.environ accesses and no settings in Idle. This alteration might be inherited from tkinter. File tkinter/_fix.py sets TCL/TK/TIX_LIBRARY if they are not already. This seem innocuous as far as other tests go.

[vsajip]

With the attached patch,

python -m test_idle test_logging

passes (though test_idle still alters locale and environment).

Running python -m idelib.idle, and using IDLE itself for inspection, the warnings.formatwarning is set to the implementation in idlelib.run.

Perhaps the PyShell changes aren't needed, but I think it may avoid similar issues in the future to leave them in.