Testosterone and sensitivity.
[kiosk.git] / kiosk.py
index 083e91760000ecfb5bcdfa8b8cdcfe2d7896865f..fe9e174262537b5267541d52483a8f3d746152ab 100755 (executable)
--- 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("</TABLE>")
 
 
+@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__":