Skip to content

[CXF-9233] Ghost RESP_OUT log #3343

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
vp340 wants to merge 8 commits into
base: main
Choose a base branch
from
Open

[CXF-9233] Ghost RESP_OUT log #3343

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
8 commits
Select commit Hold shift + click to select a range
460b44e
Disabling the log for the same Message object just for the same flow …
vp340 Jul 26, 2026
6fc77e5
Add also the ExchangeId to avoid previous REQ_OUT / RESP_IN propertie…
vp340 Jul 27, 2026
49392b5
Merge branch 'apache:main' into main
vp340 Jul 27, 2026
756c6bd
Reintroduce LIVE_LOGGING_PROP if is set and use for other feature.
vp340 Jul 27, 2026
1ef08b1
fix camel case
vp340 Jul 27, 2026
2960f66
fix comments
vp340 Jul 27, 2026
c8c0392
Merge branch 'apache:main' into CXF-9233_Ghost_RESP_OUT_log
vp340 Aug 13, 2026
508f3b6
Add a possible root solution to the problem of ghost RESP_OUT. I will…
vp340 Aug 13, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 2 additions & 0 deletions core/src/main/java/org/apache/cxf/endpoint/ClientImpl.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -650,6 +650,8 @@ protected Object[] processResult(Message message,
resContext.putAll(inMsg);
// remove the recursive reference if present
resContext.remove(Message.INVOCATION_CONTEXT);
// remove the property to disable the logging
resContext.remove(Message.LIVE_LOGGING_PROP);
setResponseContext(resContext);
}
resList = CastUtils.cast(inMsg.getContent(List.class));
Expand Down
7 changes: 7 additions & 0 deletions core/src/main/java/org/apache/cxf/message/Message.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -211,6 +211,13 @@ public interface Message extends StringMap {
*/
String THREAD_SAFE_STAX_FACTORIES = Message.class.getName() + ".THREAD_SAFE_STAX_FACTORIES";


/**
* Property to disable the interceptor log of the Message
*/
String LIVE_LOGGING_PROP = "org.apache.cxf.logging.enable";


String getId();
void setId(String id);

Expand Down
33 changes: 27 additions & 6 deletions rt/features/logging/src/main/java/org/apache/cxf/ext/logging/AbstractLoggingInterceptor.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -25,20 +25,21 @@
import java.util.regex.Pattern;

import org.apache.cxf.common.util.PropertyUtils;
import org.apache.cxf.ext.logging.event.DefaultLogEventMapper;
import org.apache.cxf.ext.logging.event.LogEvent;
import org.apache.cxf.ext.logging.event.LogEventSender;
import org.apache.cxf.ext.logging.event.PrettyLoggingFilter;
import org.apache.cxf.ext.logging.event.*;
import org.apache.cxf.interceptor.Fault;
import org.apache.cxf.message.Exchange;
import org.apache.cxf.message.Message;
import org.apache.cxf.phase.AbstractPhaseInterceptor;

import static org.apache.cxf.ext.logging.event.DefaultLogEventMapper.normalizeFlow;

public abstract class AbstractLoggingInterceptor extends AbstractPhaseInterceptor<Message> {
public static final int DEFAULT_LIMIT = 48 * 1024;
public static final int DEFAULT_THRESHOLD = -1;
public static final String CONTENT_SUPPRESSED = "--- Content suppressed ---";
protected static final String LIVE_LOGGING_PROP = "org.apache.cxf.logging.enable";

protected static final String IDEMPOTENT_LOGGING_PROP = "org.apache.cxf.idempotent.logging."; // the EventType (flow) and ExchangeId will be concatenated

@reta reta Jul 31, 2026

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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 vp340 Aug 1, 2026 •
edited
Loading

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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 reta Aug 2, 2026

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

@reta reta Aug 13, 2026

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@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 vp340 Aug 13, 2026

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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 reta Aug 13, 2026

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@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 vp340 Aug 13, 2026

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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 reta Aug 14, 2026 •
edited
Loading

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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 vp340 Aug 14, 2026

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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 reta Aug 14, 2026

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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


private static final Pattern BOUNDARY_PATTERN =
Pattern.compile("^--(\\S*)$", Pattern.MULTILINE);
private static final Pattern CONTENT_TYPE_PATTERN =
Expand All @@ -62,11 +63,31 @@ public AbstractLoggingInterceptor(String phase, LogEventSender sender) {
this.eventMapper = new DefaultLogEventMapper(maskSensitiveHelper);
}

// If the properties is set somewhere else (Bus...etc...)
protected static boolean isLoggingDisabledNow(Message message) throws Fault {
Object liveLoggingProp = message.getContextualProperty(LIVE_LOGGING_PROP);
Object liveLoggingProp = message.getContextualProperty(Message.LIVE_LOGGING_PROP);
return liveLoggingProp != null && PropertyUtils.isFalse(liveLoggingProp);
}

// The concatenated flow is added in order to enhance resilience against misuse and underlying framework
// (Reuse of the same Message object with properties still there)
// The message will be logged once per flow per ExchangeId
// If previous properties (ex. IDEMPOTENT_LOGGING_PROP + REQ_IN + ExchangeId) are still there... this will search
// only for the right properties (ex. IDEMPOTENT_LOGGING_PROP + RESP_OUT + ExchangeId)
protected boolean isLoggingDisabledForThisFlow(Message message) throws Fault {
Object idempotentLoggingProp = message.getContextualProperty(getIdempotentDisableLogKey(message)); //idempotency per Flow per ExchangeId
return idempotentLoggingProp != null && PropertyUtils.isFalse(idempotentLoggingProp);
}
protected void disableFutureLoggingForThisFlow(Message message) throws Fault {
message.put(getIdempotentDisableLogKey(message), Boolean.FALSE);
}

// IDEMPOTENT_LOGGING_PROP + FLOW + ExchangeId
protected String getIdempotentDisableLogKey(Message message){
createExchangeId(message); //Redundant
return IDEMPOTENT_LOGGING_PROP + normalizeFlow(eventMapper.getEventType(message)) + '.' + message.getExchange().get(LogEvent.KEY_EXCHANGE_ID);
}

public void addBinaryContentMediaTypes(String mediaTypes) {
eventMapper.addBinaryContentMediaTypes(mediaTypes);
}
Expand Down
15 changes: 8 additions & 7 deletions rt/features/logging/src/main/java/org/apache/cxf/ext/logging/LoggingInInterceptor.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -81,15 +81,16 @@ public Collection<PhaseInterceptor<? extends Message>> getAdditionalInterceptors
}

public void handleMessage(Message message) throws Fault {
if (isLoggingDisabledNow(message)) {

createExchangeId(message);
if (isLoggingDisabledNow(message) || isLoggingDisabledForThisFlow(message)) {
return;
} else {
//ensure only logging once for a certain message
//this can prevent message logging again when fault
//happen after PRE_INVOKE phase(rewind calls into LoggingInFaultInterceptor)
message.put(LIVE_LOGGING_PROP, Boolean.FALSE);
}
createExchangeId(message);
//ensure only logging once for a certain message
//this can prevent message logging again when fault
//happen after PRE_INVOKE phase(rewind calls into LoggingInFaultInterceptor)
disableFutureLoggingForThisFlow(message);

final LogEvent event = eventMapper.map(message, sensitiveProtocolHeaderNames);
if (shouldLogContent(event)) {
addContent(message, event);
Expand Down
15 changes: 8 additions & 7 deletions rt/features/logging/src/main/java/org/apache/cxf/ext/logging/LoggingOutInterceptor.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -59,15 +59,16 @@ public LoggingOutInterceptor(LogEventSender sender) {
}

public void handleMessage(Message message) throws Fault {
if (isLoggingDisabledNow(message)) {
createExchangeId(message);
if (isLoggingDisabledNow(message) || isLoggingDisabledForThisFlow(message)) {
return;
} else {
//ensure only logging once for a certain message
//this can prevent message logging again when fault
//happen after PRE_STREAM phase(LoggingOutInterceptor is called both in out chain and fault out chain)
message.put(LIVE_LOGGING_PROP, Boolean.FALSE);
}
createExchangeId(message);

//ensure only logging once for a certain message
//this can prevent message logging again when fault
//happen after PRE_STREAM phase(LoggingOutInterceptor is called both in out chain and fault out chain)
disableFutureLoggingForThisFlow(message);

final OutputStream os = message.getContent(OutputStream.class);
if (os != null) {
LoggingCallback callback = new LoggingCallback(sender, message, os, limit);
Expand Down
18 changes: 17 additions & 1 deletion ...eatures/logging/src/main/java/org/apache/cxf/ext/logging/event/DefaultLogEventMapper.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -47,6 +47,8 @@
import org.apache.cxf.ws.addressing.AddressingProperties;
import org.apache.cxf.ws.addressing.ContextUtils;

import static org.apache.cxf.ext.logging.event.EventType.*;

public class DefaultLogEventMapper {
public static final String MASKED_HEADER_VALUE = "XXX";
private static final Set<String> DEFAULT_BINARY_CONTENT_MEDIA_TYPES;
Expand Down Expand Up @@ -352,11 +354,25 @@ public EventType getEventType(Message message) {
return isRequestor ? EventType.REQ_OUT : EventType.RESP_OUT;
}
if (isFault) {
return EventType.FAULT_IN;
return FAULT_IN;
}
return isRequestor ? EventType.RESP_IN : EventType.REQ_IN;
}

/**
* Get the normalize 'flow' from the eventType
*
* @param eventType
* @return normalized eventType
*/
public static EventType normalizeFlow(EventType eventType){
return switch (eventType) {
case FAULT_IN -> RESP_IN;
case FAULT_OUT -> RESP_OUT;
default -> eventType;
};
}

/**
* For REST we also consider a response to be a fault if the operation is not found or the response code
* is an error
Expand Down
10 changes: 9 additions & 1 deletion rt/features/logging/src/test/java/org/apache/cxf/ext/logging/DefaultLogEventMapperTest.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -43,6 +43,8 @@
import org.junit.Test;

import static org.apache.cxf.ext.logging.event.DefaultLogEventMapper.MASKED_HEADER_VALUE;
import static org.apache.cxf.ext.logging.event.DefaultLogEventMapper.normalizeFlow;
import static org.apache.cxf.ext.logging.event.EventType.*;
import static org.hamcrest.CoreMatchers.is;
import static org.hamcrest.CoreMatchers.nullValue;
import static org.hamcrest.MatcherAssert.assertThat;
Expand Down Expand Up @@ -81,7 +83,7 @@ public void testPreflightRequestEventType() {
message.setExchange(exchange);
exchange.setOutMessage(message);
LogEvent event = mapper.map(message, Collections.emptySet());
assertEquals(EventType.RESP_OUT, event.getType());
assertEquals(RESP_OUT, event.getType());
}

/**
Expand Down Expand Up @@ -206,4 +208,10 @@ public void testNoSubjectReturned() {
LogEvent event = Subject.doAs(subject, (PrivilegedAction<LogEvent>) () -> mapper.map(message));
assertThat(event.getPrincipal(), is(nullValue()));
}

@Test
public void testNormalizeFlow(){
assertEquals(RESP_IN, normalizeFlow(FAULT_IN));
assertEquals(RESP_OUT, normalizeFlow(FAULT_OUT));
}
}
42 changes: 35 additions & 7 deletions rt/features/logging/src/test/java/org/apache/cxf/ext/logging/LoggingInInterceptorTest.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -22,27 +22,27 @@
import java.io.IOException;
import java.io.OutputStream;
import java.nio.charset.StandardCharsets;
import java.util.Arrays;
import java.util.Collections;
import java.util.HashMap;
import java.util.HashSet;
import java.util.Map;
import java.util.Set;
import java.util.*;

import org.apache.cxf.ext.logging.event.DefaultLogEventMapper;
import org.apache.cxf.ext.logging.event.LogEvent;
import org.apache.cxf.io.CachedOutputStream;
import org.apache.cxf.message.Exchange;
import org.apache.cxf.message.ExchangeImpl;
import org.apache.cxf.message.Message;
import org.apache.cxf.message.MessageImpl;

import org.junit.Before;
import org.junit.Test;

import static org.apache.cxf.common.util.PropertyUtils.isFalse;
import static org.apache.cxf.ext.logging.AbstractLoggingInterceptor.IDEMPOTENT_LOGGING_PROP;
import static org.apache.cxf.ext.logging.event.DefaultLogEventMapper.MASKED_HEADER_VALUE;
import static org.apache.cxf.ext.logging.event.EventType.*;
import static org.hamcrest.MatcherAssert.assertThat;
import static org.hamcrest.Matchers.equalToIgnoringCase;
import static org.hamcrest.Matchers.hasSize;
import static org.junit.Assert.assertEquals;
import static org.junit.Assert.*;

public class LoggingInInterceptorTest {
private static final String TEST_HEADER_VALUE = "TestValue";
Expand Down Expand Up @@ -234,4 +234,32 @@ public void shouldLogMultipartPayloadNoHeaders() throws IOException {

assertThat(event.getPayload(), equalToIgnoringCase(buf.toString()));
}

@Test
public void testLoggingEnable(){
Message message = new MessageImpl();
Exchange exchange = new ExchangeImpl();
exchange.setOutMessage(message);
message.setExchange(exchange);
message.put(Message.REQUESTOR_ROLE, Boolean.TRUE);

DefaultLogEventMapper mapper = new DefaultLogEventMapper();
assertEquals(FAULT_OUT, mapper.getEventType(message));

assertNull(message.getExchange().get(LogEvent.KEY_EXCHANGE_ID));
assertFalse(interceptor.isLoggingDisabledForThisFlow(message));
assertNotNull(message.getExchange().get(LogEvent.KEY_EXCHANGE_ID));
interceptor.disableFutureLoggingForThisFlow(message);
assertTrue(interceptor.isLoggingDisabledForThisFlow(message));

assertNull(message.getContextualProperty(IDEMPOTENT_LOGGING_PROP + REQ_IN + '.' + message.getExchange().get(LogEvent.KEY_EXCHANGE_ID)));
assertNull(message.getContextualProperty(IDEMPOTENT_LOGGING_PROP + REQ_OUT + '.' + message.getExchange().get(LogEvent.KEY_EXCHANGE_ID)));
assertNull(message.getContextualProperty(IDEMPOTENT_LOGGING_PROP + RESP_IN + '.' + message.getExchange().get(LogEvent.KEY_EXCHANGE_ID)));
assertNotNull(message.getContextualProperty(IDEMPOTENT_LOGGING_PROP + RESP_OUT + '.' + message.getExchange().get(LogEvent.KEY_EXCHANGE_ID))); //The only present // FAULT_OUT normalized
assertNull(message.getContextualProperty(IDEMPOTENT_LOGGING_PROP + FAULT_IN + '.' + message.getExchange().get(LogEvent.KEY_EXCHANGE_ID)));
assertNull(message.getContextualProperty(IDEMPOTENT_LOGGING_PROP + FAULT_OUT + '.' + message.getExchange().get(LogEvent.KEY_EXCHANGE_ID)));

assertTrue(isFalse(message.getContextualProperty(IDEMPOTENT_LOGGING_PROP + RESP_OUT + '.' + message.getExchange().get(LogEvent.KEY_EXCHANGE_ID))));

}
}