Transcoder failure - no TS found at start of file, duration not set

[eliteprox]

Describe the bug
There seems to be an issue with some segments arriving without necessary keyframe information, such as duration. When this happens, it is possible for a transcoder to fail. Transcoder has failed with the following message. See attached logs also.

[mpegts @ 0x7fe6a03b7a80] stream 1 : no TS found at start of file, duration not set
[mpegts @ 0x7fe6a03b7a80] Could not find codec parameters for stream 1 (Audio: aac ([15][0][0][0] / 0x000F), 0 channels): unspecified sample format
Consider increasing the value for the 'analyzeduration' (0) and 'probesize' (5000000) options
WARNING: decoder.c:280] No video stream found in input
fatal error: unexpected signal during runtime execution

To Reproduce

• This occurred on a separate transcoder process that was connected to O on localhost.

Expected behavior
Transcoding process should not crash. Possibly reject incomplete segments that are missing information.

Desktop (please complete the following information):

• OS: Ubuntu Desktop 22.04

Additional context

• transcoderfailure.txt
  • Stack trace at 04:39:22
• ologs.txt
  • Search logs for 127.0.0.1:57032 around 04:39:22

[thomshutt]

Thanks for the report @eliteprox - there are some known bugs in Mist that occasionally causes us to receive invalid segments.

The team are working on them at the moment and aiming to get them resolved by the end of the month, so I'll leave this open and then check back in once we've shipped a fix.

[Titan-Node]

Also getting these error reports from Transcoders as well
Similar issue: #2622

[Titan-Node]

Also getting this error may be similar issue?

[mpegts @ 0000021c11559700] Could not find codec parameters for stream 1 (Unknown: none): unknown codec
Consider increasing the value for the 'analyzeduration' (0) and 'probesize' (5000000) options
[h264 @ 0000021b10b819c0] non-existing PPS 0 referenced
[h264 @ 0000021b10b819c0] non-existing PPS 0 referenced
[h264 @ 0000021b10b819c0] decode_slice_header error
[h264 @ 0000021b10b819c0] no frame!
[mpegts @ 0000021c11559d40] Could not find codec parameters for stream 1 (Unknown: none): unknown codec
Consider increasing the value for the 'analyzeduration' (0) and 'probesize' (5000000) options
[h264 @ 0000021b10b82780] co located POCs unavailable
[mpegts @ 0000021c11559d40] probed stream 1 failed
2023/03/11 16:15:03 http: TLS handshake error from 138.199.4.164:55205: EOF
[h264 @ 0000021b10b82300] non-existing SPS 0 referenced in buffering period
[h264 @ 0000021b10b82300] non-existing PPS 0 referenced
[h264 @ 0000021b10b82300] non-existing SPS 0 referenced in buffering period
[h264 @ 0000021b10b82300] non-existing PPS 0 referenced
[h264 @ 0000021b10b82300] decode_slice_header error
[h264 @ 0000021b10b82300] no frame!

[eliteprox]

Also getting this error may be similar issue?

[mpegts @ 0000021c11559700] Could not find codec parameters for stream 1 (Unknown: none): unknown codec

Consider increasing the value for the 'analyzeduration' (0) and 'probesize' (5000000) options

[h264 @ 0000021b10b819c0] non-existing PPS 0 referenced

[h264 @ 0000021b10b819c0] non-existing PPS 0 referenced

[h264 @ 0000021b10b819c0] decode_slice_header error

[h264 @ 0000021b10b819c0] no frame!

[mpegts @ 0000021c11559d40] Could not find codec parameters for stream 1 (Unknown: none): unknown codec

Consider increasing the value for the 'analyzeduration' (0) and 'probesize' (5000000) options

[h264 @ 0000021b10b82780] co located POCs unavailable

[mpegts @ 0000021c11559d40] probed stream 1 failed

2023/03/11 16:15:03 http: TLS handshake error from 138.199.4.164:55205: EOF

[h264 @ 0000021b10b82300] non-existing SPS 0 referenced in buffering period

[h264 @ 0000021b10b82300] non-existing PPS 0 referenced

[h264 @ 0000021b10b82300] non-existing SPS 0 referenced in buffering period

[h264 @ 0000021b10b82300] non-existing PPS 0 referenced

[h264 @ 0000021b10b82300] decode_slice_header error

[h264 @ 0000021b10b82300] no frame!

I think they are from different causes, but you can see this same error in my transcoder logs prior to the crash.

The primary difference between these two errors is the one you referenced is non-fatal and the one I've come across is fatal.

I think the ideal bug fix from transcoder side will be to find a way to reproduce this and handle the error gracefully so it doesn't crash.

I think both errors are handled through similar code in livepeer and/or lpms.

[eliteprox]

I found some new errors that are leading to transcoder crashes. This is starting to happen very frequently. I think something can be improved on the transcoder side

Orchestrator logs

Apr 07 22:37:32 livepeer[190788]: I0407 22:37:32.061070  190788 ot_rpc.go:147] Transcoding taskId=165592 url=https://70.132.135.146:8935/stream/49354634/6675.tempfile
Apr 07 22:37:34 livepeer[190788]: I0407 22:37:34.007906  190788 ot_rpc.go:147] Transcoding taskId=165604 url=https://70.132.135.146:8935/stream/49354634/6676.tempfile
Apr 07 22:37:36 livepeer[190788]: I0407 22:37:36.025654  190788 ot_rpc.go:147] Transcoding taskId=165613 url=https://70.132.135.146:8935/stream/49354634/6677.tempfile
Apr 07 22:37:37 livepeer[190788]: I0407 22:37:37.284502  190788 ot_rpc.go:128] End of stream receive cycle because of err="EOF", waiting for running transcode jobs to complete
Apr 07 22:38:13 livepeer[190788]: [mpegts @ 0x7f817117c800] Invalid timestamps stream=0, pts=201246030, dts=8791171622, size=922
Apr 07 22:38:13 livepeer[190788]: [mpegts @ 0x7f817117c800] DTS 201240000 < 8791171622 out of order
Apr 07 22:38:21 livepeer[190788]: I0407 22:38:21.822445  190788 ot_rpc.go:60] Unregistering transcoder: EOF
Apr 07 22:38:22 livepeer[190788]: I0407 22:38:22.457115  190788 ot_rpc.go:58] Registering transcoder to 127.0.0.1:8935
Apr 07 22:38:39 livepeer[190788]: I0407 22:38:39.229641  190788 ot_rpc.go:147] Transcoding taskId=165953 url=https://70.132.135.146:8935/stream/051f9fc2/1951.tempfile
Apr 07 22:38:47 livepeer[190788]: I0407 22:38:47.468187  190788 ot_rpc.go:147] Transcoding taskId=165997 url=https://70.132.135.146:8935/stream/051f9fc2/1952.tempfile

Apr 11 20:37:05 livepeer[2532]: E0411 20:37:05.135324    2532 orchestrator.go:758] manifestID=manifest-agahggec seqNo=596 orchSessionID=d09a9cf9 clientIP=143.244.61.193 sender=0xc3c7c4C8f7061B7d6A72766Eee5359fE4F36e61E Fatal error with remote transcoder=127.0.0.1:46520 taskId=81000 fname=https://70.132.135.146:8935/stream/d09a9cf9/596.tempfile err="Remote transcoder took too long"

I started keeping track of these on a time chart and they are becoming more frequent