RenderHeads / UnityPlugin-AVProMovieCapture

AVPro Movie Capture is a Unity Plugin for advanced video capture to AVI/MP4/MOV files
https://renderheads.com/products/avpro-movie-capture/
48 stars 8 forks source link

Capture stops after 5-10 seconds without warning #180

Closed artoonie closed 1 year ago

artoonie commented 2 years ago

Describe the bug Occasionally (about 1 in 100 videos), the capture stops after 5-10 seconds. There are no error messages. The video just stops encoding.

Your Setup (please complete the following information):

To Reproduce Unfortunately, I don't have reliably reproducible steps, so I can't give too much useful information here. I still wanted to flag, in case others can find a way to reproduce, or in the hopes that you may somehow know what's going on.

Here's what happens:

  1. StartCapture
  2. Wait at least 15 seconds, printing out CaptureStats every second
  3. About 1% of the time, frames will stop encoding. The video is only a few seconds long. StopCapture wasn't called, and there is no Log Output about pausing, canceling, or stopping capture. When I StopCapture later, everything seems to work as I expect.

Logs Once it hits the bug, CaptureStats looks like this:

FPS: 29.88327.
FramesTotal: 309
NumDroppedFrames: 0.
NumDroppedEncoderFrames: 0
NumEncodedFrames: 309
TotalEncodedSeconds: 10

And it prints out the same thing every frame. That's also my workaround: if NumEncodedFrames isn't increasing after some time, I'm going to manually stop and start capture.

Videos Attached is one video where this has happened. Let me know if you would like additional videos.

https://user-images.githubusercontent.com/537316/180242743-ad987fbb-b2a8-496c-ae95-fe5180683b9e.MP4

Chris-RH commented 2 years ago

Hi @artoonie Thanks for letting us know. If you can provide any further details, we'd be most grateful, such as:

  1. What device(s) does this occur on?
  2. I presume for your use that your testing is always using Capture From Texture?
  3. Are you always capturing the same video specs/Do you know if it has occurred using different specs?
  4. What are your recording settings? Is it set to stop manually? Have you inserted any of your own code for this?
artoonie commented 2 years ago
  1. Occurs on iPhone 12 Pro, iPhone 12 Mini, and perhaps more
  2. Yes, always CaptureFromTexture
  3. Yes, always the same specs. I auto-restart video capture after 10 minutes, and what I see after several hours of recording is that occasionally, just one of the 10-minute clips is just a few seconds long. All others are fine. The phone was not touched in any way - there is just a set of (say) 5 working 10-minute clips, one broken one, then another 5 working ones.
  4. It is not set to stop manually. (If it were, I would expect to see debug.log output about it intentionally stopping.) None of my code is inserted into the RenderHeads libraries.
Chris-RH commented 2 years ago

Awesome, thanks for the extra info. Hopefully we'll be able to narrow down what is causing the problem.

stale[bot] commented 2 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

Chris-RH commented 2 years ago

Hey @artoonie, has this been occurring at all in the newer versions?

artoonie commented 2 years ago

Hi Chris, I have still been seeing it, <1% of the time. It only occurs on iOS, and spans all OSs and devices. Here are the stats I have on it:

image image

As hinted at above, I now have a workaround that's not great but is workable: if NumEncodedFrames doesn't increase for 1 second, I stop the recording, log a bug, and restart. I can add whatever logs you need when I log the bug, so if there's something that would help debug, I'm happy to Debug.Log it and send it to you.

My hunch is that it's related to one recording finishing writing while another one starts. My use case is the following:

Chris-RH commented 2 years ago

Hi @artoonie, Thank you for the extra information, that's very helpful. Logs would be great if you've got a chance, thank you :)

artoonie commented 2 years ago

Sounds good - currently I'm just printing out CaptureStats, which doesn't seem to contain anything useful for debugging this. Is there anything else I should log? (See initial post for the contents of CaptureStats)

Chris-RH commented 2 years ago

Our iOS dev is on holiday at the moment, so I'll see if he wants anything specific when he gets back, thanks 😊

On Wed, 17 Aug 2022, 18:34 Armin Samii, @.***> wrote:

Sounds good - currently I'm just printing out CaptureStats, which doesn't seem to contain anything useful for debugging this. Is there anything else I should log? (See initial post for the contents of CaptureStats)

— Reply to this email directly, view it on GitHub https://github.com/RenderHeads/UnityPlugin-AVProMovieCapture/issues/180#issuecomment-1218308994, or unsubscribe https://github.com/notifications/unsubscribe-auth/AYRROUPKIZX6CWG622FNJSLVZUPC3ANCNFSM54H5T5LA . You are receiving this because you commented.Message ID: @.*** com>

MorrisRH commented 2 years ago

Well this is quite weird.

As you're getting a valid movie file output something is definitely calling stop on the recorder. This could be being triggered by the app being sent to the background, for example if the device received a call this would happen.

I'll need to rig a test scene for this so if I could just check a few things:

  1. Are you using the stop mode functionality to stop the recording or something else? If so what are the stop mode settings?
  2. What is the source for the texture you're capturing? It looks like you're capturing from a video, are you using AVPro Video for this?
artoonie commented 2 years ago
  1. I auto-stop the recording after 10 minutes to restart it; the 10-second video above is manually stopped, but if I don't, the full 10-minute video holds the same frame for the full ten minutes (and the filesize is tiny - it's not re-encoding that frame over and over).
  2. The source is a WebCamTexture piped through a custom shader that adds the watermark in the bottom-right corner. AVProMovieCapture is only connected to the RenderTexture, so the WebCamTexture is probably irrelevant

Some additional information: I would expect to see this same behavior if the RenderTexture is reinitialized without calling SetSourceTexture again:

RenderTexture tex = new RenderTexture(w, h, 0, RenderTextureFormat.ARGB32);
captureFromTexture.SetSourceTexture(tex);
/* Write ten frames */
tex = new RenderTexture(w, h, 0, RenderTextureFormat.ARGB32);

However, I have several checks in the code to ensure this isn't happening. I don't know if this is the actual cause, but it seems like CaptureFromTexture is "losing" the RenderTexture - as if Unity changed RenderTexture under the hood. This hunch could be a red herring.

MorrisRH commented 2 years ago

It does feel like the RenderTexture's underlying native texture has been lost. I take it this is a real time capture then and you're not using the manual frame update mode?

artoonie commented 2 years ago

Correct, this is real time capture.

I'll add some debug logs to print out sourceTexture.GetNativeTexturePtr() every so often. When I detect this bug is encountered, I should be able to see if that value has unexpectedly changed - that may help pin this down. LMK if there's other info I should be periodically logging.

MorrisRH commented 2 years ago

So I rigged a test scene matching your description: webcam texture -> blit with custom shader to render texture -> capture from texture component. Unfortunately it worked perfectly and I now have approx. 9 hours of 10 minute clips. This was using and iPad Pro (10.5") with iOS 15.6.1. I'll switch to another device to see if that has any influence (it will be an iPhone X running iOS 14.8.1).

The capture size was 1024x1024, outputting to h264 with audio coming from the microphone.

If you could share one of the full 10 minute broken videos that might yield some clues.

MorrisRH commented 2 years ago

This is the test script I'm using. The capture component is using the default settings.

Issue180.cs ```csharp using System.Collections; using System.Collections.Generic; using UnityEngine; using RenderHeads.Media.AVProMovieCapture; [RequireComponent(typeof(CaptureFromTexture))] public class Issue180 : MonoBehaviour { CaptureFromTexture _capture; WebCamTexture _webCamTexture; RenderTexture _renderTexture; Material _material; string GetFrontCamera() { foreach(WebCamDevice device in WebCamTexture.devices) { if (device.isFrontFacing) { return device.name; } } return null; } bool ready = false; // Start is called before the first frame update IEnumerator Start() { yield return Application.RequestUserAuthorization(UserAuthorization.WebCam); if (!Application.HasUserAuthorization(UserAuthorization.WebCam)) { Debug.LogError("failed to get user authorization for the camera"); enabled = false; yield break; } yield return CaptureBase.RequestAudioCaptureDeviceUserAuthorisation(); if (CaptureBase.HasUserAuthorisationToCaptureAudio() != CaptureBase.AudioCaptureDeviceAuthorisationStatus.Authorised) { Debug.LogError("failed to get user authorization for the microphone"); enabled = false; yield break; } Resolution screenRes = Screen.currentResolution; Debug.Log("screenRes: " + screenRes); string deviceName = GetFrontCamera(); _webCamTexture = new WebCamTexture(deviceName, screenRes.width, screenRes.height, 30); if (_webCamTexture == null) { Debug.LogError("failed to create webcam texture"); enabled = false; yield break; } RenderTextureDescriptor desc = new RenderTextureDescriptor(screenRes.width, screenRes.height, RenderTextureFormat.ARGB32); _renderTexture = new RenderTexture(desc); bool created = _renderTexture.Create(); if (created == false) { Debug.LogError("failed to create render texture"); enabled = false; yield break; } _material = new Material(Shader.Find("Unlit/Pixelate")); _material.SetMatrix("_TexXfrm", Matrix4x4.Rotate(Quaternion.AngleAxis(90, Vector3.forward))); _capture = GetComponent(); _capture.SetSourceTexture(_renderTexture); _webCamTexture.Play(); StartCoroutine(Record()); ready = true; } int numCaptures = 0; IEnumerator Record() { while (true) { if (_capture.IsCapturing()) { yield return new WaitForSeconds(600); _capture.StopCapture(); } _capture.StartCapture(); numCaptures += 1; } } // Update is called once per frame void Update() { if (_webCamTexture != null && _webCamTexture.didUpdateThisFrame) { Graphics.Blit(_webCamTexture, _renderTexture, _material); } } void OnGUI() { GUI.matrix = Matrix4x4.Scale(new Vector3(3.0f, 3.0f, 1.0f)); GUILayout.BeginVertical(); GUILayout.Space(20.0f); if (!ready) { GUILayout.Label("Still getting ready"); GUILayout.EndVertical(); return; } bool isCapturing = _capture.IsCapturing(); if (isCapturing) { GUILayout.Label("Is Capturing"); if (GUILayout.Button("Stop Capturing")) { _capture.StopCapture(); } GUILayout.Label("FPS: " + _capture.CaptureStats.FPS); GUILayout.Label("FramesTotal: " + _capture.CaptureStats.FramesTotal); GUILayout.Label("NumDroppedFrames: " + _capture.CaptureStats.NumDroppedFrames); GUILayout.Label("NumDroppedEncoderFrames: " + _capture.CaptureStats.NumDroppedEncoderFrames); GUILayout.Label("NumEncodedFrames: " + _capture.CaptureStats.NumEncodedFrames); GUILayout.Label("TotalEncodedSeconds: " + _capture.CaptureStats.TotalEncodedSeconds); Rect rect = GUILayoutUtility.GetRect(300.0f, 300.0f * 16.0f / 10.0f); GUI.DrawTexture(rect, _renderTexture); } else { GUILayout.Label("NOT Capturing"); } GUILayout.Label("NumCaptures: " + numCaptures); GUILayout.EndVertical(); } } ```
artoonie commented 2 years ago

Thank you for doing that test - the code is indeed similar to what I'm doing on my end.

The bug was last reproduced with 5.0.1 - it's unlikely, but possible that it was resolved in 5.0.2 - more likely, it just hasn't been reproduced yet. (5.0.2 has not been rolled out to most of my users yet.)

Note, the 10 second attached video above is an example of a 10-minute recording; just, it stopped after 10 seconds and remained that way until I called StopCapture 590 seconds later.

For now, it seems I can't rule out that the bug is on my end, so I'm happy to leave this as CNR and the burden will be on me to show whether the bug is really in AVProMovieCapture, or if it's on my end. I'll continue adding information to this thread, but I'm okay if you don't spend any additional resources on this until I have more actionable information. Thanks for what you've done thus far!

MorrisRH commented 2 years ago

I may have reproduced this. It took about 4 hours to show up on the iPhone X and I've only managed to get it to happen once. It was caused by a race condition in the microphone audio capture when finishing a recording.

I've put in a fix which will make it into the next release. I've had the iPhone X running for ~18 hours (and it's still going) now with this in so I'm hopeful that I've caught it.

artoonie commented 2 years ago

Wow! Thank you @MorrisRH for dozens of hours of testing here. Looking forward to the next release. 🎉

Chris-RH commented 2 years ago

The latest version has been released, please let us know if this issue has not been fixed.

MorrisRH commented 1 year ago

Closing this issue for now, if it still happens please let us know and we'll reopen it.

artoonie commented 1 year ago

Hi, I've just gotten my first report of this issue still happening with 5.0.3 - any ideas / what debug info can I provide? As before, I'm limited to Debug.Log data, since it's very hard to reproduce, and that shows nothing strange.

Chris-RH commented 1 year ago

Hi @artoonie,

Thanks for letting us know. There isn't that much that can be done until its reproducible. If you could let us know which model of device and iOS version this is occurring on please, it would help. Also, any logs that you can get may point us in the right direction.

artoonie commented 1 year ago

Thank you, I will!

This has occurred on iPhone11,8 (iPhone XR) and iPhone13,2 (iPhone 12), on iOS 15 and 16.

It is also possible that my detection of the bug just needs a stricter threshold: right now, I check if m_Capture.CaptureStats.FramesTotal doesn't change for 60 frames in a row. Is it possible that there's a reason, other than this bug, that FramesTotal wouldn't change for 60 frames in a row?

I'll also note that this isn't urgent for me because it's easily detectable on my end, and I only lose two seconds of footage before I recover. I'm okay with this being marked low-priority.

MorrisRH commented 1 year ago

I'm trying a different approach to resolving this. I've got the same test as before running and it's been going for over a day now. I am wondering if some external event is acting as the trigger though, a call or notification that maybe interrupting things?

MorrisRH commented 1 year ago

An unintentional 2FA request did cause a capture to stop, however call and text notification had no effect so we can discount those. The app didn't crash though so the test picked up again.

Not sure if the -> applicationWillResignActive() log gets output in release builds but that would be indicative of an event happening that would stop a capture.

artoonie commented 1 year ago

I manually pause capture and log output OnApplicationPause, so that would get outputted and I don't think could be the cause

MorrisRH commented 1 year ago

We stop capturing on iOS in response to OnApplicationPause, this is in CaptureBase.cs line 1420. Wondering if there is a conflict there...

artoonie commented 1 year ago

It's possible, but I would guess not: I still Debug.Log OnApplicationPause, and those logs aren't appearing.

MorrisRH commented 1 year ago

I'm going to add this new approach to the next release (5.0.5). I had my test scene running for over 48 hours without a hitch so hoping this has got it.

Chris-RH commented 1 year ago

The next version has been released, please let us know if this has not fixed the issue.

artoonie commented 1 year ago

Update

This bug isn't totally fixed, but I recognize y'all have put a lot of work into investigating already and I'm doing my best to find a workaround on my end. Still, I wanted to provide some information in case it proves useful to you or others.

New Info

  1. It seems to happen far less frequently than it used to
  2. It only happens on iOS, not Android
  3. It seems to happen more frequently on lower-end iPhones
  4. After I detect that m_Capture.CaptureStats.FramesTotal doesn't change for 4 seconds, I restart the video. About 95% of the time, the restarted video works. However, about 5% of the time, the restarted video is a static video that is just getting the same frame over and over. m_Capture.CaptureStats.FramesTotal increments as expected, but the video file is just one static frame (with correct audio).

Stats

Here are some stats on which users encounter the broken video. You can see that it trends towards lower-end phones.

Screen Shot 2023-04-12 at 1 49 21 PM

Additional Symptoms

I believe, but am not 100% confident, that the secondary bug (the frozen video with incrementing m_Capture.CaptureStats.FramesTotal) only occurs when the previous broken video returns handler.IsFileReady()==false forever.

Summary

To summarize each video in this scenario:

  1. Video 1: StartCapture called
  2. Video 2: 10 minute threshold reached. StopCapture then immediately StartCapture
  3. Video 3: Bug detected. StopCapture then immediately StartCapture

Video 1 is ten minutes long and correct. Video 2 is always between 8 and 12 seconds long, with no new frames for the last 4 seconds of the video

~95% of the time, Video 3 is fine. ~5% of the time: Video 2's handler.IsFileReady() always returns false Video 3 is ten minutes long, but repeats Frame 1 for every frame throughout the video. handler.IsFileReady() eventually returns true as expected. The audio works fine. The file size is about 25% smaller than Video 1.

Chris-RH commented 1 year ago

Thanks for the very detailed report :)

Seeing as its generally older/lower end devices, its most likely a hardware/OS level issue. It is probably the system running out of encoder resources and being unable to encode any more frames. This might be improved if you wait until the previous capture has finished completely (thus releasing encoder resources) before starting the next one.

artoonie commented 1 year ago

That's a great idea. I'll put in a pause between Video 2 and Video 3 above.

I'll get back to you in about a month after our next deployment to see if this helped.

stale[bot] commented 1 year ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.