OutOfMemoryError thrown when logging records for failed tests

[bulivlad]

Description

OutOfMemoryError is thrown when trying to log all the records for complex processes due to the way the logging is implemented. As of now when a test is failing all the records are collected into a string builder then logged. There is no way to trim down or suppress the records logging.

Expected behaviour

The records logging should not throw OutOtMemoryError

Reproduction steps

Create a complex process that might generate a large stream of records.

Stacktrace

Caused by: java.lang.OutOfMemoryError: Java heap space
	at java.base/java.util.Arrays.copyOf(Arrays.java:3537)
	at java.base/java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:228)
	at java.base/java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:582)
	at java.base/java.lang.StringBuilder.append(StringBuilder.java:179)
	at ch.qos.logback.core.pattern.FormattingConverter.write(FormattingConverter.java:39)
	at ch.qos.logback.core.pattern.PatternLayoutBase.writeLoopOnConverters(PatternLayoutBase.java:115)
	at ch.qos.logback.classic.PatternLayout.doLayout(PatternLayout.java:165)
	at ch.qos.logback.classic.PatternLayout.doLayout(PatternLayout.java:39)
	at ch.qos.logback.core.encoder.LayoutWrappingEncoder.encode(LayoutWrappingEncoder.java:116)
	at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:230)
	at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102)
	at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
	at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
	at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
	at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
	at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
	at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
	at ch.qos.logback.classic.Logger.info(Logger.java:579)
	at io.camunda.zeebe.process.test.filters.logger.RecordStreamLogger.logRecords(RecordStreamLogger.java:113)
	at io.camunda.zeebe.process.test.filters.logger.RecordStreamLogger.log(RecordStreamLogger.java:106)
	at io.camunda.zeebe.process.test.filters.RecordStream.print(RecordStream.java:125)
	at io.camunda.zeebe.spring.test.AbstractZeebeTestExecutionListener.cleanup(AbstractZeebeTestExecutionListener.java:66)
	at io.camunda.zeebe.spring.test.ZeebeTestExecutionListener.afterTestMethod(ZeebeTestExecutionListener.java:35)
	at org.springframework.test.context.TestContextManager.afterTestMethod(TestContextManager.java:445)
	at org.springframework.test.context.junit.jupiter.SpringExtension.afterEach(SpringExtension.java:206)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeAfterEachCallbacks$12(TestMethodTestDescriptor.java:257)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor$$Lambda$1514/0x00000008019c5f80.invoke(Unknown Source)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeAllAfterMethodsOrCallbacks$13(TestMethodTestDescriptor.java:273)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor$$Lambda$1511/0x00000008019c56d8.execute(Unknown Source)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeAllAfterMethodsOrCallbacks$14(TestMethodTestDescriptor.java:273)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor$$Lambda$1510/0x00000008019c54a0.accept(Unknown Source)

Environment

• OS: ubuntu
• Version: 18.06

[remcowesterhoud]

ZPA Triage:

• Makes sense that this could occur as the records are stored in memory
• I feel like this must be a very large process for this to occur.
• Marking it as not prioritised for now

@bulivlad Do you have a reproducible example for this? It would be very helpful if you could share the process and test case that causes this.

[timvahlbrock]

Hello, this issue still persists with around 100,000 records. We currently managed to get around this by implementing a custom test annotation, that injects a RecordStreamSource that returns an empty ArrayList. However, we would still appreciate if this issue could be fixed within the library. As far as I can tell, converting RecordStreamSourceImpl to use streaming should do the trick. Would you be willing to accept a PR for this?

[korthout]

Would you be willing to accept a PR for this?

Of course! 🙌

As far as I can tell, converting RecordStreamSourceImpl to use streaming should do the trick.

🤔 Interesting, but how would you ensure multiple assertions can be made? A stream can only be consumed once. For example, I want to assert something about the process and about a published message.

[timvahlbrock]

🤔 Interesting, but how would you ensure multiple assertions can be made? A stream can only be consumed once. For example, I want to assert something about the process and about a published message.

Fair, did not think of that issue. This also makes it clear why the records are stored in a collection in the first place. What about creating a separate source stream for each usage? However, this would add some overhead to the transformation, as each stream would create record copies for itself.

[korthout]

What about creating a separate source stream for each usage?

As ZPT is built on top of an in-memory log storage, we'll always have some memory limit that we might exceed. So, I have two thoughts:

1. We can document (or make it easier) to provide more memory to tests run with ZPT
2. We can reduce memory footprint as much as possible

1 is the easy fix/workaround for your problem.

For 2, we can look at re-using the data stored by InMemoryLogStorage.java for assertions, rather than copying each record from it and storing it into RecordStreamSourceImpl.java.

We currently copy each record into that class for simpler code and performance: each record only needs to be deserialized once and can be easily used in any assertion afterward. We could postpone deserialization to the assertions and make the deserialization selective based on the type of assertion to find a much more memory-friendly solution (half the memory load of the complete log) without costing too much CPU.

@timvahlbrock Is that something you'd be interested in trying out? It could be a change that requires some deeper cuts, as the RecordStreamSourceImpl is used in quite some places and may require changes to how each of the assertions is implemented. Let me know what you think.

💭 Please note that records are deserialized in multiple stages:

• The log stream reader deserializes the most top-level record metadata (key, position, timestamp) but leaves the main metadata as untouched bytes
• The main metadata can be deserialized to show the RecordType, ValueType, Intent, and such (this is the information you'd need to determine whether an assertion is interested in a specific record)
• The value of the record is deserialized separately, as this depends on the ValueType (as specified in the main metadata)

[timvahlbrock]

@timvahlbrock Is that something you'd be interested in trying out?

@korthout Unfortunately, the time I got to work one this was cut by organisational changes, but I can speak with my team mates if anyone has the capacity to persue this.

One more thing to consider: I'm quite confident, that this library is not used for assertions in our case. So as far as I can tell the only place where the RecordStream is used is the debug logging in case of a test failure. So if we could disable that debug logging at the end by configuration, the records wouldn't be collected and our workaround would be obsolete. However, I feel like your solution is somewhat cleaner and I also need to verify that what I just stated is actually accurate. Can do the later tomorrow.

[korthout]

I'm quite confident, that this library is not used for assertions in our case.

That's interesting. Can I ask how you're using this instead?

[timvahlbrock]

That's interesting. Can I ask how you're using this instead?

So i just checked, we don't make any assertions on the zeebe records in the affected test suites. I also remembered, we don't use this library directly, but rather spring-starter-camunda-test to get an in memory zeebe engine per test. It is also responsible for logging the records in the case of a test failure. So my proposal to disable the logging of records would need to be addressed there.