Bug 1425462 Add additional logging and output if we observe time (based on the timeOrigin, not fuzzing) going backwards draft
authorTom Ritter <tom@mozilla.com>
Sun, 21 Jan 2018 10:53:03 -0600
changeset 724414 c7b4f997d5a5d6f722420a9bad08378c411c1142
parent 724413 7159092cda97399274ed46d1a4bd83e0c333a150
child 724415 f9c9242787928773c6329b8a1155558c05cc77c6
push id96741
push userbmo:tom@mozilla.com
push dateWed, 24 Jan 2018 22:45:52 +0000
bugs1425462
milestone59.0a1
Bug 1425462 Add additional logging and output if we observe time (based on the timeOrigin, not fuzzing) going backwards Note that this is not necessarily an error condition. t1 may occur before t2, but be rounded/jittered after t2. But it's something to investigate and confirm. MozReview-Commit-ID: lCthnhQnPd
toolkit/components/resistfingerprinting/nsRFPService.cpp
--- a/toolkit/components/resistfingerprinting/nsRFPService.cpp
+++ b/toolkit/components/resistfingerprinting/nsRFPService.cpp
@@ -142,43 +142,71 @@ nsRFPService::IsResistFingerprintingEnab
 /* static */
 bool
 nsRFPService::IsTimerPrecisionReductionEnabled()
 {
   return (sPrivacyTimerPrecisionReduction || IsResistFingerprintingEnabled()) &&
          TimerResolution() != 0;
 }
 
+#if defined(DEBUG)
 #define INIT_STACKTRACE() \
   void* callstack[4]; \
   int frames = backtrace(callstack, 4); \
-  char** strs = backtrace_symbols(callstack, frames);
+  char** thisCaller = backtrace_symbols(callstack, frames);
+
+#define CALLER(caller) \
+  ((strstr(caller[1], "Performance3Now") != NULL) ? "performance.now()" : \
+  ((strstr(caller[1], "dom5Event13TimeStampImplEv") != NULL) ? "Event.timeStamp" : \
+  ((strstr(caller[3], "Animation21DispatchPlaybackEvent") != NULL && strstr(caller[2], "AnimationTimeline22GetCurrentTimeAsDouble") != NULL) ? "AnimationTimeline::GetCurrentTimeAsDouble" : \
+  ((strstr(caller[3], "Animation21DispatchPlaybackEvent") != NULL && strstr(caller[2], "Animation22GetCurrentTimeAsDouble") != NULL) ? "Animation::DispatchPlaybackEvent() -> Animation::GetCurrentTimeAsDouble()" : \
+  ""))))
 
-#define CALLER() \
-  ((strstr(strs[1], "Performance3Now") != NULL) ? "performance.now()" : \
-  ((strstr(strs[1], "dom5Event13TimeStampImplEv") != NULL) ? "Event.timeStamp" : \
-  ((strstr(strs[2], "AnimationTimeline22GetCurrentTimeAsDouble") != NULL) ? "AnimationTimeline::GetCurrentTimeAsDouble" : \
-  "")))
+// I think these circumstances are okay
+#define CALLER_CAN_GO_BACKWARDS() \
+  ((strcmp("performance.now()", CALLER(lastCaller)) == 0 && \
+    strcmp("AnimationTimeline::GetCurrentTimeAsDouble", CALLER(thisCaller)) == 0) ? true : false \
+  )
+
+#define LOG_TIMESTAMP(aTime, timeOrigin) \
+  MOZ_LOG(gResistFingerprintingLog, LogLevel::Debug, \
+    ("Parent: %d Combined Timestamp: %f Raw: %f Caller: %s", XRE_IsParentProcess(), (aTime + timeOrigin), aTime, CALLER(thisCaller))); \
+  if (canJitter && timeOrigin != 0) { \
+    if (aTime + timeOrigin < lastSeenTimestamp && !CALLER_CAN_GO_BACKWARDS()) { \
+      MOZ_LOG(gResistFingerprintingLog, LogLevel::Debug, \
+        ("===============> TIME WENT BACKWARDS!! Last: %f This: %f", lastSeenTimestamp, (aTime + timeOrigin))); \
+    } else if (aTime + timeOrigin < lastSeenTimestamp) { \
+      MOZ_LOG(gResistFingerprintingLog, LogLevel::Debug, \
+        ("               > Time went backwards, but we think its okay. Last: %f This: %f", lastSeenTimestamp, (aTime + timeOrigin))); \
+    } \
+    lastSeenTimestamp = (aTime + timeOrigin); \
+  }
 
 #define PRINT_STACKTRACE() \
-  if (strcmp(CALLER(), "") == 0) { \
+  if (strcmp(CALLER(thisCaller), "") == 0) { \
     for (int i = 0; i < frames; ++i) { \
-      MOZ_LOG(gResistFingerprintingLog, LogLevel::Debug, ("  %s\n", strs[i])); \
+      MOZ_LOG(gResistFingerprintingLog, LogLevel::Debug, ("  %s\n", thisCaller[i])); \
     } \
   } \
-  free(strs);
+  if (canJitter && timeOrigin != 0) { \
+    free(lastCaller); \
+    lastCaller = thisCaller; \
+  }
+
+static double lastSeenTimestamp = 0;
+static char** lastCaller = NULL;
+#endif
 
 /* static */
 double
 nsRFPService::ReduceTimePrecisionAsMSecs(double aTime, double timeOrigin /* = 0 */, bool canJitter /* = true */)
 {
 #if defined(DEBUG)
   INIT_STACKTRACE();
-  MOZ_LOG(gResistFingerprintingLog, LogLevel::Debug,
-    ("Parent: %d Timestamp: %f Caller: %s", XRE_IsParentProcess(), (aTime + timeOrigin), CALLER()));
+  LOG_TIMESTAMP(aTime, timeOrigin);
   PRINT_STACKTRACE();
 #endif
 
   if (!IsTimerPrecisionReductionEnabled()) {
     return aTime;
   }
   const double resolutionMSec = TimerResolution() / 1000.0;
   double clamped = floor(aTime / resolutionMSec) * resolutionMSec;
@@ -202,18 +230,17 @@ nsRFPService::ReduceTimePrecisionAsMSecs
 }
 
 /* static */
 double
 nsRFPService::ReduceTimePrecisionAsUSecs(double aTime, double timeOrigin /* = 0 */, bool canJitter /* = true */)
 {
 #if defined(DEBUG)
   INIT_STACKTRACE();
-  MOZ_LOG(gResistFingerprintingLog, LogLevel::Debug,
-    ("Parent: %d Timestamp: %f Caller: %s", XRE_IsParentProcess(), (aTime + timeOrigin), CALLER()));
+  LOG_TIMESTAMP(aTime / 1000.0, timeOrigin);
   PRINT_STACKTRACE();
 #endif
 
   if (!IsTimerPrecisionReductionEnabled()) {
     return aTime;
   }
   double resolutionUSec = TimerResolution();
   double clamped = floor(aTime / resolutionUSec) * resolutionUSec;
@@ -244,18 +271,17 @@ nsRFPService::CalculateTargetVideoResolu
 }
 
 /* static */
 double
 nsRFPService::ReduceTimePrecisionAsSecs(double aTime, double timeOrigin /* = 0 */, bool canJitter /* = true */)
 {
 #if defined(DEBUG)
   INIT_STACKTRACE();
-  MOZ_LOG(gResistFingerprintingLog, LogLevel::Debug,
-    ("Parent: %d Timestamp: %f Caller: %s", XRE_IsParentProcess(), (aTime + timeOrigin), CALLER()));
+  LOG_TIMESTAMP(aTime * 1000.0, timeOrigin);
   PRINT_STACKTRACE();
 #endif
 
   if (!IsTimerPrecisionReductionEnabled()) {
     return aTime;
   }
   double clamped;
   double resolutionUSec = TimerResolution();