Handle inaccuracies in time conversions

Due to the differences between decimal and binary float
representations, some time values yield "suprising" results when
performing float arithmetic operations to convert seconds to
nanoseconds and vice versa.

opentracing-shim/src/opentracingshim/__init__.py

@@ -68,11 +68,13 @@ def set_tag(self, key, value):
         return self
 
     def log_kv(self, key_values, timestamp=None):
-        if timestamp is None:
-            timestamp = util.time_ns()
+        if timestamp is not None:
+            event_timestamp = util.time_seconds_to_ns(timestamp)
+        else:
+            event_timestamp = util.time_ns()
 
         event_name = util.event_name_from_kv(key_values)
-        event = Event(event_name, timestamp, key_values)
+        event = Event(event_name, event_timestamp, key_values)
         self._otel_span.add_lazy_event(event)
 
         # Return self for call chaining.

opentracing-shim/tests/test_shim.py

@@ -118,7 +118,11 @@ def test_explicit_start_time(self):
         now = time.time()
         with self.shim.start_active_span("TestSpan", start_time=now) as scope:
             result = util.time_seconds_from_ns(scope.span.unwrap().start_time)
-            self.assertEqual(result, now)
+            # Tolerate inaccuracies of less than a microsecond.
+            # TODO: Put a link to an explanation in the docs.
+            # TODO: This seems to work consistently, but we should find out the
+            # biggest possible loss of precision.
+            self.assertAlmostEqual(result, now, places=6)
 
     def test_explicit_end_time(self):
         """Test `end_time` argument of `finish()` method."""
@@ -128,7 +132,11 @@ def test_explicit_end_time(self):
         span.finish(now)
 
         end_time = util.time_seconds_from_ns(span.unwrap().end_time)
-        self.assertEqual(end_time, now)
+        # Tolerate inaccuracies of less than a microsecond.
+        # TODO: Put a link to an explanation in the docs.
+        # TODO: This seems to work consistently, but we should find out the
+        # biggest possible loss of precision.
+        self.assertAlmostEqual(end_time, now, places=6)
 
     def test_explicit_span_activation(self):
         """Test manual activation and deactivation of a span."""
@@ -355,9 +363,17 @@ def test_log_kv(self):
             self.assertIsNotNone(span.unwrap().events[0].timestamp)
 
             # Test explicit timestamp.
-            now = opentracingshim.util.time_ns()
+            now = time.time()
             span.log_kv({"foo": "bar"}, now)
-            self.assertEqual(span.unwrap().events[1].timestamp, now)
+            result = util.time_seconds_from_ns(
+                span.unwrap().events[1].timestamp
+            )
+            self.assertEqual(span.unwrap().events[1].attributes["foo"], "bar")
+            # Tolerate inaccuracies of less than a microsecond.
+            # TODO: Put a link to an explanation in the docs.
+            # TODO: This seems to work consistently, but we should find out the
+            # biggest possible loss of precision.
+            self.assertAlmostEqual(result, now, places=6)
 
     def test_span_context(self):
         """Test construction of `SpanContextWrapper` objects."""

opentracing-shim/tests/test_util.py

@@ -48,3 +48,18 @@ def test_time_seconds_from_ns(self):
         result = util.time_seconds_from_ns(time_nanoseconds)
 
         self.assertEqual(result, time_nanoseconds / 1e9)
+
+    def test_time_conversion_precision(self):
+        """Verify time conversion from seconds to nanoseconds and vice versa is
+        accurate enough.
+        """
+
+        time_seconds = 1570484241.9501917
+        time_nanoseconds = util.time_seconds_to_ns(time_seconds)
+        result = util.time_seconds_from_ns(time_nanoseconds)
+
+        # Tolerate inaccuracies of less than a microsecond.
+        # TODO: Put a link to an explanation in the docs.
+        # TODO: This seems to work consistently, but we should find out the
+        # biggest possible loss of precision.
+        self.assertAlmostEqual(result, time_seconds, places=6)