fix(writer): logging request timing (bp #2064) (#2069)

* fix(writer): logging request timing (#2064)

The logging was moved around in a previous patch. Also add a regression
test for the logging.

(cherry picked from commit 47c4da2)

* fix merge conflict

* fix test

The test assumed that an empty payload could be sent with the agent
however the patch for this is not backported

Co-authored-by: Kyle Verhoog <[email protected]>
Co-authored-by: Kyle Verhoog <[email protected]>

Author: mergify[bot]

ddtrace/internal/writer.py

@@ -194,15 +194,15 @@ def _put(self, data, headers):
             try:
                 conn.request("PUT", self._endpoint, data, headers)
                 resp = compat.get_connection_response(conn)
+                t = sw.elapsed()
+                if t >= self.interval:
+                    log_level = logging.WARNING
+                else:
+                    log_level = logging.DEBUG
+                log.log(log_level, "sent %s in %.5fs", _human_size(len(data)), t)
                 return Response.from_http_response(resp)
             finally:
                 conn.close()
-            t = sw.elapsed()
-            if t >= self.interval:
-                log_level = logging.WARNING
-            else:
-                log_level = logging.DEBUG
-            log.log(log_level, "sent %s in %.5fs", _human_size(len(data)), t)
 
     @property
     def agent_url(self):

tests/__init__.py

@@ -911,3 +911,8 @@ def __eq__(self, other):
 class AnyInt(object):
     def __eq__(self, other):
         return isinstance(other, int)
+
+
+class AnyFloat(object):
+    def __eq__(self, other):
+        return isinstance(other, float)

tests/integration/test_integration.py

@@ -1,3 +1,4 @@
+import logging
 import os
 import subprocess
 import sys
@@ -16,7 +17,9 @@
 from ddtrace.sampler import RateSampler
 from ddtrace.sampler import SamplingRule
 from ddtrace.vendor import six
+from tests import AnyFloat
 from tests import AnyInt
+from tests import AnyStr
 from tests import TracerTestCase
 from tests import override_global_config
 from tests import snapshot
@@ -504,3 +507,16 @@ def test_sampling(self, tracer):
                 pass
 
         tracer.shutdown()
+
+
+@pytest.mark.skipif(AGENT_VERSION == "testagent", reason="Test agent doesn't support empty trace payloads.")
+def test_flush_log(caplog):
+    caplog.set_level(logging.INFO)
+    tracer = Tracer()
+    with tracer.trace("test"):
+        pass
+
+    with mock.patch("ddtrace.internal.writer.log") as log:
+        tracer.writer.flush_queue()
+        calls = [mock.call(logging.DEBUG, "sent %s in %.5fs", AnyStr(), AnyFloat())]
+        log.log.assert_has_calls(calls)