cachier

cachier copied to clipboard

It seems that when running cachier, I randomly get these errors:

2021-09-17 09:05:32,357 - fsevents - ERROR - Unhandled exception in FSEventsEmitter
Traceback (most recent call last):
  File "/Users/lorenz/.../signals/.venv/lib/python3.9/site-packages/watchdog/observers/fsevents.py", line 315, in run
    _fsevents.add_watch(self, self.watch, self.events_callback, self.pathnames)
RuntimeError: Cannot add watch <ObservedWatch: path=/Users/lorenz/.cachier/, is_recursive=True> - it is already scheduled

My current solution is to delete the cache, assuming it is corrupt, and then start from scratch.

The most similar error I found on the net was the one reported in https://github.com/spyder-ide/spyder/issues/14803. There, the solution was to unwatch on switching directories/projects.

Hey,

That's look very relevant! Thank you for reaching out.

Anyway to produce the full stack trace, pointing to a code line in cachier itself? Or is this all you're getting? 

It sounds like this will be hard to reproduce to test correctly.

I get that error with my flask server from time to time, I don't have more details:

ERROR:fsevents:Unhandled exception in FSEventsEmitter
Traceback (most recent call last):
  File "/Users/louismartin/miniconda3/envs/dev3.9/lib/python3.9/site-packages/watchdog/observers/fsevents.py", line 315, in run
    _fsevents.add_watch(self, self.watch, self.events_callback, self.pathnames)
RuntimeError: Cannot add watch <ObservedWatch: path=/Users/louismartin/.cachier/, is_recursive=True> - it is already scheduled

(On macOS, python 3.9)

This seems to pop-up every now and then when I use multiple process to access the same cache value, but unable to reproduce consistently.

I can always reproduce the error on mac intel 12.7 using the latest cachier 2.2.2 and Python 3.11.1 with this script:

import logging
import threading
import time
from cachier import cachier


@cachier()
def func(x):
    logging.info("Calculating %s", x)
    time.sleep(1)
    return x * x


def thread_function(name):
    logging.info("Thread %s: starting", name)
    func(1234)
    logging.info("Thread %s: finishing", name)


def main():
    format = "%(asctime)s: %(message)s"
    logging.basicConfig(format=format, level=logging.INFO, datefmt="%H:%M:%S")

    func.clear_cache()

    threads = []
    for index in range(3):
        logging.info("Main    : create and start thread %d.", index)
        x = threading.Thread(target=thread_function, args=(index,))
        threads.append(x)
        x.start()

    for index, thread in enumerate(threads):
        logging.info("Main    : before joining thread %d.", index)
        thread.join()
        logging.info("Main    : thread %d done", index)


if __name__ == "__main__":
    main()

Output (the script hangs and I need to hit Ctrl-C):

11:30:25: Main    : create and start thread 0.
11:30:25: Thread 0: starting
11:30:25: Main    : create and start thread 1.
11:30:25: Thread 1: starting
11:30:25: Main    : create and start thread 2.
11:30:25: Thread 2: starting
11:30:25: Main    : before joining thread 0.
11:30:25: Calculating 1234
11:30:25: Unhandled exception in FSEventsEmitter
Traceback (most recent call last):
  File "/private/tmp/venv/lib/python3.11/site-packages/watchdog/observers/fsevents.py", line 324, in run
    _fsevents.add_watch(self, self.watch, self.events_callback, self.pathnames)
RuntimeError: Cannot add watch <ObservedWatch: path='/Users/ficarell/.cachier/', is_recursive=True> - it is already scheduled
11:30:26: Thread 0: finishing
11:30:26: Main    : thread 0 done
11:30:26: Main    : before joining thread 1.
11:30:26: Thread 2: finishing
^CTraceback (most recent call last):
  File "/private/tmp/try_cachier.py", line 40, in <module>
    main()
  File "/private/tmp/try_cachier.py", line 35, in main
    thread.join()
  File "/Users/ficarell/.pyenv/versions/3.11.1/lib/python3.11/threading.py", line 1112, in join
    self._wait_for_tstate_lock()
  File "/Users/ficarell/.pyenv/versions/3.11.1/lib/python3.11/threading.py", line 1132, in _wait_for_tstate_lock
    if lock.acquire(block, timeout):
       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
KeyboardInterrupt

Packages installed in the virtualenv:

❯ python -V
Python 3.11.1
❯ pip freeze
cachier==2.2.2
portalocker==2.8.2
watchdog==3.0.0

I don't get the error in any of these cases:

• if running on Linux
• if time.sleep(1) is removed
• if the disk cache is reused (not executing func.clear_cache())

Killing (CTRL-C) a long running cached function mid-miss can readily reproduce this.

Thank you both for chiming in, and @GianlucaFicarelli especially for the very detailed way to reproduce this!

This dramatically increases the chance that a past active contributor or a new one will take this on and try to solve this bug.