Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

test(dm): sequence_sharding_optimistic failed frequently #6515

Closed
buchuitoudegou opened this issue Jul 29, 2022 · 5 comments
Closed

test(dm): sequence_sharding_optimistic failed frequently #6515

buchuitoudegou opened this issue Jul 29, 2022 · 5 comments
Labels
area/dm Issues or PRs related to DM. component/test Unit tests and integration tests component. type/bug The issue is confirmed as a bug.

Comments

@buchuitoudegou
Copy link
Contributor

https://ci2.pingcap.net/blue/organizations/jenkins/dm_ghpr_integration_test/detail/dm_ghpr_integration_test/8315/pipeline

command: query-status sequence_sharding_optimistic failpoint error for FlushCheckpointStage before flush old checkpoint count: 0 != expected: 1, failed the 0-th time, will retry again

[2022-07-29T02:50:54.268Z] got=1 expected=1

[2022-07-29T02:50:54.268Z] dmctl test cmd: "resume-task sequence_sharding_optimistic"

[2022-07-29T02:50:54.268Z] dmctl test cmd: "query-status sequence_sharding_optimistic"

[2022-07-29T02:50:54.268Z] got=0 expected=1

[2022-07-29T02:50:54.268Z] command: query-status sequence_sharding_optimistic failpoint error for FlushCheckpointStage before track DDL count: 0 != expected: 1, failed the 0-th time, will retry again

[2022-07-29T02:50:56.799Z] got=0 expected=1

[2022-07-29T02:50:56.799Z] command: query-status sequence_sharding_optimistic failpoint error for FlushCheckpointStage before track DDL count: 0 != expected: 1, failed the 1-th time, will retry again

[2022-07-29T02:50:58.697Z] got=0 expected=1

[2022-07-29T02:50:58.697Z] command: query-status sequence_sharding_optimistic failpoint error for FlushCheckpointStage before track DDL count: 0 != expected: 1, failed the 2-th time, will retry again

[2022-07-29T02:51:00.593Z] got=0 expected=1

[2022-07-29T02:51:00.593Z] command: query-status sequence_sharding_optimistic failpoint error for FlushCheckpointStage before track DDL count: 0 != expected: 1, failed the 3-th time, will retry again

[2022-07-29T02:51:03.114Z] got=0 expected=1

[2022-07-29T02:51:03.114Z] command: query-status sequence_sharding_optimistic failpoint error for FlushCheckpointStage before track DDL count: 0 != expected: 1, failed the 4-th time, will retry again

[2022-07-29T02:51:05.021Z] got=0 expected=1

[2022-07-29T02:51:05.021Z] command: query-status sequence_sharding_optimistic failpoint error for FlushCheckpointStage before track DDL count: 0 != expected: 1, failed the 5-th time, will retry again

[2022-07-29T02:51:07.545Z] got=0 expected=1

[2022-07-29T02:51:07.545Z] command: query-status sequence_sharding_optimistic failpoint error for FlushCheckpointStage before track DDL count: 0 != expected: 1, failed the 6-th time, will retry again

[2022-07-29T02:51:09.437Z] got=0 expected=1

[2022-07-29T02:51:09.437Z] command: query-status sequence_sharding_optimistic failpoint error for FlushCheckpointStage before track DDL count: 0 != expected: 1, failed the 7-th time, will retry again

[2022-07-29T02:51:11.973Z] got=0 expected=1

[2022-07-29T02:51:11.973Z] command: query-status sequence_sharding_optimistic failpoint error for FlushCheckpointStage before track DDL count: 0 != expected: 1, failed the 8-th time, will retry again

[2022-07-29T02:51:13.864Z] got=0 expected=1

[2022-07-29T02:51:13.864Z] command: query-status sequence_sharding_optimistic failpoint error for FlushCheckpointStage before track DDL count: 0 != expected: 1, failed the 9-th time, will retry again

[2022-07-29T02:51:15.758Z] {

[2022-07-29T02:51:15.758Z]     "result": true,

[2022-07-29T02:51:15.758Z]     "msg": "",

[2022-07-29T02:51:15.758Z]     "sources": [

[2022-07-29T02:51:15.758Z]         {

[2022-07-29T02:51:15.758Z]             "result": true,

[2022-07-29T02:51:15.758Z]             "msg": "",

[2022-07-29T02:51:15.758Z]             "sourceStatus": {

[2022-07-29T02:51:15.758Z]                 "source": "mysql-replica-01",

[2022-07-29T02:51:15.758Z]                 "worker": "worker2",

[2022-07-29T02:51:15.758Z]                 "result": null,

[2022-07-29T02:51:15.758Z]                 "relayStatus": null

[2022-07-29T02:51:15.758Z]             },

[2022-07-29T02:51:15.758Z]             "subTaskStatus": [

[2022-07-29T02:51:15.758Z]                 {

[2022-07-29T02:51:15.758Z]                     "name": "sequence_sharding_optimistic",

[2022-07-29T02:51:15.758Z]                     "stage": "Running",

[2022-07-29T02:51:15.758Z]                     "unit": "Sync",

[2022-07-29T02:51:15.758Z]                     "result": null,

[2022-07-29T02:51:15.758Z]                     "unresolvedDDLLockID": "",

[2022-07-29T02:51:15.758Z]                     "sync": {

[2022-07-29T02:51:15.758Z]                         "totalEvents": "41",

[2022-07-29T02:51:15.758Z]                         "totalTps": "2",

[2022-07-29T02:51:15.758Z]                         "recentTps": "0",

[2022-07-29T02:51:15.758Z]                         "masterBinlog": "(dm-integration-test-go1180-8315-nrmbd-kzdzf-bin.000001, 6567)",

[2022-07-29T02:51:15.758Z]                         "masterBinlogGtid": "11e0f489-0ee7-11ed-893e-a6995e5b710f:1-25",

[2022-07-29T02:51:15.758Z]                         "syncerBinlog": "(dm-integration-test-go1180-8315-nrmbd-kzdzf-bin.000001, 5975)",

[2022-07-29T02:51:15.758Z]                         "syncerBinlogGtid": "",

[2022-07-29T02:51:15.758Z]                         "blockingDDLs": [

[2022-07-29T02:51:15.758Z]                         ],

[2022-07-29T02:51:15.758Z]                         "unresolvedGroups": [

[2022-07-29T02:51:15.758Z]                         ],

[2022-07-29T02:51:15.758Z]                         "synced": false,

[2022-07-29T02:51:15.758Z]                         "binlogType": "remote",

[2022-07-29T02:51:15.758Z]                         "secondsBehindMaster": "0",

[2022-07-29T02:51:15.758Z]                         "blockDDLOwner": "",

[2022-07-29T02:51:15.758Z]                         "conflictMsg": ""

[2022-07-29T02:51:15.758Z]                     },

[2022-07-29T02:51:15.758Z]                     "validation": null

[2022-07-29T02:51:15.758Z]                 }

[2022-07-29T02:51:15.758Z]             ]

[2022-07-29T02:51:15.758Z]         },

[2022-07-29T02:51:15.758Z]         {

[2022-07-29T02:51:15.758Z]             "result": true,

[2022-07-29T02:51:15.758Z]             "msg": "",

[2022-07-29T02:51:15.758Z]             "sourceStatus": {

[2022-07-29T02:51:15.758Z]                 "source": "mysql-replica-02",

[2022-07-29T02:51:15.758Z]                 "worker": "worker1",

[2022-07-29T02:51:15.758Z]                 "result": null,

[2022-07-29T02:51:15.758Z]                 "relayStatus": {

[2022-07-29T02:51:15.758Z]                     "masterBinlog": "(dm-integration-test-go1180-8315-nrmbd-kzdzf-bin.000001, 9603)",

[2022-07-29T02:51:15.758Z]                     "masterBinlogGtid": "1386685e-0ee7-11ed-8c9b-a6995e5b710f:1-32",

[2022-07-29T02:51:15.758Z]                     "relaySubDir": "1386685e-0ee7-11ed-8c9b-a6995e5b710f.000001",

[2022-07-29T02:51:15.758Z]                     "relayBinlog": "(dm-integration-test-go1180-8315-nrmbd-kzdzf-bin.000001, 9603)",

[2022-07-29T02:51:15.758Z]                     "relayBinlogGtid": "1386685e-0ee7-11ed-8c9b-a6995e5b710f:1-32",

[2022-07-29T02:51:15.758Z]                     "relayCatchUpMaster": true,

[2022-07-29T02:51:15.758Z]                     "stage": "Running",

[2022-07-29T02:51:15.758Z]                     "result": null

[2022-07-29T02:51:15.758Z]                 }

[2022-07-29T02:51:15.758Z]             },

[2022-07-29T02:51:15.758Z]             "subTaskStatus": [

[2022-07-29T02:51:15.758Z]                 {

[2022-07-29T02:51:15.758Z]                     "name": "sequence_sharding_optimistic",

[2022-07-29T02:51:15.758Z]                     "stage": "Paused",

[2022-07-29T02:51:15.758Z]                     "unit": "Sync",

[2022-07-29T02:51:15.758Z]                     "result": {

[2022-07-29T02:51:15.758Z]                         "isCanceled": false,

[2022-07-29T02:51:15.758Z]                         "errors": [

[2022-07-29T02:51:15.758Z]                             {

[2022-07-29T02:51:15.758Z]                                 "ErrCode": 36027,

[2022-07-29T02:51:15.758Z]                                 "ErrClass": "sync-unit",

[2022-07-29T02:51:15.758Z]                                 "ErrScope": "internal",

[2022-07-29T02:51:15.758Z]                                 "ErrLevel": "high",

[2022-07-29T02:51:15.758Z]                                 "Message": "startLocation: [position: (dm-integration-test-go1180-8315-nrmbd-kzdzf-bin|000001.000001, 2971), gtid-set: 1386685e-0ee7-11ed-8c9b-a6995e5b710f:1-8:10-11], endLocation: [position: (dm-integration-test-go1180-8315-nrmbd-kzdzf-bin|000001.000001, 3033), gtid-set: 1386685e-0ee7-11ed-8c9b-a6995e5b710f:1-8:10-11]: gen insert sqls failed, sourceTable: `sharding_seq_opt`.`t4`, targetTable: `sharding_target_opt`.`t_target`: Column count doesn't match value count: 3 (columns) vs 4 (values)",

[2022-07-29T02:51:15.758Z]                                 "RawCause": "",

[2022-07-29T02:51:15.758Z]                                 "Workaround": "Please check the log files to see if a related DDL has been skipped, and you could use `operate-schema` to get and set the table structure."

[2022-07-29T02:51:15.758Z]                             }

[2022-07-29T02:51:15.758Z]                         ],

[2022-07-29T02:51:15.758Z]                         "detail": null

[2022-07-29T02:51:15.758Z]                     },

[2022-07-29T02:51:15.759Z]                     "unresolvedDDLLockID": "",

[2022-07-29T02:51:15.759Z]                     "sync": {

[2022-07-29T02:51:15.759Z]                         "totalEvents": "3",

[2022-07-29T02:51:15.759Z]                         "totalTps": "0",

[2022-07-29T02:51:15.759Z]                         "recentTps": "0",

[2022-07-29T02:51:15.759Z]                         "masterBinlog": "(dm-integration-test-go1180-8315-nrmbd-kzdzf-bin.000001, 9603)",

[2022-07-29T02:51:15.759Z]                         "masterBinlogGtid": "1386685e-0ee7-11ed-8c9b-a6995e5b710f:1-32",

[2022-07-29T02:51:15.759Z]                         "syncerBinlog": "(dm-integration-test-go1180-8315-nrmbd-kzdzf-bin.000001, 2514)",

[2022-07-29T02:51:15.759Z]                         "syncerBinlogGtid": "1386685e-0ee7-11ed-8c9b-a6995e5b710f:1-8",

[2022-07-29T02:51:15.759Z]                         "blockingDDLs": [

[2022-07-29T02:51:15.759Z]                         ],

[2022-07-29T02:51:15.759Z]                         "unresolvedGroups": [

[2022-07-29T02:51:15.759Z]                         ],

[2022-07-29T02:51:15.759Z]                         "synced": false,

[2022-07-29T02:51:15.759Z]                         "binlogType": "local",

[2022-07-29T02:51:15.759Z]                         "secondsBehindMaster": "0",

[2022-07-29T02:51:15.759Z]                         "blockDDLOwner": "",

[2022-07-29T02:51:15.759Z]                         "conflictMsg": ""

[2022-07-29T02:51:15.759Z]                     },

[2022-07-29T02:51:15.759Z]                     "validation": null

[2022-07-29T02:51:15.759Z]                 }

[2022-07-29T02:51:15.759Z]             ]

[2022-07-29T02:51:15.759Z]         }

[2022-07-29T02:51:15.759Z]     ]

[2022-07-29T02:51:15.759Z] }

[2022-07-29T02:51:15.759Z] PASS
@buchuitoudegou
Copy link
Contributor Author

/area dm
/type bug

@ti-chi-bot ti-chi-bot added area/dm Issues or PRs related to DM. type/bug The issue is confirmed as a bug. labels Jul 29, 2022
@buchuitoudegou
Copy link
Contributor Author

related issue: #5731

@buchuitoudegou
Copy link
Contributor Author

/component test

@ti-chi-bot ti-chi-bot added the component/test Unit tests and integration tests component. label Jul 29, 2022
@buchuitoudegou
Copy link
Contributor Author 

[2022-07-29T02:51:16.599Z] [2022/07/29 10:50:53.866 +08:00] [WARN] [source_worker.go:633] ["can not update subtask config now"] [component="worker controller"] [error="[code=40052:class=dm-worker:scope=internal:level=high], Message: can only update task on Paused stage, but current stage is Running, Workaround: Please use `pause-task` command to pause the task."] [errorVerbose="[code=40052:class=dm-worker:scope=internal:level=high], Message: can only update task on Paused stage, but current stage is Running, Workaround: Please use `pause-task` command to pause the task.\ngithub.com/pingcap/tiflow/dm/pkg/terror.(*Error).Generate\n\t/home/jenkins/agent/workspace/dm_ghpr_integration_test/go/src/github.com/pingcap/tiflow/dm/pkg/terror/terror.go:271\ngithub.com/pingcap/tiflow/dm/worker.(*SubTask).Update\n\t/home/jenkins/agent/workspace/dm_ghpr_integration_test/go/src/github.com/pingcap/tiflow/dm/worker/subtask.go:658\ngithub.com/pingcap/tiflow/dm/worker.(*SourceWorker).UpdateSubTask\n\t/home/jenkins/agent/workspace/dm_ghpr_integration_test/go/src/github.com/pingcap/tiflow/dm/worker/source_worker.go:600\ngithub.com/pingcap/tiflow/dm/worker.(*SourceWorker).tryRefreshSubTaskAndSourceConfig\n\t/home/jenkins/agent/workspace/dm_ghpr_integration_test/go/src/github.com/pingcap/tiflow/dm/worker/source_worker.go:1314\ngithub.com/pingcap/tiflow/dm/worker.(*SourceWorker).OperateSubTask\n\t/home/jenkins/agent/workspace/dm_ghpr_integration_test/go/src/github.com/pingcap/tiflow/dm/worker/source_worker.go:631\ngithub.com/pingcap/tiflow/dm/worker.(*SourceWorker).operateSubTaskStage\n\t/home/jenkins/agent/workspace/dm_ghpr_integration_test/go/src/github.com/pingcap/tiflow/dm/worker/source_worker.go:833\ngithub.com/pingcap/tiflow/dm/worker.(*SourceWorker).operateSubTaskStageWithoutConfig\n\t/home/jenkins/agent/workspace/dm_ghpr_integration_test/go/src/github.com/pingcap/tiflow/dm/worker/source_worker.go:852\ngithub.com/pingcap/tiflow/dm/worker.(*SourceWorker).handleSubTaskStage\n\t/home/jenkins/agent/workspace/dm_ghpr_integration_test/go/src/github.com/pingcap/tiflow/dm/worker/source_worker.go:773\ngithub.com/pingcap/tiflow/dm/worker.(*SourceWorker).observeSubtaskStage\n\t/home/jenkins/agent/workspace/dm_ghpr_integration_test/go/src/github.com/pingcap/tiflow/dm/worker/source_worker.go:731\ngithub.com/pingcap/tiflow/dm/worker.(*SourceWorker).EnableHandleSubtasks.func1\n\t/home/jenkins/agent/workspace/dm_ghpr_integration_test/go/src/github.com/pingcap/tiflow/dm/worker/source_worker.go:481\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1571"]

[2022-07-29T02:51:16.599Z] [2022/07/29 10:50:53.867 +08:00] [INFO] [source_worker.go:636] ["resume subtask"] [component="worker controller"] [task=sequence_sharding_optimistic]

[2022-07-29T02:51:16.599Z] [2022/07/29 10:50:53.867 +08:00] [INFO] [source_worker.go:645] ["OperateSubTask finished"] [component="worker controller"] [op=Resume] [task=sequence_sharding_optimistic]

[2022-07-29T02:51:16.599Z] [2022/07/29 10:50:53.867 +08:00] [DEBUG] [basedb.go:188] ["query context"] [component="worker controller"] [query="SHOW MASTER STATUS"] [argument="[]"]

[2022-07-29T02:51:16.599Z] [2022/07/29 10:50:53.867 +08:00] [ERROR] [source_worker.go:776] ["fail to operate subtask stage"] [stage="{\"expect\":2,\"source\":\"mysql-replica-01\",\"task\":\"sequence_sharding_optimistic\"}"] ["is deleted"=false] [error="[code=40051:class=dm-worker:scope=internal:level=high], Message: current stage is Running but not paused, invalid"] [errorVerbose="[code=40051:class=dm-worker:scope=internal:level=high], Message: current stage is Running but not paused, invalid\ngithub.com/pingcap/tiflow/dm/pkg/terror.(*Error).Generate\n\t/home/jenkins/agent/workspace/dm_ghpr_integration_test/go/src/github.com/pingcap/tiflow/dm/pkg/terror/terror.go:271\ngithub.com/pingcap/tiflow/dm/worker.(*SubTask).Resume\n\t/home/jenkins/agent/workspace/dm_ghpr_integration_test/go/src/github.com/pingcap/tiflow/dm/worker/subtask.go:625\ngithub.com/pingcap/tiflow/dm/worker.(*SourceWorker).OperateSubTask\n\t/home/jenkins/agent/workspace/dm_ghpr_integration_test/go/src/github.com/pingcap/tiflow/dm/worker/source_worker.go:637\ngithub.com/pingcap/tiflow/dm/worker.(*SourceWorker).operateSubTaskStage\n\t/home/jenkins/agent/workspace/dm_ghpr_integration_test/go/src/github.com/pingcap/tiflow/dm/worker/source_worker.go:833\ngithub.com/pingcap/tiflow/dm/worker.(*SourceWorker).operateSubTaskStageWithoutConfig\n\t/home/jenkins/agent/workspace/dm_ghpr_integration_test/go/src/github.com/pingcap/tiflow/dm/worker/source_worker.go:852\ngithub.com/pingcap/tiflow/dm/worker.(*SourceWorker).handleSubTaskStage\n\t/home/jenkins/agent/workspace/dm_ghpr_integration_test/go/src/github.com/pingcap/tiflow/dm/worker/source_worker.go:773\ngithub.com/pingcap/tiflow/dm/worker.(*SourceWorker).observeSubtaskStage\n\t/home/jenkins/agent/workspace/dm_ghpr_integration_test/go/src/github.com/pingcap/tiflow/dm/worker/source_worker.go:731\ngithub.com/pingcap/tiflow/dm/worker.(*SourceWorker).EnableHandleSubtasks.func1\n\t/home/jenkins/agent/workspace/dm_ghpr_integration_test/go/src/github.com/pingcap/tiflow/dm/worker/source_worker.go:481\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1571"]

@buchuitoudegou buchuitoudegou mentioned this issue Jul 29, 2022
Merged
@lance6716
Copy link
Contributor

duplicated with #5731


[2022-07-29T02:51:16.562Z] [2022/07/29 10:50:55.806 +08:00] [ERROR] [local_reader.go:654] ["parse relay log file"] [task=sequence_sharding_optimistic] [unit="binlog replication"] [component="binlog reader"] [file=/tmp/dm_test/sequence_sharding_optimistic/worker2/relay_log/1386685e-0ee7-11ed-8c9b-a6995e5b710f.000001/dm-integration-test-go1180-8315-nrmbd-kzdzf-bin.000001] [offset=4] [error="Header &replication.EventHeader{Timestamp:0x62e34b0b, EventType:0x1e, ServerID:0x1, EventSize:0x3a, LogPos:0x107f, Flags:0x0}, Data \"\\x02\\x02\\x00\\x00\\x00\\x00\\x01\\x00\\x02\\x00\\x03\\xff\\x00\\x85\\x1a\\x06\\x00\\x00\\x00\\x00\\x00\\x06410005\\x06420005\", Err: table id 514: invalid table id, no corresponding table map event"] [errorVerbose="Header &replication.EventHeader{Timestamp:0x62e34b0b, EventType:0x1e, ServerID:0x1, EventSize:0x3a, LogPos:0x107f, Flags:0x0}, Data \"\\x02\\x02\\x00\\x00\\x00\\x00\\x01\\x00\\x02\\x00\\x03\\xff\\x00\\x85\\x1a\\x06\\x00\\x00\\x00\\x00\\x00\\x06410005\\x06420005\", Err: table id 514: invalid table id, no corresponding table map event\ngithub.com/pingcap/errors.AddStack\n\t/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211224045212-9687c2b0f87c/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211224045212-9687c2b0f87c/juju_adaptor.go:15\ngithub.com/go-mysql-org/go-mysql/replication.(*BinlogParser).parseSingleEvent\n\t/go/pkg/mod/github.com/go-mysql-org/go-mysql@v1.6.1-0.20220718092400-c855c26b37bd/replication/parser.go:155\ngithub.com/go-mysql-org/go-mysql/replication.(*BinlogParser).ParseReader\n\t/go/pkg/mod/github.com/go-mysql-org/go-mysql@v1.6.1-0.20220718092400-c855c26b37bd/replication/parser.go:171\ngithub.com/pingcap/tiflow/dm/relay.(*BinlogReader).parseFile\n\t/home/jenkins/agent/workspace/dm_ghpr_integration_test/go/src/github.com/pingcap/tiflow/dm/relay/local_reader.go:652\ngithub.com/pingcap/tiflow/dm/relay.(*BinlogReader).parseFileAsPossible\n\t/home/jenkins/agent/workspace/dm_ghpr_integration_test/go/src/github.com/pingcap/tiflow/dm/relay/local_reader.go:486\ngithub.com/pingcap/tiflow/dm/relay.(*BinlogReader).parseDirAsPossible\n\t/home/jenkins/agent/workspace/dm_ghpr_integration_test/go/src/github.com/pingcap/tiflow/dm/relay/local_reader.go:426\ngithub.com/pingcap/tiflow/dm/relay.(*BinlogReader).parseRelay\n\t/home/jenkins/agent/workspace/dm_ghpr_integration_test/go/src/github.com/pingcap/tiflow/dm/relay/local_reader.go:316\ngithub.com/pingcap/tiflow/dm/relay.(*BinlogReader).StartSyncByGTID.func1\n\t/home/jenkins/agent/workspace/dm_ghpr_integration_test/go/src/github.com/pingcap/tiflow/dm/relay/local_reader.go:285\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1571"]

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
area/dm Issues or PRs related to DM. component/test Unit tests and integration tests component. type/bug The issue is confirmed as a bug.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@lance6716 @buchuitoudegou @ti-chi-bot