ddl: fix "wrong warning messages when running some DDL jobs" #38761

wxbty · 2022-10-31T07:13:57Z

Signed-off-by: x-shadow-man 1494445739@qq.com

What problem does this PR solve?

When executing alter to change column attributes, multiple warnings display errors, and only one line is displayed when the same error is modified

Issue Number: close #38699

Problem Summary:

What is changed and how it works?

warning info format changed

Check List

Tests

[√ ] Unit test
Integration test
Manual test (add detailed scripts or steps below)
No code

Side effects

Performance regression: Consumes more CPU
Performance regression: Consumes more Memory
Breaking backward compatibility

Documentation

Release note

Please refer to Release Notes Language Style Guide to write a quality release note.

None

Signed-off-by: x-shadow-man <1494445739@qq.com>

ti-chi-bot · 2022-10-31T07:13:59Z

[REVIEW NOTIFICATION]

This pull request has been approved by:

Defined2014
mjonss

To complete the pull request process, please ask the reviewers in the list to review by filling /cc @reviewer in the comment.
After your PR has acquired the required number of LGTMs, you can assign this pull request to the committer in the list by filling /assign @committer in the comment to help you merge this pull request.

The full list of commands accepted by this bot can be found here.

Reviewer can indicate their review by submitting an approval review.
Reviewer can cancel approval by submitting a request changes review.

wxbty · 2022-10-31T07:17:34Z

/cc @bb7133 @mjonss

mjonss

LGTM, with minor suggestion and question.

ddl/ddl.go

ddl/failtest/fail_db_test.go

Signed-off-by: x-shadow-man <1494445739@qq.com>

Defined2014 · 2022-11-16T03:51:24Z

@wxbty Seems you should update two test cases.
TestModifyColumnTypeWhenInterception and TestModifyColumnTypeWithWarnings

wxbty · 2022-11-16T06:05:16Z

TestModifyColumnTypeWithWarnings

thx, TestModifyColumnTypeWhenInterception seems to fail on master

Defined2014 · 2022-11-16T06:44:37Z

The error msg

[2022/11/16 14:08:19.957 +08:00] [INFO] [callback_test.go:107] ["on job updated"] [job="ID:78, Type:modify column, State:done, SchemaState:public, SchemaID:2, TableID:76, RowCount:4096, ArgLen:2, start time: 2022-11-16 14:08:19.473 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:437407947076665345"]
[2022/11/16 14:08:19.973 +08:00] [INFO] [delete_range.go:109] ["[ddl] add job into delete-range table"] [jobID=78] [jobType="modify column"]
[2022/11/16 14:08:19.974 +08:00] [INFO] [ddl_worker.go:632] ["[ddl] finish DDL job"] [worker="worker 267, tp add index"] [job="ID:78, Type:modify column, State:synced, SchemaState:public, SchemaID:2, TableID:76, RowCount:4096, ArgLen:2, start time: 2022-11-16 14:08:19.473 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:437407947076665345"]
[2022/11/16 14:08:19.977 +08:00] [INFO] [callback_test.go:107] ["on job updated"] [job="ID:78, Type:modify column, State:synced, SchemaState:public, SchemaID:2, TableID:76, RowCount:4096, ArgLen:2, start time: 2022-11-16 14:08:19.473 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:437407947076665345"]
[2022/11/16 14:08:19.982 +08:00] [INFO] [ddl.go:1110] ["[ddl] DDL job is finished"] [jobID=78]
[2022/11/16 14:08:19.982 +08:00] [INFO] [callback_test.go:66] ["performing DDL change, must reload"]
    modify_column_test.go:898: 
        	Error Trace:	/home/jenkins/.tidb/tmp/63a9840cd0739f2c243bb46478607469/sandbox/linux-sandbox/6938/execroot/__main__/bazel-out/k8-fastbuild/bin/ddl/ddl_test_/ddl_test.runfiles/__main__/ddl/modify_column_test.go:898
        	Error:      	"[[Warning 1292 4096 warnings with this error code, first warning: Truncated incorrect DECIMAL value: '11.22']]" should have 4096 item(s), but has 1
        	Test:       	TestModifyColumnTypeWhenInterception
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_workerpool.go:82] ["[ddl] closing workerPool"]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 269, tp add index"] ["take time"=1.491µs]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 270, tp add index"] ["take time"=1.054µs]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 271, tp add index"] ["take time"=899ns]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 272, tp add index"] ["take time"=892ns]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 273, tp add index"] ["take time"=1.071µs]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 274, tp add index"] ["take time"=1.002µs]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 265, tp add index"] ["take time"=931ns]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 266, tp add index"] ["take time"=893ns]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 267, tp add index"] ["take time"=1.008µs]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 268, tp add index"] ["take time"=829ns]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_workerpool.go:82] ["[ddl] closing workerPool"]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 264, tp general"] ["take time"=1.066µs]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 262, tp general"] ["take time"=377ns]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 263, tp add index"] ["take time"=252ns]
[2022/11/16 14:08:19.984 +08:00] [INFO] [delete_range.go:148] ["[ddl] closing delRange"]
[2022/11/16 14:08:19.984 +08:00] [INFO] [session_pool.go:94] ["[ddl] closing sessionPool"]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl.go:815] ["[ddl] DDL closed"] [ID=195c88d3-e504-485f-80a8-5c6020e67a8d] ["take time"=1.956832ms]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl.go:639] ["[ddl] stop DDL"] [ID=195c88d3-e504-485f-80a8-5c6020e67a8d]
[2022/11/16 14:08:19.984 +08:00] [INFO] [domain.go:1095] ["closestReplicaReadCheckLoop exited."]
[2022/11/16 14:08:19.984 +08:00] [INFO] [domain.go:743] ["loadSchemaInLoop exited."]
[2022/11/16 14:08:19.984 +08:00] [INFO] [handle_hist.go:175] ["SubLoadWorker exited."]
[2022/11/16 14:08:19.984 +08:00] [INFO] [handle_hist.go:175] ["SubLoadWorker exited."]
[2022/11/16 14:08:19.984 +08:00] [INFO] [handle_hist.go:175] ["SubLoadWorker exited."]
[2022/11/16 14:08:19.984 +08:00] [INFO] [handle_hist.go:175] ["SubLoadWorker exited."]
[2022/11/16 14:08:19.984 +08:00] [INFO] [domain.go:1617] ["dumpFileGcChecker exited."]
[2022/11/16 14:08:19.984 +08:00] [INFO] [handle_hist.go:175] ["SubLoadWorker exited."]
[2022/11/16 14:08:19.984 +08:00] [INFO] [domain.go:1332] ["LoadSysVarCacheLoop exited."]
[2022/11/16 14:08:19.984 +08:00] [INFO] [domain.go:1282] ["loadPrivilegeInLoop exited."]
[2022/11/16 14:08:19.984 +08:00] [INFO] [domain.go:1457] ["handleEvolvePlanTasksLoop exited."]
[2022/11/16 14:08:19.985 +08:00] [INFO] [domain.go:1413] ["globalBindHandleWorkerLoop exited."]
[2022/11/16 14:08:19.985 +08:00] [INFO] [domain.go:608] ["topologySyncerKeeper exited."]
[2022/11/16 14:08:19.985 +08:00] [INFO] [domain.go:560] ["infoSyncerKeeper exited."]
[2022/11/16 14:08:19.985 +08:00] [INFO] [domain.go:585] ["globalConfigSyncerKeeper exited."]
[2022/11/16 14:08:19.985 +08:00] [INFO] [domain.go:531] ["topNSlowQueryLoop exited."]
[2022/11/16 14:08:19.985 +08:00] [INFO] [domain.go:871] ["domain closed"] ["take time"=2.393879ms]
[2022/11/16 14:08:19.996 +08:00] [INFO] [db.go:567] ["Closing database"]
[2022/11/16 14:08:20.002 +08:00] [INFO] [db.go:592] ["Memtable flushed"]
[2022/11/16 14:08:20.002 +08:00] [INFO] [db.go:596] ["Compaction finished"]
[2022/11/16 14:08:20.002 +08:00] [INFO] [db.go:615] ["BlobManager finished"]
[2022/11/16 14:08:20.002 +08:00] [INFO] [db.go:619] ["ResourceManager finished"]
[2022/11/16 14:08:20.002 +08:00] [INFO] [db.go:625] ["Waiting for closer"]
--- FAIL: TestModifyColumnTypeWhenInterception (4.84s)

[2022/11/16 14:06:49.552 +08:00] [INFO] [ddl.go:1110] ["[ddl] DDL job is finished"] [jobID=78]
[2022/11/16 14:06:49.552 +08:00] [INFO] [callback.go:121] ["performing DDL change, must reload"]
    result.go:49: 
        	Error Trace:	/home/jenkins/.tidb/tmp/63a9840cd0739f2c243bb46478607469/sandbox/linux-sandbox/6696/execroot/__main__/bazel-out/k8-fastbuild/bin/ddl/ddl_test_/ddl_test.runfiles/__main__/ddl/result.go:49
        	            				/home/jenkins/.tidb/tmp/63a9840cd0739f2c243bb46478607469/sandbox/linux-sandbox/6696/execroot/__main__/bazel-out/k8-fastbuild/bin/ddl/ddl_test_/ddl_test.runfiles/__main__/ddl/modify_column_test.go:816
        	Error:      	Not equal: 
        	            	expected: "[Warning 1292 Truncated incorrect DECIMAL value: '111.22']\n[Warning 1292 Truncated incorrect DECIMAL value: '111.22']\n[Warning 1292 Truncated incorrect DECIMAL value: '111.22']\n[Warning 1292 Truncated incorrect DECIMAL value: '111.22']\n"
        	            	actual  : "[Warning 1292 4 warnings with this error code, first warning: Truncated incorrect DECIMAL value: '111.22']\n"
        	            	
        	            	Diff:
        	            	--- Expected
        	            	+++ Actual
        	            	@@ -1,5 +1,2 @@
        	            	-[Warning 1292 Truncated incorrect DECIMAL value: '111.22']
        	            	-[Warning 1292 Truncated incorrect DECIMAL value: '111.22']
        	            	-[Warning 1292 Truncated incorrect DECIMAL value: '111.22']
        	            	-[Warning 1292 Truncated incorrect DECIMAL value: '111.22']
        	            	+[Warning 1292 4 warnings with this error code, first warning: Truncated incorrect DECIMAL value: '111.22']
        	            	 
        	Test:       	TestModifyColumnTypeWithWarnings
        	Messages:   	sql:show warnings, args:[]
[2022/11/16 14:06:49.554 +08:00] [INFO] [ddl_workerpool.go:82] ["[ddl] closing workerPool"]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 266, tp add index"] ["take time"=1.625µs]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 267, tp add index"] ["take time"=2.03µs]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 268, tp add index"] ["take time"=974ns]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 269, tp add index"] ["take time"=982ns]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 270, tp add index"] ["take time"=1.191µs]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 271, tp add index"] ["take time"=1.165µs]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 272, tp add index"] ["take time"=1.033µs]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 273, tp add index"] ["take time"=902ns]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 274, tp add index"] ["take time"=1.557µs]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 265, tp add index"] ["take time"=916ns]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_workerpool.go:82] ["[ddl] closing workerPool"]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 264, tp general"] ["take time"=1.018µs]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 262, tp general"] ["take time"=417ns]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 263, tp add index"] ["take time"=649ns]
[2022/11/16 14:06:49.555 +08:00] [INFO] [delete_range.go:148] ["[ddl] closing delRange"]
[2022/11/16 14:06:49.555 +08:00] [INFO] [session_pool.go:94] ["[ddl] closing sessionPool"]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl.go:815] ["[ddl] DDL closed"] [ID=562290da-0f7a-450e-82f1-094d5f9a3023] ["take time"=2.849804ms]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl.go:639] ["[ddl] stop DDL"] [ID=562290da-0f7a-450e-82f1-094d5f9a3023]
[2022/11/16 14:06:49.555 +08:00] [INFO] [domain.go:1095] ["closestReplicaReadCheckLoop exited."]
[2022/11/16 14:06:49.555 +08:00] [INFO] [domain.go:743] ["loadSchemaInLoop exited."]
[2022/11/16 14:06:49.555 +08:00] [INFO] [handle_hist.go:175] ["SubLoadWorker exited."]
[2022/11/16 14:06:49.555 +08:00] [INFO] [handle_hist.go:175] ["SubLoadWorker exited."]
[2022/11/16 14:06:49.555 +08:00] [INFO] [handle_hist.go:175] ["SubLoadWorker exited."]
[2022/11/16 14:06:49.555 +08:00] [INFO] [handle_hist.go:175] ["SubLoadWorker exited."]
[2022/11/16 14:06:49.555 +08:00] [INFO] [domain.go:1617] ["dumpFileGcChecker exited."]
[2022/11/16 14:06:49.555 +08:00] [INFO] [handle_hist.go:175] ["SubLoadWorker exited."]
[2022/11/16 14:06:49.555 +08:00] [INFO] [domain.go:1332] ["LoadSysVarCacheLoop exited."]
[2022/11/16 14:06:49.556 +08:00] [INFO] [domain.go:1282] ["loadPrivilegeInLoop exited."]
[2022/11/16 14:06:49.556 +08:00] [INFO] [domain.go:1457] ["handleEvolvePlanTasksLoop exited."]
[2022/11/16 14:06:49.556 +08:00] [INFO] [domain.go:1413] ["globalBindHandleWorkerLoop exited."]
[2022/11/16 14:06:49.556 +08:00] [INFO] [domain.go:608] ["topologySyncerKeeper exited."]
[2022/11/16 14:06:49.556 +08:00] [INFO] [domain.go:560] ["infoSyncerKeeper exited."]
[2022/11/16 14:06:49.556 +08:00] [INFO] [domain.go:585] ["globalConfigSyncerKeeper exited."]
[2022/11/16 14:06:49.556 +08:00] [INFO] [domain.go:531] ["topNSlowQueryLoop exited."]
[2022/11/16 14:06:49.556 +08:00] [INFO] [domain.go:871] ["domain closed"] ["take time"=3.297455ms]
[2022/11/16 14:06:49.560 +08:00] [INFO] [db.go:567] ["Closing database"]
[2022/11/16 14:06:49.561 +08:00] [INFO] [db.go:592] ["Memtable flushed"]
[2022/11/16 14:06:49.561 +08:00] [INFO] [db.go:596] ["Compaction finished"]
[2022/11/16 14:06:49.561 +08:00] [INFO] [db.go:615] ["BlobManager finished"]
[2022/11/16 14:06:49.561 +08:00] [INFO] [db.go:619] ["ResourceManager finished"]
[2022/11/16 14:06:49.561 +08:00] [INFO] [db.go:625] ["Waiting for closer"]
--- FAIL: TestModifyColumnTypeWithWarnings (4.49s)

Signed-off-by: x-shadow-man <1494445739@qq.com>

wxbty · 2022-11-16T07:11:11Z

The error msg

[2022/11/16 14:08:19.957 +08:00] [INFO] [callback_test.go:107] ["on job updated"] [job="ID:78, Type:modify column, State:done, SchemaState:public, SchemaID:2, TableID:76, RowCount:4096, ArgLen:2, start time: 2022-11-16 14:08:19.473 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:437407947076665345"]
[2022/11/16 14:08:19.973 +08:00] [INFO] [delete_range.go:109] ["[ddl] add job into delete-range table"] [jobID=78] [jobType="modify column"]
[2022/11/16 14:08:19.974 +08:00] [INFO] [ddl_worker.go:632] ["[ddl] finish DDL job"] [worker="worker 267, tp add index"] [job="ID:78, Type:modify column, State:synced, SchemaState:public, SchemaID:2, TableID:76, RowCount:4096, ArgLen:2, start time: 2022-11-16 14:08:19.473 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:437407947076665345"]
[2022/11/16 14:08:19.977 +08:00] [INFO] [callback_test.go:107] ["on job updated"] [job="ID:78, Type:modify column, State:synced, SchemaState:public, SchemaID:2, TableID:76, RowCount:4096, ArgLen:2, start time: 2022-11-16 14:08:19.473 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:437407947076665345"]
[2022/11/16 14:08:19.982 +08:00] [INFO] [ddl.go:1110] ["[ddl] DDL job is finished"] [jobID=78]
[2022/11/16 14:08:19.982 +08:00] [INFO] [callback_test.go:66] ["performing DDL change, must reload"]
    modify_column_test.go:898: 
        	Error Trace:	/home/jenkins/.tidb/tmp/63a9840cd0739f2c243bb46478607469/sandbox/linux-sandbox/6938/execroot/__main__/bazel-out/k8-fastbuild/bin/ddl/ddl_test_/ddl_test.runfiles/__main__/ddl/modify_column_test.go:898
        	Error:      	"[[Warning 1292 4096 warnings with this error code, first warning: Truncated incorrect DECIMAL value: '11.22']]" should have 4096 item(s), but has 1
        	Test:       	TestModifyColumnTypeWhenInterception
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_workerpool.go:82] ["[ddl] closing workerPool"]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 269, tp add index"] ["take time"=1.491µs]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 270, tp add index"] ["take time"=1.054µs]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 271, tp add index"] ["take time"=899ns]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 272, tp add index"] ["take time"=892ns]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 273, tp add index"] ["take time"=1.071µs]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 274, tp add index"] ["take time"=1.002µs]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 265, tp add index"] ["take time"=931ns]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 266, tp add index"] ["take time"=893ns]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 267, tp add index"] ["take time"=1.008µs]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 268, tp add index"] ["take time"=829ns]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_workerpool.go:82] ["[ddl] closing workerPool"]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 264, tp general"] ["take time"=1.066µs]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 262, tp general"] ["take time"=377ns]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 263, tp add index"] ["take time"=252ns]
[2022/11/16 14:08:19.984 +08:00] [INFO] [delete_range.go:148] ["[ddl] closing delRange"]
[2022/11/16 14:08:19.984 +08:00] [INFO] [session_pool.go:94] ["[ddl] closing sessionPool"]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl.go:815] ["[ddl] DDL closed"] [ID=195c88d3-e504-485f-80a8-5c6020e67a8d] ["take time"=1.956832ms]
[2022/11/16 14:08:19.984 +08:00] [INFO] [ddl.go:639] ["[ddl] stop DDL"] [ID=195c88d3-e504-485f-80a8-5c6020e67a8d]
[2022/11/16 14:08:19.984 +08:00] [INFO] [domain.go:1095] ["closestReplicaReadCheckLoop exited."]
[2022/11/16 14:08:19.984 +08:00] [INFO] [domain.go:743] ["loadSchemaInLoop exited."]
[2022/11/16 14:08:19.984 +08:00] [INFO] [handle_hist.go:175] ["SubLoadWorker exited."]
[2022/11/16 14:08:19.984 +08:00] [INFO] [handle_hist.go:175] ["SubLoadWorker exited."]
[2022/11/16 14:08:19.984 +08:00] [INFO] [handle_hist.go:175] ["SubLoadWorker exited."]
[2022/11/16 14:08:19.984 +08:00] [INFO] [handle_hist.go:175] ["SubLoadWorker exited."]
[2022/11/16 14:08:19.984 +08:00] [INFO] [domain.go:1617] ["dumpFileGcChecker exited."]
[2022/11/16 14:08:19.984 +08:00] [INFO] [handle_hist.go:175] ["SubLoadWorker exited."]
[2022/11/16 14:08:19.984 +08:00] [INFO] [domain.go:1332] ["LoadSysVarCacheLoop exited."]
[2022/11/16 14:08:19.984 +08:00] [INFO] [domain.go:1282] ["loadPrivilegeInLoop exited."]
[2022/11/16 14:08:19.984 +08:00] [INFO] [domain.go:1457] ["handleEvolvePlanTasksLoop exited."]
[2022/11/16 14:08:19.985 +08:00] [INFO] [domain.go:1413] ["globalBindHandleWorkerLoop exited."]
[2022/11/16 14:08:19.985 +08:00] [INFO] [domain.go:608] ["topologySyncerKeeper exited."]
[2022/11/16 14:08:19.985 +08:00] [INFO] [domain.go:560] ["infoSyncerKeeper exited."]
[2022/11/16 14:08:19.985 +08:00] [INFO] [domain.go:585] ["globalConfigSyncerKeeper exited."]
[2022/11/16 14:08:19.985 +08:00] [INFO] [domain.go:531] ["topNSlowQueryLoop exited."]
[2022/11/16 14:08:19.985 +08:00] [INFO] [domain.go:871] ["domain closed"] ["take time"=2.393879ms]
[2022/11/16 14:08:19.996 +08:00] [INFO] [db.go:567] ["Closing database"]
[2022/11/16 14:08:20.002 +08:00] [INFO] [db.go:592] ["Memtable flushed"]
[2022/11/16 14:08:20.002 +08:00] [INFO] [db.go:596] ["Compaction finished"]
[2022/11/16 14:08:20.002 +08:00] [INFO] [db.go:615] ["BlobManager finished"]
[2022/11/16 14:08:20.002 +08:00] [INFO] [db.go:619] ["ResourceManager finished"]
[2022/11/16 14:08:20.002 +08:00] [INFO] [db.go:625] ["Waiting for closer"]
--- FAIL: TestModifyColumnTypeWhenInterception (4.84s)

[2022/11/16 14:06:49.552 +08:00] [INFO] [ddl.go:1110] ["[ddl] DDL job is finished"] [jobID=78]
[2022/11/16 14:06:49.552 +08:00] [INFO] [callback.go:121] ["performing DDL change, must reload"]
    result.go:49: 
        	Error Trace:	/home/jenkins/.tidb/tmp/63a9840cd0739f2c243bb46478607469/sandbox/linux-sandbox/6696/execroot/__main__/bazel-out/k8-fastbuild/bin/ddl/ddl_test_/ddl_test.runfiles/__main__/ddl/result.go:49
        	            				/home/jenkins/.tidb/tmp/63a9840cd0739f2c243bb46478607469/sandbox/linux-sandbox/6696/execroot/__main__/bazel-out/k8-fastbuild/bin/ddl/ddl_test_/ddl_test.runfiles/__main__/ddl/modify_column_test.go:816
        	Error:      	Not equal: 
        	            	expected: "[Warning 1292 Truncated incorrect DECIMAL value: '111.22']\n[Warning 1292 Truncated incorrect DECIMAL value: '111.22']\n[Warning 1292 Truncated incorrect DECIMAL value: '111.22']\n[Warning 1292 Truncated incorrect DECIMAL value: '111.22']\n"
        	            	actual  : "[Warning 1292 4 warnings with this error code, first warning: Truncated incorrect DECIMAL value: '111.22']\n"
        	            	
        	            	Diff:
        	            	--- Expected
        	            	+++ Actual
        	            	@@ -1,5 +1,2 @@
        	            	-[Warning 1292 Truncated incorrect DECIMAL value: '111.22']
        	            	-[Warning 1292 Truncated incorrect DECIMAL value: '111.22']
        	            	-[Warning 1292 Truncated incorrect DECIMAL value: '111.22']
        	            	-[Warning 1292 Truncated incorrect DECIMAL value: '111.22']
        	            	+[Warning 1292 4 warnings with this error code, first warning: Truncated incorrect DECIMAL value: '111.22']
        	            	 
        	Test:       	TestModifyColumnTypeWithWarnings
        	Messages:   	sql:show warnings, args:[]
[2022/11/16 14:06:49.554 +08:00] [INFO] [ddl_workerpool.go:82] ["[ddl] closing workerPool"]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 266, tp add index"] ["take time"=1.625µs]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 267, tp add index"] ["take time"=2.03µs]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 268, tp add index"] ["take time"=974ns]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 269, tp add index"] ["take time"=982ns]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 270, tp add index"] ["take time"=1.191µs]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 271, tp add index"] ["take time"=1.165µs]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 272, tp add index"] ["take time"=1.033µs]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 273, tp add index"] ["take time"=902ns]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 274, tp add index"] ["take time"=1.557µs]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 265, tp add index"] ["take time"=916ns]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_workerpool.go:82] ["[ddl] closing workerPool"]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 264, tp general"] ["take time"=1.018µs]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 262, tp general"] ["take time"=417ns]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 263, tp add index"] ["take time"=649ns]
[2022/11/16 14:06:49.555 +08:00] [INFO] [delete_range.go:148] ["[ddl] closing delRange"]
[2022/11/16 14:06:49.555 +08:00] [INFO] [session_pool.go:94] ["[ddl] closing sessionPool"]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl.go:815] ["[ddl] DDL closed"] [ID=562290da-0f7a-450e-82f1-094d5f9a3023] ["take time"=2.849804ms]
[2022/11/16 14:06:49.555 +08:00] [INFO] [ddl.go:639] ["[ddl] stop DDL"] [ID=562290da-0f7a-450e-82f1-094d5f9a3023]
[2022/11/16 14:06:49.555 +08:00] [INFO] [domain.go:1095] ["closestReplicaReadCheckLoop exited."]
[2022/11/16 14:06:49.555 +08:00] [INFO] [domain.go:743] ["loadSchemaInLoop exited."]
[2022/11/16 14:06:49.555 +08:00] [INFO] [handle_hist.go:175] ["SubLoadWorker exited."]
[2022/11/16 14:06:49.555 +08:00] [INFO] [handle_hist.go:175] ["SubLoadWorker exited."]
[2022/11/16 14:06:49.555 +08:00] [INFO] [handle_hist.go:175] ["SubLoadWorker exited."]
[2022/11/16 14:06:49.555 +08:00] [INFO] [handle_hist.go:175] ["SubLoadWorker exited."]
[2022/11/16 14:06:49.555 +08:00] [INFO] [domain.go:1617] ["dumpFileGcChecker exited."]
[2022/11/16 14:06:49.555 +08:00] [INFO] [handle_hist.go:175] ["SubLoadWorker exited."]
[2022/11/16 14:06:49.555 +08:00] [INFO] [domain.go:1332] ["LoadSysVarCacheLoop exited."]
[2022/11/16 14:06:49.556 +08:00] [INFO] [domain.go:1282] ["loadPrivilegeInLoop exited."]
[2022/11/16 14:06:49.556 +08:00] [INFO] [domain.go:1457] ["handleEvolvePlanTasksLoop exited."]
[2022/11/16 14:06:49.556 +08:00] [INFO] [domain.go:1413] ["globalBindHandleWorkerLoop exited."]
[2022/11/16 14:06:49.556 +08:00] [INFO] [domain.go:608] ["topologySyncerKeeper exited."]
[2022/11/16 14:06:49.556 +08:00] [INFO] [domain.go:560] ["infoSyncerKeeper exited."]
[2022/11/16 14:06:49.556 +08:00] [INFO] [domain.go:585] ["globalConfigSyncerKeeper exited."]
[2022/11/16 14:06:49.556 +08:00] [INFO] [domain.go:531] ["topNSlowQueryLoop exited."]
[2022/11/16 14:06:49.556 +08:00] [INFO] [domain.go:871] ["domain closed"] ["take time"=3.297455ms]
[2022/11/16 14:06:49.560 +08:00] [INFO] [db.go:567] ["Closing database"]
[2022/11/16 14:06:49.561 +08:00] [INFO] [db.go:592] ["Memtable flushed"]
[2022/11/16 14:06:49.561 +08:00] [INFO] [db.go:596] ["Compaction finished"]
[2022/11/16 14:06:49.561 +08:00] [INFO] [db.go:615] ["BlobManager finished"]
[2022/11/16 14:06:49.561 +08:00] [INFO] [db.go:619] ["ResourceManager finished"]
[2022/11/16 14:06:49.561 +08:00] [INFO] [db.go:625] ["Waiting for closer"]
--- FAIL: TestModifyColumnTypeWithWarnings (4.49s)

Some modifications have been made, but the problem now is that the TestModifyColumnTypeWhenInterception testcase originally failed to run in the master, showing job.RowCount=4096, which is not equal to middleWarningsCount. This testcase is judged by warn count, which is always equal to 1 now. Is it unnecessary and can be removed?

[2022/11/16 15:06:55.461 +08:00] [INFO] [ddl.go:1110] ["[ddl] DDL job is finished"] [jobID=78]
[2022/11/16 15:06:55.461 +08:00] [INFO] [callback_test.go:66] ["performing DDL change, must reload"]
    modify_column_test.go:889: 
        	Error Trace:	/Users/zcy/IdeaProjects/tidb/ddl/modify_column_test.go:889
        	Error:      	Should be true
        	Test:       	TestModifyColumnTypeWhenInterception
[2022/11/16 15:06:55.462 +08:00] [INFO] [ddl_workerpool.go:82] ["[ddl] closing workerPool"]
[2022/11/16 15:06:55.462 +08:00] [INFO] [ddl_worker.go:165] ["[ddl] DDL worker closed"] [worker="worker 10, tp add index"] ["take time"=458ns]

ddl/modify_column_test.go

Defined2014 · 2022-11-17T05:59:10Z

/merge

ti-chi-bot · 2022-11-17T05:59:14Z

This pull request has been accepted and is ready to merge.

Commit hash: cba2577

Defined2014 · 2022-11-17T06:09:06Z

/run-mysql-test

Defined2014 · 2022-11-17T06:51:08Z

/run-check_dev_2

Defined2014 · 2022-11-17T08:52:49Z

/run-all-tests

sre-bot · 2022-11-17T10:08:28Z

TiDB MergeCI notify

🔴 Bad News! New failing [1] after this pr merged.
These new failed integration tests seem to be caused by the current PR, please try to fix these new failed integration tests, thanks!

CI Name	Result	Duration	Compare with Parent commit
idc-jenkins-ci-tidb/integration-ddl-test	🟥 failed 2, success 4, total 6	43 min	New failing
idc-jenkins-ci/integration-cdc-test	🔴 failed 1, success 38, total 39	20 min	Existing failure
idc-jenkins-ci-tidb/mybatis-test	🔴 failed 1, success 0, total 1	11 min	Existing failure
idc-jenkins-ci-tidb/integration-common-test	🟢 all 17 tests passed	14 min	Existing passed
idc-jenkins-ci-tidb/common-test	🟢 all 11 tests passed	10 min	Existing passed
idc-jenkins-ci-tidb/sqllogic-test-1	🟢 all 26 tests passed	6 min 40 sec	Existing passed
idc-jenkins-ci-tidb/sqllogic-test-2	🟢 all 28 tests passed	6 min 35 sec	Existing passed
idc-jenkins-ci-tidb/tics-test	🟢 all 1 tests passed	5 min 51 sec	Existing passed
idc-jenkins-ci-tidb/integration-compatibility-test	🟢 all 1 tests passed	2 min 51 sec	Existing passed
idc-jenkins-ci-tidb/plugin-test	🟢 build success, plugin test success	4min	Existing passed

fix: warning shows the same line

d7cca64

Signed-off-by: x-shadow-man <1494445739@qq.com>

ti-chi-bot added release-note-none Denotes a PR that doesn't merit a release note. size/M Denotes a PR that changes 30-99 lines, ignoring generated files. labels Oct 31, 2022

ti-chi-bot requested review from bb7133 and mjonss October 31, 2022 07:17

mjonss approved these changes Oct 31, 2022

View reviewed changes

ddl/ddl.go Outdated Show resolved Hide resolved

ddl/failtest/fail_db_test.go Outdated Show resolved Hide resolved

ti-chi-bot added the status/LGT1 Indicates that a PR has LGTM 1. label Oct 31, 2022

x-shadow-man and others added 7 commits November 1, 2022 10:43

format opt

e461153

Signed-off-by: x-shadow-man <1494445739@qq.com>

format opt

ed0537e

Signed-off-by: x-shadow-man <1494445739@qq.com>

Merge remote-tracking branch 'upstream/master' into bugfix-ddl-warn

6fde55d

Merge remote-tracking branch 'upstream/master' into bugfix-ddl-warn

5872c72

Merge branch 'master' into bugfix-ddl-warn

aed7673

Merge branch 'master' into bugfix-ddl-warn

68460b5

Merge branch 'master' into bugfix-ddl-warn

219a6c7

Merge branch 'master' into bugfix-ddl-warn

1e49949

update associated testcase

b6d3fd2

update associated testcase

e524c74

Signed-off-by: x-shadow-man <1494445739@qq.com>

Defined2014 reviewed Nov 16, 2022

View reviewed changes

ddl/modify_column_test.go Outdated Show resolved Hide resolved

remove unuse code

cba2577

wxbty requested review from Defined2014 and removed request for bb7133 November 17, 2022 05:55

Defined2014 approved these changes Nov 17, 2022

View reviewed changes

ti-chi-bot added status/LGT2 Indicates that a PR has LGTM 2. and removed status/LGT1 Indicates that a PR has LGTM 1. labels Nov 17, 2022

ti-chi-bot added the status/can-merge Indicates a PR has been approved by a committer. label Nov 17, 2022

ti-chi-bot and others added 2 commits November 17, 2022 13:59

Merge branch 'master' into bugfix-ddl-warn

0003db5

Merge branch 'master' into bugfix-ddl-warn

a12aec5

ti-chi-bot added 2 commits November 17, 2022 15:00

Merge branch 'master' into bugfix-ddl-warn

c8b5ff4

Merge branch 'master' into bugfix-ddl-warn

c4021ee

Merge branch 'master' into bugfix-ddl-warn

ddac87a

ti-chi-bot merged commit 077cde7 into pingcap:master Nov 17, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

ddl: fix "wrong warning messages when running some DDL jobs" #38761

ddl: fix "wrong warning messages when running some DDL jobs" #38761

wxbty commented Oct 31, 2022 •

edited

Loading

ti-chi-bot commented Oct 31, 2022 •

edited

Loading

wxbty commented Oct 31, 2022

mjonss left a comment

Defined2014 commented Nov 16, 2022

wxbty commented Nov 16, 2022

Defined2014 commented Nov 16, 2022

wxbty commented Nov 16, 2022 •

edited

Loading

Defined2014 commented Nov 17, 2022

ti-chi-bot commented Nov 17, 2022

Defined2014 commented Nov 17, 2022

Defined2014 commented Nov 17, 2022

Defined2014 commented Nov 17, 2022

sre-bot commented Nov 17, 2022

ddl: fix "wrong warning messages when running some DDL jobs" #38761

ddl: fix "wrong warning messages when running some DDL jobs" #38761

Conversation

wxbty commented Oct 31, 2022 • edited Loading

What problem does this PR solve?

What is changed and how it works?

Check List

Release note

ti-chi-bot commented Oct 31, 2022 • edited Loading

wxbty commented Oct 31, 2022

mjonss left a comment

Choose a reason for hiding this comment

Defined2014 commented Nov 16, 2022

wxbty commented Nov 16, 2022

Defined2014 commented Nov 16, 2022

wxbty commented Nov 16, 2022 • edited Loading

Defined2014 commented Nov 17, 2022

ti-chi-bot commented Nov 17, 2022

Defined2014 commented Nov 17, 2022

Defined2014 commented Nov 17, 2022

Defined2014 commented Nov 17, 2022

sre-bot commented Nov 17, 2022

TiDB MergeCI notify

wxbty commented Oct 31, 2022 •

edited

Loading

ti-chi-bot commented Oct 31, 2022 •

edited

Loading

wxbty commented Nov 16, 2022 •

edited

Loading