Execution stuck when watching directory updated very fast by external program/script

[mariantirlea]

Hello everyone,

I am tryting to use the watchdog (latest version) on a target folder from a Java project. This folder is updated every time I execute the Maven package command and I want to react on the changes of my package (created by the maven).

The first time after I start the watchdog, I see all the changes in the log file but the second time there are no messages anymore...
Somehow the python script seems to be stuck (nothing is printed anymore).

import time
import logging
from watchdog.observers import Observer
from watchdog.events import LoggingEventHandler

class Event(LoggingEventHandler):
    def dispatch(self, event):
        print(event)

TARGET_DIR = 'D:\\project\\target'

if __name__ == "__main__":
    logging.basicConfig(level=logging.INFO,
                        format='%(asctime)s - %(message)s',
                        datefmt='%Y-%m-%d %H:%M:%S')

    path = TARGET_DIR
    event_handler = LoggingEventHandler()
    observer = Observer()
    observer.schedule(event_handler, path, recursive=True)
    observer.start()
    try:
        while True:
            time.sleep(1)
    except KeyboardInterrupt:
        observer.stop()
    observer.join()

This is like the basic example from the documentation and I cannot understand why is not working.

Then, I have cloned the repo and I have tried to execute the tests to see if everthing is fine on my PC, but one test is failing. I have extracted the difference:

Expected
{<DirCreatedEvent: src_path='C:\\Users\\mti\\AppData\\Local\\Temp\\tmpwvrggzf5\\Strange ☃\\fromdir'>, 
<DirMovedEvent: src_path='C:\\Users\\mti\\AppData\\Local\\Temp\\tmpwvrggzf5\\Strange ☃\\fromdir', dest_path='C:\\Users\\mti\\AppData\\Local\\Temp\\tmpwvrggzf5\\Strange ☃\\todir'>} 

Got     
{<DirCreatedEvent: src_path='C:\\Users\\mti\\AppData\\Local\\Temp\\tmpwvrggzf5\\Strange ☃\\fromdir'>,
<DirModifiedEvent: src_path='C:\\Users\\mti\\AppData\\Local\\Temp\\tmpwvrggzf5\\Strange ☃\\todir'>, 
<DirMovedEvent: src_path='C:\\Users\\mti\\AppData\\Local\\Temp\\tmpwvrggzf5\\Strange ☃\\fromdir', dest_path='C:\\Users\\mti\\AppData\\Local\\Temp\\tmpwvrggzf5\\Strange ☃\\todir'>}

The result of the tests:

collected 81 items / 3 skipped / 78 selected

tests/test_delayed_queue.py::test_delayed_get PASSED                                                                                      [  1%]
tests/test_delayed_queue.py::test_nondelayed_get PASSED                                                                                   [  2%] 
tests/test_emitter.py::test_create PASSED                                                                                                 [  3%] 
tests/test_emitter.py::test_delete PASSED                                                                                                 [  4%] 
tests/test_emitter.py::test_modify PASSED                                                                                                 [  6%]
tests/test_emitter.py::test_move PASSED                                                                                                   [  7%] 
tests/test_emitter.py::test_move_to PASSED                                                                                                [  8%] 
tests/test_emitter.py::test_move_to_full SKIPPED                                                                                          [  9%] 
tests/test_emitter.py::test_move_from PASSED                                                                                              [ 11%]
tests/test_emitter.py::test_move_from_full SKIPPED                                                                                        [ 12%] 
tests/test_emitter.py::test_separate_consecutive_moves PASSED                                                                             [ 13%]
tests/test_emitter.py::test_delete_self PASSED                                                                                            [ 14%] 
tests/test_emitter.py::test_fast_subdirectory_creation_deletion SKIPPED                                                                   [ 16%] 
tests/test_emitter.py::test_passing_unicode_should_give_unicode PASSED                                                                    [ 17%] 
tests/test_emitter.py::test_passing_bytes_should_give_bytes SKIPPED                                                                       [ 18%] 
tests/test_emitter.py::test_recursive_on PASSED                                                                                           [ 19%]
tests/test_emitter.py::test_recursive_off PASSED                                                                                          [ 20%]
tests/test_emitter.py::test_renaming_top_level_directory SKIPPED                                                                          [ 22%] 
tests/test_emitter.py::test_renaming_top_level_directory_on_windows PASSED                                                                [ 23%]
tests/test_emitter.py::test_move_nested_subdirectories SKIPPED                                                                            [ 24%] 
tests/test_emitter.py::test_move_nested_subdirectories_on_windows PASSED                                                                  [ 25%]
tests/test_events.py::test_file_deleted_event PASSED                                                                                      [ 27%]
tests/test_events.py::test_file_delete_event_is_directory PASSED                                                                          [ 28%]
tests/test_events.py::test_file_modified_event PASSED                                                                                     [ 29%]
tests/test_events.py::test_file_modified_event_is_directory PASSED                                                                        [ 30%]
tests/test_events.py::test_file_created_event PASSED                                                                                      [ 32%]
tests/test_events.py::test_file_moved_event PASSED                                                                                        [ 33%]
tests/test_events.py::test_dir_deleted_event PASSED                                                                                       [ 34%]
tests/test_events.py::test_dir_modified_event PASSED                                                                                      [ 35%]
tests/test_events.py::test_dir_created_event PASSED                                                                                       [ 37%]
tests/test_events.py::test_file_system_event_handler_dispatch PASSED                                                                      [ 38%]
tests/test_logging_event_handler.py::test_logging_event_handler_dispatch PASSED                                                           [ 39%] 
tests/test_observer.py::test_schedule_should_start_emitter_if_running PASSED                                                              [ 40%]
tests/test_observer.py::test_schedule_should_not_start_emitter_if_not_running PASSED                                                      [ 41%]
tests/test_observer.py::test_start_should_start_emitter PASSED                                                                            [ 43%]
tests/test_observer.py::test_stop_should_stop_emitter PASSED                                                                              [ 44%]
tests/test_observer.py::test_unschedule_self PASSED                                                                                       [ 45%]
tests/test_observer.py::test_schedule_after_unschedule_all PASSED                                                                         [ 46%]
tests/test_observer.py::test_2_observers_on_the_same_path PASSED                                                                          [ 48%]
tests/test_observer.py::test_start_failure_should_not_prevent_further_try PASSED                                                          [ 49%]
tests/test_observers_api.py::test_observer_constructor PASSED                                                                             [ 50%]
tests/test_observers_api.py::test_observer__eq__ PASSED                                                                                   [ 51%] 
tests/test_observers_api.py::test_observer__ne__ PASSED                                                                                   [ 53%]
tests/test_observers_api.py::test_observer__repr__ PASSED                                                                                 [ 54%]
tests/test_observers_api.py::test_event_emitter PASSED                                                                                    [ 55%]
tests/test_observers_api.py::test_event_dispatcher PASSED                                                                                 [ 56%]
tests/test_observers_api.py::test_observer_basic PASSED                                                                                   [ 58%]
tests/test_observers_polling.py::test___init__ PASSED                                                                                     [ 59%]
tests/test_observers_polling.py::test_delete_watched_dir PASSED                                                                           [ 60%]
tests/test_observers_winapi.py::test___init__ FAILED                                                                                      [ 61%]
tests/test_observers_winapi.py::test_root_deleted PASSED                                                                                  [ 62%]
tests/test_pattern_matching_event_handler.py::test_dispatch PASSED                                                                        [ 64%] 
tests/test_pattern_matching_event_handler.py::test_handler PASSED                                                                         [ 65%] 
tests/test_pattern_matching_event_handler.py::test_ignore_directories PASSED                                                              [ 66%]
tests/test_pattern_matching_event_handler.py::test_ignore_patterns PASSED                                                                 [ 67%]
tests/test_pattern_matching_event_handler.py::test_patterns PASSED                                                                        [ 69%]
tests/test_regex_matching_event_handler.py::test_dispatch PASSED                                                                          [ 70%] 
tests/test_regex_matching_event_handler.py::test_handler PASSED                                                                           [ 71%] 
tests/test_regex_matching_event_handler.py::test_ignore_directories PASSED                                                                [ 72%] 
tests/test_regex_matching_event_handler.py::test_ignore_regexes PASSED                                                                    [ 74%] 
tests/test_regex_matching_event_handler.py::test_regexes PASSED                                                                           [ 75%] 
tests/test_regex_matching_event_handler.py::test_logging_event_handler_dispatch PASSED                                                    [ 76%] 
tests/test_skip_repeats_queue.py::test_basic_queue PASSED                                                                                 [ 77%] 
tests/test_skip_repeats_queue.py::test_allow_nonconsecutive PASSED                                                                        [ 79%] 
tests/test_skip_repeats_queue.py::test_prevent_consecutive PASSED                                                                         [ 80%]
tests/test_skip_repeats_queue.py::test_consecutives_allowed_across_empties PASSED                                                         [ 81%]
tests/test_skip_repeats_queue.py::test_eventlet_monkey_patching SKIPPED                                                                   [ 82%]
tests/test_snapshot_diff.py::test_pickle PASSED                                                                                           [ 83%]
tests/test_snapshot_diff.py::test_move_to PASSED                                                                                          [ 85%]
tests/test_snapshot_diff.py::test_move_from PASSED                                                                                        [ 86%] 
tests/test_snapshot_diff.py::test_move_internal PASSED                                                                                    [ 87%] 
tests/test_snapshot_diff.py::test_move_replace PASSED                                                                                     [ 88%] 
tests/test_snapshot_diff.py::test_dir_modify_on_create PASSED                                                                             [ 90%]
tests/test_snapshot_diff.py::test_dir_modify_on_move PASSED                                                                               [ 91%]
tests/test_snapshot_diff.py::test_detect_modify_for_moved_files PASSED                                                                    [ 92%]
tests/test_snapshot_diff.py::test_replace_dir_with_file PASSED                                                                            [ 93%]
tests/test_snapshot_diff.py::test_permission_error PASSED                                                                                 [ 95%]
tests/test_snapshot_diff.py::test_ignore_device PASSED                                                                                    [ 96%]
tests/test_snapshot_diff.py::test_empty_snapshot PASSED                                                                                   [ 97%]
tests/test_watchmedo.py::test_load_config_valid PASSED                                                                                    [ 98%]
tests/test_watchmedo.py::test_load_config_invalid PASSED                                                                                  [100%]

=================================================================== FAILURES =================================================================== 
________________________________________________________________ test___init__ _________________________________________________________________ 

event_queue = <queue.Queue object at 0x000001B9795E4550>, emitter = <WindowsApiEmitter(Thread-41, stopped daemon 23820)>

    def test___init__(event_queue, emitter):
        emitter.start()
        sleep(SLEEP_TIME)
        mkdir(p('fromdir'))

        sleep(SLEEP_TIME)
        mv(p('fromdir'), p('todir'))

        sleep(SLEEP_TIME)
        emitter.stop()

        # What we need here for the tests to pass is a collection type
        # that is:
        #   * unordered
        #   * non-unique
        # A multiset! Python's collections.Counter class seems appropriate.
        expected = {
            DirCreatedEvent(p('fromdir')),
            DirMovedEvent(p('fromdir'), p('todir')),
        }

        got = set()

        while True:
            try:
                event, _ = event_queue.get_nowait()
            except Empty:
                break
            else:
                got.add(event)

        print("Expected" + str(expected))
        print("Got" + str(got))
>       assert expected == got
E       AssertionError: assert {<DirCreatedE...ge ☃\\todir'>} == {<DirCreatedE...ge ☃\\todir'>}



Name                                               Stmts   Miss  Cover   Missing
--------------------------------------------------------------------------------
src\watchdog\__init__.py                               0      0   100%
src\watchdog\events.py                               217     19    91%   134, 137, 155, 183, 204, 218, 232, 244, 264, 465, 467, 469-470, 508, 596-600
src\watchdog\observers\__init__.py                    29     18    38%   62-65, 68-76, 79, 86-91
src\watchdog\observers\api.py                        155      3    98%   26-27, 250
src\watchdog\observers\fsevents.py                    74     74     0%   19-197
src\watchdog\observers\fsevents2.py                  128    128     0%   17-246
src\watchdog\observers\inotify.py                     79     79     0%   19-218
src\watchdog\observers\inotify_buffer.py              48     48     0%   17-98
src\watchdog\observers\inotify_c.py                  309    309     0%   18-590
src\watchdog\observers\kqueue.py                     233    233     0%   19-706
src\watchdog\observers\polling.py                     57      6    89%   62-63, 91, 133, 148-149
src\watchdog\observers\read_directory_changes.py      57      2    96%   106, 135
src\watchdog\observers\winapi.py                     182      7    96%   111, 113, 119, 318-319, 342, 382
src\watchdog\tricks\__init__.py                       85     85     0%   19-198
src\watchdog\utils\__init__.py                        57     19    67%   42-43, 80, 84, 123-127, 148-163
src\watchdog\utils\bricks.py                          16      0   100%
src\watchdog\utils\compat.py                           6      2    67%   21-22
src\watchdog\utils\delayed_queue.py                   45     13    71%   40-44, 54, 57-58, 78-83
src\watchdog\utils\dirsnapshot.py                    147     11    93%   57-58, 144, 274, 282-283, 296, 338, 347, 350, 353
src\watchdog\utils\echo.py                            64     64     0%   10-162
src\watchdog\utils\platform.py                        25      7    72%   32-39
src\watchdog\utils\unicode_paths.py                   28     15    46%   32, 46-53, 58-63
src\watchdog\utils\win32stat.py                       50     50     0%   17-126
src\watchdog\version.py                                6      0   100%
src\watchdog\watchmedo.py                            216    129    40%   59, 72-73, 94-98, 114-122, 139-144, 170-206, 235-257, 320-350, 428-447, 
517-564, 586, 590
--------------------------------------------------------------------------------
TOTAL                                               2313   1321    43%

=========================================================== short test summary info ============================================================
FAILED tests/test_observers_winapi.py::test___init__ - AssertionError: assert {<DirCreatedE...ge ☃\\todir'>} == {<DirCreatedE...ge ☃\\todir'>}   
============================================ 1 failed, 73 passed, 10 skipped, 15 warnings in 43.98s ============================================ 

Is there something wrong on my PC? How can I repair this test?
I think my first problem is caused by "rapid file created/modified". If I create files manually I see no problems but in my case I need to handle a folder where files are created very fast and a lot of them.

[Zaph-x]

I hit the same issue on one of my projects. This seems to be a Windows-only issue.

When processing 120 files on windows, by dropping them all into an input directory, at the same time, Watchdog hangs after about 38 files.
When doing the same on a Linux machine, running Arch, every file gets processed as expected.

In this specific instance, the processing of the file takes about 5 seconds pr. file, but that should not affect the result.

@mariantirlea I don't think there's anything wrong with your PC. It's simply the Windows API in Watchdog, that is not working as expected.

[BoboTiG]

@Zaph-x you could try to use a bigger buffer size:

watchdog/src/watchdog/observers/winapi.py

Line 267 in 3dea877

BUFFER_SIZE = 2048

For example, here is what I am doing for years and it works pretty well: https://github.com/nuxeo/nuxeo-drive/blob/93bcdc54a5763a29b65efad10429cc7c20a82e8b/nxdrive/engine/watcher/local_watcher.py#L28-L36

[Zaph-x]

@BoboTiG Thank you for this workaround! It seems to do the trick for now.

While this solves the issue temporarily, I don't see it as an actual solution. The library should work equally well on both Linux and Windows, and the fact it just hangs doesn't seem right in my eyes.

[BoboTiG]

@Zaph-x maybe we could change those default values. It would be a simple improvement/fix.

[mariantirlea]

Hello @BoboTiG, I have tested with version 1.0.0 and I have the same problem.
The folder am I am watching is the "target" output of a maven build and I am checking if the jar was changed. I want to react and do something when the build was executed and the jar was modified/created.

It works for the first execution but then it gets stuck and nothing is printed anymore in the console.
Is there any parameter to set or it should work with default values?

Thank you very much, if this is not possible I will try to use polling for this.

[BoboTiG]

Your best bet would be to find out where it is stuck in the code.

[mariantirlea]

The code is very simple. I only scan a folder using default LoggingEventHandler and with recursive flag set to False.

The folder "target" contains after execution: 99 Files and 39 Folders. Before each execution the folder content is deleted and new files are generated.

What I can see it that some files are logged in the console after first execution but nothing is printer after the second/third execution. Somehow it remains blocked and no other events are detected from that point.

If I will have the time I will try to fork the project and to debug it although I don't have experience with native Windows events.

import time
import logging
from watchdog.observers import Observer
from watchdog.events import LoggingEventHandler


TARGET_DIR = 'D:\\project\\target'

if __name__ == "__main__":
    logging.basicConfig(level=logging.INFO,
                        format='%(asctime)s - %(message)s',
                        datefmt='%Y-%m-%d %H:%M:%S')

    path = TARGET_DIR
    event_handler = LoggingEventHandler()
    observer = Observer()
    observer.schedule(event_handler, path, recursive=False)
    observer.start()
    try:
        while True:
            time.sleep(1)
    except KeyboardInterrupt:
        observer.stop()
    observer.join()