Selective traffic logging for SOAP services

    Almost in any of our projects that integrates with customer services, SOAP services are used. And in every such project there is a task of logging information. We are especially interested in logging requests that are related to the business operations of the solution. For example, an employee entered incorrect data and the service returned an error. We want to know the details of this error and correct it as soon as possible or submit it for discussion with the customer.

    We would like to see the requests of our client and the answers of the service unchanged, as this helps to sort out the problems that arise.

    In this article, we’ll show how we set up selective traffic logging for SOAP services.



    Problem


    To begin with, Spring has built-in request and response logging that is enabled through configuration

    logging.level.org.springframework.ws.client.MessageTracing.sent=TRACE
    logging.level.org.springframework.ws.client.MessageTracing.received=TRACE

    The problem is that these settings include logging all SOAP traffic. We need only a few methods, and then not completely. For example, we do not want to see requests for downloading files in the logs, because this is a large amount of data.

    In the Spring Framework, the de facto standard for building a client soap is to use WebServiceGatewaySupport, in which you can also add request and response processing through ClientInterceptor. But in his methods it is difficult to understand which method of our client initiated the call. And it is not clear whether it is necessary to log only a request, an answer, or all at once.

    Decision


    We will use the standard ClientInterceptor, but supply it with the missing information about the method signature and the “input”, “output” flags, by which you can determine whether the request and response should be logged.

    We make a reservation right away that such a solution will not work with streaming serialization / deserialization. But we use Axiom, which has the “payload caching” option enabled by default and this solution works.

    Structure for storing information:

    import lombok.Data;
    @Data
    public class SoapLoggingInfo {
        private String method;
        private boolean input = false;
        private boolean output = false;
    }

    Context for storing information:

    public class SoapLoggingContext {
        private static final ThreadLocal holder = new ThreadLocal<>();
        public static void set(SoapLoggingInfo value) {
            holder.set(value);
        }
        public static SoapLoggingInfo get() {
            return holder.get();
        }
    }

    To place information in a context, we will use the AOP approach with a “slice” for annotated methods and a couple of “tips”: before and after the method is called.

    Annotation for the method:

    @Target({ElementType.METHOD})
    @Retention(RetentionPolicy.RUNTIME)
    @Component
    public @interface SoapLoggable {
        boolean value() default true;
        boolean input() default true;
        boolean output() default true;
    }

    The aspect itself was put under cat.

    Aspect
    @Aspect
    @Component
    @Slf4j
    public class SoapLoggingAspect {
        @Value("${logging.soap.request.enabled:false}")
        private Boolean enabled;
        @Pointcut("execution(@ru.trueengineering.agentapi.logging.SoapLoggable * *(..))")
        public void soapLoggableMethod() {}
        @Before("soapLoggableMethod()")
        public void beforeSoapLoggable(JoinPoint joinPoint) {
            if (!enabled) {
                return;
            }
            SoapLoggable soapRequestLogger = getAnnotation(joinPoint);
            if (soapRequestLogger.value()) {
                SoapLoggingInfo loggingInfo = new SoapLoggingInfo();
                loggingInfo.setInput(soapRequestLogger.input());
                loggingInfo.setOutput(soapRequestLogger.output());
                final Class aClass = joinPoint.getTarget().getClass();
                final Signature signature = joinPoint.getSignature();
                final String name = signature.getName();
                loggingInfo.setMethod(aClass.getSimpleName() + "." + name);
                SoapLoggingContext.set(loggingInfo);
            }
        }
        @After("soapLoggableMethod()")
        public void afterSoapLoggable(JoinPoint joinPoint) {
            SoapLoggingContext.set(null);
        }
        private SoapLoggable getAnnotation(JoinPoint joinPoint) {
            MethodSignature signature = (MethodSignature) joinPoint.getSignature();
            Method method = signature.getMethod();
            return  method.getAnnotation(SoapLoggable.class);
        }
    }


    Let's take apart


    A slice is an expression meaning "all methods annotated by SoapLogable." We use the capabilities of AspectJ:

    @Pointcut("execution(@ru.trueengineering.agentapi.logging.SoapLoggable * *(..))")
    public void soapLoggableMethod() {}

    There is advice called before a method that has fallen under a slice:

    @Before("soapLoggableMethod()")
    public void beforeSoapLoggable(JoinPoint joinPoint) {}

    In this method, we take an annotation, extract the method signature and meta information from the annotation, form an object for ClientInterceptor and put it in context.

    There is a tip called after calling a method that has fallen under a slice:

    @After("soapLoggableMethod()")
    public void afterSoapLoggable(JoinPoint joinPoint) {}

    It just clears the context. Actually, logging under the cat:

    Logging
    @Component
    @Slf4j
    public class SoapLoggingInterceptor extends ClientInterceptorAdapter {
        @Override
        public boolean handleRequest(MessageContext messageContext) throws WebServiceClientException {
            SoapLoggingInfo info = SoapLoggingContext.get();
            if (info != null && info.isInput()) {
                ByteArrayOutputStream xml = new ByteArrayOutputStream();
                try {
                    messageContext.getRequest().writeTo(xml);
                    log.debug("Метод: " + info.getMethod() + ", запрос:" + xml.toString(StandardCharsets.UTF_8));
                } catch (IOException e) {
                    log.error("Ошибка получения SOAP request", e);
                }
            }
            return true;
        }
        @Override
        public boolean handleResponse(MessageContext messageContext) throws WebServiceClientException {
            return handleResponseOrFault(messageContext);
        }
        @Override
        public boolean handleFault(MessageContext messageContext) throws WebServiceClientException {
            return handleResponseOrFault(messageContext);
        }
        private boolean handleResponseOrFault(MessageContext messageContext) {
            SoapLoggingInfo info = SoapLoggingContext.get();
            if (info != null && info.isOutput()) {
                ByteArrayOutputStream xml = new ByteArrayOutputStream();
                try {
                    messageContext.getResponse().writeTo(xml);
                    log.debug("Метод: " + info.getMethod() + ", ответ:" + xml.toString(StandardCharsets.UTF_8));
                } catch (IOException e) {
                    log.error("Ошибка получения SOAP response", e);
                }
            }
            return true;
        }
    }


    We use the standard method of “intercepting" and processing SOAP requests, but we use information from the context to selectively log only the methods we need.

    Profit!


    Using this approach is very simple.

    Do not want to see the request with the attached file? Ok!

    @SoapLoggable(input = false)
    public Optional> attachFile(
                final AttachFileRequest attachFileRequest) {
            return send(new WsAttachFileRequest(attachFileRequest));
    }
    

    Want to see everything? It’s even easier.

    @SoapLoggable
    public Optional> calculate(final CalcRequest calcRequest) {
    }

    Conclusion


    This article shared their experiences on how to configure selective traffic logging for SOAP services. Thanks to this, we quickly monitor business operations and at any time use logs to analyze problems. In addition, we can use the same mechanism to keep track of the time spent on executing a SOAP request and to quickly localize the cause of the error.

    We also share a useful link to this topic: a brief set of examples of using slices and tips on AspectJ .

    Also popular now: