diff --git a/README.md b/README.md index b2aff28bb5..95ddd46458 100644 --- a/README.md +++ b/README.md @@ -429,6 +429,24 @@ The threadpool is enabled by default, and starts with 5 threads that it can incr To disable threadpool, run `cmake .. -DENABLE_KVS_THREADPOOL=OFF` +### Setting ICE related timeouts + +There are some default timeout values set for different steps in ICE in the [KvsRtcConfiguration](https://awslabs.github.io/amazon-kinesis-video-streams-webrtc-sdk-c/structKvsRtcConfiguration.html). These are configurable in the application. While the defaults are generous, there could be applications that might need more flexibility to improve chances of connection establishment because of poor network. + +You can find the default setting in the logs: +``` +2024-01-08 19:43:44.433 INFO iceAgentValidateKvsRtcConfig(): + iceLocalCandidateGatheringTimeout: 10000 ms + iceConnectionCheckTimeout: 12000 ms + iceCandidateNominationTimeout: 12000 ms + iceConnectionCheckPollingInterval: 50 ms +``` +Let us look into when each of these could be changed: +1. `iceCandidateNominationTimeout`: Say the connection with host/srflx could not be established and TURN seems to be the only resort. Let us assume it takes about 15 seconds to gather the first local relay candidate, the application could set the timeout to a value more than 15 seconds to ensure candidate pairs with the local relay candidate are tried for success. If the value is set to less than 15 seconds in this case, the SDK would lose out on trying a potential candidate pair leading to connection establishment failure +2. `iceLocalCandidateGatheringTimeout`: Say the host candidates would not work and srflx/relay candidates need to be tried. Due to poor network, it is anticipated the candidates are gathered slowly and the application does not want to spend more than 20 seconds on this step. The goal is to try all possible candidate pairs. Increasing the timeout helps in giving some more time to gather more potential candidates to try for connection. Also note, this parameter increase would not make a difference in the situation unless `iceCandidateNominationTimeout` > `iceLocalCandidateGatheringTimeout` since nomination step should also be given time to work with the new candidates +3. `iceConnectionCheckTimeout`: It is useful to increase this timeout in unstable/slow network where the packet exchange takes time and hence the binding request/response. Essentially, increasing it will allow atleast one candidate pair to be tried for nomination by the other peer. +4. `iceConnectionCheckPollingInterval`: This value is set to a default of 50 ms per [spec](https://datatracker.ietf.org/doc/html/rfc8445#section-14.2). Changing this would change the frequency of connectivity checks and essentially, the ICE state machine transitions. Decreasing the value could help in faster connection establishment in a reliable high performant network setting with good system resources. Increasing the value could help in reducing the network load, however, the connection establishment could slow down. Unless there is a strong reasoning, it is **NOT** recommended to deviate from spec/default. + ## Documentation All Public APIs are documented in our [Include.h](https://github.com/awslabs/amazon-kinesis-video-streams-webrtc-sdk-c/blob/master/src/include/com/amazonaws/kinesis/video/webrtcclient/Include.h), we also generate a [Doxygen](https://awslabs.github.io/amazon-kinesis-video-streams-webrtc-sdk-c/) each commit for easier navigation. diff --git a/samples/Samples.h b/samples/Samples.h index 83644c0689..bc182ad769 100644 --- a/samples/Samples.h +++ b/samples/Samples.h @@ -34,7 +34,7 @@ extern "C" { #define CA_CERT_PEM_FILE_EXTENSION ".pem" -#define FILE_LOGGING_BUFFER_SIZE (10 * 1024) +#define FILE_LOGGING_BUFFER_SIZE (10000 * 1024) #define MAX_NUMBER_OF_LOG_FILES 5 #define SAMPLE_HASH_TABLE_BUCKET_COUNT 50 diff --git a/src/include/com/amazonaws/kinesis/video/webrtcclient/Include.h b/src/include/com/amazonaws/kinesis/video/webrtcclient/Include.h index a3c990ea7a..3fcadf5693 100644 --- a/src/include/com/amazonaws/kinesis/video/webrtcclient/Include.h +++ b/src/include/com/amazonaws/kinesis/video/webrtcclient/Include.h @@ -255,6 +255,8 @@ extern "C" { #define STATUS_ICE_CANDIDATE_STRING_MISSING_TYPE STATUS_ICE_BASE + 0x00000029 #define STATUS_TURN_CONNECTION_ALLOCATION_FAILED STATUS_ICE_BASE + 0x0000002a #define STATUS_TURN_INVALID_STATE STATUS_ICE_BASE + 0x0000002b +#define STATUS_TURN_CONNECTION_GET_CREDENTIALS_FAILED STATUS_ICE_BASE + 0x0000002c + /*!@} */ ///////////////////////////////////////////////////// @@ -1179,7 +1181,7 @@ typedef struct { //!< USE_CANDIDATE attribute. If client is ice controlled, this is the timeout for receiving binding request //!< that has USE_CANDIDATE attribute after connection check is done. Use default value if 0. - UINT32 iceConnectionCheckPollingInterval; //!< Ta in https://tools.ietf.org/html/rfc8445 + UINT32 iceConnectionCheckPollingInterval; //!< Ta in https://datatracker.ietf.org/doc/html/rfc8445#section-14.2 //!< rate at which binding request packets are sent during connection check. Use default interval if 0. INT32 generatedCertificateBits; //!< GeneratedCertificateBits controls the amount of bits the locally generated self-signed certificate uses diff --git a/src/source/Ice/IceAgent.c b/src/source/Ice/IceAgent.c index f917667233..b806f13453 100644 --- a/src/source/Ice/IceAgent.c +++ b/src/source/Ice/IceAgent.c @@ -360,7 +360,7 @@ STATUS iceAgentValidateKvsRtcConfig(PKvsRtcConfiguration pKvsRtcConfiguration) pKvsRtcConfiguration->iceConnectionCheckPollingInterval = KVS_ICE_CONNECTION_CHECK_POLLING_INTERVAL; } - DLOGD("\n\ticeLocalCandidateGatheringTimeout: %u ms" + DLOGI("\n\ticeLocalCandidateGatheringTimeout: %u ms" "\n\ticeConnectionCheckTimeout: %u ms" "\n\ticeCandidateNominationTimeout: %u ms" "\n\ticeConnectionCheckPollingInterval: %u ms", @@ -517,7 +517,8 @@ STATUS iceAgentAddRemoteCandidate(PIceAgent pIceAgent, PCHAR pIceCandidateString pLocalIceCandidate = (PIceCandidate) pCurNode->data; pCurNode = pCurNode->pNext; - if (pLocalIceCandidate->iceCandidateType == ICE_CANDIDATE_TYPE_RELAYED) { + // TODO: Remove IPv4 check once IPv6 TURN relay candidates are chosen. Disabling this to reduce the number of TURN permissions we create + if (pLocalIceCandidate->iceCandidateType == ICE_CANDIDATE_TYPE_RELAYED && IS_IPV4_ADDR(&pLocalIceCandidate->ipAddress)) { CHK_STATUS(turnConnectionAddPeer(pLocalIceCandidate->pTurnConnection, &pIceCandidate->ipAddress)); } } @@ -2400,7 +2401,6 @@ STATUS incomingRelayedDataHandler(UINT64 customData, PSocketConnection pSocketCo CHK(pRelayedCandidate != NULL && pSocketConnection != NULL, STATUS_NULL_ARG); - DLOGV("Candidate id: %s", pRelayedCandidate->id); CHK_STATUS(turnConnectionIncomingDataHandler(pRelayedCandidate->pTurnConnection, pBuffer, bufferLen, pSrc, pDest, turnChannelData, &turnChannelDataCount)); for (i = 0; i < turnChannelDataCount; ++i) { diff --git a/src/source/Ice/IceAgent.h b/src/source/Ice/IceAgent.h index f6e1a59852..b692975c1b 100644 --- a/src/source/Ice/IceAgent.h +++ b/src/source/Ice/IceAgent.h @@ -14,12 +14,16 @@ extern "C" { #define KVS_ICE_MAX_REMOTE_CANDIDATE_COUNT 100 #define KVS_ICE_MAX_LOCAL_CANDIDATE_COUNT 100 #define KVS_ICE_GATHER_REFLEXIVE_AND_RELAYED_CANDIDATE_TIMEOUT (10 * HUNDREDS_OF_NANOS_IN_A_SECOND) -#define KVS_ICE_CONNECTIVITY_CHECK_TIMEOUT (10 * HUNDREDS_OF_NANOS_IN_A_SECOND) -#define KVS_ICE_CANDIDATE_NOMINATION_TIMEOUT (10 * HUNDREDS_OF_NANOS_IN_A_SECOND) -#define KVS_ICE_SEND_KEEP_ALIVE_INTERVAL (15 * HUNDREDS_OF_NANOS_IN_A_SECOND) -#define KVS_ICE_TURN_CONNECTION_SHUTDOWN_TIMEOUT (1 * HUNDREDS_OF_NANOS_IN_A_SECOND) -#define KVS_ICE_DEFAULT_TIMER_START_DELAY (3 * HUNDREDS_OF_NANOS_IN_A_MILLISECOND) -#define KVS_ICE_SHORT_CHECK_DELAY (50 * HUNDREDS_OF_NANOS_IN_A_MILLISECOND) +#define KVS_ICE_CONNECTIVITY_CHECK_TIMEOUT \ + (12 * HUNDREDS_OF_NANOS_IN_A_SECOND) // This should be greater than KVS_ICE_GATHER_REFLEXIVE_AND_RELAYED_CANDIDATE_TIMEOUT to ensure there is + // buffer wait time for connectivity checks with the pairs formed with near timeout created pairs +#define KVS_ICE_CANDIDATE_NOMINATION_TIMEOUT \ + (12 * HUNDREDS_OF_NANOS_IN_A_SECOND) // This should be greater than KVS_ICE_GATHER_REFLEXIVE_AND_RELAYED_CANDIDATE_TIMEOUT to ensure there is some + // buffer for nomination with near timeout generated candidates +#define KVS_ICE_SEND_KEEP_ALIVE_INTERVAL (15 * HUNDREDS_OF_NANOS_IN_A_SECOND) +#define KVS_ICE_TURN_CONNECTION_SHUTDOWN_TIMEOUT (1 * HUNDREDS_OF_NANOS_IN_A_SECOND) +#define KVS_ICE_DEFAULT_TIMER_START_DELAY (3 * HUNDREDS_OF_NANOS_IN_A_MILLISECOND) +#define KVS_ICE_SHORT_CHECK_DELAY (50 * HUNDREDS_OF_NANOS_IN_A_MILLISECOND) // Ta in https://tools.ietf.org/html/rfc8445 #define KVS_ICE_CONNECTION_CHECK_POLLING_INTERVAL (50 * HUNDREDS_OF_NANOS_IN_A_MILLISECOND) diff --git a/src/source/Ice/IceAgentStateMachine.c b/src/source/Ice/IceAgentStateMachine.c index c569104506..12f808538f 100644 --- a/src/source/Ice/IceAgentStateMachine.c +++ b/src/source/Ice/IceAgentStateMachine.c @@ -605,7 +605,7 @@ STATUS executeReadyIceAgentState(UINT64 customData, UINT64 time) if (pIceAgent->iceAgentStartTime != 0) { PROFILE_WITH_START_TIME_OBJ(pIceAgent->iceAgentStartTime, pIceAgent->iceAgentProfileDiagnostics.iceAgentSetUpTime, - "Time taken to get ICE Agent ready for media exchange"); + "ICE Agent ready for media exchange from check connection start"); pIceAgent->iceAgentStartTime = 0; } diff --git a/src/source/Ice/TurnConnection.c b/src/source/Ice/TurnConnection.c index 53459a9790..752ee49f2c 100644 --- a/src/source/Ice/TurnConnection.c +++ b/src/source/Ice/TurnConnection.c @@ -26,7 +26,6 @@ STATUS createTurnConnection(PIceServer pTurnServer, TIMER_QUEUE_HANDLE timerQueu pTurnConnection = (PTurnConnection) MEMCALLOC( 1, SIZEOF(TurnConnection) + DEFAULT_TURN_MESSAGE_RECV_CHANNEL_DATA_BUFFER_LEN * 2 + DEFAULT_TURN_MESSAGE_SEND_CHANNEL_DATA_BUFFER_LEN); CHK(pTurnConnection != NULL, STATUS_NOT_ENOUGH_MEMORY); - pTurnConnection->lock = MUTEX_CREATE(TRUE); pTurnConnection->sendLock = MUTEX_CREATE(FALSE); pTurnConnection->freeAllocationCvar = CVAR_CREATE(); @@ -215,6 +214,7 @@ STATUS turnConnectionHandleStun(PTurnConnection pTurnConnection, PBYTE pBuffer, PStunAttributeAddress pStunAttributeAddress = NULL; PStunAttributeLifetime pStunAttributeLifetime = NULL; PStunPacket pStunPacket = NULL; + CHAR profileDebugStr[MAX_TURN_PROFILE_LOG_DESC_LEN]; CHAR ipAddrStr[KVS_IP_ADDRESS_STRING_BUFFER_LEN]; BOOL locked = FALSE; ATOMIC_BOOL hasAllocation = FALSE; @@ -245,12 +245,18 @@ STATUS turnConnectionHandleStun(PTurnConnection pTurnConnection, PBYTE pBuffer, // convert lifetime to 100ns and store it pTurnConnection->allocationExpirationTime = (pStunAttributeLifetime->lifetime * HUNDREDS_OF_NANOS_IN_A_SECOND) + currentTime; - DLOGD("TURN Allocation succeeded. Life time: %u seconds. Allocation expiration epoch %" PRIu64, pStunAttributeLifetime->lifetime, - pTurnConnection->allocationExpirationTime / DEFAULT_TIME_UNIT_IN_NANOS); pStunAttributeAddress = (PStunAttributeAddress) pStunAttr; pTurnConnection->relayAddress = pStunAttributeAddress->address; ATOMIC_STORE_BOOL(&pTurnConnection->hasAllocation, TRUE); + getIpAddrStr(&pTurnConnection->relayAddress, ipAddrStr, ARRAY_SIZE(ipAddrStr)); + SNPRINTF(profileDebugStr, MAX_TURN_PROFILE_LOG_DESC_LEN, "%p - %s:%d - %s", (PVOID) pTurnConnection, ipAddrStr, + pTurnConnection->relayAddress.port, "TURN allocation"); + DLOGD("[%p - %s:%d] TURN Allocation succeeded. Life time: %u seconds. Allocation expiration epoch %" PRIu64, pTurnConnection, ipAddrStr, + pTurnConnection->relayAddress.port, pStunAttributeLifetime->lifetime, + pTurnConnection->allocationExpirationTime / DEFAULT_TIME_UNIT_IN_NANOS); + PROFILE_WITH_START_TIME_OBJ(pTurnConnection->turnProfileDiagnostics.createAllocationStartTime, + pTurnConnection->turnProfileDiagnostics.createAllocationTime, profileDebugStr); if (!pTurnConnection->relayAddressReported && pTurnConnection->turnConnectionCallbacks.relayAddressAvailableFn != NULL) { pTurnConnection->relayAddressReported = TRUE; @@ -291,7 +297,13 @@ STATUS turnConnectionHandleStun(PTurnConnection pTurnConnection, PBYTE pBuffer, if (pTurnPeer->connectionState == TURN_PEER_CONN_STATE_CREATE_PERMISSION) { pTurnPeer->connectionState = TURN_PEER_CONN_STATE_BIND_CHANNEL; CHK_STATUS(getIpAddrStr(&pTurnPeer->address, ipAddrStr, ARRAY_SIZE(ipAddrStr))); - DLOGD("create permission succeeded for peer %s", ipAddrStr); + DLOGD("[%p] Create permission succeeded for peer %s:%d", pTurnConnection, ipAddrStr, pTurnPeer->address.port); + if (pTurnPeer->firstTimeCreatePermResponse) { + pTurnPeer->firstTimeCreatePermResponse = FALSE; + SNPRINTF(profileDebugStr, MAX_TURN_PROFILE_LOG_DESC_LEN, "%p - %s:%d - %s", (PVOID) pTurnConnection, ipAddrStr, + pTurnPeer->address.port, "TURN create permission"); + PROFILE_WITH_START_TIME_OBJ(pTurnPeer->createPermissionStartTime, pTurnPeer->createPermissionTime, profileDebugStr); + } } pTurnPeer->permissionExpirationTime = TURN_PERMISSION_LIFETIME + currentTime; @@ -313,8 +325,14 @@ STATUS turnConnectionHandleStun(PTurnConnection pTurnConnection, PBYTE pBuffer, pTurnPeer->connectionState = TURN_PEER_CONN_STATE_READY; CHK_STATUS(getIpAddrStr(&pTurnPeer->address, ipAddrStr, ARRAY_SIZE(ipAddrStr))); - DLOGD("Channel bind succeeded with peer %s, port: %u, channel number %u", ipAddrStr, (UINT16) getInt16(pTurnPeer->address.port), - pTurnPeer->channelNumber); + DLOGD("[%p] Channel bind succeeded with peer %s, port: %d, channel number %u", pTurnConnection, ipAddrStr, + pTurnPeer->address.port, pTurnPeer->channelNumber); + if (pTurnPeer->firstTimeBindChannelResponse) { + pTurnPeer->firstTimeBindChannelResponse = FALSE; + SNPRINTF(profileDebugStr, MAX_TURN_PROFILE_LOG_DESC_LEN, "%p - %s:%d:%u - %s", (PVOID) pTurnConnection, ipAddrStr, + pTurnPeer->address.port, pTurnPeer->channelNumber, "TURN bind channel"); + PROFILE_WITH_START_TIME_OBJ(pTurnPeer->bindChannelStartTime, pTurnPeer->bindChannelTime, profileDebugStr); + } break; } @@ -360,6 +378,7 @@ STATUS turnConnectionHandleStunError(PTurnConnection pTurnConnection, PBYTE pBuf PStunPacket pStunPacket = NULL; BOOL locked = FALSE, iterate = TRUE; PTurnPeer pTurnPeer = NULL; + CHAR profileDebugStr[MAX_TURN_PROFILE_LOG_DESC_LEN]; UINT32 i; CHK(pTurnConnection != NULL, STATUS_NULL_ARG); @@ -412,7 +431,9 @@ STATUS turnConnectionHandleStunError(PTurnConnection pTurnConnection, PBYTE pBuf pTurnConnection->turnRealm[pStunAttributeRealm->attribute.length] = '\0'; pTurnConnection->credentialObtained = TRUE; - + SNPRINTF(profileDebugStr, MAX_TURN_PROFILE_LOG_DESC_LEN, "%p - %s", (PVOID) pTurnConnection, "TURN Get Credentials"); + PROFILE_WITH_START_TIME_OBJ(pTurnConnection->turnProfileDiagnostics.getCredentialsStartTime, + pTurnConnection->turnProfileDiagnostics.getCredentialsTime, profileDebugStr); CHK_STATUS(turnConnectionUpdateNonce(pTurnConnection)); break; @@ -561,8 +582,8 @@ STATUS turnConnectionHandleChannelDataTcpMode(PTurnConnection pTurnConnection, P /* process only one channel data and return. Because channel data can be intermixed with STUN packet. * need to check remainingBufLen too because channel data could be incomplete. */ while (remainingBufLen != 0 && channelDataCount == 0) { - DLOGV("currRecvDataLen: %d", pTurnConnection->currRecvDataLen); if (pTurnConnection->currRecvDataLen != 0) { + DLOGV("currRecvDataLen: %d", pTurnConnection->currRecvDataLen); if (pTurnConnection->currRecvDataLen >= TURN_DATA_CHANNEL_SEND_OVERHEAD) { /* pTurnConnection->recvDataBuffer always has channel data start */ paddedChannelDataLen = ROUND_UP((UINT32) getInt16(*(PINT16) (pTurnConnection->recvDataBuffer + SIZEOF(channelNumber))), 4); @@ -673,6 +694,10 @@ STATUS turnConnectionAddPeer(PTurnConnection pTurnConnection, PKvsIpAddress pPee pTurnPeer->channelNumber = (UINT16) pTurnConnection->turnPeerCount + TURN_CHANNEL_BIND_CHANNEL_NUMBER_BASE; pTurnPeer->permissionExpirationTime = INVALID_TIMESTAMP_VALUE; pTurnPeer->ready = FALSE; + pTurnPeer->firstTimeCreatePermReq = TRUE; + pTurnPeer->firstTimeBindChannelReq = TRUE; + pTurnPeer->firstTimeCreatePermResponse = TRUE; + pTurnPeer->firstTimeBindChannelResponse = TRUE; CHK_STATUS(xorIpAddress(&pTurnPeer->xorAddress, NULL)); /* only work for IPv4 for now */ CHK_STATUS(createTransactionIdStore(DEFAULT_MAX_STORED_TRANSACTION_ID_COUNT, &pTurnPeer->pTransactionIdStore)); @@ -852,6 +877,7 @@ STATUS turnConnectionRefreshPermission(PTurnConnection pTurnConnection, PBOOL pN UINT64 currTime = 0; PTurnPeer pTurnPeer = NULL; BOOL needRefresh = FALSE; + CHAR ipAddr[KVS_IP_ADDRESS_STRING_BUFFER_LEN]; UINT32 i; CHK(pTurnConnection != NULL && pNeedRefresh != NULL, STATUS_NULL_ARG); @@ -863,7 +889,8 @@ STATUS turnConnectionRefreshPermission(PTurnConnection pTurnConnection, PBOOL pN pTurnPeer = &pTurnConnection->turnPeerList[i]; if (IS_VALID_TIMESTAMP(pTurnPeer->permissionExpirationTime) && currTime + DEFAULT_TURN_PERMISSION_REFRESH_GRACE_PERIOD >= pTurnPeer->permissionExpirationTime) { - DLOGD("Refreshing turn permission"); + getIpAddrStr(&pTurnPeer->address, ipAddr, ARRAY_SIZE(ipAddr)); + DLOGD("[%p] Refreshing turn permission for %s:%d", pTurnConnection, ipAddr, pTurnPeer->address.port); needRefresh = TRUE; } } @@ -1012,6 +1039,10 @@ STATUS checkTurnPeerConnections(PTurnConnection pTurnConnection) pTurnPeer = &pTurnConnection->turnPeerList[i]; if (pTurnPeer->connectionState == TURN_PEER_CONN_STATE_CREATE_PERMISSION) { + if (pTurnPeer->firstTimeCreatePermReq) { + pTurnPeer->createPermissionStartTime = GETTIME(); + pTurnPeer->firstTimeCreatePermReq = FALSE; + } // update peer address; CHK_STATUS(getStunAttribute(pTurnConnection->pTurnCreatePermissionPacket, STUN_ATTRIBUTE_TYPE_XOR_PEER_ADDRESS, (PStunAttributeHeader*) &pStunAttributeAddress)); @@ -1028,6 +1059,10 @@ STATUS checkTurnPeerConnections(PTurnConnection pTurnConnection) pTurnConnection->pControlChannel, NULL, FALSE); } else if (pTurnPeer->connectionState == TURN_PEER_CONN_STATE_BIND_CHANNEL) { + if (pTurnPeer->firstTimeBindChannelReq) { + pTurnPeer->bindChannelStartTime = GETTIME(); + pTurnPeer->firstTimeBindChannelReq = FALSE; + } // update peer address; CHK_STATUS(getStunAttribute(pTurnConnection->pTurnChannelBindPacket, STUN_ATTRIBUTE_TYPE_XOR_PEER_ADDRESS, (PStunAttributeHeader*) &pStunAttributeAddress)); diff --git a/src/source/Ice/TurnConnection.h b/src/source/Ice/TurnConnection.h index 4e9d8d6bdc..6d73d8b336 100644 --- a/src/source/Ice/TurnConnection.h +++ b/src/source/Ice/TurnConnection.h @@ -21,11 +21,10 @@ extern "C" { #define DEFAULT_TURN_SEND_REFRESH_INVERVAL (1 * HUNDREDS_OF_NANOS_IN_A_SECOND) // turn state timeouts -#define DEFAULT_TURN_SOCKET_CONNECT_TIMEOUT (5 * HUNDREDS_OF_NANOS_IN_A_SECOND) #define DEFAULT_TURN_GET_CREDENTIAL_TIMEOUT (5 * HUNDREDS_OF_NANOS_IN_A_SECOND) #define DEFAULT_TURN_ALLOCATION_TIMEOUT (5 * HUNDREDS_OF_NANOS_IN_A_SECOND) -#define DEFAULT_TURN_CREATE_PERMISSION_TIMEOUT (2 * HUNDREDS_OF_NANOS_IN_A_SECOND) -#define DEFAULT_TURN_BIND_CHANNEL_TIMEOUT (3 * HUNDREDS_OF_NANOS_IN_A_SECOND) +#define DEFAULT_TURN_CREATE_PERMISSION_TIMEOUT (5 * HUNDREDS_OF_NANOS_IN_A_SECOND) +#define DEFAULT_TURN_BIND_CHANNEL_TIMEOUT (5 * HUNDREDS_OF_NANOS_IN_A_SECOND) #define DEFAULT_TURN_CLEAN_UP_TIMEOUT (10 * HUNDREDS_OF_NANOS_IN_A_SECOND) #define DEFAULT_TURN_ALLOCATION_REFRESH_GRACE_PERIOD (30 * HUNDREDS_OF_NANOS_IN_A_SECOND) @@ -36,8 +35,7 @@ extern "C" { #define DEFAULT_TURN_MESSAGE_RECV_CHANNEL_DATA_BUFFER_LEN MAX_TURN_CHANNEL_DATA_MESSAGE_SIZE #define DEFAULT_TURN_CHANNEL_DATA_BUFFER_SIZE 512 #define DEFAULT_TURN_MAX_PEER_COUNT 32 - -#define DEFAULT_TURN_ALLOCATION_MAX_TRY_COUNT 3 +#define MAX_TURN_PROFILE_LOG_DESC_LEN 256 // all turn channel numbers must be greater than 0x4000 and less than 0x7FFF #define TURN_CHANNEL_BIND_CHANNEL_NUMBER_BASE (UINT16) 0x4000 @@ -100,8 +98,23 @@ typedef struct { UINT16 channelNumber; UINT64 permissionExpirationTime; BOOL ready; + BOOL firstTimeCreatePermReq; + BOOL firstTimeCreatePermResponse; + UINT64 createPermissionStartTime; + UINT64 createPermissionTime; + BOOL firstTimeBindChannelReq; + BOOL firstTimeBindChannelResponse; + UINT64 bindChannelStartTime; + UINT64 bindChannelTime; } TurnPeer, *PTurnPeer; +typedef struct { + UINT64 getCredentialsStartTime; + UINT64 getCredentialsTime; + UINT64 createAllocationStartTime; + UINT64 createAllocationTime; +} TurnProfileDiagnostics, *PTurnProfileDiagnostics; + typedef struct __TurnConnection TurnConnection; struct __TurnConnection { volatile ATOMIC_BOOL stopTurnConnection; @@ -134,8 +147,6 @@ struct __TurnConnection { UINT64 state; UINT64 stateTimeoutTime; - UINT32 stateTryCount; - UINT32 stateTryCountMax; STATUS errorStatus; @@ -170,7 +181,7 @@ struct __TurnConnection { UINT64 currentTimerCallingPeriod; BOOL deallocatePacketSent; - + TurnProfileDiagnostics turnProfileDiagnostics; PStateMachine pStateMachine; }; typedef struct __TurnConnection* PTurnConnection; diff --git a/src/source/Ice/TurnConnectionStateMachine.c b/src/source/Ice/TurnConnectionStateMachine.c index 0a7dfd82d5..42da265c85 100644 --- a/src/source/Ice/TurnConnectionStateMachine.c +++ b/src/source/Ice/TurnConnectionStateMachine.c @@ -159,7 +159,6 @@ STATUS fromNewTurnState(UINT64 customData, PUINT64 pState) CHK(pTurnConnection != NULL && pState != NULL, STATUS_NULL_ARG); state = TURN_STATE_CHECK_SOCKET_CONNECTION; - *pState = state; CleanUp: @@ -191,6 +190,7 @@ STATUS fromCheckSocketConnectionTurnState(UINT64 customData, PUINT64 pState) PTurnConnection pTurnConnection = (PTurnConnection) customData; UINT64 state = TURN_STATE_CHECK_SOCKET_CONNECTION; BOOL locked = FALSE; + UINT64 currentTime; CHK(pTurnConnection != NULL && pState != NULL, STATUS_NULL_ARG); @@ -201,8 +201,10 @@ STATUS fromCheckSocketConnectionTurnState(UINT64 customData, PUINT64 pState) CHK(FALSE, STATUS_SUCCESS); } + currentTime = GETTIME(); if (socketConnectionIsConnected(pTurnConnection->pControlChannel)) { state = TURN_STATE_GET_CREDENTIALS; + pTurnConnection->stateTimeoutTime = currentTime + DEFAULT_TURN_GET_CREDENTIAL_TIMEOUT; } *pState = state; @@ -261,8 +263,6 @@ STATUS fromGetCredentialsTurnState(UINT64 customData, PUINT64 pState) if (pTurnConnection->credentialObtained) { state = TURN_STATE_ALLOCATION; pTurnConnection->stateTimeoutTime = currentTime + DEFAULT_TURN_ALLOCATION_TIMEOUT; - pTurnConnection->stateTryCountMax = DEFAULT_TURN_ALLOCATION_MAX_TRY_COUNT; - pTurnConnection->stateTryCount = 0; } *pState = state; @@ -282,10 +282,13 @@ STATUS executeGetCredentialsTurnState(UINT64 customData, UINT64 time) UNUSED_PARAM(time); STATUS retStatus = STATUS_SUCCESS; PTurnConnection pTurnConnection = (PTurnConnection) customData; - + UINT64 currentTime; CHK(pTurnConnection != NULL, STATUS_NULL_ARG); + currentTime = GETTIME(); + if (pTurnConnection->state != TURN_STATE_GET_CREDENTIALS) { + pTurnConnection->turnProfileDiagnostics.getCredentialsStartTime = currentTime; /* initialize TLS once tcp connection is established */ /* Start receiving data for TLS handshake */ ATOMIC_STORE_BOOL(&pTurnConnection->pControlChannel->receiveData, TRUE); @@ -296,6 +299,8 @@ STATUS executeGetCredentialsTurnState(UINT64 customData, UINT64 time) CHK_STATUS(socketConnectionInitSecureConnection(pTurnConnection->pControlChannel, FALSE)); } pTurnConnection->state = TURN_STATE_GET_CREDENTIALS; + } else { + CHK(currentTime <= pTurnConnection->stateTimeoutTime, STATUS_TURN_CONNECTION_GET_CREDENTIALS_FAILED); } CHK_STATUS(iceUtilsSendStunPacket(pTurnConnection->pTurnPacket, NULL, 0, &pTurnConnection->turnServer.ipAddress, pTurnConnection->pControlChannel, NULL, FALSE)); @@ -347,12 +352,13 @@ STATUS executeAllocationTurnState(UINT64 customData, UINT64 time) UNUSED_PARAM(time); STATUS retStatus = STATUS_SUCCESS; PTurnConnection pTurnConnection = (PTurnConnection) customData; - + UINT64 currentTime; CHK(pTurnConnection != NULL, STATUS_NULL_ARG); + currentTime = GETTIME(); if (pTurnConnection->state != TURN_STATE_ALLOCATION) { DLOGV("Updated turn allocation request credential after receiving 401"); - + pTurnConnection->turnProfileDiagnostics.createAllocationStartTime = GETTIME(); // update turn allocation packet with credentials CHK_STATUS(freeStunPacket(&pTurnConnection->pTurnPacket)); CHK_STATUS(turnConnectionGetLongTermKey(pTurnConnection->turnServer.username, pTurnConnection->turnRealm, @@ -363,8 +369,7 @@ STATUS executeAllocationTurnState(UINT64 customData, UINT64 time) DEFAULT_TURN_ALLOCATION_LIFETIME_SECONDS, &pTurnConnection->pTurnPacket)); pTurnConnection->state = TURN_STATE_ALLOCATION; } else { - pTurnConnection->stateTryCount++; - CHK(pTurnConnection->stateTryCount < pTurnConnection->stateTryCountMax, STATUS_TURN_CONNECTION_ALLOCATION_FAILED); + CHK(currentTime <= pTurnConnection->stateTimeoutTime, STATUS_TURN_CONNECTION_ALLOCATION_FAILED); } CHK_STATUS(iceUtilsSendStunPacket(pTurnConnection->pTurnPacket, pTurnConnection->longTermKey, ARRAY_SIZE(pTurnConnection->longTermKey), &pTurnConnection->turnServer.ipAddress, pTurnConnection->pControlChannel, NULL, FALSE)); @@ -413,7 +418,7 @@ STATUS fromCreatePermissionTurnState(UINT64 customData, PUINT64 pState) CHK(FALSE, retStatus); } - if (currentTime >= pTurnConnection->stateTimeoutTime || channelWithPermissionCount == pTurnConnection->turnPeerCount) { + if (currentTime > pTurnConnection->stateTimeoutTime || channelWithPermissionCount == pTurnConnection->turnPeerCount) { CHK(channelWithPermissionCount > 0, STATUS_TURN_CONNECTION_FAILED_TO_CREATE_PERMISSION); // go to next state if we have at least one ready peer @@ -446,7 +451,6 @@ STATUS executeCreatePermissionTurnState(UINT64 customData, UINT64 time) if (pTurnConnection->state != TURN_STATE_CREATE_PERMISSION) { CHK_STATUS(getIpAddrStr(&pTurnConnection->relayAddress, ipAddrStr, ARRAY_SIZE(ipAddrStr))); DLOGD("Relay address received: %s, port: %u", ipAddrStr, (UINT16) getInt16(pTurnConnection->relayAddress.port)); - if (pTurnConnection->pTurnCreatePermissionPacket != NULL) { CHK_STATUS(freeStunPacket(&pTurnConnection->pTurnCreatePermissionPacket)); } @@ -459,7 +463,7 @@ STATUS executeCreatePermissionTurnState(UINT64 customData, UINT64 time) CHK_STATUS(appendStunNonceAttribute(pTurnConnection->pTurnCreatePermissionPacket, pTurnConnection->turnNonce, pTurnConnection->nonceLen)); // create channel bind packet here too so for each peer as soon as permission is created, it can start - // sending chaneel bind request + // sending channel bind request if (pTurnConnection->pTurnChannelBindPacket != NULL) { CHK_STATUS(freeStunPacket(&pTurnConnection->pTurnChannelBindPacket)); } @@ -525,7 +529,7 @@ STATUS fromBindChannelTurnState(UINT64 customData, PUINT64 pState) readyPeerCount++; } } - if (currentTime >= pTurnConnection->stateTimeoutTime || readyPeerCount == pTurnConnection->turnPeerCount) { + if (currentTime > pTurnConnection->stateTimeoutTime || readyPeerCount == pTurnConnection->turnPeerCount) { CHK(readyPeerCount > 0, STATUS_TURN_CONNECTION_FAILED_TO_BIND_CHANNEL); // go to next state if we have at least one ready peer state = TURN_STATE_READY; @@ -549,7 +553,9 @@ STATUS executeBindChannelTurnState(UINT64 customData, UINT64 time) PTurnConnection pTurnConnection = (PTurnConnection) customData; CHK(pTurnConnection != NULL, STATUS_NULL_ARG); - pTurnConnection->state = TURN_STATE_BIND_CHANNEL; + if (pTurnConnection->state != TURN_STATE_BIND_CHANNEL) { + pTurnConnection->state = TURN_STATE_BIND_CHANNEL; + } CHK_STATUS(checkTurnPeerConnections(pTurnConnection)); CleanUp: @@ -652,11 +658,11 @@ STATUS fromCleanUpTurnState(UINT64 customData, PUINT64 pState) CHK(FALSE, STATUS_SUCCESS); } - /* start cleanning up even if we dont receive allocation freed response in time, or if connection is already closed, + /* start cleaning up even if we dont receive allocation freed response in time, or if connection is already closed, * since we already sent multiple STUN refresh packets with 0 lifetime. */ currentTime = GETTIME(); if (socketConnectionIsClosed(pTurnConnection->pControlChannel) || !ATOMIC_LOAD_BOOL(&pTurnConnection->hasAllocation) || - currentTime >= pTurnConnection->stateTimeoutTime) { + currentTime > pTurnConnection->stateTimeoutTime) { // clean transactionId store for each turn peer, preserving the peers for (i = 0; i < pTurnConnection->turnPeerCount; ++i) { transactionIdStoreClear(pTurnConnection->turnPeerList[i].pTransactionIdStore); diff --git a/src/source/Ice/TurnConnectionStateMachine.h b/src/source/Ice/TurnConnectionStateMachine.h index 9ae2767055..7ec545387a 100644 --- a/src/source/Ice/TurnConnectionStateMachine.h +++ b/src/source/Ice/TurnConnectionStateMachine.h @@ -25,16 +25,16 @@ extern "C" { * TURN_STATE_FAILED: */ -#define TURN_STATE_NONE ((UINT64) 0) -#define TURN_STATE_NEW ((UINT64) (1 << 0)) -#define TURN_STATE_CHECK_SOCKET_CONNECTION ((UINT64) (1 << 1)) -#define TURN_STATE_GET_CREDENTIALS ((UINT64) (1 << 2)) -#define TURN_STATE_ALLOCATION ((UINT64) (1 << 3)) -#define TURN_STATE_CREATE_PERMISSION ((UINT64) (1 << 4)) -#define TURN_STATE_BIND_CHANNEL ((UINT64) (1 << 5)) -#define TURN_STATE_READY ((UINT64) (1 << 6)) -#define TURN_STATE_CLEAN_UP ((UINT64) (1 << 7)) -#define TURN_STATE_FAILED ((UINT64) (1 << 8)) +#define TURN_STATE_NONE ((UINT64) 0) // 0x000000000 +#define TURN_STATE_NEW ((UINT64) (1 << 0)) // 0x000000001 +#define TURN_STATE_CHECK_SOCKET_CONNECTION ((UINT64) (1 << 1)) // 0x000000002 +#define TURN_STATE_GET_CREDENTIALS ((UINT64) (1 << 2)) // 0x000000004 +#define TURN_STATE_ALLOCATION ((UINT64) (1 << 3)) // 0x000000008 +#define TURN_STATE_CREATE_PERMISSION ((UINT64) (1 << 4)) // 0x000000010 +#define TURN_STATE_BIND_CHANNEL ((UINT64) (1 << 5)) // 0x000000020 +#define TURN_STATE_READY ((UINT64) (1 << 6)) // 0x000000040 +#define TURN_STATE_CLEAN_UP ((UINT64) (1 << 7)) // 0x000000080 +#define TURN_STATE_FAILED ((UINT64) (1 << 8)) // 0x000000100 #define TURN_STATE_NONE_STR (PCHAR) "TURN_STATE_NONE" #define TURN_STATE_NEW_STR (PCHAR) "TURN_STATE_NEW"