From 10d6d0782f0d1a5cc87a6d26fd3947c89de0bf4b Mon Sep 17 00:00:00 2001 From: Pablo Prietz Date: Tue, 16 Feb 2021 15:18:59 +0100 Subject: [PATCH 01/13] Ignore audio decoding errors --- pupil_src/shared_modules/audio_playback.py | 10 +++++++--- pupil_src/shared_modules/audio_utils.py | 10 +++++++--- 2 files changed, 14 insertions(+), 6 deletions(-) diff --git a/pupil_src/shared_modules/audio_playback.py b/pupil_src/shared_modules/audio_playback.py index 892969a95a..3787d6114e 100644 --- a/pupil_src/shared_modules/audio_playback.py +++ b/pupil_src/shared_modules/audio_playback.py @@ -15,6 +15,7 @@ from bisect import bisect_left as bisect from threading import Timer from time import monotonic +import traceback import av import av.filter @@ -249,9 +250,12 @@ def get_audio_sync(self): def get_audio_frame_iterator(self): for packet in self.audio.container.demux(self.audio.stream): - for frame in packet.decode(): - if frame: - yield frame + try: + for frame in packet.decode(): + if frame: + yield frame + except av.AVError: + logger.debug(traceback.format_exc()) def audio_idx_to_pts(self, idx): return idx * self.audio_pts_rate diff --git a/pupil_src/shared_modules/audio_utils.py b/pupil_src/shared_modules/audio_utils.py index 6b613a125e..9a055844f8 100644 --- a/pupil_src/shared_modules/audio_utils.py +++ b/pupil_src/shared_modules/audio_utils.py @@ -10,6 +10,7 @@ """ import collections import logging +import traceback import av import numpy as np @@ -114,9 +115,12 @@ def _setup_next_audio_part(self): def _next_audio_frame(self): for packet in self.audio.container.demux(self.audio.stream): - for frame in packet.decode(): - if frame: - yield frame + try: + for frame in packet.decode(): + if frame: + yield frame + except av.AVError: + logger.debug(traceback.format_exc()) def sec_to_frames(self, sec): return int(np.ceil(sec * self.audio.stream.rate / self.audio.stream.frame_size)) From d820db9e5042fcab56bbc241594bb893fc2e6c1a Mon Sep 17 00:00:00 2001 From: Pablo Prietz Date: Tue, 23 Feb 2021 11:36:32 +0100 Subject: [PATCH 02/13] Combine if statements --- pupil_src/shared_modules/audio_playback.py | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) diff --git a/pupil_src/shared_modules/audio_playback.py b/pupil_src/shared_modules/audio_playback.py index 3787d6114e..57b15a278d 100644 --- a/pupil_src/shared_modules/audio_playback.py +++ b/pupil_src/shared_modules/audio_playback.py @@ -277,10 +277,13 @@ def seek_to_frame(self, frame_idx): self.seek_to_audio_frame(audio_idx) def on_notify(self, notification): - if notification["subject"] == "seek_control.was_seeking": - if self.pa_stream is not None and not self.pa_stream.is_stopped(): - self.pa_stream.stop_stream() - self.play = False + if ( + notification["subject"] == "seek_control.was_seeking" + and self.pa_stream is not None + and not self.pa_stream.is_stopped() + ): + self.pa_stream.stop_stream() + self.play = False def recent_events(self, events): self.update_audio_viz() From c750a1a44646618f48aca22cabd57ba9495d703c Mon Sep 17 00:00:00 2001 From: Pablo Prietz Date: Tue, 23 Feb 2021 18:05:45 +0100 Subject: [PATCH 03/13] Methods: Sort imports --- pupil_src/shared_modules/methods.py | 10 +++++++--- 1 file changed, 7 insertions(+), 3 deletions(-) diff --git a/pupil_src/shared_modules/methods.py b/pupil_src/shared_modules/methods.py index b4ab4855ac..517767e7fc 100644 --- a/pupil_src/shared_modules/methods.py +++ b/pupil_src/shared_modules/methods.py @@ -9,16 +9,20 @@ ---------------------------------------------------------------------------~(*) """ -import os, sys, platform, getpass +import getpass +import logging +import os +import platform +import sys from time import time + +import cv2 import numpy as np try: import numexpr as ne except Exception: ne = None -import cv2 -import logging logger = logging.getLogger(__name__) From d492ec735927ba618ae5ddbe63f655d018c6d520 Mon Sep 17 00:00:00 2001 From: Pablo Prietz Date: Tue, 23 Feb 2021 18:07:52 +0100 Subject: [PATCH 04/13] Methods: Add iter_catch Helper function that wraps an iterator, yields None of it catches specified exceptions, and logs them (opt-out) --- pupil_src/shared_modules/methods.py | 22 ++++++++++++++++++++++ 1 file changed, 22 insertions(+) diff --git a/pupil_src/shared_modules/methods.py b/pupil_src/shared_modules/methods.py index 517767e7fc..33d7a47dbc 100644 --- a/pupil_src/shared_modules/methods.py +++ b/pupil_src/shared_modules/methods.py @@ -14,6 +14,8 @@ import os import platform import sys +import traceback +import typing as T from time import time import cv2 @@ -778,3 +780,23 @@ def timed(*args, **kw): return result return timed + + +X = T.TypeVar("X") + + +def iter_catch( + iterator: T.Iterator[X], + errors_to_catch: T.Union[Exception, T.Tuple[Exception]], + log_on_catch: bool = True, +) -> T.Iterator[T.Optional[X]]: + iterator = iter(iterator) + while True: + try: + yield next(iterator) + except errors_to_catch: + if log_on_catch: + logger.debug(traceback.format_exc()) + yield None + except StopIteration: + return From 29f328da821b502c22f457c937aed9fe03e66dee Mon Sep 17 00:00:00 2001 From: Pablo Prietz Date: Tue, 23 Feb 2021 18:09:26 +0100 Subject: [PATCH 05/13] AV Writer: Ignore audio decoding issues --- pupil_src/shared_modules/av_writer.py | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/pupil_src/shared_modules/av_writer.py b/pupil_src/shared_modules/av_writer.py index 0c80fa3b9b..f61f64307b 100644 --- a/pupil_src/shared_modules/av_writer.py +++ b/pupil_src/shared_modules/av_writer.py @@ -24,6 +24,7 @@ import audio_utils from video_capture.utils import Video, InvalidContainerError +from player_methods import iter_catch logger = logging.getLogger(__name__) @@ -501,7 +502,11 @@ def _iterate_audio_frames_and_audio_gaps(audio_parts): for part_idx, audio_part in enumerate(audio_parts): frames = audio_part.container.decode(audio=0) + frames = iter_catch(frames, av.AVError) for frame, timestamp in zip(frames, audio_part.timestamps): + if frame is None: + continue # ignore audio decoding errors + frame.pts = None audio_frame = _AudioPacketIterator._AudioFrame( From cb644451ed5e8e9d094e3013fa56edc6fa4c7a1a Mon Sep 17 00:00:00 2001 From: Pablo Prietz Date: Tue, 23 Feb 2021 18:18:31 +0100 Subject: [PATCH 06/13] File backend: ignore video decoding issues --- pupil_src/shared_modules/video_capture/file_backend.py | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/pupil_src/shared_modules/video_capture/file_backend.py b/pupil_src/shared_modules/video_capture/file_backend.py index 7dc18dca82..073a442716 100644 --- a/pupil_src/shared_modules/video_capture/file_backend.py +++ b/pupil_src/shared_modules/video_capture/file_backend.py @@ -24,6 +24,7 @@ from camera_models import Camera_Model from pupil_recording import PupilRecording +from player_methods import iter_catch from .base_backend import Base_Manager, Base_Source, EndofVideoError, Playback_Source from .utils import VideoSet, InvalidContainerError @@ -185,10 +186,11 @@ def seek(self, pts_position): self.video_stream.seek(pts_position) def get_frame_iterator(self): - for packet in self.container.demux(self.video_stream): - for frame in packet.decode(): - if frame: - yield frame + frames = self.container.decode(self.video_stream) + frames = iter_catch(frames, av.AVError) + for frame in frames: + if frame: + yield frame # NOTE:Base_Source is included as base class for uniqueness:by_base_class to work From 397a3f0083a48cd3b32114b8c391f3076c49c6d0 Mon Sep 17 00:00:00 2001 From: Pablo Prietz Date: Tue, 23 Feb 2021 18:19:21 +0100 Subject: [PATCH 07/13] File backend: Handle unbound variable edge case If frame_iterator is empty, return fake frame instead --- pupil_src/shared_modules/video_capture/file_backend.py | 3 +++ 1 file changed, 3 insertions(+) diff --git a/pupil_src/shared_modules/video_capture/file_backend.py b/pupil_src/shared_modules/video_capture/file_backend.py index 073a442716..e1fcf265cf 100644 --- a/pupil_src/shared_modules/video_capture/file_backend.py +++ b/pupil_src/shared_modules/video_capture/file_backend.py @@ -391,6 +391,7 @@ def get_frame(self): self._setup_video(target_entry.container_idx) # advance frame iterator until we hit the target frame + av_frame = None for av_frame in self.frame_iterator: if not av_frame: raise EndofVideoError @@ -414,6 +415,8 @@ def get_frame(self): raise EndofVideoError self.target_frame_idx = pts_indices[0] break + if av_frame is None: + return self._get_fake_frame_and_advance(target_entry) # update indices, we know that we advanced until target_frame_index! self.current_frame_idx = self.target_frame_idx From 8a00b6e59321bb0bdb2c1cb2a37c0faf5f82a2ce Mon Sep 17 00:00:00 2001 From: Pablo Prietz Date: Tue, 23 Feb 2021 18:21:16 +0100 Subject: [PATCH 08/13] File backend: Fix import --- pupil_src/shared_modules/video_capture/file_backend.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pupil_src/shared_modules/video_capture/file_backend.py b/pupil_src/shared_modules/video_capture/file_backend.py index e1fcf265cf..cd0c92bc9f 100644 --- a/pupil_src/shared_modules/video_capture/file_backend.py +++ b/pupil_src/shared_modules/video_capture/file_backend.py @@ -23,8 +23,8 @@ from pyglui import ui from camera_models import Camera_Model +from methods import iter_catch from pupil_recording import PupilRecording -from player_methods import iter_catch from .base_backend import Base_Manager, Base_Source, EndofVideoError, Playback_Source from .utils import VideoSet, InvalidContainerError From 45f4352a34137c67cf44efb80ce090d43de52e18 Mon Sep 17 00:00:00 2001 From: Pablo Prietz Date: Tue, 23 Feb 2021 18:21:38 +0100 Subject: [PATCH 09/13] File backend: Simplify if statement --- pupil_src/shared_modules/video_capture/file_backend.py | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/pupil_src/shared_modules/video_capture/file_backend.py b/pupil_src/shared_modules/video_capture/file_backend.py index cd0c92bc9f..7fe4939cf8 100644 --- a/pupil_src/shared_modules/video_capture/file_backend.py +++ b/pupil_src/shared_modules/video_capture/file_backend.py @@ -397,9 +397,7 @@ def get_frame(self): raise EndofVideoError if av_frame.pts == target_entry.pts: break - elif av_frame.pts < target_entry.pts: - pass - else: + elif av_frame.pts > target_entry.pts: # This should never happen, but just in case we should make sure # that our current_frame_idx is actually correct afterwards! logger.warn("Advancing frame iterator went past the target frame!") From 2c0c4119cb75a28dbf6a3adf52fde4385a23b91d Mon Sep 17 00:00:00 2001 From: Pablo Prietz Date: Tue, 23 Feb 2021 18:22:42 +0100 Subject: [PATCH 10/13] Methods: Add make_change_loglevel_fn() Changes log records' log level to a specified logging level. Can be used instead of logging.Filter() objects --- pupil_src/shared_modules/methods.py | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/pupil_src/shared_modules/methods.py b/pupil_src/shared_modules/methods.py index 33d7a47dbc..5cd10bf1fc 100644 --- a/pupil_src/shared_modules/methods.py +++ b/pupil_src/shared_modules/methods.py @@ -800,3 +800,12 @@ def iter_catch( yield None except StopIteration: return + + +def make_change_loglevel_fn(level): + def _change_level(record): + record.levelno = level + record.levelname = logging.getLevelName(record.levelno) + return record + + return _change_level From f550a10454ecf46c1d32d5119702055476c72a6a Mon Sep 17 00:00:00 2001 From: Pablo Prietz Date: Tue, 23 Feb 2021 18:28:19 +0100 Subject: [PATCH 11/13] File backend: Log h264 decoding issues with debug level --- pupil_src/shared_modules/video_capture/file_backend.py | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/pupil_src/shared_modules/video_capture/file_backend.py b/pupil_src/shared_modules/video_capture/file_backend.py index 7fe4939cf8..ba17213934 100644 --- a/pupil_src/shared_modules/video_capture/file_backend.py +++ b/pupil_src/shared_modules/video_capture/file_backend.py @@ -23,7 +23,7 @@ from pyglui import ui from camera_models import Camera_Model -from methods import iter_catch +from methods import make_change_loglevel_fn, iter_catch from pupil_recording import PupilRecording from .base_backend import Base_Manager, Base_Source, EndofVideoError, Playback_Source @@ -34,6 +34,10 @@ logging.getLogger("libav").setLevel(logging.ERROR) logging.getLogger("av.buffered_decoder").setLevel(logging.WARNING) +# convert 2h64 decoding errors to debug messages +av_logger = logging.getLogger("libav.h264") +av_logger.addFilter(make_change_loglevel_fn(logging.DEBUG)) + assert av.__version__ >= "0.4.5", "pyav is out-of-date, please update" From 49e453ac46f9b839bf320f9eb6d722cbfbb3fee5 Mon Sep 17 00:00:00 2001 From: Pablo Prietz Date: Tue, 23 Feb 2021 18:28:38 +0100 Subject: [PATCH 12/13] Audio playback: Log aac decoding issues with debug level --- pupil_src/shared_modules/audio_playback.py | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/pupil_src/shared_modules/audio_playback.py b/pupil_src/shared_modules/audio_playback.py index 162d459cdf..a8260c7bf5 100644 --- a/pupil_src/shared_modules/audio_playback.py +++ b/pupil_src/shared_modules/audio_playback.py @@ -26,6 +26,7 @@ import gl_utils from audio_utils import Audio_Viz_Transform, NoAudioLoadedError, load_audio +from methods import make_change_loglevel_fn from plugin import System_Plugin_Base from version_utils import parse_version @@ -36,6 +37,9 @@ logger = logging.getLogger(__name__) logger.setLevel(logger.DEBUG) +av_logger = logging.getLogger("libav.aac") +av_logger.addFilter(make_change_loglevel_fn(logging.DEBUG)) + # av.logging.set_level(av.logging.DEBUG) # logging.getLogger('libav').setLevel(logging.DEBUG) From 08f272aecd348d5b28596ee2bd8ed1ff36dd512e Mon Sep 17 00:00:00 2001 From: Pablo Prietz Date: Thu, 25 Feb 2021 10:35:18 +0100 Subject: [PATCH 13/13] Fix iter_catch import --- pupil_src/shared_modules/av_writer.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pupil_src/shared_modules/av_writer.py b/pupil_src/shared_modules/av_writer.py index f61f64307b..0621909fe6 100644 --- a/pupil_src/shared_modules/av_writer.py +++ b/pupil_src/shared_modules/av_writer.py @@ -24,7 +24,7 @@ import audio_utils from video_capture.utils import Video, InvalidContainerError -from player_methods import iter_catch +from methods import iter_catch logger = logging.getLogger(__name__)