diff --git a/README.md b/README.md index d1f1244dbb..2677a3271b 100644 --- a/README.md +++ b/README.md @@ -6,7 +6,6 @@

Pure C WebRTC Client for Amazon Kinesis Video Streams

- Build Status Coverage Status

@@ -164,7 +163,7 @@ export AWS_SESSION_TOKEN= export AWS_DEFAULT_REGION= ``` -### Setup desired log level: +### Setup logging: Set up the desired log level. The log levels and corresponding values currently available are: 1. `LOG_LEVEL_VERBOSE` ---- 1 2. `LOG_LEVEL_DEBUG` ---- 2 @@ -186,12 +185,23 @@ export AWS_KVS_LOG_LEVEL = 2 switches on DEBUG level logs while runnning the sam Note: The default log level is `LOG_LEVEL_WARN`. -* Optionally, set path to SSL CA certificate with variable (`../certs/cert.pem` is default one and points to file in this repository): +Starting v1.7.x (**TO_BE_UPDATED**), by default, the SDK creates a log file that would have execution timing details of certain steps in connection establishment. It would be stored in the `build` directory as `kvsFileLogFilter.x`. In case you do not want to use defaults, you can modify certain parameters such as log file directory, log file size and file rotation index in the `createFileLoggerWithLevelFiltering` function in the samples. +In addition to these logs, if you would like to have other level logs in a file as well, run: + +``` +export AWS_ENABLE_FILE_LOGGING=TRUE +``` + +### Set path to SSL CA certificate (**Optional**) + +If you have a custom CA certificate path to set, you can set it using: ``` export AWS_KVS_CACERT_PATH=../certs/cert.pem ``` +By defaut, the SSL CA certificate is set to `../certs/cert.pem` which points to the file in this repository: + ### Running the Samples After executing `make` you will have sample applications in your `build/samples` directory. From the `build/` directory, run any of the sample applications by passing to it the name of your signaling channel. If a signaling channel does not exist with the name you provide, the application creates one. @@ -298,11 +308,6 @@ In the mbedTLS version, the SDK uses /dev/urandom on Unix and CryptGenRandom API If you would like to print out the SDPs, run this command: `export DEBUG_LOG_SDP=TRUE` -### File logging -If you would like to enable file logging, run this command: -`export AWS_ENABLE_FILE_LOGGING=TRUE` -You can also change settings such as buffer size, number of log files for rotation and log file path in the samples - ### Adjust MTU If ICE connection can be established successfully but media can not be transferred, make sure the actual MTU is higher than the MTU setting here: https://github.com/awslabs/amazon-kinesis-video-streams-webrtc-sdk-c/blob/master/src/source/PeerConnection/Rtp.h#L12. diff --git a/samples/Common.c b/samples/Common.c index c30aec8637..76862d1bff 100644 --- a/samples/Common.c +++ b/samples/Common.c @@ -12,6 +12,18 @@ VOID sigintHandler(INT32 sigNum) } } +UINT32 setLogLevel() +{ + PCHAR pLogLevel; + UINT32 logLevel = LOG_LEVEL_DEBUG; + if (NULL == (pLogLevel = GETENV(DEBUG_LOG_LEVEL_ENV_VAR)) || STATUS_SUCCESS != STRTOUI32(pLogLevel, NULL, 10, &logLevel) || + logLevel < LOG_LEVEL_VERBOSE || logLevel > LOG_LEVEL_SILENT) { + logLevel = LOG_LEVEL_WARN; + } + SET_LOGGER_LOG_LEVEL(logLevel); + return logLevel; +} + STATUS signalingCallFailed(STATUS status) { return (STATUS_SIGNALING_GET_TOKEN_CALL_FAILED == status || STATUS_SIGNALING_DESCRIBE_CALL_FAILED == status || @@ -45,7 +57,6 @@ VOID onConnectionStateChange(UINT64 customData, RTC_PEER_CONNECTION_STATE newSta { STATUS retStatus = STATUS_SUCCESS; PSampleStreamingSession pSampleStreamingSession = (PSampleStreamingSession) customData; - CHK(pSampleStreamingSession != NULL && pSampleStreamingSession->pSampleConfiguration != NULL, STATUS_INTERNAL_ERROR); PSampleConfiguration pSampleConfiguration = pSampleStreamingSession->pSampleConfiguration; @@ -55,6 +66,10 @@ VOID onConnectionStateChange(UINT64 customData, RTC_PEER_CONNECTION_STATE newSta case RTC_PEER_CONNECTION_STATE_CONNECTED: ATOMIC_STORE_BOOL(&pSampleConfiguration->connected, TRUE); CVAR_BROADCAST(pSampleConfiguration->cvar); + + CHK_STATUS(peerConnectionGetMetrics(pSampleStreamingSession->pPeerConnection, &pSampleStreamingSession->peerConnectionMetrics)); + CHK_STATUS(iceAgentGetMetrics(pSampleStreamingSession->pPeerConnection, &pSampleStreamingSession->iceMetrics)); + if (STATUS_FAILED(retStatus = logSelectedIceCandidatesInformation(pSampleStreamingSession))) { DLOGW("Failed to get information about selected Ice candidates: 0x%08x", retStatus); } @@ -70,6 +85,7 @@ VOID onConnectionStateChange(UINT64 customData, RTC_PEER_CONNECTION_STATE newSta default: ATOMIC_STORE_BOOL(&pSampleConfiguration->connected, FALSE); CVAR_BROADCAST(pSampleConfiguration->cvar); + break; } @@ -219,8 +235,6 @@ STATUS handleOffer(PSampleConfiguration pSampleConfiguration, PSampleStreamingSe if (pSampleStreamingSession->remoteCanTrickleIce) { CHK_STATUS(createAnswer(pSampleStreamingSession->pPeerConnection, &pSampleStreamingSession->answerSessionDescriptionInit)); CHK_STATUS(respondWithAnswer(pSampleStreamingSession)); - DLOGD("time taken to send answer %" PRIu64 " ms", - (GETTIME() - pSampleStreamingSession->offerReceiveTime) / HUNDREDS_OF_NANOS_IN_A_MILLISECOND); } mediaThreadStarted = ATOMIC_EXCHANGE_BOOL(&pSampleConfiguration->mediaThreadStarted, TRUE); @@ -244,16 +258,23 @@ STATUS sendSignalingMessage(PSampleStreamingSession pSampleStreamingSession, PSi { STATUS retStatus = STATUS_SUCCESS; BOOL locked = FALSE; - + PSampleConfiguration pSampleConfiguration; // Validate the input params CHK(pSampleStreamingSession != NULL && pSampleStreamingSession->pSampleConfiguration != NULL && pMessage != NULL, STATUS_NULL_ARG); - CHK(IS_VALID_MUTEX_VALUE(pSampleStreamingSession->pSampleConfiguration->signalingSendMessageLock) && - IS_VALID_SIGNALING_CLIENT_HANDLE(pSampleStreamingSession->pSampleConfiguration->signalingClientHandle), + + pSampleConfiguration = pSampleStreamingSession->pSampleConfiguration; + + CHK(IS_VALID_MUTEX_VALUE(pSampleConfiguration->signalingSendMessageLock) && + IS_VALID_SIGNALING_CLIENT_HANDLE(pSampleConfiguration->signalingClientHandle), STATUS_INVALID_OPERATION); - MUTEX_LOCK(pSampleStreamingSession->pSampleConfiguration->signalingSendMessageLock); + MUTEX_LOCK(pSampleConfiguration->signalingSendMessageLock); locked = TRUE; - CHK_STATUS(signalingClientSendMessageSync(pSampleStreamingSession->pSampleConfiguration->signalingClientHandle, pMessage)); + CHK_STATUS(signalingClientSendMessageSync(pSampleConfiguration->signalingClientHandle, pMessage)); + if (pMessage->messageType == SIGNALING_MESSAGE_TYPE_ANSWER) { + CHK_STATUS(signalingClientGetMetrics(pSampleConfiguration->signalingClientHandle, &pSampleConfiguration->signalingClientMetrics)); + DLOGP("[Signaling offer to answer] %" PRIu64 " ms", pSampleConfiguration->signalingClientMetrics.signalingClientStats.offerToAnswerTime); + } CleanUp: @@ -315,8 +336,6 @@ VOID onIceCandidateHandler(UINT64 customData, PCHAR candidateJson) !pSampleStreamingSession->remoteCanTrickleIce) { CHK_STATUS(createAnswer(pSampleStreamingSession->pPeerConnection, &pSampleStreamingSession->answerSessionDescriptionInit)); CHK_STATUS(respondWithAnswer(pSampleStreamingSession)); - DLOGD("time taken to send answer %" PRIu64 " ms", - (GETTIME() - pSampleStreamingSession->offerReceiveTime) / HUNDREDS_OF_NANOS_IN_A_MILLISECOND); } else if (pSampleStreamingSession->pSampleConfiguration->channelInfo.channelRoleType == SIGNALING_CHANNEL_ROLE_TYPE_VIEWER && !pSampleStreamingSession->pSampleConfiguration->trickleIce) { CVAR_BROADCAST(pSampleStreamingSession->pSampleConfiguration->cvar); @@ -344,7 +363,7 @@ STATUS initializePeerConnection(PSampleConfiguration pSampleConfiguration, PRtcP RtcConfiguration configuration; UINT32 i, j, iceConfigCount, uriCount = 0, maxTurnServer = 1; PIceConfigInfo pIceConfigInfo; - UINT64 data, curTime; + UINT64 data; PRtcCertificate pRtcCertificate = NULL; CHK(pSampleConfiguration != NULL && ppRtcPeerConnection != NULL, STATUS_NULL_ARG); @@ -375,7 +394,7 @@ STATUS initializePeerConnection(PSampleConfiguration pSampleConfiguration, PRtcP * if configuration.iceServers[uriCount + 1].urls is "turn:ip:port?transport=tcp" then ICE will try TURN over TCP/TLS * if configuration.iceServers[uriCount + 1].urls is "turns:ip:port?transport=udp", it's currently ignored because sdk dont do TURN * over DTLS yet. if configuration.iceServers[uriCount + 1].urls is "turns:ip:port?transport=tcp" then ICE will try TURN over TCP/TLS - * if configuration.iceServers[uriCount + 1].urls is "turn:ip:port" then ICE will try both TURN over UPD and TCP/TLS + * if configuration.iceServers[uriCount + 1].urls is "turn:ip:port" then ICE will try both TURN over UDP and TCP/TLS * * It's recommended to not pass too many TURN iceServers to configuration because it will slow down ice gathering in non-trickle mode. */ @@ -404,10 +423,7 @@ STATUS initializePeerConnection(PSampleConfiguration pSampleConfiguration, PRtcP configuration.certificates[0] = *pRtcCertificate; } - curTime = GETTIME(); CHK_STATUS(createPeerConnection(&configuration, ppRtcPeerConnection)); - DLOGD("time taken to create peer connection %" PRIu64 " ms", (GETTIME() - curTime) / HUNDREDS_OF_NANOS_IN_A_MILLISECOND); - CleanUp: CHK_LOG_ERR(retStatus); @@ -459,6 +475,8 @@ STATUS createSampleStreamingSession(PSampleConfiguration pSampleConfiguration, P CHK((isMaster && peerId != NULL) || !isMaster, STATUS_INVALID_ARG); pSampleStreamingSession = (PSampleStreamingSession) MEMCALLOC(1, SIZEOF(SampleStreamingSession)); + pSampleStreamingSession->firstFrame = TRUE; + pSampleStreamingSession->offerReceiveTime = GETTIME(); CHK(pSampleStreamingSession != NULL, STATUS_NOT_ENOUGH_MEMORY); if (isMaster) { @@ -473,6 +491,10 @@ STATUS createSampleStreamingSession(PSampleConfiguration pSampleConfiguration, P pSampleStreamingSession->pSampleConfiguration = pSampleConfiguration; pSampleStreamingSession->rtcMetricsHistory.prevTs = GETTIME(); + + pSampleStreamingSession->peerConnectionMetrics.version = PEER_CONNECTION_METRICS_CURRENT_VERSION; + pSampleStreamingSession->iceMetrics.version = ICE_AGENT_METRICS_CURRENT_VERSION; + // if we're the viewer, we control the trickle ice mode pSampleStreamingSession->remoteCanTrickleIce = !isMaster && pSampleConfiguration->trickleIce; @@ -518,7 +540,6 @@ STATUS createSampleStreamingSession(PSampleConfiguration pSampleConfiguration, P // twcc bandwidth estimation CHK_STATUS(peerConnectionOnSenderBandwidthEstimation(pSampleStreamingSession->pPeerConnection, (UINT64) pSampleStreamingSession, sampleSenderBandwidthEstimationHandler)); - pSampleStreamingSession->firstFrame = TRUE; pSampleStreamingSession->startUpLatency = 0; CleanUp: @@ -599,24 +620,12 @@ VOID sampleVideoFrameHandler(UINT64 customData, PFrame pFrame) { UNUSED_PARAM(customData); DLOGV("Video Frame received. TrackId: %" PRIu64 ", Size: %u, Flags %u", pFrame->trackId, pFrame->size, pFrame->flags); - PSampleStreamingSession pSampleStreamingSession = (PSampleStreamingSession) customData; - if (pSampleStreamingSession->firstFrame) { - pSampleStreamingSession->firstFrame = FALSE; - pSampleStreamingSession->startUpLatency = (GETTIME() - pSampleStreamingSession->offerReceiveTime) / HUNDREDS_OF_NANOS_IN_A_MILLISECOND; - printf("Start up latency from offer to first video frame: %" PRIu64 "ms\n", pSampleStreamingSession->startUpLatency); - } } VOID sampleAudioFrameHandler(UINT64 customData, PFrame pFrame) { UNUSED_PARAM(customData); DLOGV("Audio Frame received. TrackId: %" PRIu64 ", Size: %u, Flags %u", pFrame->trackId, pFrame->size, pFrame->flags); - PSampleStreamingSession pSampleStreamingSession = (PSampleStreamingSession) customData; - if (pSampleStreamingSession->firstFrame) { - pSampleStreamingSession->firstFrame = FALSE; - pSampleStreamingSession->startUpLatency = (GETTIME() - pSampleStreamingSession->offerReceiveTime) / HUNDREDS_OF_NANOS_IN_A_MILLISECOND; - printf("Start up latency from offer to first audio frame: %" PRIu64 "ms\n", pSampleStreamingSession->startUpLatency); - } } VOID sampleBandwidthEstimationHandler(UINT64 customData, DOUBLE maximumBitrate) @@ -720,13 +729,12 @@ STATUS lookForSslCert(PSampleConfiguration* ppSampleConfiguration) return retStatus; } -STATUS createSampleConfiguration(PCHAR channelName, SIGNALING_CHANNEL_ROLE_TYPE roleType, BOOL trickleIce, BOOL useTurn, +STATUS createSampleConfiguration(PCHAR channelName, SIGNALING_CHANNEL_ROLE_TYPE roleType, BOOL trickleIce, BOOL useTurn, UINT32 logLevel, PSampleConfiguration* ppSampleConfiguration) { STATUS retStatus = STATUS_SUCCESS; - PCHAR pAccessKey, pSecretKey, pSessionToken, pLogLevel; + PCHAR pAccessKey, pSecretKey, pSessionToken; PSampleConfiguration pSampleConfiguration = NULL; - UINT32 logLevel = LOG_LEVEL_DEBUG; CHK(ppSampleConfiguration != NULL, STATUS_NULL_ARG); @@ -745,24 +753,35 @@ STATUS createSampleConfiguration(PCHAR channelName, SIGNALING_CHANNEL_ROLE_TYPE #endif pSessionToken = getenv(SESSION_TOKEN_ENV_VAR); - pSampleConfiguration->enableFileLogging = FALSE; + + // If the env is set, we generate normal log files apart from filtered profile log files + // If not set, we generate only the filtered profile log files if (NULL != getenv(ENABLE_FILE_LOGGING)) { - pSampleConfiguration->enableFileLogging = TRUE; + retStatus = createFileLoggerWithLevelFiltering(FILE_LOGGING_BUFFER_SIZE, MAX_NUMBER_OF_LOG_FILES, (PCHAR) FILE_LOGGER_LOG_FILE_DIRECTORY_PATH, + TRUE, TRUE, TRUE, LOG_LEVEL_PROFILE, NULL); + + if (retStatus != STATUS_SUCCESS) { + DLOGW("[KVS Master] createFileLogger(): operation returned status code: 0x%08x", retStatus); + } else { + pSampleConfiguration->enableFileLogging = TRUE; + } + } else { + retStatus = createFileLoggerWithLevelFiltering(FILE_LOGGING_BUFFER_SIZE, MAX_NUMBER_OF_LOG_FILES, (PCHAR) FILE_LOGGER_LOG_FILE_DIRECTORY_PATH, + TRUE, TRUE, FALSE, LOG_LEVEL_PROFILE, NULL); + + if (retStatus != STATUS_SUCCESS) { + DLOGW("[KVS Master] createFileLogger(): operation returned status code: 0x%08x", retStatus); + } else { + pSampleConfiguration->enableFileLogging = TRUE; + } } + if ((pSampleConfiguration->channelInfo.pRegion = getenv(DEFAULT_REGION_ENV_VAR)) == NULL) { pSampleConfiguration->channelInfo.pRegion = DEFAULT_AWS_REGION; } CHK_STATUS(lookForSslCert(&pSampleConfiguration)); - // Set the logger log level - if (NULL == (pLogLevel = getenv(DEBUG_LOG_LEVEL_ENV_VAR)) || STATUS_SUCCESS != STRTOUI32(pLogLevel, NULL, 10, &logLevel) || - logLevel < LOG_LEVEL_VERBOSE || logLevel > LOG_LEVEL_SILENT) { - logLevel = LOG_LEVEL_WARN; - } - - SET_LOGGER_LOG_LEVEL(logLevel); - #ifdef IOT_CORE_ENABLE_CREDENTIALS CHK_STATUS(createLwsIotCredentialProvider(pIotCoreCredentialEndPoint, pIotCoreCert, pIotCorePrivateKey, pSampleConfiguration->pCaCertPath, pIotCoreRoleAlias, channelName, &pSampleConfiguration->pCredentialProvider)); @@ -817,6 +836,7 @@ STATUS createSampleConfiguration(PCHAR channelName, SIGNALING_CHANNEL_ROLE_TYPE pSampleConfiguration->clientInfo.signalingMessagesMaximumThreads = KVS_SIGNALING_THREADPOOL_MAX; pSampleConfiguration->iceCandidatePairStatsTimerId = MAX_UINT32; pSampleConfiguration->pregenerateCertTimerId = MAX_UINT32; + pSampleConfiguration->signalingClientMetrics.version = SIGNALING_CLIENT_METRICS_CURRENT_VERSION; ATOMIC_STORE_BOOL(&pSampleConfiguration->interrupted, FALSE); ATOMIC_STORE_BOOL(&pSampleConfiguration->mediaThreadStarted, FALSE); @@ -854,6 +874,38 @@ STATUS createSampleConfiguration(PCHAR channelName, SIGNALING_CHANNEL_ROLE_TYPE return retStatus; } +STATUS initSignaling(PSampleConfiguration pSampleConfiguration, PCHAR clientId) +{ + STATUS retStatus = STATUS_SUCCESS; + SignalingClientMetrics signalingClientMetrics = pSampleConfiguration->signalingClientMetrics; + pSampleConfiguration->signalingClientCallbacks.messageReceivedFn = signalingMessageReceived; + STRCPY(pSampleConfiguration->clientInfo.clientId, clientId); + CHK_STATUS(createSignalingClientSync(&pSampleConfiguration->clientInfo, &pSampleConfiguration->channelInfo, + &pSampleConfiguration->signalingClientCallbacks, pSampleConfiguration->pCredentialProvider, + &pSampleConfiguration->signalingClientHandle)); + + // Enable the processing of the messages + CHK_STATUS(signalingClientFetchSync(pSampleConfiguration->signalingClientHandle)); + CHK_STATUS(signalingClientConnectSync(pSampleConfiguration->signalingClientHandle)); + + signalingClientGetMetrics(pSampleConfiguration->signalingClientHandle, &signalingClientMetrics); + + // Logging this here since the logs in signaling library do not get routed to file + DLOGP("[Signaling Get token] %" PRIu64 " ms", signalingClientMetrics.signalingClientStats.getTokenCallTime); + DLOGP("[Signaling Describe] %" PRIu64 " ms", signalingClientMetrics.signalingClientStats.describeCallTime); + DLOGP("[Signaling Create Channel] %" PRIu64 " ms", signalingClientMetrics.signalingClientStats.createCallTime); + DLOGP("[Signaling Get endpoint] %" PRIu64 " ms", signalingClientMetrics.signalingClientStats.getEndpointCallTime); + DLOGP("[Signaling Get ICE config] %" PRIu64 " ms", signalingClientMetrics.signalingClientStats.getIceConfigCallTime); + DLOGP("[Signaling Connect] %" PRIu64 " ms", signalingClientMetrics.signalingClientStats.connectCallTime); + DLOGP("[Signaling create client] %" PRIu64 " ms", signalingClientMetrics.signalingClientStats.createClientTime); + DLOGP("[Signaling fetch client] %" PRIu64 " ms", signalingClientMetrics.signalingClientStats.fetchClientTime); + DLOGP("[Signaling connect client] %" PRIu64 " ms", signalingClientMetrics.signalingClientStats.connectClientTime); + pSampleConfiguration->signalingClientMetrics = signalingClientMetrics; + gSampleConfiguration = pSampleConfiguration; +CleanUp: + return retStatus; +} + STATUS logSignalingClientStats(PSignalingClientMetrics pSignalingClientMetrics) { ENTERS(); @@ -1044,7 +1096,6 @@ STATUS freeSampleConfiguration(PSampleConfiguration* ppSampleConfiguration) pSampleConfiguration = *ppSampleConfiguration; CHK(pSampleConfiguration != NULL, retStatus); - if (IS_VALID_TIMER_QUEUE_HANDLE(pSampleConfiguration->timerQueueHandle)) { if (pSampleConfiguration->iceCandidatePairStatsTimerId != MAX_UINT32) { retStatus = timerQueueCancelTimer(pSampleConfiguration->timerQueueHandle, pSampleConfiguration->iceCandidatePairStatsTimerId, @@ -1144,7 +1195,9 @@ STATUS freeSampleConfiguration(PSampleConfiguration* ppSampleConfiguration) CHK_LOG_ERR(stackQueueFree(pSampleConfiguration->pregeneratedCertificates)); pSampleConfiguration->pregeneratedCertificates = NULL; } - + if (pSampleConfiguration->enableFileLogging) { + freeFileLogger(); + } SAFE_MEMFREE(*ppSampleConfiguration); CleanUp: @@ -1312,6 +1365,7 @@ STATUS signalingMessageReceived(UINT64 customData, PReceivedSignalingMessage pRe * any ice candidate messages queued in pPendingSignalingMessageForRemoteClient. If so then submit * all of them. */ + if (pSampleConfiguration->streamingSessionCount == ARRAY_SIZE(pSampleConfiguration->sampleStreamingSessionList)) { DLOGW("Max simultaneous streaming session count reached."); @@ -1325,7 +1379,6 @@ STATUS signalingMessageReceived(UINT64 customData, PReceivedSignalingMessage pRe } CHK_STATUS(createSampleStreamingSession(pSampleConfiguration, pReceivedSignalingMessage->signalingMessage.peerClientId, TRUE, &pSampleStreamingSession)); - pSampleStreamingSession->offerReceiveTime = GETTIME(); MUTEX_LOCK(pSampleConfiguration->streamingSessionListReadLock); pSampleConfiguration->sampleStreamingSessionList[pSampleConfiguration->streamingSessionCount++] = pSampleStreamingSession; MUTEX_UNLOCK(pSampleConfiguration->streamingSessionListReadLock); @@ -1368,6 +1421,8 @@ STATUS signalingMessageReceived(UINT64 customData, PReceivedSignalingMessage pRe } startStats = pSampleConfiguration->iceCandidatePairStatsTimerId == MAX_UINT32; + CHK_STATUS(signalingClientGetMetrics(pSampleConfiguration->signalingClientHandle, &pSampleConfiguration->signalingClientMetrics)); + DLOGP("[Signaling offer to answer] %" PRIu64 " ms", pSampleConfiguration->signalingClientMetrics.signalingClientStats.offerToAnswerTime); break; case SIGNALING_MESSAGE_TYPE_ICE_CANDIDATE: diff --git a/samples/Samples.h b/samples/Samples.h index 2ef6b5c35a..dedd53d65e 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 (100 * 1024) +#define FILE_LOGGING_BUFFER_SIZE (10 * 1024) #define MAX_NUMBER_OF_LOG_FILES 5 #define SAMPLE_HASH_TABLE_BUCKET_COUNT 50 @@ -110,6 +110,7 @@ typedef struct { startRoutine videoSource; startRoutine receiveAudioVideoSource; RtcOnDataChannel onDataChannel; + SignalingClientMetrics signalingClientMetrics; PStackQueue pPendingSignalingMessageForRemoteClient; PHashTable pRtcPeerConnectionForRemoteClient; @@ -134,6 +135,7 @@ typedef struct { PStackQueue pregeneratedCertificates; // Max MAX_RTCCONFIGURATION_CERTIFICATES certificates PCHAR rtspUri; + UINT32 logLevel; } SampleConfiguration, *PSampleConfiguration; typedef struct { @@ -148,6 +150,7 @@ struct __SampleStreamingSession { volatile ATOMIC_BOOL terminateFlag; volatile ATOMIC_BOOL candidateGatheringDone; volatile ATOMIC_BOOL peerIdReceived; + volatile ATOMIC_BOOL firstFrame; volatile SIZE_T frameIndex; PRtcPeerConnection pPeerConnection; PRtcRtpTransceiver pVideoRtcRtpTransceiver; @@ -158,15 +161,16 @@ struct __SampleStreamingSession { UINT64 videoTimestamp; CHAR peerId[MAX_SIGNALING_CLIENT_ID_LEN + 1]; TID receiveAudioVideoSenderTid; - UINT64 offerReceiveTime; UINT64 startUpLatency; - BOOL firstFrame; RtcMetricsHistory rtcMetricsHistory; BOOL remoteCanTrickleIce; // this is called when the SampleStreamingSession is being freed StreamSessionShutdownCallback shutdownCallback; UINT64 shutdownCallbackCustomData; + UINT64 offerReceiveTime; + PeerConnectionMetrics peerConnectionMetrics; + KvsIceAgentMetrics iceMetrics; }; VOID sigintHandler(INT32); @@ -178,7 +182,7 @@ PVOID sampleReceiveAudioVideoFrame(PVOID); PVOID getPeriodicIceCandidatePairStats(PVOID); STATUS getIceCandidatePairStatsCallback(UINT32, UINT64, UINT64); STATUS pregenerateCertTimerCallback(UINT32, UINT64, UINT64); -STATUS createSampleConfiguration(PCHAR, SIGNALING_CHANNEL_ROLE_TYPE, BOOL, BOOL, PSampleConfiguration*); +STATUS createSampleConfiguration(PCHAR, SIGNALING_CHANNEL_ROLE_TYPE, BOOL, BOOL, UINT32, PSampleConfiguration*); STATUS freeSampleConfiguration(PSampleConfiguration*); STATUS signalingClientStateChanged(UINT64, SIGNALING_CLIENT_STATE); STATUS signalingMessageReceived(UINT64, PReceivedSignalingMessage); @@ -208,7 +212,9 @@ STATUS freeMessageQueue(PPendingMessageQueue); STATUS submitPendingIceCandidate(PPendingMessageQueue, PSampleStreamingSession); STATUS removeExpiredMessageQueues(PStackQueue); STATUS getPendingMessageQueueForHash(PStackQueue, UINT64, BOOL, PPendingMessageQueue*); +STATUS initSignaling(PSampleConfiguration, PCHAR); BOOL sampleFilterNetworkInterfaces(UINT64, PCHAR); +UINT32 setLogLevel(); #ifdef __cplusplus } diff --git a/samples/kvsWebRTCClientMaster.c b/samples/kvsWebRTCClientMaster.c index 9f3ce4f5df..1913401f18 100644 --- a/samples/kvsWebRTCClientMaster.c +++ b/samples/kvsWebRTCClientMaster.c @@ -2,48 +2,29 @@ extern PSampleConfiguration gSampleConfiguration; -// #define VERBOSE - INT32 main(INT32 argc, CHAR* argv[]) { STATUS retStatus = STATUS_SUCCESS; UINT32 frameSize; PSampleConfiguration pSampleConfiguration = NULL; - SignalingClientMetrics signalingClientMetrics; PCHAR pChannelName; + SignalingClientMetrics signalingClientMetrics; signalingClientMetrics.version = SIGNALING_CLIENT_METRICS_CURRENT_VERSION; SET_INSTRUMENTED_ALLOCATORS(); + UINT32 logLevel = setLogLevel(); #ifndef _WIN32 signal(SIGINT, sigintHandler); #endif - // do trickleIce by default - printf("[KVS Master] Using trickleICE by default\n"); - #ifdef IOT_CORE_ENABLE_CREDENTIALS CHK_ERR((pChannelName = getenv(IOT_CORE_THING_NAME)) != NULL, STATUS_INVALID_OPERATION, "AWS_IOT_CORE_THING_NAME must be set"); #else pChannelName = argc > 1 ? argv[1] : SAMPLE_CHANNEL_NAME; #endif - retStatus = createSampleConfiguration(pChannelName, SIGNALING_CHANNEL_ROLE_TYPE_MASTER, TRUE, TRUE, &pSampleConfiguration); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Master] createSampleConfiguration(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - - printf("[KVS Master] Created signaling channel %s\n", pChannelName); - - if (pSampleConfiguration->enableFileLogging) { - retStatus = - createFileLogger(FILE_LOGGING_BUFFER_SIZE, MAX_NUMBER_OF_LOG_FILES, (PCHAR) FILE_LOGGER_LOG_FILE_DIRECTORY_PATH, TRUE, TRUE, NULL); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Master] createFileLogger(): operation returned status code: 0x%08x \n", retStatus); - pSampleConfiguration->enableFileLogging = FALSE; - } - } + CHK_STATUS(createSampleConfiguration(pChannelName, SIGNALING_CHANNEL_ROLE_TYPE_MASTER, TRUE, TRUE, logLevel, &pSampleConfiguration)); // Set the audio and video handlers pSampleConfiguration->audioSource = sendAudioPackets; @@ -51,79 +32,34 @@ INT32 main(INT32 argc, CHAR* argv[]) pSampleConfiguration->receiveAudioVideoSource = sampleReceiveAudioVideoFrame; pSampleConfiguration->onDataChannel = onDataChannel; pSampleConfiguration->mediaType = SAMPLE_STREAMING_AUDIO_VIDEO; - printf("[KVS Master] Finished setting audio and video handlers\n"); + DLOGI("[KVS Master] Finished setting handlers"); // Check if the samples are present - retStatus = readFrameFromDisk(NULL, &frameSize, "./h264SampleFrames/frame-0001.h264"); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Master] readFrameFromDisk(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - printf("[KVS Master] Checked sample video frame availability....available\n"); + CHK_STATUS(readFrameFromDisk(NULL, &frameSize, "./h264SampleFrames/frame-0001.h264")); + DLOGI("[KVS Master] Checked sample video frame availability....available"); - retStatus = readFrameFromDisk(NULL, &frameSize, "./opusSampleFrames/sample-001.opus"); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Master] readFrameFromDisk(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - printf("[KVS Master] Checked sample audio frame availability....available\n"); + CHK_STATUS(readFrameFromDisk(NULL, &frameSize, "./opusSampleFrames/sample-001.opus")); + DLOGI("[KVS Master] Checked sample audio frame availability....available"); // Initialize KVS WebRTC. This must be done before anything else, and must only be done once. - retStatus = initKvsWebRtc(); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Master] initKvsWebRtc(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - printf("[KVS Master] KVS WebRTC initialization completed successfully\n"); + CHK_STATUS(initKvsWebRtc()); + DLOGI("[KVS Master] KVS WebRTC initialization completed successfully"); - pSampleConfiguration->signalingClientCallbacks.messageReceivedFn = signalingMessageReceived; - - strcpy(pSampleConfiguration->clientInfo.clientId, SAMPLE_MASTER_CLIENT_ID); - - retStatus = createSignalingClientSync(&pSampleConfiguration->clientInfo, &pSampleConfiguration->channelInfo, - &pSampleConfiguration->signalingClientCallbacks, pSampleConfiguration->pCredentialProvider, - &pSampleConfiguration->signalingClientHandle); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Master] createSignalingClientSync(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - printf("[KVS Master] Signaling client created successfully\n"); - - // Enable the processing of the messages - retStatus = signalingClientFetchSync(pSampleConfiguration->signalingClientHandle); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Master] signalingClientFetchSync(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - - retStatus = signalingClientConnectSync(pSampleConfiguration->signalingClientHandle); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Master] signalingClientConnectSync(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - printf("[KVS Master] Signaling client connection to socket established\n"); - - gSampleConfiguration = pSampleConfiguration; - - printf("[KVS Master] Channel %s set up done \n", pChannelName); + CHK_STATUS(initSignaling(pSampleConfiguration, SAMPLE_MASTER_CLIENT_ID)); + DLOGI("[KVS Master] Channel %s set up done ", pChannelName); // Checking for termination - retStatus = sessionCleanupWait(pSampleConfiguration); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Master] sessionCleanupWait(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - - printf("[KVS Master] Streaming session terminated\n"); + CHK_STATUS(sessionCleanupWait(pSampleConfiguration)); + DLOGI("[KVS Master] Streaming session terminated"); CleanUp: if (retStatus != STATUS_SUCCESS) { - printf("[KVS Master] Terminated with status code 0x%08x\n", retStatus); + DLOGE("[KVS Master] Terminated with status code 0x%08x", retStatus); } - printf("[KVS Master] Cleaning up....\n"); + DLOGI("[KVS Master] Cleaning up...."); if (pSampleConfiguration != NULL) { // Kick of the termination sequence ATOMIC_STORE_BOOL(&pSampleConfiguration->appTerminateFlag, TRUE); @@ -132,26 +68,23 @@ INT32 main(INT32 argc, CHAR* argv[]) THREAD_JOIN(pSampleConfiguration->mediaSenderTid, NULL); } - if (pSampleConfiguration->enableFileLogging) { - freeFileLogger(); - } retStatus = signalingClientGetMetrics(pSampleConfiguration->signalingClientHandle, &signalingClientMetrics); if (retStatus == STATUS_SUCCESS) { logSignalingClientStats(&signalingClientMetrics); } else { - printf("[KVS Master] signalingClientGetMetrics() operation returned status code: 0x%08x\n", retStatus); + DLOGE("[KVS Master] signalingClientGetMetrics() operation returned status code: 0x%08x", retStatus); } retStatus = freeSignalingClient(&pSampleConfiguration->signalingClientHandle); if (retStatus != STATUS_SUCCESS) { - printf("[KVS Master] freeSignalingClient(): operation returned status code: 0x%08x", retStatus); + DLOGE("[KVS Master] freeSignalingClient(): operation returned status code: 0x%08x", retStatus); } retStatus = freeSampleConfiguration(&pSampleConfiguration); if (retStatus != STATUS_SUCCESS) { - printf("[KVS Master] freeSampleConfiguration(): operation returned status code: 0x%08x", retStatus); + DLOGE("[KVS Master] freeSampleConfiguration(): operation returned status code: 0x%08x", retStatus); } } - printf("[KVS Master] Cleanup done\n"); + DLOGI("[KVS Master] Cleanup done"); CHK_LOG_ERR(retStatus); RESET_INSTRUMENTED_ALLOCATORS(); @@ -168,21 +101,10 @@ STATUS readFrameFromDisk(PBYTE pFrame, PUINT32 pSize, PCHAR frameFilePath) { STATUS retStatus = STATUS_SUCCESS; UINT64 size = 0; - - if (pSize == NULL) { - printf("[KVS Master] readFrameFromDisk(): operation returned status code: 0x%08x \n", STATUS_NULL_ARG); - goto CleanUp; - } - + CHK_ERR(pSize != NULL, STATUS_NULL_ARG, "[KVS Master] Invalid file size"); size = *pSize; - // Get the size and read into frame - retStatus = readFile(frameFilePath, TRUE, pFrame, &size); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Master] readFile(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - + CHK_STATUS(readFile(frameFilePath, TRUE, pFrame, &size)); CleanUp: if (pSize != NULL) { @@ -204,11 +126,7 @@ PVOID sendVideoPackets(PVOID args) UINT32 i; UINT64 startTime, lastFrameTime, elapsed; MEMSET(&encoderStats, 0x00, SIZEOF(RtcEncoderStats)); - - if (pSampleConfiguration == NULL) { - printf("[KVS Master] sendVideoPackets(): operation returned status code: 0x%08x \n", STATUS_NULL_ARG); - goto CleanUp; - } + CHK_ERR(pSampleConfiguration != NULL, STATUS_NULL_ARG, "[KVS Master] Streaming session is NULL"); frame.presentationTs = 0; startTime = GETTIME(); @@ -216,51 +134,39 @@ PVOID sendVideoPackets(PVOID args) while (!ATOMIC_LOAD_BOOL(&pSampleConfiguration->appTerminateFlag)) { fileIndex = fileIndex % NUMBER_OF_H264_FRAME_FILES + 1; - snprintf(filePath, MAX_PATH_LEN, "./h264SampleFrames/frame-%04d.h264", fileIndex); + SNPRINTF(filePath, MAX_PATH_LEN, "./h264SampleFrames/frame-%04d.h264", fileIndex); - retStatus = readFrameFromDisk(NULL, &frameSize, filePath); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Master] readFrameFromDisk(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } + CHK_STATUS(readFrameFromDisk(NULL, &frameSize, filePath)); // Re-alloc if needed if (frameSize > pSampleConfiguration->videoBufferSize) { pSampleConfiguration->pVideoFrameBuffer = (PBYTE) MEMREALLOC(pSampleConfiguration->pVideoFrameBuffer, frameSize); - if (pSampleConfiguration->pVideoFrameBuffer == NULL) { - printf("[KVS Master] Video frame Buffer reallocation failed...%s (code %d)\n", strerror(errno), errno); - printf("[KVS Master] MEMREALLOC(): operation returned status code: 0x%08x \n", STATUS_NOT_ENOUGH_MEMORY); - goto CleanUp; - } - + CHK_ERR(pSampleConfiguration->pVideoFrameBuffer != NULL, STATUS_NOT_ENOUGH_MEMORY, "[KVS Master] Failed to allocate video frame buffer"); pSampleConfiguration->videoBufferSize = frameSize; } frame.frameData = pSampleConfiguration->pVideoFrameBuffer; frame.size = frameSize; - retStatus = readFrameFromDisk(frame.frameData, &frameSize, filePath); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Master] readFrameFromDisk(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } + CHK_STATUS(readFrameFromDisk(frame.frameData, &frameSize, filePath)); // based on bitrate of samples/h264SampleFrames/frame-* encoderStats.width = 640; encoderStats.height = 480; encoderStats.targetBitrate = 262000; frame.presentationTs += SAMPLE_VIDEO_FRAME_DURATION; - MUTEX_LOCK(pSampleConfiguration->streamingSessionListReadLock); for (i = 0; i < pSampleConfiguration->streamingSessionCount; ++i) { status = writeFrame(pSampleConfiguration->sampleStreamingSessionList[i]->pVideoRtcRtpTransceiver, &frame); + if (pSampleConfiguration->sampleStreamingSessionList[i]->firstFrame && status == STATUS_SUCCESS) { + PROFILE_WITH_START_TIME(pSampleConfiguration->sampleStreamingSessionList[i]->offerReceiveTime, "Time to first frame"); + pSampleConfiguration->sampleStreamingSessionList[i]->firstFrame = FALSE; + } encoderStats.encodeTimeMsec = 4; // update encode time to an arbitrary number to demonstrate stats update updateEncoderStats(pSampleConfiguration->sampleStreamingSessionList[i]->pVideoRtcRtpTransceiver, &encoderStats); if (status != STATUS_SRTP_NOT_READY_YET) { if (status != STATUS_SUCCESS) { -#ifdef VERBOSE - printf("writeFrame() failed with 0x%08x\n", status); -#endif + DLOGV("writeFrame() failed with 0x%08x", status); } } } @@ -276,7 +182,7 @@ PVOID sendVideoPackets(PVOID args) } CleanUp: - printf("[KVS Master] closing video thread"); + DLOGI("[KVS Master] Closing video thread"); CHK_LOG_ERR(retStatus); return (PVOID) (ULONG_PTR) retStatus; @@ -292,42 +198,26 @@ PVOID sendAudioPackets(PVOID args) UINT32 i; STATUS status; - if (pSampleConfiguration == NULL) { - printf("[KVS Master] sendAudioPackets(): operation returned status code: 0x%08x \n", STATUS_NULL_ARG); - goto CleanUp; - } - + CHK_ERR(pSampleConfiguration != NULL, STATUS_NULL_ARG, "[KVS Master] Streaming session is NULL"); frame.presentationTs = 0; while (!ATOMIC_LOAD_BOOL(&pSampleConfiguration->appTerminateFlag)) { fileIndex = fileIndex % NUMBER_OF_OPUS_FRAME_FILES + 1; - snprintf(filePath, MAX_PATH_LEN, "./opusSampleFrames/sample-%03d.opus", fileIndex); + SNPRINTF(filePath, MAX_PATH_LEN, "./opusSampleFrames/sample-%03d.opus", fileIndex); - retStatus = readFrameFromDisk(NULL, &frameSize, filePath); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Master] readFrameFromDisk(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } + CHK_STATUS(readFrameFromDisk(NULL, &frameSize, filePath)); // Re-alloc if needed if (frameSize > pSampleConfiguration->audioBufferSize) { pSampleConfiguration->pAudioFrameBuffer = (UINT8*) MEMREALLOC(pSampleConfiguration->pAudioFrameBuffer, frameSize); - if (pSampleConfiguration->pAudioFrameBuffer == NULL) { - printf("[KVS Master] Audio frame Buffer reallocation failed...%s (code %d)\n", strerror(errno), errno); - printf("[KVS Master] MEMREALLOC(): operation returned status code: 0x%08x \n", STATUS_NOT_ENOUGH_MEMORY); - goto CleanUp; - } + CHK_ERR(pSampleConfiguration->pAudioFrameBuffer != NULL, STATUS_NOT_ENOUGH_MEMORY, "[KVS Master] Failed to allocate audio frame buffer"); pSampleConfiguration->audioBufferSize = frameSize; } frame.frameData = pSampleConfiguration->pAudioFrameBuffer; frame.size = frameSize; - retStatus = readFrameFromDisk(frame.frameData, &frameSize, filePath); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Master] readFrameFromDisk(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } + CHK_STATUS(readFrameFromDisk(frame.frameData, &frameSize, filePath)); frame.presentationTs += SAMPLE_AUDIO_FRAME_DURATION; @@ -336,9 +226,10 @@ PVOID sendAudioPackets(PVOID args) status = writeFrame(pSampleConfiguration->sampleStreamingSessionList[i]->pAudioRtcRtpTransceiver, &frame); if (status != STATUS_SRTP_NOT_READY_YET) { if (status != STATUS_SUCCESS) { -#ifdef VERBOSE - printf("writeFrame() failed with 0x%08x\n", status); -#endif + DLOGV("writeFrame() failed with 0x%08x", status); + } else if (pSampleConfiguration->sampleStreamingSessionList[i]->firstFrame && status == STATUS_SUCCESS) { + PROFILE_WITH_START_TIME(pSampleConfiguration->sampleStreamingSessionList[i]->offerReceiveTime, "Time to first frame"); + pSampleConfiguration->sampleStreamingSessionList[i]->firstFrame = FALSE; } } } @@ -347,7 +238,7 @@ PVOID sendAudioPackets(PVOID args) } CleanUp: - printf("[KVS Master] closing audio thread"); + DLOGI("[KVS Master] closing audio thread"); return (PVOID) (ULONG_PTR) retStatus; } @@ -355,22 +246,9 @@ PVOID sampleReceiveAudioVideoFrame(PVOID args) { STATUS retStatus = STATUS_SUCCESS; PSampleStreamingSession pSampleStreamingSession = (PSampleStreamingSession) args; - if (pSampleStreamingSession == NULL) { - printf("[KVS Master] sampleReceiveAudioVideoFrame(): operation returned status code: 0x%08x \n", STATUS_NULL_ARG); - goto CleanUp; - } - - retStatus = transceiverOnFrame(pSampleStreamingSession->pVideoRtcRtpTransceiver, (UINT64) pSampleStreamingSession, sampleVideoFrameHandler); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Master] transceiverOnFrame(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - - retStatus = transceiverOnFrame(pSampleStreamingSession->pAudioRtcRtpTransceiver, (UINT64) pSampleStreamingSession, sampleAudioFrameHandler); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Master] transceiverOnFrame(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } + CHK_ERR(pSampleStreamingSession != NULL, STATUS_NULL_ARG, "[KVS Master] Streaming session is NULL"); + CHK_STATUS(transceiverOnFrame(pSampleStreamingSession->pVideoRtcRtpTransceiver, (UINT64) pSampleStreamingSession, sampleVideoFrameHandler)); + CHK_STATUS(transceiverOnFrame(pSampleStreamingSession->pAudioRtcRtpTransceiver, (UINT64) pSampleStreamingSession, sampleAudioFrameHandler)); CleanUp: diff --git a/samples/kvsWebRTCClientViewer.c b/samples/kvsWebRTCClientViewer.c index 21fff286b8..7ed9a3c4ba 100644 --- a/samples/kvsWebRTCClientViewer.c +++ b/samples/kvsWebRTCClientViewer.c @@ -12,7 +12,7 @@ VOID dataChannelOnMessageCallback(UINT64 customData, PRtcDataChannel pDataChanne if (isBinary) { DLOGI("DataChannel Binary Message"); } else { - DLOGI("DataChannel String Message: %.*s\n", pMessageLen, pMessage); + DLOGI("DataChannel String Message: %.*s", pMessageLen, pMessage); } } @@ -20,13 +20,13 @@ VOID dataChannelOnMessageCallback(UINT64 customData, PRtcDataChannel pDataChanne VOID dataChannelOnOpenCallback(UINT64 customData, PRtcDataChannel pDataChannel) { STATUS retStatus = STATUS_SUCCESS; - DLOGI("New DataChannel has been opened %s \n", pDataChannel->name); + DLOGI("New DataChannel has been opened %s ", pDataChannel->name); dataChannelOnMessage(pDataChannel, customData, dataChannelOnMessageCallback); ATOMIC_INCREMENT((PSIZE_T) customData); // Sending first message to the master over the data channel retStatus = dataChannelSend(pDataChannel, FALSE, (PBYTE) VIEWER_DATA_CHANNEL_MESSAGE, STRLEN(VIEWER_DATA_CHANNEL_MESSAGE)); if (retStatus != STATUS_SUCCESS) { - DLOGI("[KVS Viewer] dataChannelSend(): operation returned status code: 0x%08x \n", retStatus); + DLOGI("[KVS Viewer] dataChannelSend(): operation returned status code: 0x%08x ", retStatus); } } #endif @@ -41,109 +41,50 @@ INT32 main(INT32 argc, CHAR* argv[]) PSampleStreamingSession pSampleStreamingSession = NULL; BOOL locked = FALSE; PCHAR pChannelName; + CHAR clientId[256]; SET_INSTRUMENTED_ALLOCATORS(); + UINT32 logLevel = setLogLevel(); #ifndef _WIN32 signal(SIGINT, sigintHandler); #endif - // do trickle-ice by default - printf("[KVS Master] Using trickleICE by default\n"); - #ifdef IOT_CORE_ENABLE_CREDENTIALS CHK_ERR((pChannelName = getenv(IOT_CORE_THING_NAME)) != NULL, STATUS_INVALID_OPERATION, "AWS_IOT_CORE_THING_NAME must be set"); #else pChannelName = argc > 1 ? argv[1] : SAMPLE_CHANNEL_NAME; #endif - retStatus = createSampleConfiguration(pChannelName, SIGNALING_CHANNEL_ROLE_TYPE_VIEWER, TRUE, TRUE, &pSampleConfiguration); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Viewer] createSampleConfiguration(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - gSampleConfiguration = pSampleConfiguration; - - printf("[KVS Viewer] Created signaling channel %s\n", pChannelName); - - if (pSampleConfiguration->enableFileLogging) { - retStatus = - createFileLogger(FILE_LOGGING_BUFFER_SIZE, MAX_NUMBER_OF_LOG_FILES, (PCHAR) FILE_LOGGER_LOG_FILE_DIRECTORY_PATH, TRUE, TRUE, NULL); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Master] createFileLogger(): operation returned status code: 0x%08x \n", retStatus); - pSampleConfiguration->enableFileLogging = FALSE; - } - } + CHK_STATUS(createSampleConfiguration(pChannelName, SIGNALING_CHANNEL_ROLE_TYPE_VIEWER, TRUE, TRUE, logLevel, &pSampleConfiguration)); // Initialize KVS WebRTC. This must be done before anything else, and must only be done once. - retStatus = initKvsWebRtc(); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Viewer] initKvsWebRtc(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - - printf("[KVS Viewer] KVS WebRTC initialization completed successfully\n"); - - pSampleConfiguration->signalingClientCallbacks.messageReceivedFn = signalingMessageReceived; + CHK_STATUS(initKvsWebRtc()); + DLOGI("[KVS Viewer] KVS WebRTC initialization completed successfully"); - sprintf(pSampleConfiguration->clientInfo.clientId, "%s_%u", SAMPLE_VIEWER_CLIENT_ID, RAND() % MAX_UINT32); - - retStatus = createSignalingClientSync(&pSampleConfiguration->clientInfo, &pSampleConfiguration->channelInfo, - &pSampleConfiguration->signalingClientCallbacks, pSampleConfiguration->pCredentialProvider, - &pSampleConfiguration->signalingClientHandle); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Viewer] createSignalingClientSync(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - - printf("[KVS Viewer] Signaling client created successfully\n"); - - // Enable the processing of the messages - retStatus = signalingClientFetchSync(pSampleConfiguration->signalingClientHandle); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Master] signalingClientFetchSync(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - - retStatus = signalingClientConnectSync(pSampleConfiguration->signalingClientHandle); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Viewer] signalingClientConnectSync(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - - printf("[KVS Viewer] Signaling client connection to socket established\n"); + SPRINTF(clientId, "%s_%u", SAMPLE_VIEWER_CLIENT_ID, RAND() % MAX_UINT32); + CHK_STATUS(initSignaling(pSampleConfiguration, clientId)); + DLOGI("[KVS Viewer] Signaling client connection established"); // Initialize streaming session MUTEX_LOCK(pSampleConfiguration->sampleConfigurationObjLock); locked = TRUE; - retStatus = createSampleStreamingSession(pSampleConfiguration, NULL, FALSE, &pSampleStreamingSession); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Viewer] createSampleStreamingSession(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - printf("[KVS Viewer] Creating streaming session...completed\n"); + CHK_STATUS(createSampleStreamingSession(pSampleConfiguration, NULL, FALSE, &pSampleStreamingSession)); + DLOGI("[KVS Viewer] Creating streaming session...completed"); pSampleConfiguration->sampleStreamingSessionList[pSampleConfiguration->streamingSessionCount++] = pSampleStreamingSession; MUTEX_UNLOCK(pSampleConfiguration->sampleConfigurationObjLock); locked = FALSE; - memset(&offerSessionDescriptionInit, 0x00, SIZEOF(RtcSessionDescriptionInit)); + MEMSET(&offerSessionDescriptionInit, 0x00, SIZEOF(RtcSessionDescriptionInit)); - retStatus = setLocalDescription(pSampleStreamingSession->pPeerConnection, &offerSessionDescriptionInit); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Viewer] setLocalDescription(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - printf("[KVS Viewer] Completed setting local description\n"); + CHK_STATUS(setLocalDescription(pSampleStreamingSession->pPeerConnection, &offerSessionDescriptionInit)); + DLOGI("[KVS Viewer] Completed setting local description"); - retStatus = transceiverOnFrame(pSampleStreamingSession->pAudioRtcRtpTransceiver, (UINT64) pSampleStreamingSession, sampleAudioFrameHandler); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Viewer] transceiverOnFrame(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } + CHK_STATUS(transceiverOnFrame(pSampleStreamingSession->pAudioRtcRtpTransceiver, (UINT64) pSampleStreamingSession, sampleAudioFrameHandler)); if (!pSampleConfiguration->trickleIce) { - printf("[KVS Viewer] Non trickle ice. Wait for Candidate collection to complete\n"); + DLOGI("[KVS Viewer] Non trickle ice. Wait for Candidate collection to complete"); MUTEX_LOCK(pSampleConfiguration->sampleConfigurationObjLock); locked = TRUE; @@ -156,35 +97,22 @@ INT32 main(INT32 argc, CHAR* argv[]) MUTEX_UNLOCK(pSampleConfiguration->sampleConfigurationObjLock); locked = FALSE; - printf("[KVS Viewer] Candidate collection completed\n"); + DLOGI("[KVS Viewer] Candidate collection completed"); } - retStatus = createOffer(pSampleStreamingSession->pPeerConnection, &offerSessionDescriptionInit); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Viewer] createOffer(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - printf("[KVS Viewer] Offer creation successful\n"); + CHK_STATUS(createOffer(pSampleStreamingSession->pPeerConnection, &offerSessionDescriptionInit)); + DLOGI("[KVS Viewer] Offer creation successful"); + + DLOGI("[KVS Viewer] Generating JSON of session description...."); + CHK_STATUS(serializeSessionDescriptionInit(&offerSessionDescriptionInit, NULL, &buffLen)); - printf("[KVS Viewer] Generating JSON of session description...."); - retStatus = serializeSessionDescriptionInit(&offerSessionDescriptionInit, NULL, &buffLen); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Viewer] serializeSessionDescriptionInit(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } if (buffLen >= SIZEOF(message.payload)) { - printf("[KVS Viewer] serializeSessionDescriptionInit(): operation returned status code: 0x%08x \n", STATUS_INVALID_OPERATION); + DLOGE("[KVS Viewer] serializeSessionDescriptionInit(): operation returned status code: 0x%08x ", STATUS_INVALID_OPERATION); retStatus = STATUS_INVALID_OPERATION; goto CleanUp; } - retStatus = serializeSessionDescriptionInit(&offerSessionDescriptionInit, message.payload, &buffLen); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Viewer] serializeSessionDescriptionInit(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - - printf("Completed\n"); + CHK_STATUS(serializeSessionDescriptionInit(&offerSessionDescriptionInit, message.payload, &buffLen)); message.version = SIGNALING_MESSAGE_CURRENT_VERSION; message.messageType = SIGNALING_MESSAGE_TYPE_OFFER; @@ -192,32 +120,19 @@ INT32 main(INT32 argc, CHAR* argv[]) message.payloadLen = (buffLen / SIZEOF(CHAR)) - 1; message.correlationId[0] = '\0'; - retStatus = signalingClientSendMessageSync(pSampleConfiguration->signalingClientHandle, &message); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Viewer] signalingClientSendMessageSync(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - + CHK_STATUS(signalingClientSendMessageSync(pSampleConfiguration->signalingClientHandle, &message)); #ifdef ENABLE_DATA_CHANNEL PRtcDataChannel pDataChannel = NULL; PRtcPeerConnection pPeerConnection = pSampleStreamingSession->pPeerConnection; SIZE_T datachannelLocalOpenCount = 0; // Creating a new datachannel on the peer connection of the existing sample streaming session - retStatus = createDataChannel(pPeerConnection, pChannelName, NULL, &pDataChannel); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Viewer] createDataChannel(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - printf("[KVS Viewer] Creating data channel...completed\n"); + CHK_STATUS(createDataChannel(pPeerConnection, pChannelName, NULL, &pDataChannel)); + DLOGI("[KVS Viewer] Creating data channel...completed"); // Setting a callback for when the data channel is open - retStatus = dataChannelOnOpen(pDataChannel, (UINT64) &datachannelLocalOpenCount, dataChannelOnOpenCallback); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Viewer] dataChannelOnOpen(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - printf("[KVS Viewer] Data Channel open now...\n"); + CHK_STATUS(dataChannelOnOpen(pDataChannel, (UINT64) &datachannelLocalOpenCount, dataChannelOnOpenCallback)); + DLOGI("[KVS Viewer] Data Channel open now..."); #endif // Block until interrupted @@ -228,10 +143,10 @@ INT32 main(INT32 argc, CHAR* argv[]) CleanUp: if (retStatus != STATUS_SUCCESS) { - printf("[KVS Viewer] Terminated with status code 0x%08x", retStatus); + DLOGE("[KVS Viewer] Terminated with status code 0x%08x", retStatus); } - printf("[KVS Viewer] Cleaning up....\n"); + DLOGI("[KVS Viewer] Cleaning up...."); if (locked) { MUTEX_UNLOCK(pSampleConfiguration->sampleConfigurationObjLock); @@ -243,15 +158,15 @@ INT32 main(INT32 argc, CHAR* argv[]) if (pSampleConfiguration != NULL) { retStatus = freeSignalingClient(&pSampleConfiguration->signalingClientHandle); if (retStatus != STATUS_SUCCESS) { - printf("[KVS Master] freeSignalingClient(): operation returned status code: 0x%08x \n", retStatus); + DLOGE("[KVS Master] freeSignalingClient(): operation returned status code: 0x%08x ", retStatus); } retStatus = freeSampleConfiguration(&pSampleConfiguration); if (retStatus != STATUS_SUCCESS) { - printf("[KVS Master] freeSampleConfiguration(): operation returned status code: 0x%08x \n", retStatus); + DLOGE("[KVS Master] freeSampleConfiguration(): operation returned status code: 0x%08x ", retStatus); } } - printf("[KVS Viewer] Cleanup done\n"); + DLOGI("[KVS Viewer] Cleanup done"); RESET_INSTRUMENTED_ALLOCATORS(); diff --git a/samples/kvsWebrtcClientMasterGstSample.c b/samples/kvsWebrtcClientMasterGstSample.c index a7459c5188..1fac4cd78a 100644 --- a/samples/kvsWebrtcClientMasterGstSample.c +++ b/samples/kvsWebrtcClientMasterGstSample.c @@ -9,6 +9,7 @@ extern PSampleConfiguration gSampleConfiguration; GstFlowReturn on_new_sample(GstElement* sink, gpointer data, UINT64 trackid) { GstBuffer* buffer; + STATUS retStatus = STATUS_SUCCESS; BOOL isDroppable, delta; GstFlowReturn ret = GST_FLOW_OK; GstSample* sample = NULL; @@ -22,10 +23,7 @@ GstFlowReturn on_new_sample(GstElement* sink, gpointer data, UINT64 trackid) PRtcRtpTransceiver pRtcRtpTransceiver = NULL; UINT32 i; - if (pSampleConfiguration == NULL) { - printf("[KVS GStreamer Master] on_new_sample(): operation returned status code: 0x%08x \n", STATUS_NULL_ARG); - goto CleanUp; - } + CHK_ERR(pSampleConfiguration != NULL, STATUS_NULL_ARG, "NULL sample configuration"); info.data = NULL; sample = gst_app_sink_pull_sample(GST_APP_SINK(sink)); @@ -46,11 +44,11 @@ GstFlowReturn on_new_sample(GstElement* sink, gpointer data, UINT64 trackid) segment = gst_sample_get_segment(sample); buf_pts = gst_segment_to_running_time(segment, GST_FORMAT_TIME, buffer->pts); if (!GST_CLOCK_TIME_IS_VALID(buf_pts)) { - printf("[KVS GStreamer Master] Frame contains invalid PTS dropping the frame. \n"); + DLOGE("[KVS GStreamer Master] Frame contains invalid PTS dropping the frame"); } if (!(gst_buffer_map(buffer, &info, GST_MAP_READ))) { - printf("[KVS GStreamer Master] on_new_sample(): Gst buffer mapping failed\n"); + DLOGE("[KVS GStreamer Master] on_new_sample(): Gst buffer mapping failed"); goto CleanUp; } @@ -80,8 +78,11 @@ GstFlowReturn on_new_sample(GstElement* sink, gpointer data, UINT64 trackid) status = writeFrame(pRtcRtpTransceiver, &frame); if (status != STATUS_SRTP_NOT_READY_YET && status != STATUS_SUCCESS) { #ifdef VERBOSE - printf("writeFrame() failed with 0x%08x", status); + DLOGE("writeFrame() failed with 0x%08x", status); #endif + } else if (status == STATUS_SUCCESS && pSampleStreamingSession->firstFrame) { + PROFILE_WITH_START_TIME(pSampleStreamingSession->offerReceiveTime, "Time to first frame"); + pSampleStreamingSession->firstFrame = FALSE; } } MUTEX_UNLOCK(pSampleConfiguration->streamingSessionListReadLock); @@ -123,10 +124,7 @@ PVOID sendGstreamerAudioVideo(PVOID args) GError* error = NULL; PSampleConfiguration pSampleConfiguration = (PSampleConfiguration) args; - if (pSampleConfiguration == NULL) { - printf("[KVS GStreamer Master] sendGstreamerAudioVideo(): operation returned status code: 0x%08x \n", STATUS_NULL_ARG); - goto CleanUp; - } + CHK_ERR(pSampleConfiguration != NULL, STATUS_NULL_ARG, "[KVS Gstreamer Master] Streaming session is NULL"); /** * Use x264enc as its available on mac, pi, ubuntu and windows @@ -239,11 +237,7 @@ PVOID sendGstreamerAudioVideo(PVOID args) break; } - if (pipeline == NULL) { - printf("[KVS GStreamer Master] sendGstreamerAudioVideo(): Failed to launch gstreamer, operation returned status code: 0x%08x \n", - STATUS_INTERNAL_ERROR); - goto CleanUp; - } + CHK_ERR(pipeline != NULL, STATUS_NULL_ARG, "[KVS Gstreamer Master] Pipeline is NULL"); appsinkVideo = gst_bin_get_by_name(GST_BIN(pipeline), "appsink-video"); appsinkAudio = gst_bin_get_by_name(GST_BIN(pipeline), "appsink-audio"); @@ -260,7 +254,6 @@ PVOID sendGstreamerAudioVideo(PVOID args) if (appsinkAudio != NULL) { g_signal_connect(appsinkAudio, "new-sample", G_CALLBACK(on_new_sample_audio), (gpointer) pSampleConfiguration); } - gst_element_set_state(pipeline, GST_STATE_PLAYING); /* block until error or EOS */ @@ -271,16 +264,24 @@ PVOID sendGstreamerAudioVideo(PVOID args) if (msg != NULL) { gst_message_unref(msg); } - gst_object_unref(bus); + if (bus != NULL) { + gst_object_unref(bus); + } gst_element_set_state(pipeline, GST_STATE_NULL); - gst_object_unref(pipeline); - gst_object_unref(appsinkAudio); - gst_object_unref(appsinkVideo); + if (pipeline != NULL) { + gst_object_unref(pipeline); + } + if (appsinkAudio != NULL) { + gst_object_unref(appsinkAudio); + } + if (appsinkVideo != NULL) { + gst_object_unref(appsinkVideo); + } CleanUp: if (error != NULL) { - printf("%s", error->message); + DLOGE("%s", error->message); g_clear_error(&error); } @@ -323,13 +324,9 @@ PVOID receiveGstreamerAudioVideo(PVOID args) PSampleStreamingSession pSampleStreamingSession = (PSampleStreamingSession) args; gchar *videoDescription = "", *audioDescription = "", *audioVideoDescription; - if (pSampleStreamingSession == NULL) { - printf("[KVS GStreamer Master] receiveGstreamerAudioVideo(): operation returned status code: 0x%08x \n", STATUS_NULL_ARG); - goto CleanUp; - } - - // TODO: Wire video up with gstreamer pipeline + CHK_ERR(pSampleStreamingSession != NULL, STATUS_NULL_ARG, "[KVS Gstreamer Master] Sample streaming session is NULL"); + // TODO: For video switch (pSampleStreamingSession->pAudioRtcRtpTransceiver->receiver.track.codec) { case RTC_CODEC_OPUS: audioDescription = "appsrc name=appsrc-audio ! opusparse ! decodebin ! autoaudiosink"; @@ -348,26 +345,14 @@ PVOID receiveGstreamerAudioVideo(PVOID args) pipeline = gst_parse_launch(audioVideoDescription, &error); appsrcAudio = gst_bin_get_by_name(GST_BIN(pipeline), "appsrc-audio"); - if (appsrcAudio == NULL) { - printf("[KVS GStreamer Master] gst_bin_get_by_name(): cant find appsrc, operation returned status code: 0x%08x \n", STATUS_INTERNAL_ERROR); - goto CleanUp; - } + CHK_ERR(appsrcAudio != NULL, STATUS_INTERNAL_ERROR, "[KVS Gstreamer Master] Cannot find appsrc"); - transceiverOnFrame(pSampleStreamingSession->pAudioRtcRtpTransceiver, (UINT64) appsrcAudio, onGstAudioFrameReady); - - retStatus = streamingSessionOnShutdown(pSampleStreamingSession, (UINT64) appsrcAudio, onSampleStreamingSessionShutdown); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS GStreamer Master] streamingSessionOnShutdown(): operation returned status code: 0x%08x \n", STATUS_INTERNAL_ERROR); - goto CleanUp; - } + CHK_STATUS(transceiverOnFrame(pSampleStreamingSession->pAudioRtcRtpTransceiver, (UINT64) appsrcAudio, onGstAudioFrameReady)); + CHK_STATUS(streamingSessionOnShutdown(pSampleStreamingSession, (UINT64) appsrcAudio, onSampleStreamingSessionShutdown)); g_free(audioVideoDescription); - if (pipeline == NULL) { - printf("[KVS GStreamer Master] receiveGstreamerAudioVideo(): Failed to launch gstreamer, operation returned status code: 0x%08x \n", - STATUS_INTERNAL_ERROR); - goto CleanUp; - } + CHK_ERR(pipeline != NULL, STATUS_INTERNAL_ERROR, "[KVS Gstreamer Master] Pipeline is NULL"); gst_element_set_state(pipeline, GST_STATE_PLAYING); @@ -379,14 +364,20 @@ PVOID receiveGstreamerAudioVideo(PVOID args) if (msg != NULL) { gst_message_unref(msg); } - gst_object_unref(bus); - gst_element_set_state(pipeline, GST_STATE_NULL); - gst_object_unref(pipeline); - gst_object_unref(appsrcAudio); + if (bus != NULL) { + gst_object_unref(bus); + } + if (pipeline != NULL) { + gst_element_set_state(pipeline, GST_STATE_NULL); + gst_object_unref(pipeline); + } + if (appsrcAudio != NULL) { + gst_object_unref(appsrcAudio); + } CleanUp: if (error != NULL) { - printf("%s", error->message); + DLOGE("%s", error->message); g_clear_error(&error); } @@ -400,34 +391,17 @@ INT32 main(INT32 argc, CHAR* argv[]) PCHAR pChannelName; SET_INSTRUMENTED_ALLOCATORS(); + UINT32 logLevel = setLogLevel(); signal(SIGINT, sigintHandler); - // do trickle-ice by default - printf("[KVS GStreamer Master] Using trickleICE by default\n"); - #ifdef IOT_CORE_ENABLE_CREDENTIALS CHK_ERR((pChannelName = getenv(IOT_CORE_THING_NAME)) != NULL, STATUS_INVALID_OPERATION, "AWS_IOT_CORE_THING_NAME must be set"); #else pChannelName = argc > 1 ? argv[1] : SAMPLE_CHANNEL_NAME; #endif - retStatus = createSampleConfiguration(pChannelName, SIGNALING_CHANNEL_ROLE_TYPE_MASTER, TRUE, TRUE, &pSampleConfiguration); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS GStreamer Master] createSampleConfiguration(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - - printf("[KVS GStreamer Master] Created signaling channel %s\n", pChannelName); - - if (pSampleConfiguration->enableFileLogging) { - retStatus = - createFileLogger(FILE_LOGGING_BUFFER_SIZE, MAX_NUMBER_OF_LOG_FILES, (PCHAR) FILE_LOGGER_LOG_FILE_DIRECTORY_PATH, TRUE, TRUE, NULL); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Master] createFileLogger(): operation returned status code: 0x%08x \n", retStatus); - pSampleConfiguration->enableFileLogging = FALSE; - } - } + CHK_STATUS(createSampleConfiguration(pChannelName, SIGNALING_CHANNEL_ROLE_TYPE_MASTER, TRUE, TRUE, logLevel, &pSampleConfiguration)); pSampleConfiguration->videoSource = sendGstreamerAudioVideo; pSampleConfiguration->mediaType = SAMPLE_STREAMING_VIDEO_ONLY; @@ -437,101 +411,74 @@ INT32 main(INT32 argc, CHAR* argv[]) pSampleConfiguration->srcType = DEVICE_SOURCE; // Default to device source (autovideosrc and autoaudiosrc) /* Initialize GStreamer */ gst_init(&argc, &argv); - printf("[KVS Gstreamer Master] Finished initializing GStreamer\n"); + DLOGI("[KVS Gstreamer Master] Finished initializing GStreamer and handlers"); if (argc > 2) { if (STRCMP(argv[2], "video-only") == 0) { pSampleConfiguration->mediaType = SAMPLE_STREAMING_VIDEO_ONLY; - printf("[KVS Gstreamer Master] Streaming video only\n"); + DLOGI("[KVS Gstreamer Master] Streaming video only"); } else if (STRCMP(argv[2], "audio-video") == 0) { pSampleConfiguration->mediaType = SAMPLE_STREAMING_AUDIO_VIDEO; - printf("[KVS Gstreamer Master] Streaming audio and video\n"); + DLOGI("[KVS Gstreamer Master] Streaming audio and video"); } else { - printf("[KVS Gstreamer Master] Unrecognized streaming type. Defaulting to video-only\n"); + DLOGI("[KVS Gstreamer Master] Unrecognized streaming type. Default to video-only"); } } else { - printf("[KVS Gstreamer Master] Streaming video only\n"); + DLOGI("[KVS Gstreamer Master] Streaming video only"); } if (argc > 3) { if (STRCMP(argv[3], "testsrc") == 0) { - printf("[KVS GStreamer Master] Using test source in GStreamer\n"); + DLOGI("[KVS GStreamer Master] Using test source in GStreamer"); pSampleConfiguration->srcType = TEST_SOURCE; } else if (STRCMP(argv[3], "devicesrc") == 0) { - printf("[KVS GStreamer Master] Using device source in GStreamer\n"); + DLOGI("[KVS GStreamer Master] Using device source in GStreamer"); pSampleConfiguration->srcType = DEVICE_SOURCE; } else if (STRCMP(argv[3], "rtspsrc") == 0) { - printf("[KVS GStreamer Master] Using RTSP source in GStreamer\n"); + DLOGI("[KVS GStreamer Master] Using RTSP source in GStreamer"); if (argc < 5) { - printf("[KVS GStreamer Master] No RTSP source URI included. Defaulting to device source\n"); + printf("[KVS GStreamer Master] No RTSP source URI included. Defaulting to device source"); printf("[KVS GStreamer Master] Usage: ./kvsWebrtcClientMasterGstSample audio-video rtspsrc rtsp://\n" - "or ./kvsWebrtcClientMasterGstSample video-only rtspsrc \n"); + "or ./kvsWebrtcClientMasterGstSample video-only rtspsrc "); pSampleConfiguration->srcType = DEVICE_SOURCE; } else { pSampleConfiguration->srcType = RTSP_SOURCE; pSampleConfiguration->rtspUri = argv[4]; } } else { - printf("[KVS Gstreamer Master] Unrecognized source type. Defaulting to device source in GStreamer\n"); + DLOGI("[KVS Gstreamer Master] Unrecognized source type. Defaulting to device source in GStreamer"); } } else { printf("[KVS GStreamer Master] Using device source in GStreamer\n"); } - // Initialize KVS WebRTC. This must be done before anything else, and must only be done once. - retStatus = initKvsWebRtc(); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS GStreamer Master] initKvsWebRtc(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - printf("[KVS GStreamer Master] KVS WebRTC initialization completed successfully\n"); - - pSampleConfiguration->signalingClientCallbacks.messageReceivedFn = signalingMessageReceived; - - strcpy(pSampleConfiguration->clientInfo.clientId, SAMPLE_MASTER_CLIENT_ID); - - retStatus = createSignalingClientSync(&pSampleConfiguration->clientInfo, &pSampleConfiguration->channelInfo, - &pSampleConfiguration->signalingClientCallbacks, pSampleConfiguration->pCredentialProvider, - &pSampleConfiguration->signalingClientHandle); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS GStreamer Master] createSignalingClientSync(): operation returned status code: 0x%08x \n", retStatus); - } - printf("[KVS GStreamer Master] Signaling client created successfully\n"); - - // Enable the processing of the messages - retStatus = signalingClientFetchSync(pSampleConfiguration->signalingClientHandle); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS Master] signalingClientFetchSync(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - - retStatus = signalingClientConnectSync(pSampleConfiguration->signalingClientHandle); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS GStreamer Master] signalingClientConnectSync(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; + switch (pSampleConfiguration->mediaType) { + case SAMPLE_STREAMING_VIDEO_ONLY: + DLOGI("[KVS GStreamer Master] streaming type video-only"); + break; + case SAMPLE_STREAMING_AUDIO_VIDEO: + DLOGI("[KVS GStreamer Master] streaming type audio-video"); + break; } - printf("[KVS GStreamer Master] Signaling client connection to socket established\n"); - printf("[KVS Gstreamer Master] Beginning streaming...check the stream over channel %s\n", pChannelName); + // Initalize KVS WebRTC. This must be done before anything else, and must only be done once. + CHK_STATUS(initKvsWebRtc()); + DLOGI("[KVS GStreamer Master] KVS WebRTC initialization completed successfully"); - gSampleConfiguration = pSampleConfiguration; + CHK_STATUS(initSignaling(pSampleConfiguration, SAMPLE_MASTER_CLIENT_ID)); + DLOGI("[KVS GStreamer Master] Channel %s set up done ", pChannelName); // Checking for termination - retStatus = sessionCleanupWait(pSampleConfiguration); - if (retStatus != STATUS_SUCCESS) { - printf("[KVS GStreamer Master] sessionCleanupWait(): operation returned status code: 0x%08x \n", retStatus); - goto CleanUp; - } - - printf("[KVS GStreamer Master] Streaming session terminated\n"); + CHK_STATUS(sessionCleanupWait(pSampleConfiguration)); + DLOGI("[KVS GStreamer Master] Streaming session terminated"); CleanUp: if (retStatus != STATUS_SUCCESS) { - printf("[KVS GStreamer Master] Terminated with status code 0x%08x", retStatus); + DLOGE("[KVS GStreamer Master] Terminated with status code 0x%08x", retStatus); } - printf("[KVS GStreamer Master] Cleaning up....\n"); + DLOGI("[KVS GStreamer Master] Cleaning up...."); if (pSampleConfiguration != NULL) { // Kick of the termination sequence @@ -546,15 +493,15 @@ INT32 main(INT32 argc, CHAR* argv[]) } retStatus = freeSignalingClient(&pSampleConfiguration->signalingClientHandle); if (retStatus != STATUS_SUCCESS) { - printf("[KVS GStreamer Master] freeSignalingClient(): operation returned status code: 0x%08x \n", retStatus); + DLOGE("[KVS GStreamer Master] freeSignalingClient(): operation returned status code: 0x%08x", retStatus); } retStatus = freeSampleConfiguration(&pSampleConfiguration); if (retStatus != STATUS_SUCCESS) { - printf("[KVS GStreamer Master] freeSampleConfiguration(): operation returned status code: 0x%08x \n", retStatus); + DLOGE("[KVS GStreamer Master] freeSampleConfiguration(): operation returned status code: 0x%08x", retStatus); } } - printf("[KVS Gstreamer Master] Cleanup done\n"); + DLOGI("[KVS Gstreamer Master] Cleanup done"); RESET_INSTRUMENTED_ALLOCATORS(); diff --git a/src/include/com/amazonaws/kinesis/video/webrtcclient/Include.h b/src/include/com/amazonaws/kinesis/video/webrtcclient/Include.h index a8177fe126..943a355236 100644 --- a/src/include/com/amazonaws/kinesis/video/webrtcclient/Include.h +++ b/src/include/com/amazonaws/kinesis/video/webrtcclient/Include.h @@ -25,6 +25,33 @@ extern "C" { #pragma clang diagnostic pop #endif +/* TODO: Potentially move these call to PIC instead. Moving to PIC in the future would not cause any backward compatibility issues */ +#define PROFILE_CALL(f, msg) \ + do { \ + startTimeInMacro = GETTIME(); \ + f; \ + DLOGP("[%s] Time taken: %" PRIu64 " ms", (msg), (GETTIME() - startTimeInMacro) / HUNDREDS_OF_NANOS_IN_A_MILLISECOND); \ + } while (FALSE) + +#define PROFILE_CALL_WITH_T_OBJ(f, t, msg) \ + do { \ + startTimeInMacro = GETTIME(); \ + f; \ + t = (GETTIME() - startTimeInMacro) / HUNDREDS_OF_NANOS_IN_A_MILLISECOND; \ + DLOGP("[%s] Time taken: %" PRIu64 " ms", (msg), (t)); \ + } while (FALSE) + +#define PROFILE_WITH_START_TIME(t, msg) \ + do { \ + DLOGP("[%s] Time taken: %" PRIu64 " ms", msg, (GETTIME() - (t)) / HUNDREDS_OF_NANOS_IN_A_MILLISECOND); \ + } while (FALSE) + +#define PROFILE_WITH_START_TIME_OBJ(t1, t2, msg) \ + do { \ + t2 = (GETTIME() - (t1)) / HUNDREDS_OF_NANOS_IN_A_MILLISECOND; \ + DLOGP("[%s] Time taken: %" PRIu64 " ms", (msg), t2); \ + } while (FALSE) + /*! \addtogroup StatusCodes * WEBRTC related status codes. Each value is an positive integer formed by adding * a base integer inticating the category to an index. Users may run scripts/parse_status.py @@ -531,7 +558,17 @@ extern "C" { /** * Version of SignalingClientMetrics structure */ -#define SIGNALING_CLIENT_METRICS_CURRENT_VERSION 0 +#define SIGNALING_CLIENT_METRICS_CURRENT_VERSION 1 + +/** + * Version of PeerConnectionMetrics structure + */ +#define PEER_CONNECTION_METRICS_CURRENT_VERSION 0 + +/** + * Version of KvsIceAgentMetrics structure + */ +#define ICE_AGENT_METRICS_CURRENT_VERSION 0 /*!@} */ @@ -1441,6 +1478,22 @@ typedef struct { SignalingClientStats signalingClientStats; //!< Signaling client metrics stats. Reference in Stats.h } SignalingClientMetrics, *PSignalingClientMetrics; +/** + * @brief KVS ICE Agent Collection of ICE agent related stats. Can be expanded in the future + */ +typedef struct { + UINT32 version; //!< Structure version + KvsIceAgentStats kvsIceAgentStats; //!< ICE agent metrics. Reference in Stats.h +} KvsIceAgentMetrics, *PKvsIceAgentMetrics; + +/** + * @brief SignalingStats Collection of signaling related stats. Can be expanded in the future + */ +typedef struct { + UINT32 version; //!< Structure version + PeerConnectionStats peerConnectionStats; //!< Peer connection metrics stats. Reference in Stats.h +} PeerConnectionMetrics, *PPeerConnectionMetrics; + /** * @brief The stats object is populated based on RTCStatsType request * @@ -2023,6 +2076,22 @@ PUBLIC_API STATUS signalingClientDeleteSync(SIGNALING_CLIENT_HANDLE); */ PUBLIC_API STATUS signalingClientGetMetrics(SIGNALING_CLIENT_HANDLE, PSignalingClientMetrics); +/** + * @brief Get peer connection related metrics + * + * @param[in] PRtcPeerConnection Peer connection object + * @param[in,out] PPeerConnectionMetrics Peer connection stats object + */ +PUBLIC_API STATUS peerConnectionGetMetrics(PRtcPeerConnection, PPeerConnectionMetrics); + +/** + * @brief Get peer connection related metrics + * + * @param[in] PRtcPeerConnection Peer connection object + * @param[in,out] PKvsIceAgentMetrics KVS ICE agent stats object + */ +PUBLIC_API STATUS iceAgentGetMetrics(PRtcPeerConnection, PKvsIceAgentMetrics); + /** * @brief Get the relevant/all metrics based on the RTCStatsType field. This does not include * any signaling related metrics. The caller of the API is expected to populate requestedTypeOfStats diff --git a/src/include/com/amazonaws/kinesis/video/webrtcclient/Stats.h b/src/include/com/amazonaws/kinesis/video/webrtcclient/Stats.h index a8294fd699..39ac7cc438 100644 --- a/src/include/com/amazonaws/kinesis/video/webrtcclient/Stats.h +++ b/src/include/com/amazonaws/kinesis/video/webrtcclient/Stats.h @@ -243,6 +243,21 @@ typedef struct { UINT64 totalRoundTripTime; //!< Sum of RTTs of all the requests for which response has been received } RtcIceServerStats, *PRtcIceServerStats; +/** + * @brief: IceAgent profiling Stats related to the KVS ICE Agent + * + */ +typedef struct { + UINT64 localCandidateGatheringTime; + UINT64 hostCandidateSetUpTime; + UINT64 srflxCandidateSetUpTime; + UINT64 relayCandidateSetUpTime; + UINT64 iceServerParsingTime; + UINT64 iceCandidatePairNominationTime; + UINT64 candidateGatheringTime; + UINT64 iceAgentSetUpTime; +} KvsIceAgentStats, *PKvsIceAgentStats; + /** * @brief: RtcIceCandidateStats Stats related to a specific candidate in a pair * @@ -578,7 +593,26 @@ typedef struct { //!< In all of these cases the error callback (if specified) will be called. UINT32 numberOfReconnects; //!< Number of reconnects in the session UINT32 apiCallRetryCount; //!< Number of retries due to API call failures in the state machine -} SignalingClientStats, PSignalingClientStats; + UINT64 getTokenCallTime; //!< Time (ms) taken to get credentials for signaling + UINT64 describeCallTime; //!< Time (ms) taken to execute describeChannel call + UINT64 createCallTime; //!< Time (ms) taken to execute createChannel call + UINT64 getEndpointCallTime; //!< Time (ms) taken to execute getEndpoint call + UINT64 getIceConfigCallTime; //!< Time (ms) taken to execute getIceServerConfig call + UINT64 connectCallTime; //!< Time (ms) taken to execute connectChannel call + UINT64 createClientTime; //!< Total time (ms) taken to create signaling client which includes getting credentials + UINT64 + fetchClientTime; //!< Total time (ms) taken to fetch signaling client which includes describe, create, get endpoint and get ICE server config + UINT64 connectClientTime; //!< Total time (ms) taken to connect the signaling client which includes connecting to the signaling channel + UINT64 offerToAnswerTime; +} SignalingClientStats, *PSignalingClientStats; + +typedef struct { + UINT64 peerConnectionCreationTime; //!< Time taken (ms) for peer connection object creation time + UINT64 dtlsSessionSetupTime; //!< Time taken (ms) for DTLS handshake to complete + UINT64 iceHolePunchingTime; //!< Time taken (ms) for ICE agent set up to complete + UINT64 closePeerConnectionTime; //!< Time taken (ms) to close the peer connection + UINT64 freePeerConnectionTime; //!< Time taken (ms) to free the peer connection object +} PeerConnectionStats, *PPeerConnectionStats; /** * @brief RTCStatsObject Represents an object passed in by the application developer which will diff --git a/src/source/Crypto/Crypto.c b/src/source/Crypto/Crypto.c index 28ad657ec4..c98ef648dc 100644 --- a/src/source/Crypto/Crypto.c +++ b/src/source/Crypto/Crypto.c @@ -5,6 +5,7 @@ STATUS createRtcCertificate(PRtcCertificate* ppRtcCertificate) { ENTERS(); STATUS retStatus = STATUS_SUCCESS; + UINT64 startTimeInMacro = 0; PRtcCertificate pRtcCertificate = NULL; CHK(ppRtcCertificate != NULL, STATUS_NULL_ARG); @@ -12,16 +13,18 @@ STATUS createRtcCertificate(PRtcCertificate* ppRtcCertificate) CHK(NULL != (pRtcCertificate = (PRtcCertificate) MEMCALLOC(1, SIZEOF(RtcCertificate))), STATUS_NOT_ENOUGH_MEMORY); #ifdef KVS_USE_OPENSSL - CHK_STATUS(createCertificateAndKey(GENERATED_CERTIFICATE_BITS, FALSE, (X509**) &pRtcCertificate->pCertificate, - (EVP_PKEY**) &pRtcCertificate->pPrivateKey)); + PROFILE_CALL(CHK_STATUS(createCertificateAndKey(GENERATED_CERTIFICATE_BITS, FALSE, (X509**) &pRtcCertificate->pCertificate, + (EVP_PKEY**) &pRtcCertificate->pPrivateKey)), + "Certificate creation time"); #elif KVS_USE_MBEDTLS // Need to allocate space for the cert and the key for mbedTLS CHK(NULL != (pRtcCertificate->pCertificate = (PBYTE) MEMCALLOC(1, SIZEOF(mbedtls_x509_crt))), STATUS_NOT_ENOUGH_MEMORY); CHK(NULL != (pRtcCertificate->pPrivateKey = (PBYTE) MEMCALLOC(1, SIZEOF(mbedtls_pk_context))), STATUS_NOT_ENOUGH_MEMORY); pRtcCertificate->certificateSize = SIZEOF(mbedtls_x509_crt); pRtcCertificate->privateKeySize = SIZEOF(mbedtls_pk_context); - CHK_STATUS(createCertificateAndKey(GENERATED_CERTIFICATE_BITS, FALSE, (mbedtls_x509_crt*) pRtcCertificate->pCertificate, - (mbedtls_pk_context*) pRtcCertificate->pPrivateKey)); + PROFILE_CALL(CHK_STATUS(createCertificateAndKey(GENERATED_CERTIFICATE_BITS, FALSE, (mbedtls_x509_crt*) pRtcCertificate->pCertificate, + (mbedtls_pk_context*) pRtcCertificate->pPrivateKey)), + "Certificate creation time"); #else #error "A Crypto implementation is required." #endif diff --git a/src/source/Crypto/Dtls.c b/src/source/Crypto/Dtls.c index 58f557714e..615b2b01fe 100644 --- a/src/source/Crypto/Dtls.c +++ b/src/source/Crypto/Dtls.c @@ -68,8 +68,11 @@ STATUS dtlsSessionChangeState(PDtlsSession pDtlsSession, RTC_DTLS_TRANSPORT_STAT CHK(pDtlsSession->state != newState, retStatus); if (pDtlsSession->state == RTC_DTLS_TRANSPORT_STATE_CONNECTING && newState == RTC_DTLS_TRANSPORT_STATE_CONNECTED) { - DLOGD("DTLS init completed. Time taken %" PRIu64 " ms", - (GETTIME() - pDtlsSession->dtlsSessionStartTime) / HUNDREDS_OF_NANOS_IN_A_MILLISECOND); + // Need to set this so that we do not calculate the time taken again. We set the new state in 2 different places + if (pDtlsSession->dtlsSessionStartTime != 0) { + PROFILE_WITH_START_TIME_OBJ(pDtlsSession->dtlsSessionStartTime, pDtlsSession->dtlsSessionSetupTime, "DTLS initialization completion"); + pDtlsSession->dtlsSessionStartTime = 0; + } } pDtlsSession->state = newState; if (pDtlsSession->dtlsSessionCallbacks.stateChangeFn != NULL) { diff --git a/src/source/Crypto/Dtls.h b/src/source/Crypto/Dtls.h index 434cc5c304..f932a8c37c 100644 --- a/src/source/Crypto/Dtls.h +++ b/src/source/Crypto/Dtls.h @@ -104,6 +104,7 @@ struct __DtlsSession { TIMER_QUEUE_HANDLE timerQueueHandle; UINT32 timerId; UINT64 dtlsSessionStartTime; + UINT64 dtlsSessionSetupTime; RTC_DTLS_TRANSPORT_STATE state; MUTEX sslLock; diff --git a/src/source/Crypto/Dtls_openssl.c b/src/source/Crypto/Dtls_openssl.c index 35137cb504..d1fcb1b788 100644 --- a/src/source/Crypto/Dtls_openssl.c +++ b/src/source/Crypto/Dtls_openssl.c @@ -48,15 +48,15 @@ STATUS dtlsTransmissionTimerCallback(UINT32 timerID, UINT64 currentTime, UINT64 MUTEX_LOCK(pDtlsSession->sslLock); locked = TRUE; - /* In case we need to initiate the handshake */ - CHK_STATUS(dtlsCheckOutgoingDataBuffer(pDtlsSession)); - if (SSL_is_init_finished(pDtlsSession->pSsl)) { CHK_STATUS(dtlsSessionChangeState(pDtlsSession, RTC_DTLS_TRANSPORT_STATE_CONNECTED)); ATOMIC_STORE_BOOL(&pDtlsSession->sslInitFinished, TRUE); CHK(FALSE, STATUS_TIMER_QUEUE_STOP_SCHEDULING); } + /* In case we need to initiate the handshake */ + CHK_STATUS(dtlsCheckOutgoingDataBuffer(pDtlsSession)); + /* https://commondatastorage.googleapis.com/chromium-boringssl-docs/ssl.h.html#DTLSv1_get_timeout */ dtlsTimeoutRet = DTLSv1_get_timeout(pDtlsSession->pSsl, &timeout); if (dtlsTimeoutRet == 0) { @@ -70,7 +70,7 @@ STATUS dtlsTransmissionTimerCallback(UINT32 timerID, UINT64 currentTime, UINT64 (UINT64) timeout.tv_sec * HUNDREDS_OF_NANOS_IN_A_SECOND + (UINT64) timeout.tv_usec * HUNDREDS_OF_NANOS_IN_A_MICROSECOND; if (timeoutValDefaultTimeUnit == 0) { - DLOGD("DTLS handshake timeout event"); + DLOGD("DTLS handshake timeout event, retransmit"); /* Retransmit the packet */ DTLSv1_handle_timeout(pDtlsSession->pSsl); CHK_STATUS(dtlsCheckOutgoingDataBuffer(pDtlsSession)); @@ -81,7 +81,6 @@ STATUS dtlsTransmissionTimerCallback(UINT32 timerID, UINT64 currentTime, UINT64 if (locked) { MUTEX_UNLOCK(pDtlsSession->sslLock); } - return retStatus; } @@ -160,12 +159,16 @@ STATUS createSslCtx(PDtlsSessionCertificateInfo pCertificates, UINT32 certCount, CHK(pCertificates != NULL && ppSslCtx != NULL, STATUS_NULL_ARG); CHK(certCount > 0, STATUS_INTERNAL_ERROR); + // Version less than 1.0.2 #if (OPENSSL_VERSION_NUMBER < 0x10002000L) EC_KEY* ecdh = NULL; #endif + // Version greater than or equal to 1.1.0 #if (OPENSSL_VERSION_NUMBER >= 0x10100000L) pSslCtx = SSL_CTX_new(DTLS_method()); + + // Version greater than or equal to 1.0.1 #elif (OPENSSL_VERSION_NUMBER >= 0x10001000L) pSslCtx = SSL_CTX_new(DTLSv1_method()); #else @@ -174,6 +177,7 @@ STATUS createSslCtx(PDtlsSessionCertificateInfo pCertificates, UINT32 certCount, CHK(pSslCtx != NULL, STATUS_SSL_CTX_CREATION_FAILED); + // Version greater than or equal to 1.0.2 #if (OPENSSL_VERSION_NUMBER >= 0x10002000L) SSL_CTX_set_ecdh_auto(pSslCtx, TRUE); #else @@ -190,7 +194,6 @@ STATUS createSslCtx(PDtlsSessionCertificateInfo pCertificates, UINT32 certCount, } CHK(SSL_CTX_set_cipher_list(pSslCtx, "HIGH:!aNULL:!MD5:!RC4") == 1, STATUS_SSL_CTX_CREATION_FAILED); - *ppSslCtx = pSslCtx; CleanUp: @@ -272,6 +275,7 @@ STATUS createDtlsSession(PDtlsSessionCallbacks pDtlsSessionCallbacks, TIMER_QUEU STATUS retStatus = STATUS_SUCCESS; PDtlsSession pDtlsSession = NULL; UINT32 i, certCount; + UINT64 startTimeInMacro = 0; DtlsSessionCertificateInfo certInfos[MAX_RTCCONFIGURATION_CERTIFICATES]; MEMSET(certInfos, 0x00, SIZEOF(certInfos)); @@ -295,7 +299,8 @@ STATUS createDtlsSession(PDtlsSessionCallbacks pDtlsSessionCallbacks, TIMER_QUEU } if (certCount == 0) { - CHK_STATUS(createCertificateAndKey(certificateBits, generateRSACertificate, &certInfos[0].pCert, &certInfos[0].pKey)); + PROFILE_CALL(CHK_STATUS(createCertificateAndKey(certificateBits, generateRSACertificate, &certInfos[0].pCert, &certInfos[0].pKey)), + "Certificate creation time"); certInfos[0].created = TRUE; pDtlsSession->certificateCount = 1; } else { @@ -456,7 +461,7 @@ STATUS dtlsSessionProcessPacket(PDtlsSession pDtlsSession, PBYTE pData, PINT32 p sslRet = SSL_read(pDtlsSession->pSsl, pData, *pDataLen); if (sslRet == 0 && SSL_get_error(pDtlsSession->pSsl, sslRet) == SSL_ERROR_ZERO_RETURN) { - DLOGD("Detected DTLS close_notify alert"); + DLOGI("Detected DTLS close_notify alert"); isClosed = TRUE; } else if (sslRet <= 0) { LOG_OPENSSL_ERROR("SSL_read"); @@ -575,7 +580,6 @@ STATUS dtlsCheckOutgoingDataBuffer(PDtlsSession pDtlsSession) } CleanUp: - LEAVES(); return retStatus; } @@ -590,9 +594,15 @@ STATUS dtlsSessionIsInitFinished(PDtlsSession pDtlsSession, PBOOL pIsConnected) MUTEX_LOCK(pDtlsSession->sslLock); locked = TRUE; - *pIsConnected = SSL_is_init_finished(pDtlsSession->pSsl); + // The state change happens in the timer callback anyways. But the callback is invoked every + // 200 ms, hence by the time the state change occurs, it could be 200ms later worst case. + // This does not reduce any start up timing, but it helps in getting the accurate DTLS setup time + if (*pIsConnected) { + dtlsSessionChangeState(pDtlsSession, RTC_DTLS_TRANSPORT_STATE_CONNECTED); + } + CleanUp: if (locked) { MUTEX_UNLOCK(pDtlsSession->sslLock); diff --git a/src/source/Ice/IceAgent.c b/src/source/Ice/IceAgent.c old mode 100755 new mode 100644 index 18ed380a0c..700f81b08f --- a/src/source/Ice/IceAgent.c +++ b/src/source/Ice/IceAgent.c @@ -29,6 +29,7 @@ STATUS createIceAgent(PCHAR username, PCHAR password, PIceAgentCallbacks pIceAge STATUS retStatus = STATUS_SUCCESS; PIceAgent pIceAgent = NULL; UINT32 i; + UINT64 startTimeInMacro = 0; CHK(ppIceAgent != NULL && username != NULL && password != NULL && pConnectionListener != NULL, STATUS_NULL_ARG); CHK(STRNLEN(username, MAX_ICE_CONFIG_USER_NAME_LEN + 1) <= MAX_ICE_CONFIG_USER_NAME_LEN && @@ -75,6 +76,7 @@ STATUS createIceAgent(PCHAR username, PCHAR password, PIceAgentCallbacks pIceAge pIceAgent->disconnectionGracePeriodEndTime = INVALID_TIMESTAMP_VALUE; pIceAgent->pConnectionListener = pConnectionListener; pIceAgent->pDataSendingIceCandidatePair = NULL; + pIceAgent->iceAgentState = ICE_AGENT_STATE_NEW; CHK_STATUS(createTransactionIdStore(DEFAULT_MAX_STORED_TRANSACTION_ID_COUNT, &pIceAgent->pStunBindingRequestTransactionIdStore)); pIceAgent->relayCandidateCount = 0; @@ -92,23 +94,28 @@ STATUS createIceAgent(PCHAR username, PCHAR password, PIceAgentCallbacks pIceAge pIceAgent->iceServersCount = 0; for (i = 0; i < MAX_ICE_SERVERS_COUNT; i++) { - if (pRtcConfiguration->iceServers[i].urls[0] != '\0' && - STATUS_SUCCEEDED(parseIceServer(&pIceAgent->iceServers[pIceAgent->iceServersCount], (PCHAR) pRtcConfiguration->iceServers[i].urls, - (PCHAR) pRtcConfiguration->iceServers[i].username, - (PCHAR) pRtcConfiguration->iceServers[i].credential))) { - pIceAgent->rtcIceServerDiagnostics[i].port = (INT32) getInt16(pIceAgent->iceServers[i].ipAddress.port); - switch (pIceAgent->iceServers[pIceAgent->iceServersCount].transport) { - case KVS_SOCKET_PROTOCOL_UDP: - STRCPY(pIceAgent->rtcIceServerDiagnostics[i].protocol, ICE_TRANSPORT_TYPE_UDP); - break; - case KVS_SOCKET_PROTOCOL_TCP: - STRCPY(pIceAgent->rtcIceServerDiagnostics[i].protocol, ICE_TRANSPORT_TYPE_TCP); - break; - default: - MEMSET(pIceAgent->rtcIceServerDiagnostics[i].protocol, 0, SIZEOF(pIceAgent->rtcIceServerDiagnostics[i].protocol)); + if (pRtcConfiguration->iceServers[i].urls[0] != '\0') { + PROFILE_CALL_WITH_T_OBJ( + retStatus = parseIceServer(&pIceAgent->iceServers[pIceAgent->iceServersCount], (PCHAR) pRtcConfiguration->iceServers[i].urls, + (PCHAR) pRtcConfiguration->iceServers[i].username, (PCHAR) pRtcConfiguration->iceServers[i].credential), + pIceAgent->iceAgentProfileDiagnostics.iceServerParsingTime[i], "ICE server parsing"); + if (STATUS_SUCCEEDED(retStatus)) { + pIceAgent->rtcIceServerDiagnostics[i].port = (INT32) getInt16(pIceAgent->iceServers[i].ipAddress.port); + switch (pIceAgent->iceServers[pIceAgent->iceServersCount].transport) { + case KVS_SOCKET_PROTOCOL_UDP: + STRCPY(pIceAgent->rtcIceServerDiagnostics[i].protocol, ICE_TRANSPORT_TYPE_UDP); + break; + case KVS_SOCKET_PROTOCOL_TCP: + STRCPY(pIceAgent->rtcIceServerDiagnostics[i].protocol, ICE_TRANSPORT_TYPE_TCP); + break; + default: + MEMSET(pIceAgent->rtcIceServerDiagnostics[i].protocol, 0, SIZEOF(pIceAgent->rtcIceServerDiagnostics[i].protocol)); + } + STRCPY(pIceAgent->rtcIceServerDiagnostics[i].url, pRtcConfiguration->iceServers[i].urls); + pIceAgent->iceServersCount++; + } else { + DLOGE("Failed to parse ICE servers"); } - STRCPY(pIceAgent->rtcIceServerDiagnostics[i].url, pRtcConfiguration->iceServers[i].urls); - pIceAgent->iceServersCount++; } } @@ -444,8 +451,10 @@ STATUS iceAgentAddRemoteCandidate(PIceAgent pIceAgent, PCHAR pIceCandidateString if (STATUS_FAILED(retStatus) && freeIceCandidateIfFail) { SAFE_MEMFREE(pIceCandidate); } - - CHK_LOG_ERR(retStatus); + // Parsing TCP candidates is not an error, so do not log as error because that is misleading + if (retStatus != STATUS_ICE_CANDIDATE_STRING_IS_TCP) { + CHK_LOG_ERR(retStatus); + } LEAVES(); return retStatus; @@ -508,7 +517,6 @@ STATUS iceAgentInitHostCandidate(PIceAgent pIceAgent) CHK_STATUS(connectionListenerAddConnection(pIceAgent->pConnectionListener, pNewIceCandidate->pSocketConnection)); } } - CHK(localCandidateCount != 0, STATUS_ICE_NO_LOCAL_HOST_CANDIDATE_AVAILABLE); CleanUp: @@ -578,22 +586,29 @@ STATUS iceAgentStartAgent(PIceAgent pIceAgent, PCHAR remoteUsername, PCHAR remot STATUS iceAgentStartGathering(PIceAgent pIceAgent) { STATUS retStatus = STATUS_SUCCESS; + UINT64 startTimeInMacro = 0; CHK(pIceAgent != NULL, STATUS_NULL_ARG); CHK(!ATOMIC_LOAD_BOOL(&pIceAgent->agentStartGathering), retStatus); ATOMIC_STORE_BOOL(&pIceAgent->agentStartGathering, TRUE); - - CHK_STATUS(getLocalhostIpAddresses(pIceAgent->localNetworkInterfaces, &pIceAgent->localNetworkInterfaceCount, - pIceAgent->kvsRtcConfiguration.iceSetInterfaceFilterFunc, pIceAgent->kvsRtcConfiguration.filterCustomData)); + pIceAgent->candidateGatheringStartTime = GETTIME(); // skip gathering host candidate and srflx candidate if relay only if (pIceAgent->iceTransportPolicy != ICE_TRANSPORT_POLICY_RELAY) { - CHK_STATUS(iceAgentInitHostCandidate(pIceAgent)); - CHK_STATUS(iceAgentInitSrflxCandidate(pIceAgent)); + // Skip getting local host candidates if transport policy is relay only + PROFILE_CALL_WITH_T_OBJ(CHK_STATUS(getLocalhostIpAddresses(pIceAgent->localNetworkInterfaces, &pIceAgent->localNetworkInterfaceCount, + pIceAgent->kvsRtcConfiguration.iceSetInterfaceFilterFunc, + pIceAgent->kvsRtcConfiguration.filterCustomData)), + pIceAgent->iceAgentProfileDiagnostics.localCandidateGatheringTime, "Host candidate gathering from local interfaces"); + PROFILE_CALL_WITH_T_OBJ(CHK_STATUS(iceAgentInitHostCandidate(pIceAgent)), pIceAgent->iceAgentProfileDiagnostics.hostCandidateSetUpTime, + "Host candidates setup time"); + PROFILE_CALL_WITH_T_OBJ(CHK_STATUS(iceAgentInitSrflxCandidate(pIceAgent)), pIceAgent->iceAgentProfileDiagnostics.srflxCandidateSetUpTime, + "Srflx candidates setup time"); } - CHK_STATUS(iceAgentInitRelayCandidates(pIceAgent)); + PROFILE_CALL_WITH_T_OBJ(CHK_STATUS(iceAgentInitRelayCandidates(pIceAgent)), pIceAgent->iceAgentProfileDiagnostics.relayCandidateSetUpTime, + "Relay candidates setup time"); // start listening for incoming data CHK_STATUS(connectionListenerStart(pIceAgent->pConnectionListener)); @@ -1053,11 +1068,13 @@ STATUS createIceCandidatePairs(PIceAgent pIceAgent, PIceCandidate pIceCandidate, CHK(pIceCandidatePair != NULL, STATUS_NOT_ENOUGH_MEMORY); if (isRemoteCandidate) { - pIceCandidatePair->local = (PIceCandidate) data; + // Since we pick local candidate list + pIceCandidatePair->local = pCurrentIceCandidate; pIceCandidatePair->remote = pIceCandidate; } else { pIceCandidatePair->local = pIceCandidate; - pIceCandidatePair->remote = (PIceCandidate) data; + // Since we pick remote candidate list + pIceCandidatePair->remote = pCurrentIceCandidate; } pIceCandidatePair->nominated = FALSE; @@ -1252,10 +1269,10 @@ STATUS iceCandidatePairCheckConnection(PStunPacket pStunBindingRequest, PIceAgen transactionIdStoreInsert(pIceCandidatePair->pTransactionIdStore, pStunBindingRequest->header.transactionId); checkSum = COMPUTE_CRC32(pStunBindingRequest->header.transactionId, ARRAY_SIZE(pStunBindingRequest->header.transactionId)); CHK_STATUS(hashTableUpsert(pIceCandidatePair->requestSentTime, checkSum, GETTIME())); + CHK_STATUS(hashTableUpsert(pIceAgent->requestTimestampDiagnostics, checkSum, GETTIME())); if (pIceCandidatePair->local->iceCandidateType == ICE_CANDIDATE_TYPE_RELAYED) { pIceAgent->rtcIceServerDiagnostics[pIceCandidatePair->local->iceServerIndex].totalRequestsSent++; - CHK_STATUS(hashTableUpsert(pIceAgent->requestTimestampDiagnostics, checkSum, GETTIME())); } CHK_STATUS(iceAgentSendStunPacket(pStunBindingRequest, (PBYTE) pIceAgent->remotePassword, @@ -1361,7 +1378,6 @@ STATUS iceAgentSendSrflxCandidateRequest(PIceAgent pIceAgent) PIceServer pIceServer = NULL; PStunPacket pBindingRequest = NULL; UINT64 checkSum = 0; - CHK(pIceAgent != NULL, STATUS_NULL_ARG); // Assume holding pIceAgent->lock @@ -1452,7 +1468,6 @@ STATUS iceAgentCheckCandidatePairConnection(PIceAgent pIceAgent) } CleanUp: - CHK_LOG_ERR(retStatus); if (locked) { @@ -1547,6 +1562,17 @@ STATUS iceAgentGatherCandidateTimerCallback(UINT32 timerId, UINT64 currentTime, CHK_STATUS(createIceCandidatePairs(pIceAgent, pIceCandidate, FALSE)); } } + + // If the candidate has moved to valid state, then we can report it and start creating pairs with + // srflx candidates. + else if (pIceCandidate->state == ICE_CANDIDATE_STATE_VALID && !pIceCandidate->reported) { + newLocalCandidates[newLocalCandidateCount++] = *pIceCandidate; + pIceCandidate->reported = TRUE; + + if (pIceCandidate->iceCandidateType == ICE_CANDIDATE_TYPE_SERVER_REFLEXIVE) { + CHK_STATUS(createIceCandidatePairs(pIceAgent, pIceCandidate, FALSE)); + } + } } /* keep sending binding request if there is still pending srflx candidate */ @@ -1556,27 +1582,11 @@ STATUS iceAgentGatherCandidateTimerCallback(UINT32 timerId, UINT64 currentTime, /* stop scheduling if there is no more pending candidate or if timeout is reached. */ if ((totalCandidateCount > 0 && pendingCandidateCount == 0) || currentTime >= pIceAgent->candidateGatheringEndTime) { - DLOGD("Candidate gathering completed."); + DLOGI("Candidate gathering completed."); stopScheduling = TRUE; pIceAgent->iceCandidateGatheringTimerTask = MAX_UINT32; } - CHK_STATUS(doubleListGetHeadNode(pIceAgent->localCandidates, &pCurNode)); - while (pCurNode != NULL && newLocalCandidateCount < ARRAY_SIZE(newLocalCandidates)) { - CHK_STATUS(doubleListGetNodeData(pCurNode, &data)); - pCurNode = pCurNode->pNext; - pIceCandidate = (PIceCandidate) data; - - if (pIceCandidate->state == ICE_CANDIDATE_STATE_VALID && !pIceCandidate->reported) { - newLocalCandidates[newLocalCandidateCount++] = *pIceCandidate; - pIceCandidate->reported = TRUE; - - if (pIceCandidate->iceCandidateType == ICE_CANDIDATE_TYPE_SERVER_REFLEXIVE) { - CHK_STATUS(createIceCandidatePairs(pIceAgent, pIceCandidate, FALSE)); - } - } - } - MUTEX_UNLOCK(pIceAgent->lock); locked = FALSE; @@ -1588,6 +1598,8 @@ STATUS iceAgentGatherCandidateTimerCallback(UINT32 timerId, UINT64 currentTime, if (stopScheduling) { ATOMIC_STORE_BOOL(&pIceAgent->candidateGatheringFinished, TRUE); + PROFILE_WITH_START_TIME_OBJ(pIceAgent->candidateGatheringStartTime, pIceAgent->iceAgentProfileDiagnostics.candidateGatheringTime, + "Candidate gathering time"); /* notify that candidate gathering is finished. */ if (pIceAgent->iceAgentCallbacks.newLocalCandidateFn != NULL) { pIceAgent->iceAgentCallbacks.newLocalCandidateFn(pIceAgent->iceAgentCallbacks.customData, NULL); @@ -1661,7 +1673,7 @@ STATUS iceAgentInitSrflxCandidate(PIceAgent pIceAgent) PIceCandidate pCandidate = NULL, pNewCandidate = NULL; UINT32 j, srflxCount = 0; BOOL locked = FALSE; - PIceCandidate srflsCandidates[KVS_ICE_MAX_LOCAL_CANDIDATE_COUNT]; + PIceCandidate srflxCandidates[KVS_ICE_MAX_LOCAL_CANDIDATE_COUNT]; CHK(pIceAgent != NULL, STATUS_NULL_ARG); @@ -1697,7 +1709,7 @@ STATUS iceAgentInitSrflxCandidate(PIceAgent pIceAgent) CHK_STATUS(doubleListInsertItemHead(pIceAgent->localCandidates, (UINT64) pNewCandidate)); // Store the pointer so we can start the connection listener outside the locks - srflsCandidates[srflxCount++] = pNewCandidate; + srflxCandidates[srflxCount++] = pNewCandidate; pNewCandidate = NULL; } @@ -1710,15 +1722,21 @@ STATUS iceAgentInitSrflxCandidate(PIceAgent pIceAgent) // Create and start the connection listener outside of the locks for (j = 0; j < srflxCount; j++) { - pCandidate = srflsCandidates[j]; - // open up a new socket at host candidate's ip address for server reflex candidate. - // the new port will be stored in pNewCandidate->ipAddress.port. And the Ip address will later be updated - // with the correct ip address once the STUN response is received. - CHK_STATUS(createSocketConnection(pCandidate->ipAddress.family, KVS_SOCKET_PROTOCOL_UDP, &pCandidate->ipAddress, NULL, (UINT64) pIceAgent, - incomingDataHandler, pIceAgent->kvsRtcConfiguration.sendBufSize, &pCandidate->pSocketConnection)); - ATOMIC_STORE_BOOL(&pCandidate->pSocketConnection->receiveData, TRUE); - // connectionListener will free the pSocketConnection at the end. - CHK_STATUS(connectionListenerAddConnection(pIceAgent->pConnectionListener, pCandidate->pSocketConnection)); + pCandidate = srflxCandidates[j]; + // TODO: IPv6 STUN is not supported at the moment. Remove this check if the support is added in the future + if (IS_IPV4_ADDR(&(pCandidate->ipAddress))) { + // open up a new socket at host candidate's ip address for server reflex candidate. + // the new port will be stored in pNewCandidate->ipAddress.port. And the Ip address will later be updated + // with the correct ip address once the STUN response is received. + CHK_STATUS(createSocketConnection(pCandidate->ipAddress.family, KVS_SOCKET_PROTOCOL_UDP, &pCandidate->ipAddress, NULL, (UINT64) pIceAgent, + incomingDataHandler, pIceAgent->kvsRtcConfiguration.sendBufSize, &pCandidate->pSocketConnection)); + ATOMIC_STORE_BOOL(&pCandidate->pSocketConnection->receiveData, TRUE); + // connectionListener will free the pSocketConnection at the end. + CHK_STATUS(connectionListenerAddConnection(pIceAgent->pConnectionListener, pCandidate->pSocketConnection)); + + } else { + DLOGW("IPv6 candidate detected, ignoring...."); + } } CleanUp: @@ -2134,9 +2152,11 @@ STATUS iceAgentReadyStateSetup(PIceAgent pIceAgent) pIceAgent->pDataSendingIceCandidatePair = pNominatedAndValidCandidatePair; CHK_STATUS(getIpAddrStr(&pIceAgent->pDataSendingIceCandidatePair->local->ipAddress, ipAddrStr, ARRAY_SIZE(ipAddrStr))); - DLOGD("Selected pair %s_%s, local candidate type: %s. Round trip time %u ms. Local candidate priority: %u, ice candidate pair priority: %" PRIu64, + DLOGP("Selected pair %s_%s, local candidate type: %s. remote candidate type: %s. Round trip time %u ms. Local candidate priority: %u, ice " + "candidate pair priority: %" PRIu64, pIceAgent->pDataSendingIceCandidatePair->local->id, pIceAgent->pDataSendingIceCandidatePair->remote->id, iceAgentGetCandidateTypeStr(pIceAgent->pDataSendingIceCandidatePair->local->iceCandidateType), + iceAgentGetCandidateTypeStr(pIceAgent->pDataSendingIceCandidatePair->remote->iceCandidateType), pIceAgent->pDataSendingIceCandidatePair->roundTripTime / HUNDREDS_OF_NANOS_IN_A_MILLISECOND, pIceAgent->pDataSendingIceCandidatePair->local->priority, pIceAgent->pDataSendingIceCandidatePair->priority); @@ -2411,6 +2431,7 @@ STATUS handleStunPacket(PIceAgent pIceAgent, PBYTE pBuffer, UINT32 bufferLen, PS UINT64 connectivityCheckRequestsReceived = 0; UINT64 connectivityCheckResponsesSent = 0; UINT64 connectivityCheckResponsesReceived = 0; + UINT32 count = 0; // need to determine stunPacketType before deserializing because different password should be used depending on the packet type stunPacketType = (UINT16) getInt16(*((PUINT16) pBuffer)); @@ -2474,14 +2495,12 @@ STATUS handleStunPacket(PIceAgent pIceAgent, PBYTE pBuffer, UINT32 bufferLen, PS // Update round trip time for serial reflexive candidate pIceAgent->rtcIceServerDiagnostics[pIceCandidate->iceServerIndex].totalResponsesReceived++; - retStatus = hashTableGet(pIceAgent->requestTimestampDiagnostics, checkSum, &requestSentTime); - if (retStatus != STATUS_SUCCESS) { - DLOGW("Unable to fetch request Timestamp from the hash table. No update to totalRoundTripTime (error code: 0x%08x), " - "stunBindingRequest", - retStatus); - } else { + // Transaction ID count be same for candidates coming from same interface, which means there would only + // be one entry. It is not necessary to update a return sttaus since it is not indicative of a failure + if ((hashTableGet(pIceAgent->requestTimestampDiagnostics, checkSum, &requestSentTime)) == STATUS_SUCCESS) { pIceAgent->rtcIceServerDiagnostics[pIceCandidate->iceServerIndex].totalRoundTripTime += GETTIME() - requestSentTime; CHK_STATUS(hashTableRemove(pIceAgent->requestTimestampDiagnostics, checkSum)); + hashTableGetCount(pIceAgent->requestTimestampDiagnostics, &count); } CHK_STATUS(deserializeStunPacket(pBuffer, bufferLen, NULL, 0, &pStunPacket)); @@ -2507,13 +2526,12 @@ STATUS handleStunPacket(PIceAgent pIceAgent, PBYTE pBuffer, UINT32 bufferLen, PS ipAddrStr2, ipAddrStr); } DLOGV("Pair binding response! %s %s", pIceCandidatePair->local->id, pIceCandidatePair->remote->id); - retStatus = hashTableGet(pIceCandidatePair->requestSentTime, checkSum, &requestSentTime); - if (retStatus != STATUS_SUCCESS) { - DLOGW("Unable to fetch request Timestamp from the hash table. No update to RTT for the pair (error code: 0x%08x)", retStatus); - } else { + if (hashTableGet(pIceCandidatePair->requestSentTime, checkSum, &requestSentTime) == STATUS_SUCCESS) { pIceCandidatePair->roundTripTime = GETTIME() - requestSentTime; pIceCandidatePair->rtcIceCandidatePairDiagnostics.currentRoundTripTime = (DOUBLE) (pIceCandidatePair->roundTripTime) / HUNDREDS_OF_NANOS_IN_A_SECOND; + } else { + DLOGW("Unable to fetch request Timestamp from the hash table. No update to RTT for the pair (error code: 0x%08x)", retStatus); } CHK_WARN(transactionIdStoreHasId(pIceCandidatePair->pTransactionIdStore, pBuffer + STUN_PACKET_TRANSACTION_ID_OFFSET), retStatus, "Dropping response packet because transaction id does not match"); @@ -2522,10 +2540,7 @@ STATUS handleStunPacket(PIceAgent pIceAgent, PBYTE pBuffer, UINT32 bufferLen, PS if (pIceCandidatePair->local->iceCandidateType == ICE_CANDIDATE_TYPE_RELAYED) { pIceAgent->rtcIceServerDiagnostics[pIceCandidatePair->local->iceServerIndex].totalResponsesReceived++; retStatus = hashTableGet(pIceAgent->requestTimestampDiagnostics, checkSum, &requestSentTime); - if (retStatus != STATUS_SUCCESS) { - DLOGW("Unable to fetch request Timestamp from the hash table. No update to totalRoundTripTime (error code: 0x%08x), typeRelayed", - retStatus); - } else { + if (hashTableGet(pIceAgent->requestTimestampDiagnostics, checkSum, &requestSentTime) == STATUS_SUCCESS) { pIceAgent->rtcIceServerDiagnostics[pIceCandidatePair->local->iceServerIndex].totalRoundTripTime += GETTIME() - requestSentTime; CHK_STATUS(hashTableRemove(pIceAgent->requestTimestampDiagnostics, checkSum)); } @@ -2552,14 +2567,10 @@ STATUS handleStunPacket(PIceAgent pIceAgent, PBYTE pBuffer, UINT32 bufferLen, PS } if (pIceCandidatePair->state != ICE_CANDIDATE_PAIR_STATE_SUCCEEDED) { - DLOGV("Pair succeeded! %s %s", pIceCandidatePair->local->id, pIceCandidatePair->remote->id); + DLOGD("Pair succeeded! %s %s", pIceCandidatePair->local->id, pIceCandidatePair->remote->id); pIceCandidatePair->state = ICE_CANDIDATE_PAIR_STATE_SUCCEEDED; retStatus = hashTableGet(pIceCandidatePair->requestSentTime, checkSum, &requestSentTime); - if (retStatus != STATUS_SUCCESS) { - DLOGW( - "Unable to fetch request Timestamp from the hash table. No update to totalRoundTripTime (error code: 0x%08x), stateSucceeded", - retStatus); - } else { + if (hashTableGet(pIceCandidatePair->requestSentTime, checkSum, &requestSentTime) == STATUS_SUCCESS) { pIceCandidatePair->roundTripTime = GETTIME() - requestSentTime; DLOGD("Ice candidate pair %s_%s is connected. Round trip time: %" PRIu64 "ms", pIceCandidatePair->local->id, pIceCandidatePair->remote->id, pIceCandidatePair->roundTripTime / HUNDREDS_OF_NANOS_IN_A_MILLISECOND); @@ -2567,6 +2578,8 @@ STATUS handleStunPacket(PIceAgent pIceAgent, PBYTE pBuffer, UINT32 bufferLen, PS (DOUBLE) (pIceCandidatePair->roundTripTime) / HUNDREDS_OF_NANOS_IN_A_SECOND; CHK_STATUS(hashTableRemove(pIceCandidatePair->requestSentTime, checkSum)); + } else { + DLOGW("Unable to fetch request Timestamp from the hash table. No update to RTT for the pair (error code: 0x%08x)", retStatus); } } @@ -2770,6 +2783,7 @@ UINT64 computeCandidatePairPriority(PIceCandidatePair pIceCandidatePair, BOOL is UINT64 controllingAgentCandidatePri = pIceCandidatePair->local->priority; UINT64 controlledAgentCandidatePri = pIceCandidatePair->remote->priority; + // Swap if SDK is used as master peer if (!isLocalControlling) { controllingAgentCandidatePri = controlledAgentCandidatePri; controlledAgentCandidatePri = pIceCandidatePair->local->priority; @@ -2800,3 +2814,22 @@ UINT64 iceAgentGetCurrentTime(UINT64 customData) UNUSED_PARAM(customData); return GETTIME(); } + +STATUS getIceAgentStats(PIceAgent pIceAgent, PKvsIceAgentMetrics pKvsIceAgentMetrics) +{ + STATUS retStatus = STATUS_SUCCESS; + UINT32 i = 0; + CHK(pIceAgent != NULL && pKvsIceAgentMetrics != NULL, STATUS_NULL_ARG); + pKvsIceAgentMetrics->kvsIceAgentStats.localCandidateGatheringTime = pIceAgent->iceAgentProfileDiagnostics.localCandidateGatheringTime; + pKvsIceAgentMetrics->kvsIceAgentStats.hostCandidateSetUpTime = pIceAgent->iceAgentProfileDiagnostics.hostCandidateSetUpTime; + pKvsIceAgentMetrics->kvsIceAgentStats.srflxCandidateSetUpTime = pIceAgent->iceAgentProfileDiagnostics.srflxCandidateSetUpTime; + pKvsIceAgentMetrics->kvsIceAgentStats.relayCandidateSetUpTime = pIceAgent->iceAgentProfileDiagnostics.relayCandidateSetUpTime; + for (i = 0; i < MAX_ICE_SERVERS_COUNT; i++) { + pKvsIceAgentMetrics->kvsIceAgentStats.iceServerParsingTime += pIceAgent->iceAgentProfileDiagnostics.iceServerParsingTime[i]; + } + pKvsIceAgentMetrics->kvsIceAgentStats.iceCandidatePairNominationTime = pIceAgent->iceAgentProfileDiagnostics.iceCandidatePairNominationTime; + pKvsIceAgentMetrics->kvsIceAgentStats.candidateGatheringTime = pIceAgent->iceAgentProfileDiagnostics.candidateGatheringTime; + pKvsIceAgentMetrics->kvsIceAgentStats.iceAgentSetUpTime = pIceAgent->iceAgentProfileDiagnostics.iceAgentSetUpTime; +CleanUp: + return retStatus; +} diff --git a/src/source/Ice/IceAgent.h b/src/source/Ice/IceAgent.h index 0b02b87848..5d0d9e4933 100644 --- a/src/source/Ice/IceAgent.h +++ b/src/source/Ice/IceAgent.h @@ -178,6 +178,17 @@ typedef struct { RtcIceCandidatePairDiagnostics rtcIceCandidatePairDiagnostics; } IceCandidatePair, *PIceCandidatePair; +typedef struct { + UINT64 localCandidateGatheringTime; + UINT64 hostCandidateSetUpTime; + UINT64 srflxCandidateSetUpTime; + UINT64 relayCandidateSetUpTime; + UINT64 iceServerParsingTime[MAX_ICE_SERVERS_COUNT]; + UINT64 iceCandidatePairNominationTime; + UINT64 candidateGatheringTime; + UINT64 iceAgentSetUpTime; +} IceAgentProfileDiagnostics, *PIceAgentProfileDiagnostics; + struct __IceAgent { volatile ATOMIC_BOOL agentStartGathering; volatile ATOMIC_BOOL remoteCredentialReceived; @@ -195,6 +206,7 @@ struct __IceAgent { RtcIceServerDiagnostics rtcIceServerDiagnostics[MAX_ICE_SERVERS_COUNT]; RtcIceCandidateDiagnostics rtcSelectedLocalIceCandidateDiagnostics; RtcIceCandidateDiagnostics rtcSelectedRemoteIceCandidateDiagnostics; + IceAgentProfileDiagnostics iceAgentProfileDiagnostics; PHashTable requestTimestampDiagnostics; @@ -250,6 +262,9 @@ struct __IceAgent { // store transaction ids for stun binding request. PTransactionIdStore pStunBindingRequestTransactionIdStore; + + UINT64 candidateGatheringStartTime; + UINT64 iceAgentStartTime; }; ////////////////////////////////////////////// @@ -430,6 +445,8 @@ UINT64 computeCandidatePairPriority(PIceCandidatePair, BOOL); PCHAR iceAgentGetCandidateTypeStr(ICE_CANDIDATE_TYPE); STATUS updateSelectedLocalRemoteCandidateStats(PIceAgent); +STATUS getIceAgentStats(PIceAgent, PKvsIceAgentMetrics); + #ifdef __cplusplus } #endif diff --git a/src/source/Ice/IceAgentStateMachine.c b/src/source/Ice/IceAgentStateMachine.c index b9c2c293fa..54b48a7980 100644 --- a/src/source/Ice/IceAgentStateMachine.c +++ b/src/source/Ice/IceAgentStateMachine.c @@ -48,7 +48,7 @@ STATUS stepIceAgentStateMachine(PIceAgent pIceAgent) if (oldState != pIceAgent->iceAgentState) { if (pIceAgent->iceAgentCallbacks.connectionStateChangedFn != NULL) { - DLOGD("Ice agent state changed from %s to %s.", iceAgentStateToString(oldState), iceAgentStateToString(pIceAgent->iceAgentState)); + DLOGI("Ice agent state changed from %s to %s.", iceAgentStateToString(oldState), iceAgentStateToString(pIceAgent->iceAgentState)); pIceAgent->iceAgentCallbacks.connectionStateChangedFn(pIceAgent->iceAgentCallbacks.customData, pIceAgent->iceAgentState); } } else { @@ -286,6 +286,10 @@ STATUS executeCheckConnectionIceAgentState(UINT64 customData, UINT64 time) retStatus = STATUS_SUCCESS; } + if (pIceAgent->iceAgentStartTime == 0) { + pIceAgent->iceAgentStartTime = GETTIME(); + } + LEAVES(); return retStatus; } @@ -427,6 +431,7 @@ STATUS executeNominatingIceAgentState(UINT64 customData, UINT64 time) UNUSED_PARAM(time); STATUS retStatus = STATUS_SUCCESS; PIceAgent pIceAgent = (PIceAgent) customData; + UINT64 startTimeInMacro = 0; CHK(pIceAgent != NULL, STATUS_NULL_ARG); @@ -436,7 +441,8 @@ STATUS executeNominatingIceAgentState(UINT64 customData, UINT64 time) } if (pIceAgent->isControlling) { - CHK_STATUS(iceAgentSendCandidateNomination(pIceAgent)); + PROFILE_CALL_WITH_T_OBJ(CHK_STATUS(iceAgentSendCandidateNomination(pIceAgent)), + pIceAgent->iceAgentProfileDiagnostics.iceCandidatePairNominationTime, "ICE candidate pair nomination"); } else { // if not controlling, keep sending connection checks and wait for peer // to nominate a pair. @@ -524,7 +530,6 @@ STATUS executeReadyIceAgentState(UINT64 customData, UINT64 time) PIceAgent pIceAgent = (PIceAgent) customData; CHK(pIceAgent != NULL, STATUS_NULL_ARG); - if (pIceAgent->iceAgentState != ICE_AGENT_STATE_READY) { CHK_STATUS(iceAgentReadyStateSetup(pIceAgent)); pIceAgent->iceAgentState = ICE_AGENT_STATE_READY; @@ -539,6 +544,12 @@ STATUS executeReadyIceAgentState(UINT64 customData, UINT64 time) retStatus = STATUS_SUCCESS; } + if (pIceAgent->iceAgentStartTime != 0) { + PROFILE_WITH_START_TIME_OBJ(pIceAgent->iceAgentStartTime, pIceAgent->iceAgentProfileDiagnostics.iceAgentSetUpTime, + "Time taken to get ICE Agent ready for media exchange"); + pIceAgent->iceAgentStartTime = 0; + } + LEAVES(); return retStatus; } diff --git a/src/source/Ice/Network.c b/src/source/Ice/Network.c index 77e5a009b3..8656f15dfc 100644 --- a/src/source/Ice/Network.c +++ b/src/source/Ice/Network.c @@ -90,7 +90,7 @@ STATUS getLocalhostIpAddresses(PKvsIpAddress destIpList, PUINT32 pDestIpListLen, destIpList[ipCount].isPointToPoint = ((ifa->ifa_flags & IFF_POINTOPOINT) != 0); if (filter != NULL) { - // The callback evaluates to a FALSE if the application is interested in black listing an interface + // The callback evaluates to a FALSE if the application is interested in disallowing an interface if (filter(customData, ifa->ifa_name) == FALSE) { filterSet = FALSE; } else { @@ -110,7 +110,7 @@ STATUS getLocalhostIpAddresses(PKvsIpAddress destIpList, PUINT32 pDestIpListLen, destIpList[ipCount].family = KVS_IP_FAMILY_TYPE_IPV6; destIpList[ipCount].port = 0; pIpv6Addr = (struct sockaddr_in6*) ifa->ifa_addr; - // Ignore unspecified addres: the other peer can't use this address + // Ignore unspecified address: the other peer can't use this address // Ignore link local: not very useful and will add work unnecessarily // Ignore site local: https://tools.ietf.org/html/rfc8445#section-5.1.1.1 if (IN6_IS_ADDR_UNSPECIFIED(&pIpv6Addr->sin6_addr) || IN6_IS_ADDR_LINKLOCAL(&pIpv6Addr->sin6_addr) || @@ -405,6 +405,7 @@ STATUS getIpWithHostName(PCHAR hostname, PKvsIpAddress destIp) CHAR addressResolved[KVS_IP_ADDRESS_STRING_BUFFER_LEN + 1] = {'\0'}; CHK(hostname != NULL, STATUS_NULL_ARG); + DLOGI("ICE SERVER Hostname received: %s", hostname); hostnameLen = STRLEN(hostname); addrLen = SIZEOF(addr); @@ -442,11 +443,11 @@ STATUS getIpWithHostName(PCHAR hostname, PKvsIpAddress destIp) freeaddrinfo(res); CHK_ERR(resolved, STATUS_HOSTNAME_NOT_FOUND, "Could not find network address of %s", hostname); getIpAddrStr(destIp, addressResolved, ARRAY_SIZE(addressResolved)); - DLOGI("ICE Server address for %s with getaddrinfo: %s", hostname, addressResolved); + DLOGP("ICE Server address for %s with getaddrinfo: %s", hostname, addressResolved); } else { - DLOGI("ICE Server address for %s: %s", hostname, addr); + DLOGP("ICE Server address for %s: %s", hostname, addr); inet_pton(AF_INET, addr, &inaddr); destIp->family = KVS_IP_FAMILY_TYPE_IPV4; MEMCPY(destIp->address, &inaddr, IPV4_ADDRESS_LENGTH); diff --git a/src/source/Ice/SocketConnection.c b/src/source/Ice/SocketConnection.c index 67680db5a5..4b1b0ec7c8 100644 --- a/src/source/Ice/SocketConnection.c +++ b/src/source/Ice/SocketConnection.c @@ -130,8 +130,7 @@ VOID socketConnectionTlsSessionOnStateChange(UINT64 customData, TLS_SESSION_STAT break; case TLS_SESSION_STATE_CONNECTED: if (IS_VALID_TIMESTAMP(pSocketConnection->tlsHandshakeStartTime)) { - DLOGD("TLS handshake done. Time taken %" PRIu64 " ms", - (GETTIME() - pSocketConnection->tlsHandshakeStartTime) / HUNDREDS_OF_NANOS_IN_A_MILLISECOND); + PROFILE_WITH_START_TIME(pSocketConnection->tlsHandshakeStartTime, "TLS handshake time"); pSocketConnection->tlsHandshakeStartTime = INVALID_TIMESTAMP_VALUE; } break; @@ -186,7 +185,7 @@ STATUS socketConnectionSendData(PSocketConnection pSocketConnection, PBYTE pBuf, // Using a single CHK_WARN might output too much spew in bad network conditions if (ATOMIC_LOAD_BOOL(&pSocketConnection->connectionClosed)) { - DLOGD("Warning: Failed to send data. Socket closed already"); + DLOGW("Warning: Failed to send data. Socket closed already"); CHK(FALSE, STATUS_SOCKET_CONNECTION_CLOSED_ALREADY); } @@ -365,16 +364,16 @@ STATUS socketSendDataWithRetry(PSocketConnection pSocketConnection, PBYTE buf, U if (result == 0) { /* loop back and try again */ - DLOGD("poll() timed out"); + DLOGE("poll() timed out"); } else if (result < 0) { - DLOGD("poll() failed with errno %s", getErrorString(getErrorCode())); + DLOGE("poll() failed with errno %s", getErrorString(getErrorCode())); break; } } else if (errorNum == EINTR) { /* nothing need to be done, just retry */ } else { /* fatal error from send() */ - DLOGD("sendto() failed with errno %s", getErrorString(errorNum)); + DLOGE("sendto() failed with errno %s", getErrorString(errorNum)); break; } diff --git a/src/source/Ice/TurnConnection.c b/src/source/Ice/TurnConnection.c index 32f7fe1c76..86a75ed7b1 100644 --- a/src/source/Ice/TurnConnection.c +++ b/src/source/Ice/TurnConnection.c @@ -923,7 +923,6 @@ STATUS turnConnectionStepState(PTurnConnection pTurnConnection) } else { CHK(currentTime < pTurnConnection->stateTimeoutTime, STATUS_TURN_CONNECTION_STATE_TRANSITION_TIMEOUT); } - break; // fallthrough here, missing break intended case TURN_STATE_GET_CREDENTIALS: @@ -1064,7 +1063,6 @@ STATUS turnConnectionStepState(PTurnConnection pTurnConnection) (UINT32) ATOMIC_LOAD(&pTurnConnection->timerCallbackId), pTurnConnection->currentTimerCallingPeriod)); } - break; case TURN_STATE_CLEAN_UP: diff --git a/src/source/PeerConnection/PeerConnection.c b/src/source/PeerConnection/PeerConnection.c index 836f1157f4..5da590b125 100644 --- a/src/source/PeerConnection/PeerConnection.c +++ b/src/source/PeerConnection/PeerConnection.c @@ -268,6 +268,22 @@ STATUS changePeerConnectionState(PKvsPeerConnection pKvsPeerConnection, RTC_PEER MUTEX_LOCK(pKvsPeerConnection->peerConnectionObjLock); locked = TRUE; + switch (newState) { + case RTC_PEER_CONNECTION_STATE_CONNECTING: + if (pKvsPeerConnection->iceConnectingStartTime == 0) { + pKvsPeerConnection->iceConnectingStartTime = GETTIME(); + } + break; + case RTC_PEER_CONNECTION_STATE_CONNECTED: + if (pKvsPeerConnection->iceConnectingStartTime != 0) { + PROFILE_WITH_START_TIME_OBJ(pKvsPeerConnection->iceConnectingStartTime, + pKvsPeerConnection->peerConnectionDiagnostics.iceHolePunchingTime, "ICE Hole Punching Time"); + pKvsPeerConnection->iceConnectingStartTime = 0; + } + break; + default: + break; + } /* new and closed state are terminal*/ CHK(pKvsPeerConnection->connectionState != newState && pKvsPeerConnection->connectionState != RTC_PEER_CONNECTION_STATE_FAILED && @@ -423,7 +439,6 @@ VOID onIceConnectionStateChange(UINT64 customData, UINT64 connectionState) if (startDtlsSession) { CHK_STATUS(dtlsSessionIsInitFinished(pKvsPeerConnection->pDtlsSession, &dtlsConnected)); - if (dtlsConnected) { // In ICE restart scenario, DTLS handshake is not going to be reset. Therefore, we need to check // if the DTLS state has been connected. @@ -574,6 +589,9 @@ VOID onDtlsStateChange(UINT64 customData, RTC_DTLS_TRANSPORT_STATE newDtlsState) pKvsPeerConnection = (PKvsPeerConnection) customData; switch (newDtlsState) { + case RTC_DTLS_TRANSPORT_STATE_CONNECTED: + pKvsPeerConnection->peerConnectionDiagnostics.dtlsSessionSetupTime = pKvsPeerConnection->pDtlsSession->dtlsSessionSetupTime; + break; case RTC_DTLS_TRANSPORT_STATE_CLOSED: changePeerConnectionState(pKvsPeerConnection, RTC_PEER_CONNECTION_STATE_CLOSED); break; @@ -677,9 +695,11 @@ STATUS createPeerConnection(PRtcConfiguration pConfiguration, PRtcPeerConnection IceAgentCallbacks iceAgentCallbacks; DtlsSessionCallbacks dtlsSessionCallbacks; PConnectionListener pConnectionListener = NULL; + UINT64 startTime = 0; CHK(pConfiguration != NULL && ppPeerConnection != NULL, STATUS_NULL_ARG); + startTime = GETTIME(); MEMSET(&iceAgentCallbacks, 0, SIZEOF(IceAgentCallbacks)); MEMSET(&dtlsSessionCallbacks, 0, SIZEOF(DtlsSessionCallbacks)); @@ -738,6 +758,9 @@ STATUS createPeerConnection(PRtcConfiguration pConfiguration, PRtcPeerConnection if (STATUS_FAILED(retStatus)) { freePeerConnection((PRtcPeerConnection*) &pKvsPeerConnection); + } else { + PROFILE_WITH_START_TIME_OBJ(startTime, pKvsPeerConnection->peerConnectionDiagnostics.peerConnectionCreationTime, + "Peer connection object creation time"); } LEAVES(); @@ -761,6 +784,7 @@ STATUS freePeerConnection(PRtcPeerConnection* ppPeerConnection) PKvsPeerConnection pKvsPeerConnection; PDoubleListNode pCurNode = NULL; UINT64 item = 0; + UINT64 startTime; CHK(ppPeerConnection != NULL, STATUS_NULL_ARG); @@ -768,6 +792,7 @@ STATUS freePeerConnection(PRtcPeerConnection* ppPeerConnection) CHK(pKvsPeerConnection != NULL, retStatus); + startTime = GETTIME(); /* Shutdown IceAgent first so there is no more incoming packets which can cause * SCTP to be allocated again after SCTP is freed. */ CHK_LOG_ERR(iceAgentShutdown(pKvsPeerConnection->pIceAgent)); @@ -835,8 +860,8 @@ STATUS freePeerConnection(PRtcPeerConnection* ppPeerConnection) SAFE_MEMFREE(pKvsPeerConnection->pTwccManager); } + PROFILE_WITH_START_TIME_OBJ(startTime, pKvsPeerConnection->peerConnectionDiagnostics.freePeerConnectionTime, "Free peer connection"); SAFE_MEMFREE(*ppPeerConnection); - CleanUp: LEAVES(); @@ -1047,6 +1072,9 @@ STATUS setRemoteDescription(PRtcPeerConnection pPeerConnection, PRtcSessionDescr STRNCPY(pKvsPeerConnection->remoteCertificateFingerprint, pSessionDescription->sdpAttributes[i].attributeValue + 8, CERTIFICATE_FINGERPRINT_LENGTH); } else if (pKvsPeerConnection->isOffer && STRCMP(pSessionDescription->sdpAttributes[i].attributeName, "setup") == 0) { + // possible values are actpass, passive and active. If the incoming SDP has active, it indicates it is taking up a client role + // In case of actpass and passive, the other peer is taking up a server role and is waiting for incoming connection + // Reference: https://www.rfc-editor.org/rfc/rfc4572#section-6.2 pKvsPeerConnection->dtlsIsServer = STRCMP(pSessionDescription->sdpAttributes[i].attributeValue, "active") == 0; } else if (STRCMP(pSessionDescription->sdpAttributes[i].attributeName, "ice-options") == 0 && STRSTR(pSessionDescription->sdpAttributes[i].attributeValue, "trickle") != NULL) { @@ -1096,12 +1124,14 @@ STATUS setRemoteDescription(PRtcPeerConnection pPeerConnection, PRtcSessionDescr CHK_STATUS(generateJSONSafeString(pKvsPeerConnection->localIceUfrag, LOCAL_ICE_UFRAG_LEN)); CHK_STATUS(generateJSONSafeString(pKvsPeerConnection->localIcePwd, LOCAL_ICE_PWD_LEN)); CHK_STATUS(iceAgentRestart(pKvsPeerConnection->pIceAgent, pKvsPeerConnection->localIceUfrag, pKvsPeerConnection->localIcePwd)); + // This starts the gathering process timer callback that periodically checks for local candidate list CHK_STATUS(iceAgentStartGathering(pKvsPeerConnection->pIceAgent)); } STRNCPY(pKvsPeerConnection->remoteIceUfrag, remoteIceUfrag, MAX_ICE_UFRAG_LEN); STRNCPY(pKvsPeerConnection->remoteIcePwd, remoteIcePwd, MAX_ICE_PWD_LEN); + // This starts the state machine timer callback that transitions states periodically CHK_STATUS(iceAgentStartAgent(pKvsPeerConnection->pIceAgent, pKvsPeerConnection->remoteIceUfrag, pKvsPeerConnection->remoteIcePwd, pKvsPeerConnection->isOffer)); @@ -1347,10 +1377,11 @@ STATUS closePeerConnection(PRtcPeerConnection pPeerConnection) ENTERS(); STATUS retStatus = STATUS_SUCCESS; PKvsPeerConnection pKvsPeerConnection = (PKvsPeerConnection) pPeerConnection; - + UINT64 startTime = GETTIME(); CHK(pKvsPeerConnection != NULL, STATUS_NULL_ARG); CHK_LOG_ERR(dtlsSessionShutdown(pKvsPeerConnection->pDtlsSession)); CHK_LOG_ERR(iceAgentShutdown(pKvsPeerConnection->pIceAgent)); + PROFILE_WITH_START_TIME_OBJ(startTime, pKvsPeerConnection->peerConnectionDiagnostics.closePeerConnectionTime, "Close peer connection"); CleanUp: @@ -1360,7 +1391,7 @@ STATUS closePeerConnection(PRtcPeerConnection pPeerConnection) return retStatus; } -PUBLIC_API NullableBool canTrickleIceCandidates(PRtcPeerConnection pPeerConnection) +NullableBool canTrickleIceCandidates(PRtcPeerConnection pPeerConnection) { NullableBool canTrickle = {FALSE, FALSE}; PKvsPeerConnection pKvsPeerConnection = (PKvsPeerConnection) pPeerConnection; @@ -1472,3 +1503,37 @@ STATUS twccManagerOnPacketSent(PKvsPeerConnection pc, PRtpPacket pRtpPacket) LEAVES(); return retStatus; } + +STATUS peerConnectionGetMetrics(PRtcPeerConnection pPeerConnection, PPeerConnectionMetrics pPeerConnectionMetrics) +{ + STATUS retStatus = STATUS_SUCCESS; + PKvsPeerConnection pKvsPeerConnection = (PKvsPeerConnection) pPeerConnection; + CHK(pKvsPeerConnection != NULL && pPeerConnectionMetrics != NULL, STATUS_NULL_ARG); + if (pPeerConnectionMetrics->version > PEER_CONNECTION_METRICS_CURRENT_VERSION) { + DLOGW("Peer connection metrics object version invalid..setting to highest default version %d", PEER_CONNECTION_METRICS_CURRENT_VERSION); + pPeerConnectionMetrics->version = PEER_CONNECTION_METRICS_CURRENT_VERSION; + } + pPeerConnectionMetrics->peerConnectionStats.peerConnectionCreationTime = pKvsPeerConnection->peerConnectionDiagnostics.peerConnectionCreationTime; + pPeerConnectionMetrics->peerConnectionStats.dtlsSessionSetupTime = pKvsPeerConnection->peerConnectionDiagnostics.dtlsSessionSetupTime; + pPeerConnectionMetrics->peerConnectionStats.iceHolePunchingTime = pKvsPeerConnection->peerConnectionDiagnostics.iceHolePunchingTime; + // Cannot record these 2 in here because peer connection object would become NULL after clearing. Need another strategy + pPeerConnectionMetrics->peerConnectionStats.closePeerConnectionTime = pKvsPeerConnection->peerConnectionDiagnostics.closePeerConnectionTime; + pPeerConnectionMetrics->peerConnectionStats.freePeerConnectionTime = pKvsPeerConnection->peerConnectionDiagnostics.freePeerConnectionTime; +CleanUp: + return retStatus; +} + +STATUS iceAgentGetMetrics(PRtcPeerConnection pPeerConnection, PKvsIceAgentMetrics pKvsIceAgentMetrics) +{ + STATUS retStatus = STATUS_SUCCESS; + PKvsPeerConnection pKvsPeerConnection = (PKvsPeerConnection) pPeerConnection; + CHK(pKvsPeerConnection != NULL && pKvsIceAgentMetrics != NULL, STATUS_NULL_ARG); + + if (pKvsIceAgentMetrics->version > ICE_AGENT_METRICS_CURRENT_VERSION) { + DLOGW("ICE agent metrics object version invalid..setting to highest default version %d", PEER_CONNECTION_METRICS_CURRENT_VERSION); + pKvsIceAgentMetrics->version = ICE_AGENT_METRICS_CURRENT_VERSION; + } + CHK_STATUS(getIceAgentStats(pKvsPeerConnection->pIceAgent, pKvsIceAgentMetrics)); +CleanUp: + return retStatus; +} diff --git a/src/source/PeerConnection/PeerConnection.h b/src/source/PeerConnection/PeerConnection.h index 238cc96c2f..67cfe713d8 100644 --- a/src/source/PeerConnection/PeerConnection.h +++ b/src/source/PeerConnection/PeerConnection.h @@ -57,6 +57,14 @@ typedef struct { UINT16 lastReportedSeqNum; } TwccManager, *PTwccManager; +typedef struct { + UINT64 peerConnectionCreationTime; + UINT64 dtlsSessionSetupTime; + UINT64 iceHolePunchingTime; + UINT64 closePeerConnectionTime; + UINT64 freePeerConnectionTime; +} KvsPeerConnectionDiagnostics, *PKvsPeerConnectionDiagnostics; + typedef struct { RtcPeerConnection peerConnection; // UINT32 padding padding makes transportWideSequenceNumber 64bit aligned @@ -131,6 +139,9 @@ typedef struct { PTwccManager pTwccManager; RtcOnSenderBandwidthEstimation onSenderBandwidthEstimation; UINT64 onSenderBandwidthEstimationCustomData; + + UINT64 iceConnectingStartTime; + KvsPeerConnectionDiagnostics peerConnectionDiagnostics; } KvsPeerConnection, *PKvsPeerConnection; typedef struct { diff --git a/src/source/PeerConnection/SessionDescription.c b/src/source/PeerConnection/SessionDescription.c old mode 100755 new mode 100644 diff --git a/src/source/Signaling/Client.c b/src/source/Signaling/Client.c index 7e54682918..425edcabf0 100644 --- a/src/source/Signaling/Client.c +++ b/src/source/Signaling/Client.c @@ -62,8 +62,9 @@ STATUS createSignalingClientSync(PSignalingClientInfo pClientInfo, PChannelInfo KvsRetryStrategy createSignalingClientRetryStrategy = {NULL, NULL, KVS_RETRY_STRATEGY_DISABLED}; INT32 signalingClientCreationMaxRetryCount; UINT64 signalingClientCreationWaitTime; + UINT64 startTime = 0; - DLOGV("Creating Signaling Client Sync"); + DLOGI("Creating Signaling Client Sync"); CHK(pSignalingHandle != NULL && pClientInfo != NULL, STATUS_NULL_ARG); // Convert the client info to the internal structure with empty values @@ -77,6 +78,7 @@ STATUS createSignalingClientSync(PSignalingClientInfo pClientInfo, PChannelInfo } else { signalingClientCreationMaxRetryCount = pClientInfo->signalingClientCreationMaxRetryAttempts; } + startTime = GETTIME(); while (TRUE) { retStatus = createSignalingSync(&signalingClientInfoInternal, pChannelInfo, pCallbacks, pCredentialProvider, &pSignalingClient); // NOTE: This will retry on all status codes except SUCCESS. @@ -105,11 +107,11 @@ STATUS createSignalingClientSync(PSignalingClientInfo pClientInfo, PChannelInfo } CleanUp: - if (STATUS_FAILED(retStatus)) { DLOGE("Create signaling client API failed with return code [0x%08x]", retStatus); freeSignaling(&pSignalingClient); } else { + PROFILE_WITH_START_TIME_OBJ(startTime, pSignalingClient->diagnostics.createClientTime, "Create signaling client"); *pSignalingHandle = TO_SIGNALING_CLIENT_HANDLE(pSignalingClient); } @@ -164,10 +166,12 @@ STATUS signalingClientConnectSync(SIGNALING_CLIENT_HANDLE signalingClientHandle) ENTERS(); STATUS retStatus = STATUS_SUCCESS; PSignalingClient pSignalingClient = FROM_SIGNALING_CLIENT_HANDLE(signalingClientHandle); + UINT64 startTimeInMacro = 0; DLOGV("Signaling Client Connect Sync"); - CHK_STATUS(signalingConnectSync(pSignalingClient)); + PROFILE_CALL_WITH_T_OBJ(CHK_STATUS(signalingConnectSync(pSignalingClient)), pSignalingClient->diagnostics.connectClientTime, + "Connect signaling client"); CleanUp: @@ -185,8 +189,9 @@ STATUS signalingClientFetchSync(SIGNALING_CLIENT_HANDLE signalingClientHandle) KvsRetryStrategy createSignalingClientRetryStrategy = {NULL, NULL, KVS_RETRY_STRATEGY_DISABLED}; INT32 signalingClientCreationMaxRetryCount; UINT64 signalingClientCreationWaitTime; + UINT64 startTime = 0; - DLOGV("Signaling Client Fetch Sync"); + DLOGI("Signaling Client Fetch Sync"); CHK(pSignalingClient != NULL, STATUS_NULL_ARG); // Convert the client info to the internal structure with empty values @@ -199,7 +204,7 @@ STATUS signalingClientFetchSync(SIGNALING_CLIENT_HANDLE signalingClientHandle) if (signalingClientCreationMaxRetryCount == CREATE_SIGNALING_CLIENT_RETRY_ATTEMPTS_SENTINEL_VALUE) { signalingClientCreationMaxRetryCount = DEFAULT_CREATE_SIGNALING_CLIENT_RETRY_ATTEMPTS; } - + startTime = GETTIME(); while (TRUE) { retStatus = signalingFetchSync(pSignalingClient); // NOTE: This will retry on all status codes except SUCCESS. @@ -233,6 +238,7 @@ STATUS signalingClientFetchSync(SIGNALING_CLIENT_HANDLE signalingClientHandle) SIGNALING_UPDATE_ERROR_COUNT(pSignalingClient, retStatus); if (pSignalingClient != NULL) { freeRetryStrategyForCreatingSignalingClient(&pSignalingClient->clientInfo.signalingClientInfo, &createSignalingClientRetryStrategy); + PROFILE_WITH_START_TIME_OBJ(startTime, pSignalingClient->diagnostics.fetchClientTime, "Fetch signaling client"); } LEAVES(); return retStatus; @@ -406,13 +412,15 @@ STATUS signalingClientGetMetrics(SIGNALING_CLIENT_HANDLE signalingClientHandle, ENTERS(); STATUS retStatus = STATUS_SUCCESS; PSignalingClient pSignalingClient = FROM_SIGNALING_CLIENT_HANDLE(signalingClientHandle); - + CHK(pSignalingClient != NULL, STATUS_NULL_ARG); DLOGV("Signaling Client Get Metrics"); CHK_STATUS(signalingGetMetrics(pSignalingClient, pSignalingClientMetrics)); CleanUp: - SIGNALING_UPDATE_ERROR_COUNT(pSignalingClient, retStatus); + if (pSignalingClient != NULL) { + SIGNALING_UPDATE_ERROR_COUNT(pSignalingClient, retStatus); + } LEAVES(); return retStatus; } diff --git a/src/source/Signaling/LwsApiCalls.c b/src/source/Signaling/LwsApiCalls.c index 44ee3771c7..76d195fa35 100644 --- a/src/source/Signaling/LwsApiCalls.c +++ b/src/source/Signaling/LwsApiCalls.c @@ -2159,9 +2159,12 @@ PVOID receiveLwsMessageWrapper(PVOID args) STATUS retStatus = STATUS_SUCCESS; PSignalingMessageWrapper pSignalingMessageWrapper = (PSignalingMessageWrapper) args; PSignalingClient pSignalingClient = NULL; + SIGNALING_MESSAGE_TYPE messageType = SIGNALING_MESSAGE_TYPE_UNKNOWN; CHK(pSignalingMessageWrapper != NULL, STATUS_NULL_ARG); + messageType = pSignalingMessageWrapper->receivedSignalingMessage.signalingMessage.messageType; + pSignalingClient = pSignalingMessageWrapper->pSignalingClient; CHK(pSignalingClient != NULL, STATUS_INTERNAL_ERROR); @@ -2171,6 +2174,12 @@ PVOID receiveLwsMessageWrapper(PVOID args) // Calling client receive message callback if specified if (pSignalingClient->signalingClientCallbacks.messageReceivedFn != NULL) { + if (messageType == SIGNALING_MESSAGE_TYPE_OFFER) { + pSignalingClient->offerTime = GETTIME(); + } + if (messageType == SIGNALING_MESSAGE_TYPE_ANSWER) { + PROFILE_WITH_START_TIME_OBJ(pSignalingClient->offerTime, pSignalingClient->diagnostics.offerToAnswerTime, "Offer to answer time"); + } CHK_STATUS(pSignalingClient->signalingClientCallbacks.messageReceivedFn(pSignalingClient->signalingClientCallbacks.customData, &pSignalingMessageWrapper->receivedSignalingMessage)); } diff --git a/src/source/Signaling/Signaling.c b/src/source/Signaling/Signaling.c index 2dcbf3022d..c1fdd662d1 100644 --- a/src/source/Signaling/Signaling.c +++ b/src/source/Signaling/Signaling.c @@ -388,7 +388,12 @@ STATUS signalingSendMessageSync(PSignalingClient pSignalingClient, PSignalingMes // Perform the call CHK_STATUS(sendLwsMessage(pSignalingClient, pSignalingMessage->messageType, pSignalingMessage->peerClientId, pSignalingMessage->payload, pSignalingMessage->payloadLen, pSignalingMessage->correlationId, 0)); - + if (pSignalingMessage->messageType == SIGNALING_MESSAGE_TYPE_ANSWER) { + PROFILE_WITH_START_TIME_OBJ(pSignalingClient->offerTime, pSignalingClient->diagnostics.offerToAnswerTime, "Offer to answer time"); + } + if (pSignalingMessage->messageType == SIGNALING_MESSAGE_TYPE_OFFER) { + pSignalingClient->offerTime = GETTIME(); + } // Update the internal diagnostics only after successfully sending ATOMIC_INCREMENT(&pSignalingClient->diagnostics.numberOfMessagesSent); @@ -701,7 +706,7 @@ STATUS refreshIceConfiguration(PSignalingClient pSignalingClient) // Force the state machine to revert back to get ICE configuration without re-connection ATOMIC_STORE(&pSignalingClient->result, (SIZE_T) SERVICE_CALL_RESULT_SIGNALING_RECONNECT_ICE); ATOMIC_STORE(&pSignalingClient->refreshIceConfig, TRUE); - + DLOGI("Retrieving ICE config through getIceServerConfig call again"); // Iterate the state machinery in steady states only - ready or connected if (pStateMachineState->state == SIGNALING_STATE_READY || pStateMachineState->state == SIGNALING_STATE_CONNECTED) { CHK_STATUS(signalingStateMachineIterator(pSignalingClient, curTime + SIGNALING_REFRESH_ICE_CONFIG_STATE_TIMEOUT, pStateMachineState->state)); @@ -951,6 +956,7 @@ STATUS describeChannel(PSignalingClient pSignalingClient, UINT64 time) // Call DescribeChannel API if (STATUS_SUCCEEDED(retStatus)) { if (apiCall) { + DLOGI("Calling because call is uncached"); // Call pre hook func if (pSignalingClient->clientInfo.describePreHookFn != NULL) { retStatus = pSignalingClient->clientInfo.describePreHookFn(pSignalingClient->clientInfo.hookCustomData); @@ -1246,26 +1252,48 @@ STATUS signalingGetMetrics(PSignalingClient pSignalingClient, PSignalingClientMe curTime = SIGNALING_GET_CURRENT_TIME(pSignalingClient); CHK(pSignalingClient != NULL && pSignalingClientMetrics != NULL, STATUS_NULL_ARG); - CHK(pSignalingClientMetrics->version <= SIGNALING_CLIENT_METRICS_CURRENT_VERSION, STATUS_SIGNALING_INVALID_METRICS_VERSION); + + if (pSignalingClientMetrics->version > SIGNALING_CLIENT_METRICS_CURRENT_VERSION) { + DLOGW("Invalid signaling client metrics version...setting to highest supported by default version %d", + SIGNALING_CLIENT_METRICS_CURRENT_VERSION); + pSignalingClientMetrics->version = SIGNALING_CLIENT_METRICS_CURRENT_VERSION; + } // Interlock the threading due to data race possibility MUTEX_LOCK(pSignalingClient->diagnosticsLock); - // Fill in the data structures according to the version of the requested structure - currently only v0 - pSignalingClientMetrics->signalingClientStats.signalingClientUptime = curTime - pSignalingClient->diagnostics.createTime; - pSignalingClientMetrics->signalingClientStats.numberOfMessagesSent = (UINT32) pSignalingClient->diagnostics.numberOfMessagesSent; - pSignalingClientMetrics->signalingClientStats.numberOfMessagesReceived = (UINT32) pSignalingClient->diagnostics.numberOfMessagesReceived; - pSignalingClientMetrics->signalingClientStats.iceRefreshCount = (UINT32) pSignalingClient->diagnostics.iceRefreshCount; - pSignalingClientMetrics->signalingClientStats.numberOfErrors = (UINT32) pSignalingClient->diagnostics.numberOfErrors; - pSignalingClientMetrics->signalingClientStats.numberOfRuntimeErrors = (UINT32) pSignalingClient->diagnostics.numberOfRuntimeErrors; - pSignalingClientMetrics->signalingClientStats.numberOfReconnects = (UINT32) pSignalingClient->diagnostics.numberOfReconnects; - pSignalingClientMetrics->signalingClientStats.cpApiCallLatency = pSignalingClient->diagnostics.cpApiLatency; - pSignalingClientMetrics->signalingClientStats.dpApiCallLatency = pSignalingClient->diagnostics.dpApiLatency; - - pSignalingClientMetrics->signalingClientStats.connectionDuration = - ATOMIC_LOAD_BOOL(&pSignalingClient->connected) ? curTime - pSignalingClient->diagnostics.connectTime : 0; - pSignalingClientMetrics->signalingClientStats.apiCallRetryCount = pSignalingClient->diagnostics.stateMachineRetryCount; + MEMSET(&pSignalingClientMetrics->signalingClientStats, 0x00, SIZEOF(pSignalingClientMetrics->signalingClientStats)); + switch (pSignalingClientMetrics->version) { + case 1: + pSignalingClientMetrics->signalingClientStats.getTokenCallTime = pSignalingClient->diagnostics.getTokenCallTime; + pSignalingClientMetrics->signalingClientStats.describeCallTime = pSignalingClient->diagnostics.describeCallTime; + pSignalingClientMetrics->signalingClientStats.createCallTime = pSignalingClient->diagnostics.createCallTime; + pSignalingClientMetrics->signalingClientStats.getEndpointCallTime = pSignalingClient->diagnostics.getEndpointCallTime; + pSignalingClientMetrics->signalingClientStats.getIceConfigCallTime = pSignalingClient->diagnostics.getIceConfigCallTime; + pSignalingClientMetrics->signalingClientStats.connectCallTime = pSignalingClient->diagnostics.connectCallTime; + pSignalingClientMetrics->signalingClientStats.createClientTime = pSignalingClient->diagnostics.createClientTime; + pSignalingClientMetrics->signalingClientStats.fetchClientTime = pSignalingClient->diagnostics.fetchClientTime; + pSignalingClientMetrics->signalingClientStats.connectClientTime = pSignalingClient->diagnostics.connectClientTime; + pSignalingClientMetrics->signalingClientStats.offerToAnswerTime = pSignalingClient->diagnostics.offerToAnswerTime; + case 0: + // Fill in the data structures according to the version of the requested structure + pSignalingClientMetrics->signalingClientStats.signalingClientUptime = curTime - pSignalingClient->diagnostics.createTime; + pSignalingClientMetrics->signalingClientStats.numberOfMessagesSent = (UINT32) pSignalingClient->diagnostics.numberOfMessagesSent; + pSignalingClientMetrics->signalingClientStats.numberOfMessagesReceived = (UINT32) pSignalingClient->diagnostics.numberOfMessagesReceived; + pSignalingClientMetrics->signalingClientStats.iceRefreshCount = (UINT32) pSignalingClient->diagnostics.iceRefreshCount; + pSignalingClientMetrics->signalingClientStats.numberOfErrors = (UINT32) pSignalingClient->diagnostics.numberOfErrors; + pSignalingClientMetrics->signalingClientStats.numberOfRuntimeErrors = (UINT32) pSignalingClient->diagnostics.numberOfRuntimeErrors; + pSignalingClientMetrics->signalingClientStats.numberOfReconnects = (UINT32) pSignalingClient->diagnostics.numberOfReconnects; + pSignalingClientMetrics->signalingClientStats.cpApiCallLatency = pSignalingClient->diagnostics.cpApiLatency; + pSignalingClientMetrics->signalingClientStats.dpApiCallLatency = pSignalingClient->diagnostics.dpApiLatency; + + pSignalingClientMetrics->signalingClientStats.connectionDuration = + ATOMIC_LOAD_BOOL(&pSignalingClient->connected) ? curTime - pSignalingClient->diagnostics.connectTime : 0; + pSignalingClientMetrics->signalingClientStats.apiCallRetryCount = pSignalingClient->diagnostics.stateMachineRetryCount; + default: + break; + } MUTEX_UNLOCK(pSignalingClient->diagnosticsLock); CleanUp: diff --git a/src/source/Signaling/Signaling.h b/src/source/Signaling/Signaling.h index fe432db9c0..0355be4bac 100644 --- a/src/source/Signaling/Signaling.h +++ b/src/source/Signaling/Signaling.h @@ -180,6 +180,16 @@ typedef struct { UINT64 connectTime; UINT64 cpApiLatency; UINT64 dpApiLatency; + UINT64 getTokenCallTime; + UINT64 describeCallTime; + UINT64 createCallTime; + UINT64 getEndpointCallTime; + UINT64 getIceConfigCallTime; + UINT64 connectCallTime; + UINT64 createClientTime; + UINT64 fetchClientTime; + UINT64 connectClientTime; + UINT64 offerToAnswerTime; PHashTable pEndpointToClockSkewHashMap; UINT32 stateMachineRetryCount; } SignalingDiagnostics, PSignalingDiagnostics; @@ -332,6 +342,7 @@ typedef struct { #ifdef KVS_USE_SIGNALING_CHANNEL_THREADPOOL PThreadpool pThreadpool; #endif + UINT64 offerTime; } SignalingClient, *PSignalingClient; // Public handle to and from object converters diff --git a/src/source/Signaling/StateMachine.c b/src/source/Signaling/StateMachine.c index 47a49e993a..44462f2af7 100644 --- a/src/source/Signaling/StateMachine.c +++ b/src/source/Signaling/StateMachine.c @@ -309,6 +309,7 @@ STATUS executeGetTokenSignalingState(UINT64 customData, UINT64 time) STATUS retStatus = STATUS_SUCCESS; PSignalingClient pSignalingClient = SIGNALING_CLIENT_FROM_CUSTOM_DATA(customData); SERVICE_CALL_RESULT serviceCallResult; + UINT64 startTimeInMacro = 0; CHK(pSignalingClient != NULL, STATUS_NULL_ARG); @@ -324,7 +325,9 @@ STATUS executeGetTokenSignalingState(UINT64 customData, UINT64 time) THREAD_SLEEP_UNTIL(time); // Use the credential provider to get the token - retStatus = pSignalingClient->pCredentialProvider->getCredentialsFn(pSignalingClient->pCredentialProvider, &pSignalingClient->pAwsCredentials); + PROFILE_CALL_WITH_T_OBJ(retStatus = pSignalingClient->pCredentialProvider->getCredentialsFn(pSignalingClient->pCredentialProvider, + &pSignalingClient->pAwsCredentials), + pSignalingClient->diagnostics.getTokenCallTime, "Get token call"); // Check the expiration if (NULL == pSignalingClient->pAwsCredentials || SIGNALING_GET_CURRENT_TIME(pSignalingClient) >= pSignalingClient->pAwsCredentials->expiration) { @@ -389,6 +392,7 @@ STATUS executeDescribeSignalingState(UINT64 customData, UINT64 time) ENTERS(); STATUS retStatus = STATUS_SUCCESS; PSignalingClient pSignalingClient = SIGNALING_CLIENT_FROM_CUSTOM_DATA(customData); + UINT64 startTimeInMacro = 0; CHK(pSignalingClient != NULL, STATUS_NULL_ARG); ATOMIC_STORE(&pSignalingClient->result, (SIZE_T) SERVICE_CALL_RESULT_NOT_SET); @@ -401,7 +405,8 @@ STATUS executeDescribeSignalingState(UINT64 customData, UINT64 time) } // Call the aggregate function - retStatus = describeChannel(pSignalingClient, time); + PROFILE_CALL_WITH_T_OBJ(retStatus = describeChannel(pSignalingClient, time), pSignalingClient->diagnostics.describeCallTime, + "Describe signaling call"); CleanUp: @@ -447,6 +452,7 @@ STATUS executeCreateSignalingState(UINT64 customData, UINT64 time) ENTERS(); STATUS retStatus = STATUS_SUCCESS; PSignalingClient pSignalingClient = SIGNALING_CLIENT_FROM_CUSTOM_DATA(customData); + UINT64 startTimeInMacro = 0; CHK(pSignalingClient != NULL, STATUS_NULL_ARG); ATOMIC_STORE(&pSignalingClient->result, (SIZE_T) SERVICE_CALL_RESULT_NOT_SET); @@ -459,7 +465,7 @@ STATUS executeCreateSignalingState(UINT64 customData, UINT64 time) } // Call the aggregate function - retStatus = createChannel(pSignalingClient, time); + PROFILE_CALL_WITH_T_OBJ(retStatus = createChannel(pSignalingClient, time), pSignalingClient->diagnostics.createCallTime, "Create signaling call"); CleanUp: @@ -504,6 +510,7 @@ STATUS executeGetEndpointSignalingState(UINT64 customData, UINT64 time) ENTERS(); STATUS retStatus = STATUS_SUCCESS; PSignalingClient pSignalingClient = SIGNALING_CLIENT_FROM_CUSTOM_DATA(customData); + UINT64 startTimeInMacro = 0; CHK(pSignalingClient != NULL, STATUS_NULL_ARG); ATOMIC_STORE(&pSignalingClient->result, (SIZE_T) SERVICE_CALL_RESULT_NOT_SET); @@ -516,7 +523,8 @@ STATUS executeGetEndpointSignalingState(UINT64 customData, UINT64 time) } // Call the aggregate function - retStatus = getChannelEndpoint(pSignalingClient, time); + PROFILE_CALL_WITH_T_OBJ(retStatus = getChannelEndpoint(pSignalingClient, time), pSignalingClient->diagnostics.getEndpointCallTime, + "Get endpoint signaling call"); CleanUp: @@ -562,6 +570,7 @@ STATUS executeGetIceConfigSignalingState(UINT64 customData, UINT64 time) ENTERS(); STATUS retStatus = STATUS_SUCCESS; PSignalingClient pSignalingClient = SIGNALING_CLIENT_FROM_CUSTOM_DATA(customData); + UINT64 startTimeInMacro = 0; CHK(pSignalingClient != NULL, STATUS_NULL_ARG); ATOMIC_STORE(&pSignalingClient->result, (SIZE_T) SERVICE_CALL_RESULT_NOT_SET); @@ -574,8 +583,8 @@ STATUS executeGetIceConfigSignalingState(UINT64 customData, UINT64 time) } // Call the aggregate function - retStatus = getIceConfig(pSignalingClient, time); - + PROFILE_CALL_WITH_T_OBJ(retStatus = getIceConfig(pSignalingClient, time), pSignalingClient->diagnostics.getIceConfigCallTime, + "Get ICE config signaling call"); CleanUp: LEAVES(); @@ -719,6 +728,7 @@ STATUS executeConnectSignalingState(UINT64 customData, UINT64 time) ENTERS(); STATUS retStatus = STATUS_SUCCESS; PSignalingClient pSignalingClient = SIGNALING_CLIENT_FROM_CUSTOM_DATA(customData); + UINT64 startTimeInMacro = 0; CHK(pSignalingClient != NULL, STATUS_NULL_ARG); @@ -728,7 +738,8 @@ STATUS executeConnectSignalingState(UINT64 customData, UINT64 time) SIGNALING_CLIENT_STATE_CONNECTING)); } - retStatus = connectSignalingChannel(pSignalingClient, time); + PROFILE_CALL_WITH_T_OBJ(retStatus = connectSignalingChannel(pSignalingClient, time), pSignalingClient->diagnostics.connectCallTime, + "Connect signaling call"); CleanUp: