Rewrite utcnow usage (#801)

* Remove use of datetime.utcnow()

* Fix test

* Centralize datetime formatting for agent

* Use isoformat after all

* Test fixes

* Possible fix

* Update CHANGELOG

---------

Co-authored-by: Adam Johnson <me@adamj.eu>

Author: lancetarn

CHANGELOG.md

@@ -2,6 +2,9 @@
 
 ## Pending
 
+- Change to tz-aware dates internally (Issue #799)
+- psutil dependency un-pin (#790)
+
 ## [3.2.0] 2024-09-12
 ### Added
 - "Operation" attribute added to TrackedRequest class to better support development of [scout_apm_python_logging](https://github.com/scoutapp/scout_apm_python_logging)

DEVELOPMENT.md

@@ -85,7 +85,7 @@ Running the test app
 --------------------
 
 Note: this has not been tested in a while. Instead, the
-[scout-test-apps repo](https://github.com/tim-schilling/scout-test-apps) has
+[scout-test-apps repo](https://github.com/scoutapp/scout-test-apps) has
 been used with many individual scout apps.
 
 Add the following env variables:
@@ -133,7 +133,6 @@ architectures. Its documentation is excellent.
 Documentation
 -------------
 
-The user documentation is stored in the [slate_apm_help
-repo](https://github.com/scoutapp/slate_apm_help) in the
-`source/_includes/python.md` file. Make relevant changes there when developing
-features.
+The user documentation is stored in the [scout-documentation](https://github.com/scoutapp/scout-documentation) repo.
+It is private to the Scout Monitoring team; if you want to submit a feature feel free to
+send us some Markdown and we will get it added.

src/scout_apm/celery.py

@@ -29,7 +29,9 @@ def get_safe_settings():
 
 def before_task_publish_callback(headers=None, properties=None, **kwargs):
     if "scout_task_start" not in headers:
-        headers["scout_task_start"] = datetime_to_timestamp(dt.datetime.utcnow())
+        headers["scout_task_start"] = datetime_to_timestamp(
+            dt.datetime.now(dt.timezone.utc)
+        )
 
 
 def task_prerun_callback(task=None, **kwargs):

src/scout_apm/core/agent/commands.py

@@ -1,5 +1,6 @@
 # coding=utf-8
 
+import datetime as dt
 import logging
 import re
 
@@ -10,6 +11,18 @@
 key_regex = re.compile(r"^[a-zA-Z0-9]{20}$")
 
 
+def format_dt_for_core_agent(event_time: dt.datetime) -> str:
+    """
+    Returns expected format for Core Agent compatibility.
+    Coerce any tz-aware datetime to UTC just in case.
+    """
+    # if we somehow got a naive datetime, convert it to UTC
+    if event_time.tzinfo is None:
+        logger.warning("Naive datetime passed to format_dt_for_core_agent")
+        event_time = event_time.astimezone(dt.timezone.utc)
+    return event_time.isoformat()
+
+
 class Register(object):
     __slots__ = ("app", "key", "hostname")
 
@@ -49,7 +62,7 @@ def __init__(self, timestamp, request_id, span_id, parent, operation):
     def message(self):
         return {
             "StartSpan": {
-                "timestamp": self.timestamp.isoformat() + "Z",
+                "timestamp": format_dt_for_core_agent(self.timestamp),
                 "request_id": self.request_id,
                 "span_id": self.span_id,
                 "parent_id": self.parent,
@@ -69,7 +82,7 @@ def __init__(self, timestamp, request_id, span_id):
     def message(self):
         return {
             "StopSpan": {
-                "timestamp": self.timestamp.isoformat() + "Z",
+                "timestamp": format_dt_for_core_agent(self.timestamp),
                 "request_id": self.request_id,
                 "span_id": self.span_id,
             }
@@ -86,7 +99,7 @@ def __init__(self, timestamp, request_id):
     def message(self):
         return {
             "StartRequest": {
-                "timestamp": self.timestamp.isoformat() + "Z",
+                "timestamp": format_dt_for_core_agent(self.timestamp),
                 "request_id": self.request_id,
             }
         }
@@ -102,7 +115,7 @@ def __init__(self, timestamp, request_id):
     def message(self):
         return {
             "FinishRequest": {
-                "timestamp": self.timestamp.isoformat() + "Z",
+                "timestamp": format_dt_for_core_agent(self.timestamp),
                 "request_id": self.request_id,
             }
         }
@@ -121,7 +134,7 @@ def __init__(self, timestamp, request_id, span_id, tag, value):
     def message(self):
         return {
             "TagSpan": {
-                "timestamp": self.timestamp.isoformat() + "Z",
+                "timestamp": format_dt_for_core_agent(self.timestamp),
                 "request_id": self.request_id,
                 "span_id": self.span_id,
                 "tag": self.tag,
@@ -142,7 +155,7 @@ def __init__(self, timestamp, request_id, tag, value):
     def message(self):
         return {
             "TagRequest": {
-                "timestamp": self.timestamp.isoformat() + "Z",
+                "timestamp": format_dt_for_core_agent(self.timestamp),
                 "request_id": self.request_id,
                 "tag": self.tag,
                 "value": self.value,
@@ -162,7 +175,7 @@ def __init__(self, event_type, event_value, source, timestamp):
     def message(self):
         return {
             "ApplicationEvent": {
-                "timestamp": self.timestamp.isoformat() + "Z",
+                "timestamp": format_dt_for_core_agent(self.timestamp),
                 "event_type": self.event_type,
                 "event_value": self.event_value,
                 "source": self.source,

src/scout_apm/core/metadata.py

@@ -4,7 +4,7 @@
 import sys
 from os import getpid
 
-from scout_apm.core.agent.commands import ApplicationEvent
+from scout_apm.core.agent.commands import ApplicationEvent, format_dt_for_core_agent
 from scout_apm.core.agent.socket import CoreAgentSocketThread
 from scout_apm.core.config import scout_config
 
@@ -15,7 +15,7 @@ def report_app_metadata():
             event_type="scout.metadata",
             event_value=get_metadata(),
             source="Pid: " + str(getpid()),
-            timestamp=dt.datetime.utcnow(),
+            timestamp=dt.datetime.now(dt.timezone.utc),
         )
     )
 
@@ -24,7 +24,7 @@ def get_metadata():
     data = {
         "language": "python",
         "language_version": "{}.{}.{}".format(*sys.version_info[:3]),
-        "server_time": dt.datetime.utcnow().isoformat() + "Z",
+        "server_time": format_dt_for_core_agent(dt.datetime.now(dt.timezone.utc)),
         "framework": scout_config.value("framework"),
         "framework_version": scout_config.value("framework_version"),
         "environment": "",

src/scout_apm/core/queue_time.py

@@ -86,7 +86,7 @@ def track_job_queue_time(
         bool: Whether we succeeded in marking queue time for the job. Used for testing.
     """
     if header_value is not None:
-        now = datetime_to_timestamp(dt.datetime.utcnow()) * 1e9
+        now = datetime_to_timestamp(dt.datetime.now(dt.timezone.utc)) * 1e9
         try:
             ambiguous_float_start = typing.cast(float, header_value)
             start = _convert_ambiguous_timestamp_to_ns(ambiguous_float_start)

src/scout_apm/core/samplers/cpu.py

@@ -14,15 +14,15 @@ class Cpu(object):
     human_name = "Process CPU"
 
     def __init__(self):
-        self.last_run = dt.datetime.utcnow()
+        self.last_run = dt.datetime.now(dt.timezone.utc)
         self.last_cpu_times = psutil.Process().cpu_times()
         self.num_processors = psutil.cpu_count()
         if self.num_processors is None:
             logger.debug("Could not determine CPU count - assuming there is one.")
             self.num_processors = 1
 
     def run(self):
-        now = dt.datetime.utcnow()
+        now = dt.datetime.now(dt.timezone.utc)
         process = psutil.Process()  # get a handle on the current process
         cpu_times = process.cpu_times()
 

src/scout_apm/core/samplers/thread.py

@@ -30,7 +30,7 @@ def run(self):
                     event = ApplicationEvent(
                         event_value=event_value,
                         event_type=event_type,
-                        timestamp=dt.datetime.utcnow(),
+                        timestamp=dt.datetime.now(dt.timezone.utc),
                         source="Pid: " + str(os.getpid()),
                     )
                     CoreAgentSocketThread.send(event)

src/scout_apm/core/tracked_request.py

@@ -49,7 +49,7 @@ def instance(cls):
 
     def __init__(self):
         self.request_id = "req-" + str(uuid4())
-        self.start_time = dt.datetime.utcnow()
+        self.start_time = dt.datetime.now(dt.timezone.utc)
         self.end_time = None
         self.active_spans = []
         self.complete_spans = []
@@ -147,7 +147,7 @@ def finish(self):
 
         logger.debug("Stopping request: %s", self.request_id)
         if self.end_time is None:
-            self.end_time = dt.datetime.utcnow()
+            self.end_time = dt.datetime.now(dt.timezone.utc)
 
         if self.is_real_request:
             self.tag("mem_delta", self._get_mem_delta())
@@ -219,7 +219,7 @@ def __init__(
         should_capture_backtrace=True,
     ):
         self.span_id = "span-" + str(uuid4())
-        self.start_time = dt.datetime.utcnow()
+        self.start_time = dt.datetime.now(dt.timezone.utc)
         self.end_time = None
         self.request_id = request_id
         self.operation = operation
@@ -238,7 +238,7 @@ def __repr__(self):
         )
 
     def stop(self):
-        self.end_time = dt.datetime.utcnow()
+        self.end_time = dt.datetime.now(dt.timezone.utc)
         self.end_objtrace_counts = objtrace.get_counts()
 
     def tag(self, key, value):
@@ -254,7 +254,9 @@ def duration(self):
             return (self.end_time - self.start_time).total_seconds()
         else:
             # Current, running duration
-            return (dt.datetime.utcnow() - self.start_time).total_seconds()
+            return (
+                dt.datetime.now(tz=dt.timezone.utc) - self.start_time
+            ).total_seconds()
 
     # Add any interesting annotations to the span. Assumes that we are in the
     # process of stopping this span.

src/scout_apm/rq.py

@@ -1,6 +1,7 @@
 # coding=utf-8
 
 import datetime as dt
+import logging
 
 import wrapt
 from rq import SimpleWorker as RqSimpleWorker
@@ -14,6 +15,8 @@
 install_attempted = False
 installed = None
 
+logger = logging.getLogger(__name__)
+
 
 def ensure_scout_installed():
     global install_attempted, installed
@@ -65,7 +68,12 @@ def wrap_perform(wrapped, instance, args, kwargs):
     tracked_request.is_real_request = True
     tracked_request.tag("task_id", instance.get_id())
     tracked_request.tag("queue", instance.origin)
-    queue_time = (dt.datetime.utcnow() - instance.enqueued_at).total_seconds()
+    # rq strips tzinfo from enqueued_at during serde in at least some cases
+    # internally everything uses UTC naive datetimes, so we operate on that
+    # assumption here.
+    if instance.enqueued_at.tzinfo is None:
+        queued_at = instance.enqueued_at.replace(tzinfo=dt.timezone.utc)
+    queue_time = (dt.datetime.now(dt.timezone.utc) - queued_at).total_seconds()
     tracked_request.tag("queue_time", queue_time)
     operation = "Job/{}".format(instance.func_name)
     tracked_request.operation = operation