Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Bugfix: TypeError: Cannot read properties of null… payload.byteLength (timeline-controller) #4902

Merged
merged 10 commits into from
Oct 5, 2022

Conversation

mtoczko
Copy link
Collaborator

@mtoczko mtoczko commented Sep 13, 2022

This PR will...

Adding error handling from webCryptoDecrypt to SubtitleStreamController.
onWebCryptoError: fixes reading data from softwareDecrypt

Why is this Pull Request needed?

Prevents errors:
Uncaught (in promise) TypeError: Cannot read properties of null (reading 'byteLength')
Uncaught (in promise) TypeError: payload is null

Are there any points in the code the reviewer needs to double check?

No

Resolves issues:

#4898

Checklist

  • changes have been done against master branch, and PR does not conflict
  • new unit / functional tests have been added (whenever applicable)
  • API or design changes are documented in API.md

@robwalch
Copy link
Collaborator

robwalch commented Sep 13, 2022

Hi @mtoczko,

Thanks for the fixes. I missed this one before cutting v1.2.3. However, I closed #4898 as I was not able to reproduce the payload exceptions using the stream or steps in the AES-128 VTT loop loading issue. Is this intermittent or are there additional steps needed to repro?

@@ -473,7 +473,7 @@ export class TimelineController implements ComponentAPI {
const { initPTS, unparsedVttFrags } = this;
if (frag.type === PlaylistLevelType.SUBTITLE) {
// If fragment is subtitle type, parse as WebVTT.
if (payload.byteLength) {
if (payload?.byteLength) {
Copy link
Collaborator

@robwalch robwalch Sep 13, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would argue that if payload is undefined (or null) then onFragLoaded should not be called. My guess is that this is not an issue with FRAG_LOADED but with the FRAG_DECRYPTED or unparsedVttFrags path(s)? Or is the progressive config option enabled?

In either case, same logic applies: both event types expect payload to be defined so I'd like to know the root cause for this.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hi @robwalch
The error does not always occur, to me it was able to appear immediately after starting the stream (#4898).
You're right, it's an error with WebCrypto.

By the way, do you know the reason why subtitle-stream-controller does not use ENDED state?
Because I don't see any reason to keep trying to load the last fragment. (VOD stream)

  Show all details
base-stream-controller.ts:1395 [log] > [subtitle-stream-controller]: IDLE->KEY_LOADING
base-stream-controller.ts:1395 [log] > [subtitle-stream-controller]: KEY_LOADING->IDLE
base-stream-controller.ts:612 [log] > [subtitle-stream-controller]: Loading fragment 1 cc: 0 of [0-1] track: 0, target: 60
base-stream-controller.ts:1395 [log] > [subtitle-stream-controller]: IDLE->FRAG_LOADING
base-stream-controller.ts:373 [log] > [subtitle-stream-controller]: Loaded fragment 1 of level 0
decrypter.ts:171 [warn] > [decrypter.ts]: WebCrypto Error, disable WebCrypto API: Error
onWebCryptoError @ decrypter.ts:171
(anonymous) @ decrypter.ts:166
Promise.catch (async)
webCryptoDecrypt @ decrypter.ts:154
_handleFragmentLoadComplete @ subtitle-stream-controller.ts:314
(anonymous) @ base-stream-controller.ts:378
Promise.then (async)
_loadFragForPlayback @ base-stream-controller.ts:354
loadFragment @ base-stream-controller.ts:329
loadFragment @ subtitle-stream-controller.ts:420
onKeyLoaded @ base-stream-controller.ts:276
emit @ index.js:203
emit @ hls.ts:253
trigger @ hls.ts:261
onKeyLoading @ key-loader.ts:122
emit @ index.js:182
emit @ hls.ts:253
trigger @ hls.ts:261
loadKey @ base-stream-controller.ts:321
doTick @ subtitle-stream-controller.ts:401
tick @ task-loop.ts:110
setInterval (async)
setInterval @ task-loop.ts:72
startLoad @ subtitle-stream-controller.ts:85
(anonymous) @ hls.ts:366
startLoad @ hls.ts:365
onManifestLoaded @ level-controller.ts:196
emit @ index.js:203
emit @ hls.ts:253
trigger @ hls.ts:261
handleMasterPlaylist @ playlist-loader.ts:451
loadsuccess @ playlist-loader.ts:348
readystatechange @ xhr-loader.ts:197
XMLHttpRequest.send (async)
(anonymous) @ VM237:1
loadInternal @ xhr-loader.ts:134
load @ xhr-loader.ts:72
load @ playlist-loader.ts:310
onManifestLoading @ playlist-loader.ts:155
emit @ index.js:203
emit @ hls.ts:253
trigger @ hls.ts:261
loadSource @ hls.ts:353
loadSelectedStream @ main.js:374
(anonymous) @ main.js:227
j @ jquery.min.js:2
fireWith @ jquery.min.js:2
ready @ jquery.min.js:2
I @ jquery.min.js:2
decrypter.ts:191 [log] > [decrypter.ts]: JS AES decrypt
timeline-controller.ts:476 Uncaught (in promise) TypeError: Cannot read properties of null (reading 'byteLength')
    at TimelineController.onFragLoaded (timeline-controller.ts:476:19)
    at TimelineController.onFragDecrypted (timeline-controller.ts:639:12)
    at EventEmitter.emit (index.js:203:1)
    at Hls.emit (hls.ts:253:26)
    at Hls.trigger (hls.ts:261:19)
    at subtitle-stream-controller.ts:321:15

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No reason other than the state is related to SourceBuffer states and this controller does not have one so some flow is missing.

So implementing ENDED state for this controller would have been another approach to stopping loop loading of the last fragment?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Now we have the situation that after loading all the fragments. In the next tick it searches for a new fragment anyway. This would be more of a resource optimization.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If you want to simulate this error add throw new Error('test decrypter'); decrypter.ts#L163.
I see that softwareDecrypt as a result returns null. After that, there is no payload verification. Are you able to verify the functionality of softwareDecrypt?

Copy link
Collaborator

@robwalch robwalch Sep 14, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I still cannot reproduce. I can see how we might end up there. How about this?

-  private onWebCryptoError(err, data, key, iv): ArrayBuffer | null {
+  private onWebCryptoError(err, data, key, iv): ArrayBuffer | never {
     logger.warn('[decrypter.ts]: WebCrypto Error, disable WebCrypto API:', err);
     this.config.enableSoftwareAES = true;
     this.logEnabled = true;
-    return this.softwareDecrypt(data, key, iv);
+    const result = this.softwareDecrypt(data, key, iv);
+    if (result === null) {
+      throw err;
+    }
+    return result;
   }

and then

-      this.webCryptoDecrypt(new Uint8Array(data), key, iv).then(callback);
+      this.webCryptoDecrypt(new Uint8Array(data), key, iv)
+        .then(callback)
+        .catch(logger.error);

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for your suggestions.
For now, I would hold off on merging until I test on a longer stream.

I noticed that the error is easily reproduced as we set in the configuration "enableSoftwareAES": true .

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I was able to repro. Thanks for all the changes. It's getting close. I think we can remove this payload?.byteLength safety check now.

@phloxic
Copy link
Contributor

phloxic commented Sep 13, 2022

Thanks for the fixes. I missed this one before cutting v1.2.3. However, I closed #4898 as I was not able to reproduce the payload exceptions using the stream or steps in the AES-128 VTT loop loading issue. Is this intermittent or are there additional steps needed to repro?

@robwalch - I can still repro the payload exceptions. But by now I believe they were/are caused by hard reloads of the demo page. In 'normal' use I cannot repro (famous last words).

@robwalch robwalch added the Bug label Sep 13, 2022
@mtoczko
Copy link
Collaborator Author

mtoczko commented Sep 14, 2022

Hi @phloxic
Do you have a longer test stream? (I mean more vtt segemnts)

@mtoczko
Copy link
Collaborator Author

mtoczko commented Sep 14, 2022

@robwalch
There may also be some error with the key, because now it tries to download the fragment again if the payload was 'null'. And the error goes away after reloading the key.
Zrzut ekranu 2022-09-14 o 17 54 27
Zrzut ekranu 2022-09-14 o 18 03 21

@phloxic
Copy link
Contributor

phloxic commented Sep 14, 2022

Hi @phloxic Do you have a longer test stream? (I mean more vtt segemnts)

@mtoczko here you go: https://d12zt1n3pd4xhr.cloudfront.net/dev/aesx-s-cc-en.m3u8

src/crypt/decrypter.ts Outdated Show resolved Hide resolved
src/crypt/decrypter.ts Outdated Show resolved Hide resolved
Comment on lines 332 to 333
// remove the fragment without payload and try downloading again
this.fragmentTracker.removeFragment(frag);
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm a little worried this could lead to loop loading. We probably want to trigger a frag load error (or define a new frag decryption error event) that would go through the properly retry logic rather than leaving it up to the idle tick cycle.

Copy link
Collaborator

@robwalch robwalch Sep 14, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There may also be some error with the key, because now it tries to download the fragment again if the payload was 'null'. And the error goes away after reloading the key.

Makes sense. What concerns me is cases where the key is always bad. A frag load error (when the key fails like this) will keep the retries within the bounds of FragmentLoaderConfig max retry and retry delay params.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am a little concerned about one thing, why entering the same data. We get different results. As if something modified the loaded key, because after reloading the same key the result is correct.

I'm a little worried this could lead to loop loading. We probably want to trigger a frag load error (or define a new frag >decryption error event) that would go through the properly retry logic rather than leaving it up to the idle tick cycle.

There is such a risk, only we do not have a method to skip such a fragment, without this we will have
a fragment with unencrypted data and a gap in the subtitles.

Copy link
Collaborator

@robwalch robwalch Sep 14, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

When the fragment retry logic exhausts all attempts, a fatal error is triggered that ends playback - So the player considers this stream broken rather than leaving a gap in subs. That is better than letting it retry indefinitely without repercussions or delay between retries.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am a little concerned about one thing, why entering the same data. We get different results.

Is the initialization vector the same each time?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I will take some time and look for the error in decrypter.ts.
I'll see how it works with #4861. For now, I would remove PR from milestone 1.2.4

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

May be related to #4666

mtoczko and others added 2 commits September 14, 2022 23:59
Co-authored-by: Rob Walch <robwalch@users.noreply.github.com>
@robwalch robwalch added this to the 1.2.4 milestone Sep 14, 2022
@robwalch robwalch removed this from the 1.2.4 milestone Sep 15, 2022
@mtoczko
Copy link
Collaborator Author

mtoczko commented Sep 17, 2022

@phloxic What AES mode are you using?

@phloxic
Copy link
Contributor

phloxic commented Sep 17, 2022

@phloxic What AES mode are you using?

Oh, in that version AES-128 for audio and subtitles, and Sample AES for the video. The original symptoms were the same when using AES-128 for everything. Do you need another one like that?

@phloxic
Copy link
Contributor

phloxic commented Sep 17, 2022

@phloxic What AES mode are you using?

@mtoczko - here's a pure AES-128 version. HTH.

@mtoczko
Copy link
Collaborator Author

mtoczko commented Oct 4, 2022

Hi @robwalch
Your PR #4861 solves the problem with webCryptoDecrypt, there must have been some conflict/race.
I removed the attempt to reload the fragment, only a warning will be returned.

@@ -326,6 +326,10 @@ export class SubtitleStreamController
tdecrypt: endTime,
},
});
})
.catch((e) => {
this.warn(e.message);
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Recently, in #4933 the exception I encountered had no message, only an e.name of "OperationError". Should we account for that here?

Suggested change
this.warn(e.message);
this.warn(e.name || e.message);

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You are talking about a WebCrypto error which is handled by

 .catch((err) => {
        logger.warn(
          '[decrypter.ts]: WebCrypto Error, disable WebCrypto API:',
          err
        );

src/crypt/decrypter.ts Outdated Show resolved Hide resolved
robwalch
robwalch previously approved these changes Oct 5, 2022
Copy link
Collaborator

@robwalch robwalch left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks @mtoczko,

Can you resolve the merge conflicts or would you like me to?

@mtoczko
Copy link
Collaborator Author

mtoczko commented Oct 5, 2022

@robwalch If you could resolve this conflict, that would be great.

@robwalch robwalch merged commit ca19059 into video-dev:master Oct 5, 2022
@robwalch robwalch added this to the 1.3.0 milestone Oct 5, 2022
@mtoczko mtoczko deleted the bugfix/4898-part-2 branch October 5, 2022 21:32
@robwalch robwalch mentioned this pull request Oct 6, 2022
3 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
Development

Successfully merging this pull request may close these issues.

3 participants