pw_watch: Add proper debouncing; enter to build
This adds a more sophisticated debounce mechanism to the watcher, which
restarts with each incoming file change. This prevents starting builds
too early when doing rebases or pulls which trigger many file changes,
and can cause Ninja or GN to get into an inconsistent state.
If filesystem changes happen during a build, the build is marked as
"interrupted" and failed, to prevent confusing inconsistent builds.
Additionally, this change runs a build when pressing 'enter'. This is
useful in many cases where something outside of the watcher's view
changes that should trigger a rebuild; for example, when first running
pw watch.
Change-Id: Ifa6e36eeaf742f93ce451115f18691490e6085d4
diff --git a/pw_watch/py/pw_watch/debounce.py b/pw_watch/py/pw_watch/debounce.py
new file mode 100644
index 0000000..66cf36f
--- /dev/null
+++ b/pw_watch/py/pw_watch/debounce.py
@@ -0,0 +1,157 @@
+# Copyright 2020 The Pigweed Authors
+#
+# Licensed under the Apache License, Version 2.0 (the "License"); you may not
+# use this file except in compliance with the License. You may obtain a copy of
+# the License at
+#
+# https://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+# WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+# License for the specific language governing permissions and limitations under
+# the License.
+"""Run an interruptable, cancellable function after debouncing run requests"""
+
+import enum
+import logging
+import threading
+from abc import ABC, abstractmethod
+
+_LOG = logging.getLogger(__name__)
+
+
+class DebouncedFunction(ABC):
+ """Function to be run by Debouncer"""
+ @abstractmethod
+ def run(self):
+ """Run the function"""
+
+ @abstractmethod
+ def cancel(self):
+ """Cancel an in-progress run of the function.
+ Must be called from different thread than run().
+ Returns true if run was successfully cancelled, false otherwise"""
+
+ @abstractmethod
+ def on_complete(self, cancelled=False):
+ """Called after run() finishes. If true, cancelled indicates
+ cancel() was invoked during the last run()"""
+
+ # Note: The debounce uses threads. Since there is no way to guarantee which
+ # thread recieves a KeyboardInterrupt, it is necessary catch this event
+ # in all debouncer threads and forward it to the user.
+ @abstractmethod
+ def on_keyboard_interrupt(self):
+ """Called when keyboard interrupt is delivered to a debouncer thread"""
+
+
+class State(enum.Enum):
+ IDLE = 1
+ DEBOUNCING = 2
+ RUNNING = 3
+ INTERRUPTED = 4
+ COOLDOWN = 5
+
+
+class Debouncer:
+ """Run an interruptable, cancellable function with debouncing"""
+ def __init__(self, function):
+ super().__init__()
+ self.function = function
+
+ self.state = State.IDLE
+
+ self.debounce_seconds = 1
+ self.debounce_timer = None
+
+ self.cooldown_seconds = 1
+ self.cooldown_timer = None
+
+ self.lock = threading.Lock()
+
+ def press(self, idle_message=None):
+ """Try to run the function for the class. If the function is recently
+ started, this may push out the deadline for actually starting. If the
+ function is already running, will interrupt the function"""
+ _LOG.debug('Press - state = %s', str(self.state))
+ with self.lock:
+ if self.state == State.IDLE:
+ if idle_message:
+ _LOG.info(idle_message)
+ self._start_debounce_timer()
+ self._transition(State.DEBOUNCING)
+
+ elif self.state == State.DEBOUNCING:
+ self._start_debounce_timer()
+
+ elif self.state == State.RUNNING:
+ # Function is already running, so do nothing.
+ # TODO: It may make sense to queue an automatic re-build
+ # when an interruption is detected. Follow up on this after
+ # using the interruptable watcher in practice for awhile.
+
+ # Push an empty line to flush ongoing I/O in subprocess.
+ print()
+ print()
+ _LOG.error('File change detected while running')
+ _LOG.error('Build may be inconsistent or broken')
+ print()
+ self.function.cancel()
+ self._transition(State.INTERRUPTED)
+
+ elif self.state == State.INTERRUPTED:
+ # Function is running but was already interrupted. Do nothing.
+ _LOG.debug('Ignoring press - interrupted')
+
+ elif self.state == State.COOLDOWN:
+ # Function just finished and we are cooling down, so do nothing.
+ _LOG.debug('Ignoring press - cooldown')
+
+ def _transition(self, new_state):
+ _LOG.debug('State: %s -> %s', str(self.state), str(new_state))
+ self.state = new_state
+
+ def _start_debounce_timer(self):
+ assert self.lock.locked()
+ if self.state == State.DEBOUNCING:
+ self.debounce_timer.cancel()
+ self.debounce_timer = threading.Timer(self.debounce_seconds,
+ self._run_function)
+ self.debounce_timer.start()
+
+ # Called from debounce_timer thread.
+ def _run_function(self):
+ try:
+ with self.lock:
+ assert self.state == State.DEBOUNCING
+ self.debounce_timer = None
+ self._transition(State.RUNNING)
+
+ # Must run the function without the lock held so further press()
+ # calls don't deadlock.
+ _LOG.debug('Running debounced function')
+ self.function.run()
+
+ _LOG.debug('Finished running debounced function')
+ with self.lock:
+ self.function.on_complete(self.state == State.INTERRUPTED)
+ self._transition(State.COOLDOWN)
+ self._start_cooldown_timer()
+ except KeyboardInterrupt:
+ self.function.on_keyboard_interrupt()
+
+ def _start_cooldown_timer(self):
+ assert self.lock.locked()
+ self.cooldown_timer = threading.Timer(self.cooldown_seconds,
+ self._exit_cooldown)
+ self.cooldown_timer.start()
+
+ # Called from cooldown_timer thread.
+ def _exit_cooldown(self):
+ try:
+ with self.lock:
+ self.cooldown_timer = None
+ self._transition(State.IDLE)
+ except KeyboardInterrupt:
+ self.function.on_keyboard_interrupt()
diff --git a/pw_watch/py/pw_watch/watch.py b/pw_watch/py/pw_watch/watch.py
index 1db9261..48f9ab2 100755
--- a/pw_watch/py/pw_watch/watch.py
+++ b/pw_watch/py/pw_watch/watch.py
@@ -15,7 +15,6 @@
import argparse
from dataclasses import dataclass
-import enum
import glob
import logging
import os
@@ -23,7 +22,7 @@
import shlex
import subprocess
import sys
-import time
+import threading
from typing import List, NamedTuple, Optional, Sequence, Tuple
from watchdog.events import FileSystemEventHandler
@@ -35,6 +34,8 @@
import pw_cli.env
import pw_cli.plugins
+from pw_watch.debounce import DebouncedFunction, Debouncer, State
+
_COLOR = pw_cli.color.colors()
_LOG = logging.getLogger(__name__)
@@ -71,11 +72,6 @@
"""
-class _State(enum.Enum):
- WAITING_FOR_FILE_CHANGE_EVENT = 1
- COOLDOWN_IGNORING_EVENTS = 2
-
-
# TODO(keir): Figure out a better strategy for exiting. The problem with the
# watcher is that doing a "clean exit" is slow. However, by directly exiting,
# we remove the possibility of the wrapper script doing anything on exit.
@@ -108,7 +104,7 @@
return shlex.join(self.args())
-class PigweedBuildWatcher(FileSystemEventHandler):
+class PigweedBuildWatcher(FileSystemEventHandler, DebouncedFunction):
"""Process filesystem events and launch builds if necessary."""
def __init__(
self,
@@ -119,18 +115,37 @@
ignore_dirs=Optional[List[str]],
charset: WatchCharset = _ASCII_CHARSET,
):
- super().__init__()
+ super(PigweedBuildWatcher, self).__init__()
self.patterns = patterns
self.ignore_patterns = ignore_patterns
self.case_sensitive = case_sensitive
- self.state = _State.WAITING_FOR_FILE_CHANGE_EVENT
self.build_commands = build_commands
self.ignore_dirs = ignore_dirs or []
self.ignore_dirs.extend(cmd.build_dir for cmd in self.build_commands)
self.cooldown_finish_time = None
self.charset: WatchCharset = charset
+ self.debouncer = Debouncer(self)
+
+ # Track state of a build. These need to be members instead of locals
+ # due to the split between dispatch(), run(), and on_complete().
+ self.matching_path = None
+ self.builds_succeeded = []
+
+ self.wait_for_keypress_thread = threading.Thread(
+ None, self._wait_for_enter)
+ self.wait_for_keypress_thread.start()
+
+ def _wait_for_enter(self):
+ try:
+ while True:
+ _ = input()
+ if self.debouncer.state == State.IDLE:
+ self.debouncer.press('Manual build triggered...')
+ except KeyboardInterrupt:
+ _exit_due_to_interrupt()
+
def path_matches(self, raw_path):
"""Returns true if path matches according to the watcher patterns"""
modified_path = pathlib.Path(raw_path).resolve()
@@ -181,15 +196,23 @@
if matching_path:
self.handle_matched_event(matching_path)
- def run_builds(self, matching_path):
+ def handle_matched_event(self, matching_path):
+ if self.matching_path is None:
+ self.matching_path = matching_path
+
+ self.debouncer.press('File change detected: %s; debouncing...' %
+ matching_path)
+
+ # Implementation of DebouncedFunction.run()
+ def run(self):
"""Run all the builds in serial and capture pass/fail for each."""
# Clear the screen and show a banner indicating the build is starting.
print('\033c', end='') # TODO(pwbug/38): Not Windows compatible.
print(_COLOR.magenta(_BUILD_MESSAGE))
- _LOG.info('Change detected: %s', matching_path)
+ _LOG.info('Change detected: %s', self.matching_path)
- builds_succeeded = []
+ self.builds_succeeded = []
num_builds = len(self.build_commands)
_LOG.info(f'Starting build with {num_builds} directories')
for i, cmd in enumerate(self.build_commands, 1):
@@ -211,48 +234,59 @@
level = logging.ERROR
tag = '(FAIL)'
_LOG.log(level, f'[{i}/{num_builds}] Finished build: {cmd} {tag}')
- builds_succeeded.append(build_ok)
+ self.builds_succeeded.append(build_ok)
- if all(builds_succeeded):
- _LOG.info('Finished; all successful.')
+ # Implementation of DebouncedFunction.cancel()
+ def cancel(self):
+ # TODO: Finish implementing this by supporting cancelling the currently
+ # running build. This will require some subprocess shenanigans and
+ # so will leave this for later.
+ return False
+
+ # Implementation of DebouncedFunction.run()
+ def on_complete(self, cancelled=False):
+ # First, use the standard logging facilities to report build status.
+ if cancelled:
+ _LOG.error('Finished; build was interrupted')
+ elif all(self.builds_succeeded):
+ _LOG.info('Finished; all successful')
else:
- _LOG.info('Finished; some builds failed.')
+ _LOG.info('Finished; some builds failed')
- # Write out build summary table so you can tell which builds passed
- # and which builds failed.
- print()
- print(' .------------------------------------')
- print(' |')
- for (succeeded, cmd) in zip(builds_succeeded, self.build_commands):
- slug = self.charset.slug_ok if succeeded else self.charset.slug_fail
- print(f' | {slug} {cmd}')
- print(' |')
- print(" '------------------------------------")
+ # Then, show a more distinct colored banner.
+ if not cancelled:
+ # Write out build summary table so you can tell which builds passed
+ # and which builds failed.
+ print()
+ print(' .------------------------------------')
+ print(' |')
+ for (succeeded, cmd) in zip(self.builds_succeeded,
+ self.build_commands):
+ slug = (self.charset.slug_ok
+ if succeeded else self.charset.slug_fail)
+ print(f' | {slug} {cmd}')
+ print(' |')
+ print(" '------------------------------------")
+ else:
+ # Build was interrupted.
+ print()
+ print(' .------------------------------------')
+ print(' |')
+ print(' | ', self.charset.slug_fail, '- interrupted')
+ print(' |')
+ print(" '------------------------------------")
# Show a large color banner so it is obvious what the overall result is.
- if all(builds_succeeded):
+ if all(self.builds_succeeded) and not cancelled:
print(_COLOR.green(_PASS_MESSAGE))
else:
print(_COLOR.red(_FAIL_MESSAGE))
- def handle_matched_event(self, matching_path):
- if self.state == _State.WAITING_FOR_FILE_CHANGE_EVENT:
- self.run_builds(matching_path)
+ self.matching_path = None
- # Don't set the cooldown end time until after the build.
- self.state = _State.COOLDOWN_IGNORING_EVENTS
- _LOG.debug('State: WAITING -> COOLDOWN (file change trigger)')
-
- # 500ms is enough to allow the spurious events to get ignored.
- self.cooldown_finish_time = time.time() + 0.5
-
- elif self.state == _State.COOLDOWN_IGNORING_EVENTS:
- if time.time() < self.cooldown_finish_time:
- _LOG.debug('Skipping event; cooling down...')
- else:
- _LOG.debug('State: COOLDOWN -> WAITING (cooldown expired)')
- self.state = _State.WAITING_FOR_FILE_CHANGE_EVENT
- self.handle_matched_event(matching_path) # Retrigger.
+ # Implementation of DebouncedFunction.on_keyboard_interrupt()
+ def on_keyboard_interrupt(self):
+ _exit_due_to_interrupt()
_WATCH_PATTERN_DELIMITER = ','
@@ -300,6 +334,22 @@
'targets in out/build_dir.'))
+def _exit_due_to_interrupt():
+ # To keep the log lines aligned with each other in the presence of
+ # a '^C' from the keyboard interrupt, add a newline before the log.
+ print()
+ print()
+ _LOG.info('Got Ctrl-C; exiting...')
+
+ # Note: The "proper" way to exit is via observer.stop(), then
+ # running a join. However it's slower, so just exit immediately.
+ #
+ # Additionally, since there are several threads in the watcher, the usual
+ # sys.exit approach doesn't work. Instead, run the low level exit which
+ # kills all threads.
+ os._exit(0) # pylint: disable=protected-access
+
+
def watch(build_commands=None, patterns=None, ignore_patterns=None):
"""TODO(keir) docstring"""
@@ -389,14 +439,7 @@
while observer.isAlive():
observer.join(1)
except KeyboardInterrupt:
- # To keep the log lines aligned with each other in the presence of
- # a '^C' from the keyboard interrupt, add a newline before the log.
- print()
- _LOG.info('Got Ctrl-C; exiting...')
-
- # Note: The "proper" way to exit is via observer.stop(), then
- # running a join. However it's slower, so just exit immediately.
- sys.exit(0)
+ _exit_due_to_interrupt()
observer.join()