Snap for 7542710 from 6153305d8306499985ce6832989b93e69ddcd875 to sc-release

Change-Id: I3773ec9603dddc70ace623bb5ddcba60b25bc4ec

9 files changed, 104 insertions, 59 deletions

diff --git a/chpp/clients.c b/chpp/clients.c
index 06b0d63d..c8b564be 100644
--- a/chpp/clients.c
+++ b/chpp/clients.c
@@ -315,7 +315,7 @@ void chppClientTimestampRequest(struct ChppClientState *clientState,
   if (rRState->requestState == CHPP_REQUEST_STATE_REQUEST_SENT) {
     CHPP_LOGE("Dupe req ID=%" PRIu8 " existing ID=%" PRIu8 " from t=%" PRIu64,
               requestHeader->transaction, rRState->transaction,
-              rRState->requestTimeNs);
+              rRState->requestTimeNs / CHPP_NSEC_PER_MSEC);
 
     // Clear a possible pending timeout from the previous request
     rRState->responseTimeNs = CHPP_TIME_MAX;
@@ -338,9 +338,10 @@ void chppClientTimestampRequest(struct ChppClientState *clientState,
 
   CHPP_LOGD("Timestamp req ID=%" PRIu8 " at t=%" PRIu64 " timeout=%" PRIu64
             " (requested=%" PRIu64 "), next timeout=%" PRIu64,
-            rRState->transaction, rRState->requestTimeNs,
-            rRState->responseTimeNs, timeoutNs,
-            clientState->appContext->nextRequestTimeoutNs);
+            rRState->transaction, rRState->requestTimeNs / CHPP_NSEC_PER_MSEC,
+            rRState->responseTimeNs / CHPP_NSEC_PER_MSEC,
+            timeoutNs / CHPP_NSEC_PER_MSEC,
+            clientState->appContext->nextRequestTimeoutNs / CHPP_NSEC_PER_MSEC);
 }
 
 bool chppClientTimestampResponse(struct ChppClientState *clientState,
@@ -351,27 +352,31 @@ bool chppClientTimestampResponse(struct ChppClientState *clientState,
 
   switch (rRState->requestState) {
     case CHPP_REQUEST_STATE_NONE: {
-      CHPP_LOGE("Resp with no req t=%" PRIu64, responseTime);
+      CHPP_LOGE("Resp with no req t=%" PRIu64,
+                responseTime / CHPP_NSEC_PER_MSEC);
       break;
     }
 
     case CHPP_REQUEST_STATE_RESPONSE_RCV: {
-      CHPP_LOGE("Extra resp at t=%" PRIu64 " for req t=%" PRIu64, responseTime,
-                rRState->requestTimeNs);
+      CHPP_LOGE("Extra resp at t=%" PRIu64 " for req t=%" PRIu64,
+                responseTime / CHPP_NSEC_PER_MSEC,
+                rRState->requestTimeNs / CHPP_NSEC_PER_MSEC);
       break;
     }
 
     case CHPP_REQUEST_STATE_RESPONSE_TIMEOUT: {
-      CHPP_LOGE("Late resp at t=%" PRIu64 " for req t=%" PRIu64, responseTime,
-                rRState->requestTimeNs);
+      CHPP_LOGE("Late resp at t=%" PRIu64 " for req t=%" PRIu64,
+                responseTime / CHPP_NSEC_PER_MSEC,
+                rRState->requestTimeNs / CHPP_NSEC_PER_MSEC);
       break;
     }
 
     case CHPP_REQUEST_STATE_REQUEST_SENT: {
       if (responseHeader->transaction != rRState->transaction) {
-        CHPP_LOGE(
-            "Invalid resp ID=%" PRIu8 " at t=%" PRIu64 " expected=%" PRIu8,
-            responseHeader->transaction, responseTime, rRState->transaction);
+        CHPP_LOGE("Invalid resp ID=%" PRIu8 " at t=%" PRIu64
+                  " expected=%" PRIu8,
+                  responseHeader->transaction,
+                  responseTime / CHPP_NSEC_PER_MSEC, rRState->transaction);
       } else {
         rRState->requestState = (responseTime > rRState->responseTimeNs)
                                     ? CHPP_REQUEST_STATE_RESPONSE_TIMEOUT
@@ -381,8 +386,10 @@ bool chppClientTimestampResponse(struct ChppClientState *clientState,
         CHPP_LOGD(
             "Timestamp resp ID=%" PRIu8 " req t=%" PRIu64 " resp t=%" PRIu64
             " timeout t=%" PRIu64 " (RTT=%" PRIu64 ", timeout = %s)",
-            rRState->transaction, rRState->requestTimeNs, responseTime,
-            rRState->responseTimeNs, responseTime - rRState->requestTimeNs,
+            rRState->transaction, rRState->requestTimeNs / CHPP_NSEC_PER_MSEC,
+            responseTime / CHPP_NSEC_PER_MSEC,
+            rRState->responseTimeNs / CHPP_NSEC_PER_MSEC,
+            (responseTime - rRState->requestTimeNs) / CHPP_NSEC_PER_MSEC,
             (responseTime > rRState->responseTimeNs) ? "yes" : "no");
       }
       break;
@@ -547,7 +554,8 @@ void chppClientRecalculateNextTimeout(struct ChppAppState *context) {
     }
   }
 
-  CHPP_LOGD("nextReqTimeout=%" PRIu64, context->nextRequestTimeoutNs);
+  CHPP_LOGD("nextReqTimeout=%" PRIu64,
+            context->nextRequestTimeoutNs / CHPP_NSEC_PER_MSEC);
 }
 
 void chppClientCloseOpenRequests(struct ChppClientState *clientState,
diff --git a/chpp/clients/timesync.c b/chpp/clients/timesync.c
index b84fceee..73d5b17c 100644
--- a/chpp/clients/timesync.c
+++ b/chpp/clients/timesync.c
@@ -126,9 +126,11 @@ bool chppDispatchTimesyncServiceResponse(struct ChppAppState *context,
         clippedOffsetChangeNs;
 
     if (offsetChangeNs != clippedOffsetChangeNs) {
-      CHPP_LOGW("Drift=%" PRIi64 " clipped to %" PRIi64 " at t=%" PRIu64,
-                offsetChangeNs, clippedOffsetChangeNs,
-                context->timesyncClientContext->measureOffset.responseTimeNs);
+      CHPP_LOGW("Drift=%" PRId64 " clipped to %" PRId64 " at t=%" PRIu64,
+                offsetChangeNs / (int64_t)CHPP_NSEC_PER_MSEC,
+                clippedOffsetChangeNs / (int64_t)CHPP_NSEC_PER_MSEC,
+                context->timesyncClientContext->measureOffset.responseTimeNs /
+                    CHPP_NSEC_PER_MSEC);
     } else {
       context->timesyncClientContext->timesyncResult.measurementTimeNs =
           context->timesyncClientContext->measureOffset.responseTimeNs;
@@ -136,11 +138,14 @@ bool chppDispatchTimesyncServiceResponse(struct ChppAppState *context,
 
     context->timesyncClientContext->timesyncResult.error = CHPP_APP_ERROR_NONE;
 
-    CHPP_LOGI("Timesync RTT=%" PRIu64 " correction=%" PRIi64 " offset=%" PRIi64
+    CHPP_LOGI("Timesync RTT=%" PRIu64 " correction=%" PRId64 " offset=%" PRId64
               " t=%" PRIu64,
-              context->timesyncClientContext->timesyncResult.rttNs,
-              clippedOffsetChangeNs, offsetNs,
-              context->timesyncClientContext->timesyncResult.measurementTimeNs);
+              context->timesyncClientContext->timesyncResult.rttNs /
+                  CHPP_NSEC_PER_MSEC,
+              clippedOffsetChangeNs / (int64_t)CHPP_NSEC_PER_MSEC,
+              offsetNs / (int64_t)CHPP_NSEC_PER_MSEC,
+              context->timesyncClientContext->timesyncResult.measurementTimeNs /
+                  CHPP_NSEC_PER_MSEC);
   }
 
   return true;
@@ -148,7 +153,8 @@ bool chppDispatchTimesyncServiceResponse(struct ChppAppState *context,
 
 bool chppTimesyncMeasureOffset(struct ChppAppState *context) {
   bool result = false;
-  CHPP_LOGI("Measuring timesync t=%" PRIu64, chppGetCurrentTimeNs());
+  CHPP_LOGI("Measuring timesync t=%" PRIu64,
+            chppGetCurrentTimeNs() / CHPP_NSEC_PER_MSEC);
 
   CHPP_NOT_NULL(context->timesyncClientContext);
 
@@ -189,9 +195,10 @@ int64_t chppTimesyncGetOffset(struct ChppAppState *context,
   if (timesyncNeverDone || timesyncIsStale) {
     chppTimesyncMeasureOffset(context);
   } else {
-    CHPP_LOGD("No need to timesync at t~=%" PRIu64 "offset=%" PRIi64,
-              chppGetCurrentTimeNs(),
-              context->timesyncClientContext->timesyncResult.offsetNs);
+    CHPP_LOGD("No need to timesync at t~=%" PRIu64 "offset=%" PRId64,
+              chppGetCurrentTimeNs() / CHPP_NSEC_PER_MSEC,
+              context->timesyncClientContext->timesyncResult.offsetNs /
+                  (int64_t)CHPP_NSEC_PER_MSEC);
   }
 
   return context->timesyncClientContext->timesyncResult.offsetNs;
diff --git a/chpp/clients/wifi.c b/chpp/clients/wifi.c
index 387889a9..3de188dd 100644
--- a/chpp/clients/wifi.c
+++ b/chpp/clients/wifi.c
@@ -557,7 +557,8 @@ static void chppWifiScanEventNotification(
         (uint64_t)chppTimesyncGetOffset(gWifiClientContext.client.appContext,
                                         CHPP_WIFI_MAX_TIMESYNC_AGE_NS);
     CHPP_LOGD("WiFi scan time corrected from %" PRIu64 "to %" PRIu64,
-              chre->referenceTime, correctedTime);
+              chre->referenceTime / CHPP_NSEC_PER_MSEC,
+              correctedTime / CHPP_NSEC_PER_MSEC);
     chre->referenceTime = correctedTime;
 #endif
 
@@ -599,7 +600,8 @@ static void chppWifiRangingEventNotification(
         (uint64_t)chppTimesyncGetOffset(gWifiClientContext.client.appContext,
                                         CHPP_WIFI_MAX_TIMESYNC_AGE_NS);
     CHPP_LOGD("WiFi ranging result time corrected from %" PRIu64 "to %" PRIu64,
-              results[i].timestamp, correctedTime);
+              results[i].timestamp / CHPP_NSEC_PER_MSEC,
+              correctedTime / CHPP_NSEC_PER_MSEC);
     results[i].timestamp = correctedTime;
   }
 #endif
diff --git a/chpp/platform/linux/link.c b/chpp/platform/linux/link.c
index e21887bd..8594a8d6 100644
--- a/chpp/platform/linux/link.c
+++ b/chpp/platform/linux/link.c
@@ -53,11 +53,13 @@ static void *linkSendThread(void *arg) {
         error = CHPP_LINK_ERROR_NONE_SENT;
 
       } else if (!params->linkEstablished) {
+        CHPP_LOGE("No (fake) link");
         error = CHPP_LINK_ERROR_NO_LINK;
 
       } else if (!chppRxDataCb(params->remoteTransportContext, params->buf,
                                params->bufLen)) {
-        error = CHPP_LINK_ERROR_UNSPECIFIED;
+        CHPP_LOGW("chppRxDataCb return state!=preamble (packet incomplete)");
+        error = CHPP_LINK_ERROR_NONE_SENT;
 
       } else {
         error = CHPP_LINK_ERROR_NONE_SENT;
@@ -74,6 +76,7 @@ static void *linkSendThread(void *arg) {
 }
 
 void chppPlatformLinkInit(struct ChppPlatformLinkParameters *params) {
+  params->bufLen = 0;
   chppMutexInit(&params->mutex);
   chppNotifierInit(&params->notifier);
   pthread_create(&params->linkSendThread, NULL /* attr */, linkSendThread,
diff --git a/chpp/services.c b/chpp/services.c
index a2d355c3..dd087115 100644
--- a/chpp/services.c
+++ b/chpp/services.c
@@ -148,7 +148,8 @@ void chppServiceTimestampRequest(struct ChppRequestResponseState *rRState,
                                  struct ChppAppHeader *requestHeader) {
   if (rRState->responseTimeNs == CHPP_TIME_NONE &&
       rRState->requestTimeNs != CHPP_TIME_NONE) {
-    CHPP_LOGE("Duplicate request rx at %" PRIu64 " ns", rRState->requestTimeNs);
+    CHPP_LOGE("Duplicate request rx at t=%" PRIu64,
+              rRState->requestTimeNs / CHPP_NSEC_PER_MSEC);
   }
   rRState->requestTimeNs = chppGetCurrentTimeNs();
   rRState->responseTimeNs = CHPP_TIME_NONE;
@@ -160,17 +161,21 @@ void chppServiceTimestampResponse(struct ChppRequestResponseState *rRState) {
   rRState->responseTimeNs = chppGetCurrentTimeNs();
 
   if (rRState->requestTimeNs == CHPP_TIME_NONE) {
-    CHPP_LOGE("Tx response w/ no req t=%" PRIu64, rRState->responseTimeNs);
+    CHPP_LOGE("Tx response w/ no req t=%" PRIu64,
+              rRState->responseTimeNs / CHPP_NSEC_PER_MSEC);
 
   } else if (previousResponseTime != CHPP_TIME_NONE) {
     CHPP_LOGW("Resend response t=%" PRIu64 " for request at t=%" PRIu64,
-              rRState->responseTimeNs, rRState->responseTimeNs);
+              rRState->responseTimeNs / CHPP_NSEC_PER_MSEC,
+              rRState->responseTimeNs / CHPP_NSEC_PER_MSEC);
 
   } else {
     CHPP_LOGD("Sending initial response at t=%" PRIu64
               " for request at t=%" PRIu64 " (RTT=%" PRIu64 ")",
-              rRState->responseTimeNs, rRState->responseTimeNs,
-              rRState->responseTimeNs - rRState->requestTimeNs);
+              rRState->responseTimeNs / CHPP_NSEC_PER_MSEC,
+              rRState->responseTimeNs / CHPP_NSEC_PER_MSEC,
+              (rRState->responseTimeNs - rRState->requestTimeNs) /
+                  CHPP_NSEC_PER_MSEC);
   }
 }
 
diff --git a/chpp/services/timesync.c b/chpp/services/timesync.c
index bbbcbbb8..e66b5129 100644
--- a/chpp/services/timesync.c
+++ b/chpp/services/timesync.c
@@ -54,7 +54,7 @@ static void chppTimesyncGetTime(struct ChppAppState *context,
     response->timeNs = chppGetCurrentTimeNs();
     CHPP_LOGD("chppTimesyncGetTime returning %" PRIuSIZE
               " bytes at time=%" PRIu64,
-              responseLen, response->timeNs);
+              responseLen, response->timeNs / CHPP_NSEC_PER_MSEC);
 
     chppEnqueueTxDatagramOrFail(context->transportContext, response,
                                 responseLen);
diff --git a/chpp/test/app_test.cpp b/chpp/test/app_test.cpp
index a9ccf049..248688c6 100644
--- a/chpp/test/app_test.cpp
+++ b/chpp/test/app_test.cpp
@@ -37,6 +37,8 @@ namespace {
 
 TEST_F(AppTestBase, SimpleStartStop) {
   // Simple test to make sure start/stop work threads work without crashing
+  ASSERT_TRUE(mClientTransportContext.linkParams.linkEstablished);
+  ASSERT_TRUE(mServiceTransportContext.linkParams.linkEstablished);
 }
 
 TEST_F(AppTestBase, TransportLayerLoopback) {
diff --git a/chpp/test/app_test_base.cpp b/chpp/test/app_test_base.cpp
index 169642e1..3c4ed83f 100644
--- a/chpp/test/app_test_base.cpp
+++ b/chpp/test/app_test_base.cpp
@@ -56,6 +56,11 @@ void AppTestBase::SetUp() {
   mClientTransportContext.linkParams.linkThreadName = "Link to service";
   mClientTransportContext.linkParams.workThreadName = "Client work";
 
+  mClientTransportContext.linkParams.remoteTransportContext =
+      &mServiceTransportContext;
+  mServiceTransportContext.linkParams.remoteTransportContext =
+      &mClientTransportContext;
+
   struct ChppClientServiceSet set;
   memset(&set, 0, sizeof(set));
   set.wifiClient = 1;
@@ -66,27 +71,23 @@ void AppTestBase::SetUp() {
   chppTransportInit(&mClientTransportContext, &mClientAppContext);
   chppAppInitWithClientServiceSet(&mClientAppContext, &mClientTransportContext,
                                   set);
+  pthread_create(&mClientWorkThread, NULL, workThread,
+                 &mClientTransportContext);
+
+  // Wait a bit to emulate the scenario where the remote is not yet up
+  std::this_thread::sleep_for(std::chrono::milliseconds(450));
 
   memset(&set, 0, sizeof(set));
   set.wifiService = 1;
   set.gnssService = 1;
   set.wwanService = 1;
+
   chppTransportInit(&mServiceTransportContext, &mServiceAppContext);
   chppAppInitWithClientServiceSet(&mServiceAppContext,
                                   &mServiceTransportContext, set);
-
-  mClientTransportContext.linkParams.remoteTransportContext =
-      &mServiceTransportContext;
-  mServiceTransportContext.linkParams.remoteTransportContext =
-      &mClientTransportContext;
-
-  pthread_create(&mClientWorkThread, NULL, workThread,
-                 &mClientTransportContext);
-
-  // Wait a bit to emulate the scenario where the remote is not yet up
-  std::this_thread::sleep_for(std::chrono::milliseconds(500));
   pthread_create(&mServiceWorkThread, NULL, workThread,
                  &mServiceTransportContext);
+
   mClientTransportContext.linkParams.linkEstablished = true;
   mServiceTransportContext.linkParams.linkEstablished = true;
 
diff --git a/chpp/transport.c b/chpp/transport.c
index 5101a8f3..8490318a 100644
--- a/chpp/transport.c
+++ b/chpp/transport.c
@@ -81,6 +81,8 @@ static void chppAppendToPendingTxPacket(struct PendingTxPacket *packet,
 static const char *chppGetPacketAttrStr(uint8_t packetCode);
 static bool chppEnqueueTxDatagram(struct ChppTransportState *context,
                                   uint8_t packetCode, void *buf, size_t len);
+enum ChppLinkErrorCode chppSendPendingPacket(
+    struct ChppTransportState *context);
 
 static void chppResetTransportContext(struct ChppTransportState *context);
 static void chppReset(struct ChppTransportState *context,
@@ -442,9 +444,7 @@ static void chppProcessTransportLoopbackRequest(
               ", Tx payload len=%" PRIu16 ", Rx payload len=%" PRIuSIZE ")",
               context->pendingTxPacket.length, txHeader->length,
               context->rxDatagram.length);
-    enum ChppLinkErrorCode error = chppPlatformLinkSend(
-        &context->linkParams, context->pendingTxPacket.payload,
-        context->pendingTxPacket.length);
+    enum ChppLinkErrorCode error = chppSendPendingPacket(context);
 
     if (error != CHPP_LINK_ERROR_NONE_QUEUED) {
       chppLinkSendDoneCb(&context->linkParams, error);
@@ -1020,10 +1020,8 @@ static void chppTransportDoWork(struct ChppTransportState *context) {
               context->pendingTxPacket.length, txHeader->flags,
               txHeader->packetCode, txHeader->ackSeq, txHeader->seq,
               txHeader->length, context->txDatagramQueue.pending);
+    enum ChppLinkErrorCode error = chppSendPendingPacket(context);
 
-    enum ChppLinkErrorCode error = chppPlatformLinkSend(
-        &context->linkParams, context->pendingTxPacket.payload,
-        context->pendingTxPacket.length);
     if (error != CHPP_LINK_ERROR_NONE_QUEUED) {
       // Platform implementation for platformLinkSend() is synchronous or an
       // error occurred. In either case, we should call chppLinkSendDoneCb()
@@ -1146,6 +1144,25 @@ static bool chppEnqueueTxDatagram(struct ChppTransportState *context,
 }
 
 /**
+ * Sends the pending outgoing packet (context->pendingTxPacket) over to the link
+ * layer using chppPlatformLinkSend() and updates the last Tx packet time.
+ *
+ * @param context Maintains status for each transport layer instance.
+ *
+ * @return Result of chppPlatformLinkSend().
+ */
+enum ChppLinkErrorCode chppSendPendingPacket(
+    struct ChppTransportState *context) {
+  enum ChppLinkErrorCode error = chppPlatformLinkSend(
+      &context->linkParams, context->pendingTxPacket.payload,
+      context->pendingTxPacket.length);
+
+  context->txStatus.lastTxTimeNs = chppGetCurrentTimeNs();
+
+  return error;
+}
+
+/**
  * Resets the transport state, maintaining the link layer parameters.
  *
  * @param context Maintains status for each transport layer instance.
@@ -1270,7 +1287,7 @@ struct ChppAppHeader *chppTransportGetClientRequestTimeoutResponse(
 
     if (!timeoutClientFound) {
       CHPP_LOGE("Timeout at %" PRIu64 " but no client",
-                context->appContext->nextRequestTimeoutNs);
+                context->appContext->nextRequestTimeoutNs / CHPP_NSEC_PER_MSEC);
       chppClientRecalculateNextTimeout(context->appContext);
     }
   }
@@ -1489,7 +1506,9 @@ uint64_t chppTransportGetTimeUntilNextDoWorkNs(
   }
 
   CHPP_LOGD("NextDoWork=%" PRIu64 " currentTime=%" PRIu64 " delta=%" PRId64,
-            nextDoWorkTime, currentTime, nextDoWorkTime - currentTime);
+            nextDoWorkTime / CHPP_NSEC_PER_MSEC,
+            currentTime / CHPP_NSEC_PER_MSEC,
+            (nextDoWorkTime - currentTime) / (int64_t)CHPP_NSEC_PER_MSEC);
 
   if (nextDoWorkTime == CHPP_TIME_MAX) {
     return CHPP_TRANSPORT_TIMEOUT_INFINITE;
@@ -1535,7 +1554,8 @@ bool chppWorkThreadHandleSignal(struct ChppTransportState *context,
 
     if (chppGetCurrentTimeNs() - context->txStatus.lastTxTimeNs >=
         CHPP_TRANSPORT_TX_TIMEOUT_NS) {
-      CHPP_LOGE("ACK timeout");
+      CHPP_LOGE("ACK timeout. Tx t=%" PRIu64,
+                context->txStatus.lastTxTimeNs / CHPP_NSEC_PER_MSEC);
       chppTransportDoWork(context);
     }
 
@@ -1578,7 +1598,6 @@ void chppLinkSendDoneCb(struct ChppPlatformLinkParameters *params,
 
   chppMutexLock(&context->mutex);
 
-  context->txStatus.lastTxTimeNs = chppGetCurrentTimeNs();
   context->txStatus.linkBusy = false;
 
   // No need to free anything as pendingTxPacket.payload is static. Likewise, we
@@ -1649,9 +1668,7 @@ uint8_t chppRunTransportLoopback(struct ChppTransportState *context,
     CHPP_LOGD("Sending transport-loopback request (packet len=%" PRIuSIZE
               ", payload len=%" PRIu16 ", asked len was %" PRIuSIZE ")",
               context->pendingTxPacket.length, txHeader->length, len);
-    enum ChppLinkErrorCode error = chppPlatformLinkSend(
-        &context->linkParams, context->pendingTxPacket.payload,
-        context->pendingTxPacket.length);
+    enum ChppLinkErrorCode error = chppSendPendingPacket(context);
 
     if (error != CHPP_LINK_ERROR_NONE_QUEUED) {
       // Either sent synchronously or an error has occurred