Spring cloud gateway - Response body logging causing out of direct memory error

Question

Below is the stack I am using to build an API gateway using Spring Cloud Gateway -

SCG - Hoxton.RELEASE
Java - 1.8
Spring Boot - 2.2.1.RELEASE

I got the below "GlobalFilter" code from internet to log request/response body. This works fine but I run into errors like

"failed to allocate 16777216 byte(s) of direct memory (used: 1023410183, max: 1038876672)"

Below is the filter code -

import java.net.URI;
import java.nio.charset.StandardCharsets;
import java.util.List;

import org.reactivestreams.Publisher;
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.MediaType;
import org.springframework.http.server.reactive.ServerHttpRequest;
import org.springframework.http.server.reactive.ServerHttpResponse;
import org.springframework.http.server.reactive.ServerHttpResponseDecorator;
import org.springframework.stereotype.Component;
import org.springframework.util.MultiValueMap;
import org.springframework.web.server.ServerWebExchange;

import com.xx.GatewayJsonLogger;

import lombok.extern.slf4j.Slf4j;
import reactor.core.publisher.Flux;
import reactor.core.publisher.Mono;

@Component
@Slf4j
public class RequestResponseLogFilter implements GlobalFilter, Ordered {

    private static final String MAGIC_HEADER = "x-debug";
    private static final String START_TIME = "startTime";

    private static final String HTTP_SCHEME = "http";

    private static final String HTTPS_SCHEME = "https";

    @Override
    public Mono<Void> filter(ServerWebExchange exchange, GatewayFilterChain chain) {
        List<String> debugHeader = exchange.getRequest().getHeaders().get(MAGIC_HEADER);
        if (!log.isDebugEnabled() && debugHeader == null) {
            // DO NOTHING
            return chain.filter(exchange);
        }
        ServerHttpRequest request = exchange.getRequest();
        URI requestURI = request.getURI();
        String scheme = requestURI.getScheme();
        if (debugHeader != null) {
            String debugHeaderContent = debugHeader.get(0);
            if (!debugHeaderContent.equalsIgnoreCase("true") && !requestURI.getPath().toLowerCase().contains(debugHeaderContent.toLowerCase())) {
                return chain.filter(exchange);
            }
        }
        if ((!HTTP_SCHEME.equalsIgnoreCase(scheme) && !HTTPS_SCHEME.equals(scheme))) {
            return chain.filter(exchange);
        }
        long startTime = System.currentTimeMillis();
        exchange.getAttributes().put(START_TIME, startTime);
        logRequest(request, exchange.getAttribute("cachedRequestBodyObject"));
        return chain.filter(exchange.mutate().response(logResponse(exchange)).build());
    }

    @Override
    public int getOrder() {
        return Integer.MIN_VALUE;
    }

    private void logRequest(ServerHttpRequest request, String body) {
        URI requestURI = request.getURI();
        String scheme = requestURI.getScheme();
        HttpHeaders headers = request.getHeaders();
        log.info("Request Scheme:{},Path:{}", scheme, requestURI.getPath());
        log.info("Request Method:{},IP:{},Host:{}", request.getMethod(), request.getRemoteAddress(), requestURI.getHost());
        headers.forEach((key, value) -> log.debug("Request Headers:Key->{},Value->{}", key, value));
        MultiValueMap<String, String> queryParams = request.getQueryParams();
        if (!queryParams.isEmpty()) {
            queryParams.forEach((key, value) -> log.info("Request Query Param :Key->({}),Value->({})", key, value));
        }
        MediaType contentType = headers.getContentType();
        long length = headers.getContentLength();
        log.info("Request ContentType:{},Content Length:{}", contentType, length);
        if (body != null) {
            GatewayJsonLogger.log(null, requestURI.getPath(), body.replaceAll("\"password\"\\s*:\\s*\".*\"", "\"password\":\"*******\""), "REQUEST");
        }
    }

    private ServerHttpResponseDecorator logResponse(ServerWebExchange exchange) {
        ServerHttpResponse origResponse = exchange.getResponse();
        Long startTime = exchange.getAttribute(START_TIME);
        log.info("Response HttpStatus:{}", origResponse.getStatusCode());
        HttpHeaders headers = origResponse.getHeaders();
        headers.forEach((key, value) -> log.debug("[RequestLogFilter]Headers:Key->{},Value->{}", key, value));
        MediaType contentType = headers.getContentType();
        long length = headers.getContentLength();
        log.info("Response ContentType:{},Content Length:{}", contentType, length);
        Long executeTime = (System.currentTimeMillis() - startTime);
        log.info("Response Original Path:{},Cost:{} ms", exchange.getRequest().getURI().getPath(), executeTime);
        DataBufferFactory bufferFactory = origResponse.bufferFactory();
        return new ServerHttpResponseDecorator(origResponse) {
            @Override
            public Mono<Void> writeWith(Publisher<? extends DataBuffer> body) {
                if (body instanceof Flux) {
                    Flux<? extends DataBuffer> fluxBody = (Flux<? extends DataBuffer>) body;
                    return super.writeWith(fluxBody.map(dataBuffer -> {
                        byte[] content = new byte[dataBuffer.readableByteCount()];
                        dataBuffer.read(content);
                        String bodyContent = new String(content, StandardCharsets.UTF_8);
                        GatewayJsonLogger.log(null, exchange.getRequest().getURI().getPath(), bodyContent, "RESPONSE");
                        return bufferFactory.wrap(content);
                    }));
                }
                return super.writeWith(body);
            }
        };

    }
}

I think the "DataBuffer" being used here for logging response is causing memory issue; request part looks fine as it is coming from a cached object. Could you please help advise a more efficient way to log response? I have tried removing this filter and doing below steps -

1. Enable DEBUG logging for reactor.netty
2. Add below property to application.yml
   spring.cloud.gateway.httpserver.wiretap = true

This works in the sense that I can see request and response headers+body in log file but it is not in a readable format (some hex format I think).

Regards, Jacob

Answer 1

Try this:

return new ServerHttpResponseDecorator(origResponse) {
        @Override
        public Mono<Void> writeWith(Publisher<? extends DataBuffer> body) {
            if (body instanceof Flux) {
                Flux<? extends DataBuffer> fluxBody = (Flux<? extends DataBuffer>) body;
                return super.writeWith(fluxBody.map(dataBuffer -> {
                try{
                    byte[] content = new byte[dataBuffer.readableByteCount()];
                    dataBuffer.read(content);
                    String bodyContent = new String(content, StandardCharsets.UTF_8);
                    GatewayJsonLogger.log(null, exchange.getRequest().getURI().getPath(), bodyContent, "RESPONSE");
                    return bufferFactory.wrap(content);
                 }
                 finally{
                    DataBufferUtils.release(dataBuffer);
                }
                }));
            }
            return super.writeWith(body);
        }
    };

Answer 2

It's seems that the dataBuffer you use should be released using dataBuffer.release() because you provide a new one using bufferFactory.wrap(content) so the original dataBuffer is never released and cause memory leak.