GDT: fix time units for the request and events uptime (#6102)

maksymmalyhin · web-flow · commit fa2651201523 · 2020-07-22T11:49:55.000-04:00
* GDTCORClock: fix uptime and kernelBootTime units

* GDTCCTNanopbHelpers: fix time units for the batch and events snapshot uptime

* Formatting

* GDTCORClock: properties rename and deprecation.

* Changelog updates

* Fix renaming issues

* Cleanup

* GDTCORClockTest: reduce timestamp comparison accuracy
diff --git a/GoogleDataTransport/CHANGELOG.md b/GoogleDataTransport/CHANGELOG.md
@@ -1,12 +1,13 @@
-# v7.0.1
-- `GDTCORFlatFileStorage`: keep not expired events when expired batch removed. (#6010)
+# v7.1.0
+- Device uptime calculation fixes. (#6102)
 
 # v7.0.0
 - Storage has been completely reimplemented to a flat-file system. It
 is not backwards compatible with previously saved events.
 - Prioritizers, data futures, and upload packages have been removed.
 - Consolidated GoogleDataTransportCCTSupport with GoogleDataTransport. Starting
 with this version, GoogleDataTransportCCTSupport should no longer be linked.
+- `GDTCORFlatFileStorage`: keep not expired events when expired batch removed. (#6010)
 
 # v6.2.1
 - Stopped GDTCORUploadCoordinator from blocking main thread. (#5707, #5708)
diff --git a/GoogleDataTransport/GDTCCTLibrary/GDTCCTNanopbHelpers.m b/GoogleDataTransport/GDTCCTLibrary/GDTCCTNanopbHelpers.m
@@ -128,7 +128,7 @@ gdt_cct_LogRequest GDTCCTConstructLogRequest(int32_t logSource,
   GDTCORClock *currentTime = [GDTCORClock snapshot];
   logRequest.request_time_ms = currentTime.timeMillis;
   logRequest.has_request_time_ms = 1;
-  logRequest.request_uptime_ms = currentTime.uptime;
+  logRequest.request_uptime_ms = [currentTime uptimeMilliseconds];
   logRequest.has_request_uptime_ms = 1;
 
   return logRequest;
@@ -138,7 +138,7 @@ gdt_cct_LogEvent GDTCCTConstructLogEvent(GDTCOREvent *event) {
   gdt_cct_LogEvent logEvent = gdt_cct_LogEvent_init_default;
   logEvent.event_time_ms = event.clockSnapshot.timeMillis;
   logEvent.has_event_time_ms = 1;
-  logEvent.event_uptime_ms = event.clockSnapshot.uptime;
+  logEvent.event_uptime_ms = [event.clockSnapshot uptimeMilliseconds];
   logEvent.has_event_uptime_ms = 1;
   logEvent.timezone_offset_seconds = event.clockSnapshot.timezoneOffsetSeconds;
   logEvent.has_timezone_offset_seconds = 1;
diff --git a/GoogleDataTransport/GDTCCTTests/Unit/GDTCCTNanopbHelpersTest.m b/GoogleDataTransport/GDTCCTTests/Unit/GDTCCTNanopbHelpersTest.m
@@ -109,10 +109,34 @@ - (void)testBytesAreDecodable {
   pb_istream_t istream =
       pb_istream_from_buffer([encodedBatchLogRequest bytes], [encodedBatchLogRequest length]);
   XCTAssertTrue(pb_decode(&istream, gdt_cct_BatchedLogRequest_fields, &decodedBatch));
-  XCTAssert(decodedBatch.log_request_count == batch.log_request_count);
-  XCTAssert(decodedBatch.log_request[0].log_event_count == batch.log_request[0].log_event_count);
-  XCTAssert(decodedBatch.log_request[0].log_event[0].event_time_ms ==
-            batch.log_request[0].log_event[0].event_time_ms);
+  XCTAssertEqual(decodedBatch.log_request_count, batch.log_request_count);
+  XCTAssertEqual(decodedBatch.log_request[0].log_event_count, batch.log_request[0].log_event_count);
+  XCTAssertEqual(decodedBatch.log_request[0].log_event[0].event_time_ms,
+                 batch.log_request[0].log_event[0].event_time_ms);
+  XCTAssertEqual(decodedBatch.log_request[0].log_event[0].event_uptime_ms,
+                 batch.log_request[0].log_event[0].event_uptime_ms);
+  pb_release(gdt_cct_BatchedLogRequest_fields, &batch);
+  pb_release(gdt_cct_BatchedLogRequest_fields, &decodedBatch);
+}
+
+- (void)testDecodedEventTimestampMatchToBatchContent {
+  GDTCOREvent *storedEvent = [self.generator generateEvent:GDTCOREventQoSDaily];
+  NSSet<GDTCOREvent *> *storedEvents = [NSSet setWithObject:storedEvent];
+  gdt_cct_BatchedLogRequest batch = GDTCCTConstructBatchedLogRequest(@{@"1018" : storedEvents});
+  NSData *encodedBatchLogRequest = GDTCCTEncodeBatchedLogRequest(&batch);
+  gdt_cct_BatchedLogRequest decodedBatch = gdt_cct_BatchedLogRequest_init_default;
+  pb_istream_t istream =
+      pb_istream_from_buffer([encodedBatchLogRequest bytes], [encodedBatchLogRequest length]);
+  XCTAssertTrue(pb_decode(&istream, gdt_cct_BatchedLogRequest_fields, &decodedBatch));
+
+  gdt_cct_LogRequest decodedLogRequest = decodedBatch.log_request[0];
+  gdt_cct_LogEvent decodedLogEvent = decodedLogRequest.log_event[0];
+
+  XCTAssertEqual(decodedLogEvent.event_time_ms, storedEvent.clockSnapshot.timeMillis);
+  XCTAssertEqual(decodedLogEvent.event_uptime_ms, [storedEvent.clockSnapshot uptimeMilliseconds]);
+  XCTAssertEqual(decodedLogEvent.timezone_offset_seconds,
+                 storedEvent.clockSnapshot.timezoneOffsetSeconds);
+
   pb_release(gdt_cct_BatchedLogRequest_fields, &batch);
   pb_release(gdt_cct_BatchedLogRequest_fields, &decodedBatch);
 }
diff --git a/GoogleDataTransport/GDTCCTTests/Unit/Helpers/GDTCCTEventGenerator.m b/GoogleDataTransport/GDTCCTTests/Unit/Helpers/GDTCCTEventGenerator.m
@@ -117,8 +117,8 @@ - (NSURL *)writeConsistentMessageToDisk:(NSString *)messageResource {
     event.clockSnapshot = [GDTCORClock snapshot];
     [event.clockSnapshot setValue:@(1111111111111) forKeyPath:@"timeMillis"];
     [event.clockSnapshot setValue:@(-25200) forKeyPath:@"timezoneOffsetSeconds"];
-    [event.clockSnapshot setValue:@(1111111111111222) forKeyPath:@"kernelBootTime"];
-    [event.clockSnapshot setValue:@(1235567890) forKeyPath:@"uptime"];
+    [event.clockSnapshot setValue:@(1111111111111222) forKeyPath:@"kernelBootTimeNanoseconds"];
+    [event.clockSnapshot setValue:@(1235567890) forKeyPath:@"uptimeNanoseconds"];
     event.qosTier = GDTCOREventQosDefault;
     event.eventCode = @1986;
     NSError *error;
@@ -147,8 +147,8 @@ - (NSURL *)writeConsistentMessageToDisk:(NSString *)messageResource {
     event.clockSnapshot = [GDTCORClock snapshot];
     [event.clockSnapshot setValue:@(1111111111111) forKeyPath:@"timeMillis"];
     [event.clockSnapshot setValue:@(-25200) forKeyPath:@"timezoneOffsetSeconds"];
-    [event.clockSnapshot setValue:@(1111111111111333) forKeyPath:@"kernelBootTime"];
-    [event.clockSnapshot setValue:@(1236567890) forKeyPath:@"uptime"];
+    [event.clockSnapshot setValue:@(1111111111111333) forKeyPath:@"kernelBootTimeNanoseconds"];
+    [event.clockSnapshot setValue:@(1236567890) forKeyPath:@"uptimeNanoseconds"];
     event.qosTier = GDTCOREventQoSWifiOnly;
     NSURL *messageDataURL = [self writeConsistentMessageToDisk:@"message-35458880.dat"];
     GDTCCTEventGeneratorDataObject *dataObject = [[GDTCCTEventGeneratorDataObject alloc] init];
@@ -170,8 +170,8 @@ - (NSURL *)writeConsistentMessageToDisk:(NSString *)messageResource {
     event.clockSnapshot = [GDTCORClock snapshot];
     [event.clockSnapshot setValue:@(1111111111111) forKeyPath:@"timeMillis"];
     [event.clockSnapshot setValue:@(-25200) forKeyPath:@"timezoneOffsetSeconds"];
-    [event.clockSnapshot setValue:@(1111111111111444) forKeyPath:@"kernelBootTime"];
-    [event.clockSnapshot setValue:@(1237567890) forKeyPath:@"uptime"];
+    [event.clockSnapshot setValue:@(1111111111111444) forKeyPath:@"kernelBootTimeNanoseconds"];
+    [event.clockSnapshot setValue:@(1237567890) forKeyPath:@"uptimeNanoseconds"];
     event.qosTier = GDTCOREventQosDefault;
     NSURL *messageDataURL = [self writeConsistentMessageToDisk:@"message-39882816.dat"];
     GDTCCTEventGeneratorDataObject *dataObject = [[GDTCCTEventGeneratorDataObject alloc] init];
@@ -192,8 +192,8 @@ - (NSURL *)writeConsistentMessageToDisk:(NSString *)messageResource {
     event.clockSnapshot = [GDTCORClock snapshot];
     [event.clockSnapshot setValue:@(1111111111111) forKeyPath:@"timeMillis"];
     [event.clockSnapshot setValue:@(-25200) forKeyPath:@"timezoneOffsetSeconds"];
-    [event.clockSnapshot setValue:@(1111111111111555) forKeyPath:@"kernelBootTime"];
-    [event.clockSnapshot setValue:@(1238567890) forKeyPath:@"uptime"];
+    [event.clockSnapshot setValue:@(1111111111111555) forKeyPath:@"kernelBootTimeNanoseconds"];
+    [event.clockSnapshot setValue:@(1238567890) forKeyPath:@"uptimeNanoseconds"];
     event.qosTier = GDTCOREventQosDefault;
     NSError *error;
     event.customBytes = [NSJSONSerialization dataWithJSONObject:@{@"customParam1" : @"aValue1"}
@@ -219,8 +219,8 @@ - (NSURL *)writeConsistentMessageToDisk:(NSString *)messageResource {
     event.clockSnapshot = [GDTCORClock snapshot];
     [event.clockSnapshot setValue:@(1111111111111) forKeyPath:@"timeMillis"];
     [event.clockSnapshot setValue:@(-25200) forKeyPath:@"timezoneOffsetSeconds"];
-    [event.clockSnapshot setValue:@(1111111111111666) forKeyPath:@"kernelBootTime"];
-    [event.clockSnapshot setValue:@(1239567890) forKeyPath:@"uptime"];
+    [event.clockSnapshot setValue:@(1111111111111666) forKeyPath:@"kernelBootTimeNanoseconds"];
+    [event.clockSnapshot setValue:@(1239567890) forKeyPath:@"uptimeNanoseconds"];
     event.qosTier = GDTCOREventQoSTelemetry;
     NSError *error;
     event.customBytes = [NSJSONSerialization dataWithJSONObject:@{
diff --git a/GoogleDataTransport/GDTCORLibrary/GDTCORClock.m b/GoogleDataTransport/GDTCORLibrary/GDTCORClock.m
@@ -50,7 +50,7 @@ static int64_t KernelBootTimeInNanoseconds() {
   if (rc != 0) {
     return 0;
   }
-  return (int64_t)boottime.tv_sec * NSEC_PER_MSEC + (int64_t)boottime.tv_usec;
+  return (int64_t)boottime.tv_sec * NSEC_PER_SEC + (int64_t)boottime.tv_usec * NSEC_PER_USEC;
 }
 
 /** Returns value of gettimeofday, in nanoseconds.
@@ -60,17 +60,18 @@ static int64_t KernelBootTimeInNanoseconds() {
  * @return The value of gettimeofday, in nanoseconds.
  */
 static int64_t UptimeInNanoseconds() {
-  int64_t before_now;
-  int64_t after_now;
+  int64_t before_now_nsec;
+  int64_t after_now_nsec;
   struct timeval now;
 
-  before_now = KernelBootTimeInNanoseconds();
+  before_now_nsec = KernelBootTimeInNanoseconds();
   // Addresses a race condition in which the system time has updated, but the boottime has not.
   do {
     gettimeofday(&now, NULL);
-    after_now = KernelBootTimeInNanoseconds();
-  } while (after_now != before_now);
-  return (int64_t)now.tv_sec * NSEC_PER_MSEC + (int64_t)now.tv_usec - before_now;
+    after_now_nsec = KernelBootTimeInNanoseconds();
+  } while (after_now_nsec != before_now_nsec);
+  return (int64_t)now.tv_sec * NSEC_PER_SEC + (int64_t)now.tv_usec * NSEC_PER_USEC -
+         before_now_nsec;
 }
 
 // TODO: Consider adding a 'trustedTime' property that can be populated by the response from a BE.
@@ -79,8 +80,8 @@ @implementation GDTCORClock
 - (instancetype)init {
   self = [super init];
   if (self) {
-    _kernelBootTime = KernelBootTimeInNanoseconds();
-    _uptime = UptimeInNanoseconds();
+    _kernelBootTimeNanoseconds = KernelBootTimeInNanoseconds();
+    _uptimeNanoseconds = UptimeInNanoseconds();
     _timeMillis =
         (int64_t)((CFAbsoluteTimeGetCurrent() + kCFAbsoluteTimeIntervalSince1970) * NSEC_PER_USEC);
     CFTimeZoneRef timeZoneRef = CFTimeZoneCopySystem();
@@ -102,21 +103,26 @@ + (instancetype)clockSnapshotInTheFuture:(uint64_t)millisInTheFuture {
 
 - (BOOL)isAfter:(GDTCORClock *)otherClock {
   // These clocks are trivially comparable when they share a kernel boot time.
-  if (_kernelBootTime == otherClock->_kernelBootTime) {
+  if (_kernelBootTimeNanoseconds == otherClock->_kernelBootTimeNanoseconds) {
     int64_t timeDiff = (_timeMillis + _timezoneOffsetSeconds) -
                        (otherClock->_timeMillis + otherClock->_timezoneOffsetSeconds);
     return timeDiff > 0;
   } else {
-    int64_t kernelBootTimeDiff = otherClock->_kernelBootTime - _kernelBootTime;
+    int64_t kernelBootTimeDiff =
+        otherClock->_kernelBootTimeNanoseconds - _kernelBootTimeNanoseconds;
     // This isn't a great solution, but essentially, if the other clock's boot time is 'later', NO
     // is returned. This can be altered by changing the system time and rebooting.
     return kernelBootTimeDiff < 0 ? YES : NO;
   }
 }
 
+- (int64_t)uptimeMilliseconds {
+  return self.uptimeNanoseconds / NSEC_PER_MSEC;
+}
+
 - (NSUInteger)hash {
-  return [@(_kernelBootTime) hash] ^ [@(_uptime) hash] ^ [@(_timeMillis) hash] ^
-         [@(_timezoneOffsetSeconds) hash];
+  return [@(_kernelBootTimeNanoseconds) hash] ^ [@(_uptimeNanoseconds) hash] ^
+         [@(_timeMillis) hash] ^ [@(_timezoneOffsetSeconds) hash];
 }
 
 - (BOOL)isEqual:(id)object {
@@ -134,7 +140,7 @@ - (BOOL)isEqual:(id)object {
 /** NSKeyedCoder key for _kernelBootTime ivar. */
 static NSString *const kGDTCORClockKernelBootTime = @"GDTCORClockKernelBootTime";
 
-/** NSKeyedCoder key for _uptime ivar. */
+/** NSKeyedCoder key for _uptimeNanoseconds ivar. */
 static NSString *const kGDTCORClockUptime = @"GDTCORClockUptime";
 
 + (BOOL)supportsSecureCoding {
@@ -144,21 +150,31 @@ + (BOOL)supportsSecureCoding {
 - (instancetype)initWithCoder:(NSCoder *)aDecoder {
   self = [super init];
   if (self) {
-    // TODO: If the kernelBootTime is more recent, we need to change the kernel boot time and
-    // uptimeMillis ivars
+    // TODO: If the kernelBootTimeNanoseconds is more recent, we need to change the kernel boot time
+    // and uptimeMillis ivars
     _timeMillis = [aDecoder decodeInt64ForKey:kGDTCORClockTimeMillisKey];
     _timezoneOffsetSeconds = [aDecoder decodeInt64ForKey:kGDTCORClockTimezoneOffsetSeconds];
-    _kernelBootTime = [aDecoder decodeInt64ForKey:kGDTCORClockKernelBootTime];
-    _uptime = [aDecoder decodeInt64ForKey:kGDTCORClockUptime];
+    _kernelBootTimeNanoseconds = [aDecoder decodeInt64ForKey:kGDTCORClockKernelBootTime];
+    _uptimeNanoseconds = [aDecoder decodeInt64ForKey:kGDTCORClockUptime];
   }
   return self;
 }
 
 - (void)encodeWithCoder:(NSCoder *)aCoder {
   [aCoder encodeInt64:_timeMillis forKey:kGDTCORClockTimeMillisKey];
   [aCoder encodeInt64:_timezoneOffsetSeconds forKey:kGDTCORClockTimezoneOffsetSeconds];
-  [aCoder encodeInt64:_kernelBootTime forKey:kGDTCORClockKernelBootTime];
-  [aCoder encodeInt64:_uptime forKey:kGDTCORClockUptime];
+  [aCoder encodeInt64:_kernelBootTimeNanoseconds forKey:kGDTCORClockKernelBootTime];
+  [aCoder encodeInt64:_uptimeNanoseconds forKey:kGDTCORClockUptime];
+}
+
+#pragma mark - Deprecated properties
+
+- (int64_t)kernelBootTime {
+  return self.kernelBootTimeNanoseconds;
+}
+
+- (int64_t)uptime {
+  return self.uptimeNanoseconds;
 }
 
 @end
diff --git a/GoogleDataTransport/GDTCORLibrary/Public/GDTCORClock.h b/GoogleDataTransport/GDTCORLibrary/Public/GDTCORClock.h
@@ -27,11 +27,17 @@ NS_ASSUME_NONNULL_BEGIN
 /** The offset from UTC in seconds. */
 @property(nonatomic, readonly) int64_t timezoneOffsetSeconds;
 
-/** The kernel boot time when this clock was created. */
-@property(nonatomic, readonly) int64_t kernelBootTime;
+/** The kernel boot time when this clock was created in nanoseconds. */
+@property(nonatomic, readonly) int64_t kernelBootTimeNanoseconds;
 
-/** The device uptime when this clock was created. */
-@property(nonatomic, readonly) int64_t uptime;
+/** The device uptime when this clock was created in nanoseconds. */
+@property(nonatomic, readonly) int64_t uptimeNanoseconds;
+
+@property(nonatomic, readonly) int64_t kernelBootTime DEPRECATED_MSG_ATTRIBUTE(
+    "Please use `kernelBootTimeNanoseconds` instead");
+
+@property(nonatomic, readonly)
+    int64_t uptime DEPRECATED_MSG_ATTRIBUTE("Please use `uptimeNanoseconds` instead");
 
 /** Creates a GDTCORClock object using the current time and offsets.
  *
@@ -52,6 +58,9 @@ NS_ASSUME_NONNULL_BEGIN
  */
 - (BOOL)isAfter:(GDTCORClock *)otherClock;
 
+/** Returns value of `uptime` property in milliseconds. */
+- (int64_t)uptimeMilliseconds;
+
 @end
 
 NS_ASSUME_NONNULL_END
diff --git a/GoogleDataTransport/GDTCORTests/Unit/GDTCORClockTest.m b/GoogleDataTransport/GDTCORTests/Unit/GDTCORClockTest.m
@@ -81,4 +81,36 @@ - (void)testIsAfter {
   XCTAssertFalse([clock2 isAfter:clock1]);
 }
 
+- (void)testUptime {
+  NSTimeInterval timeDiff = 1;
+  GDTCORClock *clock1 = [GDTCORClock snapshot];
+  [[NSRunLoop currentRunLoop] runUntilDate:[NSDate dateWithTimeIntervalSinceNow:timeDiff]];
+  GDTCORClock *clock2 = [GDTCORClock snapshot];
+
+  XCTAssertGreaterThan(clock2.uptimeNanoseconds, clock1.uptimeNanoseconds);
+  NSTimeInterval uptimeDiff =
+      (clock2.uptimeNanoseconds - clock1.uptimeNanoseconds) / (double)NSEC_PER_SEC;
+  NSTimeInterval accuracy = 0.1;
+
+  // Assert that uptime difference reflects the actually passed time.
+  XCTAssertLessThanOrEqual(ABS(uptimeDiff - timeDiff), accuracy);
+}
+
+- (void)testUptimeMilliseconds {
+  NSTimeInterval timeDiff = 1;
+  GDTCORClock *clock1 = [GDTCORClock snapshot];
+  [[NSRunLoop currentRunLoop] runUntilDate:[NSDate dateWithTimeIntervalSinceNow:timeDiff]];
+  GDTCORClock *clock2 = [GDTCORClock snapshot];
+
+  XCTAssertGreaterThan(clock2.uptimeNanoseconds, clock1.uptimeNanoseconds);
+
+  NSTimeInterval millisecondsPerSecond = 1000;
+  NSTimeInterval uptimeDiff =
+      ([clock2 uptimeMilliseconds] - [clock1 uptimeMilliseconds]) / millisecondsPerSecond;
+  NSTimeInterval accuracy = 0.1;
+
+  // Assert that uptime difference reflects the actually passed time.
+  XCTAssertLessThanOrEqual(ABS(uptimeDiff - timeDiff), accuracy);
+}
+
 @end
diff --git a/GoogleDataTransport/GDTCORTests/Unit/GDTCOREventTest.m b/GoogleDataTransport/GDTCORTests/Unit/GDTCOREventTest.m
@@ -93,8 +93,8 @@ - (void)testIsEqualAndHash {
   event1.clockSnapshot = [GDTCORClock snapshot];
   [event1.clockSnapshot setValue:@(1553534573010) forKeyPath:@"timeMillis"];
   [event1.clockSnapshot setValue:@(-25200) forKeyPath:@"timezoneOffsetSeconds"];
-  [event1.clockSnapshot setValue:@(1552576634359451) forKeyPath:@"kernelBootTime"];
-  [event1.clockSnapshot setValue:@(961141365197) forKeyPath:@"uptime"];
+  [event1.clockSnapshot setValue:@(1552576634359451) forKeyPath:@"kernelBootTimeNanoseconds"];
+  [event1.clockSnapshot setValue:@(961141365197) forKeyPath:@"uptimeNanoseconds"];
   event1.qosTier = GDTCOREventQosDefault;
   event1.dataObject = [[GDTCORDataObjectTesterSimple alloc] initWithString:@"someData"];
   NSError *error1;
@@ -108,8 +108,8 @@ - (void)testIsEqualAndHash {
   event2.clockSnapshot = [GDTCORClock snapshot];
   [event2.clockSnapshot setValue:@(1553534573010) forKeyPath:@"timeMillis"];
   [event2.clockSnapshot setValue:@(-25200) forKeyPath:@"timezoneOffsetSeconds"];
-  [event2.clockSnapshot setValue:@(1552576634359451) forKeyPath:@"kernelBootTime"];
-  [event2.clockSnapshot setValue:@(961141365197) forKeyPath:@"uptime"];
+  [event2.clockSnapshot setValue:@(1552576634359451) forKeyPath:@"kernelBootTimeNanoseconds"];
+  [event2.clockSnapshot setValue:@(961141365197) forKeyPath:@"uptimeNanoseconds"];
   event2.qosTier = GDTCOREventQosDefault;
   event2.dataObject = [[GDTCORDataObjectTesterSimple alloc] initWithString:@"someData"];
   NSError *error2;
