Missed sub-second updates when using polling

[llucax]

Description

When using force_polling=True and a watched file/directory is changed more than once in the same second, the change is not reported. I was expecting to receive an event for the change. It seems like the sub-second part of the mtime is being ignored.

Example Code

import asyncio
import pathlib
import tempfile
from datetime import datetime

from watchfiles import awatch


async def change_config_file(config_file: pathlib.Path) -> None:
    await asyncio.sleep(0.2)
    config_file.write_text("World")
    print("Modified file: mtime =", config_file.stat().st_ctime)


async def test(tmpdir: pathlib.Path) -> None:
    """Test the complete flow of configuration management."""
    config_file = tmpdir / "file.txt"

    config_file.write_text("Hello")
    print("Created file: mtime =", config_file.stat().st_ctime)

    task = asyncio.create_task(change_config_file(config_file))

    try:
        async with asyncio.timeout(1):
            # Watch the parent directory for changes
            print(f"Started watching {config_file} at {datetime.now().timestamp()}")
            async for changes in awatch(
                config_file,  # Monitoring the parent directory has the issue too
                watch_filter=None,
                force_polling=True,  # Not using polling makes this work fine
                poll_delay_ms=100,
            ):
                for change_type, changed_path in changes:
                    if pathlib.Path(changed_path) == config_file:
                        print(
                            f"<<< EVENT DETECTED >> at {datetime.now().timestamp()}: {change_type} - {changed_path}"
                        )
                        await task
                        return  # Exit after first relevant change is detected
    finally:
        task.cancel()
        print(
            f"Finished at {datetime.now().timestamp()}: mtime = {config_file.stat().st_ctime}"
        )


if __name__ == "__main__":
    with tempfile.TemporaryDirectory() as tmpdir:
        try:
            asyncio.run(test(pathlib.Path(tmpdir)))
        except asyncio.TimeoutError:
            print("<<< TIMEOUT REACHED >> (changes not detected)")

I tried reproducing this using notify-rs directly, and it seems to work fine, but I'm not a rust programmer, so maybe my test is wrong.

use notify::{Config, PollWatcher, RecursiveMode, Watcher};
use std::fs;
use std::time::Duration;
use std::time::SystemTime;
use tempfile::TempDir;
use tokio::time::sleep;

#[tokio::main]
async fn main() {
    // Create temporary test file
    let dir = TempDir::new().unwrap();
    let file = dir.path().join("test.txt");

    fs::write(&file, "Hello").unwrap();
    println!("Created file: mtime = {:?}", file.metadata().unwrap().modified().unwrap());

    println!("Started watching {:?} at {:?}", file, SystemTime::now());
    let (tx, mut rx) = tokio::sync::mpsc::channel(1);
    let mut watcher = PollWatcher::new(
        move |res| {
            let tx = tx.clone();
            if let Ok(event) = res {
                let _ = tx.blocking_send(event);
            }
        },
        Config::default()
            .with_poll_interval(Duration::from_millis(100))
            .with_compare_contents(true),
    )
    .unwrap();

    watcher.watch(dir.path(), RecursiveMode::NonRecursive).unwrap();

    sleep(Duration::from_millis(200)).await;
    fs::write(&file, "World").unwrap();
    println!("Modified file: mtime = {:?}", file.metadata().unwrap().modified().unwrap());

    let timeout = Duration::from_secs(1);
    let start = std::time::Instant::now();
    while start.elapsed() < timeout {
        if let Ok(event) = rx.try_recv() {
            println!("<<< EVENT DETECTED >> at {:?}: {:?}", SystemTime::now(), event);
            return;
        }
        sleep(Duration::from_millis(100)).await;
    }
    println!("Finished at {:?}: mtime = {:?}", SystemTime::now(), file.metadata().unwrap().modified().unwrap());
    println!("<<< TIMEOUT REACHED >> (changes not detected)");
}

This always work, even when the update is done on the same second.

Watchfiles Output

$ python test_file_watcher.py 
Created file: mtime = 1734607409.951942
Started watching /tmp/tmpxee5za0m/file.txt at 1734607409.957442
Modified file: mtime = 1734607410.159944
<<< EVENT DETECTED >> at 1734607410.312549: 2 - /tmp/tmpxee5za0m/file.txt
Finished at 1734607410.312607: mtime = 1734607410.159944
$ python test_file_watcher.py 
Created file: mtime = 1734607411.6479588
Started watching /tmp/tmp5u5ql5yc/file.txt at 1734607411.652159
Modified file: mtime = 1734607411.851961
Finished at 1734607412.653835: mtime = 1734607411.851961
<<< TIMEOUT REACHED >> (changes not detected)

• In the first run, that succeed, the updated mtime crosses the second-boundary: 1734607409 to 1734607410.
• In the second run, that fails, the updated mtime and the initial mtime are in the same second (1734607411) and only the sub-second part changes

Operating System & Architecture

Linux-6.11.10-amd64-x86_64-with-glibc2.40
#1 SMP PREEMPT_DYNAMIC Debian 6.11.10-1 (2024-11-23)

Environment

Tried on ext4 and tmpfs, both fail.

Python & Watchfiles Version

python: 3.11.10 (main, Sep 9 2024, 22:11:19) [Clang 18.1.8 ], watchfiles: 1.0.3

Rust & Cargo Version

cargo 1.83.0 (5ffbef321 2024-10-29) rustc 1.83.0 (90b35a623 2024-11-26)

[samuelcolvin]

I don't have time right now to look into this, but PR welcome to fix it. No idea how much work it would be.