What really determines if the new transcoder transcodes or remuxes?

chDVRuser · May 12, 2020, 11:00pm

Channels Plus DVR v2020.05.07.2058
On TVE streams it sometimes transcodes and sometimes remuxes.

2020/05/12 15:45:09.433150 [TVE] stream timestamps: nbcsn-bayarea: start_at=2020-05-12T15:15:04-07:00 current_at=2020-05-12T15:44:41-07:00 end_at=2020-05-12T15:44:53-07:00
2020/05/12 15:45:09.433275 [TNR] Opened connection to TVE-Comcast_SSO for ch6167 NBCSN-BAYAREA
2020/05/12 15:45:09.435041 [HLS] Starting transcoder for channel 6167 from 192.168.1.2 (encoder=remux, resolution=, deinterlacer=, bitrate=0)
2020/05/12 15:45:10.787016 [HLS] Probed live stream in 1.351656552s: h264 1920x1080 progressive 5368583bps
2020/05/12 15:45:10.887352 [HLS] Session ch6167-dANY-ip192.168.1.2 started in 5.384384675s
2020/05/12 15:45:10.890313 [ENC] Starting encoder for ch6167 in /volume1/arkives/ChannelsDVR/Streaming/ch6167-dANY-ip192.168.1.2-617984438/encoder-1-459665496 at 1 (0.033367) (encoder=libx264, resolution=720, deinterlacer=linear, bitrate=5368 segment_size=0.01)
2020/05/12 15:46:13.786539 [HLS] Stopping transcoder session ch6167-dANY-ip192.168.1.2 (out: 1m15.273244s, finished: false)
2020/05/12 15:46:13.812068 [ENC] Stopped encoder for ch6167 in /volume1/arkives/ChannelsDVR/Streaming/ch6167-dANY-ip192.168.1.2-617984438/encoder-1-459665496 after encoding 1 to 16
2020/05/12 15:46:13.843855 [TNR] Closed connection to TVE-Comcast_SSO for ch6167 NBCSN-BAYAREA
2020/05/12 15:46:29.155894 [TVE] stream timestamps: nbcsn-california: start_at=2020-05-12T15:16:21-07:00 current_at=2020-05-12T15:46:01-07:00 end_at=2020-05-12T15:46:13-07:00
2020/05/12 15:46:29.155980 [TNR] Opened connection to TVE-Comcast_SSO for ch6168 NBCSN-CALIFORNIA
2020/05/12 15:46:29.157403 [HLS] Starting transcoder for channel 6168 from 192.168.1.2 (encoder=remux, resolution=, deinterlacer=, bitrate=0)
2020/05/12 15:46:31.020942 [HLS] Probed live stream in 1.863257483s: h264 1920x1080 progressive 7043728bps
2020/05/12 15:46:31.294885 [HLS] Session ch6168-dANY-ip192.168.1.2 started in 6.510688603s
2020/05/12 15:46:46.225369 [HLS] Stopping transcoder session ch6168-dANY-ip192.168.1.2 (out: 34.976789s, finished: false)
2020/05/12 15:46:46.246918 [TNR] Closed connection to TVE-Comcast_SSO for ch6168 NBCSN-CALIFORNIA

Same soccer game on 6167 transcodes in logs above and remuxes now

2020/05/12 16:20:48.722634 [TVE] stream timestamps: nbcsn-bayarea: start_at=2020-05-12T15:50:42-07:00 current_at=2020-05-12T16:20:22-07:00 end_at=2020-05-12T16:20:34-07:00
2020/05/12 16:20:48.722785 [TNR] Opened connection to TVE-Comcast_SSO for ch6167 NBCSN-BAYAREA
2020/05/12 16:20:48.723938 [HLS] Starting transcoder for channel 6167 from 192.168.1.2 (encoder=remux, resolution=, deinterlacer=, bitrate=0)
2020/05/12 16:20:50.590723 [HLS] Probed live stream in 1.866458015s: h264 1920x1080 progressive 6077642bps
2020/05/12 16:20:50.735259 [HLS] Session ch6167-dANY-ip192.168.1.2 started in 5.690037239s
2020/05/12 16:21:17.853248 [HLS] Stopping transcoder session ch6167-dANY-ip192.168.1.2 (out: 41.149033s, finished: false)
2020/05/12 16:21:17.877300 [TNR] Closed connection to TVE-Comcast_SSO for ch6167 NBCSN-BAYAREA

If I enable the Old Transcoder it consistently remuxes as I would expect.

chDVRuser · May 15, 2020, 9:37pm

New prerelease version 2020.05.15.0133 is much better and remuxes TVE instead of transcoding.

Tested a bunch of TVE channels and only ran into a few glitches.

Started watching 6044-HISTORY the player shows Remux running, but no stats, then switches to Transcoding. Stopping playback and restarting worked.

2020/05/15 13:09:28.582898 [TNR] Opened connection to TVE-Comcast_SSO for ch6044 HISTORY
2020/05/15 13:09:28.583979 [HLS] Starting transcoder for channel 6044 from 192.168.1.2 (encoder=remux, resolution=, deinterlacer=, bitrate=0)
2020/05/15 13:09:31.622530 [HLS] Probe failed for live stream after 3.038276851s and 0 bytes
2020/05/15 13:09:54.186013 [HLS] Session ch6044-dANY-ip192.168.1.2 started in 32.702359511s
2020/05/15 13:09:54.194568 [ERR] Cannot probe non-Stream reader: *streaming.abrLiveReader
2020/05/15 13:09:54.195487 [ENC] Starting encoder for ch6044 in /volume1/arkives/ChannelsDVR/Streaming/ch6044-dANY-ip192.168.1.2-084689464/encoder-1-802528641 at 1 (0.201000) (encoder=libx264, resolution=1080, deinterlacer=linear, bitrate=10000 segment_size=0.01)
2020/05/15 13:10:26.311405 [HLS] Stopping transcoder session ch6044-dANY-ip192.168.1.2 (out: 1m14.306489s, finished: false)
2020/05/15 13:10:26.355450 [ENC] Stopped encoder for ch6044 in /volume1/arkives/ChannelsDVR/Streaming/ch6044-dANY-ip192.168.1.2-084689464/encoder-1-802528641 after encoding 1 to 5
2020/05/15 13:10:26.378032 [TNR] Closed connection to TVE-Comcast_SSO for ch6044 HISTORY
...
2020/05/15 13:14:50.048617 [TNR] Opened connection to TVE-Comcast_SSO for ch6044 HISTORY
2020/05/15 13:14:50.049721 [HLS] Starting transcoder for channel 6044 from 192.168.1.2 (encoder=remux, resolution=, deinterlacer=, bitrate=0)
2020/05/15 13:14:51.467466 [HLS] Probed live stream in 1.41743539s: h264 1920x1080 progressive 3628376bps
2020/05/15 13:14:51.571518 [HLS] Session ch6044-dANY-ip192.168.1.2 started in 2.44781533s
2020/05/15 13:15:09.171580 [HLS] Stopping transcoder session ch6044-dANY-ip192.168.1.2 (out: 29.930522s, finished: false)
2020/05/15 13:15:09.183272 [TNR] Closed connection to TVE-Comcast_SSO for ch6044 HISTORY

6045-FYI took awhile to start playing

2020/05/15 13:16:10.372943 [TNR] Opened connection to TVE-Comcast_SSO for ch6045 FYI
2020/05/15 13:16:10.374086 [HLS] Starting transcoder for channel 6045 from 192.168.1.2 (encoder=remux, resolution=, deinterlacer=, bitrate=0)
2020/05/15 13:16:11.785973 [HLS] Couldn't generate master playlist for ch6045-dANY-ip192.168.1.2: Could not determine video format
2020/05/15 13:16:11.786040 [HLS] Stopping transcoder session ch6045-dANY-ip192.168.1.2
2020/05/15 13:16:11.789671 [HLS] Probed live stream in 1.41530917s: h264 1920x1080 progressive 3700453bps
2020/05/15 13:16:11.799619 [HLS] ffmpeg: ch6045-dANY-ip192.168.1.2-remux:  [hls @ 0x28ea540] failed to rename file /volume1/arkives/ChannelsDVR/Streaming/ch6045-dANY-ip192.168.1.2-532965650/remux/stream3.ts.tmp to /volume1/arkives/ChannelsDVR/Streaming/ch6045-dANY-ip192.168.1.2-532965650/remux/stream3.ts: No such file or directory
2020/05/15 13:16:11.799764 [HLS] ffmpeg: ch6045-dANY-ip192.168.1.2-remux:  [hls @ 0x28ea540] failed to rename file /volume1/arkives/ChannelsDVR/Streaming/ch6045-dANY-ip192.168.1.2-532965650/remux/stream.m3u8.tmp to /volume1/arkives/ChannelsDVR/Streaming/ch6045-dANY-ip192.168.1.2-532965650/remux/stream.m3u8: No such file or directory
2020/05/15 13:16:11.799902 [HLS] ffmpeg: ch6045-dANY-ip192.168.1.2-remux:      Last message repeated 1 times
2020/05/15 13:16:11.799931 [HLS] ffmpeg: ch6045-dANY-ip192.168.1.2-remux:  Error writing trailer of /volume1/arkives/ChannelsDVR/Streaming/ch6045-dANY-ip192.168.1.2-532965650/remux/stream.m3u8: No such file or directory
2020/05/15 13:16:11.804646 [TNR] Closed connection to TVE-Comcast_SSO for ch6045 FYI
2020/05/15 13:16:12.848937 [TNR] Opened connection to TVE-Comcast_SSO for ch6045 FYI
2020/05/15 13:16:12.849996 [HLS] Starting transcoder for channel 6045 from 192.168.1.2 (encoder=remux, resolution=, deinterlacer=, bitrate=0)
2020/05/15 13:16:13.733219 [HLS] Probed live stream in 882.990748ms: h264 1920x1080 progressive 3706953bps
2020/05/15 13:16:13.781904 [HLS] Session ch6045-dANY-ip192.168.1.2 started in 972.611428ms
2020/05/15 13:17:02.276779 [HLS] Stopping transcoder session ch6045-dANY-ip192.168.1.2 (out: 1m5.944667s, finished: false)
2020/05/15 13:17:02.306038 [TNR] Closed connection to TVE-Comcast_SSO for ch6045 FYI

6061-OXYGENP took awhile to start playing

2020/05/15 13:21:59.359281 [TNR] Opened connection to TVE-Comcast_SSO for ch6061 OXYGENP
2020/05/15 13:21:59.360346 [HLS] Starting transcoder for channel 6061 from 192.168.1.2 (encoder=remux, resolution=, deinterlacer=, bitrate=0)
2020/05/15 13:22:00.414287 [HLS] Probed live stream in 1.05362621s: h264 1920x1080 progressive 3921726bps
2020/05/15 13:22:00.415918 [HLS] Couldn't generate master playlist for ch6061-dANY-ip192.168.1.2: Could not determine video format
2020/05/15 13:22:00.415979 [HLS] Stopping transcoder session ch6061-dANY-ip192.168.1.2
2020/05/15 13:22:00.446208 [HLS] ffmpeg: ch6061-dANY-ip192.168.1.2-remux:  [hls @ 0x304ecc0] failed to rename file /volume1/arkives/ChannelsDVR/Streaming/ch6061-dANY-ip192.168.1.2-792849804/remux/stream6.ts.tmp to /volume1/arkives/ChannelsDVR/Streaming/ch6061-dANY-ip192.168.1.2-792849804/remux/stream6.ts: No such file or directory
2020/05/15 13:22:00.446319 [HLS] ffmpeg: ch6061-dANY-ip192.168.1.2-remux:  [hls @ 0x304ecc0] failed to rename file /volume1/arkives/ChannelsDVR/Streaming/ch6061-dANY-ip192.168.1.2-792849804/remux/stream.m3u8.tmp to /volume1/arkives/ChannelsDVR/Streaming/ch6061-dANY-ip192.168.1.2-792849804/remux/stream.m3u8: No such file or directory
2020/05/15 13:22:00.446385 [HLS] ffmpeg: ch6061-dANY-ip192.168.1.2-remux:  av_interleaved_write_frame(): No such file or directory
2020/05/15 13:22:00.446443 [HLS] ffmpeg: ch6061-dANY-ip192.168.1.2-remux:  [hls @ 0x304ecc0] failed to rename file /volume1/arkives/ChannelsDVR/Streaming/ch6061-dANY-ip192.168.1.2-792849804/remux/stream.m3u8.tmp to /volume1/arkives/ChannelsDVR/Streaming/ch6061-dANY-ip192.168.1.2-792849804/remux/stream.m3u8: No such file or directory
2020/05/15 13:22:00.461412 [TNR] Closed connection to TVE-Comcast_SSO for ch6061 OXYGENP
2020/05/15 13:22:01.510223 [TNR] Opened connection to TVE-Comcast_SSO for ch6061 OXYGENP
2020/05/15 13:22:01.511259 [HLS] Starting transcoder for channel 6061 from 192.168.1.2 (encoder=remux, resolution=, deinterlacer=, bitrate=0)
2020/05/15 13:22:02.264436 [HLS] Probed live stream in 752.86893ms: h264 1920x1080 progressive 3933978bps
2020/05/15 13:22:02.299586 [HLS] Session ch6061-dANY-ip192.168.1.2 started in 852.416655ms
2020/05/15 13:22:46.163256 [HLS] Stopping transcoder session ch6061-dANY-ip192.168.1.2 (out: 59.893011s, finished: false)
2020/05/15 13:22:46.183731 [TNR] Closed connection to TVE-Comcast_SSO for ch6061 OXYGENP

eric · May 16, 2020, 12:33am

What client are you playing with? A browser or the app?

chDVRuser · May 16, 2020, 12:51am

Firefox 76.0.1 (64-bit) browser on same unmanaged switch as Channels DVR.

Browser%20settings1

chDVRuser · May 17, 2020, 3:42am

@eric
Just wanted to add I don't know if this is a reproducable issue.
I was just checking various TVE Channels (about 50 of them) after the update to see if they transcoded or remuxed and would only wait until they started playing to move to the next channel.

eric · May 17, 2020, 4:17am

It's very hard to identify exactly what's going on here. The order of log messages that you pasted doesn't line up with how the code should be working, so there's something I'm missing that's happening here.

Would you be able to enable "HTTP Logging" and try this again? Also, when you're done, if you could also Submit Diagnostic Logs as well as pulling out the ones that had problems, that could really help me in trying to isolate what's happening.

chDVRuser · May 17, 2020, 4:29am

I know, the logs seemed out of step to me also.

Like I said, I was only verifying that the new version remuxed instead of transcoded the TVE streams, and I hardly ever use TVE (have all the TVE channels I need in my Xfinity pkg) so would be unlikely to see it again. Just wanted to show the logs in case there was something obvious.

If I do run across it again, I'll try to remember this post.

I basically just tried to "tune" each TVE Channel in order from the grid guide (testing to make sure it remuxed) and got tired after doing 50 channels.

eric · May 17, 2020, 4:30am

Thank you!

eric · May 20, 2020, 5:32am

I finally understood what was causing those spurious errors you were seeing from time to time when you tuned to these channels.

I've released a fix for it and I appreciate you going through all of these tests to give some examples.

chDVRuser · May 21, 2020, 2:08am

Glad to hear you found it.
Curious what it was (appeared to be some timing issue)?

eric · May 21, 2020, 3:03am

It was a race condition that could occur in the error handling of a function.

chDVRuser · June 2, 2020, 4:22am

It's happening again. Transcoding instead of remuxing.

Just updated to v2020.06.02.0238 and was testing a few channels by viewing them in my web browser.
First time that I tuned to ch6108 DiY it transcoded, I stopped and restarted playback and it then remuxed.

2020/06/01 20:37:30.154467 [TVE] stream timestamps: diy: start_at=2020-06-01T20:37:28-07:00 current_at=2020-06-01T20:37:32-07:00 end_at=2020-06-01T20:37:40-07:00
2020/06/01 20:37:30.154618 [TNR] Opened connection to TVE-Comcast_SSO for ch6108 DIY
2020/06/01 20:37:30.157026 [HLS] Starting transcoder for channel 6108 from 192.168.1.2 (encoder=remux, resolution=, deinterlacer=, bitrate=5832)
2020/06/01 20:37:33.196471 [HLS] Probe failed for live stream after 3.039085657s and 0 bytes
2020/06/01 20:37:40.643405 [HLS] Session ch6108-dANY-ip192.168.1.2 started in 12.942185902s
2020/06/01 20:37:40.653573 [ERR] Cannot probe non-Stream reader: *streaming.abrLiveReader
2020/06/01 20:37:40.654679 [ENC] Starting encoder for ch6108 in /volume1/arkives/ChannelsDVR/Streaming/ch6108-dANY-ip192.168.1.2-702654677/encoder-1-096057807 at 1 (0.000478) (encoder=libx264, resolution=1080, deinterlacer=linear, bitrate=10000 segment_size=0.01)
2020/06/01 20:38:26.804751 [HLS] Stopping transcoder session ch6108-dANY-ip192.168.1.2 (out: 1m9.187467s, finished: false)
2020/06/01 20:38:26.853449 [ENC] Stopped encoder for ch6108 in /volume1/arkives/ChannelsDVR/Streaming/ch6108-dANY-ip192.168.1.2-702654677/encoder-1-096057807 after encoding 1 to 7
2020/06/01 20:38:26.865569 [TNR] Closed connection to TVE-Comcast_SSO for ch6108 DIY
2020/06/01 20:38:40.068365 [TVE] stream timestamps: diy: start_at=2020-06-01T20:38:39-07:00 current_at=2020-06-01T20:38:59-07:00 end_at=2020-06-01T20:39:07-07:00
2020/06/01 20:38:40.068478 [TNR] Opened connection to TVE-Comcast_SSO for ch6108 DIY
2020/06/01 20:38:40.069671 [HLS] Starting transcoder for channel 6108 from 192.168.1.2 (encoder=remux, resolution=, deinterlacer=, bitrate=5848)
2020/06/01 20:38:41.220669 [HLS] Probed live stream in 1.150538538s: h264 1920x1080 progressive 5081596bps
2020/06/01 20:38:41.308933 [HLS] Session ch6108-dANY-ip192.168.1.2 started in 2.150577702s
2020/06/01 20:39:51.248427 [HLS] Stopping transcoder session ch6108-dANY-ip192.168.1.2 (out: 1m17.824s, finished: false)
2020/06/01 20:39:51.270737 [TNR] Closed connection to TVE-Comcast_SSO for ch6108 DIY

racameron · June 2, 2020, 6:14am

Both streams in your example show encoder=remux, meaning they're not transcoding, but remuxing from TS to HLS. Where is the transcoding?

chDVRuser · June 2, 2020, 2:41pm

2020/06/01 20:37:40.654679 [ENC] Starting encoder for ch6108 in /volume1/arkives/ChannelsDVR/Streaming/ch6108-dANY-ip192.168.1.2-702654677/encoder-1-096057807 at 1 (0.000478) (encoder=libx264, resolution=1080, deinterlacer=linear, bitrate=10000 segment_size=0.01)

racameron · June 2, 2020, 3:03pm

Looks like the interlacing present when you opened the stream may have triggered the transcode. Could have possibly been during a commercial, as those don't always match the resolution or bitrate of the main program.

chDVRuser · June 2, 2020, 9:46pm

Not sure what triggers transcode vs remux in Channels DVR, hence the subject of the post.
Those transcoder settings are what I set in the DVR web UI. My question is what's causing Channels DVR to think it needs to transcode TVE streams instead of remuxing them. I don't know the code used.
Screenshot_2020-06-02 Channels DVR

tmm1 · June 2, 2020, 9:54pm

There were some changes recently which probably affected this. We're trying to make it always remux even if you tune in during commercials. @eric will be able to comment further about this case.

chDVRuser · June 2, 2020, 10:35pm

Thanks Aman.

Not a show-stopper. TVE is not my only source.

Was just grabbing logs when something unexpected occurs, FYI.

I only record one show from TVE once per week.

When I update my TVE server, I test a few channels by viewing live to make sure when it does record something there will be no issues.

eric · June 3, 2020, 12:32am

When the channel was opened, we attempted to identify what the bitrate and format was for the stream. After 3 seconds it failed to read any bytes. Because we could not read the details of the stream, we defaulted to transcoding to the requested format and bitrate.

2020/06/01 20:37:33.196471 [HLS] Probe failed for live stream after 3.039085657s and 0 bytes

After 13 seconds, we started receiving data from the stream and started transcoding.

2020/06/01 20:37:40.643405 [HLS] Session ch6108-dANY-ip192.168.1.2 started in 12.942185902s

There might be things that we can do to improve this situation, but it is abnormal that it takes that long for a stream to start. If you continue to see these sorts of issues we can see what we can do to fix it.

chDVRuser · June 3, 2020, 3:24am

Thanks @eric, that makes perfect sense.
Appreciate your candor.
I understand the safety net of falling back to transcoding if unsure of stream details.
Like I said, no issue, just passing on log info for this abnormality when I upgraded to this version.