Merge pull request #2101 from pupil-labs/support-audio-decoding-issues

Support recordings with decoding issues

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

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

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(

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

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