Latest DVR v2019.04.27.0504 H264 recording remux gets stuck playing in web browser


#1

Play starts normally and runs until 11 minutes, 33 seconds, then shows buffering circle and is displaying Remux Paused: 11m35.190211s @ 1.55x

Looking at http://x.x.x.x:8089/hls, it thinks the view position is at 8 minutes, 44 seconds, but it's actually at 11 minutes, 33 seconds.

OutPosition "11m35.190211s"
ViewPosition "8m55s" ACTUALLY 11m33s
Speed "1.55x"
Finished false
StartedAt "2019-04-27T12:43:13.514642449-07:00"
LastActive "2019-04-27T12:54:52.571677257-07:00"
Started true
Stopped false
Paused true
FileProgressDuration 0


TV Everywhere Beta Experiences
#2

More info, this is happening using Safari on iOS v12.1.4 and now iOS v12.2 (iPod and iPadPro) and Mozilla Firefox v66.03 (Windows PC) on multiple (3 so far) H.264 recordings streamed locally (in home). The transcoder pauses and the player tries to play past the pause point and freezes. Something must be wrong with the elapsed time math as the play time on the player doesn't match the hls streaming info from the DVR at http://x.x.x.x:8089/hls

So far all 3 recordings (1hr H.264 720p) I've tried exhibit this at different times during playback.

H.264 LiveTV and Mpeg2 recordings/LiveTV work fine.

Update: a fourth H.264 recording does not exhibit the freeze, but the "ViewPosition " in the hls Streaming web page is way off (too far ahead of reality).

Let me know if you want me to upload a recording that exhibits the problem.


#3

Another one tonight after updating to the latest pre-release 2019.04.28.2113

Started remux playback of H.264 720p recording in browser at 19:22:30
No skipping forward or backward or commercial skipping, just letting it play.
Playback was normal until 19:34:07 at which time the playback froze at a playback time of 11:37

hls streaming info is wrong, showing view position at 09:00

OutPosition "11m38.643667s"
ViewPosition "9m0s"
Speed "1.54x"
Finished false
StartedAt "2019-04-28T19:22:30.126638332-07:00"
LastActive "2019-04-28T19:34:34.322904554-07:00"
Started true
Stopped false
Paused true
FileProgressDuration 0

logfile shows inaccuracy in view time

2019/04/28 19:22:30 [HLS] Starting transcoder for file1265-ip192.168.1.2 at 0s from 192.168.1.2 (encoder=remux, resolution=1080, deinterlacer=hardware, bitrate=10000)
[mpegts @ 0x23e6100] start time for stream 3 is not set in estimate_timings_from_pts
[mpegts @ 0x23e6100] start time for stream 4 is not set in estimate_timings_from_pts
[mpegts @ 0x23e6100] start time for stream 5 is not set in estimate_timings_from_pts
[mpegts @ 0x23e6100] Dropped corrupted packet (stream = 1)
[mpegts @ 0x23e6100] Dropped corrupted packet (stream = 2)
2019/04/28 19:22:59 [HLS] Pausing transcoder (out: 6m14.169511s, view: 1m10s)... 00:29 ACTUAL VIEWTIME
2019/04/28 19:26:17 [HLS] Resuming transcoder (out: 6m14.169511s, view: 3m45s)... 03:47 ACTUAL VIEWTIME
2019/04/28 19:26:29 [HLS] Pausing transcoder (out: 8m57.015533s, view: 3m53s)... 03:59 ACTUAL VIEWTIME
2019/04/28 19:29:51 [HLS] Resuming transcoder (out: 8m57.015533s, view: 6m28s)... 07:21 ACTUAL VIEWTIME
2019/04/28 19:30:04 [HLS] Pausing transcoder (out: 11m38.643667s, view: 6m37s)... 07:34 ACTUAL VIEWTIME

At this point the only way to get the player working again is to pause, stop and choose to resume watching.

And then it fails again in the same way after playing an additional 11 minutes from where it froze the first time, so resuming from 11:37 and freezing again at 22:43.


#4

This is related to Unpredictable skipping/fast forward during remote playback of recordings


#5

Still happening with version 2019.05.24.1933

Letting an H.264 remux play in the web UI from the beginning without any trick play (pause/skip fwd/skip back) it stopped (stuck) at 11 min, 37 secs.

Clipboard01
Clipboard02

Appears the value ViewPosition: "9m0s" is incorrectly calculated by assuming each hls segment is exactly 1 sec long, when in reality the segment sizes vary from 0.016678 to 2.001333 secs long.
540 segemnts were output (540 * 1 sec each) = 540 secs or 9m0s

Clipboard03

m3u8 playlist generated by ffmpeg in the streaming directory shows segement lengths
#EXTM3U
#EXT-X-VERSION:3
#EXT-X-TARGETDURATION:2
#EXT-X-MEDIA-SEQUENCE:0
#EXTINF:1.984656,
stream0.ts
#EXTINF:2.001333,
stream1.ts
#EXTINF:2.001333,
stream2.ts
#EXTINF:2.001333,
stream3.ts
#EXTINF:2.001333,
stream4.ts
#EXTINF:1.150767,
stream5.ts
#EXTINF:0.850567,
stream6.ts
#EXTINF:2.001333,
stream7.ts
#EXTINF:2.001333,
stream8.ts
#EXTINF:0.350233,
stream9.ts
#EXTINF:1.651100,
stream10.ts
#EXTINF:0.216811,
stream11.ts
...
...
#EXTINF:0.483656,
stream533.ts
#EXTINF:1.517678,
stream534.ts
#EXTINF:0.983989,
stream535.ts
#EXTINF:1.017344,
stream536.ts
#EXTINF:0.950633,
stream537.ts
#EXTINF:1.050700,
stream538.ts
#EXTINF:0.116744,
stream539.ts

Curious (but unable to test) if removing the ffmpeg parameter hls_time 1 (to let it default to 2+ second segments) or removing hls_flags split_by_ts (to let it split segments at reference frames) would help.

Not sure where that ViewPosition variable is coming from, ffmpeg or Channels. The web player knows the current view position being played, but appears Channels DVR doesn't so it doesn't unpause the remux and the player eventually hits the last remuxed hls segment and appears to be buffering. Only way out is to pause, stop and then continue play.


#6

Don't know what this means.

If I look at the entry for the recording that's being remuxed and played in the web browser,
in this case http://127.0.0.1:8089/dvr/files/1265,
the value PlaybackTime tracks where my current plackback time is in the web player to the second, including pauses, skips forward and back.

But over at http://127.0.0.1:8089/hls the value ViewPosition is incorrect and seems to be based on the last hls segment number the player requested and the false assumption that each segment is exactly 1 second in length. After doing skips forwards or backwards that incorrect math causes major discrepancies in the true player time.

Example;
Currently have the remuxed file 1265 paused in the web player at 9m0s.

http://127.0.0.1:8089/dvr/files/1265
PlaybackTime: 540

http://127.0.0.1:8089/hls
SecondsPerSegment: 1
OutPosition: 12m16.731711s
ViewPosition: 7m28s

Now I skip forward 30 seconds twice to 10m0s.

http://127.0.0.1:8089/dvr/files/1265
PlaybackTime: 600

http://127.0.0.1:8089/hls
SecondsPerSegment: 1
OutPosition: 12m16.731711s
ViewPosition: 8m10s

Now I skip backward 10 seconds three times to 9m30s.

http://127.0.0.1:8089/dvr/files/1265
PlaybackTime: 570

http://127.0.0.1:8089/hls
SecondsPerSegment: 1
OutPosition: 12m16.731711s
ViewPosition: 8m10s

Now I skip forward 30 seconds eleven times to 15m0s.

http://127.0.0.1:8089/dvr/files/1265
PlaybackTime: 900

http://127.0.0.1:8089/hls
SecondsPerSegment: 1
OutPosition: 17m32.080078s
ViewPosition: 12m29s


#7

Your analysis is correct. Previously we used "-hls_flags split_by_time" which ensured 1s segment files. As you know we removed that in Unable to remote stream because of audio issues, and that introduced this new problem when you are remuxing existing h264.

We are working on a solution


#8

This appears to be fixed in the latest pre-release!
At least for the recording that I noticed the issue on.