Valentino Porta created CXF-9251:
------------------------------------
Summary: Possible Memory Leak with
DelayedCachedOutputStreamCleaner and double callback REQ_OUT/RESP_OUT logging
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
Attachments: clean.png, log.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)
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)
