[plugin-rest-api] Add extended logging for HTTP requests and responses

docs/modules/plugins/pages/plugin-rest-api.adoc

@@ -30,6 +30,12 @@ include::partial$plugin-installation.adoc[]
 |`<empty>`
 |The property family to set HTTP headers for all outgoing requests, e.g. rest-api.http.header.my-sample-header=my-sample-value
 
+|`rest-api.http.extended-logging`
+a|`true`
+`false`
+|`false`
+|Enable header and body (only text types) logging for HTTP requests and responses
+
 |===
 
 See xref:ROOT:tests-configuration.adoc#_http_configuration[HTTP configuration] for more fine-grained control over the HTTP interactions.

vividus-plugin-rest-api/src/main/java/org/vividus/http/ExtendedHttpLoggingInterceptor.java

@@ -0,0 +1,142 @@
+/*
+ * Copyright 2019-2023 the original author or authors.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     https://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.vividus.http;
+
+import static org.apache.hc.core5.http.ContentType.APPLICATION_JSON;
+import static org.apache.hc.core5.http.ContentType.APPLICATION_XML;
+import static org.apache.hc.core5.http.ContentType.TEXT_HTML;
+import static org.apache.hc.core5.http.ContentType.TEXT_PLAIN;
+import static org.apache.hc.core5.http.ContentType.TEXT_XML;
+
+import java.io.IOException;
+import java.nio.charset.StandardCharsets;
+import java.util.Optional;
+import java.util.Set;
+import java.util.stream.Collectors;
+import java.util.stream.Stream;
+
+import org.apache.commons.lang3.StringUtils;
+import org.apache.hc.core5.http.ContentType;
+import org.apache.hc.core5.http.EntityDetails;
+import org.apache.hc.core5.http.Header;
+import org.apache.hc.core5.http.HeaderElement;
+import org.apache.hc.core5.http.HttpEntity;
+import org.apache.hc.core5.http.HttpEntityContainer;
+import org.apache.hc.core5.http.HttpHeaders;
+import org.apache.hc.core5.http.HttpRequest;
+import org.apache.hc.core5.http.HttpRequestInterceptor;
+import org.apache.hc.core5.http.ProtocolVersion;
+import org.apache.hc.core5.http.io.entity.StringEntity;
+import org.apache.hc.core5.http.message.MessageSupport;
+import org.apache.hc.core5.http.protocol.HttpContext;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+import org.slf4j.spi.LoggingEventBuilder;
+import org.vividus.http.client.HttpResponse;
+import org.vividus.http.handler.HttpResponseHandler;
+
+public class ExtendedHttpLoggingInterceptor implements HttpRequestInterceptor, HttpResponseHandler
+{
+    private static final String NEW_LINE = "\n";
+    private static final String HEADERS_FORMAT = "\nHeaders:\n{}";
+    private static final String BODY_FORMAT = "\nBody: {}";
+
+    private static final Set<String> LOGGED_CONTENT_TYPES = Set.of(APPLICATION_JSON.getMimeType(),
+            APPLICATION_XML.getMimeType(), TEXT_HTML.getMimeType(), TEXT_PLAIN.getMimeType(), TEXT_XML.getMimeType());
+
+    private final Logger logger;
+
+    private final boolean extendedLogging;
+
+    public ExtendedHttpLoggingInterceptor(Class<?> loggerType, boolean extendedLogging)
+    {
+        this.logger = LoggerFactory.getLogger(loggerType);
+        this.extendedLogging = extendedLogging;
+    }
+
+    @Override
+    public void process(HttpRequest request, EntityDetails entityDetails, HttpContext context) throws IOException
+    {
+        String argBrackets = " {}";
+        LoggingEventBuilder loggingEventBuilder = logger.atInfo();
+        StringBuilder loggerFormat = new StringBuilder("Request:");
+
+        ProtocolVersion protocolVersion = request.getVersion();
+        if (protocolVersion != null)
+        {
+            loggingEventBuilder = loggingEventBuilder.addArgument(protocolVersion);
+            loggerFormat.append(argBrackets);
+        }
+        loggingEventBuilder = loggingEventBuilder.addArgument(request);
+        loggerFormat.append(argBrackets);
+
+        if (extendedLogging)
+        {
+            Header[] headers = request.getHeaders();
+            String headersAsString = Stream.of(headers).map(Object::toString).collect(Collectors.joining(NEW_LINE));
+            loggingEventBuilder = loggingEventBuilder.addArgument(headersAsString);
+            loggerFormat.append(HEADERS_FORMAT);
+
+            if (request instanceof HttpEntityContainer httpEntityContainer)
+            {
+                HttpEntity entity = httpEntityContainer.getEntity();
+                if (entity instanceof StringEntity stringEntity)
+                {
+                    String textBody = new String(stringEntity.getContent().readAllBytes(), StandardCharsets.UTF_8);
+                    loggingEventBuilder = loggingEventBuilder.addArgument(textBody);
+                    loggerFormat.append(BODY_FORMAT);
+                }
+            }
+        }
+        loggingEventBuilder.log(loggerFormat.toString());
+    }
+
+    @Override
+    public void handle(HttpResponse httpResponse)
+    {
+        LoggingEventBuilder loggingEventBuilder = logger.atInfo().addArgument(httpResponse.getStatusCode())
+                .addArgument(httpResponse.getFrom());
+        StringBuilder loggerFormat = new StringBuilder("Response: status code {}, {}");
+
+        if (extendedLogging)
+        {
+            Header[] headers = httpResponse.getResponseHeaders();
+            String headersAsString = Stream.of(headers).map(Object::toString).collect(Collectors.joining(NEW_LINE));
+            loggingEventBuilder = loggingEventBuilder.addArgument(headersAsString);
+            loggerFormat.append(HEADERS_FORMAT);
+
+            String mimeType = getMimeType(headers).orElseGet(ContentType.DEFAULT_TEXT::getMimeType);
+            if (LOGGED_CONTENT_TYPES.contains(mimeType) && httpResponse.getResponseBody() != null)
+            {
+                loggingEventBuilder = loggingEventBuilder.addArgument(httpResponse.getResponseBodyAsString());
+                loggerFormat.append(BODY_FORMAT);
+            }
+        }
+        loggingEventBuilder.log(loggerFormat.toString());
+    }
+
+    private Optional<String> getMimeType(Header... headers)
+    {
+        return Stream.of(headers)
+                .filter(h -> HttpHeaders.CONTENT_TYPE.equalsIgnoreCase(h.getName())
+                        && StringUtils.isNotBlank(h.getValue()))
+                .findFirst()
+                .map(MessageSupport::parse)
+                .map(elements -> elements[0])
+                .map(HeaderElement::getName);
+    }
+}

vividus-plugin-rest-api/src/main/resources/log4j2-vividus-plugin-rest-api.xml

@@ -0,0 +1,9 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<Configuration>
+    <Loggers>
+        <Logger name="org.vividus.http.HttpRequestExecutor" level="INFO" additivity="false">
+            <AppenderRef ref="console" />
+            <AppenderRef ref="file" />
+        </Logger>
+    </Loggers>
+</Configuration>

vividus-plugin-rest-api/src/main/resources/properties/defaults/default.properties

@@ -1,3 +1,4 @@
 # Default API endpoint
 rest-api.http.endpoint=
 rest-api.http.cookie-store-level=global
+rest-api.http.extended-logging=false

vividus-plugin-rest-api/src/main/resources/vividus-plugin/spring.xml

@@ -58,6 +58,7 @@
                 <constructor-arg value="rest-api.http.header." />
             </bean>
         </property>
+        <property name="firstRequestInterceptor" ref="extendedHttpLoggingInterceptor"/>
         <property name="lastRequestInterceptor" ref="publishingAttachmentInterceptor" />
         <property name="lastResponseInterceptor">
             <bean class="org.vividus.http.SavingConnectionDetailsHttpResponseInterceptor">
@@ -69,6 +70,7 @@
         </property>
         <property name="httpResponseHandlers">
             <list>
+                <ref bean="extendedHttpLoggingInterceptor" />
                 <ref bean="publishingAttachmentInterceptor" />
             </list>
         </property>
@@ -80,6 +82,11 @@
         <constructor-arg ref="softAssert" />
     </bean>
 
+    <bean id="extendedHttpLoggingInterceptor" class="org.vividus.http.ExtendedHttpLoggingInterceptor">
+        <constructor-arg value="org.vividus.http.HttpRequestExecutor" type="java.lang.Class" />
+        <constructor-arg value="${rest-api.http.extended-logging}" />
+    </bean>
+
     <bean id="publishingAttachmentInterceptor" class="org.vividus.http.PublishingAttachmentInterceptor" />
 
     <bean id="httpCookieSteps" class="org.vividus.steps.api.HttpCookieSteps"/>

vividus-plugin-rest-api/src/test/java/org/vividus/http/ExtendedHttpLoggingInterceptorTests.java

@@ -0,0 +1,183 @@
+/*
+ * Copyright 2019-2023 the original author or authors.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     https://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.vividus.http;
+
+import static com.github.valfirst.slf4jtest.LoggingEvent.info;
+import static org.hamcrest.MatcherAssert.assertThat;
+import static org.hamcrest.Matchers.is;
+
+import java.io.ByteArrayInputStream;
+import java.io.IOException;
+import java.net.URI;
+import java.nio.charset.StandardCharsets;
+import java.util.List;
+
+import com.github.valfirst.slf4jtest.TestLogger;
+import com.github.valfirst.slf4jtest.TestLoggerFactory;
+import com.github.valfirst.slf4jtest.TestLoggerFactoryExtension;
+
+import org.apache.hc.core5.http.ClassicHttpRequest;
+import org.apache.hc.core5.http.ContentType;
+import org.apache.hc.core5.http.Header;
+import org.apache.hc.core5.http.HttpEntity;
+import org.apache.hc.core5.http.HttpStatus;
+import org.apache.hc.core5.http.ProtocolVersion;
+import org.apache.hc.core5.http.io.entity.BasicHttpEntity;
+import org.apache.hc.core5.http.io.entity.StringEntity;
+import org.apache.hc.core5.http.message.BasicClassicHttpRequest;
+import org.apache.hc.core5.http.message.BasicHeader;
+import org.apache.hc.core5.http.message.BasicHttpRequest;
+import org.junit.jupiter.api.Test;
+import org.junit.jupiter.api.extension.ExtendWith;
+import org.junit.jupiter.params.ParameterizedTest;
+import org.junit.jupiter.params.provider.CsvSource;
+import org.vividus.http.client.HttpResponse;
+
+@ExtendWith(TestLoggerFactoryExtension.class)
+class ExtendedHttpLoggingInterceptorTests
+{
+    private static final String ENDPOINT = "https://uri.com/";
+    private static final URI ENDPOINT_URI = URI.create(ENDPOINT);
+    private static final String METHOD = "method";
+    private static final String STRING = "string";
+    private static final String AUTHORIZATION = "Authorization";
+    private static final String AUTH_HEADER_VALUE = "Basic a2Vr";
+
+    private static final String CONTENT_TYPE = "Content-Type";
+    private static final String IMAGE_PNG = "image/png";
+    private static final String TEXT_PLAIN = "text/plain";
+
+    private static final String REQUEST_HEADERS = "Request: {}\nHeaders:\n{}";
+    private static final String RESPONSE_HEADERS = "Response: status code {}, {}\nHeaders:\n{}";
+
+    private static final ExtendedHttpLoggingInterceptor LOGGING_INTERCEPTOR = new ExtendedHttpLoggingInterceptor(
+            ExtendedHttpLoggingInterceptor.class, false);
+    private static final ExtendedHttpLoggingInterceptor LOGGING_INTERCEPTOR_EXT = new ExtendedHttpLoggingInterceptor(
+            ExtendedHttpLoggingInterceptor.class, true);
+
+    private final TestLogger logger = TestLoggerFactory.getTestLogger(ExtendedHttpLoggingInterceptor.class);
+
+    @Test
+    void shouldLogRequestInfoWithoutAdditionalInformationAndProtocolVersion() throws IOException
+    {
+        ClassicHttpRequest httpRequest = new BasicClassicHttpRequest(METHOD, ENDPOINT);
+        LOGGING_INTERCEPTOR.process(httpRequest, null, null);
+        assertThat(logger.getLoggingEvents(), is(List.of(info("Request: {}", httpRequest))));
+    }
+
+    @Test
+    void shouldLogRequestInfoWithoutAdditionalInformation() throws IOException
+    {
+        ClassicHttpRequest httpRequest = new BasicClassicHttpRequest(METHOD, ENDPOINT);
+        ProtocolVersion protocolVersion = new ProtocolVersion("TLS", 1, 1);
+        httpRequest.setVersion(protocolVersion);
+        LOGGING_INTERCEPTOR.process(httpRequest, null, null);
+        assertThat(logger.getLoggingEvents(), is(List.of(info("Request: {} {}", protocolVersion, httpRequest))));
+    }
+
+    @Test
+    void shouldLogRequestInfoWithAdditionalInformationNoBody() throws IOException
+    {
+        Header authHeader = new BasicHeader(AUTHORIZATION, AUTH_HEADER_VALUE);
+        BasicHttpRequest httpRequest = new BasicHttpRequest(METHOD, ENDPOINT);
+        httpRequest.setHeader(authHeader);
+        LOGGING_INTERCEPTOR_EXT.process(httpRequest, null, null);
+        assertThat(logger.getLoggingEvents(),
+                is(List.of(info(REQUEST_HEADERS, httpRequest, authHeader.toString()))));
+    }
+
+    @Test
+    void shouldLogRequestInfoWithAdditionalInformationWithNotTextBody() throws IOException
+    {
+        Header contentHeader = new BasicHeader(CONTENT_TYPE, IMAGE_PNG);
+        ClassicHttpRequest httpRequest = new BasicClassicHttpRequest(METHOD, ENDPOINT);
+        httpRequest.setHeader(contentHeader);
+        HttpEntity entity = new BasicHttpEntity(new ByteArrayInputStream(new byte[] { 1 }), ContentType.IMAGE_PNG);
+        httpRequest.setEntity(entity);
+        LOGGING_INTERCEPTOR_EXT.process(httpRequest, null, null);
+        assertThat(logger.getLoggingEvents(),
+                is(List.of(info(REQUEST_HEADERS, httpRequest, contentHeader.toString()))));
+    }
+
+    @Test
+    void shouldLogRequestInfoWithAdditionalInformationWithTextBody() throws IOException
+    {
+        Header contentHeader = new BasicHeader(CONTENT_TYPE, TEXT_PLAIN);
+        ClassicHttpRequest httpRequest = new BasicClassicHttpRequest(METHOD, ENDPOINT);
+        httpRequest.setHeader(contentHeader);
+        HttpEntity entity = new StringEntity(STRING);
+        httpRequest.setEntity(entity);
+        LOGGING_INTERCEPTOR_EXT.process(httpRequest, null, null);
+        assertThat(logger.getLoggingEvents(), is(List.of(info("Request: {}\nHeaders:\n{}\nBody: {}", httpRequest,
+                contentHeader.toString(), new String(entity.getContent().readAllBytes(), StandardCharsets.UTF_8)))));
+    }
+
+    @Test
+    void shouldLogResponseInfoWithoutAdditionalInformation()
+    {
+        HttpResponse httpResponse = new HttpResponse();
+        httpResponse.setFrom(ENDPOINT_URI);
+        httpResponse.setStatusCode(HttpStatus.SC_OK);
+        LOGGING_INTERCEPTOR.handle(httpResponse);
+        assertThat(logger.getLoggingEvents(),
+                is(List.of(info("Response: status code {}, {}", HttpStatus.SC_OK, ENDPOINT_URI))));
+    }
+
+    @Test
+    void shouldLogResponseInfoWithAdditionalInformationNoBody()
+    {
+        HttpResponse httpResponse = new HttpResponse();
+        httpResponse.setFrom(ENDPOINT_URI);
+        httpResponse.setStatusCode(HttpStatus.SC_OK);
+        Header authHeader = new BasicHeader(AUTHORIZATION, AUTH_HEADER_VALUE);
+        httpResponse.setResponseHeaders(authHeader);
+        LOGGING_INTERCEPTOR_EXT.handle(httpResponse);
+        assertThat(logger.getLoggingEvents(),
+                is(List.of(info(RESPONSE_HEADERS, HttpStatus.SC_OK, ENDPOINT_URI, authHeader.toString()))));
+    }
+
+    @Test
+    void shouldLogResponseInfoWithAdditionalInformationWithNotTextBody()
+    {
+        HttpResponse httpResponse = new HttpResponse();
+        httpResponse.setFrom(ENDPOINT_URI);
+        httpResponse.setStatusCode(HttpStatus.SC_OK);
+        Header contentHeader = new BasicHeader(CONTENT_TYPE, IMAGE_PNG);
+        httpResponse.setResponseHeaders(contentHeader);
+        httpResponse.setResponseBody(new byte[] { 1 });
+        LOGGING_INTERCEPTOR_EXT.handle(httpResponse);
+        assertThat(logger.getLoggingEvents(),
+                is(List.of(info(RESPONSE_HEADERS, HttpStatus.SC_OK, ENDPOINT_URI, contentHeader.toString()))));
+    }
+
+    @ParameterizedTest
+    @CsvSource({
+            TEXT_PLAIN, "text/html", "text/xml", "application/json", "application/xml"
+    })
+    void shouldLogResponseInfoWithAdditionalInformationWithBody(String contentType)
+    {
+        HttpResponse httpResponse = new HttpResponse();
+        httpResponse.setFrom(ENDPOINT_URI);
+        httpResponse.setStatusCode(HttpStatus.SC_OK);
+        Header contentHeader = new BasicHeader(CONTENT_TYPE, contentType);
+        httpResponse.setResponseHeaders(contentHeader);
+        httpResponse.setResponseBody(STRING.getBytes(StandardCharsets.UTF_8));
+        LOGGING_INTERCEPTOR_EXT.handle(httpResponse);
+        assertThat(logger.getLoggingEvents(), is(List.of(info("Response: status code {}, {}\nHeaders:\n{}\nBody: {}",
+                HttpStatus.SC_OK, ENDPOINT_URI, contentHeader.toString(), STRING))));
+    }
+}