fi.evolver.basics.spring.http.LoggingHttpClient Maven / Gradle / Ivy

Go to download
package fi.evolver.basics.spring.http;

import java.io.ByteArrayOutputStream;
import java.io.IOException;
import java.io.UncheckedIOException;
import java.net.Authenticator;
import java.net.CookieHandler;
import java.net.ProxySelector;
import java.net.URI;
import java.net.http.HttpClient;
import java.net.http.HttpHeaders;
import java.net.http.HttpRequest;
import java.net.http.HttpRequest.BodyPublisher;
import java.net.http.HttpResponse;
import java.net.http.HttpResponse.BodyHandler;
import java.net.http.HttpResponse.BodySubscriber;
import java.net.http.HttpResponse.PushPromiseHandler;
import java.net.http.HttpResponse.ResponseInfo;
import java.nio.ByteBuffer;
import java.nio.channels.Channels;
import java.nio.channels.WritableByteChannel;
import java.time.Duration;
import java.time.LocalDateTime;
import java.util.ArrayList;
import java.util.List;
import java.util.Map;
import java.util.Objects;
import java.util.Optional;
import java.util.concurrent.CompletableFuture;
import java.util.concurrent.CompletionStage;
import java.util.concurrent.Executor;
import java.util.concurrent.Flow.Subscriber;
import java.util.concurrent.Flow.Subscription;
import java.util.zip.GZIPOutputStream;

import javax.net.ssl.SSLContext;
import javax.net.ssl.SSLParameters;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.http.HttpStatus;

import fi.evolver.basics.spring.log.MessageLogService;
import fi.evolver.basics.spring.log.entity.MessageLog.Direction;
import fi.evolver.basics.spring.log.entity.MessageLogMetadata;
import fi.evolver.basics.spring.util.MessageChainUtils;
import fi.evolver.basics.spring.util.MessageChainUtils.MessageChain;
import fi.evolver.utils.ContextUtils;
import fi.evolver.utils.ContextUtils.Context;
import fi.evolver.utils.ContextUtils.ContextCloser;


/**
 * A wrapper for java.net.HttpClient that logs requests to communication log.
 */
public class LoggingHttpClient extends HttpClient {
	private static final Logger LOG = LoggerFactory.getLogger(LoggingHttpClient.class);

	private final MessageLogService messageLogService;
	private final HttpClient httpClient;


	public LoggingHttpClient(MessageLogService messageLogService, HttpClient httpClient) {
		Objects.requireNonNull(messageLogService, "%s is required".formatted(MessageLogService.class.getSimpleName()));
		Objects.requireNonNull(httpClient, "%s is required".formatted(HttpClient.class.getSimpleName()));
		this.messageLogService = messageLogService;
		this.httpClient = httpClient;
	}


	@Override
	public Optional cookieHandler() {
		return httpClient.cookieHandler();
	}

	@Override
	public Optional connectTimeout() {
		return httpClient.connectTimeout();
	}

	@Override
	public Redirect followRedirects() {
		return httpClient.followRedirects();
	}

	@Override
	public Optional proxy() {
		return httpClient.proxy();
	}

	@Override
	public SSLContext sslContext() {
		return httpClient.sslContext();
	}

	@Override
	public SSLParameters sslParameters() {
		return httpClient.sslParameters();
	}

	@Override
	public Optional authenticator() {
		return httpClient.authenticator();
	}

	@Override
	public Version version() {
		return httpClient.version();
	}

	@Override
	public Optional executor() {
		return httpClient.executor();
	}


	@Override
	public  HttpResponse send(HttpRequest request, BodyHandler responseBodyHandler) throws IOException, InterruptedException {
		return send(request, responseBodyHandler, defaultLogParameters(request));
	}

	/**
	 * Sends the HTTP request and logs the result.
	 *
	 * @param  The response body type.
	 * @param request Details about the HTTP request.
	 * @param responseBodyHandler Handler for the response body.
	 * @param logParameters Parameters for logging.
	 * @return The HTTP response.
	 * @throws IOException Thrown on I/O errors.
	 * @throws InterruptedException Thrown if the request is interrupted.
	 */
	public  HttpResponse send(HttpRequest request, BodyHandler responseBodyHandler, LogParameters logParameters) throws IOException, InterruptedException {
		RequestLogger requestLogger = new RequestLogger<>(messageLogService, request, responseBodyHandler, logParameters);
		try {
			HttpResponse response = httpClient.send(requestLogger.getHttpRequest(), requestLogger.getBodyHandler());
			requestLogger.setHttpResponse(response, null);
			return response;
		}
		catch (IOException | InterruptedException | RuntimeException e) {
			requestLogger.setHttpResponse(null, e);
			throw e;
		}
	}


	@Override
	public  CompletableFuture> sendAsync(HttpRequest request, BodyHandler responseBodyHandler) {
		return sendAsync(request, responseBodyHandler, defaultLogParameters(request));
	}

	/**
	 * Sends the HTTP request asynchronously and logs the result.
	 *
	 * @param  The response body type.
	 * @param request Details about the HTTP request.
	 * @param responseBodyHandler Handler for the response body.
	 * @param logParameters Parameters for logging.
	 * @return A future HTTP response.
	 */
	public  CompletableFuture> sendAsync(HttpRequest request, BodyHandler responseBodyHandler, LogParameters logParameters) {
		return sendAsync(request, responseBodyHandler, null, logParameters);
	}


	@Override
	public  CompletableFuture> sendAsync(HttpRequest request, BodyHandler responseBodyHandler, PushPromiseHandler pushPromiseHandler) {
		return sendAsync(request, responseBodyHandler, pushPromiseHandler, defaultLogParameters(request));
	}

	/**
	 * Sends the HTTP request asynchronously and logs the result.
	 *
	 * @param  The response body type.
	 * @param request Details about the HTTP request.
	 * @param responseBodyHandler Handler for the response body.
	 * @param pushPromiseHandler A push promise handler, may be null.
	 * @param logParameters Parameters for logging.
	 * @return A future HTTP response.
	 */
	public  CompletableFuture> sendAsync(HttpRequest request, BodyHandler responseBodyHandler, PushPromiseHandler pushPromiseHandler, LogParameters logParameters) {
		RequestLogger requestLogger = new RequestLogger<>(messageLogService, request, responseBodyHandler, logParameters);
		CompletableFuture> response = httpClient.sendAsync(requestLogger.getHttpRequest(), requestLogger.getBodyHandler(), pushPromiseHandler);
		return response.whenComplete(requestLogger::setHttpResponse);
	}


	private static  LogParameters defaultLogParameters(HttpRequest request) {
		return new LogParameters<>(request.uri().getPath());
	}


	private static class RequestLogger {
		private final MessageLogService messageLogService;
		private final Context context;
		private final LogParameters logParameters;

		private final long messageChainId;
		private final Optional requestSaver;
		private final LoggingBodyHandler responseSaver;
		private final LocalDateTime startTime = LocalDateTime.now();

		private final HttpRequest httpRequest;
		private Optional> httpResponse = Optional.empty();
		private Optional httpException = Optional.empty();
		private boolean logWritten;


		public RequestLogger(MessageLogService messageLogService, HttpRequest httpRequest, BodyHandler responseBodyHandler, LogParameters logParameters) {
			this.context = ContextUtils.getContext();
			this.messageChainId = MessageChainUtils.getMessageChainId();
			this.messageLogService = messageLogService;
			this.logParameters = logParameters;
			this.requestSaver = httpRequest.bodyPublisher().map(LoggingBodyPublisher::new);
			this.httpRequest = requestSaver.map(p -> (HttpRequest)new HttpRequestWrapper(httpRequest, p)).orElse(httpRequest);
			this.responseSaver = new LoggingBodyHandler(responseBodyHandler);
		}


		/**
		 * Set the result state of the HTTP request.
		 *
		 * @param httpResponse The HTTP response, if available.
		 * @param throwable The error that caused the HTTP request to fails, if any.
		 */
		public void setHttpResponse(HttpResponse httpResponse, Throwable throwable) {
			try (ContextCloser c = ContextUtils.ensureContext(context)) {
				this.httpResponse = Optional.ofNullable(httpResponse);
				this.httpException = Optional.ofNullable(throwable);

				if (httpResponse != null) {
					for (LogMetadataCallback callback: logParameters.metadataCallbacks) {
						try {
							callback.onResponse(httpResponse).forEach(logParameters::addMetadata);
						}
						catch (RuntimeException e) {
							LOG.warn("Metadata callback failed", e);
						}
					}
				}
				else {
					for (LogMetadataCallback callback: logParameters.metadataCallbacks) {
						try {
							callback.onError(throwable).forEach(logParameters::addMetadata);
						}
						catch (RuntimeException e) {
							LOG.warn("Metadata callback failed", e);
						}
					}
				}
				log();
			}
		}


		/**
		 * Returns a wrapped HTTP request.
		 *
		 * @return Wrapped HTTP request.
		 */
		public HttpRequest getHttpRequest() {
			return httpRequest;
		}


		/**
		 * Returns a wrapped body handler.
		 *
		 * @return
		 */
		public BodyHandler getBodyHandler() {
			return responseSaver;
		}


		/**
		 * Log the request if all requirements have been met. Only logs the request once.
		 */
		public synchronized void log() {
			if (logWritten)
				return;
			if (httpException.isEmpty() && (httpResponse.isEmpty() || !requestSaver.map(LoggingBodyPublisher::isDone).orElse(true) || !responseSaver.isDone()))
				return;
			if (requestSaver.map(LoggingBodyPublisher::finishAndLog).orElse(false))
				return;

			String statusCode = httpResponse
					.map(HttpResponse::statusCode)
					.map(Object::toString)
					.orElse(httpException.map(Throwable::getClass).map(Class::getSimpleName).orElse("ERROR"));

			String statusMessage = httpResponse
					.map(HttpResponse::statusCode)
					.map(HttpStatus::valueOf)
					.map(HttpStatus::getReasonPhrase)
					.orElse(httpException.map(Throwable::getMessage).orElse("Unexpected failure"));

			try (MessageChain mc = MessageChainUtils.isMessageChainOpen() ? null : MessageChainUtils.startMessageChain(messageChainId)) {
				messageLogService.logZippedMessage(
						startTime,
						logParameters.messageType,
						httpRequest.uri().getScheme(),
						httpRequest.uri().toString(),
						messageLogService.getApplicationName(),
						logParameters.targetSystem.orElse(httpRequest.uri().getHost()),
						logParameters.direction.orElseGet(() -> "GET".equalsIgnoreCase(httpRequest.method()) ? Direction.INBOUND : Direction.OUTBOUND),
						requestSaver.map(LoggingBodyPublisher::getSize).orElse(-1),
						requestSaver.map(LoggingBodyPublisher::getData).orElse(null),
						httpRequest.headers().map(),
						responseSaver.getSize(),
						responseSaver.getData(),
						httpResponse.map(HttpResponse::headers).map(HttpHeaders::map).orElse(Map.of()),
						statusCode,
						statusMessage,
						logParameters.metadata);
			}
			logWritten = true;
		}


		/**
		 * A wrapper BodyPublisher that wraps any subscribers so the body contents can be captured for logging.
		 *
		 * This class is used for capturing the HTTP request body for logging.
		 */
		private class LoggingBodyPublisher implements BodyPublisher {
			private final BodyPublisher bodyPublisher;
			private LoggingRequestSubscriber subscriber;


			public LoggingBodyPublisher(BodyPublisher bodyPublisher) {
				this.bodyPublisher = bodyPublisher;
			}


			@Override
			public void subscribe(Subscriber subscriber) {
				this.subscriber = new LoggingRequestSubscriber(subscriber);
				bodyPublisher.subscribe(this.subscriber);
			}

			@Override
			public long contentLength() {
				return bodyPublisher.contentLength();
			}


			public boolean finishAndLog() {
				boolean result = subscriber == null;
				if (result)
					subscribe(null);
				return result;
			}


			public boolean isDone() {
				// body publishers with 0 length will not be subscribed to by the http client
				if (contentLength() == 0)
					return true;
				return subscriber != null && subscriber.done;
			}

			public int getSize() {
				return subscriber != null ? subscriber.size : (int) contentLength();
			}

			public byte[] getData() {
				return subscriber != null ? subscriber.bout.toByteArray() : null;
			}
		}



		/**
		 * A wrapper class for subscribers of the {@link LoggingBodyPublisher}.
		 *
		 * Captures the data from the actual BodyPublisher and passes it on to the downstream
		 * Subscriber. In the case the downstream cancels the subscription, we still read the rest
		 * of the data for logging purposes.
		 */
		private class LoggingRequestSubscriber implements Subscriber {
			private volatile Subscriber downstreamSubscriber;

			private final ByteArrayOutputStream bout = new ByteArrayOutputStream();
			private final WritableByteChannel channel;
			private int size;
			private boolean done;


			public LoggingRequestSubscriber(Subscriber downstreamSubscriber) {
				this.downstreamSubscriber = downstreamSubscriber;
				try {
					this.channel = Channels.newChannel(new GZIPOutputStream(bout));
				}
				catch (IOException e) {
					throw new UncheckedIOException(e);
				}
			}


			@Override
			public void onSubscribe(Subscription subscription) {
				if (downstreamSubscriber != null)
					downstreamSubscriber.onSubscribe(new MockSubscription(subscription));
				else
					subscription.request(Long.MAX_VALUE);
			}


			private void removeDownstream() {
				downstreamSubscriber = null;
			}


			@Override
			public void onNext(ByteBuffer buffer) {
				try (ContextCloser c = ContextUtils.ensureContext(context)) {
					try {
						size += buffer.remaining();
						channel.write(buffer.duplicate());
					}
					catch (IOException e) {
						throw new UncheckedIOException("Could not write to channel", e);
					}

					try {
						if (downstreamSubscriber != null)
							downstreamSubscriber.onNext(buffer);
					}
					catch (RuntimeException e) {
						LOG.warn("Downstream Subscriber.onNext() failed");
					}
				}
			}


			@Override
			public void onError(Throwable throwable) {
				try (ContextCloser c = ContextUtils.ensureContext(context)) {
					try {
						channel.close();
					}
					catch (IOException | RuntimeException e) {
						LOG.error("Could not close channel on error", e);
					}
					done = true;
					log();
					if (downstreamSubscriber != null)
						downstreamSubscriber.onError(throwable);
					removeDownstream();
				}
			}


			@Override
			public void onComplete() {
				try (ContextCloser c = ContextUtils.ensureContext(context)) {
					try {
						channel.close();
					}
					catch (IOException | RuntimeException e) {
						LOG.error("Could not close channel", e);
					}
					done = true;
					log();
					if (downstreamSubscriber != null)
						downstreamSubscriber.onComplete();
					removeDownstream();
				}
			}


			private class MockSubscription implements Subscription {
				private final Subscription subscription;

				public MockSubscription(Subscription subscription) {
					this.subscription = subscription;
				}

				@Override
				public void request(long n) {
					subscription.request(n);
				}

				@Override
				public void cancel() {
					removeDownstream();
					subscription.request(Long.MAX_VALUE);
				}
			}
		}


		/**
		 * A wrapper BodyHandler that wraps any subscribers so the body contents can be captured for logging.
		 *
		 * This class is used for capturing the HTTP response body for logging.
		 */
		public class LoggingBodyHandler implements BodyHandler {
			private final BodyHandler downstreamBodyHandler;
			private LoggingBodySubscriber subscriber;

			public LoggingBodyHandler(BodyHandler downstream) {
				this.downstreamBodyHandler = downstream;
			}

			@Override
			public BodySubscriber apply(ResponseInfo responseInfo) {
				BodySubscriber downstreamSubscriber = downstreamBodyHandler.apply(responseInfo);
				subscriber = new LoggingBodySubscriber(downstreamSubscriber);
				return subscriber;
			}


			public boolean isDone() {
				return subscriber != null && subscriber.done;
			}

			public int getSize() {
				return subscriber != null ? subscriber.size : -1;
			}

			public byte[] getData() {
				return subscriber != null ? subscriber.bout.toByteArray() : null;
			}
		}


		/**
		 * A wrapper class for subscribers of the {@link LoggingBodyHandler}.
		 *
		 * Captures the data meant for the actual BodySubscriber and passes it on to the downstream
		 * BodySubscriber. In the case the downstream cancels the subscription, we still read the rest
		 * of the data for logging purposes.
		 */
		private class LoggingBodySubscriber implements BodySubscriber {
			private volatile BodySubscriber downstreamSubscriber;

			private final ByteArrayOutputStream bout = new ByteArrayOutputStream();
			private final WritableByteChannel channel;
			private int size;
			private boolean done;
			private final CompletionStage body;


			public LoggingBodySubscriber(BodySubscriber downstreamSubscriber) {
				this.downstreamSubscriber = downstreamSubscriber;
				this.body = downstreamSubscriber.getBody();
				try {
					this.channel = Channels.newChannel(new GZIPOutputStream(bout));
				}
				catch (IOException e) {
					throw new UncheckedIOException(e);
				}
			}


			@Override
			public void onSubscribe(Subscription subscription) {
				downstreamSubscriber.onSubscribe(new MockSubscription(subscription));
			}


			private void removeDownstream() {
				downstreamSubscriber = null;
			}


			@Override
			public void onNext(List items) {
				try (ContextCloser c = ContextUtils.ensureContext(context)) {
					for (ByteBuffer buffer : items) {
						try {
							size += buffer.remaining();
							channel.write(buffer.duplicate());
						}
						catch (IOException e) {
							throw new UncheckedIOException("Could not write to channel", e);
						}
					}

					try {
						if (downstreamSubscriber != null) {
							downstreamSubscriber.onNext(items);
						}
					}
					catch (RuntimeException e) {
						LOG.warn("Downstream BodySubscriber.onNext() failed");
					}
				}
			}


			@Override
			public void onError(Throwable throwable) {
				try (ContextCloser c = ContextUtils.ensureContext(context)) {
					try {
						channel.close();
					}
					catch (IOException | RuntimeException e) {
						LOG.error("Could not close channel on error", e);
					}
					done = true;
					log();
					if (downstreamSubscriber != null) {
						downstreamSubscriber.onError(throwable);
					}
					removeDownstream();
				}
			}


			@Override
			public void onComplete() {
				try (ContextCloser c = ContextUtils.ensureContext(context)) {
					try {
						channel.close();
					}
					catch (IOException | RuntimeException e) {
						LOG.error("Could not close channel", e);
					}
					done = true;
					log();
					if (downstreamSubscriber != null) {
						downstreamSubscriber.onComplete();
					}
					removeDownstream();
				}
			}


			@Override
			public CompletionStage getBody() {
				return body;
			}


			private class MockSubscription implements Subscription {
				private final Subscription subscription;

				public MockSubscription(Subscription subscription) {
					this.subscription = subscription;
				}

				@Override
				public void request(long n) {
					subscription.request(n);
				}

				@Override
				public void cancel() {
					removeDownstream();
					subscription.request(Long.MAX_VALUE);
				}
			}
		}
	}


	public static class LogParameters {
		private final String messageType;
		private final List metadata = new ArrayList<>();
		private final List> metadataCallbacks = new ArrayList<>();
		private Optional targetSystem = Optional.empty();
		private Optional direction = Optional.empty();

		public LogParameters(String messageType) {
			this.messageType = messageType;
		}

		public LogParameters addMetadata(String key, Object value) {
			if (key != null && value != null) {
				try {
					metadata.add(new MessageLogMetadata(key, value.toString()));
				}
				catch (RuntimeException e) {
					LOG.warn("Could not add metadata for key {}", key, e);
				}
			}
			return this;
		}

		public LogParameters addMetadataCallback(LogMetadataCallback callback) {
			if (callback != null)
				metadataCallbacks.add(callback);
			return this;
		}

		public LogParameters setTargetSystem(String targetSystem) {
			this.targetSystem = Optional.ofNullable(targetSystem);
			return this;
		}

		public LogParameters setDirection(Direction direction) {
			this.direction = Optional.ofNullable(direction);
			return this;
		}
	}


	/**
	 * A wrapper class for HttpRequests that overrides the configured BodyPublisher.
	 *
	 * This class is used for replacing the actual BodyPublisher with a wrapper class.
	 */
	private static class HttpRequestWrapper extends HttpRequest {
		private final HttpRequest httpRequest;
		private final Optional bodyPublisher;


		public HttpRequestWrapper(HttpRequest httpRequest, BodyPublisher bodyPublisher) {
			this.httpRequest = httpRequest;
			this.bodyPublisher = Optional.ofNullable(bodyPublisher);
		}


		@Override
		public Optional bodyPublisher() {
			return bodyPublisher;
		}

		@Override
		public String method() {
			return httpRequest.method();
		}

		@Override
		public Optional timeout() {
			return httpRequest.timeout();
		}

		@Override
		public boolean expectContinue() {
			return httpRequest.expectContinue();
		}

		@Override
		public URI uri() {
			return httpRequest.uri();
		}

		@Override
		public Optional version() {
			return httpRequest.version();
		}

		@Override
		public HttpHeaders headers() {
			return httpRequest.headers();
		}
	}


	/**
	 * Callback for adding log metadata based on the response.
	 *
	 * @param  The response body type.
	 */
	public static interface LogMetadataCallback {

		/**
		 * Add extra metadata to log on HTTP response.
		 *
		 * @param httpResponse The HTTP response.
		 * @return Metadata to add to the log.
		 */
		Map onResponse(HttpResponse httpResponse);

		/**
		 * Add extra metadata to log on error situations.
		 *
		 * @param throwable Details about the encountered error.
		 * @return Metadata to add to the log.
		 */
		default Map onError(Throwable throwable) {
			return Map.of();
		}

	}

}