kp_info_cacher inappropriately using local TZ calculations

[saramsey]

This code in kp_info_cacher.py is TZ-dependent, right?

        # At this point the KP info caches must NOT be in the process of being
        # refreshed, so we create/update if needed.  In particular, this ensures
        # that the caches will be created/fresh even on dev machines, that don't
        # run the background refresh task.
        one_day_ago = datetime.now() - timedelta(hours=24)

        smart_api_and_meta_map_pathlib_path = pathlib.Path(self.smart_api_and_meta_map_cache)
        try:
            if not smart_api_and_meta_map_pathlib_path.exists():
                raise Exception("KP info cache(s) do not exist.")
            elif (datetime.fromtimestamp(smart_api_and_meta_map_pathlib_path.stat().st_mtime) < one_day_ago):
                raise Exception("KP info cache(s) are older than 24 hours.")
            
        except Exception as e:
            log.error(f"Unable to load KP info caches: {e}")

I kinda think we should be using POSIX time or explicitly UTC, perhaps like this:

import time
from datetime import timedelta

mtime = smart_api_and_meta_map_pathlib_path.stat().st_mtime
if time.time() - mtime > 24 * 3600:
    raise Exception("KP info cache(s) are older than 24 hours.")

[saramsey]

Also, ARAX_response.py logfile timestamps do not have the TZ indicated:

2026-03-09T05:16:24.453880 INFO: (107758) [] Processing action 'expand' with parameters {'': 'true'}
2026-03-09T05:16:24.454151 ERROR: (107758) [UnknownError] Unable to load KP info caches: KP info cache(s) are older than 24 hours.

These should indicate the TZ (which in an EC2- and Docker-deployed ARAX would almost always be UTC, but someone or something analyzing the logfile may not know that).

[saramsey]

@hodgesf what's the status on this?

[hodgesf]

Hi @saramsey, sorry I did write code to fix the above bug, but found another issue (maybe). See below for update on proposed changes, and additional bug found. Let me know if the "bug" I found is actually desired behavior or not. If not, I will fix it and make a PR. If it is, then I will make a PR and leave it as is.

1. Switch to POSIX time for the staleness check

Replace the naive-datetime comparison with a straight time.time() - st_mtime check. Both values are UTC epoch floats, so there's no TZ ambiguity:

in kp_info_cacher.py:

import time

ONE_DAY_SECONDS = 24 * 3600
mtime = smart_api_and_meta_map_pathlib_path.stat().st_mtime
if time.time() - mtime > ONE_DAY_SECONDS:
    raise Exception("KP info cache(s) are older than 24 hours.")

This drops the datetime.now() and datetime.fromtimestamp() calls entirely. The exists() guard stays as-is since we still need that before calling stat().

2. Make log timestamps TZ-aware

in ARAX_response.py, change:

timestamp = str(datetime.datetime.now().isoformat())

to:

timestamp = datetime.datetime.now(datetime.timezone.utc).isoformat()

This gives us timestamps like 2026-03-09T05:16:24.453880+00:00 instead of the current ambiguous format.

Both are small, self-contained changes. I'll put them up in a PR shortly.

Before I do though, I noticed the current try/except block in kp_info_cacher.py has a control flow issue:

• when the cache is missing or stale, the code raises an exception inside a try, catches it, logs an error, and then falls through to open() the cache file anyway.
• If the cache doesn't exist, that'll crash. If it's stale, it silently loads stale data right after logging an error saying it couldn't.

Should I fix this so that when the cache is missing or stale, we actually call self.refresh_kp_info_caches() before proceeding to load:

needs_refresh = False
if not smart_api_and_meta_map_pathlib_path.exists():
    log.warning("KP info cache(s) do not exist; refreshing.")
    needs_refresh = True
elif time.time() - smart_api_and_meta_map_pathlib_path.stat().st_mtime > ONE_DAY_SECONDS:
    log.warning("KP info cache(s) are older than 24 hours; refreshing.")
    needs_refresh = True

if needs_refresh:
    try:
        self.refresh_kp_info_caches()
    except Exception as e:
        log.error(f"Unable to refresh KP info caches: {e}")
        raise 

Will need to double-check that calling refresh_kp_info_caches() here doesn't race with the background refresh task (it writes a PID file to prevent concurrent refreshes, so should be fine, but worth verifying).

[saramsey]

I concur with @hodgesf that kp_info_cacher.py::load_kp_info_caches seemingly tries to continue to open the cache file even after raising an exception that the file doesn't exist. So @hodgesf and I are thinking about having Frankie fixing the code along these lines:

[saramsey]

Frankie I like your proposed code simplification (in item 1 above):

import time

ONE_DAY_SECONDS = 24 * 3600
mtime = smart_api_and_meta_map_pathlib_path.stat().st_mtime
if time.time() - mtime > ONE_DAY_SECONDS:
    raise Exception("KP info cache(s) are older than 24 hours.")

[saramsey]

@hodgesf your proposed changes to the logging code also look good, except I don't think we want microsecond accuracy (millisecond is fine). So could you please change that to only millisecond accuracy? Otherwise it's just a lot of digits cluttering up the logfile.

Also, as concerns the proposed change to the logfile timestamp format, please loop in @edeutsch so he is aware of this change. Thanks.