[
https://issues.apache.org/jira/browse/CXF-9251?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Valentino Porta updated CXF-9251:
---------------------------------
Attachment: double_log.png
> 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
> Priority: Major
> Attachments: clean.png, double_log.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)
