diff --git a/CHANGELOG.md b/CHANGELOG.md index 01a0ae1309..a7a27de768 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,9 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 * The GP2GP Adaptor will no longer incorrectly fail schema validation. * The GP2GP Adaptor now sources the references correctly from within the service code rather than fetching them from the test folder. +### Changed +* Updated logging configuration to route application logs through async appender settings for improved runtime logging performance. + ## [3.0.0] - 2025-11-06 ### Added diff --git a/service/src/main/java/uk/nhs/adaptors/gp2gp/common/service/WebClientFilterService.java b/service/src/main/java/uk/nhs/adaptors/gp2gp/common/service/WebClientFilterService.java index 8ac0fa48ec..4f6bbec8fc 100644 --- a/service/src/main/java/uk/nhs/adaptors/gp2gp/common/service/WebClientFilterService.java +++ b/service/src/main/java/uk/nhs/adaptors/gp2gp/common/service/WebClientFilterService.java @@ -101,7 +101,7 @@ private static ExchangeFilterFunction errorHandling(RequestType requestType, Htt var statusCode = clientResponse.statusCode(); if (statusCode.equals(httpStatus)) { - LOGGER.info(requestType + " request successful status_code: {}", statusCode.value()); + LOGGER.info("{} request successful status_code: {}", requestType, statusCode.value()); return Mono.just(clientResponse); } if (statusCode.is5xxServerError()) { diff --git a/service/src/main/java/uk/nhs/adaptors/gp2gp/ehr/SendDocumentTaskExecutor.java b/service/src/main/java/uk/nhs/adaptors/gp2gp/ehr/SendDocumentTaskExecutor.java index 38202d3a80..f2e208773c 100644 --- a/service/src/main/java/uk/nhs/adaptors/gp2gp/ehr/SendDocumentTaskExecutor.java +++ b/service/src/main/java/uk/nhs/adaptors/gp2gp/ehr/SendDocumentTaskExecutor.java @@ -57,7 +57,7 @@ public void execute(SendDocumentTaskDefinition taskDefinition) { } var binary = outboundMessage.getAttachments().get(0).getPayload(); - LOGGER.debug("Attachment size=" + getBytesLengthOfString(binary) + " content-type=" + taskDefinition.getDocumentContentType()); + LOGGER.debug("Attachment size={} content-type={}", getBytesLengthOfString(binary), taskDefinition.getDocumentContentType()); if (isLargeAttachment(binary)) { outboundMessage.getAttachments().clear(); // since it's a large message, chunks will be sent as external attachments outboundMessage.setExternalAttachments(new ArrayList<>()); diff --git a/service/src/main/java/uk/nhs/adaptors/gp2gp/ehr/mapper/ConditionLinkSetMapper.java b/service/src/main/java/uk/nhs/adaptors/gp2gp/ehr/mapper/ConditionLinkSetMapper.java index 33289aa40f..3638a8e906 100644 --- a/service/src/main/java/uk/nhs/adaptors/gp2gp/ehr/mapper/ConditionLinkSetMapper.java +++ b/service/src/main/java/uk/nhs/adaptors/gp2gp/ehr/mapper/ConditionLinkSetMapper.java @@ -115,7 +115,7 @@ public void testForValidReferences(Condition condition) { try { messageContext.getInputBundleHolder().getResource(idType); } catch (Exception e) { - LOGGER.warn("Bundle mapping aborted. Reason: " + e.getMessage()); + LOGGER.warn("Bundle mapping aborted. Reason: {}", e.getMessage()); throw e; } } diff --git a/service/src/main/java/uk/nhs/adaptors/gp2gp/ehr/request/EhrExtractRequestHandler.java b/service/src/main/java/uk/nhs/adaptors/gp2gp/ehr/request/EhrExtractRequestHandler.java index c87298e488..a0b1e7b892 100644 --- a/service/src/main/java/uk/nhs/adaptors/gp2gp/ehr/request/EhrExtractRequestHandler.java +++ b/service/src/main/java/uk/nhs/adaptors/gp2gp/ehr/request/EhrExtractRequestHandler.java @@ -130,7 +130,7 @@ public void handleContinue(String conversationId, String payload) { ehrExtractStatusService.updateEhrExtractStatusContinue(conversationId) .ifPresent(ehrExtractStatus -> { var documents = ehrExtractStatus.getGpcAccessDocument().getDocuments(); - LOGGER.info("Sending documents for: ConversationId: " + conversationId); + LOGGER.info("Sending documents for: ConversationId: {}", conversationId); for (int documentPosition = 0; documentPosition < documents.size(); documentPosition++) { var document = documents.get(documentPosition); createSendDocumentTasks( diff --git a/service/src/main/java/uk/nhs/adaptors/gp2gp/transformjsontoxmltool/TransformJsonToXml.java b/service/src/main/java/uk/nhs/adaptors/gp2gp/transformjsontoxmltool/TransformJsonToXml.java index 19dde3b36b..d718231962 100644 --- a/service/src/main/java/uk/nhs/adaptors/gp2gp/transformjsontoxmltool/TransformJsonToXml.java +++ b/service/src/main/java/uk/nhs/adaptors/gp2gp/transformjsontoxmltool/TransformJsonToXml.java @@ -85,7 +85,7 @@ private List getFiles() throws UnreadableJsonFileException, NoJsonFil throw new NoJsonFileFound("No json files found"); } - LOGGER.info("Processing " + files.length + " files from location: " + JSON_FILE_INPUT_PATH); + LOGGER.info("Processing {} files from location: {}", files.length, JSON_FILE_INPUT_PATH); Arrays.stream(files) .peek(file -> LOGGER.info("Parsing file: {}", file.getName())) diff --git a/service/src/main/resources/logback.xml b/service/src/main/resources/logback.xml index b9b882fdf4..a2d214544a 100644 --- a/service/src/main/resources/logback.xml +++ b/service/src/main/resources/logback.xml @@ -6,16 +6,18 @@ + + + ${GP2GP_LOGGING_ASYNC_QUEUE_SIZE:-2048} + 0 + true + false + - + - - - - - \ No newline at end of file diff --git a/service/src/test/java/uk/nhs/adaptors/gp2gp/common/configuration/LogbackConfigurationTest.java b/service/src/test/java/uk/nhs/adaptors/gp2gp/common/configuration/LogbackConfigurationTest.java new file mode 100644 index 0000000000..9f6c2473db --- /dev/null +++ b/service/src/test/java/uk/nhs/adaptors/gp2gp/common/configuration/LogbackConfigurationTest.java @@ -0,0 +1,119 @@ +package uk.nhs.adaptors.gp2gp.common.configuration; + +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.Appender; +import ch.qos.logback.core.read.ListAppender; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; +import org.slf4j.LoggerFactory; +import org.slf4j.MDC; + +import static org.assertj.core.api.Assertions.assertThat; + +class LogbackConfigurationTest { + + public static final int MILLIS_100 = 100; + private Logger rootLogger; + private Logger gp2gpLogger; + private Logger reactorNettyLogger; + + @BeforeEach + void setUp() { + rootLogger = (Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME); + gp2gpLogger = (Logger) LoggerFactory.getLogger("uk.nhs.adaptors.gp2gp"); + reactorNettyLogger = (Logger) LoggerFactory.getLogger("reactor.netty.http.client"); + } + + @Test + void shouldHaveAsyncAppenderOnRootLogger() { + + assertThat(rootLogger.getAppender("ASYNC")) + .as("AsyncAppender 'ASYNC' should be attached to root logger") + .isNotNull(); + + Appender appender = rootLogger.getAppender("ASYNC"); + assertThat(appender.getClass().getSimpleName()) + .contains("AsyncAppender"); + } + + @Test + void shouldHaveGp2gpLoggerConfiguredWithProperLevel() { + assertThat(gp2gpLogger.getEffectiveLevel()) + .as("GP2GP logger should inherit or override level explicitly") + .isNotNull(); + } + + @Test + void shouldDecoupleReactorNettyLoggingLevelFromGp2GpLevel() { + Level reactorLevel = reactorNettyLogger.getEffectiveLevel(); + + assertThat(reactorLevel) + .as("Reactor Netty logger should have explicit level to decouple from GP2GP logger") + .isNotNull(); + } + + @Test + void shouldPreserveMdcInAsyncLogging() { + + ListAppender listAppender = new ListAppender<>(); + listAppender.start(); + gp2gpLogger.addAppender(listAppender); + gp2gpLogger.setLevel(Level.INFO); + + MDC.put("ConversationId", "test-conv-123"); + MDC.put("TaskId", "test-task-456"); + + gp2gpLogger.info("Test message with MDC"); + + try { + Thread.sleep(MILLIS_100); + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + } + + assertThat(listAppender.list).isNotEmpty(); + + ILoggingEvent event = listAppender.list.getFirst(); + assertThat(event.getMDCPropertyMap()) + .containsEntry("ConversationId", "test-conv-123") + .containsEntry("TaskId", "test-task-456"); + + MDC.clear(); + gp2gpLogger.detachAppender(listAppender); + listAppender.stop(); + } + + @Test + void shouldNotBlockOnLoggingIo() { + + Appender asyncAppender = rootLogger.getAppender("ASYNC"); + + assertThat(asyncAppender) + .as("AsyncAppender should be configured to never block producer threads") + .isNotNull(); + + assertThat(asyncAppender.getClass().getSimpleName()) + .isEqualTo("AsyncAppender"); + } + + @Test + void rootLoggerShouldHaveValidTextAppenderReference() { + + Appender appender = rootLogger.getAppender("ASYNC"); + + assertThat(appender) + .as("Root logger should have valid ASYNC appender (wraps corrected TEXT appender)") + .isNotNull(); + + assertThat(appender.getName()) + .as("Appender name should be ASYNC, not a default fallback") + .isEqualTo("ASYNC"); + } +} + + + + + diff --git a/service/src/test/java/uk/nhs/adaptors/gp2gp/common/service/WebClientFilterServiceTest.java b/service/src/test/java/uk/nhs/adaptors/gp2gp/common/service/WebClientFilterServiceTest.java new file mode 100644 index 0000000000..2f86673980 --- /dev/null +++ b/service/src/test/java/uk/nhs/adaptors/gp2gp/common/service/WebClientFilterServiceTest.java @@ -0,0 +1,291 @@ +package uk.nhs.adaptors.gp2gp.common.service; + +import ch.qos.logback.classic.Level; +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.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; +import org.mockito.Mockito; +import org.slf4j.LoggerFactory; +import org.springframework.http.HttpHeaders; +import org.springframework.http.HttpMethod; +import org.springframework.http.HttpStatus; +import org.springframework.web.reactive.function.client.ClientRequest; +import org.springframework.web.reactive.function.client.ClientResponse; +import org.springframework.web.reactive.function.client.ExchangeFilterFunction; +import org.springframework.web.reactive.function.client.ExchangeFunction; +import reactor.core.publisher.Mono; +import uk.nhs.adaptors.gp2gp.common.configuration.WebClientConfiguration; + +import java.net.URI; +import java.time.Duration; +import java.util.ArrayList; +import java.util.List; + +import static org.assertj.core.api.Assertions.assertThat; +import static org.mockito.ArgumentMatchers.any; +import static org.mockito.Mockito.when; + +class WebClientFilterServiceTest { + + public static final int TEN_SECONDS = 10; + public static final int THREE_ATTEMPTS = 3; + public static final int FIVE_SECONDS = 5; + public static final int THIRTY_SECONDS = 30; + private ListAppender logAppender; + private Logger logger; + + @BeforeEach + void setUp() { + logger = (Logger) LoggerFactory.getLogger(WebClientFilterService.class); + logAppender = new ListAppender<>(); + logAppender.start(); + logger.addAppender(logAppender); + } + + @AfterEach + void tearDown() { + logger.detachAppender(logAppender); + logAppender.stop(); + } + + @Nested + class SuccessfulResponseLogging { + + @Test + void shouldLogSuccessWithParameterisedMessage() { + + var filters = new ArrayList(); + var clientConfig = mockWebClientConfiguration(); + + WebClientFilterService.addWebClientFilters( + filters, + WebClientFilterService.RequestType.GPC, + HttpStatus.OK, + clientConfig + ); + + var composedFilter = filters.stream() + .reduce(ExchangeFilterFunction::andThen) + .orElseThrow(); + + var clientRequest = ClientRequest.create(HttpMethod.GET, URI.create("http://localhost/test")) + .build(); + + var clientResponse = ClientResponse.create(HttpStatus.OK) + .header("Content-Type", "application/json") + .build(); + + ExchangeFunction exchangeFunction = Mockito.mock(ExchangeFunction.class); + when(exchangeFunction.exchange(any())).thenReturn(Mono.just(clientResponse)); + + composedFilter.filter(clientRequest, exchangeFunction).block(); + + List infoLogs = logAppender.list.stream() + .filter(event -> event.getLevel() == Level.INFO) + .toList(); + + assertThat(infoLogs) + .anyMatch(event -> { + String msg = event.getFormattedMessage(); + return msg.contains("GPC") + && msg.contains("request successful") + && msg.contains("200"); + }); + + assertThat(infoLogs).anyMatch(event -> event.getMessage().contains("{}")); + } + + @Test + void shouldLogMhsOutboundRequestTypeOnSuccess() { + + var filters = new ArrayList(); + var clientConfig = mockWebClientConfiguration(); + + WebClientFilterService.addWebClientFilters( + filters, + WebClientFilterService.RequestType.MHS_OUTBOUND, + HttpStatus.ACCEPTED, + clientConfig + ); + + var composedFilter = filters.stream() + .reduce(ExchangeFilterFunction::andThen) + .orElseThrow(); + + var clientRequest = ClientRequest.create(HttpMethod.POST, URI.create("http://localhost/mhs")) + .build(); + + var clientResponse = ClientResponse.create(HttpStatus.ACCEPTED).build(); + + ExchangeFunction exchangeFunction = Mockito.mock(ExchangeFunction.class); + when(exchangeFunction.exchange(any())).thenReturn(Mono.just(clientResponse)); + + composedFilter.filter(clientRequest, exchangeFunction).block(); + + List infoLogs = logAppender.list.stream() + .filter(event -> event.getLevel() == Level.INFO) + .toList(); + + assertThat(infoLogs) + .anyMatch(event -> { + String msg = event.getFormattedMessage(); + return msg.contains("MHS_OUTBOUND") + && msg.contains("request successful") + && msg.contains("202"); + }); + } + } + + @Nested + class DebugLogging { + + @Test + void shouldNotLogRequestResponseHeadersWhenDebugIsDisabled() { + + logger.setLevel(Level.INFO); + + var filters = new ArrayList(); + var clientConfig = mockWebClientConfiguration(); + + WebClientFilterService.addWebClientFilters( + filters, + WebClientFilterService.RequestType.GPC, + HttpStatus.OK, + clientConfig + ); + + var composedFilter = filters.stream() + .reduce(ExchangeFilterFunction::andThen) + .orElseThrow(); + + var clientRequest = ClientRequest.create(HttpMethod.GET, URI.create("http://localhost/test")) + .header(HttpHeaders.AUTHORIZATION, "Bearer secret-token") + .build(); + + var clientResponse = ClientResponse.create(HttpStatus.OK).build(); + + ExchangeFunction exchangeFunction = Mockito.mock(ExchangeFunction.class); + when(exchangeFunction.exchange(any())).thenReturn(Mono.just(clientResponse)); + + composedFilter.filter(clientRequest, exchangeFunction).block(); + + List debugLogs = logAppender.list.stream() + .filter(event -> event.getLevel() == Level.DEBUG) + .toList(); + + assertThat(debugLogs).isEmpty(); + } + + @Test + void shouldLogRequestResponseHeadersWhenDebugIsEnabled() { + + logger.setLevel(Level.DEBUG); + + var filters = new ArrayList(); + var clientConfig = mockWebClientConfiguration(); + + WebClientFilterService.addWebClientFilters( + filters, + WebClientFilterService.RequestType.GPC, + HttpStatus.OK, + clientConfig + ); + + var composedFilter = filters.stream() + .reduce(ExchangeFilterFunction::andThen) + .orElseThrow(); + + var clientRequest = ClientRequest.create(HttpMethod.GET, URI.create("http://localhost/test")) + .header("X-Custom-Header", "value123") + .build(); + + var clientResponse = ClientResponse.create(HttpStatus.OK) + .header("X-Response-Header", "resp-value") + .build(); + + ExchangeFunction exchangeFunction = Mockito.mock(ExchangeFunction.class); + when(exchangeFunction.exchange(any())).thenReturn(Mono.just(clientResponse)); + + composedFilter.filter(clientRequest, exchangeFunction).block(); + + List debugLogs = logAppender.list.stream() + .filter(event -> event.getLevel() == Level.DEBUG) + .toList(); + + assertThat(debugLogs) + .anyMatch(event -> event.getFormattedMessage().contains("Request:")) + .anyMatch(event -> event.getFormattedMessage().contains("Response:")); + } + } + + @Nested + class RetryLogging { + + @Test + void shouldLogRetryWithParameterisedFormatOnFailure() { + + var filters = new ArrayList(); + var clientConfig = mockWebClientConfiguration(2, 1); + + WebClientFilterService.addWebClientFilters( + filters, + WebClientFilterService.RequestType.GPC, + HttpStatus.OK, + clientConfig + ); + + var composedFilter = filters.stream() + .reduce(ExchangeFilterFunction::andThen) + .orElseThrow(); + + var clientRequest = ClientRequest.create(HttpMethod.GET, URI.create("http://localhost/test")) + .build(); + + var serverErrorResponse = ClientResponse.create(HttpStatus.INTERNAL_SERVER_ERROR) + .body("internal error") + .build(); + + ExchangeFunction exchangeFunction = Mockito.mock(ExchangeFunction.class); + when(exchangeFunction.exchange(any())).thenReturn(Mono.just(serverErrorResponse)); + + try { + composedFilter.filter(clientRequest, exchangeFunction).block(Duration.ofSeconds(TEN_SECONDS)); + } catch (uk.nhs.adaptors.gp2gp.common.exception.RetryLimitReachedException e) { + assertThat(e).isNotNull(); + } + + List retryLogs = logAppender.list.stream() + .filter(event -> event.getLevel() == Level.INFO) + .filter(event -> event.getFormattedMessage().contains("retrying request")) + .toList(); + + assertThat(retryLogs).isNotEmpty(); + assertThat(retryLogs).allMatch(event -> event.getMessage().contains("{}")); + + assertThat(retryLogs) + .anyMatch(event -> { + String msg = event.getFormattedMessage(); + return msg.contains("Request to `GPC` failed") + && msg.contains("retrying request"); + }); + } + } + + private static WebClientConfiguration mockWebClientConfiguration() { + return mockWebClientConfiguration(THREE_ATTEMPTS, FIVE_SECONDS); + } + + private static WebClientConfiguration mockWebClientConfiguration(int maxAttempts, int minBackoffSeconds) { + var config = Mockito.mock(WebClientConfiguration.class); + when(config.getMaxBackoffAttempts()).thenReturn(maxAttempts); + when(config.getMinBackOff()).thenReturn(Duration.ofSeconds(minBackoffSeconds)); + when(config.getTimeout()).thenReturn(Duration.ofSeconds(THIRTY_SECONDS)); + return config; + } +} + + diff --git a/service/src/test/resources/logback-test.xml b/service/src/test/resources/logback-test.xml index c08b7b0d9f..183d27791f 100644 --- a/service/src/test/resources/logback-test.xml +++ b/service/src/test/resources/logback-test.xml @@ -6,9 +6,16 @@ + + + ${GP2GP_LOGGING_ASYNC_QUEUE_SIZE:-2048} + 0 + true + false + - +