Reactor-netty: DNS resolution problems since version 1.x

Created on 8 Mar 2021 · 48Comments · Source: reactor/reactor-netty

Hello,

I tried to migrate my spring boot application from version 2.3.x to 2.4.2 and I have DNS resolution issues with the WebClient.
I have heard that some implementation has changed in DNS resolution from reactor-netty 0.9 to 1.0

Expected Behavior

I expected Webclient http calls working correctly like the previous version of Netty Reactor 0.9.13.

Actual Behavior

Since updating to Spring Boot 2.4.x, the version of Netty changed for 1.x.x, and there are problems of DNS resolution.

Depending of the URL endpoint (endpoint in public Internet or endpoint in the company network), it's could work or not.

Windows 10 local machine (with AdoptOpenJdk 11.0.4.11 hotspot) : DNS resolution OK for public internet endpoints / KO for internal company endpoints
Docker container linux-based (with adoptopenjdk:11.0.7_10-jre-hotspot): DNS resolution KO for public internet endpoints / OK for internal company endpoints

WebClient configuration

  HttpClient httpClient =
                HttpClient.create(resourceFactory.getConnectionProvider())
                        .resolver(spec -> spec.trace("somelogger", LogLevel.DEBUG))
                        .runOn(resourceFactory.getLoopResources())
                        .option(CONNECT_TIMEOUT_MILLIS, (int) connectionTimeout.toMillis())
                        .doOnConnected((connection) -> connection.addHandlerLast(new ReadTimeoutHandler(readTimeout.toMillis(), MILLISECONDS)));

On Windows 10 (local machine) - Test KO for an internal company endpoint

2021-01-21 12:01:15.092 DEBUG 9396 --- [ctor-http-nio-4] somelogger                               : from /x.x.x.x:53 : DefaultDnsQuestion(xxxxxxxx. IN A) failure

io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No matching record type found
    at io.netty.resolver.dns.DnsResolveContext.onResponseAorAAAA(..)(Unknown Source)

2021-01-21 12:01:15.093 DEBUG 9396 --- [ctor-http-nio-4] somelogger                               : from /x.x.x.x:53 : DefaultDnsQuestion(xxxxxxxx. IN AAAA) failure

io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No matching record type found
    at io.netty.resolver.dns.DnsResolveContext.onResponseAorAAAA(..)(Unknown Source)

2021-01-21 12:01:15.117 DEBUG 9396 --- [ctor-http-nio-4] somelogger                               : from /x.x.x.x:53 : DefaultDnsQuestion(xxxxxxxx. IN AAAA) no answer ServFail(2)
2021-01-21 12:01:15.137 DEBUG 9396 --- [ctor-http-nio-4] somelogger                               : from /x.x.x.x:53 : DefaultDnsQuestion(xxxxxxxx. IN AAAA) no answer ServFail(2)
2021-01-21 12:01:20.141 DEBUG 9396 --- [ctor-http-nio-4] somelogger                               : from /x.x.x.x:53 : DefaultDnsQuestion(xxxxxxxx. IN AAAA) failure

io.netty.resolver.dns.DnsNameResolverTimeoutException: [/x.x.x.x:53] query via UDP timed out after 5000 milliseconds (no stack trace available)

2021-01-21 12:01:25.145 DEBUG 9396 --- [ctor-http-nio-4] somelogger                               : from /x.x.x.x:53 : DefaultDnsQuestion(xxxxxxxx. IN AAAA) failure

io.netty.resolver.dns.DnsNameResolverTimeoutException: [/x.x.x.x:53] query via UDP timed out after 5000 milliseconds (no stack trace available)

2021-01-21 12:01:25.145 DEBUG 9396 --- [ctor-http-nio-4] somelogger                               : DefaultDnsQuestion(xxxxxxxx. IN AAAA) query never written and failed

io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No name servers returned an answer
    at io.netty.resolver.dns.DnsResolveContext.tryToFinishResolve(..)(Unknown Source)

2021-01-21 12:01:25.192 ERROR 9396 --- [ctor-http-nio-4] LOGGER_STACK                             :
2021-01-21 12:01:25.193 ERROR 9396 --- [ctor-http-nio-4] s.o.c.w.iolog.LocalHttpRequestLogger     : Error with HTTP request

org.springframework.web.reactive.function.client.WebClientRequestException: failed to resolve 'xxxxxxxx' after 6 queries ; nested exception is java.net.UnknownHostException: failed to resolve 'xxxxxxxx' after 6 queries
    at org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:137)
    at reactor.core.publisher.MonoErrorSupplied.subscribe(MonoErrorSupplied.java:70)
    at reactor.core.publisher.Mono.subscribe(Mono.java:4046)
    at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:103)
    at reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:221)
    at reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:221)
    at reactor.core.publisher.FluxMap$MapSubscriber.onError(FluxMap.java:132)
    at reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:221)
    at reactor.core.publisher.MonoNext$NextSubscriber.onError(MonoNext.java:93)
    at reactor.core.publisher.MonoFlatMapMany$FlatMapManyMain.onError(MonoFlatMapMany.java:204)
    at reactor.core.publisher.SerializedSubscriber.onError(SerializedSubscriber.java:124)
    at reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.whenError(FluxRetryWhen.java:224)
    at reactor.core.publisher.FluxRetryWhen$RetryWhenOtherSubscriber.onError(FluxRetryWhen.java:273)
    at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.drain(FluxConcatMap.java:413)
    at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.onNext(FluxConcatMap.java:250)
    at reactor.core.publisher.EmitterProcessor.drain(EmitterProcessor.java:491)
    at reactor.core.publisher.EmitterProcessor.tryEmitNext(EmitterProcessor.java:299)
    at reactor.core.publisher.SinkManySerialized.tryEmitNext(SinkManySerialized.java:97)
    at reactor.core.publisher.InternalManySink.emitNext(InternalManySink.java:27)
    at reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.onError(FluxRetryWhen.java:189)
    at reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:189)
    at reactor.netty.http.client.HttpClientConnect$MonoHttpConnect$ClientTransportSubscriber.onError(HttpClientConnect.java:306)
    at reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:189)
    at reactor.netty.resources.DefaultPooledConnectionProvider$DisposableAcquire.onError(DefaultPooledConnectionProvider.java:166)
    at reactor.netty.internal.shaded.reactor.pool.AbstractPool$Borrower.fail(AbstractPool.java:427)
    at reactor.netty.internal.shaded.reactor.pool.SimpleDequePool.lambda$drainLoop$5(SimpleDequePool.java:309)
    at reactor.core.publisher.FluxDoOnEach$DoOnEachSubscriber.onError(FluxDoOnEach.java:186)
    at reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:189)
    at reactor.netty.resources.DefaultPooledConnectionProvider$PooledConnectionAllocator$PooledConnectionInitializer.onError(DefaultPooledConnectionProvider.java:565)
    at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondError(MonoFlatMap.java:192)
    at reactor.core.publisher.MonoFlatMap$FlatMapInner.onError(MonoFlatMap.java:259)
    at reactor.netty.transport.TransportConnector$MonoChannelPromise.tryFailure(TransportConnector.java:464)
    at reactor.netty.transport.TransportConnector.lambda$doResolveAndConnect$6(TransportConnector.java:271)
    at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:578)
    at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:571)
    at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:550)
    at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:491)
    at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:616)
    at io.netty.util.concurrent.DefaultPromise.setFailure0(DefaultPromise.java:609)
    at io.netty.util.concurrent.DefaultPromise.setFailure(DefaultPromise.java:109)
    at io.netty.resolver.InetSocketAddressResolver$1.operationComplete(InetSocketAddressResolver.java:62)
    at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:578)
    at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:571)
    at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:550)
    at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:491)
    at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:616)
    at io.netty.util.concurrent.DefaultPromise.setFailure0(DefaultPromise.java:609)
    at io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:117)
    at io.netty.resolver.dns.DnsNameResolver.tryFailure(DnsNameResolver.java:936)
    at io.netty.resolver.dns.DnsNameResolver.access$500(DnsNameResolver.java:90)
    at io.netty.resolver.dns.DnsNameResolver$5.operationComplete(DnsNameResolver.java:956)
    at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:578)
    at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:552)
    at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:491)
    at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:616)
    at io.netty.util.concurrent.DefaultPromise.setFailure0(DefaultPromise.java:609)
    at io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:117)
    at io.netty.resolver.dns.DnsResolveContext.finishResolve(DnsResolveContext.java:1021)
    at io.netty.resolver.dns.DnsResolveContext.tryToFinishResolve(DnsResolveContext.java:966)
    at io.netty.resolver.dns.DnsResolveContext.query(DnsResolveContext.java:414)
    at io.netty.resolver.dns.DnsResolveContext.access$600(DnsResolveContext.java:63)
    at io.netty.resolver.dns.DnsResolveContext$2.operationComplete(DnsResolveContext.java:463)
    at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:578)
    at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:571)
    at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:550)
    at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:491)
    at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:616)
    at io.netty.util.concurrent.DefaultPromise.setFailure0(DefaultPromise.java:609)
    at io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:117)
    at io.netty.resolver.dns.DnsQueryContext.tryFailure(DnsQueryContext.java:225)
    at io.netty.resolver.dns.DnsQueryContext$4.run(DnsQueryContext.java:177)
    at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)
    at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170)
    at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: java.net.UnknownHostException: failed to resolve 'xxxxxxxx' after 6 queries
    at io.netty.resolver.dns.DnsResolveContext.finishResolve(DnsResolveContext.java:1013)
    ... 22 common frames omitted
Caused by: io.netty.resolver.dns.DnsNameResolverTimeoutException: [/x.x.x.x:53] query via UDP timed out after 5000 milliseconds (no stack trace available)

2021-01-21 12:01:25.199  WARN 9396 --- [ctor-http-nio-4] s.o.c.webclient.iolog.WiretapConnector   : No match for Log-Request-Id=[4ca57941]
2021-01-21 12:01:25.199 DEBUG 9396 --- [ctor-http-nio-4] somelogger                               : DefaultDnsQuestion(xxxxxxxx. IN AAAA) query never written and failed

io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No name servers returned an answer
    at io.netty.resolver.dns.DnsResolveContext.tryToFinishResolve(..)(Unknown Source)

On Docker container using adoptopenjdk:11.0.7_10-jre-hotspot - TEST KO for public Internet endpoint

{"@timestamp":"2021-01-21T14:16:14.922+01:00","@version":"1","message":"from /x.x.x.x:53 : DefaultDnsQuestion(api.ouibus-acc.cloud.sqills.com.vsp.svc.cluster.local. IN A) failure","log
ger_name":"somelogger","thread_name":"reactor-http-epoll-2","level":"DEBUG","level_value":10000,"stack_trace":"io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No answe
r found and NXDOMAIN response code returned\n\tat io.netty.resolver.dns.DnsResolveContext.onResponse(..)(Unknown Source)\n"}
{"@timestamp":"2021-01-21T14:16:14.922+01:00","@version":"1","message":"DefaultDnsQuestion(api.ouibus-acc.cloud.sqills.com.vsp.svc.cluster.local. IN A) query never written and failed","lo
gger_name":"somelogger","thread_name":"reactor-http-epoll-2","level":"DEBUG","level_value":10000,"stack_trace":"io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No name
 servers returned an answer\n\tat io.netty.resolver.dns.DnsResolveContext.tryToFinishResolve(..)(Unknown Source)\n"}
{"@timestamp":"2021-01-21T14:16:15.013+01:00","@version":"1","message":"from /x.x.x.x:53 : DefaultDnsQuestion(api.ouibus-acc.cloud.sqills.com.vsp.svc.cluster.local. IN CNAME) failure",
"logger_name":"somelogger","thread_name":"reactor-http-epoll-2","level":"DEBUG","level_value":10000,"stack_trace":"io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No a
nswer found and NXDOMAIN response code returned\n\tat io.netty.resolver.dns.DnsResolveContext.onResponse(..)(Unknown Source)\n"}
{"@timestamp":"2021-01-21T14:16:15.013+01:00","@version":"1","message":"DefaultDnsQuestion(api.ouibus-acc.cloud.sqills.com.vsp.svc.cluster.local. IN CNAME) query never written and failed"
,"logger_name":"somelogger","thread_name":"reactor-http-epoll-2","level":"DEBUG","level_value":10000,"stack_trace":"io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No
name servers returned an answer\n\tat io.netty.resolver.dns.DnsResolveContext.tryToFinishResolve(..)(Unknown Source)\n"}
{"@timestamp":"2021-01-21T14:16:15.014+01:00","@version":"1","message":"from /x.x.x.x:53 : DefaultDnsQuestion(api.ouibus-acc.cloud.sqills.com.svc.cluster.local. IN A) failure","logger_
name":"somelogger","thread_name":"reactor-http-epoll-2","level":"DEBUG","level_value":10000,"stack_trace":"io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No answer fo
und and NXDOMAIN response code returned\n\tat io.netty.resolver.dns.DnsResolveContext.onResponse(..)(Unknown Source)\n"}
{"@timestamp":"2021-01-21T14:16:15.014+01:00","@version":"1","message":"DefaultDnsQuestion(api.ouibus-acc.cloud.sqills.com.svc.cluster.local. IN A) query never written and failed","logger
_name":"somelogger","thread_name":"reactor-http-epoll-2","level":"DEBUG","level_value":10000,"stack_trace":"io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No name ser
vers returned an answer\n\tat io.netty.resolver.dns.DnsResolveContext.tryToFinishResolve(..)(Unknown Source)\n"}
{"@timestamp":"2021-01-21T14:16:15.015+01:00","@version":"1","message":"from /x.x.x.x:53 : DefaultDnsQuestion(api.ouibus-acc.cloud.sqills.com.svc.cluster.local. IN CNAME) failure","log
ger_name":"somelogger","thread_name":"reactor-http-epoll-2","level":"DEBUG","level_value":10000,"stack_trace":"io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No answe
r found and NXDOMAIN response code returned\n\tat io.netty.resolver.dns.DnsResolveContext.onResponse(..)(Unknown Source)\n"}
{"@timestamp":"2021-01-21T14:16:15.015+01:00","@version":"1","message":"DefaultDnsQuestion(api.ouibus-acc.cloud.sqills.com.svc.cluster.local. IN CNAME) query never written and failed","lo
gger_name":"somelogger","thread_name":"reactor-http-epoll-2","level":"DEBUG","level_value":10000,"stack_trace":"io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No name
 servers returned an answer\n\tat io.netty.resolver.dns.DnsResolveContext.tryToFinishResolve(..)(Unknown Source)\n"}
{"@timestamp":"2021-01-21T14:16:15.015+01:00","@version":"1","message":"from /x.x.x.x:53 : DefaultDnsQuestion(api.ouibus-acc.cloud.sqills.com.cluster.local. IN A) failure","logger_name
":"somelogger","thread_name":"reactor-http-epoll-2","level":"DEBUG","level_value":10000,"stack_trace":"io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No answer found
and NXDOMAIN response code returned\n\tat io.netty.resolver.dns.DnsResolveContext.onResponse(..)(Unknown Source)\n"}
{"@timestamp":"2021-01-21T14:16:15.015+01:00","@version":"1","message":"DefaultDnsQuestion(api.ouibus-acc.cloud.sqills.com.cluster.local. IN A) query never written and failed","logger_nam
e":"somelogger","thread_name":"reactor-http-epoll-2","level":"DEBUG","level_value":10000,"stack_trace":"io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No name servers
 returned an answer\n\tat io.netty.resolver.dns.DnsResolveContext.tryToFinishResolve(..)(Unknown Source)\n"}
{"@timestamp":"2021-01-21T14:16:15.016+01:00","@version":"1","message":"from /x.x.x.x:53 : DefaultDnsQuestion(api.ouibus-acc.cloud.sqills.com.cluster.local. IN CNAME) failure","logger_
name":"somelogger","thread_name":"reactor-http-epoll-2","level":"DEBUG","level_value":10000,"stack_trace":"io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No answer fo
und and NXDOMAIN response code returned\n\tat io.netty.resolver.dns.DnsResolveContext.onResponse(..)(Unknown Source)\n"}
{"@timestamp":"2021-01-21T14:16:15.016+01:00","@version":"1","message":"DefaultDnsQuestion(api.ouibus-acc.cloud.sqills.com.cluster.local. IN CNAME) query never written and failed","logger
_name":"somelogger","thread_name":"reactor-http-epoll-2","level":"DEBUG","level_value":10000,"stack_trace":"io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No name ser
vers returned an answer\n\tat io.netty.resolver.dns.DnsResolveContext.tryToFinishResolve(..)(Unknown Source)\n"}
{"@timestamp":"2021-01-21T14:16:15.017+01:00","@version":"1","message":"from /x.x.x.x:53 : DefaultDnsQuestion(api.ouibus-acc.cloud.sqills.com.socrate.vsct.fr. IN A) failure","logger_na
me":"somelogger","thread_name":"reactor-http-epoll-2","level":"DEBUG","level_value":10000,"stack_trace":"io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No answer foun
d and NXDOMAIN response code returned\n\tat io.netty.resolver.dns.DnsResolveContext.onResponse(..)(Unknown Source)\n"}
{"@timestamp":"2021-01-21T14:16:15.017+01:00","@version":"1","message":"DefaultDnsQuestion(api.ouibus-acc.cloud.sqills.com.socrate.vsct.fr. IN A) query never written and failed","logger_n
ame":"somelogger","thread_name":"reactor-http-epoll-2","level":"DEBUG","level_value":10000,"stack_trace":"io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No name serve
rs returned an answer\n\tat io.netty.resolver.dns.DnsResolveContext.tryToFinishResolve(..)(Unknown Source)\n"}
{"@timestamp":"2021-01-21T14:16:15.017+01:00","@version":"1","message":"from /x.x.x.x:53 : DefaultDnsQuestion(api.ouibus-acc.cloud.sqills.com.socrate.vsct.fr. IN CNAME) failure","logge
r_name":"somelogger","thread_name":"reactor-http-epoll-2","level":"DEBUG","level_value":10000,"stack_trace":"io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No answer
found and NXDOMAIN response code returned\n\tat io.netty.resolver.dns.DnsResolveContext.onResponse(..)(Unknown Source)\n"}
{"@timestamp":"2021-01-21T14:16:15.018+01:00","@version":"1","message":"DefaultDnsQuestion(api.ouibus-acc.cloud.sqills.com.socrate.vsct.fr. IN CNAME) query never written and failed","logg
er_name":"somelogger","thread_name":"reactor-http-epoll-2","level":"DEBUG","level_value":10000,"stack_trace":"io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No name s
ervers returned an answer\n\tat io.netty.resolver.dns.DnsResolveContext.tryToFinishResolve(..)(Unknown Source)\n"}
{"@timestamp":"2021-01-21T14:16:15.018+01:00","@version":"1","message":"DefaultDnsQuestion(api.ouibus-acc.cloud.sqills.com.socrate.vsct.fr. IN CNAME) query never written and failed","logg
er_name":"somelogger","thread_name":"reactor-http-epoll-2","level":"DEBUG","level_value":10000,"stack_trace":"io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No name s
ervers returned an answer\n\tat io.netty.resolver.dns.DnsResolveContext.tryToFinishResolve(..)(Unknown Source)\n"}
{"@timestamp":"2021-01-21T14:16:15.019+01:00","@version":"1","message":"from /x.x.x.x:53 : DefaultDnsQuestion(api.ouibus-acc.cloud.sqills.com. IN A) no answer ServFail(2)","logger_name
":"somelogger","thread_name":"reactor-http-epoll-2","level":"DEBUG","level_value":10000}
{"@timestamp":"2021-01-21T14:16:15.019+01:00","@version":"1","message":"from /x.x.x.x:53 : DefaultDnsQuestion(api.ouibus-acc.cloud.sqills.com. IN A) failure","logger_name":"somelogger"
,"thread_name":"reactor-http-epoll-2","level":"DEBUG","level_value":10000,"stack_trace":"io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No name servers returned an an
swer\n\tat io.netty.resolver.dns.DnsResolveContext.tryToFinishResolve(..)(Unknown Source)\n"}
{"@timestamp":"2021-01-21T14:16:15.020+01:00","@version":"1","message":"from /x.x.x.x:53 : DefaultDnsQuestion(api.ouibus-acc.cloud.sqills.com. IN CNAME) no answer ServFail(2)","logger_
name":"somelogger","thread_name":"reactor-http-epoll-2","level":"DEBUG","level_value":10000}
{"@timestamp":"2021-01-21T14:16:15.020+01:00","@version":"1","message":"from /x.x.x.x:53 : DefaultDnsQuestion(api.ouibus-acc.cloud.sqills.com. IN CNAME) failure","logger_name":"somelog
ger","thread_name":"reactor-http-epoll-2","level":"DEBUG","level_value":10000,"stack_trace":"io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No name servers returned a
n answer\n\tat io.netty.resolver.dns.DnsResolveContext.tryToFinishResolve(..)(Unknown Source)\n"}
{"@timestamp":"2021-01-21T14:16:15.113+01:00","@version":"1","message":"","logger_name":"LOGGER_STACK","thread_name":"reactor-http-epoll-2","level":"ERROR","level_value":40000,"avro":{"ti
mestamp8601": "2021-01-21T14:16:15.113+0100", "correlationId": "", "requestId": "", "version": "1.148.0-SNAPSHOT", "instance": "cart-services-cart-2895-default-dns", "logMessage": "Error
with HTTP request", "exceptionToString": "org.springframework.web.reactive.function.client.WebClientRequestException: failed to resolve 'api.ouibus-acc.cloud.sqills.com' after 2 queries ;
 nested exception is java.net.UnknownHostException: failed to resolve 'api.ouibus-acc.cloud.sqills.com' after 2 queries", "stack1stLine": "org.springframework.web.reactive.function.client
.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:137)", "causeException": "java.net.UnknownHostException: failed to resolve 'api.ouibus-acc.cloud.s
qills.com' after 2 queries ", "causeStack1stLine": "io.netty.resolver.dns.DnsResolveContext.finishResolve(DnsResolveContext.java:1013)", "fullStack": "org.springframework.web.reactive.fun
ction.client.WebClientRequestException: failed to resolve 'api.ouibus-acc.cloud.sqills.com' after 2 queries ; nested exception is java.net.UnknownHostException: failed to resolve 'api.oui
bus-acc.cloud.sqills.com' after 2 queries \n\tat org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:1
37)\n\tat reactor.core.publisher.MonoErrorSupplied.subscribe(MonoErrorSupplied.java:70)\n\tat reactor.core.publisher.Mono.subscribe(Mono.java:4046)\n\tat reactor.core.publisher.FluxOnErro
rResume$ResumeSubscriber.onError(FluxOnErrorResume.java:103)\n\tat reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:221)\n\tat reactor.core.publisher.FluxPeek$PeekSubs
criber.onError(FluxPeek.java:221)\n\tat reactor.core.publisher.FluxMap$MapSubscriber.onError(FluxMap.java:132)\n\tat reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:2
21)\n\tat reactor.core.publisher.MonoNext$NextSubscriber.onError(MonoNext.java:93)\n\tat reactor.core.publisher.MonoFlatMapMany$FlatMapManyMain.onError(MonoFlatMapMany.java:204)\n\tat rea
ctor.core.publisher.SerializedSubscriber.onError(SerializedSubscriber.java:124)\n\tat reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.whenError(FluxRetryWhen.java:224)\n\tat
reactor.core.publisher.FluxRetryWhen$RetryWhenOtherSubscriber.onError(FluxRetryWhen.java:273)\n\tat reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.drain(FluxConcatMap.java:413)\n
\tat reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.onNext(FluxConcatMap.java:250)\n\tat reactor.core.publisher.EmitterProcessor.drain(EmitterProcessor.java:491)\n\tat reactor.co
re.publisher.EmitterProcessor.tryEmitNext(EmitterProcessor.java:299)\n\tat reactor.core.publisher.SinkManySerialized.tryEmitNext(SinkManySerialized.java:97)\n\tat reactor.core.publisher.I
nternalManySink.emitNext(InternalManySink.java:27)\n\tat reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.onError(FluxRetryWhen.java:189)\n\tat reactor.core.publisher.MonoCrea
te$DefaultMonoSink.error(Mon

Thank you for the help.

fouser-attention typbug

Source

rschlick

👍2

All 48 comments

@rschlick As you can reproduce that, are you able to test this scenario with Java >= 15?

violetagg on 12 Mar 2021

violetagg on 15 Mar 2021

Thank you @violetagg for your help.
I understand better why you propose me to try with JDK 15..
I was not able to try already, but it's on my short todo list.

rschlick on 15 Mar 2021

👍1

Hello @violetagg

I have try OpenJdk 15. It's working now on my local Windows 10 machine.
But I still have some issue running in Docker container (using adoptopenjdk:15.0.2_7-jre-hotspot image) on EKS AWS.
I don't have DNS error now, but I have timeout exception.
With previous version of Nett Reactor, I don't have errors.
I have configured a proxy.
Here is my configuration of WebClient:

HttpClient httpClient =
                HttpClient.create(resourceFactory.getConnectionProvider())
                        .runOn(resourceFactory.getLoopResources())
                        .option(CONNECT_TIMEOUT_MILLIS, (int) connectionTimeout.toMillis())
                        .doOnConnected((connection) -> connection.addHandlerLast(new ReadTimeoutHandler(readTimeout.toMillis(), MILLISECONDS)));

        if (needsProxy()) {
            httpClient.proxy(createProxyOptions());
        }

        return httpClient;
    }


    private boolean needsProxy() {
        return StringUtils.isNotBlank(proxyHost);
    }

    private Consumer<? super ProxyProvider.TypeSpec> createProxyOptions() {
        return proxySpec -> proxySpec
                .type(ProxyProvider.Proxy.HTTP)
                .host(proxyHost)
                .port(proxyPort);
    }

Here is the stacktrace error :

org.springframework.web.reactive.function.client.WebClientRequestException: connection timed out: api.ouibus-acc.cloud.sqills.com/35.157.49.81:443; nested exception is io.netty.channel.ConnectTimeoutException: connection timed out: api.ouibus-acc.cloud.sqills.com/35.157.49.81:443\n\t
at org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:137)\n\t
at reactor.core.publisher.MonoErrorSupplied.subscribe(MonoErrorSupplied.java:70)\n\t
at reactor.core.publisher.Mono.subscribe(Mono.java:4046)\n\t
at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:103)\n\t
at reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:221)\n\t
at reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:221)\n\t
at reactor.core.publisher.FluxMap$MapSubscriber.onError(FluxMap.java:132)\n\t
at reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:221)\n\t
at reactor.core.publisher.MonoNext$NextSubscriber.onError(MonoNext.java:93)\n\t
at reactor.core.publisher.MonoFlatMapMany$FlatMapManyMain.onError(MonoFlatMapMany.java:204)\n\t
at reactor.core.publisher.SerializedSubscriber.onError(SerializedSubscriber.java:124)\n\t
at reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.whenError(FluxRetryWhen.java:224)\n\t
at reactor.core.publisher.FluxRetryWhen$RetryWhenOtherSubscriber.onError(FluxRetryWhen.java:273)\n\t
at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onError(FluxContextWrite.java:121)\n\t
at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.drain(FluxConcatMap.java:413)\n\t
at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.onNext(FluxConcatMap.java:250)\n\t
at reactor.core.publisher.EmitterProcessor.drain(EmitterProcessor.java:491)\n\t
at reactor.core.publisher.EmitterProcessor.tryEmitNext(EmitterProcessor.java:299)\n\t
at reactor.core.publisher.SinkManySerialized.tryEmitNext(SinkManySerialized.java:97)\n\t
at reactor.core.publisher.InternalManySink.emitNext(InternalManySink.java:27)\n\t
at reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.onError(FluxRetryWhen.java:189)\n\t
at reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:189)\n\t
at reactor.netty.http.client.HttpClientConnect$MonoHttpConnect$ClientTransportSubscriber.onError(HttpClientConnect.java:306)\n\t
at reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:189)\n\t
at reactor.netty.resources.DefaultPooledConnectionProvider$DisposableAcquire.onError(DefaultPooledConnectionProvider.java:166)\n\t
at reactor.netty.internal.shaded.reactor.pool.AbstractPool$Borrower.fail(AbstractPool.java:427)\n\t
at reactor.netty.internal.shaded.reactor.pool.SimpleDequePool.lambda$drainLoop$5(SimpleDequePool.java:309)\n\t
at reactor.core.publisher.FluxDoOnEach$DoOnEachSubscriber.onError(FluxDoOnEach.java:186)\n\t
at reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:189)\n\t
at reactor.netty.resources.DefaultPooledConnectionProvider$PooledConnectionAllocator$PooledConnectionInitializer.onError(DefaultPooledConnectionProvider.java:565)\n\t
at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondError(MonoFlatMap.java:192)\n\t
at reactor.core.publisher.MonoFlatMap$FlatMapInner.onError(MonoFlatMap.java:259)\n\t
at reactor.netty.transport.TransportConnector$MonoChannelPromise.tryFailure(TransportConnector.java:464)\n\t
at reactor.netty.transport.TransportConnector$MonoChannelPromise$1.tryFailure(TransportConnector.java:515)\n\t
at io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe$2.run(AbstractEpollChannel.java:577)\n\t
at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)\n\t
at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170)\n\t
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)\n\t
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)\n\t
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)\n\t
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)\n\t
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)\n\t
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\t
at java.base/java.lang.Thread.run(Unknown Source)\n
Caused by: io.netty.channel.ConnectTimeoutException: connection timed out: api.ouibus-acc.cloud.sqills.com/35.157.49.81:443\n\t
at io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe$2.run(AbstractEpollChannel.java:576)\n\t... 9 more\n"}

rschlick on 17 Mar 2021

@rschlick Just to check my understanding: on Windows with java < 15 you see the issue and with java >= 15 everything is OK. Is that correct?

About Docker container, do you think I can reproduce it somehow?

violetagg on 17 Mar 2021

@rschlick Mmmm, actually you may need to configure Proxy timeout.
Please check this documentation:
https://projectreactor.io/docs/netty/release/reference/index.html#_timeout_configuration

violetagg on 17 Mar 2021

@violetagg I will try a solution with proxy timeout configuration. Thank you.
I will try again on Windows with JDK 11 to be sure it was the issue in this environment.

rschlick on 17 Mar 2021

@violetagg After verification :
On local machine windows 10, I still have some issues even with JDK 15.
But, it's seems working with :
.resolver(DefaultAddressResolverGroup.INSTANCE)

But on docker container adoptopenjdk:15.0.2_7-jre-hotspot, I still have a timeout error..

Do you know an easy way to migrate to Spring Boot 2.4.x including previous pom/bom version of Netty Reactor ?

rschlick on 17 Mar 2021

Spring Boot 2.4.x uses Reactor 2020.0.x (Reactor Netty 1.0.x)
Spring Boot 2.3.x and 2.2.x use Reactor Dysprosium (Reactor Netty 0.9.x)

violetagg on 18 Mar 2021

@violetagg So Spring boot 2.4.x is not compatible with Reactor Dysprosium (Reactor Netty 0.9.x) ?

rschlick on 18 Mar 2021

@violetagg So Spring boot 2.4.x is not compatible with Reactor Dysprosium (Reactor Netty 0.9.x) ?

violetagg on 18 Mar 2021

@rschlick Please use .resolver(DefaultAddressResolverGroup.INSTANCE) while investigating this issue.

violetagg on 24 Mar 2021

I confirm It is broken on windows and windows containers (nanoserver) with spring version 2.4.x, I rolled back to 2.3.9.
I am using consul as a discovery server and spring cloud gateway. During dev I found a workaroung adding my hostname to 127.0.0.1 in windows host file (c/windows/system32/drivers/etc/host) but that is not suitable for production (docker windows nanoservers)

@violetagg I tried with java 15, it does not work, same issue.

broadside74 on 30 Mar 2021

@violetagg I have tried also with .resolver(DefaultAddressResolverGroup.INSTANCE)
@broadside74 "Glad" to know I'm not the only one. And, I hope it will be fixed, but we are stuck to upgrade to Spring Boot 2.4

rschlick on 30 Mar 2021

@broadside74 Any chance to guide us how to reproduce this? With the workaround above you should be able to upgrade to Spring Boot 2.4 or the workaround also is not working?

violetagg on 30 Mar 2021

@violetagg I have tried also with .resolver(DefaultAddressResolverGroup.INSTANCE)
@broadside74 "Glad" to know I'm not the only one. And, I hope it will be fixed, but we are stuck to upgrade to Spring Boot 2.4

@rschlick Do you mean that the workaround is also not working and thus you cannot upgrade to Spring Boot 2.4?

violetagg on 30 Mar 2021

@violetagg I have found no workaround :(

rschlick on 30 Mar 2021

@broadside74 Any chance to guide us how to reproduce this? With the workaround above you should be able to upgrade to Spring Boot 2.4 or the workaround also is not working?

@violetagg I reproduced the problem here https://github.com/broadside74/reactor-netty-dns-problem

broadside74 on 30 Mar 2021

It seems this code did the trick


@Bean
HttpClient httpClient(){
    return HttpClient.create().resolver(DefaultAddressResolverGroup.INSTANCE);
}

Lets see if I have the timeout problem, i'll come back to you

broadside74 on 30 Mar 2021

Maybe the workaround for the DNS problem is working for me. But I still have some timeout errors.
I pass through a proxy I have configured like this ->

private HttpClient createHttpClient() {
        HttpClient httpClient =
                HttpClient.create(resourceFactory.getConnectionProvider())
                        .resolver(DefaultAddressResolverGroup.INSTANCE)
                        .runOn(resourceFactory.getLoopResources())
                        .option(CONNECT_TIMEOUT_MILLIS, (int) connectionTimeout.toMillis())
                        .doOnConnected((connection) -> connection.addHandlerLast(new ReadTimeoutHandler(readTimeout.toMillis(), MILLISECONDS)));

            httpClient.proxy(createProxyOptions());


        return httpClient;
    }

    private Consumer<? super ProxyProvider.TypeSpec> createProxyOptions() {
        return proxySpec -> proxySpec
                .type(ProxyProvider.Proxy.HTTP)
                .host(proxyHost)
                .port(proxyPort)
                .connectTimeoutMillis(10_000);
    }

rschlick on 31 Mar 2021

@rschlick Please capture the traffic with Wireshark and share it.

violetagg on 2 Apr 2021

@broadside74 I created an issue for Netty project - https://github.com/netty/netty/issues/11142

violetagg on 7 Apr 2021

👍1

Hi @violetagg,
On my local dev machine with Windows 10, it's working with the workaround DefaultAddressResolverGroup.INSTANCE.
But, still some issues in the linux container. DNS resolution problem is gone, but I still have timeout issues (passing by a proxy)
I can't use Wireshark on the container I guess ?
Is it possible to debug this timeout problem ?

rschlick on 7 Apr 2021

@rschlick is there a way to check the connectivity from the container to the proxy?

violetagg on 7 Apr 2021

HTTP_PROXY and HTTPS_PROXY are set in the variable's environment.
Using curl, I have verified that the queries are passing through the proxy and I'm able to get an answer from the webservice.

With the WebClient, I have implemented that :

    private Consumer<? super ProxyProvider.TypeSpec> createProxyOptions() {
        return proxySpec -> proxySpec
                .type(ProxyProvider.Proxy.HTTP)
                .host(proxyHost)
                .port(proxyPort)
                .connectTimeoutMillis(10_000);
    }

With previous version on Netty, we were configurating the proxy on TCPClient level :

TcpClient tcpClient = TcpClient.create(resourceFactory.getConnectionProvider());

        if (needsProxy()) {
            tcpClient = tcpClient.proxy(createProxyOptions());
        }

It's possible to debug WebClient to be sure he is passing through the proxy ?

rschlick on 7 Apr 2021

@rschlick If you are able to debug it than try to check this class https://github.com/netty/netty/blob/4.1/handler-proxy/src/main/java/io/netty/handler/proxy/HttpProxyHandler.java

violetagg on 7 Apr 2021

@rschlick Additional things that you may check: whether you need usr/pass or some special headers for the proxied connection. Does the proxy support CONNECT method as the Netty's HttpProxyHandler uses CONNECT.

violetagg on 8 Apr 2021

@violetagg The proxy configuration is just an url/port. And, with the same proxy configuration with previous version of Netty Reactor we don't have problem.
We have a Squid proxy, so I guess it's accepting CONNECT method.
I was not have time to debug in the container environment..

rschlick on 8 Apr 2021

@rschlick Last time I checked the Squid proxy, there was a configuration for CONNECT method, see this issue comment https://github.com/reactor/reactor-netty/issues/617#issuecomment-467182121

violetagg on 21 Apr 2021

@rschlick Were you able to check Squid's configuration for CONNECT method?

violetagg on 26 Apr 2021

@violetagg Yes, I have check the Squid config and look at the logs.
The CONNECT method is well accepted by the Squid proxy and the request is returning HTTP 200.
But, I still have a timeout exception from the WebClient.
With the same code and same environment with previous version of Netty Reactor all queries are OK.

The squid log :

{
  "_index": "squid-rollover-000113",
  "_type": "my_type",
  "_id": "ZdSNEnkB3Urw0a1C4C8z",
  "_version": 1,
  "_score": null,
  "_source": {
    "@timestamp": "2021-04-27T08:59:18.194Z",
    "clientip": "100.89.14.143",
    "ident": "-",
    "uname": "-",
    "timestamp": "27/Apr/2021:10:59:18 +0200",
    "verb": "CONNECT",
    "request": "api.ouibus-acc.cloud.sqills.com:443",
    "httpversion": "HTTP/1.1",
    "response": 200,
    "bytes": 23085,
    "referer": "-",
    "agent": "Apache-HttpClient/4.5.13 (Java/11.0.8)",
    "request_status": "TCP_TUNNEL",
    "hierarchy_status": "HIER_DIRECT",
    "response_time": 174369,
    "dnslookup_time": 12,
    "request_size": 13409,
    "reply_size": 23085,
    "peer_response_time": 60030,
    "total_time": 174356,
    "err_code": "-",
    "err_detail": "-",
    "az": "eu-west-3b",
    "ec2_instance_id": "XXXXXX",
    "ec2_instance_type": "t3.small",
    "private_ip": "XXXXXXX",
    "vpc_id": "vpc-XXXXXX",
    "ami_id": "XXXXX",
    "account_id": "XXXXXX",
    "hostname": "XXXXXX.eu-west-3.compute.internal"
  },
  "fields": {
    "@timestamp": [
      "2021-04-27T08:59:18.194Z"
    ]
  },
  "highlight": {
    "verb.keyword": [
      "@kibana-highlighted-field@CONNECT@/kibana-highlighted-field@"
    ],
    "request.keyword": [
      "@[email protected]:443@/kibana-highlighted-field@"
    ]
  },
  "sort": [
    1619513958194
  ]
}

rschlick on 27 Apr 2021

@rschlick Then I'll need some reproducible example for further investigation.

violetagg on 27 Apr 2021

@violetagg I don't know how I could provide a reproducible example.
The containers are running in an EKS AWS environment with specific AWS architecture of my company...

rschlick on 28 Apr 2021

@rschlick When you are on Linux can you check with nslookup the DNS server that resolves the IP and the same for Reactor Netty, which is the server used for the resolution?

violetagg on 10 May 2021

Update: Two issues were found related only to Windows OS

https://github.com/netty/netty/issues/9796 - Fixed with Java >= 15
https://github.com/netty/netty/issues/11142 - Fixed with Netty 4.1.64.Final

violetagg on 17 May 2021

@violetagg Thank you for the updates.
I was run the nslookup in command line. How I can know the DNS server used by Reactor Netty ?

rschlick on 18 May 2021

When I do a curl on the host, it's passing through the squid proxy successfully :

userapp@cart-services-cart-2895-spring-deprecated-6c46fc4cc9-hqx8m:/application$ curl -I partner.magroup-webservice.com
HTTP/1.1 200 OK
Date: Tue, 18 May 2021 15:17:43 GMT
Server: Apache
Last-Modified: Thu, 02 Jun 2016 11:45:06 GMT
ETag: "fd-5344a233c7296"
Accept-Ranges: bytes
Content-Length: 253
Vary: Accept-Encoding
P3P: CP= CAO DSP COR CURa ADMa DEVa OUR IND PHY ONL UNI COM NAV INT DEM PRE
Content-Type: text/html
Age: 21
X-Cache: HIT from ip-xxxxxxxxx.eu-west-3.compute.internal
X-Cache-Lookup: HIT from ip-xxxxxxxxx.eu-west-3.compute.internal:3128
Via: 1.1 ip-xxxxxxxxxxx.eu-west-3.compute.internal (squid)
Connection: keep-alive

nslookup seems to be fine too :

userapp@cart-services-cart-2895-spring-deprecated-6c46fc4cc9-hqx8m:/application$ nslookup partner.magroup-webservice.com
Server:         172.20.0.10
Address:        172.20.0.10#53

Non-authoritative answer:
Name:   partner.magroup-webservice.com
Address: 62.23.205.223

When I look the logs of Squid Proxy, it's a CONNECT 200 OK. But, still webclient is throwing a timeout exception.
When I rollback to previous WebClient/Netty version using TcpClient.create() (instead of HttpClient.create()) I don't have this timeout exception.

rschlick on 18 May 2021

@rschlick Please enable io.netty=debug and look for logs from io.netty.resolver.dns

violetagg on 18 May 2021

@violetagg How to enable the log debug ?
Like that ?

HttpClient.create(resourceFactory.getConnectionProvider())
                        .resolver(DefaultAddressResolverGroup.INSTANCE)
                        .resolver(spec -> spec.trace("somelogger", LogLevel.DEBUG))

I was tried but I don't have any debug logs.

rschlick on 19 May 2021

@rschlick If you are using Spring Boot - in application.properties add logging.level.io.netty=debug

violetagg on 19 May 2021

@violetagg Yes, I use Spring Boot. I did the configuration, but I don't see so much more logs.
For example, I have these logs :

{"@timestamp":"2021-05-19T14:53:43.349+02:00","@version":"1","message":"-Dio.netty.allocator.numHeapArenas: 1","logger_name":"io.netty.buffer.PooledByteBufAllocator","thread_name":"http-nio-8080-exec-54","level":"DEBUG","level_value":10000,"x-client-app-id":"VSD","instana.trace.id":"6b769f0aaffe21d9","AVRO_LOG_HELPER_MDC_KEY_CORRELATION_ID":"07ec9833-d206-4918-9b5f-308cc2abf225","SUMON_AUDITED_PARENT_SERVICE":"BookProposalController","channel":"web","locale":"fr_FR","SUMON_AUDITED_PARENT_METHOD":"bookProposalV2","AVRO_LOG_HELPER_MDC_KEY_REQUEST_ID":"YKUKTk3X6Y-0vWPMNSH2KwAAAO0"}
{"@timestamp":"2021-05-19T14:53:43.349+02:00","@version":"1","message":"-Dio.netty.allocator.numDirectArenas: 1","logger_name":"io.netty.buffer.PooledByteBufAllocator","thread_name":"http-nio-8080-exec-54","level":"DEBUG","level_value":10000,"x-client-app-id":"VSD","instana.trace.id":"6b769f0aaffe21d9","AVRO_LOG_HELPER_MDC_KEY_CORRELATION_ID":"07ec9833-d206-4918-9b5f-308cc2abf225","SUMON_AUDITED_PARENT_SERVICE":"BookProposalController","channel":"web","locale":"fr_FR","SUMON_AUDITED_PARENT_METHOD":"bookProposalV2","AVRO_LOG_HELPER_MDC_KEY_REQUEST_ID":"YKUKTk3X6Y-0vWPMNSH2KwAAAO0"}
{"@timestamp":"2021-05-19T14:53:43.349+02:00","@version":"1","message":"-Dio.netty.allocator.pageSize: 8192","logger_name":"io.netty.buffer.PooledByteBufAllocator","thread_name":"http-nio-8080-exec-54","level":"DEBUG","level_value":10000,"x-client-app-id":"VSD","instana.trace.id":"6b769f0aaffe21d9","AVRO_LOG_HELPER_MDC_KEY_CORRELATION_ID":"07ec9833-d206-4918-9b5f-308cc2abf225","SUMON_AUDITED_PARENT_SERVICE":"BookProposalController","channel":"web","locale":"fr_FR","SUMON_AUDITED_PARENT_METHOD":"bookProposalV2","AVRO_LOG_HELPER_MDC_KEY_REQUEST_ID":"YKUKTk3X6Y-0vWPMNSH2KwAAAO0"}
{"@timestamp":"2021-05-19T14:53:43.349+02:00","@version":"1","message":"-Dio.netty.allocator.maxOrder: 11","logger_name":"io.netty.buffer.PooledByteBufAllocator","thread_name":"http-nio-8080-exec-54","level":"DEBUG","level_value":10000,"x-client-app-id":"VSD","instana.trace.id":"6b769f0aaffe21d9","AVRO_LOG_HELPER_MDC_KEY_CORRELATION_ID":"07ec9833-d206-4918-9b5f-308cc2abf225","SUMON_AUDITED_PARENT_SERVICE":"BookProposalController","channel":"web","locale":"fr_FR","SUMON_AUDITED_PARENT_METHOD":"bookProposalV2","AVRO_LOG_HELPER_MDC_KEY_REQUEST_ID":"YKUKTk3X6Y-0vWPMNSH2KwAAAO0"}
{"@timestamp":"2021-05-19T14:53:43.350+02:00","@version":"1","message":"-Dio.netty.allocator.chunkSize: 16777216","logger_name":"io.netty.buffer.PooledByteBufAllocator","thread_name":"http-nio-8080-exec-54","level":"DEBUG","level_value":10000,"x-client-app-id":"VSD","instana.trace.id":"6b769f0aaffe21d9","AVRO_LOG_HELPER_MDC_KEY_CORRELATION_ID":"07ec9833-d206-4918-9b5f-308cc2abf225","SUMON_AUDITED_PARENT_SERVICE":"BookProposalController","channel":"web","locale":"fr_FR","SUMON_AUDITED_PARENT_METHOD":"bookProposalV2","AVRO_LOG_HELPER_MDC_KEY_REQUEST_ID":"YKUKTk3X6Y-0vWPMNSH2KwAAAO0"}
{"@timestamp":"2021-05-19T14:53:43.350+02:00","@version":"1","message":"-Dio.netty.allocator.smallCacheSize: 256","logger_name":"io.netty.buffer.PooledByteBufAllocator","thread_name":"http-nio-8080-exec-54","level":"DEBUG","level_value":10000,"x-client-app-id":"VSD","instana.trace.id":"6b769f0aaffe21d9","AVRO_LOG_HELPER_MDC_KEY_CORRELATION_ID":"07ec9833-d206-4918-9b5f-308cc2abf225","SUMON_AUDITED_PARENT_SERVICE":"BookProposalController","channel":"web","locale":"fr_FR","SUMON_AUDITED_PARENT_METHOD":"bookProposalV2","AVRO_LOG_HELPER_MDC_KEY_REQUEST_ID":"YKUKTk3X6Y-0vWPMNSH2KwAAAO0"}
{"@timestamp":"2021-05-19T14:53:43.350+02:00","@version":"1","message":"-Dio.netty.allocator.normalCacheSize: 64","logger_name":"io.netty.buffer.PooledByteBufAllocator","thread_name":"http-nio-8080-exec-54","level":"DEBUG","level_value":10000,"x-client-app-id":"VSD","instana.trace.id":"6b769f0aaffe21d9","AVRO_LOG_HELPER_MDC_KEY_CORRELATION_ID":"07ec9833-d206-4918-9b5f-308cc2abf225","SUMON_AUDITED_PARENT_SERVICE":"BookProposalController","channel":"web","locale":"fr_FR","SUMON_AUDITED_PARENT_METHOD":"bookProposalV2","AVRO_LOG_HELPER_MDC_KEY_REQUEST_ID":"YKUKTk3X6Y-0vWPMNSH2KwAAAO0"}
{"@timestamp":"2021-05-19T14:53:43.350+02:00","@version":"1","message":"-Dio.netty.allocator.maxCachedBufferCapacity: 32768","logger_name":"io.netty.buffer.PooledByteBufAllocator","thread_name":"http-nio-8080-exec-54","level":"DEBUG","level_value":10000,"x-client-app-id":"VSD","instana.trace.id":"6b769f0aaffe21d9","AVRO_LOG_HELPER_MDC_KEY_CORRELATION_ID":"07ec9833-d206-4918-9b5f-308cc2abf225","SUMON_AUDITED_PARENT_SERVICE":"BookProposalController","channel":"web","locale":"fr_FR","SUMON_AUDITED_PARENT_METHOD":"bookProposalV2","AVRO_LOG_HELPER_MDC_KEY_REQUEST_ID":"YKUKTk3X6Y-0vWPMNSH2KwAAAO0"}
{"@timestamp":"2021-05-19T14:53:43.350+02:00","@version":"1","message":"-Dio.netty.allocator.cacheTrimInterval: 8192","logger_name":"io.netty.buffer.PooledByteBufAllocator","thread_name":"http-nio-8080-exec-54","level":"DEBUG","level_value":10000,"x-client-app-id":"VSD","instana.trace.id":"6b769f0aaffe21d9","AVRO_LOG_HELPER_MDC_KEY_CORRELATION_ID":"07ec9833-d206-4918-9b5f-308cc2abf225","SUMON_AUDITED_PARENT_SERVICE":"BookProposalController","channel":"web","locale":"fr_FR","SUMON_AUDITED_PARENT_METHOD":"bookProposalV2","AVRO_LOG_HELPER_MDC_KEY_REQUEST_ID":"YKUKTk3X6Y-0vWPMNSH2KwAAAO0"}
{"@timestamp":"2021-05-19T14:53:43.351+02:00","@version":"1","message":"-Dio.netty.allocator.cacheTrimIntervalMillis: 0","logger_name":"io.netty.buffer.PooledByteBufAllocator","thread_name":"http-nio-8080-exec-54","level":"DEBUG","level_value":10000,"x-client-app-id":"VSD","instana.trace.id":"6b769f0aaffe21d9","AVRO_LOG_HELPER_MDC_KEY_CORRELATION_ID":"07ec9833-d206-4918-9b5f-308cc2abf225","SUMON_AUDITED_PARENT_SERVICE":"BookProposalController","channel":"web","locale":"fr_FR","SUMON_AUDITED_PARENT_METHOD":"bookProposalV2","AVRO_LOG_HELPER_MDC_KEY_REQUEST_ID":"YKUKTk3X6Y-0vWPMNSH2KwAAAO0"}
{"@timestamp":"2021-05-19T14:53:43.351+02:00","@version":"1","message":"-Dio.netty.allocator.useCacheForAllThreads: true","logger_name":"io.netty.buffer.PooledByteBufAllocator","thread_name":"http-nio-8080-exec-54","level":"DEBUG","level_value":10000,"x-client-app-id":"VSD","instana.trace.id":"6b769f0aaffe21d9","AVRO_LOG_HELPER_MDC_KEY_CORRELATION_ID":"07ec9833-d206-4918-9b5f-308cc2abf225","SUMON_AUDITED_PARENT_SERVICE":"BookProposalController","channel":"web","locale":"fr_FR","SUMON_AUDITED_PARENT_METHOD":"bookProposalV2","AVRO_LOG_HELPER_MDC_KEY_REQUEST_ID":"YKUKTk3X6Y-0vWPMNSH2KwAAAO0"}
{"@timestamp":"2021-05-19T14:53:43.351+02:00","@version":"1","message":"-Dio.netty.allocator.maxCachedByteBuffersPerChunk: 1023","logger_name":"io.netty.buffer.PooledByteBufAllocator","thread_name":"http-nio-8080-exec-54","level":"DEBUG","level_value":10000,"x-client-app-id":"VSD","instana.trace.id":"6b769f0aaffe21d9","AVRO_LOG_HELPER_MDC_KEY_CORRELATION_ID":"07ec9833-d206-4918-9b5f-308cc2abf225","SUMON_AUDITED_PARENT_SERVICE":"BookProposalController","channel":"web","locale":"fr_FR","SUMON_AUDITED_PARENT_METHOD":"bookProposalV2","AVRO_LOG_HELPER_MDC_KEY_REQUEST_ID":"YKUKTk3X6Y-0vWPMNSH2KwAAAO0"}
{"@timestamp":"2021-05-19T14:53:43.543+02:00","@version":"1","message":"-Dio.netty.allocator.type: pooled","logger_name":"io.netty.buffer.ByteBufUtil","thread_name":"http-nio-8080-exec-54","level":"DEBUG","level_value":10000,"x-client-app-id":"VSD","instana.trace.id":"6b769f0aaffe21d9","AVRO_LOG_HELPER_MDC_KEY_CORRELATION_ID":"07ec9833-d206-4918-9b5f-308cc2abf225","SUMON_AUDITED_PARENT_SERVICE":"BookProposalController","channel":"web","locale":"fr_FR","SUMON_AUDITED_PARENT_METHOD":"bookProposalV2","AVRO_LOG_HELPER_MDC_KEY_REQUEST_ID":"YKUKTk3X6Y-0vWPMNSH2KwAAAO0"}
{"@timestamp":"2021-05-19T14:53:43.543+02:00","@version":"1","message":"-Dio.netty.threadLocalDirectBufferSize: 0","logger_name":"io.netty.buffer.ByteBufUtil","thread_name":"http-nio-8080-exec-54","level":"DEBUG","level_value":10000,"x-client-app-id":"VSD","instana.trace.id":"6b769f0aaffe21d9","AVRO_LOG_HELPER_MDC_KEY_CORRELATION_ID":"07ec9833-d206-4918-9b5f-308cc2abf225","SUMON_AUDITED_PARENT_SERVICE":"BookProposalController","channel":"web","locale":"fr_FR","SUMON_AUDITED_PARENT_METHOD":"bookProposalV2","AVRO_LOG_HELPER_MDC_KEY_REQUEST_ID":"YKUKTk3X6Y-0vWPMNSH2KwAAAO0"}
{"@timestamp":"2021-05-19T14:53:43.543+02:00","@version":"1","message":"-Dio.netty.maxThreadLocalCharBufferSize: 16384","logger_name":"io.netty.buffer.ByteBufUtil","thread_name":"http-nio-8080-exec-54","level":"DEBUG","level_value":10000,"x-client-app-id":"VSD","instana.trace.id":"6b769f0aaffe21d9","AVRO_LOG_HELPER_MDC_KEY_CORRELATION_ID":"07ec9833-d206-4918-9b5f-308cc2abf225","SUMON_AUDITED_PARENT_SERVICE":"BookProposalController","channel":"web","locale":"fr_FR","SUMON_AUDITED_PARENT_METHOD":"bookProposalV2","AVRO_LOG_HELPER_MDC_KEY_REQUEST_ID":"YKUKTk3X6Y-0vWPMNSH2KwAAAO0"}
{"@timestamp":"2021-05-19T14:53:44.753+02:00","@version":"1","message":"-Dio.netty.buffer.checkAccessible: true","logger_name":"io.netty.buffer.AbstractByteBuf","thread_name":"reactor-http-epoll-2","level":"DEBUG","level_value":10000,"instana.trace.id":"6b769f0aaffe21d9"}
{"@timestamp":"2021-05-19T14:53:44.754+02:00","@version":"1","message":"-Dio.netty.buffer.checkBounds: true","logger_name":"io.netty.buffer.AbstractByteBuf","thread_name":"reactor-http-epoll-2","level":"DEBUG","level_value":10000,"instana.trace.id":"6b769f0aaffe21d9"}
{"@timestamp":"2021-05-19T14:53:44.840+02:00","@version":"1","message":"Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@2421ca9d","logger_name":"io.netty.util.ResourceLeakDetectorFactory","thread_name":"reactor-http-epoll-2","level":"DEBUG","level_value":10000,"instana.trace.id":"6b769f0aaffe21d9"}
{"@timestamp":"2021-05-19T14:53:50.558+02:00","@version":"1","message":"","logger_name":"LOGGER_STACK","thread_name":"reactor-http-epoll-2","level":"ERROR","level_value":40000,"instana.trace.id":"6b769f0aaffe21d9","avro":{"timestamp8601": "2021-05-19T14:53:50.550+0200", "correlationId": "", "requestId": "", "version": "1.169.0-SNAPSHOT", "instance": "cart-services-cart-2895-spring-deprecated", "logMessage": "Error with HTTP request", "exceptionToString": "org.springframework.web.reactive.function.client.WebClientRequestException: connection timed out: api.ouibus-acc.cloud.sqills.com/18.158.188.92:443; nested exception is 
.channel.ConnectTimeoutException: connection timed out: api.ouibus-acc.cloud.sqills.com/18.158.188.92:443", "stack1stLine": "org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:137)", "causeException": "io.netty.channel.ConnectTimeoutException: connection timed out: api.ouibus-acc.cloud.sqills.com/18.158.188.92:443", "causeStack1stLine": "io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe$2.run(AbstractEpollChannel.java:576)", "fullStack": "org.springframework.web.reactive.function.client.WebClientRequestException: connection timed out: api.ouibus-acc.cloud.sqills.com/18.158.188.92:443; nested exception is io.netty.channel.ConnectTimeoutException: connection timed out: api.ouibus-acc.cloud.sqills.com/18.158.188.92:443\n\tat org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:137)\n\tat reactor.core.publisher.MonoErrorSupplied.subscribe(MonoErrorSupplied.java:70)\n\tat reactor.core.publisher.Mono.subscribe(Mono.java:4046)\n\tat reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:103)\n\tat reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:221)\n\tat reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:221)\n\tat reactor.core.publisher.FluxMap$MapSubscriber.onError(FluxMap.java:132)\n\tat reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:221)\n\tat reactor.core.publisher.MonoNext$NextSubscriber.onError(MonoNext.java:93)\n\tat reactor.core.publisher.MonoFlatMapMany$FlatMapManyMain.onError(MonoFlatMapMany.java:204)\n\tat reactor.core.publisher.SerializedSubscriber.onError(SerializedSubscriber.java:124)\n\tat reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.whenError(FluxRetryWhen.java:224)\n\tat reactor.core.publisher.FluxRetryWhen$RetryWhenOtherSubscriber.onError(FluxRetryWhen.java:273)\n\tat reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onError(FluxContextWrite.java:121)\n\tat reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.drain(FluxConcatMap.java:413)\n\tat reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.onNext(FluxConcatMap.java:250)\n\tat reactor.core.publisher.EmitterProcessor.drain(EmitterProcessor.java:491)\n\tat reactor.core.publisher.EmitterProcessor.tryEmitNext(EmitterProcessor.java:299)\n\tat reactor.core.publisher.SinkManySerialized.tryEmitNext(SinkManySerialized.java:97)\n\tat reactor.core.publisher.InternalManySink.emitNext(InternalManySink.java:27)\n\tat reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.onError(FluxRetryWhen.java:189)\n\tat reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:189)\n\tat reactor.netty.http.client.HttpClientConnect$MonoHttpConnect$ClientTransportSubscriber.onError(HttpClientConnect.java:306)\n\tat reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:189)\n\tat reactor.netty.resources.DefaultPooledConnectionProvider$DisposableAcquire.onError(DefaultPooledConnectionProvider.java:166)\n\tat reactor.netty.internal.shaded.reactor.pool.AbstractPool$Borrower.fail(AbstractPool.java:427)\n\tat reactor.netty.internal.shaded.reactor.pool.SimpleDequePool.lambda$drainLoop$5(SimpleDequePool.java:309)\n\tat reactor.core.publisher.FluxDoOnEach$DoOnEachSubscriber.onError(FluxDoOnEach.java:186)\n\tat reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:189)\n\tat reactor.netty.resources.DefaultPooledConnectionProvider$PooledConnectionAllocator$PooledConnectionInitializer.onError(DefaultPooledConnectionProvider.java:565)\n\tat reactor.core.publisher.MonoFlatMap$FlatMapMain.secondError(MonoFlatMap.java:192)\n\tat reactor.core.publisher.MonoFlatMap$FlatMapInner.onError(MonoFlatMap.java:259)\n\tat reactor.netty.transport.TransportConnector$MonoChannelPromise.tryFailure(TransportConnector.java:464)\n\tat reactor.netty.transport.TransportConnector$MonoChannelPromise$1.tryFailure(TransportConnector.java:515)\n\tat io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe$2.run(AbstractEpollChannel.java:577)\n\tat io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)\n\tat io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170)\n\tat io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)\n\tat io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)\n\tat io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)\n\tat io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)\n\tat io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)\n\tat io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\tat java.base/java.lang.Thread.run(Unknown Source)\nCaused by: io.netty.channel.ConnectTimeoutException: connection timed out: api.ouibus-acc.cloud.sqills.com/18.158.188.92:443\n\tat io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe$2.run(AbstractEpollChannel.java:576)\n\t... 9 more\n"}}
{"@timestamp":"2021-05-19T14:53:50.558+02:00","@version":"1","message":"","logger_name":"LOGGER_STACK","thread_name":"reactor-http-epoll-2","level":"ERROR","level_value":40000,"instana.trace.id":"6b769f0aaffe21d9","avro":{"timestamp8601": "2021-05-19T14:53:50.550+0200", "correlationId": "", "requestId": "", "version": "1.169.0-SNAPSHOT", "instance": "cart-services-cart-2895-spring-deprecated", "logMessage": "Error with HTTP request", "exceptionToString": "org.springframework.web.reactive.function.client.WebClientRequestException: connection timed out: api.ouibus-acc.cloud.sqills.com/18.158.188.92:443; nested exception is io.netty.channel.ConnectTimeoutException: connection timed out: api.ouibus-acc.cloud.sqills.com/18.158.188.92:443", "stack1stLine": "org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:137)", "causeException": "io.netty.channel.ConnectTimeoutException: connection timed out: api.ouibus-acc.cloud.sqills.com/18.158.188.92:443", "causeStack1stLine": "io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe$2.run(AbstractEpollChannel.java:576)", "fullStack": "org.springframework.web.reactive.function.client.WebClientRequestException: connection timed out: api.ouibus-acc.cloud.sqills.com/18.158.188.92:443; nested exception is io.netty.channel.ConnectTimeoutException: connection timed out: api.ouibus-acc.cloud.sqills.com/18.158.188.92:443\n\tat org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:137)\n\tat reactor.core.publisher.MonoErrorSupplied.subscribe(MonoErrorSupplied.java:70)\n\tat reactor.core.publisher.Mono.subscribe(Mono.java:4046)\n\tat reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:103)\n\tat reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:221)\n\tat reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:221)\n\tat reactor.core.publisher.FluxMap$MapSubscriber.onError(FluxMap.java:132)\n\tat reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:221)\n\tat reactor.core.publisher.MonoNext$NextSubscriber.onError(MonoNext.java:93)\n\tat reactor.core.publisher.MonoFlatMapMany$FlatMapManyMain.onError(MonoFlatMapMany.java:204)\n\tat reactor.core.publisher.SerializedSubscriber.onError(SerializedSubscriber.java:124)\n\tat reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.whenError(FluxRetryWhen.java:224)\n\tat reactor.core.publisher.FluxRetryWhen$RetryWhenOtherSubscriber.onError(FluxRetryWhen.java:273)\n\tat reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onError(FluxContextWrite.java:121)\n\tat reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.drain(FluxConcatMap.java:413)\n\tat reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.onNext(FluxConcatMap.java:250)\n\tat reactor.core.publisher.EmitterProcessor.drain(EmitterProcessor.java:491)\n\tat reactor.core.publisher.EmitterProcessor.tryEmitNext(EmitterProcessor.java:299)\n\tat reactor.core.publisher.SinkManySerialized.tryEmitNext(SinkManySerialized.java:97)\n\tat reactor.core.publisher.InternalManySink.emitNext(InternalManySink.java:27)\n\tat reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.onError(FluxRetryWhen.java:189)\n\tat reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:189)\n\tat reactor.netty.http.client.HttpClientConnect$MonoHttpConnect$ClientTransportSubscriber.onError(HttpClientConnect.java:306)\n\tat reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:189)\n\tat reactor.netty.resources.DefaultPooledConnectionProvider$DisposableAcquire.onError(DefaultPooledConnectionProvider.java:166)\n\tat reactor.netty.internal.shaded.reactor.pool.AbstractPool$Borrower.fail(AbstractPool.java:427)\n\tat reactor.netty.internal.shaded.reactor.pool.SimpleDequePool.lambda$drainLoop$5(SimpleDequePool.java:309)\n\tat reactor.core.publisher.FluxDoOnEach$DoOnEachSubscriber.onError(FluxDoOnEach.java:186)\n\tat reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:189)\n\tat reactor.netty.resources.DefaultPooledConnectionProvider$PooledConnectionAllocator$PooledConnectionInitializer.onError(DefaultPooledConnectionProvider.java:565)\n\tat reactor.core.publisher.MonoFlatMap$FlatMapMain.secondError(MonoFlatMap.java:192)\n\tat reactor.core.publisher.MonoFlatMap$FlatMapInner.onError(MonoFlatMap.java:259)\n\tat reactor.netty.transport.TransportConnector$MonoChannelPromise.tryFailure(TransportConnector.java:464)\n\tat reactor.netty.transport.TransportConnector$MonoChannelPromise$1.tryFailure(TransportConnector.java:515)\n\tat io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe$2.run(AbstractEpollChannel.java:577)\n\tat io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)\n\tat io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170)\n\tat io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)\n\tat io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)\n\tat io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)\n\tat io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)\n\tat io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)\n\tat io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\tat java.base/java.lang.Thread.run(Unknown Source)\nCaused by: io.netty.channel.ConnectTimeoutException: connection timed out: api.ouibus-acc.cloud.sqills.com/18.158.188.92:443\n\tat io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe$2.run(AbstractEpollChannel.java:576)\n\t... 9 more\n"}}
{"@timestamp":"2021-05-19T14:53:50.643+02:00","@version":"1","message":"","logger_name":"LOGGER_STACK","thread_name":"reactor-http-epoll-2","level":"ERROR","level_value":40000,"instana.trace.id":"6b769f0aaffe21d9","avro":{"timestamp8601": "2021-05-19T14:53:50.640+0200", "correlationId": "", "requestId": "", "version": "1.169.0-SNAPSHOT", "instance": "cart-services-cart-2895-spring-deprecated", "logMessage": "Error with HTTP request", "exceptionToString": "org.springframework.web.reactive.function.client.WebClientRequestException: connection timed out: api.ouibus-acc.cloud.sqills.com/18.158.188.92:443; nested exception is io.netty.channel.ConnectTimeoutException: connection timed out: api.ouibus-acc.cloud.sqills.com/18.158.188.92:443", "stack1stLine": "org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:137)", "causeException": "io.netty.channel.ConnectTimeoutException: connection timed out: api.ouibus-acc.cloud.sqills.com/18.158.188.92:443", "causeStack1stLine": "io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe$2.run(AbstractEpollChannel.java:576)", "fullStack": "org.springframework.web.reactive.function.client.WebClientRequestException: connection timed out: api.ouibus-acc.cloud.sqills.com/18.158.188.92:443; nested exception is io.netty.channel.ConnectTimeoutException: connection timed out: api.ouibus-acc.cloud.sqills.com/18.158.188.92:443\n\tat org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:137)\n\tSuppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: \nError has been observed at the following site(s):\n\t|_ checkpoint ⇢ Request to POST https://api.ouibus-acc.cloud.sqills.com/oauth/v2/token [DefaultWebClient]\nStack trace:\n\t\tat org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:137)\n\t\tat reactor.core.publisher.MonoErrorSupplied.subscribe(MonoErrorSupplied.java:70)\n\t\tat reactor.core.publisher.Mono.subscribe(Mono.java:4046)\n\t\tat reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:103)\n\t\tat reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:221)\n\t\tat reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:221)\n\t\tat reactor.core.publisher.FluxMap$MapSubscriber.onError(FluxMap.java:132)\n\t\tat reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:221)\n\t\tat reactor.core.publisher.MonoNext$NextSubscriber.onError(MonoNext.java:93)\n\t\tat reactor.core.publisher.MonoFlatMapMany$FlatMapManyMain.onError(MonoFlatMapMany.java:204)\n\t\tat reactor.core.publisher.SerializedSubscriber.onError(SerializedSubscriber.java:124)\n\t\tat reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.whenError(FluxRetryWhen.java:224)\n\t\tat reactor.core.publisher.FluxRetryWhen$RetryWhenOtherSubscriber.onError(FluxRetryWhen.java:273)\n\t\tat reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onError(FluxContextWrite.java:121)\n\t\tat reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.drain(FluxConcatMap.java:413)\n\t\tat reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.onNext(FluxConcatMap.java:250)\n\t\tat reactor.core.publisher.EmitterProcessor.drain(EmitterProcessor.java:491)\n\t\tat reactor.core.publisher.EmitterProcessor.tryEmitNext(EmitterProcessor.java:299)\n\t\tat reactor.core.publisher.SinkManySerialized.tryEmitNext(SinkManySerialized.java:97)\n\t\tat reactor.core.publisher.InternalManySink.emitNext(InternalManySink.java:27)\n\t\tat reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.onError(FluxRetryWhen.java:189)\n\t\tat reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:189)\n\t\tat reactor.netty.http.client.HttpClientConnect$MonoHttpConnect$ClientTransportSubscriber.onError(HttpClientConnect.java:306)\n\t\tat reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:189)\n\t\tat reactor.netty.resources.DefaultPooledConnectionProvider$DisposableAcquire.onError(DefaultPooledConnectionProvider.java:166)\n\t\tat reactor.netty.internal.shaded.reactor.pool.AbstractPool$Borrower.fail(AbstractPool.java:427)\n\t\tat reactor.netty.internal.shaded.reactor.pool.SimpleDequePool.lambda$drainLoop$5(SimpleDequePool.java:309)\n\t\tat reactor.core.publisher.FluxDoOnEach$DoOnEachSubscriber.onError(FluxDoOnEach.java:186)\n\t\tat reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:189)\n\t\tat reactor.netty.resources.DefaultPooledConnectionProvider$PooledConnectionAllocator$PooledConnectionInitializer.onError(DefaultPooledConnectionProvider.java:565)\n\t\tat reactor.core.publisher.MonoFlatMap$FlatMapMain.secondError(MonoFlatMap.java:192)\n\t\tat reactor.core.publisher.MonoFlatMap$FlatMapInner.onError(MonoFlatMap.java:259)\n\t\tat reactor.netty.transport.TransportConnector$MonoChannelPromise.tryFailure(TransportConnector.java:464)\n\t\tat reactor.netty.transport.TransportConnector$MonoChannelPromise$1.tryFailure(TransportConnector.java:515)\n\t\tat io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe$2.run(AbstractEpollChannel.java:577)\n\t\tat io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)\n\t\tat io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170)\n\t\tat io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)\n\t\tat io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)\n\t\tat io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)\n\t\tat io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)\n\t\tat io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)\n\t\tat io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\t\tat java.base/java.lang.Thread.run(Unknown Source)\nCaused by: io.netty.channel.ConnectTimeoutException: connection timed out: api.ouibus-acc.cloud.sqills.com/18.158.188.92:443\n\tat io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe$2.run(AbstractEpollChannel.java:576)\n\tat io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)\n\tat io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170)\n\tat io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)\n\tat io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)\n\tat io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)\n\tat io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)\n\tat io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)\n\tat io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\tat java.base/java.lang.Thread.run(Unknown Source)\n"}}
{"@timestamp":"2021-05-19T14:53:50.643+02:00","@version":"1","message":"","logger_name":"LOGGER_STACK","thread_name":"reactor-http-epoll-2","level":"ERROR","level_value":40000,"instana.trace.id":"6b769f0aaffe21d9","avro":{"timestamp8601": "2021-05-19T14:53:50.640+0200", "correlationId": "", "requestId": "", "version": "1.169.0-SNAPSHOT", "instance": "cart-services-cart-2895-spring-deprecated", "logMessage": "Error with HTTP request", "exceptionToString": "org.springframework.web.reactive.function.client.WebClientRequestException: connection timed out: api.ouibus-acc.cloud.sqills.com/18.158.188.92:443; nested exception is io.netty.channel.ConnectTimeoutException: connection timed out: api.ouibus-acc.cloud.sqills.com/18.158.188.92:443", "stack1stLine": "org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:137)", "causeException": "io.netty.channel.ConnectTimeoutException: connection timed out: api.ouibus-acc.cloud.sqills.com/18.158.188.92:443", "causeStack1stLine": "io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe$2.run(AbstractEpollChannel.java:576)", "fullStack": "org.springframework.web.reactive.function.client.WebClientRequestException: connection timed out: api.ouibus-acc.cloud.sqills.com/18.158.188.92:443; nested exception is io.netty.channel.ConnectTimeoutException: connection timed out: api.ouibus-acc.cloud.sqills.com/18.158.188.92:443\n\tat org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:137)\n\tSuppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: \nError has been observed at the following site(s):\n\t|_ checkpoint ⇢ Request to POST https://api.ouibus-acc.cloud.sqills.com/oauth/v2/token [DefaultWebClient]\nStack trace:\n\t\tat org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:137)\n\t\tat reactor.core.publisher.MonoErrorSupplied.subscribe(MonoErrorSupplied.java:70)\n\t\tat reactor.core.publisher.Mono.subscribe(Mono.java:4046)\n\t\tat reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:103)\n\t\tat reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:221)\n\t\tat reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:221)\n\t\tat reactor.core.publisher.FluxMap$MapSubscriber.onError(FluxMap.java:132)\n\t\tat reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:221)\n\t\tat reactor.core.publisher.MonoNext$NextSubscriber.onError(MonoNext.java:93)\n\t\tat reactor.core.publisher.MonoFlatMapMany$FlatMapManyMain.onError(MonoFlatMapMany.java:204)\n\t\tat reactor.core.publisher.SerializedSubscriber.onError(SerializedSubscriber.java:124)\n\t\tat reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.whenError(FluxRetryWhen.java:224)\n\t\tat reactor.core.publisher.FluxRetryWhen$RetryWhenOtherSubscriber.onError(FluxRetryWhen.java:273)\n\t\tat reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onError(FluxContextWrite.java:121)\n\t\tat reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.drain(FluxConcatMap.java:413)\n\t\tat reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.onNext(FluxConcatMap.java:250)\n\t\tat reactor.core.publisher.EmitterProcessor.drain(EmitterProcessor.java:491)\n\t\tat reactor.core.publisher.EmitterProcessor.tryEmitNext(EmitterProcessor.java:299)\n\t\tat reactor.core.publisher.SinkManySerialized.tryEmitNext(SinkManySerialized.java:97)\n\t\tat reactor.core.publisher.InternalManySink.emitNext(InternalManySink.java:27)\n\t\tat reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.onError(FluxRetryWhen.java:189)\n\t\tat reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:189)\n\t\tat reactor.netty.http.client.HttpClientConnect$MonoHttpConnect$ClientTransportSubscriber.onError(HttpClientConnect.java:306)\n\t\tat reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:189)\n\t\tat reactor.netty.resources.DefaultPooledConnectionProvider$DisposableAcquire.onError(DefaultPooledConnectionProvider.java:166)\n\t\tat reactor.netty.internal.shaded.reactor.pool.AbstractPool$Borrower.fail(AbstractPool.java:427)\n\t\tat reactor.netty.internal.shaded.reactor.pool.SimpleDequePool.lambda$drainLoop$5(SimpleDequePool.java:309)\n\t\tat reactor.core.publisher.FluxDoOnEach$DoOnEachSubscriber.onError(FluxDoOnEach.java:186)\n\t\tat reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:189)\n\t\tat reactor.netty.resources.DefaultPooledConnectionProvider$PooledConnectionAllocator$PooledConnectionInitializer.onError(DefaultPooledConnectionProvider.java:565)\n\t\tat reactor.core.publisher.MonoFlatMap$FlatMapMain.secondError(MonoFlatMap.java:192)\n\t\tat reactor.core.publisher.MonoFlatMap$FlatMapInner.onError(MonoFlatMap.java:259)\n\t\tat reactor.netty.transport.TransportConnector$MonoChannelPromise.tryFailure(TransportConnector.java:464)\n\t\tat reactor.netty.transport.TransportConnector$MonoChannelPromise$1.tryFailure(TransportConnector.java:515)\n\t\tat io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe$2.run(AbstractEpollChannel.java:577)\n\t\tat io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)\n\t\tat io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170)\n\t\tat io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)\n\t\tat io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)\n\t\tat io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)\n\t\tat io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)\n\t\tat io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)\n\t\tat io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\t\tat java.base/java.lang.Thread.run(Unknown Source)\nCaused by: io.netty.channel.ConnectTimeoutException: connection timed out: api.ouibus-acc.cloud.sqills.com/18.158.188.92:443\n\tat io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe$2.run(AbstractEpollChannel.java:576)\n\tat io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)\n\tat io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170)\n\tat io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)\n\tat io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)\n\tat io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)\n\tat io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)\n\tat io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)\n\tat io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\tat java.base/java.lang.Thread.run(Unknown Source)\n"}}
{"@timestamp":"2021-05-19T14:53:50.649+02:00","@version":"1","message":"No match for Log-Request-Id=[62edf67e] ","logger_name":"sncf.oui.cart.webclient.iolog.WiretapConnector","thread_name":"reactor-http-epoll-2","level":"WARN","level_value":30000,"instana.trace.id":"6b769f0aaffe21d9"}
{"@timestamp":"2021-05-19T14:53:50.649+02:00","@version":"1","message":"No match for Log-Request-Id=[dc6448d] ","logger_name":"sncf.oui.cart.webclient.iolog.WiretapConnector","thread_name":"reactor-http-epoll-2","level":"WARN","level_value":30000,"instana.trace.id":"6b769f0aaffe21d9"}
{"@timestamp":"2021-05-19T14:53:50.755+02:00","@version":"1","message":"","logger_name":"LOGGER_PARTNER","thread_name":"http-nio-8080-exec-54","level":"INFO","level_value":20000,"x-client-app-id":"VSD","instana.trace.id":"6b769f0aaffe21d9","AVRO_LOG_HELPER_MDC_KEY_CORRELATION_ID":"07ec9833-d206-4918-9b5f-308cc2abf225","SUMON_AUDITED_PARENT_SERVICE":"BookProposalController","channel":"web","SIFT_DISCRIMINATOR_PARTNER":"ext-sqills","locale":"fr_FR","SUMON_AUDITED_PARENT_METHOD":"bookProposalV2","AVRO_LOG_HELPER_MDC_KEY_REQUEST_ID":"YKUKTk3X6Y-0vWPMNSH2KwAAAO0","avro":{"timestamp8601": "2021-05-19T14:53:50.754+0200", "correlationId": "07ec9833-d206-4918-9b5f-308cc2abf225", "requestId": "YKUKTk3X6Y-0vWPMNSH2KwAAAO0", "application": "cart-services", "service": "Reservation.book", "elapsedTimeMs": 12492, "errorFlag": "KO", "errorCode": "VSP_PARTNER_TIMEOUT", "errorMsg": "", "version": "1.169.0-SNAPSHOT", "client": "", "instance": "cart-services-cart-2895-spring-deprecated", "thread": "113", "input": {}, "context": {"x-client-app-id": "VSD", "channel": "web", "locale": "fr_FR"}, "output": {"warnings": ""}, "partner": "sqills", "partnerType": "extern", "assetService": "book"}}
{"@timestamp":"2021-05-19T14:53:50.755+02:00","@version":"1","message":"","logger_name":"LOGGER_PARTNER","thread_name":"http-nio-8080-exec-54","level":"INFO","level_value":20000,"x-client-app-id":"VSD","instana.trace.id":"6b769f0aaffe21d9","AVRO_LOG_HELPER_MDC_KEY_CORRELATION_ID":"07ec9833-d206-4918-9b5f-308cc2abf225","SUMON_AUDITED_PARENT_SERVICE":"BookProposalController","channel":"web","SIFT_DISCRIMINATOR_PARTNER":"ext-sqills","locale":"fr_FR","SUMON_AUDITED_PARENT_METHOD":"bookProposalV2","AVRO_LOG_HELPER_MDC_KEY_REQUEST_ID":"YKUKTk3X6Y-0vWPMNSH2KwAAAO0","avro":{"timestamp8601": "2021-05-19T14:53:50.754+0200", "correlationId": "07ec9833-d206-4918-9b5f-308cc2abf225", "requestId": "YKUKTk3X6Y-0vWPMNSH2KwAAAO0", "application": "cart-services", "service": "Reservation.book", "elapsedTimeMs": 12492, "errorFlag": "KO", "errorCode": "VSP_PARTNER_TIMEOUT", "errorMsg": "", "version": "1.169.0-SNAPSHOT", "client": "", "instance": "cart-services-cart-2895-spring-deprecated", "thread": "113", "input": {}, "context": {"x-client-app-id": "VSD", "channel": "web", "locale": "fr_FR"}, "output": {"warnings": ""}, "partner": "sqills", "partnerType": "extern", "assetService": "book"}}
{"@timestamp":"2021-05-19T14:53:50.846+02:00","@version":"1","message":"","logger_name":"LOGGER_IOLOG_PARTNER","thread_name":"http-nio-8080-exec-54","level":"INFO","level_value":20000,"x-client-app-id":"VSD","instana.trace.id":"6b769f0aaffe21d9","AVRO_LOG_HELPER_MDC_KEY_CORRELATION_ID":"07ec9833-d206-4918-9b5f-308cc2abf225","SUMON_AUDITED_PARENT_SERVICE":"BookProposalController","channel":"web","SIFT_DISCRIMINATOR_PARTNER":"ext-sqills","locale":"fr_FR","SUMON_AUDITED_PARENT_METHOD":"bookProposalV2","AVRO_LOG_HELPER_MDC_KEY_REQUEST_ID":"YKUKTk3X6Y-0vWPMNSH2KwAAAO0","avro":{"timestamp8601": "2021-05-19T14:53:50.846+0200", "correlationId": "07ec9833-d206-4918-9b5f-308cc2abf225", "requestId": "YKUKTk3X6Y-0vWPMNSH2KwAAAO0", "application": "cart-services", "service": "Reservation.book", "elapsedTimeMs": 12492, "errorFlag": "KO", "errorCode": "VSP_PARTNER_TIMEOUT", "errorMsg": "", "version": "1.169.0-SNAPSHOT", "client": "", "instance": "cart-services-cart-2895-spring-deprecated", "thread": "113", "entryPoint": "", "input": {}, "context": {"x-client-app-id": "VSD", "channel": "web", "locale": "fr_FR"}, "output": {}, "partner": "sqills", "assetService": "book"}}
{"@timestamp":"2021-05-19T14:53:50.946+02:00","@version":"1","message":"Audited method raised an Exception/Error.","logger_name":"com.vsct.supervision.sumon.spring.annotation.advice.SumonAuditedAdvice","thread_name":"http-nio-8080-exec-54","level":"INFO","level_value":20000,"x-client-app-id":"VSD","instana.trace.id":"6b769f0aaffe21d9","AVRO_LOG_HELPER_MDC_KEY_CORRELATION_ID":"07ec9833-d206-4918-9b5f-308cc2abf225","SUMON_AUDITED_PARENT_SERVICE":"BookProposalController","channel":"web","locale":"fr_FR","SUMON_AUDITED_PARENT_METHOD":"bookProposalV2","AVRO_LOG_HELPER_MDC_KEY_REQUEST_ID":"YKUKTk3X6Y-0vWPMNSH2KwAAAO0"}
{"@timestamp":"2021-05-19T14:53:50.955+02:00","@version":"1","message":"","logger_name":"LOGGER_AUDITOUTLINE","thread_name":"http-nio-8080-exec-54","level":"INFO","level_value":20000,"x-client-app-id":"VSD","instana.trace.id":"6b769f0aaffe21d9","AVRO_LOG_HELPER_MDC_KEY_CORRELATION_ID":"07ec9833-d206-4918-9b5f-308cc2abf225","SUMON_AUDITED_PARENT_SERVICE":"BookProposalController","channel":"web","locale":"fr_FR","SUMON_AUDITED_PARENT_METHOD":"bookProposalV2","AVRO_LOG_HELPER_MDC_KEY_REQUEST_ID":"YKUKTk3X6Y-0vWPMNSH2KwAAAO0","avro":{"timestamp8601": "2021-05-19T14:53:50.954+0200", "correlationId": "07ec9833-d206-4918-9b5f-308cc2abf225", "requestId": "YKUKTk3X6Y-0vWPMNSH2KwAAAO0", "application": "cart-services", "service": "BookProposalController.bookProposalV2", "elapsedTimeMs": 15495, "errorFlag": "KO", "errorCode": "500", "errorMsg": "ErrorException{errorType='/errors/reservation/reservation-error', code='/errors/vsp_partner_timeout', status=400, title='Reservation error', extension='{errors=[ReservationError(type=RESERVATION, code=VSP_PARTNER_TIMEOUT, inventory=sqills, inventoryCode=null, inventoryMessage=null)]}'}", "version": "1.169.0-SNAPSHOT", "client": "", "instance": "cart-services-cart-2895-spring-deprecated", "thread": "113", "input": {"headers": "x-forwarded-for:185.214.52.1, 185.214.52.1, 151.80.22.62, 100.80.91.135, 100.89.164.79, 100.89.144.66, 100.89.183.198, 100.89.57.8, 100.89.184.175;x-forwarded-proto:https;x-forwarded-port:443;host:cart-services-cart-2895-spring-deprecated.paris.evoyageurs-dev.aws.vsct.fr;x-amzn-trace-id:Self=1-60a50a4e-7d230ab3077f328a0391f785;Root=1-60a50a4e-715aeeeb731b2aba724ec93e;content-length:3023;x-akamai-edgescape:georegion=IDF,country_code=FR,lat=48.85430,long=2.35270,timezone=NA,continent=EU,throughput=NA,bw=NA,network=VSC Technologies SASU,asnum=NA,location_id=NA;x-instana-t:a6b0573c6a7be82a;x-market-locale:fr_FR;sec-ch-ua-mobile:?0;x-instana-l:1,correlationType=web;correlationId=a6b0573c6a7be82a;x-vsd-locale:fr_FR;x-client-channel:web;user-agent:Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/90.0.4430.212 Safari/537.36;x-client-app-id:VSD;x-instana-s:a6b0573c6a7be82a;content-type:application/json;sec-ch-ua:\" Not A;Brand\";v=\"99\", \"Chromium\";v=\"90\", \"Google Chrome\";v=\"90\";accept:*/*;origin:https://usine1-www.test-oui.sncf;sec-fetch-site:same-origin;sec-fetch-mode:cors;sec-fetch-dest:empty;referer:https://usine1-www.test-oui.sncf/proposition/outward/bus?wishId=22197ba7-a6ce-44f1-901f-32b3ac5e3b05;accept-encoding:gzip, deflate, br;accept-language:fr-FR,fr;q=0.9,en-US;q=0.8,en;q=0.7;true-client-ip:185.214.52.1;x-varnish:206734008;clientip:185.214.52.1;x-forwarded-host:usine1-www.test-oui.sncf, usine1-www.test-oui.sncf,usine1-www.test-oui.sncf:58010;x-forwarded-server:preprod2-www.test-oui.sncf, usine1-www.test-oui.sncf;cookie:******;wl-proxy-ssl:true;x-vsc-request-id:YKUKTk3X6Y-0vWPMNSH2KwAAAO0;srchost:http://usine1-www.test-oui.sncf:50085;srcuri:/api/web/cart/reservations;x-api-env:usine10;x-proxy-application-name:cart", "body": "{\"context\":{\"cartId\":\"4a5f5d66-1ff9-4c51-96b4-de06e7156489\",\"country\":\"FR\",\"language\":\"fr\",\"userAgent\":\"\",\"resaExpress\":false,\"cardToPush\":null,\"wishId\":\"22197ba7-a6ce-44f1-901f-32b3ac5e3b05\",\"authenticated\":false},\"selectedOutwardTravel\":{\"localities\":[{\"id\":\"f0fdc5d1-947a-4eb0-8421-0c137cfc5c60\",\"name\":null,\"adress\":null,\"services\":null,\"metaData\":{\"SQILLSBUS\":{\"@type\":\"MetaDataCode\",\"code\":\"XPB\"}},\"geoLocalization\":null,\"cityId\":\"57bc8aa4-bd08-416a-b7e9-4903089de599\"},{\"id\":\"ea54578f-d243-4d15-be7c-982ace37784f\",\"name\":null,\"adress\":null,\"services\":null,\"metaData\":{\"SQILLSBUS\":{\"@type\":\"MetaDataCode\",\"code\":\"XDB\"}},\"geoLocalization\":null,\"cityId\":null}],\"cities\":[{\"id\":\"57bc8aa4-bd08-416a-b7e9-4903089de599\",\"name\":\"Paris\",\"metaData\":{\"SQILLSBUS\":{\"@type\":\"MetaDataCode\",\"code\":\"PAR\"},\"PAO\":{\"@type\":\"MetaDataCode\",\"code\":\"FRPAR\"}},\"geoLocalization\":null}],\"products\":[{\"id\":\"9fe60876-b952-426a-ad2d-85d1fb22fbce\",\"label\":null,\"code\":\"ST4\",\"productConditions\":{\"microConditions\":null,\"inwardMandatory\":false,\"flexibility\":null,\"advantageCard\":null},\"type\":\"NORMAL\"}],\"segments\":[{\"id\":\"8b7198cc-ed02-4151-b1df-0371d9522197\",\"originLocalityId\":\"f0fdc5d1-947a-4eb0-8421-0c137cfc5c60\",\"destinationLocalityId\":\"ea54578f-d243-4d15-be7c-982ace37784f\",\"departureDateTime\":\"2021-05-19T12:15:00\",\"arrivalDateTime\":\"2021-05-19T15:00:00\",\"secondDuration\":null,\"vehiculeType\":\"BUS\",\"transporter\":{\"type\":null,\"label\":\"BLABLACAR BUS\",\"distributor\":\"BLABLACAR BUS\",\"company\":\"BLABLABUS\",\"commercialInformation\":null,\"metaData\":{}},\"identifier\":\"50131\",\"state\":{\"realTimeInformations\":null},\"onBoardServices\":[],\"metaData\":{\"SQILLSBUS\":{\"@type\":\"OuibusSegment\",\"serviceIdentifier\":\"0:R 50131 SCH-MAZEREEUW 2021-05-19\",\"serviceScheduleDate\":\"2021-05-19T00:00:00\"}}}],\"selectedProposal\":{\"type\":\"NORMAL\",\"offers\":[{\"id\":\"86b14fff-56fa-4eaa-9b39-c87d66b5fc5e\",\"metaData\":{},\"productIds\":[\"9fe60876-b952-426a-ad2d-85d1fb22fbce\"],\"passengerIds\":[\"621380f0-cf69-4aaf-b7ea-596c271ffadb\"],\"segmentOfferIds\":[\"0348825f-4642-4dce-8de3-a83f89a1e9db\"],\"offerServices\":[],\"offerManager\":\"SQILLSBUS\",\"optionalPrice\":null,\"promoCodeApplied\":false,\"advantageInformationIds\":[]}],\"selectedSegmentOffers\":[{\"id\":\"0348825f-4642-4dce-8de3-a83f89a1e9db\",\"segmentId\":\"8b7198cc-ed02-4151-b1df-0371d9522197\",\"travelClass\":null,\"selectedPlacementMode\":\"WITHOUT_PLACEMENT\",\"selectedPlacements\":[],\"metaData\":{}}],\"flexibility\":\"CONDITIONAL_FLEXIBILITY\"},\"solutionPassengers\":[{\"id\":\"621380f0-cf69-4aaf-b7ea-596c271ffadb\",\"type\":\"HUMAN\",\"passengerCategory\":\"NORMAL\",\"wishPassengerId\":\"0\",\"rank\":0,\"typology\":null,\"customerId\":null,\"firstname\":null,\"lastname\":null,\"dateOfBirth\":null,\"age\":28,\"promoCode\":null,\"bicycle\":null,\"passengerCards\":[],\"passengerDisabilityInformation\":null,\"metaData\":{\"SQILLSBUS\":{\"@type\":\"OuibusPassenger\",\"sqillsBusPassengerType\":\"A\"}},\"disabilityGuideLevel\":null,\"disabilityCategory\":\"NONE\",\"wheelchair\":false,\"withoutSeat\":false}],\"advantageInformations\":[],\"travelType\":\"NORMAL\",\"metaData\":{}},\"selectedInwardTravel\":null}"}, "context": {"x-client-app-id": "VSD", "channel": "web", "locale": "fr_FR"}, "output": {"valid": true, "ineligibilityCauses": "", "eligible": true, "invalidityCauses": "", "errors": "ReservationError(type=RESERVATION, code=VSP_PARTNER_TIMEOUT, inventory=sqills, inventoryCode=null, inventoryMessage=null)"}}}
{"@timestamp":"2021-05-19T14:53:50.955+02:00","@version":"1","message":"","logger_name":"LOGGER_AUDITOUTLINE","thread_name":"http-nio-8080-exec-54","level":"INFO","level_value":20000,"x-client-app-id":"VSD","instana.trace.id":"6b769f0aaffe21d9","AVRO_LOG_HELPER_MDC_KEY_CORRELATION_ID":"07ec9833-d206-4918-9b5f-308cc2abf225","SUMON_AUDITED_PARENT_SERVICE":"BookProposalController","channel":"web","locale":"fr_FR","SUMON_AUDITED_PARENT_METHOD":"bookProposalV2","AVRO_LOG_HELPER_MDC_KEY_REQUEST_ID":"YKUKTk3X6Y-0vWPMNSH2KwAAAO0","avro":{"timestamp8601": "2021-05-19T14:53:50.954+0200", "correlationId": "07ec9833-d206-4918-9b5f-308cc2abf225", "requestId": "YKUKTk3X6Y-0vWPMNSH2KwAAAO0", "application": "cart-services", "service": "BookProposalController.bookProposalV2", "elapsedTimeMs": 15495, "errorFlag": "KO", "errorCode": "500", "errorMsg": "ErrorException{errorType='/errors/reservation/reservation-error', code='/errors/vsp_partner_timeout', status=400, title='Reservation error', extension='{errors=[ReservationError(type=RESERVATION, code=VSP_PARTNER_TIMEOUT, inventory=sqills, inventoryCode=null, inventoryMessage=null)]}'}", "version": "1.169.0-SNAPSHOT", "client": "", "instance": "cart-services-cart-2895-spring-deprecated", "thread": "113", "input": {"headers": "x-forwarded-for:185.214.52.1, 185.214.52.1, 151.80.22.62, 100.80.91.135, 100.89.164.79, 100.89.144.66, 100.89.183.198, 100.89.57.8, 100.89.184.175;x-forwarded-proto:https;x-forwarded-port:443;host:cart-services-cart-2895-spring-deprecated.paris.evoyageurs-dev.aws.vsct.fr;x-amzn-trace-id:Self=1-60a50a4e-7d230ab3077f328a0391f785;Root=1-60a50a4e-715aeeeb731b2aba724ec93e;content-length:3023;x-akamai-edgescape:georegion=IDF,country_code=FR,lat=48.85430,long=2.35270,timezone=NA,continent=EU,throughput=NA,bw=NA,network=VSC Technologies SASU,asnum=NA,location_id=NA;x-instana-t:a6b0573c6a7be82a;x-market-locale:fr_FR;sec-ch-ua-mobile:?0;x-instana-l:1,correlationType=web;correlationId=a6b0573c6a7be82a;x-vsd-locale:fr_FR;x-client-channel:web;user-agent:Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/90.0.4430.212 Safari/537.36;x-client-app-id:VSD;x-instana-s:a6b0573c6a7be82a;content-type:application/json;sec-ch-ua:\" Not A;Brand\";v=\"99\", \"Chromium\";v=\"90\", \"Google Chrome\";v=\"90\";accept:*/*;origin:https://usine1-www.test-oui.sncf;sec-fetch-site:same-origin;sec-fetch-mode:cors;sec-fetch-dest:empty;referer:https://usine1-www.test-oui.sncf/proposition/outward/bus?wishId=22197ba7-a6ce-44f1-901f-32b3ac5e3b05;accept-encoding:gzip, deflate, br;accept-language:fr-FR,fr;q=0.9,en-US;q=0.8,en;q=0.7;true-client-ip:185.214.52.1;x-varnish:206734008;clientip:185.214.52.1;x-forwarded-host:usine1-www.test-oui.sncf, usine1-www.test-oui.sncf,usine1-www.test-oui.sncf:58010;x-forwarded-server:preprod2-www.test-oui.sncf, usine1-www.test-oui.sncf;cookie:******;wl-proxy-ssl:true;x-vsc-request-id:YKUKTk3X6Y-0vWPMNSH2KwAAAO0;srchost:http://usine1-www.test-oui.sncf:50085;srcuri:/api/web/cart/reservations;x-api-env:usine10;x-proxy-application-name:cart", "body": "{\"context\":{\"cartId\":\"4a5f5d66-1ff9-4c51-96b4-de06e7156489\",\"country\":\"FR\",\"language\":\"fr\",\"userAgent\":\"\",\"resaExpress\":false,\"cardToPush\":null,\"wishId\":\"22197ba7-a6ce-44f1-901f-32b3ac5e3b05\",\"authenticated\":false},\"selectedOutwardTravel\":{\"localities\":[{\"id\":\"f0fdc5d1-947a-4eb0-8421-0c137cfc5c60\",\"name\":null,\"adress\":null,\"services\":null,\"metaData\":{\"SQILLSBUS\":{\"@type\":\"MetaDataCode\",\"code\":\"XPB\"}},\"geoLocalization\":null,\"cityId\":\"57bc8aa4-bd08-416a-b7e9-4903089de599\"},{\"id\":\"ea54578f-d243-4d15-be7c-982ace37784f\",\"name\":null,\"adress\":null,\"services\":null,\"metaData\":{\"SQILLSBUS\":{\"@type\":\"MetaDataCode\",\"code\":\"XDB\"}},\"geoLocalization\":null,\"cityId\":null}],\"cities\":[{\"id\":\"57bc8aa4-bd08-416a-b7e9-4903089de599\",\"name\":\"Paris\",\"metaData\":{\"SQILLSBUS\":{\"@type\":\"MetaDataCode\",\"code\":\"PAR\"},\"PAO\":{\"@type\":\"MetaDataCode\",\"code\":\"FRPAR\"}},\"geoLocalization\":null}],\"products\":[{\"id\":\"9fe60876-b952-426a-ad2d-85d1fb22fbce\",\"label\":null,\"code\":\"ST4\",\"productConditions\":{\"microConditions\":null,\"inwardMandatory\":false,\"flexibility\":null,\"advantageCard\":null},\"type\":\"NORMAL\"}],\"segments\":[{\"id\":\"8b7198cc-ed02-4151-b1df-0371d9522197\",\"originLocalityId\":\"f0fdc5d1-947a-4eb0-8421-0c137cfc5c60\",\"destinationLocalityId\":\"ea54578f-d243-4d15-be7c-982ace37784f\",\"departureDateTime\":\"2021-05-19T12:15:00\",\"arrivalDateTime\":\"2021-05-19T15:00:00\",\"secondDuration\":null,\"vehiculeType\":\"BUS\",\"transporter\":{\"type\":null,\"label\":\"BLABLACAR BUS\",\"distributor\":\"BLABLACAR BUS\",\"company\":\"BLABLABUS\",\"commercialInformation\":null,\"metaData\":{}},\"identifier\":\"50131\",\"state\":{\"realTimeInformations\":null},\"onBoardServices\":[],\"metaData\":{\"SQILLSBUS\":{\"@type\":\"OuibusSegment\",\"serviceIdentifier\":\"0:R 50131 SCH-MAZEREEUW 2021-05-19\",\"serviceScheduleDate\":\"2021-05-19T00:00:00\"}}}],\"selectedProposal\":{\"type\":\"NORMAL\",\"offers\":[{\"id\":\"86b14fff-56fa-4eaa-9b39-c87d66b5fc5e\",\"metaData\":{},\"productIds\":[\"9fe60876-b952-426a-ad2d-85d1fb22fbce\"],\"passengerIds\":[\"621380f0-cf69-4aaf-b7ea-596c271ffadb\"],\"segmentOfferIds\":[\"0348825f-4642-4dce-8de3-a83f89a1e9db\"],\"offerServices\":[],\"offerManager\":\"SQILLSBUS\",\"optionalPrice\":null,\"promoCodeApplied\":false,\"advantageInformationIds\":[]}],\"selectedSegmentOffers\":[{\"id\":\"0348825f-4642-4dce-8de3-a83f89a1e9db\",\"segmentId\":\"8b7198cc-ed02-4151-b1df-0371d9522197\",\"travelClass\":null,\"selectedPlacementMode\":\"WITHOUT_PLACEMENT\",\"selectedPlacements\":[],\"metaData\":{}}],\"flexibility\":\"CONDITIONAL_FLEXIBILITY\"},\"solutionPassengers\":[{\"id\":\"621380f0-cf69-4aaf-b7ea-596c271ffadb\",\"type\":\"HUMAN\",\"passengerCategory\":\"NORMAL\",\"wishPassengerId\":\"0\",\"rank\":0,\"typology\":null,\"customerId\":null,\"firstname\":null,\"lastname\":null,\"dateOfBirth\":null,\"age\":28,\"promoCode\":null,\"bicycle\":null,\"passengerCards\":[],\"passengerDisabilityInformation\":null,\"metaData\":{\"SQILLSBUS\":{\"@type\":\"OuibusPassenger\",\"sqillsBusPassengerType\":\"A\"}},\"disabilityGuideLevel\":null,\"disabilityCategory\":\"NONE\",\"wheelchair\":false,\"withoutSeat\":false}],\"advantageInformations\":[],\"travelType\":\"NORMAL\",\"metaData\":{}},\"selectedInwardTravel\":null}"}, "context": {"x-client-app-id": "VSD", "channel": "web", "locale": "fr_FR"}, "output": {"valid": true, "ineligibilityCauses": "", "eligible": true, "invalidityCauses": "", "errors": "ReservationError(type=RESERVATION, code=VSP_PARTNER_TIMEOUT, inventory=sqills, inventoryCode=null, inventoryMessage=null)"}}}
{"@timestamp":"2021-05-19T14:53:51.046+02:00","@version":"1","message":"","logger_name":"LOGGER_IOLOG","thread_name":"http-nio-8080-exec-54","level":"INFO","level_value":20000,"x-client-app-id":"VSD","instana.trace.id":"6b769f0aaffe21d9","AVRO_LOG_HELPER_MDC_KEY_CORRELATION_ID":"07ec9833-d206-4918-9b5f-308cc2abf225","SUMON_AUDITED_PARENT_SERVICE":"BookProposalController","channel":"web","locale":"fr_FR","SUMON_AUDITED_PARENT_METHOD":"bookProposalV2","AVRO_LOG_HELPER_MDC_KEY_REQUEST_ID":"YKUKTk3X6Y-0vWPMNSH2KwAAAO0","avro":{"timestamp8601": "2021-05-19T14:53:51.045+0200", "correlationId": "07ec9833-d206-4918-9b5f-308cc2abf225", "requestId": "YKUKTk3X6Y-0vWPMNSH2KwAAAO0", "application": "cart-services", "service": "BookProposalController.bookProposalV2", "elapsedTimeMs": 15495, "errorFlag": "KO", "errorCode": "500", "errorMsg": "ErrorException{errorType='/errors/reservation/reservation-error', code='/errors/vsp_partner_timeout', status=400, title='Reservation error', extension='{errors=[ReservationError(type=RESERVATION, code=VSP_PARTNER_TIMEOUT, inventory=sqills, inventoryCode=null, inventoryMessage=null)]}'}", "version": "1.169.0-SNAPSHOT", "client": "", "instance": "cart-services-cart-2895-spring-deprecated", "thread": "113", "entryPoint": "", "input": {}, "context": {"x-client-app-id": "VSD", "channel": "web", "locale": "fr_FR"}, "output": {}}}
{"@timestamp":"2021-05-19T14:53:51.046+02:00","@version":"1","message":"","logger_name":"LOGGER_IOLOG","thread_name":"http-nio-8080-exec-54","level":"INFO","level_value":20000,"x-client-app-id":"VSD","instana.trace.id":"6b769f0aaffe21d9","AVRO_LOG_HELPER_MDC_KEY_CORRELATION_ID":"07ec9833-d206-4918-9b5f-308cc2abf225","SUMON_AUDITED_PARENT_SERVICE":"BookProposalController","channel":"web","locale":"fr_FR","SUMON_AUDITED_PARENT_METHOD":"bookProposalV2","AVRO_LOG_HELPER_MDC_KEY_REQUEST_ID":"YKUKTk3X6Y-0vWPMNSH2KwAAAO0","avro":{"timestamp8601": "2021-05-19T14:53:51.045+0200", "correlationId": "07ec9833-d206-4918-9b5f-308cc2abf225", "requestId": "YKUKTk3X6Y-0vWPMNSH2KwAAAO0", "application": "cart-services", "service": "BookProposalController.bookProposalV2", "elapsedTimeMs": 15495, "errorFlag": "KO", "errorCode": "500", "errorMsg": "ErrorException{errorType='/errors/reservation/reservation-error', code='/errors/vsp_partner_timeout', status=400, title='Reservation error', extension='{errors=[ReservationError(type=RESERVATION, code=VSP_PARTNER_TIMEOUT, inventory=sqills, inventoryCode=null, inventoryMessage=null)]}'}", "version": "1.169.0-SNAPSHOT", "client": "", "instance": "cart-services-cart-2895-spring-deprecated", "thread": "113", "entryPoint": "", "input": {}, "context": {"x-client-app-id": "VSD", "channel": "web", "locale": "fr_FR"}, "output": {}}}
{"@timestamp":"2021-05-19T14:53:51.052+02:00","@version":"1","message":"","logger_name":"LOGGER_STACK","thread_name":"http-nio-8080-exec-54","level":"ERROR","level_value":40000,"channel":"web","x-client-app-id":"VSD","instana.trace.id":"6b769f0aaffe21d9","AVRO_LOG_HELPER_MDC_KEY_CORRELATION_ID":"07ec9833-d206-4918-9b5f-308cc2abf225","locale":"fr_FR","AVRO_LOG_HELPER_MDC_KEY_REQUEST_ID":"YKUKTk3X6Y-0vWPMNSH2KwAAAO0","avro":{"timestamp8601": "2021-05-19T14:53:51.051+0200", "correlationId": "07ec9833-d206-4918-9b5f-308cc2abf225", "requestId": "YKUKTk3X6Y-0vWPMNSH2KwAAAO0", "version": "1.169.0-SNAPSHOT", "instance": "cart-services-cart-2895-spring-deprecated", "logMessage": "Error exception", "exceptionToString": "sncf.oui.cart.domain.exception.ErrorException: ErrorException{errorType='/errors/reservation/reservation-error', code='/errors/vsp_partner_timeout', status=400, title='Reservation error', extension='{errors=[ReservationError(type=RESERVATION, code=VSP_PARTNER_TIMEOUT, inventory=sqills, inventoryCode=null, inventoryMessage=null)]}'}", "stack1stLine": "sncf.oui.cart.domain.exception.ErrorException$ErrorExceptionBuilder.build(ErrorException.kt:50)", "causeException": "sncf.oui.cart.domain.exception.ErrorException: ErrorException{errorType='/errors/reservation/reservation-error', code='/errors/vsp_partner_timeout', status=400, title='Reservation error', extension='{errors=[ReservationError(type=RESERVATION, code=VSP_PARTNER_TIMEOUT, inventory=sqills, inventoryCode=null, inventoryMessage=null)]}'}", "causeStack1stLine": "sncf.oui.cart.domain.exception.ErrorException$ErrorExceptionBuilder.build(ErrorException.kt:50)", "fullStack": "sncf.oui.cart.domain.exception.ErrorException: ErrorException{errorType='/errors/reservation/reservation-error', code='/errors/vsp_partner_timeout', status=400, title='Reservation error', extension='{errors=[ReservationError(type=RESERVATION, code=VSP_PARTNER_TIMEOUT, inventory=sqills, inventoryCode=null, inventoryMessage=null)]}'}\n\tat sncf.oui.cart.domain.exception.ErrorException$ErrorExceptionBuilder.build(ErrorException.kt:50)\n\tat sncf.oui.reservation.service.ReservationErrorUtils.throwErrorExceptionOnError(ReservationErrorUtils.kt:57)\n\tat sncf.oui.cart.api.reservation.v2.BookProposalController.prepareResponse(BookProposalController.kt:69)\n\tat sncf.oui.cart.api.reservation.v2.BookProposalController.bookProposalV2(BookProposalController.kt:57)\n\tat sncf.oui.cart.api.reservation.v2.BookProposalController$$FastClassBySpringCGLIB$$be03700.invoke(<generated>)\n\tat org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)\n\tat org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:779)\n\tat org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)\n\tat org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)\n\tat org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:89)\n\tat com.vsct.supervision.sumon.spring.annotation.advice.SumonAuditedAdvice.doAuditMethod(SumonAuditedAdvice.java:63)\n\tat com.vsct.supervision.sumon.spring.annotation.AuditedAspect.auditAction(AuditedAspect.java:34)\n\tat java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)\n\tat java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)\n\tat java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)\n\tat java.base/java.lang.reflect.Method.invoke(Unknown Source)\n\tat org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:634)\n\tat org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:624)\n\tat org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:72)\n\tat org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)\n\tat org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)\n\tat org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)\n\tat org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)\n\tat org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)\n\tat org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:692)\n\tat sncf.oui.cart.api.reservation.v2.BookProposalController$$EnhancerBySpringCGLIB$$86096434.bookProposalV2(<generated>)\n\tat java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)\n\tat java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)\n\tat java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)\n\tat java.base/java.lang.reflect.Method.invoke(Unknown Source)\n\tat org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:197)\n\tat org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:141)\n\tat org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:106)\n\tat org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:894)\n\tat org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808)\n\tat org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)\n\tat org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1060)\n\tat org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:962)\n\tat org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)\n\tat org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:909)\n\tat javax.servlet.http.HttpServlet.service(HttpServlet.java:652)\n\tat org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)\n\tat javax.servlet.http.HttpServlet.service(HttpServlet.java:733)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)\n\tat org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)\n\tat org.springframework.web.filter.AbstractRequestLoggingFilter.doFilterInternal(AbstractRequestLoggingFilter.java:289)\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)\n\tat sncf.oui.cart.monitoring.filter.LogContextFilter.doFilterInternal(LogContextFilter.java:42)\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)\n\tat org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)\n\tat org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)\n\tat org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:93)\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)\n\tat org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)\n\tat org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)\n\tat org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)\n\tat org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542)\n\tat org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143)\n\tat org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)\n\tat org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)\n\tat org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:764)\n\tat org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)\n\tat org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:374)\n\tat org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)\n\tat org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:888)\n\tat org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1597)\n\tat org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)\n\tat org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)\n\tat java.base/java.lang.Thread.run(Unknown Source)\n"}}
{"@timestamp":"2021-05-19T14:53:51.052+02:00","@version":"1","message":"","logger_name":"LOGGER_STACK","thread_name":"http-nio-8080-exec-54","level":"ERROR","level_value":40000,"channel":"web","x-client-app-id":"VSD","instana.trace.id":"6b769f0aaffe21d9","AVRO_LOG_HELPER_MDC_KEY_CORRELATION_ID":"07ec9833-d206-4918-9b5f-308cc2abf225","locale":"fr_FR","AVRO_LOG_HELPER_MDC_KEY_REQUEST_ID":"YKUKTk3X6Y-0vWPMNSH2KwAAAO0","avro":{"timestamp8601": "2021-05-19T14:53:51.051+0200", "correlationId": "07ec9833-d206-4918-9b5f-308cc2abf225", "requestId": "YKUKTk3X6Y-0vWPMNSH2KwAAAO0", "version": "1.169.0-SNAPSHOT", "instance": "cart-services-cart-2895-spring-deprecated", "logMessage": "Error exception", "exceptionToString": "sncf.oui.cart.domain.exception.ErrorException: ErrorException{errorType='/errors/reservation/reservation-error', code='/errors/vsp_partner_timeout', status=400, title='Reservation error', extension='{errors=[ReservationError(type=RESERVATION, code=VSP_PARTNER_TIMEOUT, inventory=sqills, inventoryCode=null, inventoryMessage=null)]}'}", "stack1stLine": "sncf.oui.cart.domain.exception.ErrorException$ErrorExceptionBuilder.build(ErrorException.kt:50)", "causeException": "sncf.oui.cart.domain.exception.ErrorException: ErrorException{errorType='/errors/reservation/reservation-error', code='/errors/vsp_partner_timeout', status=400, title='Reservation error', extension='{errors=[ReservationError(type=RESERVATION, code=VSP_PARTNER_TIMEOUT, inventory=sqills, inventoryCode=null, inventoryMessage=null)]}'}", "causeStack1stLine": "sncf.oui.cart.domain.exception.ErrorException$ErrorExceptionBuilder.build(ErrorException.kt:50)", "fullStack": "sncf.oui.cart.domain.exception.ErrorException: ErrorException{errorType='/errors/reservation/reservation-error', code='/errors/vsp_partner_timeout', status=400, title='Reservation error', extension='{errors=[ReservationError(type=RESERVATION, code=VSP_PARTNER_TIMEOUT, inventory=sqills, inventoryCode=null, inventoryMessage=null)]}'}\n\tat sncf.oui.cart.domain.exception.ErrorException$ErrorExceptionBuilder.build(ErrorException.kt:50)\n\tat sncf.oui.reservation.service.ReservationErrorUtils.throwErrorExceptionOnError(ReservationErrorUtils.kt:57)\n\tat sncf.oui.cart.api.reservation.v2.BookProposalController.prepareResponse(BookProposalController.kt:69)\n\tat sncf.oui.cart.api.reservation.v2.BookProposalController.bookProposalV2(BookProposalController.kt:57)\n\tat sncf.oui.cart.api.reservation.v2.BookProposalController$$FastClassBySpringCGLIB$$be03700.invoke(<generated>)\n\tat org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)\n\tat org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:779)\n\tat org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)\n\tat org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)\n\tat org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:89)\n\tat com.vsct.supervision.sumon.spring.annotation.advice.SumonAuditedAdvice.doAuditMethod(SumonAuditedAdvice.java:63)\n\tat com.vsct.supervision.sumon.spring.annotation.AuditedAspect.auditAction(AuditedAspect.java:34)\n\tat java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)\n\tat java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)\n\tat java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)\n\tat java.base/java.lang.reflect.Method.invoke(Unknown Source)\n\tat org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:634)\n\tat org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:624)\n\tat org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:72)\n\tat org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)\n\tat org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)\n\tat org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)\n\tat org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)\n\tat org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)\n\tat org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:692)\n\tat sncf.oui.cart.api.reservation.v2.BookProposalController$$EnhancerBySpringCGLIB$$86096434.bookProposalV2(<generated>)\n\tat java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)\n\tat java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)\n\tat java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)\n\tat java.base/java.lang.reflect.Method.invoke(Unknown Source)\n\tat org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:197)\n\tat org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:141)\n\tat org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:106)\n\tat org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:894)\n\tat org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808)\n\tat org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)\n\tat org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1060)\n\tat org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:962)\n\tat org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)\n\tat org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:909)\n\tat javax.servlet.http.HttpServlet.service(HttpServlet.java:652)\n\tat org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)\n\tat javax.servlet.http.HttpServlet.service(HttpServlet.java:733)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)\n\tat org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)\n\tat org.springframework.web.filter.AbstractRequestLoggingFilter.doFilterInternal(AbstractRequestLoggingFilter.java:289)\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)\n\tat sncf.oui.cart.monitoring.filter.LogContextFilter.doFilterInternal(LogContextFilter.java:42)\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)\n\tat org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)\n\tat org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)\n\tat org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:93)\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)\n\tat org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)\n\tat org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)\n\tat org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)\n\tat org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542)\n\tat org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143)\n\tat org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)\n\tat org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)\n\tat org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:764)\n\tat org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)\n\tat org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:374)\n\tat org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)\n\tat org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:888)\n\tat org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1597)\n\tat org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)\n\tat org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)\n\tat java.base/java.lang.Thread.run(Unknown Source)\n"}}

rschlick on 19 May 2021

@rschlick the address with nslookup is different than the one above? We need to see how the address is resolved with nslookup and with Reactor Netty

When I enable Netty logs I'm able to see

17:02:11.148 [reactor-http-nio-1] DEBUG i.netty.resolver.dns.DnsQueryContext - [id: 0xd1c330d0] WRITE: UDP, [28089: /IP:53]...
17:02:11.167 [reactor-http-nio-1] DEBUG i.netty.resolver.dns.DnsNameResolver - [id: 0xd1c330d0] RECEIVED: UDP [28089: /IP:53]...

violetagg on 19 May 2021

@rschlick I am using spring boot 2.4.4 (netty 4.1.60) and the debug above works fine.
logging.level.io.netty=debug

Obviously you have to make a WebClient call (to a none localhost) and when I do this I see:

. . . [ctor-http-nio-2] io.netty.resolver.dns.DnsQueryContext   [0;39m [2m:[0;39m [id: 0x52fa5c4f] WRITE: UDP, [56659: /10.122.142.1:53]
. . . [ctor-http-nio-2] io.netty.resolver.dns.DnsNameResolver   [0;39m [2m:[0;39m [id: 0x52fa5c4f] RECEIVED: UDP [56659: /10.122.142.1:53]

is it because you have overridden the DNS resolver? My flow drops into DnsQueryContext.query

davidmelia on 19 May 2021

@rschlick We need an update in order to continue with the investigation.

violetagg on 25 May 2021

I don't have any logs.

Here is my conf :

 HttpClient httpClient =
                HttpClient.create(resourceFactory.getConnectionProvider())
                        .resolver(DefaultAddressResolverGroup.INSTANCE)
                        .runOn(resourceFactory.getLoopResources())
                        .option(CONNECT_TIMEOUT_MILLIS, (int) connectionTimeout.toMillis())
                        .doOnConnected((connection) -> connection.addHandlerLast(new ReadTimeoutHandler(readTimeout.toMillis(), MILLISECONDS)));

application.yml :

logging.level.io.netty: debug

logback.xml:

 <logger name="io.netty" level="DEBUG">
        <appender-ref ref="APPENDER_CONSOLE"/>
    </logger>

    <root level="DEBUG">
        <appender-ref ref="APPENDER_CONSOLE"/>
    </root>

rschlick on 26 May 2021

@rschlick Please do not override the resolver, but use the default.

violetagg on 28 May 2021

@violetagg I have removed the resolver overriding, but I just have this log :

Connect attempt to [global.api-dev.flixbus.com/95.100.171.175:443] failed.","logger_name":"reactor.netty.transport.TransportConnector","thread_name":"reactor-http-epoll-2","level":"DEBUG","level_value":10000,"stack_trace":"io.netty.channel.ConnectTimeoutException: connection timed out: global.api-dev.flixbus.com/95.100.171.175:443\n\tat io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe$2.run(AbstractEpollChannel.java:613)\n\tat io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)\n\tat io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170)\n\tat io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)\n\tat io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)\n\tat io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)\n\tat io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)\n\tat io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)\n\tat io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\tat java.base/java.lang.Thread.run(Unknown Source)\n","instana.trace.id":"c46231080e19d5ed"}

rschlick on 31 May 2021

@rschlick And do you have some logs from io.netty.resolver.dns. What is the result of nslookup? Is it the same resolution result as the one in the above log?

violetagg on 1 Jun 2021

Was this page helpful?

0 / 5 - 0 ratings