Review and reduce amount of log messages being displayed in the UI

pupil_src/launchables/eye.py

@@ -402,7 +402,7 @@ def on_drop(window, paths):
             os.path.join(g_pool.user_dir, "user_settings_eye{}".format(eye_id))
         )
         if parse_version(session_settings.get("version", "0.0")) != g_pool.version:
-            logger.info(
+            logger.debug(
                 "Session setting are from a different version of this app. I will not use those."
             )
             session_settings.clear()
@@ -607,7 +607,7 @@ def set_window_size():
         def window_should_update():
             return next(window_update_timer)
 
-        logger.warning("Process started.")
+        logger.debug("Process started.")
 
         frame = None
 
@@ -636,7 +636,7 @@ def window_should_update():
                         g_pool.rec_path = notification["rec_path"]
                         raw_mode = notification["compression"]
                         start_time_synced = notification["start_time_synced"]
-                        logger.info(f"Will save eye video to: {g_pool.rec_path}")
+                        logger.debug(f"Saving eye video to: {g_pool.rec_path}")
                         video_path = os.path.join(
                             g_pool.rec_path, "eye{}.mp4".format(eye_id)
                         )
@@ -653,11 +653,11 @@ def window_should_update():
                             g_pool.writer = MPEG_Writer(video_path, start_time_synced)
                 elif subject == "recording.stopped":
                     if g_pool.writer:
-                        logger.info("Done recording.")
+                        logger.debug("Done recording.")
                         try:
                             g_pool.writer.release()
                         except RuntimeError:
-                            logger.error("No eye video recorded")
+                            logger.info("No eye video recorded")
                         else:
                             # TODO: wrap recording logic into plugin
                             g_pool.capture.intrinsics.save(
@@ -780,7 +780,7 @@ def window_should_update():
 
         # in case eye recording was still runnnig: Save&close
         if g_pool.writer:
-            logger.info("Done recording eye.")
+            logger.debug("Done recording eye.")
             g_pool.writer.release()
             g_pool.writer = None
 
@@ -815,7 +815,7 @@ def window_should_update():
     glfw.destroy_window(main_window)
     g_pool.gui.terminate()
     glfw.terminate()
-    logger.info("Process shutting down.")
+    logger.debug("Process shutting down.")
 
 
 def eye_profiled(

pupil_src/launchables/world.py

@@ -140,8 +140,8 @@ def detection_enabled_setter(value: int):
         from methods import normalize, denormalize, delta_t, get_system_info, timer
         from uvc import get_time_monotonic
 
-        logger.info("Application Version: {}".format(version))
-        logger.info("System Info: {}".format(get_system_info()))
+        logger.debug("Application Version: {}".format(version))
+        logger.debug("System Info: {}".format(get_system_info()))
         logger.debug(f"Debug flag: {debug}")
 
         import audio
@@ -459,7 +459,7 @@ def get_dt():
             os.path.join(g_pool.user_dir, "user_settings_world")
         )
         if parse_version(session_settings.get("version", "0.0")) != g_pool.version:
-            logger.info(
+            logger.debug(
                 "Session setting are from a different version of this app. I will not use those."
             )
             session_settings.clear()
@@ -716,7 +716,7 @@ def window_should_update():
             launch_eye_process(0, delay=0.3)
 
         ipc_pub.notify({"subject": "world_process.started"})
-        logger.warning("Process started.")
+        logger.debug("Process started.")
 
         if platform.system() == "Darwin":
             # On macOS, calls to glfw.swap_buffers() deliberately take longer in case of
@@ -866,7 +866,7 @@ def window_should_update():
         stop_eye_process(0)
         stop_eye_process(1)
 
-        logger.info("Process shutting down.")
+        logger.debug("Process shutting down.")
         ipc_pub.notify({"subject": "world_process.stopped"})
         sleep(1.0)
 

pupil_src/shared_modules/calibration_choreography/base_plugin.py

@@ -508,7 +508,7 @@ def on_notify(self, note_dict):
 
         if note.action == ChoreographyAction.SHOULD_STOP:
             if not self.is_active:
-                logger.warning(f"{self.current_mode.label} already stopped.")
+                logger.debug(f"{self.current_mode.label} already stopped.")
             else:
                 self._perform_stop()
 

pupil_src/shared_modules/camera_models.py

@@ -345,9 +345,8 @@ def save(self, directory, custom_name=None):
         intrinsics_dict[str(self.resolution)] = intrinsics
 
         save_object(intrinsics_dict, save_path)
-        logger.info(
-            f"Intrinsics for camera {cam_name} at resolution {self.resolution} saved"
-            f" to {save_path}"
+        logger.debug(
+            f"Saved camera intrinsics for {cam_name} {self.resolution} to {save_path}"
         )
 
     @staticmethod
@@ -380,7 +379,7 @@ def from_file(
                 )
 
             intrinsics = intrinsics_dict[str(resolution)]
-            logger.info("Loading previously recorded intrinsics...")
+            logger.debug("Loading previously recorded intrinsics...")
             return Camera_Model._from_raw_intrinsics(cam_name, resolution, intrinsics)
         except Exception:
             logger.debug(
@@ -401,7 +400,7 @@ def from_default(cam_name: str, resolution: T.Tuple[int]) -> "Camera_Model":
             cam_name in default_intrinsics
             and str(resolution) in default_intrinsics[cam_name]
         ):
-            logger.info("Loading default intrinsics!")
+            logger.debug("Loading default intrinsics!")
             intrinsics = default_intrinsics[cam_name][str(resolution)]
             return Camera_Model._from_raw_intrinsics(cam_name, resolution, intrinsics)
         else:

pupil_src/shared_modules/gaze_mapping/utils.py

@@ -24,10 +24,17 @@ def _filter_pupil_list_by_confidence(pupil_list, threshold):
     pupil_list = [p for p in pupil_list if p["confidence"] >= threshold]
     len_post_filter = len(pupil_list)
     dismissed_percentage = 100 * (1.0 - len_post_filter / len_pre_filter)
-    logger.info(
+    logger.debug(
         f"Dismissing {dismissed_percentage:.2f}% pupil data due to "
         f"confidence < {threshold:.2f}"
     )
+    max_expected_percentage = 20.0
+    if dismissed_percentage >= max_expected_percentage:
+        logger.warning(
+            "An unexpectedly large amout of pupil data "
+            f"(> {max_expected_percentage:.0f}%) was dismissed due to low confidence. "
+            "Please check the pupil detection."
+        )
     return pupil_list
 
 

pupil_src/shared_modules/methods.py

@@ -22,7 +22,9 @@
 import numpy as np
 
 try:
+    logging.getLogger("numexpr.utils").setLevel(logging.ERROR)
     import numexpr as ne
+
 except Exception:
     ne = None
 

pupil_src/shared_modules/os_utils.py

@@ -30,14 +30,13 @@ def __init__(self):
 
         def __enter__(self):
             self.caffeine_process = sp.Popen(["caffeinate", "-w", str(os.getpid())])
-            logger.info("Disabled idle sleep.")
+            logger.debug("Disabled idle sleep.")
 
         def __exit__(self, etype, value, tb):
             if etype is not None:
                 logger.debug("".join(traceback.format_exception(etype, value, tb)))
             self.caffeine_process.terminate()
             self.caffeine_process = None
-            logger.info("Re-enabled idle sleep.")
             # NOTE: Suppress KeyboardInterrupt
             return etype is KeyboardInterrupt
 

pupil_src/shared_modules/pupil_detector_plugins/__init__.py

@@ -42,10 +42,10 @@ def available_detector_plugins() -> T.List[T.Type[PupilDetectorPlugin]]:
     try:
         from .pye3d_plugin import Pye3DPlugin
     except ImportError:
-        logger.info("Refraction corrected 3D pupil detector not available!")
+        logger.warning("Refraction corrected 3D pupil detector not available!")
         logger.debug(traceback.format_exc())
     else:
-        logger.info("Using refraction corrected 3D pupil detector.")
+        logger.debug("Using refraction corrected 3D pupil detector.")
         all_plugins.append(Pye3DPlugin)
 
     return all_plugins

pupil_src/shared_modules/recorder.py

@@ -288,7 +288,7 @@ def on_notify(self, notification):
             if self.running:
                 self.stop()
             else:
-                logger.info("Recording already stopped!")
+                logger.debug("Recording already stopped!")
 
     def get_rec_time_str(self):
         rec_time = gmtime(time() - self.start_time)
@@ -517,10 +517,6 @@ def stop(self):
                 _, filename = os.path.split(source_path)
                 target_path = os.path.join(self.rec_path, filename)
                 copy2(source_path, target_path)
-        else:
-            logger.info(
-                "No surface_definitions data found. You may want this if you do marker tracking."
-            )
 
         self.meta_info.duration_s = duration_s
         self.meta_info.save_file()