Fix #17: Fehler und Warnungen nicht mehr als INFO loggen

Verarbeitungsfehler (PreCheckFailed, AiFunctionalFailure) und
Retry-Entscheidungen (FAILED_RETRYABLE, FAILED_FINAL) werden nun auf
WARN-Level geloggt. EmptyList- und IncompleteConfiguration-Ergebnisse
des Modellabrufs sowie fehlende Quelldateien im Mini-Lauf ebenfalls.
Tests angepasst: Assertions prüfen jetzt das korrekte WARN-Level.

Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
This commit is contained in:
2026-04-23 17:58:30 +02:00
parent 955adc0c45
commit 67275eb2f5
6 changed files with 43 additions and 35 deletions
@@ -194,14 +194,14 @@ public final class GuiModelCatalogCoordinator {
String message = "Provider " + displayName String message = "Provider " + displayName
+ " liefert aktuell keine Modelle. Manuelle Eingabe aktiv."; + " liefert aktuell keine Modelle. Manuelle Eingabe aktiv.";
pendingMessages.add(GuiMessageEntry.of(GuiMessageSeverity.HINT, message, "Modellabruf")); pendingMessages.add(GuiMessageEntry.of(GuiMessageSeverity.HINT, message, "Modellabruf"));
LOG.info("GUI-Modellabruf: {} (Provider: {})", message, family.getIdentifier()); LOG.warn("GUI-Modellabruf: {} (Provider: {})", message, family.getIdentifier());
} }
case ModelCatalogResult.IncompleteConfiguration incomplete -> { case ModelCatalogResult.IncompleteConfiguration incomplete -> {
container.applyManualFallback(GuiModelSource.LIST_UNAVAILABLE_MANUAL_INPUT); container.applyManualFallback(GuiModelSource.LIST_UNAVAILABLE_MANUAL_INPUT);
String message = "Modellliste nicht abrufbar: " + incomplete.missingReason() String message = "Modellliste nicht abrufbar: " + incomplete.missingReason()
+ ". Manuelle Eingabe aktiv."; + ". Manuelle Eingabe aktiv.";
pendingMessages.add(GuiMessageEntry.of(GuiMessageSeverity.WARNING, message, "Modellabruf")); pendingMessages.add(GuiMessageEntry.of(GuiMessageSeverity.WARNING, message, "Modellabruf"));
LOG.info("GUI-Modellabruf: {} (Provider: {})", message, family.getIdentifier()); LOG.warn("GUI-Modellabruf: {} (Provider: {})", message, family.getIdentifier());
} }
case ModelCatalogResult.TechnicalFailure failure -> { case ModelCatalogResult.TechnicalFailure failure -> {
container.applyManualFallback(GuiModelSource.LIST_FAILED_MANUAL_INPUT); container.applyManualFallback(GuiModelSource.LIST_FAILED_MANUAL_INPUT);
@@ -1017,7 +1017,7 @@ public final class GuiBatchRunTab {
upsertResultRowByFingerprint(missingRow); upsertResultRowByFingerprint(missingRow);
appendMessage(message); appendMessage(message);
failedCount++; failedCount++;
LOG.info("GUI-Mini-Lauf: Quelldatei fehlt für Auswahl '{}' Status " LOG.warn("GUI-Mini-Lauf: Quelldatei fehlt für Auswahl '{}' Status "
+ "permanent fehlgeschlagen.", originalName); + "permanent fehlgeschlagen.", originalName);
} }
} }
@@ -688,12 +688,12 @@ public class DocumentProcessingCoordinator {
}); });
if (!retryable) { if (!retryable) {
logger.info("Retry decision for '{}' (fingerprint: {}): FAILED_FINAL — " logger.warn("Retry decision for '{}' (fingerprint: {}): FAILED_FINAL — "
+ "transient error limit reached ({}/{} attempts). No further retry.", + "transient error limit reached ({}/{} attempts). No further retry.",
candidate.uniqueIdentifier(), fingerprint.sha256Hex(), candidate.uniqueIdentifier(), fingerprint.sha256Hex(),
updatedCounters.transientErrorCount(), maxRetriesTransient); updatedCounters.transientErrorCount(), maxRetriesTransient);
} else { } else {
logger.info("Retry decision for '{}' (fingerprint: {}): FAILED_RETRYABLE — " logger.warn("Retry decision for '{}' (fingerprint: {}): FAILED_RETRYABLE — "
+ "transient error, will retry in later run ({}/{} attempts).", + "transient error, will retry in later run ({}/{} attempts).",
candidate.uniqueIdentifier(), fingerprint.sha256Hex(), candidate.uniqueIdentifier(), fingerprint.sha256Hex(),
updatedCounters.transientErrorCount(), maxRetriesTransient); updatedCounters.transientErrorCount(), maxRetriesTransient);
@@ -1060,14 +1060,14 @@ public class DocumentProcessingCoordinator {
}); });
if (outcome.overallStatus() == ProcessingStatus.FAILED_RETRYABLE) { if (outcome.overallStatus() == ProcessingStatus.FAILED_RETRYABLE) {
logger.info("Retry decision for '{}' (fingerprint: {}): FAILED_RETRYABLE — " logger.warn("Retry decision for '{}' (fingerprint: {}): FAILED_RETRYABLE — "
+ "will retry in later scheduler run. " + "will retry in later scheduler run. "
+ "ContentErrors={}, TransientErrors={}.", + "ContentErrors={}, TransientErrors={}.",
candidate.uniqueIdentifier(), fingerprint.sha256Hex(), candidate.uniqueIdentifier(), fingerprint.sha256Hex(),
outcome.counters().contentErrorCount(), outcome.counters().contentErrorCount(),
outcome.counters().transientErrorCount()); outcome.counters().transientErrorCount());
} else if (outcome.overallStatus() == ProcessingStatus.FAILED_FINAL) { } else if (outcome.overallStatus() == ProcessingStatus.FAILED_FINAL) {
logger.info("Retry decision for '{}' (fingerprint: {}): FAILED_FINAL — " logger.warn("Retry decision for '{}' (fingerprint: {}): FAILED_FINAL — "
+ "permanently failed, no further retry. " + "permanently failed, no further retry. "
+ "ContentErrors={}, TransientErrors={}.", + "ContentErrors={}, TransientErrors={}.",
candidate.uniqueIdentifier(), fingerprint.sha256Hex(), candidate.uniqueIdentifier(), fingerprint.sha256Hex(),
@@ -554,7 +554,7 @@ public class DefaultBatchRunProcessingUseCase implements BatchRunProcessingUseCa
private void logProcessingOutcome(SourceDocumentCandidate candidate, DocumentProcessingOutcome outcome) { private void logProcessingOutcome(SourceDocumentCandidate candidate, DocumentProcessingOutcome outcome) {
switch (outcome) { switch (outcome) {
case de.gecheckt.pdf.umbenenner.domain.model.PreCheckFailed failed -> case de.gecheckt.pdf.umbenenner.domain.model.PreCheckFailed failed ->
logger.info("Pre-checks failed for '{}': {} (deterministic content error).", logger.warn("Pre-checks failed for '{}': {} (deterministic content error).",
candidate.uniqueIdentifier(), failed.failureReasonDescription()); candidate.uniqueIdentifier(), failed.failureReasonDescription());
case de.gecheckt.pdf.umbenenner.domain.model.TechnicalDocumentError technicalError -> case de.gecheckt.pdf.umbenenner.domain.model.TechnicalDocumentError technicalError ->
logger.warn("Processing failed for '{}': {} (transient technical error retryable).", logger.warn("Processing failed for '{}': {} (transient technical error retryable).",
@@ -568,7 +568,7 @@ public class DefaultBatchRunProcessingUseCase implements BatchRunProcessingUseCa
logger.warn("AI invocation failed for '{}': {} (transient technical error retryable).", logger.warn("AI invocation failed for '{}': {} (transient technical error retryable).",
candidate.uniqueIdentifier(), aiTechnical.errorMessage()); candidate.uniqueIdentifier(), aiTechnical.errorMessage());
case de.gecheckt.pdf.umbenenner.domain.model.AiFunctionalFailure aiFunctional -> case de.gecheckt.pdf.umbenenner.domain.model.AiFunctionalFailure aiFunctional ->
logger.info("AI naming failed for '{}': {} (deterministic content error).", logger.warn("AI naming failed for '{}': {} (deterministic content error).",
candidate.uniqueIdentifier(), aiFunctional.errorMessage()); candidate.uniqueIdentifier(), aiFunctional.errorMessage());
default -> { /* other outcomes are handled elsewhere */ } default -> { /* other outcomes are handled elsewhere */ }
} }
@@ -770,8 +770,8 @@ class DocumentProcessingCoordinatorTest {
coordinatorWithCapturingLogger.process(candidate, fingerprint, outcome, context, attemptStart); coordinatorWithCapturingLogger.process(candidate, fingerprint, outcome, context, attemptStart);
assertTrue(capturingLogger.infoCallCount > 0, assertTrue(capturingLogger.warnCallCount > 0,
"Nach erfolgreichem Verarbeiten eines neuen Dokuments muss eine Info geloggt werden"); "Nach Verarbeiten eines neuen Dokuments mit PreCheckPassed muss eine Warnung geloggt werden");
} }
@Test @Test
@@ -1126,12 +1126,12 @@ class DocumentProcessingCoordinatorTest {
coordinatorWithCapturing.processDeferredOutcome(candidate, fingerprint, context, attemptStart, c -> null); coordinatorWithCapturing.processDeferredOutcome(candidate, fingerprint, context, attemptStart, c -> null);
assertTrue(capturingLogger.anyInfoContains("FAILED_RETRYABLE"), assertTrue(capturingLogger.anyWarnContains("FAILED_RETRYABLE"),
"Retry decision log for a retryable transient copy error must contain FAILED_RETRYABLE. " "Retry decision log for a retryable transient copy error must contain FAILED_RETRYABLE. "
+ "Captured info messages: " + capturingLogger.infoMessages); + "Captured warn messages: " + capturingLogger.warnMessages);
assertTrue(capturingLogger.anyInfoContains("will retry in later run"), assertTrue(capturingLogger.anyWarnContains("will retry in later run"),
"Retry decision log for a retryable transient error must contain 'will retry in later run'. " "Retry decision log for a retryable transient error must contain 'will retry in later run'. "
+ "Captured info messages: " + capturingLogger.infoMessages); + "Captured warn messages: " + capturingLogger.warnMessages);
} }
@Test @Test
@@ -1153,12 +1153,12 @@ class DocumentProcessingCoordinatorTest {
coordinatorWithCapturing.processDeferredOutcome(candidate, fingerprint, context, attemptStart, c -> null); coordinatorWithCapturing.processDeferredOutcome(candidate, fingerprint, context, attemptStart, c -> null);
assertTrue(capturingLogger.anyInfoContains("FAILED_FINAL"), assertTrue(capturingLogger.anyWarnContains("FAILED_FINAL"),
"Retry decision log for a finalising transient copy error must contain FAILED_FINAL. " "Retry decision log for a finalising transient copy error must contain FAILED_FINAL. "
+ "Captured info messages: " + capturingLogger.infoMessages); + "Captured warn messages: " + capturingLogger.warnMessages);
assertTrue(capturingLogger.anyInfoContains("transient error limit reached"), assertTrue(capturingLogger.anyWarnContains("transient error limit reached"),
"Retry decision log for a finalising transient error must contain 'transient error limit reached'. " "Retry decision log for a finalising transient error must contain 'transient error limit reached'. "
+ "Captured info messages: " + capturingLogger.infoMessages); + "Captured warn messages: " + capturingLogger.warnMessages);
} }
@Test @Test
@@ -1602,12 +1602,12 @@ class DocumentProcessingCoordinatorTest {
new PreCheckFailed(candidate, PreCheckFailureReason.NO_USABLE_TEXT), new PreCheckFailed(candidate, PreCheckFailureReason.NO_USABLE_TEXT),
context, attemptStart); context, attemptStart);
assertTrue(capturingLogger.anyInfoContains(FINGERPRINT_HEX), assertTrue(capturingLogger.anyWarnContains(FINGERPRINT_HEX),
"Retry decision log must contain the document fingerprint. " "Retry decision log must contain the document fingerprint. "
+ "Captured info messages: " + capturingLogger.infoMessages); + "Captured warn messages: " + capturingLogger.warnMessages);
assertTrue(capturingLogger.anyInfoContains("FAILED_RETRYABLE"), assertTrue(capturingLogger.anyWarnContains("FAILED_RETRYABLE"),
"Retry decision log must contain the FAILED_RETRYABLE classification. " "Retry decision log must contain the FAILED_RETRYABLE classification. "
+ "Captured info messages: " + capturingLogger.infoMessages); + "Captured warn messages: " + capturingLogger.warnMessages);
} }
@Test @Test
@@ -1627,16 +1627,16 @@ class DocumentProcessingCoordinatorTest {
new PreCheckFailed(candidate, PreCheckFailureReason.PAGE_LIMIT_EXCEEDED), new PreCheckFailed(candidate, PreCheckFailureReason.PAGE_LIMIT_EXCEEDED),
context, attemptStart); context, attemptStart);
assertTrue(capturingLogger.anyInfoContains(FINGERPRINT_HEX), assertTrue(capturingLogger.anyWarnContains(FINGERPRINT_HEX),
"Finalising retry decision log must contain the document fingerprint. " "Finalising retry decision log must contain the document fingerprint. "
+ "Captured info messages: " + capturingLogger.infoMessages); + "Captured warn messages: " + capturingLogger.warnMessages);
assertTrue(capturingLogger.anyInfoContains("FAILED_FINAL"), assertTrue(capturingLogger.anyWarnContains("FAILED_FINAL"),
"Finalising retry decision log must contain the FAILED_FINAL classification. " "Finalising retry decision log must contain the FAILED_FINAL classification. "
+ "Captured info messages: " + capturingLogger.infoMessages); + "Captured warn messages: " + capturingLogger.warnMessages);
assertTrue(capturingLogger.anyInfoContains("permanently failed"), assertTrue(capturingLogger.anyWarnContains("permanently failed"),
"Finalising retry decision log must contain 'permanently failed' to distinguish " "Finalising retry decision log must contain 'permanently failed' to distinguish "
+ "the FAILED_FINAL branch from the generic status log. " + "the FAILED_FINAL branch from the generic status log. "
+ "Captured info messages: " + capturingLogger.infoMessages); + "Captured warn messages: " + capturingLogger.warnMessages);
} }
// ------------------------------------------------------------------------- // -------------------------------------------------------------------------
@@ -1879,6 +1879,10 @@ class DocumentProcessingCoordinatorTest {
return infoMessages.stream().anyMatch(m -> m.contains(text)); return infoMessages.stream().anyMatch(m -> m.contains(text));
} }
boolean anyWarnContains(String text) {
return warnMessages.stream().anyMatch(m -> m.contains(text));
}
boolean anyErrorContains(String text) { boolean anyErrorContains(String text) {
return errorMessages.stream().anyMatch(m -> m.contains(text)); return errorMessages.stream().anyMatch(m -> m.contains(text));
} }
@@ -672,10 +672,11 @@ class BatchRunProcessingUseCaseTest {
} }
@Test @Test
void execute_extractionContentError_logsDebugAndPreCheckFailedInfo() throws Exception { void execute_extractionContentError_logsDebugAndPreCheckFailedWarn() throws Exception {
// Prüft, dass bei PdfExtractionContentError debug (logExtractionResult) und info (logProcessingOutcome) geloggt wird. // Prüft, dass bei PdfExtractionContentError debug (logExtractionResult) und warn (logProcessingOutcome) geloggt wird.
// Erwartete debug()-Aufrufe: 4 (lock acquired + fingerprint + logExtractionResult (content) + lock released) // Erwartete debug()-Aufrufe: 4 (lock acquired + fingerprint + logExtractionResult (content) + lock released)
// Erwartete info()-Aufrufe: 6 (Batch initiiert + gestartet + Kandidaten gefunden + erkannte Quelldatei + PreCheckFailed + abgeschlossen) // Erwartete info()-Aufrufe: 5 (Batch initiiert + gestartet + Kandidaten gefunden + erkannte Quelldatei + abgeschlossen)
// Erwartete warn()-Aufrufe: >= 1 (PreCheckFailed)
CapturingProcessingLogger capturingLogger = new CapturingProcessingLogger(); CapturingProcessingLogger capturingLogger = new CapturingProcessingLogger();
RuntimeConfiguration config = buildConfig(tempDir); RuntimeConfiguration config = buildConfig(tempDir);
@@ -695,10 +696,13 @@ class BatchRunProcessingUseCaseTest {
assertTrue(capturingLogger.debugCallCount >= 4, assertTrue(capturingLogger.debugCallCount >= 4,
"logExtractionResult muss bei PdfExtractionContentError debug() aufrufen (erwartet >= 4, war: " "logExtractionResult muss bei PdfExtractionContentError debug() aufrufen (erwartet >= 4, war: "
+ capturingLogger.debugCallCount + ")"); + capturingLogger.debugCallCount + ")");
// Ohne logProcessingOutcome (PreCheckFailed) wären es 5 info()-Aufrufe; mit >= 6 // PreCheckFailed wird als WARN geloggt; ohne diesen Aufruf wären es 5 info()-Aufrufe
assertTrue(capturingLogger.infoCallCount >= 6, assertTrue(capturingLogger.infoCallCount >= 5,
"logProcessingOutcome muss bei PreCheckFailed info() aufrufen (erwartet >= 6, war: " "Batch-Ablauf muss bei PdfExtractionContentError mind. 5 info()-Aufrufe erzeugen (erwartet >= 5, war: "
+ capturingLogger.infoCallCount + ")"); + capturingLogger.infoCallCount + ")");
assertTrue(capturingLogger.warnCallCount >= 1,
"logProcessingOutcome muss bei PreCheckFailed warn() aufrufen (erwartet >= 1, war: "
+ capturingLogger.warnCallCount + ")");
} }
@Test @Test