En ciertas ocasiones, al desarrollar una nueva comunicación entre APIs, es útil poder hacer logging de las peticiones y respuestas que se realizan desde un cliente REST.
En esta página se enumeran algunas alternativas para pintar esta información en el log de nuestra aplicación en Spring-Boot.
Esta página es la equivalente en Spring a la WiKi Logear Mensajes In/OUT en FundeWeb.
Guía detallada
A continuación se detallan las distintas configuraciones que permiten realizar el logging de peticiones y respuestas en clientes REST.
1. Logging básico con RestTemplate
Es muy fácil de configurar pero proporciona poca información:
- No aparecen las cabeceras
- No aparece el body de la respuesta.
Configuración:
Añadir en el fichero application.properties:
##Configuración RestTemplate para logging básico de request y response en clientes logging.level.org.springframework.web.client.RestTemplate=DEBUG
Cliente con RestTemplate:
final RestTemplate plantilla = new RestTemplate(); final HttpHeaders headers = new HttpHeaders(); headers.set( "Cabecera-test", "Valor de test" ); headers.set( "Cabecera-test2", "Valor de test 2" ); final HttpEntity<String> entity = new HttpEntity<>( "Body de test", headers ); final String url = "https://fundewebjsshowcasedesa.um.es/api/v1.0/public/test/CS"; final ResponseEntity<String> response = plantilla.exchange( url, HttpMethod.GET, entity, String.class );
Ejemplo de log de petición:
13-05-2021 13:25:44.165 DEBUG 12864 --- [nio-8080-exec-1] o.s.w.c.RestTemplate : HTTP GET https://fundewebjsshowcasedesa.um.es/api/v1.0/public/test/CS 13-05-2021 13:25:44.166 DEBUG 12864 --- [nio-8080-exec-1] o.s.w.c.RestTemplate : Accept=[text/plain, application/json, application/*+json, */*] 13-05-2021 13:25:44.166 DEBUG 12864 --- [nio-8080-exec-1] o.s.w.c.RestTemplate : Writing [Body de test] with org.springframework.http.converter.StringHttpMessageConverter 13-05-2021 13:25:44.197 DEBUG 12864 --- [nio-8080-exec-1] o.s.w.c.RestTemplate : Response 200 OK 13-05-2021 13:25:44.197 DEBUG 12864 --- [nio-8080-exec-1] o.s.w.c.RestTemplate : Reading to [java.lang.String] as "application/json"
2. Logging completo con Apache HttpComponents.
Como puede observarse, el log pintado con el método anterior es bastante escueto y no proporciona demasiada información. En concreto, sería interesante que pintara el body de la respuesta.
Con este segundo método la información pintada es mucho más completa (incluso excesiva).
Configuración:
- Añadir en el fichero pom.xml la dependencia:
<dependency> <groupId>org.apache.httpcomponents</groupId> <artifactId>httpclient</artifactId> </dependency>
- Añadir en el fichero application.properties:
logging.level.org.apache.http=DEBUG logging.level.org.apache.http.wire=DEBUG
Cliente con RestTemplate:
final RestTemplate plantilla = new RestTemplate(); plantilla.setRequestFactory( new HttpComponentsClientHttpRequestFactory() ); //Configuración Apache HttpClient final HttpHeaders headers = new HttpHeaders(); headers.set( "Cabecera-test", "Valor de test" ); headers.set( "Cabecera-test2", "Valor de test 2" ); final HttpEntity<String> entity = new HttpEntity<>( "Body de test", headers ); final String url = "https://fundewebjsshowcasedesa.um.es/api/v1.0/public/test/u"; final ResponseEntity re = plantilla.exchange( url, HttpMethod.GET, entity, String.class );
Ejemplo de log de petición:
En esta petición se ha forzado que el endpoint al que llama el cliente devuelva un error 401 para poder distinguir mejor el body de la respuesta.
------------------------------------------ Log de la petición
21-10-2021 09:05:45.064 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.c.p.RequestAddCookies : CookieSpec selected: default
21-10-2021 09:05:45.069 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.c.p.RequestAuthCache : Auth cache not set in the context
21-10-2021 09:05:45.072 DEBUG 2104 --- [http-nio-8080-exec-4] h.i.c.PoolingHttpClientConnectionManager : Connection request: [route: {s}->https://fundewebjsshowcasedesa.um.es:443][total available: 0; route allocated: 0 of 5; total allocated: 0 of 10]
21-10-2021 09:05:45.077 DEBUG 2104 --- [http-nio-8080-exec-4] h.i.c.PoolingHttpClientConnectionManager : Connection leased: [id: 2][route: {s}->https://fundewebjsshowcasedesa.um.es:443][total available: 0; route allocated: 1 of 5; total allocated: 1 of 10]
21-10-2021 09:05:45.080 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.i.e.MainClientExec : Opening connection {s}->https://fundewebjsshowcasedesa.um.es:443
21-10-2021 09:05:45.084 DEBUG 2104 --- [http-nio-8080-exec-4] .i.c.DefaultHttpClientConnectionOperator : Connecting to fundewebjsshowcasedesa.um.es/155.54.228.138:443
21-10-2021 09:05:45.086 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.c.s.SSLConnectionSocketFactory : Connecting socket to fundewebjsshowcasedesa.um.es/155.54.228.138:443 with timeout 0
21-10-2021 09:05:45.160 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.c.s.SSLConnectionSocketFactory : Enabled protocols: [TLSv1.2]
21-10-2021 09:05:45.165 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.c.s.SSLConnectionSocketFactory : Enabled cipher suites:[TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, TLS_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_RSA_WITH_AES_256_GCM_SHA384, TLS_DHE_RSA_WITH_AES_256_GCM_SHA384, TLS_DHE_DSS_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_DSS_WITH_AES_128_GCM_SHA256, TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384, TLS_RSA_WITH_AES_256_CBC_SHA256, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384, TLS_DHE_RSA_WITH_AES_256_CBC_SHA256, TLS_DHE_DSS_WITH_AES_256_CBC_SHA256, TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_RSA_WITH_AES_256_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_DSS_WITH_AES_256_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_DSS_WITH_AES_128_CBC_SHA256, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]
21-10-2021 09:05:45.179 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.c.s.SSLConnectionSocketFactory : Starting handshake
21-10-2021 09:05:47.361 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.c.s.SSLConnectionSocketFactory : Secure session established
21-10-2021 09:05:47.363 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.c.s.SSLConnectionSocketFactory : negotiated protocol: TLSv1.2
21-10-2021 09:05:47.365 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.c.s.SSLConnectionSocketFactory : negotiated cipher suite: TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
21-10-2021 09:05:47.368 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.c.s.SSLConnectionSocketFactory : peer principal: CN=mncskubedesa.atica.um.es, OU=ATICA, O=Universidad de Murcia, L=Murcia, ST=Murcia, C=ES
21-10-2021 09:05:47.371 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.c.s.SSLConnectionSocketFactory : peer alternative names: [mncskubedesa.atica.um.es, fundewebjsshowcasedesa.um.es, verdacciodesa.um.es]
21-10-2021 09:05:47.376 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.c.s.SSLConnectionSocketFactory : issuer principal: CN=GEANT OV RSA CA 4, O=GEANT Vereniging, C=NL
21-10-2021 09:05:47.384 DEBUG 2104 --- [http-nio-8080-exec-4] .i.c.DefaultHttpClientConnectionOperator : Connection established 155.54.67.188:54720<->155.54.228.138:443
21-10-2021 09:05:47.387 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.i.e.MainClientExec : Executing request GET /api/v1.0/public/test/u HTTP/1.1
21-10-2021 09:05:47.389 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.i.e.MainClientExec : Target auth state: UNCHALLENGED
21-10-2021 09:05:47.389 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.i.e.MainClientExec : Proxy auth state: UNCHALLENGED
21-10-2021 09:05:47.389 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.headers : http-outgoing-2 >> GET /api/v1.0/public/test/u HTTP/1.1
21-10-2021 09:05:47.389 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.headers : http-outgoing-2 >> Accept: text/plain, application/json, application/*+json, */*
21-10-2021 09:05:47.389 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.headers : http-outgoing-2 >> Cabecera-test: Valor de test
21-10-2021 09:05:47.389 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.headers : http-outgoing-2 >> Cabecera-test2: Valor de test 2
21-10-2021 09:05:47.408 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.headers : http-outgoing-2 >> Content-Type: text/plain;charset=ISO-8859-1
21-10-2021 09:05:47.411 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.headers : http-outgoing-2 >> Host: fundewebjsshowcasedesa.um.es
21-10-2021 09:05:47.412 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.headers : http-outgoing-2 >> Connection: Keep-Alive
21-10-2021 09:05:47.412 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.headers : http-outgoing-2 >> User-Agent: Apache-HttpClient/4.5.12 (Java/1.8.0_301)
21-10-2021 09:05:47.412 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.headers : http-outgoing-2 >> Accept-Encoding: gzip,deflate
21-10-2021 09:05:47.412 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 >> "GET /api/v1.0/public/test/u HTTP/1.1[\r][\n]"
21-10-2021 09:05:47.424 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 >> "Accept: text/plain, application/json, application/*+json, */*[\r][\n]"
21-10-2021 09:05:47.440 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 >> "Cabecera-test: Valor de test[\r][\n]"
21-10-2021 09:05:47.450 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 >> "Cabecera-test2: Valor de test 2[\r][\n]"
21-10-2021 09:05:47.453 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 >> "Content-Type: text/plain;charset=ISO-8859-1[\r][\n]"
21-10-2021 09:05:47.455 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 >> "Host: fundewebjsshowcasedesa.um.es[\r][\n]"
21-10-2021 09:05:47.459 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 >> "Connection: Keep-Alive[\r][\n]"
21-10-2021 09:05:47.462 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 >> "User-Agent: Apache-HttpClient/4.5.12 (Java/1.8.0_301)[\r][\n]"
21-10-2021 09:05:47.465 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 >> "Accept-Encoding: gzip,deflate[\r][\n]"
21-10-2021 09:05:47.468 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 >> "[\r][\n]"
------------------------------------------ Log de la respuesta => Dirección flechas "<<"
------------------------------------------ Log del código de estado devuelto
21-10-2021 09:05:47.490 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 << "HTTP/1.1 401 [\r][\n]"
------------------------------------------
21-10-2021 09:05:47.493 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 << "Strict-Transport-Security: max-age=15768000; includeSubDomains[\r][\n]"
21-10-2021 09:05:47.496 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 << "Date: Thu, 21 Oct 2021 07:05:46 GMT[\r][\n]"
21-10-2021 09:05:47.499 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 << "Content-Type: application/json[\r][\n]"
21-10-2021 09:05:47.502 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 << "Transfer-Encoding: chunked[\r][\n]"
21-10-2021 09:05:47.505 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 << "Connection: keep-alive[\r][\n]"
21-10-2021 09:05:47.506 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 << "Vary: Origin[\r][\n]"
21-10-2021 09:05:47.506 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 << "Vary: Access-Control-Request-Method[\r][\n]"
21-10-2021 09:05:47.506 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 << "Vary: Access-Control-Request-Headers[\r][\n]"
21-10-2021 09:05:47.506 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 << "Set-Cookie: JSESSIONID=8249A87231939143E042C26AA99C4D70; Path=/api; HttpOnly[\r][\n]"
21-10-2021 09:05:47.506 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 << "X-Content-Type-Options: nosniff[\r][\n]"
21-10-2021 09:05:47.506 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 << "X-XSS-Protection: 1; mode=block[\r][\n]"
21-10-2021 09:05:47.524 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 << "Cache-Control: no-cache, no-store, max-age=0, must-revalidate[\r][\n]"
21-10-2021 09:05:47.527 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 << "Pragma: no-cache[\r][\n]"
21-10-2021 09:05:47.529 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 << "Expires: 0[\r][\n]"
21-10-2021 09:05:47.532 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 << "X-Frame-Options: SAMEORIGIN[\r][\n]"
21-10-2021 09:05:47.534 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 << "[\r][\n]"
21-10-2021 09:05:47.539 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.headers : http-outgoing-2 << HTTP/1.1 401
21-10-2021 09:05:47.543 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.headers : http-outgoing-2 << Strict-Transport-Security: max-age=15768000; includeSubDomains
21-10-2021 09:05:47.546 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.headers : http-outgoing-2 << Date: Thu, 21 Oct 2021 07:05:46 GMT
21-10-2021 09:05:47.548 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.headers : http-outgoing-2 << Content-Type: application/json
21-10-2021 09:05:47.550 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.headers : http-outgoing-2 << Transfer-Encoding: chunked
21-10-2021 09:05:47.553 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.headers : http-outgoing-2 << Connection: keep-alive
21-10-2021 09:05:47.555 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.headers : http-outgoing-2 << Vary: Origin
21-10-2021 09:05:47.559 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.headers : http-outgoing-2 << Vary: Access-Control-Request-Method
21-10-2021 09:05:47.561 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.headers : http-outgoing-2 << Vary: Access-Control-Request-Headers
21-10-2021 09:05:47.563 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.headers : http-outgoing-2 << Set-Cookie: JSESSIONID=8249A87231939143E042C26AA99C4D70; Path=/api; HttpOnly
21-10-2021 09:05:47.566 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.headers : http-outgoing-2 << X-Content-Type-Options: nosniff
21-10-2021 09:05:47.568 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.headers : http-outgoing-2 << X-XSS-Protection: 1; mode=block
21-10-2021 09:05:47.571 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.headers : http-outgoing-2 << Cache-Control: no-cache, no-store, max-age=0, must-revalidate
21-10-2021 09:05:47.575 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.headers : http-outgoing-2 << Pragma: no-cache
21-10-2021 09:05:47.577 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.headers : http-outgoing-2 << Expires: 0
21-10-2021 09:05:47.579 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.headers : http-outgoing-2 << X-Frame-Options: SAMEORIGIN
21-10-2021 09:05:47.584 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.i.e.MainClientExec : Connection can be kept alive indefinitely
21-10-2021 09:05:47.587 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.i.a.HttpAuthenticator : Authentication required
21-10-2021 09:05:47.589 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.i.a.HttpAuthenticator : fundewebjsshowcasedesa.um.es:443 requested authentication
21-10-2021 09:05:47.589 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.i.a.HttpAuthenticator : Response contains no authentication challenges
21-10-2021 09:05:47.589 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.c.p.ResponseProcessCookies : Cookie accepted [JSESSIONID="8249A87231939143E042C26AA99C4D70", version:0, domain:fundewebjsshowcasedesa.um.es, path:/api, expiry:null]
21-10-2021 09:05:47.609 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 << "a0[\r][\n]"
---------------------------- Log con Body de la respuesta
21-10-2021 09:05:47.613 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 << "{"fecha":"21/10/2021 07:05:46","estado":"UNAUTHORIZED","mensaje":"No tiene acceso para solicitar este servicio","tipoRespuesta":"CUSTOM_DefaultErrorAttributes"}[\r][\n]"
-----------------------------
21-10-2021 09:05:47.618 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 << "0[\r][\n]"
21-10-2021 09:05:47.620 DEBUG 2104 --- [http-nio-8080-exec-4] o.a.h.wire : http-outgoing-2 << "[\r][\n]"
21-10-2021 09:05:47.625 DEBUG 2104 --- [http-nio-8080-exec-4] h.i.c.PoolingHttpClientConnectionManager : Connection [id: 2][route: {s}->https://fundewebjsshowcasedesa.um.es:443] can be kept alive indefinitely
21-10-2021 09:05:47.628 DEBUG 2104 --- [http-nio-8080-exec-4] h.i.c.DefaultManagedHttpClientConnection : http-outgoing-2: set socket timeout to 0
21-10-2021 09:05:47.631 DEBUG 2104 --- [http-nio-8080-exec-4] h.i.c.PoolingHttpClientConnectionManager : Connection released: [id: 2][route: {s}->https://fundewebjsshowcasedesa.um.es:443][total available: 1; route allocated: 1 of 5; total allocated: 1 of 10]
Referencias:
Artículos Relacionados
Contenido por etiqueta
No hay ningún contenido con las etiquetas especificadas