CXF-9251_DelayedCachedOutputStreamCleaner_double_callback_out_logging

[vp340]

DelayedCachedOutputStreamCleaner held in a queue list the reference to CachedOutputStream s. The ones never unregistered from the queue are the one who has a tmp file not deleted.
When the timer thread tries to close() the cos ... if the cos is actually a LoggingOutputStream it also calls the onClose() of LoggingCallback.
In certain cases so it logs twice (the second without payload because it is already consumed)
Furthermore, it keeps inMem all the objects that are referenced in the class (such as the Message) and that are needed for logging.

I propose to deregister the callback at the end to avoid rewind calls to it.
This way even if DelayedCachedOutputStreamCleaner keeps the LoggingOutputStream in the queue, there isn't the reference to the callback and so GC can clean those object. And double logs are not produce in the first place

[vp340]

Hi @reta ,
I hope U're doing well.
After the ghost RESP_OUT log , I might have found a double RESP_OUT log ... U know how it is... just to balance things out :) ...
Let me know if U or your team needs anything.

Unfortunately, as I wrote in https://issues.apache.org/jira/browse/CXF-9251 ... I couldn't right now simulate the scenario that I had at work. For now U have to trust me on that :/ .
Not on purpose I simulate another scenario that I had described better on Jira. But instead of double logging I reproduced a delayed logging unleashed only by DelayedCachedOutputStreamCleaner .
The thing is, it's difficult to simulate all the cases that provoke https://issues.apache.org/jira/browse/CXF-7396.
Hope U have best luck with that.

If I have news I'll keep U posted.
Let me know if I had to add any tests to this PR or anything else.
I'm glad to help.

Keep me updated about what U think about this problem.
Have a great job!

[reta]

Hi @reta ,
I hope U're doing well.
After the ghost RESP_OUT log , I might have found a double RESP_OUT log ... U know how it is... just to balance things out :) ...
Let me know if U or your team needs anything.

Thanks a lot @vp340 , it is very possible we have missed few places, thank you for reporting those, I will take a closer look shortly

[vp340]

Thanks a lot for your time.
Sorry for the long comment lines that broke tests. :/
I'll shorten them tonight when I have PC access.

[vp340]

Hi @reta,
so I fix the indentation, but found that I made a mistake.
I couldn't deregister the callback there, because onClose is called inside a cycle of the same callbacks list... so java.util.ConcurrentModificationException was thrown.

I try another simple approch: Implement a LoggingCallback wrapper (OneTimeLoggingCallback) that ensures logging occurs only once and helps prevent memory leaks by dereferencing the LoggingCallback instance upon completion, making it eligible for garbage collection.
Let me know what U think or if U have cleaner solution in mind.

Have a great evening!

P.S.
I also update the Jira ticket with more evidence about the problem, but I still couldn't resimulate what happened yesterday at work.

[reta]

@vp340 I think we should just unregister callback on close? That would make sure, it will be called only once

message.setContent(OutputStream.class, origStream);
cos.deregisterCallback(this);

[vp340]

Hi @reta,
We are on the same page on that :) .
If fact the first thought that I have was also to unregister the callback from the cos (see first commit of this PR 2b482dc ).

Then when I ran the tests, half failed due to java.util.ConcurrentModificationException .
This happens because the cb.onClose() is called inside a cycle of the callbacks list itself.
for (CachedOutputStreamCallback cb : callbacks) { try { cb.onClose(this);
So obviously we can't just deregister the cb from the list (that under the hood does callbacks.remove(cb) as we would modify the list while the for loop is still cycling it.

I introduced the OneTimeLoggingCallback to resolve the problem in the feature logging module in order not to touch the core module.

But if U wan't to pursue the cos.deregisterCallback(this); solution (that in my opinion is more elegant ) , we have to cycle a snapshot of the callbacks in the CachedOutputStream ... and not the real callbacks list.
I prepare this alternative solution in #3535 .
I also add the check in the test to ensure that che callback is deregister from the cos.

Let me know which solution do U prefer ;)

Have a good evening!

[reta]

If fact the first thought that I have was also to unregister the callback from the cos (see first commit of this PR 2b482dc ).

Sorry about that @vp340 , I just checked the latest revision

So obviously we can't just deregister the cb from the list (that under the hood does callbacks.remove(cb) as we would modify the list while the for loop is still cycling it.

Fair point, I think we could fix that by guarding CachedOutputStream::close() - once closed, it should not be closed again (and invoke the callbacks), that should fix it for everyone, not only for logging interceptor

[vp340]

Sorry about that @vp340 , I just checked the latest revision

@reta no problems :) .

Fair point, I think we could fix that by guarding CachedOutputStream::close() - once closed, it should not be closed again (and invoke the callbacks), that should fix it for everyone, not only for logging interceptor

U mean to use a similar logic as the OneTimeLoggingCallback with a boolean that guards if it's already close?
I think we need to be careful about that. In my case the LoggingCallback was called 2 times... So the first one logged, but encounter some sort of error after... cause the cos was never unregister from the cachedOutputStreamCleaner. So if we put a guard not to close the cos a second time... we could reintroduce the tmp file problem nullifying the purpuse of the clean() of DelayedCachedOutputStreamCleaner (that will call a .close() method that does nothing).

I was searching the root cause, but I couldn't reproduce my scenario a second time (Logging twice + memory leak). I only have the log of that happening.
The solutions in these PRs are only for that.

But in the Jira ticket when I tryed to reproduce that again I obtained a 2nd scenario for which I haven't found a workaround: the .close() is never called the first time. (so no log) ... and after N minutes DelayedCachedOutputStreamCleaner call .close (so delayed log ... + memory leak) .

I suggest to tackle one problem at a time ;)

[reta]

Thank @vp340 uh ... its getting pretty messy, since CachedOutputStream could actually reset the stream and callbacks should be called again. I will spend a bit more time on that, I suspect that the fix should land in CachedOutputStream but not as simple as I thought (just unregsiter or close check).

[vp340]

@reta U're welcome.
I know the situation it's quite difficult and confusing.
We need to tackle the two scenario separately.

Maybe I found the root cause for the 2nd scenario ((memory leak in queue + logging only after N minutes when DelayedCachedOutputStreamCleaner does its clean).
It could be how tomcat handle the outputStream after a java.io.IOException: Connection reset by peer .
In CoyoteOutputStream.class they doesn't close the stream after that exception while write()ing ....(it seams at least) and I don't have sufficient knowledge to say they should.
Pls see the last comment in the Jira ticket. for details (stack and image) .

If we clear up that problem then it remains only the 1st scenario (memory leak in queue + double logging).
As I can't reproduce the problem we can't debug the root cause, but we can threat it as a black box and do a workaround.
We already know for sure that the OutputStream is close. (first callback log). For some unknown reason it remains in the queue and so it create possible memoryLeak (reference to LoggingCallback ..and so to Message and others) and do the double partial log when close.
I think that for this 1st scenario #3521 or #3535 should do the job, cause they solve all the 2 problems.
They only both say "ehi this LoggingCallback should be called only once" (so they are conceptually correct).
If I had to chose I would go with #3535 . (it seems more clean to me).

Let me know what U think.
Now I'll go to bed (here it's 3 a.m. so...) ... I hope I won't have nightmares about this aahaha.

See U tomorrow.