Just to make sure I understand the situation: If you leave the player for a long enough time it will start playing again. It doesn’t stop forever.
Is that accurate?
If it isn't forever, is there any sort of consistency to how long it takes to start playing again?
Yes mostly. Usually it's a series of buffering events within 5 minutes total time and usually add up to 2½ minutes on the time bar. I have had it stop being and stay frozen. I had to back out and good back in but that's rare.
Sometimes it's an hour or so between buffering events or sometimes it happens a few times in an hour.
If you watch the video I posted earlier you can see what happens.
@eric @tmm1
Did you guys change anything in the latest server? I'm on 20200402 and I have been watching Fox News for 3 hours with zero issues!
Nope
Awesome, guess I got lucky.
@tmm1
Here is a new log for you on the newest beta release with improved diagnostic logs info....
Problem is that this one failed to keep playing after all the buffering. Ended up with a frozen screen and had to back out.
04-06 00:34:57.203 9785 9785 V mpvstats: AV: 1978.198 A-V: 0.000 Dropped: 4 Cache: 11.648s + 0KB
04-06 00:35:00.205 9785 9785 V mpvstats: AV: 1981.201 A-V: 0.000 Dropped: 4 Cache: 8.661s + 0KB
04-06 00:35:03.205 9785 9785 V mpvstats: AV: 1984.204 A-V: 0.000 Dropped: 4 Cache: 5.675s + 0KB
04-06 00:35:06.205 9785 9785 V mpvstats: AV: 1987.207 A-V: 0.000 Dropped: 4 Cache: 2.603s + 0KB
04-06 00:35:08.832 9785 9834 V mpv : event: unpause
04-06 00:35:08.832 9785 9834 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 50%) [0.500500s].
04-06 00:35:08.833 9785 9834 V mpv : property: buffering = true
04-06 00:35:08.833 9785 9785 V PlayerActivity: state PLAYING -> BUFFERING
04-06 00:35:08.834 9785 9785 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=1962.3322221111112, end=1988.975511}], cache-end=1990.4102887777779, reader-pts=1989.9097887777777, cache-duration=0.5005000000001019, eof=false, underrun=true, idle=false, total-bytes=30942208, fw-bytes=567040, debug-low-level-seeks=0, debug-ts-last=1989.8597223333334, ts-per-stream=[{type=video, duration=0.5005000000001019, reader=1989.9264777777778, end=1990.426977777778}, {type=audio, duration=0.0, reader=1990.4186444444445, end=1990.4186444444445}]}
04-06 00:35:09.205 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.501s + 0KB
04-06 00:35:12.206 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.501s + 0KB
04-06 00:35:15.207 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.501s + 0KB
04-06 00:35:18.208 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.501s + 0KB
04-06 00:35:21.209 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.501s + 0KB
04-06 00:35:24.210 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.501s + 0KB
04-06 00:35:27.211 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.501s + 0KB
04-06 00:35:28.922 9785 14844 V ApiServer: REQUEST: GET /log
04-06 00:35:30.212 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.501s + 0KB
04-06 00:35:33.213 9785 9785 I chatty : uid=10149(com.getchannels.dvr.app) identical 1 line
04-06 00:35:36.213 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.501s + 0KB
04-06 00:35:39.065 9785 14505 V Streamer: mpv read bytes:0 after retries:32000 (pos:1601536000)
04-06 00:35:39.214 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.501s + 0KB
04-06 00:35:42.214 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.501s + 0KB
04-06 00:35:45.216 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.501s + 0KB
04-06 00:35:48.216 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.501s + 0KB
04-06 00:35:51.216 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.501s + 0KB
04-06 00:35:54.217 9785 9785 I chatty : uid=10149(com.getchannels.dvr.app) identical 1 line
04-06 00:35:57.218 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.501s + 0KB
04-06 00:36:00.219 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.501s + 0KB
04-06 00:36:03.220 9785 9785 I chatty : uid=10149(com.getchannels.dvr.app) identical 1 line
04-06 00:36:06.220 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.501s + 0KB
04-06 00:36:09.221 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.501s + 0KB
04-06 00:36:11.479 9785 14505 V Streamer: mpv read bytes:0 after retries:32000 (pos:1601536000)
04-06 00:36:12.222 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.517s + 0KB
04-06 00:36:15.223 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.517s + 0KB
04-06 00:36:18.224 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.517s + 0KB
04-06 00:36:21.225 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.517s + 0KB
04-06 00:36:24.226 9785 9785 I chatty : uid=10149(com.getchannels.dvr.app) identical 1 line
04-06 00:36:27.227 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.517s + 0KB
04-06 00:36:30.228 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.517s + 0KB
04-06 00:36:33.229 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.517s + 0KB
04-06 00:36:36.230 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.517s + 0KB
04-06 00:36:39.231 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.517s + 0KB
04-06 00:36:42.232 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.517s + 0KB
04-06 00:36:43.902 9785 14505 V Streamer: mpv read bytes:0 after retries:32000 (pos:1601536000)
04-06 00:36:45.233 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.043s + 0KB
04-06 00:36:48.234 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.043s + 0KB
04-06 00:36:51.235 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.043s + 0KB
04-06 00:36:54.237 9785 9785 I chatty : uid=10149(com.getchannels.dvr.app) identical 1 line
04-06 00:36:57.237 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.043s + 0KB
04-06 00:37:00.240 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.043s + 0KB
04-06 00:37:03.241 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.043s + 0KB
04-06 00:37:05.593 9785 14861 V ApiServer: REQUEST: GET /log
04-06 00:37:05.832 9785 9793 W System : A resource failed to call end.
04-06 00:37:06.242 9785 9785 V mpvstats: AV: 1989.843 A-V: 0.000 Dropped: 4 Cache: 0.043s + 0KB
04-06 00:37:06.622 9785 9834 V mpv : [lavf] EOF reached.
04-06 00:37:06.625 9785 9834 V mpv : event: unpause
04-06 00:37:06.625 9785 9834 V mpv : [cplayer] End buffering (waited 117.791124 secs) [0.042667s].
04-06 00:37:06.628 9785 9834 V mpv : property: buffering = false
04-06 00:37:06.629 9785 9785 V PlayerActivity: state BUFFERING -> PLAYING
04-06 00:37:06.629 9785 9834 E mpv : [ffmpeg/audio] aac: decode_band_types: Input buffer exhausted before END element found
04-06 00:37:06.633 9785 9834 E mpv : [ad] Error decoding audio.
04-06 00:37:06.633 9785 9785 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=1962.3322221111112, end=1990.4446221111111}], cache-end=1990.4436443333334, reader-pts=1989.9431443333333, cache-duration=0.5005000000001019, eof=true, underrun=false, idle=true, total-bytes=30966656, fw-bytes=552896, debug-low-level-seeks=0, debug-ts-last=1989.8931001111112, ts-per-stream=[{type=video, duration=0.5005000000001019, reader=1989.9598333333333, end=1990.4603333333334}, {type=audio, duration=0.0, reader=1990.4613111111112, end=1990.4613111111112}]}
04-06 00:37:06.633 9785 9834 V mpv : [af] filter input EOF
04-06 00:37:06.634 9785 9834 V mpv : [af] filter output EOF
04-06 00:37:06.758 9785 9834 V mpv : [cplayer] audio EOF reached
04-06 00:37:06.821 9785 14503 V Streamer: finished
04-06 00:37:07.104 9785 9834 E mpv : [ffmpeg/video] h264: error while decoding MB 41 11, bytestream -11
04-06 00:37:07.105 9785 9834 V mpv : [ffmpeg/video] h264: concealing 2728 DC, 2728 AC, 2728 MV errors in P frame
04-06 00:37:07.185 9785 9834 V mpv : [vf] filter input EOF
04-06 00:37:07.185 9785 9834 V mpv : [vf] filter output EOF
04-06 00:37:07.185 9785 9834 V mpv : [cplayer] using demuxer frame duration for last frame
04-06 00:37:07.185 9785 9834 D mpv : [cplayer] video EOF (status=4)
04-06 00:37:07.215 9785 9834 I chatty : uid=10149(com.getchannels.dvr.app) mpv-events identical 4 lines
04-06 00:37:07.231 9785 9834 D mpv : [cplayer] video EOF (status=4)
04-06 00:37:07.232 9785 9834 D mpv : [cplayer] video EOF (status=4)
04-06 00:37:07.233 9785 9834 V mpv : [cplayer] video EOF reached
04-06 00:37:07.234 9785 9834 D mpv : [cplayer] video EOF (status=5)
04-06 00:37:07.234 9785 9834 V mpv : [cplayer] EOF code: 1
04-06 00:37:07.234 9785 9834 V mpv : [ad] Uninit decoder.
04-06 00:37:07.235 9785 9834 V mpv : event: audio-reconfig
04-06 00:37:07.235 9785 9834 V mpv : [vd] Uninit decoder.
04-06 00:37:07.236 9785 9834 V mpv : event: video-reconfig
04-06 00:37:07.242 9785 9834 V mpv : event: audio-reconfig
04-06 00:37:07.242 9785 9834 D mpv : [cplayer] Terminating demuxers...
04-06 00:37:07.252 9785 9834 D mpv : [cplayer] Done terminating demuxers.
04-06 00:37:07.252 9785 9834 V mpv : event: tracks-changed
04-06 00:37:07.252 9785 9834 V mpv : event: end-file
04-06 00:37:07.253 9785 9834 V mpv : [cplayer] finished playback, success (reason 0)
04-06 00:37:07.253 9785 9834 I mpv : [cplayer]
04-06 00:37:07.253 9785 9785 V PlayerActivity: state PLAYING -> STOPPED
04-06 00:37:07.254 9785 14411 W libEGL : EGLNativeWindowType 0xb4916008 disconnect failed
04-06 00:37:07.255 9785 9834 V mpv : event: video-reconfig
04-06 00:37:07.256 9785 9834 V mpv : event: idle
04-06 00:37:07.256 9785 9834 V mpv : [cplayer] Set property: aid=1 -> 1
04-06 00:37:07.256 9785 9834 V mpv : property: buffering = false
04-06 00:37:07.257 9785 9834 V mpv : property: track-list has 0 entries
04-06 00:37:07.783 9785 9785 V mpvstats: AV: 1990.444 A-V: 0.000 Dropped: 0 Cache: 0.000s + 0KB
04-06 00:37:09.243 9785 9785 V mpvstats: AV: 1990.444 A-V: 0.000 Dropped: 0 Cache: 0.000s + 0KB
04-06 00:37:12.243 9785 9785 V mpvstats: AV: 1990.444 A-V: 0.000 Dropped: 0 Cache: 0.000s + 0KB
04-06 00:37:15.244 9785 9785 V mpvstats: AV: 1990.444 A-V: 0.000 Dropped: 0 Cache: 0.000s + 0KB
04-06 00:37:18.245 9785 9785 V mpvstats: AV: 1990.444 A-V: 0.000 Dropped: 0 Cache: 0.000s + 0KB
04-06 00:37:21.245 9785 9785 V mpvstats: AV: 1990.444 A-V: 0.000 Dropped: 0 Cache: 0.000s + 0KB
04-06 00:37:24.246 9785 9785 V mpvstats: AV: 1990.444 A-V: 0.000 Dropped: 0 Cache: 0.000s + 0KB
04-06 00:37:27.266 9785 9785 V mpvstats: AV: 1990.444 A-V: 0.000 Dropped: 0 Cache: 0.000s + 0KB
04-06 00:37:30.267 9785 9785 V mpvstats: AV: 1990.444 A-V: 0.000 Dropped: 0 Cache: 0.000s + 0KB
04-06 00:37:33.269 9785 9785 V mpvstats: AV: 1990.444 A-V: 0.000 Dropped: 0 Cache: 0.000s + 0KB
04-06 00:37:35.041 9785 9834 V mpv : [cplayer] Set property: pause="no" -> 1
04-06 00:37:36.269 9785 9785 V mpvstats: AV: 1990.444 A-V: 0.000 Dropped: 0 Cache: 0.000s + 0KB
04-06 00:37:38.783 9785 9785 V PlayerActivity: onPause
04-06 00:37:38.810 9785 9785 V OnNowFragment: onResume
04-06 00:37:38.932 9785 9851 D mali_winsys: EGLint new_window_surface(egl_winsys_display *, void *, EGLSurface, EGLConfig, egl_winsys_surface **, EGLBoolean) returns 0x3000
04-06 00:37:38.962 9785 9865 W ExifInterface: Stop reading file since a wrong offset may cause an infinite loop: 0
04-06 00:37:39.196 9785 12774 W ExifInterface: Stop reading file since a wrong offset may cause an infinite loop: 0
04-06 00:37:39.214 9785 9834 D mpv : [cplayer] Run command: stop, flags=64, args=[]
04-06 00:37:39.214 9785 9834 D mpv : [cplayer] Setting option 'wid' = 0 (flags = 64) -> 0
04-06 00:37:39.218 9785 9834 D mpv : [cplayer] Setting option 'mediacodec-embed-osd-surface' = 0 (flags = 64) -> 0
04-06 00:37:39.219 9785 9851 W libEGL : EGLNativeWindowType 0xb56d7008 disconnect failed
04-06 00:37:39.227 9785 9785 V PlayerActivity: onStop
04-06 00:37:39.230 9785 9785 V PlayerActivity: onDestroy
04-06 00:37:39.231 9785 9834 D mpv : [cplayer] Run command: stop, flags=64, args=[]
04-06 00:37:44.565 9785 14881 V ApiServer: REQUEST: GET /log 04-06 23:08:11.535 29639 29771 V Streamer: ch6073 has 1 possible sources
04-06 23:08:11.536 29639 29771 V Streamer: trying TVE-Fubo: http://192.168.5.101:8089/devices/TVE-Fubo/channels/6073/stream.mpg?transcode=none&codec=copy
04-06 23:08:11.537 29639 29771 V Streamer: http socket receiveBufferSize = 1048576
04-06 23:08:11.547 29639 29733 W ExifInterface: Stop reading file since a wrong offset may cause an infinite loop: 0
04-06 23:08:11.584 29639 29639 V PlayerActivity: state STOPPED -> LOADING
04-06 23:08:11.833 29639 29703 W libEGL : EGLNativeWindowType 0xec245008 disconnect failed
04-06 23:08:13.318 29639 29771 V Streamer: started with 2317735252 byte buffer in /data/user/0/com.getchannels.dvr.app/cache/channels-streamer.ts
04-06 23:08:13.321 29639 29771 V Streamer: seek(0) = 0 -> 0
04-06 23:08:13.321 29639 29688 D mpv : [stream_callback] Stream opened successfully.
04-06 23:08:13.322 29639 29688 V mpv : [demux] Trying demuxers for level=force.
04-06 23:08:13.322 29639 29688 D mpv : [demux] Trying demuxer: lavf (force-level: force)
04-06 23:08:13.922 29639 29688 V mpv : [lavf] Found 'mpegts' at score=50 size=2048.
04-06 23:08:13.926 29639 29688 V mpv : [lavf] avformat_open_input() finished after 2048 bytes.
04-06 23:08:13.926 29639 29688 D mpv : [ffmpeg/demuxer] mpegts: Before avformat_find_stream_info() pos: 0 bytes read:2048 seeks:0 nb_streams:3
04-06 23:08:13.940 29639 29688 D mpv : [ffmpeg/demuxer] mpegts: parser not found for codec timed_id3, packets or times may be invalid.
04-06 23:08:13.940 29639 29688 D mpv : [ffmpeg/demuxer] mpegts: parser not found for codec timed_id3, packets or times may be invalid.
04-06 23:08:13.962 29639 29688 D mpv : [ffmpeg/video] h264: Reinit context to 1280x720, pix_fmt: yuv420p
04-06 23:08:14.104 29639 29688 V mpv : [ffmpeg/demuxer] mpegts: Skipping duration calculation in estimate_timings_from_pts
04-06 23:08:14.104 29639 29771 V Streamer: seek(0) = 395264 -> 0
04-06 23:08:14.105 29639 29688 D mpv : [ffmpeg/demuxer] mpegts: After avformat_find_stream_info() pos: 0 bytes read:395264 seeks:1 frames:31
04-06 23:08:14.105 29639 29688 V mpv : [lavf] avformat_find_stream_info() finished after 0 bytes.
04-06 23:08:14.105 29639 29688 V mpv : [demux] Detected file format: mpegts (libavformat)
04-06 23:08:14.106 29639 29688 V mpv : [cplayer] Opening done: hdhr://6073
04-06 23:08:14.107 29639 29688 V mpv : event: tracks-changed
04-06 23:08:14.107 29639 29688 V mpv : event: tracks-changed
04-06 23:08:14.108 29639 29688 V mpv : event: metadata-update
04-06 23:08:14.108 29639 29688 D mpv : [global] config path: 'sub' -/-> '/data/user/0/com.getchannels.dvr.app/files/mpv/sub'
04-06 23:08:14.108 29639 29688 V mpv : [lavf] select track 0
04-06 23:08:14.108 29639 29688 V mpv : [lavf] select track 1
04-06 23:08:14.108 29639 29688 I mpv : [cplayer] (+) Video --vid=1 (h264 1280x720 60.000fps)
04-06 23:08:14.109 29639 29688 I mpv : [cplayer] (+) Audio --aid=1 (aac 2ch 48000Hz 63kbps)
04-06 23:08:14.109 29639 29783 D mali_winsys: EGLint new_window_surface(egl_winsys_display *, void *, EGLSurface, EGLConfig, egl_winsys_surface **, EGLBoolean) returns 0x3000
04-06 23:08:14.118 29639 29688 V mpv : [vd] Container reported FPS: 60.000000
04-06 23:08:14.119 29639 29688 V mpv : [vd] Codec list:
04-06 23:08:14.119 29639 29688 V mpv : [vd] h264 - H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10
04-06 23:08:14.120 29639 29688 V mpv : [vd] h264_mediacodec (h264) - H.264 Android MediaCodec decoder
04-06 23:08:14.120 29639 29688 V mpv : [vd] Opening decoder h264
04-06 23:08:14.120 29639 29688 V mpv : [vd] Looking at hwdec h264_mediacodec-mediacodec-copy...
04-06 23:08:14.120 29639 29688 V mpv : [vd] Trying hardware decoding via h264_mediacodec-mediacodec-copy.
04-06 23:08:14.120 29639 29688 V mpv : [vd] Using underlying hw-decoder 'h264_mediacodec'
04-06 23:08:14.120 29639 29688 D mpv : [ffmpeg] AVBSFContext: The input looks like it is Annex B already
04-06 23:08:14.122 29639 29688 V mpv : [vd] Pixel formats supported by decoder: mediacodec
04-06 23:08:14.122 29639 29688 V mpv : [vd] Codec profile: High (0x64)
04-06 23:08:14.122 29639 29688 V mpv : [vd] Requesting pixfmt 'mediacodec' from decoder.
04-06 23:08:14.122 29639 29688 V mpv : [ffmpeg/video] h264_mediacodec: Using surface 0x0
04-06 23:08:14.126 29639 29687 W AudioCapabilities: Unsupported mime audio/x-adpcm-ima
04-06 23:08:14.132 29639 29687 W AudioCapabilities: Unsupported mime audio/ape
04-06 23:08:14.133 29639 29687 W AudioCapabilities: Unsupported mime audio/vnd.dts
04-06 23:08:14.133 29639 29687 W AudioCapabilities: Unsupported mime audio/vnd.dts.hd;profile=lbr
04-06 23:08:14.134 29639 29687 W AudioCapabilities: Unsupported mime audio/vnd.dts.hd
04-06 23:08:14.144 29639 29687 W AudioCapabilities: Unsupported mime audio/mpeg-L1
04-06 23:08:14.146 29639 29687 W AudioCapabilities: Unsupported mime audio/mpeg-L2
04-06 23:08:14.148 29639 29687 W AudioCapabilities: Unsupported mime audio/x-ms-wma
04-06 23:08:14.149 29639 29687 W AudioCapabilities: Unsupported mime audio/x-ms-wmapro
04-06 23:08:14.157 29639 29687 W VideoCapabilities: Unsupported mime video/dolby-vision
04-06 23:08:14.170 29639 29687 I chatty : uid=10149(com.getchannels.dvr.app) Thread-23 identical 6 lines
04-06 23:08:14.173 29639 29687 W VideoCapabilities: Unsupported mime video/dolby-vision
04-06 23:08:14.184 29639 29687 W VideoCapabilities: Unrecognized profile 4 for video/hevc
04-06 23:08:14.186 29639 29687 W VideoCapabilities: Unsupported mime video/mjpeg
04-06 23:08:14.188 29639 29687 W VideoCapabilities: Unrecognized profile/level 0/3 for video/mpeg2
04-06 23:08:14.188 29639 29687 I VideoCapabilities: Unsupported profile 4 for video/mpeg2
04-06 23:08:14.188 29639 29687 I VideoCapabilities: Unsupported profile 5 for video/mpeg2
04-06 23:08:14.190 29639 29687 W VideoCapabilities: Unrecognized profile/level 0/3 for video/mpeg2
04-06 23:08:14.190 29639 29687 I VideoCapabilities: Unsupported profile 4 for video/mpeg2
04-06 23:08:14.190 29639 29687 I VideoCapabilities: Unsupported profile 5 for video/mpeg2
04-06 23:08:14.193 29639 29687 W VideoCapabilities: Unrecognized profile/level 0/3 for video/mpeg2
04-06 23:08:14.201 29639 29687 W VideoCapabilities: Unsupported mime video/x-vp6
04-06 23:08:14.214 29639 29687 W VideoCapabilities: Unsupported mime video/x-ms-wmv
04-06 23:08:14.222 29639 29687 I VideoCapabilities: Unsupported profile 4 for video/mp4v-es
04-06 23:08:14.256 29639 29687 D MtkACodecPlugin: MtkACodecPlugin createAPlugin
04-06 23:08:14.257 29639 29785 D MtkACodecPlugin: OMX.MTK.VIDEO.DECODER.AVC needRmClient (680)
04-06 23:08:14.258 29639 29785 D MtkACodecPlugin: OMX.MTK.VIDEO.DECODER.AVC mNeedVdpImgrz (686)
04-06 23:08:14.260 29639 29785 I OMXClient: IOmx service obtained
04-06 23:08:14.284 29639 29784 D MtkMediaCodecPlugin: No surfaceTextureClient, [OMX.MTK.VIDEO.DECODER.AVC] set mOutputPath = 1024 L(158)
04-06 23:08:14.296 29639 29785 I ACodec : codec does not support config priority (err -1010)
04-06 23:08:14.347 29639 29688 E mpv : [ffmpeg/video] h264_mediacodec: Output color format 0x7f000103 (value=2130706691) is not supported
04-06 23:08:14.347 29639 29688 E mpv : [ffmpeg/video] h264_mediacodec: Output color format is not supported
04-06 23:08:14.347 29639 29688 E mpv : [ffmpeg/video] h264_mediacodec: Failed to configure context
04-06 23:08:14.347 29639 29688 E mpv : [ffmpeg/video] h264_mediacodec: MediaCodec 0xb844a200 failed to start
04-06 23:08:14.386 29639 29687 D MediaCodec: mState = 0, mHaveKick = 0, L(711)
04-06 23:08:14.389 29639 29687 D MtkACodecPlugin: MtkACodecPlugin destoryAPlugin
04-06 23:08:14.390 29639 29688 E mpv : [vd] Could not open codec.
04-06 23:08:14.390 29639 29688 V mpv : [vd] Falling back to software decoding.
04-06 23:08:14.390 29639 29688 V mpv : [vd] Detected 4 logical cores.
04-06 23:08:14.391 29639 29688 V mpv : [vd] Requesting 5 threads for decoding.
04-06 23:08:14.393 29639 29688 V mpv : event: audio-reconfig
04-06 23:08:14.393 29639 29688 V mpv : [vd] Selected codec: h264 (H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10)
04-06 23:08:14.394 29639 29688 V mpv : [vf] User filter list:
04-06 23:08:14.394 29639 29688 V mpv : [vf] (empty)
04-06 23:08:14.395 29639 29688 V mpv : [ad] Codec list:
04-06 23:08:14.395 29639 29688 V mpv : [ad] aac - AAC (Advanced Audio Coding)
04-06 23:08:14.396 29639 29688 V mpv : event: audio-reconfig
04-06 23:08:14.396 29639 29688 V mpv : event: file-loaded
04-06 23:08:14.397 29639 29688 V mpv : [ad] aac_fixed (aac) - AAC (Advanced Audio Coding)
04-06 23:08:14.397 29639 29688 V mpv : [ad] Opening decoder aac
04-06 23:08:14.397 29639 29688 V mpv : [ad] Requesting 1 threads for decoding.
04-06 23:08:14.397 29639 29688 V mpv : [ad] Selected codec: aac (AAC (Advanced Audio Coding))
04-06 23:08:14.397 29639 29688 V mpv : [af] User filter list:
04-06 23:08:14.398 29639 29688 V mpv : property: buffering = false
04-06 23:08:14.403 29639 29688 V mpv : property: track-list has 2 entries
04-06 23:08:14.404 29639 29639 V PlayerActivity: state LOADING -> LOADED
04-06 23:08:14.416 29639 29687 W AudioTrack: Use of stream types is deprecated for operations other than volume control
04-06 23:08:14.417 29639 29687 W AudioTrack: See the documentation of AudioTrack() for what to use instead with android.media.AudioAttributes to qualify your playback use case
04-06 23:08:14.560 29639 29688 V mpv : event: audio-reconfig
04-06 23:08:14.560 29639 29688 V mpv : event: video-reconfig
04-06 23:08:14.569 29639 29688 V mpv : event: tracks-changed
04-06 23:08:14.570 29639 29688 V mpv : event: video-reconfig
04-06 23:08:14.570 29639 29688 V mpv : [af] (empty)
04-06 23:08:14.570 29639 29688 V mpv : [cplayer] Starting playback...
04-06 23:08:14.570 29639 29639 V mpvstats: AV: 0.000 A-V: 0.000 Dropped: 0 Cache: 7.765s + 0KB
04-06 23:08:14.570 29639 29688 V mpv : [af] [in] 48000Hz stereo 2ch floatp
04-06 23:08:14.570 29639 29688 V mpv : [af] [userspeed] 48000Hz stereo 2ch floatp
04-06 23:08:14.570 29639 29688 V mpv : [af] [userspeed] (disabled)
04-06 23:08:14.570 29639 29688 V mpv : [af] [convert] 48000Hz stereo 2ch floatp
04-06 23:08:14.570 29639 29688 V mpv : [ao] Trying audio driver 'audiotrack'
04-06 23:08:14.570 29639 29688 V mpv : [ao/audiotrack] requested format: 48000 Hz, stereo channels, floatp
04-06 23:08:14.570 29639 29688 V mpv : [ao/audiotrack] AudioTrack.nativeOutputSampleRate = 48000
04-06 23:08:14.570 29639 29688 V mpv : [ao/audiotrack] Setting bufferSize = 28800 (driver=16416, min=19200, max=28800)
04-06 23:08:14.570 29639 29688 V mpv : [ao/audiotrack] device buffer: 14400 samples.
04-06 23:08:14.570 29639 29688 V mpv : [ao/audiotrack] using soft-buffer of 14400 samples.
04-06 23:08:14.570 29639 29688 I mpv : [cplayer] AO: [audiotrack] 48000Hz stereo 2ch s16
04-06 23:08:14.571 29639 29688 V mpv : [cplayer] AO: Description: Android AudioTrack audio output
04-06 23:08:14.571 29639 29688 V mpv : [autoconvert] inserting resampler
04-06 23:08:14.571 29639 29688 V mpv : [swresample] format change, reinitializing resampler
04-06 23:08:14.571 29639 29688 V mpv : [swresample] 48000Hz stereo floatp -> 48000Hz stereo s16
04-06 23:08:14.571 29639 29688 V mpv : [af] [out] 48000Hz stereo 2ch s16
04-06 23:08:14.571 29639 29688 D mpv : [ffmpeg/video] h264: Reinit context to 1280x720, pix_fmt: yuv420p
04-06 23:08:14.571 29639 29688 D mpv : [vd] DR parameter change to 1280x738 yuv420p align=16
04-06 23:08:14.571 29639 29688 D mpv : [vd] Allocating new DR image...
04-06 23:08:14.571 29639 29688 D mpv : [vd] ...failed..
04-06 23:08:14.571 29639 29688 V mpv : [vd] DR failed - disabling.
04-06 23:08:14.571 29639 29688 V mpv : [vd] Using software decoding.
04-06 23:08:14.571 29639 29688 V mpv : [vd] Decoder format: 1280x720 yuv420p auto/auto/auto/auto/auto CL=mpeg2/4/h264 (auto 0.000000/0.000000/0.000000)
04-06 23:08:14.571 29639 29688 V mpv : [vd] Forcing user-set aspect ratio.
04-06 23:08:14.571 29639 29688 V mpv : [vf] [in] 1280x720 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
04-06 23:08:14.571 29639 29688 V mpv : [vf] [userdeint] 1280x720 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
04-06 23:08:14.571 29639 29688 V mpv : [vf] [userdeint] (disabled)
04-06 23:08:14.571 29639 29688 V mpv : [vf] [autorotate] 1280x720 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
04-06 23:08:14.571 29639 29688 V mpv : [vf] [autorotate] (disabled)
04-06 23:08:14.572 29639 29688 V mpv : [vf] [convert] 1280x720 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
04-06 23:08:14.572 29639 29688 V mpv : [vf] [convert] (disabled)
04-06 23:08:14.572 29639 29688 V mpv : [vf] [out] 1280x720 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
04-06 23:08:14.572 29639 29688 I mpv : [cplayer] VO: [gpu] 1280x720 => 1280x720 yuv420p
04-06 23:08:14.573 29639 29688 V mpv : [cplayer] VO: Description: Shader-based GPU Renderer
04-06 23:08:14.573 29639 29688 V mpv : [cplayer] first video frame after restart shown
04-06 23:08:14.573 29639 29688 I mpv : [cplayer] Track switched:
04-06 23:08:14.573 29639 29688 I mpv : [cplayer] (+) Video --vid=1 (h264 1280x720 60.000fps)
04-06 23:08:14.573 29639 29688 I mpv : [cplayer] (+) Audio --aid=1 (aac 2ch 48000Hz 63kbps)
04-06 23:08:14.573 29639 29688 V mpv : [cplayer] Set property: aid=1 -> 1
04-06 23:08:14.573 29639 29688 D mpv : [cplayer] Setting option 'cache-pause-initial' = "1" (flags = 64) -> 0
04-06 23:08:14.573 29639 29688 D mpv : [cplayer] Setting option 'cache-pause-wait' = "0.25" (flags = 64) -> 0
04-06 23:08:14.573 29639 29688 D mpv : [cplayer] Setting option 'cache-pause-fill' = "1" (flags = 64) -> 0
04-06 23:08:14.573 29639 29688 I mpv : [cplayer] (+) Video --vid=1 (h264 1280x720 60.000fps)
04-06 23:08:14.573 29639 29688 I mpv : [cplayer] (+) Audio --aid=1 (aac 2ch 48000Hz 63kbps)
04-06 23:08:14.573 29639 29688 I mpv : [cplayer] Subs --sid=1 (*) (eia_608)
04-06 23:08:14.578 29639 29688 V mpv : property: track-list has 3 entries
04-06 23:08:14.578 29639 29688 V mpv : [cplayer] starting audio playback
04-06 23:08:14.587 29639 29688 V mpv : event: playback-restart
04-06 23:08:14.591 29639 29639 V PlayerActivity: state LOADED -> PLAYING
04-06 23:08:14.591 29639 29688 V mpv : [cplayer] playback restart complete @ 0.015867
04-06 23:08:15.398 29639 29639 V mpvstats: AV: 0.800 A-V: 0.000 Dropped: 1 Cache: 10.965s + 0KB
04-06 23:08:17.571 29639 29639 V mpvstats: AV: 2.969 A-V: 0.000 Dropped: 1 Cache: 8.747s + 0KB
04-06 23:08:20.572 29639 29639 V mpvstats: AV: 5.972 A-V: 0.000 Dropped: 1 Cache: 5.760s + 0KB
04-06 23:08:23.573 29639 29639 V mpvstats: AV: 8.975 A-V: 0.000 Dropped: 1 Cache: 11.008s + 0KB
04-06 23:08:26.574 29639 29639 V mpvstats: AV: 11.978 A-V: 0.000 Dropped: 1 Cache: 12.075s + 0KB
04-06 23:08:29.576 29639 29639 V mpvstats: AV: 14.981 A-V: 0.000 Dropped: 1 Cache: 8.960s + 0KB
04-06 23:08:32.579 29639 29639 V mpvstats: AV: 17.984 A-V: 0.000 Dropped: 1 Cache: 10.112s + 0KB
04-06 23:08:35.580 29639 29639 V mpvstats: AV: 20.987 A-V: 0.000 Dropped: 1 Cache: 11.221s + 0KB
04-06 23:08:38.582 29639 29639 V mpvstats: AV: 23.990 A-V: 0.000 Dropped: 1 Cache: 12.331s + 0KB
04-06 23:08:41.583 29639 29639 V mpvstats: AV: 26.976 A-V: 0.000 Dropped: 1 Cache: 9.344s + 0KB
04-06 23:08:44.583 29639 29639 V mpvstats: AV: 29.979 A-V: 0.000 Dropped: 1 Cache: 10.411s + 0KB
04-06 23:08:47.584 29639 29639 V mpvstats: AV: 32.982 A-V: 0.000 Dropped: 1 Cache: 11.563s + 0KB
04-06 23:08:50.585 29639 29639 V mpvstats: AV: 35.985 A-V: 0.000 Dropped: 1 Cache: 12.629s + 0KB
04-06 23:08:53.586 29639 29639 V mpvstats: AV: 38.988 A-V: 0.000 Dropped: 1 Cache: 9.643s + 0KB
04-06 23:08:56.587 29639 29639 V mpvstats: AV: 41.991 A-V: 0.000 Dropped: 1 Cache: 6.656s + 0KB
04-06 23:08:59.588 29639 29639 V mpvstats: AV: 44.994 A-V: 0.000 Dropped: 1 Cache: 3.669s + 0KB
04-06 23:09:02.590 29639 29639 V mpvstats: AV: 47.980 A-V: 0.000 Dropped: 1 Cache: 0.597s + 0KB
04-06 23:09:03.194 29639 29688 V mpv : event: unpause
04-06 23:09:03.194 29639 29688 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 41%) [0.417078s].
04-06 23:09:03.195 29639 29688 V mpv : property: buffering = true
04-06 23:09:03.195 29639 29639 V PlayerActivity: state PLAYING -> BUFFERING
04-06 23:09:03.197 29639 29639 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=6.105266555555556, end=49.04816655555556}], cache-end=49.09822211111111, reader-pts=48.681144333333336, cache-duration=0.4170777777777772, eof=false, underrun=true, idle=false, total-bytes=31406976, fw-bytes=365312, debug-low-level-seeks=0, debug-ts-last=48.63110011111111, ts-per-stream=[{type=video, duration=0.4170777777777772, reader=48.697833333333335, end=49.11491111111111}, {type=audio, duration=0.0, reader=49.126022222222225, end=49.126022222222225}]}
04-06 23:09:04.784 29639 29649 I hannels.dvr.ap: Background concurrent copying GC freed 281713(15MB) AllocSpace objects, 6(6MB) LOS objects, 50% free, 11MB/23MB, paused 328us total 101.522ms
04-06 23:09:05.590 29639 29639 V mpvstats: AV: 48.598 A-V: 0.000 Dropped: 1 Cache: 0.417s + 0KB
04-06 23:09:05.946 29639 29688 V mpv : event: unpause
04-06 23:09:05.946 29639 29688 V mpv : [cplayer] End buffering (waited 2.748551 secs) [1.322667s].
04-06 23:09:05.951 29639 29688 V mpv : property: buffering = false
04-06 23:09:05.951 29639 29639 V PlayerActivity: state BUFFERING -> PLAYING
04-06 23:09:05.957 29639 29639 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=6.105266555555556, end=49.14826655555556}], cache-end=50.77333322222223, reader-pts=49.279999888888895, cache-duration=1.4933333333333323, eof=false, underrun=false, idle=false, total-bytes=32620480, fw-bytes=1565248, debug-low-level-seeks=0, debug-ts-last=50.799933333333335, ts-per-stream=[{type=video, duration=2.0854111111111138, reader=48.71452222222222, end=50.799933333333335}, {type=audio, duration=1.4933333333333323, reader=49.296688888888895, end=50.79002222222223}]}
04-06 23:09:06.447 29639 29639 V mpvstats: AV: 49.282 A-V: 0.000 Dropped: 14 Cache: 3.499s + 0KB
04-06 23:09:08.591 29639 29639 V mpvstats: AV: 51.417 A-V: 0.000 Dropped: 14 Cache: 1.365s + 0KB
04-06 23:09:11.592 29639 29639 V mpvstats: AV: 54.420 A-V: 0.000 Dropped: 14 Cache: 2.389s + 0KB
04-06 23:09:14.150 29639 29688 V mpv : event: unpause
04-06 23:09:14.150 29639 29688 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 23%) [0.233567s].
04-06 23:09:14.151 29639 29688 V mpv : property: buffering = true
04-06 23:09:14.151 29639 29639 V PlayerActivity: state PLAYING -> BUFFERING
04-06 23:09:14.152 29639 29639 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=12.211366555555557, end=57.23969988888889}], cache-end=57.306433222222225, reader-pts=57.07286655555556, cache-duration=0.23356666666666825, eof=false, underrun=true, idle=false, total-bytes=32151744, fw-bytes=282496, debug-low-level-seeks=0, debug-ts-last=57.00612233333334, ts-per-stream=[{type=video, duration=0.23356666666666825, reader=57.089555555555556, end=57.323122222222224}, {type=audio, duration=0.0, reader=57.318022222222226, end=57.318022222222226}]}
04-06 23:09:14.592 29639 29639 V mpvstats: AV: 56.989 A-V: 0.000 Dropped: 14 Cache: 0.234s + 0KB
04-06 23:09:17.593 29639 29639 V mpvstats: AV: 56.989 A-V: 0.000 Dropped: 14 Cache: 0.234s + 0KB
04-06 23:09:19.688 29639 29688 V mpv : [cplayer] Still buffering (buffer went from 23% -> 4%) [0.042667s].
04-06 23:09:19.692 29639 29688 V mpv : [cplayer] Still buffering (buffer went from 4% -> 25%) [0.250233s].
04-06 23:09:19.704 29639 29688 V mpv : [cplayer] Still buffering (buffer went from 25% -> 4%) [0.042667s].
04-06 23:09:19.704 29639 29688 V mpv : [cplayer] Still buffering (buffer went from 4% -> 28%) [0.283611s].
04-06 23:09:19.708 29639 29688 V mpv : [cplayer] Still buffering (buffer went from 28% -> 4%) [0.042667s].
04-06 23:09:19.919 29639 29688 V mpv : event: unpause
04-06 23:09:19.919 29639 29688 V mpv : [cplayer] End buffering (waited 5.767367 secs) [3.157333s].
04-06 23:09:19.923 29639 29688 V mpv : property: buffering = false
04-06 23:09:19.923 29639 29639 V PlayerActivity: state BUFFERING -> PLAYING
04-06 23:09:19.936 29639 29639 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=12.211366555555557, end=59.34178877777778}], cache-end=60.84266655555556, reader-pts=57.685333222222226, cache-duration=3.1573333333333338, eof=false, underrun=false, idle=false, total-bytes=35037632, fw-bytes=3155328, debug-low-level-seeks=0, debug-ts-last=60.85997777777778, ts-per-stream=[{type=video, duration=3.753755555555557, reader=57.10622222222222, end=60.85997777777778}, {type=audio, duration=3.1573333333333338, reader=57.702022222222226, end=60.85935555555556}]}
04-06 23:09:20.455 29639 29639 V mpvstats: AV: 57.757 A-V: 0.000 Dropped: 34 Cache: 2.560s + 0KB
04-06 23:09:20.594 29639 29639 V mpvstats: AV: 57.890 A-V: 0.000 Dropped: 34 Cache: 2.475s + 0KB
04-06 23:09:23.596 29639 29639 V mpvstats: AV: 60.893 A-V: 0.000 Dropped: 34 Cache: 20.523s + 0KB
04-06 23:09:26.598 29639 29639 V mpvstats: AV: 63.896 A-V: 0.000 Dropped: 34 Cache: 21.589s + 0KB
04-06 23:09:29.600 29639 29639 V mpvstats: AV: 66.899 A-V: 0.000 Dropped: 34 Cache: 22.656s + 0KB
04-06 23:09:32.601 29639 29639 V mpvstats: AV: 69.902 A-V: 0.000 Dropped: 34 Cache: 23.765s + 0KB
04-06 23:09:35.602 29639 29639 V mpvstats: AV: 72.905 A-V: 0.000 Dropped: 34 Cache: 20.779s + 0KB
04-06 23:09:38.603 29639 29639 V mpvstats: AV: 75.908 A-V: 0.000 Dropped: 34 Cache: 21.888s + 0KB
04-06 23:09:39.764 29639 29805 V ApiServer: REQUEST: GET /log
...
...
...
And more....
04-06 23:09:41.603 29639 29639 V mpvstats: AV: 78.895 A-V: 0.000 Dropped: 34 Cache: 22.912s + 0KB
04-06 23:09:44.604 29639 29639 V mpvstats: AV: 81.898 A-V: 0.000 Dropped: 34 Cache: 22.101s + 0KB
04-06 23:09:47.605 29639 29639 V mpvstats: AV: 84.901 A-V: 0.000 Dropped: 34 Cache: 21.077s + 0KB
04-06 23:09:50.606 29639 29639 V mpvstats: AV: 87.904 A-V: 0.000 Dropped: 34 Cache: 22.101s + 0KB
04-06 23:09:53.607 29639 29639 V mpvstats: AV: 90.907 A-V: 0.000 Dropped: 34 Cache: 23.296s + 0KB
04-06 23:09:56.608 29639 29639 V mpvstats: AV: 93.910 A-V: 0.000 Dropped: 34 Cache: 24.363s + 0KB
04-06 23:09:59.611 29639 29639 V mpvstats: AV: 96.913 A-V: 0.000 Dropped: 34 Cache: 21.376s + 0KB
04-06 23:10:02.612 29639 29639 V mpvstats: AV: 99.899 A-V: 0.000 Dropped: 34 Cache: 22.400s + 0KB
04-06 23:10:05.615 29639 29639 V mpvstats: AV: 102.902 A-V: 0.000 Dropped: 34 Cache: 19.371s + 0KB
04-06 23:10:08.616 29639 29639 V mpvstats: AV: 105.905 A-V: 0.000 Dropped: 34 Cache: 20.523s + 0KB
04-06 23:10:11.617 29639 29639 V mpvstats: AV: 108.908 A-V: 0.000 Dropped: 34 Cache: 21.632s + 0KB
04-06 23:10:14.618 29639 29639 V mpvstats: AV: 111.911 A-V: 0.000 Dropped: 34 Cache: 19.029s + 0KB
04-06 23:10:17.619 29639 29639 V mpvstats: AV: 114.914 A-V: 0.000 Dropped: 34 Cache: 19.755s + 0KB
04-06 23:10:20.620 29639 29639 V mpvstats: AV: 117.917 A-V: 0.000 Dropped: 34 Cache: 20.821s + 0KB
04-06 23:10:23.621 29639 29639 V mpvstats: AV: 120.920 A-V: 0.000 Dropped: 34 Cache: 17.749s + 0KB
04-06 23:10:26.621 29639 29639 V mpvstats: AV: 123.923 A-V: 0.000 Dropped: 34 Cache: 18.859s + 0KB
04-06 23:10:29.622 29639 29639 V mpvstats: AV: 126.909 A-V: 0.000 Dropped: 34 Cache: 19.968s + 0KB
04-06 23:10:32.624 29639 29639 V mpvstats: AV: 129.912 A-V: 0.000 Dropped: 34 Cache: 21.077s + 0KB
04-06 23:10:35.626 29639 29639 V mpvstats: AV: 132.915 A-V: 0.000 Dropped: 34 Cache: 22.187s + 0KB
04-06 23:10:38.627 29639 29639 V mpvstats: AV: 135.918 A-V: 0.000 Dropped: 34 Cache: 19.285s + 0KB
04-06 23:10:41.628 29639 29639 V mpvstats: AV: 138.921 A-V: 0.000 Dropped: 34 Cache: 20.309s + 0KB
04-06 23:10:44.630 29639 29639 V mpvstats: AV: 141.924 A-V: 0.000 Dropped: 34 Cache: 21.419s + 0KB
04-06 23:10:47.631 29639 29639 V mpvstats: AV: 144.927 A-V: 0.000 Dropped: 34 Cache: 22.485s + 0KB
04-06 23:10:50.632 29639 29639 V mpvstats: AV: 147.930 A-V: 0.000 Dropped: 34 Cache: 20.651s + 0KB
04-06 23:10:53.633 29639 29639 V mpvstats: AV: 150.933 A-V: 0.000 Dropped: 34 Cache: 20.608s + 0KB
04-06 23:10:56.634 29639 29639 V mpvstats: AV: 153.936 A-V: 0.000 Dropped: 34 Cache: 21.632s + 0KB
04-06 23:10:59.635 29639 29639 V mpvstats: AV: 156.923 A-V: 0.000 Dropped: 34 Cache: 22.699s + 0KB
04-06 23:11:02.637 29639 29639 V mpvstats: AV: 159.926 A-V: 0.000 Dropped: 34 Cache: 19.712s + 0KB
04-06 23:11:05.638 29639 29639 V mpvstats: AV: 162.929 A-V: 0.000 Dropped: 34 Cache: 16.725s + 0KB
04-06 23:11:07.411 29639 29647 W System : A resource failed to call end.
04-06 23:11:08.638 29639 29639 V mpvstats: AV: 165.932 A-V: 0.000 Dropped: 34 Cache: 13.739s + 0KB
04-06 23:11:11.639 29639 29639 V mpvstats: AV: 168.935 A-V: 0.000 Dropped: 34 Cache: 23.040s + 0KB
04-06 23:11:14.640 29639 29639 V mpvstats: AV: 171.938 A-V: 0.000 Dropped: 34 Cache: 21.120s + 0KB
04-06 23:11:17.641 29639 29639 V mpvstats: AV: 174.941 A-V: 0.000 Dropped: 34 Cache: 21.035s + 0KB
04-06 23:11:20.641 29639 29639 V mpvstats: AV: 177.944 A-V: 0.000 Dropped: 34 Cache: 22.272s + 0KB
04-06 23:11:23.644 29639 29639 V mpvstats: AV: 180.947 A-V: 0.000 Dropped: 34 Cache: 23.381s + 0KB
04-06 23:11:26.646 29639 29639 V mpvstats: AV: 183.950 A-V: 0.000 Dropped: 34 Cache: 20.395s + 0KB
04-06 23:11:29.647 29639 29639 V mpvstats: AV: 186.936 A-V: 0.000 Dropped: 34 Cache: 21.504s + 0KB
04-06 23:11:32.648 29639 29639 V mpvstats: AV: 189.939 A-V: 0.000 Dropped: 34 Cache: 18.475s + 0KB
04-06 23:11:35.649 29639 29639 V mpvstats: AV: 192.942 A-V: 0.000 Dropped: 34 Cache: 15.488s + 0KB
04-06 23:11:38.650 29639 29639 V mpvstats: AV: 195.945 A-V: 0.000 Dropped: 34 Cache: 12.416s + 0KB
04-06 23:11:41.651 29639 29639 V mpvstats: AV: 198.948 A-V: 0.000 Dropped: 34 Cache: 9.429s + 0KB
04-06 23:11:44.652 29639 29639 V mpvstats: AV: 201.951 A-V: 0.000 Dropped: 34 Cache: 9.088s + 0KB
04-06 23:11:47.653 29639 29639 V mpvstats: AV: 204.954 A-V: 0.000 Dropped: 34 Cache: 7.552s + 0KB
04-06 23:11:50.653 29639 29639 V mpvstats: AV: 207.957 A-V: 0.000 Dropped: 34 Cache: 4.480s + 0KB
04-06 23:11:53.655 29639 29639 V mpvstats: AV: 210.943 A-V: 0.000 Dropped: 34 Cache: 1.451s + 0KB
04-06 23:11:55.324 29639 29688 V mpv : event: unpause
04-06 23:11:55.325 29639 29688 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 23%) [0.233578s].
04-06 23:11:55.326 29639 29688 V mpv : property: buffering = true
04-06 23:11:55.326 29639 29639 V PlayerActivity: state PLAYING -> BUFFERING
04-06 23:11:55.327 29639 29639 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=174.0396998888889, end=212.8951998888889}], cache-end=212.94524433333333, reader-pts=212.71166655555555, cache-duration=0.2335777777777821, eof=false, underrun=true, idle=false, total-bytes=31939520, fw-bytes=225216, debug-low-level-seeks=0, debug-ts-last=212.37802233333335, ts-per-stream=[{type=video, duration=0.2335777777777821, reader=212.72835555555557, end=212.96193333333335}, {type=audio, duration=0.0, reader=212.96602222222222, end=212.96602222222222}]}
04-06 23:11:56.656 29639 29639 V mpvstats: AV: 212.628 A-V: 0.000 Dropped: 34 Cache: 0.234s + 0KB
04-06 23:11:59.657 29639 29639 V mpvstats: AV: 212.628 A-V: 0.000 Dropped: 34 Cache: 0.234s + 0KB
04-06 23:12:02.658 29639 29639 V mpvstats: AV: 212.628 A-V: 0.000 Dropped: 34 Cache: 0.234s + 0KB
04-06 23:12:05.659 29639 29639 V mpvstats: AV: 212.628 A-V: 0.000 Dropped: 34 Cache: 0.234s + 0KB
04-06 23:12:08.660 29639 29639 V mpvstats: AV: 212.628 A-V: 0.000 Dropped: 34 Cache: 0.234s + 0KB
04-06 23:12:11.661 29639 29639 V mpvstats: AV: 212.628 A-V: 0.000 Dropped: 34 Cache: 0.234s + 0KB
04-06 23:12:14.662 29639 29639 V mpvstats: AV: 212.628 A-V: 0.000 Dropped: 34 Cache: 0.234s + 0KB
04-06 23:12:17.248 29639 29781 V Streamer: mpv read bytes:0 after retries:32000 (pos:167608320)
04-06 23:12:17.327 29639 29688 V mpv : [cplayer] Still buffering (buffer went from 23% -> 25%) [0.250267s].
04-06 23:12:17.663 29639 29639 V mpvstats: AV: 212.628 A-V: 0.000 Dropped: 34 Cache: 0.250s + 0KB
04-06 23:12:20.664 29639 29639 V mpvstats: AV: 212.628 A-V: 0.000 Dropped: 34 Cache: 0.250s + 0KB
04-06 23:12:21.039 29639 29688 V mpv : [cplayer] Still buffering (buffer went from 25% -> 4%) [0.042667s].
04-06 23:12:21.040 29639 29688 V mpv : [cplayer] Still buffering (buffer went from 4% -> 28%) [0.283622s].
04-06 23:12:21.043 29639 29688 V mpv : [cplayer] Still buffering (buffer went from 28% -> 8%) [0.085333s].
04-06 23:12:21.092 29639 29688 V mpv : event: unpause
04-06 23:12:21.093 29639 29688 V mpv : [cplayer] End buffering (waited 25.768425 secs) [1.066667s].
04-06 23:12:21.103 29639 29688 V mpv : property: buffering = false
04-06 23:12:21.104 29639 29639 V PlayerActivity: state BUFFERING -> PLAYING
04-06 23:12:21.106 29639 29639 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=174.0396998888889, end=212.97859988888888}], cache-end=214.2293332222222, reader-pts=213.29066655555556, cache-duration=0.9386666666666486, eof=false, underrun=false, idle=false, total-bytes=32760896, fw-bytes=1027776, debug-low-level-seeks=0, debug-ts-last=214.24602222222222, ts-per-stream=[{type=video, duration=1.4681333333333555, reader=212.74505555555555, end=214.2131888888889}, {type=audio, duration=0.9386666666666486, reader=213.30735555555557, end=214.24602222222222}]}
04-06 23:12:21.279 29639 29688 E mpv : [ffmpeg/video] h264: error while decoding MB 11 42, bytestream -19
04-06 23:12:21.281 29639 29688 V mpv : [ffmpeg/video] h264: concealing 278 DC, 278 AC, 278 MV errors in P frame
04-06 23:12:21.588 29639 29639 V mpvstats: AV: 213.329 A-V: 0.000 Dropped: 54 Cache: 3.200s + 0KBThis timeout indicates a network or hardware issue. I haven't seen any other customers reporting this particular message so it's something specific about your setup that's causing this.
Is your shield using a usb drive for storage?
No, it's using my NAS.
So every read and every write that goes through your DVR is additionally making a transit across your network. This makes the topology of your network of the utmost importance. Additionally, it also calls into question the specs of your NAS on top of your DVR.
I believe this is the first you've mentioned your DVR's storage being network-attached while trying to troubleshoot these issues …
It was never asked.
Live OTA has no problem nor does OTA have a problem if I transcode or use tuner sharing. I can record 4 OTA shows at the same time without skipping a beat.
It acts like I paused it, the time-bar keys growing while it's buffering and I never miss any data.
My NAS is a QNAP 431+ 3 WD drives running raid 5.
When watching Live TV the timeline does not in any way reflect the actual amount of data buffered. It simply grows as time progresses and does not in any way indicate what is actually locally available to watch.
It was created at a time when streaming via the HDHomerun was the only way to watch TV, which would stream 1 second of content every second and would have very short timeouts.
So... the timeline bar is not useful for understanding the current state of buffers or anything like that.
OT:
Is this slated for an update in the future, then? It would be nice to have the UI reflect the actual state of things.
You guys crack me up. I'm not saying its linked to any specific time.
The time-bar grows when you pause live content.... lets call it a buffer or whatever the heck you want to call it I don't care. The buffer grows while it is buffering just like it does when you pause it. While it is buffering I never miss any content just like I paused it! After the 1-2.5 minute buffering event I can skip forward if I want or I can go back to before the buffering even started and rewatch that section that was buffering and not miss a darn thing. Do you guys get that? I do not miss any of the content while it is buffering.. That means that its not a streaming issue.
My question..... If I pause live TVE TV, Where does it buffer? On the client device or the TVE Server?
The buffer is not growing. The time-bar UI is based on the clock and not the buffer. So it doesn't matter that its getting longer, because the log shows that no video data is coming from the DVR for over 30 seconds.
For OTA, the video is buffered in RAM on the DVR and then sent to the client (when tuner sharing is on).
For TVE, the video is first downloaded to DISK on the DVR, then sent to the client (which also stores it in a client disk buffer). I'm guessing your problems are because you're using a NAS, which is introducing some kind of delay because the TVE video is being downloaded to the NAS first before being downloaded from the NAS and sent to your client. (This means the video data travels over your network 4 times before making it to the video player, which is why we highly recommend that the DVR use a USB drive and not communicate to the disk over a network).
Have you even watched the video I posted earlier in this thread? It shows that when the buffering is complete I can FF minutes to get back live. I can also go back and rewatch that section that buffered and there is no missing video.
If this is true, don't you think that I would have issues with watching DVR Recordings?
Yes. I understand the video appears eventually. So it's buffering somewhere, but not on the client. It's buffered on your NAS or network somewhere because it doesn't make it to the client until several minutes later.
The same issue is happening while recording, but you're not there watching it live so you can't tell that it stalled for 3 minutes and then caught up.
I'll ask differently.
If the DVR records.... the stalling or buffering doesn't happen to the recording because it comes in from the modem to the router then to the switch then to the Shield then thru the Switch on the NAS and stays there.
Once it is recorded and I watch it, My devices are connected to my router so my client asks for the file.... thru the router, to the switch, to the Shield which takes it from the NAS. So from the NAS it goes to the switch then to the Shield then to the switch then to the router then to my client.
My point is.... wouldn't I see the same problems while watching a recorded show on the NAS?
By using a USB HDD all I eliminate is the Ethernet to the NAS. How is that different than it going via USB to the HDD?
My guess is that all your TVE streams are stalling. It doesn't matter if you're watching it or recording. If you checked the file size of the recording you would probably see it stops growing during the stall and then later it catches up. By the time you watch the recording it doesn't matter because the stall happened long ago.