Guide repairs and expose worker progress

README.md

@@ -68,6 +68,21 @@ Der Default `AUTOMATION_MODE=dry-run` claimt einen offenen Report, erzeugt den
 anonymisierten Auftrag und setzt ihn danach wieder auf `open`. Es wird weder ein Agent
 gestartet noch gepusht.
 
+## Fortschritt beobachten
+
+```bash
+docker compose ps automation
+docker compose exec automation lai-agent check
+docker compose logs -f automation
+```
+
+Der Worker protokolliert nur sichere Metadaten, keine Prompts, SQL-Ergebnisse, Secrets oder
+Modellausgaben. Fuer jeden Report erscheinen Workspace-Vorbereitung, Agentenversuch, Anzahl
+und Pfade geaenderter Dateien, Policy-Pruefung, jeder Validierungsbefehl, Commit, PR-URL und
+Cleanup. Bei laengeren Agenten- oder Testphasen wird alle 30 Sekunden Laufzeitfortschritt
+ausgegeben. `agent_running` ohne Heartbeat oder Unterprozess deutet auf einen unterbrochenen
+Container hin; normale Claims werden nach `STALE_CLAIM_MINUTES` wieder freigegeben.
+
 ## PR-Modus
 
 ```dotenv

src/lai_automation/prompt.py

@@ -18,6 +18,33 @@ _SECRET_PATTERNS = (
     (re.compile(r"\b[A-Za-z0-9_-]+\.[A-Za-z0-9_-]+\.[A-Za-z0-9_-]+\b"), "[JWT]"),
 )
 
+_REPOSITORY_PLAYBOOK = """
+Repository ownership map:
+- app/Services/SQLGeneratorService.php assembles live schema and business context for SQL generation.
+- config/erp_semantics.php owns ERP joins, metrics, formulas, filters, and reference examples.
+- config/cockpit_semantics.php owns device and customer-database semantics.
+- app/Services/AIService.php owns provider calls, pseudonymization boundaries, and response parsing.
+- app/Services/TenantDatabaseService.php owns ERP/config/customer source selection and tenant metadata.
+- app/Services/SQLValidatorService.php owns read-only SQL safety; do not weaken it to accept a fix.
+- app/Http/Controllers/ChatController.php orchestrates routing, execution, answers, and diagnostics.
+- app/Services/FailureTrackingService.php and FailureAutomationService.php own failure handoff.
+- tests/Unit is preferred for deterministic service/context rules; tests/Feature is for HTTP,
+  persistence, authorization, or real isolated-database behavior.
+
+Repair workflow:
+1. Inspect the owning implementation, its configuration, and the nearest existing test first.
+2. State one root-cause hypothesis and make the smallest change that can prove it.
+3. Put reusable business knowledge in tracked semantics configuration, not question-specific code.
+4. A prompt/context fix must test the real generated context. A deterministic SQL builder must test
+    its exact SQL and execute it against synthetic fixtures when useful.
+5. Tests must contain assertions that execute; reject empty loops and broad unrelated fallbacks.
+6. Do not expose protected production methods publicly for tests. Use a test-only subclass.
+7. Do not duplicate one rule in service code and semantics config, or add explanatory comments for
+    self-evident test setup.
+8. Inspect the final diff for malformed edits, unrelated files, hardcoded report values, and tests
+    that pass without exercising the changed behavior.
+"""
+
 
 def redact(value: str | None) -> str:
     result = value or ""
@@ -62,6 +89,8 @@ itself deterministically builds and executes the SQL under test.
 
     return f"""You are fixing failure report #{report.id} in the Laravel AI Chat repository.
 
+{_REPOSITORY_PLAYBOOK}
+
 Rules:
 - First add a regression test that reproduces the reported behavior.
 - The regression test must execute the relevant production behavior; never mock or stub the behavior being tested.

src/lai_automation/worker.py

@@ -3,6 +3,9 @@ from __future__ import annotations
 import logging
 import signal
 import threading
+import time
+from collections.abc import Iterator
+from contextlib import contextmanager
 from dataclasses import asdict
 
 from .agent import AiderAgent
@@ -31,7 +34,13 @@ class AutomationWorker:
             LOG.info("No open failure reports")
             return False
 
-        LOG.info("Claimed failure report %s", report.id)
+        LOG.info(
+            "Claimed failure report %s category=%s source=%s database_type=%s",
+            report.id,
+            report.category,
+            report.source,
+            report.context.get("database_type", "unknown"),
+        )
         if self.settings.dry_run:
             task = build_task(report)
             LOG.info("Dry-run task for report %s:\n%s", report.id, task)
@@ -41,13 +50,31 @@ class AutomationWorker:
         workspace = GitWorkspace(self.settings, report.id)
         metadata: dict = {"mode": self.settings.mode, "model": self.settings.agent_model}
         try:
+            with self._progress(report.id, "workspace preparation"):
                 workspace.prepare()
+            LOG.info("Report %s branch=%s workspace ready", report.id, workspace.branch)
             task = build_task(report)
             metadata["agent_output"] = []
             for attempt in range(1, self.settings.max_agent_attempts + 1):
+                LOG.info(
+                    "Report %s agent attempt %s/%s starting",
+                    report.id,
+                    attempt,
+                    self.settings.max_agent_attempts,
+                )
+                with self._progress(report.id, f"agent attempt {attempt}"):
                     metadata["agent_output"].append(self.agent.run(workspace.path, task))
                 summary = workspace.summary()
                 metadata["changes"] = asdict(summary)
+                LOG.info(
+                    "Report %s attempt %s changed files=%s lines=+%s/-%s paths=%s",
+                    report.id,
+                    attempt,
+                    len(summary.files),
+                    summary.added_lines,
+                    summary.deleted_lines,
+                    ",".join(summary.files) or "none",
+                )
                 policy = evaluate_changes(summary, self.settings, workspace.path)
                 if not policy.allowed:
                     if not summary.files and attempt < self.settings.max_agent_attempts:
@@ -67,7 +94,8 @@ class AutomationWorker:
                         "Policy rejected changes: " + "; ".join(policy.errors)
                     )
                 try:
-                    metadata["tests"] = self._run_tests(workspace)
+                    metadata["tests"] = self._run_tests(workspace, report.id, attempt)
+                    LOG.info("Report %s attempt %s validation passed", report.id, attempt)
                     break
                 except RuntimeError as exception:
                     if attempt >= self.settings.max_agent_attempts:
@@ -88,14 +116,17 @@ class AutomationWorker:
                 )
             commit = workspace.commit(report.id)
             metadata["commit"] = commit
+            LOG.info("Report %s committed %s", report.id, commit)
 
             if self.settings.mode == "pr":
+                with self._progress(report.id, "branch publication"):
                     workspace.push_branch()
                     metadata["pull_request"] = self.gitea.create_pull_request(
                         workspace.branch,
                         f"Fix failure report #{report.id}",
                         self._pull_request_body(report, summary, metadata["tests"]),
                     )
+                LOG.info("Report %s pull request=%s", report.id, metadata["pull_request"])
             elif self.settings.mode == "direct-main":
                 workspace.push_main()
                 metadata["direct_main"] = True
@@ -110,10 +141,20 @@ class AutomationWorker:
         finally:
             try:
                 workspace.cleanup()
+                LOG.info("Report %s workspace cleaned", report.id)
             except OSError:
                 LOG.exception("Could not clean workspace for report %s", report.id)
 
     def run_forever(self) -> None:
+        LOG.info(
+            "Worker started mode=%s model=%s poll_seconds=%s max_attempts=%s tests=%s direct_main=%s",
+            self.settings.mode,
+            self.settings.agent_model,
+            self.settings.poll_seconds,
+            self.settings.max_agent_attempts,
+            len(self.settings.test_commands),
+            self.settings.allow_direct_main,
+        )
         signal.signal(signal.SIGTERM, self._stop)
         signal.signal(signal.SIGINT, self._stop)
         while not self.stop_event.is_set():
@@ -124,7 +165,12 @@ class AutomationWorker:
         LOG.info("Received signal %s; stopping after the current report", signum)
         self.stop_event.set()
 
-    def _run_tests(self, workspace: GitWorkspace) -> list[dict]:
+    def _run_tests(
+        self,
+        workspace: GitWorkspace,
+        report_id: int | None = None,
+        attempt: int | None = None,
+    ) -> list[dict]:
         results = []
         test_environment = {
             "AGENT_TEST_DB_ENABLED": "true",
@@ -152,6 +198,9 @@ class AutomationWorker:
             "COCKPIT_CONFIG_DATABASE": self.settings.test_config_database,
         }
         for command in self.settings.test_commands:
+            label = f"validation command: {command}"
+            LOG.info("Report %s attempt %s %s starting", report_id, attempt, label)
+            with self._progress(report_id, label):
                 result = workspace.run(
                     command,
                     check=False,
@@ -164,11 +213,51 @@ class AutomationWorker:
                 "stdout": result.stdout[-6000:],
                 "stderr": result.stderr[-6000:],
             })
+            LOG.info(
+                "Report %s attempt %s %s finished returncode=%s",
+                report_id,
+                attempt,
+                label,
+                result.returncode,
+            )
             if result.returncode != 0:
                 output = (result.stdout + "\n" + result.stderr)[-4000:]
                 raise RuntimeError(f"Test command failed: {command}\n{output}")
         return results
 
+    @contextmanager
+    def _progress(
+        self,
+        report_id: int | None,
+        stage: str,
+        interval: float = 30.0,
+    ) -> Iterator[None]:
+        started = time.monotonic()
+        stopped = threading.Event()
+
+        def heartbeat() -> None:
+            while not stopped.wait(interval):
+                LOG.info(
+                    "Report %s %s still running elapsed=%ss",
+                    report_id,
+                    stage,
+                    round(time.monotonic() - started),
+                )
+
+        thread = threading.Thread(target=heartbeat, daemon=True)
+        thread.start()
+        try:
+            yield
+        finally:
+            stopped.set()
+            thread.join(timeout=0.1)
+            LOG.info(
+                "Report %s %s finished elapsed=%.1fs",
+                report_id,
+                stage,
+                time.monotonic() - started,
+            )
+
     @staticmethod
     def _pull_request_body(report: FailureReport, summary, tests: list[dict]) -> str:
         checks = "\n".join(

tests/test_prompt.py

@@ -33,6 +33,10 @@ def test_task_contains_constraints_and_redacted_report() -> None:
     assert "admin@example.com" not in task
     assert "Do not commit or push" in task
     assert "never mock or stub the behavior being tested" in task
+    assert "Repository ownership map:" in task
+    assert "config/erp_semantics.php owns ERP joins" in task
+    assert "Tests must contain assertions that execute" in task
+    assert "Do not expose protected production methods publicly" in task
     assert "Feedback type: wrong_join" in task
     assert "Join FK_Artikel with FK_AuftragPos and filter Auftragkennung = 3." in task
     assert "The wrong product count was returned." in task

tests/test_worker.py

@@ -1,3 +1,4 @@
+import threading
 from pathlib import Path
 from unittest.mock import Mock, patch
 
@@ -60,6 +61,29 @@ def test_database_credentials_are_only_passed_to_test_process() -> None:
     assert environment["COCKPIT_CONFIG_DATABASE"] == "cockpit_agent_test"
 
 
+def test_validation_commands_are_logged_without_output(caplog) -> None:
+    worker = AutomationWorker(settings())
+    workspace = Mock()
+    workspace.run.return_value = Mock(returncode=0, stdout="sensitive output", stderr="")
+
+    with caplog.at_level("INFO"):
+        worker._run_tests(workspace, report_id=7, attempt=2)
+
+    assert "Report 7 attempt 2 validation command: php artisan test starting" in caplog.text
+    assert "returncode=0" in caplog.text
+    assert "sensitive output" not in caplog.text
+
+
+def test_long_stage_emits_heartbeat(caplog) -> None:
+    worker = AutomationWorker(settings())
+
+    with caplog.at_level("INFO"), worker._progress(7, "agent attempt 1", interval=0.001):
+        threading.Event().wait(0.01)
+
+    assert "Report 7 agent attempt 1 still running" in caplog.text
+    assert "Report 7 agent attempt 1 finished" in caplog.text
+
+
 def test_failed_validation_gets_one_correction_before_pr() -> None:
     report = FailureReport(
         id=13,