Make background tasks idempotent - prevent duplicate bans on retry

CRITICAL FIX: Background tasks (especially blocklist_import) crashed mid-execution,
leaving partial state. On retry, the same bans were applied again, causing duplicates.

Solution: Content-hash based operation tracking for blocklist imports:
- Added import_runs table (migration 6) to track operations by source + content hash
- Before banning, check if this exact content has already been imported
- If completed: skip banning (already done), optionally re-warm cache
- If new or failed: proceed with ban and mark as completed or failed

Changes:
- Database: Migration 6 adds import_runs table with operation state tracking
- Model: Added ImportRunEntry for import run records
- Repository: New import_run_repo module with CRUD operations
- Workflow: Updated blocklist_import_workflow to check operation history before banning
- Dependencies: Registered import_run_repo for dependency injection
- Tests: Added test_import_source_idempotent_on_retry and test_import_source_different_content_not_reused
- Documentation: Added Task Idempotency section to Backend-Development.md

Verification:
- All 7 import tests pass (5 existing + 2 new idempotency tests)
- Type checking: mypy --strict 
- Linting: ruff 
- No API changes, backwards compatible via automatic migration

Fixes: Background tasks not idempotent #CRITICAL

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
This commit is contained in:
2026-04-30 21:54:14 +02:00
parent 400ab1a3f1
commit 52f237d5d4
20 changed files with 1029 additions and 226 deletions

View File

@@ -305,6 +305,105 @@ class TestImport:
assert len(result.results) == 1
assert result.results[0].source_url == "https://s1.test/"
@patch("app.utils.ip_utils.validate_blocklist_url")
async def test_import_source_idempotent_on_retry(
self, mock_validate: AsyncMock, db: aiosqlite.Connection
) -> None:
"""Retry of same content skips banning and reuses existing import record."""
mock_validate.return_value = None
content = "1.2.3.4\n5.6.7.8\n"
session = _make_session(content)
source = await blocklist_service.create_source(db, "Idempotency Test", "https://t.test/")
from app.services import ban_service
ban_count = 0
async def mock_ban_ip(ip: str, jail: str, socket_path: str) -> None:
nonlocal ban_count
ban_count += 1
# First import: should ban 2 IPs
with patch("app.services.ban_service.ban_ip", side_effect=mock_ban_ip):
result1 = await blocklist_service.import_source(
source,
session,
"/tmp/fake.sock",
db,
ban_ip=ban_service.ban_ip,
)
assert result1.ips_imported == 2
assert ban_count == 2
first_ban_count = ban_count
# Second import with same content: should skip banning
session2 = _make_session(content)
ban_count = 0
with patch("app.services.ban_service.ban_ip", side_effect=mock_ban_ip):
result2 = await blocklist_service.import_source(
source,
session2,
"/tmp/fake.sock",
db,
ban_ip=ban_service.ban_ip,
)
# Should skip banning entirely
assert result2.ips_imported == 2
assert result2.error is None
assert ban_count == 0 # No bans called on retry
assert first_ban_count == 2
@patch("app.utils.ip_utils.validate_blocklist_url")
async def test_import_source_different_content_not_reused(
self, mock_validate: AsyncMock, db: aiosqlite.Connection
) -> None:
"""Different content creates new import record, even from same source."""
mock_validate.return_value = None
source = await blocklist_service.create_source(db, "Different Content Test", "https://t.test/")
from app.services import ban_service
ban_count = 0
async def mock_ban_ip(ip: str, jail: str, socket_path: str) -> None:
nonlocal ban_count
ban_count += 1
# First import with 2 IPs
content1 = "1.2.3.4\n5.6.7.8\n"
session1 = _make_session(content1)
with patch("app.services.ban_service.ban_ip", side_effect=mock_ban_ip):
result1 = await blocklist_service.import_source(
source,
session1,
"/tmp/fake.sock",
db,
ban_ip=ban_service.ban_ip,
)
assert result1.ips_imported == 2
assert ban_count == 2
first_ban_count = ban_count
# Second import with different content (3 IPs): should ban again
content2 = "1.2.3.4\n5.6.7.8\n9.10.11.12\n"
session2 = _make_session(content2)
ban_count = 0
with patch("app.services.ban_service.ban_ip", side_effect=mock_ban_ip):
result2 = await blocklist_service.import_source(
source,
session2,
"/tmp/fake.sock",
db,
ban_ip=ban_service.ban_ip,
)
# Different content means new import
assert result2.ips_imported == 3
assert result2.error is None
assert ban_count == 3 # All 3 IPs banned because content is different
# ---------------------------------------------------------------------------
# Schedule

View File

@@ -0,0 +1,144 @@
"""Tests for timeout protection utilities for background tasks.
Validates that :func:`~app.tasks.timeout_utils.run_with_timeout` correctly
enforces timeouts on async tasks and logs appropriate warnings.
"""
from __future__ import annotations
import asyncio
from unittest.mock import AsyncMock, patch
import pytest
class TestRunWithTimeout:
"""Tests for :func:`~app.tasks.timeout_utils.run_with_timeout`."""
@pytest.mark.asyncio
async def test_run_with_timeout_completes_quickly(self) -> None:
"""``run_with_timeout`` must complete and return the result when task finishes quickly."""
from app.tasks.timeout_utils import run_with_timeout
async def _quick_task() -> str:
return "success"
result = await run_with_timeout("test_task", _quick_task(), timeout_seconds=10)
assert result == "success"
@pytest.mark.asyncio
async def test_run_with_timeout_raises_timeout_error(self) -> None:
"""``run_with_timeout`` must raise TimeoutError when task exceeds timeout."""
from app.tasks.timeout_utils import run_with_timeout
async def _slow_task() -> None:
await asyncio.sleep(5)
with pytest.raises(TimeoutError):
await run_with_timeout("slow_task", _slow_task(), timeout_seconds=0.1)
@pytest.mark.asyncio
async def test_run_with_timeout_logs_timeout_event(self) -> None:
"""``run_with_timeout`` must log a warning when timeout occurs."""
from app.tasks.timeout_utils import run_with_timeout
async def _slow_task() -> None:
await asyncio.sleep(5)
with patch("app.tasks.timeout_utils.log") as mock_log:
with pytest.raises(TimeoutError):
await run_with_timeout("slow_task", _slow_task(), timeout_seconds=0.1)
# Verify timeout was logged
timeout_calls = [
c for c in mock_log.warning.call_args_list if c[0][0] == "task_timeout"
]
assert len(timeout_calls) == 1
call_kwargs = timeout_calls[0][1]
assert call_kwargs["task_name"] == "slow_task"
assert call_kwargs["timeout_seconds"] == 0.1
assert call_kwargs["elapsed_seconds"] >= 0.1
@pytest.mark.asyncio
async def test_run_with_timeout_logs_approaching_timeout(self) -> None:
"""``run_with_timeout`` must log warning when task uses >80% of timeout."""
from app.tasks.timeout_utils import run_with_timeout
async def _medium_task() -> None:
await asyncio.sleep(0.25)
with patch("app.tasks.timeout_utils.log") as mock_log:
await run_with_timeout("medium_task", _medium_task(), timeout_seconds=0.3)
# Verify approaching timeout warning was logged (task used >80% of timeout)
approaching_calls = [
c
for c in mock_log.warning.call_args_list
if c[0][0] == "task_approaching_timeout"
]
assert len(approaching_calls) == 1
call_kwargs = approaching_calls[0][1]
assert call_kwargs["task_name"] == "medium_task"
assert call_kwargs["timeout_seconds"] == 0.3
assert call_kwargs["usage_percent"] > 80
@pytest.mark.asyncio
async def test_run_with_timeout_no_warning_when_well_under_timeout(self) -> None:
"""``run_with_timeout`` must not log warning when task completes well before timeout."""
from app.tasks.timeout_utils import run_with_timeout
async def _quick_task() -> None:
await asyncio.sleep(0.01)
with patch("app.tasks.timeout_utils.log") as mock_log:
await run_with_timeout("quick_task", _quick_task(), timeout_seconds=1.0)
# Verify no approaching timeout warning was logged
approaching_calls = [
c
for c in mock_log.warning.call_args_list
if c[0][0] == "task_approaching_timeout"
]
assert len(approaching_calls) == 0
@pytest.mark.asyncio
async def test_run_with_timeout_logs_elapsed_time(self) -> None:
"""``run_with_timeout`` must include elapsed time in timeout log."""
from app.tasks.timeout_utils import run_with_timeout
async def _slow_task() -> None:
await asyncio.sleep(0.2)
with patch("app.tasks.timeout_utils.log") as mock_log:
with pytest.raises(TimeoutError):
await run_with_timeout("slow_task", _slow_task(), timeout_seconds=0.1)
timeout_calls = [
c for c in mock_log.warning.call_args_list if c[0][0] == "task_timeout"
]
call_kwargs = timeout_calls[0][1]
assert "elapsed_seconds" in call_kwargs
assert call_kwargs["elapsed_seconds"] >= 0.1
@pytest.mark.asyncio
async def test_run_with_timeout_returns_correct_type(self) -> None:
"""``run_with_timeout`` must preserve the return type of the coroutine."""
from app.tasks.timeout_utils import run_with_timeout
async def _task_returns_int() -> int:
return 42
result = await run_with_timeout("int_task", _task_returns_int(), timeout_seconds=10)
assert isinstance(result, int)
assert result == 42
@pytest.mark.asyncio
async def test_run_with_timeout_task_exception_propagates(self) -> None:
"""``run_with_timeout`` must propagate exceptions from the task (not timeout)."""
from app.tasks.timeout_utils import run_with_timeout
async def _failing_task() -> None:
raise ValueError("Task failed")
with pytest.raises(ValueError, match="Task failed"):
await run_with_timeout("failing_task", _failing_task(), timeout_seconds=10)