Lost Connection


#1

I moved our DVR from a Windows laptop to a DS218+ yesterday. The DVR seems to be working fine, but three times now when turning on the family room TV I have seen a black screen with 'Lost Connection' in the middle. Turning everything off and then on again clears it. The ATV was idle for about 4 hours prior to this.

The ATV is connected via MoCa back to an ethernet port on the wifi router and has been operating with no issues for at least a year.

Any thoughts or things to check?

This is from the DVR log:

2019/04/02 11:52:13 [DVR] Cancelling stream 131B881C ch1009 after 6s read timeout
2019/04/02 11:52:13 [TNR] Closed connection to 131B881C for ch1009
2019/04/02 12:03:28 [NAT] Successfully mapped port 8089 using natpmp
2019/04/02 12:47:06 [TNR] Opened connection to 131B881C for ch1009 <-- When i turned it back on

And hereis the log from the AppleTV covering that time period:

2019-04-02 11:22:25.700 Notification: LTGuideDataUpdated
2019-04-02 11:52:09.170 read(32768) = 0 after 5000000
2019-04-02 11:52:13.738 read got (55) No buffer space available
2019-04-02 11:52:13.742 read got (55) No buffer space available
2019-04-02 11:52:13.747 read got (55) No buffer space available
2019-04-02 11:52:13.751 read got (55) No buffer space available
2019-04-02 11:52:13.755 read got (55) No buffer space available
2019-04-02 11:52:13.758 read got (55) No buffer space available
2019-04-02 11:52:13.760 read got (55) No buffer space available
2019-04-02 11:52:13.763 read got (55) No buffer space available
2019-04-02 11:52:13.767 read got (55) No buffer space available
2019-04-02 11:52:13.771 read got (55) No buffer space available
2019-04-02 11:52:13.775 read got (55) No buffer space available
2019-04-02 11:52:13.779 read got (55) No buffer space available
2019-04-02 11:52:13.782 read got (55) No buffer space available
2019-04-02 11:52:13.785 read got (55) No buffer space available
2019-04-02 11:52:13.788 read got (55) No buffer space available
2019-04-02 11:52:13.791 read got (55) No buffer space available
2019-04-02 11:52:13.795 read got (55) No buffer space available
2019-04-02 11:52:13.799 read got (55) No buffer space available
2019-04-02 11:52:13.803 read got (55) No buffer space available
2019-04-02 11:52:13.807 read got (55) No buffer space available
2019-04-02 11:52:13.810 streamer stopping after 17339300 packets and 20 timeouts (302529 waits)
2019-04-02 11:52:13.872 [lavf] v: EOF reached.
2019-04-02 11:52:14.043 [ffmpeg/audio] error: ac3: incomplete frame
2019-04-02 11:52:14.122 [af] v: filter input EOF
2019-04-02 11:52:14.131 [af] v: filter output EOF
2019-04-02 11:52:14.148 [cplayer] v: audio EOF reached
2019-04-02 11:52:14.733 [ffmpeg/video] error: mpeg2video: ac-tex damaged at 49 55
2019-04-02 11:52:14.740 [ffmpeg/video] error: mpeg2video: Warning MVs not available
2019-04-02 11:52:14.747 [ffmpeg/video] v: mpeg2video: concealing 1560 DC, 1560 AC, 1560 MV errors in P frame
2019-04-02 11:52:15.000 [ffmpeg/video] error: mpeg2video: invalid cbp -1 at 67 28
2019-04-02 11:52:15.005 [ffmpeg/video] error: mpeg2video: Warning MVs not available
2019-04-02 11:52:15.015 [ffmpeg/video] v: mpeg2video: concealing 4800 DC, 4800 AC, 4800 MV errors in B frame
2019-04-02 11:52:15.066 [vf] v: filter input EOF
2019-04-02 11:52:15.069 [vf] v: filter output EOF
2019-04-02 11:52:15.099 [cplayer] v: video EOF reached
2019-04-02 11:52:15.102 event: audio-reconfig
2019-04-02 11:52:15.112 event: video-reconfig
2019-04-02 11:52:15.118 event: tracks-changed
2019-04-02 11:52:15.121 event: end-file
2019-04-02 11:52:15.127 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateError
2019-04-02 11:52:15.133 event: audio-reconfig
2019-04-02 11:52:15.135 event: video-reconfig
2019-04-02 11:52:15.139 [cplayer] v: EOF code: 1
2019-04-02 11:52:15.143 [ad] v: Uninit decoder.
2019-04-02 11:52:15.146 [vd] v: Uninit decoder.
2019-04-02 11:52:15.147 [cplayer] v: finished playback, success (reason 0)
2019-04-02 11:52:15.150 [cplayer] info:
2019-04-02 11:52:15.154 [cplayer] v: Set property: aid=1 -> 1
2019-04-02 11:52:15.158 [cplayer] v: Set property: audio=1 -> 1
2019-04-02 11:52:15.160 [cplayer] v: Set property: sid=0 -> 1
2019-04-02 11:52:15.164 [cplayer] v: Set property: sub=0 -> 1
2019-04-02 12:22:26.571 Notification: LTGuideDataUpdated
2019-04-02 12:45:14.965 App will resign active (0)
2019-04-02 12:45:21.136 App did become active (0)
2019-04-02 12:46:55.792 App will resign active (0)
2019-04-02 12:46:55.796 App did enter background (2)
2019-04-02 12:46:55.799 jsonpipe failed with Error Domain=NSURLErrorDomain Code=-999 "cancelled" UserInfo={NSErrorFailingURLStringKey=http://192.168.2.24:8089/dvr/events/subscribe, NSErrorFailingURLKey=http://192.168.2.24:8089/dvr/events/subscribe, _NSURLErrorRelatedURLSessionTaskErrorKey=(
"LocalDataTask .<2>"
), _NSURLErrorFailingURLSessionTaskErrorKey=LocalDataTask .<2>, NSLocalizedDescription=cancelled}
2019-04-02 12:46:55.806 App did enter background (2)
2019-04-02 12:46:55.809 [cplayer] v: Set property: pause=true -> 1
2019-04-02 12:46:55.813 Updating playState from LTVideoPlayerPlayStateError to LTVideoPlayerPlayStateStopped
2019-04-02 12:46:55.819 [cplayer] v: Set property: pause=false -> 1
2019-04-02 12:47:06.228 App will enter foreground (1)
2019-04-02 12:47:06.243 App will enter foreground (1)
2019-04-02 12:47:06.246 App did become active (0)
2019-04-02 12:47:06.249 [cplayer] v: Set property: pause=false -> 1
2019-04-02 12:47:06.252 Updating playState from LTVideoPlayerPlayStateStopped to LTVideoPlayerPlayStateStopped
2019-04-02 12:47:06.256 Updating playState from LTVideoPlayerPlayStateStopped to LTVideoPlayerPlayStateLoading
2019-04-02 12:47:06.260 set streaming buffer to 128 segments (free bytes: 18681643008)
2019-04-02 12:47:06.266 streamer sent request to DVR 192.168.2.24: device 131B881C, channel <HRChannel:0x280b0ebe0 number=1009 name=WGNDT (WGNDT)> [/devices/131B881C/channels/1009/stream.mpg?codec=copy]
2019-04-02 12:47:06.576 Notification: LTGuideDataUpdated
2019-04-02 12:47:06.615 Startup Tab: {
Tab = LTTVOnNowViewController;
}
2019-04-02 12:47:06.621 Device Found: {
DRM = false;
DRMChannels = 0;
DVB = false;
FirmwareUpToDate = true;
FirmwareVersion = 20180817;
FriendlyName = "HDHomeRun PRIME";
Legacy = false;
ModelNumber = "HDHR3-CC";
TunerCount = 3;
}
2019-04-02 12:47:06.627 Device Found: {
DRM = false;
DRMChannels = 0;
DVB = false;
FirmwareUpToDate = true;
FirmwareVersion = 20180817;
FriendlyName = "HDHomeRun PRIME";
Legacy = false;
ModelNumber = "HDHR3-CC";
TunerCount = 3;
}
2019-04-02 12:47:06.656 Found DVR server dvr-captainrondvr.local. @ (
"192.168.2.24:8089",
"[fe80::211:32ff:fea2:8bcb]:8089"
)
2019-04-02 12:47:06.795 event: start-file
2019-04-02 12:47:06.799 Updating playState from LTVideoPlayerPlayStateLoading to LTVideoPlayerPlayStateLoading
2019-04-02 12:47:06.804 [cplayer] info: Playing: cb://1554227226256
2019-04-02 12:47:06.808 [stream_callback] v: Opening cb://1554227226256
2019-04-02 12:47:06.812 [demux] v: Trying demuxers for level=force.
2019-04-02 12:47:07.063 streamer started receiving data
2019-04-02 12:47:07.069 [lavf] v: Found 'mpegts' at score=50 size=2048.
2019-04-02 12:47:07.072 [lavf] v: avformat_open_input() finished after 2048 bytes.
2019-04-02 12:47:07.076 event: tracks-changed
2019-04-02 12:47:07.083 event: tracks-changed
2019-04-02 12:47:07.086 event: tracks-changed
2019-04-02 12:47:07.090 event: metadata-update
2019-04-02 12:47:07.094 event: audio-reconfig
2019-04-02 12:47:07.098 event: audio-reconfig
2019-04-02 12:47:07.102 event: file-loaded
2019-04-02 12:47:07.105 [lavf] v: avformat_find_stream_info() skipped
2019-04-02 12:47:07.108 [demux] v: Detected file format: mpegts (libavformat)
2019-04-02 12:47:07.112 [cplayer] v: Opening done: cb://1554227226256
2019-04-02 12:47:07.116 [lavf] v: select track 0
2019-04-02 12:47:07.119 [lavf] v: select track 1
2019-04-02 12:47:07.124 [cplayer] info: (+) Video --vid=1 (mpeg2video)
2019-04-02 12:47:07.127 [cplayer] info: (+) Audio --aid=1 --alang=eng (ac3)
2019-04-02 12:47:07.129 [cplayer] info: Audio --aid=2 --alang=spa (ac3)
2019-04-02 12:47:07.132 [vd] v: Container reported FPS: 0.000000
2019-04-02 12:47:07.135 [vd] v: Codec list:
2019-04-02 12:47:07.139 [vd] v: mpeg2video - MPEG-2 video
2019-04-02 12:47:07.143 [vd] v: mpegvideo (mpeg2video) - MPEG-1 video
2019-04-02 12:47:07.147 [vd] v: Opening decoder mpeg2video
2019-04-02 12:47:07.151 [vd] v: Not trying to use hardware decoding: codec mpeg2video is not on whitelist.
2019-04-02 12:47:07.154 [vd] v: Using software decoding.
2019-04-02 12:47:07.158 [vd] v: Detected 3 logical cores.
2019-04-02 12:47:07.161 [vd] v: Requesting 4 threads for decoding.
2019-04-02 12:47:07.165 [vd] v: Selected codec: mpeg2video (MPEG-2 video)
2019-04-02 12:47:07.169 [vf] v: User filter list:
2019-04-02 12:47:07.173 [vf] v: lavfi (lavfi.00)
2019-04-02 12:47:07.178 [ad] v: Codec list:
2019-04-02 12:47:07.182 [ad] v: ac3 - ATSC A/52A (AC-3)
2019-04-02 12:47:07.185 [ad] v: ac3_fixed (ac3) - ATSC A/52A (AC-3)
2019-04-02 12:47:07.189 [ad] v: ac3_at (ac3) - ac3 (AudioToolbox)
2019-04-02 12:47:07.192 [ad] v: Opening decoder ac3
2019-04-02 12:47:07.196 [ad] v: Requesting 1 threads for decoding.
2019-04-02 12:47:07.200 [ad] v: Selected codec: ac3 (ATSC A/52A (AC-3))
2019-04-02 12:47:07.204 [af] v: User filter list:
2019-04-02 12:47:07.208 [af] v: (empty)
2019-04-02 12:47:07.212 [cplayer] v: Starting playback...
2019-04-02 12:47:07.216 [vd] warn: Error while decoding frame (-1094995529)!
2019-04-02 12:47:07.220 [vd] warn: Error while decoding frame (-1094995529)!
2019-04-02 12:47:07.229 [vd] warn: Error while decoding frame (-1094995529)!
2019-04-02 12:47:07.232 [vd] warn: Error while decoding frame (-1094995529)!
2019-04-02 12:47:07.235 [vd] warn: Error while decoding frame (-1094995529)!
2019-04-02 12:47:07.239 [vd] warn: Error while decoding frame (-1094995529)!
2019-04-02 12:47:07.301 [af] v: [in] 48000Hz 5.1(side) 6ch floatp
2019-04-02 12:47:07.306 [af] v: [userspeed] 48000Hz 5.1(side) 6ch floatp
2019-04-02 12:47:07.309 [af] v: [userspeed] (disabled)
2019-04-02 12:47:07.313 event: audio-reconfig
2019-04-02 12:47:07.317 [af] v: [convert] 48000Hz 5.1(side) 6ch floatp
2019-04-02 12:47:07.321 [ao] v: Trying audio driver 'audiounit'
2019-04-02 12:47:07.325 [ao/audiounit] v: requested format: 48000 Hz, 5.1(side) channels, floatp
2019-04-02 12:47:07.329 [ao/audiounit] v: using soft-buffer of 9600 samples.
2019-04-02 12:47:07.333 [cplayer] info: AO: [audiounit] 48000Hz stereo 2ch floatp
2019-04-02 12:47:07.337 [cplayer] v: AO: Description: AudioUnit (iOS)
2019-04-02 12:47:07.341 [autoconvert] v: inserting resampler
2019-04-02 12:47:07.344 [swresample] v: format change, reinitializing resampler
2019-04-02 12:47:07.347 [swresample] v: 48000Hz 5.1(side) floatp -> 48000Hz stereo floatp
2019-04-02 12:47:07.351 [swresample] v: Remix: 5.1(side) -> stereo
2019-04-02 12:47:07.355 [af] v: [out] 48000Hz stereo 2ch floatp
2019-04-02 12:47:07.412 [vd] warn: Error while decoding frame (-1094995529)!
2019-04-02 12:47:07.415 [vd] v: DR failed - disabling.
2019-04-02 12:47:07.468 [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)
2019-04-02 12:47:07.470 [vf] v: [in] 1920x1080 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
2019-04-02 12:47:07.474 [vf] v: [userdeint] 1920x1080 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
2019-04-02 12:47:07.477 event: video-reconfig
2019-04-02 12:47:07.481 event: video-reconfig
2019-04-02 12:47:07.485 event: tracks-changed
2019-04-02 12:47:07.487 [vf] v: [userdeint] (disabled)
2019-04-02 12:47:07.491 [vf] v: [lavfi] 1920x1080 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
2019-04-02 12:47:07.494 [vf] v: [autorotate] 1920x1080 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
2019-04-02 12:47:07.497 [vf] v: [autorotate] (disabled)
2019-04-02 12:47:07.498 [vf] v: [convert] 1920x1080 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
2019-04-02 12:47:07.501 [vf] v: [convert] (disabled)
2019-04-02 12:47:07.505 [vf] v: [out] 1920x1080 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
2019-04-02 12:47:07.509 [cplayer] info: VO: [libmpv] 1920x1080 yuv420p
2019-04-02 12:47:07.511 [cplayer] v: VO: Description: render API for libmpv
2019-04-02 12:47:07.515 [vo/libmpv] v: reconfig to 1920x1080 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
2019-04-02 12:47:07.518 [cplayer] v: first video frame after restart shown
2019-04-02 12:47:07.521 [cplayer] info: (+) Video --vid=1 (mpeg2video)
2019-04-02 12:47:07.522 [cplayer] info: (+) Audio --aid=1 --alang=eng (ac3)
2019-04-02 12:47:07.525 [cplayer] info: Audio --aid=2 --alang=spa (ac3)
2019-04-02 12:47:07.529 [cplayer] info: Subs --sid=1 (*) (eia_608)
2019-04-02 12:47:08.392 [cplayer] v: starting audio playback
2019-04-02 12:47:08.395 event: playback-restart
2019-04-02 12:47:08.398 Updating playState from LTVideoPlayerPlayStateLoading to LTVideoPlayerPlayStatePlaying
2019-04-02 12:47:08.402 [cplayer] v: playback restart complete
2019-04-02 13:02:23.619 read got (9) Bad file descriptor
2019-04-02 13:02:23.623 [cplayer] v: Set property: pause=false -> 1


#2

try restarting the ATV from the settings, system menu


#3

You're using tuner sharing so the dvr is what's connecting to the HDHR. It's apparently not a stable connection because it stops receiving data for 6 seconds and disconnects.

What is the network path between the HDHR and dvr NAS? Is there moca there as well? I would double check the cables and try to reduce the number of hops by plugging both devices into the same switch


#4

They are both connected to the switch built into the WiFi’s router. The DS218+ is actually connected to the same cable that the laptop that was running the DVR was connected to, so none of that has changed. I disconnected the cable from the laptop and connected it to the DS218+.

As far as I can tell, this hasn’t affected any recordings. Since switching the DVR ther ehave only been a few recordings, so I can check them out, I guess.


#5

Sounds crazy, but the ATV restart that I suggested above fixes this exact issue in some circumstances.

EDIT: It fixed a similar issue that I had once with a wired ATV and wired synology connected to the same switch and using tuner sharing. I didn't know why I was getting the connection error. Restarted ATV. No more errors.


#6

I restarted it earlier, so we’ll see. I figured it couldn’t hurt :smile:

Thanks!


#7

Restarting the ATV didn't stop this issue. It happened once overnight (01:03:42) and once while I was watching live TV this morning (06:40:06). When it happened while I was watching the picture froze for a couple of seconds and then the black screen with Connection Lost came up. (DVR logs below).

Some questions:

  1. I don't recall this happening with the laptop-based DVR. What would be different with the DS218+? I looked at the logs on the DS128+ and didn't see any errors on there.

  2. Also, what is displaying the Connection Lost message? I suspect that it is the TV (Samsung), but if it is, why would it show lost connection?

  3. What impact would turning off tuner sharing have? I have 2 HDHR primes, so 6 tuners total, and as far as I can tell the max number of shows recording concurrently is 4, plus a live stream, so 5 tuners in use.

Thanks for helping me figure this out! It is strange that it seems to have popped up after switching out the DVR host.

2019/04/02 23:03:29 [NAT] Successfully mapped port 8089 using natpmp
2019/04/02 23:32:19 [DVR] Commercial detection finished with 6 markers.
2019/04/03 00:03:29 [NAT] Successfully mapped port 8089 using natpmp
2019/04/03 01:03:29 [NAT] Successfully mapped port 8089 using natpmp

2019/04/03 01:03:42 [DVR] Cancelling stream 131B881C ch1009 after 6s read timeout
2019/04/03 01:03:42 [TNR] Closed connection to 131B881C for ch1009

2019/04/03 02:03:29 [NAT] Successfully mapped port 8089 using natpmp
2019/04/03 03:03:29 [NAT] Successfully mapped port 8089 using natpmp
2019/04/03 04:03:29 [NAT] Successfully mapped port 8089 using natpmp
2019/04/03 05:03:29 [NAT] Successfully mapped port 8089 using natpmp
2019/04/03 06:03:29 [NAT] Successfully mapped port 8089 using natpmp

2019/04/03 06:14:49 [TNR] Opened connection to 131B881C for ch1009
2019/04/03 06:40:06 [DVR] Cancelling stream 131B881C ch1009 after 6s read timeout
2019/04/03 06:40:06 [TNR] Closed connection to 131B881C for ch1009
2019/04/03 06:40:35 [TNR] Opened connection to 131B881C for ch1009

2019/04/03 07:03:29 [NAT] Successfully mapped port 8089 using natpmp
2019/04/03 07:59:30 [DVR] Starting job 1554296370-ch1185 Father Knows Best on ch=[1185]
2019/04/03 07:59:30 [DVR] Waiting 29m59.953484703s until next job 1554298170-ch1185 Father Knows Best
2019/04/03 07:59:30 [TNR] Opened connection to 13276CF3 for ch1185
2019/04/03 07:59:38 [DVR] Recording for job 1554296370-ch1185 from 13276CF3 ch1185 into "TV/Father Knows Best/Father Knows Best S03E17 1957-01-02 Margaret Hires a Gardener 2019-04-03-0759.mpg" for 30m59.953377273s
2019/04/03 08:03:29 [NAT] Successfully mapped port 8089 using natpmp


#8

There is no difference. The DS218+ is the most popular NAS among Channels DVR users. There are hundreds in use with issue.

The dvr is losing its connection to the HDHR, and so it stops sending video to the tv and then the tv shows the message.

Two TVs watching the same show would use two timers instead of one.

With tuner sharing off the tv will connect directly to the HDHR which may or may not affect the issue you're having.

Like I mentioned before this is almost always a network issue. Maybe the cable didn't get plugged in correctly? If you have a cheap gigabit switch you can use it will likely perform better than the switch built into your router.

The DS218+ has multiple Ethernet ports iirc. Are you using one or both?


#9

Understood, but this didn't happen with the laptop, and is now, so something has changed, and using the DS218+ is the only difference. What can I look at to troubleshoot?

Makes sense, but since the ATV is actually connected to the TV I wasn't sure.

[quote="tmm1, post:8, topic:15304"]Two TVs watching the same show would use two timers instead of one.

With tuner sharing off the tv will connect directly to the HDHR which may or may not affect the issue you're having.
[/quote]

OK. I may try that if nothing else works. We rarely watch two TVs at the same time. It is typically the DVR and one TV and it looks like we have enough tuners.

Like I mentioned before this is almost always a network issue. Maybe the cable didn't get plugged in correctly? If you have a cheap gigabit switch you can use it will likely perform better than the switch built into your router.

The DS218+ has multiple Ethernet ports iirc. Are you using one or both?

Again, understood, and I am not denying that it may be a network issue. I am at a loss to explain why this has started since switching to the DS218+, that's all. I doubt that is it a Channels issue, but since the Channels DVR is all that is running on the DS right now I am hoping that you can help me out. As I mentioned, the cables and switch are the same as before, so if one of them was causing the problem, what is different with the DS over the laptop?

As far as multiple ethernet ports, I only see one.


#10

One other thing :slight_smile:

Based on the DVR log, the issue is between the DVR and the HDHR primes, correct?


#11

Just an update...

It has been about 36 hours since the last occurrence. The only change that I made was to disable hibernation on the DS218+ after reading a couple of comments here and on the Synology forum. I didn't see any instances of the drives hibernating in the DS log, but I thought that i would give it a try.


#12

I would attach the DS218+, HDHomeRun and ATV to a separate gigabit switch to verify.
Also unless your MOCA adapter is v2 it runs at 100mbps.

Could also be related to the new DSM version if you have that installed.
Version: 6.2.2-24922 (2019-03-28)
Fixed Issues
-Enhanced vulnerabilities protection from KPTI to Spectre and Meltdown Protection for improved security. Applied models:
18-Series : DS218+, DS418play, DS718+, DS918+, DS1618+, DS3018xs, RS2418+, RS2418RP+, RS2818RP+, FS1018
19-Series : DS1019+, DS1819+, DS2419+, RS1619xs+

On my DS1019+ after installing that update and rebooting, my LAN1 negotiated 100 mbps instead of 1 gbps. I disconnected and reconnected the cat6 network cable and it's been fine since.


#13

Thanks... Adding some comments inline below...

I appreciate the thoughts. Everything ran fine overnight, so I'm at a loss to explain the issue and why it hasn't occurred again. The biggest question for me is why it happened at all? I unplugged the network cable from the laptop and plugged it into the DS218+. No other changes. Aside from a couple of issues with the laptop not recovering after a power outage, the laptop based DVR ran for over a year. I have no idea why the switch to the DS218+ made a difference.