Connection lost issues


#1

I’m also having constant freezes with the app - I’ve been trying all sorts to resolve and now have everything hard wired.

It’s just done it again, can’t see an option to send logs?

I’m running 3.2 App Store build, and tvOS 12


Horrible playback on Apple tv
#2

You can check the logs yourself by finding the IP of your Apple TV and checking http://x.x.x.x:57000/log


#3

Hmm… I get connection refused. I also just got a connection lost message.

Difficult tracking this down!


#4

Just read in another post that Channels has to be running… will check logs now.


#5
2018-07-03 14:28:17.483 read(32768) = 0 after 5000000

2018-07-03 14:28:22.898 read(32768) = 0 after 5000000
2018-07-03 14:28:28.276 read(32768) = 0 after 5000000
2018-07-03 14:28:33.713 read(32768) = 0 after 5000000
2018-07-03 14:28:33.717 [lavf] v: EOF reached.
2018-07-03 14:28:33.722 [af] v: filter input EOF
2018-07-03 14:28:33.727 [af] v: filter output EOF
2018-07-03 14:28:33.730 [cplayer] v: audio EOF reached
2018-07-03 14:28:34.343 [ffmpeg/video] error: h264: error while decoding MB 93 12, bytestream -5
2018-07-03 14:28:34.348 [ffmpeg/video] v: h264: concealing 6676 DC, 6676 AC, 6676 MV errors in I frame
2018-07-03 14:28:34.619 [vf] v: filter input EOF
2018-07-03 14:28:34.623 [vf] v: filter output EOF
2018-07-03 14:28:34.763 [cplayer] v: video EOF reached
2018-07-03 14:28:34.767 event: audio-reconfig
2018-07-03 14:28:34.772 [cplayer] v: EOF code: 1
2018-07-03 14:28:34.776 event: video-reconfig
2018-07-03 14:28:34.779 [ad] v: Uninit decoder.
2018-07-03 14:28:34.782 [vd] v: Uninit decoder.
2018-07-03 14:28:39.039 read got (9) Bad file descriptor
2018-07-03 14:28:39.044 event: tracks-changed
2018-07-03 14:28:39.048 streamer stopping after 256500 packets and 1 timeouts (9514 waits)
2018-07-03 14:28:39.133 event: end-file
2018-07-03 14:28:39.143 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateError
2018-07-03 14:28:39.151 event: audio-reconfig
2018-07-03 14:28:39.154 event: video-reconfig
2018-07-03 14:28:39.157 [cplayer] v: finished playback, success (reason 0)
2018-07-03 14:28:39.161 [cplayer] info:
2018-07-03 14:28:39.165 [cplayer] v: Set property: aid=1 -> 1
2018-07-03 14:28:39.169 [cplayer] v: Set property: audio=1 -> 1
2018-07-03 14:28:39.173 [cplayer] v: Set property: sid=0 -> 1
2018-07-03 14:28:39.177 [cplayer] v: Set property: sub=0 -> 1
2018-07-03 14:29:07.742 [cplayer] v: Set property: pause=false -> 1
2018-07-03 14:29:07.745 Updating playState from LTVideoPlayerPlayStateError to LTVideoPlayerPlayStateStopped
2018-07-03 14:29:07.750 Guide Loaded: {
Filter = All;
Source = “On Now”;
}
2018-07-03 14:29:08.304 Favorite Channels View (Main View/FavoriteChannelsView): (null)
2018-07-03 14:29:11.232 jsonpipe failed with Error Domain=NSURLErrorDomain Code=-999 “cancelled” UserInfo={NSErrorFailingURLStringKey=http://192.168.1.15:8089/dvr/events/subscribe, NSErrorFailingURLKey=http://192.168.1.15:8089/dvr/events/subscribe, _NSURLErrorRelatedURLSessionTaskErrorKey=(
“LocalDataTask .<1>”
), _NSURLErrorFailingURLSessionTaskErrorKey=LocalDataTask .<1>, NSLocalizedDescription=cancelled}


#6

That’s all that is in the logs - not sure if it is any help!


#7

It has just frozen again - log below.

2018-07-03 15:10:33.962 read(32768) = 0 after 5000000
2018-07-03 15:10:39.350 read(32768) = 0 after 5000000
2018-07-03 15:10:44.734 read(32768) = 0 after 5000000
2018-07-03 15:10:50.149 read(32768) = 0 after 5000000
2018-07-03 15:10:50.153 [lavf] v: EOF reached.
2018-07-03 15:10:50.157 [af] v: filter input EOF
2018-07-03 15:10:50.158 [af] v: filter output EOF
2018-07-03 15:10:50.162 [cplayer] v: audio EOF reached
2018-07-03 15:10:50.701 [ffmpeg/video] error: h264: error while decoding MB 114 44, bytestream -5
2018-07-03 15:10:50.877 [vf] v: filter input EOF
2018-07-03 15:10:50.880 [vf] v: filter output EOF
2018-07-03 15:10:50.896 [cplayer] v: video EOF reached
2018-07-03 15:10:50.898 [cplayer] v: EOF code: 1
2018-07-03 15:10:50.901 event: audio-reconfig
2018-07-03 15:10:50.904 event: video-reconfig
2018-07-03 15:10:50.907 [ad] v: Uninit decoder.
2018-07-03 15:10:50.911 [vd] v: Uninit decoder.
2018-07-03 15:10:55.303 read got (9) Bad file descriptor
2018-07-03 15:10:55.307 event: tracks-changed
2018-07-03 15:10:55.312 streamer stopping after 230200 packets and 1 timeouts (5990 waits)
2018-07-03 15:10:55.616 event: end-file
2018-07-03 15:10:55.620 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateError
2018-07-03 15:10:55.634 event: audio-reconfig
2018-07-03 15:10:55.637 event: video-reconfig
2018-07-03 15:10:55.641 [cplayer] v: finished playback, success (reason 0)
2018-07-03 15:10:55.645 [cplayer] info:
2018-07-03 15:10:55.649 [cplayer] v: Set property: aid=1 -> 1
2018-07-03 15:10:55.652 [cplayer] v: Set property: audio=1 -> 1
2018-07-03 15:10:55.655 [cplayer] v: Set property: sid=0 -> 1
2018-07-03 15:10:55.658 [cplayer] v: Set property: sub=0 -> 1


#8

That was followed by a connection lost error. I restarted the channel, and the rest of the log is below. I don’t know if it is a channels issue, or a network issue or what. It’s very strange.

2018-07-03 15:12:57.942 [cplayer] v: Set property: pause=false -> 1
2018-07-03 15:12:57.944 Updating playState from LTVideoPlayerPlayStateError to LTVideoPlayerPlayStateStopped
2018-07-03 15:12:57.949 Guide Loaded: {
Filter = All;
Source = “On Now”;
}
2018-07-03 15:12:58.507 Favorite Channels View (Main View/FavoriteChannelsView): (null)
2018-07-03 15:13:00.197 Updating playState from LTVideoPlayerPlayStateStopped to LTVideoPlayerPlayStateStopped
2018-07-03 15:13:00.201 [cplayer] v: Set property: pause=false -> 1
2018-07-03 15:13:00.241 Updating playState from LTVideoPlayerPlayStateStopped to LTVideoPlayerPlayStateLoading
2018-07-03 15:13:00.243 set streaming buffer to 128 segments (free bytes: 11317899264)
2018-07-03 15:13:00.247 streamer sent request to 192.168.1.114: tuner 3, channel <HRChannel:0x282120e40 number=101 name=BBC1 (BBC ONE HD)> []
2018-07-03 15:13:00.796 Video View (Main View/VideoView): (null)
2018-07-03 15:13:00.870 event: start-file
2018-07-03 15:13:00.875 Updating playState from LTVideoPlayerPlayStateLoading to LTVideoPlayerPlayStateLoading
2018-07-03 15:13:00.878 [cplayer] info: Playing: cb://1530627180240
2018-07-03 15:13:00.882 [stream_callback] v: Opening cb://1530627180240
2018-07-03 15:13:00.886 [demux] v: Trying demuxers for level=force.
2018-07-03 15:13:01.023 streamer started receiving data
2018-07-03 15:13:01.042 [lavf] v: Found ‘mpegts’ at score=50 size=2048.
2018-07-03 15:13:01.046 [lavf] v: avformat_open_input() finished after 2048 bytes.
2018-07-03 15:13:01.050 event: tracks-changed
2018-07-03 15:13:01.053 event: tracks-changed
2018-07-03 15:13:01.636 event: tracks-changed
2018-07-03 15:13:01.641 event: metadata-update
2018-07-03 15:13:01.644 event: audio-reconfig
2018-07-03 15:13:01.648 event: audio-reconfig
2018-07-03 15:13:01.652 event: file-loaded
2018-07-03 15:13:01.656 event: audio-reconfig
2018-07-03 15:13:01.660 [lavf] v: avformat_find_stream_info() skipped
2018-07-03 15:13:01.664 [demux] v: Detected file format: mpegts (libavformat)
2018-07-03 15:13:01.667 [cplayer] v: Opening done: cb://1530627180240
2018-07-03 15:13:01.670 [lavf] v: select track 0
2018-07-03 15:13:01.673 [lavf] v: select track 1
2018-07-03 15:13:01.677 [cplayer] info: (+) Video --vid=1 (h264)
2018-07-03 15:13:01.682 [cplayer] info: (+) Audio --aid=1 --alang=eng (aac_latm)
2018-07-03 15:13:01.685 [cplayer] info: Subs --sid=1 --slang=eng (dvb_subtitle)
2018-07-03 15:13:01.689 [vd] v: Container reported FPS: 0.000000
2018-07-03 15:13:01.692 [vd] v: Codec list:
2018-07-03 15:13:01.695 [vd] v: h264 - H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10
2018-07-03 15:13:01.698 [vd] v: Opening decoder h264
2018-07-03 15:13:01.701 [vd] v: Not trying to use hardware decoding: codec h264 is not on whitelist.
2018-07-03 15:13:01.705 [vd] v: Using software decoding.
2018-07-03 15:13:01.709 [vd] v: Detected 3 logical cores.
2018-07-03 15:13:01.713 [vd] v: Requesting 4 threads for decoding.
2018-07-03 15:13:01.717 [vd] v: Selected codec: h264 (H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10)
2018-07-03 15:13:01.720 [vf] v: User filter list:
2018-07-03 15:13:01.723 [vf] v: lavfi (lavfi.00)
2018-07-03 15:13:01.726 [ad] v: Codec list:
2018-07-03 15:13:01.729 [ad] v: aac_latm - AAC LATM (Advanced Audio Coding LATM syntax)
2018-07-03 15:13:01.733 [ad] v: Opening decoder aac_latm
2018-07-03 15:13:01.737 [ad] v: Requesting 1 threads for decoding.
2018-07-03 15:13:01.741 [ad] v: Selected codec: aac_latm (AAC LATM (Advanced Audio Coding LATM syntax))
2018-07-03 15:13:01.745 [af] v: User filter list:
2018-07-03 15:13:01.748 [af] v: (empty)
2018-07-03 15:13:01.751 [cplayer] v: Starting playback…
2018-07-03 15:13:01.754 [af] v: [in] 48000Hz 5.1 6ch floatp
2018-07-03 15:13:01.757 [af] v: format changed, draining filter chain
2018-07-03 15:13:01.761 [af] v: done format change draining
2018-07-03 15:13:01.765 [af] v: probing new format
2018-07-03 15:13:01.769 [af] v: [userspeed] 48000Hz 5.1 6ch floatp
2018-07-03 15:13:01.773 [af] v: [convert] 48000Hz 5.1 6ch floatp
2018-07-03 15:13:01.776 [af] v: got output format from probing
2018-07-03 15:13:01.779 [ao] v: Trying audio driver ‘audiounit’
2018-07-03 15:13:01.782 [ao/audiounit] v: requested format: 48000 Hz, 5.1 channels, floatp
2018-07-03 15:13:01.785 [ao/audiounit] v: using soft-buffer of 9600 samples.
2018-07-03 15:13:01.789 [cplayer] info: AO: [audiounit] 48000Hz fl-fr-lfe-fc-bl-br (5.1) 6ch floatp
2018-07-03 15:13:01.793 [cplayer] v: AO: Description: AudioUnit (iOS)
2018-07-03 15:13:01.797 [autoconvert] v: inserting resampler
2018-07-03 15:13:01.801 [swresample] v: format change, reinitializing resampler
2018-07-03 15:13:01.804 [swresample] v: 48000Hz 5.1 floatp -> 48000Hz fl-fr-lfe-fc-bl-br floatp
2018-07-03 15:13:01.807 [af] v: [convert] 48000Hz fl-fr-lfe-fc-bl-br (5.1
2018-07-03 15:13:01.810 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.813 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.817 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.821 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.825 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.829 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.832 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.835 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.838 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.841 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.845 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.849 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.851 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.855 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.858 event: video-reconfig
2018-07-03 15:13:01.861 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.862 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.865 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.869 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.873 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.875 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.879 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.882 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.885 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.886 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.889 [ffmpeg/video] error: h264: mmco: unref short failure
2018-07-03 15:13:01.893 [ffmpeg/video] error: h264: mmco: unref short failure
2018-07-03 15:13:01.897 [ffmpeg/video] error: h264: mmco: unref short failure
2018-07-03 15:13:01.899 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.903 [vd] warn: Error while decoding frame (-1094995529)!
2018-07-03 15:13:01.906 [ffmpeg/video] error: h264: reference picture missing during reorder
2018-07-03 15:13:01.909 [ffmpeg/video] error: h264: Missing reference picture, default is 2147483647
2018-07-03 15:13:01.910 [vd] v: Decoder format: 1920x1080 yuv420p bt.709/bt.709/bt.1886/limited/auto CL=mpeg2/4/h264 (auto 0.000000/0.000000/0.000000)
2018-07-03 15:13:01.913 [vf] v: [in] 1920x1080 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
2018-07-03 15:13:01.917 updating dvb stream pid filter to 0x0000 0x19c8-0x19ca 0x19cd-0x19ce 0x1bc4 0x1bc6 0x1c86 0x1c97 0x12
2018-07-03 15:13:01.921 [vf] v: [userdeint] 1920x1080 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
2018-07-03 15:13:01.925 [ffmpeg/video] error: h264: reference picture missing during reorder
2018-07-03 15:13:01.928 [ffmpeg/video] error: h264: Missing reference picture, default is 65313
2018-07-03 15:13:01.931 [ffmpeg/video] error: h264: mmco: unref short failure
2018-07-03 15:13:01.934 [ffmpeg/video] error: h264: mmco: unref short failure
2018-07-03 15:13:01.937 [ffmpeg/video] error: h264: number of reference frames (0+5) exceeds max (4; probably corrupt input), discarding one
2018-07-03 15:13:02.108 [vf] v: [lavfi] 1920x1080 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
2018-07-03 15:13:02.112 [vf] v: [autorotate] 1920x1080 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
2018-07-03 15:13:02.116 event: video-reconfig
2018-07-03 15:13:02.121 event: video-reconfig
2018-07-03 15:13:02.123 [vf] v: [convert] 1920x1080 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
2018-07-03 15:13:02.126 [cplayer] info: VO: [libmpv] 1920x1080 yuv420p
2018-07-03 15:13:02.129 [cplayer] v: VO: Description: render API for libmpv
2018-07-03 15:13:02.133 [vo/libmpv] v: reconfig to 1920x1080 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
2018-07-03 15:13:02.136 [cplayer] v: first video frame after restart shown
2018-07-03 15:13:03.083 [cplayer] v: starting audio playback
2018-07-03 15:13:03.104 event: playback-restart
2018-07-03 15:13:03.112 Updating playState from LTVideoPlayerPlayStateLoading to LTVideoPlayerPlayStatePlaying
2018-07-03 15:13:03.117 [cplayer] v: playback restart complete
2018-07-03 15:13:03.131 [ffmpeg/video] warn: h264: Increasing reorder buffer to 3


#9

This means the HDHR stopped sending video data all of a sudden. Could be either a tuner issue or something happening on the network.

Are the HDHR and Apple TV plugged into the same switch now or different switches?


#10

Hmm…

I’m using 2 Netgear Orbi with ethernet backhaul.

In case it was those, I put a switch at each end, and just had a single ethernet cable from each Orbi to the switch instead.

Everything else on the Apple TV plays just fine.

Recordings from the Channels DVR play just fine too - however the tuner and the DVR are on the same switch.

Nothing else appears to be affected on the network, so it’s a bit strange.

Think I’ll fire up Plex DVR and try via that and see how I get on.


#11

Plex transcodes all content at the server. If you want to do that with the DVR you can enable the transcoding option under Home Quality in Channels, which will make the DVR stream and not the app.

A better direct comparison would be with free apps InstaTV or VLC


#12

It appears to be an issue with Netgear Orbi when in ethernet backhaul mode - at least so far that is what I am leaning towards.

Even with the Orbi units just plugged into the switches it still causes the freezes - as though it is flooding the network or something similar. There were issues previously with ethernet backhaul mode but recent firmware has supposedly fixed those, so I dunno!

I’ll do some more troubleshooting today, but it can take a while for it to happen, so it’s a waiting game!


#13

I’m more baffled now. I tried InstaTV (horrible app!) and it worked just fine.

I’ve just been prompted with a firmware update 20180327 for the HDHomerun which seems odd, since it looks like it is from March and I have checked recently for firmware updates and none were available!

I’ve updated the firmware and back on Channels and it has just frozen again.

When it froze I checked the HDHomerun and none of the tuners were tuned.

HDHomerun log shows this (Apple TV is 192.168.1.111) - any idea?

19700101-00:00:01 System: reset reason = firmware upgrade
19700101-00:00:02 System: network link 100f
19700101-00:00:04 System: ip address obtained: 192.168.1.114 / 255.255.255.0
20180704-12:27:02 System: time changed from Thu Jan 1 00:00:20 1970 to Wed Jul 4 12:27:02 2018
20180704-12:28:47 Tuner: tuner0 streaming udp to 192.168.1.111:2003
20180704-12:29:06 Tuner: tuner0 udp stream ended (remote closed)
20180704-12:29:15 Tuner: tuner3 tuning 102 BBC TWO HD (tt8qam256:738MHz-17472)
20180704-12:29:16 Tuner: tuner3 streaming http to 192.168.1.111:49282
20180704-12:29:16 Tuner: tuner3 lockkey forced release by 192.168.1.111
20180704-12:37:01 Tuner: tuner3 http stream ended (remote closed)


#14

This post is the exact same symptoms that I have and we are running the same version of Channels & tvOS 12.

Of course it could be a tvOS 12 issue, and therefore may get resolved.


#15

Ignore this for now.

I have removed the ethernet backhaul on the Orbi and it has been fine so far - although it means I will need to get another Orbi satellite for full coverage.

I’ll come back if the problem reoccurs, but looks like Netgear Orbi is the culprit at the moment!


#16

Glad you got to the bottom of this!

It looks like from the HDHR Log you posted that InstaTV is using UDP streaming instead of the better/modern HTTP method. So I guess VLC is the best comparison app.

I’ve heard other reports of problems with Orbi but it’s good to know the problem happens specifically with the Ethernet backhaul.


#17

The HDHR log was from using Channels…

I haven’t used InstaTV since I did the firmware update on the HDHomerun - which can also be seen in the log.


#18

The log shows 1) firmware upgrade, 2) UDP stream from tuner0 to the Apple TV, 3) http stream from tuner3 to Apple TV (Channels)


#19

Unless InstaTV was doing something in the background?

After the firmware update, I only used Channels.


#20

Since removing the ethernet backhaul, I have had the tennis on all afternoon and it has been rock solid :slight_smile:

I’ve ordered another Orbi satellite so I can use the 5Ghz backhaul instead. Sigh!