|
16 | 16 | from datadog_checks.postgres import PostgreSql |
17 | 17 | from datadog_checks.postgres.data_observability import EVENT_TRACK_TYPE |
18 | 18 |
|
19 | | -# --------------------------------------------------------------------------- |
20 | | -# Cron schedule / lateness helpers |
21 | | -# --------------------------------------------------------------------------- |
22 | | -# A "frozen" epoch that sits between two hourly boundaries: |
23 | | -# xx:49:00 (previous hour + 49 min) |
24 | | -# xx:50:00 (next cron tick for "50 * * * *") |
25 | | -# xx:51:00 (tick for "51 * * * *") |
26 | | -# |
27 | | -# We use an absolute epoch so croniter's calendar arithmetic stays stable. |
28 | | -# 2026-01-01 00:49:00 UTC → 1751331940 (approx; exact value computed below) |
29 | | -_BASE_EPOCH = calendar.timegm(datetime.datetime(2026, 1, 1, 0, 49, 0).timetuple()) # 00:49:00 UTC |
| 19 | +# Fixed epoch (2026-01-01 00:49:00 UTC) chosen to sit 1 minute before the ":50" cron tick used in tests. |
| 20 | +_BASE_EPOCH = calendar.timegm(datetime.datetime(2026, 1, 1, 0, 49, 0).timetuple()) |
30 | 21 |
|
31 | 22 | pytestmark = pytest.mark.unit |
32 | 23 |
|
@@ -531,12 +522,11 @@ def test_multi_query_different_dbnames(aggregator, pg_instance): |
531 | 522 | } |
532 | 523 |
|
533 | 524 |
|
534 | | -def _make_cron_check(pg_instance, queries=None, fake_time=None): |
535 | | - """Create a check with a cron-scheduled query, optionally monkeypatching time.time.""" |
| 525 | +def _make_cron_check(pg_instance, queries=None): |
| 526 | + """Create a check with a cron-scheduled query.""" |
536 | 527 | if queries is None: |
537 | 528 | queries = [deepcopy(CRON_QUERY)] |
538 | | - check = _create_check(pg_instance, queries=queries) |
539 | | - return check |
| 529 | + return _create_check(pg_instance, queries=queries) |
540 | 530 |
|
541 | 531 |
|
542 | 532 | def test_schedule_query_does_not_fire_before_tick(pg_instance, monkeypatch): |
@@ -582,19 +572,11 @@ def test_schedule_advances_after_run(pg_instance, monkeypatch): |
582 | 572 | check = _make_cron_check(pg_instance) |
583 | 573 | check.db_pool = _mock_db_pool(mock_conn) |
584 | 574 |
|
585 | | - # First run: registers first future tick (00:50:00 is already past, so next is 01:50:00) |
| 575 | + # First run at 00:50:05: registers next_run = 01:50:00 (croniter.get_next is strictly after now); no fire. |
586 | 576 | check.data_observability.run_job() |
587 | | - # At this point next_run should be set (but nothing fired yet — it's first sight) |
588 | 577 | mid = CRON_QUERY['monitor_id'] |
589 | 578 | first_next_run = check.data_observability._next_run[mid] |
590 | 579 |
|
591 | | - # Second run: now we're past the registered next_run (which was set to 00:50:00) |
592 | | - # Actually at 00:50:05 the first sight records 00:50:00 as next and skips. Let me re-check. |
593 | | - # At 00:50:05 > 00:49:00 = _BASE_EPOCH, so first sight computes next_run = 00:50:00 (already past). |
594 | | - # Wait — croniter(schedule, now).get_next() returns the first tick AFTER `now`. |
595 | | - # At now=00:50:05, get_next("50 * * * *") = 01:50:00 (the next tick after 00:50:05). |
596 | | - # So first call: next_run = 01:50:00 → skip (no fire). |
597 | | - # Advance to 01:50:05: |
598 | 580 | current_time[0] = _BASE_EPOCH + 3665 # ~01:50:05 |
599 | 581 | check.data_observability.run_job() |
600 | 582 |
|
@@ -698,16 +680,6 @@ def test_lateness_metric_emitted_for_cron(pg_instance, aggregator, monkeypatch): |
698 | 680 | """Cron query fired late emits a positive lateness gauge with mode:cron tag.""" |
699 | 681 | # next_run will be at 00:50:00; fire at 00:52:00 → 120s lateness |
700 | 682 | fire_time = float(_BASE_EPOCH + 180) # 00:52:00 |
701 | | - |
702 | | - call_count = [0] |
703 | | - |
704 | | - def fake_clock(): |
705 | | - call_count[0] += 1 |
706 | | - # First call: _get_due_queries registration at tick_time |
707 | | - # The sequence is complex; just use a simpler two-phase approach: |
708 | | - # Use monkeypatch to control time directly via a mutable list. |
709 | | - return current_time[0] |
710 | | - |
711 | 683 | current_time = [float(_BASE_EPOCH)] # 00:49:00 — before the tick |
712 | 684 | monkeypatch.setattr('datadog_checks.postgres.data_observability.time.time', lambda: current_time[0]) |
713 | 685 |
|
@@ -780,26 +752,9 @@ def test_lateness_clamped_at_zero(pg_instance, aggregator, monkeypatch): |
780 | 752 | check = _make_cron_check(pg_instance) |
781 | 753 | check.db_pool = _mock_db_pool(mock_conn) |
782 | 754 |
|
783 | | - # First call: registers next_run = 01:50:00 (future) |
784 | | - check.data_observability.run_job() |
785 | | - mid = CRON_QUERY['monitor_id'] |
786 | | - |
787 | | - # Manually set next_run to a value slightly in the future to simulate skew |
788 | | - # (i.e., scheduled_fire_time > now_at_fire_start) |
789 | | - check.data_observability._next_run[mid] = current_time[0] + 1000.0 |
790 | | - |
791 | | - # Force it to look "due" by setting now past that point but making now_at_fire_start < scheduled |
792 | | - # We achieve this by having _get_due_queries return a past-tick but then fire_start < scheduled_tick. |
793 | | - # Simpler approach: directly manipulate state so the query is seen as due with scheduled > fire_start. |
794 | | - # Set next_run to a past value so it's due: |
795 | | - past_tick = current_time[0] - 5.0 |
796 | | - check.data_observability._next_run[mid] = past_tick |
797 | | - # But shift time so now_at_fire_start < past_tick (synthetic skew): |
798 | | - # Actually, just verify the clamp: if scheduled_fire_time > now_at_fire_start, value = 0. |
799 | | - # We construct this by running at a time just after next_run but having time.time() |
800 | | - # return a value LESS than next_run for now_at_fire_start — achieved by decrementing after due check. |
801 | | - # The cleanest way: patch _get_due_queries directly. |
802 | | - skewed_scheduled = current_time[0] + 100.0 # scheduled in the future |
| 755 | + # Patch _get_due_queries to return a scheduled_fire_time in the future of fire_start |
| 756 | + # (synthetic clock-skew scenario). Lateness must clamp to 0 rather than go negative. |
| 757 | + skewed_scheduled = current_time[0] + 100.0 |
803 | 758 | with patch.object( |
804 | 759 | check.data_observability, |
805 | 760 | '_get_due_queries', |
@@ -951,3 +906,41 @@ def test_cron_startup_lookback_advances_next_run_past_recovered_tick(pg_instance |
951 | 906 | next_run = check.data_observability._next_run[mid] |
952 | 907 | # Recovered fire at 00:50:10 should advance _next_run to 01:50:00, not to 00:50:00. |
953 | 908 | assert next_run >= _BASE_EPOCH + 3600 # at least one hour past _BASE_EPOCH (00:49:00) |
| 909 | + |
| 910 | + |
| 911 | +def test_cron_startup_lookback_default_is_300_seconds(pg_instance): |
| 912 | + """The default lookback window is 5 minutes; pin the constant so a regression is loud.""" |
| 913 | + from datadog_checks.postgres.data_observability import DEFAULT_CRON_STARTUP_LOOKBACK_SECONDS |
| 914 | + |
| 915 | + assert DEFAULT_CRON_STARTUP_LOOKBACK_SECONDS == 300 |
| 916 | + check = _make_cron_lookback_check(pg_instance, lookback_seconds=None) |
| 917 | + assert check.data_observability._cron_startup_lookback_seconds() == 300 |
| 918 | + |
| 919 | + |
| 920 | +def test_cron_startup_lookback_negative_clamped_to_zero_with_warning(pg_instance, caplog): |
| 921 | + """A negative lookback value clamps to 0 and emits a warning so it isn't silently dropped.""" |
| 922 | + import logging |
| 923 | + |
| 924 | + check = _make_cron_lookback_check(pg_instance, lookback_seconds=-100) |
| 925 | + with caplog.at_level(logging.WARNING, logger=check.data_observability._log.name): |
| 926 | + result = check.data_observability._cron_startup_lookback_seconds() |
| 927 | + assert result == 0 |
| 928 | + assert any('Invalid cron_startup_lookback_seconds' in r.message for r in caplog.records) |
| 929 | + |
| 930 | + |
| 931 | +def test_cron_startup_lookback_does_not_double_fire(pg_instance, aggregator, monkeypatch): |
| 932 | + """A startup-recovery fire must not re-fire the same tick on the next run_job() call.""" |
| 933 | + current_time = [float(_BASE_EPOCH + 70)] # 00:50:10 — inside the default 300s lookback |
| 934 | + monkeypatch.setattr('datadog_checks.postgres.data_observability.time.time', lambda: current_time[0]) |
| 935 | + |
| 936 | + mock_conn, _ = _make_mock_conn() |
| 937 | + check = _make_cron_lookback_check(pg_instance, lookback_seconds=None) |
| 938 | + check.db_pool = _mock_db_pool(mock_conn) |
| 939 | + check.data_observability.run_job() |
| 940 | + assert len(aggregator.metrics('dd.postgres.data_observability.query_executions')) == 1 |
| 941 | + |
| 942 | + # Advance a few seconds (still well before the next 01:50 tick); a second run must not re-fire. |
| 943 | + current_time[0] = _BASE_EPOCH + 80 |
| 944 | + aggregator.reset() |
| 945 | + check.data_observability.run_job() |
| 946 | + assert len(aggregator.metrics('dd.postgres.data_observability.query_executions')) == 0 |
0 commit comments