[
https://issues.apache.org/jira/browse/CXF-9251?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Valentino Porta updated CXF-9251:
---------------------------------
Description:
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!
was:
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!
> 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)- ( 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)
