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 6 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
6 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
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
29 changes: 25 additions & 4 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


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);
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))));

}
}