Merge pull request #2190 from pupil-labs/less_logs

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/accuracy_visualizer.py

@@ -140,7 +140,8 @@ def update(
             and self.gazer_class_name != gazer_class_name
         ):
             logger.debug(
-                f'Overwriting gazer_class_name from "{self.gazer_class_name}" to "{gazer_class_name}" and resetting the input.'
+                f'Overwriting gazer_class_name from "{self.gazer_class_name}" to '
+                f'"{gazer_class_name}" and resetting the input.'
             )
             self.clear()
 
@@ -275,7 +276,8 @@ def ignore(_):
                 self,
                 "Angular Accuracy",
                 setter=ignore,
-                getter=lambda: self.accuracy
+                getter=lambda: f"{self.accuracy.result:.3f} deg. Samples used: "
+                f"{self.accuracy.num_used} / {self.accuracy.num_total}"
                 if self.accuracy is not None
                 else "Not available",
             )
@@ -287,7 +289,8 @@ def ignore(_):
                 self,
                 "Angular Precision",
                 setter=ignore,
-                getter=lambda: self.precision
+                getter=lambda: f"{self.precision.result:.3f} deg. Samples used: "
+                f"{self.precision.num_used} / {self.precision.num_total}"
                 if self.precision is not None
                 else "Not available",
             )
@@ -391,29 +394,23 @@ def recalculate(self):
             logger.warning(NOT_ENOUGH_DATA_COLLECTED_ERR_MSG)
             return
 
-        accuracy = results.accuracy.result
-        if np.isnan(accuracy):
+        if np.isnan(results.accuracy.result):
             self.accuracy = None
             logger.warning(
                 "Not enough data available for angular accuracy calculation."
             )
         else:
-            self.accuracy = accuracy
-            logger.info(
-                "Angular accuracy: {}. Used {} of {} samples.".format(*results[0])
-            )
+            self.accuracy = results.accuracy
+            logger.info(f"Angular accuracy: {results.accuracy.result:.3f} degrees")
 
-        precision = results.precision.result
-        if np.isnan(precision):
+        if np.isnan(results.precision.result):
             self.precision = None
             logger.warning(
                 "Not enough data available for angular precision calculation."
             )
         else:
-            self.precision = precision
-            logger.info(
-                "Angular precision: {}. Used {} of {} samples.".format(*results[1])
-            )
+            self.precision = results.precision
+            logger.info(f"Angular precision: {results.precision.result:.3f} degrees")
 
         self.error_lines = results.error_lines
         ref_locations = results.correlation.norm_space[1::2, :]
@@ -489,8 +486,8 @@ def calc_acc_prec_errlines(
             "ij,ij->i", undistorted_3d[:-1, 3:], undistorted_3d[1:, 3:]
         )
 
-        # if the ref distance is to big we must have moved to a new fixation or there is headmovement,
-        # if the gaze dis is to big we can assume human error
+        # if the ref distance is to big we must have moved to a new fixation or there is
+        # headmovement, if the gaze dis is to big we can assume human error
         # both times gaze data is not valid for this mesurement
         selected_indices = np.logical_and(
             succesive_distances_gaze > succession_threshold,

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 amount 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()

pupil_src/shared_modules/video_capture/uvc_backend.py

@@ -87,7 +87,7 @@ def __init__(
                 self.uvc_capture = uvc.Capture(uid)
             except uvc.OpenError:
                 logger.warning(
-                    "No avalilable camera found that matched {}".format(preferred_names)
+                    f"Camera matching {preferred_names} found but not available"
                 )
             except uvc.InitError:
                 logger.error("Camera failed to initialize.")
@@ -264,7 +264,7 @@ def verify_drivers(self):
                     )
                     logger.debug(traceback.format_exc())
 
-            logger.warning("Done updating drivers!")
+            logger.info("Done updating drivers!")
 
     def configure_capture(self, frame_size, frame_rate, uvc_controls):
         # Set camera defaults. Override with previous settings afterwards
@@ -285,10 +285,9 @@ def configure_capture(self, frame_size, frame_rate, uvc_controls):
                 # use hardware timestamps
                 self.ts_offset = None
         else:
-            logger.info(
-                "Hardware timestamps not supported for {}. Using software timestamps.".format(
-                    self.uvc_capture.name
-                )
+            logger.debug(
+                f"Hardware timestamps not supported for {self.uvc_capture.name}. "
+                "Using software timestamps."
             )
             self.ts_offset = -0.1
 
@@ -442,9 +441,7 @@ def _re_init_capture_by_names(self, names, backup_uvc_controls={}):
     def _restart_logic(self):
         if self._restart_in <= 0:
             if self.uvc_capture:
-                logger.warning(
-                    "Capture failed to provide frames. Attempting to reinit."
-                )
+                logger.warning("Camera disconnected. Reconnecting...")
                 self.name_backup = (self.uvc_capture.name,)
                 self.backup_uvc_controls = self._get_uvc_controls()
                 self.uvc_capture = None
@@ -481,7 +478,7 @@ def recent_events(self, events):
             if self.stripe_detector and self.stripe_detector.require_restart(frame):
                 # set the self.frame_rate in order to restart
                 self.frame_rate = self.frame_rate
-                logger.info("Stripes detected")
+                logger.debug("Stripes detected")
 
         except uvc.StreamError:
             self._recent_frame = None
@@ -732,9 +729,8 @@ def set_exposure_mode(exposure_mode):
                     self.preferred_exposure_time = None
 
                 logger.info(
-                    "Exposure mode for camera {0} is now set to {1} mode".format(
-                        self.uvc_capture.name, exposure_mode
-                    )
+                    f"Exposure mode for camera {self.uvc_capture.name} is now set to "
+                    f"{exposure_mode} mode"
                 )
                 self.update_menu()
 
@@ -843,17 +839,13 @@ def set_check_stripes(enable_stripe_checks):
                 self.enable_stripe_checks = enable_stripe_checks
                 if self.enable_stripe_checks:
                     self.stripe_detector = Check_Frame_Stripes()
-                    logger.info(
-                        "Check Stripes for camera {} is now on".format(
-                            self.uvc_capture.name
-                        )
+                    logger.debug(
+                        f"Check Stripes for camera {self.uvc_capture.name} is now on"
                     )
                 else:
                     self.stripe_detector = None
-                    logger.info(
-                        "Check Stripes for camera {} is now off".format(
-                            self.uvc_capture.name
-                        )
+                    logger.debug(
+                        f"Check Stripes for camera {self.uvc_capture.name} is now off"
                     )
 
             ui_elements.append(
@@ -955,6 +947,7 @@ def activate_source(self, source_uid):
                 return
         except ValueError as ve:
             logger.error(str(ve))
+            logger.debug(traceback.format_exc())
             return
 
         settings = {