Arquitectura de microservicios: trazabilidad de peticiones.

Con el éxito y la expansión de las arquitecturas de microservicios se dan una serie de situaciones tecnológicas y funcionalmente nuevas, que no eran necesario solventar en las arquitecturas clásicas. Algunas de ellas se deben principalmente a la característica distribuida de estas arquitecturas. Actualmente existen medios para solventar algunas de estas casuísticas como los proporcionados por spring-cloud-netflix para el registro de instancias, comprobación de estado, balanceo de carga, gestión de fallos en cascada…

Una de estas nuevas situaciones a las que nos tenemos que enfrentar es la trazabilidad de las peticiones. En las arquitecturas clásicas una petición que llegaba a la aplicación era resuelta funcionalmente dentro de la propia aplicación, salvo alguna interacción con base de datos o con algún servicio para funcionalidades de autenticación o similares. Pero en las arquitecturas de microservicios basados en el principio de responsabilidad única, nos encontramos un ecosistema compuesto por varias aplicaciones (cientos incluso en el caso de la arquitectura de Netflix).

Todo esto provoca que una sola petición del cliente pueda pasar por diversas aplicaciones hasta ser respondida. Y aquí surge el problema, ¿cómo podemos seguir el recorrido de esa petición?, es decir ¿como la trazamos?

Esta situación, que a priori puede parecer trivial, se convierte en crucial a la hora de solventar bugs y depurar nuestra aplicación, labor que se puede convertir en un infierno si la petición recorre más de una decena de microservicios.

¿Cómo enfrentarse a la trazabilidad de peticiones?

La resolución a este problema pasa por asociar un identificador a cada petición que el usuario realice a nuestro microservicio, este identificador se incluirá también en las trazas de log que vaya generando dicha petición en la aplicación y en caso de invocar a otro microservicio también se propagará, de forma que tendrá el mismo valor en microservicios diferentes, permitiéndonos seguir la funcionalidad ejecutada por cada petición realizada por el usuario. El flujo de ejecución será el siguiente:

• El microservicio A recibe una petición del usuario y le asigna un identificador 1234.
• Las trazas generadas por la funcionalidad invocada por el usuario en el microservicio A incluirán el identificador 1234.
• El microservicio A realiza una petición al microservicio B e incluye el identificador 1234.
• El microservicio B recibe la petición con el identificador 1234.
• Las trazas generadas por la funcionalidad en el microservicio B incluyen el identificador 1234.

Por tanto las funcionalidades que necesitamos implementar son las siguientes:

• Comprobar en una petición si existe el identificador. De no ser así, generarlo y almacenar dicho identificador.
• En cada traza de log leer el identificador e incluirlo en las mismas.
• En las peticiones que salgan de un microservicio leer el identificador e incluirlo.

Para ello lo que haremos será:

• Crear un filtro que comprobará si se proporciona el identificador y lo almacenará, o en caso de que no se proporcione lo creará y lo almacenará.
• Modificaremos además la librería de log (en este caso logback) para recuperar el identificador e imprimirlo en las trazas.
• Finalmente crearemos un interceptor que añadirá el identificador en todas las peticiones REST que realicemos. Almacenaremos este identificador en el contexto del thread, que está ejecutando la petición, de forma que siempre podremos recuperarlo. El código fuente se puede encontrar aquí.

Filtro de peticiones

El objetivo de este filtro es obtener el identificador (a partir de ahora correlationId) y almacenarlo en el contexto del thread. En caso de no existir se asumirá que se trata de una petición del usuario y se creará un nuevo correlationId, que se almacenará en el contexto. En este caso se ha optado por usar una cabecera para enviarlo en las peticiones, pero podría haberse pasado como parámetro o de cualquier otra forma.

A continuación se puede ver el código correspondiente al filtro:

public class CorrelationFilter implements Filter {
    public static final String CORRELATION_HEADER_NAME = "CorrelationId";
    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain)
        throws IOException, ServletException {
        HttpServletRequest httpServletRequest = (HttpServletRequest) request;
        String correlationId = httpServletRequest.getHeader(CORRELATION_HEADER_NAME);
        /* If not correlationId exists, we have to create it */
        if (StringUtils.isEmpty(correlationId)) {
            correlationId = UUID.randomUUID().toString();
        }
        /* Settle the correlationId for the context */
        CorrelationContext.getContext().setCorrelationId(correlationId);
        /* Continue with the execution */
        chain.doFilter(request, response);
    }
    @Override
    public void init(FilterConfig filterConfig) throws ServletException {}
    @Override
    public void destroy() {}
}

Como vemos en la línea 14, se ha utilizado la clase UUID para la generación del correlationId, pero se podría haber generado uno a mano dotándolo de semántica. Esto es incluyendo en el contenido, por ejemplo, el timestamp, el identificador de usuario… de forma similar a como genera MongoDB sus ObjectID.

En la línea 18 vemos cómo se establece el correlationId en el contexto (más adelante veremos el código encargado de realizar dicha operación).

Una de las ventajas de esta implementación es que el filtro no hace distinción de si la cabecera le llega en una llamada de otro microservicio o en una de usuario. Por lo que podríamos añadir la cabecera en una petición de usuario y luego, conociendo el correlationId incluido, seguir dicha petición para depurar un flujo concreto.

Ahora solo será necesario registrar dicho filtro como se muestra en la imagen a continuación:

@Configuration
public class FilterConfiguration {
    @Bean
    public FilterRegistrationBean getCorrelationFilter() {
        FilterRegistrationBean registration = new FilterRegistrationBean();
        registration.setFilter(new CorrelationFilter());
        registration.addUrlPatterns("/*");
        registration.setName("correlationFilter");
        return registration;
    }
}

Contexto del thread y logback

La siguiente imagen muestra la clase encargada de almacenar el correlationId en el contexto del thread. Como se puede observar, la clase no tiene mayor complejidad:

public class CorrelationContext {
    private static final ThreadLocal<CorrelationContext> CONTEXT =
        new ThreadLocal<CorrelationContext>();
    private String correlationId;
    public static CorrelationContext getContext() {
        CorrelationContext result = CONTEXT.get();
        if (result == null) {
            result = new CorrelationContext();
            CONTEXT.set(result);
        }
        return result;
    }
}

Ahora deberemos extender las clases de logback para que este añada el correlationId en cada traza.

La siguiente imagen muestra la clase CorrelationConverter, que será la encargada de reemplazar el elemento del patrón de logback que configuremos por su valor concreto:

public class CorrelationConverter extends ClassicConverter {
    @Override
    public String convert(ILoggingEvent event) {
        /* Return the current correlationId stored in the context */
        return CorrelationContext.getContext().getCorrelationId();
    }
}

Ahora extenderemos la clase PatternLayoutEncoder encargada de los patrones de expresión de log para incluir el CorrelationConverter, como se muestra en la siguiente imagen:

public class CorrelationPatternLayoutEncoder extends PatternLayoutEncoder {
    public static final String CORRELATION_PATTERN = "id";
    public void start() {
        PatternLayout patternLayout = new PatternLayout();
        patternLayout.getDefaultConverterMap().put(
            CORRELATION_PATTERN, CorrelationConverter.class.getName());
        patternLayout.setContext(context);
        patternLayout.setPattern(getPattern());
        patternLayout.setOutputPatternAsHeader(outputPatternAsHeader);
        patternLayout.start();
        this.layout = patternLayout;
        this.started = true;
    }
}

En la línea 8 insertamos nuestro conversor, que reemplazará la expresión ‘id’. Esto quiere decir que el elemento que deberemos incluir en nuestra expresión de log en la configuración de logback será sustituido por el correlationId es ‘%id’, como se muestra en la siguiente imagen:

xml

<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender"/>
    <encoder class="com.example.test.logback.CorrelationPatternLayoutEncoder">
        <charset>utf-8</charset>
        <Pattern>%d{HH:mm:ss.SSS} %thread %id [%p] %c - %m%n</Pattern>
    </encoder>
</appender>

Así, el ‘%id’ en el Pattern será reemplazado por el valor del correlationId. Observemos también que hemos cambiado la clase del encoder para que sea nuestro CorrelationPatternLayoutEncoder.

Interceptor

Si no queremos incluir manualmente la cabecera con el correlationId en cada petición que realicemos en nuestro código, podemos crear un interceptor que insertaremos en el RestTemplate. La siguiente imagen muestra dicho interceptor:

public class CorrelationInterceptor implements ClientHttpRequestInterceptor {
    @Override
    public ClientHttpResponse intercept(HttpRequest request, byte[] body, ClientHttpRequestExecution execution) throws IOException {
        /* Add the correlationId header for the output requests */
        HttpHeaders headers = request.getHeaders();
        headers.set(CorrelationFilter.CORRELATION_HEADER_NAME, CorrelationContext.getContext().getCorrelationId());
        return execution.execute(request, body);
    }
}

Ahora será necesario incluirlo en el RestTemplate. Aquí hay que tener en cuenta que si utilizamos Ribbon, como es habitual en las arquitecturas de microservicios, este ya tiene un RestTemplate modificado para incluir su funcionalidad. Deberemos, por tanto, modificar dicho RestTemplate en lugar de crear uno nuevo como se muestra en la siguiente imagen:

@Configuration
public class RestTemplateConfiguration {
    @Autowired
    private RestTemplate restTemplate;
    @PostConstruct
    public void addInterceptor() {
        List<ClientHttpRequestInterceptor> interceptors = restTemplate.getInterceptors();
        interceptors.add(new CorrelationInterceptor());
        restTemplate.setInterceptors(interceptors);
    }
}

Bonus: trazas con rsyslog

Una situación también habitual en estas arquitecturas es que dispongamos de un servidor centralizado de logs, como por ejemplo Kibana, y que utilicemos rsyslog para enviar esas trazas a Kibana. Logback dispone actualmente de un Appender para enviar las trazas a Syslog cuya configuración se puede ver en el siguiente enlace.

Como podemos ver en este caso no hay un Encoder, o sea que no podremos crearnos el nuestro. Por tanto deberemos modificar la clase SyslogAppender. Para ello nos copiaremos su código y realizaremos las modificaciones necesarias para añadir el CorrelationConverter que hemos desarrollado.

En concreto los Converter se establecen en el método setupStackTraceLayout(), que modificaremos como se puede ver en esta imagen:

private void setupStackTraceLayout() {
    stackTraceLayout.getInstanceConverterMap().put("syslogStart", SyslogStartConverter.class.getName());
    /** Include the correlationConverter **/
    stackTraceLayout.getInstanceConverterMap().put( CorrelationPatternLayoutEncoder.CORRELATION_PATTERN, CorrelationConverter.class.getName());
    /**************************************/
    stackTraceLayout.setPattern(getPrefixPattern() + stackTracePattern);
    stackTraceLayout.setContext(getContext());
    stackTraceLayout.start();
}

De la misma forma cambiaremos la configuración del logback.xml en el appender de syslog para utilizar nuestra nueva clase e incluiremos el ‘%id’ para mostrar el correlationId como se puede ver a continuación:

xml

<appender name="RSYSLOG" class="com.example.test.logback.syslog.CorrelationSyslogAppender">
    <syslogHost>localhost</syslogHost>
    <port>2177</port>
    <facility>LOCAL0</facility>
    <suffixPattern>%d{HH:mm:ss.SSS} %thread %id [%p] %c - %m%n</suffixPattern>
</appender>

Conclusión

La principal ventaja de la centralización de logs, en conjunto con el correlationId, es que una vez identifiquemos el correlationId asociado a la petición del usuario podemos filtrar por el mismo en Kibana. Obtenemos así todas las trazas provocadas por dicha petición sin importar en qué microservicio o qué instancia se han producido.

Como vemos esta implementación nos permite abordar la trazabilidad de peticiones entre aplicaciones, incluyendo además un sistema de centralización de logs. La solución sería similar para otras implementaciones de log diferentes a logback y para otro tipo de arquitecturas diferentes a las de microservicios.

La necesidad de esta solución está directamente relacionada con la complejidad de nuestro ecosistema de aplicaciones y su aporte será mayor a mayor cantidad y complejidad de los bugs que tengamos. Si deseas disponer de una arquitectura distribuida mínimamente compleja y poder resolver bugs de forma rápida y eficiente te recomiendo incluir esta solución.
A mayores de esto la trazabilidad de las peticiones es la puerta de entrada a una infinidad de posibilidades en lo que a estudio de comportamiento del usuario se refiere. Si el correlationId que generemos está relacionado con el identificador de usuario podremos ver sus franjas horarias de interacción, los flujos que realiza, la duración de sus interacciones… lo cual supone una información con un gran valor de negocio.