classification
Title: log rotator cookbook example might waste disk space
Type: resource usage Stage: resolved
Components: Documentation Versions:
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: vinay.sajip Nosy List: docs@python, miss-islington, mori-b, vinay.sajip
Priority: normal Keywords: patch

Created on 2021-06-11 19:50 by mori-b, last changed 2021-07-28 10:48 by vinay.sajip. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 27348 merged vinay.sajip, 2021-07-25 16:35
PR 27350 open miss-islington, 2021-07-25 17:08
PR 27351 closed miss-islington, 2021-07-25 17:08
PR 27352 merged miss-islington, 2021-07-25 17:08
PR 27407 merged vinay.sajip, 2021-07-28 10:23
Messages (10)
msg395658 - (view) Author: (mori-b) Date: 2021-06-11 19:50
In https://docs.python.org/3/howto/logging-cookbook.html#using-a-rotator-and-namer-to-customize-log-rotation-processing, the log rotator example deletes the original log file after compressing it. However, running on Linux the command "lsof +S1" shows that the deleted original log file might still hold the same disk space, and keep growing.
Replacing the command "os.remove(source)" with "os.truncate(source,0)" seems to solve the issue by freeing the original log file disk space at each rotation.
msg395659 - (view) Author: (mori-b) Date: 2021-06-11 19:59
In https://docs.python.org/3/howto/logging-cookbook.html#using-a-rotator-and-namer-to-customize-log-rotation-processing, the log rotator example deletes the original log file after compressing it. However, running on Linux the command "lsof +L1" shows that the deleted original log file might still hold the same disk space, and keep growing.
Replacing the command "os.remove(source)" with "os.truncate(source,0)" seems to solve the issue by freeing the original log file disk space at each rotation.
msg395664 - (view) Author: (mori-b) Date: 2021-06-11 21:59
Additional precision : this issue can happen when the log file is shared between multiple threads. And naturally also between different processes, which is not recommended but can happen by mistake.
msg395751 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2021-06-13 14:07
The cookbook example is (by design) limited in scope and doesn't especially discuss usage in multi-thread or multi-process scenarios - as with other examples in the cookbook which aren't specifically concerned with such scenarios. I don't think this is a problem with the example.

The problem occurs because on POSIX-style platforms, you can have multiple sources pointing to a file, and if deleted it only actually disappears when there are no references to it (such as open file descriptors/handles in other threads/processes). On Windows, for example, you would typically get a "sharing violation" type of error because you can't have multiple concurrent writers to a given file. This is not specifically a logging issue, as you could get the same thing happening with other kinds of files shared between processes and/or threads.

Adding os.truncate() might just serve to hide the problem for a while, but the right answer is to avoid opening the same log file multiple times. In the examples you mention, do multiple threads create handlers pointing to the same file? That might be an anti-pattern. Normally, the main thread configures logging (early in the "if __name__ == '__main__'" clause which creates the relevant handlers) and then any subsequently created threads just log to their loggers, but don't create any new handlers in the thread.
msg395757 - (view) Author: (mori-b) Date: 2021-06-13 16:13
Indeed this situation would rise only under misusage of the log, where multiple processes inherit by  mistake or by wrong design a file descriptor of a same log file (Regarding the threads case I unfortunately cannot reproduce).
While this kind of misusage doesn't have terrible consequences when not using the rotator, the growing used disk space which occurs when using the rotator is more serious, that's why I found appropriate to try and protect the programmer from his own mistake. But I understand if this is out of scope.
msg395760 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2021-06-13 19:33
> But I understand if this is out of scope.

I think it's out of scope here (as discussion of such issues will obscure the basic point about how to use the namer and rotator).

However, it might be useful to have a "gotchas" section somewhere in the logging docs called something like "Things to be careful about", "Anti-patterns", "Patterns to Avoid" or similar. Or maybe have it in the cookbook with a section at the end - "Recipes to Avoid".
msg398189 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2021-07-25 17:05
New changeset 9751f85914e0ef3324671a91da34a635d48b17fb by Vinay Sajip in branch 'main':
bpo-44399: Update logging cookbook to document patterns to be avoided. (GH-27348)
https://github.com/python/cpython/commit/9751f85914e0ef3324671a91da34a635d48b17fb
msg398193 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2021-07-25 19:32
New changeset 628baf6fef4d633e756024cf813941a4075360c1 by Miss Islington (bot) in branch '3.10':
[3.10] bpo-44399: Update logging cookbook to document patterns to be avoided. (GH-27348) (GH-27352)
https://github.com/python/cpython/commit/628baf6fef4d633e756024cf813941a4075360c1
msg398194 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2021-07-25 19:32
New changeset 5a0c6abb569cadfc6b418a7d23ecffec01bd234d by Miss Islington (bot) in branch '3.9':
[3.9] bpo-44399: Update logging cookbook to document patterns to be avoided. (GH-27348) (GH-27350)
https://github.com/python/cpython/commit/5a0c6abb569cadfc6b418a7d23ecffec01bd234d
msg398366 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2021-07-28 10:47
New changeset 174fbd85f60d7877d3a4f58214a852209f8dfbea by Vinay Sajip in branch 'main':
bpo-44399: Document another example of unexpected behavior. (GH-27407)
https://github.com/python/cpython/commit/174fbd85f60d7877d3a4f58214a852209f8dfbea
History
Date User Action Args
2021-07-28 10:48:11vinay.sajipsetstatus: open -> closed
resolution: fixed
stage: patch review -> resolved
2021-07-28 10:47:09vinay.sajipsetmessages: + msg398366
2021-07-28 10:23:18vinay.sajipsetpull_requests: + pull_request25940
2021-07-25 19:32:23vinay.sajipsetmessages: + msg398194
2021-07-25 19:32:02vinay.sajipsetmessages: + msg398193
2021-07-25 17:08:28miss-islingtonsetpull_requests: + pull_request25893
2021-07-25 17:08:23miss-islingtonsetpull_requests: + pull_request25892
2021-07-25 17:08:17miss-islingtonsetnosy: + miss-islington
pull_requests: + pull_request25891
2021-07-25 17:05:46vinay.sajipsetmessages: + msg398189
2021-07-25 16:35:34vinay.sajipsetkeywords: + patch
stage: patch review
pull_requests: + pull_request25889
2021-06-13 19:33:54vinay.sajipsetmessages: + msg395760
2021-06-13 16:13:32mori-bsetmessages: + msg395757
2021-06-13 14:07:41vinay.sajipsetmessages: + msg395751
2021-06-13 09:01:27rhettingersetassignee: docs@python -> vinay.sajip

nosy: + vinay.sajip
2021-06-11 21:59:01mori-bsetmessages: + msg395664
2021-06-11 19:59:50mori-bsetmessages: + msg395659
2021-06-11 19:50:16mori-bcreate