📜 ⬆️ ⬇️

Selective logging of traffic for SOAP services

Virtually any of our projects that integrate with customer services uses SOAP services. And in every such project there is the task of logging information. We are especially interested in logging queries 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 bring it up for discussion with the customer.

We would like to see our client's requests and service responses unchanged, as this helps to sort out problems that arise.

This article will explain how we set up selective traffic logging for SOAP services.
')


Problem


Let's start with the fact that Spring has built-in logging of requests and responses, which is enabled through the 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 of all SOAP traffic. We need only a few methods and not completely. For example, we do not want to see requests for downloading files in the logs, because it is a large amount of data.

In the Spring Framework, the de facto standard for building a client's soap is using the WebServiceGatewaySupport, in which you can also add request and response processing via the 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 the request, the answer or all at once.

Decision


We will use the standard ClientInterceptor, but we will provide it with the missing information about the method signature and the “input”, “output” flags, which let you know whether you need to log the request and the response.

Say at once 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<SoapLoggingInfo> holder = new ThreadLocal<>(); public static void set(SoapLoggingInfo value) { holder.set(value); } public static SoapLoggingInfo get() { return holder.get(); } } 

To put information in context, we will use an AOP approach with a “slice” on annotated methods and a pair of “tips”: before and after the method call.

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


We will analyze in parts


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

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

There is advice called before the method that fell under the 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, create an object for the ClientInterceptor and put it in context.

There is a tip called after calling a method that fell under the slice:

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

He simply 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 way 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 attached file? Ok!

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

Want to see everything? It's even easier.

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

Conclusion


In this article, we shared our experience on how to set up selective traffic logging for SOAP services. Due to this, we quickly track business transactions and at any time use logs to analyze problems. In addition, using the same mechanism, we can keep track of the time spent on the execution of a SOAP request and localize the cause of the error more quickly.

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

Source: https://habr.com/ru/post/456712/


All Articles