[
https://issues.apache.org/jira/browse/CXF-9251?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=18124601#comment-18124601
]
Freeman Yue Fang commented on CXF-9251:
---------------------------------------
Hi [~vp340], [~reta],
I've attached a reproducer (cxf-9251-tomcat-reset.tar) for a temp file leak
that can happen after the fix in [PR
#3541|https://github.com/apache/cxf/pull/3541] on Tomcat 10.1.
*Summary: the leaked temp file is never deleted, not even by the
{{DelayedCachedOutputStreamCleaner}} cleanup thread. It stays on disk until it
is removed by hand.*
*Scenario*
# The server sends a response with LoggingFeature enabled and a low
{{inMemThreshold}}.
# The client resets the connection while one large write is in progress.
# With #3541, {{LoggingOutputStream.write()}} catches the failure and closes
itself, logging RESP_OUT straight away.
# The fault chain then writes the closing tags (~165 bytes, from
{{SoapOutEndingInterceptor}}) to the same, already closed, stream.
# Tomcat 10.1 silently accepts writes to a closed response stream, so
{{CacheAndWriteOutputStream}} caches those bytes again. {{totalLength}} is
still above the threshold, so they are written to a *new* temp file, and the
stream is registered with {{DelayedCachedOutputStreamCleaner}} again.
# *The cleanup thread can't remove that file.* When the cleaner fires (after 30
minutes by default), it removes the stream from its queue and calls
{{close()}}. The {{closed}} guard added in #3541 makes that second {{close()}}
a no-op, so {{CachedOutputStream.close()}} never runs and the temp file is
never deleted. Since the stream has now left the cleaner's queue, nothing else
will ever try to delete the file.
Before #3541 the cleaner's {{close()}} did reach {{CachedOutputStream}}, so a
file like this was deleted when the cleaner fired, at most 30 minutes later.
#3541 turns that delayed cleanup into a *permanent* leak.
*How to run*
The project uses an embedded Tomcat + {{CXFNonSpringServlet}} and a raw socket
client that sends a RST mid-response. It uses CXF {{4.2.5-SNAPSHOT}}, so build
current main first ({{mvn install}} for at least {{core}},
{{rt/frontend/jaxws}}, {{rt/transports/http}} and {{rt/features/logging}}).
{code}
mvn test # Tomcat 10.1.60 (default)
{code}
To avoid waiting 30 minutes, each scenario calls
{{DelayedCachedOutputStreamCleaner.forceClean()}}. It runs the same clean as
the cleanup thread, just right away. Afterwards each scenario asserts that the
temp file has been deleted and that the stream is no longer registered with the
cleaner. On Tomcat 10.1 with current main, the temp file *still exists after
forceClean()*.
*Proposed fix*
In {{LoggingOutputStream}}, once the stream is closed, {{write()}} only passes
the bytes through to the underlying stream and does not cache them again:
{code:java}
if (closed.get()) {
// already closed and logged: pass through only, do not cache again
getFlowThroughStream().write(b, off, len);
return;
}
{code}
I have it locally with 2 unit tests in {{LoggingOutInterceptorTest}}; both fail
on current main with "temp file leaked" after {{forceClean()}}. And I will send
a PR soon
This matters especially if #3541 gets backported to 4.1.x/4.0.x, where Tomcat
10.1 is the common container.
Freeman
> Possible Memory Leak with DelayedCachedOutputStreamCleaner and IOException
> Connection Reset by peer
> ---------------------------------------------------------------------------------------------------
>
> Key: CXF-9251
> URL: https://issues.apache.org/jira/browse/CXF-9251
> Project: CXF
> Issue Type: Bug
> Components: logging
> Affects Versions: 4.0.11
> Reporter: Valentino Porta
> Priority: Major
> Fix For: 3.6.14, 4.2.5, 4.1.10
>
> Attachments: clean.png, cxf-9251-tomcat-reset.tar, double_log.png,
> image-2026-10-04-02-44-57-518.png, log.txt, log_stack_2nd_scenario.txt,
> queue.png
>
>
> Hi everyone,
> I'm here to share with U a possible bug / unwanted behaviour.
>
> Here the problem:
> - Now after the fix https://issues.apache.org/jira/browse/CXF-7396 the
> DelayedCachedOutputStreamCleaner handles orphans tmp cached files, trying to
> close them after a certain period of time (default 30 minutes)
> - if we set a threshold in CxfLogging feature (ex. 1 so all log are cached
> to file) ... also the log modules use the CachedOutputStream with tmp file ,
> and so they are handle by DelayedCachedOutputStreamCleaner too
> - for the OUT flows (REQ_OUT, RESP_OUT, FAULT_OUT) the logging is done by
> attacching a callback and log when the LoggingOutputStream.java (that wrap
> CachedOutputStream) is closed
>
> With this in mind, I noticed multiple behaviour:
> * at work I discover the issue by seeing that dossing my service ... the
> RESP_OUT (big size with attachments) was logged immediatly ... but after 15
> minutes I notice another log (with the payload already consume obviously. So
> the .close method was called and the callback had logged. But for same reason
> (the same of CXF-7396 I suppose) the tmp file was not eliminated. So after 15
> minutes when DelayedCachedOutputStreamCleaner try to close it, the callback
> was still attached!
> * now I was trying to replicate with a more simple sample service that I
> could share with U, but I only manage to replicate the tmp file not
> eliminated scenario without the first call to .close(). So the RESP_OUT log
> was vanished and reappeared only when DelayedCachedOutputStreamCleaner close
> the stream after minutes (with the payload from the tmp file because it was
> the first time it was consumed. But logged as a FAULT_OUT ... 500 (see
> log.txt... notice the thread that log [DelayedCachedOutputStreamCleaner]
> after printing Unclosed (leaked?) stream detected: 1623223103) )
>
> So the two main problems in my opinion here are:
> * possible memory leak (maybe negligible but I let U decide that) , due to
> LoggingCallback holding references to some Objects (like private final
> Message message). So for 30 minutes the GC can't delete those;
> * double logging (in the first case that I experienced) ;
>
> Possible fix (I will try to open a PR):
> * -deregister the callback after it finishes logging (so there will be no
> future double log and also the GC could delete the class and the relative
> attribute)- ( we can't because onClose is called inside a cycle of the same
> callbacks list... so java.util.ConcurrentModificationException)
> * Implement a LoggingCallback wrapper (OneTimeLoggingCallback) that ensures
> logging occurs only once and helps prevent memory leaks.
>
> The second case (where the log doesn't happen right away but only after
> minutes) it could be ok for the concept of logging (even if U wait minutes if
> It hasn't already logged the tmp file then U will have your log). But It
> means that the relative objects needs to stay alive in mem until then :( .
>
> I 'll keep U upadated if I find anything else!
> Have a great job!
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
