OutOfMemoryError produced by huge response, that must be excluded.

[stavskiy]

Hello!
I catch java.lang.OutOfMemoryError: Java heap space when I download huge text file (70 Mb) and response body become very big. This request (and response correspondingly) was excluded in property file and doesn't appear in log.
JVM params are -Xmx256m -Xms128m
I tried to use logbook.write.chunk-size with values 10 and 10000 - it didn't work.
Here is the error log: https://pastebin.com/ESTUwqZW
How can I avoid this exception?

• Version used: 1.9.0

[whiskeysierra]

What client are you using? Apache HTTP Client?

[stavskiy]

No, I'm using Spring RestController and download file by Postman.
Stream from mongoDB goes to OutputStream of HttpServletResponse directly.

[whiskeysierra]

Ok, so you're responding from within your service. Can you show me your request and the logbook configuration?

[stavskiy]

Yes,
logbook configuration is:

logbook:
exclude:
 - /health
 - /v2/api-docs
 - /swagger-ui.html
 - /admin/**
 - /webjars/**
 - /swagger-resources/**
 - /etrack/exportArchive
obfuscate:
headers:
  - Authorization
  - X-Secret
parameters:
- access_token
   - password

Request is:
`POST /etrack/exportArchive HTTP/1.1
Host: localhost:10731
Content-Type: application/json
Cache-Control: no-cache
Postman-Token: 389d800d-7459-06fe-03bb-afe6f5497d8f

{"startDate": "01/07/18", "startTime" : "00/00/00", "endDate": "15/07/18", "endTime" : "23/59/59"}`

[whiskeysierra]

Request is not visible in log, yet exception is still thrown?

[stavskiy]

Yes. When I disable logbook application works fine. I also tried to use LogbookBuilder and customized HeaderFilter, RawResponseFilter and BodyFilter, but it gave the same result.

[whiskeysierra]

Either your config is wrong or just incorrectly formatted. Can you verify?

[whiskeysierra]

Should look like this:

logbook:
  exclude:
    - /etrack/exportArchive

[stavskiy]

I reduced logbook config to this, request was excluded from log, but exception was still thrown.

[whiskeysierra]

Can you run it with a debugger and put a breakpoint here

logbook/logbook-core/src/main/java/org/zalando/logbook/DefaultLogbook.java

Line 43 in 44c0a9c

final String correlationId = generateCorrelationId();

? The use of an exclude (which seems to work) doesn't make any sense to me with the supplied stack trace.

[whiskeysierra]

@lukasniemeier-zalando I believe the problem is this one here:

logbook/logbook-servlet/src/main/java/org/zalando/logbook/servlet/SecurityStrategy.java

Lines 31 to 33 in 5e8396d

	final LocalResponse response = new LocalResponse(httpResponse, protocolVersion);
	chain.doFilter(request, response);

Do you remember why we did that? We basically buffer everything and then later decide what to do, because we don't want anyone flodding the log file, right?

[stavskiy]

Here is the stacktrace at that point:

write:43, DefaultLogbook (org.zalando.logbook)
logRequestIfNecessary:48, NormalStrategy (org.zalando.logbook.servlet)
doFilter:32, NormalStrategy (org.zalando.logbook.servlet)
doFilter:39, LogbookFilter (org.zalando.logbook.servlet)
doFilter:31, HttpFilter (org.zalando.logbook.servlet)
internalDoFilter:193, ApplicationFilterChain (org.apache.catalina.core)
doFilter:166, ApplicationFilterChain (org.apache.catalina.core)
doFilterInternal:110, WebRequestTraceFilter (org.springframework.boot.actuate.trace)
doFilter:107, OncePerRequestFilter (org.springframework.web.filter)
internalDoFilter:193, ApplicationFilterChain (org.apache.catalina.core)
doFilter:166, ApplicationFilterChain (org.apache.catalina.core)
doFilterInternal:208, FilterChainProxy (org.springframework.security.web)
doFilter:177, FilterChainProxy (org.springframework.security.web)
invokeDelegate:347, DelegatingFilterProxy (org.springframework.web.filter)
doFilter:263, DelegatingFilterProxy (org.springframework.web.filter)
internalDoFilter:193, ApplicationFilterChain (org.apache.catalina.core)
doFilter:166, ApplicationFilterChain (org.apache.catalina.core)
doFilterInternal:99, RequestContextFilter (org.springframework.web.filter)
doFilter:107, OncePerRequestFilter (org.springframework.web.filter)
internalDoFilter:193, ApplicationFilterChain (org.apache.catalina.core)
doFilter:166, ApplicationFilterChain (org.apache.catalina.core)
doFilterInternal:108, HttpPutFormContentFilter (org.springframework.web.filter)
doFilter:107, OncePerRequestFilter (org.springframework.web.filter)
internalDoFilter:193, ApplicationFilterChain (org.apache.catalina.core)
doFilter:166, ApplicationFilterChain (org.apache.catalina.core)
doFilterInternal:81, HiddenHttpMethodFilter (org.springframework.web.filter)
doFilter:107, OncePerRequestFilter (org.springframework.web.filter)
internalDoFilter:193, ApplicationFilterChain (org.apache.catalina.core)
doFilter:166, ApplicationFilterChain (org.apache.catalina.core)
doFilter:164, TraceFilter (org.springframework.cloud.sleuth.instrument.web)
internalDoFilter:193, ApplicationFilterChain (org.apache.catalina.core)
doFilter:166, ApplicationFilterChain (org.apache.catalina.core)
doFilter:33, SecurityStrategy (org.zalando.logbook.servlet)
doFilter:39, LogbookFilter (org.zalando.logbook.servlet)
doFilter:31, HttpFilter (org.zalando.logbook.servlet)
internalDoFilter:193, ApplicationFilterChain (org.apache.catalina.core)
doFilter:166, ApplicationFilterChain (org.apache.catalina.core)
doFilterInternal:197, CharacterEncodingFilter (org.springframework.web.filter)
doFilter:107, OncePerRequestFilter (org.springframework.web.filter)
internalDoFilter:193, ApplicationFilterChain (org.apache.catalina.core)
doFilter:166, ApplicationFilterChain (org.apache.catalina.core)
doFilterInternal:106, MetricsFilter (org.springframework.boot.actuate.autoconfigure)
doFilter:107, OncePerRequestFilter (org.springframework.web.filter)
internalDoFilter:193, ApplicationFilterChain (org.apache.catalina.core)
doFilter:166, ApplicationFilterChain (org.apache.catalina.core)
invoke:199, StandardWrapperValve (org.apache.catalina.core)
invoke:96, StandardContextValve (org.apache.catalina.core)
invoke:478, AuthenticatorBase (org.apache.catalina.authenticator)
invoke:140, StandardHostValve (org.apache.catalina.core)
invoke:81, ErrorReportValve (org.apache.catalina.valves)
invoke:87, StandardEngineValve (org.apache.catalina.core)
service:342, CoyoteAdapter (org.apache.catalina.connector)
service:803, Http11Processor (org.apache.coyote.http11)
process:66, AbstractProcessorLight (org.apache.coyote)
process:868, AbstractProtocol$ConnectionHandler (org.apache.coyote)
doRun:1459, NioEndpoint$SocketProcessor (org.apache.tomcat.util.net)
run:49, SocketProcessorBase (org.apache.tomcat.util.net)
runWorker:1149, ThreadPoolExecutor (java.util.concurrent)
run:624, ThreadPoolExecutor$Worker (java.util.concurrent)
run:61, TaskThread$WrappingRunnable (org.apache.tomcat.util.threads)
run:748, Thread (java.lang)

[whiskeysierra]

Your stacktrace proves that you reach this line:

logbook/logbook-core/src/main/java/org/zalando/logbook/DefaultLogbook.java

Line 43 in 44c0a9c

final String correlationId = generateCorrelationId();

That means the predicate returned true, which shouldn't be the case for your configuration. Please make sure your config is correct and verify here:

logbook/logbook-spring-boot-starter/src/main/java/org/zalando/logbook/spring/LogbookAutoConfiguration.java

Line 109 in b2c5cc3

return properties.getExclude().stream()