quarkus.oidc.auth-server-url causing weird start-up failure

[ambition-consulting]

Describe the bug

adding this line makes all the difference:

%ecom-dev.quarkus.oidc.auth-server-url=http://ecom-portal-keycloak:8080/realms/quarkus

makes the application crash without much explanation on DEBUG log level:

exec java -Dquarkus.http.host=0.0.0.0 -Djava.util.logging.manager=org.jboss.logmanager.LogManager -XX:+UseG1GC -XX:+UseStringDeduplication -XX:InitialRAMPercentage=50.0 -XX:MaxRAMPercentage=50.0 -Xss256k -Xmx512m -cp . -jar /deployments/quarkus-run.jar
Nov 22, 2022 11:04:30 PM org.hibernate.validator.internal.util.Version
INFO: HV000001: Hibernate Validator %s
Nov 22, 2022 11:04:38 PM io.quarkus.opentelemetry.runtime.tracing.LateBoundSampler
WARN: No Sampler delegate specified, no action taken.
Nov 22, 2022 11:04:48 PM io.vertx.core.net.impl.ConnectionBase
ERROR: Connection reset
java.net.SocketException: Connection reset
at java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:394)
at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:426)
at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:258)
at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132)
at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:357)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
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:831)
Nov 22, 2022 11:04:48 PM io.quarkus.runtime.ApplicationLifecycleManager run
ERROR: Failed to start application (with profile ecom-dev)
java.net.SocketException: Connection reset
at java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:394)
at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:426)
at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:258)
at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132)
at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:357)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
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:831)

The keycloak server 19.0.3 is ready and reachable:

/ $ curl -kv http://ecom-portal-keycloak:8080/realms/quarkus
*   Trying 172.20.93.10:8080...
* Connected to ecom-portal-keycloak (172.20.93.10) port 8080 (#0)
> GET /realms/quarkus HTTP/1.1
> Host: ecom-portal-keycloak:8080
> User-Agent: curl/7.79.1
> Accept: */*
> 
* Mark bundle as not supporting multiuse
< HTTP/1.1 200 OK
< referrer-policy: no-referrer
< x-frame-options: SAMEORIGIN
< strict-transport-security: max-age=31536000; includeSubDomains
< cache-control: no-cache
< x-content-type-options: nosniff
< x-xss-protection: 1; mode=block
< content-type: application/json
< content-length: 655
< x-envoy-upstream-service-time: 92
< date: Tue, 22 Nov 2022 23:08:14 GMT
< server: envoy
< 
* Connection #0 to host ecom-portal-keycloak left intact
{"realm":"quarkus","public_key":"MIIBIjANBgkqhkiG9w0BAQEFAAOCAQ8AMIIBCgKCAQEAzNMrtvYNG/QBFl+wH+89/asjb+PFU5I+8c+7y1qVgR88NoG53vGKM6GJMnu22nEf24AxXiRLR6SNgiKXhYISNlONREoDJcz9J5Fupm+5MkujHyMn7wLrBTDlFVWwMyVdCTcbmSddM8CkNqMpc8M49HroxxlJLlyaQZNiUKjQVKIsxVMzP5jXfthUtR2eMLLxSyLb6TOZfVrIRouQcDdSdn4q4Oj5eaEWHUg9EH6Q3nGmbL/JnWcvTlb1wDV/LMd4AvOZYKXEuf2RrOdkmNrZ0yXGT0dCzjjRDr+GvH7xUqAw8yAkw6/LegaN8+MPb0Qd9sEnGbkAh2iNrEg+LYDnnQIDAQAB","token-service":"https://portal.ecom-dev.app.whirlpool.aws.fisv.cloud/realms/quarkus/protocol/openid-connect","account-service":"https://portal.ecom-dev.app.whirlpool.aws.fisv.cloud/realms/quarkus/account","tokens-not-before":0}/ $ 

Any ideas why such a configuration would make the application not start-up anymore?

Expected behavior

some meaningful error log, or for it to just work.

Actual behavior

quarkus dead, sad developer.

How to Reproduce?

No response

Output of uname -a or ver

No response

Output of java -version

No response

GraalVM version (if different from Java)

No response

Quarkus version or git rev

No response

Build tool (ie. output of mvnw --version or gradlew --version)

No response

Additional information

No response

[quarkus-bot]

/cc @pedroigor, @sberyozkin

[geoand]

Any chance you can get us a sample application? Unfortunately the stacktrace does not provide any clues.

[ambition-consulting]

Unlikely, I will only stay in this project for another week, and probably won't find time for a reproducer.

To increase logs, is there anything else I can do other than:

quarkus.log.category."io.quarkus.oidc".min-level=TRACE
quarkus.log.category."io.quarkus.oidc".level=TRACE

?

[geoand]

I doubt it, the problem is that the exception happens in async code, so we don;t have a proper stacktrace

[ambition-consulting]

I forgot the min-level before, now I get additionally:
"message":"OIDC Server is not available:","processId":1,"processName":"quarkus-run.jar","sequence":5093,"stackTrace":"javax.net.ssl.SSLHandshakeException: Received fatal alert: handshake_failure\n\tat java.base/sun.security.ssl.Alert.createSSLException(Alert.java:131)\n\tat java.base/sun.security.ssl.Alert.createSSLException(Alert.java:117)\n\tat java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:356)\n\tat java.base/sun.security.ssl.Alert$AlertConsumer.consume(Alert.java:293)\n\tat java.base/sun.security.ssl.TransportContext.dispatch(TransportContext.java:202)\n\tat java.base/sun.security.ssl.SSLTransport.decode(SSLTransport.java:171)\n\tat java.base/sun.security.ssl.SSLEngineImpl.decode(SSLEngineImpl.java:736)\n\tat java.base/sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:691)\n\tat java.base/sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:506)\n\tat java.base/sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:482)\n\tat java.base/javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:679)\n\tat io.netty.handler.ssl.SslHandler$SslEngineType$3.unwrap(SslHandler.java:296)\n\tat io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1343)\n\tat io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1236)\n\tat io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1285)\n\tat io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:519)\n\tat io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:458)\n\tat io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:280)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)\n\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)\n\tat io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)\n\tat io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)\n\tat io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)\n\tat io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)\n\tat io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)\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(Thread.java:831)\n"

[ambition-consulting]

despite having specified http scheme, it seems to insist on ssl

[sberyozkin]

Hi @ambition-consulting Does it work without %ecom-dev. ? There a few issues around related to - in env properties

[sberyozkin]

@ambition-consulting Or try may be %ecomdev., I'm pretty sure for some reasons this profile specific property is not activated

[gsmet]

So for me, there are two issues here:

• we need to understand why the exception is not propagated and you have absolutely no idea what's going on
• secondly, we need to understand the connection issue

As for the former, @sberyozkin could you have a look at why the exception is somehow swallowed and there's no information in the log? Note that the log looks like garbage to me so I'm not sure the app is started as it should.

As for the latter, I think Sergey has a point and you should first try to simplify the config and see how it goes. If it still doesn't fix your issue without even using a profile then we probably need to have another look.

[andrm]

Check your keycloak conf, it seems it insists on https. Make sure backchannel can be unencrypted.

[yyvess]

I was face to the same issue with Quarkus 15.1
It's was time consuming for me to find the root cause of this Quarkus startup exception 'java.net.SocketException: Connection reset' that give no context 👎

As work around I disabled the oidc.discovery as is =>

quarkus.oidc.discovery-enabled=false
quarkus.oidc.token-path=/protocol/openid-connect/token
quarkus.oidc.jwks-path=/protocol/openid-connect/certs
quarkus.oidc.user-info-path=/protocol/openid-connect/userinfo
quarkus.oidc.introspection-path=/protocol/openid-connect/tokens/introspect

Root cause on my case was due to different way to expose Keycloak on kubernetes
between internal and external network traffic.

Keycloak external traffic is overs https and use "standard" DNS, internal traffic is overs http (encrypted by Istio proxy) and use Kubernetes internal service name.

Keycloak auto discovery end-point /.well-known/openid-configuration return a configuration with https and external dns that cannot be use by the Quarkus backend application running inside the cluster .

A understandable error message will be more than welcome ;-)

[sberyozkin]

Sure, I'll try to look into having a better error message produced, sorry for a delay

[geoand]

@sberyozkin what's the status of this?

[sberyozkin]

@yyvess @gsmet @geoand Sorry for the delay, when the connection attempt fails, an attempt is made to recover during the first request, I think the problem it is at a very low level like debug or trace, I'll need to get at info I guess at the startup and error if it fails again during the recovery attempt. Will try to close a few simple issues asap