Error: Failed to set remote answer sdp: Called in wrong state: kStable;

colden.prime · October 19, 2022, 1:21pm

In our app, I need to be able to start multiple WebRTC streams in a row. I am able to start and end one stream successfully. The startup and shutdown processes follow this order: What is the proper order of operations for starting and ending WebRTC sessions?

However, on subsequent stream attempts to establish a new connection, I receive a Error: Failed to set remote answer sdp: Called in wrong state: kStable; error when attempting to set the remote answer. When this occurs, the only way to resolve this error is to terminate our app and restarted it before trying again.

Am I missing something in the shutdown process?

Unity Editor version: 2022.02.0b9
ML2 OS version: B3E.220818.12-R.046-R.417
MLSDK version: 1.0.1

Error messages from logs:

2022-10-19 13:00:55.940;10101;30043;30070;Info;luminkarrot;nova/frameworks/kali/kaliwebrtc/simple/src/Connection.cpp:417 Setting remote answer;
2022-10-19 13:00:55.940;10101;30043;30070;Info;luminkarrot;nova/frameworks/kali/kaliwebrtc/simple/src/Connection.cpp:356 Connection State: 3 (awaiting answer) --> 4 (setting remote answer);
2022-10-19 13:00:55.940;10101;30043;30070;Warn;luminkarrot;nova/frameworks/kali/kaliwebrtc/simple/src/Connection.cpp:358 Connection is in invalid state, expected=3, got=0;
2022-10-19 13:00:55.940;10101;30043;30147;Error;luminkarrot;nova/frameworks/kali/kaliwebrtc/simple/src/Connection.cpp:364 Error: Failed to set remote answer sdp: Called in wrong state: kStable;

sengelman · October 19, 2022, 2:28pm

@colden.prime , I've reached out to our WebRTC team to see what could be happening.

sengelman · October 20, 2022, 3:15pm

@colden.prime , it looks like a state machine mishap. 'Any chance you could send us full logs? Our team is already doing some forensics with what we have in the meantime.

colden.prime · October 20, 2022, 9:40pm

device_Log_20221019_0904_49.txt (8.6 MB)

sengelman · October 21, 2022, 4:54pm

@colden.prime , after analyzing the logs, we have some insights to offer:

The first connection was created the create offer requested, offer was created and sent to remote, remote answer was received and set. The connection was established successfully. No issue here

Regarding the second connection:

Connection was created
Create offer requested
Local offer created and sent to remote
While the second connection was waiting for remote answer
While the second connection was waiting for the remote answer, the third connection was created.
Now the remote answer was received but it was set to the third connection instead of second connection. And that causes the issue. Because the third connection is in idle state which is expecting to receive create offer or set remote offer request. But it received set remote answer. And that put it to invalid state.
This flow is controlled by the application.
Moreover when we look for the issues, the third connection did not send create offer may be because the camera creation failed. But, the application should maintain the connection identity and pass the offer and answer to the right connection.

Offending logs:

2022-10-19 13:00:48.110;10101;30043;30070;Info;Unity;[Proapp]: CreatePeerConnection;
2022-10-19 13:00:48.110;10101;30043;30070;Info;Unity;Proapp.RemoteLogger:LogFormat(LogType, Object, String, Object[]);
2022-10-19 13:00:48.110;10101;30043;30070;Info;Unity;Proapp.WebRTCManager:CreatePeerConnection(List`1);
2022-10-19 13:00:48.110;10101;30043;30070;Info;Unity;Proapp.WebRTCManager:<Connect>b__29_0(Result`1);
2022-10-19 13:00:48.110;10101;30043;30070;Info;Unity;Proapp.<>c__DisplayClass19_0`1:<SendWebRequest>b__0(Result`1);
2022-10-19 13:00:48.110;10101;30043;30070;Info;Unity;UnityEngine.AsyncOperation:InvokeCompletionEvent();
2022-10-19 13:00:48.110;10101;30043;30070;Info;Unity;;
2022-10-19 13:00:48.110;10101;30043;30070;Info;Unity;[Proapp]: CreateIceServers;
2022-10-19 13:00:48.110;10101;30043;30070;Info;luminkarrot;nova/frameworks/kali/kaliwebrtc/simple/src/Factory.cpp:71 Creating peer connection;
.
.
.
2022-10-19 13:00:48.121;10101;30043;30070;Info;Unity;[Proapp]: CreateOffer;
2022-10-19 
13:00:48.121;10101;30043;30070;Info;luminkarrot;nova/frameworks/kali/kaliwebrtc/simple/src/Connection.cpp:386 Creating offer;
2022-10-19 13:00:48.121;10101;30043;30070;Info;luminkarrot;nova/frameworks/kali/kaliwebrtc/simple/src/Connection.cpp:356 Connection State: 0 (idle) --> 1 (creating offer);
2022-10-19 13:00:48.122;10101;30043;30147;Info;luminkarrot;nova/frameworks/kali/kaliwebrtc/simple/src/Connection.cpp:356 Connection State: 1 (creating offer) --> 2 (setting local offer);
2022-10-19 13:00:48.122;10101;30043;30147;Debug;luminkarrot;nova/frameworks/kali/kaliwebrtc/simple/src/Connection.cpp:255 Set local description;
2022-10-19 13:00:48.125;10101;30043;30147;Info;luminkarrot;nova/frameworks/kali/kaliwebrtc/simple/src/Connection.cpp:199 Sending local offer;
2022-10-19 13:00:48.125;10101;30043;30147;Info;luminkarrot;nova/frameworks/kali/kaliwebrtc/simple/src/Connection.cpp:356 Connection State: 2 (setting local offer) --> 3 (awaiting answer);
2022-10-19 13:00:48.121;10101;30043;30070;Info;luminkarrot;nova/frameworks/kali/kaliwebrtc/simple/src/Connection.cpp:356 Connection State: 0 (idle) --> 1 (creating offer);
2
While the offer was being created for second connection, third connection was created
2022-10-19 13:00:48.173;10101;30043;30070;Info;Unity;[Proapp]: SendWebRequest: https://xxx/login POST - 200 {"id":"37bb8ce7b6e41482e25e56e59bd6bcff","tokens":{"accountSid":"AC6d02f0ff65b10b2b41f09359e87928dc","dateCreated":"2022-10-19T13:00:47.000Z","dateUpdated":"2022-10-19T13:00:47.000Z","iceServers":[{"url":"stun:global.stun.twilio.com:3478?transport=udp","urls":"stun:global.stun.twilio.com:3478?transport=udp"},{"url":"turn:global.turn.twilio.com:3478?transport=udp","username":"fc99cfab526a5d838bff1e9b1ca25010e89ef30e7ea3c2544b9d16d95496b5f7","urls":"turn:global.turn.twilio.com:3478?transport=udp","credential":"w+GDu/kRztgabnNdJxHdhGhlTkPyVkm9MkzYLChAYqw="},{"url":"turn:global.turn.twilio.com:3478?transport=tcp","username":"fc99cfab526a5d838bff1e9b1ca25010e89ef30e7ea3c2544b9d16d95496b5f7","urls":"turn:global.turn.twilio.com:3478?transport=tcp","credential":"w+GDu/kRztgabnNdJxHdhGhlTkPyVkm9MkzYLChAYqw="},{"url":"turn:global.turn.twilio.com:443?transport=tcp","username":"fc99cfab526a5d838bff1e9b1ca25010e89ef;
2022-10-19 13:00:48.173;10101;30043;30070;Info;Unity;[Proapp]: httpClient.Login - Success: 37bb8ce7b6e41482e25e56e59bd6bcff - 4 servers;
2022-10-19 13:00:48.174;10101;30043;30070;Info;Unity;[Proapp]: CreatePeerConnection;
2022-10-19 13:00:48.174;10101;30043;30070;Info;Unity;Proapp.RemoteLogger:LogFormat(LogType, Object, String, Object[]);
2022-10-19 13:00:48.174;10101;30043;30070;Info;Unity;Proapp.WebRTCManager:CreatePeerConnection(List`1);
2022-10-19 13:00:48.174;10101;30043;30070;Info;Unity;Proapp.WebRTCManager:<Connect>b__29_0(Result`1);
2022-10-19 13:00:48.174;10101;30043;30070;Info;Unity;Proapp.<>c__DisplayClass19_0`1:<SendWebRequest>b__0(Result`1);
2022-10-19 13:00:48.174;10101;30043;30070;Info;Unity;UnityEngine.AsyncOperation:InvokeCompletionEvent();
2022-10-19 13:00:48.174;10101;30043;30070;Info;Unity;;
2022-10-19 13:00:48.174;10101;30043;30070;Info;Unity;[Proapp]: CreateIceServers;
2022-10-19 13:00:48.174;10101;30043;30070;Info;luminkarrot;nova/frameworks/kali/kaliwebrtc/simple/src/Factory.cpp:71 Creating peer connection;
...
2022-10-19 13:00:48.176;10101;30043;30070;Info;Unity;[Proapp]: SubscribeToConnection;
2022-10-19 13:00:48.176;10101;30043;30070;Info;Unity;[Proapp]: CreateLocalMediaStream;
2022-10-19 13:00:50.152;10101;30043;30070;Error;Unity;[Proapp]: Failed to connect to local camera. Reason: CannotConnect.;
You can see the third connection was created but the camera connect failed for it
Now the remote answer was received but set to wrong connection
2022-10-19 13:00:55.937;10101;30043;30070;Info;Unity;[Proapp]: SendWebRequest: https://xxx/offers/37bb8ce7b6e41482e25e56e59bd6bcff/answers GET - 200 {"700dad83-929c-4ba0-b139-12f6d3b12985":{"type":"answer","sdp":"v=0\r\no=- 1089130965728465282 2 IN IP4 127.0.0.1\r\ns=-\r\nt=0 0\r\na=group:BUNDLE 0 1 2\r\na=msid-semantic: WMS H746Q6B3BChohnE6zkZD9g3TrAGVNIjqnXob\r\nm=video 9 UDP/TLS/RTP/SAVPF 96 97 98 99 100\r\nc=IN IP4 0.0.0.0\r\na=rtcp:9 IN IP4 0.0.0.0\r\na=ice-ufrag:lwC8\r\na=ice-pwd:a4IWU/CXRKbOtZuQes2+ktgt\r\na=ice-options:trickle\r\na=fingerprint:sha-256 67:07:C4:C4:4A:09:8F:F7:05:B9:11:2A:93:DA:FD:AF:C7:5C:4A:F7:4B:81:D5:D4:6F:E7:BE:04:0B:54:EA:F0\r\na=setup:active\r\na=mid:0\r\na=extmap:14 urn:ietf:params:rtp-hdrext:toffset\r\na=extmap:13 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time\r\na=extmap:12 urn:3gpp:video-orientation\r\na=extmap:2 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01\r\na=extmap:11 http://www.webrtc.org/experiments/rtp-hdrext/playout-delay\r\na=;
2022-10-19 13:00:55.938;10101;30043;30070;Info;Unity;[Proapp]: httpClient.GetAnswers - Success: 1;
2022-10-19 13:00:55.938;10101;30043;30070;Info;Unity;Proapp.RemoteLogger:LogFormat(LogType, Object, String, Object[]);
2022-10-19 13:00:55.938;10101;30043;30070;Info;Unity;Proapp.WebRTCManager:<Update>b__28_0(Result`1);
2022-10-19 13:00:55.938;10101;30043;30070;Info;Unity;Proapp.<>c__DisplayClass19_0`1:<SendWebRequest>b__0(Result`1);
2022-10-19 13:00:55.938;10101;30043;30070;Info;Unity;UnityEngine.AsyncOperation:InvokeCompletionEvent();
2022-10-19 13:00:55.938;10101;30043;30070;Info;Unity;;
2022-10-19 13:00:55.939;10101;30043;30070;Info;Unity;[Proapp]: LocalAudioEnabled.get: True;
2022-10-19 13:00:55.939;10101;30043;30070;Info;Unity;Proapp.RemoteLogger:LogFormat(LogType, Object, String, Object[]);
2022-10-19 13:00:55.939;10101;30043;30070;Info;Unity;Proapp.WebRTCManager:get_LocalAudioEnabled();
2022-10-19 13:00:55.939;10101;30043;30070;Info;Unity;Proapp.AppController:UpdateUI();
2022-10-19 13:00:55.939;10101;30043;30070;Info;Unity;Proapp.WebRTCManager:UpdateStatus(ConnectionStatus, String);
2022-10-19 13:00:55.939;10101;30043;30070;Info;Unity;Proapp.WebRTCManager:<Update>b__28_0(Result`1);
2022-10-19 13:00:55.939;10101;30043;30070;Info;Unity;Proapp.<>c__DisplayClass19_0`1:<SendWebRequest>b__0(Result`1);
2022-10-19 13:00:55.939;10101;30043;30070;Info;Unity;UnityEngine.AsyncOperation:InvokeCompletionEvent();
2022-10-19 13:00:55.939;10101;30043;30070;Info;Unity;;
2022-10-19 13:00:55.940;10101;30043;30070;Info;Unity;[Proapp]: WebRTCManager.UpdateStatus Connecting;
2022-10-19 13:00:55.940;10101;30043;30070;Info;Unity;Proapp.RemoteLogger:LogFormat(LogType, Object, String, Object[]);
2022-10-19 13:00:55.940;10101;30043;30070;Info;Unity;Proapp.WebRTCManager:UpdateStatus(ConnectionStatus, String);
2022-10-19 13:00:55.940;10101;30043;30070;Info;Unity;Proapp.WebRTCManager:<Update>b__28_0(Result`1);
2022-10-19 13:00:55.940;10101;30043;30070;Info;Unity;Proapp.<>c__DisplayClass19_0`1:<SendWebRequest>b__0(Result`1);
2022-10-19 13:00:55.940;10101;30043;30070;Info;Unity;UnityEngine.AsyncOperation:InvokeCompletionEvent();
2022-10-19 13:00:55.940;10101;30043;30070;Info;Unity;;
2022-10-19 13:00:55.940;10101;30043;30070;Info;luminkarrot;nova/frameworks/kali/kaliwebrtc/simple/src/Connection.cpp:417 Setting remote answer;
2022-10-19 13:00:55.940;10101;30043;30070;Info;luminkarrot;nova/frameworks/kali/kaliwebrtc/simple/src/Connection.cpp:356 Connection State: 3 (awaiting answer) --> 4 (setting remote answer);
2022-10-19 13:00:55.940;10101;30043;30070;Warn;luminkarrot;nova/frameworks/kali/kaliwebrtc/simple/src/Connection.cpp:358 Connection is in invalid state, expected=3, got=0;
2022-10-19 13:00:55.942;10101;30043;30070;Error;Unity;[Proapp]: OnConnectionError: $Failed to set remote answer sdp: Called in wrong state: kStable;

kdowney · November 3, 2022, 2:31pm

Hi @colden.prime, does this offer any insight into what may be the problem? Thank you for your post.

colden.prime · November 14, 2022, 10:45pm

@kdowney @sengelman I was able to determine that his issue was caused by a bug present in both the example code and my app's code:

private void OnPermissionGranted(string permission)
        {
            grantedPermissions.Add(permission);
            if (grantedPermissions.Count == requiredPermissions.Length)
            {
                StartAfterPermissions();
            }
        }

On the second connection attempt, if grantedPermissions still contains the results from the first connection, StartAfterPermissions will get executed multiple times in quick succession causing the wrong state error.

However, if we clear the grantedPermissions before the second attempt, the second connection will be successful.

kdowney · November 15, 2022, 2:11pm

@colden.prime Thank you for your feedback and the above info. Super helpful and I'll pass this to our engineers.

Topic		Replies	Views
What is the proper order of operations for starting and ending WebRTC sessions? WebRTC development , unity	2	342	October 20, 2022
WebRTC Native Crash: When Reopening WebRTC Calling Screen to Restart Call Functionality in Single Session Unity Development development , unity	15	322	July 24, 2023
InvalidOperationException: Insecure Connection Not Allowed in MLWebRTCExample Unity Development development , unity	2	442	June 9, 2023
Magic Leap 2 Shutting Down and Video Stuck During WebRTC 1v1 Calls Unity Development development , unity	4	244	July 3, 2023
Crash with MLCamera API (we know it has deprecated) Unity Development development , unity , app-sim	13	55	October 18, 2024
WebRTC scene Example Error: MLResult_NotImplemented Unity Development development , unity	2	295	August 30, 2023

Error: Failed to set remote answer sdp: Called in wrong state: kStable;

Related topics