amazon-kinesis-video-streams-webrtc-sdk-c
amazon-kinesis-video-streams-webrtc-sdk-c copied to clipboard
awslabs
[BUG] Channel master does not receive signalling channel messages
Logging 2021-10-12 05:11:59 VERBOSE rtcpReportsCallback(): sender report 714470242 16505577869281378154 4187603 : 4362 packets 741540 bytes 2021-10-12 05:11:59 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577869675665172 7825823 : 13985 packets 5523459 bytes 2021-10-12 05:11:59 VERBOSE rtcpReportsCallback(): sender report 714470242 16505577869724858868 4192559 : 4367 packets 742390 bytes 2021-10-12 05:11:59 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577870205153035 7836918 : 14005 packets 5531152 bytes 2021-10-12 05:11:59 VERBOSE rtcpReportsCallback(): sender report 714470242 16505577870700661264 4203465 : 4379 packets 744430 bytes 2021-10-12 05:11:59 VERBOSE rtcpReportsCallback(): sender report 714470242 16505577871178557121 4208806 : 4385 packets 745450 bytes 2021-10-12 05:11:59 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577871253756415 7858892 : 14057 packets 5561116 bytes 2021-10-12 05:11:59 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577871830282760 7870973 : 14077 packets 5570450 bytes 2021-10-12 05:11:59 VERBOSE rtcpReportsCallback(): sender report 714470242 16505577872381806383 4222253 : 4398 packets 747660 bytes 2021-10-12 05:11:59 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577872513967251 7885299 : 14102 packets 5579237 bytes 2021-10-12 05:12:00 VERBOSE rtcpReportsCallback(): sender report 714470242 16505577873018506938 4229369 : 4406 packets 749020 bytes 2021-10-12 05:12:00 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577873331958805 7902440 : 14127 packets 5587846 bytes 2021-10-12 05:12:00 VERBOSE rtcpReportsCallback(): sender report 714470242 16505577873955903736 4239845 : 4417 packets 750890 bytes 2021-10-12 05:12:00 VERBOSE onRtcpSenderReport(): RTCP_PACKET_TYPE_SENDER_REPORT -871050967 16505577873956624861 rtpTs: 693779614 4441 pkts 244765 bytes 2021-10-12 05:12:00 VERBOSE onRtcpPacket(): unhandled packet type RTCP_PACKET_TYPE_SOURCE_DESCRIPTION 2021-10-12 05:12:00 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577874436713299 7925590 : 14167 packets 5601561 bytes 2021-10-12 05:12:00 VERBOSE rtcpReportsCallback(): sender report 714470242 16505577874905340187 4250456 : 4428 packets 752760 bytes 2021-10-12 05:12:00 VERBOSE rtcpReportsCallback(): sender report 714470242 16505577875498950194 4257090 : 4435 packets 753950 bytes 2021-10-12 05:12:00 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577875614438858 7950269 : 14207 packets 5615703 bytes 2021-10-12 05:12:00 VERBOSE rtcpReportsCallback(): sender report 714470242 16505577876191400713 4264829 : 4443 packets 755310 bytes 2021-10-12 05:12:00 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577876543330763 7969733 : 14242 packets 5628873 bytes 2021-10-12 05:12:01 VERBOSE rtcpReportsCallback(): sender report 714470242 16505577877171495500 4275782 : 4454 packets 757180 bytes 2021-10-12 05:12:01 VERBOSE iceAgentSendKeepAliveTimerCallback(): send keep alive 2021-10-12 05:12:01 VERBOSE iceAgentSendKeepAliveTimerCallback(): send keep alive 2021-10-12 05:12:01 VERBOSE iceAgentSendKeepAliveTimerCallback(): send keep alive 2021-10-12 05:12:01 VERBOSE iceAgentSendKeepAliveTimerCallback(): send keep alive 2021-10-12 05:12:01 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577877753035360 7995082 : 14282 packets 5644730 bytes 2021-10-12 05:12:01 VERBOSE rtcpReportsCallback(): sender report 714470242 16505577878034623724 4285428 : 4464 packets 758880 bytes 2021-10-12 05:12:01 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577878827703608 8017602 : 14322 packets 5662295 bytes 2021-10-12 05:12:01 VERBOSE onRtcpPacket(): unhandled packet type RTCP_PACKET_TYPE_SOURCE_DESCRIPTION 2021-10-12 05:12:01 WARN onRtcpPacket(): unhandled packet type 203 2021-10-12 05:12:01 DEBUG dtlsSessionProcessPacket(): Detected DTLS close_notify alert 2021-10-12 05:12:01 INFO onConnectionStateChange(): New connection state 6 2021-10-12 05:12:01 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 1 2021-10-12 05:12:01 DEBUG sessionCleanupWait(): Termination flag detected for session index 0 2021-10-12 05:12:01 DEBUG sessionCleanupWait(): Will check hash table: session index 0 2021-10-12 05:12:01 DEBUG sessionCleanupWait(): Will remove from hash table: session index 0 2021-10-12 05:12:01 DEBUG sessionCleanupWait(): Will free session with index 0 2021-10-12 05:12:01 DEBUG freeStreamingSession(): Freeing streaming session with peer id: 428eca56-fc08-4418-90ed-9f17bb241066 2021-10-12 05:12:01 DEBUG freeStreamingSession(): Set terminate flag to true for streaming session with peer id: 428eca56-fc08-4418-90ed-9f17bb241066 2021-10-12 05:12:01 DEBUG freeStreamingSession(): Shutdown callback for streaming session with peer id: 428eca56-fc08-4418-90ed-9f17bb241066 2021-10-12 05:12:01 DEBUG freeStreamingSession(): Shutdown callback done for streaming session with peer id: 428eca56-fc08-4418-90ed-9f17bb241066 2021-10-12 05:12:01 DEBUG freeStreamingSession(): Will join receiveAudioVideoSenderTid for streaming session with peer id: 428eca56-fc08-4418-90ed-9f17bb241066 2021-10-12 05:12:01 VERBOSE rtcpReportsCallback(): sender report 714470242 16505577879001932393 4296239 : 4474 packets 760580 bytes 2021-10-12 05:12:01 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577879502975117 8031752 : 14322 packets 5662295 bytes 2021-10-12 05:12:01 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577880020169925 8042590 : 14322 packets 5662295 bytes 2021-10-12 05:12:01 VERBOSE rtcpReportsCallback(): sender report 714470242 16505577880226982908 4309930 : 4474 packets 760580 bytes 2021-10-12 05:12:01 VERBOSE rtcpReportsCallback(): sender report 714470242 16505577880868310002 4317097 : 4474 packets 760580 bytes 2021-10-12 05:12:01 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577881203091106 8067378 : 14322 packets 5662295 bytes 2021-10-12 05:12:02 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577881876674263 8081492 : 14322 packets 5662295 bytes 2021-10-12 05:12:02 VERBOSE rtcpReportsCallback(): sender report 714470242 16505577881930982407 4328973 : 4474 packets 760580 bytes 2021-10-12 05:12:02 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577882505691121 8094673 : 14322 packets 5662295 bytes 2021-10-12 05:12:02 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577882988122034 8104782 : 14322 packets 5662295 bytes 2021-10-12 05:12:02 VERBOSE rtcpReportsCallback(): sender report 714470242 16505577883135515434 4342435 : 4474 packets 760580 bytes 2021-10-12 05:12:02 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577883510902447 8115737 : 14322 packets 5662295 bytes 2021-10-12 05:12:02 VERBOSE rtcpReportsCallback(): sender report 714470242 16505577884030225411 4352434 : 4474 packets 760580 bytes 2021-10-12 05:12:02 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577884406598550 8134506 : 14322 packets 5662295 bytes 2021-10-12 05:12:02 VERBOSE rtcpReportsCallback(): sender report 714470242 16505577884599233846 4358793 : 4474 packets 760580 bytes 2021-10-12 05:12:02 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577885010743682 8147166 : 14322 packets 5662295 bytes 2021-10-12 05:12:02 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577885629505876 8160132 : 14322 packets 5662295 bytes 2021-10-12 05:12:02 VERBOSE rtcpReportsCallback(): sender report 714470242 16505577885644871551 4370479 : 4474 packets 760580 bytes 2021-10-12 05:12:03 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577886234311574 8172806 : 14322 packets 5662295 bytes 2021-10-12 05:12:03 DEBUG socketConnectionClosed(): Close socket 12 2021-10-12 05:12:03 DEBUG socketConnectionClosed(): Close socket 11 2021-10-12 05:12:03 VERBOSE rtcpReportsCallback(): sender report 714470242 16505577886870905185 4384181 : 4474 packets 760580 bytes 2021-10-12 05:12:03 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577887152610372 8192048 : 14322 packets 5662295 bytes 2021-10-12 05:12:03 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577888026246663 8210355 : 14322 packets 5662295 bytes 2021-10-12 05:12:03 VERBOSE rtcpReportsCallback(): sender report 714470242 16505577888151712106 4398495 : 4474 packets 760580 bytes 2021-10-12 05:12:03 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577888834763519 8227297 : 14322 packets 5662295 bytes 2021-10-12 05:12:03 DEBUG turnConnectionStepState(): TurnConnection state changed from TURN_STATE_READY to TURN_STATE_CLEAN_UP 2021-10-12 05:12:03 VERBOSE rtcpReportsCallback(): sender report 714470242 16505577889391682909 4412353 : 4474 packets 760580 bytes 2021-10-12 05:12:03 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577889764702107 8246784 : 14322 packets 5662295 bytes 2021-10-12 05:12:04 VERBOSE rtcpReportsCallback(): sender report 714470242 16505577890493140586 4424663 : 4474 packets 760580 bytes 2021-10-12 05:12:04 VERBOSE rtcpReportsCallback(): sender report 1226125112 16505577890694044553 8266258 : 14322 packets 5662295 bytes 2021-10-12 05:12:04 VERBOSE rtcpReportsCallback(): sender report 714470242 16505577891139509971 4431887 : 4474 packets 760580 bytes 2021-10-12 05:12:04 WARN iceAgentShutdown(): TurnConnection shutdown did not complete within 1 seconds 2021-10-12 05:12:04 DEBUG socketConnectionClosed(): Close socket 14 2021-10-12 05:12:04 DEBUG freeStreamingSession(): Closed peer connection for streaming session with peer id: 428eca56-fc08-4418-90ed-9f17bb241066 2021-10-12 05:12:06 DEBUG freeStreamingSession(): Freed peer connection for streaming session with peer id: 428eca56-fc08-4418-90ed-9f17bb241066 2021-10-12 05:12:06 DEBUG freeStreamingSession(): Removed streaming session from memory 2021-10-12 05:12:06 DEBUG freeStreamingSession(): Returning from freeStreamingSession 2021-10-12 05:12:06 DEBUG sessionCleanupWait(): Freed session index 0 2021-10-12 05:12:06 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:12:11 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:12:11 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:12:16 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:12:16 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:12:21 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:12:21 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:12:26 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:12:26 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:12:31 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:12:31 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:12:36 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:12:36 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:12:41 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:12:41 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:12:46 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:12:46 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:12:51 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:12:51 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:12:56 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:12:56 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:13:01 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:13:01 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:13:06 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:13:06 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:13:11 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:13:11 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:13:16 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:13:16 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:13:21 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:13:21 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:13:26 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:13:26 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:13:31 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:13:31 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:13:36 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:13:36 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:13:41 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:13:41 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:13:46 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:13:46 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:13:51 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:13:51 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:13:56 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:13:56 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:14:01 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:14:01 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:14:06 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:14:06 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:14:11 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:14:11 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:14:16 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:14:16 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:14:21 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:14:21 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:14:26 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:14:26 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:14:31 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:14:31 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:14:36 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:14:36 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:14:41 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:14:41 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:14:46 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:14:46 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:14:51 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:14:51 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:14:56 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:14:56 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:15:01 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:15:01 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:15:06 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:15:06 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:15:11 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:15:11 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:15:16 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:15:16 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:15:21 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:15:21 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:15:26 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:15:26 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:15:31 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:15:31 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:15:36 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:15:36 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:15:41 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:15:41 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:15:46 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:15:46 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:15:51 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:15:51 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:15:56 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:15:56 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:16:01 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:16:01 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:16:06 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:16:06 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:16:11 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:16:11 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:16:16 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:16:16 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:16:21 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:16:21 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:16:26 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:16:26 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:16:31 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:16:31 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:16:36 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:16:36 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:16:41 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:16:41 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:16:46 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:16:46 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:16:51 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:16:51 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:16:56 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:16:56 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:17:01 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:17:01 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:17:06 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:17:06 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:17:11 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:17:11 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:17:16 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:17:16 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:17:21 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:17:21 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:17:26 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:17:26 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:17:31 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:17:31 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:17:36 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:17:36 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:17:41 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:17:41 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:17:46 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:17:46 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:17:51 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 2021-10-12 05:17:51 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State 2021-10-12 05:17:56 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0
Describe the bug On our client side logs (uses JS SDK), and on KVS-generated metrics, we see that SDP_OFFER and ICE candidates are being sent without failure however, on the master side, there is no log of any message received. Log level is VERBOSE and there is no log of "WSS callback with reason" or anything later than that. A restart of the software immediately fixes the problem.
SDK version number v1.6 (C SDK)
To Reproduce Occurs intermittently.
Expected behavior SDP_OFFER and ICE_CANDIDATEs are expected to be received at the channel master
Desktop (please complete the following information):
- OS: Ubuntu 18.04 (NVidia Jetson OS) aarch64 platform
Additional context This issue occurs intermittently and once the channel master gets into this state, it can no longer receive signaling channel messages until the master software is restarted. We don't think it is a network issue because none of the messages are received and we start receiving them immediately after software restart.
@tuncalie ,
Thank you for this. Can we get the complete logs as a file from start to finish? I see only part of the logs here.
It looks like this issue has not been active for a long time. If the issue is not resolved, please add an update to the ticket, else it will be automatically resolved in a few days.
![github-actions[bot] avatar](https://avatars.githubusercontent.com/in/15368?v=4 "Published by a pub.dev verified publisher"){kind=small}
Please find the full logs as attached. Note that there is a successful connection previously but the issue happens while the channel master keeps putting VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0 logs.
device_not_receiving_sdp_offer_full_logs.txt
@tuncalie ,
From the logs, I see that the active session count goes to zero because of this: "Detected DTLS close_notify alert". This usually happens if the viewer session is terminated for some reason, but I am going to look into other potential causes. Meanwhile, have you tried recreating the signaling client in your application instead of restarting the master application? I am not sure about the changes you have made in the sample but, can you try recreating the signaling client?
@disa6302 The issue is not about number of viewer sessions going to zero. In our application, the number of viewers go to zero and new connections are received many times. The problem is: While there are no viewers, and the master is waiting for connection requests, a viewer sends an SDP offer. KVS Cloudwatch metrics also has a recorded SDP offer. However, on the master side, there are no logs of that SDP offer. During that time, the following keeps repeating:
2021-10-12 05:16:56 VERBOSE signalingClientGetCurrentState(): Signaling Client Get Current State
2021-10-12 05:17:01 DEBUG sessionCleanupWait(): sessionCleanupWait: Active session count: 0
This issue occurs randomly. We typically get 100s of connections without a problem but when the master gets into this state, the only way to fix this is restarting the master application. Viewer sending the SDP offer again also does not work.
We are suspecting that a thread which may be created and used by SDK for listening the connections dies or gets into a deadlock. We haven't changed anything about this from the sample code and handling of the connections are done deep in the SDK that we don't know what part may be failing.
@tuncalie are you still seeing this issue since Nov 19th? We've released a new SDK version v1.7.0. We would recommend switching to that version first and see if it fixes the issue.
Meanwhile - Can you please tell if this issue reproducible by any chance? You mentioned that the issue occurs randomly. But have you seen any pattern? It is going to be challenging to simply see the code and find any potential deadlock or other bug :)
Attaching a new log file. What I suspect, based on a quick look is that the turnConnection state machine may be stuck in FAILURE state as the latest related log is showing the state as FAILURE. At a first glance into the code (I may be missing something here), it seems like when there is an error, state transitions as TURN_STATE_FAILED -> TURN_STATE_CLEAN_UP -> TURN_STATE_FAILED and then stopScheduling is set to TRUE . Next time turnConnectionStart function is called, as the function first checks if the state is TURN_STATE_NEW and that check will fail (the latest state is TURN_STATE_FAILED) a new TURN connection may not start. These new logs are coming from sdk v1.7.1
2022-02-24 05:38:42 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x00000002 2022-02-24 05:38:42 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x5a000005 2022-02-24 05:38:42 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x00000002 2022-02-24 05:38:44 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:38:44 ERROR turnConnectionSendData(): operation returned status code: 0x5a000027 2022-02-24 05:38:44 ERROR iceUtilsSendData(): operation returned status code: 0x5a000027 2022-02-24 05:38:44 ERROR iceUtilsSendStunPacket(): operation returned status code: 0x5a000027 2022-02-24 05:38:44 WARN iceAgentSendStunPacket(): iceUtilsSendStunPacket failed with 0x5a000027 2022-02-24 05:38:44 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:38:44 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:38:44 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:38:44 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:38:45 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:38:45 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:38:45 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:38:45 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:38:45 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:38:45 WARN handleStunPacket(): Cannot find candidate pair with local candidate 0000:0000:0000:0000:0000:0000:0000:0000 and remote candidate 54.70.112.242. Dropping STUN binding success response 2022-02-24 05:38:45 WARN handleStunPacket(): Cannot find candidate pair with local candidate 0000:0000:0000:0000:0000:0000:0000:0000 and remote candidate 54.70.112.242. Dropping STUN binding success response 2022-02-24 05:38:45 WARN handleStunPacket(): Cannot find candidate pair with local candidate 0000:0000:0000:0000:0000:0000:0000:0000 and remote candidate 54.70.112.242. Dropping STUN binding success response 2022-02-24 05:38:45 WARN handleStunPacket(): Cannot find candidate pair with local candidate 0000:0000:0000:0000:0000:0000:0000:0000 and remote candidate 54.70.112.242. Dropping STUN binding success response 2022-02-24 05:38:45 WARN handleStunPacket(): Cannot find candidate pair with local candidate 0000:0000:0000:0000:0000:0000:0000:0000 and remote candidate 54.70.112.242. Dropping STUN binding success response 2022-02-24 05:38:45 WARN handleStunPacket(): Cannot find candidate pair with local candidate 0000:0000:0000:0000:0000:0000:0000:0000 and remote candidate 54.70.112.242. Dropping STUN binding success response 2022-02-24 05:38:45 WARN handleStunPacket(): Cannot find candidate pair with local candidate 0000:0000:0000:0000:0000:0000:0000:0000 and remote candidate 54.70.112.242. Dropping STUN binding success response 2022-02-24 05:38:45 WARN handleStunPacket(): Cannot find candidate pair with local candidate 0000:0000:0000:0000:0000:0000:0000:0000 and remote candidate 54.70.112.242. Dropping STUN binding success response 2022-02-24 05:38:57 WARN onRtcpPacket(): unhandled packet type 203 2022-02-24 05:39:13 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x00000002 2022-02-24 05:39:13 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x5a000005 2022-02-24 05:39:13 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:39:13 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:39:13 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:39:13 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:39:13 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x00000002 2022-02-24 05:39:14 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:39:14 ERROR turnConnectionSendData(): operation returned status code: 0x5a000027 2022-02-24 05:39:14 ERROR iceUtilsSendData(): operation returned status code: 0x5a000027 2022-02-24 05:39:14 ERROR iceUtilsSendStunPacket(): operation returned status code: 0x5a000027 2022-02-24 05:39:14 WARN iceAgentSendStunPacket(): iceUtilsSendStunPacket failed with 0x5a000027 2022-02-24 05:39:14 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:39:14 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:39:14 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:39:14 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:39:22 WARN onRtcpPacket(): unhandled packet type 203 2022-02-24 05:39:32 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:39:32 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:39:32 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x00000002 2022-02-24 05:39:32 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x00000002 2022-02-24 05:39:32 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x5a000005 2022-02-24 05:39:32 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:39:32 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:39:32 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:39:32 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:39:33 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:39:33 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:39:33 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:39:33 ERROR turnConnectionSendData(): operation returned status code: 0x5a000027 2022-02-24 05:39:33 ERROR iceUtilsSendData(): operation returned status code: 0x5a000027 2022-02-24 05:39:33 ERROR iceUtilsSendStunPacket(): operation returned status code: 0x5a000027 2022-02-24 05:39:33 WARN iceAgentSendStunPacket(): iceUtilsSendStunPacket failed with 0x5a000027 2022-02-24 05:39:33 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:39:34 WARN handleStunPacket(): Cannot find candidate pair with local candidate 0000:0000:0000:0000:0000:0000:0000:0000 and remote candidate 52.36.23.27. Dropping STUN binding success response 2022-02-24 05:39:34 WARN handleStunPacket(): Cannot find candidate pair with local candidate 0000:0000:0000:0000:0000:0000:0000:0000 and remote candidate 54.188.50.186. Dropping STUN binding success response 2022-02-24 05:39:34 WARN handleStunPacket(): Cannot find candidate pair with local candidate 0000:0000:0000:0000:0000:0000:0000:0000 and remote candidate 54.188.50.186. Dropping STUN binding success response 2022-02-24 05:39:34 WARN handleStunPacket(): Cannot find candidate pair with local candidate 0000:0000:0000:0000:0000:0000:0000:0000 and remote candidate 52.36.23.27. Dropping STUN binding success response 2022-02-24 05:39:34 WARN handleStunPacket(): Cannot find candidate pair with local candidate 0000:0000:0000:0000:0000:0000:0000:0000 and remote candidate 52.36.23.27. Dropping STUN binding success response 2022-02-24 05:39:39 WARN onRtcpPacket(): unhandled packet type 203 2022-02-24 05:39:48 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x00000002 2022-02-24 05:39:48 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:39:48 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x5a000005 2022-02-24 05:39:48 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x00000002 2022-02-24 05:39:48 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:39:48 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:39:48 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:39:49 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:39:49 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:39:49 ERROR turnConnectionSendData(): operation returned status code: 0x5a000027 2022-02-24 05:39:49 ERROR iceUtilsSendData(): operation returned status code: 0x5a000027 2022-02-24 05:39:49 ERROR iceUtilsSendStunPacket(): operation returned status code: 0x5a000027 2022-02-24 05:39:49 WARN iceAgentSendStunPacket(): iceUtilsSendStunPacket failed with 0x5a000027 2022-02-24 05:39:49 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:39:49 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:39:57 WARN onRtcpPacket(): unhandled packet type 203 2022-02-24 05:40:03 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x00000002 2022-02-24 05:40:03 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:40:03 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x00000002 2022-02-24 05:40:03 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x5a000005 2022-02-24 05:40:03 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:40:03 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:40:04 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:40:04 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:40:04 ERROR turnConnectionSendData(): operation returned status code: 0x5a000027 2022-02-24 05:40:04 ERROR iceUtilsSendData(): operation returned status code: 0x5a000027 2022-02-24 05:40:04 ERROR iceUtilsSendStunPacket(): operation returned status code: 0x5a000027 2022-02-24 05:40:04 WARN iceAgentSendStunPacket(): iceUtilsSendStunPacket failed with 0x5a000027 2022-02-24 05:40:04 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:40:04 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:40:05 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:40:05 WARN handleStunPacket(): Unable to fetch request Timestamp from the hash table. No update to RTT for the pair (error code: 0x40100001) 2022-02-24 05:40:05 WARN handleStunPacket(): Dropping response packet because transaction id does not match 2022-02-24 05:40:05 ERROR handleStunPacket(): operation returned status code: 0x40100001 2022-02-24 05:40:05 ERROR incomingDataHandler(): operation returned status code: 0x40100001 2022-02-24 05:40:05 WARN handleStunPacket(): Unable to fetch request Timestamp from the hash table. No update to RTT for the pair (error code: 0x40100001) 2022-02-24 05:40:05 WARN handleStunPacket(): Dropping response packet because transaction id does not match 2022-02-24 05:40:05 ERROR handleStunPacket(): operation returned status code: 0x40100001 2022-02-24 05:40:05 ERROR incomingDataHandler(): operation returned status code: 0x40100001 2022-02-24 05:40:05 WARN handleStunPacket(): Unable to fetch request Timestamp from the hash table. No update to RTT for the pair (error code: 0x40100001) 2022-02-24 05:40:05 WARN handleStunPacket(): Dropping response packet because transaction id does not match 2022-02-24 05:40:05 ERROR handleStunPacket(): operation returned status code: 0x40100001 2022-02-24 05:40:05 ERROR incomingDataHandler(): operation returned status code: 0x40100001 2022-02-24 05:40:05 WARN handleStunPacket(): Unable to fetch request Timestamp from the hash table. No update to RTT for the pair (error code: 0x40100001) 2022-02-24 05:40:05 WARN handleStunPacket(): Dropping response packet because transaction id does not match 2022-02-24 05:40:05 ERROR handleStunPacket(): operation returned status code: 0x40100001 2022-02-24 05:40:05 ERROR incomingDataHandler(): operation returned status code: 0x40100001 2022-02-24 05:40:05 WARN handleStunPacket(): Cannot find candidate pair with local candidate 0000:0000:0000:0000:0000:0000:0000:0000 and remote candidate 54.188.50.186. Dropping STUN binding success response 2022-02-24 05:40:05 WARN handleStunPacket(): Cannot find candidate pair with local candidate 0000:0000:0000:0000:0000:0000:0000:0000 and remote candidate 52.36.23.27. Dropping STUN binding success response 2022-02-24 05:40:05 WARN handleStunPacket(): Unable to fetch request Timestamp from the hash table. No update to RTT for the pair (error code: 0x40100001) 2022-02-24 05:40:05 WARN handleStunPacket(): Dropping response packet because transaction id does not match 2022-02-24 05:40:05 ERROR handleStunPacket(): operation returned status code: 0x40100001 2022-02-24 05:40:05 ERROR incomingDataHandler(): operation returned status code: 0x40100001 2022-02-24 05:40:05 WARN handleStunPacket(): Cannot find candidate pair with local candidate 0000:0000:0000:0000:0000:0000:0000:0000 and remote candidate 54.188.50.186. Dropping STUN binding success response 2022-02-24 05:40:05 WARN handleStunPacket(): Cannot find candidate pair with local candidate 0000:0000:0000:0000:0000:0000:0000:0000 and remote candidate 52.36.23.27. Dropping STUN binding success response 2022-02-24 05:40:05 WARN handleStunPacket(): Cannot find candidate pair with local candidate 0000:0000:0000:0000:0000:0000:0000:0000 and remote candidate 52.36.23.27. Dropping STUN binding success response 2022-02-24 05:40:05 WARN handleStunPacket(): Cannot find candidate pair with local candidate 0000:0000:0000:0000:0000:0000:0000:0000 and remote candidate 54.188.50.186. Dropping STUN binding success response 2022-02-24 05:40:05 WARN handleStunPacket(): Cannot find candidate pair with local candidate 0000:0000:0000:0000:0000:0000:0000:0000 and remote candidate 52.36.23.27. Dropping STUN binding success response 2022-02-24 05:40:05 WARN handleStunPacket(): Unable to fetch request Timestamp from the hash table. No update to RTT for the pair (error code: 0x40100001) 2022-02-24 05:40:05 WARN handleStunPacket(): Dropping response packet because transaction id does not match 2022-02-24 05:40:05 ERROR handleStunPacket(): operation returned status code: 0x40100001 2022-02-24 05:40:05 ERROR incomingDataHandler(): operation returned status code: 0x40100001 2022-02-24 05:40:06 WARN handleStunPacket(): Unable to fetch request Timestamp from the hash table. No update to RTT for the pair (error code: 0x40100001) 2022-02-24 05:40:06 WARN handleStunPacket(): Dropping response packet because transaction id does not match 2022-02-24 05:40:06 ERROR handleStunPacket(): operation returned status code: 0x40100001 2022-02-24 05:40:06 ERROR incomingDataHandler(): operation returned status code: 0x40100001 2022-02-24 05:40:11 WARN onRtcpPacket(): unhandled packet type 203 2022-02-24 05:41:06 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x00000002 2022-02-24 05:41:06 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:41:06 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x00000002 2022-02-24 05:41:06 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x5a000005 2022-02-24 05:41:06 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:41:06 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:41:06 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:41:07 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:41:07 ERROR turnConnectionSendData(): operation returned status code: 0x5a000027 2022-02-24 05:41:07 ERROR iceUtilsSendData(): operation returned status code: 0x5a000027 2022-02-24 05:41:07 ERROR iceUtilsSendStunPacket(): operation returned status code: 0x5a000027 2022-02-24 05:41:07 WARN iceAgentSendStunPacket(): iceUtilsSendStunPacket failed with 0x5a000027 2022-02-24 05:41:07 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:41:07 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:41:07 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:41:07 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:41:12 WARN onRtcpPacket(): unhandled packet type 203 2022-02-24 05:41:20 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x00000002 2022-02-24 05:41:20 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x5a000005 2022-02-24 05:41:20 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:41:20 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:41:20 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:41:20 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:41:20 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x00000002 2022-02-24 05:41:21 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:41:21 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:41:21 ERROR turnConnectionSendData(): operation returned status code: 0x5a000027 2022-02-24 05:41:21 ERROR iceUtilsSendData(): operation returned status code: 0x5a000027 2022-02-24 05:41:21 ERROR iceUtilsSendStunPacket(): operation returned status code: 0x5a000027 2022-02-24 05:41:21 WARN iceAgentSendStunPacket(): iceUtilsSendStunPacket failed with 0x5a000027 2022-02-24 05:41:21 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:41:21 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:41:21 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:41:21 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:41:27 WARN onRtcpPacket(): unhandled packet type 203 2022-02-24 05:41:52 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x00000002 2022-02-24 05:41:52 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x00000002 2022-02-24 05:41:52 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x5a000005 2022-02-24 05:41:52 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:41:52 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:41:52 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:41:53 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:41:53 ERROR turnConnectionSendData(): operation returned status code: 0x5a000027 2022-02-24 05:41:53 ERROR iceUtilsSendData(): operation returned status code: 0x5a000027 2022-02-24 05:41:53 ERROR iceUtilsSendStunPacket(): operation returned status code: 0x5a000027 2022-02-24 05:41:53 WARN iceAgentSendStunPacket(): iceUtilsSendStunPacket failed with 0x5a000027 2022-02-24 05:41:53 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:41:53 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:41:53 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:41:53 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:41:58 WARN onRtcpPacket(): unhandled packet type 203
2022-02-24 05:49:40 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x00000002 2022-02-24 05:49:40 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x00000002 2022-02-24 05:49:40 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:49:40 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:49:40 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:49:40 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress 2022-02-24 05:49:40 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x5a000005 2022-02-24 05:49:41 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:49:41 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:49:41 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:49:41 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:49:41 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:49:41 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. attribute len 16, Error detail: Forbidden IP. 2022-02-24 05:49:41 WARN handleStunPacket(): Unable to fetch request Timestamp from the hash table. No update to RTT for the pair (error code: 0x40100001) 2022-02-24 05:49:41 WARN handleStunPacket(): Dropping response packet because transaction id does not match 2022-02-24 05:49:41 ERROR handleStunPacket(): operation returned status code: 0x40100001 2022-02-24 05:49:41 ERROR incomingDataHandler(): operation returned status code: 0x40100001 2022-02-24 05:49:41 WARN handleStunPacket(): Unable to fetch request Timestamp from the hash table. No update to RTT for the pair (error code: 0x40100001) 2022-02-24 05:49:41 WARN handleStunPacket(): Dropping response packet because transaction id does not match 2022-02-24 05:49:41 ERROR handleStunPacket(): operation returned status code: 0x40100001 2022-02-24 05:49:41 ERROR incomingDataHandler(): operation returned status code: 0x40100001 2022-02-24 05:54:40 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x5a000005 2022-02-24 05:59:40 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x5a000005 2022-02-24 06:04:40 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x5a000005 2022-02-24 06:09:41 ERROR iceAgentAddRemoteCandidate(): operation returned status code: 0x5a000005 2022-02-24 06:10:03 WARN onRtcpPacket(): unhandled packet type 203
I looked at the above correspondence and looks like there are some theories regarding a potential bug in turn connection state machine. I can deep dive into the code but I'm skeptical about catching any issue without being able to reproduce it. @tuncalie @donwyze can you help me with the details of repro steps? Also can you please answer the questions that will help me reproduce the issue - (1) Are the viewers and master on same host? If not, have you already tried reproducing by running both on the host? (2) You said that the issue occurs intermittently. How intermittent is it? As in how much time should we wait in an anticipation of the issue to get triggered? (3) Did you see any pattern in the number of viewers that were successfully connected and then started failing? Is there a rough range (say 20 viewers) always connect successfully and then things fail? (4) What was the max number of concurrent viewers that were connected before the next viewer could not connect? Any recurring data regarding this?
(1) Viewers and master are on different devices. There are different viewers in different locations and different masters in different locations. Typically, only one viewer connects to the stream simultaneiously. Running both on the same host is not an option for us. (2 and 3) It is random, sometimes, it happens the same day after starting, after around 10-20 different successful sessions, sometimes it is after more than 100 successful sessions. (4) Typically, there is only one viewer connected at a time. In some edge cases there can be 2 viewers connected at the same time, but over time, we haven't seen a correlation between multiple viewers being connected.
In general, what happens is, one viewer connects, streams for around 5 minutes in average, they disconnect, after a while (sometimes very soon after the disconnection), another viewer (could be a different person) connects to the stream. After having some number of successful sessions like this, at some point new connections do not happen. There are not even any logs on the master side about someone trying to connect. KVS cloud side has metrics that a viewer is trying to connect. When this happens, different viewers, at different locations can also not connect to the stream.
This is a very old issue. We encourage you to check if this is still an issue in the latest release and if you find that this is still a problem, please feel free to open a new one.
1.6 had a known connectivity issue that has since been resolved. If this is still occurring on the newest version please open a new ticket with the current version logs.
