You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@kafka.apache.org by ta...@gmail.com on 2024/05/29 13:57:12 UTC
standalone race condition?
Hi Folks,
I quite often get this issue with the kafka standalone and I really need it
fixing as I can't continue working like this so any help would be gratefully
received.
Scenario:
Server starts OK.
Deploy a connector or two using the REST API.
Then I deploy the JDBC connector and sometimes it deploys OK and sometimes
it doesn't - more usually doesn't. When this happens, I then can't use the
REST API at all - it doesn't accept any more connections - or at least it
doesn't seem to. The below trace is deploying the connector when it's
failing - I had literally just deployed it into the same standalone instance
and then deleted it and it had all worked fine but this time it decided not
to. When it works, it works just fine ! It seems to be something blocking it
from recognising that the connector has actually started OK - like one of
the many lambda callbacks didn't work or was mistimed so that a wait
happened after a notify on a thread and so the wait just sticks there? I've
looked at the standalone code and can't figure it out - but there's a lot
going on ! I don't believe that this is the connectors fault as I've had
this issue before on other connectors - it just seems to happen more on this
connector - perhaps the connector calls-back too quickly or too slowly?
Thanks for any help,
John.
[2024-05-29 14:47:04,335] DEBUG Getting plugin class loader:
'PluginClassLoader{pluginLocation=file:/C:/opsis/connectors/opsis-sagex3-con
nector-0.1.0-SNAPSHOT.jar}' for connector:
io.confluent.connect.jdbc.JdbcSourceConnector
(org.apache.kafka.connect.runtime.isolation.DelegatingClassLoader:94)
[2024-05-29 14:47:04,336] INFO JdbcSourceConnectorConfig values:
batch.max.rows = 100
catalog.pattern = null
connection.attempts = 3
connection.backoff.ms = 10000
connection.password = [hidden]
connection.url = [hidden]
connection.user = [hidden]
db.timezone = UTC
dialect.name =
incrementing.column.name = ROWID
mode = timestamp+incrementing
numeric.mapping = null
numeric.precision.mapping = false
poll.interval.ms = 5000
query =
query.retry.attempts = -1
query.suffix =
quote.sql.identifiers = ALWAYS
schema.pattern = [hidden]
table.blacklist = []
table.monitoring.startup.polling.limit.ms = 10000
table.poll.interval.ms = 60000
table.types = [VIEW]
table.whitelist = [hidden]
timestamp.column.name = [hidden]
timestamp.delay.interval.ms = 0
timestamp.granularity = connect_logical
timestamp.initial = 1714518000000
topic.prefix =
transaction.isolation.mode = DEFAULT
validate.non.null = false
(io.confluent.connect.jdbc.source.JdbcSourceConnectorConfig:370)
[2024-05-29 14:47:04,338] INFO AbstractConfig values:
(org.apache.kafka.common.config.AbstractConfig:370)
[2024-05-29 14:47:04,339] DEBUG [SageX3Connector|worker] Getting plugin
class loader:
'PluginClassLoader{pluginLocation=file:/C:/opsis/connectors/opsis-sagex3-con
nector-0.1.0-SNAPSHOT.jar}' for connector:
io.confluent.connect.jdbc.JdbcSourceConnector
(org.apache.kafka.connect.runtime.isolation.DelegatingClassLoader:94)
[2024-05-29 14:47:04,339] INFO [SageX3Connector|worker] Creating connector
SageX3Connector of type io.confluent.connect.jdbc.JdbcSourceConnector
(org.apache.kafka.connect.runtime.Worker:309)
[2024-05-29 14:47:04,340] INFO [SageX3Connector|worker]
SourceConnectorConfig values:
config.action.reload = restart
connector.class = io.confluent.connect.jdbc.JdbcSourceConnector
errors.log.enable = false
errors.log.include.messages = false
errors.retry.delay.max.ms = 60000
errors.retry.timeout = 0
errors.tolerance = none
exactly.once.support = requested
header.converter = null
key.converter = null
name = SageX3Connector
offsets.storage.topic = null
predicates = []
tasks.max = 1
topic.creation.groups = []
transaction.boundary = poll
transaction.boundary.interval.ms = null
transforms = []
value.converter = null
(org.apache.kafka.connect.runtime.SourceConnectorConfig:370)
[2024-05-29 14:47:04,340] INFO [SageX3Connector|worker]
EnrichedConnectorConfig values:
config.action.reload = restart
connector.class = io.confluent.connect.jdbc.JdbcSourceConnector
errors.log.enable = false
errors.log.include.messages = false
errors.retry.delay.max.ms = 60000
errors.retry.timeout = 0
errors.tolerance = none
exactly.once.support = requested
header.converter = null
key.converter = null
name = SageX3Connector
offsets.storage.topic = null
predicates = []
tasks.max = 1
topic.creation.groups = []
transaction.boundary = poll
transaction.boundary.interval.ms = null
transforms = []
value.converter = null
(org.apache.kafka.connect.runtime.ConnectorConfig$EnrichedConnectorConfig:37
0)
[2024-05-29 14:47:04,341] INFO [SageX3Connector|worker] Instantiated
connector SageX3Connector with version 10.7.4 of type class
io.confluent.connect.jdbc.JdbcSourceConnector
(org.apache.kafka.connect.runtime.Worker:331)
[2024-05-29 14:47:04,341] INFO [SageX3Connector|worker] Finished creating
connector SageX3Connector (org.apache.kafka.connect.runtime.Worker:352)
[2024-05-29 14:47:04,341] DEBUG [SageX3Connector|worker]
WorkerConnector{id=SageX3Connector} Initializing connector SageX3Connector
(org.apache.kafka.connect.runtime.WorkerConnector:167)
[2024-05-29 14:47:04,342] DEBUG [SageX3Connector|worker]
WorkerConnector{id=SageX3Connector} Transition connector to STARTED
(org.apache.kafka.connect.runtime.WorkerConnector:369)
[2024-05-29 14:47:04,342] INFO [SageX3Connector|worker] Starting JDBC Source
Connector (io.confluent.connect.jdbc.JdbcSourceConnector:71)
[2024-05-29 14:47:04,343] INFO [SageX3Connector|worker]
JdbcSourceConnectorConfig values:
batch.max.rows = 100
catalog.pattern = null
connection.attempts = 3
connection.backoff.ms = 10000
connection.password = [hidden]
connection.url = [hidden]
connection.user = [hidden]
db.timezone = UTC
dialect.name =
incrementing.column.name = ROWID
mode = timestamp+incrementing
numeric.mapping = null
numeric.precision.mapping = false
poll.interval.ms = 5000
query =
query.retry.attempts = -1
query.suffix =
quote.sql.identifiers = ALWAYS
schema.pattern = [hidden]
table.blacklist = []
table.monitoring.startup.polling.limit.ms = 10000
table.poll.interval.ms = 60000
table.types = [VIEW]
table.whitelist = [hidden]
timestamp.column.name = [hidden]
timestamp.delay.interval.ms = 0
timestamp.granularity = connect_logical
timestamp.initial = 1714518000000
topic.prefix =
transaction.isolation.mode = DEFAULT
validate.non.null = false
(io.confluent.connect.jdbc.source.JdbcSourceConnectorConfig:370)
[2024-05-29 14:47:04,343] INFO [SageX3Connector|worker] Validating JDBC URL.
(io.confluent.connect.jdbc.dialect.DatabaseDialects:171)
[2024-05-29 14:47:04,344] INFO [SageX3Connector|worker] Validated JDBC URL.
(io.confluent.connect.jdbc.dialect.DatabaseDialects:174)
[2024-05-29 14:47:04,344] INFO [SageX3Connector|worker] Validating JDBC URL.
(io.confluent.connect.jdbc.dialect.DatabaseDialects:171)
[2024-05-29 14:47:04,345] INFO [SageX3Connector|worker] Validated JDBC URL.
(io.confluent.connect.jdbc.dialect.DatabaseDialects:174)
[2024-05-29 14:47:04,345] INFO [SageX3Connector|worker] Initial connection
attempt with the database.
(io.confluent.connect.jdbc.JdbcSourceConnector:94)
[2024-05-29 14:47:04,369] INFO [SageX3Connector|worker] Starting thread to
monitor tables. (io.confluent.connect.jdbc.source.TableMonitorThread:82)
[2024-05-29 14:47:04,369] INFO SourceConnectorConfig values:
config.action.reload = restart
connector.class = io.confluent.connect.jdbc.JdbcSourceConnector
errors.log.enable = false
errors.log.include.messages = false
errors.retry.delay.max.ms = 60000
errors.retry.timeout = 0
errors.tolerance = none
exactly.once.support = requested
header.converter = null
key.converter = null
name = SageX3Connector
offsets.storage.topic = null
predicates = []
tasks.max = 1
topic.creation.groups = []
transaction.boundary = poll
transaction.boundary.interval.ms = null
transforms = []
value.converter = null
(org.apache.kafka.connect.runtime.SourceConnectorConfig:370)
[2024-05-29 14:47:04,372] INFO EnrichedConnectorConfig values:
config.action.reload = restart
connector.class = io.confluent.connect.jdbc.JdbcSourceConnector
errors.log.enable = false
errors.log.include.messages = false
errors.retry.delay.max.ms = 60000
errors.retry.timeout = 0
errors.tolerance = none
exactly.once.support = requested
header.converter = null
key.converter = null
name = SageX3Connector
offsets.storage.topic = null
predicates = []
tasks.max = 1
topic.creation.groups = []
transaction.boundary = poll
transaction.boundary.interval.ms = null
transforms = []
value.converter = null
(org.apache.kafka.connect.runtime.ConnectorConfig$EnrichedConnectorConfig:37
0)
[2024-05-29 14:47:04,425] DEBUG Connector SageX3Connector task count changed
from 0 to 1 (org.apache.kafka.connect.runtime.AbstractHerder:852)
[2024-05-29 14:47:04,425] INFO [SageX3Connector|worker]
SourceConnectorConfig values:
config.action.reload = restart
connector.class = io.confluent.connect.jdbc.JdbcSourceConnector
errors.log.enable = false
errors.log.include.messages = false
errors.retry.delay.max.ms = 60000
errors.retry.timeout = 0
errors.tolerance = none
exactly.once.support = requested
header.converter = null
key.converter = null
name = SageX3Connector
offsets.storage.topic = null
predicates = []
tasks.max = 1
topic.creation.groups = []
transaction.boundary = poll
transaction.boundary.interval.ms = null
transforms = []
value.converter = null
(org.apache.kafka.connect.runtime.SourceConnectorConfig:370)
[2024-05-29 14:47:04,426] DEBUG Reconfiguring connector SageX3Connector:
writing new updated configurations for tasks
(org.apache.kafka.connect.runtime.AbstractHerder:864)
[2024-05-29 14:47:04,428] INFO [SageX3Connector|worker]
EnrichedConnectorConfig values:
config.action.reload = restart
connector.class = io.confluent.connect.jdbc.JdbcSourceConnector
errors.log.enable = false
errors.log.include.messages = false
errors.retry.delay.max.ms = 60000
errors.retry.timeout = 0
errors.tolerance = none
exactly.once.support = requested
header.converter = null
key.converter = null
name = SageX3Connector
offsets.storage.topic = null
predicates = []
tasks.max = 1
topic.creation.groups = []
transaction.boundary = poll
transaction.boundary.interval.ms = null
transforms = []
value.converter = null
(org.apache.kafka.connect.runtime.ConnectorConfig$EnrichedConnectorConfig:37
0)
[2024-05-29 14:47:04,429] DEBUG [SageX3Connector|worker] Connector
SageX3Connector task count changed from 0 to 1
(org.apache.kafka.connect.runtime.AbstractHerder:852)
[2024-05-29 14:47:04,429] DEBUG [SageX3Connector|worker] Reconfiguring
connector SageX3Connector: writing new updated configurations for tasks
(org.apache.kafka.connect.runtime.AbstractHerder:864)
[2024-05-29 14:47:32,460] DEBUG Uncaught exception in REST call to
/connectors/SageX3Connector/config
(org.apache.kafka.connect.runtime.rest.errors.ConnectExceptionMapper:42)
org.apache.kafka.connect.runtime.rest.errors.ConnectRestException: Request
timed out
at
org.apache.kafka.connect.runtime.rest.HerderRequestHandler.completeRequest(H
erderRequestHandler.java:89)
RE: standalone race condition?
Posted by ta...@gmail.com.
To add to my own comments 😊
I’ve put debug on to the adapter that’s failing more than the others and I observe that sometimes it fails to start up and sometimes it doesn’t. Either way the call back to the REST interface to tell it that it can return back to the API doesn’t work and the original HTTP call timesout.
When it does fail to startup the whole REST API dies and goes unresponsive – all HTTP calls timeout with no response i.e. a query to see what connectors are working.
Is there documentation showing all the various threads/lambdas at play here?
Thanks,
John.
From: talljhawkins@gmail.com <ta...@gmail.com>
Sent: Wednesday, May 29, 2024 2:57 PM
To: dev@kafka.apache.org
Subject: standalone race condition?
Hi Folks,
I quite often get this issue with the kafka standalone and I really need it fixing as I can’t continue working like this so any help would be gratefully received…
Scenario:
Server starts OK.
Deploy a connector or two using the REST API.
Then I deploy the JDBC connector and sometimes it deploys OK and sometimes it doesn’t – more usually doesn’t. When this happens, I then can’t use the REST API at all – it doesn’t accept any more connections – or at least it doesn’t seem to. The below trace is deploying the connector when it’s failing – I had literally just deployed it into the same standalone instance and then deleted it and it had all worked fine but this time it decided not to. When it works, it works just fine ! It seems to be something blocking it from recognising that the connector has actually started OK – like one of the many lambda callbacks didn’t work or was mistimed so that a wait happened after a notify on a thread and so the wait just sticks there? I’ve looked at the standalone code and can’t figure it out – but there’s a lot going on ! I don’t believe that this is the connectors fault as I’ve had this issue before on other connectors – it just seems to happen more on this connector – perhaps the connector calls-back too quickly or too slowly?
Thanks for any help,
John.
[2024-05-29 14:47:04,335] DEBUG Getting plugin class loader: 'PluginClassLoader{pluginLocation=file:/C:/opsis/connectors/opsis-sagex3-connector-0.1.0-SNAPSHOT.jar}' for connector: io.confluent.connect.jdbc.JdbcSourceConnector (org.apache.kafka.connect.runtime.isolation.DelegatingClassLoader:94)
[2024-05-29 14:47:04,336] INFO JdbcSourceConnectorConfig values:
batch.max.rows = 100
catalog.pattern = null
connection.attempts = 3
connection.backoff.ms = 10000
connection.password = [hidden]
connection.url = [hidden]
connection.user = [hidden]
db.timezone = UTC
dialect.name =
incrementing.column.name = ROWID
mode = timestamp+incrementing
numeric.mapping = null
numeric.precision.mapping = false
poll.interval.ms = 5000
query =
query.retry.attempts = -1
query.suffix =
quote.sql.identifiers = ALWAYS
schema.pattern = [hidden]
table.blacklist = []
table.monitoring.startup.polling.limit.ms = 10000
table.poll.interval.ms = 60000
table.types = [VIEW]
table.whitelist = [hidden]
timestamp.column.name = [hidden]
timestamp.delay.interval.ms = 0
timestamp.granularity = connect_logical
timestamp.initial = 1714518000000
topic.prefix =
transaction.isolation.mode = DEFAULT
validate.non.null = false
(io.confluent.connect.jdbc.source.JdbcSourceConnectorConfig:370)
[2024-05-29 14:47:04,338] INFO AbstractConfig values:
(org.apache.kafka.common.config.AbstractConfig:370)
[2024-05-29 14:47:04,339] DEBUG [SageX3Connector|worker] Getting plugin class loader: 'PluginClassLoader{pluginLocation=file:/C:/opsis/connectors/opsis-sagex3-connector-0.1.0-SNAPSHOT.jar}' for connector: io.confluent.connect.jdbc.JdbcSourceConnector (org.apache.kafka.connect.runtime.isolation.DelegatingClassLoader:94)
[2024-05-29 14:47:04,339] INFO [SageX3Connector|worker] Creating connector SageX3Connector of type io.confluent.connect.jdbc.JdbcSourceConnector (org.apache.kafka.connect.runtime.Worker:309)
[2024-05-29 14:47:04,340] INFO [SageX3Connector|worker] SourceConnectorConfig values:
config.action.reload = restart
connector.class = io.confluent.connect.jdbc.JdbcSourceConnector
errors.log.enable = false
errors.log.include.messages = false
errors.retry.delay.max.ms = 60000
errors.retry.timeout = 0
errors.tolerance = none
exactly.once.support = requested
header.converter = null
key.converter = null
name = SageX3Connector
offsets.storage.topic = null
predicates = []
tasks.max = 1
topic.creation.groups = []
transaction.boundary = poll
transaction.boundary.interval.ms = null
transforms = []
value.converter = null
(org.apache.kafka.connect.runtime.SourceConnectorConfig:370)
[2024-05-29 14:47:04,340] INFO [SageX3Connector|worker] EnrichedConnectorConfig values:
config.action.reload = restart
connector.class = io.confluent.connect.jdbc.JdbcSourceConnector
errors.log.enable = false
errors.log.include.messages = false
errors.retry.delay.max.ms = 60000
errors.retry.timeout = 0
errors.tolerance = none
exactly.once.support = requested
header.converter = null
key.converter = null
name = SageX3Connector
offsets.storage.topic = null
predicates = []
tasks.max = 1
topic.creation.groups = []
transaction.boundary = poll
transaction.boundary.interval.ms = null
transforms = []
value.converter = null
(org.apache.kafka.connect.runtime.ConnectorConfig$EnrichedConnectorConfig:370)
[2024-05-29 14:47:04,341] INFO [SageX3Connector|worker] Instantiated connector SageX3Connector with version 10.7.4 of type class io.confluent.connect.jdbc.JdbcSourceConnector (org.apache.kafka.connect.runtime.Worker:331)
[2024-05-29 14:47:04,341] INFO [SageX3Connector|worker] Finished creating connector SageX3Connector (org.apache.kafka.connect.runtime.Worker:352)
[2024-05-29 14:47:04,341] DEBUG [SageX3Connector|worker] WorkerConnector{id=SageX3Connector} Initializing connector SageX3Connector (org.apache.kafka.connect.runtime.WorkerConnector:167)
[2024-05-29 14:47:04,342] DEBUG [SageX3Connector|worker] WorkerConnector{id=SageX3Connector} Transition connector to STARTED (org.apache.kafka.connect.runtime.WorkerConnector:369)
[2024-05-29 14:47:04,342] INFO [SageX3Connector|worker] Starting JDBC Source Connector (io.confluent.connect.jdbc.JdbcSourceConnector:71)
[2024-05-29 14:47:04,343] INFO [SageX3Connector|worker] JdbcSourceConnectorConfig values:
batch.max.rows = 100
catalog.pattern = null
connection.attempts = 3
connection.backoff.ms = 10000
connection.password = [hidden]
connection.url = [hidden]
connection.user = [hidden]
db.timezone = UTC
dialect.name =
incrementing.column.name = ROWID
mode = timestamp+incrementing
numeric.mapping = null
numeric.precision.mapping = false
poll.interval.ms = 5000
query =
query.retry.attempts = -1
query.suffix =
quote.sql.identifiers = ALWAYS
schema.pattern = [hidden]
table.blacklist = []
table.monitoring.startup.polling.limit.ms = 10000
table.poll.interval.ms = 60000
table.types = [VIEW]
table.whitelist = [hidden]
timestamp.column.name = [hidden]
timestamp.delay.interval.ms = 0
timestamp.granularity = connect_logical
timestamp.initial = 1714518000000
topic.prefix =
transaction.isolation.mode = DEFAULT
validate.non.null = false
(io.confluent.connect.jdbc.source.JdbcSourceConnectorConfig:370)
[2024-05-29 14:47:04,343] INFO [SageX3Connector|worker] Validating JDBC URL. (io.confluent.connect.jdbc.dialect.DatabaseDialects:171)
[2024-05-29 14:47:04,344] INFO [SageX3Connector|worker] Validated JDBC URL. (io.confluent.connect.jdbc.dialect.DatabaseDialects:174)
[2024-05-29 14:47:04,344] INFO [SageX3Connector|worker] Validating JDBC URL. (io.confluent.connect.jdbc.dialect.DatabaseDialects:171)
[2024-05-29 14:47:04,345] INFO [SageX3Connector|worker] Validated JDBC URL. (io.confluent.connect.jdbc.dialect.DatabaseDialects:174)
[2024-05-29 14:47:04,345] INFO [SageX3Connector|worker] Initial connection attempt with the database. (io.confluent.connect.jdbc.JdbcSourceConnector:94)
[2024-05-29 14:47:04,369] INFO [SageX3Connector|worker] Starting thread to monitor tables. (io.confluent.connect.jdbc.source.TableMonitorThread:82)
[2024-05-29 14:47:04,369] INFO SourceConnectorConfig values:
config.action.reload = restart
connector.class = io.confluent.connect.jdbc.JdbcSourceConnector
errors.log.enable = false
errors.log.include.messages = false
errors.retry.delay.max.ms = 60000
errors.retry.timeout = 0
errors.tolerance = none
exactly.once.support = requested
header.converter = null
key.converter = null
name = SageX3Connector
offsets.storage.topic = null
predicates = []
tasks.max = 1
topic.creation.groups = []
transaction.boundary = poll
transaction.boundary.interval.ms = null
transforms = []
value.converter = null
(org.apache.kafka.connect.runtime.SourceConnectorConfig:370)
[2024-05-29 14:47:04,372] INFO EnrichedConnectorConfig values:
config.action.reload = restart
connector.class = io.confluent.connect.jdbc.JdbcSourceConnector
errors.log.enable = false
errors.log.include.messages = false
errors.retry.delay.max.ms = 60000
errors.retry.timeout = 0
errors.tolerance = none
exactly.once.support = requested
header.converter = null
key.converter = null
name = SageX3Connector
offsets.storage.topic = null
predicates = []
tasks.max = 1
topic.creation.groups = []
transaction.boundary = poll
transaction.boundary.interval.ms = null
transforms = []
value.converter = null
(org.apache.kafka.connect.runtime.ConnectorConfig$EnrichedConnectorConfig:370)
[2024-05-29 14:47:04,425] DEBUG Connector SageX3Connector task count changed from 0 to 1 (org.apache.kafka.connect.runtime.AbstractHerder:852)
[2024-05-29 14:47:04,425] INFO [SageX3Connector|worker] SourceConnectorConfig values:
config.action.reload = restart
connector.class = io.confluent.connect.jdbc.JdbcSourceConnector
errors.log.enable = false
errors.log.include.messages = false
errors.retry.delay.max.ms = 60000
errors.retry.timeout = 0
errors.tolerance = none
exactly.once.support = requested
header.converter = null
key.converter = null
name = SageX3Connector
offsets.storage.topic = null
predicates = []
tasks.max = 1
topic.creation.groups = []
transaction.boundary = poll
transaction.boundary.interval.ms = null
transforms = []
value.converter = null
(org.apache.kafka.connect.runtime.SourceConnectorConfig:370)
[2024-05-29 14:47:04,426] DEBUG Reconfiguring connector SageX3Connector: writing new updated configurations for tasks (org.apache.kafka.connect.runtime.AbstractHerder:864)
[2024-05-29 14:47:04,428] INFO [SageX3Connector|worker] EnrichedConnectorConfig values:
config.action.reload = restart
connector.class = io.confluent.connect.jdbc.JdbcSourceConnector
errors.log.enable = false
errors.log.include.messages = false
errors.retry.delay.max.ms = 60000
errors.retry.timeout = 0
errors.tolerance = none
exactly.once.support = requested
header.converter = null
key.converter = null
name = SageX3Connector
offsets.storage.topic = null
predicates = []
tasks.max = 1
topic.creation.groups = []
transaction.boundary = poll
transaction.boundary.interval.ms = null
transforms = []
value.converter = null
(org.apache.kafka.connect.runtime.ConnectorConfig$EnrichedConnectorConfig:370)
[2024-05-29 14:47:04,429] DEBUG [SageX3Connector|worker] Connector SageX3Connector task count changed from 0 to 1 (org.apache.kafka.connect.runtime.AbstractHerder:852)
[2024-05-29 14:47:04,429] DEBUG [SageX3Connector|worker] Reconfiguring connector SageX3Connector: writing new updated configurations for tasks (org.apache.kafka.connect.runtime.AbstractHerder:864)
[2024-05-29 14:47:32,460] DEBUG Uncaught exception in REST call to /connectors/SageX3Connector/config (org.apache.kafka.connect.runtime.rest.errors.ConnectExceptionMapper:42)
org.apache.kafka.connect.runtime.rest.errors.ConnectRestException: Request timed out
at org.apache.kafka.connect.runtime.rest.HerderRequestHandler.completeRequest(HerderRequestHandler.java:89)
Re: standalone race condition?
Posted by Greg Harris <gr...@aiven.io.INVALID>.
Hi John,
Thanks for your question!
I wasn't able to identify anything obviously wrong from your logfile and
visible configurations. REST timeouts are something that we have ongoing
problems with, and they're usually caused by blocking plugins.
You can capture some additional diagnostics with `jstack` to see what all
of the threads in the process are doing, and see where something might be
stuck.
You can also try to switch to the Distributed mode, which has much more
complex behaviors, but has also received more attention and improvement in
this area. Notably this change [1] reports potential problems that may
cause timeouts to occur.
There are also some known issues with old versions of source connectors
causing stalling on newer framework versions [2] so make sure you're using
the latest connector version available.
If you manage to find a deadlock or otherwise undesirable stalling, we
would gladly accept a bug report with the results of your debugging. You
may also consider reporting this issue to your connector developer.
Hope this helps,
Greg
[1] https://issues.apache.org/jira/browse/KAFKA-15563
[2] https://issues.apache.org/jira/browse/KAFKA-15090
On Wed, May 29, 2024 at 7:44 AM <ta...@gmail.com> wrote:
> Hi Folks,
>
> I quite often get this issue with the kafka standalone and I really need it
> fixing as I can't continue working like this so any help would be
> gratefully
> received.
>
>
>
> Scenario:
>
> Server starts OK.
>
> Deploy a connector or two using the REST API.
>
> Then I deploy the JDBC connector and sometimes it deploys OK and sometimes
> it doesn't - more usually doesn't. When this happens, I then can't use the
> REST API at all - it doesn't accept any more connections - or at least it
> doesn't seem to. The below trace is deploying the connector when it's
> failing - I had literally just deployed it into the same standalone
> instance
> and then deleted it and it had all worked fine but this time it decided not
> to. When it works, it works just fine ! It seems to be something blocking
> it
> from recognising that the connector has actually started OK - like one of
> the many lambda callbacks didn't work or was mistimed so that a wait
> happened after a notify on a thread and so the wait just sticks there? I've
> looked at the standalone code and can't figure it out - but there's a lot
> going on ! I don't believe that this is the connectors fault as I've had
> this issue before on other connectors - it just seems to happen more on
> this
> connector - perhaps the connector calls-back too quickly or too slowly?
>
>
>
> Thanks for any help,
>
> John.
>
>
>
> [2024-05-29 14:47:04,335] DEBUG Getting plugin class loader:
>
> 'PluginClassLoader{pluginLocation=file:/C:/opsis/connectors/opsis-sagex3-con
> nector-0.1.0-SNAPSHOT.jar}' for connector:
> io.confluent.connect.jdbc.JdbcSourceConnector
> (org.apache.kafka.connect.runtime.isolation.DelegatingClassLoader:94)
>
> [2024-05-29 14:47:04,336] INFO JdbcSourceConnectorConfig values:
>
> batch.max.rows = 100
>
> catalog.pattern = null
>
> connection.attempts = 3
>
> connection.backoff.ms = 10000
>
> connection.password = [hidden]
>
> connection.url = [hidden]
>
> connection.user = [hidden]
>
> db.timezone = UTC
>
> dialect.name =
>
> incrementing.column.name = ROWID
>
> mode = timestamp+incrementing
>
> numeric.mapping = null
>
> numeric.precision.mapping = false
>
> poll.interval.ms = 5000
>
> query =
>
> query.retry.attempts = -1
>
> query.suffix =
>
> quote.sql.identifiers = ALWAYS
>
> schema.pattern = [hidden]
>
> table.blacklist = []
>
> table.monitoring.startup.polling.limit.ms = 10000
>
> table.poll.interval.ms = 60000
>
> table.types = [VIEW]
>
> table.whitelist = [hidden]
>
> timestamp.column.name = [hidden]
>
> timestamp.delay.interval.ms = 0
>
> timestamp.granularity = connect_logical
>
> timestamp.initial = 1714518000000
>
> topic.prefix =
>
> transaction.isolation.mode = DEFAULT
>
> validate.non.null = false
>
> (io.confluent.connect.jdbc.source.JdbcSourceConnectorConfig:370)
>
> [2024-05-29 14:47:04,338] INFO AbstractConfig values:
>
> (org.apache.kafka.common.config.AbstractConfig:370)
>
> [2024-05-29 14:47:04,339] DEBUG [SageX3Connector|worker] Getting plugin
> class loader:
>
> 'PluginClassLoader{pluginLocation=file:/C:/opsis/connectors/opsis-sagex3-con
> nector-0.1.0-SNAPSHOT.jar}' for connector:
> io.confluent.connect.jdbc.JdbcSourceConnector
> (org.apache.kafka.connect.runtime.isolation.DelegatingClassLoader:94)
>
> [2024-05-29 14:47:04,339] INFO [SageX3Connector|worker] Creating connector
> SageX3Connector of type io.confluent.connect.jdbc.JdbcSourceConnector
> (org.apache.kafka.connect.runtime.Worker:309)
>
> [2024-05-29 14:47:04,340] INFO [SageX3Connector|worker]
> SourceConnectorConfig values:
>
> config.action.reload = restart
>
> connector.class = io.confluent.connect.jdbc.JdbcSourceConnector
>
> errors.log.enable = false
>
> errors.log.include.messages = false
>
> errors.retry.delay.max.ms = 60000
>
> errors.retry.timeout = 0
>
> errors.tolerance = none
>
> exactly.once.support = requested
>
> header.converter = null
>
> key.converter = null
>
> name = SageX3Connector
>
> offsets.storage.topic = null
>
> predicates = []
>
> tasks.max = 1
>
> topic.creation.groups = []
>
> transaction.boundary = poll
>
> transaction.boundary.interval.ms = null
>
> transforms = []
>
> value.converter = null
>
> (org.apache.kafka.connect.runtime.SourceConnectorConfig:370)
>
> [2024-05-29 14:47:04,340] INFO [SageX3Connector|worker]
> EnrichedConnectorConfig values:
>
> config.action.reload = restart
>
> connector.class = io.confluent.connect.jdbc.JdbcSourceConnector
>
> errors.log.enable = false
>
> errors.log.include.messages = false
>
> errors.retry.delay.max.ms = 60000
>
> errors.retry.timeout = 0
>
> errors.tolerance = none
>
> exactly.once.support = requested
>
> header.converter = null
>
> key.converter = null
>
> name = SageX3Connector
>
> offsets.storage.topic = null
>
> predicates = []
>
> tasks.max = 1
>
> topic.creation.groups = []
>
> transaction.boundary = poll
>
> transaction.boundary.interval.ms = null
>
> transforms = []
>
> value.converter = null
>
>
> (org.apache.kafka.connect.runtime.ConnectorConfig$EnrichedConnectorConfig:37
> 0)
>
> [2024-05-29 14:47:04,341] INFO [SageX3Connector|worker] Instantiated
> connector SageX3Connector with version 10.7.4 of type class
> io.confluent.connect.jdbc.JdbcSourceConnector
> (org.apache.kafka.connect.runtime.Worker:331)
>
> [2024-05-29 14:47:04,341] INFO [SageX3Connector|worker] Finished creating
> connector SageX3Connector (org.apache.kafka.connect.runtime.Worker:352)
>
> [2024-05-29 14:47:04,341] DEBUG [SageX3Connector|worker]
> WorkerConnector{id=SageX3Connector} Initializing connector SageX3Connector
> (org.apache.kafka.connect.runtime.WorkerConnector:167)
>
> [2024-05-29 14:47:04,342] DEBUG [SageX3Connector|worker]
> WorkerConnector{id=SageX3Connector} Transition connector to STARTED
> (org.apache.kafka.connect.runtime.WorkerConnector:369)
>
> [2024-05-29 14:47:04,342] INFO [SageX3Connector|worker] Starting JDBC
> Source
> Connector (io.confluent.connect.jdbc.JdbcSourceConnector:71)
>
> [2024-05-29 14:47:04,343] INFO [SageX3Connector|worker]
> JdbcSourceConnectorConfig values:
>
> batch.max.rows = 100
>
> catalog.pattern = null
>
> connection.attempts = 3
>
> connection.backoff.ms = 10000
>
> connection.password = [hidden]
>
> connection.url = [hidden]
>
> connection.user = [hidden]
>
> db.timezone = UTC
>
> dialect.name =
>
> incrementing.column.name = ROWID
>
> mode = timestamp+incrementing
>
> numeric.mapping = null
>
> numeric.precision.mapping = false
>
> poll.interval.ms = 5000
>
> query =
>
> query.retry.attempts = -1
>
> query.suffix =
>
> quote.sql.identifiers = ALWAYS
>
> schema.pattern = [hidden]
>
> table.blacklist = []
>
> table.monitoring.startup.polling.limit.ms = 10000
>
> table.poll.interval.ms = 60000
>
> table.types = [VIEW]
>
> table.whitelist = [hidden]
>
> timestamp.column.name = [hidden]
>
> timestamp.delay.interval.ms = 0
>
> timestamp.granularity = connect_logical
>
> timestamp.initial = 1714518000000
>
> topic.prefix =
>
> transaction.isolation.mode = DEFAULT
>
> validate.non.null = false
>
> (io.confluent.connect.jdbc.source.JdbcSourceConnectorConfig:370)
>
> [2024-05-29 14:47:04,343] INFO [SageX3Connector|worker] Validating JDBC
> URL.
> (io.confluent.connect.jdbc.dialect.DatabaseDialects:171)
>
> [2024-05-29 14:47:04,344] INFO [SageX3Connector|worker] Validated JDBC URL.
> (io.confluent.connect.jdbc.dialect.DatabaseDialects:174)
>
> [2024-05-29 14:47:04,344] INFO [SageX3Connector|worker] Validating JDBC
> URL.
> (io.confluent.connect.jdbc.dialect.DatabaseDialects:171)
>
> [2024-05-29 14:47:04,345] INFO [SageX3Connector|worker] Validated JDBC URL.
> (io.confluent.connect.jdbc.dialect.DatabaseDialects:174)
>
> [2024-05-29 14:47:04,345] INFO [SageX3Connector|worker] Initial connection
> attempt with the database.
> (io.confluent.connect.jdbc.JdbcSourceConnector:94)
>
> [2024-05-29 14:47:04,369] INFO [SageX3Connector|worker] Starting thread to
> monitor tables. (io.confluent.connect.jdbc.source.TableMonitorThread:82)
>
> [2024-05-29 14:47:04,369] INFO SourceConnectorConfig values:
>
> config.action.reload = restart
>
> connector.class = io.confluent.connect.jdbc.JdbcSourceConnector
>
> errors.log.enable = false
>
> errors.log.include.messages = false
>
> errors.retry.delay.max.ms = 60000
>
> errors.retry.timeout = 0
>
> errors.tolerance = none
>
> exactly.once.support = requested
>
> header.converter = null
>
> key.converter = null
>
> name = SageX3Connector
>
> offsets.storage.topic = null
>
> predicates = []
>
> tasks.max = 1
>
> topic.creation.groups = []
>
> transaction.boundary = poll
>
> transaction.boundary.interval.ms = null
>
> transforms = []
>
> value.converter = null
>
> (org.apache.kafka.connect.runtime.SourceConnectorConfig:370)
>
> [2024-05-29 14:47:04,372] INFO EnrichedConnectorConfig values:
>
> config.action.reload = restart
>
> connector.class = io.confluent.connect.jdbc.JdbcSourceConnector
>
> errors.log.enable = false
>
> errors.log.include.messages = false
>
> errors.retry.delay.max.ms = 60000
>
> errors.retry.timeout = 0
>
> errors.tolerance = none
>
> exactly.once.support = requested
>
> header.converter = null
>
> key.converter = null
>
> name = SageX3Connector
>
> offsets.storage.topic = null
>
> predicates = []
>
> tasks.max = 1
>
> topic.creation.groups = []
>
> transaction.boundary = poll
>
> transaction.boundary.interval.ms = null
>
> transforms = []
>
> value.converter = null
>
>
> (org.apache.kafka.connect.runtime.ConnectorConfig$EnrichedConnectorConfig:37
> 0)
>
> [2024-05-29 14:47:04,425] DEBUG Connector SageX3Connector task count
> changed
> from 0 to 1 (org.apache.kafka.connect.runtime.AbstractHerder:852)
>
> [2024-05-29 14:47:04,425] INFO [SageX3Connector|worker]
> SourceConnectorConfig values:
>
> config.action.reload = restart
>
> connector.class = io.confluent.connect.jdbc.JdbcSourceConnector
>
> errors.log.enable = false
>
> errors.log.include.messages = false
>
> errors.retry.delay.max.ms = 60000
>
> errors.retry.timeout = 0
>
> errors.tolerance = none
>
> exactly.once.support = requested
>
> header.converter = null
>
> key.converter = null
>
> name = SageX3Connector
>
> offsets.storage.topic = null
>
> predicates = []
>
> tasks.max = 1
>
> topic.creation.groups = []
>
> transaction.boundary = poll
>
> transaction.boundary.interval.ms = null
>
> transforms = []
>
> value.converter = null
>
> (org.apache.kafka.connect.runtime.SourceConnectorConfig:370)
>
> [2024-05-29 14:47:04,426] DEBUG Reconfiguring connector SageX3Connector:
> writing new updated configurations for tasks
> (org.apache.kafka.connect.runtime.AbstractHerder:864)
>
> [2024-05-29 14:47:04,428] INFO [SageX3Connector|worker]
> EnrichedConnectorConfig values:
>
> config.action.reload = restart
>
> connector.class = io.confluent.connect.jdbc.JdbcSourceConnector
>
> errors.log.enable = false
>
> errors.log.include.messages = false
>
> errors.retry.delay.max.ms = 60000
>
> errors.retry.timeout = 0
>
> errors.tolerance = none
>
> exactly.once.support = requested
>
> header.converter = null
>
> key.converter = null
>
> name = SageX3Connector
>
> offsets.storage.topic = null
>
> predicates = []
>
> tasks.max = 1
>
> topic.creation.groups = []
>
> transaction.boundary = poll
>
> transaction.boundary.interval.ms = null
>
> transforms = []
>
> value.converter = null
>
>
> (org.apache.kafka.connect.runtime.ConnectorConfig$EnrichedConnectorConfig:37
> 0)
>
> [2024-05-29 14:47:04,429] DEBUG [SageX3Connector|worker] Connector
> SageX3Connector task count changed from 0 to 1
> (org.apache.kafka.connect.runtime.AbstractHerder:852)
>
> [2024-05-29 14:47:04,429] DEBUG [SageX3Connector|worker] Reconfiguring
> connector SageX3Connector: writing new updated configurations for tasks
> (org.apache.kafka.connect.runtime.AbstractHerder:864)
>
>
>
> [2024-05-29 14:47:32,460] DEBUG Uncaught exception in REST call to
> /connectors/SageX3Connector/config
> (org.apache.kafka.connect.runtime.rest.errors.ConnectExceptionMapper:42)
>
> org.apache.kafka.connect.runtime.rest.errors.ConnectRestException: Request
> timed out
>
> at
>
> org.apache.kafka.connect.runtime.rest.HerderRequestHandler.completeRequest(H
> erderRequestHandler.java:89)
>
>