Helidon Service Wait 30 Seconds Then Fail (FAN Suspected)

[RichardExley]

For example:

kubectl logs -f inventory-helidon-b7d89bcb-g7vk7 -n msdataworkshop Dec 16, 2021 7:33:51 PM io.helidon.common.LogConfig doConfigureLogging INFO: Logging at initialization configured using classpath: /logging.properties Dec 16, 2021 7:33:52 PM org.jboss.weld.bootstrap.WeldStartup <clinit> INFO: WELD-000900: 3.1.6 (Final) Dec 16, 2021 7:33:53 PM io.helidon.microprofile.openapi.OpenApiCdiExtension <init> INFO: OpenAPI support could not locate the Jandex index file META-INF/jandex.idx so will build an in-memory index. This slows your app start-up and, depending on CDI configuration, might omit some type information needed for a complete OpenAPI document. Consider using the Jandex maven plug-in during your build to create the index and add it to your app. Dec 16, 2021 7:33:53 PM org.jboss.weld.environment.deployment.discovery.DiscoveryStrategyFactory create INFO: WELD-ENV-000020: Using jandex for bean discovery Dec 16, 2021 7:33:53 PM org.jboss.weld.bootstrap.WeldStartup startContainer INFO: WELD-000101: Transactional services not available. Injection of @Inject UserTransaction not available. Transactional observers will be invoked synchronously. Dec 16, 2021 7:33:53 PM org.jboss.weld.event.ExtensionObserverMethodImpl checkRequiredTypeAnnotations INFO: WELD-000411: Observer method [BackedAnnotatedMethod] public org.glassfish.jersey.ext.cdi1x.internal.ProcessAllAnnotatedTypes.processAnnotatedType(@Observes ProcessAnnotatedType<?>, BeanManager) receives events for all annotated types. Consider restricting events using @WithAnnotations or a generic type with bounds. Dec 16, 2021 7:33:53 PM org.jboss.weld.event.ExtensionObserverMethodImpl checkRequiredTypeAnnotations INFO: WELD-000411: Observer method [BackedAnnotatedMethod] private io.helidon.microprofile.openapi.OpenApiCdiExtension.processAnnotatedType(@Observes ProcessAnnotatedType<X>) receives events for all annotated types. Consider restricting events using @WithAnnotations or a generic type with bounds. Dec 16, 2021 7:33:55 PM io.helidon.tracing.jaeger.JaegerTracerBuilder build INFO: Creating Jaeger tracer for 'inventory.msdataworkshop' configured with http://jaeger-collector.msdataworkshop:14268 Dec 16, 2021 7:33:55 PM io.helidon.microprofile.security.SecurityCdiExtension registerSecurity INFO: Authentication provider is missing from security configuration, but security extension for microprofile is enabled (requires providers configuration at key security.providers). Security will not have any valid authentication provider Dec 16, 2021 7:33:55 PM io.helidon.microprofile.security.SecurityCdiExtension registerSecurity INFO: Authorization provider is missing from security configuration, but security extension for microprofile is enabled (requires providers configuration at key security.providers). ABAC provider is configured for authorization. InventoryResource.init ContainerInitialized event for container with ID: e6c42950-3301-4950-bf9c-4ce6952cb413 Dec 16, 2021 7:33:59 PM io.helidon.common.SerializationConfig lambda$configure$0 WARNING: Deserialization attempted for class oracle.sql.converter.CharacterConverter1Byte, yet there is no global serial filter configured. To automatically configure a filter, please set system property "helidon.serialFilter.missing.action" to "configure" Dec 16, 2021 7:34:30 PM oracle.ucp.logging.ClioSupport _log WARNING: :::failed to start ONS: Server time out Dec 16, 2021 7:34:30 PM oracle.ucp.logging.ClioSupport _log WARNING: :::failed to start ONS with the following exception: [oracle.ucp.util.UCPErrorHandler.newUniversalConnectionPoolException(UCPErrorHandler.java:379), oracle.ucp.util.UCPErrorHandler.newUniversalConnectionPoolException(UCPErrorHandler.java:347), oracle.ucp.util.UCPErrorHandler.newUniversalConnectionPoolException(UCPErrorHandler.java:361), oracle.ucp.common.ONSDriver.start(ONSDriver.java:113), oracle.ucp.common.Topology.onsDriver(Topology.java:531), oracle.ucp.common.CoreConnectionImpl.<init>(CoreConnectionImpl.java:110), oracle.ucp.common.CoreConnectionImpl.create(CoreConnectionImpl.java:76), oracle.ucp.common.Service.create(Service.java:890), oracle.ucp.common.Service.create(Service.java:617), oracle.ucp.common.Topology.create(Topology.java:164), oracle.ucp.common.Core.growBorrowed(Core.java:1254), oracle.ucp.common.UniversalConnectionPoolImpl.helpGrowBorrowed(UniversalConnectionPoolImpl.java:407), oracle.ucp.common.UniversalConnectionPoolImpl.borrowConnectionWithoutCountingRequests(UniversalConnectionPoolImpl.java:350), oracle.ucp.common.UniversalConnectionPoolImpl.borrowConnectionAndValidateHelper(UniversalConnectionPoolImpl.java:206), oracle.ucp.common.UniversalConnectionPoolImpl.borrowConnectionAndValidate(UniversalConnectionPoolImpl.java:166), oracle.ucp.common.UniversalConnectionPoolImpl.borrowConnection(UniversalConnectionPoolImpl.java:139), oracle.ucp.jdbc.JDBCConnectionPool.borrowConnection(JDBCConnectionPool.java:185), oracle.ucp.jdbc.oracle.OracleJDBCConnectionPool.borrowConnection(OracleJDBCConnectionPool.java:611), oracle.ucp.jdbc.oracle.OracleConnectionConnectionPool.borrowConnection(OracleConnectionConnectionPool.java:119), oracle.ucp.jdbc.PoolDataSourceImpl.getConnection(PoolDataSourceImpl.java:1856), oracle.ucp.jdbc.PoolDataSourceImpl.access$300(PoolDataSourceImpl.java:223), oracle.ucp.jdbc.PoolDataSourceImpl$3.build(PoolDataSourceImpl.java:3999), oracle.ucp.jdbc.PoolDataSourceImpl.getConnection(PoolDataSourceImpl.java:1801), oracle.ucp.jdbc.PoolDataSourceImpl.getConnection(PoolDataSourceImpl.java:1756), oracle.ucp.jdbc.PoolDataSourceImpl.getConnection(PoolDataSourceImpl.java:1742), java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method), java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source), java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source), java.base/java.lang.reflect.Method.invoke(Unknown Source), org.jboss.weld.bean.proxy.AbstractBeanInstance.invoke(AbstractBeanInstance.java:38), org.jboss.weld.bean.proxy.ProxyMethodHandler.invoke(ProxyMethodHandler.java:106), org.jboss.weld.io.Serializable$CommonDataSource$DataSource$ObjectFactory$PoolDataSource$Referenceable$UniversalConnectionPoolAdapter$Wrapper$$Proxy$_$$_WeldClientProxy.getConnection(Unknown Source), io.helidon.data.examples.InventoryResource.init(InventoryResource.java:82), java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method), java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source), java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source), java.base/java.lang.reflect.Method.invoke(Unknown Source), org.jboss.weld.injection.StaticMethodInjectionPoint.invoke(StaticMethodInjectionPoint.java:95), org.jboss.weld.injection.StaticMethodInjectionPoint.invoke(StaticMethodInjectionPoint.java:85), org.jboss.weld.injection.MethodInvocationStrategy$SimpleMethodInvocationStrategy.invoke(MethodInvocationStrategy.java:168), org.jboss.weld.event.ObserverMethodImpl.sendEvent(ObserverMethodImpl.java:330), org.jboss.weld.event.ObserverMethodImpl.sendEvent(ObserverMethodImpl.java:308), org.jboss.weld.event.ObserverMethodImpl.notify(ObserverMethodImpl.java:286), javax.enterprise.inject.spi.ObserverMethod.notify(ObserverMethod.java:124), org.jboss.weld.util.Observers.notify(Observers.java:166), org.jboss.weld.event.ObserverNotifier.notifySyncObservers(ObserverNotifier.java:285), org.jboss.weld.event.ObserverNotifier.notify(ObserverNotifier.java:273), org.jboss.weld.event.EventImpl.fire(EventImpl.java:96), io.helidon.microprofile.cdi.HelidonContainerImpl.doStart(HelidonContainerImpl.java:341), io.helidon.common.context.Contexts.runInContext(Contexts.java:137), io.helidon.microprofile.cdi.HelidonContainerImpl.start(HelidonContainerImpl.java:251), io.helidon.microprofile.cdi.Main.main(Main.java:80), io.helidon.microprofile.server.Main.main(Main.java:44)] InventoryResource.init connection:oracle.ucp.jdbc.proxy.oracle$1ucp$1jdbc$1proxy$1oracle$1ConnectionProxy$2oracle$1jdbc$1internal$1OracleConnection$$$Proxy@350bbd5d Receive messages... isPLSQL:false ... isRollback:false ... isAutoCommit:false Dec 16, 2021 7:34:30 PM io.helidon.microprofile.server.ServerCdiExtension addApplication INFO: Registering JAX-RS Application: InventoryApplication Dec 16, 2021 7:34:31 PM io.helidon.webserver.NettyWebServer lambda$start$7 INFO: Channel '@default' started: [id: 0xea696a06, L:/0:0:0:0:0:0:0:0:8080] Dec 16, 2021 7:34:31 PM io.helidon.microprofile.server.ServerCdiExtension startServer INFO: Server started on http://localhost:8080 (and all other host addresses) in 40226 milliseconds (since JVM startup). Dec 16, 2021 7:34:32 PM io.helidon.common.HelidonFeatures features INFO: Helidon MP 2.4.0 features: [CDI, Config, Fault Tolerance, Health, JAX-RS, Metrics, Open API, REST Client, Security, Server, Tracing]

How to disable FAN for helidon? The current setting "System.setProperty("oracle.jdbc.fanEnabled", "false");" does not appear to be working.

[paulparkinson]

Needs to be fixed regardless of course but how to reproduce this? Is this intermittent as I haven't see it?

[RichardExley]

I think this happens every time on every helidon-mp service when connecting to ATP.

[paulparkinson]

ok by "Then Fail" I thought you meant the actual service fails when you meant "then failed to start ONS message is logged".

I think that value may be getting set too late and so we should add the following at line 63 of OrderResource.java ...

static {
    System.setProperty("oracle.jdbc.fanEnabled", "false");
}

There should be a way to set this in microprofile-config.properties as well that I'm looking into...