X-Request-ID in logging

Extending the server
1

I would like to have the X-Request-ID from the request header in the keycloak logging. My first approach was to implement ContainerRequestFilter and ContainerResponseFilter:

public class TraceIdFilter implements ContainerRequestFilter, ContainerResponseFilter {
    private static final String TRACE_ID_HEADER = "X-Request-ID";

    protected static final TraceIdFilter INSTANCE = new TraceIdFilter();

    @Override
    public void filter(ContainerRequestContext requestContext) {
        String traceId = requestContext.getHeaderString(TRACE_ID_HEADER);

        if(traceId == null) {
            traceId = UUID.randomUUID().toString();
        }

        MDC.put(TRACE_ID_HEADER, traceId);
    }

    @Override
    public void filter(ContainerRequestContext requestContext, ContainerResponseContext responseContext) {
        MDC.remove(TRACE_ID_HEADER);
    }
}

And using the logging pattern:

<pattern-formatter pattern="%K{level}%d{HH:mm:ss,SSS} %-5p [%c] (%t) [%X{X-Request-ID}] %s%e%n"/>

The requestId is logged but unfortunately the ContainerRequestFilter/ContainerResponseFilter is executed before the transaction starts/ends. The requestId is missing in some important logs, especially the keycloak event logs.
I tried also to implement io.undertow.server.HttpHandler but this one is called too early, before the actual dispatching to the worker thread, so the requestId is lost.

Is there any other approach to this issue?

3 Likes
2

Maybe this Logging requests with Undertow can be an inspiration.

3

Thank you. I tried the approach using a HttpHandler. But as already mentioned, the HttpHandler is executed by another thread and the context is lost in the worker thread that is responsible for the actual execution.

4

@viktorgt Did you found the solution?

5

@arulrajnet Unfortunately, no solution yet.

6

In theory tracing lib may have custom propagator, which will use request header "X-Request-ID to create/propagate current trace id. And then you will just use trace id in the logger pattern
(e.g. opentelemetry-java-instrumentation/logger-mdc-instrumentation.md at main · open-telemetry/opentelemetry-java-instrumentation · GitHub).

Easier option will be to add X-Request-ID into X-B3-TraceId request header (on the proxy/LB level) and then standard B3 propagator can be used.

7

@viktorgt May I know if you have solution for this issue? I also encounter such issue that need log some values in http request headers. I tried them in event listener spi, yet the httpheaders are always null while getting it from KeycloakContext while event occurred. So would you help share your solution if possible? many thanks.

        KeycloakContext context = session.getContext();
        UriInfo uriInfo = context.getUri();
        HttpHeaders headers = context.getRequestHeaders();
8

We are using a workaround by register a transaction listener to cleanup the MDC. This can still lead to logs without the traceId, if other transaction listeners are executed after the mentioned one.

@PreMatching
public class TraceIdFilter implements ContainerRequestFilter, ContainerResponseFilter {
    private static final String TRACE_ID_HEADER = "X-Request-ID";

    protected static final TraceIdFilter INSTANCE = new TraceIdFilter();
    private static final Logger logger = Logger.getLogger(TraceIdFilter.class);

    @Override
    public void filter(ContainerRequestContext requestContext) {
        String traceId = requestContext.getHeaderString(TRACE_ID_HEADER);
        logger.trace("Entering filter");
        if(traceId == null) {
            traceId = UUID.randomUUID().toString();
        }
        MDC.put(TRACE_ID_HEADER, traceId);
        logger.trace("Leaving filter");
    }

    @Override
    public void filter(ContainerRequestContext requestContext, ContainerResponseContext responseContext) {
        Resteasy.getContextData(KeycloakSession.class).getTransactionManager().enlistAfterCompletion(new KeycloakTransaction() {
            @Override
            public void begin() {
                // NOOP
            }

            @Override
            public void commit() {
                MDC.remove(TRACE_ID_HEADER);
            }

            @Override
            public void rollback() {
                MDC.remove(TRACE_ID_HEADER);
            }

            @Override
            public void setRollbackOnly() {
                // NOOP
            }

            @Override
            public boolean getRollbackOnly() {
                return false;
            }

            @Override
            public boolean isActive() {
                return false;
            }
        });
    }
}
9

Thank you @viktorgt !
I tried another method, i.e. save to session attribute firstly in the filter, then create another log event listener which would be responsible for put and clear MDC for log. This listener also implement also all codes in JBossLoggingEventListenerProvider. This method can work, yet I’m not sure if it will work fine for the scenario you mentioned. BTW, if also need config such event listener with such event listener in keycloak console.

//source code in filter
    @Override
    public void filter(ContainerRequestContext requestContext) throws IOException {
        String traceId = requestContext.getHeaderString(Constants.RequestHeader.TRACE_ID);

        KeycloakSession session = ResteasyProviderFactory.getContextData(KeycloakSession.class);
        if(session != null){
            Map<String, String> traceMap = new HashMap<>();
            traceMap.put(Constants.EFKLogging.TRACE_ID, traceId);
            ......
            session.setAttribute(TraceUtil.TRACE_INFO_KEY, traceMap);
        }
    }

//source code in custom log event listener
final Object traceObj = session.getAttribute(TraceUtil.TRACE_INFO_KEY);
        if(traceObj == null){
            logger.warn("traceObj is null");
        }else{
            Map<String, String> traceMap = (Map)traceObj;

            MDC.put(Constants.EFKLogging.TRACE_ID, traceMap.getOrDefault(Constants.EFKLogging.TRACE_ID,TraceUtil.emptyString));
            
        }