From 19137f3f4e6413273ab11c1173660d3b541008ff Mon Sep 17 00:00:00 2001 From: Pablo Prietz Date: Mon, 13 Sep 2021 20:57:02 +0200 Subject: [PATCH 01/12] Clean up os_utils logs --- pupil_src/shared_modules/os_utils.py | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/pupil_src/shared_modules/os_utils.py b/pupil_src/shared_modules/os_utils.py index 3bd404f652..fa083d37af 100644 --- a/pupil_src/shared_modules/os_utils.py +++ b/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 From 1e975df2088b8373ea715bd95534c6d84d6939f0 Mon Sep 17 00:00:00 2001 From: Pablo Prietz Date: Tue, 21 Sep 2021 08:44:01 +0200 Subject: [PATCH 02/12] Hide numexpr info logs --- pupil_src/shared_modules/methods.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/pupil_src/shared_modules/methods.py b/pupil_src/shared_modules/methods.py index a503c1f83a..dff161f352 100644 --- a/pupil_src/shared_modules/methods.py +++ b/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 From 0d921e88722eb7bc1c8ffb72c729185dc1fde9b5 Mon Sep 17 00:00:00 2001 From: Pablo Prietz Date: Tue, 21 Sep 2021 09:31:29 +0200 Subject: [PATCH 03/12] Clean up world logs --- pupil_src/launchables/world.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/pupil_src/launchables/world.py b/pupil_src/launchables/world.py index a82539b2c5..3ee7c9c7d7 100644 --- a/pupil_src/launchables/world.py +++ b/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) From 037e4eadf743d7165fb9f5dc363bc269517f0ac5 Mon Sep 17 00:00:00 2001 From: Pablo Prietz Date: Tue, 21 Sep 2021 09:36:25 +0200 Subject: [PATCH 04/12] Clean up camera_models logs --- pupil_src/shared_modules/camera_models.py | 9 ++++----- 1 file changed, 4 insertions(+), 5 deletions(-) diff --git a/pupil_src/shared_modules/camera_models.py b/pupil_src/shared_modules/camera_models.py index 01b599ea73..132b12f422 100644 --- a/pupil_src/shared_modules/camera_models.py +++ b/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: From b983e0b01b2c863f27e2e387b46490b7f42f6ce2 Mon Sep 17 00:00:00 2001 From: Pablo Prietz Date: Tue, 21 Sep 2021 10:12:39 +0200 Subject: [PATCH 05/12] Clean up eye process logs --- pupil_src/launchables/eye.py | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/pupil_src/launchables/eye.py b/pupil_src/launchables/eye.py index 04dcbe4b73..71ce654117 100644 --- a/pupil_src/launchables/eye.py +++ b/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( From c7ead470e021d800b93b109270749b9d20e73afc Mon Sep 17 00:00:00 2001 From: Pablo Prietz Date: Tue, 21 Sep 2021 10:17:15 +0200 Subject: [PATCH 06/12] Clean up pupil detector plugin logs --- pupil_src/shared_modules/pupil_detector_plugins/__init__.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/pupil_src/shared_modules/pupil_detector_plugins/__init__.py b/pupil_src/shared_modules/pupil_detector_plugins/__init__.py index 0357110dd1..6e256030a8 100644 --- a/pupil_src/shared_modules/pupil_detector_plugins/__init__.py +++ b/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 From ff2eccedd53add89d713ec505b21ce374855ec54 Mon Sep 17 00:00:00 2001 From: Pablo Prietz Date: Tue, 21 Sep 2021 10:31:23 +0200 Subject: [PATCH 07/12] Clean up recorder logs --- pupil_src/shared_modules/recorder.py | 6 +----- 1 file changed, 1 insertion(+), 5 deletions(-) diff --git a/pupil_src/shared_modules/recorder.py b/pupil_src/shared_modules/recorder.py index 5de9b105a9..bd6c7b09c3 100644 --- a/pupil_src/shared_modules/recorder.py +++ b/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() From b39b5cc06de8d4a7dac0263182b2a61cce92b935 Mon Sep 17 00:00:00 2001 From: Pablo Prietz Date: Tue, 21 Sep 2021 10:39:30 +0200 Subject: [PATCH 08/12] Clean up calibration choreography logs --- .../shared_modules/calibration_choreography/base_plugin.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pupil_src/shared_modules/calibration_choreography/base_plugin.py b/pupil_src/shared_modules/calibration_choreography/base_plugin.py index c4ff870972..6bd499fe2b 100644 --- a/pupil_src/shared_modules/calibration_choreography/base_plugin.py +++ b/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() From 7ee714cc6268ea90fd4ad389a7e72044b15e76f3 Mon Sep 17 00:00:00 2001 From: Pablo Prietz Date: Tue, 21 Sep 2021 17:05:12 +0200 Subject: [PATCH 09/12] Dismissed data log: Only warn users if threshold (20%) is exceeded --- pupil_src/shared_modules/gaze_mapping/utils.py | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/pupil_src/shared_modules/gaze_mapping/utils.py b/pupil_src/shared_modules/gaze_mapping/utils.py index c6f181f543..5d8be9c289 100644 --- a/pupil_src/shared_modules/gaze_mapping/utils.py +++ b/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 From 61208b8f38edb46fae5da611ad5b56db2e19f2d0 Mon Sep 17 00:00:00 2001 From: Pablo Prietz Date: Tue, 21 Sep 2021 18:47:19 +0200 Subject: [PATCH 10/12] Clean up uvc_backend logs --- .../video_capture/uvc_backend.py | 35 ++++++++----------- 1 file changed, 14 insertions(+), 21 deletions(-) diff --git a/pupil_src/shared_modules/video_capture/uvc_backend.py b/pupil_src/shared_modules/video_capture/uvc_backend.py index ea509d3bb2..ba7336f2fe 100644 --- a/pupil_src/shared_modules/video_capture/uvc_backend.py +++ b/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 = { From f993608a2f24c6479d58fa0509b4242cc38ea186 Mon Sep 17 00:00:00 2001 From: Pablo Prietz Date: Tue, 21 Sep 2021 18:49:09 +0200 Subject: [PATCH 11/12] Clean up accuracy visualizer logs --- .../shared_modules/accuracy_visualizer.py | 31 +++++++++---------- 1 file changed, 14 insertions(+), 17 deletions(-) diff --git a/pupil_src/shared_modules/accuracy_visualizer.py b/pupil_src/shared_modules/accuracy_visualizer.py index 6c1d8d96ed..1aa2068710 100644 --- a/pupil_src/shared_modules/accuracy_visualizer.py +++ b/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, From d62e08579e842172283796106fc723e48a6702d9 Mon Sep 17 00:00:00 2001 From: Pablo Prietz Date: Fri, 24 Sep 2021 08:59:44 +0200 Subject: [PATCH 12/12] Fix typo Co-authored-by: Neil M. Thomas --- pupil_src/shared_modules/gaze_mapping/utils.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pupil_src/shared_modules/gaze_mapping/utils.py b/pupil_src/shared_modules/gaze_mapping/utils.py index 5d8be9c289..bd16ca649c 100644 --- a/pupil_src/shared_modules/gaze_mapping/utils.py +++ b/pupil_src/shared_modules/gaze_mapping/utils.py @@ -31,7 +31,7 @@ def _filter_pupil_list_by_confidence(pupil_list, threshold): max_expected_percentage = 20.0 if dismissed_percentage >= max_expected_percentage: logger.warning( - "An unexpectedly large amout of pupil data " + "An unexpectedly large amount of pupil data " f"(> {max_expected_percentage:.0f}%) was dismissed due to low confidence. " "Please check the pupil detection." )