Cómo depurar una aplicación Spring WebFlux

La depuración de una aplicación Spring WebFlux puede ser una tarea desafiante, especialmente cuando se trata de flujos reactivos complejos. A diferencia de las aplicaciones de bloqueo tradicionales, donde el seguimiento de la pila proporciona una indicación clara de la causa raíz de un problema, las aplicaciones reactivas pueden ser más difíciles de depurar. Los problemas como el código de bloqueo, los problemas de concurrencia y las condiciones de carrera pueden causar errores sutiles que son difíciles de diagnosticar.

Guión

Cuando se trata de un error, no siempre se trata de un problema relacionado con el código. Podría ser un conjunto de factores, como una refactorización reciente, cambios de equipo, plazos estrictos, etc. En la vida real, es común terminar resolviendo problemas de aplicaciones grandes creadas por personas que dejaron la empresa hace un tiempo y usted acaba de unirse.

Saber un poco sobre un dominio y tecnologías no le hará la vida más fácil.

En el ejemplo de código a continuación, quería imaginar cómo se vería un código con errores para una persona que se unió recientemente a un equipo.

Considere depurar este código más como un viaje que como un desafío. La causa raíz podría ser obvia para aquellos que están familiarizados con las aplicaciones reactivas. Sin embargo, algunas prácticas a continuación podrían ser muy útiles para revisar.

 @GetMapping("/greeting/{firstName}/{lastName}") public Mono<String> greeting(@PathVariable String firstName, @PathVariable String lastName) { return Flux.fromIterable(Arrays.asList(firstName, lastName)) .filter(this::wasWorkingNiceBeforeRefactoring) .transform(this::senselessTransformation) .collect(Collectors.joining()) .map(names -> "Hello, " + names); } private boolean wasWorkingNiceBeforeRefactoring(String aName) { // We don't want to greet with John, sorry return !aName.equals("John"); } private Flux<String> senselessTransformation(Flux<String> flux) { return flux .single() .flux() .subscribeOn(Schedulers.parallel()); }

Entonces, lo que hace este fragmento de código es: antepone "Hola" a los nombres proporcionados como parámetros. Su colega John le dice que todo funciona en su computadora portátil. Eso es cierto:

 > curl localhost:8080/greeting/John/Doe > Hello, Doe

Pero cuando lo ejecutas como curl localhost:8080/greeting/Mick/Jagger , ves el siguiente seguimiento de pila:

 java.lang.IndexOutOfBoundsException: Source emitted more than one item at reactor.core.publisher.MonoSingle$SingleSubscriber.onNext(MonoSingle.java:134) ~[reactor-core-3.5.5.jar:3.5.5] Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: Error has been observed at the following site(s): *__checkpoint ⇢ Handler com.example.demo.controller.GreetingController#greeting(String, String) [DispatcherHandler] *__checkpoint ⇢ HTTP GET "/greeting/Mick/Jagger" [ExceptionHandlingWebHandler] Original Stack Trace: <18 internal lines> at java.base/java.util.concurrent.FutureTask.run(FutureTask.java) ~[na:na] (4 internal lines)

Genial, ninguno de los rastros conduce a un ejemplo de código anterior.

Todo lo que revela es que 1) ocurrió en el método GreetingController#greeting , y 2) el cliente realizó un `HTTP GET "/saludo/Mick/Jagger

.doOnError()

Lo primero y lo más fácil de probar es agregar la devolución de llamada `.doOnError()` al final de la cadena de saludo.

 @GetMapping("/greeting/{firstName}/{lastName}") public Mono<String> greeting(@PathVariable String firstName, @PathVariable String lastName) { return Flux.fromIterable(Arrays.asList(firstName, lastName)) // <...> .doOnError(e -> logger.error("Error while greeting", e)); }

Buen intento, pero los registros no muestran ninguna mejora.

No obstante, el seguimiento de la pila interna de Reactor:

Aquí hay algunas formas en que doOnError puede/no puede ser útil durante la depuración:

1. Registro : puede usar doOnError para registrar mensajes de error y proporcionar más contexto sobre lo que salió mal en su transmisión reactiva. Esto puede ser especialmente útil al depurar problemas en un flujo complejo con muchos operadores.

2. Recuperación : doOnError también se puede usar para recuperarse de errores y continuar procesando la transmisión. Por ejemplo, puede usar onErrorResume para proporcionar un valor alternativo o una secuencia en caso de error.

3. Depuración : lo más probable es doOnError no proporcione un seguimiento de pila mejor, excepto lo que ya vio en los registros. No confíe en él como un buen solucionador de problemas.

   
   

registro()

La próxima parada es reemplazar doOnError() previamente agregado por la llamada al método log() . Tan simple como se pone. log() observa todas las señales de Reactive Streams y las rastrea en registros bajo el nivel INFO de forma predeterminada.

Veamos qué información adicional vemos en los registros ahora:

Podemos ver qué métodos Reactivos se han llamado ( onSubscribe , request y onError ). Además, saber desde qué subprocesos (grupos) se han llamado estos métodos puede ser información muy útil. Sin embargo, no es relevante para nuestro caso.

log() le permite agregar declaraciones de registro a su transmisión, lo que facilita el seguimiento del flujo de datos y el diagnóstico de problemas. Si tuviéramos un flujo de datos más complejo con cosas como flatMap, subcadenas, bloqueo de llamadas, etc., nos beneficiaríamos mucho al tenerlo todo desconectado. Es una cosa muy fácil y agradable para el uso diario. Sin embargo, todavía no conocemos la causa raíz.

Ganchos.onOperatorDebug()

La instrucción Hooks.onOperatorDebug() le dice a Reactor que habilite el modo de depuración para todos los operadores en flujos reactivos, lo que permite mensajes de error más detallados y seguimientos de pila.

Según la documentación oficial:

La instrucción debe llamarse una vez por tiempo de ejecución. Uno de los mejores lugares sería Configuración o Clases principales. Para nuestro caso de uso sería:

 public Mono<String> greeting(@PathVariable String firstName, @PathVariable String lastName) { Hooks.onOperatorDebug(); return // <...> }

Al agregar Hooks.onOperatorDebug() finalmente podemos avanzar en nuestra investigación. Stacktrace es mucho más útil:

Y en la línea 42 tenemos una llamada single() .

No se desplace hacia arriba, el senselessTransformation se ve a continuación:

 private Flux<String> senselessTransformation(Flux<String> flux) { return flux .single() // line 42 .flux() .subscribeOn(Schedulers.parallel()); }

Esa es la causa raíz.

single() emite un elemento de la fuente Flux o señala IndexOutOfBoundsException para una fuente con más de un elemento. Eso significa que el flujo en el método emite más de 1 elemento. Al subir en la jerarquía de llamadas vemos que originalmente hay un Flux con dos elementos Flux.fromIterable(Arrays.asList(firstName, lastName)) .

El método de filtrado wasWorkingNiceBeforeRefactoring elimina un elemento de un flujo cuando es igual a John . Esa es la razón por la que el código funciona para una universidad llamada John. Eh.

Hooks.onOperatorDebug() puede ser particularmente útil al depurar flujos reactivos complejos, ya que proporciona información más detallada sobre cómo se procesa el flujo. Sin embargo, habilitar el modo de depuración puede afectar el rendimiento de su aplicación (debido a los seguimientos de pila completados), por lo que solo debe usarse durante el desarrollo y la depuración, y no en producción.

puntos de control

Para lograr casi el mismo efecto que ofrece Hooks.onOperatorDebug() con un impacto mínimo en el rendimiento, hay un operador especial checkpoint() . Habilitará el modo de depuración para esa sección de la transmisión, mientras que el resto de la transmisión no se verá afectado.

Agreguemos dos puntos de control después del filtrado y después de la transformación:

 public Mono<String> greeting(@PathVariable String firstName, @PathVariable String lastName) { return Flux.fromIterable(Arrays.asList(firstName, lastName)) .filter(this::wasWorkingNiceBeforeRefactoring) /* new */ .checkpoint("After filtering") .transform(this::senselessTransformation) /* new */ .checkpoint("After transformation") .collect(Collectors.joining()) .map(names -> "Hello, " + names); }

Echa un vistazo a los registros:

Este desglose de puntos de control nos dice que el error se ha observado después de nuestro segundo punto de control descrito como Después de la transformación . No significa que no se haya alcanzado el primer punto de control durante la ejecución. Lo fue, pero el error comenzó a aparecer solo después del segundo. Es por eso que no vemos Después de filtrar .

También puede ver dos puntos de control más mencionados en el desglose, de y . Fueron alcanzados después del que establecimos, hasta la jerarquía de llamadas.

Además de la descripción, puede obligar a Reactor a generar un seguimiento de pila para su punto de control agregando true como segundo parámetro al método checkpoint() . Es importante tener en cuenta que el stacktrace generado lo llevará a la línea con un punto de control. No completará un seguimiento de pila para la excepción original. Por lo tanto, no tiene mucho sentido porque puede encontrar fácilmente un punto de control proporcionando una descripción.

Conclusión

Al seguir estas mejores prácticas, puede simplificar el proceso de depuración e identificar y resolver problemas rápidamente en su aplicación Spring WebFlux. Tanto si es un desarrollador experimentado como si acaba de empezar con la programación reactiva, estos consejos le ayudarán a mejorar la calidad y la fiabilidad de su código y a ofrecer mejores experiencias a sus usuarios.