milvus icon indicating copy to clipboard operation
milvus copied to clipboard

Published 20 hours ago • verified publisher icon milvus-io

[Bug]: proto: cannot parse invalid wire-format data

Open qi49125 opened this issue 3 years ago • 7 comments

Is there an existing issue for this?

  • [X] I have searched the existing issues

Environment

- Milvus version:2.1.0
- Deployment mode(standalone or cluster):cluster
- SDK version(e.g. pymilvus v2.0.0rc2):2.1.0
- OS(Ubuntu or CentOS): Ubuntu 
- CPU/Memory: 360
- GPU: 
- Others:

Current Behavior

2022/08/02 10:50:24 maxprocs: Updating GOMAXPROCS=5: determined from CPU quota

/ |/ / / /| | / / / / / __/ / /|/ // // /| |/ / // /\
// /////_/__/

Welcome to use Milvus! Version: v2.1.0 Built: Wed Jul 27 08:27:34 UTC 2022 GitCommit: 1b33c731 GoVersion: go version go1.16.9 linux/amd64

open pid file: /run/milvus/datacoord.pid lock pid file: /run/milvus/datacoord.pid [2022/08/02 10:50:24.044 +00:00] [INFO] [roles/roles.go:358] ["starting running Milvus components"] [2022/08/02 10:50:24.045 +00:00] [INFO] [paramtable/base_table.go:459] ["Pulsar config"] ["pulsar url"=pulsar://pulsar:6650] ["pulsar web url"=http://pulsar:80] [2022/08/02 10:50:24.046 +00:00] [DEBUG] [paramtable/component_param.go:769] ["init cacheSize"] ["cacheSize (GB)"=0] [2022/08/02 10:50:24.046 +00:00] [DEBUG] [metrics/metrics.go:91] ["metrics listen"] [addr=:9091] [2022/08/02 10:50:24.047 +00:00] [INFO] [paramtable/base_table.go:459] ["Pulsar config"] ["pulsar url"=pulsar://pulsar:6650] ["pulsar web url"=http://pulsar:80] [2022/08/02 10:50:24.047 +00:00] [DEBUG] [paramtable/grpc_param.go:157] [initServerMaxSendSize] [role=datacoord] [grpc.serverMaxSendSize=2147483647] [2022/08/02 10:50:24.047 +00:00] [DEBUG] [paramtable/grpc_param.go:181] [initServerMaxRecvSize] [role=datacoord] [grpc.serverMaxRecvSize=2147483647] [2022/08/02 10:50:24.050 +00:00] [DEBUG] [datacoord/service.go:125] ["network port"] [port=13333] [2022/08/02 10:50:24.150 +00:00] [DEBUG] [sessionutil/session_util.go:86] ["Session try to connect to etcd"] [2022/08/02 10:50:24.152 +00:00] [DEBUG] [sessionutil/session_util.go:101] ["Session connect to etcd success"] [2022/08/02 10:50:24.155 +00:00] [DEBUG] [sessionutil/session_util.go:180] ["Session get serverID success"] [key=id] [ServerId=1155] [2022/08/02 10:50:24.155 +00:00] [INFO] [logutil/logutil.go:165] ["Log directory"] [configDir=] [2022/08/02 10:50:24.155 +00:00] [INFO] [logutil/logutil.go:166] ["Set log file to "] [path=] [2022/08/02 10:50:24.155 +00:00] [DEBUG] [datacoord/service.go:210] ["DataCoord init done ..."] [2022/08/02 10:50:24.155 +00:00] [DEBUG] [sessionutil/session_util.go:86] ["Session try to connect to etcd"] [2022/08/02 10:50:24.156 +00:00] [DEBUG] [sessionutil/session_util.go:101] ["Session connect to etcd success"] [2022/08/02 10:50:24.157 +00:00] [INFO] [paramtable/base_table.go:459] ["Pulsar config"] ["pulsar url"=pulsar://pulsar:6650] ["pulsar web url"=http://pulsar:80] [2022/08/02 10:50:24.158 +00:00] [DEBUG] [paramtable/grpc_param.go:244] ["Init client max send size"] [role=rootcoord] [grpc.clientMaxSendSize=104857600] [2022/08/02 10:50:24.158 +00:00] [DEBUG] [paramtable/grpc_param.go:244] ["Init client max recv size"] [role=rootcoord] [grpc.clientMaxRecvSize=104857600] [2022/08/02 10:50:24.158 +00:00] [DEBUG] [paramtable/grpc_param.go:244] ["Init dial timeout"] [role=rootcoord] [grpc.client.dialTimeout=104857600] [2022/08/02 10:50:24.158 +00:00] [DEBUG] [paramtable/grpc_param.go:244] ["Init keep alive timeout"] [role=rootcoord] [grpc.client.keepAliveTimeout=104857600] [2022/08/02 10:50:24.158 +00:00] [DEBUG] [paramtable/grpc_param.go:244] ["Init keep alive time"] [role=rootcoord] [grpc.client.keepAliveTime=104857600] [2022/08/02 10:50:24.158 +00:00] [DEBUG] [paramtable/grpc_param.go:244] ["Init max attempts"] [role=rootcoord] [grpc.client.maxMaxAttempts=104857600] [2022/08/02 10:50:24.158 +00:00] [DEBUG] [paramtable/grpc_param.go:244] ["Init initial back off"] [role=rootcoord] [grpc.client.initialBackOff=104857600] [2022/08/02 10:50:24.158 +00:00] [DEBUG] [paramtable/grpc_param.go:244] ["Init max back off"] [role=rootcoord] [grpc.client.maxBackoff=104857600] [2022/08/02 10:50:24.158 +00:00] [DEBUG] [paramtable/grpc_param.go:244] ["Init back off multiplier"] [role=rootcoord] [grpc.client.backoffMultiplier=104857600] [2022/08/02 10:50:24.652 +00:00] [INFO] [datacoord/server.go:420] ["DataCoord success to get DataNode sessions"] [sessions={}] [2022/08/02 10:50:24.652 +00:00] [DEBUG] [datacoord/channel_manager.go:155] ["starting etcd states checker"] [2022/08/02 10:50:24.652 +00:00] [INFO] [datacoord/channel_manager.go:158] ["cluster start up"] [nodes="[]"] [oNodes="[]"] ["old onlines"="[]"] ["new onlines"="[]"] [offLines="[]"] [2022/08/02 10:50:24.654 +00:00] [DEBUG] [sessionutil/session_util.go:299] ["SessionUtil GetSessions "] [prefix=rootcoord] [key=rootcoord] [address=12.11.0.111:53100] [2022/08/02 10:50:24.655 +00:00] [INFO] [datacoord/segment_reference_manager.go:41] ["create a new segment reference manager"] [2022/08/02 10:50:24.660 +00:00] [ERROR] [datacoord/segment_reference_manager.go:57] ["unmarshal segment reference lock failed"] [error="proto: cannot parse invalid wire-format data"] [stack="github.com/milvus-io/milvus/internal/datacoord.NewSegmentReferenceManager\n\t/go/src/github.com/milvus-io/milvus/internal/datacoord/segment_reference_manager.go:57\ngithub.com/milvus-io/milvus/internal/datacoord.(*Server).initServiceDiscovery\n\t/go/src/github.com/milvus-io/milvus/internal/datacoord/server.go:468\ngithub.com/milvus-io/milvus/internal/datacoord.(*Server).Start\n\t/go/src/github.com/milvus-io/milvus/internal/datacoord/server.go:287\ngithub.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).start\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:162\ngithub.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).Run\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:212\ngithub.com/milvus-io/milvus/cmd/components.(*DataCoord).Run\n\t/go/src/github.com/milvus-io/milvus/cmd/components/data_coord.go:47\ngithub.com/milvus-io/milvus/cmd/roles.(*MilvusRoles).runDataCoord.func1\n\t/go/src/github.com/milvus-io/milvus/cmd/roles/roles.go:251"] [2022/08/02 10:50:24.660 +00:00] [ERROR] [datacoord/service.go:164] ["DataCoord start failed"] [error="proto: cannot parse invalid wire-format data"] [stack="github.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).start\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:164\ngithub.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).Run\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:212\ngithub.com/milvus-io/milvus/cmd/components.(*DataCoord).Run\n\t/go/src/github.com/milvus-io/milvus/cmd/components/data_coord.go:47\ngithub.com/milvus-io/milvus/cmd/roles.(*MilvusRoles).runDataCoord.func1\n\t/go/src/github.com/milvus-io/milvus/cmd/roles/roles.go:251"]

Expected Behavior

No response

Steps To Reproduce

No response

Milvus Log

No response

Anything else?

No response

qi49125 avatar Aug 02 '22 11:08 qi49125

/assign @wayblink pls help on investigating this issue

xiaofan-luan avatar Aug 02 '22 11:08 xiaofan-luan

Before the upgrade, delete the IVF_SQ8 index and create the IVF_PQ. So, I wonder if it had anything to do with this operation.

qi49125 avatar Aug 02 '22 11:08 qi49125

milvusdb/milvus-dev:wayblink-i-18496-975a76baf-20220804版本

2022/08/04 10:43:44 maxprocs: Updating GOMAXPROCS=5: determined from CPU quota

/ |/ / / /| | / / / / / __/ / /|/ // // /| |/ / // /\
// /////_/__/

Welcome to use Milvus! Version: v2.0.0-testing-20220331-708-g975a76baf Built: Thu Aug 4 09:29:23 UTC 2022 GitCommit: 975a76baf GoVersion: go version go1.16.9 linux/amd64

open pid file: /run/milvus/datacoord.pid lock pid file: /run/milvus/datacoord.pid [2022/08/04 10:43:44.239 +00:00] [INFO] [roles/roles.go:358] ["starting running Milvus components"] [2022/08/04 10:43:44.241 +00:00] [INFO] [paramtable/base_table.go:459] ["Pulsar config"] ["pulsar url"=pulsar://pulsar:6650] ["pulsar web url"=http://pulsar:80] [2022/08/04 10:43:44.241 +00:00] [DEBUG] [paramtable/component_param.go:769] ["init cacheSize"] ["cacheSize (GB)"=0] [2022/08/04 10:43:44.241 +00:00] [DEBUG] [metrics/metrics.go:91] ["metrics listen"] [addr=:9091] [2022/08/04 10:43:44.242 +00:00] [INFO] [paramtable/base_table.go:459] ["Pulsar config"] ["pulsar url"=pulsar://pulsar:6650] ["pulsar web url"=http://pulsar:80] [2022/08/04 10:43:44.243 +00:00] [DEBUG] [paramtable/grpc_param.go:157] [initServerMaxSendSize] [role=datacoord] [grpc.serverMaxSendSize=2147483647] [2022/08/04 10:43:44.243 +00:00] [DEBUG] [paramtable/grpc_param.go:181] [initServerMaxRecvSize] [role=datacoord] [grpc.serverMaxRecvSize=2147483647] [2022/08/04 10:43:44.244 +00:00] [DEBUG] [datacoord/service.go:125] ["network port"] [port=13333] [2022/08/04 10:43:44.346 +00:00] [DEBUG] [sessionutil/session_util.go:86] ["Session try to connect to etcd"] [2022/08/04 10:43:44.347 +00:00] [DEBUG] [sessionutil/session_util.go:101] ["Session connect to etcd success"] [2022/08/04 10:43:44.350 +00:00] [DEBUG] [sessionutil/session_util.go:180] ["Session get serverID success"] [key=id] [ServerId=1157] [2022/08/04 10:43:44.350 +00:00] [INFO] [logutil/logutil.go:165] ["Log directory"] [configDir=] [2022/08/04 10:43:44.350 +00:00] [INFO] [logutil/logutil.go:166] ["Set log file to "] [path=] [2022/08/04 10:43:44.350 +00:00] [DEBUG] [datacoord/service.go:210] ["DataCoord init done ..."] [2022/08/04 10:43:44.350 +00:00] [DEBUG] [sessionutil/session_util.go:86] ["Session try to connect to etcd"] [2022/08/04 10:43:44.350 +00:00] [DEBUG] [sessionutil/session_util.go:101] ["Session connect to etcd success"] [2022/08/04 10:43:44.353 +00:00] [INFO] [paramtable/base_table.go:459] ["Pulsar config"] ["pulsar url"=pulsar://pulsar:6650] ["pulsar web url"=http://pulsar:80] [2022/08/04 10:43:44.353 +00:00] [DEBUG] [paramtable/grpc_param.go:244] ["Init client max send size"] [role=rootcoord] [grpc.clientMaxSendSize=104857600] [2022/08/04 10:43:44.353 +00:00] [DEBUG] [paramtable/grpc_param.go:244] ["Init client max recv size"] [role=rootcoord] [grpc.clientMaxRecvSize=104857600] [2022/08/04 10:43:44.353 +00:00] [DEBUG] [paramtable/grpc_param.go:244] ["Init dial timeout"] [role=rootcoord] [grpc.client.dialTimeout=104857600] [2022/08/04 10:43:44.353 +00:00] [DEBUG] [paramtable/grpc_param.go:244] ["Init keep alive timeout"] [role=rootcoord] [grpc.client.keepAliveTimeout=104857600] [2022/08/04 10:43:44.353 +00:00] [DEBUG] [paramtable/grpc_param.go:244] ["Init keep alive time"] [role=rootcoord] [grpc.client.keepAliveTime=104857600] [2022/08/04 10:43:44.353 +00:00] [DEBUG] [paramtable/grpc_param.go:244] ["Init max attempts"] [role=rootcoord] [grpc.client.maxMaxAttempts=104857600] [2022/08/04 10:43:44.353 +00:00] [DEBUG] [paramtable/grpc_param.go:244] ["Init initial back off"] [role=rootcoord] [grpc.client.initialBackOff=104857600] [2022/08/04 10:43:44.353 +00:00] [DEBUG] [paramtable/grpc_param.go:244] ["Init max back off"] [role=rootcoord] [grpc.client.maxBackoff=104857600] [2022/08/04 10:43:44.353 +00:00] [DEBUG] [paramtable/grpc_param.go:244] ["Init back off multiplier"] [role=rootcoord] [grpc.client.backoffMultiplier=104857600] [2022/08/04 10:43:44.748 +00:00] [INFO] [datacoord/server.go:421] ["DataCoord success to get DataNode sessions"] [sessions={}] [2022/08/04 10:43:44.748 +00:00] [DEBUG] [datacoord/channel_manager.go:155] ["starting etcd states checker"] [2022/08/04 10:43:44.748 +00:00] [INFO] [datacoord/channel_manager.go:158] ["cluster start up"] [nodes="[]"] [oNodes="[]"] ["old onlines"="[]"] ["new onlines"="[]"] [offLines="[]"] [2022/08/04 10:43:44.751 +00:00] [DEBUG] [sessionutil/session_util.go:299] ["SessionUtil GetSessions "] [prefix=rootcoord] [key=rootcoord] [address=12.11.0.111:53100] [2022/08/04 10:43:44.751 +00:00] [INFO] [datacoord/segment_reference_manager.go:41] ["create a new segment reference manager"] [2022/08/04 10:43:44.756 +00:00] [ERROR] [datacoord/segment_reference_manager.go:57] ["unmarshal segment reference lock failed"] [error="proto: cannot parse invalid wire-format data"] [value=1098] [stack="github.com/milvus-io/milvus/internal/datacoord.NewSegmentReferenceManager\n\t/go/src/github.com/milvus-io/milvus/internal/datacoord/segment_reference_manager.go:57\ngithub.com/milvus-io/milvus/internal/datacoord.(*Server).initServiceDiscovery\n\t/go/src/github.com/milvus-io/milvus/internal/datacoord/server.go:469\ngithub.com/milvus-io/milvus/internal/datacoord.(*Server).Start\n\t/go/src/github.com/milvus-io/milvus/internal/datacoord/server.go:287\ngithub.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).start\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:162\ngithub.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).Run\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:212\ngithub.com/milvus-io/milvus/cmd/components.(*DataCoord).Run\n\t/go/src/github.com/milvus-io/milvus/cmd/components/data_coord.go:47\ngithub.com/milvus-io/milvus/cmd/roles.(*MilvusRoles).runDataCoord.func1\n\t/go/src/github.com/milvus-io/milvus/cmd/roles/roles.go:251"] [2022/08/04 10:43:44.756 +00:00] [ERROR] [datacoord/service.go:164] ["DataCoord start failed"] [error="proto: cannot parse invalid wire-format data"] [stack="github.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).start\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:164\ngithub.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).Run\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:212\ngithub.com/milvus-io/milvus/cmd/components.(*DataCoord).Run\n\t/go/src/github.com/milvus-io/milvus/cmd/components/data_coord.go:47\ngithub.com/milvus-io/milvus/cmd/roles.(*MilvusRoles).runDataCoord.func1\n\t/go/src/github.com/milvus-io/milvus/cmd/roles/roles.go:251"]

qi49125 avatar Aug 04 '22 10:08 qi49125

after delete lock value from etcd ,indexcoord--log

[2022/08/05 01:44:16.004 +00:00] [DEBUG] [indexcoord/meta_table.go:455] ["IndexCoord get index file path from meta table"] [indexBuildID=434686640316219418] [2022/08/05 01:44:16.004 +00:00] [WARN] [indexcoord/index_coord.go:638] ["IndexCoord GetIndexFilePaths failed"] [indexBuildID=434686640316219418] [error="index not exists with ID = 434686640316219418"] [2022/08/05 01:44:16.006 +00:00] [DEBUG] [indexcoord/index_coord.go:619] ["IndexCoord GetIndexFilePaths"] ["number of IndexBuildIds"=1] [2022/08/05 01:44:16.006 +00:00] [DEBUG] [indexcoord/meta_table.go:455] ["IndexCoord get index file path from meta table"] [indexBuildID=434686640683221012] [2022/08/05 01:44:16.006 +00:00] [WARN] [indexcoord/index_coord.go:638] ["IndexCoord GetIndexFilePaths failed"] [indexBuildID=434686640683221012] [error="index not exists with ID = 434686640683221012"] [2022/08/05 01:44:16.009 +00:00] [DEBUG] [indexcoord/index_coord.go:619] ["IndexCoord GetIndexFilePaths"] ["number of IndexBuildIds"=1] [2022/08/05 01:44:16.009 +00:00] [DEBUG] [indexcoord/meta_table.go:455] ["IndexCoord get index file path from meta table"] [indexBuildID=434686640538779668] [2022/08/05 01:44:16.009 +00:00] [WARN] [indexcoord/index_coord.go:638] ["IndexCoord GetIndexFilePaths failed"] [indexBuildID=434686640538779668] [error="index not exists with ID = 434686640538779668"] [2022/08/05 01:44:16.011 +00:00] [DEBUG] [indexcoord/index_coord.go:619] ["IndexCoord GetIndexFilePaths"] ["number of IndexBuildIds"=1] [2022/08/05 01:44:16.011 +00:00] [DEBUG] [indexcoord/meta_table.go:455] ["IndexCoord get index file path from meta table"] [indexBuildID=434686640538779654] [2022/08/05 01:44:16.011 +00:00] [WARN] [indexcoord/index_coord.go:638] ["IndexCoord GetIndexFilePaths failed"] [indexBuildID=434686640538779654] [error="index not exists with ID = 434686640538779654"] [2022/08/05 01:44:16.014 +00:00] [DEBUG] [indexcoord/index_coord.go:619] ["IndexCoord GetIndexFilePaths"] ["number of IndexBuildIds"=1] [2022/08/05 01:44:16.014 +00:00] [DEBUG] [indexcoord/meta_table.go:455] ["IndexCoord get index file path from meta table"] [indexBuildID=434686640027861000] [2022/08/05 01:44:16.014 +00:00] [WARN] [indexcoord/index_coord.go:638] ["IndexCoord GetIndexFilePaths failed"] [indexBuildID=434686640027861000] [error="index not exists with ID = 434686640027861000"] [2022/08/05 01:44:16.016 +00:00] [DEBUG] [indexcoord/index_coord.go:619] ["IndexCoord GetIndexFilePaths"] ["number of IndexBuildIds"=1] [2022/08/05 01:44:16.016 +00:00] [DEBUG] [indexcoord/meta_table.go:455] ["IndexCoord get index file path from meta table"] [indexBuildID=434686639988539416] [2022/08/05 01:44:16.016 +00:00] [WARN] [indexcoord/index_coord.go:638] ["IndexCoord GetIndexFilePaths failed"] [indexBuildID=434686639988539416] [error="index not exists with ID = 434686639988539416"] [2022/08/05 01:44:16.019 +00:00] [DEBUG] [indexcoord/index_coord.go:619] ["IndexCoord GetIndexFilePaths"] ["number of IndexBuildIds"=1] [2022/08/05 01:44:16.019 +00:00] [DEBUG] [indexcoord/meta_table.go:455] ["IndexCoord get index file path from meta table"] [indexBuildID=434686640722280460] [2022/08/05 01:44:16.019 +00:00] [WARN] [indexcoord/index_coord.go:638] ["IndexCoord GetIndexFilePaths failed"] [indexBuildID=434686640722280460] [error="index not exists with ID = 434686640722280460"] [2022/08/05 01:44:16.021 +00:00] [DEBUG] [indexcoord/index_coord.go:619] ["IndexCoord GetIndexFilePaths"] ["number of IndexBuildIds"=1] [2022/08/05 01:44:16.021 +00:00] [DEBUG] [indexcoord/meta_table.go:455] ["IndexCoord get index file path from meta table"] [indexBuildID=434686640014491680] [2022/08/05 01:44:16.021 +00:00] [WARN] [indexcoord/index_coord.go:638] ["IndexCoord GetIndexFilePaths failed"] [indexBuildID=434686640014491680] [error="index not exists with ID = 434686640014491680"] [2022/08/05 01:44:16.024 +00:00] [DEBUG] [indexcoord/index_coord.go:619] ["IndexCoord GetIndexFilePaths"] ["number of IndexBuildIds"=1] [2022/08/05 01:44:16.024 +00:00] [DEBUG] [indexcoord/meta_table.go:455] ["IndexCoord get index file path from meta table"] [indexBuildID=434686640433922068] [2022/08/05 01:44:16.024 +00:00] [WARN] [indexcoord/index_coord.go:638] ["IndexCoord GetIndexFilePaths failed"] [indexBuildID=434686640433922068] [error="index not exists with ID = 434686640433922068"] [2022/08/05 01:44:16.026 +00:00] [DEBUG] [indexcoord/index_coord.go:619] ["IndexCoord GetIndexFilePaths"] ["number of IndexBuildIds"=1] [2022/08/05 01:44:16.026 +00:00] [DEBUG] [indexcoord/meta_table.go:455] ["IndexCoord get index file path from meta table"] [indexBuildID=434686640263528476] [2022/08/05 01:44:16.026 +00:00] [WARN] [indexcoord/index_coord.go:638] ["IndexCoord GetIndexFilePaths failed"] [indexBuildID=434686640263528476] [error="index not exists with ID = 434686640263528476"] [2022/08/05 01:44:16.028 +00:00] [DEBUG] [indexcoord/index_coord.go:619] ["IndexCoord GetIndexFilePaths"] ["number of IndexBuildIds"=1] [2022/08/05 01:44:16.028 +00:00] [DEBUG] [indexcoord/meta_table.go:455] ["IndexCoord get index file path from meta table"] [indexBuildID=434686640591208460] [2022/08/05 01:44:16.028 +00:00] [WARN] [indexcoord/index_coord.go:638] ["IndexCoord GetIndexFilePaths failed"] [indexBuildID=434686640591208460] [error="index not exists with ID = 434686640591208460"] [2022/08/05 01:44:16.031 +00:00] [DEBUG] [indexcoord/index_coord.go:619] ["IndexCoord GetIndexFilePaths"] ["number of IndexBuildIds"=1] [2022/08/05 01:44:16.031 +00:00] [DEBUG] [indexcoord/meta_table.go:455] ["IndexCoord get index file path from meta table"] [indexBuildID=434686640787816478] [2022/08/05 01:44:16.031 +00:00] [WARN] [indexcoord/index_coord.go:638] ["IndexCoord GetIndexFilePaths failed"] [indexBuildID=434686640787816478] [error="index not exists with ID = 434686640787816478"] [2022/08/05 01:44:16.034 +00:00] [DEBUG] [indexcoord/index_coord.go:619] ["IndexCoord GetIndexFilePaths"] ["number of IndexBuildIds"=1] [2022/08/05 01:44:16.034 +00:00] [DEBUG] [indexcoord/meta_table.go:455] ["IndexCoord get index file path from meta table"] [indexBuildID=434686640604315660] [2022/08/05 01:44:16.034 +00:00] [WARN] [indexcoord/index_coord.go:638] ["IndexCoord GetIndexFilePaths failed"] [indexBuildID=434686640604315660] [error="index not exists with ID = 434686640604315660"] [2022/08/05 01:44:16.036 +00:00] [DEBUG] [indexcoord/index_coord.go:619] ["IndexCoord GetIndexFilePaths"] ["number of IndexBuildIds"=1] [2022/08/05 01:44:16.036 +00:00] [DEBUG] [indexcoord/meta_table.go:455] ["IndexCoord get index file path from meta table"] [indexBuildID=434686640145563672] [2022/08/05 01:44:16.036 +00:00] [WARN] [indexcoord/index_coord.go:638] ["IndexCoord GetIndexFilePaths failed"] [indexBuildID=434686640145563672] [error="index not exists with ID = 434686640145563672"] [2022/08/05 01:44:16.039 +00:00] [DEBUG] [indexcoord/index_coord.go:619] ["IndexCoord GetIndexFilePaths"] ["number of IndexBuildIds"=1] [2022/08/05 01:44:16.039 +00:00] [DEBUG] [indexcoord/meta_table.go:455] ["IndexCoord get index file path from meta table"] [indexBuildID=434686639975170058] [2022/08/05 01:44:16.039 +00:00] [WARN] [indexcoord/index_coord.go:638] ["IndexCoord GetIndexFilePaths failed"] [indexBuildID=434686639975170058] [error="index not exists with ID = 434686639975170058"] [2022/08/05 01:44:16.042 +00:00] [DEBUG] [indexcoord/index_coord.go:619] ["IndexCoord GetIndexFilePaths"] ["number of IndexBuildIds"=1] [2022/08/05 01:44:16.042 +00:00] [DEBUG] [indexcoord/meta_table.go:455] ["IndexCoord get index file path from meta table"] [indexBuildID=434686640827400200] [2022/08/05 01:44:16.042 +00:00] [WARN] [indexcoord/index_coord.go:638] ["IndexCoord GetIndexFilePaths failed"] [indexBuildID=434686640827400200] [error="index not exists with ID = 434686640827400200"] [2022/08/05 01:44:16.045 +00:00] [DEBUG] [indexcoord/index_coord.go:619] ["IndexCoord GetIndexFilePaths"] ["number of IndexBuildIds"=1] [2022/08/05 01:44:16.045 +00:00] [DEBUG] [indexcoord/meta_table.go:455] ["IndexCoord get index file path from meta table"] [indexBuildID=434686640394600470] [2022/08/05 01:44:16.045 +00:00] [WARN] [indexcoord/index_coord.go:638] ["IndexCoord GetIndexFilePaths failed"] [indexBuildID=434686640394600470] [error="index not exists with ID = 434686640394600470"] [2022/08/05 01:44:16.049 +00:00] [DEBUG] [indexcoord/index_coord.go:619] ["IndexCoord GetIndexFilePaths"] ["number of IndexBuildIds"=1] [2022/08/05 01:44:16.049 +00:00] [DEBUG] [indexcoord/meta_table.go:455] ["IndexCoord get index file path from meta table"] [indexBuildID=434686640093134862] [2022/08/05 01:44:16.049 +00:00] [WARN] [indexcoord/index_coord.go:638] ["IndexCoord GetIndexFilePaths failed"] [indexBuildID=434686640093134862] [error="index not exists with ID = 434686640093134862"] [2022/08/05 01:44:16.055 +00:00] [DEBUG] [indexcoord/index_coord.go:619] ["IndexCoord GetIndexFilePaths"] ["number of IndexBuildIds"=1] [2022/08/05 01:44:16.055 +00:00] [DEBUG] [indexcoord/meta_table.go:455] ["IndexCoord get index file path from meta table"] [indexBuildID=434686640814030852] [2022/08/05 01:44:16.055 +00:00] [WARN] [indexcoord/index_coord.go:638] ["IndexCoord GetIndexFilePaths failed"] [indexBuildID=434686640814030852] [error="index not exists with ID = 434686640814030852"] [2022/08/05 01:44:16.057 +00:00] [DEBUG] [indexcoord/index_coord.go:619] ["IndexCoord GetIndexFilePaths"] ["number of IndexBuildIds"=1] [2022/08/05 01:44:16.057 +00:00] [DEBUG] [indexcoord/meta_table.go:455] ["IndexCoord get index file path from meta table"] [indexBuildID=434686640709435418] [2022/08/05 01:44:16.057 +00:00] [WARN] [indexcoord/index_coord.go:638] ["IndexCoord GetIndexFilePaths failed"] [indexBuildID=434686640709435418] [error="index not exists with ID = 434686640709435418"]

qi49125 avatar Aug 05 '22 01:08 qi49125

datacoord-----log 2022/08/05 02:00:45.819 +00:00] [INFO] [datacoord/compaction_trigger.go:394] ["generate a plan for small candidates"] [plan="segmentBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > deltalogs: binlogs: > > segmentBinlogs: > fieldBinlogs: > fieldBinlogs: > fieldBinlogs: > field2StatslogPaths: > field2StatslogPaths: > field2StatslogPaths: > deltalogs:<> > segmentBinlogs: binlogs: > fieldBinlogs: binlogs: > fieldBinlogs: binlogs: > fieldBinlogs: binlogs: > field2StatslogPaths: binlogs: > field2StatslogPaths: binlogs: > field2StatslogPaths: binlogs: > deltalogs: > > type:MixCompaction timetravel:434957935129395200 channel:"by-dev-rootcoord-dml_4_432520058327793665v0" "] ["target segment row"=93731] ["target segment size"=292679701] [2022/08/05 02:00:45.821 +00:00] [INFO] [datacoord/compaction_trigger.go:256] ["time cost of generating global compaction"] [planID=435071181337395204] ["time cost"=0] [collectionID=0] [channel=by-dev-rootcoord-dml_4_432520058327793665v0] [partitionID=432529593881329665] [2022/08/05 02:00:45.821 +00:00] [INFO] [datacoord/compaction_trigger.go:394] ["generate a plan for small candidates"] [plan="segmentBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > deltalogs: > > segmentBinlogs: > fieldBinlogs: > fieldBinlogs: > fieldBinlogs: > field2StatslogPaths: > field2StatslogPaths: > field2StatslogPaths: > deltalogs:<> > segmentBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > deltalogs: binlogs: binlogs: binlogs: binlogs: > > type:MixCompaction timetravel:434957935129395200 channel:"by-dev-rootcoord-dml_4_432520058327793665v0" "] ["target segment row"=88357] ["target segment size"=275818301] [2022/08/05 02:00:45.822 +00:00] [WARN] [datacoord/session_manager.go:148] ["failed to execute compaction"] [node=1192] [error="compaction plan illegal"] [planID=435071181337395203] [2022/08/05 02:00:45.822 +00:00] [WARN] [datacoord/session_manager.go:148] ["failed to execute compaction"] [node=1192] [error="compaction plan illegal"] [planID=435071181337395202] [2022/08/05 02:00:45.823 +00:00] [INFO] [datacoord/compaction_trigger.go:256] ["time cost of generating global compaction"] [planID=435071181337395205] ["time cost"=1] [collectionID=0] [channel=by-dev-rootcoord-dml_4_432520058327793665v0] [partitionID=432523724490276865] [2022/08/05 02:00:45.823 +00:00] [WARN] [datacoord/session_manager.go:148] ["failed to execute compaction"] [node=1192] [error="compaction plan illegal"] [planID=435071181337395204] [2022/08/05 02:00:45.823 +00:00] [INFO] [datacoord/compaction_trigger.go:394] ["generate a plan for small candidates"] [plan="segmentBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > deltalogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > > segmentBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > deltalogs: binlogs: > > type:MixCompaction timetravel:434957935129395200 channel:"by-dev-rootcoord-dml_4_432520058327793665v0" "] ["target segment row"=98033] ["target segment size"=305032866] [2022/08/05 02:00:45.825 +00:00] [INFO] [datacoord/compaction_trigger.go:256] ["time cost of generating global compaction"] [planID=435071181337395206] ["time cost"=1] [collectionID=0] [channel=by-dev-rootcoord-dml_4_432520058327793665v0] [partitionID=432542867805175809] [2022/08/05 02:00:45.825 +00:00] [INFO] [datacoord/compaction_trigger.go:394] ["generate a plan for small candidates"] [plan="segmentBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > deltalogs: binlogs: binlogs: binlogs: binlogs: > > segmentBinlogs: > fieldBinlogs: > fieldBinlogs: > fieldBinlogs: > field2StatslogPaths: > field2StatslogPaths: > field2StatslogPaths: > deltalogs:<> > segmentBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > deltalogs: > > type:MixCompaction timetravel:434957935129395200 channel:"by-dev-rootcoord-dml_4_432520058327793665v0" "] ["target segment row"=131356] ["target segment size"=410489579][2022/08/05 02:00:45.827 +00:00] [INFO] [datacoord/compaction_trigger.go:256] ["time cost of generating global compaction"] [planID=435071181337395207] ["time cost"=0] [collectionID=0] [channel=by-dev-rootcoord-dml_4_432520058327793665v0] [partitionID=432526620539224065][2022/08/05 02:00:45.827 +00:00] [WARN] [datacoord/session_manager.go:148] ["failed to execute compaction"] [node=1192] [error="compaction plan illegal"] [planID=435071181337395205][2022/08/05 02:00:45.827 +00:00] [WARN] [datacoord/session_manager.go:148] ["failed to execute compaction"] [node=1192] [error="compaction plan illegal"] [planID=435071181337395206][2022/08/05 02:00:45.827 +00:00] [INFO] [datacoord/compaction_trigger.go:394] ["generate a plan for small candidates"] [plan="segmentBinlogs:

binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > deltalogs: binlogs: > > segmentBinlogs: > fieldBinlogs: > fieldBinlogs: > fieldBinlogs: > field2StatslogPaths: > field2StatslogPaths: > field2StatslogPaths: > deltalogs:<> > segmentBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > deltalogs:<> > type:MixCompaction timetravel:434957935129395200 channel:"by-dev-rootcoord-dml_4_432520058327793665v0" "] ["target segment row"=117750] ["target segment size"=366443576][2022/08/05 02:00:45.828 +00:00] [INFO] [datacoord/compaction_trigger.go:256] ["time cost of generating global compaction"] [planID=435071181337395208] ["time cost"=0] [collectionID=0] [channel=by-dev-rootcoord-dml_4_432520058327793665v0] [partitionID=432531566659108865][2022/08/05 02:00:45.829 +00:00] [WARN] [datacoord/session_manager.go:148] ["failed to execute compaction"] [node=1192] [error="compaction plan illegal"] [planID=435071181337395207][2022/08/05 02:00:45.829 +00:00] [INFO] [datacoord/compaction_trigger.go:394] ["generate a plan for small candidates"] [plan="segmentBinlogs:

binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > fieldBinlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > field2StatslogPaths: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: binlogs: > deltalogs: > > segmentBinlogs: binlogs: > fieldBinlogs: binlogs: > fieldBinlogs: binlogs: > fieldBinlogs: binlogs: > field2StatslogPaths: binlogs: > field2StatslogPaths: binlogs: > field2StatslogPaths: binlogs: > deltalogs:<> > type:MixCompaction timetravel:434957935129395200 channel:"by-dev-rootcoord-dml_4_432520058327793665v0" "] ["target segment row"=95339] ["target segment size"=298267421][2022/08/05 02:00:45.830 +00:00] [INFO] [datacoord/compaction_trigger.go:256] ["time cost of generating global compaction"] [planID=435071181337395209] ["time cost"=0] [collectionID=0] [channel=by-dev-rootcoord-dml_4_432520058327793665v0] [partitionID=432520296852619265][2022/08/05 02:00:45.835 +00:00] [WARN] [datacoord/session_manager.go:148] ["failed to execute compaction"] [node=1192] [error="compaction plan illegal"] [planID=435071181337395208][2022/08/05 02:00:45.835 +00:00] [WARN] [datacoord/session_manager.go:148] ["failed to execute compaction"] [node=1192] [error="compaction plan illegal"] [planID=435071181337395209][2022/08/05 02:00:59.405 +00:00] [INFO] [datacoord/channel_checker.go:104] ["timeout and stop timer: wait for channel ACK timeout"] ["watch state"=ToRelease] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0] ["timeout time"=2022/08/05 02:00:59.404 +00:00][2022/08/05 02:00:59.405 +00:00] [DEBUG] [datacoord/channel_manager.go:653] ["receive timeout acks from state watcher"] [state=6] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0][2022/08/05 02:00:59.405 +00:00] [INFO] [msgstream/msgstream_util.go:29] ["unsubscribe channel"] [subname=by-dev-dataNode-1192-432520058327793665] [channels="[by-dev-rootcoord-dml_4]"][2022/08/05 02:00:59.411 +00:00] [WARN] [msgstream/mq_factory.go:99] ["failed to clean up subscriptions"] ["pulsar web"=http://pulsar:80] [topic=by-dev-rootcoord-dml_4] [subname=by-dev-dataNode-1192-432520058327793665] [error="Delete "http://pulsar:80/admin/v2/persistent/public/default/by-dev-rootcoord-dml_4/subscription/by-dev-dataNode-1192-432520058327793665?force=true": dial tcp 12.12.227.64:80: connect: connection refused"]time="2022-08-05T02:00:59Z" level=info msg="[Connected consumer]" consumerID=148 name=ziwtj subscription=by-dev-dataNode-1192-432520058327793665 topic="persistent://public/default/by-dev-rootcoord-dml_4"time="2022-08-05T02:00:59Z" level=info msg="[Created consumer]" consumerID=148 name=ziwtj subscription=by-dev-dataNode-1192-432520058327793665 topic="persistent://public/default/by-dev-rootcoord-dml_4"[2022/08/05 02:00:59.421 +00:00] [INFO] [msgstream/mq_msgstream.go:175] ["Successfully create consumer"] [channel=by-dev-rootcoord-dml_4] [subname=by-dev-dataNode-1192-432520058327793665]time="2022-08-05T02:00:59Z" level=info msg="The consumer[148] successfully unsubscribed" consumerID=148 name=ziwtj subscription=by-dev-dataNode-1192-432520058327793665 topic="persistent://public/default/by-dev-rootcoord-dml_4"time="2022-08-05T02:00:59Z" level=info msg="Closing consumer=148" consumerID=148 name=ziwtj subscription=by-dev-dataNode-1192-432520058327793665 topic="persistent://public/default/by-dev-rootcoord-dml_4"time="2022-08-05T02:00:59Z" level=info msg="[Closed consumer]" consumerID=148 name=ziwtj subscription=by-dev-dataNode-1192-432520058327793665 topic="persistent://public/default/by-dev-rootcoord-dml_4"[2022/08/05 02:00:59.432 +00:00] [WARN] [datacoord/channel_manager.go:806] ["failed to reassign channel to other nodes, add channel to the original node"] ["node ID"=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0][2022/08/05 02:00:59.432 +00:00] [INFO] [datacoord/channel_manager.go:816] ["channel manager reassigning channels"] ["old nodeID"=1192] [updates="["{type=Add,nodeID=1192,channels=\"[by-dev-rootcoord-dml_4_432520058327793665v0]\"}"]"][2022/08/05 02:00:59.432 +00:00] [INFO] [datacoord/handler.go:54] [GetSegmentsByChannel] [collectionID=432520058327793665] [channel=by-dev-rootcoord-dml_4_432520058327793665v0] [numOfSegments=1196][2022/08/05 02:00:59.432 +00:00] [DEBUG] [datacoord/channel_checker.go:97] ["timer started"] ["watch state"=ToWatch] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0] ["timeout time"=2022/08/05 02:01:19.432 +00:00][2022/08/05 02:01:19.432 +00:00] [INFO] [datacoord/channel_checker.go:104] ["timeout and stop timer: wait for channel ACK timeout"] ["watch state"=ToWatch] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0] ["timeout time"=2022/08/05 02:01:19.432 +00:00][2022/08/05 02:01:19.432 +00:00] [DEBUG] [datacoord/channel_manager.go:653] ["receive timeout acks from state watcher"] [state=3] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0][2022/08/05 02:01:19.432 +00:00] [INFO] [datacoord/handler.go:54] [GetSegmentsByChannel] [collectionID=432520058327793665] [channel=by-dev-rootcoord-dml_4_432520058327793665v0] [numOfSegments=1196][2022/08/05 02:01:19.433 +00:00] [DEBUG] [datacoord/channel_checker.go:97] ["timer started"] ["watch state"=ToRelease] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0] ["timeout time"=2022/08/05 02:01:39.432 +00:00][2022/08/05 02:01:33.490 +00:00] [WARN] [datacoord/server.go:576] ["time tick lag behind for more than 1 minutes"] [channel=by-dev-rootcoord-dml_4_432520058327793665v0] [timetick=2022/07/19 05:50:45.831 +00:00][2022/08/05 02:01:33.492 +00:00] [DEBUG] [datacoord/channel_checker.go:112] ["stop timer before timeout"] ["watch state"=ToRelease] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0] ["timeout time"=2022/08/05 02:01:39.432 +00:00][2022/08/05 02:01:33.493 +00:00] [WARN] [datacoord/channel_manager.go:754] ["failed to reassign channel to other nodes, assigning to the original DataNode"] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0][2022/08/05 02:01:33.493 +00:00] [INFO] [datacoord/channel_manager.go:764] ["channel manager reassigning channels"] ["old node ID"=1192] [updates="["{type=Add,nodeID=1192,channels=\"[by-dev-rootcoord-dml_4_432520058327793665v0]\"}"]"][2022/08/05 02:01:33.494 +00:00] [INFO] [datacoord/handler.go:54] [GetSegmentsByChannel] [collectionID=432520058327793665] [channel=by-dev-rootcoord-dml_4_432520058327793665v0] [numOfSegments=1196][2022/08/05 02:01:33.494 +00:00] [DEBUG] [datacoord/channel_checker.go:97] ["timer started"] ["watch state"=ToWatch] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0] ["timeout time"=2022/08/05 02:01:53.493 +00:00][2022/08/05 02:01:53.494 +00:00] [INFO] [datacoord/channel_checker.go:104] ["timeout and stop timer: wait for channel ACK timeout"] ["watch state"=ToWatch] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0] ["timeout time"=2022/08/05 02:01:53.493 +00:00][2022/08/05 02:01:53.494 +00:00] [DEBUG] [datacoord/channel_manager.go:653] ["receive timeout acks from state watcher"] [state=3] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0][2022/08/05 02:01:53.494 +00:00] [INFO] [datacoord/handler.go:54] [GetSegmentsByChannel] [collectionID=432520058327793665] [channel=by-dev-rootcoord-dml_4_432520058327793665v0] [numOfSegments=1196][2022/08/05 02:01:53.495 +00:00] [DEBUG] [datacoord/channel_checker.go:97] ["timer started"] ["watch state"=ToRelease] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0] ["timeout time"=2022/08/05 02:02:13.494 +00:00][2022/08/05 02:02:13.495 +00:00] [INFO] [datacoord/channel_checker.go:104] ["timeout and stop timer: wait for channel ACK timeout"] ["watch state"=ToRelease] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0] ["timeout time"=2022/08/05 02:02:13.494 +00:00][2022/08/05 02:02:13.495 +00:00] [DEBUG] [datacoord/channel_manager.go:653] ["receive timeout acks from state watcher"] [state=6] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0][2022/08/05 02:02:13.495 +00:00] [INFO] [msgstream/msgstream_util.go:29] ["unsubscribe channel"] [subname=by-dev-dataNode-1192-432520058327793665] [channels="[by-dev-rootcoord-dml_4]"][2022/08/05 02:02:13.499 +00:00] [WARN] [msgstream/mq_factory.go:99] ["failed to clean up subscriptions"] ["pulsar web"=http://pulsar:80] [topic=by-dev-rootcoord-dml_4] [subname=by-dev-dataNode-1192-432520058327793665] [error="Delete "http://pulsar:80/admin/v2/persistent/public/default/by-dev-rootcoord-dml_4/subscription/by-dev-dataNode-1192-432520058327793665?force=true": dial tcp 12.12.227.64:80: connect: connection refused"]time="2022-08-05T02:02:13Z" level=info msg="[Connected consumer]" consumerID=149 name=rgfal subscription=by-dev-dataNode-1192-432520058327793665 topic="persistent://public/default/by-dev-rootcoord-dml_4"time="2022-08-05T02:02:13Z" level=info msg="[Created consumer]" consumerID=149 name=rgfal subscription=by-dev-dataNode-1192-432520058327793665 topic="persistent://public/default/by-dev-rootcoord-dml_4"[2022/08/05 02:02:13.511 +00:00] [INFO] [msgstream/mq_msgstream.go:175] ["Successfully create consumer"] [channel=by-dev-rootcoord-dml_4] [subname=by-dev-dataNode-1192-432520058327793665]time="2022-08-05T02:02:13Z" level=info msg="The consumer[149] successfully unsubscribed" consumerID=149 name=rgfal subscription=by-dev-dataNode-1192-432520058327793665 topic="persistent://public/default/by-dev-rootcoord-dml_4"time="2022-08-05T02:02:13Z" level=info msg="Closing consumer=149" consumerID=149 name=rgfal subscription=by-dev-dataNode-1192-432520058327793665 topic="persistent://public/default/by-dev-rootcoord-dml_4"time="2022-08-05T02:02:13Z" level=info msg="[Closed consumer]" consumerID=149 name=rgfal subscription=by-dev-dataNode-1192-432520058327793665 topic="persistent://public/default/by-dev-rootcoord-dml_4"[2022/08/05 02:02:13.516 +00:00] [WARN] [datacoord/channel_manager.go:806] ["failed to reassign channel to other nodes, add channel to the original node"] ["node ID"=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0][2022/08/05 02:02:13.516 +00:00] [INFO] [datacoord/channel_manager.go:816] ["channel manager reassigning channels"] ["old nodeID"=1192] [updates="["{type=Add,nodeID=1192,channels=\"[by-dev-rootcoord-dml_4_432520058327793665v0]\"}"]"][2022/08/05 02:02:13.516 +00:00] [INFO] [datacoord/handler.go:54] [GetSegmentsByChannel] [collectionID=432520058327793665] [channel=by-dev-rootcoord-dml_4_432520058327793665v0] [numOfSegments=1196][2022/08/05 02:02:13.517 +00:00] [DEBUG] [datacoord/channel_checker.go:97] ["timer started"] ["watch state"=ToWatch] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0] ["timeout time"=2022/08/05 02:02:33.516 +00:00][2022/08/05 02:02:33.516 +00:00] [INFO] [datacoord/channel_checker.go:104] ["timeout and stop timer: wait for channel ACK timeout"] ["watch state"=ToWatch] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0] ["timeout time"=2022/08/05 02:02:33.516 +00:00][2022/08/05 02:02:33.517 +00:00] [DEBUG] [datacoord/channel_manager.go:653] ["receive timeout acks from state watcher"] [state=3] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0][2022/08/05 02:02:33.517 +00:00] [INFO] [datacoord/handler.go:54] [GetSegmentsByChannel] [collectionID=432520058327793665] [channel=by-dev-rootcoord-dml_4_432520058327793665v0] [numOfSegments=1196][2022/08/05 02:02:33.517 +00:00] [DEBUG] [datacoord/channel_checker.go:97] ["timer started"] ["watch state"=ToRelease] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0] ["timeout time"=2022/08/05 02:02:53.517 +00:00][2022/08/05 02:02:53.517 +00:00] [INFO] [datacoord/channel_checker.go:104] ["timeout and stop timer: wait for channel ACK timeout"] ["watch state"=ToRelease] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0] ["timeout time"=2022/08/05 02:02:53.517 +00:00][2022/08/05 02:02:53.517 +00:00] [DEBUG] [datacoord/channel_manager.go:653] ["receive timeout acks from state watcher"] [state=6] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0][2022/08/05 02:02:53.517 +00:00] [INFO] [msgstream/msgstream_util.go:29] ["unsubscribe channel"] [subname=by-dev-dataNode-1192-432520058327793665] [channels="[by-dev-rootcoord-dml_4]"][2022/08/05 02:02:53.523 +00:00] [WARN] [msgstream/mq_factory.go:99] ["failed to clean up subscriptions"] ["pulsar web"=http://pulsar:80] [topic=by-dev-rootcoord-dml_4] [subname=by-dev-dataNode-1192-432520058327793665] [error="Delete "http://pulsar:80/admin/v2/persistent/public/default/by-dev-rootcoord-dml_4/subscription/by-dev-dataNode-1192-432520058327793665?force=true": dial tcp 12.12.227.64:80: connect: connection refused"]time="2022-08-05T02:02:53Z" level=info msg="[Connected consumer]" consumerID=150 name=uwsww subscription=by-dev-dataNode-1192-432520058327793665 topic="persistent://public/default/by-dev-rootcoord-dml_4"time="2022-08-05T02:02:53Z" level=info msg="[Created consumer]" consumerID=150 name=uwsww subscription=by-dev-dataNode-1192-432520058327793665 topic="persistent://public/default/by-dev-rootcoord-dml_4"[2022/08/05 02:02:53.530 +00:00] [INFO] [msgstream/mq_msgstream.go:175] ["Successfully create consumer"] [channel=by-dev-rootcoord-dml_4] [subname=by-dev-dataNode-1192-432520058327793665]time="2022-08-05T02:02:53Z" level=info msg="The consumer[150] successfully unsubscribed" consumerID=150 name=uwsww subscription=by-dev-dataNode-1192-432520058327793665 topic="persistent://public/default/by-dev-rootcoord-dml_4"time="2022-08-05T02:02:53Z" level=info msg="Closing consumer=150" consumerID=150 name=uwsww subscription=by-dev-dataNode-1192-432520058327793665 topic="persistent://public/default/by-dev-rootcoord-dml_4"time="2022-08-05T02:02:53Z" level=info msg="[Closed consumer]" consumerID=150 name=uwsww subscription=by-dev-dataNode-1192-432520058327793665 topic="persistent://public/default/by-dev-rootcoord-dml_4"[2022/08/05 02:02:53.540 +00:00] [WARN] [datacoord/channel_manager.go:806] ["failed to reassign channel to other nodes, add channel to the original node"] ["node ID"=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0][2022/08/05 02:02:53.540 +00:00] [INFO] [datacoord/channel_manager.go:816] ["channel manager reassigning channels"] ["old nodeID"=1192] [updates="["{type=Add,nodeID=1192,channels=\"[by-dev-rootcoord-dml_4_432520058327793665v0]\"}"]"][2022/08/05 02:02:53.541 +00:00] [INFO] [datacoord/handler.go:54] [GetSegmentsByChannel] [collectionID=432520058327793665] [channel=by-dev-rootcoord-dml_4_432520058327793665v0] [numOfSegments=1196][2022/08/05 02:02:53.541 +00:00] [DEBUG] [datacoord/channel_checker.go:97] ["timer started"] ["watch state"=ToWatch] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0] ["timeout time"=2022/08/05 02:03:13.541 +00:00][2022/08/05 02:03:13.541 +00:00] [INFO] [datacoord/channel_checker.go:104] ["timeout and stop timer: wait for channel ACK timeout"] ["watch state"=ToWatch] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0] ["timeout time"=2022/08/05 02:03:13.541 +00:00][2022/08/05 02:03:13.541 +00:00] [DEBUG] [datacoord/channel_manager.go:653] ["receive timeout acks from state watcher"] [state=3] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0][2022/08/05 02:03:13.541 +00:00] [INFO] [datacoord/handler.go:54] [GetSegmentsByChannel] [collectionID=432520058327793665] [channel=by-dev-rootcoord-dml_4_432520058327793665v0] [numOfSegments=1196][2022/08/05 02:03:13.542 +00:00] [DEBUG] [datacoord/channel_checker.go:97] ["timer started"] ["watch state"=ToRelease] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0] ["timeout time"=2022/08/05 02:03:33.541 +00:00][2022/08/05 02:03:27.188 +00:00] [WARN] [datacoord/server.go:576] ["time tick lag behind for more than 1 minutes"] [channel=by-dev-rootcoord-dml_4_432520058327793665v0] [timetick=2022/07/19 05:50:45.831 +00:00][2022/08/05 02:03:27.190 +00:00] [DEBUG] [datacoord/channel_checker.go:112] ["stop timer before timeout"] ["watch state"=ToRelease] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0] ["timeout time"=2022/08/05 02:03:33.541 +00:00][2022/08/05 02:03:27.191 +00:00] [WARN] [datacoord/channel_manager.go:754] ["failed to reassign channel to other nodes, assigning to the original DataNode"] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0][2022/08/05 02:03:27.191 +00:00] [INFO] [datacoord/channel_manager.go:764] ["channel manager reassigning channels"] ["old node ID"=1192] [updates="["{type=Add,nodeID=1192,channels=\"[by-dev-rootcoord-dml_4_432520058327793665v0]\"}"]"][2022/08/05 02:03:27.191 +00:00] [INFO] [datacoord/handler.go:54] [GetSegmentsByChannel] [collectionID=432520058327793665] [channel=by-dev-rootcoord-dml_4_432520058327793665v0] [numOfSegments=1196][2022/08/05 02:03:27.192 +00:00] [DEBUG] [datacoord/channel_checker.go:97] ["timer started"] ["watch state"=ToWatch] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0] ["timeout time"=2022/08/05 02:03:47.191 +00:00][2022/08/05 02:03:47.191 +00:00] [INFO] [datacoord/channel_checker.go:104] ["timeout and stop timer: wait for channel ACK timeout"] ["watch state"=ToWatch] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0] ["timeout time"=2022/08/05 02:03:47.191 +00:00][2022/08/05 02:03:47.192 +00:00] [DEBUG] [datacoord/channel_manager.go:653] ["receive timeout acks from state watcher"] [state=3] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0][2022/08/05 02:03:47.192 +00:00] [INFO] [datacoord/handler.go:54] [GetSegmentsByChannel] [collectionID=432520058327793665] [channel=by-dev-rootcoord-dml_4_432520058327793665v0] [numOfSegments=1196][2022/08/05 02:03:47.192 +00:00] [DEBUG] [datacoord/channel_checker.go:97] ["timer started"] ["watch state"=ToRelease] [nodeID=1192] ["channel name"=by-dev-rootcoord-dml_4_432520058327793665v0] ["timeout time"=2022/08/05 02:04:07.192 +00:00]

qi49125 avatar Aug 05 '22 02:08 qi49125

@wayblink

yanliang567 avatar Aug 11 '22 06:08 yanliang567

The former part of this issue is a compatibility issue between 2.0 and 2.1. SegmentReferences' key format in etcd is changed. The problem is solved after user deleting the SegmentReferences in etcd. It is not a bug. We may need to provide Q&A guiding users upgrade Milvus from 2.0.

The following part is another issue, still uncertain. I have asked user to upload more log. I will create a new issue if need.

wayblink avatar Aug 11 '22 12:08 wayblink

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions. Rotten issues close after 30d of inactivity. Reopen the issue with /reopen.

stale[bot] avatar Sep 10 '22 14:09 stale[bot]

@wayblink any updates

yanliang567 avatar Sep 11 '22 01:09 yanliang567

@qi49125 Hi! This issue stays for a long time. We have solved the former part problem. I will close this issue. You can create a new issue if you get new problems. Thank you for feedback.

wayblink avatar Sep 13 '22 02:09 wayblink

/close

wayblink avatar Sep 13 '22 02:09 wayblink

@wayblink: Closing this issue.

In response to this:

/close

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

sre-ci-robot avatar Sep 13 '22 02:09 sre-ci-robot