One ID shared between many requests in Spring-CodePudding

I want to ask about something like conversationId, that could be shared between many requests/responses in one API call. For instance, we have /test endpoint, this endpoint call another service, then another and return response based on obtained results. It can looks like:

  Conversation:
  1) Sending test request.
  2) API calls /info endpoint.
  3) Returns /info response.
  4) API calls /example endpoint.
  5) Returns /example response.
  6) Returns /test response.

When we call /test API simultaneously 4-5 times, then log could be messy and we don't know how to combine the individual calls.

I want to tag it with any random request scope ID, like high value number. It could looks like:

  1) Sending test request of ID 12345.
  2) Sending test request of ID 98765.
  3) API calls /info endpoint of ID 12345.
  4) Returns /info response of ID 12345.
  5) API calls /info endpoint of ID 98765.
  6) API calls /example endpoint of ID 12345.
  7) Returns /info response of ID 98765.
  and so on

Is there any Spring mechanism to share data between ClientHttpRequestInterceptor and GenericFilterBean in request way without recreating those beans? Like a custom scope bean with lifecycle starts at doFilter and end there as well.

CodePudding user response：

You can use MDC along with OncePerRequestFilter something like this for this kind of requirement.:

    @Component
    public class MDCFilter implements OncePerRequestFilter{
    @Override
        protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {
            MDC.put("request_ID", someNumberGeneratorUtility());
            try {
                filterChain.doFilter(request, response);
            } finally {
                MDC.remove("request_ID");
            }
        }
}

CodePudding user response：

1. Using Sleuth (Limitation - Spring Cloud Sleuth is Spring Boot based)

Spring sleuth could provide trace ID, and span ID. Using trace ID you can combine the individual call.

The below example may be useful for someone.

Add spring sleuth

<dependency>
            <groupId>org.springframework.cloud</groupId>
            <artifactId>spring-cloud-starter-sleuth</artifactId>
        </dependency>

Your /test

        @GetMapping("/test")
        public String test() {

            LOG.info("Sending test request.");
            LOG.info("API calls /info endpoint.");
            // Calling /info service or endpoint
            LOG.info("Returns /info response.");
            LOG.info("API calls /example endpoint.");
            // Calling /example service or endpoint
            LOG.info("Returns /example response.");
            LOG.info("Returns /test response");

            return "test";
        }

Calling /test API simultaneously 5 times and the server call log is shown below

2022-04-28 00:40:11.108  INFO [test,be0b352e1f8664d1,be0b352e1f8664d1] 10766 --- [nio-9091-exec-5] c.k.d.d.a.AccountServiceApplication      : Sending test request.
2022-04-28 00:40:11.109  INFO [test,29c2e863354fca33,29c2e863354fca33] 10766 --- [nio-9091-exec-1] c.k.d.d.a.AccountServiceApplication      : Sending test request.
2022-04-28 00:40:11.115  INFO [test,29c2e863354fca33,29c2e863354fca33] 10766 --- [nio-9091-exec-1] c.k.d.d.a.AccountServiceApplication      : API calls /info endpoint.
2022-04-28 00:40:11.115  INFO [test,29c2e863354fca33,29c2e863354fca33] 10766 --- [nio-9091-exec-1] c.k.d.d.a.AccountServiceApplication      : Returns /info response.
2022-04-28 00:40:11.115  INFO [test,29c2e863354fca33,29c2e863354fca33] 10766 --- [nio-9091-exec-1] c.k.d.d.a.AccountServiceApplication      : API calls /example endpoint.
2022-04-28 00:40:11.115  INFO [test,29c2e863354fca33,29c2e863354fca33] 10766 --- [nio-9091-exec-1] c.k.d.d.a.AccountServiceApplication      : Returns /example response.
2022-04-28 00:40:11.115  INFO [test,29c2e863354fca33,29c2e863354fca33] 10766 --- [nio-9091-exec-1] c.k.d.d.a.AccountServiceApplication      : Returns /test response
2022-04-28 00:40:11.115  INFO [test,be0b352e1f8664d1,be0b352e1f8664d1] 10766 --- [nio-9091-exec-5] c.k.d.d.a.AccountServiceApplication      : API calls /info endpoint.
2022-04-28 00:40:11.116  INFO [test,be0b352e1f8664d1,be0b352e1f8664d1] 10766 --- [nio-9091-exec-5] c.k.d.d.a.AccountServiceApplication      : Returns /info response.
2022-04-28 00:40:11.116  INFO [test,be0b352e1f8664d1,be0b352e1f8664d1] 10766 --- [nio-9091-exec-5] c.k.d.d.a.AccountServiceApplication      : API calls /example endpoint.
2022-04-28 00:40:11.116  INFO [test,be0b352e1f8664d1,be0b352e1f8664d1] 10766 --- [nio-9091-exec-5] c.k.d.d.a.AccountServiceApplication      : Returns /example response.
2022-04-28 00:40:11.116  INFO [test,be0b352e1f8664d1,be0b352e1f8664d1] 10766 --- [nio-9091-exec-5] c.k.d.d.a.AccountServiceApplication      : Returns /test response
2022-04-28 00:40:11.109  INFO [test,b26d689f73b974b7,b26d689f73b974b7] 10766 --- [nio-9091-exec-4] c.k.d.d.a.AccountServiceApplication      : Sending test request.
2022-04-28 00:40:11.116  INFO [test,b26d689f73b974b7,b26d689f73b974b7] 10766 --- [nio-9091-exec-4] c.k.d.d.a.AccountServiceApplication      : API calls /info endpoint.
2022-04-28 00:40:11.116  INFO [test,b26d689f73b974b7,b26d689f73b974b7] 10766 --- [nio-9091-exec-4] c.k.d.d.a.AccountServiceApplication      : Returns /info response.
2022-04-28 00:40:11.116  INFO [test,b26d689f73b974b7,b26d689f73b974b7] 10766 --- [nio-9091-exec-4] c.k.d.d.a.AccountServiceApplication      : API calls /example endpoint.
2022-04-28 00:40:11.116  INFO [test,b26d689f73b974b7,b26d689f73b974b7] 10766 --- [nio-9091-exec-4] c.k.d.d.a.AccountServiceApplication      : Returns /example response.
2022-04-28 00:40:11.116  INFO [test,b26d689f73b974b7,b26d689f73b974b7] 10766 --- [nio-9091-exec-4] c.k.d.d.a.AccountServiceApplication      : Returns /test response
2022-04-28 00:40:11.109  INFO [test,4f28a79ecc2ce6da,4f28a79ecc2ce6da] 10766 --- [nio-9091-exec-2] c.k.d.d.a.AccountServiceApplication      : Sending test request.
2022-04-28 00:40:11.109  INFO [test,ee7bfa89b05b69ad,ee7bfa89b05b69ad] 10766 --- [nio-9091-exec-3] c.k.d.d.a.AccountServiceApplication      : Sending test request.
etc....

Notice that the application name is inside the brackets at the beginning. These brackets are added by Sleuth. They represent the application name, trace ID, and span ID.

Also, You can get the current trace programmatically.

        @Autowired
        private Tracer tracer;

        @GetMapping("/test")
        public String account() {

            LOG.info("Sending test request, "   "trace ID="   tracer.currentSpan().context().traceId().toString());
            LOG.info("API calls /info endpoint, "   "trace ID="   tracer.currentSpan().context().traceId().toString());
            // Calling /info service or endpoint
            LOG.info("Returns /info response, "   "trace ID="   tracer.currentSpan().context().traceId().toString());
            LOG.info("API calls /example endpoint, "   "trace ID="
                      tracer.currentSpan().context().traceId().toString());
            // Calling /example service or endpoint
            LOG.info("Returns /example response, "   "trace ID="   tracer.currentSpan().context().traceId().toString());
            LOG.info("Returns /test response, "   "trace ID="   tracer.currentSpan().context().traceId().toString());

            return "test";
        }

Log

....Sending test request, trace ID=51322ee614962951
.... API calls /info endpoint, trace ID=51322ee614962951
.... Sending test request, trace ID=4bc5017e2beceaf8
.... Sending test request, trace ID=75b638bda78a7bb5
.... Returns /info response, trace ID=51322ee614962951
.... API calls /info endpoint, trace ID=4bc5017e2beceaf8
.... API calls /example endpoint, trace ID=51322ee614962951
.... Sending test request, trace ID=f20cde67b4376777
  etc....

2. You can use Thread Context Map

        @GetMapping("/test")
        public String test() {
            ThreadContext.put("id", UUID.randomUUID().toString());
            LOG.info("Sending test request, "   ThreadContext.get("id"));
            LOG.info("API calls /info endpoint, "   ThreadContext.get("id"));
            // Calling /info service or endpoint
            LOG.info("Returns /info response, "   ThreadContext.get("id"));
            LOG.info("API calls /example endpoint, "   ThreadContext.get("id"));
            // Calling /example service or endpoint
            LOG.info("Returns /example response, "   ThreadContext.get("id"));
            LOG.info("Returns /test response, "   ThreadContext.get("id"));

            return "test";
        }

CodePudding user response：

I have created RequestContext bean as a holder to my request data, such as conversationId:

@Component
@RequestScope
public class RequestContext {
    private final String conversationId;

    public RequestContext() {
        conversationId = UUID.randomUUID().toString();
    }

    public String getConversationId() {
        return conversationId;
    }
}

and, later, inject it into my Filter:

@Component
public class LoggingFilter extends GenericFilterBean {

    private final RequestContext requestContext;

    public RestServerLoggingFilter(RequestContext requestContext) {
        this.requestContext = requestContext;
    }


...
}

but most important thing is configuration and order:

@Configuration
public class RestServerConfiguration {

    private static final int LOGGING_FILTER_ORDER = -104;

    @Bean
    public FilterRegistrationBean<RestServerLoggingFilter> initFilter(LoggingFilter filter) {
        FilterRegistrationBean<RestServerLoggingFilter> registrationBean = new FilterRegistrationBean<>();
        registrationBean.setFilter(filter);
        registrationBean.setDispatcherTypes(
                EnumSet.complementOf(EnumSet.of(DispatcherType.ERROR))
        );
        registrationBean.setOrder(LOGGING_FILTER_ORDER);
        return registrationBean;
    }

}

Filters are stacked into a list under ApplicationFilterChain class. When we browse this stack, we've got a OrderedRequestContextFilter bean with order -105 that init RequestScope defining it's attributes at initContextHolders. It's very important to know about that. Then You can inject requested scope bean into any filter, that is after OrderedRequestContextFilter in chain.