watchdog icon indicating copy to clipboard operation
watchdog copied to clipboard

When an event occurs, watchdog will always execute function 2 times

Open timelessnesses opened this issue 1 year ago • 5 comments

Here's my module reloader implemented with watchdog:

class FileHandler(FileSystemEventHandler):
    def on_modified(self, event):
        log.info(f"File changed: {event.src_path}")
        if event.src_path.endswith(".py"):
            log.info("Reloading...")
            path = event.src_path.replace("\\", "/").replace("/", ".")[:-3]
            try:
                asyncio.run(bot.reload_extension(path))
                log.info(f"Reloaded {path}")
            except Exception as e:
                log.error(f"Failed to reload {path}")
                log.error(e)
                log.error(traceback.format_exc())

And when the on_modified event occurs, watchdog will execute the function 2 times.
Logs:

[2023/08/20 10:49:37] - [INFO] [lavalinking.bot] File changed: src/music.py
[2023/08/20 10:49:37] - [INFO] [lavalinking.bot] Reloading...
[2023/08/20 10:49:37] - [DEBUG] [asyncio] Using selector: EpollSelector
[2023/08/20 10:49:37] - [INFO] [lavalinking.src.music] Unloaded
[2023/08/20 10:49:37] - [INFO] [lavalinking.bot] Reloaded src.music
[2023/08/20 10:49:37] - [INFO] [lavalinking.bot] File changed: src/music.py
[2023/08/20 10:49:37] - [INFO] [lavalinking.bot] Reloading...
[2023/08/20 10:49:37] - [DEBUG] [asyncio] Using selector: EpollSelector
[2023/08/20 10:49:37] - [INFO] [lavalinking.src.music] Unloaded
[2023/08/20 10:49:37] - [INFO] [lavalinking.bot] Reloaded src.music

timelessnesses avatar Aug 20 '23 03:08 timelessnesses

Are you, by any chance, using Visual Studio Code to edit your programs?

I have noticed that saving the file through VSC editor will trigger two modification events at once, not exactly at the same time (few miliseconds of difference). Saving the file using another editor (for example, Windows Notepad) will trigger a single one, so maybe the issue is related to the editor itself and not watchdog.

I have come up with a simple (thus not fully reliable) solution:

from time import perf_counter as pc
from typing import Any

import watchdog.events


class _DuplicateEventLimiter:
    """Duplicate event limiter.

    This class is responsible for limiting duplicated event detection. It works
    by comparing the timestamp of the previous event (if existent) to the
    current one, as well as the event itself. If the difference between the
    timestamps is less than a threshold and the events are the same, the event
    is considered a duplicate.
    """

    _DUPLICATE_THRESHOLD: float = 0.05

    def __init__(self) -> None:
        """Initialize a _DuplicateEventLimiter instance."""
        # Dummy event:
        self._last_event: dict[str, Any] = {
            "time": 0,
            "event": None
        }

    def _is_duplicate(self, event: watchdog.events.FileSystemEvent) -> bool:
        """Determine if an event is a duplicate.

        Args:
            event (watchdog.events.FileSystemEvent): event to check.

        Returns:
            bool: True if the event is a duplicate, False otherwise.
        """
        is_duplicate = (
            pc() - self._last_event["time"] < self._DUPLICATE_THRESHOLD
            and self._last_event["event"] == event
        )

        self._last_event = {
            "time": pc(),
            "event": event
        }

        return is_duplicate

That class should then be inherited by your event handler, for example:

class YourEventHandler(
            watchdog.events.RegexMatchingEventHandler,
            _DuplicateEventLimiter  # Inherit the class from the child.
        ):

    def __init__(self, ...):
        ...
        # Add _DuplicateEventLimiter init call on child init:
        _DuplicateEventLimiter.__init__(self)
        ...

    def on_modified(self, event):
        # Add this block at the top of the event handler method body:
        if self._is_duplicate(event):
            # Do whatever if event is duplicate.
            return  # Or just stop execution of the method.

In my experience, the duplicate event took place at a 30ms delay from the original one, so I chose to set the _DUPLICATE_THRESHOLD to 50ms (0.05s). You can customize that as you wish, although it be strictly reliable on the power of the device you are using, number of available threads, etc.

Hope this helped!

erlete avatar Aug 22 '23 23:08 erlete

i tested this theory with nano and i found that nano also saves it more than 2 times?
is this nano's fault?
yes i also use vscode but i didn't think it would trigger saving 2 times.

[2023/08/23 00:29:05] - [DEBUG] [watchdog.observers.inotify_buffer] in-event <InotifyEvent: src_path=b'src', wd=1, mask=IN_ISDIR|IN_OPEN, cookie=0, name=''>
[2023/08/23 00:29:07] - [DEBUG] [watchdog.observers.inotify_buffer] in-event <InotifyEvent: src_path=b'src', wd=1, mask=IN_ISDIR|IN_OPEN, cookie=0, name=''>
[2023/08/23 00:29:07] - [DEBUG] [watchdog.observers.inotify_buffer] in-event <InotifyEvent: src_path=b'src', wd=1, mask=IN_ISDIR|IN_OPEN, cookie=0, name=''>
[2023/08/23 00:29:10] - [DEBUG] [watchdog.observers.inotify_buffer] in-event <InotifyEvent: src_path=b'src/.event.py.swp', wd=1, mask=IN_CREATE, cookie=0, name='.event.py.swp'>
[2023/08/23 00:29:10] - [INFO] [AlphabetBot] File changed: src
[2023/08/23 00:29:10] - [DEBUG] [watchdog.observers.inotify_buffer] in-event <InotifyEvent: src_path=b'src/.event.py.swp', wd=1, mask=IN_OPEN, cookie=0, name='.event.py.swp'>
[2023/08/23 00:29:10] - [DEBUG] [watchdog.observers.inotify_buffer] in-event <InotifyEvent: src_path=b'src/.event.py.swp', wd=1, mask=IN_MODIFY, cookie=0, name='.event.py.swp'>
[2023/08/23 00:29:10] - [INFO] [AlphabetBot] File changed: src/.event.py.swp
[2023/08/23 00:29:10] - [DEBUG] [watchdog.observers.inotify_buffer] in-event <InotifyEvent: src_path=b'src/.event.py.swp', wd=1, mask=IN_CLOSE_WRITE, cookie=0, name='.event.py.swp'>
[2023/08/23 00:29:10] - [INFO] [AlphabetBot] File changed: src
[2023/08/23 00:29:10] - [DEBUG] [watchdog.observers.inotify_buffer] in-event <InotifyEvent: src_path=b'src/event.py', wd=1, mask=IN_OPEN, cookie=0, name='event.py'>
[2023/08/23 00:29:15] - [DEBUG] [watchdog.observers.inotify_buffer] in-event <InotifyEvent: src_path=b'src/.event.py.swp', wd=1, mask=IN_DELETE, cookie=0, name='.event.py.swp'>
[2023/08/23 00:29:15] - [INFO] [AlphabetBot] File changed: src
[2023/08/23 00:29:15] - [DEBUG] [watchdog.observers.inotify_buffer] in-event <InotifyEvent: src_path=b'src/.event.py.swp', wd=1, mask=IN_CREATE, cookie=0, name='.event.py.swp'>
[2023/08/23 00:29:15] - [INFO] [AlphabetBot] File changed: src
[2023/08/23 00:29:15] - [DEBUG] [watchdog.observers.inotify_buffer] in-event <InotifyEvent: src_path=b'src/.event.py.swp', wd=1, mask=IN_OPEN, cookie=0, name='.event.py.swp'>
[2023/08/23 00:29:15] - [DEBUG] [watchdog.observers.inotify_buffer] in-event <InotifyEvent: src_path=b'src/.event.py.swp', wd=1, mask=IN_MODIFY, cookie=0, name='.event.py.swp'>
[2023/08/23 00:29:15] - [DEBUG] [watchdog.observers.inotify_buffer] in-event <InotifyEvent: src_path=b'src/.event.py.swp', wd=1, mask=IN_CLOSE_WRITE, cookie=0, name='.event.py.swp'>
[2023/08/23 00:29:15] - [INFO] [AlphabetBot] File changed: src/.event.py.swp
[2023/08/23 00:29:15] - [INFO] [AlphabetBot] File changed: src
[2023/08/23 00:29:17] - [DEBUG] [watchdog.observers.inotify_buffer] in-event <InotifyEvent: src_path=b'src/event.py', wd=1, mask=IN_MODIFY, cookie=0, name='event.py'>
[2023/08/23 00:29:17] - [INFO] [AlphabetBot] File changed: src/event.py
[2023/08/23 00:29:17] - [INFO] [AlphabetBot] Reloading...
[2023/08/23 00:29:17] - [DEBUG] [watchdog.observers.inotify_buffer] in-event <InotifyEvent: src_path=b'src/event.py', wd=1, mask=IN_OPEN, cookie=0, name='event.py'>
[2023/08/23 00:29:17] - [DEBUG] [watchdog.observers.inotify_buffer] in-event <InotifyEvent: src_path=b'src/event.py', wd=1, mask=IN_MODIFY, cookie=0, name='event.py'>
[2023/08/23 00:29:17] - [DEBUG] [watchdog.observers.inotify_buffer] in-event <InotifyEvent: src_path=b'src', wd=1, mask=IN_ISDIR|IN_OPEN, cookie=0, name=''>
[2023/08/23 00:29:17] - [DEBUG] [watchdog.observers.inotify_buffer] in-event <InotifyEvent: src_path=b'src/event.py', wd=1, mask=IN_OPEN, cookie=0, name='event.py'>
[2023/08/23 00:29:17] - [DEBUG] [watchdog.observers.inotify_buffer] in-event <InotifyEvent: src_path=b'src/event.py', wd=1, mask=IN_CLOSE_WRITE, cookie=0, name='event.py'>
[2023/08/23 00:29:17] - [INFO] [AlphabetBot] Reloaded src.event
[2023/08/23 00:29:17] - [INFO] [AlphabetBot] File changed: src/event.py
[2023/08/23 00:29:17] - [INFO] [AlphabetBot] Reloading...
[2023/08/23 00:29:17] - [INFO] [AlphabetBot] Reloaded src.event
[2023/08/23 00:29:17] - [INFO] [AlphabetBot] File changed: src
[2023/08/23 00:29:18] - [DEBUG] [watchdog.observers.inotify_buffer] in-event <InotifyEvent: src_path=b'src/.event.py.swp', wd=1, mask=IN_DELETE, cookie=0, name='.event.py.swp'>
[2023/08/23 00:29:18] - [INFO] [AlphabetBot] File changed: src

timelessnesses avatar Aug 23 '23 00:08 timelessnesses

Honestly, I do not have a clue about how nano saves files, but seems sort of strange that it does it twice. Could you make sure to test it out with a couple more editors and share your feedback? It will probably help developers if the issue needs to be properly addressed.

In my case, as I said before, VSC saved the file twice, but Notepad did not. Seems like an editor issue more than a watchdog one.

erlete avatar Aug 29 '23 22:08 erlete

I suspect this has less to do with vscode/nano and more to do with the fact that you're probably working on windows. This appears to be a problem with windows in general as the windows kernel will often fire two kernel events for every change.

dfidler avatar Oct 26 '23 09:10 dfidler

I am having the exact same issue will working on Linux (NixOS 24.01; Kernel 6.9.7-zen1; Ext4 FS).

The file is being edited through neoVIm. In total watchdog posts modified event 10 times. 8 times for the containing directory, 2 times for the actual file.

HiImJulien avatar Jul 06 '24 12:07 HiImJulien