diff --git a/docs/company-followup.md b/docs/company-followup.md index 95f6133..d50547e 100644 --- a/docs/company-followup.md +++ b/docs/company-followup.md @@ -67,3 +67,12 @@ call_count를 기록한다. 응답 envelope가 없으면 토큰은 0(실제 사 Java 21과 redis-server가 있는 환경에서 `./gradlew test`를 실행한다. 가짜 WebClient와 가상 시계로 호출 분기·엄격 스키마·폴백·시간 예산·취소·슬롯 반환을 검증한다. 기존 프롬프트 골든·준비 요청·Redis·질문 ID·부모 관계·TTS 테스트도 함께 실행한다. + +## 실시간 꼬리질문 진단 로그 + +- `follow_up.decision`은 정상 생성(`generated`), 정상 생략(`model_not_required`), 호출 실패(`ai_timeout`/`ai_unavailable`), 잘못된 응답(`invalid_response`)을 구분한다. +- 빈 HTTP 본문이나 잘못된 모델 응답도 꼬리질문 없음 결과를 반환해 면접을 계속 진행한다. +- `follow_up.skipped`는 `current_is_follow`와 `policy_limit`을 구분한다. +- 실패 로그의 sessionId/interviewId/questionId로 요청을 연결한다. 답변·기업 자료·모델 응답·예외 메시지는 이 로그에 넣지 않는다. +- 기업 재작성 실패 시 A 단계 질문을 보존한다. 기존 질문 수·required 판정 정책은 변경하지 않는다. +- 피드백 화면의 예상 꼬리질문은 분석 서버의 별도 산출물이다. diff --git a/src/main/java/com/person/repit/interview/service/company/CompanyFollowUpGenerator.java b/src/main/java/com/person/repit/interview/service/company/CompanyFollowUpGenerator.java index 9fa322d..f94de27 100644 --- a/src/main/java/com/person/repit/interview/service/company/CompanyFollowUpGenerator.java +++ b/src/main/java/com/person/repit/interview/service/company/CompanyFollowUpGenerator.java @@ -38,29 +38,36 @@ public static boolean hasCompany(FollowQuestionAiRequest request) { public Mono generate(FollowQuestionAiRequest request, FollowQuestionAiResponse decision, long started) { + return generateWithOutcome(request, decision, started).map(Outcome::response); + } + + public record Outcome(FollowQuestionAiResponse response, String fallbackReason) {} + + public Mono generateWithOutcome(FollowQuestionAiRequest request, FollowQuestionAiResponse decision, + long started) { return Mono.defer(() -> { if (!hasCompany(request) || !Boolean.TRUE.equals(decision.getRequired())) { - return Mono.just(decision); + return Mono.just(new Outcome(decision, null)); } if (!settings.enabled()) { - return fallback(decision, "disabled"); + return fallback(request, decision, "disabled"); } if (decision.getScore() == null || decision.getScore() < 0 || decision.getScore() > 5) { - return fallback(decision, "invalid_decision"); + return fallback(request, decision, "invalid_decision"); } long remaining = settings.totalTimeout().toNanos() - Math.max(0, FollowUpModelClient.now() - started); if (remaining <= 0) { - return fallback(decision, "deadline"); + return fallback(request, decision, "deadline"); } Duration timeout = Duration.ofNanos(Math.min(remaining, settings.generationTimeout().toNanos())); return Mono.defer(() -> client.call(CompanyFollowUpPrompt.body(mapper, model, settings.maxTokens(), request, decision), "B")) .map(this::parse) - .map(content -> content.merge(decision)) + .map(content -> new Outcome(content.merge(decision), null)) .timeout(timeout) .doOnNext(ignored -> log.info("follow_up.company status=applied")) - .switchIfEmpty(Mono.defer(() -> fallback(decision, "empty_response"))) - .onErrorResume(error -> fallback(decision, + .switchIfEmpty(Mono.defer(() -> fallback(request, decision, "empty_response"))) + .onErrorResume(error -> fallback(request, decision, error instanceof TimeoutException ? "timeout" : "generation_failed")); }); } @@ -81,8 +88,10 @@ private CompanyFollowUpContent parse(JsonNode response) { } } - private Mono fallback(FollowQuestionAiResponse decision, String reason) { - log.info("follow_up.company status=fallback reason={}", reason); - return Mono.just(decision); + private Mono fallback(FollowQuestionAiRequest request, + FollowQuestionAiResponse decision, String reason) { + log.info("follow_up.company status=fallback reason={} sessionId={} interviewId={} questionId={}", + reason, request.getSessionId(), request.getInterviewId(), request.getQuestionId()); + return Mono.just(new Outcome(decision, reason)); } } diff --git a/src/main/java/com/person/repit/interview/service/impl/AiQuestionClientImpl.java b/src/main/java/com/person/repit/interview/service/impl/AiQuestionClientImpl.java index 418567d..8510a78 100644 --- a/src/main/java/com/person/repit/interview/service/impl/AiQuestionClientImpl.java +++ b/src/main/java/com/person/repit/interview/service/impl/AiQuestionClientImpl.java @@ -26,6 +26,7 @@ import java.util.List; import java.util.Map; import java.util.concurrent.RejectedExecutionException; +import java.util.concurrent.TimeoutException; @Slf4j @Component @@ -74,22 +75,41 @@ public Mono decideFollowQuestion(FollowQuestionAiReque if (CompanyFollowUpGenerator.hasCompany(request)) { decision = decision.timeout(companySettings.totalTimeout()); } - return decision.flatMap(result -> companyGenerator.generate(request, result, started)); + return decision.flatMap(result -> companyGenerator.generateWithOutcome(request, result, started)); }))) - .doOnError( - exception -> !isExpectedFallback(exception), - exception -> log.warn("follow_up status=failed reason={}", exception.getClass().getSimpleName()) - ) + .doOnNext(result -> log.info( + "follow_up.decision status={} reason={} sessionId={} interviewId={} questionId={}", + result.fallbackReason() == null ? "completed" : "fallback", + result.fallbackReason() == null + ? (Boolean.TRUE.equals(result.response().getRequired()) ? "generated" : "model_not_required") + : "company_" + result.fallbackReason(), + request.getSessionId(), request.getInterviewId(), request.getQuestionId())) + .map(CompanyFollowUpGenerator.Outcome::response) + .doOnError(error -> log.warn( + "follow_up.decision status=fallback reason={} sessionId={} interviewId={} questionId={}", + fallbackReason(error), request.getSessionId(), request.getInterviewId(), request.getQuestionId())) .onErrorReturn(FollowQuestionAiResponse.notRequired()); } - private boolean isExpectedFallback(Throwable exception) { - return exception instanceof RejectedExecutionException - || exception.getCause() instanceof ReadTimeoutException; + private String fallbackReason(Throwable error) { + for (Throwable cause = error; cause != null; cause = cause.getCause()) { + if (cause instanceof InvalidFollowUpResponseException) return "invalid_response"; + if (cause instanceof TimeoutException || cause instanceof ReadTimeoutException) return "ai_timeout"; + if (cause instanceof RejectedExecutionException) return "ai_unavailable"; + } + return "ai_unavailable"; + } + + private static final class InvalidFollowUpResponseException extends IllegalStateException { + private InvalidFollowUpResponseException() { + super("Invalid follow-up model response"); + } } private Mono executeRequest(FollowQuestionAiRequest request) { - return modelClient.call(createRequestBody(request), "A").map(this::parseResponse); + return modelClient.call(createRequestBody(request), "A") + .map(this::parseResponse) + .switchIfEmpty(Mono.error(new InvalidFollowUpResponseException())); } private FollowQuestionAiResponse parseResponse(JsonNode response) { @@ -97,7 +117,7 @@ private FollowQuestionAiResponse parseResponse(JsonNode response) { String text = extractText(response); if (text == null || text.isBlank()) { - return FollowQuestionAiResponse.notRequired(); + throw new InvalidFollowUpResponseException(); } String json = cleanJson(text); @@ -109,7 +129,7 @@ private FollowQuestionAiResponse parseResponse(JsonNode response) { || (Boolean.TRUE.equals(result.getRequired()) && (!StringUtils.hasText(result.getContent()) || !StringUtils.hasText(result.getExpectedAnswer())))) { - result = FollowQuestionAiResponse.notRequired(); + throw new InvalidFollowUpResponseException(); } return result; @@ -117,7 +137,7 @@ private FollowQuestionAiResponse parseResponse(JsonNode response) { } catch (RuntimeException exception) { throw exception; } catch (Exception exception) { - throw new IllegalStateException("Anthropic 응답 처리에 실패했습니다.", exception); + throw new InvalidFollowUpResponseException(); } } diff --git a/src/main/java/com/person/repit/interview/service/impl/ChatInterviewServiceImpl.java b/src/main/java/com/person/repit/interview/service/impl/ChatInterviewServiceImpl.java index f867228..3e68177 100644 --- a/src/main/java/com/person/repit/interview/service/impl/ChatInterviewServiceImpl.java +++ b/src/main/java/com/person/repit/interview/service/impl/ChatInterviewServiceImpl.java @@ -246,7 +246,9 @@ private Mono createFollowQuestionIfRequired( ChatAnswerRequest request ) { if (!canCreateFollowQuestion(session, currentQuestion)) { - log.info("[FOLLOW SKIPPED] follow question limit reached or current question is follow-up"); + log.info("follow_up.skipped reason={} sessionId={} interviewId={} questionId={}", + currentQuestion.getType() == QuestionType.FOLLOW ? "current_is_follow" : "policy_limit", + session.getSessionId(), session.getInterviewId(), currentQuestion.getQuestionId()); return Mono.just(FollowQuestionAiResponse.notRequired()); } diff --git a/src/test/java/com/person/repit/interview/service/company/FollowUpDecisionLoggingTest.java b/src/test/java/com/person/repit/interview/service/company/FollowUpDecisionLoggingTest.java new file mode 100644 index 0000000..1c279c4 --- /dev/null +++ b/src/test/java/com/person/repit/interview/service/company/FollowUpDecisionLoggingTest.java @@ -0,0 +1,138 @@ +package com.person.repit.interview.service.company; + +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.read.ListAppender; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.params.ParameterizedTest; +import org.junit.jupiter.params.provider.ValueSource; +import org.slf4j.LoggerFactory; +import org.springframework.http.HttpStatus; +import org.springframework.web.reactive.function.client.ClientResponse; +import reactor.core.publisher.Mono; + +import java.util.List; +import java.util.concurrent.RejectedExecutionException; +import java.util.concurrent.TimeoutException; + +import static com.person.repit.interview.service.company.CompanyFollowUpTestSupport.*; +import static org.assertj.core.api.Assertions.assertThat; + +class FollowUpDecisionLoggingTest { + @Test + void 정상적인_생략은_호출_실패와_구분한다() { + try (var logs = new CapturedLogs()) { + var h = harness(enabled(), index -> Mono.just(response("{\"score\":5,\"required\":false}"))); + assertThat(h.client().decideFollowQuestion(request(null)).block().getRequired()).isFalse(); + assertThat(h.bodies()).hasSize(1); + assertThat(logs.lines()).anySatisfy(line -> assertThat(line) + .contains("status=completed", "reason=model_not_required", "sessionId=s", "questionId=4")); + assertThat(logs.lines()).noneMatch(line -> line.contains("status=fallback")); + } + } + + @ParameterizedTest + @ValueSource(strings = {"", "{}", "not-json", "{\"required\":true,\"content\":\"비공개 응답\"}"}) + void 잘못된_기본_응답은_정상_생략으로_기록하지_않는다(String body) { + try (var logs = new CapturedLogs()) { + var h = harness(enabled(), index -> Mono.just(response(body))); + assertThat(h.client().decideFollowQuestion(request(null)).block().getRequired()).isFalse(); + assertThat(h.bodies()).hasSize(1); + assertThat(logs.lines()).anySatisfy(line -> assertThat(line) + .contains("status=fallback", "reason=invalid_response", "interviewId=1", "questionId=4")); + assertThat(logs.lines()).noneMatch(line -> line.contains("reason=model_not_required")); + assertThat(String.join("\n", logs.lines())).doesNotContain("비공개 응답", "구현했습니다"); + } + } + + @Test + void 빈_HTTP_본문도_면접_진행을_위한_불필요_결과를_반환한다() { + try (var logs = new CapturedLogs()) { + var h = harness(enabled(), index -> Mono.just(ClientResponse.create(HttpStatus.OK).build())); + assertThat(h.client().decideFollowQuestion(request(null)).block()).isNotNull() + .satisfies(result -> assertThat(result.getRequired()).isFalse()); + assertThat(logs.lines()).anyMatch(line -> line.contains("reason=invalid_response")); + } + } + + @Test + void 시간초과와_동시요청_제한을_구분하고_원문은_로그에_남기지_않는다() { + try (var logs = new CapturedLogs()) { + var timeout = harness(enabled(), index -> Mono.error(new TimeoutException("비공개 예외"))); + var unavailable = harness(enabled(), index -> Mono.error(new RejectedExecutionException("비공개 예외"))); + assertThat(timeout.client().decideFollowQuestion(request(null)).block().getRequired()).isFalse(); + assertThat(unavailable.client().decideFollowQuestion(request(null)).block().getRequired()).isFalse(); + assertThat(logs.lines()).anyMatch(line -> line.contains("reason=ai_timeout")); + assertThat(logs.lines()).anyMatch(line -> line.contains("reason=ai_unavailable")); + assertThat(String.join("\n", logs.lines())).doesNotContain("비공개 예외"); + } + } + + @Test + void 기업_재작성_실패는_원래_질문을_유지하고_식별자를_기록한다() { + try (var logs = new CapturedLogs()) { + var h = harness(enabled(), index -> Mono.just(response(index == 0 ? BASE : "비공개 기업 응답"))); + assertThat(h.client().decideFollowQuestion(request("비공개 기업")).block().getContent()) + .isEqualTo("일반 질문?"); + assertThat(logs.lines()).anySatisfy(line -> assertThat(line) + .contains("follow_up.company status=fallback", "reason=generation_failed", + "sessionId=s", "interviewId=1", "questionId=4")); + assertThat(String.join("\n", logs.lines())).doesNotContain("비공개 기업"); + } + } + + @ParameterizedTest + @ValueSource(strings = {"timeout", "empty", "invalid"}) + void 기업_폴백을_생성_성공으로_기록하지_않는다(String failure) { + try (var logs = new CapturedLogs()) { + var h = harness(enabled(), index -> index == 0 ? Mono.just(response(BASE)) : switch (failure) { + case "timeout" -> Mono.error(new TimeoutException()); + case "empty" -> Mono.just(ClientResponse.create(HttpStatus.OK).build()); + default -> Mono.just(response("invalid")); + }); + assertThat(h.client().decideFollowQuestion(request("기업")).block().getContent()) + .isEqualTo("일반 질문?"); + String reason = switch (failure) { + case "timeout" -> "company_timeout"; + case "empty" -> "company_empty_response"; + default -> "company_generation_failed"; + }; + assertThat(logs.lines()).anySatisfy(line -> assertThat(line) + .contains("follow_up.decision status=fallback", "reason=" + reason)); + assertThat(logs.lines()).noneMatch(line -> line.contains("follow_up.decision status=completed")); + } + } + + @Test + void 기업_재작성_성공만_생성_성공으로_기록한다() { + try (var logs = new CapturedLogs()) { + var h = harness(enabled(), index -> Mono.just(response(index == 0 ? BASE : COMPANY))); + assertThat(h.client().decideFollowQuestion(request("기업")).block().getContent()) + .isEqualTo("기업 관점 질문?"); + assertThat(logs.lines()).anySatisfy(line -> assertThat(line) + .contains("follow_up.decision status=completed reason=generated")); + assertThat(logs.lines()).noneMatch(line -> line.contains("status=fallback")); + } + } + + private static final class CapturedLogs implements AutoCloseable { + private final Logger logger = (Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME); + private final ListAppender appender = new ListAppender<>(); + + private CapturedLogs() { + appender.start(); + logger.addAppender(appender); + } + + private List lines() { + return appender.list.stream().map(ILoggingEvent::getFormattedMessage) + .filter(line -> line.startsWith("follow_up.")).toList(); + } + + @Override + public void close() { + logger.detachAppender(appender); + appender.stop(); + } + } +}