Hi Channels Team,
My Apple TV client dropped the video stream for several seconds this evening and I wondered if you could have a look at my submitted logs please? Wife has complained that this occasionally happens so thought I'd best have it looked into.
My HD Home Run logs and Channels DVR server logs showed no errors, and all devices are connected via ethernet.
I had a look at the logs myself via (http://<apple_tv_ip>:57000/log), and at 19:49 saw messages such as Audio device underrun detected and [ffmpeg/audio] error: aac_latm: Number of bands (62) exceeds limit (40).
Could it be just a network glitch or something else?
Log extract below as well:
2022-04-24 19:49:03.335 [u=454.8MB f=1643.2MB] mpvstats: AV: 3066.339 A-V: 0.000008 Dropped: 0 Cache: 0.80s video + 0.19s audio
2022-04-24 19:49:08.334 [u=454.8MB f=1643.2MB] streamstats: strength=100% quality=99% symbol=100% rate=4.9Mb/sec
2022-04-24 19:49:08.334 [u=454.8MB f=1643.2MB] mpvstats: AV: 3071.339 A-V: 0.000033 Dropped: 0 Cache: 0.92s video + 0.23s audio
2022-04-24 19:49:13.333 [u=454.5MB f=1643.5MB] streamstats: strength=100% quality=97% symbol=100% rate=8.5Mb/sec
2022-04-24 19:49:13.333 [u=454.5MB f=1643.5MB] mpvstats: AV: 3076.339 A-V: 0.000007 Dropped: 0 Cache: 0.64s video + 0.17s audio
2022-04-24 19:49:17.870 [u=454.0MB f=1644.0MB] [3082.88s] IS BUFFERING = YES
2022-04-24 19:49:17.875 [u=454.0MB f=1644.0MB] streamstats: strength=100% quality=97% symbol=100% rate=6.3Mb/sec
2022-04-24 19:49:17.875 [u=454.0MB f=1644.0MB] Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateBuffering
2022-04-24 19:49:17.875 [u=454.0MB f=1644.0MB] mpvstats: AV: 3080.899 A-V: 0.000010 Dropped: 0 Cache: 0.48s video + 0.00s audio
2022-04-24 19:49:17.875 [u=454.0MB f=1644.0MB] [3082.88s] [cplayer] warn: Audio device underrun detected.
2022-04-24 19:49:17.875 [u=454.0MB f=1644.0MB] [3082.88s] [cplayer] v: Enter buffering (buffer went from 100% -> 0%) [0.000000s].
2022-04-24 19:49:17.876 [u=454.0MB f=1644.0MB] mpvstats: demuxer-cache-state={ "bof-cached" = 0; "cache-duration" = 0; "cache-end" = "3080.853333000006"; "debug-byte-level-seeks" = 1; "debug-low-level-seeks" = 0; "debug-ts-last" = "75915.09937777778"; eof = 0; "eof-cached" = 0; "fw-bytes" = 321216; idle = 0; "raw-input-rate" = 846605; "reader-pts" = "3080.853333000006"; "seekable-ranges" = ( { end = "3080.831999666669"; start = "2855.738510777781"; } ); "total-bytes" = 159271888; "ts-per-stream" = ( { duration = "0.4799999999959255"; end = "75915.09937777778"; reader = "75914.61937777778"; type = video; }, { duration = 0; end = "75914.25420000001"; reader = "75914.25420000001"; type = audio; } ); underrun = 1;}
2022-04-24 19:49:18.338 [u=454.1MB f=1643.9MB] mpvstats: AV: 3080.899 A-V: 0.000010 Dropped: 0 Cache: 0.48s video + 0.00s audio
2022-04-24 19:49:18.338 [u=454.1MB f=1643.9MB] streamstats: strength=100% quality=97% symbol=100% rate=6.3Mb/sec
2022-04-24 19:49:23.337 [u=454.0MB f=1644.0MB] streamstats: strength=100% quality=97% symbol=100% rate=6.3Mb/sec
2022-04-24 19:49:23.337 [u=454.0MB f=1644.0MB] mpvstats: AV: 3080.899 A-V: 0.000010 Dropped: 0 Cache: 0.48s video + 0.00s audio
2022-04-24 19:49:28.337 [u=453.9MB f=1644.1MB] streamstats: strength=100% quality=98% symbol=100% rate=4.3Mb/sec recentnetbad=0%
2022-04-24 19:49:28.337 [u=453.9MB f=1644.1MB] mpvstats: AV: 3080.899 A-V: 0.000010 Dropped: 0 Cache: 0.48s video + 0.00s audio
2022-04-24 19:49:28.338 [u=453.9MB f=1644.1MB] signal: Displaying tuner network problem notification: strength=100% quality=98% symbol=100% rate=4.3Mb/sec recentnetbad=0%
2022-04-24 19:49:30.856 [u=445.9MB f=1652.1MB] [3095.86s] [cplayer] v: Still buffering (buffer went from 0% -> 8%) [0.021333s].
2022-04-24 19:49:30.857 [u=446.1MB f=1651.9MB] [3095.87s] [cplayer] v: Still buffering (buffer went from 8% -> 51%) [0.128000s].
2022-04-24 19:49:30.908 [u=445.5MB f=1652.5MB] [3095.92s] [cplayer] v: End buffering (waited 13.038127 secs) [1.002667s].
2022-04-24 19:49:30.908 [u=445.5MB f=1652.5MB] [3095.92s] IS BUFFERING = NO
2022-04-24 19:49:30.909 [u=445.5MB f=1652.5MB] Updating playState from LTVideoPlayerPlayStateBuffering to LTVideoPlayerPlayStatePlaying
2022-04-24 19:49:30.909 [u=445.5MB f=1652.5MB] [3095.92s] [cplayer] v: restarting audio after underrun
2022-04-24 19:49:33.332 [u=454.3MB f=1643.7MB] streamstats: strength=100% quality=99% symbol=100% rate=5.7Mb/sec recentnetbad=0%
2022-04-24 19:49:33.332 [u=454.3MB f=1643.7MB] mpvstats: AV: 3083.299 A-V: 0.000006 Dropped: 0 Cache: 13.76s video + 13.29s audio
2022-04-24 19:49:33.332 [u=454.3MB f=1643.7MB] signal: Displaying tuner network problem notification: strength=100% quality=99% symbol=100% rate=5.7Mb/sec recentnetbad=0%
2022-04-24 19:49:35.766 [u=454.5MB f=1643.5MB] [3100.77s] [ffmpeg/audio] error: aac_latm: Number of bands (62) exceeds limit (40).
2022-04-24 19:49:35.766 [u=453.7MB f=1644.4MB] [3100.77s] [ad] error: Error decoding audio in send_packet (-1094995529).
2022-04-24 19:49:35.766 [u=452.8MB f=1645.2MB] [3100.77s] [ad] error: Error decoding audio in send_packet (-1094995529).
2022-04-24 19:49:35.766 [u=452.0MB f=1646.0MB] [3100.77s] [ad] warn: Invalid audio PTS: 3085.930667 -> 3094.336000
2022-04-24 19:49:35.766 [u=451.2MB f=1646.8MB] [3100.78s] [cplayer] warn: Reset playback due to audio timestamp reset.
2022-04-24 19:49:35.772 [u=403.0MB f=1695.0MB] [3100.78s] [cplayer] v: blocked, waiting for old audio to play
2022-04-24 19:49:35.773 [u=403.5MB f=1694.4MB] [3100.78s] [cplayer] v: audio ready
2022-04-24 19:49:35.776 [u=410.1MB f=1687.8MB] [3100.78s] [ffmpeg/video] error: h264: co located POCs unavailable
2022-04-24 19:49:35.777 [u=411.5MB f=1686.5MB] [3100.79s] [ffmpeg/video] error: h264: co located POCs unavailable
2022-04-24 19:49:35.778 [u=413.6MB f=1684.3MB] [3100.79s] [ffmpeg/video] error: h264: reference picture missing during reorder
2022-04-24 19:49:35.778 [u=414.1MB f=1683.9MB] [3100.79s] [ffmpeg/video] error: h264: reference picture missing during reorder
2022-04-24 19:49:35.779 [u=414.1MB f=1683.8MB] [3100.79s] [ffmpeg/video] error: h264: Missing reference picture, default is 65972
2022-04-24 19:49:35.779 [u=414.7MB f=1683.3MB] [3100.79s] [ffmpeg/video] error: h264: Missing reference picture, default is 65972
2022-04-24 19:49:35.779 [u=415.2MB f=1682.8MB] [3100.79s] [ffmpeg/video] error: h264: mmco: unref short failure
2022-04-24 19:49:35.810 [u=425.9MB f=1672.1MB] [3100.82s] [ffmpeg/video] error: h264: mmco: unref short failure
2022-04-24 19:49:35.826 [u=428.0MB f=1670.0MB] [3100.83s] [ffmpeg/video] error: h264: error while decoding MB 52 54, bytestream -6
2022-04-24 19:49:35.826 [u=428.0MB f=1670.0MB] [3100.83s] [ffmpeg/video] v: h264: concealing 1677 DC, 1677 AC, 1677 MV errors in B frame
2022-04-24 19:49:35.834 [u=432.5MB f=1665.5MB] [3100.84s] [ffmpeg/video] error: h264: co located POCs unavailable
2022-04-24 19:49:35.844 [u=436.7MB f=1661.3MB] [3100.85s] [ffmpeg/video] error: h264: reference picture missing during reorder
2022-04-24 19:49:35.846 [u=437.8MB f=1660.2MB] [3100.85s] [ffmpeg/video] error: h264: reference picture missing during reorder
2022-04-24 19:49:35.846 [u=437.8MB f=1660.2MB] [3100.85s] [ffmpeg/video] error: h264: Missing reference picture, default is 66192
2022-04-24 19:49:35.846 [u=437.8MB f=1660.2MB] [3100.86s] [ffmpeg/video] error: h264: Missing reference picture, default is 66192
2022-04-24 19:49:35.850 [u=437.9MB f=1660.1MB] [3100.86s] [vd] v: Decoder format: 1920x1080 yuv420p bt.709/bt.709/bt.1886/limited/auto CL=mpeg2/4/h264
2022-04-24 19:49:35.853 [u=437.9MB f=1660.1MB] [3100.86s] [cplayer] warn: Invalid video timestamp: 3086.898511 -> 3094.778511 (7.880000 > 5.000000)
2022-04-24 19:49:35.855 [u=437.9MB f=1660.1MB] [3100.86s] event: playback-restart
2022-04-24 19:49:35.857 [u=437.9MB f=1660.1MB] Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStatePlaying
2022-04-24 19:49:35.861 [u=437.9MB f=1660.1MB] [3100.87s] [cplayer] v: first video frame after restart shown
2022-04-24 19:49:35.861 [u=438.0MB f=1660.0MB] [3100.87s] [cplayer] v: delaying audio start 3094.189978 vs. 3086.898511, diff=7.291467
2022-04-24 19:49:35.861 [u=438.0MB f=1660.0MB] [3100.87s] [cplayer] v: playback restart complete @ 3086.898511, audio=ready, video=playing
2022-04-24 19:49:35.861 [u=438.0MB f=1660.0MB] [3100.87s] [cplayer] v: delaying audio start 3094.189999 vs. 3086.898511, diff=7.291488
2022-04-24 19:49:35.861 [u=438.0MB f=1660.0MB] [3100.87s] [cplayer] v: starting audio playback
2022-04-24 19:49:36.181 [u=437.8MB f=1660.2MB] [3101.19s] [ffmpeg/video] error: h264: mmco: unref short failure
2022-04-24 19:49:38.333 [u=441.0MB f=1657.0MB] streamstats: strength=100% quality=97% symbol=100% rate=5Mb/sec recentnetbad=0%
2022-04-24 19:49:38.333 [u=441.0MB f=1657.0MB] mpvstats: AV: 3096.819 A-V: -0.125160 Dropped: 0 Cache: 5.36s video + 4.93s audio
2022-04-24 19:49:38.334 [u=441.0MB f=1657.0MB] signal: Displaying tuner network problem notification: strength=100% quality=97% symbol=100% rate=5Mb/sec recentnetbad=0%
2022-04-24 19:49:43.332 [u=441.7MB f=1656.3MB] streamstats: strength=100% quality=100% symbol=100% rate=4.5Mb/sec recentnetbad=0%
2022-04-24 19:49:43.332 [u=441.7MB f=1656.3MB] mpvstats: AV: 3101.699 A-V: 0.000027 Dropped: 0 Cache: 5.32s video + 4.86s audio
2022-04-24 19:49:43.332 [u=441.7MB f=1656.3MB] signal: Displaying tuner network problem notification: strength=100% quality=100% symbol=100% rate=4.5Mb/sec recentnetbad=0%
2022-04-24 19:49:47.291 [u=442.0MB f=1656.0MB] libchannels: creating new segment at idx=38
2022-04-24 19:49:47.292 [u=442.0MB f=1656.0MB] libchannels: pruning segment with idx=24
2022-04-24 19:49:47.301 [u=442.0MB f=1656.0MB] libchannels: rolling over reader to segment with idx=38
2022-04-24 19:49:48.332 [u=442.0MB f=1656.0MB] streamstats: strength=100% quality=98% symbol=100% rate=4.2Mb/sec recentnetbad=0%
2022-04-24 19:49:48.332 [u=442.0MB f=1656.0MB] mpvstats: AV: 3106.699 A-V: 0.000022 Dropped: 0 Cache: 5.32s video + 4.89s audio
2022-04-24 19:49:53.331 [u=442.3MB f=1655.7MB] streamstats: strength=100% quality=98% symbol=100% rate=5Mb/sec recentnetbad=0%
2022-04-24 19:49:53.331 [u=442.3MB f=1655.7MB] mpvstats: AV: 3111.699 A-V: 0.000028 Dropped: 0 Cache: 5.56s video + 4.84s audio
2022-04-24 19:49:58.331 [u=442.0MB f=1656.0MB] streamstats: strength=100% quality=97% symbol=100% rate=5.4Mb/sec recentnetbad=0%
Thanks.