A new beta was uploaded to the Play Store with a possible fix. I have another change I'm also considering but I left it out for now.
1 Like
Weird, I still don't see it being available....
I had to remove myself from the beta in the Play store, Uninstall the beta and reinstall the non-beta then install the beta from the app.
You might have to check it when you first open the player.
Did you try the beta on the fire tv?
Sucks! Its still happening on my Sony TV
04-02 00:25:57.271 15602 15602 V mpvstats: AV: 1355.322 A-V: 0.000 Dropped: 0 Cache: 14.293s + 0KB
04-02 00:26:00.271 15602 15602 V mpvstats: AV: 1358.325 A-V: 0.000 Dropped: 0 Cache: 12.288s + 0KB
04-02 00:26:00.393 15602 15612 I ls.dvr.app.bet: Background concurrent copying GC freed 304396(12MB) AllocSpace objects, 0(0B) LOS objects, 49% free, 12MB/25MB, paused 416us total 120.974ms
04-02 00:26:03.272 15602 15602 V mpvstats: AV: 1361.328 A-V: 0.000 Dropped: 0 Cache: 12.245s + 0KB
04-02 00:26:06.272 15602 15602 V mpvstats: AV: 1364.331 A-V: 0.000 Dropped: 0 Cache: 13.141s + 0KB
04-02 00:26:09.272 15602 15602 V mpvstats: AV: 1367.334 A-V: 0.000 Dropped: 0 Cache: 14.464s + 0KB
04-02 00:26:11.904 15602 15648 D mpv : [ffmpeg/video] h264: Reinit context to 1280x720, pix_fmt: yuv420p
04-02 00:26:11.970 15602 15648 V mpv : [vd] Decoder format: 1280x720 [0:1] yuv420p bt.709/bt.709/bt.1886/limited/auto CL=mpeg2/4/h264 (auto 0.000000/0.000000/0.000000)
04-02 00:26:11.970 15602 15648 V mpv : [vd] Forcing user-set aspect ratio.
04-02 00:26:12.273 15602 15602 V mpvstats: AV: 1370.312 A-V: 0.000 Dropped: 0 Cache: 13.611s + 0KB
04-02 00:26:15.274 15602 15602 V mpvstats: AV: 1373.315 A-V: 0.000 Dropped: 0 Cache: 11.307s + 0KB
04-02 00:26:18.274 15602 15602 V mpvstats: AV: 1376.318 A-V: 0.000 Dropped: 0 Cache: 14.379s + 0KB
04-02 00:26:21.275 15602 15602 V mpvstats: AV: 1379.321 A-V: 0.000 Dropped: 0 Cache: 15.445s + 0KB
04-02 00:26:24.276 15602 15602 V mpvstats: AV: 1382.324 A-V: 0.000 Dropped: 0 Cache: 16.640s + 0KB
04-02 00:26:27.277 15602 15602 V mpvstats: AV: 1385.350 A-V: 0.000 Dropped: 0 Cache: 13.653s + 0KB
04-02 00:26:30.278 15602 15602 V mpvstats: AV: 1388.353 A-V: 0.000 Dropped: 0 Cache: 11.349s + 0KB
04-02 00:26:33.279 15602 15602 V mpvstats: AV: 1391.356 A-V: 0.000 Dropped: 0 Cache: 12.544s + 0KB
04-02 00:26:36.280 15602 15602 V mpvstats: AV: 1394.359 A-V: 0.000 Dropped: 0 Cache: 9.557s + 0KB
04-02 00:26:39.280 15602 15602 V mpvstats: AV: 1397.328 A-V: 0.000 Dropped: 0 Cache: 10.624s + 0KB
04-02 00:26:42.280 15602 15602 V mpvstats: AV: 1400.320 A-V: 0.000 Dropped: 0 Cache: 11.691s + 0KB
04-02 00:26:45.282 15602 15602 V mpvstats: AV: 1403.323 A-V: 0.000 Dropped: 0 Cache: 11.563s + 0KB
04-02 00:26:48.282 15602 15602 V mpvstats: AV: 1406.326 A-V: 0.000 Dropped: 0 Cache: 13.300s + 0KB
04-02 00:26:51.284 15602 15602 V mpvstats: AV: 1409.329 A-V: 0.000 Dropped: 0 Cache: 10.655s + 0KB
04-02 00:26:54.284 15602 15602 V mpvstats: AV: 1412.332 A-V: 0.000 Dropped: 0 Cache: 11.721s + 0KB
04-02 00:26:56.838 15602 15648 W mpv : [ad] Invalid audio PTS: 1415.390833 -> 1416.402933
04-02 00:26:57.286 15602 15602 V mpvstats: AV: 1415.235 A-V: 0.879 Dropped: 0 Cache: 11.776s + 0KB
04-02 00:27:00.287 15602 15602 V mpvstats: AV: 1419.206 A-V: 0.137 Dropped: 0 Cache: 11.520s + 0KB
04-02 00:27:03.288 15602 15602 V mpvstats: AV: 1422.342 A-V: 0.000 Dropped: 0 Cache: 8.533s + 0KB
04-02 00:27:06.288 15602 15602 V mpvstats: AV: 1425.345 A-V: 0.000 Dropped: 0 Cache: 11.776s + 0KB
04-02 00:27:09.290 15602 15602 V mpvstats: AV: 1428.348 A-V: 0.000 Dropped: 0 Cache: 8.789s + 0KB
04-02 00:27:12.291 15602 15602 V mpvstats: AV: 1431.351 A-V: 0.000 Dropped: 0 Cache: 5.717s + 0KB
04-02 00:27:15.292 15602 15602 V mpvstats: AV: 1434.343 A-V: 0.000 Dropped: 0 Cache: 2.731s + 0KB
04-02 00:27:18.102 15602 15648 V mpv : event: unpause
04-02 00:27:18.103 15602 15648 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 26%) [0.266933s].
04-02 00:27:18.106 15602 15648 V mpv : property: buffering = true
04-02 00:27:18.106 15602 15602 V PlayerActivity: state PLAYING -> BUFFERING
04-02 00:27:18.108 15602 15602 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=1386.517499888889, end=1437.112511}], cache-end=1437.5796554444444, reader-pts=1437.312722111111, cache-duration=0.266933333333327, eof=false, underrun=true, idle=false, total-bytes=31724992, fw-bytes=161984, debug-low-level-seeks=0, debug-ts-last=1437.5963444444444, ts-per-stream=[{type=video, duration=0.266933333333327, reader=1437.329411111111, end=1437.5963444444444}, {type=audio, duration=0.0, reader=1437.6249555555555, end=1437.6249555555555}]}
04-02 00:27:18.297 15602 15602 V mpvstats: AV: 1437.179 A-V: 0.000 Dropped: 0 Cache: 0.267s + 0KB
04-02 00:27:21.298 15602 15602 V mpvstats: AV: 1437.179 A-V: 0.000 Dropped: 0 Cache: 0.267s + 0KB
04-02 00:27:24.298 15602 15602 V mpvstats: AV: 1437.179 A-V: 0.000 Dropped: 0 Cache: 0.267s + 0KB
04-02 00:27:27.300 15602 15602 V mpvstats: AV: 1437.179 A-V: 0.000 Dropped: 0 Cache: 0.267s + 0KB
04-02 00:27:30.300 15602 15602 V mpvstats: AV: 1437.179 A-V: 0.000 Dropped: 0 Cache: 0.267s + 0KB
04-02 00:27:33.302 15602 15602 V mpvstats: AV: 1437.179 A-V: 0.000 Dropped: 0 Cache: 0.267s + 0KB
04-02 00:27:35.347 15602 15648 V mpv : event: unpause
04-02 00:27:35.348 15602 15648 V mpv : [cplayer] End buffering (waited 17.243174 secs) [1.237333s].
04-02 00:27:35.358 15602 15648 V mpv : property: buffering = false
04-02 00:27:35.358 15602 15602 V PlayerActivity: state BUFFERING -> PLAYING
04-02 00:27:35.514 15602 15602 V mpvstats: AV: 1437.480 A-V: 0.000 Dropped: 5 Cache: 2.603s + 0KB
04-02 00:27:36.303 15602 15602 V mpvstats: AV: 1438.280 A-V: 0.000 Dropped: 5 Cache: 7.680s + 0KB
04-02 00:27:39.304 15602 15602 V mpvstats: AV: 1441.283 A-V: 0.000 Dropped: 5 Cache: 26.069s + 0KB
04-02 00:27:42.305 15602 15602 V mpvstats: AV: 1444.286 A-V: 0.000 Dropped: 5 Cache: 27.136s + 0KB
04-02 00:27:45.305 15602 15602 V mpvstats: AV: 1447.278 A-V: 0.000 Dropped: 5 Cache: 28.117s + 0KB
04-02 00:27:48.307 15602 15602 V mpvstats: AV: 1450.281 A-V: 0.000 Dropped: 5 Cache: 29.867s + 0KB
04-02 00:27:51.308 15602 15602 V mpvstats: AV: 1453.284 A-V: 0.000 Dropped: 5 Cache: 27.008s + 0KB
04-02 00:27:54.309 15602 15602 V mpvstats: AV: 1456.287 A-V: 0.000 Dropped: 5 Cache: 28.075s + 0KB
04-02 00:27:57.310 15602 15602 V mpvstats: AV: 1459.290 A-V: 0.000 Dropped: 5 Cache: 25.088s + 0KB
04-02 00:28:00.311 15602 15602 V mpvstats: AV: 1462.282 A-V: 0.000 Dropped: 5 Cache: 30.293s + 0KB
04-02 00:28:03.312 15602 15602 V mpvstats: AV: 1465.285 A-V: 0.000 Dropped: 5 Cache: 27.307s + 0KB
04-02 00:28:06.313 15602 15602 V mpvstats: AV: 1468.288 A-V: 0.000 Dropped: 5 Cache: 28.288s + 0KB
04-02 00:28:09.315 15602 15602 V mpvstats: AV: 1471.291 A-V: 0.000 Dropped: 5 Cache: 29.525s + 0KB
04-02 00:28:12.316 15602 15602 V mpvstats: AV: 1474.294 A-V: 0.000 Dropped: 5 Cache: 30.635s + 0KB
04-02 00:28:15.318 15602 15602 V mpvstats: AV: 1477.301 A-V: 0.000 Dropped: 5 Cache: 27.648s + 0KB
04-02 00:28:18.319 15602 15602 V mpvstats: AV: 1480.304 A-V: 0.000 Dropped: 5 Cache: 25.941s + 0KB
04-02 00:28:21.320 15602 15602 V mpvstats: AV: 1483.307 A-V: 0.000 Dropped: 5 Cache: 29.099s + 0KB
04-02 00:28:24.320 15602 15602 V mpvstats: AV: 1486.310 A-V: 0.000 Dropped: 5 Cache: 30.251s + 0KB
04-02 00:28:27.322 15602 15602 V mpvstats: AV: 1489.279 A-V: 0.000 Dropped: 5 Cache: 27.264s + 0KB
04-02 00:28:30.323 15602 15602 V mpvstats: AV: 1492.316 A-V: 0.000 Dropped: 5 Cache: 28.245s + 0KB
04-02 00:28:33.327 15602 15602 V mpvstats: AV: 1495.285 A-V: 0.000 Dropped: 5 Cache: 25.259s + 0KB
04-02 00:28:36.329 15602 15602 V mpvstats: AV: 1498.288 A-V: 0.000 Dropped: 5 Cache: 24.320s + 0KB
04-02 00:28:39.329 15602 15602 V mpvstats: AV: 1501.291 A-V: 0.000 Dropped: 5 Cache: 27.605s + 0KB
04-02 00:28:42.330 15602 15602 V mpvstats: AV: 1504.294 A-V: 0.000 Dropped: 5 Cache: 28.587s + 0KB
04-02 00:28:45.333 15602 15602 V mpvstats: AV: 1507.290 A-V: 0.000 Dropped: 5 Cache: 28.885s + 0KB
04-02 00:28:48.335 15602 15602 V mpvstats: AV: 1510.293 A-V: 0.000 Dropped: 5 Cache: 30.182s + 0KB
04-02 00:28:51.337 15602 15602 V mpvstats: AV: 1513.296 A-V: 0.000 Dropped: 5 Cache: 27.110s + 0KB
04-02 00:28:54.337 15602 15602 V mpvstats: AV: 1516.299 A-V: 0.000 Dropped: 5 Cache: 28.390s + 0KB
04-02 00:28:57.338 15602 15602 V mpvstats: AV: 1519.302 A-V: 0.000 Dropped: 5 Cache: 29.499s + 0KB
04-02 00:29:00.339 15602 15602 V mpvstats: AV: 1522.305 A-V: 0.000 Dropped: 5 Cache: 33.169s + 0KB
04-02 00:29:03.340 15602 15602 V mpvstats: AV: 1525.308 A-V: 0.000 Dropped: 5 Cache: 30.182s + 0KB
04-02 00:29:06.341 15602 15602 V mpvstats: AV: 1528.311 A-V: 0.000 Dropped: 5 Cache: 31.121s + 0KB
04-02 00:29:09.341 15602 15602 V mpvstats: AV: 1531.314 A-V: 0.000 Dropped: 5 Cache: 28.134s + 0KB
04-02 00:29:12.343 15602 15602 V mpvstats: AV: 1534.317 A-V: 0.000 Dropped: 5 Cache: 25.147s + 0KB
04-02 00:29:14.900 15602 15648 V mpv : [vd] Decoder format: 1280x720 [0:1] yuv420p bt.709/bt.709/bt.1886/limited/auto CL=mpeg1/jpeg (auto 0.000000/0.000000/0.000000)
04-02 00:29:14.900 15602 15648 V mpv : [vd] Forcing user-set aspect ratio.
04-02 00:29:14.900 15602 15648 V mpv : [vf] [in] 1280x720 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:14.916 15602 15648 V mpv : event: video-reconfig
04-02 00:29:14.916 15602 15648 V mpv : [vf] [userdeint] 1280x720 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:14.916 15602 15648 V mpv : [vf] [autorotate] 1280x720 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:14.916 15602 15648 V mpv : [vf] [convert] 1280x720 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:14.916 15602 15648 V mpv : [vf] [out] 1280x720 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:14.948 15602 15648 I mpv : [cplayer] VO: [gpu] 1280x720 => 1280x720 yuv420p
04-02 00:29:14.948 15602 15648 V mpv : [cplayer] VO: Description: Shader-based GPU Renderer
04-02 00:29:14.953 15602 15648 V mpv : event: video-reconfig
04-02 00:29:15.344 15602 15602 V mpvstats: AV: 1537.320 A-V: 0.001 Dropped: 0 Cache: 22.144s + 0KB
04-02 00:29:15.572 15602 15602 V mpvstats: AV: 1537.554 A-V: 0.001 Dropped: 0 Cache: 21.888s + 0KB
04-02 00:29:18.345 15602 15602 V mpvstats: AV: 1540.323 A-V: 0.000 Dropped: 0 Cache: 19.712s + 0KB
04-02 00:29:21.346 15602 15602 V mpvstats: AV: 1543.326 A-V: 0.000 Dropped: 0 Cache: 32.085s + 0KB
04-02 00:29:23.819 15602 15612 I ls.dvr.app.bet: Background concurrent copying GC freed 310046(12MB) AllocSpace objects, 0(0B) LOS objects, 49% free, 12MB/25MB, paused 166us total 116.692ms
04-02 00:29:24.347 15602 15602 V mpvstats: AV: 1546.329 A-V: 0.000 Dropped: 0 Cache: 33.195s + 0KB
04-02 00:29:27.349 15602 15602 V mpvstats: AV: 1549.332 A-V: 0.000 Dropped: 0 Cache: 30.165s + 0KB
04-02 00:29:29.792 15602 15648 D mpv : [ffmpeg/video] h264: Reinit context to 1920x1088, pix_fmt: yuv420p
04-02 00:29:29.919 15602 15648 V mpv : [vd] Decoder format: 1920x1080 [0:1] yuv420p bt.709/bt.709/bt.1886/limited/auto CL=mpeg1/jpeg (auto 0.000000/0.000000/0.000000)
04-02 00:29:29.919 15602 15648 V mpv : [vd] Forcing user-set aspect ratio.
04-02 00:29:29.919 15602 15648 V mpv : [vf] [in] 1920x1080 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:29.927 15602 15648 V mpv : event: video-reconfig
04-02 00:29:29.927 15602 15648 V mpv : [vf] [userdeint] 1920x1080 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:29.927 15602 15648 V mpv : [vf] [autorotate] 1920x1080 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:29.927 15602 15648 V mpv : [vf] [convert] 1920x1080 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:29.927 15602 15648 V mpv : [vf] [out] 1920x1080 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:29.957 15602 15648 I mpv : [cplayer] VO: [gpu] 1920x1080 => 1920x1080 yuv420p
04-02 00:29:29.957 15602 15648 V mpv : [cplayer] VO: Description: Shader-based GPU Renderer
04-02 00:29:29.958 15602 15648 V mpv : event: video-reconfig
04-02 00:29:30.350 15602 15602 V mpvstats: AV: 1552.339 A-V: 0.000 Dropped: 0 Cache: 31.275s + 0KB
04-02 00:29:33.350 15602 15602 V mpvstats: AV: 1555.342 A-V: 0.000 Dropped: 0 Cache: 28.203s + 0KB
04-02 00:29:36.353 15602 15602 V mpvstats: AV: 1558.351 A-V: 0.000 Dropped: 0 Cache: 29.397s + 0KB
04-02 00:29:39.355 15602 15602 V mpvstats: AV: 1561.361 A-V: 0.000 Dropped: 0 Cache: 26.411s + 0KB
04-02 00:29:42.356 15602 15602 V mpvstats: AV: 1564.337 A-V: 0.000 Dropped: 0 Cache: 23.424s + 0KB
04-02 00:29:45.356 15602 15602 V mpvstats: AV: 1567.340 A-V: 0.000 Dropped: 0 Cache: 20.437s + 0KB
04-02 00:29:48.356 15602 15602 V mpvstats: AV: 1570.350 A-V: 0.000 Dropped: 0 Cache: 17.365s + 0KB
04-02 00:29:51.359 15602 15602 V mpvstats: AV: 1573.360 A-V: 0.000 Dropped: 0 Cache: 14.336s + 0KB
04-02 00:29:54.361 15602 15602 V mpvstats: AV: 1576.369 A-V: 0.000 Dropped: 0 Cache: 11.349s + 0KB
04-02 00:29:57.362 15602 15602 V mpvstats: AV: 1579.372 A-V: 0.000 Dropped: 0 Cache: 8.363s + 0KB
04-02 00:29:57.863 15602 15648 D mpv : [ffmpeg/video] h264: Reinit context to 1280x720, pix_fmt: yuv420p
04-02 00:29:58.000 15602 15648 V mpv : [vd] Decoder format: 1280x720 yuv420p bt.709/bt.709/bt.1886/limited/auto CL=mpeg1/jpeg (auto 0.000000/0.000000/0.000000)
04-02 00:29:58.001 15602 15648 V mpv : [vd] Forcing user-set aspect ratio.
04-02 00:29:58.002 15602 15648 V mpv : [vf] [in] 1280x720 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:58.033 15602 15648 V mpv : [vf] [userdeint] 1280x720 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:58.034 15602 15648 V mpv : event: video-reconfig
04-02 00:29:58.034 15602 15648 V mpv : event: video-reconfig
04-02 00:29:58.034 15602 15648 V mpv : [vf] [autorotate] 1280x720 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:58.034 15602 15648 V mpv : [vf] [convert] 1280x720 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:58.034 15602 15648 V mpv : [vf] [out] 1280x720 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:58.038 15602 15648 I mpv : [cplayer] VO: [gpu] 1280x720 => 1280x720 yuv420p
04-02 00:29:58.038 15602 15648 V mpv : [cplayer] VO: Description: Shader-based GPU Renderer
04-02 00:30:00.365 15602 15602 V mpvstats: AV: 1582.365 A-V: 0.000 Dropped: 0 Cache: 5.376s + 0KB
04-02 00:30:03.366 15602 15602 V mpvstats: AV: 1585.368 A-V: 0.000 Dropped: 0 Cache: 5.291s + 0KB
04-02 00:30:06.366 15602 15602 V mpvstats: AV: 1588.371 A-V: 0.000 Dropped: 0 Cache: 2.304s + 0KB
04-02 00:30:08.846 15602 15648 V mpv : event: unpause
04-02 00:30:08.847 15602 15648 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 23%) [0.233578s].
04-02 00:30:08.847 15602 15648 V mpv : property: buffering = true
04-02 00:30:08.847 15602 15602 V PlayerActivity: state PLAYING -> BUFFERING
04-02 00:30:08.848 15602 15602 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=1543.1258221111111, end=1590.2398443333334}], cache-end=1591.174111, reader-pts=1590.9405332222223, cache-duration=0.2335777777777821, eof=false, underrun=true, idle=false, total-bytes=31728768, fw-bytes=124928, debug-low-level-seeks=0, debug-ts-last=1590.1731223333334, ts-per-stream=[{type=video, duration=0.2335777777777821, reader=1590.9572222222223, end=1591.1908}, {type=audio, duration=0.0, reader=1591.199011111111, end=1591.199011111111}]}
04-02 00:30:09.367 15602 15602 V mpvstats: AV: 1590.857 A-V: 0.000 Dropped: 0 Cache: 0.234s + 0KB
04-02 00:30:12.368 15602 15602 V mpvstats: AV: 1590.857 A-V: 0.000 Dropped: 0 Cache: 0.234s + 0KB
04-02 00:30:13.722 15602 22455 V ApiServer: REQUEST: GET /log
04-02 00:30:13.726 15602 22455 I hls : goroutine 17 [running, locked to thread]:
04-02 00:30:13.726 15602 22455 I hls : main.FullStackTrace(0x9204c070, 0x92038f50)
04-02 00:30:13.726 15602 22455 I hls : /Users/fancybox/source/channels-android/vendor/libhls/channels-server/hls/libhls/hls_c.go:249 +0x80
04-02 00:30:13.726 15602 22455 I hls : main.hls_log_stack()
04-02 00:30:13.726 15602 22455 I hls : /Users/fancybox/source/channels-android/vendor/libhls/channels-server/hls/libhls/hls_c.go:259 +0x14
04-02 00:30:13.726 15602 22455 I hls : main._cgoexpwrap_277a0c6059f4_hls_log_stack()
04-02 00:30:13.726 15602 22455 I hls : _cgo_gotypes.go:299 +0x14
04-02 00:30:13.726 15602 22455 I hls :
04-02 00:30:13.726 15602 22455 I hls : goroutine 6 [syscall]:
04-02 00:30:13.726 15602 22455 I hls : os/signal.signal_recv(0x0)
04-02 00:30:13.726 15602 22455 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/runtime/sigqueue.go:147 +0x14c
04-02 00:30:13.726 15602 22455 I hls : os/signal.loop()
04-02 00:30:13.726 15602 22455 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/os/signal/signal_unix.go:23 +0x14
04-02 00:30:13.726 15602 22455 I hls : created by os/signal.Notify.func1
04-02 00:30:13.726 15602 22455 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/os/signal/signal.go:127 +0x38
04-02 00:30:13.726 15602 22455 I hls :
04-02 00:30:13.726 15602 22455 I hls : goroutine 19 [select]:
04-02 00:30:13.726 15602 22455 I hls : github.com/grafov/kiwi.processSink(0x92096080)
04-02 00:30:13.726 15602 22455 I hls : /Users/fancybox/go/pkg/mod/github.com/grafov/[email protected]/sink.go:327 +0x90
04-02 00:30:13.726 15602 22455 I hls : created by github.com/grafov/kiwi.SinkTo
04-02 00:30:13.726 15602 22455 I hls : /Users/fancybox/go/pkg/mod/github.com/grafov/[email protected]/sink.go:111 +0x310
04-02 00:30:15.369 15602 15602 V mpvstats: AV: 1590.857 A-V: 0.000 Dropped: 0 Cache: 0.234s + 0KB
04-02 00:30:18.370 15602 15602 V mpvstats: AV: 1590.857 A-V: 0.000 Dropped: 0 Cache: 0.234s + 0KB
04-02 00:30:21.371 15602 15602 V mpvstats: AV: 1590.857 A-V: 0.000 Dropped: 0 Cache: 0.234s + 0KB
04-02 00:30:24.371 15602 15602 V mpvstats: AV: 1590.857 A-V: 0.000 Dropped: 0 Cache: 0.234s + 0KB
04-02 00:30:27.183 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 23% -> 17%) [0.170667s].
04-02 00:30:27.190 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 17% -> 41%) [0.417100s].
04-02 00:30:27.198 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 41% -> 25%) [0.256000s].
04-02 00:30:27.227 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 25% -> 89%) [0.896000s].
04-02 00:30:27.372 15602 15602 V mpvstats: AV: 1590.857 A-V: 0.000 Dropped: 0 Cache: 2.005s + 0KB
04-02 00:30:27.431 15602 15648 V mpv : event: unpause
04-02 00:30:27.432 15602 15648 V mpv : [cplayer] End buffering (waited 18.584090 secs) [2.005333s].
04-02 00:30:27.435 15602 15648 V mpv : property: buffering = false
04-02 00:30:27.435 15602 15602 V PlayerActivity: state BUFFERING -> PLAYING
04-02 00:30:27.621 15602 15602 V mpvstats: AV: 1591.258 A-V: 0.000 Dropped: 13 Cache: 1.664s + 0KB
04-02 00:30:29.389 15602 15648 V mpv : event: unpause
04-02 00:30:29.389 15602 15648 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 23%) [0.233578s].
04-02 00:30:29.389 15602 15648 V mpv : property: buffering = true
04-02 00:30:29.390 15602 15602 V PlayerActivity: state PLAYING -> BUFFERING
04-02 00:30:29.391 15602 15602 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=1547.1965443333333, end=1592.3252665555556}], cache-end=1593.3429443333334, reader-pts=1593.1093665555557, cache-duration=0.2335777777777821, eof=false, underrun=true, idle=false, total-bytes=31192896, fw-bytes=136000, debug-low-level-seeks=0, debug-ts-last=1593.0593223333335, ts-per-stream=[{type=video, duration=0.2335777777777821, reader=1593.1260555555557, end=1593.3596333333335}, {type=audio, duration=0.0, reader=1593.3750111111112, end=1593.3750111111112}]}
04-02 00:30:30.373 15602 15602 V mpvstats: AV: 1593.026 A-V: 0.000 Dropped: 13 Cache: 0.234s + 0KB
04-02 00:30:33.374 15602 15602 V mpvstats: AV: 1593.026 A-V: 0.000 Dropped: 13 Cache: 0.234s + 0KB
04-02 00:30:34.208 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 23% -> 4%) [0.042667s].
04-02 00:30:34.210 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 4% -> 30%) [0.300311s].
04-02 00:30:34.219 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 30% -> 4%) [0.042667s].
04-02 00:30:34.219 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 4% -> 35%) [0.350356s].
04-02 00:30:34.219 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 35% -> 4%) [0.042667s].
04-02 00:30:34.222 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 4% -> 38%) [0.383733s].
04-02 00:30:34.224 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 38% -> 4%) [0.042667s].
04-02 00:30:34.225 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 4% -> 40%) [0.400411s].
04-02 00:30:34.263 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 40% -> 76%) [0.768000s].
04-02 00:30:34.365 15602 15610 W System : A resource failed to call end.
04-02 00:30:34.454 15602 15648 V mpv : event: unpause
04-02 00:30:34.455 15602 15648 V mpv : [cplayer] End buffering (waited 5.063865 secs) [2.389333s].
04-02 00:30:34.455 15602 15648 V mpv : property: buffering = false
04-02 00:30:34.455 15602 15602 V PlayerActivity: state BUFFERING -> PLAYING
04-02 00:30:34.650 15602 15602 V mpvstats: AV: 1593.410 A-V: 0.000 Dropped: 28 Cache: 2.048s + 0KB
04-02 00:30:36.375 15602 15602 V mpvstats: AV: 1595.145 A-V: 0.000 Dropped: 28 Cache: 0.256s + 0KB
04-02 00:30:36.842 15602 15648 V mpv : event: unpause
04-02 00:30:36.842 15602 15648 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 23%) [0.233567s].
04-02 00:30:36.842 15602 15648 V mpv : property: buffering = true
04-02 00:30:36.843 15602 15602 V PlayerActivity: state PLAYING -> BUFFERING
04-02 00:30:36.844 15602 15602 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=1549.2652776666666, end=1594.3272665555555}], cache-end=1595.9288665555555, reader-pts=1595.695299888889, cache-duration=0.23356666666654746, eof=false, underrun=true, idle=false, total-bytes=31842752, fw-bytes=161984, debug-low-level-seeks=0, debug-ts-last=1595.628555666667, ts-per-stream=[{type=video, duration=0.23356666666654746, reader=1595.711988888889, end=1595.9455555555555}, {type=audio, duration=0.0, reader=1595.9350111111112, end=1595.9350111111112}]}
04-02 00:30:39.376 15602 15602 V mpvstats: AV: 1595.612 A-V: 0.000 Dropped: 28 Cache: 0.234s + 0KB
04-02 00:30:41.590 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 23% -> 8%) [0.085333s].
04-02 00:30:41.593 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 8% -> 35%) [0.350333s].
04-02 00:30:41.602 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 35% -> 4%) [0.042667s].
04-02 00:30:41.606 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 4% -> 36%) [0.367022s].
04-02 00:30:41.606 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 36% -> 4%) [0.042667s].
04-02 00:30:41.608 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 4% -> 8%) [0.085333s].
04-02 00:30:41.609 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 8% -> 12%) [0.128000s].
04-02 00:30:41.609 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 12% -> 17%) [0.170667s].
04-02 00:30:41.609 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 17% -> 21%) [0.213333s].
04-02 00:30:41.643 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 21% -> 46%) [0.469333s].
04-02 00:30:41.709 15602 15648 V mpv : event: unpause
04-02 00:30:41.709 15602 15648 V mpv : [cplayer] End buffering (waited 4.865330 secs) [1.536000s].
04-02 00:30:41.719 15602 15648 V mpv : property: buffering = false
04-02 00:30:41.719 15602 15602 V PlayerActivity: state BUFFERING -> PLAYING
04-02 00:30:42.377 15602 15602 V mpvstats: AV: 1596.429 A-V: 0.000 Dropped: 44 Cache: 3.541s + 0KB
04-02 00:30:42.671 15602 15602 V mpvstats: AV: 1596.713 A-V: 0.000 Dropped: 44 Cache: 3.285s + 0KB
04-02 00:30:44.403 15602 22469 V ApiServer: REQUEST: GET /log
04-02 00:30:44.403 15602 22469 I hls : goroutine 17 [running, locked to thread]:
04-02 00:30:44.403 15602 22469 I hls : main.FullStackTrace(0x9204c070, 0x92038f50)
04-02 00:30:44.403 15602 22469 I hls : /Users/fancybox/source/channels-android/vendor/libhls/channels-server/hls/libhls/hls_c.go:249 +0x80
04-02 00:30:44.403 15602 22469 I hls : main.hls_log_stack()
04-02 00:30:44.403 15602 22469 I hls : /Users/fancybox/source/channels-android/vendor/libhls/channels-server/hls/libhls/hls_c.go:259 +0x14
04-02 00:30:44.403 15602 22469 I hls : main._cgoexpwrap_277a0c6059f4_hls_log_stack()
04-02 00:30:44.403 15602 22469 I hls : _cgo_gotypes.go:299 +0x14
04-02 00:30:44.403 15602 22469 I hls :
04-02 00:30:44.403 15602 22469 I hls : goroutine 6 [syscall]:
04-02 00:30:44.403 15602 22469 I hls : os/signal.signal_recv(0x0)
04-02 00:30:44.403 15602 22469 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/runtime/sigqueue.go:147 +0x14c
04-02 00:30:44.403 15602 22469 I hls : os/signal.loop()
04-02 00:30:44.403 15602 22469 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/os/signal/signal_unix.go:23 +0x14
04-02 00:30:44.403 15602 22469 I hls : created by os/signal.Notify.func1
04-02 00:30:44.403 15602 22469 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/os/signal/signal.go:127 +0x38
04-02 00:30:44.403 15602 22469 I hls :
04-02 00:30:44.403 15602 22469 I hls : goroutine 19 [select]:
04-02 00:30:44.403 15602 22469 I hls : github.com/grafov/kiwi.processSink(0x92096080)
04-02 00:30:44.403 15602 22469 I hls : /Users/fancybox/go/pkg/mod/github.com/grafov/[email protected]/sink.go:327 +0x90
04-02 00:30:44.403 15602 22469 I hls : created by github.com/grafov/kiwi.SinkTo
04-02 00:30:44.403 15602 22469 I hls : /Users/fancybox/go/pkg/mod/github.com/grafov/[email protected]/sink.go:111 +0x310That looks like a different issue, unrelated to audio. Seems more like a regular buffering event not split-second pause.
It isn't any different, it is exactly the same, the log is exactly the same too.
type=audio, duration=0.0
Watch the video I posted earlier that shows the buffering and the time bar growing.
The split second pausing was fixed by using a different decoder.
As I said before, if I was recording the same program, the recording never experiences the same issue. It only happens watching live.
EDIT: Does using Transcoding on the server bypas the Live TV Buffer on the Client? I don't see any action in the Client log while transcoding.
No it's not. The "End buffering" lines show much longer wait times.
This doesn't matter anymore with the new beta because it does not pause when audio is 0.0, only when video packets run out.
I understand that. I don't have an explanation for how that's possible because live tv and recordings use the same player.
Yes.
It's really challenging to help you because you constantly keep switching devices. Can you please stick to one device and one bug at a time? Are you still having issues on the Sony TV, and if so what is happening?
1 Like
My fox news is back to buffering like crazy again today, dang made it almost 2 days.. diag submitted 1:25
OK I rebooted the SONY TV and started a new stream from Fox News TVE.
I've been following the LOG and I just had a pause event and saw this error.
**04-02 14:45:57.945 6854 6957 E mpv : [ffmpeg/video] h264: error while decoding MB 55 18, bytestream -11**
**04-02 14:45:57.947 6854 6957 V mpv : [ffmpeg/video] h264: concealing 2154 DC, 2154 AC, 2154 MV errors in P frame**
Could this be something?
Here is the LOG of the Event:
04-02 14:43:12.927 6854 6957 D mpv : [ffmpeg/video] h264: Reinit context to 1280x720, pix_fmt: yuv420p
04-02 14:43:13.060 6854 6957 V mpv : [vd] Decoder format: 1280x720 yuv420p auto/auto/auto/auto/auto CL=mpeg2/4/h264 (auto 0.000000/0.000000/0.000000)
04-02 14:43:13.061 6854 6957 V mpv : [vf] [in] 1280x720 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
04-02 14:43:13.091 6854 6957 V mpv : [vf] [userdeint] 1280x720 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
04-02 14:43:13.092 6854 6957 V mpv : [vf] [autorotate] 1280x720 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
04-02 14:43:13.092 6854 6957 V mpv : [vf] [convert] 1280x720 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
04-02 14:43:13.092 6854 6957 V mpv : [vf] [out] 1280x720 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
04-02 14:43:13.092 6854 6957 I mpv : [cplayer] VO: [gpu] 1280x720 yuv420p
04-02 14:43:13.092 6854 6957 V mpv : event: video-reconfig
04-02 14:43:13.096 6854 6957 V mpv : event: video-reconfig
04-02 14:43:13.096 6854 6957 V mpv : [cplayer] VO: Description: Shader-based GPU Renderer
04-02 14:43:15.737 6854 6854 V mpvstats: AV: 1464.856 A-V: 0.000 Dropped: 0 Cache: 9.131s + 0KB
04-02 14:43:18.739 6854 6854 V mpvstats: AV: 1467.859 A-V: 0.000 Dropped: 0 Cache: 10.155s + 0KB
04-02 14:43:21.741 6854 6854 V mpvstats: AV: 1470.862 A-V: 0.000 Dropped: 0 Cache: 11.264s + 0KB
04-02 14:43:24.743 6854 6854 V mpvstats: AV: 1473.865 A-V: 0.000 Dropped: 0 Cache: 12.373s + 0KB
04-02 14:43:27.745 6854 6854 V mpvstats: AV: 1476.868 A-V: 0.000 Dropped: 0 Cache: 13.483s + 0KB
04-02 14:43:30.747 6854 6854 V mpvstats: AV: 1479.871 A-V: 0.000 Dropped: 0 Cache: 10.581s + 0KB
04-02 14:43:33.747 6854 6854 V mpvstats: AV: 1482.874 A-V: 0.001 Dropped: 0 Cache: 11.648s + 0KB
04-02 14:43:36.748 6854 6854 V mpvstats: AV: 1485.877 A-V: 0.000 Dropped: 0 Cache: 12.587s + 0KB
04-02 14:43:39.749 6854 6854 V mpvstats: AV: 1488.880 A-V: 0.000 Dropped: 0 Cache: 11.605s + 0KB
04-02 14:43:42.750 6854 6854 V mpvstats: AV: 1491.883 A-V: 0.000 Dropped: 0 Cache: 10.795s + 0KB
04-02 14:43:45.751 6854 6854 V mpvstats: AV: 1494.886 A-V: 0.000 Dropped: 0 Cache: 11.861s + 0KB
04-02 14:43:48.752 6854 6854 V mpvstats: AV: 1497.872 A-V: 0.000 Dropped: 0 Cache: 13.013s + 0KB
04-02 14:43:51.754 6854 6854 V mpvstats: AV: 1500.875 A-V: 0.000 Dropped: 0 Cache: 13.995s + 0KB
04-02 14:43:54.755 6854 6854 V mpvstats: AV: 1503.878 A-V: 0.000 Dropped: 0 Cache: 10.965s + 0KB
04-02 14:43:57.756 6854 6854 V mpvstats: AV: 1506.881 A-V: 0.000 Dropped: 0 Cache: 12.117s + 0KB
04-02 14:44:00.757 6854 6854 V mpvstats: AV: 1509.884 A-V: 0.000 Dropped: 0 Cache: 13.227s + 0KB
04-02 14:44:03.758 6854 6854 V mpvstats: AV: 1512.887 A-V: 0.000 Dropped: 0 Cache: 14.251s + 0KB
04-02 14:44:06.759 6854 6854 V mpvstats: AV: 1515.890 A-V: 0.000 Dropped: 0 Cache: 11.349s + 0KB
04-02 14:44:09.759 6854 6854 V mpvstats: AV: 1518.893 A-V: 0.000 Dropped: 0 Cache: 12.416s + 0KB
04-02 14:44:12.760 6854 6854 V mpvstats: AV: 1521.880 A-V: 0.000 Dropped: 0 Cache: 13.568s + 0KB
04-02 14:44:15.761 6854 6854 V mpvstats: AV: 1524.899 A-V: 0.000 Dropped: 0 Cache: 13.867s + 0KB
04-02 14:44:18.762 6854 6854 V mpvstats: AV: 1527.886 A-V: 0.000 Dropped: 0 Cache: 11.648s + 0KB
04-02 14:44:21.763 6854 6854 V mpvstats: AV: 1530.889 A-V: 0.000 Dropped: 0 Cache: 12.757s + 0KB
04-02 14:44:24.766 6854 6854 V mpvstats: AV: 1533.892 A-V: 0.000 Dropped: 0 Cache: 13.867s + 0KB
04-02 14:44:27.766 6854 6854 V mpvstats: AV: 1536.895 A-V: 0.000 Dropped: 0 Cache: 10.880s + 0KB
04-02 14:44:30.767 6854 6854 V mpvstats: AV: 1539.898 A-V: 0.000 Dropped: 0 Cache: 7.808s + 0KB
04-02 14:44:33.768 6854 6854 V mpvstats: AV: 1542.901 A-V: 0.000 Dropped: 0 Cache: 13.013s + 0KB
04-02 14:44:36.769 6854 6854 V mpvstats: AV: 1545.904 A-V: 0.000 Dropped: 0 Cache: 10.027s + 0KB
04-02 14:44:39.769 6854 6854 V mpvstats: AV: 1548.907 A-V: 0.000 Dropped: 0 Cache: 6.997s + 0KB
04-02 14:44:42.770 6854 6854 V mpvstats: AV: 1551.893 A-V: 0.000 Dropped: 0 Cache: 4.011s + 0KB
04-02 14:44:45.770 6854 6854 V mpvstats: AV: 1554.896 A-V: 0.000 Dropped: 0 Cache: 1.024s + 0KB
04-02 14:44:46.709 6854 6957 V mpv : event: unpause
04-02 14:44:46.709 6854 6957 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 46%) [0.467122s].
04-02 14:44:46.709 6854 6957 V mpv : property: buffering = true
04-02 14:44:46.709 6854 6854 V PlayerActivity: state PLAYING -> BUFFERING
04-02 14:44:46.712 6854 6854 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=1523.5978998888888, end=1556.3472887777777}], cache-end=1556.3806443333333, reader-pts=1555.9135221111112, cache-duration=0.46712222222208766, eof=false, underrun=true, idle=false, total-bytes=32547200, fw-bytes=592960, debug-low-level-seeks=0, debug-ts-last=1555.8134223333334, ts-per-stream=[{type=video, duration=0.46712222222208766, reader=1555.9302111111112, end=1556.3973333333333}, {type=audio, duration=0.0, reader=1556.4186333333334, end=1556.4186333333334}]}
04-02 14:44:48.770 6854 6854 V mpvstats: AV: 1555.847 A-V: 0.000 Dropped: 0 Cache: 0.467s + 0KB
04-02 14:44:51.771 6854 6854 V mpvstats: AV: 1555.847 A-V: 0.000 Dropped: 0 Cache: 0.467s + 0KB
04-02 14:44:54.772 6854 6854 V mpvstats: AV: 1555.847 A-V: 0.000 Dropped: 0 Cache: 0.467s + 0KB
04-02 14:44:55.079 6854 8919 V ApiServer: REQUEST: GET /log
04-02 14:44:55.079 6854 8919 I hls : goroutine 17 [running, locked to thread]:
04-02 14:44:55.079 6854 8919 I hls : main.FullStackTrace(0x8cc4c070, 0x8cc38f50)
04-02 14:44:55.079 6854 8919 I hls : /Users/fancybox/source/channels-android/vendor/libhls/channels-server/hls/libhls/hls_c.go:249 +0x80
04-02 14:44:55.079 6854 8919 I hls : main.hls_log_stack()
04-02 14:44:55.079 6854 8919 I hls : /Users/fancybox/source/channels-android/vendor/libhls/channels-server/hls/libhls/hls_c.go:259 +0x14
04-02 14:44:55.079 6854 8919 I hls : main._cgoexpwrap_277a0c6059f4_hls_log_stack()
04-02 14:44:55.079 6854 8919 I hls : _cgo_gotypes.go:299 +0x14
04-02 14:44:55.079 6854 8919 I hls :
04-02 14:44:55.079 6854 8919 I hls : goroutine 6 [syscall]:
04-02 14:44:55.079 6854 8919 I hls : os/signal.signal_recv(0x0)
04-02 14:44:55.079 6854 8919 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/runtime/sigqueue.go:147 +0x14c
04-02 14:44:55.079 6854 8919 I hls : os/signal.loop()
04-02 14:44:55.079 6854 8919 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/os/signal/signal_unix.go:23 +0x14
04-02 14:44:55.079 6854 8919 I hls : created by os/signal.Notify.func1
04-02 14:44:55.079 6854 8919 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/os/signal/signal.go:127 +0x38
04-02 14:44:55.079 6854 8919 I hls :
04-02 14:44:55.079 6854 8919 I hls : goroutine 19 [select]:
04-02 14:44:55.079 6854 8919 I hls : github.com/grafov/kiwi.processSink(0x8cd8e080)
04-02 14:44:55.079 6854 8919 I hls : /Users/fancybox/go/pkg/mod/github.com/grafov/[email protected]/sink.go:327 +0x90
04-02 14:44:55.079 6854 8919 I hls : created by github.com/grafov/kiwi.SinkTo
04-02 14:44:55.079 6854 8919 I hls : /Users/fancybox/go/pkg/mod/github.com/grafov/[email protected]/sink.go:111 +0x310
04-02 14:44:57.772 6854 6854 V mpvstats: AV: 1555.847 A-V: 0.000 Dropped: 0 Cache: 0.467s + 0KB
04-02 14:45:00.772 6854 6854 V mpvstats: AV: 1555.847 A-V: 0.000 Dropped: 0 Cache: 0.467s + 0KB
04-02 14:45:03.773 6854 6854 V mpvstats: AV: 1555.847 A-V: 0.000 Dropped: 0 Cache: 0.467s + 0KB
04-02 14:45:05.068 6854 8408 V Streamer: mpv read bytes:0 after retries:32000 (pos:1135542272)
04-02 14:45:06.774 6854 6854 V mpvstats: AV: 1555.847 A-V: 0.000 Dropped: 0 Cache: 0.484s + 0KB
04-02 14:45:09.775 6854 6854 V mpvstats: AV: 1555.847 A-V: 0.000 Dropped: 0 Cache: 0.484s + 0KB
04-02 14:45:12.776 6854 6854 V mpvstats: AV: 1555.847 A-V: 0.000 Dropped: 0 Cache: 0.484s + 0KB
04-02 14:45:15.777 6854 6854 V mpvstats: AV: 1555.847 A-V: 0.000 Dropped: 0 Cache: 0.484s + 0KB
04-02 14:45:18.777 6854 6854 V mpvstats: AV: 1555.847 A-V: 0.000 Dropped: 0 Cache: 0.469s + 0KB
04-02 14:45:18.921 6854 6957 V mpv : event: unpause
04-02 14:45:18.921 6854 6957 V mpv : [cplayer] End buffering (waited 32.207532 secs) [1.706667s].
04-02 14:45:18.930 6854 6957 V mpv : property: buffering = false
04-02 14:45:18.933 6854 6854 V PlayerActivity: state BUFFERING -> PLAYING
04-02 14:45:19.198 6854 6957 E mpv : [ffmpeg/video] h264: error while decoding MB 57 41, bytestream -6
04-02 14:45:19.200 6854 6957 V mpv : [ffmpeg/video] h264: concealing 312 DC, 312 AC, 312 MV errors in P frame
04-02 14:45:19.902 6854 6854 V mpvstats: AV: 1557.081 A-V: 0.000 Dropped: 19 Cache: 2.560s + 0KB
04-02 14:45:21.778 6854 6854 V mpvstats: AV: 1558.967 A-V: 0.000 Dropped: 19 Cache: 0.597s + 0KB
04-02 14:45:22.559 6854 6957 V mpv : event: unpause
04-02 14:45:22.559 6854 6957 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 23%) [0.233556s].
04-02 14:45:22.561 6854 6957 V mpv : property: buffering = true
04-02 14:45:22.561 6854 6854 V PlayerActivity: state PLAYING -> BUFFERING
04-02 14:45:22.562 6854 6854 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=1531.7894221111112, end=1558.432688777778}], cache-end=1560.0676665555557, reader-pts=1559.8341110000001, cache-duration=0.2335555555555402, eof=false, underrun=true, idle=false, total-bytes=31279296, fw-bytes=269632, debug-low-level-seeks=0, debug-ts-last=1559.7340001111113, ts-per-stream=[{type=video, duration=0.2335555555555402, reader=1559.8508000000002, end=1560.0843555555557}, {type=audio, duration=0.0, reader=1560.0879666666667, end=1560.0879666666667}]}
04-02 14:45:24.779 6854 6854 V mpvstats: AV: 1559.751 A-V: 0.000 Dropped: 19 Cache: 0.234s + 0KB
04-02 14:45:26.835 6854 8928 V ApiServer: REQUEST: GET /log
04-02 14:45:26.836 6854 8928 I hls : goroutine 17 [running, locked to thread]:
04-02 14:45:26.836 6854 8928 I hls : main.FullStackTrace(0x8cc4c070, 0x8cc38f50)
04-02 14:45:26.836 6854 8928 I hls : /Users/fancybox/source/channels-android/vendor/libhls/channels-server/hls/libhls/hls_c.go:249 +0x80
04-02 14:45:26.836 6854 8928 I hls : main.hls_log_stack()
04-02 14:45:26.836 6854 8928 I hls : /Users/fancybox/source/channels-android/vendor/libhls/channels-server/hls/libhls/hls_c.go:259 +0x14
04-02 14:45:26.836 6854 8928 I hls : main._cgoexpwrap_277a0c6059f4_hls_log_stack()
04-02 14:45:26.836 6854 8928 I hls : _cgo_gotypes.go:299 +0x14
04-02 14:45:26.836 6854 8928 I hls :
04-02 14:45:26.836 6854 8928 I hls : goroutine 6 [syscall]:
04-02 14:45:26.836 6854 8928 I hls : os/signal.signal_recv(0x0)
04-02 14:45:26.836 6854 8928 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/runtime/sigqueue.go:147 +0x14c
04-02 14:45:26.836 6854 8928 I hls : os/signal.loop()
04-02 14:45:26.836 6854 8928 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/os/signal/signal_unix.go:23 +0x14
04-02 14:45:26.836 6854 8928 I hls : created by os/signal.Notify.func1
04-02 14:45:26.836 6854 8928 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/os/signal/signal.go:127 +0x38
04-02 14:45:26.836 6854 8928 I hls :
04-02 14:45:26.836 6854 8928 I hls : goroutine 19 [select]:
04-02 14:45:26.836 6854 8928 I hls : github.com/grafov/kiwi.processSink(0x8cd8e080)
04-02 14:45:26.836 6854 8928 I hls : /Users/fancybox/go/pkg/mod/github.com/grafov/[email protected]/sink.go:327 +0x90
04-02 14:45:26.836 6854 8928 I hls : created by github.com/grafov/kiwi.SinkTo
04-02 14:45:26.836 6854 8928 I hls : /Users/fancybox/go/pkg/mod/github.com/grafov/[email protected]/sink.go:111 +0x310
04-02 14:45:27.779 6854 6854 V mpvstats: AV: 1559.751 A-V: 0.000 Dropped: 19 Cache: 0.234s + 0KB
04-02 14:45:30.780 6854 6854 V mpvstats: AV: 1559.751 A-V: 0.000 Dropped: 19 Cache: 0.234s + 0KB
04-02 14:45:33.781 6854 6854 V mpvstats: AV: 1559.751 A-V: 0.000 Dropped: 19 Cache: 0.234s + 0KB
04-02 14:45:36.781 6854 6854 I chatty : uid=10147(com.getchannels.dvr.app.beta) identical 1 line
04-02 14:45:39.782 6854 6854 V mpvstats: AV: 1559.751 A-V: 0.000 Dropped: 19 Cache: 0.234s + 0KB
04-02 14:45:42.783 6854 6854 V mpvstats: AV: 1559.751 A-V: 0.000 Dropped: 19 Cache: 0.234s + 0KB
04-02 14:45:45.784 6854 6854 V mpvstats: AV: 1559.751 A-V: 0.000 Dropped: 19 Cache: 0.234s + 0KB
04-02 14:45:48.784 6854 6854 V mpvstats: AV: 1559.751 A-V: 0.000 Dropped: 19 Cache: 0.234s + 0KB
04-02 14:45:50.213 6854 6862 W System : A resource failed to call end.
04-02 14:45:50.214 6854 6862 W System : A resource failed to call end.
04-02 14:45:51.549 6854 8408 V Streamer: mpv read bytes:0 after retries:32000 (pos:1140097024)
04-02 14:45:51.728 6854 6957 V mpv : [cplayer] Still buffering (buffer went from 23% -> 25%) [0.250244s].
04-02 14:45:51.787 6854 6854 V mpvstats: AV: 1559.751 A-V: 0.000 Dropped: 19 Cache: 0.250s + 0KB
04-02 14:45:54.787 6854 6854 V mpvstats: AV: 1559.751 A-V: 0.000 Dropped: 19 Cache: 0.250s + 0KB
04-02 14:45:57.530 6854 6957 V mpv : [cplayer] Still buffering (buffer went from 25% -> 4%) [0.042667s].
04-02 14:45:57.531 6854 6957 V mpv : [cplayer] Still buffering (buffer went from 4% -> 26%) [0.266911s].
04-02 14:45:57.545 6854 6957 V mpv : [cplayer] Still buffering (buffer went from 26% -> 28%) [0.283600s].
04-02 14:45:57.545 6854 6957 V mpv : [cplayer] Still buffering (buffer went from 28% -> 8%) [0.085333s].
04-02 14:45:57.547 6854 6957 V mpv : [cplayer] Still buffering (buffer went from 8% -> 41%) [0.417078s].
04-02 14:45:57.591 6854 6957 V mpv : [cplayer] Still buffering (buffer went from 41% -> 29%) [0.298667s].
04-02 14:45:57.739 6854 6957 V mpv : event: unpause
04-02 14:45:57.740 6854 6957 V mpv : [cplayer] End buffering (waited 35.177989 secs) [1.536000s].
04-02 14:45:57.747 6854 6957 V mpv : property: buffering = false
04-02 14:45:57.748 6854 6854 V PlayerActivity: state BUFFERING -> PLAYING
04-02 14:45:57.799 6854 6854 V mpvstats: AV: 1559.767 A-V: 0.199 Dropped: 19 Cache: 1.963s + 0KB
04-02 14:45:57.945 6854 6957 E mpv : [ffmpeg/video] h264: error while decoding MB 55 18, bytestream -11
04-02 14:45:57.947 6854 6957 V mpv : [ffmpeg/video] h264: concealing 2154 DC, 2154 AC, 2154 MV errors in P frame
04-02 14:45:58.013 6854 6854 V mpvstats: AV: 1559.767 A-V: 0.042 Dropped: 36 Cache: 3.627s + 0KB
04-02 14:45:59.014 6854 6854 V mpvstats: AV: 1561.169 A-V: 0.000 Dropped: 40 Cache: 11.093s + 0KB
04-02 14:46:00.800 6854 6854 V mpvstats: AV: 1562.954 A-V: 0.000 Dropped: 40 Cache: 29.099s + 0KB
04-02 14:46:03.801 6854 6854 V mpvstats: AV: 1565.957 A-V: 0.000 Dropped: 40 Cache: 59.563s + 0KB
04-02 14:46:06.803 6854 6854 V mpvstats: AV: 1568.960 A-V: 0.000 Dropped: 40 Cache: 81.109s + 0KB
04-02 14:46:09.803 6854 6854 V mpvstats: AV: 1571.946 A-V: 0.000 Dropped: 40 Cache: 78.080s + 0KB
04-02 14:46:12.805 6854 6854 V mpvstats: AV: 1574.949 A-V: 0.000 Dropped: 40 Cache: 79.104s + 0KB
04-02 14:46:15.806 6854 6854 V mpvstats: AV: 1577.969 A-V: 0.000 Dropped: 40 Cache: 80.256s + 0KB
04-02 14:46:18.807 6854 6854 V mpvstats: AV: 1580.955 A-V: 0.000 Dropped: 40 Cache: 81.323s + 0KB
04-02 14:46:21.807 6854 6854 V mpvstats: AV: 1583.958 A-V: 0.000 Dropped: 40 Cache: 78.336s + 0KB
04-02 14:46:24.808 6854 6854 V mpvstats: AV: 1586.961 A-V: 0.000 Dropped: 40 Cache: 79.445s + 0KB
04-02 14:46:27.809 6854 6854 V mpvstats: AV: 1589.964 A-V: 0.000 Dropped: 40 Cache: 80.555s + 0KB
04-02 14:46:29.951 6854 8937 V ApiServer: REQUEST: GET /logThis message is showing the root cause. The streamer is waiting for 32s to receive data and no more data is coming from the DVR server for the channel. This indicates a network issue, a bug on the DVR side, or an issue with the feed itself.
This seems to match what you're seeing in the video. It waited 48s before resuming playback.
This is unexpected too, it's saying there's corrupted video packets which should not happen for a TVE stream.
That's interesting, is there any reason why that would show up after the stream pauses and during buffering?
Do you have a recommendation of the best way to test the network to rule that out?
The message shows up when the streamer gives up, after trying for the previous 32 seconds.
There's a speedtest button in the app. Did you try that?
Yes and it always seems to be fine.
100mbps, 1.91 Latency and 0.77 Jitter
Here is what I get pinging to the server with my Laptop:
Pinging 192.168.5.101 with 32 bytes of data:
Reply from 192.168.5.101: bytes=32 time=3ms TTL=64
Reply from 192.168.5.101: bytes=32 time=7ms TTL=64
Reply from 192.168.5.101: bytes=32 time=4ms TTL=64
Reply from 192.168.5.101: bytes=32 time=5ms TTL=64
Ping statistics for 192.168.5.101:
Packets: Sent = 4, Received = 4, Lost = 0 (0% loss),
Approximate round trip times in milli-seconds:
Minimum = 3ms, Maximum = 7ms, Average = 4ms
and here are Pings to my TV with my Laptop.
Pinging 192.168.5.10 with 32 bytes of data:
Reply from 192.168.5.10: bytes=32 time=7ms TTL=64
Reply from 192.168.5.10: bytes=32 time=3ms TTL=64
Reply from 192.168.5.10: bytes=32 time=4ms TTL=64
Reply from 192.168.5.10: bytes=32 time=5ms TTL=64
Ping statistics for 192.168.5.10:
Packets: Sent = 4, Received = 4, Lost = 0 (0% loss),
Approximate round trip times in milli-seconds:
Minimum = 3ms, Maximum = 7ms, Average = 4ms
Can you try playing some other channel for a while and see if it hits the same problem?
Since the issue is intermittent you should leave an infinite ping running and then you can see if there were disruptions that match the time when the video stalled.
1 Like
I just tried to go into another channels and it wouldn't let me because the DV was still showing I was streaming Fox even though I stopped it 10 minutes ago. It finally released after a few tries from Fox then the stream started.
I just turned on Discovery
This was on Discovery TVE on the SonyTV:
04-02 15:23:27.162 6854 6957 V mpv : event: unpause
04-02 15:23:27.162 6854 6957 V mpv : [cplayer] End buffering (waited 0.765094 secs) [4.053333s].
04-02 15:23:27.168 6854 6957 V mpv : property: buffering = false
04-02 15:23:27.169 6854 6854 V PlayerActivity: state BUFFERING -> PLAYING
04-02 15:23:27.886 6854 6854 V mpvstats: AV: 7.903 A-V: 0.000 Dropped: 6 Cache: 7.339s + 0KB
04-02 15:23:28.904 6854 6854 V mpvstats: AV: 8.937 A-V: 0.000 Dropped: 6 Cache: 6.315s + 0KB
04-02 15:23:31.905 6854 6854 V mpvstats: AV: 11.940 A-V: 0.000 Dropped: 6 Cache: 7.424s + 0KB
04-02 15:23:34.905 6854 6854 V mpvstats: AV: 14.943 A-V: 0.000 Dropped: 6 Cache: 6.400s + 0KB
04-02 15:23:37.906 6854 6854 V mpvstats: AV: 17.946 A-V: 0.000 Dropped: 6 Cache: 5.461s + 0KB
04-02 15:23:40.906 6854 6854 V mpvstats: AV: 20.949 A-V: 0.000 Dropped: 6 Cache: 6.528s + 0KB
04-02 15:23:43.907 6854 6854 V mpvstats: AV: 23.952 A-V: 0.000 Dropped: 6 Cache: 7.595s + 0KB
04-02 15:23:46.908 6854 6854 V mpvstats: AV: 26.955 A-V: 0.000 Dropped: 6 Cache: 4.608s + 0KB
04-02 15:23:49.908 6854 6854 V mpvstats: AV: 29.925 A-V: 0.000 Dropped: 6 Cache: 5.675s + 0KB
04-02 15:23:52.910 6854 6854 V mpvstats: AV: 32.961 A-V: 0.000 Dropped: 6 Cache: 6.784s + 0KB
04-02 15:23:55.911 6854 6854 V mpvstats: AV: 35.931 A-V: 0.000 Dropped: 6 Cache: 7.936s + 0KB
04-02 15:23:58.910 6854 6854 V mpvstats: AV: 38.934 A-V: 0.000 Dropped: 6 Cache: 4.949s + 0KB
04-02 15:24:01.911 6854 6854 V mpvstats: AV: 41.937 A-V: 0.000 Dropped: 6 Cache: 6.144s + 0KB
04-02 15:24:04.912 6854 6854 V mpvstats: AV: 44.940 A-V: 0.000 Dropped: 6 Cache: 7.253s + 0KB
04-02 15:24:07.913 6854 6854 V mpvstats: AV: 47.943 A-V: 0.000 Dropped: 6 Cache: 8.235s + 0KB
04-02 15:24:10.914 6854 6854 V mpvstats: AV: 50.946 A-V: 0.000 Dropped: 6 Cache: 5.248s + 0KB
04-02 15:24:13.915 6854 6854 V mpvstats: AV: 53.949 A-V: 0.000 Dropped: 6 Cache: 6.357s + 0KB
04-02 15:24:16.916 6854 6854 V mpvstats: AV: 56.952 A-V: 0.000 Dropped: 6 Cache: 7.467s + 0KB
04-02 15:24:19.917 6854 6854 V mpvstats: AV: 59.955 A-V: 0.000 Dropped: 6 Cache: 8.576s + 0KB
04-02 15:24:22.917 6854 6854 V mpvstats: AV: 62.958 A-V: 0.000 Dropped: 6 Cache: 5.504s + 0KB
04-02 15:24:25.918 6854 6854 V mpvstats: AV: 65.961 A-V: 0.000 Dropped: 6 Cache: 6.613s + 0KB
04-02 15:24:28.919 6854 6854 V mpvstats: AV: 68.964 A-V: 0.000 Dropped: 6 Cache: 7.680s + 0KB
04-02 15:24:31.920 6854 6854 V mpvstats: AV: 71.967 A-V: 0.000 Dropped: 6 Cache: 8.789s + 0KB
04-02 15:24:34.921 6854 6854 V mpvstats: AV: 74.970 A-V: 0.000 Dropped: 6 Cache: 5.803s + 0KB
04-02 15:24:37.925 6854 6854 V mpvstats: AV: 77.940 A-V: 0.000 Dropped: 6 Cache: 6.869s + 0KB
04-02 15:24:40.926 6854 6854 V mpvstats: AV: 80.976 A-V: 0.000 Dropped: 6 Cache: 7.893s + 0KB
04-02 15:24:43.927 6854 6854 V mpvstats: AV: 83.979 A-V: 0.000 Dropped: 6 Cache: 9.003s + 0KB
04-02 15:24:46.928 6854 6854 V mpvstats: AV: 86.949 A-V: 0.000 Dropped: 6 Cache: 6.101s + 0KB
04-02 15:24:49.929 6854 6854 V mpvstats: AV: 89.952 A-V: 0.000 Dropped: 6 Cache: 7.253s + 0KB
04-02 15:24:52.929 6854 6854 V mpvstats: AV: 92.955 A-V: 0.000 Dropped: 6 Cache: 8.363s + 0KB
04-02 15:24:55.930 6854 6854 V mpvstats: AV: 95.958 A-V: 0.000 Dropped: 6 Cache: 9.429s + 0KB
04-02 15:24:58.931 6854 6854 V mpvstats: AV: 98.961 A-V: 0.000 Dropped: 6 Cache: 7.680s + 0KB
04-02 15:25:01.934 6854 6854 V mpvstats: AV: 101.964 A-V: 0.000 Dropped: 6 Cache: 7.424s + 0KB
04-02 15:25:04.934 6854 6854 V mpvstats: AV: 104.967 A-V: 0.000 Dropped: 6 Cache: 8.576s + 0KB
04-02 15:25:07.935 6854 6854 V mpvstats: AV: 107.970 A-V: 0.000 Dropped: 6 Cache: 9.643s + 0KB
04-02 15:25:10.936 6854 6854 V mpvstats: AV: 110.973 A-V: 0.000 Dropped: 6 Cache: 6.656s + 0KB
04-02 15:25:13.938 6854 6854 V mpvstats: AV: 113.976 A-V: 0.000 Dropped: 6 Cache: 7.680s + 0KB
04-02 15:25:16.939 6854 6854 V mpvstats: AV: 116.979 A-V: 0.000 Dropped: 6 Cache: 8.789s + 0KB
04-02 15:25:19.940 6854 6854 V mpvstats: AV: 119.982 A-V: 0.000 Dropped: 6 Cache: 9.941s + 0KB
04-02 15:25:22.941 6854 6854 V mpvstats: AV: 122.985 A-V: 0.000 Dropped: 6 Cache: 6.912s + 0KB
04-02 15:25:25.941 6854 6854 V mpvstats: AV: 125.988 A-V: 0.000 Dropped: 6 Cache: 8.021s + 0KB
04-02 15:25:28.942 6854 6854 V mpvstats: AV: 128.991 A-V: 0.000 Dropped: 6 Cache: 9.173s + 0KB
04-02 15:25:31.943 6854 6854 V mpvstats: AV: 131.994 A-V: 0.000 Dropped: 6 Cache: 6.101s + 0KB
04-02 15:25:34.945 6854 6854 V mpvstats: AV: 134.963 A-V: 0.000 Dropped: 6 Cache: 7.211s + 0KB
04-02 15:25:37.946 6854 6854 V mpvstats: AV: 137.966 A-V: 0.000 Dropped: 6 Cache: 8.363s + 0KB
04-02 15:25:40.947 6854 6854 V mpvstats: AV: 140.969 A-V: 0.000 Dropped: 6 Cache: 5.376s + 0KB
04-02 15:25:43.948 6854 6854 V mpvstats: AV: 143.972 A-V: 0.000 Dropped: 6 Cache: 6.485s + 0KB
04-02 15:25:46.949 6854 6854 V mpvstats: AV: 146.975 A-V: 0.000 Dropped: 6 Cache: 7.552s + 0KB
04-02 15:25:49.950 6854 6854 V mpvstats: AV: 149.978 A-V: 0.000 Dropped: 6 Cache: 4.565s + 0KB
04-02 15:25:52.950 6854 6854 V mpvstats: AV: 152.981 A-V: 0.000 Dropped: 6 Cache: 5.504s + 0KB
04-02 15:25:55.951 6854 6854 V mpvstats: AV: 155.984 A-V: 0.000 Dropped: 6 Cache: 6.613s + 0KB
04-02 15:25:57.887 6854 6864 I ls.dvr.app.bet: Background concurrent copying GC freed 514575(19MB) AllocSpace objects, 10(2MB) LOS objects, 49% free, 14MB/28MB, paused 195us total 123.081ms
04-02 15:25:57.902 6854 6862 W System : A resource failed to call end.
04-02 15:25:58.951 6854 6854 V mpvstats: AV: 158.987 A-V: 0.000 Dropped: 6 Cache: 7.765s + 0KB
04-02 15:26:01.952 6854 6854 V mpvstats: AV: 161.990 A-V: 0.000 Dropped: 6 Cache: 7.296s + 0KB
04-02 15:26:04.954 6854 6854 V mpvstats: AV: 164.993 A-V: 0.000 Dropped: 6 Cache: 5.931s + 0KB
04-02 15:26:07.955 6854 6854 V mpvstats: AV: 167.996 A-V: 0.000 Dropped: 6 Cache: 6.869s + 0KB
04-02 15:26:10.956 6854 6854 V mpvstats: AV: 170.999 A-V: 0.000 Dropped: 6 Cache: 8.021s + 0KB
04-02 15:26:13.956 6854 6854 V mpvstats: AV: 174.002 A-V: 0.000 Dropped: 6 Cache: 9.131s + 0KB
04-02 15:26:16.958 6854 6854 V mpvstats: AV: 177.005 A-V: 0.000 Dropped: 6 Cache: 6.229s + 0KB
04-02 15:26:19.959 6854 6854 V mpvstats: AV: 180.008 A-V: 0.000 Dropped: 6 Cache: 7.339s + 0KB
04-02 15:26:22.960 6854 6854 V mpvstats: AV: 183.011 A-V: 0.000 Dropped: 6 Cache: 8.405s + 0KB
04-02 15:26:25.962 6854 6854 V mpvstats: AV: 185.981 A-V: 0.000 Dropped: 6 Cache: 6.187s + 0KB
04-02 15:26:28.964 6854 6854 V mpvstats: AV: 188.984 A-V: 0.000 Dropped: 6 Cache: 6.400s + 0KB
04-02 15:26:31.965 6854 6854 V mpvstats: AV: 191.987 A-V: 0.000 Dropped: 6 Cache: 7.509s + 0KB
04-02 15:26:34.965 6854 6854 V mpvstats: AV: 194.990 A-V: 0.000 Dropped: 6 Cache: 8.661s + 0KB
04-02 15:26:37.966 6854 6854 V mpvstats: AV: 197.993 A-V: 0.000 Dropped: 6 Cache: 6.443s + 0KB
04-02 15:26:40.967 6854 6854 V mpvstats: AV: 200.996 A-V: 0.000 Dropped: 6 Cache: 6.784s + 0KB
04-02 15:26:43.969 6854 6854 V mpvstats: AV: 203.999 A-V: 0.000 Dropped: 6 Cache: 7.893s + 0KB
04-02 15:26:46.970 6854 6854 V mpvstats: AV: 207.002 A-V: 0.000 Dropped: 6 Cache: 8.917s + 0KB
04-02 15:26:49.971 6854 6854 V mpvstats: AV: 210.005 A-V: 0.000 Dropped: 6 Cache: 5.888s + 0KB
04-02 15:26:52.972 6854 6854 V mpvstats: AV: 213.008 A-V: 0.000 Dropped: 6 Cache: 2.901s + 0KB
04-02 15:26:55.931 6854 6957 V mpv : event: unpause
04-02 15:26:55.931 6854 6957 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 23%) [0.233556s].
04-02 15:26:55.931 6854 6957 V mpv : property: buffering = true
04-02 15:26:55.932 6854 6854 V PlayerActivity: state PLAYING -> BUFFERING
04-02 15:26:55.934 6854 6854 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=171.46647744444445, end=212.3739996666667}], cache-end=216.37799966666668, reader-pts=216.1444441111111, cache-duration=0.23355555555556862, eof=false, underrun=true, idle=false, total-bytes=29860736, fw-bytes=107968, debug-low-level-seeks=0, debug-ts-last=216.04434477777778, ts-per-stream=[{type=video, duration=0.23355555555556862, reader=216.1778111111111, end=216.41136666666668}, {type=audio, duration=0.0, reader=216.48136666666667, end=216.48136666666667}]}
04-02 15:26:55.982 6854 6854 V mpvstats: AV: 215.978 A-V: 0.000 Dropped: 6 Cache: 0.234s + 0KB
04-02 15:26:57.163 6854 6957 V mpv : event: unpause
04-02 15:26:57.164 6854 6957 V mpv : [cplayer] End buffering (waited 1.232014 secs) [1.749333s].
04-02 15:26:57.164 6854 6957 V mpv : property: buffering = false
04-02 15:26:57.164 6854 6854 V PlayerActivity: state BUFFERING -> PLAYING
04-02 15:26:58.036 6854 6854 V mpvstats: AV: 216.979 A-V: 0.000 Dropped: 10 Cache: 3.029s + 0KB
04-02 15:26:58.983 6854 6854 V mpvstats: AV: 217.913 A-V: 0.000 Dropped: 10 Cache: 2.091s + 0KB
04-02 15:27:01.984 6854 6854 V mpvstats: AV: 220.916 A-V: 0.000 Dropped: 10 Cache: 11.392s + 0KB
04-02 15:27:04.985 6854 6854 V mpvstats: AV: 223.919 A-V: 0.000 Dropped: 10 Cache: 8.405s + 0KB
04-02 15:27:07.986 6854 6854 V mpvstats: AV: 226.922 A-V: 0.000 Dropped: 10 Cache: 9.557s + 0KB
04-02 15:27:10.987 6854 6854 V mpvstats: AV: 229.925 A-V: 0.000 Dropped: 10 Cache: 10.581s + 0KB
04-02 15:27:12.127 6854 9724 V ApiServer: REQUEST: GET /log
04-02 15:27:12.127 6854 9724 I hls : goroutine 17 [running, locked to thread]:
04-02 15:27:12.127 6854 9724 I hls : main.FullStackTrace(0x8cc4c070, 0x8cc38f50)
04-02 15:27:12.127 6854 9724 I hls : /Users/fancybox/source/channels-android/vendor/libhls/channels-server/hls/libhls/hls_c.go:249 +0x80
04-02 15:27:12.127 6854 9724 I hls : main.hls_log_stack()
04-02 15:27:12.127 6854 9724 I hls : /Users/fancybox/source/channels-android/vendor/libhls/channels-server/hls/libhls/hls_c.go:259 +0x14
04-02 15:27:12.127 6854 9724 I hls : main._cgoexpwrap_277a0c6059f4_hls_log_stack()
04-02 15:27:12.127 6854 9724 I hls : _cgo_gotypes.go:299 +0x14
04-02 15:27:12.127 6854 9724 I hls :
04-02 15:27:12.127 6854 9724 I hls : goroutine 6 [syscall]:
04-02 15:27:12.127 6854 9724 I hls : os/signal.signal_recv(0x0)
04-02 15:27:12.127 6854 9724 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/runtime/sigqueue.go:147 +0x14c
04-02 15:27:12.127 6854 9724 I hls : os/signal.loop()
04-02 15:27:12.127 6854 9724 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/os/signal/signal_unix.go:23 +0x14
04-02 15:27:12.127 6854 9724 I hls : created by os/signal.Notify.func1
04-02 15:27:12.127 6854 9724 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/os/signal/signal.go:127 +0x38
04-02 15:27:12.127 6854 9724 I hls :
04-02 15:27:12.127 6854 9724 I hls : goroutine 19 [select]:
04-02 15:27:12.127 6854 9724 I hls : github.com/grafov/kiwi.processSink(0x8cd8e080)
04-02 15:27:12.127 6854 9724 I hls : /Users/fancybox/go/pkg/mod/github.com/grafov/[email protected]/sink.go:327 +0x90
04-02 15:27:12.127 6854 9724 I hls : created by github.com/grafov/kiwi.SinkTo
04-02 15:27:12.127 6854 9724 I hls : /Users/fancybox/go/pkg/mod/github.com/grafov/[email protected]/sink.go:111 +0x310
04-02 15:27:13.988 6854 6854 V mpvstats: AV: 232.928 A-V: 0.000 Dropped: 10 Cache: 11.605s + 0KB
04-02 15:27:16.989 6854 6854 V mpvstats: AV: 235.931 A-V: 0.000 Dropped: 10 Cache: 8.619s + 0KB
04-02 15:27:19.990 6854 6854 V mpvstats: AV: 238.934 A-V: 0.000 Dropped: 10 Cache: 9.728s + 0KB
04-02 15:27:22.991 6854 6854 V mpvstats: AV: 241.904 A-V: 0.000 Dropped: 10 Cache: 10.837s + 0KB
04-02 15:27:25.993 6854 6854 V mpvstats: AV: 244.907 A-V: 0.000 Dropped: 10 Cache: 7.851s + 0KB
04-02 15:27:28.993 6854 6854 V mpvstats: AV: 247.910 A-V: 0.000 Dropped: 10 Cache: 8.960s + 0KB
04-02 15:27:31.993 6854 6854 V mpvstats: AV: 250.913 A-V: 0.000 Dropped: 10 Cache: 6.059s + 0KB
04-02 15:27:34.994 6854 6854 V mpvstats: AV: 253.916 A-V: 0.000 Dropped: 10 Cache: 7.083s + 0KB
04-02 15:27:37.995 6854 6854 V mpvstats: AV: 256.919 A-V: 0.000 Dropped: 10 Cache: 8.192s + 0KB
04-02 15:27:40.996 6854 6854 V mpvstats: AV: 259.922 A-V: 0.000 Dropped: 10 Cache: 5.205s + 0KB
04-02 15:27:43.997 6854 6854 V mpvstats: AV: 262.925 A-V: 0.000 Dropped: 10 Cache: 2.219s + 0KB
04-02 15:27:46.218 6854 6957 V mpv : event: unpause
04-02 15:27:46.218 6854 6957 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 23%) [0.233578s].
04-02 15:27:46.219 6854 6957 V mpv : property: buffering = true
04-02 15:27:46.219 6854 6854 V PlayerActivity: state PLAYING -> BUFFERING
04-02 15:27:46.221 6854 6854 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=220.61556633333333, end=261.5231107777778}], cache-end=265.5604774444445, reader-pts=265.3268996666667, cache-duration=0.2335777777777821, eof=false, underrun=true, idle=false, total-bytes=29895104, fw-bytes=113856, debug-low-level-seeks=0, debug-ts-last=264.359267, ts-per-stream=[{type=video, duration=0.2335777777777821, reader=265.3602666666667, end=265.59384444444447}, {type=audio, duration=0.0, reader=265.6333666666667, end=265.6333666666667}]}
04-02 15:27:46.919 6854 6957 V mpv : [cplayer] Still buffering (buffer went from 23% -> 85%) [0.853333s].
04-02 15:27:46.976 6854 6957 V mpv : event: unpause
04-02 15:27:46.976 6854 6957 V mpv : [cplayer] End buffering (waited 0.757162 secs) [1.536000s].
04-02 15:27:46.977 6854 6957 V mpv : property: buffering = false
04-02 15:27:46.977 6854 6854 V PlayerActivity: state BUFFERING -> PLAYING
04-02 15:27:47.005 6854 6854 V mpvstats: AV: 265.227 A-V: 0.056 Dropped: 13 Cache: 1.792s + 0KB
04-02 15:27:47.074 6854 6854 V mpvstats: AV: 265.394 A-V: 0.000 Dropped: 14 Cache: 3.243s + 0KB
04-02 15:27:50.006 6854 6854 V mpvstats: AV: 268.297 A-V: 0.000 Dropped: 14 Cache: 9.088s + 0KB
04-02 15:27:52.154 6854 9732 V ApiServer: REQUEST: GET /log
04-02 15:27:52.155 6854 9732 I hls : goroutine 17 [running, locked to thread]:
04-02 15:27:52.155 6854 9732 I hls : main.FullStackTrace(0x8cc4c070, 0x8cc38f50)
04-02 15:27:52.155 6854 9732 I hls : /Users/fancybox/source/channels-android/vendor/libhls/channels-server/hls/libhls/hls_c.go:249 +0x80
04-02 15:27:52.155 6854 9732 I hls : main.hls_log_stack()
04-02 15:27:52.155 6854 9732 I hls : /Users/fancybox/source/channels-android/vendor/libhls/channels-server/hls/libhls/hls_c.go:259 +0x14
04-02 15:27:52.155 6854 9732 I hls : main._cgoexpwrap_277a0c6059f4_hls_log_stack()
04-02 15:27:52.155 6854 9732 I hls : _cgo_gotypes.go:299 +0x14
04-02 15:27:52.155 6854 9732 I hls :
04-02 15:27:52.155 6854 9732 I hls : goroutine 6 [syscall]:
04-02 15:27:52.155 6854 9732 I hls : os/signal.signal_recv(0x0)
04-02 15:27:52.155 6854 9732 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/runtime/sigqueue.go:147 +0x14c
04-02 15:27:52.155 6854 9732 I hls : os/signal.loop()
04-02 15:27:52.155 6854 9732 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/os/signal/signal_unix.go:23 +0x14
04-02 15:27:52.155 6854 9732 I hls : created by os/signal.Notify.func1
04-02 15:27:52.155 6854 9732 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/os/signal/signal.go:127 +0x38
04-02 15:27:52.155 6854 9732 I hls :
04-02 15:27:52.155 6854 9732 I hls : goroutine 19 [select]:
04-02 15:27:52.155 6854 9732 I hls : github.com/grafov/kiwi.processSink(0x8cd8e080)
04-02 15:27:52.155 6854 9732 I hls : /Users/fancybox/go/pkg/mod/github.com/grafov/[email protected]/sink.go:327 +0x90
04-02 15:27:52.155 6854 9732 I hls : created by github.com/grafov/kiwi.SinkTo
04-02 15:27:52.155 6854 9732 I hls : /Users/fancybox/go/pkg/mod/github.com/grafov/[email protected]/sink.go:111 +0x310
04-02 15:27:52.504 6854 6864 I ls.dvr.app.bet: Background concurrent copying GC freed 555578(16MB) AllocSpace objects, 18(5MB) LOS objects, 49% free, 14MB/28MB, paused 1.602ms total 100.335ms
04-02 15:27:52.505 6854 6862 W System : A resource failed to call end.
04-02 15:27:53.006 6854 6854 V mpvstats: AV: 271.300 A-V: 0.000 Dropped: 14 Cache: 10.240s + 0KB
04-02 15:27:56.009 6854 6854 V mpvstats: AV: 274.303 A-V: 0.000 Dropped: 14 Cache: 7.253s + 0KB
04-02 15:27:59.010 6854 6854 V mpvstats: AV: 277.306 A-V: 0.000 Dropped: 14 Cache: 8.235s + 0KB
04-02 15:28:02.011 6854 6854 V mpvstats: AV: 280.309 A-V: 0.000 Dropped: 14 Cache: 9.344s + 0KB
04-02 15:28:05.012 6854 6854 V mpvstats: AV: 283.312 A-V: 0.000 Dropped: 14 Cache: 10.411s + 0KB
04-02 15:28:08.013 6854 6854 V mpvstats: AV: 286.315 A-V: 0.000 Dropped: 14 Cache: 7.424s + 0KB
04-02 15:28:11.014 6854 6854 V mpvstats: AV: 289.318 A-V: 0.000 Dropped: 14 Cache: 8.576s + 0KB
04-02 15:28:14.018 6854 6854 V mpvstats: AV: 292.321 A-V: 0.000 Dropped: 14 Cache: 5.504s + 0KB
04-02 15:28:17.019 6854 6854 V mpvstats: AV: 295.324 A-V: 0.000 Dropped: 14 Cache: 10.709s + 0KB
04-02 15:28:20.021 6854 6854 V mpvstats: AV: 298.327 A-V: 0.000 Dropped: 14 Cache: 7.680s + 0KB
04-02 15:28:23.022 6854 6854 V mpvstats: AV: 301.330 A-V: 0.000 Dropped: 14 Cache: 8.832s + 0KB
04-02 15:28:26.023 6854 6854 V mpvstats: AV: 304.333 A-V: 0.000 Dropped: 14 Cache: 5.845s + 0KB
04-02 15:28:29.024 6854 6854 V mpvstats: AV: 307.336 A-V: 0.000 Dropped: 14 Cache: 6.869s + 0KB
04-02 15:28:32.026 6854 6854 V mpvstats: AV: 310.339 A-V: 0.000 Dropped: 14 Cache: 8.021s + 0KB
04-02 15:28:35.027 6854 6854 V mpvstats: AV: 313.342 A-V: 0.000 Dropped: 14 Cache: 9.131s + 0KB
04-02 15:28:38.028 6854 6854 V mpvstats: AV: 316.345 A-V: 0.000 Dropped: 14 Cache: 10.240s + 0KB
04-02 15:28:41.029 6854 6854 V mpvstats: AV: 319.348 A-V: 0.000 Dropped: 14 Cache: 11.307s + 0KB
04-02 15:28:44.030 6854 6854 V mpvstats: AV: 322.351 A-V: 0.000 Dropped: 14 Cache: 8.277s + 0KB
04-02 15:28:47.031 6854 6854 V mpvstats: AV: 325.354 A-V: 0.000 Dropped: 14 Cache: 9.429s + 0KB
04-02 15:28:50.032 6854 6854 V mpvstats: AV: 328.357 A-V: 0.000 Dropped: 14 Cache: 10.453s + 0KB
04-02 15:28:53.033 6854 6854 V mpvstats: AV: 331.360 A-V: 0.000 Dropped: 14 Cache: 11.563s + 0KB
04-02 15:28:56.034 6854 6854 V mpvstats: AV: 334.329 A-V: 0.000 Dropped: 14 Cache: 8.576s + 0KB
04-02 15:28:59.035 6854 6854 V mpvstats: AV: 337.332 A-V: 0.000 Dropped: 14 Cache: 9.643s + 0KB
04-02 15:29:02.037 6854 6854 V mpvstats: AV: 340.335 A-V: 0.000 Dropped: 14 Cache: 10.752s + 0KB
04-02 15:29:05.038 6854 6854 V mpvstats: AV: 343.338 A-V: 0.000 Dropped: 14 Cache: 11.861s + 0KB
04-02 15:29:08.040 6854 6854 V mpvstats: AV: 346.341 A-V: 0.000 Dropped: 14 Cache: 8.875s + 0KB
04-02 15:29:11.041 6854 6854 V mpvstats: AV: 349.344 A-V: 0.000 Dropped: 14 Cache: 9.941s + 0KB
04-02 15:29:14.042 6854 6854 V mpvstats: AV: 352.347 A-V: 0.000 Dropped: 14 Cache: 11.051s + 0KB
04-02 15:29:17.042 6854 6854 V mpvstats: AV: 355.350 A-V: 0.000 Dropped: 14 Cache: 8.064s + 0KB
04-02 15:29:20.043 6854 6854 V mpvstats: AV: 358.353 A-V: 0.000 Dropped: 14 Cache: 9.216s + 0KB
04-02 15:29:23.044 6854 6854 V mpvstats: AV: 361.356 A-V: 0.000 Dropped: 14 Cache: 6.229s + 0KB
04-02 15:29:26.045 6854 6854 V mpvstats: AV: 364.326 A-V: 0.000 Dropped: 14 Cache: 8.235s + 0KB
04-02 15:29:29.047 6854 6854 V mpvstats: AV: 367.362 A-V: 0.000 Dropped: 14 Cache: 9.344s + 0KB
04-02 15:29:32.050 6854 6854 V mpvstats: AV: 370.359 A-V: 0.000 Dropped: 14 Cache: 10.411s + 0KB
04-02 15:29:35.050 6854 6854 V mpvstats: AV: 373.362 A-V: 0.000 Dropped: 14 Cache: 7.424s + 0KB
04-02 15:29:38.051 6854 6854 V mpvstats: AV: 376.364 A-V: 0.000 Dropped: 14 Cache: 6.357s + 0KB
04-02 15:29:41.053 6854 6854 V mpvstats: AV: 379.367 A-V: 0.000 Dropped: 14 Cache: 3.499s + 0KB
04-02 15:29:44.054 6854 6854 V mpvstats: AV: 382.369 A-V: 0.000 Dropped: 14 Cache: 0.640s + 0KB
04-02 15:29:44.719 6854 6957 V mpv : event: unpause
04-02 15:29:44.720 6854 6957 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 20%) [0.208500s].
04-02 15:29:44.720 6854 6957 V mpv : property: buffering = true
04-02 15:29:44.720 6854 6854 V PlayerActivity: state PLAYING -> BUFFERING
04-02 15:29:44.721 6854 6854 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=335.2968107777778, end=383.3702218888889}], cache-end=383.45364411111115, reader-pts=383.24514411111113, cache-duration=0.208500000000015, eof=false, underrun=true, idle=false, total-bytes=31247552, fw-bytes=140032, debug-low-level-seeks=0, debug-ts-last=383.5640333333333, ts-per-stream=[{type=video, duration=0.208500000000015, reader=383.27851111111113, end=383.48701111111114}, {type=audio, duration=0.0, reader=383.5640333333333, end=383.5640333333333}]}
04-02 15:29:45.354 6854 6957 V mpv : [cplayer] Still buffering (buffer went from 20% -> 34%) [0.341333s].
04-02 15:29:45.355 6854 6957 V mpv : [cplayer] Still buffering (buffer went from 34% -> 55%) [0.554667s].
04-02 15:29:45.355 6854 6957 V mpv : [cplayer] Still buffering (buffer went from 55% -> 59%) [0.597333s].
04-02 15:29:45.374 6854 6957 V mpv : [cplayer] Still buffering (buffer went from 59% -> 98%) [0.981333s].
04-02 15:29:45.578 6854 6957 V mpv : event: unpause
04-02 15:29:45.578 6854 6957 V mpv : [cplayer] End buffering (waited 0.860866 secs) [4.608000s].
04-02 15:29:45.583 6854 6957 V mpv : property: buffering = false
04-02 15:29:45.583 6854 6854 V PlayerActivity: state BUFFERING -> PLAYING
04-02 15:29:46.135 6854 6854 V mpvstats: AV: 383.829 A-V: 0.000 Dropped: 19 Cache: 8.064s + 0KB
04-02 15:29:47.054 6854 6854 V mpvstats: AV: 384.738 A-V: 0.000 Dropped: 19 Cache: 8.149s + 0KB
04-02 15:29:50.055 6854 6854 V mpvstats: AV: 387.741 A-V: 0.000 Dropped: 19 Cache: 8.192s + 0KB
04-02 15:29:51.658 6854 9775 V ApiServer: REQUEST: GET /log
04-02 15:29:51.659 6854 9775 I hls : goroutine 17 [running, locked to thread]:
04-02 15:29:51.659 6854 9775 I hls : main.FullStackTrace(0x8cc4c070, 0x8cc38f50)
04-02 15:29:51.659 6854 9775 I hls : /Users/fancybox/source/channels-android/vendor/libhls/channels-server/hls/libhls/hls_c.go:249 +0x80
04-02 15:29:51.659 6854 9775 I hls : main.hls_log_stack()
04-02 15:29:51.659 6854 9775 I hls : /Users/fancybox/source/channels-android/vendor/libhls/channels-server/hls/libhls/hls_c.go:259 +0x14
04-02 15:29:51.659 6854 9775 I hls : main._cgoexpwrap_277a0c6059f4_hls_log_stack()
04-02 15:29:51.659 6854 9775 I hls : _cgo_gotypes.go:299 +0x14
04-02 15:29:51.659 6854 9775 I hls :
04-02 15:29:51.659 6854 9775 I hls : goroutine 6 [syscall]:
04-02 15:29:51.659 6854 9775 I hls : os/signal.signal_recv(0x0)
04-02 15:29:51.659 6854 9775 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/runtime/sigqueue.go:147 +0x14c
04-02 15:29:51.659 6854 9775 I hls : os/signal.loop()
04-02 15:29:51.659 6854 9775 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/os/signal/signal_unix.go:23 +0x14
04-02 15:29:51.659 6854 9775 I hls : created by os/signal.Notify.func1
04-02 15:29:51.659 6854 9775 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/os/signal/signal.go:127 +0x38
04-02 15:29:51.659 6854 9775 I hls :
04-02 15:29:51.659 6854 9775 I hls : goroutine 19 [select]:
04-02 15:29:51.659 6854 9775 I hls : github.com/grafov/kiwi.processSink(0x8cd8e080)
04-02 15:29:51.659 6854 9775 I hls : /Users/fancybox/go/pkg/mod/github.com/grafov/[email protected]/sink.go:327 +0x90
04-02 15:29:51.659 6854 9775 I hls : created by github.com/grafov/kiwi.SinkTo
04-02 15:29:51.659 6854 9775 I hls : /Users/fancybox/go/pkg/mod/github.com/grafov/[email protected]/sink.go:111 +0x310
I was running a continius ping during the show to the DVR and to the TV with zero packet drops.
EDIT: I don't see the problem with DVR'd programs or OTA so I can't imagine its my network anyway.
Please try with a channel between 6007-6062
Ok trying SyFy. Could be an hour or three before I see a problem.
What's the reason for the number range?
Also I was surprised at how quick it started happening to me with Discovery. Lately I've been having Fox News on most of the day when I'm not doing at home schooling with the kids.....