X-Git-Url: https://wannabe.guru.org/gitweb/?a=blobdiff_plain;f=kiosk.py;h=fe9e174262537b5267541d52483a8f3d746152ab;hb=5ea88ab72e175e2d4f57ae8645ca6f825549a7a9;hp=083e91760000ecfb5bcdfa8b8cdcfe2d7896865f;hpb=0f522f8824e357616c3d267bbca0166f62ac1721;p=kiosk.git diff --git a/kiosk.py b/kiosk.py index 083e917..fe9e174 100755 --- a/kiosk.py +++ b/kiosk.py @@ -10,7 +10,7 @@ import re from threading import Thread import time import tracemalloc -from typing import Dict, List, Optional +from typing import Dict, List, Optional, Tuple from queue import Queue import astral # type: ignore @@ -22,6 +22,7 @@ import pytz from pyutils import ( bootstrap, config, + logging_utils, ) from pyutils.datetimes import datetime_utils from pyutils.files import file_utils @@ -37,9 +38,10 @@ import trigger_catalog cfg = config.add_commandline_args( f"Kiosk Server ({__file__})", "A python server that runs a kiosk." ) -logger = logging.getLogger(__file__) +logger = logging.getLogger(__name__) +@logging_utils.LoggingContext(logger, prefix="janitor:") def thread_janitor() -> None: tracemalloc.start() tracemalloc_target = 0.0 @@ -61,26 +63,27 @@ def thread_janitor() -> None: key_type = "lineno" limit = 10 top_stats = snapshot.statistics(key_type) - logger.info(f"janitor: Top {limit} lines") + logger.info(f"Top {limit} lines") for index, stat in enumerate(top_stats[:limit], 1): frame = stat.traceback[0] # replace "/path/to/module/file.py" with "module/file.py" filename = os.sep.join(frame.filename.split(os.sep)[-2:]) logger.info( - f"janitor: #{index}: {filename}:{frame.lineno}: {stat.size / 1024:.1f} KiB" + f"#{index}: {filename}:{frame.lineno}: {stat.size / 1024:.1f} KiB" ) other = top_stats[limit:] if other: size = sum(stat.size for stat in other) - logger.info(f"janitor: {len(other)} others: {size/1024:.1f} KiB") + logger.info(f"{len(other)} others: {size/1024:.1f} KiB") total = sum(stat.size for stat in top_stats) - logger.info(f"janitor: Total allocated size: {total / 1024:.1f} KiB") + logger.info(f"Total allocated size: {total / 1024:.1f} KiB") if now > gc_target: - logger.info("janitor: kicking off a manual gc operation now.") + logger.info("Kicking off a manual gc operation now.") gc.collect() gc_target = now + 120.0 + logger.info("Having a little nap...") time.sleep(30.0) @@ -98,7 +101,7 @@ def guess_page(command: str, page_chooser: chooser.chooser) -> str: page = page.replace("gohouse", "house list honey do") page = page.replace("gcal", "google calendar events") page = page.replace("mynorthwest", "northwest news") - page = page.replace("myq", "myq garage door status") + page = page.replace("ratago", "ratago garage door status") page = page.replace("gomenu", "dinner menu") page = page.replace("gmaps-seattle-unwrapped", "traffic") page = page.replace("gomenu", "dinner menu") @@ -147,7 +150,7 @@ def process_command( while True: (page, _) = page_chooser.choose_next_page() if page == page_history[0]: - logger.debug(f"chooser: {page} is the same as last time! Try again.") + logger.debug(f"{page} is the same as last time! Try again.") else: break elif "internal" in command: @@ -214,6 +217,7 @@ def process_command( return page +@logging_utils.LoggingContext(logger, prefix="chooser:") def thread_change_current(command_queue: Queue) -> None: page_history = ["", ""] swap_page_target = 0.0 @@ -229,53 +233,67 @@ def thread_change_current(command_queue: Queue) -> None: or "wsj" in page ) - page_chooser = chooser.weighted_random_chooser_with_triggers( - trigger_catalog.get_triggers(), [filter_news_during_dinnertime] - ) - current_file = os.path.join(kiosk_constants.pages_dir, "current.shtml") - emergency_file = os.path.join(kiosk_constants.pages_dir, "reload_immediately.html") - - # Main chooser loop - while True: - now = time.time() - - # Check for a verbal command. + def check_for_command() -> Tuple[Optional[str], Optional[str]]: command = None try: command = command_queue.get(block=False) except Exception: command = None - if command is not None: - logger.info( - f'chooser: We got a verbal command ("{command}"), parsing it...' - ) + if command: + logger.info(f'We got a verbal command ("{command}"), parsing it...') page = process_command(command, page_history, page_chooser) if page: - triggered = True + return page, command + return None, None - if not triggered: - while True: - (page, triggered) = page_chooser.choose_next_page() - if triggered: - logger.info("chooser: A trigger is active...") - break + def choose_page_randomly() -> Tuple[str, bool]: + while True: + (page, triggered) = page_chooser.choose_next_page() + if triggered: + logger.info("A trigger is active...") + break + else: + if page == page_history[0]: + logger.debug(f"{page} is the same as last time! Try again.") else: - if page == page_history[0]: - logger.debug( - f"chooser: {page} is the same as last time! Try again." - ) - else: - break + break + return (page, triggered) + + page_chooser = chooser.weighted_random_chooser_with_triggers( + trigger_catalog.get_triggers(), [filter_news_during_dinnertime] + ) + current_file = os.path.join(kiosk_constants.pages_dir, "current.shtml") + emergency_file = os.path.join(kiosk_constants.pages_dir, "reload_immediately.html") + + # Main chooser loop -- note that this executes a couple of times per second + # to be responsive to triggers. + while True: + now = time.time() + page = None + triggered = False + command = None + + # Is there a verbal command to parse? + (page, command) = check_for_command() + if page and command: + triggered = True + else: + # If not, choose the a (new!) page randomly or respond to a trigger. + (page, triggered) = choose_page_randomly() + # By now we have a page and we may be triggered. if triggered: - if page != page_history[0] or (swap_page_target - now) < 10.0: + + # If we are triggered and the page is new, change the + # current page to the new page immediately. + if page != page_history[0]: logger.info( - f"chooser: An emergency page reload to {page} is needed at this time." + f"An emergency page reload to {page} is needed at this time." ) swap_page_target = now + kiosk_constants.emergency_refresh_period_sec - # Set current.shtml to the right page. + # Set current.shtml to the triggered page. try: with open(current_file, "w") as f: emit( @@ -284,41 +302,42 @@ def thread_change_current(command_queue: Queue) -> None: override_refresh_sec=kiosk_constants.emergency_refresh_period_sec, command=command, ) - logger.debug(f"chooser: Wrote {current_file}.") - except Exception as e: - logger.exception(e) - logger.error( - f"chooser: Unexpected exception; assuming {page} doesn't exist?!" + logger.debug(f"Wrote {current_file}.") + except Exception: + logger.exception( + f"Unexpected exception; assuming {page} doesn't exist?!" ) continue - # Also notify XMLHTTP clients that they need to refresh now. + # Notify XMLHTTP clients that they need to refresh now. with open(emergency_file, "w") as f: f.write(f"Reload, suckers... you HAVE to see {page}!") - logger.debug(f"chooser: Wrote {emergency_file}...") + logger.debug(f"Wrote {emergency_file}...") # Fix this hack... maybe read the webserver logs and see if it # actually was picked up? time.sleep(0.999) os.remove(emergency_file) - logger.debug(f"chooser: ...and removed {emergency_file}.") + logger.debug(f"...and removed {emergency_file}.") + page_history.insert(0, page) + page_history = page_history[0:10] + # If we're not triggered, only render a new page if time has expired. elif now >= swap_page_target: - assert page != page_history[0] - logger.info(f"chooser: Nominal choice of {page} as the next to show.") + logger.info(f"Nominal choice of {page} as the next to show.") swap_page_target = now + kiosk_constants.refresh_period_sec try: with open(current_file, "w") as f: emit(f, page) - logger.debug(f"chooser: Wrote {current_file}.") - except Exception as e: - logger.exception(e) - logger.error( - f"chooser: Unexpected exception; assuming {page} doesn't exist?!" + logger.debug(f"Wrote {current_file}.") + except Exception: + logger.exception( + f"Unexpected exception; assuming {page} doesn't exist?!" ) continue - page_history.insert(0, page) - page_history = page_history[0:10] + page_history.insert(0, page) + page_history = page_history[0:10] + time.sleep(0.5) @@ -589,7 +608,7 @@ def renderer_update_internal_stats_page( render_counts: collections.Counter, render_times: Dict[str, np.array], ) -> None: - logger.info("renderer: Updating internal render statistics page.") + logger.info("Updating internal render statistics page.") with file_writer.file_writer(kiosk_constants.render_stats_pagename) as f: f.write( """ @@ -638,6 +657,7 @@ def renderer_update_internal_stats_page( f.write("") +@logging_utils.LoggingContext(logger, prefix="renderer:") def thread_invoke_renderers() -> None: render_times: Dict[str, np.array] = {} render_counts: collections.Counter = collections.Counter() @@ -648,17 +668,17 @@ def thread_invoke_renderers() -> None: # Main renderer loop while True: - logger.info("renderer: invoking all overdue renderers in catalog...") + logger.info("invoking all overdue renderers in catalog...") for r in renderer_catalog.get_renderers(): name = r.get_name() now = time.time() - logger.info(f"renderer: Invoking {name}'s render method.") + logger.info(f"Invoking {name}'s render method.") try: r.render() except Exception as e: logger.exception(e) logger.error( - f"renderer: Unexpected and unhandled exception ({e}) in {name}, swallowing it." + f"Unexpected and unhandled exception ({e}) in {name}, swallowing it." ) continue @@ -674,17 +694,16 @@ def thread_invoke_renderers() -> None: times = np.insert(times, 0, delta) render_times[name] = times if delta > 1.0: - hdr = "renderer: " logger.warning( f""" -{hdr} Warning: {name}'s rendering took {delta:5.2f}s. -{hdr} FYI: {name}'s render times: p25={np.percentile(times, 25):5.2f}, p50={np.percentile(times, 50):5.2f}, p75={np.percentile(times, 75):5.2f}, p90={np.percentile(times, 90):5.2f}, p99={np.percentile(times, 99):5.2f} +Warning: {name}'s rendering took {delta:5.2f}s. +FYI: {name}'s render times: p25={np.percentile(times, 25):5.2f}, p50={np.percentile(times, 50):5.2f}, p75={np.percentile(times, 75):5.2f}, p90={np.percentile(times, 90):5.2f}, p99={np.percentile(times, 99):5.2f} """ ) # Update a page about internal stats of renderers. renderer_update_internal_stats_page(last_render, render_counts, render_times) - logger.info("renderer: having a little nap...") + logger.info("Having a little nap...") time.sleep(kiosk_constants.render_period_sec) @@ -695,57 +714,67 @@ def main() -> None: renderer_thread: Optional[Thread] = None janitor_thread: Optional[Thread] = None hotword_thread: Optional[Thread] = None - while True: - if hotword_thread is None or not hotword_thread.is_alive(): - if hotword_thread is None: - logger.info("watchdog: Starting up the hotword detector thread...") - else: - logger.warning( - "watchdog: The hotword detector thread seems to have died; restarting it and hoping for the best." - ) - keyword_paths = [pvporcupine.KEYWORD_PATHS[x] for x in ["bumblebee"]] - sensitivities = [0.7] * len(keyword_paths) - listener = listen.HotwordListener( - command_queue, - keyword_paths, - sensitivities, - ) - hotword_thread = Thread(target=listener.listen_forever, args=()) - hotword_thread.start() - if changer_thread is None or not changer_thread.is_alive(): - if changer_thread is None: - logger.info("watchdog: Starting up the current page changer thread...") - else: - logger.warning( - "watchdog: The current page changer thread seems to have died; restarting it and hoping for the best." + with logging_utils.LoggingContext(logger, prefix="watchdog:"): + while True: + if hotword_thread is None or not hotword_thread.is_alive(): + if hotword_thread is None: + logger.info("Starting up the hotword detector thread...") + else: + logger.warning( + "The hotword detector thread seems to have died; restarting it and hoping for the best." + ) + keyword_paths = [pvporcupine.KEYWORD_PATHS[x] for x in ["bumblebee"]] + + # Sensitivity is the parameter that enables trading + # miss rate for the false alarm rate. It is a floating + # point number within [0, 1]. A higher sensitivity + # reduces the miss rate at the cost of increased false + # alarm rate. + sensitivities = [0.4] * len(keyword_paths) + listener = listen.HotwordListener( + command_queue, + keyword_paths, + sensitivities, ) - changer_thread = Thread(target=thread_change_current, args=(command_queue,)) - changer_thread.start() + hotword_thread = Thread(target=listener.listen_forever, args=()) + hotword_thread.start() - if renderer_thread is None or not renderer_thread.is_alive(): - if renderer_thread is None: - logger.info("watchdog: Starting up the page renderer thread...") - else: - logger.warning( - "watchdog: The page renderer thread seems to have died; restarting it and hoping for the best." + if changer_thread is None or not changer_thread.is_alive(): + if changer_thread is None: + logger.info("Starting up the current page changer thread...") + else: + logger.warning( + "The current page changer thread seems to have died; restarting it and hoping for the best." + ) + changer_thread = Thread( + target=thread_change_current, args=(command_queue,) ) - renderer_thread = Thread(target=thread_invoke_renderers, args=()) - renderer_thread.start() + changer_thread.start() - if janitor_thread is None or not janitor_thread.is_alive(): - if janitor_thread is None: - logger.info("watchdog: Starting up the memory janitor thread...") - else: - logger.warning( - "watchdog: The memory janitor thread seems to have died; restarting it and hoping for the best." - ) - janitor_thread = Thread(target=thread_janitor, args=()) - janitor_thread.start() + if renderer_thread is None or not renderer_thread.is_alive(): + if renderer_thread is None: + logger.info("Starting up the page renderer thread...") + else: + logger.warning( + "The page renderer thread seems to have died; restarting it and hoping for the best." + ) + renderer_thread = Thread(target=thread_invoke_renderers, args=()) + renderer_thread.start() + + if janitor_thread is None or not janitor_thread.is_alive(): + if janitor_thread is None: + logger.info("Starting up the memory janitor thread...") + else: + logger.warning( + "The memory janitor thread seems to have died; restarting it and hoping for the best." + ) + janitor_thread = Thread(target=thread_janitor, args=()) + janitor_thread.start() - # Have a little break and then check to make sure all threads are still alive. - logger.debug("watchdog: having a little nap.") - time.sleep(kiosk_constants.check_threads_period_sec) + # Have a little break and then check to make sure all threads are still alive. + logger.debug("Having a little nap...") + time.sleep(kiosk_constants.check_threads_period_sec) if __name__ == "__main__":