Skip to content
Draft
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -14,6 +14,7 @@ A task that passed on a log name the checker should not have trusted can report

- One stray log name can no longer hold a dead job at `FRESH`. The checker took the last matching filename in sort order, so a name stamped in the future, or one with a date that does not exist, was read as the newest run. Its age came out negative or missing, so the staleness test never fired, and the success line inside it passed the task while every real log went unread. A name now counts only when its stamp is a real time no more than five minutes ahead of the clock, and the newest log is chosen by that time. Each skipped name is listed in the task's detail line.
- A task whose log names were all skipped reports `LOG_UNREADABLE`. Before, it reported `NEVER_RAN`, or `MANUAL_OK` on a manual task, which never goes stale.
- An age measured across a daylight-saving change is no longer an hour out. With `timezone` set to a named zone, the checker subtracted two readings of that zone's wall clock, so noon to noon read 24 hours on the night the clocks went back, where 25 had passed, and 24 on the night they went forward, where 23 had. A job could stay `FRESH` an hour past its window, or turn `STALE` an hour early. Ages are now taken in UTC. `local`, `UTC` and fixed offsets were never affected.
- `{time}` in `log_pattern` accepts `HHMMSS` as well as `HHMM`. A producer that stamps seconds into its log names used to match nothing, with the same `MANUAL_OK` result.

### Changed
Expand Down
17 changes: 15 additions & 2 deletions deadmans.py
Original file line number Diff line number Diff line change
Expand Up @@ -188,6 +188,19 @@ def as_aware(value: dt.datetime, tz: dt.tzinfo) -> dt.datetime:
return value if value.tzinfo is not None else value.replace(tzinfo=tz)


def hours_between(later: dt.datetime, earlier: dt.datetime) -> float:
"""Elapsed hours from `earlier` to `later`, both aware, measured in UTC.

Python subtracts two datetimes that share one tzinfo object by their
wall-clock readings and ignores the offset each one carries. In a named
zone that is an hour out whenever a daylight-saving change falls between
them: noon to noon across a fall-back night reads 24 hours where 25 went
by. Converting both to UTC first gives the time that really passed.
"""
utc = dt.timezone.utc
return (later.astimezone(utc) - earlier.astimezone(utc)).total_seconds() / 3600.0


class Artefact(NamedTuple):
"""A second freshness signal, keyed to what the job produces.

Expand Down Expand Up @@ -771,7 +784,7 @@ def _check_task(
)

def from_artefact(when: dt.datetime, note: str) -> Status:
age = (now - when).total_seconds() / 3600.0
age = hours_between(now, when)
label = task.artefact.path.name
if age > task.max_age_hours:
return Status(
Expand Down Expand Up @@ -803,7 +816,7 @@ def from_artefact(when: dt.datetime, note: str) -> Status:
return Status(task.name, "NEVER_RAN", None, None, "no log file matches pattern")

log_time = parse_log_time(log, task.name, log_pattern, tz)
age_hours = (now - log_time).total_seconds() / 3600.0 if log_time else None
age_hours = hours_between(now, log_time) if log_time else None

try:
body = log.read_text(encoding="utf-8", errors="replace")
Expand Down
95 changes: 95 additions & 0 deletions test_deadmans.py
Original file line number Diff line number Diff line change
Expand Up @@ -428,6 +428,101 @@ def test_naive_now_is_read_in_the_configured_zone(self) -> None:
self.assertAlmostEqual(result.age_hours, 4.0, places=3)


class TestAgeAcrossDaylightSavingChange(TempDirCase):
"""An age is the time that passed, whatever the wall clock did meanwhile.

Two datetimes that share one named zone subtract by wall clock in Python,
so noon to noon across a clock change used to read 24 hours either way.
Each window below sits between the wall-clock figure and the real one, so
the state is wrong as well as the number if the age is taken that way.
"""

def setUp(self) -> None:
super().setUp()
self.log_dir = self.tmp_path / "logs"

def zone(self, name: str) -> ZoneInfo:
try:
return ZoneInfo(name)
except ZoneInfoNotFoundError:
self.skipTest("no tz database on this host")

def task(self, max_age_hours: float, **keys) -> deadmans.Task:
return deadmans.Task(
name="scheduled",
max_age_hours=max_age_hours,
sentinel="OK_SENTINEL",
failure_sentinel=None,
manual=False,
**keys,
)

def check(self, task: deadmans.Task, now: dt.datetime) -> deadmans.Status:
return deadmans.check_task(
task, self.log_dir, deadmans.DEFAULT_LOG_PATTERN, now=now, tz=now.tzinfo
)

def ledger_task(self, max_age_hours: float, stamp: str) -> deadmans.Task:
ledger = self.tmp_path / "findings.jsonl"
ledger.write_text(json.dumps({"ts": stamp}) + "\n", encoding="utf-8")
artefact = deadmans.parse_artefact(
{"path": str(ledger), "format": "jsonl"}, self.tmp_path, "test"
)
return self.task(max_age_hours, artefact=artefact)

def test_hours_between_counts_the_repeated_hour(self) -> None:
# Clocks in New York go back an hour at 02:00 on 2026-11-01.
zone = self.zone("America/New_York")
earlier = dt.datetime(2026, 10, 31, 12, 0, tzinfo=zone)
later = dt.datetime(2026, 11, 1, 12, 0, tzinfo=zone)
self.assertAlmostEqual((later - earlier).total_seconds() / 3600.0, 24.0)
self.assertAlmostEqual(deadmans.hours_between(later, earlier), 25.0)

def test_hours_between_drops_the_skipped_hour(self) -> None:
# Clocks in Sydney go forward an hour at 02:00 on 2026-10-04.
zone = self.zone("Australia/Sydney")
earlier = dt.datetime(2026, 10, 3, 12, 0, tzinfo=zone)
later = dt.datetime(2026, 10, 4, 12, 0, tzinfo=zone)
self.assertAlmostEqual((later - earlier).total_seconds() / 3600.0, 24.0)
self.assertAlmostEqual(deadmans.hours_between(later, earlier), 23.0)

def test_hours_between_is_plain_across_fixed_offsets(self) -> None:
plus_ten = dt.timezone(dt.timedelta(hours=10))
earlier = dt.datetime(2026, 1, 15, 0, 0, tzinfo=dt.timezone.utc)
later = dt.datetime(2026, 1, 15, 20, 0, tzinfo=plus_ten)
self.assertAlmostEqual(deadmans.hours_between(later, earlier), 10.0)

def test_log_age_across_a_fall_back_change_is_stale(self) -> None:
zone = self.zone("America/New_York")
write_log(self.log_dir, "scheduled_2026-10-31-1200.log", "OK_SENTINEL\n")
now = dt.datetime(2026, 11, 1, 12, 0, tzinfo=zone)
result = self.check(self.task(24.5), now)
self.assertAlmostEqual(result.age_hours, 25.0, places=3)
self.assertEqual(result.state, "STALE")

def test_log_age_across_a_spring_forward_change_is_fresh(self) -> None:
zone = self.zone("Australia/Sydney")
write_log(self.log_dir, "scheduled_2026-10-03-1200.log", "OK_SENTINEL\n")
now = dt.datetime(2026, 10, 4, 12, 0, tzinfo=zone)
result = self.check(self.task(23.5), now)
self.assertAlmostEqual(result.age_hours, 23.0, places=3)
self.assertEqual(result.state, "FRESH")

def test_artefact_age_across_a_fall_back_change_is_stale(self) -> None:
zone = self.zone("America/New_York")
now = dt.datetime(2026, 11, 1, 12, 0, tzinfo=zone)
result = self.check(self.ledger_task(24.5, "2026-10-31T12:00:00"), now)
self.assertAlmostEqual(result.age_hours, 25.0, places=3)
self.assertEqual(result.state, "STALE")

def test_artefact_age_across_a_spring_forward_change_is_fresh(self) -> None:
zone = self.zone("Australia/Sydney")
now = dt.datetime(2026, 10, 4, 12, 0, tzinfo=zone)
result = self.check(self.ledger_task(23.5, "2026-10-03T12:00:00"), now)
self.assertAlmostEqual(result.age_hours, 23.0, places=3)
self.assertEqual(result.state, "FRESH")


class TestLatestLogAndParseTime(TempDirCase):
def test_missing_log_dir_returns_none(self) -> None:
missing = self.tmp_path / "nope"
Expand Down
Loading