This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

classification
Title: test.regrtest: changed environment variables are not logged
Type: Stage:
Components: Tests Versions: Python 3.6
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: python-dev, serhiy.storchaka, vstinner
Priority: normal Keywords: buildbot

Created on 2016-08-22 12:17 by vstinner, last changed 2022-04-11 14:58 by admin. This issue is now closed.

Messages (11)
msg273364 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2016-08-22 12:17
It's common to get a random "env failed" issue when tests are run by buildbots, but changed environment variables are not logged, so the "env changed "information cannot be used to fix the issue :-/

Example:
------------------
...
0:07:32 [160/402] test_io failed (env changed) (51 sec)
0:07:33 [161/402] test_threading_local passed
...
0:13:04 [289/402/2] test_ssl failed (env changed) -- running: test_multiprocessing_spawn (119 sec)
0:13:05 [290/402/2] test_wsgiref passed -- running: test_multiprocessing_spawn (120 sec)
...
2 tests altered the execution environment:
    test_io test_ssl
------------------
http://buildbot.python.org/all/builders/AMD64%20FreeBSD%20CURRENT%20Debug%203.x/builds/932/steps/test/logs/stdio

I expected "Warning -- xxx was modfied by test_xxx" lines, but no, there is no such line. I don't know if it's related to stderr buffering or something else?

This buildbot runs tests in subprocesses.
msg273366 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2016-08-22 12:32
New changeset 2e23f7b9515c by Victor Stinner in branch 'default':
Issue #27829: libregrtest.save_env: flush stderr
https://hg.python.org/cpython/rev/2e23f7b9515c
msg275595 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2016-09-10 08:08
New changeset 491bbba73bca by Victor Stinner in branch 'default':
Show regrtest env changed warn on Windows buildbot
https://hg.python.org/cpython/rev/491bbba73bca
msg277261 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2016-09-23 09:18
New changeset cbe049647a04 by Victor Stinner in branch '3.5':
Issue #27829: regrtest -W displays stderr if env changed
https://hg.python.org/cpython/rev/cbe049647a04

New changeset 12e3023d19bd by Victor Stinner in branch '3.6':
Merge 3.5 (issue #27829)
https://hg.python.org/cpython/rev/12e3023d19bd

New changeset 8210873bd684 by Victor Stinner in branch 'default':
Merge 3.6 (issue #27829)
https://hg.python.org/cpython/rev/8210873bd684
msg277262 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2016-09-23 09:19
I was able to reproduce the missing warning by modifying test_sys.py to modify sys.path and then run:
./python -m test -W test_sys

The -W eats stderr even if the environment changed. I modified regrtest to copy stderr if the test doesn't pass which includes: fail, interrupted, env changed, etc.
msg277264 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2016-09-23 09:56
I thought sys.stderr is line buffered and doesn't need flush=True if prints a complete line.
msg277265 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2016-09-23 09:58
> I thought sys.stderr is line buffered and doesn't need flush=True if prints a complete line.

I tried random changes since I was unable to reproduce the issue and didn't understand why the the warning was not printed.

I'm not sure that stderr is always line buffered. Is it the case even if stderr is redirected to a pipe?
msg277267 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2016-09-23 10:02
> I tried random changes since I was unable to reproduce the issue and didn't understand why the the warning was not printed.

Ooops, I forgot to say: my flush=True changes may be removed if my latest change fixed the issue (if the warning is now displayed).
msg277268 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2016-09-23 10:14
Cool, my change fixed this issue. Examples:

http://buildbot.python.org/all/builders/s390x%20RHEL%203.x/builds/1953/steps/test/logs/stdio
Warning -- threading._dangling was modified by test_logging

http://buildbot.python.org/all/builders/AMD64%20Windows7%20SP1%203.x/builds/8590/steps/test/logs/stdio
Warning -- files was modified by test_distutils3
msg277272 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2016-09-23 12:43
More warnings.

http://buildbot.python.org/all/builders/AMD64%20FreeBSD%209.x%203.x/builds/5058/steps/test/logs/stdio

Warning -- threading._dangling was modified by test_logging
Warning -- files was modified by test_io

http://buildbot.python.org/all/builders/AMD64%20FreeBSD%2010.x%20Shared%203.x/builds/5148/steps/test/logs/stdio

Warning -- threading._dangling was modified by test_logging
Warning -- threading._dangling was modified by test_asyncio
Warning -- files was modified by test_io

http://buildbot.python.org/all/builders/AMD64%20Windows10%203.x/builds/1573/steps/test/logs/stdio

Warning -- files was modified by test_distutils
Warning -- threading._dangling was modified by test_asyncio
msg277288 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2016-09-23 17:16
> More warnings.

Excellent result!

> my flush=True changes may be removed if my latest change fixed the issue

Don't bother. The buffering of standard streams was changed in 3.x and I'm not sure it always work as expected. For example the meaning of the -u option seems was changed. Maybe my beliefs about this are wrong.
History
Date User Action Args
2022-04-11 14:58:35adminsetgithub: 72016
2016-12-05 17:31:15vstinnersetstatus: open -> closed
resolution: fixed
2016-09-23 17:16:19serhiy.storchakasetmessages: + msg277288
2016-09-23 12:43:54vstinnersetmessages: + msg277272
2016-09-23 10:14:30vstinnersetmessages: + msg277268
2016-09-23 10:02:18vstinnersetmessages: + msg277267
2016-09-23 09:58:05vstinnersetmessages: + msg277265
2016-09-23 09:56:42serhiy.storchakasetnosy: + serhiy.storchaka
messages: + msg277264
2016-09-23 09:19:48vstinnersetmessages: + msg277262
2016-09-23 09:18:31python-devsetmessages: + msg277261
2016-09-10 08:08:02python-devsetmessages: + msg275595
2016-08-22 12:32:15python-devsetnosy: + python-dev
messages: + msg273366
2016-08-22 12:17:58vstinnersetkeywords: + buildbot
2016-08-22 12:17:55vstinnercreate