app-swt-detection (and also bake-swt-visaid) produces hundreds of lines of text output when encountering decode problems

[owencking]

Bug Description

When I run app-swt-detection on cpb-aacip-0b2dcf6b574.mp4, it finishes successfully, but there are many hundreds (thousands?) of lines of error/diagnostic output.

I think this is due to encountering a decode error. I have encountered this problem only about 10 times (out of tens of thousands of runs). I can supply additional media files if necessary.

Reproduction steps

Run app-swt-detection on [cpb-aacip-0b2dcf6b574.mp4]. Look at output.

(It may be necessary to set the tp sampling interval to something low, like 250ms.)

Expected behavior

Ideally, it just logs a warning once and moves on.

Log output

[NULL @ 0x5624b32d08c0] Invalid NAL unit size (0 > 1286).
[NULL @ 0x5624b32d08c0] missing picture in access unit with size 1290
[h264 @ 0x5624b2fdcc00] Invalid NAL unit size (0 > 1286).
[h264 @ 0x5624b2fdcc00] Error splitting the input into NAL units.
[NULL @ 0x5624b32d08c0] Invalid NAL unit size (0 > 481).
[NULL @ 0x5624b32d08c0] missing picture in access unit with size 485
[h264 @ 0x5624b3c3e240] Invalid NAL unit size (0 > 481).
[h264 @ 0x5624b3c3e240] Error splitting the input into NAL units.
[NULL @ 0x5624b32d08c0] Invalid NAL unit size (0 > 523).
[NULL @ 0x5624b32d08c0] missing picture in access unit with size 527
[h264 @ 0x5624b35ba440] Invalid NAL unit size (0 > 523).
[h264 @ 0x5624b35ba440] Error splitting the input into NAL units.
. . .
[NULL @ 0x5624b32d08c0] Invalid NAL unit size (0 > 524).
[NULL @ 0x5624b32d08c0] missing picture in access unit with size 528
[h264 @ 0x5624b2f62540] Invalid NAL unit size (0 > 631).
[h264 @ 0x5624b2f62540] Error splitting the input into NAL units.
[h264 @ 0x5624b2f300c0] Invalid NAL unit size (0 > 524).
[h264 @ 0x5624b2f300c0] Error splitting the input into NAL units.
[NULL @ 0x5624b32d08c0] Invalid NAL unit size (0 > 5533).
[NULL @ 0x5624b32d08c0] missing picture in access unit with size 5537
[h264 @ 0x5624b34c3580] Invalid NAL unit size (0 > 5533).
[h264 @ 0x5624b34c3580] Error splitting the input into NAL units.

Screenshots

No response

Additional context

For the same videos that cause this error, I have had problems with visaid_builder also. At first, they caused crashes, until I started handling decode errors. I also started supressing extra output.

However, I think there's an additional factor. I think the amount of output depends on the version of PyAV being used. I think that maybe using PyAV 13 instead of 12 might quell most of this output.

[keighrim]

This is probably a duplicate of clamsproject/app-swt-detection#67, which I just closed a couple days ago due to me being unable to reproduce the messages using the same file reported in that old issue. For video seeking operations, the app uses video_document_helper implementation in the mmif-python SDK, so I'm moving the issue to the SDK repo.

[keighrim]

For a stopgap, since the video_document_helper uses opencv to handle video files, which in turn wraps ffmpeg for low-level operations, setting OPENCV_FFMPEG_LOGLEVEL envvar (https://docs.opencv.org/4.x/d6/dea/tutorial_env_reference.html) to -8 (https://ffmpeg.org/ffmpeg.html#Generic-options, search for -loglevel) should suppress any of those output. In container setting, for example,

docker run -it --env OPENCV_FFMPEG_LOGLEVEL=-8 --rm ... docker pull ghcr.io/clamsproject/app-swt-detection:v7.5 cli.py ... 

should do that.

For a long-term solution, I'm trying to redirect the ffmpeg error/warning messages to a python string so that we can record that as a part of output MMIF.

[keighrim]

An example output MMIF from experimental implementation:
https://gist.githubusercontent.com/keighrim/b1a73c30a9caa976afee3fcba6c9c702/raw/85f10a86b713e5e5750a9a2f48ec86f3b6ee2156/cpb-aacip-0b2dcf6b574.swt.ffmpeg-warnings.mmif
(look view id v_2)

Not sure we want to keep all the messages from the ffmpeg, that can potentially be thousands of lines (or more), but at the same time, I don't want to deal with trimming or re-organizing ffmpeg errors into a more concise format (I just don't believe that should be our responsibility or discretion).

One idea we can implement on the clams-python SDK side is to provide a global parameter (just like pretty) to write the "warning views" (like v_2), or discard them at all. This parameter is configured on a app-by-app basis, so users can suppress ffmpeg error messages when they know they will be dealing with video files. Problem is that if other parts of the app (pytorch, for example) produce some other warnings, they will also be discarded.

[keighrim]

With current implementation in #308, error messages from ffmpeg/opencv during video frame extraction are captured but not thrown as python warnings (so that they can be written to a "warning" view), unless the client using frame extraction method tell so.

[keighrim]

For the reference, here's another MMIF output from the HEAD of #308.
https://gist.githubusercontent.com/keighrim/b1a73c30a9caa976afee3fcba6c9c702/raw/4406a778b890762ff2390f9080ebcef9463c9176/cpb-aacip-0b2dcf6b574.swt.sdk-warnings.mmif

As shown in v_2 view, there is no redirected ffmpeg errors written, but there are more human-readable warning messages from SDK, one line for each sampled frame that's not properly extracted, roughly 4 lines every second since I used 250ms sampling rate.

"{message : UserWarning('Frame #90098 (3006.272939606273s) could not be read from the video d1 @ file:///home/krim/cpb-aacip-0b2dcf6b574.mp4 .'), category : 'UserWarning', filename : '/home/krim/Dropbox/Projects/clams/clamsproject/mmif-python/mmif/utils/video_document_helper.py', lineno : 103, line : None}",
"{message : UserWarning('Frame #90105 (3006.5065065065064s) could not be read from the video d1 @ file:///home/krim/cpb-aacip-0b2dcf6b574.mp4 .'), category : 'UserWarning', filename : '/home/krim/Dropbox/Projects/clams/clamsproject/mmif-python/mmif/utils/video_document_helper.py', lineno : 103, line : None}",
"{message : UserWarning('Frame #90113 (3006.7734401067737s) could not be read from the video d1 @ file:///home/krim/cpb-aacip-0b2dcf6b574.mp4 .'), category : 'UserWarning', filename : '/home/krim/Dropbox/Projects/clams/clamsproject/mmif-python/mmif/utils/video_document_helper.py', lineno : 103, line : None}",
"{message : UserWarning('Frame #90120 (3007.007007007007s) could not be read from the video d1 @ file:///home/krim/cpb-aacip-0b2dcf6b574.mp4 .'), category : 'UserWarning', filename : '/home/krim/Dropbox/Projects/clams/clamsproject/mmif-python/mmif/utils/video_document_helper.py', lineno : 103, line : None}",
"{message : UserWarning('Frame #90128 (3007.273940607274s) could not be read from the video d1 @ file:///home/krim/cpb-aacip-0b2dcf6b574.mp4 .'), category : 'UserWarning', filename : '/home/krim/Dropbox/Projects/clams/clamsproject/mmif-python/mmif/utils/video_document_helper.py', lineno : 103, line : None}",
"{message : UserWarning('Frame #90135 (3007.5075075075074s) could not be read from the video d1 @ file:///home/krim/cpb-aacip-0b2dcf6b574.mp4 .'), category : 'UserWarning', filename : '/home/krim/Dropbox/Projects/clams/clamsproject/mmif-python/mmif/utils/video_document_helper.py', lineno : 103, line : None}",
"{message : UserWarning('Frame #90143 (3007.7744411077747s) could not be read from the video d1 @ file:///home/krim/cpb-aacip-0b2dcf6b574.mp4 .'), category : 'UserWarning', filename : '/home/krim/Dropbox/Projects/clams/clamsproject/mmif-python/mmif/utils/video_document_helper.py', lineno : 103, line : None}",
"{message : UserWarning('Frame #90150 (3008.0080080080083s) could not be read from the video d1 @ file:///home/krim/cpb-aacip-0b2dcf6b574.mp4 .'), category : 'UserWarning', filename : '/home/krim/Dropbox/Projects/clams/clamsproject/mmif-python/mmif/utils/video_document_helper.py', lineno : 103, line : None}",
"{message : UserWarning('Frame #90158 (3008.274941608275s) could not be read from the video d1 @ file:///home/krim/cpb-aacip-0b2dcf6b574.mp4 .'), category : 'UserWarning', filename : '/home/krim/Dropbox/Projects/clams/clamsproject/mmif-python/mmif/utils/video_document_helper.py', lineno : 103, line : None}",
"{message : UserWarning('Frame #90165 (3008.508508508509s) could not be read from the video d1 @ file:///home/krim/cpb-aacip-0b2dcf6b574.mp4 .'), category : 'UserWarning', filename : '/home/krim/Dropbox/Projects/clams/clamsproject/mmif-python/mmif/utils/video_document_helper.py', lineno : 103, line : None}",
"{message : UserWarning('Frame #90173 (3008.7754421087757s) could not be read from the video d1 @ file:///home/krim/cpb-aacip-0b2dcf6b574.mp4 .'), category : 'UserWarning', filename : '/home/krim/Dropbox/Projects/clams/clamsproject/mmif-python/mmif/utils/video_document_helper.py', lineno : 103, line : None}",
"{message : UserWarning('Frame #90180 (3009.0090090090093s) could not be read from the video d1 @ file:///home/krim/cpb-aacip-0b2dcf6b574.mp4 .'), category : 'UserWarning', filename : '/home/krim/Dropbox/Projects/clams/clamsproject/mmif-python/mmif/utils/video_document_helper.py', lineno : 103, line : None}",

Also note that current release version of the SDK has a bug in that when it encounters an error while trying to pull out an image from a list of sampled frame numbers, it essentially stops processing the rest of the video. a12a17e in #308 fixes the problem.

[keighrim]

Notes from the meeting yesterday;

1. more videos with decoding problems from the test dataset used for the initial test drive of bake-swt-visaid
   • 144 cpb-aacip-0b2dcf6b574
   • 423 cpb-aacip-1fa4c7f4c81
   • 448 cpb-aacip-217a3aa66dc
   • 1398 cpb-aacip-6489e38262f
   • 1504 cpb-aacip-6b9625387b9
   • 1643 cpb-aacip-74d95ac59c3
   • 1715 cpb-aacip-7aa7722a8e3
   • 2202 cpb-aacip-9c839a9612c
   • 2224 cpb-aacip-9e344ff3734
   • 2609 cpb-aacip-b9dba1946b0
   • 2746 cpb-aacip-c3d7e66cbd9
   • 3389 cpb-aacip-f17e38ce311
2. as "corrupted" videos were found rare in the dataset, and also fixing this at the SDK level and going through the chain of releases down to the app level might not something we want to deal with at the moment (before conferences), we decided to postpone this fix (including for early termination bug) until later the month
3. In addition to (or instead of) showing the warning msgs for un-decodable frame, extract_frames_as_images can also include "null"-like objects for those frames in the returning list, so that SDK clients (such as app-swt) can handle errors without implementing their own warning handling.

[owencking]

Several additional videos exhibiting the relevant kind of corruption are in this Google Drive folder.