Code address of this series: https://github.com/JoJoTec/spring-cloud-parent

In this section, we implement the GlobalFilter for public logging based on the Publisher factory with link information implemented earlier. Review our needs:

We need to record the of each request at the gateway:

• HTTP related elements:
  • URL related information
  • Request information, such as HTTP HEADER, request time, etc
  • Some types of request bodies
  • Response information, such as response code
  • Response body for certain types of responses
• Link information

What should be noted about the Body that records the request and response

As mentioned in the previous chapter, if the results of the request and response body processing are put into the main link, the link information of Spring Cloud Sleuth will be lost. There are two other points to note:

• TCP sticky packet unpacking causes a request body to be divided into several copies or a packet contains several requests
• After reading, release the data buffer read from the original request body

Why release the DataBuffer read from the original request body? If the data buffer occupied after reading is not released manually, the underlying count will not return to zero, resulting in memory leakage. It can be seen from the framework code that the DataBuffer here needs to be released manually. Refer to the source code:

ByteBufferDecoder.java

@Override
public ByteBuffer decode(DataBuffer dataBuffer, ResolvableType elementType,
		@Nullable MimeType mimeType, @Nullable Map<String, Object> hints) {

	int byteCount = dataBuffer.readableByteCount();
	ByteBuffer copy = ByteBuffer.allocate(byteCount);
	copy.put(dataBuffer.asByteBuffer());
	copy.flip();
	DataBufferUtils.release(dataBuffer);
	if (logger.isDebugEnabled()) {
		logger.debug(Hints.getLogPrefix(hints) + "Read " + byteCount + " bytes");
	}
	return copy;
}

We want to convert the body that can be output to the log into a string for output. In order to simplify the code and prevent errors, we use a tool class to read the DataBuffer into a string and release it:

package com.github.jojotech.spring.cloud.apigateway.common;

import com.google.common.base.Charsets;

import org.springframework.core.io.buffer.DataBuffer;
import org.springframework.core.io.buffer.DataBufferUtils;

public class BufferUtil {
	public static String dataBufferToString(DataBuffer dataBuffer) {
		byte[] content = new byte[dataBuffer.readableByteCount()];
		dataBuffer.read(content);
		DataBufferUtils.release(dataBuffer);
		return new String(content, Charsets.UTF_8);
	}
}

Write and implement GlobalFilter for public logging

With so much foreshadowing, we can finally start writing this log GlobalFilter:

package com.github.jojotech.spring.cloud.apigateway.filter;

import java.net.URI;
import java.util.Set;

import com.alibaba.fastjson.JSON;
import com.github.jojotech.spring.cloud.apigateway.common.BufferUtil;
import com.github.jojotech.spring.cloud.apigateway.common.TracedPublisherFactory;
import lombok.extern.log4j.Log4j2;
import org.reactivestreams.Publisher;
import reactor.core.publisher.Flux;
import reactor.core.publisher.Mono;

import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.cloud.gateway.filter.GatewayFilterChain;
import org.springframework.cloud.gateway.filter.GlobalFilter;
import org.springframework.core.Ordered;
import org.springframework.core.io.buffer.DataBuffer;
import org.springframework.core.io.buffer.DataBufferFactory;
import org.springframework.http.HttpHeaders;
import org.springframework.http.HttpMethod;
import org.springframework.http.MediaType;
import org.springframework.http.server.reactive.ServerHttpRequest;
import org.springframework.http.server.reactive.ServerHttpRequestDecorator;
import org.springframework.http.server.reactive.ServerHttpResponse;
import org.springframework.http.server.reactive.ServerHttpResponseDecorator;
import org.springframework.stereotype.Component;
import org.springframework.web.server.ServerWebExchange;

@Log4j2
@Component
public class CommonLogFilter implements GlobalFilter, Ordered {
	//body format that can be output
	public static final Set<MediaType> legalLogMediaTypes = Set.of(
			MediaType.TEXT_XML,
			MediaType.TEXT_PLAIN,
			MediaType.APPLICATION_XML,
			MediaType.APPLICATION_JSON
	);

	@Autowired
	private TracedPublisherFactory tracedPublisherFactory;

	@Override
	public Mono<Void> filter(ServerWebExchange exchange, GatewayFilterChain chain) {
		long startTime = System.currentTimeMillis();
		ServerHttpRequest request = exchange.getRequest();
		ServerHttpResponse response = exchange.getResponse();
		//Gets the factory of the buffer used to unpack the aggregate read request and response body
		DataBufferFactory dataBufferFactory = response.bufferFactory();
		//Request http header
		HttpHeaders requestHeaders = request.getHeaders();
		//Request body type
		MediaType requestContentType = requestHeaders.getContentType();
		//Request uri
		String uri = request.getURI().toString();
		//Request http method
		HttpMethod method = request.getMethod();
		log.info("{} -> {}: header: {}", method, uri, JSON.toJSONString(requestHeaders));
		Flux<DataBuffer> dataBufferFlux = tracedPublisherFactory.getTracedFlux(request.getBody(), exchange)
				//Use buffer to read all the bodies here to avoid the impact of unpacking
				.buffer()
				.map(dataBuffers -> {
					//Glue all buffer s together
					DataBuffer dataBuffer = dataBufferFactory.join(dataBuffers);
					//body will be output only when debug is enabled
					if (log.isDebugEnabled()) {
						//Only a specific body type will output a specific
						if (legalLogMediaTypes.contains(requestContentType)) {
							try {
								//Convert the body into a String for output. At the same time, note that the original buffer needs to be released because the body stream has been read out, but there is no place to recycle
								//reference resources
								String s = BufferUtil.dataBufferToString(dataBuffer);
								log.debug("body: {}", s);
								dataBuffer = dataBufferFactory.wrap(s.getBytes());
							}
							catch (Exception e) {
								log.error("error read request body: {}", e.getMessage(), e);
							}
						}
						else {
							log.debug("body: {}", request);
						}
					}
					return dataBuffer;
				});
		return chain.filter(exchange.mutate().request(new ServerHttpRequestDecorator(request) {
			@Override
			public Flux<DataBuffer> getBody() {
				return dataBufferFlux;
			}
		}).response(new ServerHttpResponseDecorator(response) {
			@Override
			public Mono<Void> writeWith(Publisher<? extends DataBuffer> body) {
				HttpHeaders responseHeaders = super.getHeaders();
				//The call here is to write back the response to the HttpClientConnect of the client, which has jumped out of the link Span of Spring Cloud Sleuth, so there is no link tracking information
				//However, in the CommonTraceFilter, we put the link information into the response Header, so we don't need to manually add the link information here
				log.info("response: {} -> {} {} header: {}, time: {}ms", method, uri, getStatusCode(), JSON.toJSONString(responseHeaders), System.currentTimeMillis() - startTime);
				final MediaType contentType = responseHeaders.getContentType();
				if (contentType != null && body instanceof Flux && legalLogMediaTypes.contains(contentType) && log.isDebugEnabled()) {
					//There is a problem of TCP packet sticking and unpacking. This body is written many times, and the complete body cannot be obtained in one call, so it is converted to fluxBody, and the buffer is used to accept the complete body
					Flux<? extends DataBuffer> fluxBody = tracedPublisherFactory.getTracedFlux(Flux.from(body), exchange);
					return super.writeWith(fluxBody.buffer().map(buffers -> {
						DataBuffer buffer = dataBufferFactory.join(buffers);
						try {
							String s = BufferUtil.dataBufferToString(buffer);
							log.debug("response: body: {}", s);
							return dataBufferFactory.wrap(s.getBytes());
						} catch (Exception e) {
							log.error("error read response body: {}", e.getMessage(), e);
						}
						return buffer;
					}));
				}
				// if body is not a flux. never got there.
				return super.writeWith(body);
			}
		}).build());
	}

	@Override
	public int getOrder() {
		//Specify the order after the CommonTraceFilter (this Filter reads the link information, preferably before all filters)
		return new CommonTraceFilter().getOrder() + 1;
	}
}

The points needing attention are clearly marked in the notes. Please refer to them.

view log

By adding the following log configuration, we open the log of the body, so that the log is complete:

<AsyncLogger name="com.github.jojotech.spring.cloud.apigateway.filter.CommonLogFilter" level="debug" additivity="false" includeLocation="true">
    <appender-ref ref="console" />
</AsyncLogger>

Send a POST request with body, and you can see from the log:

2021-11-29 14:08:42,231  INFO [sports,8481ce2786b686fa,8481ce2786b686fa] [24916] [reactor-http-nio-2][com.github.jojotech.spring.cloud.apigateway.filter.CommonLogFilter:59]:POST -> http://127.0.0.1:8181/test-ss/anything?test=1: header: {"Content-Type":["text/plain"],"User-Agent":["PostmanRuntime/7.28.4"],"Accept":["*/*"],"Postman-Token":["666b17c9-0789-46e6-b515-9a4538803308"],"Host":["127.0.0.1:8181"],"Accept-Encoding":["gzip, deflate, br"],"Connection":["keep-alive"],"content-length":["8"]}
2021-11-29 14:08:42,233 DEBUG [sports,8481ce2786b686fa,8481ce2786b686fa] [24916] [reactor-http-nio-2][com.github.jojotech.spring.cloud.apigateway.filter.CommonLogFilter:74]:body: ifasdasd
2021-11-29 14:08:42,463  INFO [sports,,] [24916] [reactor-http-nio-2][com.github.jojotech.spring.cloud.apigateway.filter.CommonLogFilter$1:96]:response: POST -> http://127.0.0.1:8181/test-ss/anything?test=1 200 OK header: {"traceId":["8481ce2786b686fa"],"spanId":["8481ce2786b686fa"],"Date":["Mon, 29 Nov 2021 14:08:43 GMT"],"Content-Type":["application/json"],"Server":["gunicorn/19.9.0"],"Access-Control-Allow-Origin":["*"],"Access-Control-Allow-Credentials":["true"],"content-length":["886"]}, time: 232ms
2021-11-29 14:08:42,466 DEBUG [sports,8481ce2786b686fa,8481ce2786b686fa] [24916] [reactor-http-nio-2][com.github.jojotech.spring.cloud.apigateway.filter.CommonLogFilter$1:105]:response: body: {
  "args": {
    "test": "1"
  }, 
  "data": "ifasdasd", 
  "files": {}, 
  "form": {}, 
  "headers": {
    "Accept": "*/*", 
    "Accept-Encoding": "gzip, deflate, br", 
    "Content-Length": "8", 
    "Content-Type": "text/plain", 
    "Forwarded": "proto=http;host=\"127.0.0.1:8181\";for=\"127.0.0.1:57526\"", 
    "Host": "httpbin.org", 
    "Postman-Token": "666b17c9-0789-46e6-b515-9a4538803308", 
    "User-Agent": "PostmanRuntime/7.28.4", 
    "X-Amzn-Trace-Id": "Root=1-61a4deeb-3d016ff729306d862edcca0b", 
    "X-B3-Parentspanid": "8481ce2786b686fa", 
    "X-B3-Sampled": "0", 
    "X-B3-Spanid": "5def545b28a7a842", 
    "X-B3-Traceid": "8481ce2786b686fa", 
    "X-Forwarded-Host": "127.0.0.1:8181", 
    "X-Forwarded-Prefix": "/test-ss"
  }, 
  "json": null, 
  "method": "POST", 
  "origin": "127.0.0.1, 61.244.202.46", 
  "url": "http://127.0.0.1:8181/anything?test=1"
}

2021-11-29 14:08:42,474  INFO [sports,,] [24916] [reactor-http-nio-2][reactor.util.Loggers$Slf4JLogger:269]:8481ce2786b686fa,8481ce2786b686fa -> 127.0.0.1:57526 - - [2021-11-29T14:08:42.230008Z[Etc/GMT]] "POST /test-ss/anything?test=1 HTTP/1.1" 200 886 243 ms