Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

#2530 Fix StringLogAppender leaks for MockHandler #2535

Conversation

brown-kaew
Copy link

Description

As the issue is reproducible by the long-running mock server, see: #2530

Memory analyzer
Screenshot 2567-03-18 at 00 56 49

The thread stack from GC.heap_dump

armeria-common-worker-kqueue-3-2
  at java.lang.OutOfMemoryError.<init>()V (OutOfMemoryError.java:48)
  at java.util.Arrays.copyOf([BI)[B (Arrays.java:3745)
  at java.lang.AbstractStringBuilder.ensureCapacityInternal(I)V (AbstractStringBuilder.java:172)
  at java.lang.AbstractStringBuilder.append(Ljava/lang/String;)Ljava/lang/AbstractStringBuilder; (AbstractStringBuilder.java:538)
  at java.lang.StringBuilder.append(Ljava/lang/String;)Ljava/lang/StringBuilder; (StringBuilder.java:178)
  at com.intuit.karate.shell.StringLogAppender.append(Ljava/lang/String;)V (StringLogAppender.java:56)
  at com.intuit.karate.Logger.append(Ljava/lang/String;)V (Logger.java:146)
  at com.intuit.karate.Logger.formatAndAppend(Ljava/lang/String;[Ljava/lang/Object;)V (Logger.java:140)
  at com.intuit.karate.Logger.debug(Ljava/lang/String;[Ljava/lang/Object;)V (Logger.java:97)
  at com.intuit.karate.core.MockHandler.isMatchingScenario(Lcom/intuit/karate/core/Scenario;Lcom/intuit/karate/core/ScenarioEngine;)Z (MockHandler.java:287)
  at com.intuit.karate.core.MockHandler.handle(Lcom/intuit/karate/http/Request;)Lcom/intuit/karate/http/Response; (MockHandler.java:185)
  at com.intuit.karate.http.HttpServerHandler.lambda$serve$0(Lcom/linecorp/armeria/server/ServiceRequestContext;Lcom/linecorp/armeria/common/AggregatedHttpRequest;)Lcom/linecorp/armeria/common/HttpResponse; (HttpServerHandler.java:59)
  at com.intuit.karate.http.HttpServerHandler$$Lambda$517.apply(Ljava/lang/Object;)Ljava/lang/Object; ()
  at java.util.concurrent.CompletableFuture$UniApply.tryFire(I)Ljava/util/concurrent/CompletableFuture; (CompletableFuture.java:642)
  at java.util.concurrent.CompletableFuture.postComplete()V (CompletableFuture.java:506)
  at java.util.concurrent.CompletableFuture.complete(Ljava/lang/Object;)Z (CompletableFuture.java:2073)
  at com.linecorp.armeria.common.stream.AggregationSupport.lambda$aggregate$2(Ljava/util/concurrent/CompletableFuture;Ljava/lang/Object;Ljava/lang/Throwable;)Ljava/lang/Object; (AggregationSupport.java:133)
  at com.linecorp.armeria.common.stream.AggregationSupport$$Lambda$516.apply(Ljava/lang/Object;Ljava/lang/Object;)Ljava/lang/Object; ()
  at java.util.concurrent.CompletableFuture.uniHandle(Ljava/lang/Object;Ljava/util/function/BiFunction;Ljava/util/concurrent/CompletableFuture$UniHandle;)Z (CompletableFuture.java:930)
  at java.util.concurrent.CompletableFuture$UniHandle.tryFire(I)Ljava/util/concurrent/CompletableFuture; (CompletableFuture.java:907)
  at java.util.concurrent.CompletableFuture.postComplete()V (CompletableFuture.java:506)
  at java.util.concurrent.CompletableFuture.complete(Ljava/lang/Object;)Z (CompletableFuture.java:2073)
  at com.linecorp.armeria.common.stream.StreamMessageCollector.onComplete()V (StreamMessageCollector.java:67)
  at com.linecorp.armeria.common.stream.CancellableStreamMessage$CloseEvent.notifySubscriber(Lcom/linecorp/armeria/common/stream/CancellableStreamMessage$SubscriptionImpl;Ljava/util/concurrent/CompletableFuture;)V (CancellableStreamMessage.java:258)
  at com.linecorp.armeria.common.stream.DefaultStreamMessage.notifySubscriberOfCloseEvent0(Lcom/linecorp/armeria/common/stream/CancellableStreamMessage$SubscriptionImpl;Lcom/linecorp/armeria/common/stream/CancellableStreamMessage$CloseEvent;)V (DefaultStreamMessage.java:303)
  at com.linecorp.armeria.common.stream.DefaultStreamMessage.notifySubscriberOfCloseEvent(Lcom/linecorp/armeria/common/stream/CancellableStreamMessage$SubscriptionImpl;Lcom/linecorp/armeria/common/stream/CancellableStreamMessage$CloseEvent;)V (DefaultStreamMessage.java:295)
  at com.linecorp.armeria.common.stream.DefaultStreamMessage.handleCloseEvent(Lcom/linecorp/armeria/common/stream/CancellableStreamMessage$SubscriptionImpl;Lcom/linecorp/armeria/common/stream/CancellableStreamMessage$CloseEvent;)V (DefaultStreamMessage.java:432)
  at com.linecorp.armeria.common.stream.DefaultStreamMessage.notifySubscriber0()V (DefaultStreamMessage.java:375)
  at com.linecorp.armeria.common.stream.DefaultStreamMessage.notifySubscriber()V (DefaultStreamMessage.java:331)
  at com.linecorp.armeria.common.stream.DefaultStreamMessage.addObjectOrEvent(Ljava/lang/Object;)V (DefaultStreamMessage.java:317)
  at com.linecorp.armeria.common.stream.DefaultStreamMessage.close()V (DefaultStreamMessage.java:439)
  at com.linecorp.armeria.server.Http1RequestDecoder.channelRead(Lio/netty/channel/ChannelHandlerContext;Ljava/lang/Object;)V (Http1RequestDecoder.java:328)
  at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(Ljava/lang/Object;)V (AbstractChannelHandlerContext.java:442)
  at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(Lio/netty/channel/AbstractChannelHandlerContext;Ljava/lang/Object;)V (AbstractChannelHandlerContext.java:420)
  at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(Ljava/lang/Object;)Lio/netty/channel/ChannelHandlerContext; (AbstractChannelHandlerContext.java:412)
  at com.linecorp.armeria.server.HttpServerUpgradeHandler.channelRead(Lio/netty/channel/ChannelHandlerContext;Ljava/lang/Object;)V (HttpServerUpgradeHandler.java:228)
  at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(Ljava/lang/Object;)V (AbstractChannelHandlerContext.java:444)
  at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(Lio/netty/channel/AbstractChannelHandlerContext;Ljava/lang/Object;)V (AbstractChannelHandlerContext.java:420)
  at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(Ljava/lang/Object;)Lio/netty/channel/ChannelHandlerContext; (AbstractChannelHandlerContext.java:412)
  at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(Ljava/lang/Object;)Lio/netty/channel/ChannelHandlerContext; (CombinedChannelDuplexHandler.java:436)
  at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(Lio/netty/channel/ChannelHandlerContext;Lio/netty/handler/codec/CodecOutputList;I)V (ByteToMessageDecoder.java:346)
  at io.netty.handler.codec.ByteToMessageDecoder.channelRead(Lio/netty/channel/ChannelHandlerContext;Ljava/lang/Object;)V (ByteToMessageDecoder.java:318)
  at io.netty.channel.CombinedChannelDuplexHandler.channelRead(Lio/netty/channel/ChannelHandlerContext;Ljava/lang/Object;)V (CombinedChannelDuplexHandler.java:251)
  at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(Ljava/lang/Object;)V (AbstractChannelHandlerContext.java:442)
  at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(Lio/netty/channel/AbstractChannelHandlerContext;Ljava/lang/Object;)V (AbstractChannelHandlerContext.java:420)
  at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(Ljava/lang/Object;)Lio/netty/channel/ChannelHandlerContext; (AbstractChannelHandlerContext.java:412)
  at io.netty.handler.codec.ByteToMessageDecoder.handlerRemoved(Lio/netty/channel/ChannelHandlerContext;)V (ByteToMessageDecoder.java:266)
  at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(Lio/netty/channel/ChannelHandlerContext;Lio/netty/buffer/ByteBuf;Ljava/util/List;)V (ByteToMessageDecoder.java:536)
  at io.netty.handler.codec.ByteToMessageDecoder.callDecode(Lio/netty/channel/ChannelHandlerContext;Lio/netty/buffer/ByteBuf;Ljava/util/List;)V (ByteToMessageDecoder.java:468)
  at io.netty.handler.codec.ByteToMessageDecoder.channelRead(Lio/netty/channel/ChannelHandlerContext;Ljava/lang/Object;)V (ByteToMessageDecoder.java:290)
  at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(Ljava/lang/Object;)V (AbstractChannelHandlerContext.java:444)
  at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(Lio/netty/channel/AbstractChannelHandlerContext;Ljava/lang/Object;)V (AbstractChannelHandlerContext.java:420)
  at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(Ljava/lang/Object;)Lio/netty/channel/ChannelHandlerContext; (AbstractChannelHandlerContext.java:412)
  at io.netty.handler.logging.LoggingHandler.channelRead(Lio/netty/channel/ChannelHandlerContext;Ljava/lang/Object;)V (LoggingHandler.java:280)
  at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(Ljava/lang/Object;)V (AbstractChannelHandlerContext.java:442)
  at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(Lio/netty/channel/AbstractChannelHandlerContext;Ljava/lang/Object;)V (AbstractChannelHandlerContext.java:420)
  at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(Ljava/lang/Object;)Lio/netty/channel/ChannelHandlerContext; (AbstractChannelHandlerContext.java:412)
  at io.netty.handler.flush.FlushConsolidationHandler.channelRead(Lio/netty/channel/ChannelHandlerContext;Ljava/lang/Object;)V (FlushConsolidationHandler.java:152)
  at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(Ljava/lang/Object;)V (AbstractChannelHandlerContext.java:442)
  at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(Lio/netty/channel/AbstractChannelHandlerContext;Ljava/lang/Object;)V (AbstractChannelHandlerContext.java:420)
  at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(Ljava/lang/Object;)Lio/netty/channel/ChannelHandlerContext; (AbstractChannelHandlerContext.java:412)
  at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(Lio/netty/channel/ChannelHandlerContext;Ljava/lang/Object;)V (DefaultChannelPipeline.java:1410)
  at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(Ljava/lang/Object;)V (AbstractChannelHandlerContext.java:440)
  at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(Lio/netty/channel/AbstractChannelHandlerContext;Ljava/lang/Object;)V (AbstractChannelHandlerContext.java:420)
  at io.netty.channel.DefaultChannelPipeline.fireChannelRead(Ljava/lang/Object;)Lio/netty/channel/ChannelPipeline; (DefaultChannelPipeline.java:919)
  at io.netty.channel.kqueue.AbstractKQueueStreamChannel$KQueueStreamUnsafe.readReady(Lio/netty/channel/kqueue/KQueueRecvByteAllocatorHandle;)V (AbstractKQueueStreamChannel.java:544)
  at io.netty.channel.kqueue.AbstractKQueueChannel$AbstractKQueueUnsafe.readReady(J)V (AbstractKQueueChannel.java:387)
  at io.netty.channel.kqueue.KQueueEventLoop.processReady(I)V (KQueueEventLoop.java:218)
  at io.netty.channel.kqueue.KQueueEventLoop.run()V (KQueueEventLoop.java:296)
  at io.netty.util.concurrent.SingleThreadEventExecutor$4.run()V (SingleThreadEventExecutor.java:997)
  at io.netty.util.internal.ThreadExecutorMap$2.run()V (ThreadExecutorMap.java:74)
  at io.netty.util.concurrent.FastThreadLocalRunnable.run()V (FastThreadLocalRunnable.java:30)
  at java.lang.Thread.run()V (Thread.java:829)

The StringBuilder object inside StringLogAppender has never been called collect() to de-refer all the string objects. it leads to memory leaks on the long-running mock server.

Solutions

It seems that the mock usage does not need to use LogAppender, so MockHandler should have some ability to disable the appender.

Before
The memory trend increases over time and OOM at some point
monitor

After fixed
The memory trend is now stable (the lowest memory usage after GC is keeping below 100MB)
Screenshot 2567-03-18 at 00 45 01

The StringBuilder object inside StringLogAppender has never be called collect() to de-refer all the string objects. it leads memory leak on long running mock server
@ptrthomas ptrthomas merged commit 2050f57 into karatelabs:develop Mar 18, 2024
1 check passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants