Im a systems engineer for a large IT company in the UK. Im 100% sure I don't have any network issues.
Just to completely rule this out, can you run it from within the VM you are using for the DVR?
2 Likes
I think it may be dropping packets. Why aren't you getting gigabit speeds on a wired connection?
should look something like this:
Apple TV is currently on WiFi and only has 100mb nic built in.
Does it work if you turn off tuner sharing? - nevermind i see this only happens on recordings.
What channel is it?
I haven’t tried it but don’t see it making a difference as the issue is only on recordings and not live TV.
It happens across all channels and even SD recordings as well as HD
If you think it is an issue that arose with a software change, you can try any of the last 5 downloaded versions. On *nix-type os, the older versions are stored in the app dir and there is a symlink called latest. Whatever the latest symlink is set to is what version the DVR will use when the service is stopped and restarted. I don't know what it looks like on Windows, but it is probably similar.
I think it’s a client side issue as when the quality settings are on 8mbps I have no playback issues at all.
Only when home steaming is set to original we start having issues.
Is it OTA? aka: around 15mbps mpeg signals? What mbps is it trying to process at original setting?
maybe it is the same bitrate as original when you set it to 8mbps... especially if you are using a cable connection which is probably a lower bitrate. So it could just be the remux that makes it work.
You can watch the app/player logs via http://x.x.x.x:57000/log using the IP of your Apple TV while the Channels app is running.
From what we saw in your previous diagnostics, the "Cache" entry in the player logs goes up to 140s+ as the player quickly downloads a chunk of the recording. Then it stops receiving data as a fast rate, and slowly the cache runs out. Then the player has to pause and starts sputtering as it struggles to receive new parts of the video file for playback.
I'd also recommend turning on the experimental http logging checkbox on your DVR, and then check out the two logs (on the DVR and for the app/player using the url above) to see if any patterns are apparent.
I hooked up an Apple TV 4 for testing and I'm seeing 417mbps over wifi using the app speedtest, and no playback issues (with the player logs showing "Cache: 95s" steadily).
Quite a lot of this:
2020-02-12 00:23:54.595 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.595 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.596 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.596 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.597 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.604 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.629 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.629 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.629 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.630 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.630 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.633 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.635 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.636 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.637 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.639 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.640 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.640 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.641 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.642 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.642 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.643 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.643 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.647 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.655 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.657 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.657 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.657 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.658 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.658 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.663 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.686 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.687 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.687 [ffmpeg] error: NULL: reference count 1 overflow
2020-02-12 00:23:54.813 [af] v: [userspeed] (disabled)
2020-02-12 00:23:54.813 [af] v: [convert] 48000Hz stereo 2ch floatp
2020-02-12 00:23:54.815 [ao] v: Trying audio driver 'audiounit'
2020-02-12 00:23:54.815 [ao/audiounit] v: requested format: 48000 Hz, stereo channels, floatp
2020-02-12 00:23:54.852 [ao/audiounit] v: using soft-buffer of 9600 samples.
2020-02-12 00:23:54.852 [cplayer] info: AO: [audiounit] 48000Hz stereo 2ch floatp
2020-02-12 00:23:54.852 [cplayer] v: AO: Description: AudioUnit (iOS)
2020-02-12 00:23:54.854 event: audio-reconfig
2020-02-12 00:23:54.855 [af] v: [convert] (disabled)
2020-02-12 00:23:54.855 [af] v: [out] 48000Hz stereo 2ch floatp
2020-02-12 00:23:54.855 [vd] v: DR failed - disabling.
2020-02-12 00:23:54.879 [ffmpeg/video] error: h264: mmco: unref short failure
2020-02-12 00:23:55.156 [ffmpeg/video] error: h264: mmco: unref short failure
2020-02-12 00:23:55.219 [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)
2020-02-12 00:23:55.220 [vf] v: [in] 1920x1080 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
2020-02-12 00:23:55.220 [vf] v: [userdeint] 1920x1080 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
2020-02-12 00:23:55.220 [vf] v: [userdeint] (disabled)
2020-02-12 00:23:55.221 [vf] v: [lavfi] 1920x1080 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
2020-02-12 00:23:55.228 [vf] v: [autorotate] 1920x1080 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
2020-02-12 00:23:55.228 [vf] v: [autorotate] (disabled)
2020-02-12 00:23:55.229 [vf] v: [convert] 1920x1080 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
2020-02-12 00:23:55.229 [vf] v: [convert] (disabled)
2020-02-12 00:23:55.229 event: video-reconfig
2020-02-12 00:28:40.619 mpvstats: AV: 1358.022 A-V: 0.000 Dropped: 20 Cache: 95.02s + 0KB
2020-02-12 00:28:45.618 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2203/playback_time/1363
2020-02-12 00:28:45.619 mpvstats: AV: 1363.022 A-V: 0.000 Dropped: 20 Cache: 95.02s + 0KB
2020-02-12 00:28:50.618 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2203/playback_time/1368
2020-02-12 00:28:50.619 mpvstats: AV: 1368.022 A-V: 0.000 Dropped: 20 Cache: 95.02s + 0KB
2020-02-12 00:28:55.619 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2203/playback_time/1373
2020-02-12 00:28:55.620 mpvstats: AV: 1373.022 A-V: 0.000 Dropped: 20 Cache: 95.02s + 0KB
2020-02-12 00:29:00.618 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2203/playback_time/1378
2020-02-12 00:29:00.619 mpvstats: AV: 1378.022 A-V: 0.000 Dropped: 20 Cache: 95.02s + 0KB
2020-02-12 00:29:05.619 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2203/playback_time/1383
2020-02-12 00:29:05.620 mpvstats: AV: 1383.022 A-V: 0.000 Dropped: 20 Cache: 95.02s + 0KB
2020-02-12 00:29:08.620 [ffmpeg/audio] error: aac_latm: Number of bands (57) exceeds limit (40).
2020-02-12 00:29:08.620 [ad] error: Error decoding audio.
2020-02-12 00:29:08.621 [ad] error: Error decoding audio.
2020-02-12 00:29:08.621 [ad] error: Error decoding audio.
2020-02-12 00:29:08.621 [ad] warn: Invalid audio PTS: 1386.282667 -> 1387.050667
2020-02-12 00:29:08.628 [cplayer] warn:
2020-02-12 00:29:08.628 [cplayer] warn: Audio/Video desynchronisation detected! Possible reasons include too slow
2020-02-12 00:29:08.628 [cplayer] warn: hardware, temporary CPU spikes, broken drivers, and broken files. Audio
2020-02-12 00:29:08.628 [cplayer] warn: position will not match to the video (see A-V status field).
2020-02-12 00:29:08.629 [cplayer] warn:
2020-02-12 00:29:09.205 [ffmpeg/video] v: h264: concealing 5709 DC, 5709 AC, 5709 MV errors in I frame
2020-02-12 00:29:09.236 [ffmpeg/video] error: h264: co located POCs unavailable
2020-02-12 00:29:09.907 [ffmpeg/video] error: h264: mmco: unref short failure
2020-02-12 00:29:10.229 [ffmpeg/video] error: h264: mmco: unref short failure
2020-02-12 00:29:10.617 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2203/playback_time/1388
2020-02-12 00:29:10.619 mpvstats: AV: 1388.642 A-V: 0.178 Dropped: 42 Cache: 95.02s + 0KB
2020-02-12 00:29:15.618 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2203/playback_time/1393
2020-02-12 00:29:15.619 mpvstats: AV: 1393.822 A-V: 0.000 Dropped: 51 Cache: 95.02s + 0KB
2020-02-12 00:29:20.617 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2203/playback_time/1398
2020-02-12 00:29:20.618 mpvstats: AV: 1398.822 A-V: 0.000 Dropped: 51 Cache: 95.02s + 0KB
2020-02-12 00:29:25.614 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2203/playback_time/1403
2020-02-12 00:29:25.615 mpvstats: AV: 1403.822 A-V: 0.000 Dropped: 51 Cache: 95.02s + 0KB
These are normal at the beginning of a recording.
This is a blip in your aerial signal. Mostly harmless.
This is the value to watch. It will print to the log every 5 seconds. If it starts dipping from 95s it means there's no data being received from the DVR. You could check your network stats on the VM or hypervisor when that occurs too, as well as see if the DVR log shows any errors and if http requests are coming in and being printed to the log from the IP of the Apple TV.
Ill keep a eye on it and let you know if I see anything.
This just happened:
2020-02-12 00:46:39.152 mpvstats: AV: 2454.343 A-V: 0.000 Dropped: 0 Cache: 95.02s + 0KB
2020-02-12 00:46:41.311 jsonpipe failed with Error Domain=NSURLErrorDomain Code=-1005 "The network connection was lost." UserInfo={_kCFStreamErrorCodeKey=54, NSUnderlyingError=0x2807d3570 {Error Domain=kCFErrorDomainCFNetwork Code=-1005 "(null)" UserInfo={NSErrorPeerAddressKey=<CFData 0x282b12ee0 [0x1b7af43f0]>{length = 16, capacity = 16, bytes = 0x10021f99ac1e00fb0000000000000000}, _kCFStreamErrorCodeKey=54, _kCFStreamErrorDomainKey=1}}, _NSURLErrorFailingURLSessionTaskErrorKey=LocalDataTask <825AFF96-3145-4DDC-8DE3-C052879B90D3>.<2>, _NSURLErrorRelatedURLSessionTaskErrorKey=(
"LocalDataTask <825AFF96-3145-4DDC-8DE3-C052879B90D3>.<2>"
), NSLocalizedDescription=The network connection was lost., NSErrorFailingURLStringKey=http://172.30.0.251:8089/dvr/events/subscribe, NSErrorFailingURLKey=http://172.30.0.251:8089/dvr/events/subscribe, _kCFStreamErrorDomainKey=1}
2020-02-12 00:46:41.380 jsonpipe will reconnect in 1.000000s
2020-02-12 00:46:42.527 jsonpipe failed with Error Domain=NSURLErrorDomain Code=-1004 "Could not connect to the server." UserInfo={_kCFStreamErrorCodeKey=61, NSUnderlyingError=0x28041cf00 {Error Domain=kCFErrorDomainCFNetwork Code=-1004 "(null)" UserInfo={_kCFStreamErrorCodeKey=61, _kCFStreamErrorDomainKey=1}}, _NSURLErrorFailingURLSessionTaskErrorKey=LocalDataTask .<3>, _NSURLErrorRelatedURLSessionTaskErrorKey=(
"LocalDataTask .<3>"
), NSLocalizedDescription=Could not connect to the server., NSErrorFailingURLStringKey=http://172.30.0.251:8089/dvr/events/subscribe, NSErrorFailingURLKey=http://172.30.0.251:8089/dvr/events/subscribe, _kCFStreamErrorDomainKey=1}
2020-02-12 00:46:42.588 jsonpipe will reconnect in 2.000000s
2020-02-12 00:46:44.146 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2205/playback_time/2459
2020-02-12 00:46:44.149 mpvstats: AV: 2459.343 A-V: 0.000 Dropped: 0 Cache: 95.02s + 0KB
2020-02-12 00:46:44.183 LTHTTPClient: requestWithURL: error: url=http://172.30.0.251:8089/dvr/files/2205/playback_time/2459 error=Error Domain=NSURLErrorDomain Code=-1004 "Could not connect to the server." UserInfo={_kCFStreamErrorCodeKey=61, NSUnderlyingError=0x2807dcae0 {Error Domain=kCFErrorDomainCFNetwork Code=-1004 "(null)" UserInfo={_kCFStreamErrorCodeKey=61, _kCFStreamErrorDomainKey=1}}, _NSURLErrorFailingURLSessionTaskErrorKey=LocalDataTask <383A4A83-0282-492D-A626-803B33D8F301>.<4574>, _NSURLErrorRelatedURLSessionTaskErrorKey=(
"LocalDataTask <383A4A83-0282-492D-A626-803B33D8F301>.<4574>"
), NSLocalizedDescription=Could not connect to the server., NSErrorFailingURLStringKey=http://172.30.0.251:8089/dvr/files/2205/playback_time/2459, NSErrorFailingURLKey=http://172.30.0.251:8089/dvr/files/2205/playback_time/2459, _kCFStreamErrorDomainKey=1} response=(null) body=(null)
2020-02-12 00:46:44.787 jsonpipe failed with Error Domain=NSURLErrorDomain Code=-1004 "Could not connect to the server." UserInfo={_kCFStreamErrorCodeKey=61, NSUnderlyingError=0x28041c450 {Error Domain=kCFErrorDomainCFNetwork Code=-1004 "(null)" UserInfo={_kCFStreamErrorCodeKey=61, _kCFStreamErrorDomainKey=1}}, _NSURLErrorFailingURLSessionTaskErrorKey=LocalDataTask .<4>, _NSURLErrorRelatedURLSessionTaskErrorKey=(
"LocalDataTask .<4>"
), NSLocalizedDescription=Could not connect to the server., NSErrorFailingURLStringKey=http://172.30.0.251:8089/dvr/events/subscribe, NSErrorFailingURLKey=http://172.30.0.251:8089/dvr/events/subscribe, _kCFStreamErrorDomainKey=1}
2020-02-12 00:46:44.812 jsonpipe will reconnect in 4.000000s
2020-02-12 00:46:49.151 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2205/playback_time/2464
2020-02-12 00:46:49.153 mpvstats: AV: 2464.343 A-V: 0.000 Dropped: 0 Cache: 95.02s + 0KB
2020-02-12 00:46:50.849 [ffmpeg] warn: http: Will reconnect at 631684522 in 0 second(s), error=Connection reset by peer.
2020-02-12 00:46:54.150 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2205/playback_time/2469
2020-02-12 00:46:54.153 mpvstats: AV: 2469.343 A-V: 0.000 Dropped: 0 Cache: 95.02s + 0KB
2020-02-12 00:46:59.149 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2205/playback_time/2474
2020-02-12 00:46:59.151 mpvstats: AV: 2474.363 A-V: 0.000 Dropped: 0 Cache: 95.02s + 0KB
2020-02-12 00:47:04.148 LTHTTPClient:
These are all error messages coming from tvOS saying that the network connection is not working. Maybe setup a ping loop from a third machine to both the DVR IP and the Apple TV IP and see if there are any drops?
Well I've just had the issue occur and this is the log from the Apple TV. I'm going to look through the server log now:
2020-02-12 01:01:02.112 mpvstats: AV: 3633.803 A-V: 0.000 Dropped: 0 Cache: 12.00s + 0KB
2020-02-12 01:01:07.109 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2205/playback_time/3638
2020-02-12 01:01:07.111 mpvstats: AV: 3638.803 A-V: 0.000 Dropped: 0 Cache: 9.89s + 0KB
2020-02-12 01:01:12.108 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2205/playback_time/3643
2020-02-12 01:01:12.110 mpvstats: AV: 3643.803 A-V: 0.000 Dropped: 0 Cache: 8.35s + 0KB
2020-02-12 01:01:17.095 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2205/playback_time/3648
2020-02-12 01:01:17.096 mpvstats: AV: 3648.803 A-V: 0.000 Dropped: 0 Cache: 7.54s + 0KB
2020-02-12 01:01:22.109 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2205/playback_time/3653
2020-02-12 01:01:22.112 mpvstats: AV: 3653.803 A-V: 0.000 Dropped: 0 Cache: 6.58s + 0KB
2020-02-12 01:01:27.111 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2205/playback_time/3658
2020-02-12 01:01:27.113 mpvstats: AV: 3658.803 A-V: 0.000 Dropped: 0 Cache: 7.46s + 0KB
2020-02-12 01:01:32.110 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2205/playback_time/3663
2020-02-12 01:01:32.112 mpvstats: AV: 3663.803 A-V: 0.000 Dropped: 0 Cache: 7.51s + 0KB
2020-02-12 01:01:37.108 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2205/playback_time/3668
2020-02-12 01:01:37.111 mpvstats: AV: 3668.803 A-V: 0.000 Dropped: 0 Cache: 4.82s + 0KB
2020-02-12 01:01:42.110 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2205/playback_time/3673
2020-02-12 01:01:42.113 mpvstats: AV: 3673.803 A-V: 0.000 Dropped: 0 Cache: 2.40s + 0KB
2020-02-12 01:01:44.865 [ffmpeg/video] error: mpeg2video: ac-tex damaged at 29 32
2020-02-12 01:01:44.866 [ffmpeg/video] error: mpeg2video: invalid cbp -1 at 2 35
2020-02-12 01:01:44.867 [ffmpeg/video] error: mpeg2video: end mismatch left=85650 18346D at 0 36
2020-02-12 01:01:44.868 [ffmpeg/video] error: mpeg2video: Warning MVs not available
2020-02-12 01:01:44.869 [ffmpeg/video] v: mpeg2video: concealing 180 DC, 180 AC, 180 MV errors in B frame
2020-02-12 01:01:47.108 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2205/playback_time/3678
2020-02-12 01:01:47.111 mpvstats: AV: 3678.803 A-V: 0.000 Dropped: 0 Cache: 0.26s + 0KB
2020-02-12 01:01:52.108 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2205/playback_time/3681
2020-02-12 01:01:52.111 mpvstats: AV: 3681.963 A-V: 0.000 Dropped: 0 Cache: 0.05s + 0KB
2020-02-12 01:01:57.108 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2205/playback_time/3684
2020-02-12 01:01:57.110 mpvstats: AV: 3684.603 A-V: 0.000 Dropped: 0 Cache: 0.00s + 0KB
2020-02-12 01:02:02.107 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2205/playback_time/3686
2020-02-12 01:02:02.110 mpvstats: AV: 3686.843 A-V: 0.001 Dropped: 0 Cache: 0.07s + 0KB
2020-02-12 01:02:07.111 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2205/playback_time/3689
2020-02-12 01:02:07.114 mpvstats: AV: 3689.363 A-V: 0.000 Dropped: 0 Cache: 0.00s + 0KB
2020-02-12 01:02:12.104 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2205/playback_time/3692
2020-02-12 01:02:12.105 mpvstats: AV: 3692.003 A-V: 0.000 Dropped: 0 Cache: 0.00s + 0KB
2020-02-12 01:02:17.107 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2205/playback_time/3694
2020-02-12 01:02:17.109 mpvstats: AV: 3694.343 A-V: 0.000 Dropped: 0 Cache: 0.05s + 0KB
2020-02-12 01:02:22.108 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2205/playback_time/3696
2020-02-12 01:02:22.110 mpvstats: AV: 3696.803 A-V: 0.000 Dropped: 0 Cache: 0.00s + 0KB
2020-02-12 01:02:27.108 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2205/playback_time/3698
2020-02-12 01:02:27.110 mpvstats: AV: 3698.823 A-V: -0.000 Dropped: 0 Cache: 0.00s + 0KB
2020-02-12 01:02:32.106 LTHTTPClient: PUT http://172.30.0.251:8089/dvr/files/2205/playback_time/3701