Hi. I don't think I can troubleshoot this issue any further without assistance. Any and all help would be appreciated. Apologies in advance if this is too much for an initial post but wanted to be thorough based on reading the previous posts.
I am also having this issue with my Channels app over an Orbi network. I receive Connection Lost errors multiple times a day while trying to watch live TV using Channels DVR app on an Apple TV 4k. When I get frustrated enough with the issue, I just watch the stream coming from the HDHomeRun Extend directly on my LG TV. Sometimes the LG has a minor hiccup and it spins for a second or two but then the stream returns to playing without exception. (With the Channels app I would have received the Connection Lost message and had to back up to the guide and reselect the channel to continue watching the program.)
I have changed the settings on my Orbi router to mimic the configuration described in the posts above to the best of my ability. I have also pulled logs that I have replicated below.
So here is what I’m running.
Orbi RBR50 — Orbi AC3000 Tri-band WiFi Router with Firmware Version V2.2.1.210. Backhaul Topology/Daisy-Chain Topology, Implicit Beamforming, MU-MIMO and Fast Roaming are all disabled. WMM (Wi-Fi multimedia) settings are enabled for both the 2.4 and 5GHz networks.
HDHomeRun EXTEND with an antenna for OTA and HDHomeRun Premium TV Channels
Model: HDTC-2US
Firmware: 20180817
Transcode configuration set to Heavy
Tuner Sharing is Off
Apple TV 4K running tvOS 12.1.1 (16K45)
I’m using the tvOS Channels DVR app (version 3.2.10) and running the Channels DVR (v2018.11.20.2224) on a Mac Mini. I have not experienced or at least noticed any lost connection issues with respect to recorded programming.
Channels DVR log (from Mac Mini where “10592E5D” is the Device ID of my HDHomeRun Extend)
2019/01/13 17:21:04 [TNR] Opened connection to 10592E5D for ch1113 [transcode=heavy]
2019/01/13 18:27:24 [DVR] Cancelling stream 10592E5D ch1113 after 3s read timeout
2019/01/13 18:27:24 [TNR] Closed connection to 10592E5D for ch1113
2019/01/13 18:28:48 [TNR] Opened connection to 10592E5D for ch1113 [transcode=heavy]
2019/01/13 22:32:20 [DVR] Cancelling stream 10592E5D ch1113 after 3s read timeout
2019/01/13 22:32:20 [TNR] Closed connection to 10592E5D for ch1113
2019/01/13 22:34:49 [TNR] Opened connection to 10592E5D for ch1113 [transcode=heavy]
2019/01/13 23:07:33 [TNR] Closed connection to 10592E5D for ch1113
HDHomeRun Extend log where “192.168.1.14” is the Mac Mini
20190113-22:21:04 Tuner: tuner0 streaming http to 192.168.1.14:56535
20190113-23:27:24 Tuner: tuner0 http stream ended (remote closed)
20190113-23:28:46 Tuner: tuner0 requesting 1113 MSNBC
20190113-23:28:48 Tuner: tuner0 streaming http to 192.168.1.14:56708
20190114-03:32:20 Tuner: tuner0 http stream ended (remote closed)
20190114-03:34:47 Tuner: tuner0 requesting 1113 MSNBC
20190114-03:34:49 Tuner: tuner0 streaming http to 192.168.1.14:57481
20190114-04:07:33 Tuner: tuner0 http stream ended (remote closed)
Apple TV / Channels DVR app log [http://192.168.1.31:57000/log]
2019-01-13 18:27:22.643 event: unpause
2019-01-13 18:27:22.645 [cplayer] v: Enter buffering (buffer went from 100% -> 0%) [0.000000s].
2019-01-13 18:27:22.648 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateBuffering
2019-01-13 18:27:24.212 read got (55) No buffer space available
2019-01-13 18:27:24.215 read got (55) No buffer space available
2019-01-13 18:27:24.217 read got (55) No buffer space available
2019-01-13 18:27:24.219 read got (55) No buffer space available
2019-01-13 18:27:24.221 read got (55) No buffer space available
2019-01-13 18:27:24.223 read got (55) No buffer space available
2019-01-13 18:27:24.225 read got (55) No buffer space available
2019-01-13 18:27:24.227 read got (55) No buffer space available
2019-01-13 18:27:24.229 read got (55) No buffer space available
2019-01-13 18:27:24.231 read got (55) No buffer space available
2019-01-13 18:27:24.233 read got (55) No buffer space available
2019-01-13 18:27:24.235 read got (55) No buffer space available
2019-01-13 18:27:24.237 read got (55) No buffer space available
2019-01-13 18:27:24.239 read got (55) No buffer space available
2019-01-13 18:27:24.241 read got (55) No buffer space available
2019-01-13 18:27:24.243 read got (55) No buffer space available
2019-01-13 18:27:24.245 read got (55) No buffer space available
2019-01-13 18:27:24.247 read got (55) No buffer space available
2019-01-13 18:27:24.249 read got (55) No buffer space available
2019-01-13 18:27:24.250 read got (55) No buffer space available
2019-01-13 18:27:24.252 streamer stopping after 685800 packets and 20 timeouts (73370 waits)
2019-01-13 18:27:24.279 [lavf] v: EOF reached.
2019-01-13 18:27:24.284 event: unpause
2019-01-13 18:27:24.286 [cplayer] v: End buffering (waited 1.656180 secs) [0.066733s].
2019-01-13 18:27:24.288 Updating playState from LTVideoPlayerPlayStateBuffering to LTVideoPlayerPlayStatePlaying
2019-01-13 18:27:24.420 [af] v: filter input EOF
2019-01-13 18:27:24.422 [af] v: filter output EOF
2019-01-13 18:27:24.424 [cplayer] v: audio EOF reached
2019-01-13 18:27:24.541 [vf] v: filter input EOF
2019-01-13 18:27:24.543 [vf] v: filter output EOF
2019-01-13 18:27:24.583 [cplayer] v: video EOF reached
2019-01-13 18:27:24.584 [cplayer] v: EOF code: 1
2019-01-13 18:27:24.586 event: audio-reconfig
2019-01-13 18:27:24.588 event: video-reconfig
2019-01-13 18:27:24.589 [ad] v: Uninit decoder.
2019-01-13 18:27:24.591 [vd] v: Uninit decoder.
2019-01-13 18:27:24.599 event: tracks-changed
2019-01-13 18:27:24.618 event: end-file
2019-01-13 18:27:24.623 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateError
2019-01-13 18:27:24.629 event: audio-reconfig
2019-01-13 18:27:24.630 event: video-reconfig
2019-01-13 18:27:24.632 [cplayer] v: finished playback, success (reason 0)
2019-01-13 18:27:24.633 [cplayer] info:
2019-01-13 18:27:24.635 [cplayer] v: Set property: aid=1 -> 1
2019-01-13 18:27:24.637 [cplayer] v: Set property: audio=1 -> 1
2019-01-13 18:27:24.639 [cplayer] v: Set property: sid=0 -> 1
2019-01-13 18:27:24.641 [cplayer] v: Set property: sub=0 -> 1
2019-01-13 18:28:42.025 [cplayer] v: Set property: pause=false -> 1
2019-01-13 18:28:42.030 Updating playState from LTVideoPlayerPlayStateError to LTVideoPlayerPlayStateStopped
2019-01-13 18:28:42.041 Guide Loaded: {
Filter = "All Channels";
Source = Guide;
}
2019-01-13 18:28:42.618 Guide View (Main View/GuideView): (null)
2019-01-13 18:28:46.305 Updating playState from LTVideoPlayerPlayStateStopped to LTVideoPlayerPlayStateStopped
2019-01-13 18:28:46.307 [cplayer] v: Set property: pause=false -> 1
2019-01-13 18:28:46.349 Updating playState from LTVideoPlayerPlayStateStopped to LTVideoPlayerPlayStateLoading
2019-01-13 18:28:46.351 set streaming buffer to 128 segments (free bytes: 33951707136)
2019-01-13 18:28:46.353 Play Channel: {
Source = "Guide View Item Cell";
}
2019-01-13 18:28:46.355 streamer sent request to DVR 192.168.1.14: device 10592E5D, channel <HRChannel:0x280edebe0 number=1113 name=MSNBC (MSNBC)> [/devices/10592E5D/channels/1113/stream.mpg?codec=copy&transcode=heavy]
2019-01-13 18:28:46.886 Video View (Main View/VideoView): (null)
2019-01-13 18:28:48.348 event: start-file
2019-01-13 18:28:48.353 Updating playState from LTVideoPlayerPlayStateLoading to LTVideoPlayerPlayStateLoading
2019-01-13 18:28:48.355 [cplayer] info: Playing: cb://1547422126349
2019-01-13 18:28:48.357 [stream_callback] v: Opening cb://1547422126349
2019-01-13 18:28:48.359 [demux] v: Trying demuxers for level=force.
2019-01-13 18:28:48.946 streamer started receiving data
2019-01-13 18:28:48.955 [lavf] v: Found 'mpegts' at score=50 size=2048.
2019-01-13 18:28:48.957 [lavf] v: avformat_open_input() finished after 2048 bytes.
2019-01-13 18:28:48.959 event: tracks-changed
2019-01-13 18:28:48.968 event: tracks-changed
2019-01-13 18:28:49.020 event: metadata-update
2019-01-13 18:28:49.022 event: audio-reconfig
2019-01-13 18:28:49.024 event: audio-reconfig
2019-01-13 18:28:49.026 event: file-loaded
2019-01-13 18:28:49.028 event: audio-reconfig
2019-01-13 18:28:49.030 event: video-reconfig
2019-01-13 18:28:49.032 event: unpause
2019-01-13 18:28:49.034 event: tracks-changed
2019-01-13 18:28:49.036 event: video-reconfig
2019-01-13 18:28:49.038 event: playback-restart
2019-01-13 18:28:49.040 Updating playState from LTVideoPlayerPlayStateLoading to LTVideoPlayerPlayStatePlaying
2019-01-13 18:28:49.042 [lavf] v: avformat_find_stream_info() skipped
2019-01-13 18:28:49.044 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateBuffering
2019-01-13 18:28:49.046 [demux] v: Detected file format: mpegts (libavformat)
2019-01-13 18:28:49.048 [cplayer] v: Opening done: cb://1547422126349
2019-01-13 18:28:49.050 [lavf] v: select track 0
2019-01-13 18:28:49.052 [lavf] v: select track 1
2019-01-13 18:28:49.054 [cplayer] info: (+) Video --vid=1 (h264)
2019-01-13 18:28:49.056 [cplayer] info: (+) Audio --aid=1 (aac)
2019-01-13 18:28:49.058 [vd] v: Container reported FPS: 0.000000
2019-01-13 18:28:49.060 [vd] v: Codec list:
2019-01-13 18:28:49.062 [vd] v: h264 - H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10
2019-01-13 18:28:49.064 [vd] v: Opening decoder h264
2019-01-13 18:28:49.066 [vd] v: Not trying to use hardware decoding: codec h264 is not on whitelist.
2019-01-13 18:28:49.068 [vd] v: Using software decoding.
2019-01-13 18:28:49.070 [vd] v: Detected 3 logical cores.
2019-01-13 18:28:49.072 [vd] v: Requesting 4 threads for decoding.
2019-01-13 18:28:49.074 [vd] v: Selected codec: h264 (H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10)
2019-01-13 18:28:49.076 [vf] v: User filter list:
2019-01-13 18:28:49.078 [vf] v: lavfi (lavfi.00)
2019-01-13 18:28:49.080 [ad] v: Codec list:
2019-01-13 18:28:49.082 [ad] v: aac - AAC (Advanced Audio Coding)
2019-01-13 18:28:49.084 [ad] v: aac_fixed (aac) - AAC (Advanced Audio Coding)
2019-01-13 18:28:49.086 [ad] v: aac_at (aac) - aac (AudioToolbox)
2019-01-13 18:28:49.088 [ad] v: Opening decoder aac
2019-01-13 18:28:49.090 [ad] v: Requesting 1 threads for decoding.
2019-01-13 18:28:49.092 [ad] v: Selected codec: aac (AAC (Advanced Audio Coding))
2019-01-13 18:28:49.094 [af] v: User filter list:
2019-01-13 18:28:49.096 [af] v: (empty)
2019-01-13 18:28:49.098 [cplayer] v: Starting playback...
2019-01-13 18:28:49.100 [af] v: [in] 48000Hz stereo 2ch floatp
2019-01-13 18:28:49.102 [af] v: format changed, draining filter chain
2019-01-13 18:28:49.104 [af] v: done format change draining
2019-01-13 18:28:49.106 [af] v: probing new format
2019-01-13 18:28:49.108 [af] v: [userspeed] 48000Hz stereo 2ch floatp
2019-01-13 18:28:49.110 [af] v: [convert] 48000Hz stereo 2ch floatp
2019-01-13 18:28:49.112 [af] v: got output format from probing
2019-01-13 18:28:49.114 [ao] v: Trying audio driver 'audiounit'
2019-01-13 18:28:49.116 [ao/audiounit] v: requested format: 48000 Hz, stereo channels, floatp
2019-01-13 18:28:49.118 [ao/audiounit] v: using soft-buffer of 9600 samples.
2019-01-13 18:28:49.120 [cplayer] info: AO: [audiounit] 48000Hz stereo 2ch floatp
2019-01-13 18:28:49.122 [cplayer] v: AO: Description: AudioUnit (iOS)
2019-01-13 18:28:49.124 [vd] v: Decoder format: 1280x720 yuv420p auto/auto/auto/auto/auto CL=mpeg2/4/h264 (auto 0.000000/0.000000/0.000000)
2019-01-13 18:28:49.126 [vf] v: [in] 1280x720 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
2019-01-13 18:28:49.128 [vf] v: [userdeint] 1280x720 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
2019-01-13 18:28:49.130 [vf] v: [lavfi] 1280x720 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
2019-01-13 18:28:49.132 [vf] v: [autorotate] 1280x720 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
2019-01-13 18:28:49.134 [vf] v: [convert] 1280x720 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
2019-01-13 18:28:49.136 [cplayer] info: VO: [libmpv] 1280x720 yuv420p
2019-01-13 18:28:49.138 [cplayer] v: VO: Description: render API for libmpv
2019-01-13 18:28:49.140 [vo/libmpv] v: reconfig to 1280x720 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
2019-01-13 18:28:49.142 [cplayer] v: first video frame after restart shown
2019-01-13 18:28:49.144 [cplayer] v: Enter buffering (buffer went from 100% -> 30%) [0.300300s].
2019-01-13 18:28:49.146 [cplayer] info: (+) Video --vid=1 (h264)
2019-01-13 18:28:49.148 [cplayer] info: (+) Audio --aid=1 (aac)
2019-01-13 18:28:49.150 [cplayer] info: Subs --sid=1 (*) (eia_608)
2019-01-13 18:28:49.152 [cplayer] v: starting audio playback
2019-01-13 18:28:49.154 [cplayer] v: playback restart complete
2019-01-13 18:28:50.175 event: unpause
2019-01-13 18:28:50.181 [cplayer] v: End buffering (waited 0.913696 secs) [1.201200s].
2019-01-13 18:28:50.189 Updating playState from LTVideoPlayerPlayStateBuffering to LTVideoPlayerPlayStatePlaying
2019-01-13 18:29:33.992 event: unpause
2019-01-13 18:29:33.994 [cplayer] v: Enter buffering (buffer went from 100% -> 0%) [0.000000s].
2019-01-13 18:29:33.997 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateBuffering
2019-01-13 18:29:34.095 event: unpause
2019-01-13 18:29:34.098 [cplayer] v: End buffering (waited 0.104467 secs) [1.534867s].
2019-01-13 18:29:34.100 Updating playState from LTVideoPlayerPlayStateBuffering to LTVideoPlayerPlayStatePlaying
2019-01-13 18:29:35.654 event: unpause
2019-01-13 18:29:35.656 [cplayer] v: Enter buffering (buffer went from 100% -> 0%) [0.000000s].
2019-01-13 18:29:35.659 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateBuffering
2019-01-13 18:29:36.082 event: unpause
2019-01-13 18:29:36.087 [cplayer] v: End buffering (waited 0.415240 secs) [1.835167s].
2019-01-13 18:29:36.102 Updating playState from LTVideoPlayerPlayStateBuffering to LTVideoPlayerPlayStatePlaying
2019-01-13 18:29:55.272 [ad] warn: Invalid audio PTS: 78150.189089 -> 78151.767756
2019-01-13 18:29:55.274 [cplayer] warn:
2019-01-13 18:29:55.277 [cplayer] warn: Audio/Video desynchronisation detected! Possible reasons include too slow
2019-01-13 18:29:55.279 [cplayer] warn: hardware, temporary CPU spikes, broken drivers, and broken files. Audio
2019-01-13 18:29:55.281 [cplayer] warn: position will not match to the video (see A-V status field).
2019-01-13 18:29:55.282 [cplayer] warn:
2019-01-13 18:34:55.205 event: unpause
2019-01-13 18:34:55.208 [cplayer] v: Enter buffering (buffer went from 100% -> 0%) [0.000000s].
2019-01-13 18:34:55.212 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateBuffering
2019-01-13 18:34:55.415 event: unpause
2019-01-13 18:34:55.416 [cplayer] v: End buffering (waited 0.200890 secs) [1.634967s].
2019-01-13 18:34:55.423 Updating playState from LTVideoPlayerPlayStateBuffering to LTVideoPlayerPlayStatePlaying
2019-01-13 18:35:31.619 event: unpause
2019-01-13 18:35:31.622 [cplayer] v: Enter buffering (buffer went from 100% -> 0%) [0.000000s].
2019-01-13 18:35:31.625 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateBuffering
2019-01-13 18:35:31.808 event: unpause
2019-01-13 18:35:31.810 [cplayer] v: End buffering (waited 0.193390 secs) [1.901900s].
2019-01-13 18:35:31.813 Updating playState from LTVideoPlayerPlayStateBuffering to LTVideoPlayerPlayStatePlaying
2019-01-13 18:36:24.376 event: unpause
2019-01-13 18:36:24.378 [cplayer] v: Enter buffering (buffer went from 100% -> 0%) [0.000000s].
2019-01-13 18:36:24.381 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateBuffering
2019-01-13 18:36:25.015 event: unpause
2019-01-13 18:36:25.019 [cplayer] v: End buffering (waited 0.629029 secs) [2.302300s].
2019-01-13 18:36:25.032 Updating playState from LTVideoPlayerPlayStateBuffering to LTVideoPlayerPlayStatePlaying
2019-01-13 18:46:43.744 [ffmpeg/audio] error: aac: skip_data_stream_element: Input buffer exhausted before END element found
2019-01-13 18:46:43.746 [ad] error: Error decoding audio.
2019-01-13 18:46:43.749 [ffmpeg/audio] error: aac: channel element 2.9 is not allocated
2019-01-13 18:46:43.751 [ad] error: Error decoding audio.
2019-01-13 18:47:42.557 event: unpause
2019-01-13 18:47:42.559 [cplayer] v: Enter buffering (buffer went from 100% -> 0%) [0.000000s].
2019-01-13 18:47:42.562 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateBuffering
2019-01-13 18:47:42.828 event: unpause
2019-01-13 18:47:42.830 [cplayer] v: End buffering (waited 0.253421 secs) [2.769433s].
2019-01-13 18:47:42.833 Updating playState from LTVideoPlayerPlayStateBuffering to LTVideoPlayerPlayStatePlaying
2019-01-13 18:58:30.342 event: unpause
2019-01-13 18:58:30.345 [cplayer] v: Enter buffering (buffer went from 100% -> 0%) [0.000000s].
2019-01-13 18:58:30.347 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateBuffering
2019-01-13 18:58:32.967 event: unpause
2019-01-13 18:58:32.970 [cplayer] v: End buffering (waited 2.524862 secs) [5.405400s].
2019-01-13 18:58:32.994 Updating playState from LTVideoPlayerPlayStateBuffering to LTVideoPlayerPlayStatePlaying
2019-01-13 18:58:33.021 [ad] warn: Invalid audio PTS: 79865.495756 -> 79870.829089
2019-01-13 18:58:33.022 [cplayer] v: Reset playback due to audio timestamp reset.
2019-01-13 18:58:33.107 [vd] v: Decoder format: 1280x720 yuv420p auto/auto/auto/auto/auto CL=mpeg2/4/h264 (auto 0.000000/0.000000/0.000000)
2019-01-13 18:58:33.111 [cplayer] v: first video frame after restart shown
2019-01-13 18:58:33.114 event: unpause
2019-01-13 18:58:33.116 event: playback-restart
2019-01-13 18:58:33.118 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStatePlaying
2019-01-13 18:58:33.120 [cplayer] v: Enter buffering (buffer went from 100% -> 44%) [0.448000s].
2019-01-13 18:58:33.122 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateBuffering
2019-01-13 18:58:33.124 [cplayer] v: playback restart complete
2019-01-13 18:58:33.970 event: unpause
2019-01-13 18:58:33.972 [cplayer] v: End buffering (waited 0.827938 secs) [1.002667s].
2019-01-13 18:58:34.007 Updating playState from LTVideoPlayerPlayStateBuffering to LTVideoPlayerPlayStatePlaying
2019-01-13 18:58:37.531 [cplayer] v: starting audio playback
2019-01-13 19:20:17.160 Notification: LTGuideDataUpdated
2019-01-13 19:32:10.080 [ffmpeg/audio] error: aac: TYPE_FIL: Input buffer exhausted before END element found
2019-01-13 19:32:10.083 [ad] error: Error decoding audio.
2019-01-13 19:32:10.085 [ffmpeg/audio] error: aac: Reserved bit set.
2019-01-13 19:32:10.087 [ffmpeg/audio] error: aac: Number of scalefactor bands in group (52) exceeds limit (49).
2019-01-13 19:32:10.089 [ad] error: Error decoding audio.
2019-01-13 20:20:16.899 Notification: LTGuideDataUpdated