Выборочное логирование трафика для сервисов 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.
    • +10
    • 1,5k
    • 2
    True Engineering
    97,54
    Лаборатория технологических инноваций
    Поделиться публикацией

    Комментарии 2

      +1

      Спасибо за статью. Как раз сейчас пишу SOAP-клиента, логирование пригодится.

        0

        Спасибо за отклик! Рады, что наш опыт вам полезен

      Только полноправные пользователи могут оставлять комментарии. Войдите, пожалуйста.

      Самое читаемое