[CXF-9233] Ghost RESP_OUT log

[vp340]

Pull Request related to Jira: [CXF-9233] AbstractLoggingInterceptor.LIVE_LOGGING_PROP already set in the message properties, so RESP_OUT log is disable :(

[reta]

Thanks for the pull request @vp340 , I would advice against introducing yet another property, not only it becomes very confusing, it also difficult to figured out where all these different properties are coming from. I will try to spend some time looking into the problem, if you could attach a simple reproducer to the JIRA ticket, that would be great to understand the issue in context. Thank you.

[vp340]

Hi @reta ,
thank you for the reply!

I added as you requested an example project https://github.com/vp340/cxf-log-example to the JIRA ticket where I develop a simple ExampleService that simulate the error-prone situation.
I added in the last JIRA comment a more detailed explanation. :)
If you have any problem to run it locally let me know and I'll try to help you. (I'm currently on vacation, but I will try to reply asap :D )

I prepared wiremock configuration and a soapUI project (or if U prefer the endpoint and the raw request) .

If U go to src/main/resources/spring/example/v1/route-context.xml ... and uncomment the processor U can make the RESP_OUT log reapper as I described in the JIRA ticket.

As i wrote in the comment, I undestand that adding the IDEMPOTENT_LOGGING_PROP can be "confusing", but so is not finding the RESP_OUT log because a generic property has already been set somewhere else and the framework propagates it, if U don't manually intervene .
My goal with the IDEMPOTENT_LOGGING_PROP was to fullfill the use case "not log twice" without using the same property used to disable completely the log from the Bus (and that can lead to these sneaky situations ) .
In my project it worked fine without adding manual processor.

Hope it helps. Keep me updated :)

[reta]

Thanks a lot @vp340, I am off this week, will surely pick it up when I am back. My apologies, thank you

[reta]

@vp340 just to let you know - was able to reproduce the issue , thanks to the sample project and instructions, haven't figured out the flow / cause yet, but working on it.

[vp340]

Hi @reta,
Thanks for keeping me updated.
As I wrote somewhere in the jira ticket or in some comment in the demo project I presume that the "ResponseContext" header is the culprit along with the Camel CxfProducer/CxfConsumer that set/reset It. If I were U I would look that way first.

Now in my company I have bypassed the issue using the solution that I posted in the PR and It seems to work fine, but clearly there Is something more Camel related stuff that Is interfering :/ ...and which requires further exploration.

Let me know if U need anything. If I have time I'll try to investigate something myself.

Let's keep each other updated. :)

Have a good job!

Valentino Porta

[reta]

@vp340 prototyped a fix here #3372 , I still have to add test case(s) for it, I am wondering if you could give it a shot, thanks

[vp340]

Hi thanks.
I was updating the Jira ticket right now. (sorry I live in Italy and here is almost 2 a.m right now and tomorrow I have work) .
Yeah the #3372 could be an easier and more understandable solution.
If I understand well the isRequestor() method is the same use to retrieve the EventType for logging ..so isRequestor ? EventType.RESP_IN : EventType.REQ_IN
It will set 'LIVE_LOGGING_PROP + true' if it's a client and a 'LIVE_LOGGING_PROP + false' if is a server.

The only doubt situation could be 2 backend call in a row...
So the flow would be:
REQ_IN (set LIVE_LOGGING_PROP + false but not propagated)
REQ_OUT (set LIVE_LOGGING_PROP + true but not propagated)
RESP_IN (set LIVE_LOGGING_PROP + true AND propagated!)
REQ_OUT (find LIVE_LOGGING_PROP + true ...so ghost REQ_OUT logging)
RESP_IN
RESP_OUT

(This is a situation that I thought right know... it should be tested)...

Another possible problem is that if we modify the property name itself, someone who had already set that property on the Bus to completely disable the logging would no longer be able to do so. This could therefore break backward compatibility. (I read something related to this in https://issues.apache.org/jira/browse/CXF-7000 )

If U are interested in reviewing another possible solution, going deeply in debug in the sample project I believe I found the very place where the LIVE_LOGGING_PROP is set and propagated.
I open a new #3373

In the class org.apache.cxf.endpoint.ClientImpl ... processResult method
Message inMsg = exchange.getInMessage();
if (inMsg != null) {
if (null != resContext)
{
resContext.putAll(inMsg);
// remove the recursive reference if present
resContext.remove(Message.INVOCATION_CONTEXT);
// remove the logging disable property //ADDED
resContext.remove(Message.LIVE_LOGGING_PROP); //ADDED
setResponseContext(resContext);
}

Here someone already remove a Message.INVOCATION_CONTEXT property from the Response Context ... so I think It could be a good place to prevent that the logging properties is propagated in the ResponseContext at all!

To do so I had to transfer the String Constant from the AbstractLoggingInterceptor to the Message.
This way we won't change the behaviour at all.
(I'm very confident that it works... at least in debug I removed it manually and the RESP_OUT log reapperead... so the property was not propagated).

Let me know what U think about it.
And if you have any suggestions, especially regarding design patterns or the overall architecture, please feel free to share them. If you think there’s a better way to approach it, I’d be more than happy to hear it...I have a lot to learn from you!

Have a great work!

Valentino Porta

[reta]

I was updating the Jira ticket right now. (sorry I live in Italy and here is almost 2 a.m right now and tomorrow I have work) .

Thanks @vp340 , np at all

If I understand well the isRequestor() method is the same use to retrieve the EventType for logging ..so isRequestor ? EventType.RESP_IN : EventType.REQ_IN
It will set 'LIVE_LOGGING_PROP + true' if it's a client and a 'LIVE_LOGGING_PROP + false' if is a server.

This is correct (in the nutshell) just benefiting from CXF message handling logic

The only doubt situation could be 2 backend call in a row...

This should have different message instance created per call, the message should not be reused

I open a new #3373

This is possible but not the best option: the framework core (Client / Message) knows nothing about properties that are specific to custom interceptors. The tracking and decision making has to be done within in/out logging interceptors.

Another possible problem is that if we modify the property name itself, someone who had already set that property on the Bus to completely disable the logging would no longer be able to do so. This could therefore break backward compatibility. (I read something related to this in https://issues.apache.org/jira/browse/CXF-7000 )

There is risk of that but the property is intentionally not public (it is protected), so if someone relies on implementation details - we could not guarantee that it will always work for non-public APIs.

[vp340]

Hi @reta,
Thanks again for your precious time.
I understand... The core module should in fact be discern from the logging one.
Now I have some days off that I Will spend in a chalet (a poor version :/ ...not the Rich one ) and I won't be assure to have internet access all the time.
If U don't mind waiting for me, next weekend when I came back I could test your solution against some of my Company projects or simulate some strange situations in the sample project and share the results.
If I have time I would like also to improve my solution as well and try to decouple the core module from the logging one. (As a personal exercise).
Let me know what U think!
Good weekend!

[reta]

Thank you @vp340 , please take as much time as you need, no pressure here, Have a great weekend and days off