os.scandir() Windows bug dir_entry.stat() not works on file during writing.

[CezaryWagner]

BPO	41106
Nosy	@pfmoore, @tjguk, @zware, @eryksun, @zooba
Files	s03_dir_entry.py s03_dir_entry.py

^{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 = None
closed_at = None
created_at = <Date 2020-06-24.16:55:03.506>
labels = ['3.9', '3.10', 'OS-windows', 'type-crash', 'docs']
title = 'os.scandir() Windows bug dir_entry.stat() not works on file during writing.'
updated_at = <Date 2020-07-01.16:18:23.133>
user = 'https://bugs.python.org/CezaryWagner'

bugs.python.org fields:

activity = <Date 2020-07-01.16:18:23.133>
actor = 'eryksun'
assignee = 'docs@python'
closed = False
closed_date = None
closer = None
components = ['Documentation', 'Windows']
creation = <Date 2020-06-24.16:55:03.506>
creator = 'Cezary.Wagner'
dependencies = []
files = ['49259', '49260']
hgrepos = []
issue_num = 41106
keywords = []
message_count = 17.0
messages = ['372264', '372266', '372269', '372273', '372281', '372283', '372354', '372355', '372359', '372389', '372393', '372404', '372430', '372432', '372434', '372748', '372763']
nosy_count = 7.0
nosy_names = ['paul.moore', 'tim.golden', 'docs@python', 'zach.ware', 'eryksun', 'steve.dower', 'Cezary.Wagner']
pr_nums = []
priority = 'normal'
resolution = None
stage = None
status = 'open'
superseder = None
type = 'crash'
url = 'https://bugs.python.org/issue41106'
versions = ['Python 3.9', 'Python 3.10']

[CezaryWagner]

I have problem with change detection of log during writing under Windows (normal fs and windows share). Probably bad order of Windows API calls - no idea.

Test program is attached. You can reproduce it. Try with os.scandir() without os.stats() and os.stat().

Source code responsible for it is probably this -> I do not understand CPython code -> https://github.com/python/cpython/blob/master/Modules/posixmodule.c.

Here is full description - many test was done.

# os.scandir() Windows bug dir_entry.stat() not works on file during writing.
# Such files is for example application log.
# No problem with os.stat()

# Call of os.stat() before os.scandir() -> dir_entry.stat() is workaround.
# Open file during writing other program "fixes" dir_entry.stat().
# Get properties on open file during writing "fixes" dir_entry.stat().

# Notice that I run os.scandir() separately so dir_entry.stat() is not cached.

# Steps to reproduce lack of modification update:
# 1. Close all explorers or other application using PATH (it has impact).
# 2. Set PATH to test folder can be directory or windows share.
# 3. Run program without DO_STAT (False).

# Alternative steps (external app force valid modification date):
# 4. run 'touch' or 'echo' on file should "fix" problem. 'echo' will throw error not matter.

# Alternative scenario (os.stat() force valid modification date - very slow):
# 3. Run program without DO_STAT (True). No problems.

# Error result:
# Modification date from dir_entry.stat() is stalled (not changing after modification)
# if os.stat() or other Windows application not read file.

# Excepted result:
# Modification date from dir_entry.stat() is update from separate calls os.scandir()
# or cached if it is same os.scandir() call.

# Notice that os.scandir() must be call before dir_entry.stat() to avoid caching as described in documentation.
# And this is done but not work on files during writing..

# Ask question if you have since is very hard to find bug.

[CezaryWagner]

Extra file for for tests with:

DO_STAT = False

See not changes but file was writing every second. If os.stat() run all between call os.scandir() all works.

C:\root\Python38\python.exe C:/Users/Cezary.Wagner/PycharmProjects/dptr-monitoring-v2/sandbox/python/s13_dir_entry/s03_dir_entry.py
dir_entry.stat() T:\\test.txt 1593017872.9109812 since last change 0.0009987354278564453
2020-06-24 18:57:52.911980 1593017872.91198
dir_entry.stat() T:\\test.txt 1593017872.9109812 since last change 1.0078418254852295
2020-06-24 18:57:53.918823 1593017873.918823
dir_entry.stat() T:\\test.txt 1593017872.9109812 since last change 2.0103507041931152
2020-06-24 18:57:54.921332 1593017874.921332
dir_entry.stat() T:\\test.txt 1593017872.9109812 since last change 3.023340940475464
2020-06-24 18:57:55.934322 1593017875.934322
dir_entry.stat() T:\\test.txt 1593017872.9109812 since last change 4.036783933639526
2020-06-24 18:57:56.947765 1593017876.947765
dir_entry.stat() T:\\test.txt 1593017872.9109812 since last change 5.049667835235596
2020-06-24 18:57:57.960649 1593017877.960649
dir_entry.stat() T:\\test.txt 1593017872.9109812 since last change 6.063947916030884
2020-06-24 18:57:58.974929 1593017878.974929
dir_entry.stat() T:\\test.txt 1593017872.9109812 since last change 7.0797247886657715
2020-06-24 18:57:59.990706 1593017879.990706
dir_entry.stat() T:\\test.txt 1593017872.9109812 since last change 8.091670751571655
2020-06-24 18:58:01.002652 1593017881.002652
dir_entry.stat() T:\\test.txt 1593017872.9109812 since last change 9.1053147315979
2020-06-24 18:58:02.016296 1593017882.016296
dir_entry.stat() T:\\test.txt 1593017872.9109812 since last change 10.120086908340454
2020-06-24 18:58:03.031068 1593017883.031068

[CezaryWagner]

One hint more.

Start of new process os.scandir() give invalid modification date for file open for writing until external tool is not called (like explorer, touch, etc.).

So (log open for writing and write is done between 1, 2):

1. Run program with os.scandir() -> dir_entry.stat().st_mtime() = t1.
2. Run program with os.scandir() -> dir_entry.stat().st_mtime() = t1.
   Modification is stalled.

Another scenario (log open for writing and write is done between 1, 3):

1. Run program with os.scandir() -> dir_entry.stat().st_mtime() = t1.
2. touch -> dir_entry.path
3. Run program with os.scandir() -> dir_entry.stat().st_mtime() = t2.
   Modification works.

[zooba]

I'm going to have to spend more time to analyse this (later), but it seems like Windows deciding not to update the directory's data structures (containing the st_mtime retrieved by scandir) as long as the file is still open.

I suspect the answer for your scenario is that you'll just have to use os.stat() to get the information from the file's entry, rather than the directory's entry. It's unlikely there's anything we can do at Python's level without sacrificing all the performance gains of scandir() for all other scenarios.

[eryksun]

In FSBO [1] section 6 "Time Stamps", note that the LastWriteTime value gets updated when an IRP_MJ_FLUSH_BUFFERS is processed. In the Windows API, this is a FlushFileBuffers [2] call. In the C runtime, it's a _commit [3] call, which is an os.fsync [4] call in Python. Calling the latter will update the directory entry for the file.

For an example implementation in the FAT32 filesystem, see FatCommonFlushBuffers [5]. Note in the UserFileOpen case that it flushes any cached data via FatFlushFile and then updates the directory entry from the file control block (FCB) via FatUpdateDirentFromFcb, and finally it flushes the parent directory control blocks (DCBs) -- and possibly also the volume.

Example with os.fsync:

    import os
    import time
    import datetime

    UPDATE_DIR = True

    FILEPATH = 'C:/Temp/test/spam.txt'

    def scan(filepath):
        dir_path, filename = os.path.split(filepath)
        with os.scandir(dir_path) as iter_dir:
            for entry in iter_dir:
                if entry.name == filename:
                    return entry

    with open(FILEPATH, 'w') as f:
        while True:
            print('spam', file=f, flush=True)
            if UPDATE_DIR:
                os.fsync(f.fileno())
            entry = scan(FILEPATH)
            stat_result = entry.stat()
            now = datetime.datetime.now()
            print(f'st_mtime: {stat_result.st_mtime:0.3f}, '
                  f'delta_t: {now.timestamp() - stat_result.st_mtime:0.3f}')
            time.sleep(1.0)

[1] https://go.microsoft.com/fwlink/?LinkId=140636
[2] https://docs.microsoft.com/en-us/windows/win32/api/fileapi/nf-fileapi-flushfilebuffers
[3] https://docs.microsoft.com/en-us/cpp/c-runtime-library/reference/commit?view=vs-2019
[4] https://docs.python.org/3/library/os.html#os.fsync
[5] https://github.com/microsoft/Windows-driver-samples/blob/9afd93066dfd9db12f66099cf9ec44b6fd734b2d/filesys/fastfat/flush.c#L145

[zooba]

Does it make the most sense for us to make .flush() also do an implicit .fsync() (when it's actually a file object)?

[CezaryWagner]

I do some test on linux all works - changes are detected and os.scandir() works but in Windows not - probably there is not unit test which check if os.scandir() is working on open files for writing.

f.flush() no matter since file can be changed in external Python/Java/C#/C++, ... application - anyone can write logs in Windows. I will explain it in next comment. I just write this code to show only problem.

Result from linux STAT = False so only repeat os.scandir() calls. Modification are detected correctly in Linux but not in Windows.

[wagnecaz@nsdptrms01 ~]$ python3 s03_dir_entry.py
dir_entry.stat() /home/wagnecaz/test.txt 1593085189.1000397 since last change 0.001112222671508789
2020-06-25 13:39:49.101368 1593085189.101368
dir_entry.stat() /home/wagnecaz/test.txt 1593085189.1000397 since last change 1.0028572082519531
2020-06-25 13:39:50.103111 1593085190.103111
dir_entry.stat() /home/wagnecaz/test.txt 1593085190.1020408 since last change 1.0026073455810547
2020-06-25 13:39:51.104881 1593085191.104881
dir_entry.stat() /home/wagnecaz/test.txt 1593085191.104042 since last change 1.0023958683013916
2020-06-25 13:39:52.106793 1593085192.106793
dir_entry.stat() /home/wagnecaz/test.txt 1593085192.106043 since last change 1.0023260116577148
2020-06-25 13:39:53.108582 1593085193.108582
dir_entry.stat() /home/wagnecaz/test.txt 1593085193.1080444 since last change 1.0021436214447021
2020-06-25 13:39:54.110500 1593085194.1105
dir_entry.stat() /home/wagnecaz/test.txt 1593085194.1100454 since last change 1.0013866424560547
2020-06-25 13:39:55.111684 1593085195.111684
dir_entry.stat() /home/wagnecaz/test.txt 1593085195.1110466 since last change 1.0022354125976562
2020-06-25 13:39:56.113542 1593085196.113542
dir_entry.stat() /home/wagnecaz/test.txt 1593085196.1130476 since last change 1.0021603107452393
2020-06-25 13:39:57.115450 1593085197.11545
dir_entry.stat() /home/wagnecaz/test.txt 1593085197.1140487 since last change 1.003014326095581

Change is done every 1s and detected in Linux in Windows it is stalled.
2020-06-25 13:39:58.117287 1593085198.117287
dir_entry.stat() /home/wagnecaz/test.txt 1593085198.11605 since last change 1.002938985824585
2020-06-25 13:39:59.119224 1593085199.119224
dir_entry.stat() /home/wagnecaz/test.txt 1593085199.118051 since last change 1.0027978420257568
2020-06-25 13:40:00.121166 1593085200.121166

[CezaryWagner]

Use case - detection of changes in open files is very important - log scanning - synchronization ...

I think that first of all it is need good unit test to detect this problem (rare edge case - probably it is missed because hard to imagine that it can not work when file is open - I will miss this I think).

It should work like this.

First program is writing file under Windows and second program (unit test) is running os.scandir() if repeated os.scandir() detect changes it is O.K. (same like in Linux).

To make it simpler it can be unit test in one program.

1. Open test file in test directory.
2. os.scandir() in test directory.
3. Some writes to test file (f.write() with and without flush, ... - to be defined what is sufficient to test).
4. os.scandir() in test directory - if change detected it O.K.
5. f.close()

I do not know Windows API now but I think we can detect id directory is changed between scans or we can detect if file is open (it is rare situation - rare edge case) in 90% all files will be closed.

So if all files is closed current os.scandir() maybe is good (not I do not understand implementation to evaluate it correclty) and when one of file or more there is need another implementation which will detect modification.

If you think I missed something please comment. You are welcome.

[CezaryWagner]

I read some comments os.flush() or os.fsync() can be unrelated to problem. External application can be written in C# or whatever you want.

Under Windows (not Linux) - modification dates will be stalled in such sequence.
os.scandir()
dir_entry.stat() # let it be dir_entry.path == 'test.txt'
dir_entry.stat().st_mtime # will be for example 1
os.scandir()
dir_entry.stat() # let it be dir_entry.path == 'test.txt'
dir_entry.stat().st_mtime # will be STALLED for example 1

Under Windows (not Linux) - modification dates will be refreshed in such sequence.
os.scandir()
dir_entry.stat() # let it be dir_entry.path == 'test.txt'
dir_entry.stat().st_mtime # will be for example 1
os.stat('test.txt') # this code do something and it is not stalled in next call
os.scandir()
dir_entry.stat() # let it be dir_entry.path == 'test.txt'
dir_entry.stat().st_mtime # will be CHANGED for example 2