search

elasticio / jdbc-component

Open Integration Hub component to access databases via JDBC API
https://www.openintegrationhub.org/
Other
0 stars 0 forks source link

Unexpected error `Shutdown in progress` #106

Open HannaTrotsenko opened 5 days ago

HannaTrotsenko commented 5 days ago

Component Bug Report

Description

Unexpected error during flow execution

java.lang.IllegalStateException: Shutdown in progress
    at java.lang.ApplicationShutdownHooks.add(ApplicationShutdownHooks.java:66)
    at java.lang.Runtime.addShutdownHook(Runtime.java:203)
    at io.elastic.jdbc.utils.Utils.getConnection(Utils.java:70)
    at io.elastic.jdbc.triggers.GetRowsPollingTrigger.execute(GetRowsPollingTrigger.java:67)
    at io.elastic.sailor.impl.MessageProcessorImpl.processMessage(MessageProcessorImpl.java:69)
    at io.elastic.sailor.impl.MessageConsumer.lambda$handleDelivery$0(MessageConsumer.java:79)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:750)

Logs:

[2024-07-03 07:50:42.702]: [INFO  tini (1)] Main child exited normally (with status '143')
[2024-07-03 07:50:42.658]: Successfully disconnected from AMQP
[2024-07-03 07:50:42.646]: No messages are being processed anymore
[2024-07-03 07:50:42.646]: About to disconnect from AMQP
[2024-07-03 07:50:42.645]: Waiting for 0 messages before exiting
[2024-07-03 07:50:42.645]: Decremented the number of messages concurrently processed to 0
[2024-07-03 07:50:42.644]: Reject received messages 1
[2024-07-03 07:50:42.644]: Execution stats: ExecutionStats{dataCount=0, errorCount=1, reboundCount=0}
[2024-07-03 07:50:42.643]: Successfully published data to 59d341e9037f7200184a408b_org
[2024-07-03 07:50:42.639]: Waiting for publish confirm
[2024-07-03 07:50:42.637]: isPersistentMessagesEnabled=false, isPublishConfirmEnabled=true, properties=#contentHeader<basic>(content-type=application/json, content-encoding=utf8, headers={stepId=step_1, start=1719993042545, messageId=82953321-6229-4738-b86e-85abe2c410d6, userId=59d22e7eeb865b0018adc248, execId=88139d05863b42b0b88be0ea061f0095, threadId=0b618eac-95c2-40e0-b56d-45e88dd4617b, compId=64a3d7d21bb50d0012dccffc, function=getRowsPolling, parentMessageId=01565a16-2fab-4af7-82a5-c1d447d10d07, x-eio-meta-trace-id=0b618eac-95c2-40e0-b56d-45e88dd4617b, containerId=29a37009-6007-4ba3-9013-c762a7db727e, taskId=6672c06ccb06860012de9ee2, workspaceId=59d341e9037f7200184a408b}, delivery-mode=1, priority=1, correlation-id=null, reply-to=null, expiration=null, message-id=null, timestamp=null, type=null, user-id=null, app-id=null, cluster-id=null)
[2024-07-03 07:50:42.637]: Publish options=59d341e9037f7200184a408b_org, retryCount=59d341e9037f7200184a408b.6672c06ccb06860012de9ee2/ordinary.step_1.error
[2024-07-03 07:50:42.636]: Opened publish channel
[2024-07-03 07:50:42.631]: Pushing to exchange=59d341e9037f7200184a408b_org, routingKey=59d341e9037f7200184a408b.6672c06ccb06860012de9ee2/ordinary.step_1.error
[2024-07-03 07:50:42.545]: Component execution failed
[2024-07-03 07:50:42.129]: Connecting to connection string
[2024-07-03 07:50:41.708]: Executing row polling trigger
[2024-07-03 07:50:41.705]: About to execute select trigger
[2024-07-03 07:50:41.705]: Got snapshot
[2024-07-03 07:50:41.704]: Now waiting for 1 messages to be processed before exiting
[2024-07-03 07:50:41.703]: Canceled all message consumers.
[2024-07-03 07:50:41.700]: Component descriptor from classpath: /component.json
[2024-07-03 07:50:41.699]: Canceling consumer amq.ctag-Wo5dflC55HuUvE82ctKvQw
[2024-07-03 07:50:41.698]: Shutdown hook called. Will exit gracefully now
[2024-07-03 07:50:41.697]: Message will be emitted as is
[2024-07-03 07:50:41.681]: No id to retrieve the object from storage found
[2024-07-03 07:50:41.681]: About to retrieve message body from storage
[2024-07-03 07:50:41.680]: Parsing message JSON
[2024-07-03 07:50:41.626]: Sending GET request to /v1/tasks/6672c06ccb06860012de9ee2/steps/step_1
[2024-07-03 07:50:41.620]: messageId=01565a16-2fab-4af7-82a5-c1d447d10d07, parentMessageId=unknown, threadId=0b618eac-95c2-40e0-b56d-45e88dd4617b
[2024-07-03 07:50:41.619]: Incremented the number of messages concurrently processed to 1
[2024-07-03 07:50:41.616]: Sailor started
[2024-07-03 07:50:41.615]: Consumer amq.ctag-Wo5dflC55HuUvE82ctKvQw is registered
[2024-07-03 07:50:41.615]: Subscribed consumer amq.ctag-Wo5dflC55HuUvE82ctKvQw. Waiting for messages to arrive ...
[2024-07-03 07:50:41.607]: Subscribing to queues
[2024-07-03 07:50:41.606]: Initializing function for execution
[2024-07-03 07:50:41.604]: Component id to be executed: 64a3d7d21bb50d0012dccffc
[2024-07-03 07:50:41.604]: Function to be executed: getRowsPolling
[2024-07-03 07:50:41.604]: Function Java class to be instantiated: io.elastic.jdbc.triggers.GetRowsPollingTrigger
[2024-07-03 07:50:41.604]: Instantiating component io.elastic.jdbc.triggers.GetRowsPollingTrigger
[2024-07-03 07:50:41.603]: Registered a graceful shutdown hook
[2024-07-03 07:50:41.603]: Processing flow step: step_1
[2024-07-03 07:50:41.601]: Opened subscribe channel
[2024-07-03 07:50:41.557]: Connected to AMQP with thread pool of 1 threads
[2024-07-03 07:50:41.304]: Connecting to AMQP
[2024-07-03 07:50:41.301]: Component descriptor from classpath: /component.json
[2024-07-03 07:50:40.898]: Sending GET request to /v1/tasks/6672c06ccb06860012de9ee2/steps/step_1
[2024-07-03 07:50:40.208]: Retrieving step data at: /v1/tasks/6672c06ccb06860012de9ee2/steps/step_1
[2024-07-03 07:50:40.149]: Component descriptor from classpath: /component.json
[2024-07-03 07:50:39.637]: About to init Sailor
[2024-07-03 07:50:39.506]: 07:50:39,049 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
[2024-07-03 07:50:39.506]: 07:50:38,930 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
[2024-07-03 07:50:39.506]: 07:50:39,113 |-ERROR in ch.qos.logback.core.joran.spi.Interpreter@6:22 - no applicable action for [pattern], current ElementPath  is [[configuration][appender][encoder][pattern]]
[2024-07-03 07:50:39.506]: 07:50:39,105 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
[2024-07-03 07:50:39.506]: 07:50:39,502 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
[2024-07-03 07:50:39.506]: 07:50:38,930 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [jar:file:/home/apprunner/build/dependencies/sailor-jvm-4.0.2.jar!/logback.xml]
[2024-07-03 07:50:39.506]: 07:50:39,501 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to TRACE
[2024-07-03 07:50:39.506]: (no message)
[2024-07-03 07:50:39.506]: 07:50:38,991 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@7f13d6e - URL [jar:file:/home/apprunner/build/dependencies/sailor-jvm-4.0.2.jar!/logback.xml] is not of type file
[2024-07-03 07:50:39.506]: 07:50:39,102 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
[2024-07-03 07:50:39.506]: 07:50:39,502 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
[2024-07-03 07:50:39.506]: 07:50:39,503 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@51cdd8a - Registering current configuration as safe fallback point
[2024-07-03 07:50:38.777]: [INFO  tini (1)] Spawned child process 'java' with pid '7'

Component Version

v2.5.8

Steps to Reproduce

  1. no steps

Actual Result

error happened and no way to anderstand the reason

Expected Result

mo clear understang the sourse of error ?

Workaround(s)

[Any known workaround(s) to circumvent the above issue]

A3a3e1 commented 5 days ago

The issue is caused by something killing the JVM before the code is trying to set up a JVM shutdown hook that would be closing the connection. https://github.com/elasticio/jdbc-component/blob/bc71063d0e1e9e6184aab5510e6318b87d693984/src/main/java/io/elastic/jdbc/utils/Utils.java#L70 The issue above took place on the staging server. We will keep monitoring the issue if it keeps happening on the production environment. Due to the complexity of finding out who/what has killed the JVM, my suggestion is leave the issue as is. If the issue will be raising more or less often, we should take a look more accurately. Otherwise, it can be ignored. As the only consequence is that the connection will be closed not by the code but by the DB server. It takes a bit longer, but not a big deal if it happens very rare.