classification
Title: [Windows] test_logging.test_namer_rotator_inheritance() logs a logging error
Type: Stage: resolved
Components: Tests, Windows Versions: Python 3.10, Python 3.9
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: miss-islington, paul.moore, steve.dower, tim.golden, vinay.sajip, vstinner, zach.ware
Priority: normal Keywords: patch

Created on 2021-04-27 21:25 by vstinner, last changed 2021-04-28 15:28 by vstinner. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 25684 merged vstinner, 2021-04-28 11:23
PR 25688 merged miss-islington, 2021-04-28 13:48
Messages (6)
msg392137 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-04-27 21:25
vstinner@DESKTOP-DK7VBIL C:\vstinner\python\master>python -m test test_logging -m test_namer_rotator_inheritance
Running Debug|x64 interpreter...
0:00:00 Run tests sequentially
0:00:00 [1/1] test_logging
--- Logging error ---
Traceback (most recent call last):
  File "C:\vstinner\python\master\lib\logging\handlers.py", line 74, in emit
    self.doRollover()
  File "C:\vstinner\python\master\lib\logging\handlers.py", line 179, in doRollover
    self.rotate(self.baseFilename, dfn)
  File "C:\vstinner\python\master\lib\logging\handlers.py", line 117, in rotate
    self.rotator(source, dest)
  File "C:\vstinner\python\master\lib\test\test_logging.py", line 5222, in rotator
    os.rename(source, dest + ".rotated")
FileExistsError: [WinError 183] Cannot create a file when that file already exists: 'C:\\Users\\vstinner\\AppData\\Local\\Temp\\test_logging-2-tj71b
t8k.log' -> 'C:\\Users\\vstinner\\AppData\\Local\\Temp\\test_logging-2-tj71bt8k.log.1.test.rotated'
Call stack:
  File "C:\vstinner\python\master\lib\runpy.py", line 196, in _run_module_as_main
    return _run_code(code, main_globals, None,
  File "C:\vstinner\python\master\lib\runpy.py", line 86, in _run_code
    exec(code, run_globals)
  File "C:\vstinner\python\master\lib\test\__main__.py", line 2, in <module>
    main()
  File "C:\vstinner\python\master\lib\test\libregrtest\main.py", line 719, in main
    Regrtest().main(tests=tests, **kwargs)
  File "C:\vstinner\python\master\lib\test\libregrtest\main.py", line 641, in main
    self._main(tests, kwargs)
  File "C:\vstinner\python\master\lib\test\libregrtest\main.py", line 694, in _main
    self.run_tests()
  File "C:\vstinner\python\master\lib\test\libregrtest\main.py", line 521, in run_tests
    self.run_tests_sequential()
  File "C:\vstinner\python\master\lib\test\libregrtest\main.py", line 423, in run_tests_sequential
    result = runtest(self.ns, test_name)
  File "C:\vstinner\python\master\lib\test\libregrtest\runtest.py", line 194, in runtest
    return _runtest(ns, test_name)
  File "C:\vstinner\python\master\lib\test\libregrtest\runtest.py", line 154, in _runtest
    result = _runtest_inner(ns, test_name,
  File "C:\vstinner\python\master\lib\test\libregrtest\runtest.py", line 282, in _runtest_inner
    refleak = _runtest_inner2(ns, test_name)
  File "C:\vstinner\python\master\lib\test\libregrtest\runtest.py", line 246, in _runtest_inner2
    test_runner()
  File "C:\vstinner\python\master\lib\test\support\__init__.py", line 682, in inner
    return func(*args, **kwds)
  File "C:\vstinner\python\master\lib\test\test_logging.py", line 5503, in test_main
    support.run_unittest(*tests)
  File "C:\vstinner\python\master\lib\test\support\__init__.py", line 1082, in run_unittest
    _run_suite(suite)
  File "C:\vstinner\python\master\lib\test\support\__init__.py", line 959, in _run_suite
    result = runner.run(suite)
  File "C:\vstinner\python\master\lib\test\support\testresult.py", line 169, in run
    test(self.result)
  File "C:\vstinner\python\master\lib\unittest\suite.py", line 84, in __call__
    return self.run(*args, **kwds)
  File "C:\vstinner\python\master\lib\unittest\suite.py", line 122, in run
    test(result)
  File "C:\vstinner\python\master\lib\unittest\suite.py", line 84, in __call__
    return self.run(*args, **kwds)
  File "C:\vstinner\python\master\lib\unittest\suite.py", line 122, in run
    test(result)
  File "C:\vstinner\python\master\lib\unittest\case.py", line 652, in __call__
    return self.run(*args, **kwds)
  File "C:\vstinner\python\master\lib\unittest\case.py", line 592, in run
    self._callTestMethod(testMethod)
  File "C:\vstinner\python\master\lib\unittest\case.py", line 549, in _callTestMethod
    method()
  File "C:\vstinner\python\master\lib\test\test_logging.py", line 5229, in test_namer_rotator_inheritance
    rh.emit(self.next_rec())
Message: '2'
Arguments: None

== Tests result: SUCCESS ==

1 test OK.

Total duration: 1.1 sec
Tests result: SUCCESS
msg392138 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-04-27 21:27
Ah, I only see this output on Windows. On Linux, I don't see it.
msg392156 - (view) Author: Steve Dower (steve.dower) * (Python committer) Date: 2021-04-28 00:07
What does os.rename do on Linux? Does it just overwrite existing files by default?
msg392185 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-04-28 11:24
I wrote PR 25684 to fix this issue.

> What does os.rename do on Linux? Does it just overwrite existing files by default?

os.rename() calls rename():
https://man7.org/linux/man-pages/man2/rename.2.html

       rename() renames a file, moving it between directories if
       required.  Any other hard links to the file (as created using
       link(2)) are unaffected.  Open file descriptors for oldpath are
       also unaffected.

       If newpath already exists, it will be atomically replaced, so
       that there is no point at which another process attempting to
       access newpath will find it missing.  However, there will
       probably be a window in which both oldpath and newpath refer to
       the file being renamed.

On Windows, os.rename() is implemented with MoveFileExW(src, dst, 0).

Maybe the test should use os.replace() instead of os.rename()? On Windows, os.replace() is implemented with with MoveFileExW(src, dst, MOVEFILE_REPLACE_EXISTING).

HandlerWithNamerAndRotator.rotator() of test_logging calls os.rename() when the file already exists:

if os.path.exists(source):
    os.rename(source, dest + ".rotated")

And the test fails with "Cannot create a file when that file already exists"... well yes, we just tested that it exists.
msg392198 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-04-28 13:47
New changeset fe52eb62191e640e720d184a9a1a04e965b8a062 by Victor Stinner in branch 'master':
bpo-43961: Fix test_logging.test_namer_rotator_inheritance() (GH-25684)
https://github.com/python/cpython/commit/fe52eb62191e640e720d184a9a1a04e965b8a062
msg392220 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-04-28 15:28
New changeset 629ef0fb9cad6ac340d3be884af7b47fb393ae99 by Miss Islington (bot) in branch '3.9':
bpo-43961: Fix test_logging.test_namer_rotator_inheritance() (GH-25684) (GH-25688)
https://github.com/python/cpython/commit/629ef0fb9cad6ac340d3be884af7b47fb393ae99
History
Date User Action Args
2021-04-28 15:28:58vstinnersetstatus: open -> closed
stage: patch review -> resolved
resolution: fixed
versions: + Python 3.9
2021-04-28 15:28:22vstinnersetmessages: + msg392220
2021-04-28 13:48:04miss-islingtonsetnosy: + miss-islington
pull_requests: + pull_request24378
2021-04-28 13:47:15vstinnersetmessages: + msg392198
2021-04-28 11:24:18vstinnersetmessages: + msg392185
2021-04-28 11:23:48vstinnersetkeywords: + patch
stage: patch review
pull_requests: + pull_request24374
2021-04-28 00:07:48steve.dowersetmessages: + msg392156
2021-04-27 21:27:14vstinnersetnosy: + paul.moore, tim.golden, zach.ware, steve.dower

components: + Windows
title: test_logging.test_namer_rotator_inheritance() logs a logging error -> [Windows] test_logging.test_namer_rotator_inheritance() logs a logging error
2021-04-27 21:27:02vstinnersetmessages: + msg392138
2021-04-27 21:25:51vstinnercreate