Transcoding errors - "Request for ___ is for different transcoding parameters"

Channels DVR Server Troubleshooting
#1

I’m seeing sporadic instances of transcoding to a remote Apple TV client, even though I have the client’s internet streaming quality set to “Original.” The Apple TV is the 2018 4K model running the latest App Store version of Channels. I submitted logs from the server.

Most of the time it is transcoding down to 2mbps or 1mbps for TVE streams or streams I’ve grabbed from YouTube livestreams. The stats in the settings page always say buf=0% drop=0% so I don’t think this is an instance of insufficient bandwidth, although I believe the “Original” setting should negate any adaptive streaming.

#2

I have some more detailed logs, looks like the main error is "Request for XXX is for different transcoding parameters". It's not unusual for a multi-hour remote stream to be switching from remux to 3mbps transcoding, then 2mbps transcoding even though the remote client is set to stream "Original" quality.

2022/10/18 16:07:54.715532 [TNR] Opened connection to TVE-DTV for ch6030 CNN
2022/10/18 16:07:54.862612 [HLS] Starting live stream for channel 6030 from X.X.X.X (bitrate=4549)
2022/10/18 16:07:56.255280 [HLS] Probed live stream in 1.392233781s: h264 1280x720 progressive 3899133bps
2022/10/18 16:52:39.524228 [NAT] Successfully mapped port 8089 using upnp
2022/10/18 17:17:20.833706 [HLS] Couldn't generate stream playlist for ch6030-dANY-e2e53c14099d: Playlist has not been updated in 20.519149117s
2022/10/18 17:17:20.857769 [HLS] Stopping transcoder session ch6030-dANY-e2e53c14099d (out: 1h9m16.551567s, finished: false)
2022/10/18 17:17:21.380091 [TNR] Closed connection to TVE-DTV for ch6030 CNN
2022/10/18 17:17:21.419726 [SNR] Buffer statistics for ch6030 CNN: buf=0% drop=0%
2022/10/18 17:17:22.910782 [TVE] stream timestamps: cnn: start_at=2022-10-18T17:07:15-04:00 end_at=2022-10-18T17:17:08-04:00 live_delay=8.27377057s
2022/10/18 17:17:22.910978 [TNR] Opened connection to TVE-DTV for ch6030 CNN
2022/10/18 17:17:22.976144 [HLS] Starting live stream for channel 6030 from X.X.X.X (bitrate=4549)
2022/10/18 17:17:24.193031 [HLS] Probed live stream in 1.216399269s: h264 1280x720 progressive 3635080bps
2022/10/18 17:18:02.350773 [HLS] Stopping inactive session ch6030-dANY-e2e53c14099d
2022/10/18 17:18:02.350853 [HLS] Stopping transcoder session ch6030-dANY-e2e53c14099d (out: 47.9404s, finished: false)
2022/10/18 17:18:02.380879 [TNR] Closed connection to TVE-DTV for ch6030 CNN
2022/10/18 17:18:02.380923 [SNR] Buffer statistics for ch6030 CNN: buf=0% drop=0%
2022/10/18 17:35:49.919298 [TVE] stream timestamps: cnn: start_at=2022-10-18T17:25:47-04:00 end_at=2022-10-18T17:35:38-04:00 live_delay=5.30829087s
2022/10/18 17:35:49.919423 [TNR] Opened connection to TVE-DTV for ch6030 CNN
2022/10/18 17:35:49.920432 [HLS] Starting live stream for channel 6030 from X.X.X.X (bitrate=4549)
2022/10/18 17:35:51.167050 [HLS] Probed live stream in 1.244471561s: h264 1280x720 progressive 3819114bps
2022/10/18 17:50:25.013992 [ENC] Starting encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-442-1102380509 at 442 (877.977100) (encoder=h264_vaapi, resolution=384, deinterlacer=hardware, bitrate=436, segment_size=0.01)
2022/10/18 17:52:39.659688 [NAT] Successfully mapped port 8089 using upnp
2022/10/18 17:59:56.525065 [ENC] Request for 442 is for different transcoding parameters: 686kbps
2022/10/18 17:59:56.533715 [ENC] Stopped encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-442-1102380509 after encoding 442 to 726
2022/10/18 17:59:56.534811 [ENC] Starting encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-442-510137678 at 442 (877.977100) (encoder=h264_vaapi, resolution=384, deinterlacer=hardware, bitrate=686, segment_size=0.01)
2022/10/18 17:59:58.707254 [ENC] Request for 727 is for different transcoding parameters: 436kbps
2022/10/18 17:59:58.715201 [ENC] Stopped encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-442-510137678 after encoding 442 to 443
2022/10/18 17:59:58.716420 [ENC] Starting encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-727-1933668340 at 727 (1447.679567) (encoder=h264_vaapi, resolution=384, deinterlacer=hardware, bitrate=436, segment_size=0.01)
2022/10/18 18:00:00.506995 [ENC] Request for 444 is for different transcoding parameters: 686kbps
2022/10/18 18:00:00.514481 [ENC] Stopped encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-727-1933668340 after starting from 727 without encoding any segments
2022/10/18 18:00:00.515508 [ENC] Starting encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-444-1379578205 at 444 (881.981100) (encoder=h264_vaapi, resolution=384, deinterlacer=hardware, bitrate=686, segment_size=0.01)
2022/10/18 18:00:08.985076 [ENC] Request for 442 is for different transcoding parameters: 904kbps
2022/10/18 18:00:08.993349 [ENC] Stopped encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-444-1379578205 after encoding 444 to 460
2022/10/18 18:00:08.996291 [ENC] Starting encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-442-3371570132 at 442 (877.977100) (encoder=h264_vaapi, resolution=576, deinterlacer=hardware, bitrate=904, segment_size=0.01)
2022/10/18 18:00:10.706976 [ENC] Request for 461 is for different transcoding parameters: 686kbps
2022/10/18 18:00:10.714849 [ENC] Stopped encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-442-3371570132 after starting from 442 without encoding any segments
2022/10/18 18:00:10.718911 [ENC] Starting encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-461-985964364 at 461 (915.014100) (encoder=h264_vaapi, resolution=384, deinterlacer=hardware, bitrate=686, segment_size=0.01)
2022/10/18 18:00:12.107185 [ENC] Request for 443 is for different transcoding parameters: 904kbps
2022/10/18 18:00:12.115863 [ENC] Stopped encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-461-985964364 after starting from 461 without encoding any segments
2022/10/18 18:00:12.117140 [ENC] Starting encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-443-481822129 at 443 (879.979100) (encoder=h264_vaapi, resolution=576, deinterlacer=hardware, bitrate=904, segment_size=0.01)
2022/10/18 18:00:49.261870 [ENC] Request for 442 is for different transcoding parameters: copy
2022/10/18 18:00:49.269953 [ENC] Stopped encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-443-481822129 after encoding 443 to 504
2022/10/18 18:00:49.271108 [ENC] Starting encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-442-23175472 at 442 (877.977100) (encoder=h264_vaapi, resolution=720, deinterlacer=hardware, bitrate=2230, segment_size=0.01)
2022/10/18 18:00:51.507166 [ENC] Request for 505 is for different transcoding parameters: aac
2022/10/18 18:00:51.516916 [ENC] Stopped encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-442-23175472 after starting from 442 without encoding any segments
2022/10/18 18:00:51.518964 [ENC] Starting encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-505-1146959615 at 505 (1003.068733) (encoder=h264_vaapi, resolution=576, deinterlacer=hardware, bitrate=904, segment_size=0.01)
2022/10/18 18:00:53.706535 [ENC] Request for 443 is for different transcoding parameters: copy
2022/10/18 18:00:53.714629 [ENC] Stopped encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-505-1146959615 after starting from 505 without encoding any segments
2022/10/18 18:00:53.729293 [ENC] Starting encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-443-3103924720 at 443 (879.979100) (encoder=h264_vaapi, resolution=720, deinterlacer=hardware, bitrate=2230, segment_size=0.01)
2022/10/18 18:01:09.363436 [ENC] Request for 442 is for different transcoding parameters: 2mbps
2022/10/18 18:01:09.372746 [ENC] Stopped encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-443-3103924720 after encoding 443 to 464
2022/10/18 18:01:09.373879 [ENC] Starting encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-442-1812198167 at 442 (877.977100) (encoder=h264_vaapi, resolution=720, deinterlacer=hardware, bitrate=2880, segment_size=0.01)
2022/10/18 18:01:11.506613 [ENC] Request for 465 is for different transcoding parameters: 2mbps
2022/10/18 18:01:11.515447 [ENC] Stopped encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-442-1812198167 after starting from 442 without encoding any segments
2022/10/18 18:01:11.517006 [ENC] Starting encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-465-1140684897 at 465 (923.022100) (encoder=h264_vaapi, resolution=720, deinterlacer=hardware, bitrate=2230, segment_size=0.01)
2022/10/18 18:01:13.907686 [ENC] Request for 443 is for different transcoding parameters: 2mbps
2022/10/18 18:01:13.922344 [ENC] Stopped encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-465-1140684897 after starting from 465 without encoding any segments
2022/10/18 18:01:13.924026 [ENC] Starting encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-443-359311837 at 443 (879.979100) (encoder=h264_vaapi, resolution=720, deinterlacer=hardware, bitrate=2880, segment_size=0.01)
2022/10/18 20:29:12.302688 [HLS] Stopping transcoder session ch6030-dANY-e2e53c14099d (out: 2h53m27.383533s, finished: false)
2022/10/18 20:29:12.539071 [ENC] Stopped encoder for ch6030 in /volume1/dvr/Streaming/ch6030-dANY-e2e53c14099d-1119555505/encoder-443-359311837 after encoding 443 to 5210
2022/10/18 20:29:12.646972 [TNR] Closed connection to TVE-DTV for ch6030 CNN
2022/10/18 20:29:12.647023 [SNR] Buffer statistics for ch6030 CNN: buf=0% drop=0%
#3

Seems like client is not set to Original

Can you submit diagnostics from the client after it happens

#4

If you are streaming H.264 content (TVE qualifies), the Original setting will still perform the adaptive bitrate handling to accommodate situations where the client can’t keep up with the bitrate of the source.

As @tmm1 said, the diagnostics of the client will be helpful for us regardless to give you more insight into what is happening.

#5

Ok thanks for clarifying, has this always been the case? I'm trying to figure out if the change is in Channels' behavior or my family member's internet connection, since this only started happening in the last month or two. When I visited ~6 months ago, all H264 streams seemed to stream fine in "Original" quality with very occasional buffering (maybe 1-2 three second buffering pause per hour).

I'll try to get them to submit diagnostics and update the thread when they're sent.

#6

Yep, it’s always been that way since ABR was introduced a few years ago. The goal has been to not require fidgeting with settings to have a good streaming experience.

If we were able to do ABR for all codec/format types, we would, but due to current limitations on how our playback pipeline works we are unable to seamlessly move between codecs and formats so we can’t do it for MPEG2 or MKV’s, etc.

Because HLS (the remote streaming protocol) is based on H.264, we are able to seamlessly move between the Original and transcoded streams.

Are you running into negative impacts of the transcoding happening or was this just surprising to you?

#7

A little bit of both – I run Channels on a Synology that does other things so I'd rather it not be transcoding, even at the expense of some buffering for clients. Transcoding some low bitrate TVE streams doesn't seem too resource-intensive so I'm not upset about it, but I never noticed this behavior in the past. Thanks again for the info.

#8

@eric Sorry to revive this months later, but could you take a look at the diagnostics I sent from the client and see if there's anything out of the ordinary? I'm using the remote Apple TV in question since I'm visiting family, and now I see their download speeds can fluctuate pretty widely. That's probably something I need to call Comcast about, but I'm wondering if Channels is a little too aggressive in downgrading a TVE stream all the way to 2mbps or 1mbps and not bringing it back up. They're supposed to have 200 Mbps, but even when their speeds are degraded I've never seen speeds dip below 15-20 Mbps.

If it's working as intended given their connection conditions, then no worries.

#9

Ok, I turned on stats and saw the download speed crater to 2 Mbps for seemingly no reason. Based on that, Channels is responding appropriately.

Re-tuned to the same channel and it instantly went back up to 20-30 Mbps. Then did a speed test afterwards and got ~57 Mbps.

Edit: sorry I keep adding info but this kind of driving me crazy. I’m streaming a live 4K YouTube stream and staring at stats for nerds, and this Apple TV has no problem maintaining 16-18 Mbps down. This seems like a Channels-specific issue, or maybe Comcast is limiting my DVR traffic somehow?

#10

Yep, it does look like there's something going on where Channels decided to reduce the quality in a case where it doesn't look like it was necessary. It's going to take some work to figure out exactly how to solve this.

If you do pause the stream for 10 seconds and then start playing, you'll let the client build up enough of a buffer that it will start proactively probing higher bitrates from time to time. I know none of this is optimal, but we're continuing to work at figuring out how to balance quality with not buffering.

#11

Thanks for taking a look, I’ll try to have them send more diagnostics if it happens again.

#12

This topic was automatically closed 365 days after the last reply. New replies are no longer allowed.