We encountered an anomaly when using DM's SQL expression to filter DML archived data; the filtering rules are ineffective on certain dates

Translated
1

Note:
This topic has been translated from a Chinese forum by GPT and might contain errors.

Original topic: 我们使用DM的SQL表达式过滤DML归档数据出现了异常，过滤规则在某些日期上不生效

| username: TiDBer_2nbBAGRs

[TiDB Usage Environment] Production Environment
[TiDB Version] 6.6.0
[Reproduction Path]
We set up DM to filter DML based on SQL expressions, with the rule that data older than 14 days is deleted from the upstream MySQL, but no action is taken on the downstream TiDB.

The configuration rule is delete-value-expr: “timestampdiff(day, ORDER_DATE, NOW())>14”
In the rule, the type of ORDER_DATE is date.

The configuration file is as follows:

image
image976×803 35.2 KB

[Encountered Problem: Problem Phenomenon and Impact]
At the beginning of the archiving process, everything was normal. Since it was the first time using this feature, I was manually deleting data from the table cztycdb.pdc1_dwv_out_order in MySQL to observe TiDB. When I started deleting data from January 28, 2023, I found that even though the data was older than 14 days and was deleted from the upstream MySQL, it was also deleted from the downstream TiDB.
Today, March 10, 2023, I manually deleted data from February 4, 2023, in the upstream MySQL table cztycdb.pdc1_dwv_out_order, and found that the data from February 4, 2023, in TiDB was also gone.

2
| username: TiDBer_2nbBAGRs | Original post link

Is there an official expert here who can help me take a look?

3
| username: okenJiang | Original post link

Please provide the upstream version and the corresponding logs.

4
| username: TiDBer_2nbBAGRs | Original post link

Upstream MySQL 5.7
DM version v6.5.0

Snipaste_2023-03-11_15-02-00
Snipaste_2023-03-11_15-02-001378×96 4.15 KB

TiDB cluster v6.50

image
image1522×80 3.63 KB

5
| username: TiDBer_2nbBAGRs | Original post link

Do you need the dm worker logs?

6
| username: okenJiang | Original post link

好的，请提供需要翻译的中文内容。

7
| username: TiDBer_2nbBAGRs | Original post link

There are no log files in the data directory.
There is a log in the deploy directory.

cd /data1/tidb/dm/deploy/dm-worker-8262/log/ && ls
The files are as follows:
Yesterday, an archive delete SQL was executed in MySQL.

So the file should be this one.

But this log file only contains this kind of content.

[2023/03/10 08:37:39.345 +08:00] [INFO] [ddl.go:375] [“prepare to handle ddls”] [task=mysql-pro-82] [unit=“binlog replication”] [component=ddl] [event=query] [queryEventContext=“{schema: test, originSQL: CREATE DATABASE IF NOT EXISTS test, startLocation: position: (mysql-binlog.001628, 427179382), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786300, endLocation: position: (mysql-binlog.001628, 427179492), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786301, lastLocation: position: (mysql-binlog.001628, 427179492), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786301, re-sync: , needHandleDDLs: CREATE DATABASE IF NOT EXISTS test, trackInfos: {originDDL: CREATE DATABASE IF NOT EXISTS test, routedDDL: CREATE DATABASE IF NOT EXISTS test, sourceTables: test, targetTables: test}}”]
[2023/03/10 08:37:39.345 +08:00] [INFO] [syncer.go:3061] [“flush all jobs”] [task=mysql-pro-82] [unit=“binlog replication”] [“global checkpoint”=“location(position: (mysql-binlog.001628, 427179317), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786300) (flushed location(position: (mysql-binlog.001628, 427146368), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786268))”] [“flush job seq”=3237]
[2023/03/10 08:37:39.346 +08:00] [INFO] [checkpoint_flush_worker.go:67] [“about to sync flush checkpoint snapshot”] [task=mysql-pro-82] [unit=“binlog replication”] [snapshot_id=1689480]
[2023/03/10 08:37:39.399 +08:00] [INFO] [checkpoint_flush_worker.go:108] [“sync flush checkpoint snapshot successfully”] [task=mysql-pro-82] [unit=“binlog replication”] [snapshot_id=1689480] [pos=“position: (mysql-binlog.001628, 427179317), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786300”]
[2023/03/10 08:37:39.400 +08:00] [INFO] [syncer.go:1284] [“after sync flushed checkpoint, gc all causality keys”] [task=mysql-pro-82] [unit=“binlog replication”]
[2023/03/10 08:37:39.400 +08:00] [INFO] [ddl.go:403] [“start to handle ddls in normal mode”] [task=mysql-pro-82] [unit=“binlog replication”] [component=ddl] [mode=normal] [event=query] [queryEventContext=“{schema: test, originSQL: CREATE DATABASE IF NOT EXISTS test, startLocation: position: (mysql-binlog.001628, 427179382), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786300, endLocation: position: (mysql-binlog.001628, 427179492), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786301, lastLocation: position: (mysql-binlog.001628, 427179492), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786301, re-sync: , needHandleDDLs: CREATE DATABASE IF NOT EXISTS test, trackInfos: {originDDL: CREATE DATABASE IF NOT EXISTS test, routedDDL: CREATE DATABASE IF NOT EXISTS test, sourceTables: test, targetTables: test}}”]
[2023/03/10 08:37:39.407 +08:00] [INFO] [checkpoint_flush_worker.go:67] [“about to sync flush checkpoint snapshot”] [task=mysql-pro-82] [unit=“binlog replication”] [snapshot_id=1689481]
[2023/03/10 08:37:39.416 +08:00] [INFO] [checkpoint_flush_worker.go:108] [“sync flush checkpoint snapshot successfully”] [task=mysql-pro-82] [unit=“binlog replication”] [snapshot_id=1689481] [pos=“position: (mysql-binlog.001628, 427179492), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786301”]
[2023/03/10 08:37:39.416 +08:00] [INFO] [syncer.go:1284] [“after sync flushed checkpoint, gc all causality keys”] [task=mysql-pro-82] [unit=“binlog replication”]
[2023/03/10 08:37:39.416 +08:00] [INFO] [ddl.go:444] [“finish to handle ddls in normal mode”] [task=mysql-pro-82] [unit=“binlog replication”] [component=ddl] [mode=normal] [event=query] [queryEventContext=“{schema: test, originSQL: CREATE DATABASE IF NOT EXISTS test, startLocation: position: (mysql-binlog.001628, 427179382), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786300, endLocation: position: (mysql-binlog.001628, 427179492), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786301, lastLocation: position: (mysql-binlog.001628, 427179492), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786301, re-sync: , needHandleDDLs: CREATE DATABASE IF NOT EXISTS test, trackInfos: {originDDL: CREATE DATABASE IF NOT EXISTS test, routedDDL: CREATE DATABASE IF NOT EXISTS test, sourceTables: test, targetTables: test}}”]
[2023/03/10 08:37:40.539 +08:00] [INFO] [ddl.go:934] [“parse ddl”] [task=mysql-pro-82] [unit=“binlog replication”] [event=query] [“query event context”=“{schema: test, originSQL: CREATE DATABASE IF NOT EXISTS test, startLocation: position: (mysql-binlog.001628, 427228093), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786342, endLocation: position: (mysql-binlog.001628, 427228203), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786343, lastLocation: position: (mysql-binlog.001628, 427228203), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786343, re-sync: , needHandleDDLs: , trackInfos: }”]
[2023/03/10 08:37:40.540 +08:00] [INFO] [ddl.go:294] [“ready to split ddl”] [task=mysql-pro-82] [unit=“binlog replication”] [component=ddl] [event=query] [queryEventContext=“{schema: test, originSQL: CREATE DATABASE IF NOT EXISTS test, startLocation: position: (mysql-binlog.001628, 427228093), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786342, endLocation: position: (mysql-binlog.001628, 427228203), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786343, lastLocation: position: (mysql-binlog.001628, 427228203), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786343, re-sync: , needHandleDDLs: , trackInfos: }”]
[2023/03/10 08:37:40.540 +08:00] [INFO] [ddl.go:314] [“resolve sql”] [task=mysql-pro-82] [unit=“binlog replication”] [component=ddl] [event=query] [appliedDDLs=“[“CREATE DATABASE IF NOT EXISTS test”]”] [queryEventContext=“{schema: test, originSQL: CREATE DATABASE IF NOT EXISTS test, startLocation: position: (mysql-binlog.001628, 427228093), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786342, endLocation: position: (mysql-binlog.001628, 427228203), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786343, lastLocation: position: (mysql-binlog.001628, 427228203), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786343, re-sync: , needHandleDDLs: , trackInfos: }”]
[2023/03/10 08:37:40.540 +08:00] [INFO] [ddl.go:375] [“prepare to handle ddls”] [task=mysql-pro-82] [unit=“binlog replication”] [component=ddl] [event=query] [queryEventContext=“{schema: test, originSQL: CREATE DATABASE IF NOT EXISTS test, startLocation: position: (mysql-binlog.001628, 427228093), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786342, endLocation: position: (mysql-binlog.001628, 427228203), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786343, lastLocation: position: (mysql-binlog.001628, 427228203), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786343, re-sync: , needHandleDDLs: CREATE DATABASE IF NOT EXISTS test, trackInfos: {originDDL: CREATE DATABASE IF NOT EXISTS test, routedDDL: CREATE DATABASE IF NOT EXISTS test, sourceTables: test, targetTables: test}}”]
[2023/03/10 08:37:40.540 +08:00] [INFO] [syncer.go:3061] [“flush all jobs”] [task=mysql-pro-82] [unit=“binlog replication”] [“global checkpoint”=“location(position: (mysql-binlog.001628, 427228028), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786342) (flushed location(position: (mysql-binlog.001628, 427179492), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786301))”] [“flush job seq”=3238]
[2023/03/10 08:37:40.541 +08:00] [INFO] [checkpoint_flush_worker.go:67] [“about to sync flush checkpoint snapshot”] [task=mysql-pro-82] [unit=“binlog replication”] [snapshot_id=1689482]
[2023/03/10 08:37:40.589 +08:00] [INFO] [checkpoint_flush_worker.go:108] [“sync flush checkpoint snapshot successfully”] [task=mysql-pro-82] [unit=“binlog replication”] [snapshot_id=1689482] [pos=“position: (mysql-binlog.001628, 427228028), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786342”]
[2023/03/10 08:37:40.589 +08:00] [INFO] [syncer.go:1284] [“after sync flushed checkpoint, gc all causality keys”] [task=mysql-pro-82] [unit=“binlog replication”]
[2023/03/10 08:37:40.589 +08:00] [INFO] [ddl.go:403] [“start to handle ddls in normal mode”] [task=mysql-pro-82] [unit=“binlog replication”] [component=ddl] [mode=normal] [event=query] [queryEventContext=“{schema: test, originSQL: CREATE DATABASE IF NOT EXISTS test, startLocation: position: (mysql-binlog.001628, 427228093), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786342, endLocation: position: (mysql-binlog.001628, 427228203), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786343, lastLocation: position: (mysql-binlog.001628, 427228203), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786343, re-sync: , needHandleDDLs: CREATE DATABASE IF NOT EXISTS test, trackInfos: {originDDL: CREATE DATABASE IF NOT EXISTS test, routedDDL: CREATE DATABASE IF NOT EXISTS test, sourceTables: test, targetTables: test}}”]
[2023/03/10 08:37:40.596 +08:00] [INFO] [checkpoint_flush_worker.go:67] [“about to sync flush checkpoint snapshot”] [task=mysql-pro-82] [unit=“binlog replication”] [snapshot_id=1689483]
[2023/03/10 08:37:40.605 +08:00] [INFO] [checkpoint_flush_worker.go:108] [“sync flush checkpoint snapshot successfully”] [task=mysql-pro-82] [unit=“binlog replication”] [snapshot_id=1689483] [pos=“position: (mysql-binlog.001628, 427228203), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786343”]
[2023/03/10 08:37:40.605 +08:00] [INFO] [syncer.go:1284] [“after sync flushed checkpoint, gc all causality keys”] [task=mysql-pro-82] [unit=“binlog replication”]
[2023/03/10 08:37:40.605 +08:00] [INFO] [ddl.go:444] [“finish to handle ddls in normal mode”] [task=mysql-pro-82] [unit=“binlog replication”] [component=ddl] [mode=normal] [event=query] [queryEventContext=“{schema: test, originSQL: CREATE DATABASE IF NOT EXISTS test, startLocation: position: (mysql-binlog.001628, 427228093), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786342, endLocation: position: (mysql-binlog.001628, 427228203), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786343, lastLocation: position: (mysql-binlog.001628, 427228203), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786343, re-sync: , needHandleDDLs: CREATE DATABASE IF NOT EXISTS test, trackInfos: {originDDL: CREATE DATABASE IF NOT EXISTS test, routedDDL: CREATE DATABASE IF NOT EXISTS test, sourceTables: test, targetTables: test}}”]
[2023/03/10 08:37:41.734 +08:00] [INFO] [ddl.go:934] [“parse ddl”] [task=mysql-pro-82] [unit=“binlog replication”] [event=query] [“query event context”=“{schema: test, originSQL: CREATE DATABASE IF NOT EXISTS test, startLocation: position: (mysql-binlog.001628, 427264740), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786376, endLocation: position: (mysql-binlog.001628, 427264850), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786377, lastLocation: position: (mysql-binlog.001628, 427264850), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786377, re-sync: , needHandleDDLs: , trackInfos: }”]
[2023/03/10 08:37:41.735 +08:00] [INFO] [ddl.go:294] [“ready to split ddl”] [task=mysql-pro-82] [unit=“binlog replication”] [component=ddl] [event=query] [queryEventContext="{schema: test, originSQL: CREATE DATABASE IF NOT EXISTS test, startLocation: position: (mysql-binlog.001628, 427264740), gtid-set: adac6965-f5df-11eb-860f-286ed488c748:1-112786376, endLocation: position:

8
| username: okenJiang | Original post link

Your log doesn’t even contain the database and table cztycdb.pdc1_dwv_out_order, which is obviously incorrect… Check other files and see if there’s anything in worker.log.