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

Race detected for test TestLoadRemote/TestZStd #47776

Closed
Tracked by #41316
YangKeao opened this issue Oct 19, 2023 · 0 comments · Fixed by #47965
Closed
Tracked by #41316

Race detected for test TestLoadRemote/TestZStd #47776

YangKeao opened this issue Oct 19, 2023 · 0 comments · Fixed by #47965
Labels
affects-7.5 This bug affects the 7.5.x(LTS) versions. component/lightning This issue is related to Lightning of TiDB. component/test severity/major type/bug The issue is confirmed as a bug.

Comments

@YangKeao
Copy link
Member

Here is the log:

=== RUN   TestLoadRemote/TestZStd
[2023/10/19 12:54:29.595 +08:00] [INFO] [session.go:3908] ["CRUCIAL OPERATION"] [conn=2] [schemaVersion=55] [cur_db=snappy] [sql="drop database if exists zstd"] [user=]
[2023/10/19 12:54:29.596 +08:00] [INFO] [session.go:3908] ["CRUCIAL OPERATION"] [conn=2] [schemaVersion=55] [cur_db=snappy] [sql="create database zstd"] [user=]
[2023/10/19 12:54:29.608 +08:00] [INFO] [ddl.go:1088] ["start DDL job"] [category=ddl] [job="ID:113, Type:create schema, State:queueing, SchemaState:none, SchemaID:112, TableID:0, RowCount:0, ArgLen:1, start time: 2023-10-19 12:54:29.567 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="create database zstd"]
[2023/10/19 12:54:29.608 +08:00] [INFO] [ddl_worker.go:252] ["add DDL jobs"] [category=ddl] ["batch count"=1] [jobs="ID:113, Type:create schema, State:queueing, SchemaState:none, SchemaID:112, TableID:0, RowCount:0, ArgLen:1, start time: 2023-10-19 12:54:29.567 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0; "] [table=true]
[2023/10/19 12:54:29.623 +08:00] [INFO] [ddl_worker.go:995] ["run DDL job"] [worker="worker 12, tp general"] [category=ddl] [jobID=113] [conn=2] [category=ddl] [job="ID:113, Type:create schema, State:queueing, SchemaState:none, SchemaID:112, TableID:0, RowCount:0, ArgLen:0, start time: 2023-10-19 12:54:29.567 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2023/10/19 12:54:29.637 +08:00] [INFO] [domain.go:262] ["diff load InfoSchema success"] [currentSchemaVersion=55] [neededSchemaVersion=56] ["start time"=951.083µs] [gotSchemaVersion=56] [phyTblIDs="[]"] [actionTypes="[]"]
[2023/10/19 12:54:29.641 +08:00] [INFO] [domain.go:860] ["mdl gets lock, update to owner"] [jobID=113] [version=56]
[2023/10/19 12:54:29.687 +08:00] [INFO] [ddl_worker.go:1229] ["wait latest schema version changed(get the metadata lock if tidb_enable_metadata_lock is true)"] [category=ddl] [ver=56] ["take time"=52.908933ms] [job="ID:113, Type:create schema, State:done, SchemaState:public, SchemaID:112, TableID:0, RowCount:0, ArgLen:1, start time: 2023-10-19 12:54:29.567 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2023/10/19 12:54:29.702 +08:00] [INFO] [ddl_worker.go:619] ["finish DDL job"] [worker="worker 12, tp general"] [category=ddl] [jobID=113] [conn=2] [job="ID:113, Type:create schema, State:synced, SchemaState:public, SchemaID:112, TableID:0, RowCount:0, ArgLen:0, start time: 2023-10-19 12:54:29.567 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2023/10/19 12:54:29.712 +08:00] [INFO] [ddl.go:1190] ["DDL job is finished"] [category=ddl] [jobID=113]
[2023/10/19 12:54:29.712 +08:00] [INFO] [callback.go:139] ["performing DDL change, must reload"]
[2023/10/19 12:54:29.715 +08:00] [INFO] [session.go:3908] ["CRUCIAL OPERATION"] [conn=2] [schemaVersion=56] [cur_db=zstd] [sql="CREATE TABLE zstd.t (i INT PRIMARY KEY, s varchar(32));"] [user=]
[2023/10/19 12:54:29.729 +08:00] [INFO] [ddl.go:1088] ["start DDL job"] [category=ddl] [job="ID:115, Type:create table, State:queueing, SchemaState:none, SchemaID:112, TableID:114, RowCount:0, ArgLen:2, start time: 2023-10-19 12:54:29.716 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE zstd.t (i INT PRIMARY KEY, s varchar(32));"]
[2023/10/19 12:54:29.729 +08:00] [INFO] [ddl_worker.go:252] ["add DDL jobs"] [category=ddl] ["batch count"=1] [jobs="ID:115, Type:create table, State:queueing, SchemaState:none, SchemaID:112, TableID:114, RowCount:0, ArgLen:2, start time: 2023-10-19 12:54:29.716 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0; "] [table=true]
[2023/10/19 12:54:29.751 +08:00] [INFO] [ddl_worker.go:995] ["run DDL job"] [worker="worker 12, tp general"] [category=ddl] [jobID=115] [conn=2] [category=ddl] [job="ID:115, Type:create table, State:queueing, SchemaState:none, SchemaID:112, TableID:114, RowCount:0, ArgLen:0, start time: 2023-10-19 12:54:29.716 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2023/10/19 12:54:29.763 +08:00] [INFO] [scheduler.go:93] ["scheduler exits"] [task-id=3] [error="context canceled"]
[2023/10/19 12:54:29.771 +08:00] [INFO] [domain.go:262] ["diff load InfoSchema success"] [currentSchemaVersion=56] [neededSchemaVersion=57] ["start time"=1.962489ms] [gotSchemaVersion=57] [phyTblIDs="[114]"] [actionTypes="[3]"]
[2023/10/19 12:54:29.775 +08:00] [INFO] [domain.go:860] ["mdl gets lock, update to owner"] [jobID=115] [version=57]
[2023/10/19 12:54:29.819 +08:00] [INFO] [ddl_worker.go:1229] ["wait latest schema version changed(get the metadata lock if tidb_enable_metadata_lock is true)"] [category=ddl] [ver=57] ["take time"=53.473799ms] [job="ID:115, Type:create table, State:done, SchemaState:public, SchemaID:112, TableID:114, RowCount:0, ArgLen:2, start time: 2023-10-19 12:54:29.716 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2023/10/19 12:54:29.839 +08:00] [INFO] [ddl_worker.go:619] ["finish DDL job"] [worker="worker 12, tp general"] [category=ddl] [jobID=115] [conn=2] [job="ID:115, Type:create table, State:synced, SchemaState:public, SchemaID:112, TableID:114, RowCount:0, ArgLen:0, start time: 2023-10-19 12:54:29.716 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2023/10/19 12:54:29.850 +08:00] [INFO] [ddl.go:1190] ["DDL job is finished"] [category=ddl] [jobID=115]
[2023/10/19 12:54:29.851 +08:00] [INFO] [callback.go:139] ["performing DDL change, must reload"]
[2023/10/19 12:54:30.008 +08:00] [INFO] [dispatcher_manager.go:283] ["task finished"] [task-id=3]
[2023/10/19 12:54:30.009 +08:00] [INFO] [import_into.go:199] ["get job importer"] [param="{\"file-location\":\"gs://zstd/t.*?endpoint=http://127.0.0.1:4443/storage/v1/\",\"format\":\"csv\",\"options\":{\"thread\":\"1\"}}"] [dist-task-enabled=false]
[2023/10/19 12:54:30.016 +08:00] [INFO] [dispatcher_manager.go:329] ["cleanUp routine start"]
[2023/10/19 12:54:30.027 +08:00] [INFO] [job.go:205] ["job submitted to global task queue"] [task-id=4] [job-id=4] [thread-cnt=1]
[2023/10/19 12:54:30.027 +08:00] [INFO] [job.go:105] ["start distribute IMPORT INTO"] [task-id=4]
[2023/10/19 12:54:30.029 +08:00] [INFO] [dispatcher_manager.go:338] ["cleanUp routine success"]
[2023/10/19 12:54:30.995 +08:00] [INFO] [dispatcher.go:130] ["execute one task"] [task-id=4] [task-type=ImportInto] [state=pending] [concurrency=1]
[2023/10/19 12:54:31.498 +08:00] [INFO] [dispatcher.go:503] [onNextStage] [task-id=4] [task-type=ImportInto] [current-step=-1] [next-step=1]
[2023/10/19 12:54:31.499 +08:00] [INFO] [dispatcher.go:218] ["on next subtasks batch"] [type=ImportInto] [task-id=4] [curr-step=init] [next-step=import]
==================
WARNING: DATA RACE
Read at 0x00c0626af2f0 by goroutine 96236:
  github.com/pingcap/tidb/br/pkg/storage.(*gcsObjectReader).Seek()
      br/pkg/storage/gcs.go:427 +0x1fd
  github.com/pingcap/tidb/br/pkg/storage.(*compressReader).Seek()
      br/pkg/storage/compress.go:136 +0x88
  github.com/pingcap/tidb/br/pkg/lightning/mydump.calculateFileBytes()
      br/pkg/lightning/mydump/loader.go:727 +0x369
  github.com/pingcap/tidb/br/pkg/lightning/mydump.SampleFileCompressRatio()
      br/pkg/lightning/mydump/loader.go:770 +0x2b4
  github.com/pingcap/tidb/pkg/executor/importer.(*LoadDataController).getFileRealSize()
      pkg/executor/importer/import.go:1073 +0xb7
  github.com/pingcap/tidb/pkg/executor/importer.(*LoadDataController).InitDataFiles.func2()
      pkg/executor/importer/import.go:1053 +0x2c4
  github.com/pingcap/tidb/br/pkg/storage.(*GCSStorage).WalkDir()
      br/pkg/storage/gcs.go:260 +0x5c1
  github.com/pingcap/tidb/pkg/executor/importer.(*LoadDataController).InitDataFiles()
      pkg/executor/importer/import.go:1038 +0x17f4
  github.com/pingcap/tidb/pkg/disttask/importinto.generateImportSpecs()
      pkg/disttask/importinto/planner.go:261 +0x12d
  github.com/pingcap/tidb/pkg/disttask/importinto.(*LogicalPlan).ToPhysicalPlan()
      pkg/disttask/importinto/planner.go:112 +0x4f9
  github.com/pingcap/tidb/pkg/disttask/importinto.(*ImportDispatcherExt).OnNextSubtasksBatch()
      pkg/disttask/importinto/dispatcher.go:313 +0x1904
  github.com/pingcap/tidb/pkg/disttask/framework/dispatcher.(*BaseDispatcher).onNextStage()
      pkg/disttask/framework/dispatcher/dispatcher.go:548 +0x821
  github.com/pingcap/tidb/pkg/disttask/framework/dispatcher.(*BaseDispatcher).onPending()
      pkg/disttask/framework/dispatcher/dispatcher.go:319 +0x2a4
  github.com/pingcap/tidb/pkg/disttask/framework/dispatcher.(*BaseDispatcher).scheduleTask()
      pkg/disttask/framework/dispatcher/dispatcher.go:212 +0x14bc
  github.com/pingcap/tidb/pkg/disttask/framework/dispatcher.(*BaseDispatcher).ExecuteTask()
      pkg/disttask/framework/dispatcher/dispatcher.go:132 +0x28a
  github.com/pingcap/tidb/pkg/disttask/importinto.(*importDispatcher).ExecuteTask()
      <autogenerated>:1 +0x3e
  github.com/pingcap/tidb/pkg/disttask/framework/dispatcher.(*Manager).dispatchTaskLoop.(*Manager).startDispatcher.func2()
      pkg/disttask/framework/dispatcher/dispatcher_manager.go:282 +0x37c
  github.com/pingcap/tidb/pkg/resourcemanager/pool/spool.(*Pool).run.func1()
      pkg/resourcemanager/pool/spool/spool.go:145 +0x6d

Previous write at 0x00c0626af2f0 by goroutine 97428:
  github.com/pingcap/tidb/br/pkg/storage.(*gcsObjectReader).Read()
      br/pkg/storage/gcs.go:406 +0x26b
  io.ReadAtLeast()
      GOROOT/src/io/io.go:335 +0xcf
  io.ReadFull()
      GOROOT/src/io/io.go:354 +0x6b
  github.com/klauspost/compress/zstd.(*readerWrapper).readSmall()
      external/com_github_klauspost_compress/zstd/bytebuf.go:86 +0x26
  github.com/klauspost/compress/zstd.(*frameDec).reset()
      external/com_github_klauspost_compress/zstd/framedec.go:72 +0xc1
  github.com/klauspost/compress/zstd.(*Decoder).startStreamDecoder()
      external/com_github_klauspost_compress/zstd/decoder.go:845 +0x5e4
  github.com/klauspost/compress/zstd.(*Decoder).Reset.func1()
      external/com_github_klauspost_compress/zstd/decoder.go:236 +0x79

Goroutine 96236 (running) created at:
  github.com/pingcap/tidb/pkg/resourcemanager/pool/spool.(*Pool).run()
      pkg/resourcemanager/pool/spool/spool.go:137 +0xe4
  github.com/pingcap/tidb/pkg/resourcemanager/pool/spool.(*Pool).Run()
      pkg/resourcemanager/pool/spool/spool.go:117 +0x144
  github.com/pingcap/tidb/pkg/disttask/framework/dispatcher.(*Manager).startDispatcher()
      pkg/disttask/framework/dispatcher/dispatcher_manager.go:269 +0x138b
  github.com/pingcap/tidb/pkg/disttask/framework/dispatcher.(*Manager).dispatchTaskLoop()
      pkg/disttask/framework/dispatcher/dispatcher_manager.go:212 +0x12a5
  github.com/pingcap/tidb/pkg/disttask/framework/dispatcher.(*Manager).dispatchTaskLoop-fm()
      <autogenerated>:1 +0x33
  github.com/pingcap/tidb/pkg/util.(*WaitGroupWrapper).Run.func1()
      pkg/util/wait_group_wrapper.go:154 +0x72

Goroutine 97428 (running) created at:
  github.com/klauspost/compress/zstd.(*Decoder).Reset()
      external/com_github_klauspost_compress/zstd/decoder.go:236 +0xa97
  github.com/klauspost/compress/zstd.NewReader()
      external/com_github_klauspost_compress/zstd/decoder.go:122 +0x911
  github.com/pingcap/tidb/br/pkg/storage.newCompressReader()
      br/pkg/storage/writer.go:107 +0x146
  github.com/pingcap/tidb/br/pkg/storage.InterceptDecompressReader()
      br/pkg/storage/compress.go:103 +0x72
  github.com/pingcap/tidb/br/pkg/storage.NewLimitedInterceptReader()
      br/pkg/storage/compress.go:130 +0x23b
  github.com/pingcap/tidb/br/pkg/lightning/mydump.calculateFileBytes()
      br/pkg/lightning/mydump/loader.go:708 +0x17c
  github.com/pingcap/tidb/br/pkg/lightning/mydump.SampleFileCompressRatio()
      br/pkg/lightning/mydump/loader.go:770 +0x2b4
  github.com/pingcap/tidb/pkg/executor/importer.(*LoadDataController).getFileRealSize()
      pkg/executor/importer/import.go:1073 +0xb7
  github.com/pingcap/tidb/pkg/executor/importer.(*LoadDataController).InitDataFiles.func2()
      pkg/executor/importer/import.go:1053 +0x2c4
  github.com/pingcap/tidb/br/pkg/storage.(*GCSStorage).WalkDir()
      br/pkg/storage/gcs.go:260 +0x5c1
  github.com/pingcap/tidb/pkg/executor/importer.(*LoadDataController).InitDataFiles()
      pkg/executor/importer/import.go:1038 +0x17f4
  github.com/pingcap/tidb/pkg/disttask/importinto.generateImportSpecs()
      pkg/disttask/importinto/planner.go:261 +0x12d
  github.com/pingcap/tidb/pkg/disttask/importinto.(*LogicalPlan).ToPhysicalPlan()
      pkg/disttask/importinto/planner.go:112 +0x4f9
  github.com/pingcap/tidb/pkg/disttask/importinto.(*ImportDispatcherExt).OnNextSubtasksBatch()
      pkg/disttask/importinto/dispatcher.go:313 +0x1904
  github.com/pingcap/tidb/pkg/disttask/framework/dispatcher.(*BaseDispatcher).onNextStage()
      pkg/disttask/framework/dispatcher/dispatcher.go:548 +0x821
  github.com/pingcap/tidb/pkg/disttask/framework/dispatcher.(*BaseDispatcher).onPending()
      pkg/disttask/framework/dispatcher/dispatcher.go:319 +0x2a4
  github.com/pingcap/tidb/pkg/disttask/framework/dispatcher.(*BaseDispatcher).scheduleTask()
      pkg/disttask/framework/dispatcher/dispatcher.go:212 +0x14bc
  github.com/pingcap/tidb/pkg/disttask/framework/dispatcher.(*BaseDispatcher).ExecuteTask()
      pkg/disttask/framework/dispatcher/dispatcher.go:132 +0x28a
  github.com/pingcap/tidb/pkg/disttask/importinto.(*importDispatcher).ExecuteTask()
      <autogenerated>:1 +0x3e
  github.com/pingcap/tidb/pkg/disttask/framework/dispatcher.(*Manager).dispatchTaskLoop.(*Manager).startDispatcher.func2()
      pkg/disttask/framework/dispatcher/dispatcher_manager.go:282 +0x37c
  github.com/pingcap/tidb/pkg/resourcemanager/pool/spool.(*Pool).run.func1()
      pkg/resourcemanager/pool/spool/spool.go:145 +0x6d
==================
[2023/10/19 12:54:31.519 +08:00] [INFO] [table_import.go:331] ["populate chunks start"] [table=t]
[2023/10/19 12:54:31.519 +08:00] [INFO] [table_import.go:342] ["adjust max engine size"] [table=t] [before=536870912000] [after=56]
[2023/10/19 12:54:31.519 +08:00] [INFO] [region.go:292] [makeTableRegions] [filesCount=2] [MaxChunkSize=268435456] [RegionsCount=2] [BatchSize=56] [cost=80.984µs]
[2023/10/19 12:54:31.519 +08:00] [INFO] [table_import.go:333] ["populate chunks completed"] [table=t] [takeTime=196.357µs] []
[2023/10/19 12:54:31.520 +08:00] [INFO] [dispatcher.go:321] ["generate subtasks"] [type=ImportInto] [task-id=4] [curr-step=init] [next-step=import] [subtask-count=1]
[2023/10/19 12:54:31.520 +08:00] [INFO] [dispatcher.go:576] ["dispatch subtasks"] [task-id=4] [task-type=ImportInto] [state=pending] [step=-1] [concurrency=1] [subtasks=1]
[2023/10/19 12:54:31.527 +08:00] [INFO] [dispatcher.go:591] ["eligible instances"] [task-id=4] [task-type=ImportInto] [num=1]
[2023/10/19 12:54:31.527 +08:00] [INFO] [dispatcher.go:431] ["task state transform"] [from=pending] [to=pending]
[2023/10/19 12:54:31.539 +08:00] [INFO] [dispatcher.go:538] ["move to next stage"] [task-id=4] [task-type=ImportInto] [from=-1] [to=1]
[2023/10/19 12:54:31.539 +08:00] [INFO] [dispatcher.go:431] ["task state transform"] [from=pending] [to=running]
[2023/10/19 12:54:31.798 +08:00] [INFO] [manager.go:206] ["detect new subtask"] [task-id=4]
[2023/10/19 12:54:31.798 +08:00] [INFO] [manager.go:292] [onRunnableTask] [task-id=4] [type=ImportInto]
[2023/10/19 12:54:32.008 +08:00] [INFO] [pd_service_discovery.go:606] ["[pd] update member urls"] [old-urls="[http://127.0.0.1:2379]"] [new-urls="[http://127.0.0.1:2379,http://127.0.0.1:2382,http://127.0.0.1:2384]"]
[2023/10/19 12:54:32.009 +08:00] [INFO] [pd_service_discovery.go:632] ["[pd] switch leader"] [new-leader=http://127.0.0.1:2382] [old-leader=]
[2023/10/19 12:54:32.009 +08:00] [INFO] [pd_service_discovery.go:197] ["[pd] init cluster id"] [cluster-id=7291527715429987715]
[2023/10/19 12:54:32.010 +08:00] [INFO] [client.go:600] ["[pd] changing service mode"] [old-mode=UNKNOWN_SVC_MODE] [new-mode=PD_SVC_MODE]
[2023/10/19 12:54:32.010 +08:00] [INFO] [tso_client.go:230] ["[tso] switch dc tso global allocator serving address"] [dc-location=global] [new-address=http://127.0.0.1:2382]
[2023/10/19 12:54:32.011 +08:00] [INFO] [tso_dispatcher.go:318] ["[tso] tso dispatcher created"] [dc-location=global]
[2023/10/19 12:54:32.011 +08:00] [INFO] [client.go:648] ["[pd] service mode changed"] [old-mode=UNKNOWN_SVC_MODE] [new-mode=PD_SVC_MODE]
[2023/10/19 12:54:32.011 +08:00] [INFO] [tikv_mode.go:60] ["switch tikv mode"] [task-id=4] [mode=Import]
[2023/10/19 12:54:32.025 +08:00] [INFO] [tso_dispatcher.go:240] ["exit tso dispatcher loop"]
[2023/10/19 12:54:32.025 +08:00] [INFO] [pd_service_discovery.go:248] ["[pd] exit member loop due to context canceled"]
[2023/10/19 12:54:32.025 +08:00] [INFO] [tso_dispatcher.go:405] ["[tso] stop fetching the pending tso requests due to context canceled"] [dc-location=global]
[2023/10/19 12:54:32.025 +08:00] [INFO] [resource_manager_client.go:314] ["[resource manager] exit resource token dispatcher"]
[2023/10/19 12:54:32.025 +08:00] [INFO] [tso_dispatcher.go:186] ["exit tso requests cancel loop"]
[2023/10/19 12:54:32.025 +08:00] [INFO] [tso_dispatcher.go:339] ["[tso] exit tso dispatcher"] [dc-location=global]
[2023/10/19 12:54:32.025 +08:00] [INFO] [tso_client.go:134] ["closing tso client"]
[2023/10/19 12:54:32.025 +08:00] [INFO] [tso_client.go:139] ["close tso client"]
[2023/10/19 12:54:32.025 +08:00] [INFO] [tso_client.go:150] ["tso client is closed"]
[2023/10/19 12:54:32.025 +08:00] [INFO] [pd_service_discovery.go:294] ["[pd] close pd service discovery client"]
[2023/10/19 12:54:32.031 +08:00] [INFO] [dispatcher.go:96] ["register task to pd or refresh lease success"] [task-id=4]
[2023/10/19 12:54:32.103 +08:00] [INFO] [scheduler.go:149] ["scheduler run a step"] [task-id=4] [step=1] [concurrency=1]
[2023/10/19 12:54:32.105 +08:00] [INFO] [scheduler.go:485] ["create step scheduler"] [type=ImportInto] [task-id=4] [step=import]
[2023/10/19 12:54:32.105 +08:00] [INFO] [scheduler.go:91] ["init subtask env"] [type=ImportInto] [task-id=4] [step=import]
[2023/10/19 12:54:32.110 +08:00] [INFO] [pd_service_discovery.go:606] ["[pd] update member urls"] [old-urls="[http://127.0.0.1:2379]"] [new-urls="[http://127.0.0.1:2379,http://127.0.0.1:2382,http://127.0.0.1:2384]"]
[2023/10/19 12:54:32.110 +08:00] [INFO] [pd_service_discovery.go:632] ["[pd] switch leader"] [new-leader=http://127.0.0.1:2382] [old-leader=]
[2023/10/19 12:54:32.110 +08:00] [INFO] [pd_service_discovery.go:197] ["[pd] init cluster id"] [cluster-id=7291527715429987715]
[2023/10/19 12:54:32.111 +08:00] [INFO] [client.go:600] ["[pd] changing service mode"] [old-mode=UNKNOWN_SVC_MODE] [new-mode=PD_SVC_MODE]
[2023/10/19 12:54:32.111 +08:00] [INFO] [tso_client.go:230] ["[tso] switch dc tso global allocator serving address"] [dc-location=global] [new-address=http://127.0.0.1:2382]
[2023/10/19 12:54:32.112 +08:00] [INFO] [tso_dispatcher.go:318] ["[tso] tso dispatcher created"] [dc-location=global]
[2023/10/19 12:54:32.112 +08:00] [INFO] [client.go:648] ["[pd] service mode changed"] [old-mode=UNKNOWN_SVC_MODE] [new-mode=PD_SVC_MODE]
[2023/10/19 12:54:32.112 +08:00] [INFO] [tso_dispatcher.go:186] ["exit tso requests cancel loop"]
[2023/10/19 12:54:32.112 +08:00] [INFO] [pd_service_discovery.go:248] ["[pd] exit member loop due to context canceled"]
[2023/10/19 12:54:32.112 +08:00] [INFO] [tso_dispatcher.go:240] ["exit tso dispatcher loop"]
[2023/10/19 12:54:32.112 +08:00] [WARN] [resource_manager_client.go:326] ["[resource_manager] get token stream error"] [error="rpc error: code = Canceled desc = context canceled"]
[2023/10/19 12:54:32.112 +08:00] [ERROR] [tso_dispatcher.go:557] ["[tso] update connection contexts failed"] [dc=global] [error="rpc error: code = Canceled desc = context canceled"] [stack="github.com/tikv/pd/client.(*tsoClient).updateTSOConnectionCtxs\n\texternal/com_github_tikv_pd_client/tso_dispatcher.go:557\ngithub.com/tikv/pd/client.(*tsoClient).handleDispatcher\n\texternal/com_github_tikv_pd_client/tso_dispatcher.go:348"]
[2023/10/19 12:54:32.112 +08:00] [INFO] [resource_manager_client.go:314] ["[resource manager] exit resource token dispatcher"]
[2023/10/19 12:54:32.112 +08:00] [INFO] [tso_dispatcher.go:339] ["[tso] exit tso dispatcher"] [dc-location=global]
[2023/10/19 12:54:32.112 +08:00] [INFO] [tso_client.go:134] ["closing tso client"]
[2023/10/19 12:54:32.112 +08:00] [INFO] [tso_client.go:139] ["close tso client"]
[2023/10/19 12:54:32.112 +08:00] [INFO] [tso_client.go:150] ["tso client is closed"]
[2023/10/19 12:54:32.112 +08:00] [INFO] [pd_service_discovery.go:294] ["[pd] close pd service discovery client"]
[2023/10/19 12:54:32.116 +08:00] [INFO] [pd_service_discovery.go:606] ["[pd] update member urls"] [old-urls="[http://127.0.0.1:2379]"] [new-urls="[http://127.0.0.1:2379,http://127.0.0.1:2382,http://127.0.0.1:2384]"]
[2023/10/19 12:54:32.116 +08:00] [INFO] [pd_service_discovery.go:632] ["[pd] switch leader"] [new-leader=http://127.0.0.1:2382] [old-leader=]
[2023/10/19 12:54:32.116 +08:00] [INFO] [pd_service_discovery.go:197] ["[pd] init cluster id"] [cluster-id=7291527715429987715]
[2023/10/19 12:54:32.117 +08:00] [INFO] [client.go:600] ["[pd] changing service mode"] [old-mode=UNKNOWN_SVC_MODE] [new-mode=PD_SVC_MODE]
[2023/10/19 12:54:32.117 +08:00] [INFO] [tso_client.go:230] ["[tso] switch dc tso global allocator serving address"] [dc-location=global] [new-address=http://127.0.0.1:2382]
[2023/10/19 12:54:32.118 +08:00] [INFO] [tso_dispatcher.go:318] ["[tso] tso dispatcher created"] [dc-location=global]
[2023/10/19 12:54:32.118 +08:00] [INFO] [client.go:648] ["[pd] service mode changed"] [old-mode=UNKNOWN_SVC_MODE] [new-mode=PD_SVC_MODE]
[2023/10/19 12:54:32.128 +08:00] [INFO] [local.go:697] ["multi ingest support"]
[2023/10/19 12:54:32.128 +08:00] [INFO] [table_import.go:578] ["use 0.8 of the storage size as default disk quota"] [table=t] [quota=374.2GB]
[2023/10/19 12:54:32.128 +08:00] [INFO] [scheduler.go:110] ["index writer memory size limit"] [type=ImportInto] [task-id=4] [step=import] [limit=256MiB]
[2023/10/19 12:54:32.142 +08:00] [INFO] [scheduler.go:117] ["run subtask start"] [type=ImportInto] [task-id=4] [step=import] [subtask-id=7]
[2023/10/19 12:54:32.146 +08:00] [INFO] [backend.go:245] ["open engine"] [engineTag=`zstd`.`t`:0] [engineUUID=dbc9135c-0d8b-582b-8c22-5316c1b4dadf]
[2023/10/19 12:54:32.150 +08:00] [INFO] [backend.go:245] ["open engine"] [engineTag=`zstd`.`t`:-1] [engineUUID=e9c114a8-45b3-5791-b514-c60a7e19a6dd]
[2023/10/19 12:54:32.150 +08:00] [INFO] [subtask_executor.go:68] ["execute chunk"] [type=ImportInto] [table-id=114]
[2023/10/19 12:54:32.172 +08:00] [INFO] [chunk_process.go:243] ["process chunk start"] [type=ImportInto] [table-id=114] [key=t.01.csv.zst:0]
[2023/10/19 12:54:32.174 +08:00] [INFO] [chunk_process.go:245] ["process chunk completed"] [type=ImportInto] [table-id=114] [key=t.01.csv.zst:0] [readDur=1.095149ms] [encodeDur=229.359µs] [deliverDur=509.892µs] [checksum="{cksum=14262047008891545520,size=66,kvs=2}"] [takeTime=2.237347ms] []
[2023/10/19 12:54:32.175 +08:00] [INFO] [subtask_executor.go:68] ["execute chunk"] [type=ImportInto] [table-id=114]
[2023/10/19 12:54:32.175 +08:00] [INFO] [engine.go:861] ["write data to local DB"] [size=66] [kvs=2] [files=1] [sstFileSize=976] [file=/tmp/tidb/import-4000/4/dbc9135c-0d8b-582b-8c22-5316c1b4dadf.sst/1184b4c4-146f-4ec2-b1ce-ab27e31a1910.sst] [firstKey=7480000000000000725F728000000000000001] [lastKey=7480000000000000725F728000000000000002]
[2023/10/19 12:54:32.364 +08:00] [INFO] [chunk_process.go:243] ["process chunk start"] [type=ImportInto] [table-id=114] [key=t.02.csv.zstd:0]
[2023/10/19 12:54:32.365 +08:00] [INFO] [chunk_process.go:245] ["process chunk completed"] [type=ImportInto] [table-id=114] [key=t.02.csv.zstd:0] [readDur=1.01294ms] [encodeDur=231.767µs] [deliverDur=13.853µs] [checksum="{cksum=6510788178300023669,size=66,kvs=2}"] [takeTime=1.62375ms] []
[2023/10/19 12:54:32.366 +08:00] [INFO] [scheduler.go:119] ["run subtask completed"] [type=ImportInto] [task-id=4] [step=import] [subtask-id=7] [takeTime=224.389109ms] []
[2023/10/19 12:54:32.366 +08:00] [INFO] [engine.go:861] ["write data to local DB"] [size=66] [kvs=2] [files=1] [sstFileSize=976] [file=/tmp/tidb/import-4000/4/dbc9135c-0d8b-582b-8c22-5316c1b4dadf.sst/e840a5ff-5a63-4950-b157-85416639b1c3.sst] [firstKey=7480000000000000725F728000000000000003] [lastKey=7480000000000000725F728000000000000004]
[2023/10/19 12:54:32.367 +08:00] [INFO] [scheduler.go:189] ["on subtask finished"] [type=ImportInto] [task-id=4] [step=import] [engine-id=0]
[2023/10/19 12:54:32.367 +08:00] [INFO] [scheduler.go:203] ["import data engine"] [type=ImportInto] [task-id=4] [step=import] [engine-id=0]
[2023/10/19 12:54:32.367 +08:00] [INFO] [backend.go:322] ["engine close start"] [engineTag=`zstd`.`t`:0] [engineUUID=dbc9135c-0d8b-582b-8c22-5316c1b4dadf]
[2023/10/19 12:54:32.370 +08:00] [INFO] [backend.go:324] ["engine close completed"] [engineTag=`zstd`.`t`:0] [engineUUID=dbc9135c-0d8b-582b-8c22-5316c1b4dadf] [takeTime=3.017975ms] []
[2023/10/19 12:54:32.370 +08:00] [INFO] [backend.go:364] ["import start"] [engineTag=`zstd`.`t`:0] [engineUUID=dbc9135c-0d8b-582b-8c22-5316c1b4dadf] [retryCnt=0]
[2023/10/19 12:54:32.376 +08:00] [INFO] [local.go:1511] ["pause pd scheduler of table scope"]
[2023/10/19 12:54:32.377 +08:00] [INFO] [local.go:1549] ["start import engine"] [uuid=dbc9135c-0d8b-582b-8c22-5316c1b4dadf] ["region ranges"=1] [count=4] [size=132]
[2023/10/19 12:54:32.378 +08:00] [INFO] [local.go:1117] ["import engine ranges"] [count=1]
[2023/10/19 12:54:32.378 +08:00] [INFO] [local.go:1130] ["split and scatter ranges start"] [uuid=dbc9135c-0d8b-582b-8c22-5316c1b4dadf]
[2023/10/19 12:54:32.378 +08:00] [INFO] [localhelper.go:159] ["split and scatter region"] [minKey=7480000000000000FF725F728000000000FF0000010000000000FA] [maxKey=7480000000000000FF725F728000000000FF0000050000000000FA] [retry=0]
[2023/10/19 12:54:32.379 +08:00] [INFO] [localhelper.go:178] ["paginate scan regions"] [count=1] [start=7480000000000000FF725F728000000000FF0000010000000000FA] [end=7480000000000000FF725F728000000000FF0000050000000000FA]
[2023/10/19 12:54:32.379 +08:00] [INFO] [localhelper.go:186] ["paginate scan region finished"] [minKey=7480000000000000FF725F728000000000FF0000010000000000FA] [maxKey=7480000000000000FF725F728000000000FF0000050000000000FA] [regions=1]
[2023/10/19 12:54:32.379 +08:00] [INFO] [localhelper.go:359] ["waiting for scattering regions done"] [regions=1] [take=484.277µs]
[2023/10/19 12:54:32.379 +08:00] [INFO] [local.go:1144] ["split and scatter ranges completed"] [uuid=dbc9135c-0d8b-582b-8c22-5316c1b4dadf] [takeTime=1.543964ms] []
[2023/10/19 12:54:32.395 +08:00] [WARN] [region_job.go:483] ["meet error and handle the job later"] ["job stage"=regionScanned] [error="[Lightning:KV:EpochNotMatch]EpochNotMatch current epoch of region 14 is conf_ver: 5 version: 13, but you sent conf_ver: 5 version: 11"] [region="{ID=56,startKey=7480000000000000FF725F728000000000FF0000010000000000FA,endKey=7480000000000000FF725F728000000000FF0000050000000000FA,epoch=\"conf_ver:5 version:13 \",peers=\"id:57 store_id:3 ,id:58 store_id:1 ,id:59 store_id:2 \"}"] [start=7480000000000000725F728000000000000001] [end=7480000000000000725F728000000000000005]
[2023/10/19 12:54:32.395 +08:00] [INFO] [local.go:1652] ["put job back to jobCh to retry later"] [startKey=7480000000000000725F728000000000000001] [endKey=7480000000000000725F728000000000000005] [stage=regionScanned] [retryCount=1] [waitUntil=2023/10/19 12:54:34.395 +08:00]
[2023/10/19 12:54:32.423 +08:00] [INFO] [region_request.go:1532] ["send request meet region error without retry"] [req-ts=445039580916482050] [req-type=Cop] [region="{ region id: 14, ver: 11, confVer: 5 }"] [replica-read-type=leader] [stale-read=false] [request-sender="{rpcError:<nil>,replicaSelector: replicaSelector{selectorStateStr: accessKnownLeader, cacheRegionIsValid: false, replicaStatus: [peer: 15, store: 3, isEpochStale: false, attempts: 1, replica-epoch: 0, store-epoch: 0, store-state: resolved, store-liveness-state: reachable peer: 18, store: 1, isEpochStale: false, attempts: 0, replica-epoch: 0, store-epoch: 0, store-state: resolved, store-liveness-state: reachable peer: 25, store: 2, isEpochStale: false, attempts: 0, replica-epoch: 0, store-epoch: 0, store-state: resolved, store-liveness-state: reachable]}}"] [retry-times=0] [total-backoff-ms=0] [total-backoff-times=0] [max-exec-timeout-ms=60000] [total-region-errors=15-epoch_not_match:1]
[2023/10/19 12:54:32.423 +08:00] [INFO] [region_request.go:1532] ["send request meet region error without retry"] [req-ts=445039580916482050] [req-type=Cop] [region="{ region id: 14, ver: 11, confVer: 5 }"] [replica-read-type=leader] [stale-read=false] [request-sender="{rpcError:<nil>,replicaSelector: replicaSelector{selectorStateStr: accessKnownLeader, cacheRegionIsValid: false, replicaStatus: [peer: 15, store: 3, isEpochStale: false, attempts: 1, replica-epoch: 0, store-epoch: 0, store-state: resolved, store-liveness-state: reachable peer: 18, store: 1, isEpochStale: false, attempts: 0, replica-epoch: 0, store-epoch: 0, store-state: resolved, store-liveness-state: reachable peer: 25, store: 2, isEpochStale: false, attempts: 0, replica-epoch: 0, store-epoch: 0, store-state: resolved, store-liveness-state: reachable]}}"] [retry-times=0] [total-backoff-ms=0] [total-backoff-times=0] [max-exec-timeout-ms=60000] [total-region-errors=15-epoch_not_match:1]
[2023/10/19 12:54:32.423 +08:00] [INFO] [region_request.go:1532] ["send request meet region error without retry"] [req-ts=445039580916482052] [req-type=Cop] [region="{ region id: 14, ver: 11, confVer: 5 }"] [replica-read-type=leader] [stale-read=false] [request-sender="{rpcError:<nil>,replicaSelector: replicaSelector{selectorStateStr: accessKnownLeader, cacheRegionIsValid: false, replicaStatus: [peer: 15, store: 3, isEpochStale: false, attempts: 1, replica-epoch: 0, store-epoch: 0, store-state: resolved, store-liveness-state: reachable peer: 18, store: 1, isEpochStale: false, attempts: 0, replica-epoch: 0, store-epoch: 0, store-state: resolved, store-liveness-state: reachable peer: 25, store: 2, isEpochStale: false, attempts: 0, replica-epoch: 0, store-epoch: 0, store-state: resolved, store-liveness-state: reachable]}}"] [retry-times=0] [total-backoff-ms=0] [total-backoff-times=0] [max-exec-timeout-ms=60000] [total-region-errors=15-epoch_not_match:1]
[2023/10/19 12:54:34.410 +08:00] [INFO] [local.go:1560] ["import engine success"] [uuid=dbc9135c-0d8b-582b-8c22-5316c1b4dadf] [size=132] [kvs=4] [importedSize=132] [importedCount=4]
[2023/10/19 12:54:34.411 +08:00] [INFO] [backend.go:370] ["import completed"] [engineTag=`zstd`.`t`:0] [engineUUID=dbc9135c-0d8b-582b-8c22-5316c1b4dadf] [retryCnt=0] [takeTime=2.041076107s] []
[2023/10/19 12:54:34.411 +08:00] [INFO] [backend.go:383] ["cleanup start"] [engineTag=`zstd`.`t`:0] [engineUUID=dbc9135c-0d8b-582b-8c22-5316c1b4dadf]
[2023/10/19 12:54:34.412 +08:00] [INFO] [backend.go:385] ["cleanup completed"] [engineTag=`zstd`.`t`:0] [engineUUID=dbc9135c-0d8b-582b-8c22-5316c1b4dadf] [takeTime=1.05901ms] []
[2023/10/19 12:54:34.412 +08:00] [INFO] [scheduler.go:213] ["import index engine"] [type=ImportInto] [task-id=4] [step=import] [engine-id=0]
[2023/10/19 12:54:34.412 +08:00] [INFO] [backend.go:322] ["engine close start"] [engineTag=`zstd`.`t`:-1] [engineUUID=e9c114a8-45b3-5791-b514-c60a7e19a6dd]
[2023/10/19 12:54:34.414 +08:00] [INFO] [backend.go:324] ["engine close completed"] [engineTag=`zstd`.`t`:-1] [engineUUID=e9c114a8-45b3-5791-b514-c60a7e19a6dd] [takeTime=1.450991ms] []
[2023/10/19 12:54:34.414 +08:00] [INFO] [backend.go:364] ["import start"] [engineTag=`zstd`.`t`:-1] [engineUUID=e9c114a8-45b3-5791-b514-c60a7e19a6dd] [retryCnt=0]
[2023/10/19 12:54:34.414 +08:00] [INFO] [local.go:1489] ["engine contains no kv, skip import"] [engine=e9c114a8-45b3-5791-b514-c60a7e19a6dd]
[2023/10/19 12:54:34.414 +08:00] [INFO] [backend.go:370] ["import completed"] [engineTag=`zstd`.`t`:-1] [engineUUID=e9c114a8-45b3-5791-b514-c60a7e19a6dd] [retryCnt=0] [takeTime=45.979µs] []
[2023/10/19 12:54:34.414 +08:00] [INFO] [backend.go:383] ["cleanup start"] [engineTag=`zstd`.`t`:-1] [engineUUID=e9c114a8-45b3-5791-b514-c60a7e19a6dd]
[2023/10/19 12:54:34.415 +08:00] [INFO] [backend.go:385] ["cleanup completed"] [engineTag=`zstd`.`t`:-1] [engineUUID=e9c114a8-45b3-5791-b514-c60a7e19a6dd] [takeTime=734.741µs] []
[2023/10/19 12:54:34.504 +08:00] [INFO] [dispatcher.go:503] [onNextStage] [task-id=4] [task-type=ImportInto] [current-step=1] [next-step=2]
[2023/10/19 12:54:34.505 +08:00] [INFO] [dispatcher.go:218] ["on next subtasks batch"] [type=ImportInto] [task-id=4] [curr-step=import] [next-step=post-process]
[2023/10/19 12:54:34.508 +08:00] [INFO] [pd_service_discovery.go:606] ["[pd] update member urls"] [old-urls="[http://127.0.0.1:2379]"] [new-urls="[http://127.0.0.1:2379,http://127.0.0.1:2382,http://127.0.0.1:2384]"]
[2023/10/19 12:54:34.509 +08:00] [INFO] [pd_service_discovery.go:632] ["[pd] switch leader"] [new-leader=http://127.0.0.1:2382] [old-leader=]
[2023/10/19 12:54:34.509 +08:00] [INFO] [pd_service_discovery.go:197] ["[pd] init cluster id"] [cluster-id=7291527715429987715]
[2023/10/19 12:54:34.510 +08:00] [INFO] [client.go:600] ["[pd] changing service mode"] [old-mode=UNKNOWN_SVC_MODE] [new-mode=PD_SVC_MODE]
[2023/10/19 12:54:34.510 +08:00] [INFO] [tso_client.go:230] ["[tso] switch dc tso global allocator serving address"] [dc-location=global] [new-address=http://127.0.0.1:2382]
[2023/10/19 12:54:34.511 +08:00] [INFO] [tso_dispatcher.go:318] ["[tso] tso dispatcher created"] [dc-location=global]
[2023/10/19 12:54:34.511 +08:00] [INFO] [client.go:648] ["[pd] service mode changed"] [old-mode=UNKNOWN_SVC_MODE] [new-mode=PD_SVC_MODE]
[2023/10/19 12:54:34.511 +08:00] [INFO] [tikv_mode.go:60] ["switch tikv mode"] [type=ImportInto] [task-id=4] [curr-step=import] [next-step=post-process] [mode=Normal]
[2023/10/19 12:54:34.527 +08:00] [INFO] [pd_service_discovery.go:248] ["[pd] exit member loop due to context canceled"]
[2023/10/19 12:54:34.527 +08:00] [INFO] [tso_dispatcher.go:186] ["exit tso requests cancel loop"]
[2023/10/19 12:54:34.527 +08:00] [INFO] [resource_manager_client.go:314] ["[resource manager] exit resource token dispatcher"]
[2023/10/19 12:54:34.527 +08:00] [INFO] [tso_dispatcher.go:405] ["[tso] stop fetching the pending tso requests due to context canceled"] [dc-location=global]
[2023/10/19 12:54:34.527 +08:00] [INFO] [tso_client.go:134] ["closing tso client"]
[2023/10/19 12:54:34.527 +08:00] [INFO] [tso_dispatcher.go:339] ["[tso] exit tso dispatcher"] [dc-location=global]
[2023/10/19 12:54:34.527 +08:00] [INFO] [tso_dispatcher.go:240] ["exit tso dispatcher loop"]
[2023/10/19 12:54:34.527 +08:00] [INFO] [tso_client.go:139] ["close tso client"]
[2023/10/19 12:54:34.527 +08:00] [INFO] [tso_client.go:150] ["tso client is closed"]
[2023/10/19 12:54:34.527 +08:00] [INFO] [pd_service_discovery.go:294] ["[pd] close pd service discovery client"]
[2023/10/19 12:54:34.543 +08:00] [INFO] [dispatcher.go:295] ["move to post-process step "] [type=ImportInto] [task-id=4] [curr-step=import] [next-step=post-process] [result="{\"LoadedRowCnt\":4,\"ColSizeMap\":{\"1\":4,\"2\":24}}"]
[2023/10/19 12:54:34.544 +08:00] [INFO] [dispatcher.go:321] ["generate subtasks"] [type=ImportInto] [task-id=4] [curr-step=import] [next-step=post-process] [subtask-count=1]
[2023/10/19 12:54:34.544 +08:00] [INFO] [dispatcher.go:576] ["dispatch subtasks"] [task-id=4] [task-type=ImportInto] [state=running] [step=1] [concurrency=1] [subtasks=1]
[2023/10/19 12:54:34.550 +08:00] [INFO] [dispatcher.go:591] ["eligible instances"] [task-id=4] [task-type=ImportInto] [num=1]
[2023/10/19 12:54:34.550 +08:00] [INFO] [dispatcher.go:431] ["task state transform"] [from=running] [to=running]
[2023/10/19 12:54:34.563 +08:00] [INFO] [dispatcher.go:538] ["move to next stage"] [task-id=4] [task-type=ImportInto] [from=1] [to=2]
[2023/10/19 12:54:34.563 +08:00] [INFO] [dispatcher.go:431] ["task state transform"] [from=running] [to=running]
[2023/10/19 12:54:34.733 +08:00] [INFO] [scheduler.go:249] ["cleanup subtask env"] [type=ImportInto] [task-id=4] [step=import]
[2023/10/19 12:54:34.734 +08:00] [INFO] [resource_manager_client.go:314] ["[resource manager] exit resource token dispatcher"]
[2023/10/19 12:54:34.734 +08:00] [INFO] [tso_dispatcher.go:405] ["[tso] stop fetching the pending tso requests due to context canceled"] [dc-location=global]
[2023/10/19 12:54:34.734 +08:00] [INFO] [pd_service_discovery.go:248] ["[pd] exit member loop due to context canceled"]
[2023/10/19 12:54:34.734 +08:00] [INFO] [tso_dispatcher.go:186] ["exit tso requests cancel loop"]
[2023/10/19 12:54:34.734 +08:00] [INFO] [tso_dispatcher.go:339] ["[tso] exit tso dispatcher"] [dc-location=global]
[2023/10/19 12:54:34.734 +08:00] [INFO] [tso_client.go:134] ["closing tso client"]
[2023/10/19 12:54:34.734 +08:00] [INFO] [tso_dispatcher.go:240] ["exit tso dispatcher loop"]
[2023/10/19 12:54:34.734 +08:00] [INFO] [tso_client.go:139] ["close tso client"]
[2023/10/19 12:54:34.734 +08:00] [INFO] [tso_client.go:150] ["tso client is closed"]
[2023/10/19 12:54:34.734 +08:00] [INFO] [pd_service_discovery.go:294] ["[pd] close pd service discovery client"]
[2023/10/19 12:54:34.735 +08:00] [INFO] [tso_client.go:134] ["closing tso client"]
[2023/10/19 12:54:34.735 +08:00] [INFO] [tso_client.go:139] ["close tso client"]
[2023/10/19 12:54:34.735 +08:00] [INFO] [tso_client.go:150] ["tso client is closed"]
[2023/10/19 12:54:34.735 +08:00] [INFO] [scheduler.go:93] ["scheduler exits"] [task-id=4] [error="context canceled"]
[2023/10/19 12:54:35.041 +08:00] [INFO] [scheduler.go:149] ["scheduler run a step"] [task-id=4] [step=2] [concurrency=1]
[2023/10/19 12:54:35.042 +08:00] [INFO] [scheduler.go:485] ["create step scheduler"] [type=ImportInto] [task-id=4] [step=post-process]
[2023/10/19 12:54:35.055 +08:00] [INFO] [scheduler.go:436] ["run subtask start"] [type=ImportInto] [task-id=4] [step=post-process] [subtask-id=8]
[2023/10/19 12:54:35.055 +08:00] [INFO] [subtask_executor.go:104] ["post process start"] [type=ImportInto] [task-id=4] [step=post-process] [subtask-id=8]
[2023/10/19 12:54:35.055 +08:00] [INFO] [subtask_executor.go:245] ["rebase allocators start"] [type=ImportInto] [task-id=4] [step=post-process] [subtask-id=8]
[2023/10/19 12:54:35.055 +08:00] [INFO] [subtask_executor.go:247] ["rebase allocators completed"] [type=ImportInto] [task-id=4] [step=post-process] [subtask-id=8] [takeTime=1.82µs] []
[2023/10/19 12:54:35.055 +08:00] [INFO] [subtask_executor.go:128] ["local checksum"] [type=ImportInto] [task-id=4] [step=post-process] [subtask-id=8] [checksum="{cksum=11508402849382241477,size=132,kvs=4}"]
[2023/10/19 12:54:35.056 +08:00] [INFO] [subtask_executor.go:240] ["set backoff weight"] [type=ImportInto] [task-id=4] [step=post-process] [subtask-id=8] [weight=30]
[2023/10/19 12:54:35.058 +08:00] [INFO] [subtask_executor.go:158] ["checksum pass"] [type=ImportInto] [task-id=4] [step=post-process] [subtask-id=8] [local="{cksum=11508402849382241477,size=132,kvs=4}"]
[2023/10/19 12:54:35.058 +08:00] [INFO] [subtask_executor.go:106] ["post process completed"] [type=ImportInto] [task-id=4] [step=post-process] [subtask-id=8] [takeTime=3.084463ms] []
[2023/10/19 12:54:35.058 +08:00] [INFO] [scheduler.go:438] ["run subtask completed"] [type=ImportInto] [task-id=4] [step=post-process] [subtask-id=8] [takeTime=3.204287ms] []
[2023/10/19 12:54:35.505 +08:00] [INFO] [dispatcher.go:503] [onNextStage] [task-id=4] [task-type=ImportInto] [current-step=2] [next-step=-2]
[2023/10/19 12:54:35.506 +08:00] [INFO] [dispatcher.go:218] ["on next subtasks batch"] [type=ImportInto] [task-id=4] [curr-step=post-process] [next-step=done]
[2023/10/19 12:54:35.507 +08:00] [INFO] [dispatcher.go:111] ["unregister task success"] [task-id=4]
[2023/10/19 12:54:35.514 +08:00] [INFO] [dispatcher.go:576] ["dispatch subtasks"] [task-id=4] [task-type=ImportInto] [state=running] [step=2] [concurrency=1] [subtasks=0]
[2023/10/19 12:54:35.520 +08:00] [INFO] [dispatcher.go:591] ["eligible instances"] [task-id=4] [task-type=ImportInto] [num=1]
[2023/10/19 12:54:35.520 +08:00] [INFO] [dispatcher.go:431] ["task state transform"] [from=running] [to=running]
[2023/10/19 12:54:35.532 +08:00] [INFO] [dispatcher.go:536] ["all subtasks dispatched and processed, finish the task"] [task-id=4] [task-type=ImportInto]
[2023/10/19 12:54:35.532 +08:00] [INFO] [dispatcher.go:431] ["task state transform"] [from=running] [to=succeed]
[2023/10/19 12:54:35.683 +08:00] [INFO] [scheduler.go:93] ["scheduler exits"] [task-id=4] [error="context canceled"]
[2023/10/19 12:54:35.738 +08:00] [WARN] [adapter.go:1620] ["# Txn_start_ts: 0\n# Conn_ID: 2\n# Query_time: 5.783005952\n# Parse_time: 0.000091136\n# Compile_time: 0.00038095\n# Rewrite_time: 0.000093219\n# Optimize_time: 0.000153635\n# Wait_TS: 0.00029668\n# DB: zstd\n# Is_internal: false\n# Digest: 224cbd7bc4c5e4c15b75463317df9f8aff0269f709c2192f128e50cf21d1a758\n# Num_cop_tasks: 0\n# Prepared: false\n# Plan_from_cache: false\n# Plan_from_binding: false\n# Has_more_results: false\n# KV_total: 0\n# PD_total: 0\n# Backoff_total: 0\n# Write_sql_response_total: 0\n# Result_rows: 1\n# Succ: true\n# IsExplicitTxn: false\n# IsSyncStatsFailed: false\n# Plan: tidb_decode_plan('LbAwCTU5XzIJMAkwCU4vQQkxCXRpbWU6NS43OHMsIGxvb3BzOjIJTi9BCU4vQQo=')\n# Binary_plan: tidb_decode_binary_plan('SMgKRAoMSW1wb3J0SW50b18yMAE4AUABUgNOL0FaE3RpbWU6NS43OHMsIGxvb3BzOjJw//8NAjQBeP///////////wEYAQ==')\nuse zstd;\nIMPORT INTO `zstd`.`t` FROM 'gs://zstd/t.*?endpoint=http://127.0.0.1:4443/storage/v1/' WITH thread=1;"]
    testing.go:1465: race detected during execution of test
[2023/10/19 12:54:35.742 +08:00] [WARN] [manager.go:300] ["is not the owner"] ["owner info"="[ddl] /tidb/ddl/fg/owner ownerManager 9631740f-ca41-4513-b7c9-772f4633cc1e"]
[2023/10/19 12:54:35.742 +08:00] [INFO] [manager.go:267] ["break campaign loop, context is done"] ["owner info"="[ddl] /tidb/ddl/fg/owner ownerManager 9631740f-ca41-4513-b7c9-772f4633cc1e"]
[2023/10/19 12:54:35.744 +08:00] [INFO] [manager.go:311] ["revoke session"] ["owner info"="[ddl] /tidb/ddl/fg/owner ownerManager 9631740f-ca41-4513-b7c9-772f4633cc1e"] []
[2023/10/19 12:54:35.745 +08:00] [INFO] [ddl_workerpool.go:83] ["closing workerPool"] [category=ddl]
[2023/10/19 12:54:35.745 +08:00] [INFO] [ddl_worker.go:183] ["DDL worker closed"] [worker="worker 20, tp add index"] [category=ddl] ["take time"=6.062µs]
[2023/10/19 12:54:35.745 +08:00] [INFO] [ddl_worker.go:183] ["DDL worker closed"] [worker="worker 21, tp add index"] [category=ddl] ["take time"=5.743µs]
[2023/10/19 12:54:35.745 +08:00] [INFO] [ddl_worker.go:183] ["DDL worker closed"] [worker="worker 22, tp add index"] [category=ddl] ["take time"=4.661µs]
[2023/10/19 12:54:35.745 +08:00] [INFO] [ddl_worker.go:183] ["DDL worker closed"] [worker="worker 13, tp add index"] [category=ddl] ["take time"=3.031µs]
[2023/10/19 12:54:35.745 +08:00] [INFO] [ddl_worker.go:183] ["DDL worker closed"] [worker="worker 14, tp add index"] [category=ddl] ["take time"=3.222µs]
[2023/10/19 12:54:35.745 +08:00] [INFO] [ddl_worker.go:183] ["DDL worker closed"] [worker="worker 15, tp add index"] [category=ddl] ["take time"=3.079µs]
[2023/10/19 12:54:35.745 +08:00] [INFO] [ddl_worker.go:183] ["DDL worker closed"] [worker="worker 16, tp add index"] [category=ddl] ["take time"=5.248µs]
[2023/10/19 12:54:35.745 +08:00] [INFO] [ddl_worker.go:183] ["DDL worker closed"] [worker="worker 17, tp add index"] [category=ddl] ["take time"=4.075µs]
[2023/10/19 12:54:35.745 +08:00] [INFO] [ddl_worker.go:183] ["DDL worker closed"] [worker="worker 18, tp add index"] [category=ddl] ["take time"=3.593µs]
[2023/10/19 12:54:35.745 +08:00] [INFO] [ddl_worker.go:183] ["DDL worker closed"] [worker="worker 19, tp add index"] [category=ddl] ["take time"=3.168µs]
[2023/10/19 12:54:35.745 +08:00] [INFO] [ddl_workerpool.go:83] ["closing workerPool"] [category=ddl]
[2023/10/19 12:54:35.745 +08:00] [INFO] [ddl_worker.go:183] ["DDL worker closed"] [worker="worker 12, tp general"] [category=ddl] ["take time"=3.435µs]
[2023/10/19 12:54:35.745 +08:00] [INFO] [delete_range.go:150] ["closing delRange"] [category=ddl]
[2023/10/19 12:54:35.745 +08:00] [INFO] [session_pool.go:99] ["closing session pool"] [category=ddl]
[2023/10/19 12:54:35.749 +08:00] [INFO] [ddl.go:893] ["DDL closed"] [category=ddl] [ID=9631740f-ca41-4513-b7c9-772f4633cc1e] ["take time"=7.212348ms]
[2023/10/19 12:54:35.749 +08:00] [INFO] [ddl.go:725] ["stop DDL"] [category=ddl] [ID=9631740f-ca41-4513-b7c9-772f4633cc1e]
[2023/10/19 12:54:35.751 +08:00] [INFO] [domain.go:998] ["stopping ttlJobManager"]
[2023/10/19 12:54:35.751 +08:00] [INFO] [runtime.go:190] ["TimerGroupRuntime loop exit"] [groupID=ttl]
[2023/10/19 12:54:35.751 +08:00] [INFO] [notifier.go:142] ["etcd watcher exited to watch timer events"] [EtcdKey=/tidb/timer/cluster/1/notify/73ce5cc5-72f5-4524-9f33-1915b2d20ed1] [watcherID=eb015f30-06a6-4c2c-b5da-5bb97f476296]
[2023/10/19 12:54:35.751 +08:00] [INFO] [notifier.go:227] ["etcd notify loop to watch timer events stopped"] [EtcdKey=/tidb/timer/cluster/1/notify/73ce5cc5-72f5-4524-9f33-1915b2d20ed1]
[2023/10/19 12:54:35.751 +08:00] [INFO] [task_manager.go:193] ["shrink ttl worker"] [ttl-worker=job-manager] [ttl-worker=task-manager] [originalCount=4] [newCount=0]
[2023/10/19 12:54:35.751 +08:00] [INFO] [scan.go:309] ["ttlScanWorker loop exited."]
[2023/10/19 12:54:35.751 +08:00] [INFO] [scan.go:309] ["ttlScanWorker loop exited."]
[2023/10/19 12:54:35.751 +08:00] [INFO] [scan.go:309] ["ttlScanWorker loop exited."]
[2023/10/19 12:54:35.751 +08:00] [INFO] [scan.go:309] ["ttlScanWorker loop exited."]
[2023/10/19 12:54:35.751 +08:00] [INFO] [task_manager.go:193] ["shrink ttl worker"] [ttl-worker=job-manager] [ttl-worker=task-manager] [originalCount=4] [newCount=0]
[2023/10/19 12:54:35.752 +08:00] [INFO] [del.go:261] ["ttlDeleteWorker loop exited."]
[2023/10/19 12:54:35.752 +08:00] [INFO] [del.go:261] ["ttlDeleteWorker loop exited."]
[2023/10/19 12:54:35.752 +08:00] [INFO] [del.go:261] ["ttlDeleteWorker loop exited."]
[2023/10/19 12:54:35.752 +08:00] [INFO] [del.go:261] ["ttlDeleteWorker loop exited."]
[2023/10/19 12:54:35.753 +08:00] [INFO] [job_manager.go:160] ["ttlJobManager loop exited."] [ttl-worker=job-manager]
[2023/10/19 12:54:35.753 +08:00] [INFO] [domain.go:1009] ["ttlJobManager exited."]
[2023/10/19 12:54:35.754 +08:00] [INFO] [domain.go:2775] ["releaseServerID succeed"] [serverID=115]
[2023/10/19 12:54:35.754 +08:00] [INFO] [domain.go:2324] ["loadStatsWorker exited."]
[2023/10/19 12:54:35.754 +08:00] [INFO] [domain.go:1698] ["LoadSysVarCacheLoop exited."]
[2023/10/19 12:54:35.754 +08:00] [INFO] [domain.go:2044] ["PlanReplayerTaskCollectHandle exited."]
[2023/10/19 12:54:35.754 +08:00] [INFO] [wait_group_wrapper.go:137] ["background process exited"] [source=domain] [process=mdlCheckLoop]
[2023/10/19 12:54:35.754 +08:00] [INFO] [wait_group_wrapper.go:137] ["background process exited"] [source=domain] [process=runawayRecordFlushLoop]
[2023/10/19 12:54:35.754 +08:00] [INFO] [wait_group_wrapper.go:137] ["background process exited"] [source=domain] [process=PlanReplayerTaskCollectHandle]
[2023/10/19 12:54:35.754 +08:00] [INFO] [wait_group_wrapper.go:137] ["background process exited"] [source=domain] [process=LoadSysVarCacheLoop]
[2023/10/19 12:54:35.754 +08:00] [INFO] [handle_hist.go:181] ["SubLoadWorker exited."]
[2023/10/19 12:54:35.754 +08:00] [INFO] [wait_group_wrapper.go:137] ["background process exited"] [source=domain] [process=loadStatsWorker]
[2023/10/19 12:54:35.754 +08:00] [INFO] [domain.go:1508] ["stopping dist task dispatcher manager because the current node is not DDL owner anymore"] [id=9631740f-ca41-4513-b7c9-772f4633cc1e]
[2023/10/19 12:54:35.754 +08:00] [INFO] [domain.go:879] ["loadSchemaInLoop exited."]
[2023/10/19 12:54:35.754 +08:00] [INFO] [wait_group_wrapper.go:137] ["background process exited"] [source=domain] [process=runawayWatchSyncLoop]
[2023/10/19 12:54:35.754 +08:00] [INFO] [domain.go:1834] ["globalBindHandleWorkerLoop exited."]
[2023/10/19 12:54:35.754 +08:00] [INFO] [handle_hist.go:181] ["SubLoadWorker exited."]
[2023/10/19 12:54:35.754 +08:00] [INFO] [handle_hist.go:181] ["SubLoadWorker exited."]
[2023/10/19 12:54:35.754 +08:00] [INFO] [domain.go:712] ["globalConfigSyncerKeeper exited."]
[2023/10/19 12:54:35.754 +08:00] [INFO] [domain.go:686] ["infoSyncerKeeper exited."]
[2023/10/19 12:54:35.754 +08:00] [INFO] [dispatcher_manager.go:159] ["dispatch task loop exits"] [error="context canceled"] [interval=3000]
[2023/10/19 12:54:35.754 +08:00] [INFO] [handle_hist.go:181] ["SubLoadWorker exited."]
[2023/10/19 12:54:35.754 +08:00] [INFO] [wait_group_wrapper.go:137] ["background process exited"] [source=domain] [process=globalConfigSyncerKeeper]
[2023/10/19 12:54:35.754 +08:00] [INFO] [domain.go:2480] ["gcAnalyzeHistory exited."]
[2023/10/19 12:54:35.754 +08:00] [INFO] [wait_group_wrapper.go:137] ["background process exited"] [source=domain] [process=loadSchemaInLoop]
[2023/10/19 12:54:35.754 +08:00] [INFO] [domain.go:2459] ["autoAnalyzeWorker exited."]
[2023/10/19 12:54:35.754 +08:00] [INFO] [dispatcher.go:160] ["schedule task exits"] [task-id=4] [task-type=ImportInto] [error="context canceled"]
[2023/10/19 12:54:35.754 +08:00] [INFO] [domain.go:2129] ["HistoricalStatsWorker exited."]
[2023/10/19 12:54:35.754 +08:00] [INFO] [handle_hist.go:181] ["SubLoadWorker exited."]
[2023/10/19 12:54:35.754 +08:00] [INFO] [dispatcher_manager.go:283] ["task finished"] [task-id=4]
[2023/10/19 12:54:35.754 +08:00] [INFO] [wait_group_wrapper.go:137] ["background process exited"] [source=domain] [process=infoSyncerKeeper]
[2023/10/19 12:54:35.754 +08:00] [INFO] [wait_group_wrapper.go:137] ["background process exited"] [source=domain] [process=gcAnalyzeHistory]
[2023/10/19 12:54:35.755 +08:00] [INFO] [plan_replayer.go:396] ["planReplayerTaskDumpWorker exited."]
[2023/10/19 12:54:35.755 +08:00] [INFO] [wait_group_wrapper.go:137] ["background process exited"] [source=domain] [process=HistoricalStatsWorker]
[2023/10/19 12:54:35.754 +08:00] [INFO] [domain.go:1648] ["loadPrivilegeInLoop exited."]
[2023/10/19 12:54:35.754 +08:00] [INFO] [dispatcher_manager.go:295] ["cleanUp loop exits"] [error="context canceled"]
[2023/10/19 12:54:35.754 +08:00] [INFO] [domain.go:2839] ["serverIDKeeper exited."]
[2023/10/19 12:54:35.755 +08:00] [INFO] [manager.go:440] ["watcher is closed, no owner"] ["owner info"="[stats] ownerManager 9631740f-ca41-4513-b7c9-772f4633cc1e watch owner key /tidb/stats/owner/6f188b46463bbff8"]
[2023/10/19 12:54:35.755 +08:00] [INFO] [wait_group_wrapper.go:137] ["background process exited"] [source=domain] [process=loadPrivilegeInLoop]
[2023/10/19 12:54:35.755 +08:00] [INFO] [advancer.go:349] ["Meet task event"] [category="log backup advancer"] [event="Err(, err = EOF)"]
[2023/10/19 12:54:35.754 +08:00] [WARN] [manager.go:300] ["is not the owner"] ["owner info"="[bindinfo] /tidb/bindinfo/owner ownerManager 9631740f-ca41-4513-b7c9-772f4633cc1e"]
[2023/10/19 12:54:35.755 +08:00] [WARN] [manager.go:300] ["is not the owner"] ["owner info"="[stats] /tidb/stats/owner ownerManager 9631740f-ca41-4513-b7c9-772f4633cc1e"]
[2023/10/19 12:54:35.755 +08:00] [ERROR] [advancer.go:352] ["listen task meet error, would reopen."] [error=EOF] [stack="github.com/pingcap/tidb/br/pkg/streamhelper.(*CheckpointAdvancer).StartTaskListener.func1\n\tbr/pkg/streamhelper/advancer.go:352"]
[2023/10/19 12:54:35.755 +08:00] [INFO] [manager.go:251] ["etcd session is done, creates a new one"] ["owner info"="[bindinfo] /tidb/bindinfo/owner ownerManager 9631740f-ca41-4513-b7c9-772f4633cc1e"]
[2023/10/19 12:54:35.754 +08:00] [INFO] [wait_group_wrapper.go:137] ["background process exited"] [source=domain] [process=globalBindHandleWorkerLoop]
[2023/10/19 12:54:35.754 +08:00] [INFO] [domain.go:2382] ["updateStatsWorker is going to exit, start to flush stats"]
[2023/10/19 12:54:35.755 +08:00] [INFO] [advancer.go:355] ["Task watcher exits due to some error."] [category="log backup advancer"] [error=EOF]
[2023/10/19 12:54:35.754 +08:00] [INFO] [wait_group_wrapper.go:137] ["background process exited"] [source=domain] [process=loadSigningCertLoop]
[2023/10/19 12:54:35.754 +08:00] [INFO] [dispatcher_manager.go:245] ["subtask history table gc loop exits"] [error="context canceled"]
[2023/10/19 12:54:35.754 +08:00] [INFO] [domain.go:2098] ["dumpFileGcChecker exited."]
[2023/10/19 12:54:35.755 +08:00] [INFO] [manager.go:255] ["break campaign loop, NewSession failed"] ["owner info"="[bindinfo] /tidb/bindinfo/owner ownerManager 9631740f-ca41-4513-b7c9-772f4633cc1e"] [error="context canceled"] [errorVerbose="context canceled\ngithub.com/pingcap/errors.AddStack\n\texternal/com_github_pingcap_errors/errors.go:174\ngithub.com/pingcap/errors.Trace\n\texternal/com_github_pingcap_errors/juju_adaptor.go:15\ngithub.com/pingcap/tidb/pkg/util.contextDone\n\tpkg/util/etcd.go:90\ngithub.com/pingcap/tidb/pkg/util.NewSession\n\tpkg/util/etcd.go:50\ngithub.com/pingcap/tidb/pkg/owner.(*ownerManager).campaignLoop\n\tpkg/owner/manager.go:253\nruntime.goexit\n\tsrc/runtime/asm_amd64.s:1650"]
[2023/10/19 12:54:35.754 +08:00] [INFO] [domain.go:2064] ["PlanReplayerTaskDumpHandle exited."]
[2023/10/19 12:54:35.755 +08:00] [INFO] [wait_group_wrapper.go:137] ["background process exited"] [source=domain] [process=dumpFileGcChecker]
[2023/10/19 12:54:35.755 +08:00] [INFO] [domain.go:1510] ["dist task dispatcher manager stopped"] [id=9631740f-ca41-4513-b7c9-772f4633cc1e]
[2023/10/19 12:54:35.755 +08:00] [INFO] [wait_group_wrapper.go:137] ["background process exited"] [source=domain] [process=PlanReplayerTaskDumpHandle]
[2023/10/19 12:54:35.754 +08:00] [INFO] [wait_group_wrapper.go:137] ["background process exited"] [source=domain] [process=autoAnalyzeWorker]
[2023/10/19 12:54:35.754 +08:00] [INFO] [domain.go:736] ["topologySyncerKeeper exited."]
[2023/10/19 12:54:35.755 +08:00] [INFO] [domain.go:1488] ["stopping dist task scheduler manager"]
[2023/10/19 12:54:35.755 +08:00] [INFO] [wait_group_wrapper.go:137] ["background process exited"] [source=domain] [process=topologySyncerKeeper]
[2023/10/19 12:54:35.755 +08:00] [INFO] [manager.go:146] ["fetchAndHandleRunnableTasks done"]
[2023/10/19 12:54:35.755 +08:00] [INFO] [manager.go:166] ["fetchAndFastCancelTasks done"]
[2023/10/19 12:54:35.755 +08:00] [INFO] [manager.go:286] ["failed to campaign"] ["owner info"="[log-backup] /tidb/br-stream/owner ownerManager 66998aaf-5720-417e-b73b-36318f021f24"] [error="lost watcher waiting for delete"]
[2023/10/19 12:54:35.755 +08:00] [INFO] [domain.go:1490] ["dist task scheduler manager stopped"]
[2023/10/19 12:54:35.755 +08:00] [INFO] [manager.go:251] ["etcd session is done, creates a new one"] ["owner info"="[log-backup] /tidb/br-stream/owner ownerManager 66998aaf-5720-417e-b73b-36318f021f24"]
[2023/10/19 12:54:35.755 +08:00] [INFO] [wait_group_wrapper.go:137] ["background process exited"] [source=domain] [process=distTaskFrameworkLoop]
[2023/10/19 12:54:35.755 +08:00] [INFO] [owner_daemon.go:87] ["daemon loop exits"] [id=66998aaf-5720-417e-b73b-36318f021f24] [daemon-id=LogBackup::Advancer]
[2023/10/19 12:54:35.755 +08:00] [INFO] [domain.go:658] ["topNSlowQueryLoop exited."]
[2023/10/19 12:54:35.755 +08:00] [INFO] [domain.go:1330] ["closestReplicaReadCheckLoop exited."]
[2023/10/19 12:54:35.755 +08:00] [INFO] [wait_group_wrapper.go:137] ["background process exited"] [source=domain] [process=logBackupAdvancer]
[2023/10/19 12:54:35.755 +08:00] [INFO] [wait_group_wrapper.go:137] ["background process exited"] [source=domain] [process=topNSlowQueryLoop]
[2023/10/19 12:54:35.755 +08:00] [INFO] [wait_group_wrapper.go:137] ["background process exited"] [source=domain] [process=closestReplicaReadCheckLoop]
[2023/10/19 12:54:35.755 +08:00] [WARN] [etcd.go:78] ["failed to new session to etcd"] [ownerInfo="[log-backup] /tidb/br-stream/owner ownerManager 66998aaf-5720-417e-b73b-36318f021f24"] [error="context canceled"]
[2023/10/19 12:54:35.797 +08:00] [INFO] [domain.go:2384] ["updateStatsWorker ready to release owner"]
[2023/10/19 12:54:35.797 +08:00] [INFO] [manager.go:286] ["failed to campaign"] ["owner info"="[stats] /tidb/stats/owner ownerManager 9631740f-ca41-4513-b7c9-772f4633cc1e"] [error="context canceled"]
[2023/10/19 12:54:35.797 +08:00] [INFO] [manager.go:267] ["break campaign loop, context is done"] ["owner info"="[stats] /tidb/stats/owner ownerManager 9631740f-ca41-4513-b7c9-772f4633cc1e"]
[2023/10/19 12:54:35.956 +08:00] [INFO] [manager.go:255] ["break campaign loop, NewSession failed"] ["owner info"="[log-backup] /tidb/br-stream/owner ownerManager 66998aaf-5720-417e-b73b-36318f021f24"] [error="context canceled"] [errorVerbose="context canceled\ngithub.com/pingcap/errors.AddStack\n\texternal/com_github_pingcap_errors/errors.go:174\ngithub.com/pingcap/errors.Trace\n\texternal/com_github_pingcap_errors/juju_adaptor.go:15\ngithub.com/pingcap/tidb/pkg/util.contextDone\n\tpkg/util/etcd.go:90\ngithub.com/pingcap/tidb/pkg/util.NewSession\n\tpkg/util/etcd.go:50\ngithub.com/pingcap/tidb/pkg/owner.(*ownerManager).campaignLoop\n\tpkg/owner/manager.go:253\nruntime.goexit\n\tsrc/runtime/asm_amd64.s:1650"]
[2023/10/19 12:54:37.009 +08:00] [INFO] [manager.go:311] ["revoke session"] ["owner info"="[bindinfo] /tidb/bindinfo/owner ownerManager 9631740f-ca41-4513-b7c9-772f4633cc1e"] [error="rpc error: code = Canceled desc = grpc: the client connection is closing"]
[2023/10/19 12:54:37.009 +08:00] [INFO] [domain.go:1877] ["handleEvolvePlanTasksLoop exited."]
[2023/10/19 12:54:37.009 +08:00] [INFO] [wait_group_wrapper.go:137] ["background process exited"] [source=domain] [process=handleEvolvePlanTasksLoop]
[2023/10/19 12:54:37.056 +08:00] [INFO] [manager.go:311] ["revoke session"] ["owner info"="[stats] /tidb/stats/owner ownerManager 9631740f-ca41-4513-b7c9-772f4633cc1e"] [error="rpc error: code = Canceled desc = grpc: the client connection is closing"]
[2023/10/19 12:54:37.056 +08:00] [INFO] [domain.go:2390] ["updateStatsWorker exit preprocessing finished"]
[2023/10/19 12:54:37.056 +08:00] [INFO] [domain.go:2413] ["updateStatsWorker exited."]
[2023/10/19 12:54:37.056 +08:00] [INFO] [wait_group_wrapper.go:137] ["background process exited"] [source=domain] [process=updateStatsWorker]
[2023/10/19 12:54:37.062 +08:00] [INFO] [domain.go:1046] ["domain closed"] ["take time"=1.319703137s]
[2023/10/19 12:54:37.063 +08:00] [INFO] [tso_dispatcher.go:240] ["exit tso dispatcher loop"]
[2023/10/19 12:54:37.063 +08:00] [INFO] [tso_dispatcher.go:405] ["[tso] stop fetching the pending tso requests due to context canceled"] [dc-location=global]
[2023/10/19 12:54:37.063 +08:00] [INFO] [tso_dispatcher.go:186] ["exit tso requests cancel loop"]
[2023/10/19 12:54:37.063 +08:00] [INFO] [tso_dispatcher.go:339] ["[tso] exit tso dispatcher"] [dc-location=global]
[2023/10/19 12:54:37.063 +08:00] [INFO] [pd_service_discovery.go:248] ["[pd] exit member loop due to context canceled"]
[2023/10/19 12:54:37.063 +08:00] [INFO] [resource_manager_client.go:314] ["[resource manager] exit resource token dispatcher"]
[2023/10/19 12:54:37.063 +08:00] [INFO] [tso_client.go:134] ["closing tso client"]
[2023/10/19 12:54:37.063 +08:00] [INFO] [tso_client.go:139] ["close tso client"]
[2023/10/19 12:54:37.063 +08:00] [INFO] [tso_client.go:150] ["tso client is closed"]
[2023/10/19 12:54:37.063 +08:00] [INFO] [pd_service_discovery.go:294] ["[pd] close pd service discovery client"]
[2023/10/19 12:54:37.063 +08:00] [INFO] [pd.go:231] ["closed pd http client"]
=== NAME  TestLoadRemote
    testing.go:1465: race detected during execution of test
--- FAIL: TestLoadRemote (35.88s)
@YangKeao YangKeao added the type/bug The issue is confirmed as a bug. label Oct 19, 2023
@YangKeao YangKeao mentioned this issue Oct 19, 2023
Merged
5 tasks
@YangKeao YangKeao added the component/lightning This issue is related to Lightning of TiDB. label Oct 19, 2023
@hawkingrei hawkingrei mentioned this issue Oct 19, 2023
Open
@ti-chi-bot ti-chi-bot bot added may-affects-5.3 This bug maybe affects 5.3.x versions. may-affects-5.4 This bug maybe affects 5.4.x versions. may-affects-6.1 may-affects-6.5 may-affects-7.1 may-affects-7.5 labels Oct 23, 2023
@ti-chi-bot ti-chi-bot added the affects-7.5 This bug affects the 7.5.x(LTS) versions. label Oct 23, 2023
@D3Hunter D3Hunter removed may-affects-5.3 This bug maybe affects 5.3.x versions. may-affects-5.4 This bug maybe affects 5.4.x versions. may-affects-6.1 may-affects-6.5 may-affects-7.1 labels Oct 25, 2023
@D3Hunter D3Hunter mentioned this issue Oct 25, 2023
Merged
13 tasks
ti-chi-bot bot pushed a commit that referenced this issue Oct 26, 2023
@D3Hunter
importinto: fix data race in test (#47965)
a7366f9 
close #47776
@ti-chi-bot ti-chi-bot mentioned this issue Oct 26, 2023
Merged
13 tasks
ti-chi-bot bot pushed a commit that referenced this issue Oct 26, 2023
@ti-chi-bot
importinto: fix data race in test (#47965) (#47994)
2ccf023 
close #47776
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
affects-7.5 This bug affects the 7.5.x(LTS) versions. component/lightning This issue is related to Lightning of TiDB. component/test severity/major type/bug The issue is confirmed as a bug.
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

importinto: fix data race in test D3Hunter/tidb
4 participants
@D3Hunter @YangKeao @seiya-annie @ti-chi-bot