diff --git a/pupil_src/shared_modules/audio_playback.py b/pupil_src/shared_modules/audio_playback.py index 22cd749b5f..a8260c7bf5 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 @@ -25,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 @@ -35,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) @@ -249,9 +254,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 @@ -273,10 +281,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() diff --git a/pupil_src/shared_modules/audio_utils.py b/pupil_src/shared_modules/audio_utils.py index 86df37cb22..8f338736f4 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)) diff --git a/pupil_src/shared_modules/av_writer.py b/pupil_src/shared_modules/av_writer.py index 0c80fa3b9b..0621909fe6 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 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( diff --git a/pupil_src/shared_modules/methods.py b/pupil_src/shared_modules/methods.py index b4ab4855ac..5cd10bf1fc 100644 --- a/pupil_src/shared_modules/methods.py +++ b/pupil_src/shared_modules/methods.py @@ -9,16 +9,22 @@ ---------------------------------------------------------------------------~(*) """ -import os, sys, platform, getpass +import getpass +import logging +import os +import platform +import sys +import traceback +import typing as T 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__) @@ -774,3 +780,32 @@ 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 + + +def make_change_loglevel_fn(level): + def _change_level(record): + record.levelno = level + record.levelname = logging.getLevelName(record.levelno) + return record + + return _change_level diff --git a/pupil_src/shared_modules/video_capture/file_backend.py b/pupil_src/shared_modules/video_capture/file_backend.py index 7dc18dca82..ba17213934 100644 --- a/pupil_src/shared_modules/video_capture/file_backend.py +++ b/pupil_src/shared_modules/video_capture/file_backend.py @@ -23,6 +23,7 @@ from pyglui import ui from camera_models import Camera_Model +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 @@ -33,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" @@ -185,10 +190,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 @@ -389,14 +395,13 @@ 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 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!") @@ -412,6 +417,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