kafka-connect-oracle icon indicating copy to clipboard operation
kafka-connect-oracle copied to clipboard

Published 20 hours ago • verified publisher icon erdemcer

can not start LogMiner Session

Open bellacat82 opened this issue 4 years ago • 8 comments

It can starting LogMiner Session at the first starting connector.But when I stop the connector and start it again,it can not start Logminer session. why.

bellacat82 avatar Jun 23 '20 12:06 bellacat82

Hi, Could you please give some detail ? Are you using standalone or distributed ? any log file for share including all processes? Thanks

erdemcer avatar Jun 23 '20 12:06 erdemcer

I used standalone. the right log is : [2020-06-23 18:01:13,220] INFO Created connector oracle-logminer-connector (org.apache.kafka.connect.cli.ConnectStandalone:112) [2020-06-23 18:01:13,220] INFO Oracle Kafka Connector is starting on testdb(com.ecer.kafka.connect.oracle.OracleSourceTask:112) [2020-06-23 18:01:13,221] INFO [Producer clientId=connector-producer-oracle-logminer-connector-0] Cluster ID: 6LTQxJq3QJKSRxZn8KHGfg (org.apache.kafka.clients.Metadata:280) [2020-06-23 18:01:13,554] INFO Connected to database version 112040 (com.ecer.kafka.connect.oracle.OracleSourceTask:117) [2020-06-23 18:01:13,555] INFO Starting LogMiner Session (com.ecer.kafka.connect.oracle.OracleSourceTask:120) [2020-06-23 18:01:13,582] INFO Resetting offset with new SCN (com.ecer.kafka.connect.oracle.OracleSourceTask:168) [2020-06-23 18:01:13,587] INFO Getting current scn from database 6150992960992 (com.ecer.kafka.connect.oracle.OracleSourceTask:183) [2020-06-23 18:01:13,587] INFO Commit SCN : 0 (com.ecer.kafka.connect.oracle.OracleSourceTask:186) [2020-06-23 18:01:13,587] INFO Log Miner will start at new position SCN : 6150992960992 with fetch size : 1 (com.ecer.kafka.connect. oracle.OracleSourceTask:187)

And the wrong log is : [2020-06-23 18:02:49,902] INFO Oracle Kafka Connector is starting on testdb(com.ecer.kafka.connect.oracle.OracleSourceTask:112) [2020-06-23 18:02:49,902] INFO Created connector oracle-logminer-connector (org.apache.kafka.connect.cli.ConnectStandalone:112) [2020-06-23 18:02:49,914] INFO [Producer clientId=connector-producer-oracle-logminer-connector-0] Cluster ID: Z90DAXWuSsW8c_-BmLqlow (org.apache.kafka.clients.Metadata:280) [2020-06-23 18:02:59,902] INFO WorkerSourceTask{id=oracle-logminer-connector-0} Committing offsets (org.apache.kafka.connect.runtime .WorkerSourceTask:424) [2020-06-23 18:02:59,903] INFO WorkerSourceTask{id=oracle-logminer-connector-0} flushing 0 outstanding messages for offset commit (o rg.apache.kafka.connect.runtime.WorkerSourceTask:441)

bellacat82 avatar Jun 23 '20 13:06 bellacat82

How do you stop connector ctrl+c , kill Oracle process or ? Could you also please send connector logs regarding stopping statements ?

erdemcer avatar Jun 23 '20 13:06 erdemcer

I stop connector ctrl+c. The whole log is : [2020-06-23 18:01:13,220] INFO Created connector oracle-logminer-connector (org.apache.kafka.connect.cli.ConnectStandalone:112) [2020-06-23 18:01:13,220] INFO Oracle Kafka Connector is starting on testdb(com.ecer.kafka.connect.oracle.OracleSourceTask:112) [2020-06-23 18:01:13,221] INFO [Producer clientId=connector-producer-oracle-logminer-connector-0] Cluster ID: 6LTQxJq3QJKSRxZn8KHGfg (org.apache.kafka.clients.Metadata:280) [2020-06-23 18:01:13,554] INFO Connected to database version 112040 (com.ecer.kafka.connect.oracle.OracleSourceTask:117) [2020-06-23 18:01:13,555] INFO Starting LogMiner Session (com.ecer.kafka.connect.oracle.OracleSourceTask:120) [2020-06-23 18:01:13,582] INFO Resetting offset with new SCN (com.ecer.kafka.connect.oracle.OracleSourceTask:168) [2020-06-23 18:01:13,587] INFO Getting current scn from database 6150992960992 (com.ecer.kafka.connect.oracle.OracleSourceTask:183) [2020-06-23 18:01:13,587] INFO Commit SCN : 0 (com.ecer.kafka.connect.oracle.OracleSourceTask:186) [2020-06-23 18:01:13,587] INFO Log Miner will start at new position SCN : 6150992960992 with fetch size : 1 (com.ecer.kafka.connect. oracle.OracleSourceTask:187) [2020-06-23 18:01:23,220] INFO WorkerSourceTask{id=oracle-logminer-connector-0} Committing offsets (org.apache.kafka.connect.runtime .WorkerSourceTask:424) [2020-06-23 18:01:23,221] INFO WorkerSourceTask{id=oracle-logminer-connector-0} flushing 0 outstanding messages for offset commit (o rg.apache.kafka.connect.runtime.WorkerSourceTask:441) [2020-06-23 18:01:33,222] INFO WorkerSourceTask{id=oracle-logminer-connector-0} Committing offsets (org.apache.kafka.connect.runtime .WorkerSourceTask:424) [2020-06-23 18:01:33,223] INFO WorkerSourceTask{id=oracle-logminer-connector-0} flushing 0 outstanding messages for offset commit (o rg.apache.kafka.connect.runtime.WorkerSourceTask:441) [2020-06-23 18:01:43,223] INFO WorkerSourceTask{id=oracle-logminer-connector-0} Committing offsets (org.apache.kafka.connect.runtime .WorkerSourceTask:424) [2020-06-23 18:01:43,224] INFO WorkerSourceTask{id=oracle-logminer-connector-0} flushing 0 outstanding messages for offset commit (o rg.apache.kafka.connect.runtime.WorkerSourceTask:441) [2020-06-23 18:01:53,226] INFO WorkerSourceTask{id=oracle-logminer-connector-0} Committing offsets (org.apache.kafka.connect.runtime .WorkerSourceTask:424) [2020-06-23 18:01:53,227] INFO WorkerSourceTask{id=oracle-logminer-connector-0} flushing 0 outstanding messages for offset commit (o rg.apache.kafka.connect.runtime.WorkerSourceTask:441) [2020-06-23 18:01:59,673] INFO Logminer started successfully (com.ecer.kafka.connect.oracle.OracleSourceTask:195) [2020-06-23 18:01:59,674] INFO WorkerSourceTask{id=oracle-logminer-connector-0} Source task finished initialization and start (org.a pache.kafka.connect.runtime.WorkerSourceTask:214) [2020-06-23 18:01:59,680] INFO Getting dictionary details for table : TEST_TB(com.ecer.kafka.connect.oracle.OracleSourceConnectorU tils:153) [2020-06-23 18:02:03,229] INFO WorkerSourceTask{id=oracle-logminer-connector-0} Committing offsets (org.apache.kafka.connect.runtime .WorkerSourceTask:424) [2020-06-23 18:02:03,229] INFO WorkerSourceTask{id=oracle-logminer-connector-0} flushing 0 outstanding messages for offset commit (o rg.apache.kafka.connect.runtime.WorkerSourceTask:441) [2020-06-23 18:02:03,237] INFO WorkerSourceTask{id=oracle-logminer-connector-0} Finished commitOffsets successfully in 8 ms (org.apa che.kafka.connect.runtime.WorkerSourceTask:523) [2020-06-23 18:02:13,238] INFO WorkerSourceTask{id=oracle-logminer-connector-0} Committing offsets (org.apache.kafka.connect.runtime .WorkerSourceTask:424) [2020-06-23 18:02:13,239] INFO WorkerSourceTask{id=oracle-logminer-connector-0} flushing 0 outstanding messages for offset commit (o rg.apache.kafka.connect.runtime.WorkerSourceTask:441) [2020-06-23 18:02:23,240] INFO WorkerSourceTask{id=oracle-logminer-connector-0} Committing offsets (org.apache.kafka.connect.runtime .WorkerSourceTask:424) [2020-06-23 18:02:23,242] INFO WorkerSourceTask{id=oracle-logminer-connector-0} flushing 0 outstanding messages for offset commit (o rg.apache.kafka.connect.runtime.WorkerSourceTask:441) [2020-06-23 18:02:25,910] INFO Kafka Connect stopping (org.apache.kafka.connect.runtime.Connect:67) [2020-06-23 18:02:25,911] INFO Stopping REST server (org.apache.kafka.connect.runtime.rest.RestServer:321) [2020-06-23 18:02:25,923] INFO Stopped http_8083@47a5b70d{HTTP/1.1,[http/1.1]}{0.0.0.0:8083} (org.eclipse.jetty.server.AbstractConne ctor:380) [2020-06-23 18:02:25,923] INFO node0 Stopped scavenging (org.eclipse.jetty.server.session:158) [2020-06-23 18:02:25,926] INFO REST server stopped (org.apache.kafka.connect.runtime.rest.RestServer:338) [2020-06-23 18:02:25,927] INFO Herder stopping (org.apache.kafka.connect.runtime.standalone.StandaloneHerder:100) [2020-06-23 18:02:25,928] INFO Stopping task oracle-logminer-connector-0 (org.apache.kafka.connect.runtime.Worker:704) [2020-06-23 18:02:25,928] INFO Stop called for logminer (com.ecer.kafka.connect.oracle.OracleSourceTask:294) [2020-06-23 18:02:25,928] INFO Logminer session cancel (com.ecer.kafka.connect.oracle.OracleSourceTask:297) [2020-06-23 18:02:25,939] ERROR SQL error during poll (com.ecer.kafka.connect.oracle.OracleSourceTask:281) java.sql.SQLTimeoutException: ORA-01013: user requested cancel of current operation

    at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:447)
    at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:396)
    at oracle.jdbc.driver.T4C8Oall.processError(T4C8Oall.java:951)
    at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:513)
    at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:227)
    at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:531)
    at oracle.jdbc.driver.T4CCallableStatement.doOall8(T4CCallableStatement.java:205)
    at oracle.jdbc.driver.T4CCallableStatement.fetch(T4CCallableStatement.java:1118)
    at oracle.jdbc.driver.OracleResultSetImpl.close_or_fetch_from_next(OracleResultSetImpl.java:384)
    at oracle.jdbc.driver.OracleResultSetImpl.next(OracleResultSetImpl.java:288)
    at com.ecer.kafka.connect.oracle.OracleSourceTask.poll(OracleSourceTask.java:229)
    at org.apache.kafka.connect.runtime.WorkerSourceTask.poll(WorkerSourceTask.java:270)
    at org.apache.kafka.connect.runtime.WorkerSourceTask.execute(WorkerSourceTask.java:237)
    at org.apache.kafka.connect.runtime.WorkerTask.doRun(WorkerTask.java:184)
    at org.apache.kafka.connect.runtime.WorkerTask.run(WorkerTask.java:234)
    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:748)

[2020-06-23 18:02:25,942] INFO WorkerSourceTask{id=oracle-logminer-connector-0} Committing offsets (org.apache.kafka.connect.runtime .WorkerSourceTask:424) [2020-06-23 18:02:25,952] INFO Closing database connection.Last SCN : 6150992961005 (com.ecer.kafka.connect.oracle.OracleSourceTask: 301) [2020-06-23 18:02:25,955] INFO WorkerSourceTask{id=oracle-logminer-connector-0} flushing 0 outstanding messages for offset commit (o rg.apache.kafka.connect.runtime.WorkerSourceTask:441) [2020-06-23 18:02:25,956] INFO [Producer clientId=connector-producer-oracle-logminer-connector-0] Closing the Kafka producer with ti meoutMillis = 30000 ms. (org.apache.kafka.clients.producer.KafkaProducer:1182) [2020-06-23 18:02:25,966] INFO Stopping connector oracle-logminer-connector (org.apache.kafka.connect.runtime.Worker:358) [2020-06-23 18:02:25,969] INFO Stopped connector oracle-logminer-connector (org.apache.kafka.connect.runtime.Worker:374) [2020-06-23 18:02:25,969] INFO Worker stopping (org.apache.kafka.connect.runtime.Worker:198) [2020-06-23 18:02:25,970] INFO Stopped FileOffsetBackingStore (org.apache.kafka.connect.storage.FileOffsetBackingStore:66) [2020-06-23 18:02:25,971] INFO Worker stopped (org.apache.kafka.connect.runtime.Worker:219) [2020-06-23 18:02:25,972] INFO Herder stopped (org.apache.kafka.connect.runtime.standalone.StandaloneHerder:117) [2020-06-23 18:02:25,972] INFO Kafka Connect stopped (org.apache.kafka.connect.runtime.Connect:72)

bellacat82 avatar Jun 23 '20 13:06 bellacat82

[2020-06-23 22:19:13,248] INFO Kafka Connect stopping (org.apache.kafka.connect.runtime.Connect:67) [2020-06-23 22:19:13,249] INFO Stopping REST server (org.apache.kafka.connect.runtime.rest.RestServer:321) [2020-06-23 22:19:13,259] INFO Stopped http_8083@47a5b70d{HTTP/1.1,[http/1.1]}{0.0.0.0:8083} (org.eclipse.jetty.server.AbstractConnector:380) [2020-06-23 22:19:13,260] INFO node0 Stopped scavenging (org.eclipse.jetty.server.session:158) [2020-06-23 22:19:13,262] INFO REST server stopped (org.apache.kafka.connect.runtime.rest.RestServer:338) [2020-06-23 22:19:13,263] INFO Herder stopping (org.apache.kafka.connect.runtime.standalone.StandaloneHerder:100) [2020-06-23 22:19:13,264] INFO Stopping task oracle-logminer-connector-0 (org.apache.kafka.connect.runtime.Worker:704) [2020-06-23 22:19:18,269] ERROR Graceful stop of task oracle-logminer-connector-0 failed. (org.apache.kafka.connect.runtime.Worker:736) [2020-06-23 22:19:18,270] INFO Stopping connector oracle-logminer-connector (org.apache.kafka.connect.runtime.Worker:358) [2020-06-23 22:19:18,271] INFO Stopped connector oracle-logminer-connector (org.apache.kafka.connect.runtime.Worker:374) [2020-06-23 22:19:18,272] INFO Worker stopping (org.apache.kafka.connect.runtime.Worker:198) [2020-06-23 22:19:18,273] INFO Stopped FileOffsetBackingStore (org.apache.kafka.connect.storage.FileOffsetBackingStore:66) [2020-06-23 22:19:18,274] INFO Worker stopped (org.apache.kafka.connect.runtime.Worker:219) [2020-06-23 22:19:18,276] INFO Herder stopped (org.apache.kafka.connect.runtime.standalone.StandaloneHerder:117) [2020-06-23 22:19:18,276] INFO Kafka Connect stopped (org.apache.kafka.connect.runtime.Connect:72)

bellacat82 avatar Jun 23 '20 14:06 bellacat82

Hi Erdem, Thank you for your good work. I have tried debezium logminer method and it seems your connector is better than debeizum connector. Same problem here. But i dont know whether it is connector problem or oracle problem. When i query v$session after starting connector, it seems connector hangs because of query hangs (select .... from v$logminer_content). May be it is related with this oracle "Bug 26650226". (linux , oracle 11.2.0.4.0 SE)

fozerol avatar Oct 21 '20 13:10 fozerol

Hi, Thank you for comments. I will check it out . Thanks

erdemcer avatar Oct 22 '20 04:10 erdemcer

Hi, Bug you mentioned is a Oracle problem and it has been fixed with patch for 12c . In addition query of v$logmnr_contents view never ends if continuous_mine is specified at releases before 19c. You can see this that query hangs. Thanks

erdemcer avatar Nov 13 '20 07:11 erdemcer