Выборочное логирование трафика для сервисов SOAP

Практически в любом нашем проекте, который интегрируется с сервисами заказчика, используются SOAP-сервисы. И в каждом таком проекте есть задача логирования информации. Мы особенно заинтересованы в логировании запросов, которые связаны с бизнес-операциями решения. Например, сотрудник ввел неправильные данные и сервис вернул ошибку. Мы хотим знать детали этой ошибки и как можно быстрее её поправить или вынести на обсуждение с заказчиком.

Мы хотели бы видеть запросы нашего клиента и ответы сервиса в неизменном виде, поскольку это помогает разбирать возникающие проблемы.

В этой статье расскажем, как мы настроили выборочное логирование трафика для сервисов SOAP.

Проблема

Начнём с того, что Spring имеет встроенное логирование запросов и ответов, которое включается через конфигурацию

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

Проблема в том, что эти настройки включают логирование всего SOAP трафика. Нам же нужны только несколько методов и то не полностью. Например, мы не хотим видеть запросы по загрузке файлов в логах, потому что это большой объем данных.

В Spring Framework стандартом де-факто для построения soap клиента является использование WebServiceGatewaySupport, в котором можно также добавить обработку запросов и ответов через ClientInterceptor. Но в его методах сложно понять, какой метод нашего клиента инициировал вызов. И непонятно, надо ли логировать только запрос, ответ или всё сразу.

Решение

Мы будем использовать стандартный ClientInterceptor, но снабдим его недостающей информацией о сигнатуре метода и флажками «input», «output», по которым можно понять, нужно ли логировать запрос и ответ.

Оговоримся сразу, что такое решение не будет работать с «потоковой» сериализацией/десериализацией. Но мы используем Axiom, у которого по умолчанию включена опция “payload caching” и такое решение работает.

Структура для хранения информации:

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

Контекст для хранения информации:

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

Для помещения информации в контекст мы будем использовать АОП подход со «срезом» по аннотированным методам и парой «советов»: до вызова метода и после.

Аннотация для метода:

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

Сам аспект положили под кат.

Аспект

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

}

Разберём по частям

Срез представляет собой выражение, означающее «все методы, аннотированные SoapLogable». Мы используем возможности AspectJ:

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

Есть совет, вызываемый до метода, попавшего под срез:

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

В этом методе мы берём аннотацию, извлекаем сигнатуру метода и метаинформацию из аннотации, формируем объект для ClientInterceptor и помещаем его в контекст.

Есть совет, вызываемый после вызова метода, попавшего под срез:

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

Он просто чистит контекст. Собственно, логирование под катом:

Логирование

@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;
    }
}

Используем стандартный способ «перехвата» и обработки SOAP запросов, но используем информацию из контекста, чтобы выборочно логировать только нужные нам методы.

Profit!

Пользоваться этим подходом очень просто.

Не желаем видеть запрос с приаттаченным файлом? Оk!

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

Хотим видеть всё? Так ещё проще.

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

Заключение

В этой статье поделились опытом, как настроили выборочное логирование трафика для сервисов SOAP. Благодаря этому, мы оперативно отслеживаем бизнес-операции и в любой момент используем логи для разбора проблем. Кроме этого, мы можем при помощи этого же механизма вести учёт времени, которое потрачено на выполнение запроса SOAP и быстрее локализовать причину ошибки.

Также делимся полезной ссылкой на эту тему: краткий набор примеров использования срезов и советов на AspectJ.