"Unsupported operation" warnings

[Per Dahlén]

We get a couple of "An unsupported operation detected for table" warnings in our connector logs every hour for two of the tables we "subscribe" to in our Oracle Connector.

I checked with Oracle logminer what the operation was for the specific SCN, and it was 3 (UPDATE), which looks like it should be supported by the Oracle connector code for v2.5.1.Final.

My questions are:

1. Can there be other reasons for this warning message?
2. Is this an indication that we may loose changes?

Kind regards,

Per Dahlén

[Chris Cranford]

Hi,

When you checked LogMiner, did you also check that there were no other logical changes associated with that SCN?  Oracle can technically record up to 12k logical changes per SCN on Oracle 12c and up to 96k changes per SCN on Oracle 19c+. 

This warning happens when the LogMiner data set returns an OPERATION / OPERATION_CODE of 255 / UNSUPPORTED. These rows typically involve situations where the underlying table or column type within the table isn't supported by LogMiner.  I would suggest taking a look at all changes related to the SCN in question and see what details you can deduce from the LogMiner data.

As for data loss, when we detect this problem, it's a situation where the connector simply cannot generate a change event. In this cases, you'll need to review what the physical change was and replicate that manually into your target system.  Unfortunately if LogMiner is incapable of providing Debezium the data for a specific type of change made on the system, there isn't much Debezium can do in this regard.

If you can provide the full log entry and all related changes for the SCN, we can certain dive into the details.

Hope that helps.
Chris

--
You received this message because you are subscribed to the Google Groups "debezium" group.
To unsubscribe from this group and stop receiving emails from it, send an email to debezium+u...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/debezium/0d194f8d-fc9e-4143-92c5-a2949f03ca22n%40googlegroups.com.

[Per Dahlén]

I found a warning in the connector log and dug into the log entries.

For the table and transaction mentioned in the connector log, I could not find an operation that matched.

I have attached a description of my findings and how I set up the logminer session.

I have also sent all log records (from the logmining session) in a separate excel file.

/Per

[Chris Cranford]

Hi,

So I must admit this is really baffling because the data you've shared does not seem to align at all with the logged message.  While we can see the transaction id and the SCN line-up, what's strange is that the log entry reported "redo thread 0" and  yet your data dump only reflects thread 1.  Can you share what version of Oracle you're connecting to, what version of the Debezium connector you're using, and whether this is Oracle RAC or Standalone.  If RAC, how many nodes are in the cluster?

Thanks,
Chris

To view this discussion on the web visit https://groups.google.com/d/msgid/debezium/17da2bbc-f1bf-431c-a008-d6a432b6902en%40googlegroups.com.

[Per Dahlén]

We're connecting to Oracle 19c:

select version from v$instance; => 19.0.0.0.0

It's not RAC.

/Per

[Chris Cranford]

Thank you.  As you originally indicated that this happens frequently, would you be willing to enable DEBUG logging and restart the connector.  When the connector logs the warning next, could you send me a full copy of the connector logs so I could take a closer look at the details the connector got from Oracle? 

Chris

To view this discussion on the web visit https://groups.google.com/d/msgid/debezium/5dea95f6-bcb9-4566-981a-d03cfc1da193n%40googlegroups.com.

[Per Dahlén]

Forgot the connector.

We're using Debezium Connector Oracle 2.5.1.Final.

It's deployed with Strimzi.

/Per

[Per Dahlén]

Absolutely, I can set up DEBUG logging etc.

Per

[Per Dahlén]

I had some difficulty in setting up DEBUG log level, I tried via the REST api, but it reverts to INFO after some time.

After some deep digging into the KafkaConnectSpec as outlined here KafkaConnect Logging, I finally got it working though.

I'll get back with more info when I get an "Unsupported operation" warning again!

Per

[Per Dahlén]

I'm trying to attach a zip-file with the logs, but it complains about my message being too long.

What is the limit for an attached file?

When turning on DEBUG log level the log becomes VERY large.

Per

[Per Dahlén]

Reduced log time window even further to reduce file size...

[Per Dahlén]

8 MB was too large, 4 MB seems to work.

There is only 3 minutes worth of log (~100MB in uncompressed format), I hope it is enough.

Per

[Chris Cranford]

Hi Per -

That was really helpful, could you do me one last favor.  You could extract the contents from V$LOGMNR_CONTENTS for this specific transaction:

    00110006018e3dcb

I have a theory, but I need the contents from LogMiner to confirm my theory.

Thanks,
Chris

--
You received this message because you are subscribed to the Google Groups "debezium" group.
To unsubscribe from this group and stop receiving emails from it, send an email to debezium+u...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/debezium/9935ee8d-d7ec-4402-8d29-8137dbf4f3ben%40googlegroups.com.

[Chris Cranford]

Sorry, I should have also included that it seems to have started around SCN 504580244013 and concluded at SCN 504580244439.

[Per Dahlén]

Here you are!

Per

[Chris Cranford]

Hi Per -

Thanks for the details, they were quite helpful and now I need to try and reproduce what I see to determine if indeed continuation flag lines are problematic across log switches.

Thanks,
Chris

To view this discussion on the web visit https://groups.google.com/d/msgid/debezium/eba168c1-2274-457a-b021-983df41c49abn%40googlegroups.com.

[Chris Cranford]

Hi Per -

I haven't been able to reproduce the problem yet. 

Can you please provide the output of this query:
    SELECT VERSION_FULL FROM V$INSTANCE

Can you also provide your complete connector configuration as I didn't see that logged in the log files.

Thanks,
Chris

[Per Dahlén]

SELECT VERSION_FULL FROM V$INSTANCE:

19.12.0.0.0

This is the config as from the REST endpoint 

{
    "snapshot.locking.mode": "none",
    "connector.class": "io.debezium.connector.oracle.OracleConnector",
    "message.key.columns": "EHDA.A_COSHIPTO:CONO,COSHIPTOSEQNO; EHDA.A_CSCUBUSINESS:CUSTNO,BUUNIT,COMPNO; EHDA.A_CUSTPARTGRP:CUSTPARTGRP,PARTNO; EHDA.A_ISINVSTATHOLD:PARTNO,STOCKNO,INVSTATCD,INVHOLDSEQNO; EHDA.A_LOCALPART:COMPNO,PARTNO; EHDA.A_PARTPRICE:PARTNO,PRICELIST,VALID_FROM; EHDA.A_POPARTVENDOR:COMPNO,PARTNO,VENDNO,FROMDATE; EHDA.A_POSHIPTO:PONO,POSHIPTOSEQNO; EHDA.A_PSBASE:PARTNO,STOCKNO; EHDA.A_PSPARTPACK:PARTNO,PARTPACK; EHDA.A_PSPARTSTOPDATES:PARTNO,STOPTYPE; EHDA.A_PSRESERV:PARTNO,STOCKNO; EHDA.A_PSSTLOC:PARTNO,STOCKNO; EHDA.A_SYCOMPORGUNIT:COMPNO,ORGUNIT; EHDA.A_SYEVENTTRIGGER:ESSEVENT,ESSID,ESSIDQUAL,EVENTSEQNO; EHDA.COAGREEHEAD:CUSTNO,AGREETYPE,COCLASS,BUUNIT,COMPNO,CURRENCY,COOBJ,CUSTDISC,SEQNO; EHDA.COAGREELINE:CUSTNO,AGREETYPE,COCLASS,BUUNIT,COMPNO,CURRENCY,COOBJ,CUSTDISC,SEQNO,LINENO; EHDA.COHEAD:CONO; EHDA.COROW:CONO,ROWPOS,ROWSUBPOS,ROWSEQ; EHDA.CUSTBILL:CUSTNOBILL; EHDA.CUSTBUY:CUSTNO; EHDA.CUSTSHIP:CUSTNO,SHIPTONO; EHDA.CZACCGROUPHEAD:COMPNO,CZCUSTNOGROUP,CUSTNO,SHIPTONO; EHDA.CZACCGROUPLINE:COMPNO,CZCUSTNOGROUP,CLASS1,CLASS2,CLASS3,CLASS4,CLASS5,CZCLASS8; EHDA.CZAGRPRDATE:CUSTNO,AGREETYPE,COCLASS,BUUNIT,COMPNO,CURRENCY,COOBJ,CUSTDISC,SEQNO,LINENO; EHDA.CZCLASS8GEN:COMPNO,PARTNO,VALID_FROM; EHDA.CZDISCTEMPLATE:CZDISCTEMPL,COMPNO; EHDA.CZDISCTEMPLATEROW:CZDISCTEMPL,COMPNO,CUSTDISC; EHDA.CZCUSTCOM:CZCUSTNOCOM; EHDA.CZCUSTCOMBREAK:CZCUSTNOCOM,CZCUSTCOMBR; EHDA.CZEDIORDERERRLOG:EDISEQNO,CODATE,CUSTNO,CONO,ROWPOS,PARTNO,CZEDIERRORTEXT,METHOFREC,CZEDIERRORNO; EHDA.CZHICLASS8:COMPNO,PARTNO,VALID_TO; EHDA.CZMULTIPLEAGR:CUSTNO,BUUNIT,COMPNO,CUSTDISC; EHDA.CZPARTPROPERTYART:COMPNO,PARTNO,CZSUBPROPERTY2; EHDA.CZPRFACTCLASS8:COMPNO,CZCLASS8; EHDA.CZPRFACTGEN:COMPNO,VALID_FROM,PARTNO,CZCLASS8; EHDA.CZREGIONORGSTRUCT:COMPNO,REGION,DISTRICT,CUSTCLASS,BRANCH; EHDA.CZVENDCOM:CZVENDNOCOM; EHDA.CZVENDCOMBREAK:CZVENDNOCOM,CZVENDCOMBR; EHDA.PART:PARTNO; EHDA.PARTKIT:PARTNO,PARTPOS; EHDA.PARTSEARCH:PARTSEARCHNAME,PARTNO,CZDUBBLETTYN; EHDA.PERS:SY_USER; EHDA.POHEAD:PONO; EHDA.POROW:PONO,POROWPOS,POROWSEQ; EHDA.SFSYCODEVALUE:CODEID,CODEKEY,COMPNO; EHDA.SFSYTEXTLANG:CMPTNAME,CMPTTYPE,CMPTID1,CMPTID2,LANGCODE; EHDA.STOCK:STOCKNO; EHDA.STOCKLOC:STOCKNO,PICKST,STOCKLOC; EHDA.STOCKPICK:STOCKNO,PICKST; EHDA.STOCKTAKE:STOCKNO,PARTNO,PICKST,STOCKLOC,STMISSNO,INDNO; EHDA.VENDBILL:VENDNO; EHDA.VENDBUY:VENDNO;",
    "topic.creation.default.allow.auto.create.topics": "true",
    "topic.creation.default.partitions": "6",
    "schema.history.internal.consumer.sasl.jaas.config": "org.apache.kafka.common.security.plain.PlainLoginModule required username='${file:/opt/kafka/external-configuration/dbz-ccloud-credentials/cred:username}' password='${file:/opt/kafka/external-configuration/dbz-ccloud-credentials/cred:password}';",
    "config.providers": "file",
    "topic.creation.default.auto.create.topics.enable": "true",
    "value.converter.basic.auth.credentials.source": "USER_INFO",
    "topic.creation.default.delete.retention.ms": "604800000",
    "schema.history.internal.producer.security.protocol": "SASL_SSL",
    "poll.interval.ms": "500",
    "topic.creation.default.replication.factor": "3",
    "config.providers.file.class": "org.apache.kafka.common.config.provider.FileConfigProvider",
    "key.converter": "io.confluent.connect.avro.AvroConverter",
    "schema.history.internal.producer.sasl.mechanism": "PLAIN",
    "schema.history.internal.producer.allow.auto.create.topics": "true",
    "database.dbname": "VIVP",
    "database.user": "${file:/opt/kafka/external-configuration/dbz-oracle-credentials/oracle:user}",
    "topic.creation.default.compression.type": "lz4",
    "schema.history.internal.kafka.bootstrap.servers": "redacted",
    "key.converter.schemas.enable": "false",
    "value.converter.schema.registry.url": "redacted",
    "database.password": "${file:/opt/kafka/external-configuration/dbz-oracle-credentials/oracle:password}",
    "topic.creation.default.min.compaction.lag.ms": "604800000",
    "value.converter.schemas.enable": "false",
    "name": "vivaldi-cdc-connector",
    "schema.history.internal.consumer.sasl.mechanism": "PLAIN",
    "schema.history.internal.producer.sasl.jaas.config": "org.apache.kafka.common.security.plain.PlainLoginModule required username='${file:/opt/kafka/external-configuration/dbz-ccloud-credentials/cred:username}' password='${file:/opt/kafka/external-configuration/dbz-ccloud-credentials/cred:password}';",
    "key.converter.schema.registry.basic.auth.user.info": "${file:/opt/kafka/external-configuration/dbz-ccloud-sr-credentials/cred:username}:${file:/opt/kafka/external-configuration/dbz-ccloud-sr-credentials/cred:password}",
    "schema.history.internal.producer.auto.create.topics.enable": "true",
    "max.batch.size": "10000",
    "key.converter.basic.auth.credentials.source": "USER_INFO",
    "snapshot.mode": "initial",
    "schema.history.internal.consumer.security.protocol": "SASL_SSL",
    "schema.history.internal.consumer.allow.auto.create.topics": "true",
    "max.queue.size": "40000",
    "tasks.max": "1",
    "value.converter.schema.registry.basic.auth.user.info": "${file:/opt/kafka/external-configuration/dbz-ccloud-sr-credentials/cred:username}:${file:/opt/kafka/external-configuration/dbz-ccloud-sr-credentials/cred:password}",
    "log.mining.strategy": "online_catalog",
    "schema.history.internal.consumer.auto.create.topics.enable": "true",
    "schema.history.internal.store.only.captured.databases.ddl": "true",
    "schema.history.internal.store.only.captured.tables.ddl": "true",
    "value.converter.enhanced.avro.schema.support": "true",
    "topic.prefix": "dbzvivaldi",
    "decimal.handling.mode": "double",
    "schema.history.internal.kafka.topic": "dbzvivaldi.schema-changes.vivaldi-cdc-connector",
    "topic.creation.default.key.converter.schemas.enable": "false",
    "value.converter": "io.confluent.connect.avro.AvroConverter",
    "topic.creation.default.cleanup.policy": "compact",
    "database.url": "jdbc:oracle:thin:@(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP) (HOST= redacted )(PORT=1521)) (CONNECT_DATA=(SID=VIVP)))",
    "topic.creation.default.value.converter.schemas.enable": "false",
    "snapshot.max.threads": "53",
    "log.mining.query.filter.mode": "in",
    "table.include.list": "EHDA.A_COSHIPTO, EHDA.A_CSCUBUSINESS, EHDA.A_CUSTPARTGRP, EHDA.A_ISINVSTATHOLD, EHDA.A_LOCALPART, EHDA.A_PARTPRICE, EHDA.A_POPARTVENDOR, EHDA.A_POSHIPTO, EHDA.A_PSBASE, EHDA.A_PSPARTPACK, EHDA.A_PSPARTSTOPDATES, EHDA.A_PSRESERV, EHDA.A_PSSTLOC, EHDA.A_SYCOMPORGUNIT, EHDA.A_SYEVENTTRIGGER, EHDA.COAGREEHEAD, EHDA.COAGREELINE, EHDA.COHEAD, EHDA.COROW, EHDA.CUSTBILL, EHDA.CUSTBUY, EHDA.CUSTSHIP, EHDA.CZACCGROUPHEAD, EHDA.CZACCGROUPLINE, EHDA.CZAGRPRDATE, EHDA.CZCLASS8GEN, EHDA.CZDISCTEMPLATE, EHDA.CZDISCTEMPLATEROW, EHDA.CZCUSTCOM, EHDA.CZCUSTCOMBREAK, EHDA.CZEDIORDERERRLOG, EHDA.CZHICLASS8, EHDA.CZMULTIPLEAGR, EHDA.CZPARTPROPERTYART, EHDA.CZPRFACTCLASS8, EHDA.CZPRFACTGEN, EHDA.CZREGIONORGSTRUCT, EHDA.CZVENDCOM, EHDA.CZVENDCOMBREAK, EHDA.PART, EHDA.PARTKIT, EHDA.PARTSEARCH, EHDA.PERS, EHDA.POHEAD, EHDA.POROW, EHDA.SFSYCODEVALUE, EHDA.SFSYTEXTLANG, EHDA.STOCK, EHDA.STOCKLOC, EHDA.STOCKPICK, EHDA.STOCKTAKE, EHDA.VENDBILL, EHDA.VENDBUY",
    "key.converter.schema.registry.url": "redacted"
}

Per

[Chris Cranford]

Hi Per -

Unfortunately I haven't been able to reproduce the scenario.  I've logged DBZ-7555 [1], in case you want to watch the Jira issue.  I have a few more ideas I want to try, and I've given some insight in the comments about my working theory.  If anything else comes to mind on your end that can shed any light, feel free to comment on the Jira or reply here.

Thanks,
Chris

[1]: https://issues.redhat.com/browse/DBZ-7555

To view this discussion on the web visit https://groups.google.com/d/msgid/debezium/a3ed24f1-df65-4ddf-9522-74dd220d0c5bn%40googlegroups.com.

[Per Dahlén]

Here is what Oracle writes in the Oracle 10 documentation:

"If a log switch occurs while LogMiner is reading an online redo log file, the database will overwrite what LogMiner is attempting to read. The data that LogMiner returns if the file it is trying to read gets overwritten by the database is unpredictable."

I'm not sure if this is still true with Oracle 19.12 though.

Per

[Chris Cranford]

Hi Per -

This can happen yes, but that will trigger an Oracle ORA error and a retart of the connector in those corner cases, but that isn't what happened here.  Instead, a single change in a transaction was marked as unsupported and LogMiner continued to read the remainder of the data for the transaction and other transactions thereafter uninterrupted.  It wouldn't have been able to do that if the log file changed in-flight.  Furthermore, looking at the logs you shared, those changes were part of an archive log at the time, not a redo log.

You mention this happened regularly, are there any database operations that are happening at that time when this happens, a backup or something like that?

Chris

To view this discussion on the web visit https://groups.google.com/d/msgid/debezium/836a4aaa-c742-482a-ad8b-5f7741398362n%40googlegroups.com.

[Oren Elias]

I have seen unsupported operations as well and have not been able to pinpoint those. 

Is this database also using Golden Gate by any chance?

Oren. 

To view this discussion on the web visit https://groups.google.com/d/msgid/debezium/0feb2ea4-d1e1-4789-9ca0-fef604fc081c%40gmail.com.

[Per Dahlén]

I just took the SCN from the application log and figured out which log file it was part of.

Unfortunately I am usually not quick enough to catch the warning when the SCN is still in an online redo log, so I usually have to look in the v$archived_log to find the file.

At peak hours, we switch redo log once a minute or two. We have four redo log files, so that means I have just a couple of minutes to set up an ad-hoc logminer session before LGWR starts writing to the same file again.

However, I've looked and found a pattern when we get the most of these errors. All the peaks you see in the graph are at 03:00 in the morning. I'll check if there is something special going on around that time.

Per

[Per Dahlén]

Oren, no we are not using Golden Gate.

Per

[Chris Cranford]

Great detective work Per, keep me updated. 

To view this discussion on the web visit https://groups.google.com/d/msgid/debezium/2a56865d-58c0-4f5b-aaeb-caabba82d768n%40googlegroups.com.

[Per Dahlén]

I've had a chat with to one of the application knowledgable, and he replied that they start 200 parallel jobs to calculate prices for invoices at 2 am.

Apart from that there is nothing special going on that he knows of.

Per

[Chris Cranford]

Hi Per -

On the date and time of the occurances, can your DBA pull the Oracle alert logs and see whether there are any obvious errors or warnings in the logs either directly from LogMiner or Oracle in general that could give any insight?

Thanks,
Chris

To view this discussion on the web visit https://groups.google.com/d/msgid/debezium/85e6f491-506b-4e9f-a937-0b5d52336026n%40googlegroups.com.

[Per Dahlén]

I've checked with our DBA and he cannot find any obvious errors or warnings in the Oracle alert logs.

//Per