Death audio clip not playing

ppineda · April 25, 2020, 4:09pm

When processing the death sequence, the explosion audio clip is not being played. This happened after Ben suggested stopping the “thrust” audio clip before playing the “explosion” audio clip. In short, my code performs the following sequence, but the explosion audio clip is not being played.

                        audioSource.Stop();
                        audioSource.PlayOneShot(explosionAudio);

During debugging and troubleshooting, I found a few issues.

The value of state member variable seems to be cached and not changing
[SerializeField] explosionAudio is being set to null outside of my C# script

What am I doing wrong? Is there a bug with C# or Unity or both?

I am using Unity version 2019.3.11f1 (ceef2d848e70) Personal

I thought that this may be a thread synchronization issue, and I added ‘lock(this)’ to synchronize setting the value of state, but this did’t help. I also added volatile to the state declaration ‘volatile State state’, but this didn’t work either.

Below is my code.

using System;
using UnityEngine;
using UnityEngine.SceneManagement;

public class Rocket : MonoBehaviour
{
    // rotation control system 
    [SerializeField] float rcsThrust = 10f;
    [SerializeField] float mainThrust = 100f;
    [SerializeField] AudioClip mainEngineAudio;
    [SerializeField] AudioClip explosionAudio;
    [SerializeField] AudioClip finishedAudio;

    enum State
    {
        Alive,
        Dying,
        Transcending
    }
    volatile State state;

    int currentPlayLevel = 0;

    Rigidbody rigidBody;
    AudioSource audioSource;

    // Start is called before the first frame update
    void Start()
    {
        rigidBody = GetComponent<Rigidbody>();
        audioSource = GetComponent<AudioSource>();
        ResetGameEnvironment();
    }

    // Update is called once per frame
    void Update()
    {
        if (state == State.Alive )
        {
            HandleThrustInput();
            HandleRotateInput();
        }
    }

    // Reports when collisions have occurred
    void OnCollisionEnter(Collision collision)
    {
        Debug.Log("OnCollision - ");
        if (state != State.Alive)
        {
            return;
        }

        switch (collision.gameObject.tag)
        {
            case "Friendly":
                // do nothing
                break;
            case "Finish":
                FinishAndTransitionToNextLevelLevel();
                break;
            default:
                DieAndRestartLevel();
                break;
        }
    }

    private void FinishAndTransitionToNextLevelLevel()
    {
        if (state != State.Transcending)
        {
            Debug.Log("StartFinishedSequence - state = State.Transcending");
            state = State.Transcending;
            if (audioSource.isPlaying)
            {
                Debug.Log("StartFinishedSequence - audioSource.Stop()");
                audioSource.Stop();
            }
            audioSource.PlayOneShot(finishedAudio);
            // LoadNextLevel after 1 second
            Invoke("LoadNextLevel", 1f);  // todo parameterize delay time
        }
        else
        {
            Debug.Log("StartFinishedSequence state already State.Transcending");
        }
    }

    private void DieAndRestartLevel()
    {
        Debug.Log("Starting Death Sequence state: " + state );

        // Variable state is not synchronized when it is updated.
        // OnCollisionEnter may be called multiple times
        // Through race condition, this may be called again just before
        // state is set to State.Dying
        if (state != State.Dying)
        {
            Debug.Log("StartDeathSequence - gettting lock");
            lock (this)
            {
                Debug.Log("StartDeathSequence - got lock");
                if (state != State.Dying)
                {
                    Debug.Log("StartDeathSequence - state = State.Dying");
                    state = State.Dying;

                    // If mainEngineAudio is playing,
                    // stop playing it.
                    if (audioSource.isPlaying)
                    {
                        Debug.Log("StartDeathSequence - audioSource.Stop()");
                        audioSource.Stop();
                    }
                    if (explosionAudio != null)
                    {
                        Debug.LogError("Playing explosionAudio");
                        audioSource.PlayOneShot(explosionAudio);
                    }
                    else
                    {
                        // This may be set to null because the scene could have been
                        // reloaded because of a race condition
                        Debug.LogError("explosionAudio is null!!");
                    }
                    // LoadNextLevel after 1 second
                    Invoke("ReloadLevel", 1f);  // todo parameterize delay time
                }
            }
        }
        else
        {
            Debug.Log("StartDeathSequence state already State.Dying");
        }
    }

    private void ReloadLevel()
    {
        LoadLevel(currentPlayLevel);
    }

    private void LoadNextLevel()
    {
        currentPlayLevel++;
        LoadLevel(currentPlayLevel);
    }

    private void LoadLevel(int levelId)
    {
        SceneManager.LoadScene(levelId);
    }

    private void ResetGameEnvironment()
    {
        Debug.Log("ResetGameEnvironment - state = State.Alive");
        state = State.Alive;
        // If any audio is playing,
        // stop playing audio.
        if (audioSource.isPlaying)
        {
            Debug.Log("ResetGameEnvironment - audioSource.Stop()");
            audioSource.Stop();
        }
    }

    private void HandleThrustInput()
    {
        float thrustSpeed = mainThrust * Time.deltaTime;

        if (Input.GetKey(KeyCode.Space))
        {
            if (!audioSource.isPlaying)
            {
                if (mainEngineAudio != null)
                {
                    audioSource.PlayOneShot(mainEngineAudio);
                }
            }
            // apply force in the direction rocket is facing
            rigidBody.AddRelativeForce(Vector3.up * thrustSpeed);
        }
        if (Input.GetKeyUp(KeyCode.Space))
        {
            if (audioSource.isPlaying)
            {
                Debug.Log("RespondToThrustInput - audioSource.Stop()");
                audioSource.Stop();
            }
        }
    }

    private void HandleRotateInput()
    {
        float rotationSpeed = rcsThrust * Time.deltaTime;

        // Take manual control of rotation
        rigidBody.freezeRotation = true;

        if (Input.GetKey(KeyCode.A))
        {
            transform.Rotate(Vector3.forward * rotationSpeed);
        }
        else if (Input.GetKey(KeyCode.S))
        {
            transform.Rotate(-Vector3.forward * rotationSpeed);
        }

        // return rotation control back to Physics engine
        rigidBody.freezeRotation = false;
    }

}

Below is the output from the Unity Editor console:
Note that even though state is being set to State.Dying, somehow, on subsequent calls to OnCollisionEnter(), state’s value is changed back to State.Alive.

-------------------------------------------------------------------
ResetGameEnvironment - state = State.Alive
UnityEngine.Debug:Log(Object)
Rocket:ResetGameEnvironment() (at Assets/Scenes/Rocket.cs:155)
Rocket:Start() (at Assets/Scenes/Rocket.cs:32)
-------------------------------------------------------------------
ResetGameEnvironment - audioSource.Stop()
UnityEngine.Debug:Log(Object)
Rocket:ResetGameEnvironment() (at Assets/Scenes/Rocket.cs:161)
Rocket:Start() (at Assets/Scenes/Rocket.cs:32)
-------------------------------------------------------------------
ResetGameEnvironment - state = State.Alive
UnityEngine.Debug:Log(Object)
Rocket:ResetGameEnvironment() (at Assets/Scenes/Rocket.cs:155)
Rocket:Start() (at Assets/Scenes/Rocket.cs:32)
-------------------------------------------------------------------
OnCollision - 
UnityEngine.Debug:Log(Object)
Rocket:OnCollisionEnter(Collision) (at Assets/Scenes/Rocket.cs:48)
-------------------------------------------------------------------
OnCollision - 
UnityEngine.Debug:Log(Object)
Rocket:OnCollisionEnter(Collision) (at Assets/Scenes/Rocket.cs:48)
-------------------------------------------------------------------
OnCollision - 
UnityEngine.Debug:Log(Object)
Rocket:OnCollisionEnter(Collision) (at Assets/Scenes/Rocket.cs:48)
-------------------------------------------------------------------
OnCollision - 
UnityEngine.Debug:Log(Object)
Rocket:OnCollisionEnter(Collision) (at Assets/Scenes/Rocket.cs:48)
-------------------------------------------------------------------
OnCollision - 
UnityEngine.Debug:Log(Object)
Rocket:OnCollisionEnter(Collision) (at Assets/Scenes/Rocket.cs:48)
-------------------------------------------------------------------
Starting Death Sequence state: Alive
UnityEngine.Debug:Log(Object)
Rocket:DieAndRestartLevel() (at Assets/Scenes/Rocket.cs:91)
Rocket:OnCollisionEnter(Collision) (at Assets/Scenes/Rocket.cs:63)
-------------------------------------------------------------------
StartDeathSequence - gettting lock
UnityEngine.Debug:Log(Object)
Rocket:DieAndRestartLevel() (at Assets/Scenes/Rocket.cs:99)
Rocket:OnCollisionEnter(Collision) (at Assets/Scenes/Rocket.cs:63)
-------------------------------------------------------------------
StartDeathSequence - got lock
UnityEngine.Debug:Log(Object)
Rocket:DieAndRestartLevel() (at Assets/Scenes/Rocket.cs:102)
Rocket:OnCollisionEnter(Collision) (at Assets/Scenes/Rocket.cs:63)
-------------------------------------------------------------------
StartDeathSequence - state = State.Dying
UnityEngine.Debug:Log(Object)
Rocket:DieAndRestartLevel() (at Assets/Scenes/Rocket.cs:105)
Rocket:OnCollisionEnter(Collision) (at Assets/Scenes/Rocket.cs:63)
-------------------------------------------------------------------
StartDeathSequence - audioSource.Stop()
UnityEngine.Debug:Log(Object)
Rocket:DieAndRestartLevel() (at Assets/Scenes/Rocket.cs:112)
Rocket:OnCollisionEnter(Collision) (at Assets/Scenes/Rocket.cs:63)
-------------------------------------------------------------------
Playing explosionAudio
UnityEngine.Debug:LogError(Object)
Rocket:DieAndRestartLevel() (at Assets/Scenes/Rocket.cs:117)
Rocket:OnCollisionEnter(Collision) (at Assets/Scenes/Rocket.cs:63)
-------------------------------------------------------------------
OnCollision - 
UnityEngine.Debug:Log(Object)
Rocket:OnCollisionEnter(Collision) (at Assets/Scenes/Rocket.cs:48)
-------------------------------------------------------------------
Starting Death Sequence state: Alive
UnityEngine.Debug:Log(Object)
Rocket:DieAndRestartLevel() (at Assets/Scenes/Rocket.cs:91)
Rocket:OnCollisionEnter(Collision) (at Assets/Scenes/Rocket.cs:63)
-------------------------------------------------------------------
StartDeathSequence - gettting lock
UnityEngine.Debug:Log(Object)
Rocket:DieAndRestartLevel() (at Assets/Scenes/Rocket.cs:99)
Rocket:OnCollisionEnter(Collision) (at Assets/Scenes/Rocket.cs:63)
-------------------------------------------------------------------
StartDeathSequence - got lock
UnityEngine.Debug:Log(Object)
Rocket:DieAndRestartLevel() (at Assets/Scenes/Rocket.cs:102)
Rocket:OnCollisionEnter(Collision) (at Assets/Scenes/Rocket.cs:63)
-------------------------------------------------------------------
StartDeathSequence - state = State.Dying
UnityEngine.Debug:Log(Object)
Rocket:DieAndRestartLevel() (at Assets/Scenes/Rocket.cs:105)
Rocket:OnCollisionEnter(Collision) (at Assets/Scenes/Rocket.cs:63)
-------------------------------------------------------------------
StartDeathSequence - audioSource.Stop()
UnityEngine.Debug:Log(Object)
Rocket:DieAndRestartLevel() (at Assets/Scenes/Rocket.cs:112)
Rocket:OnCollisionEnter(Collision) (at Assets/Scenes/Rocket.cs:63)
-------------------------------------------------------------------
explosionAudio is null!!
UnityEngine.Debug:LogError(Object)
Rocket:DieAndRestartLevel() (at Assets/Scenes/Rocket.cs:124)
Rocket:OnCollisionEnter(Collision) (at Assets/Scenes/Rocket.cs:63)
-------------------------------------------------------------------
ResetGameEnvironment - state = State.Alive
UnityEngine.Debug:Log(Object)
Rocket:ResetGameEnvironment() (at Assets/Scenes/Rocket.cs:155)
Rocket:Start() (at Assets/Scenes/Rocket.cs:32)
-------------------------------------------------------------------
ResetGameEnvironment - audioSource.Stop()
UnityEngine.Debug:Log(Object)
Rocket:ResetGameEnvironment() (at Assets/Scenes/Rocket.cs:161)
Rocket:Start() (at Assets/Scenes/Rocket.cs:32)
-------------------------------------------------------------------
ResetGameEnvironment - state = State.Alive
UnityEngine.Debug:Log(Object)
Rocket:ResetGameEnvironment() (at Assets/Scenes/Rocket.cs:155)
Rocket:Start() (at Assets/Scenes/Rocket.cs:32)
-------------------------------------------------------------------
OnCollision - 
UnityEngine.Debug:Log(Object)
Rocket:OnCollisionEnter(Collision) (at Assets/Scenes/Rocket.cs:48)
-------------------------------------------------------------------
OnCollision - 
UnityEngine.Debug:Log(Object)
Rocket:OnCollisionEnter(Collision) (at Assets/Scenes/Rocket.cs:48)
-------------------------------------------------------------------
OnCollision - 
UnityEngine.Debug:Log(Object)
Rocket:OnCollisionEnter(Collision) (at Assets/Scenes/Rocket.cs:48)
-------------------------------------------------------------------
OnCollision - 
UnityEngine.Debug:Log(Object)
Rocket:OnCollisionEnter(Collision) (at Assets/Scenes/Rocket.cs:48)
-------------------------------------------------------------------

Nina · April 24, 2020, 4:43pm

Hi Pierre,

First of all, good job on adding helpful Debug.Logs to your code.

Since you do not know how/why the state value gets set back to State.Alive, the goal should be to lift this secret. Comment out parts of your code to simplify it. Also log GetInstanceID() into your console to see if the messages in your console stem from the same Rocket object.

And you could also log Time.frameCount into your console, so you know what is going on in each frame.

ppineda · April 24, 2020, 5:03pm

Hi Nina,

Thanks a lot for the GetInstanceID() suggestion! There are 2 different instances of the rocket being used.

I updated DieAndRestartLevel() with the following.

    private void DieAndRestartLevel()
    {
        int myInstId = this.GetInstanceID();
        Debug.Log("Starting Death Sequence instanceId: " + myInstId + " state: " + state );

Now I see the following in the console when OnCollisionEnter() is called.

Starting Death Sequence instanceId: -1258 state: Alive
:
:
Starting Death Sequence instanceId: -1262 state: Alive

How is the second instance getting created?

How do I detect via the Unity Editor if I have either multiple instances of “Rocket Ship” or if I have multiple references to my Rocket.cs script?

I only see one “Rocket Ship” in my scene as seen the image

Nina · April 24, 2020, 5:42pm

Does your first rocket get destroyed? This could happen when a new or the same level get loaded. Unless I’m wrong, the level gets reloaded in the ReloadLevel method.

By the way, currentPlayLevel gets destroyed along with the Rocket object. Instead of reloading the level, you could simply set the starting position of the rocket to transform.position.

ppineda · April 24, 2020, 6:20pm

Hi Nina,

On collision, I don’t reload the level anymore. I still see a second instance in the console logs. I reduced the code to the following.

using UnityEngine;

public class Rocket : MonoBehaviour
{
    // rotation control system 
    [SerializeField] float rcsThrust = 10f;
    [SerializeField] float mainThrust = 100f;
    [SerializeField] AudioClip mainEngineAudio;
    [SerializeField] AudioClip explosionAudio;

    enum State
    {
        Alive,
        Dying,
        Transcending
    }
    volatile State state;

    int currentPlayLevel = 0;

    Rigidbody rigidBody;
    AudioSource audioSource;

    // Start is called before the first frame update
    void Start()
    {
        rigidBody = GetComponent<Rigidbody>();
        audioSource = GetComponent<AudioSource>();
    }

    // Update is called once per frame
    void Update()
    {
        if (state == State.Alive )
        {
            HandleThrustInput();
            HandleRotateInput();
        }
    }

    // Reports when collisions have occurred
    void OnCollisionEnter(Collision collision)
    {
        Debug.Log("OnCollision - ");
        if (state != State.Alive)
        {
            return;
        }

        switch (collision.gameObject.tag)
        {
            case "Friendly":
                // do nothing
                break;
            default:
                Die();
                break;
        }
    }

    private void Die()
    {
        int myInstId = this.GetInstanceID();
        Debug.Log("Starting Death Sequence instanceId: " + myInstId + " state: " + state);

        // Variable state is not synchronized when it is updated.
        // OnCollisionEnter may be called multiple times
        // Through race condition, this may be called again just before
        // state is set to State.Dying
        if (state != State.Dying)
        {
            Debug.Log("StartDeathSequence - gettting lock");
            lock (this)
            {
                Debug.Log("StartDeathSequence - got lock");
                if (state != State.Dying)
                {
                    Debug.Log("StartDeathSequence - state = State.Dying");
                    state = State.Dying;

                    // If mainEngineAudio is playing,
                    // stop playing it.
                    if (audioSource.isPlaying)
                    {
                        Debug.Log("StartDeathSequence - audioSource.Stop()");
                        audioSource.Stop();
                    }
                    if (explosionAudio != null)
                    {
                        Debug.LogError("Playing explosionAudio");
                        audioSource.PlayOneShot(explosionAudio);
                    }
                    else
                    {
                        // This may be set to null because the scene could have been
                        // reloaded because of a race condition
                        Debug.LogError("explosionAudio is null!!");
                    }
                }
            }
        }
        else
        {
            Debug.Log("StartDeathSequence state already State.Dying");
        }
    }

    private void HandleThrustInput()
    {
        float thrustSpeed = mainThrust * Time.deltaTime;

        if (Input.GetKey(KeyCode.Space))
        {
            if (!audioSource.isPlaying)
            {
                if (mainEngineAudio != null)
                {
                    audioSource.PlayOneShot(mainEngineAudio);
                }
            }
            // apply force in the direction rocket is facing
            rigidBody.AddRelativeForce(Vector3.up * thrustSpeed);
        }
        if (Input.GetKeyUp(KeyCode.Space))
        {
            if (audioSource.isPlaying)
            {
                Debug.Log("RespondToThrustInput - audioSource.Stop()");
                audioSource.Stop();
            }
        }
    }

    private void HandleRotateInput()
    {
        float rotationSpeed = rcsThrust * Time.deltaTime;

        // Take manual control of rotation
        rigidBody.freezeRotation = true;

        if (Input.GetKey(KeyCode.A))
        {
            transform.Rotate(Vector3.forward * rotationSpeed);
        }
        else if (Input.GetKey(KeyCode.S))
        {
            transform.Rotate(-Vector3.forward * rotationSpeed);
        }

        // return rotation control back to Physics engine
        rigidBody.freezeRotation = false;
    }

}

Nina · April 24, 2020, 6:24pm

Where does the volatile keyword come from? I haven’t noticed it the first time.

In Awake, add the following:

    void Awake()
    {
        Debug.Log(Time.frameCount + " --- Rocket was created.", gameObject);
        Debug.Log(Time.frameCount + " --- Rocket id: " + GetInstanceID());
    }

When the message appears a second time, click on the first message once. A game object in your Hierarchy should get highlighted.

Also add:

    void OnDestroy()
    {
        Debug.Log(Time.frameCount + " --- Rocket was destroyed.");
        Debug.Log(Time.frameCount + " --- Rocket id: " + GetInstanceID());
    }

It might be that there is more than one Rocket component in your scene.

ppineda · April 24, 2020, 6:33pm

HI Nina,

Attached is my Unity project without the Library directory.

3_project_boost - backup 2.zip (809.8 KB)

I’ll add the functions Awake() and OnDestroy() above and get back with you.

ppineda · April 24, 2020, 6:57pm

Hi Nina,

I played Level 1 two times. Both times, Awake() is called twice before Start() is called. Below is the output from console logs:

Awake - 0 --- Rocket was created.
UnityEngine.Debug:Log(Object, Object)
Rocket:Awake() (at Assets/Scenes/Rocket.cs:37)

Awake - 0 --- Rocket id: -6048
UnityEngine.Debug:Log(Object)
Rocket:Awake() (at Assets/Scenes/Rocket.cs:38)

Awake - 0 --- Rocket was created.
UnityEngine.Debug:Log(Object, Object)
Rocket:Awake() (at Assets/Scenes/Rocket.cs:37)

Awake - 0 --- Rocket id: -6044
UnityEngine.Debug:Log(Object)
Rocket:Awake() (at Assets/Scenes/Rocket.cs:38)

Start
UnityEngine.Debug:Log(Object)
Rocket:Start() (at Assets/Scenes/Rocket.cs:28)

After playing the first time, I clicked on the first Awake log, and the Unity Editor highlighted the Rocket Ship instance in the Level 1 hierarchy. After playing the second time, I clicked on the second Awake log, and the Unity Editor highlighted the same Rocket Ship instance in the Level 1 hierarchy.

With respect to OnDestroy(), it was executed twice for both Rocket Ship instances created by Awake() when I stopped the game in Unity Editor.

ppineda · April 24, 2020, 7:00pm

Hi Nina,

I forgot to answer your question about ‘volatile’. I added that when I thought there was only one instance of Rocket Ship getting created. I was thinking that the C# compiler was caching the state member variable value as an optimization. I added ‘volatile’ hoping to prevent caching. Now that I know that there are 2 Rocket Ship instances getting created, it may no longer be needed.

Nina · April 24, 2020, 7:04pm

Click on the first and third message. A game object should get highlighted in your Hierarchy. Is it the same?

ppineda · April 24, 2020, 9:42pm

Yes, when clicking on the first and third message, the same game object is getting highlighted.

Nina · April 24, 2020, 9:56pm

Could you share a screenshot of the Inspector of that game object? I suspect that there might be two Rocket scripts assigned to it. Otherwise, the messages would not make any sense unless the message from the OnDestroy method appeared as well.

ppineda · April 24, 2020, 10:22pm

Hi Nina,

You nailed it!! I found a second script attached to the Rocket Ship. See the red rectangles in the image below.

I also noticed that the second script doesn’t have explosionAudio initialized.

I removed the second script, and now only one object is getting logged in the console. However, now the rocket ship doesn’t move up when pressing the space bar. I’ll review the videos again to see what I’m missing.

Thanks for helping me find the second script attached to the rocket!

I did test the thrust sound getting stopped and the explosion getting played by moving the rocket to another place and just letting the rocket drop to the ground.

Thanks for all your help! This is a very big lesson which I won’t forget.

Nina · April 24, 2020, 10:31pm

If you cannot find the issue in your project: There is a strange bug in Unity which prevents the rocket from flying when it is selected in the Hierarchy. Try to select something else and click into the game window once to set Unity’s focus on the game window again.

I’m glad to hear that. In my opinion, interpreting information correctly is usually the most difficult part about debugging. The rest is strategy.

ppineda · April 25, 2020, 4:09pm

Just FYI, I solved my thrust and rotation problem.

When I was working through the challenges, I wound up mixing up the scripts which I was adjusting during testing.

One script had explosionAudio initialized but had bad values for rcs and thrust. The other script had explosionAudio set, but had bad values for rcs and thrust.

After correcting the rcsThrust and mainThrust in the remaining script, I’m good to go again.

Again, thanks for all your help.

Nina · April 25, 2020, 4:09pm

Good job!