[Bug]: In milvus-standalone docker container. Issue related to `goroutine`, automaticly exits with code `134` after sometime. If no collection is loaded, no problem is caused.

devasheeshG commented 8 months ago

Environment

- Milvus version: 2.3.4
- Deployment mode(standalone or cluster): standalone
- MQ type(rocksmq, pulsar or kafka):    
- SDK version(e.g. pymilvus v2.0.0rc2):
- OS(Ubuntu or CentOS): Unraid OS v6.12.6
- CPU/Memory: Ryzen5 3600x / 48GB
- GPU: 2 x Tesla P60 (but running CPU version)
- Others: Docker version 20.10.24, build 297e128 | Docker Compose version v2.21.0

Current Behavior

container milvus-standalone automatically exits after loading a collection.

Milvus Log

github.com/panjf2000/ants/v2.(goWorker).run.func1() /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:63 +0x7b fp=0xc0044d5fe0 sp=0xc0044d5f88 pc=0x3396e1b runtime.goexit() /usr/local/go/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc0044d5fe8 sp=0xc0044d5fe0 pc=0x1a609e1 created by github.com/panjf2000/ants/v2.(goWorker).run /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:48 +0x65

goroutine 9740 [chan receive, 1 minutes, locked to thread]: runtime.gopark(0x730d868?, 0x4faff38?, 0x0?, 0x0?, 0x8?) /usr/local/go/src/runtime/proc.go:381 +0xd6 fp=0xc0043cced0 sp=0xc0043cceb0 pc=0x1a2a116 runtime.chanrecv(0xc001f4c780, 0xc0043ccfa8, 0x1) /usr/local/go/src/runtime/chan.go:583 +0x49d fp=0xc0043ccf60 sp=0xc0043cced0 pc=0x19f25fd runtime.chanrecv2(0xc001ce6460?, 0xc002d59770?) /usr/local/go/src/runtime/chan.go:447 +0x18 fp=0xc0043ccf88 sp=0xc0043ccf60 pc=0x19f2138 github.com/panjf2000/ants/v2.(goWorker).run.func1() /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:63 +0x7b fp=0xc0043ccfe0 sp=0xc0043ccf88 pc=0x3396e1b runtime.goexit() /usr/local/go/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc0043ccfe8 sp=0xc0043ccfe0 pc=0x1a609e1 created by github.com/panjf2000/ants/v2.(goWorker).run /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:48 +0x65

goroutine 9741 [chan receive, 1 minutes, locked to thread]: runtime.gopark(0x730d868?, 0x4faff38?, 0x0?, 0x0?, 0x8?) /usr/local/go/src/runtime/proc.go:381 +0xd6 fp=0xc003bc1ed0 sp=0xc003bc1eb0 pc=0x1a2a116 runtime.chanrecv(0xc001f4c7e0, 0xc003bc1fa8, 0x1) /usr/local/go/src/runtime/chan.go:583 +0x49d fp=0xc003bc1f60 sp=0xc003bc1ed0 pc=0x19f25fd runtime.chanrecv2(0xc001ce6460?, 0xc002d59830?) /usr/local/go/src/runtime/chan.go:447 +0x18 fp=0xc003bc1f88 sp=0xc003bc1f60 pc=0x19f2138 github.com/panjf2000/ants/v2.(goWorker).run.func1() /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:63 +0x7b fp=0xc003bc1fe0 sp=0xc003bc1f88 pc=0x3396e1b runtime.goexit() /usr/local/go/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc003bc1fe8 sp=0xc003bc1fe0 pc=0x1a609e1 created by github.com/panjf2000/ants/v2.(goWorker).run /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:48 +0x65

goroutine 9742 [chan receive, 1 minutes, locked to thread]: runtime.gopark(0x730d868?, 0x4faff38?, 0x0?, 0x0?, 0x8?) /usr/local/go/src/runtime/proc.go:381 +0xd6 fp=0xc0033fded0 sp=0xc0033fdeb0 pc=0x1a2a116 runtime.chanrecv(0xc001f4c840, 0xc0033fdfa8, 0x1) /usr/local/go/src/runtime/chan.go:583 +0x49d fp=0xc0033fdf60 sp=0xc0033fded0 pc=0x19f25fd runtime.chanrecv2(0xc001ce6460?, 0xc002d598f0?) /usr/local/go/src/runtime/chan.go:447 +0x18 fp=0xc0033fdf88 sp=0xc0033fdf60 pc=0x19f2138 github.com/panjf2000/ants/v2.(goWorker).run.func1() /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:63 +0x7b fp=0xc0033fdfe0 sp=0xc0033fdf88 pc=0x3396e1b runtime.goexit() /usr/local/go/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc0033fdfe8 sp=0xc0033fdfe0 pc=0x1a609e1 created by github.com/panjf2000/ants/v2.(goWorker).run /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:48 +0x65

goroutine 9743 [chan receive, 1 minutes, locked to thread]: runtime.gopark(0x730d868?, 0x4faff38?, 0x0?, 0x0?, 0x8?) /usr/local/go/src/runtime/proc.go:381 +0xd6 fp=0xc002395ed0 sp=0xc002395eb0 pc=0x1a2a116 runtime.chanrecv(0xc001f4c8a0, 0xc002395fa8, 0x1) /usr/local/go/src/runtime/chan.go:583 +0x49d fp=0xc002395f60 sp=0xc002395ed0 pc=0x19f25fd runtime.chanrecv2(0xc001ce6460?, 0xc002d599b0?) /usr/local/go/src/runtime/chan.go:447 +0x18 fp=0xc002395f88 sp=0xc002395f60 pc=0x19f2138 github.com/panjf2000/ants/v2.(goWorker).run.func1() /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:63 +0x7b fp=0xc002395fe0 sp=0xc002395f88 pc=0x3396e1b runtime.goexit() /usr/local/go/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc002395fe8 sp=0xc002395fe0 pc=0x1a609e1 created by github.com/panjf2000/ants/v2.(goWorker).run /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:48 +0x65

goroutine 12460 [chan receive]: runtime.gopark(0xc00401a120?, 0xc0024bd7a8?, 0x0?, 0x0?, 0xc003dc8712?) /usr/local/go/src/runtime/proc.go:381 +0xd6 fp=0xc000594ed0 sp=0xc000594eb0 pc=0x1a2a116 runtime.chanrecv(0xc001fb7560, 0xc000594fa8, 0x1) /usr/local/go/src/runtime/chan.go:583 +0x49d fp=0xc000594f60 sp=0xc000594ed0 pc=0x19f25fd runtime.chanrecv2(0xc001065040?, 0xc0027b98f0?) /usr/local/go/src/runtime/chan.go:447 +0x18 fp=0xc000594f88 sp=0xc000594f60 pc=0x19f2138 github.com/panjf2000/ants/v2.(goWorker).run.func1() /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:63 +0x7b fp=0xc000594fe0 sp=0xc000594f88 pc=0x3396e1b runtime.goexit() /usr/local/go/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc000594fe8 sp=0xc000594fe0 pc=0x1a609e1 created by github.com/panjf2000/ants/v2.(goWorker).run /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:48 +0x65

goroutine 12663 [chan receive]: runtime.gopark(0x6332affbd4c01ff?, 0xc00276cf18?, 0x0?, 0x0?, 0xc000e91230?) /usr/local/go/src/runtime/proc.go:381 +0xd6 fp=0xc00276ced0 sp=0xc00276ceb0 pc=0x1a2a116 runtime.chanrecv(0xc001bbede0, 0xc00276cfa8, 0x1) /usr/local/go/src/runtime/chan.go:583 +0x49d fp=0xc00276cf60 sp=0xc00276ced0 pc=0x19f25fd runtime.chanrecv2(0xc0003b9220?, 0xc0056a4390?) /usr/local/go/src/runtime/chan.go:447 +0x18 fp=0xc00276cf88 sp=0xc00276cf60 pc=0x19f2138 github.com/panjf2000/ants/v2.(goWorker).run.func1() /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:63 +0x7b fp=0xc00276cfe0 sp=0xc00276cf88 pc=0x3396e1b runtime.goexit() /usr/local/go/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc00276cfe8 sp=0xc00276cfe0 pc=0x1a609e1 created by github.com/panjf2000/ants/v2.(goWorker).run /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:48 +0x65

xiaofan-luan commented 8 months ago

could you offer the full log.

All the goroutines you offers seems to be reasonable.

There might be some system signal that trigger the standalone process to stop.

devasheeshG commented 8 months ago

[2024/01/07 17:16:01.599 +00:00] [INFO] [roles/roles.go:306] ["starting running Milvus components"]
[2024/01/07 17:16:01.600 +00:00] [INFO] [roles/roles.go:169] ["Enable Jemalloc"] ["Jemalloc Path"=/milvus/lib/libjemalloc.so]
[2024/01/07 17:16:01.606 +00:00] [INFO] [config/refresher.go:66] ["start refreshing configurations"] [source=FileSource]
[2024/01/07 17:16:01.606 +00:00] [DEBUG] [config/etcd_source.go:49] ["init etcd source"] [etcdInfo="{\"UseEmbed\":false,\"UseSSL\":false,\"Endpoints\":[\"etcd:2379\"],\"KeyPrefix\":\"by-dev\",\"CertFile\":\"/path/to/etcd-client.pem\",\"KeyFile\":\"/path/to/etcd-client-key.pem\",\"CaCertFile\":\"/path/to/ca.pem\",\"MinVersion\":\"1.3\",\"RefreshInterval\":5000000000}"]
[2024/01/07 17:16:01.607 +00:00] [INFO] [etcd/etcd_util.go:47] ["create etcd client"] [useEmbedEtcd=false] [useSSL=false] [endpoints="[etcd:2379]"] [minVersion=1.3]
[2024/01/07 17:16:01.607 +00:00] [DEBUG] [config/etcd_source.go:141] ["etcd refreshConfigurations"] [prefix=by-dev/config] [endpoints="[etcd:2379]"]
[2024/01/07 17:16:02.535 +00:00] [INFO] [config/refresher.go:66] ["start refreshing configurations"] [source=EtcdSource]
[2024/01/07 17:16:02.536 +00:00] [INFO] [paramtable/hook_config.go:21] ["hook config"] [hook={}]
[2024/01/07 17:16:02.536 +00:00] [INFO] [roles/roles.go:255] [setupPrometheusHTTPServer]
[2024/01/07 17:16:02.536 +00:00] [INFO] [config/refresher.go:66] ["start refreshing configurations"] [source=FileSource]
[2024/01/07 17:16:02.536 +00:00] [INFO] [http/server.go:112] ["management listen"] [addr=:9091]
[2024/01/07 17:16:02.536 +00:00] [INFO] [rootcoord/root_coord.go:157] ["update rootcoord state"] [state=Abnormal]
[2024/01/07 17:16:02.536 +00:00] [DEBUG] [rootcoord/service.go:166] ["init params done.."]
[2024/01/07 17:16:02.536 +00:00] [INFO] [etcd/etcd_util.go:47] ["create etcd client"] [useEmbedEtcd=false] [useSSL=false] [endpoints="[etcd:2379]"] [minVersion=1.3]
[2024/01/07 17:16:02.536 +00:00] [INFO] [etcd/etcd_util.go:47] ["create etcd client"] [useEmbedEtcd=false] [useSSL=false] [endpoints="[etcd:2379]"] [minVersion=1.3]
[2024/01/07 17:16:02.536 +00:00] [DEBUG] [rootcoord/service.go:183] ["etcd connect done ..."]
[2024/01/07 17:16:02.536 +00:00] [DEBUG] [rootcoord/service.go:243] ["start grpc "] [port=53100]
[2024/01/07 17:16:02.536 +00:00] [INFO] [components/index_coord.go:38] ["IndexCoord running ..."]
[2024/01/07 17:16:02.536 +00:00] [DEBUG] [datacoord/service.go:147] ["network port"] [port=13333]
[2024/01/07 17:16:02.536 +00:00] [INFO] [etcd/etcd_util.go:47] ["create etcd client"] [useEmbedEtcd=false] [useSSL=false] [endpoints="[etcd:2379]"] [minVersion=1.3]
[2024/01/07 17:16:02.537 +00:00] [DEBUG] [querycoord/service.go:215] [network] [port=19531]
[2024/01/07 17:16:02.537 +00:00] [DEBUG] [querynode/service.go:100] [QueryNode] [port=21123]
[2024/01/07 17:16:02.537 +00:00] [INFO] [etcd/etcd_util.go:47] ["create etcd client"] [useEmbedEtcd=false] [useSSL=false] [endpoints="[etcd:2379]"] [minVersion=1.3]
[2024/01/07 17:16:02.537 +00:00] [INFO] [etcd/etcd_util.go:47] ["create etcd client"] [useEmbedEtcd=false] [useSSL=false] [endpoints="[etcd:2379]"] [minVersion=1.3]
[2024/01/07 17:16:02.537 +00:00] [DEBUG] [querynode/service.go:117] ["QueryNode connect to etcd successfully"]
[2024/01/07 17:16:02.537 +00:00] [DEBUG] [indexnode/indexnode.go:116] ["New IndexNode ..."]
[2024/01/07 17:16:02.537 +00:00] [DEBUG] [indexnode/service.go:87] [IndexNode] ["network address"=172.18.0.4:21121] ["network port: "=21121]
[2024/01/07 17:16:02.537 +00:00] [INFO] [datanode/service.go:245] ["DataNode address"] [address=172.18.0.4:21124]
[2024/01/07 17:16:02.537 +00:00] [INFO] [proxy/lb_policy.go:78] ["use look_aside policy on replica selection"]
[2024/01/07 17:16:02.537 +00:00] [INFO] [runtime/asm_amd64.s:1598] ["Start check query node health loop"]
[2024/01/07 17:16:02.537 +00:00] [DEBUG] [proxy/multi_rate_limiter.go:188] ["RateLimiter register for rateType"] [rateType=DDLIndex] [rateLimit=+inf] [burst=1.7976931348623157e+308]
[2024/01/07 17:16:02.538 +00:00] [DEBUG] [proxy/multi_rate_limiter.go:188] ["RateLimiter register for rateType"] [rateType=DDLFlush] [rateLimit=+inf] [burst=1.7976931348623157e+308]
[2024/01/07 17:16:02.538 +00:00] [DEBUG] [proxy/service.go:119] ["create a new Proxy instance"] [state=2]
[2024/01/07 17:16:02.538 +00:00] [DEBUG] [proxy/service.go:398] ["init Proxy server"]
[2024/01/07 17:16:02.538 +00:00] [DEBUG] [proxy/service.go:429] ["Proxy init service's parameter table done"]
[2024/01/07 17:16:02.538 +00:00] [DEBUG] [proxy/service.go:431] ["Proxy init http server's parameter table done"]
[2024/01/07 17:16:02.538 +00:00] [DEBUG] [proxy/service.go:438] ["init Proxy's parameter table done"] ["internal address"=172.18.0.4:19529] ["external address"=172.18.0.4:19530]
[2024/01/07 17:16:02.538 +00:00] [DEBUG] [proxy/service.go:441] ["init Proxy's tracer done"] ["service name"="Proxy ip: 172.18.0.4, port: 19530"]
[2024/01/07 17:16:02.538 +00:00] [INFO] [etcd/etcd_util.go:47] ["create etcd client"] [useEmbedEtcd=false] [useSSL=false] [endpoints="[etcd:2379]"] [minVersion=1.3]
[2024/01/07 17:16:02.538 +00:00] [INFO] [proxy/service.go:345] ["Proxy internal server listen on tcp"] [port=19529]
[2024/01/07 17:16:02.538 +00:00] [INFO] [proxy/service.go:352] ["Proxy internal server already listen on tcp"] [port=19529]
[2024/01/07 17:16:02.538 +00:00] [INFO] [proxy/service.go:384] ["create Proxy internal grpc server"] ["enforcement policy"="{\"MinTime\":5000000000,\"PermitWithoutStream\":true}"] ["server parameters"="{\"MaxConnectionIdle\":0,\"MaxConnectionAge\":0,\"MaxConnectionAgeGrace\":0,\"Time\":60000000000,\"Timeout\":10000000000}"]
[2024/01/07 17:16:02.538 +00:00] [INFO] [proxy/service.go:468] ["Proxy server listen on tcp"] [port=19530]
[2024/01/07 17:16:02.538 +00:00] [INFO] [proxy/service.go:472] ["Proxy server already listen on tcp"] [port=19530]
[2024/01/07 17:16:02.538 +00:00] [DEBUG] [proxy/service.go:242] ["Get proxy rate limiter done"] [port=19530]
[2024/01/07 17:16:02.538 +00:00] [DEBUG] [proxy/service.go:320] ["create Proxy grpc server"] ["enforcement policy"="{\"MinTime\":5000000000,\"PermitWithoutStream\":true}"] ["server parameters"="{\"MaxConnectionIdle\":0,\"MaxConnectionAge\":0,\"MaxConnectionAgeGrace\":0,\"Time\":60000000000,\"Timeout\":10000000000}"]
[2024/01/07 17:16:02.538 +00:00] [INFO] [proxy/service.go:550] ["register Proxy http server"]
[2024/01/07 17:16:02.538 +00:00] [DEBUG] [proxy/service.go:557] ["create RootCoord client for Proxy"]
[2024/01/07 17:16:02.538 +00:00] [INFO] [etcd/etcd_util.go:47] ["create etcd client"] [useEmbedEtcd=false] [useSSL=false] [endpoints="[etcd:2379]"] [minVersion=1.3]
[2024/01/07 17:16:02.538 +00:00] [DEBUG] [sessionutil/session_util.go:253] ["Session try to connect to etcd"]
[2024/01/07 17:16:02.539 +00:00] [DEBUG] [sessionutil/session_util.go:268] ["Session connect to etcd success"]
[2024/01/07 17:16:02.539 +00:00] [DEBUG] [proxy/service.go:563] ["create RootCoord client for Proxy done"]
[2024/01/07 17:16:02.539 +00:00] [DEBUG] [proxy/service.go:566] ["Proxy wait for RootCoord to be healthy"]
[2024/01/07 17:16:02.540 +00:00] [WARN] [client/client.go:89] ["RootCoordClient mess key not exist"] [key=rootcoord]
[2024/01/07 17:16:02.540 +00:00] [WARN] [grpcclient/client.go:213] ["failed to get client address"] [error="find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.540 +00:00] [WARN] [grpcclient/client.go:548] ["fail to get grpc client"] [client_role=rootcoord] [error="find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.540 +00:00] [WARN] [retry/retry.go:44] ["grpc client is nil, maybe fail to get client in the retry state"] [client_role=rootcoord] [error="empty grpc client: find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.540 +00:00] [WARN] [client/client.go:89] ["RootCoordClient mess key not exist"] [key=rootcoord]
[2024/01/07 17:16:02.540 +00:00] [WARN] [grpcclient/client.go:213] ["failed to get client address"] [error="find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.540 +00:00] [WARN] [grpcclient/client.go:471] ["fail to get grpc client in the retry state"] [client_role=rootcoord] [error="find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.540 +00:00] [ERROR] [grpcclient/client.go:462] ["retry func failed"] ["retry time"=0] [error="empty grpc client: find no available rootcoord, check rootcoord state"] [stack="github.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase[...]).call\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:462\ngithub.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase[...]).Call\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:548\ngithub.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase[...]).ReCall\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:564\ngithub.com/milvus-io/milvus/internal/distributed/rootcoord/client.wrapGrpcCall[...]\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/rootcoord/client/client.go:106\ngithub.com/milvus-io/milvus/internal/distributed/rootcoord/client.(*Client).GetComponentStates\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/rootcoord/client/client.go:120\ngithub.com/milvus-io/milvus/internal/util/componentutil.WaitForComponentStates[...].func1\n\t/go/src/github.com/milvus-io/milvus/internal/util/componentutil/componentutil.go:37\ngithub.com/milvus-io/milvus/pkg/util/retry.Do\n\t/go/src/github.com/milvus-io/milvus/pkg/util/retry/retry.go:44\ngithub.com/milvus-io/milvus/internal/util/componentutil.WaitForComponentStates[...]\n\t/go/src/github.com/milvus-io/milvus/internal/util/componentutil/componentutil.go:61\ngithub.com/milvus-io/milvus/internal/util/componentutil.WaitForComponentHealthy[...]\n\t/go/src/github.com/milvus-io/milvus/internal/util/componentutil/componentutil.go:82\ngithub.com/milvus-io/milvus/internal/distributed/proxy.(*Server).init\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/proxy/service.go:567\ngithub.com/milvus-io/milvus/internal/distributed/proxy.(*Server).Run\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/proxy/service.go:399\ngithub.com/milvus-io/milvus/cmd/components.(*Proxy).Run\n\t/go/src/github.com/milvus-io/milvus/cmd/components/proxy.go:52\ngithub.com/milvus-io/milvus/cmd/roles.runComponent[...].func1\n\t/go/src/github.com/milvus-io/milvus/cmd/roles/roles.go:115"]
[2024/01/07 17:16:02.636 +00:00] [DEBUG] [rootcoord/service.go:200] ["grpc init done ..."]
[2024/01/07 17:16:02.637 +00:00] [DEBUG] [rootcoord/service.go:203] ["RootCoord start to create DataCoord client"]
[2024/01/07 17:16:02.637 +00:00] [DEBUG] [sessionutil/session_util.go:253] ["Session try to connect to etcd"]
[2024/01/07 17:16:02.637 +00:00] [INFO] [dependency/factory.go:84] ["try to init mq"] [standalone=true] [mqType=rocksmq]
[2024/01/07 17:16:02.637 +00:00] [DEBUG] [server/global_rmq.go:39] ["initializing global rmq"] [path=/var/lib/milvus/rdb_data]
[2024/01/07 17:16:02.637 +00:00] [DEBUG] [sessionutil/session_util.go:253] ["Session try to connect to etcd"]
[2024/01/07 17:16:02.637 +00:00] [DEBUG] [server/rocksmq_impl.go:177] ["Start rocksmq "] ["max proc"=12] [parallism=2] ["lru cache"=2015273533]
[2024/01/07 17:16:02.637 +00:00] [DEBUG] [querynode/service.go:127] [QueryNode] [State=Initializing]
[2024/01/07 17:16:02.637 +00:00] [INFO] [querynodev2/server.go:267] ["QueryNode session info"] [metaPath=by-dev/meta]
[2024/01/07 17:16:02.637 +00:00] [DEBUG] [sessionutil/session_util.go:253] ["Session try to connect to etcd"]
[2024/01/07 17:16:02.637 +00:00] [DEBUG] [sessionutil/session_util.go:268] ["Session connect to etcd success"]
[2024/01/07 17:16:02.637 +00:00] [DEBUG] [sessionutil/session_util.go:268] ["Session connect to etcd success"]
[2024/01/07 17:16:02.637 +00:00] [INFO] [etcd/etcd_util.go:47] ["create etcd client"] [useEmbedEtcd=false] [useSSL=false] [endpoints="[etcd:2379]"] [minVersion=1.3]
[2024/01/07 17:16:02.637 +00:00] [DEBUG] [querycoord/service.go:165] ["QueryCoord try to wait for RootCoord ready"]
[2024/01/07 17:16:02.637 +00:00] [DEBUG] [rootcoord/service.go:212] ["RootCoord start to create QueryCoord client"]
[2024/01/07 17:16:02.637 +00:00] [INFO] [datanode/service.go:254] ["initializing RootCoord client for DataNode"]
[2024/01/07 17:16:02.637 +00:00] [DEBUG] [sessionutil/session_util.go:253] ["Session try to connect to etcd"]
[2024/01/07 17:16:02.638 +00:00] [DEBUG] [sessionutil/session_util.go:253] ["Session try to connect to etcd"]
[2024/01/07 17:16:02.638 +00:00] [WARN] [client/client.go:89] ["RootCoordClient mess key not exist"] [key=rootcoord]
[2024/01/07 17:16:02.638 +00:00] [DEBUG] [sessionutil/session_util.go:268] ["Session connect to etcd success"]
[2024/01/07 17:16:02.638 +00:00] [WARN] [grpcclient/client.go:213] ["failed to get client address"] [error="find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.638 +00:00] [DEBUG] [sessionutil/session_util.go:268] ["Session connect to etcd success"]
[2024/01/07 17:16:02.638 +00:00] [DEBUG] [sessionutil/session_util.go:268] ["Session connect to etcd success"]
[2024/01/07 17:16:02.638 +00:00] [WARN] [grpcclient/client.go:548] ["fail to get grpc client"] [client_role=rootcoord] [error="find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.638 +00:00] [INFO] [dependency/factory.go:84] ["try to init mq"] [standalone=true] [mqType=rocksmq]
[2024/01/07 17:16:02.638 +00:00] [INFO] [indexnode/indexnode.go:207] ["IndexNode init"] [state=Initializing]
[2024/01/07 17:16:02.638 +00:00] [DEBUG] [sessionutil/session_util.go:253] ["Session try to connect to etcd"]
[2024/01/07 17:16:02.638 +00:00] [WARN] [retry/retry.go:44] ["grpc client is nil, maybe fail to get client in the retry state"] [client_role=rootcoord] [error="empty grpc client: find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.642 +00:00] [DEBUG] [sessionutil/session_util.go:268] ["Session connect to etcd success"]
[2024/01/07 17:16:02.642 +00:00] [WARN] [client/client.go:89] ["RootCoordClient mess key not exist"] [key=rootcoord]
[2024/01/07 17:16:02.642 +00:00] [WARN] [client/client.go:89] ["RootCoordClient mess key not exist"] [key=rootcoord]
[2024/01/07 17:16:02.642 +00:00] [WARN] [grpcclient/client.go:213] ["failed to get client address"] [error="find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.642 +00:00] [WARN] [grpcclient/client.go:548] ["fail to get grpc client"] [client_role=rootcoord] [error="find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.642 +00:00] [DEBUG] [sessionutil/session_util.go:311] [getServerID] [reuse=true]
[2024/01/07 17:16:02.642 +00:00] [WARN] [grpcclient/client.go:213] ["failed to get client address"] [error="find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.642 +00:00] [WARN] [retry/retry.go:44] ["grpc client is nil, maybe fail to get client in the retry state"] [client_role=rootcoord] [error="empty grpc client: find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.642 +00:00] [WARN] [grpcclient/client.go:471] ["fail to get grpc client in the retry state"] [client_role=rootcoord] [error="find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.642 +00:00] [ERROR] [grpcclient/client.go:462] ["retry func failed"] ["retry time"=0] [error="empty grpc client: find no available rootcoord, check rootcoord state"] [stack="github.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase[...]).call\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:462\ngithub.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase[...]).Call\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:548\ngithub.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase[...]).ReCall\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:564\ngithub.com/milvus-io/milvus/internal/distributed/rootcoord/client.wrapGrpcCall[...]\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/rootcoord/client/client.go:106\ngithub.com/milvus-io/milvus/internal/distributed/rootcoord/client.(*Client).GetComponentStates\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/rootcoord/client/client.go:120\ngithub.com/milvus-io/milvus/internal/util/componentutil.WaitForComponentStates[...].func1\n\t/go/src/github.com/milvus-io/milvus/internal/util/componentutil/componentutil.go:37\ngithub.com/milvus-io/milvus/pkg/util/retry.Do\n\t/go/src/github.com/milvus-io/milvus/pkg/util/retry/retry.go:44\ngithub.com/milvus-io/milvus/internal/util/componentutil.WaitForComponentStates[...]\n\t/go/src/github.com/milvus-io/milvus/internal/util/componentutil/componentutil.go:61\ngithub.com/milvus-io/milvus/internal/util/componentutil.WaitForComponentHealthy[...]\n\t/go/src/github.com/milvus-io/milvus/internal/util/componentutil/componentutil.go:82\ngithub.com/milvus-io/milvus/internal/distributed/querycoord.(*Server).init\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/querycoord/service.go:166\ngithub.com/milvus-io/milvus/internal/distributed/querycoord.(*Server).Run\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/querycoord/service.go:100\ngithub.com/milvus-io/milvus/cmd/components.(*QueryCoord).Run\n\t/go/src/github.com/milvus-io/milvus/cmd/components/query_coord.go:53\ngithub.com/milvus-io/milvus/cmd/roles.runComponent[...].func1\n\t/go/src/github.com/milvus-io/milvus/cmd/roles/roles.go:115"]
[2024/01/07 17:16:02.646 +00:00] [WARN] [client/client.go:89] ["RootCoordClient mess key not exist"] [key=rootcoord]
[2024/01/07 17:16:02.646 +00:00] [WARN] [grpcclient/client.go:213] ["failed to get client address"] [error="find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.646 +00:00] [WARN] [grpcclient/client.go:471] ["fail to get grpc client in the retry state"] [client_role=rootcoord] [error="find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.646 +00:00] [ERROR] [grpcclient/client.go:462] ["retry func failed"] ["retry time"=0] [error="empty grpc client: find no available rootcoord, check rootcoord state"] [stack="github.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase[...]).call\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:462\ngithub.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase[...]).Call\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:548\ngithub.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase[...]).ReCall\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:564\ngithub.com/milvus-io/milvus/internal/distributed/rootcoord/client.wrapGrpcCall[...]\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/rootcoord/client/client.go:106\ngithub.com/milvus-io/milvus/internal/distributed/rootcoord/client.(*Client).GetComponentStates\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/rootcoord/client/client.go:120\ngithub.com/milvus-io/milvus/internal/util/componentutil.WaitForComponentStates[...].func1\n\t/go/src/github.com/milvus-io/milvus/internal/util/componentutil/componentutil.go:37\ngithub.com/milvus-io/milvus/pkg/util/retry.Do\n\t/go/src/github.com/milvus-io/milvus/pkg/util/retry/retry.go:44\ngithub.com/milvus-io/milvus/internal/util/componentutil.WaitForComponentStates[...]\n\t/go/src/github.com/milvus-io/milvus/internal/util/componentutil/componentutil.go:61\ngithub.com/milvus-io/milvus/internal/util/componentutil.WaitForComponentHealthy[...]\n\t/go/src/github.com/milvus-io/milvus/internal/util/componentutil/componentutil.go:82\ngithub.com/milvus-io/milvus/internal/distributed/datanode.(*Server).init\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datanode/service.go:261\ngithub.com/milvus-io/milvus/internal/distributed/datanode.(*Server).Run\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datanode/service.go:187\ngithub.com/milvus-io/milvus/cmd/components.(*DataNode).Run\n\t/go/src/github.com/milvus-io/milvus/cmd/components/data_node.go:53\ngithub.com/milvus-io/milvus/cmd/roles.runComponent[...].func1\n\t/go/src/github.com/milvus-io/milvus/cmd/roles/roles.go:115"]
[2024/01/07 17:16:02.650 +00:00] [DEBUG] [sessionutil/session_util.go:369] ["Session get serverID success"] [key=id] [ServerId=17]
[2024/01/07 17:16:02.650 +00:00] [INFO] [sessionutil/session_util.go:285] ["start server"] [name=querynode] [address=172.18.0.4:21123] [id=17]
[2024/01/07 17:16:02.650 +00:00] [DEBUG] [sessionutil/session_util.go:311] [getServerID] [reuse=true]
[2024/01/07 17:16:02.650 +00:00] [INFO] [sessionutil/session_util.go:1216] ["save server info into file"] [content="querynode-17\n"] [filePath=/tmp/milvus/server_id_8]
[2024/01/07 17:16:02.650 +00:00] [INFO] [sessionutil/session_util.go:285] ["start server"] [name=indexnode] [address=172.18.0.4:21121] [id=17]
[2024/01/07 17:16:02.650 +00:00] [INFO] [querynodev2/server.go:160] ["QueryNode init session"] [nodeID=17] ["node address"=172.18.0.4:21123]
[2024/01/07 17:16:02.650 +00:00] [INFO] [dependency/factory.go:84] ["try to init mq"] [standalone=true] [mqType=rocksmq]
[2024/01/07 17:16:02.650 +00:00] [INFO] [sessionutil/session_util.go:1216] ["save server info into file"] [content="indexnode-17\n"] [filePath=/tmp/milvus/server_id_8]
[2024/01/07 17:16:02.650 +00:00] [INFO] [indexnode/indexnode.go:214] ["IndexNode init session successful"] [serverID=17]
I20240107 17:16:02.650751    28 knowhere_config.cc:63] [KNOWHERE][SetSimdType][milvus] FAISS expect simdType::AUTO
I20240107 17:16:02.650768    28 knowhere_config.cc:88] [KNOWHERE][SetSimdType][milvus] FAISS hook AVX2
I20240107 17:16:02.650813    28 Common.cpp:41] [SEGCORE][SetHighPriorityThreadCoreCoefficient][milvus] set high priority thread pool core coefficient: 10
I20240107 17:16:02.650842    28 Common.cpp:48] [SEGCORE][SetMiddlePriorityThreadCoreCoefficient][milvus] set middle priority thread pool core coefficient: 5
I20240107 17:16:02.650854    28 Common.cpp:55] [SEGCORE][SetLowPriorityThreadCoreCoefficient][milvus] set low priority thread pool core coefficient: 1
W20240107 17:16:02.650872    28 thread_pool.h:116] [KNOWHERE][InitGlobalBuildThreadPool][milvus] Global Build ThreadPool has already been initialized with threads num: 12
[2024/01/07 17:16:02.650 +00:00] [INFO] [indexnode/indexnode.go:219] ["init indexnode done"] [nodeID=17] [Address=172.18.0.4:21121]
[2024/01/07 17:16:02.650 +00:00] [DEBUG] [indexnode/service.go:74] ["IndexNode init done ..."]
[2024/01/07 17:16:02.650 +00:00] [INFO] [indexnode/indexnode.go:230] [IndexNode] [State=Healthy]
[2024/01/07 17:16:02.650 +00:00] [INFO] [indexnode/indexnode.go:233] ["IndexNode start finished"] []
[2024/01/07 17:16:02.650 +00:00] [DEBUG] [sessionutil/session_util.go:432] ["service begin to register to etcd"] [serverName=indexnode] [ServerID=17]
[2024/01/07 17:16:02.651 +00:00] [DEBUG] [indexnode/task_scheduler.go:242] ["IndexNode TaskScheduler start build loop ..."]
[2024/01/07 17:16:02.659 +00:00] [INFO] [sessionutil/session_util.go:462] ["put session key into etcd"] [key=by-dev/meta/session/indexnode-17] [value="{\"ServerID\":17,\"ServerName\":\"indexnode\",\"Address\":\"172.18.0.4:21121\",\"TriggerKill\":true,\"Version\":\"2.3.4\",\"IndexEngineVersion\":{},\"LeaseID\":7587875862039163667,\"HostName\":\"2de1263f898b\",\"EnableDisk\":true}"]
[2024/01/07 17:16:02.659 +00:00] [INFO] [sessionutil/session_util.go:472] ["Service registered successfully"] [ServerName=indexnode] [serverID=17]
[2024/01/07 17:16:02.660 +00:00] [DEBUG] [indexnode/service.go:206] ["IndexNode Register etcd success"]
[2024/01/07 17:16:02.660 +00:00] [DEBUG] [indexnode/service.go:78] ["IndexNode start done ..."]
[2024/01/07 17:16:02.660 +00:00] [DEBUG] [components/index_node.go:55] ["IndexNode successfully started"]
[2024/01/07 17:16:02.725 +00:00] [INFO] [tso/tso.go:122] ["sync and save timestamp"] [last=2024/01/07 15:01:26.682 +00:00] [save=2024/01/07 17:16:05.725 +00:00] [next=2024/01/07 17:16:02.725 +00:00]
[2024/01/07 17:16:02.725 +00:00] [INFO] [msgstream/mq_factory.go:18] ["init rocksmq msgstream success"] [path=/var/lib/milvus/rdb_data]
[2024/01/07 17:16:02.725 +00:00] [DEBUG] [sessionutil/session_util.go:253] ["Session try to connect to etcd"]
[2024/01/07 17:16:02.725 +00:00] [DEBUG] [server/rocksmq_retention.go:80] ["Rocksmq retention goroutine start!"]
[2024/01/07 17:16:02.725 +00:00] [INFO] [msgstream/mq_factory.go:18] ["init rocksmq msgstream success"] [path=/var/lib/milvus/rdb_data]
[2024/01/07 17:16:02.725 +00:00] [DEBUG] [sessionutil/session_util.go:253] ["Session try to connect to etcd"]
[2024/01/07 17:16:02.725 +00:00] [INFO] [msgstream/mq_factory.go:18] ["init rocksmq msgstream success"] [path=/var/lib/milvus/rdb_data]
[2024/01/07 17:16:02.726 +00:00] [DEBUG] [sessionutil/session_util.go:268] ["Session connect to etcd success"]
[2024/01/07 17:16:02.726 +00:00] [DEBUG] [sessionutil/session_util.go:268] ["Session connect to etcd success"]
[2024/01/07 17:16:02.728 +00:00] [INFO] [storage/remote_chunk_manager.go:83] ["remote chunk manager init success."] [remote=aws] [bucketname=a-bucket] [root=files]
[2024/01/07 17:16:02.729 +00:00] [INFO] [storage/remote_chunk_manager.go:83] ["remote chunk manager init success."] [remote=aws] [bucketname=a-bucket] [root=files]
[2024/01/07 17:16:02.729 +00:00] [INFO] [querynodev2/server.go:321] ["queryNode try to connect etcd success"] [MetaRootPath=by-dev/meta]
[2024/01/07 17:16:02.729 +00:00] [INFO] [tasks/concurrent_safe_scheduler.go:27] ["query node use concurrent safe scheduler"] [max_concurrency=12]
[2024/01/07 17:16:02.729 +00:00] [INFO] [querynodev2/server.go:327] ["queryNode init scheduler"] [policy=fifo]
[2024/01/07 17:16:02.729 +00:00] [INFO] [segments/segment_loader.go:117] ["SegmentLoader created"] [ioPoolSize=96]
W20240107 17:16:02.729643    27 thread_pool.h:128] [KNOWHERE][InitGlobalSearchThreadPool][milvus] Global Search ThreadPool has already been initialized with threads num: 12
I20240107 17:16:02.729707    27 knowhere_config.cc:63] [KNOWHERE][SetSimdType][milvus] FAISS expect simdType::AUTO
I20240107 17:16:02.729720    27 knowhere_config.cc:88] [KNOWHERE][SetSimdType][milvus] FAISS hook AVX2
I20240107 17:16:02.729807    27 MinioChunkManager.cpp:158] [SEGCORE][InitSDKAPIDefault][milvus] init aws with log level:fatal
[2024/01/07 17:16:02.730 +00:00] [DEBUG] [sessionutil/session_util.go:311] [getServerID] [reuse=true]
[2024/01/07 17:16:02.730 +00:00] [INFO] [sessionutil/session_util.go:285] ["start server"] [name=indexcoord] [address=172.18.0.4:13333] [id=17]
[2024/01/07 17:16:02.731 +00:00] [DEBUG] [sessionutil/session_util.go:253] ["Session try to connect to etcd"]
[2024/01/07 17:16:02.740 +00:00] [DEBUG] [sessionutil/session_util.go:311] [getServerID] [reuse=true]
[2024/01/07 17:16:02.740 +00:00] [INFO] [sessionutil/session_util.go:285] ["start server"] [name=rootcoord] [address=172.18.0.4:53100] [id=17]
[2024/01/07 17:16:02.740 +00:00] [INFO] [rootcoord/root_coord.go:157] ["update rootcoord state"] [state=Initializing]
[2024/01/07 17:16:02.740 +00:00] [DEBUG] [sessionutil/session_util.go:268] ["Session connect to etcd success"]
[2024/01/07 17:16:02.741 +00:00] [WARN] [retry/retry.go:44] ["grpc client is nil, maybe fail to get client in the retry state"] [client_role=rootcoord] [error="empty grpc client: find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.745 +00:00] [WARN] [client/client.go:89] ["RootCoordClient mess key not exist"] [key=rootcoord]
[2024/01/07 17:16:02.745 +00:00] [WARN] [grpcclient/client.go:213] ["failed to get client address"] [error="find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.745 +00:00] [WARN] [grpcclient/client.go:471] ["fail to get grpc client in the retry state"] [client_role=rootcoord] [error="find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.745 +00:00] [DEBUG] [sessionutil/session_util.go:311] [getServerID] [reuse=true]
[2024/01/07 17:16:02.745 +00:00] [INFO] [sessionutil/session_util.go:285] ["start server"] [name=datacoord] [address=172.18.0.4:13333] [id=17]
[2024/01/07 17:16:02.745 +00:00] [DEBUG] [sessionutil/session_util.go:253] ["Session try to connect to etcd"]
[2024/01/07 17:16:02.749 +00:00] [DEBUG] [sessionutil/session_util.go:268] ["Session connect to etcd success"]
[2024/01/07 17:16:02.750 +00:00] [INFO] [datacoord/server.go:335] ["init rootcoord client done"]
[2024/01/07 17:16:02.750 +00:00] [INFO] [tso/tso.go:122] ["sync and save timestamp"] [last=2024/01/07 15:01:26.692 +00:00] [save=2024/01/07 17:16:05.745 +00:00] [next=2024/01/07 17:16:02.745 +00:00]
[2024/01/07 17:16:02.750 +00:00] [INFO] [rootcoord/root_coord.go:402] ["id allocator initialized"] [root_path=by-dev/kv] [sub_path=gid] [key=idTimestamp]
[2024/01/07 17:16:02.751 +00:00] [INFO] [sessionutil/session_util.go:908] ["register session success"] [role=indexnode] [key=by-dev/meta/session/indexnode-17]
[2024/01/07 17:16:02.752 +00:00] [INFO] [storage/remote_chunk_manager.go:83] ["remote chunk manager init success."] [remote=aws] [bucketname=a-bucket] [root=files]
[2024/01/07 17:16:02.752 +00:00] [INFO] [datacoord/server.go:343] ["init chunk manager factory done"]
[2024/01/07 17:16:02.752 +00:00] [INFO] [datacoord/server.go:570] ["data coordinator connecting to metadata store"] [metaType=etcd]
[2024/01/07 17:16:02.752 +00:00] [INFO] [datacoord/server.go:583] ["data coordinator successfully connected to metadata store"] [metaType=etcd]
[2024/01/07 17:16:02.753 +00:00] [INFO] [tso/tso.go:122] ["sync and save timestamp"] [last=2024/01/07 15:02:50.732 +00:00] [save=2024/01/07 17:16:05.750 +00:00] [next=2024/01/07 17:16:02.750 +00:00]
[2024/01/07 17:16:02.753 +00:00] [INFO] [rootcoord/root_coord.go:426] ["tso allocator initialized"] [root_path=by-dev/kv] [sub_path=gid] [key=idTimestamp]
[2024/01/07 17:16:02.753 +00:00] [INFO] [rootcoord/root_coord.go:345] ["Using etcd as meta storage."]
[2024/01/07 17:16:02.753 +00:00] [DEBUG] [rootcoord/suffix_snapshot.go:555] ["suffix snapshot GC goroutine start!"]
[2024/01/07 17:16:02.754 +00:00] [INFO] [rootcoord/meta_table.go:150] ["recover databases"] ["num of dbs"=2]
[2024/01/07 17:16:02.755 +00:00] [INFO] [datacoord/meta.go:175] ["DataCoord meta reloadFromKV done"] [duration=3.322599ms]
[2024/01/07 17:16:02.755 +00:00] [INFO] [datacoord/server.go:1171] ["all old data node down, enable auto balance!"]
[2024/01/07 17:16:02.756 +00:00] [INFO] [datacoord/channel_store.go:268] ["channel store reload channel"] [nodeID=16] [channel=by-dev-rootcoord-dml_0_446748065920713215v0]
[2024/01/07 17:16:02.756 +00:00] [INFO] [datacoord/channel_store.go:272] ["channel store reload done"] [duration=495.272µs]
[2024/01/07 17:16:02.756 +00:00] [INFO] [datacoord/server.go:357] ["init datanode cluster done"]
[2024/01/07 17:16:02.756 +00:00] [INFO] [rootcoord/meta_table.go:188] ["recover collections from db"] [collection_num=1] [partition_num=1]
[2024/01/07 17:16:02.756 +00:00] [INFO] [datacoord/server.go:502] ["DataCoord success to get DataNode sessions"] [sessions={}]
[2024/01/07 17:16:02.756 +00:00] [INFO] [msgstream/msgstream_util.go:33] ["unsubscribe channel"] [subname=by-dev-dataNode-16-by-dev-rootcoord-dml_0_446748065920713215v0] [channels="[by-dev-rootcoord-dml_0]"]
[2024/01/07 17:16:02.756 +00:00] [INFO] [msgstream/common_mq_factory.go:31] ["Msg Stream state"] [can_produce=true]
[2024/01/07 17:16:02.757 +00:00] [DEBUG] [server/rocksmq_impl.go:520] ["Rocksmq create consumer group successfully "] [topic=by-dev-rootcoord-dml_0] [group=by-dev-dataNode-16-by-dev-rootcoord-dml_0_446748065920713215v0] [elapsed=0]
[2024/01/07 17:16:02.757 +00:00] [DEBUG] [server/rocksmq_impl.go:546] ["Rocksmq register consumer successfully "] [topic=by-dev-rootcoord-dml_0] [elapsed=0]
[2024/01/07 17:16:02.757 +00:00] [INFO] [msgstream/mq_msgstream.go:206] ["Successfully create consumer"] [channel=by-dev-rootcoord-dml_0] [subname=by-dev-dataNode-16-by-dev-rootcoord-dml_0_446748065920713215v0]
[2024/01/07 17:16:02.757 +00:00] [INFO] [msgstream/mq_msgstream.go:216] ["start to close mq msg stream"] ["producer num"=0] ["consumer num"=1]
[2024/01/07 17:16:02.758 +00:00] [INFO] [rootcoord/meta_table.go:204] ["RootCoord meta table reload done"] [duration=4.72769ms]
[2024/01/07 17:16:02.758 +00:00] [INFO] [msgstream/common_mq_factory.go:31] ["Msg Stream state"] [can_produce=true]
[2024/01/07 17:16:02.758 +00:00] [INFO] [datacoord/channel_manager.go:384] ["deregister node"] [nodeID=16] [updates="[\"{type=Delete,nodeID=16,channels=\\\"[by-dev-rootcoord-dml_0_446748065920713215v0]\\\"}\",\"{type=Add,nodeID=-9223372036854775808,channels=\\\"[by-dev-rootcoord-dml_0_446748065920713215v0]\\\"}\"]"]
[2024/01/07 17:16:02.758 +00:00] [INFO] [datacoord/channel_manager.go:397] ["remove timers for channel of the deregistered node"] [channels="[by-dev-rootcoord-dml_0_446748065920713215v0]"] [nodeID=16]
[2024/01/07 17:16:02.758 +00:00] [INFO] [datacoord/handler.go:62] [GetDataVChanPositions] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [numOfSegments=1]
[2024/01/07 17:16:02.758 +00:00] [INFO] [datacoord/handler.go:299] ["channel seek position set from channel checkpoint meta"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [posTs=446840488061042689] [posTime=2024/01/06 17:13:07.977 +00:00]
[2024/01/07 17:16:02.758 +00:00] [WARN] [server/rocksmq_impl.go:398] ["rocksmq topic already exists "] [topic=by-dev-rootcoord-dml_0]
[2024/01/07 17:16:02.758 +00:00] [INFO] [msgstream/common_mq_factory.go:31] ["Msg Stream state"] [can_produce=true]
[2024/01/07 17:16:02.758 +00:00] [WARN] [server/rocksmq_impl.go:398] ["rocksmq topic already exists "] [topic=by-dev-rootcoord-dml_1]
[2024/01/07 17:16:02.758 +00:00] [INFO] [msgstream/common_mq_factory.go:31] ["Msg Stream state"] [can_produce=true]
[2024/01/07 17:16:02.758 +00:00] [WARN] [server/rocksmq_impl.go:398] ["rocksmq topic already exists "] [topic=by-dev-rootcoord-dml_2]
[2024/01/07 17:16:02.758 +00:00] [INFO] [msgstream/common_mq_factory.go:31] ["Msg Stream state"] [can_produce=true]
[2024/01/07 17:16:02.759 +00:00] [WARN] [server/rocksmq_impl.go:398] ["rocksmq topic already exists "] [topic=by-dev-rootcoord-dml_3]
[2024/01/07 17:16:02.759 +00:00] [INFO] [msgstream/common_mq_factory.go:31] ["Msg Stream state"] [can_produce=true]
[2024/01/07 17:16:02.759 +00:00] [WARN] [server/rocksmq_impl.go:398] ["rocksmq topic already exists "] [topic=by-dev-rootcoord-dml_4]
[2024/01/07 17:16:02.759 +00:00] [INFO] [msgstream/common_mq_factory.go:31] ["Msg Stream state"] [can_produce=true]
[2024/01/07 17:16:02.759 +00:00] [WARN] [server/rocksmq_impl.go:398] ["rocksmq topic already exists "] [topic=by-dev-rootcoord-dml_5]
[2024/01/07 17:16:02.759 +00:00] [INFO] [msgstream/common_mq_factory.go:31] ["Msg Stream state"] [can_produce=true]
[2024/01/07 17:16:02.759 +00:00] [WARN] [server/rocksmq_impl.go:398] ["rocksmq topic already exists "] [topic=by-dev-rootcoord-dml_6]
[2024/01/07 17:16:02.759 +00:00] [INFO] [msgstream/common_mq_factory.go:31] ["Msg Stream state"] [can_produce=true]
[2024/01/07 17:16:02.759 +00:00] [WARN] [server/rocksmq_impl.go:398] ["rocksmq topic already exists "] [topic=by-dev-rootcoord-dml_7]
[2024/01/07 17:16:02.759 +00:00] [INFO] [msgstream/common_mq_factory.go:31] ["Msg Stream state"] [can_produce=true]
[2024/01/07 17:16:02.759 +00:00] [WARN] [server/rocksmq_impl.go:398] ["rocksmq topic already exists "] [topic=by-dev-rootcoord-dml_8]
[2024/01/07 17:16:02.759 +00:00] [INFO] [msgstream/common_mq_factory.go:31] ["Msg Stream state"] [can_produce=true]
[2024/01/07 17:16:02.759 +00:00] [WARN] [server/rocksmq_impl.go:398] ["rocksmq topic already exists "] [topic=by-dev-rootcoord-dml_9]
[2024/01/07 17:16:02.759 +00:00] [INFO] [msgstream/common_mq_factory.go:31] ["Msg Stream state"] [can_produce=true]
[2024/01/07 17:16:02.759 +00:00] [WARN] [server/rocksmq_impl.go:398] ["rocksmq topic already exists "] [topic=by-dev-rootcoord-dml_10]
[2024/01/07 17:16:02.759 +00:00] [INFO] [msgstream/common_mq_factory.go:31] ["Msg Stream state"] [can_produce=true]
[2024/01/07 17:16:02.759 +00:00] [WARN] [server/rocksmq_impl.go:398] ["rocksmq topic already exists "] [topic=by-dev-rootcoord-dml_11]
[2024/01/07 17:16:02.759 +00:00] [INFO] [msgstream/common_mq_factory.go:31] ["Msg Stream state"] [can_produce=true]
[2024/01/07 17:16:02.759 +00:00] [WARN] [server/rocksmq_impl.go:398] ["rocksmq topic already exists "] [topic=by-dev-rootcoord-dml_12]
[2024/01/07 17:16:02.759 +00:00] [INFO] [msgstream/common_mq_factory.go:31] ["Msg Stream state"] [can_produce=true]
[2024/01/07 17:16:02.759 +00:00] [WARN] [server/rocksmq_impl.go:398] ["rocksmq topic already exists "] [topic=by-dev-rootcoord-dml_13]
[2024/01/07 17:16:02.759 +00:00] [INFO] [msgstream/common_mq_factory.go:31] ["Msg Stream state"] [can_produce=true]
[2024/01/07 17:16:02.759 +00:00] [WARN] [server/rocksmq_impl.go:398] ["rocksmq topic already exists "] [topic=by-dev-rootcoord-dml_14]
[2024/01/07 17:16:02.759 +00:00] [INFO] [msgstream/common_mq_factory.go:31] ["Msg Stream state"] [can_produce=true]
[2024/01/07 17:16:02.759 +00:00] [WARN] [server/rocksmq_impl.go:398] ["rocksmq topic already exists "] [topic=by-dev-rootcoord-dml_15]
[2024/01/07 17:16:02.759 +00:00] [INFO] [rootcoord/dml_channels.go:215] ["init dml channels"] [prefix=by-dev-rootcoord-dml] [num=16]
[2024/01/07 17:16:02.759 +00:00] [INFO] [rootcoord/timeticksync.go:126] ["recover physical channels"] [collectionID=446748065920713215] ["physical channels"="[by-dev-rootcoord-dml_0]"]
[2024/01/07 17:16:02.759 +00:00] [INFO] [rootcoord/root_coord.go:476] ["create TimeTick sync done"]
[2024/01/07 17:16:02.759 +00:00] [INFO] [rootcoord/root_coord.go:493] ["init proxy manager done"]
[2024/01/07 17:16:02.759 +00:00] [DEBUG] [rootcoord/root_coord.go:498] ["RootCoord init QuotaCenter done"]
[2024/01/07 17:16:02.762 +00:00] [INFO] [rootcoord/root_coord.go:503] ["init import manager done"]
[2024/01/07 17:16:02.762 +00:00] [INFO] [rootcoord/root_coord.go:508] ["init credentials done"]
[2024/01/07 17:16:02.766 +00:00] [INFO] [rootcoord/meta_table.go:1240] ["role already exists"] [role=admin]
[2024/01/07 17:16:02.766 +00:00] [INFO] [datacoord/channel_manager.go:156] ["starting etcd states checker"]
[2024/01/07 17:16:02.766 +00:00] [INFO] [datacoord/channel_manager.go:161] ["starting background balance checker"]
[2024/01/07 17:16:02.766 +00:00] [INFO] [datacoord/channel_manager.go:164] ["cluster start up"] [nodes="[]"] [oNodes="[16]"] ["old onlines"="[]"] ["new onlines"="[]"] [offLines="[16]"]
[2024/01/07 17:16:02.767 +00:00] [DEBUG] [sessionutil/session_util.go:615] ["SessionUtil GetSessions"] [prefix=indexnode] [key=indexnode-17] [address=172.18.0.4:21121]
[2024/01/07 17:16:02.767 +00:00] [DEBUG] [datacoord/indexnode_manager.go:83] ["add IndexNode"] [nodeID=17] ["node address"=172.18.0.4:21121]
[2024/01/07 17:16:02.767 +00:00] [DEBUG] [sessionutil/session_util.go:253] ["Session try to connect to etcd"]
[2024/01/07 17:16:02.767 +00:00] [DEBUG] [sessionutil/session_util.go:268] ["Session connect to etcd success"]
[2024/01/07 17:16:02.767 +00:00] [INFO] [rootcoord/meta_table.go:1240] ["role already exists"] [role=public]
[2024/01/07 17:16:02.767 +00:00] [DEBUG] [datacoord/indexnode_manager.go:56] ["set IndexNode client"] [nodeID=17]
[2024/01/07 17:16:02.767 +00:00] [DEBUG] [datacoord/indexnode_manager.go:61] ["IndexNode IndexNodeManager setClient success"] [nodeID=17] ["IndexNode num"=1]
[2024/01/07 17:16:02.768 +00:00] [INFO] [datacoord/server.go:366] ["init service discovery done"]
[2024/01/07 17:16:02.768 +00:00] [INFO] [datacoord/server.go:371] ["init compaction scheduler done"]
[2024/01/07 17:16:02.769 +00:00] [WARN] [client/client.go:89] ["RootCoordClient mess key not exist"] [key=rootcoord]
[2024/01/07 17:16:02.769 +00:00] [WARN] [grpcclient/client.go:213] ["failed to get client address"] [error="find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.769 +00:00] [WARN] [grpcclient/client.go:548] ["fail to get grpc client"] [client_role=rootcoord] [error="find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.769 +00:00] [WARN] [retry/retry.go:44] ["grpc client is nil, maybe fail to get client in the retry state"] [client_role=rootcoord] [error="empty grpc client: find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.769 +00:00] [WARN] [client/client.go:89] ["RootCoordClient mess key not exist"] [key=rootcoord]
[2024/01/07 17:16:02.769 +00:00] [WARN] [grpcclient/client.go:213] ["failed to get client address"] [error="find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.769 +00:00] [WARN] [grpcclient/client.go:471] ["fail to get grpc client in the retry state"] [client_role=rootcoord] [error="find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.769 +00:00] [ERROR] [grpcclient/client.go:462] ["retry func failed"] ["retry time"=0] [error="empty grpc client: find no available rootcoord, check rootcoord state"] [stack="github.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase[...]).call\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:462\ngithub.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase[...]).Call\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:548\ngithub.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase[...]).ReCall\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:564\ngithub.com/milvus-io/milvus/internal/distributed/rootcoord/client.wrapGrpcCall[...]\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/rootcoord/client/client.go:106\ngithub.com/milvus-io/milvus/internal/distributed/rootcoord/client.(*Client).AllocTimestamp\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/rootcoord/client/client.go:307\ngithub.com/milvus-io/milvus/internal/datacoord.(*rootCoordAllocator).allocTimestamp\n\t/go/src/github.com/milvus-io/milvus/internal/datacoord/allocator.go:53\ngithub.com/milvus-io/milvus/internal/datacoord.(*SegmentManager).genExpireTs\n\t/go/src/github.com/milvus-io/milvus/internal/datacoord/segment_manager.go:363\ngithub.com/milvus-io/milvus/internal/datacoord.(*SegmentManager).maybeResetLastExpireForSegments.func1\n\t/go/src/github.com/milvus-io/milvus/internal/datacoord/segment_manager.go:235\ngithub.com/milvus-io/milvus/pkg/util/retry.Do\n\t/go/src/github.com/milvus-io/milvus/pkg/util/retry/retry.go:44\ngithub.com/milvus-io/milvus/internal/datacoord.(*SegmentManager).maybeResetLastExpireForSegments\n\t/go/src/github.com/milvus-io/milvus/internal/datacoord/segment_manager.go:234\ngithub.com/milvus-io/milvus/internal/datacoord.newSegmentManager\n\t/go/src/github.com/milvus-io/milvus/internal/datacoord/segment_manager.go:214\ngithub.com/milvus-io/milvus/internal/datacoord.(*Server).initSegmentManager\n\t/go/src/github.com/milvus-io/milvus/internal/datacoord/server.go:554\ngithub.com/milvus-io/milvus/internal/datacoord.(*Server).initDataCoord\n\t/go/src/github.com/milvus-io/milvus/internal/datacoord/server.go:374\ngithub.com/milvus-io/milvus/internal/datacoord.(*Server).Init\n\t/go/src/github.com/milvus-io/milvus/internal/datacoord/server.go:326\ngithub.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).init\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:126\ngithub.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).Run\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:249\ngithub.com/milvus-io/milvus/cmd/components.(*DataCoord).Run\n\t/go/src/github.com/milvus-io/milvus/cmd/components/data_coord.go:50\ngithub.com/milvus-io/milvus/cmd/roles.runComponent[...].func1\n\t/go/src/github.com/milvus-io/milvus/cmd/roles/roles.go:115"]
[2024/01/07 17:16:02.769 +00:00] [INFO] [rootcoord/root_coord.go:514] ["init rootcoord done"] [nodeID=17] [Address=172.18.0.4:53100]
[2024/01/07 17:16:02.769 +00:00] [DEBUG] [rootcoord/service.go:151] ["RootCoord init done ..."]
[2024/01/07 17:16:02.769 +00:00] [INFO] [rootcoord/service.go:291] ["RootCoord Core start ..."]
[2024/01/07 17:16:02.769 +00:00] [DEBUG] [sessionutil/session_util.go:432] ["service begin to register to etcd"] [serverName=rootcoord] [ServerID=17]
[2024/01/07 17:16:02.775 +00:00] [INFO] [sessionutil/session_util.go:462] ["put session key into etcd"] [key=by-dev/meta/session/rootcoord] [value="{\"ServerID\":17,\"ServerName\":\"rootcoord\",\"Address\":\"172.18.0.4:53100\",\"Exclusive\":true,\"TriggerKill\":true,\"Version\":\"2.3.4\",\"IndexEngineVersion\":{},\"LeaseID\":7587875862039163722,\"HostName\":\"2de1263f898b\"}"]
[2024/01/07 17:16:02.775 +00:00] [INFO] [sessionutil/session_util.go:472] ["Service registered successfully"] [ServerName=rootcoord] [serverID=17]
[2024/01/07 17:16:02.775 +00:00] [INFO] [rootcoord/root_coord.go:280] ["RootCoord Register Finished"]
[2024/01/07 17:16:02.776 +00:00] [INFO] [rootcoord/proxy_manager.go:88] ["succeed to init sessions on etcd"] [sessions=null] [revision=31906]
[2024/01/07 17:16:02.776 +00:00] [INFO] [rootcoord/root_coord.go:157] ["update rootcoord state"] [state=Healthy]
[2024/01/07 17:16:02.776 +00:00] [INFO] [rootcoord/proxy_manager.go:111] ["start to watch etcd"]
[2024/01/07 17:16:02.776 +00:00] [WARN] [rootcoord/proxy_client_manager.go:234] ["proxy client is empty, RefreshPrivilegeInfoCache will not send to any client"]
[2024/01/07 17:16:02.776 +00:00] [INFO] [sessionutil/session_util.go:1216] ["save server info into file"] [content="rootcoord-17\n"] [filePath=/tmp/milvus/server_id_8]
[2024/01/07 17:16:02.776 +00:00] [INFO] [rootcoord/quota_center.go:135] ["Start QuotaCenter"] [collectInterval/s=3]
[2024/01/07 17:16:02.777 +00:00] [INFO] [rootcoord/root_coord.go:753] ["rootcoord startup successfully"]
[2024/01/07 17:16:02.777 +00:00] [DEBUG] [rootcoord/service.go:156] ["RootCoord start done ..."]
[2024/01/07 17:16:02.777 +00:00] [INFO] [components/root_coord.go:56] ["RootCoord successfully started"]
[2024/01/07 17:16:02.843 +00:00] [WARN] [retry/retry.go:44] ["grpc client is nil, maybe fail to get client in the retry state"] [client_role=rootcoord] [error="empty grpc client: find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.847 +00:00] [WARN] [retry/retry.go:44] ["grpc client is nil, maybe fail to get client in the retry state"] [client_role=rootcoord] [error="empty grpc client: find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.847 +00:00] [DEBUG] [sessionutil/session_util.go:615] ["SessionUtil GetSessions"] [prefix=rootcoord] [key=rootcoord] [address=172.18.0.4:53100]
[2024/01/07 17:16:02.847 +00:00] [DEBUG] [client/client.go:92] ["RootCoordClient GetSessions success"] [address=172.18.0.4:53100] [serverID=17]
[2024/01/07 17:16:02.847 +00:00] [DEBUG] [sessionutil/session_util.go:615] ["SessionUtil GetSessions"] [prefix=rootcoord] [key=rootcoord] [address=172.18.0.4:53100]
[2024/01/07 17:16:02.847 +00:00] [DEBUG] [client/client.go:92] ["RootCoordClient GetSessions success"] [address=172.18.0.4:53100] [serverID=17]
[2024/01/07 17:16:02.851 +00:00] [INFO] [sessionutil/session_util.go:908] ["register session success"] [role=rootcoord] [key=by-dev/meta/session/rootcoord]
[2024/01/07 17:16:02.970 +00:00] [WARN] [retry/retry.go:44] ["grpc client is nil, maybe fail to get client in the retry state"] [client_role=rootcoord] [error="empty grpc client: find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:02.971 +00:00] [DEBUG] [sessionutil/session_util.go:615] ["SessionUtil GetSessions"] [prefix=rootcoord] [key=rootcoord] [address=172.18.0.4:53100]
[2024/01/07 17:16:02.971 +00:00] [DEBUG] [client/client.go:92] ["RootCoordClient GetSessions success"] [address=172.18.0.4:53100] [serverID=17]
[2024/01/07 17:16:02.977 +00:00] [WARN] [rootcoord/root_coord.go:198] ["zero ts was met, this should be only occurred in starting state"] [minBgDdlTs=446863183177842689] [minNormalDdlTs=0]
[2024/01/07 17:16:03.145 +00:00] [WARN] [retry/retry.go:44] ["grpc client is nil, maybe fail to get client in the retry state"] [client_role=rootcoord] [error="empty grpc client: find no available rootcoord, check rootcoord state"]
[2024/01/07 17:16:03.146 +00:00] [DEBUG] [sessionutil/session_util.go:615] ["SessionUtil GetSessions"] [prefix=rootcoord] [key=rootcoord] [address=172.18.0.4:53100]
[2024/01/07 17:16:03.146 +00:00] [DEBUG] [client/client.go:92] ["RootCoordClient GetSessions success"] [address=172.18.0.4:53100] [serverID=17]
[2024/01/07 17:16:03.249 +00:00] [DEBUG] [querycoord/service.go:175] ["QueryCoord report RootCoord ready"]
[2024/01/07 17:16:03.249 +00:00] [DEBUG] [sessionutil/session_util.go:253] ["Session try to connect to etcd"]
[2024/01/07 17:16:03.249 +00:00] [INFO] [datanode/service.go:265] ["RootCoord client is ready for DataNode"]
[2024/01/07 17:16:03.249 +00:00] [DEBUG] [datanode/service.go:273] ["starting DataCoord client for DataNode"]
[2024/01/07 17:16:03.250 +00:00] [DEBUG] [sessionutil/session_util.go:253] ["Session try to connect to etcd"]
[2024/01/07 17:16:03.250 +00:00] [DEBUG] [sessionutil/session_util.go:268] ["Session connect to etcd success"]
[2024/01/07 17:16:03.250 +00:00] [DEBUG] [sessionutil/session_util.go:268] ["Session connect to etcd success"]
[2024/01/07 17:16:03.250 +00:00] [DEBUG] [querycoord/service.go:186] ["QueryCoord try to wait for DataCoord ready"]
[2024/01/07 17:16:03.251 +00:00] [DEBUG] [client/client.go:87] ["DataCoordClient, not existed in msess "] [key=datacoord] ["len of msess"=0]
[2024/01/07 17:16:03.251 +00:00] [WARN] [grpcclient/client.go:213] ["failed to get client address"] [error="find no available datacoord, check datacoord state"]
[2024/01/07 17:16:03.251 +00:00] [WARN] [grpcclient/client.go:548] ["fail to get grpc client"] [client_role=datacoord] [error="find no available datacoord, check datacoord state"]
[2024/01/07 17:16:03.251 +00:00] [DEBUG] [client/client.go:87] ["DataCoordClient, not existed in msess "] [key=datacoord] ["len of msess"=0]
[2024/01/07 17:16:03.251 +00:00] [WARN] [grpcclient/client.go:213] ["failed to get client address"] [error="find no available datacoord, check datacoord state"]
[2024/01/07 17:16:03.251 +00:00] [WARN] [retry/retry.go:44] ["grpc client is nil, maybe fail to get client in the retry state"] [client_role=datacoord] [error="empty grpc client: find no available datacoord, check datacoord state"]
[2024/01/07 17:16:03.251 +00:00] [WARN] [grpcclient/client.go:548] ["fail to get grpc client"] [client_role=datacoord] [error="find no available datacoord, check datacoord state"]
[2024/01/07 17:16:03.251 +00:00] [WARN] [retry/retry.go:44] ["grpc client is nil, maybe fail to get client in the retry state"] [client_role=datacoord] [error="empty grpc client: find no available datacoord, check datacoord state"]
[2024/01/07 17:16:03.251 +00:00] [DEBUG] [client/client.go:87] ["DataCoordClient, not existed in msess "] [key=datacoord] ["len of msess"=0]
[2024/01/07 17:16:03.251 +00:00] [WARN] [grpcclient/client.go:213] ["failed to get client address"] [error="find no available datacoord, check datacoord state"]
[2024/01/07 17:16:03.251 +00:00] [WARN] [grpcclient/client.go:471] ["fail to get grpc client in the retry state"] [client_role=datacoord] [error="find no available datacoord, check datacoord state"]
[2024/01/07 17:16:03.251 +00:00] [DEBUG] [client/client.go:87] ["DataCoordClient, not existed in msess "] [key=datacoord] ["len of msess"=0]
[2024/01/07 17:16:03.251 +00:00] [WARN] [grpcclient/client.go:213] ["failed to get client address"] [error="find no available datacoord, check datacoord state"]
[2024/01/07 17:16:03.251 +00:00] [WARN] [grpcclient/client.go:471] ["fail to get grpc client in the retry state"] [client_role=datacoord] [error="find no available datacoord, check datacoord state"]
[2024/01/07 17:16:03.251 +00:00] [ERROR] [grpcclient/client.go:462] ["retry func failed"] ["retry time"=0] [error="empty grpc client: find no available datacoord, check datacoord state"] [stack="github.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase[...]).call\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:462\ngithub.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase[...]).Call\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:548\ngithub.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase[...]).ReCall\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:564\ngithub.com/milvus-io/milvus/internal/distributed/datacoord/client.wrapGrpcCall[...]\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/client/client.go:101\ngithub.com/milvus-io/milvus/internal/distributed/datacoord/client.(*Client).GetComponentStates\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/client/client.go:115\ngithub.com/milvus-io/milvus/internal/util/componentutil.WaitForComponentStates[...].func1\n\t/go/src/github.com/milvus-io/milvus/internal/util/componentutil/componentutil.go:37\ngithub.com/milvus-io/milvus/pkg/util/retry.Do\n\t/go/src/github.com/milvus-io/milvus/pkg/util/retry/retry.go:44\ngithub.com/milvus-io/milvus/internal/util/componentutil.WaitForComponentStates[...]\n\t/go/src/github.com/milvus-io/milvus/internal/util/componentutil/componentutil.go:61\ngithub.com/milvus-io/milvus/internal/util/componentutil.WaitForComponentInitOrHealthy[...]\n\t/go/src/github.com/milvus-io/milvus/internal/util/componentutil/componentutil.go:68\ngithub.com/milvus-io/milvus/internal/distributed/datanode.(*Server).init\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datanode/service.go:280\ngithub.com/milvus-io/milvus/internal/distributed/datanode.(*Server).Run\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datanode/service.go:187\ngithub.com/milvus-io/milvus/cmd/components.(*DataNode).Run\n\t/go/src/github.com/milvus-io/milvus/cmd/components/data_node.go:53\ngithub.com/milvus-io/milvus/cmd/roles.runComponent[...].func1\n\t/go/src/github.com/milvus-io/milvus/cmd/roles/roles.go:115"]
[2024/01/07 17:16:03.251 +00:00] [ERROR] [grpcclient/client.go:462] ["retry func failed"] ["retry time"=0] [error="empty grpc client: find no available datacoord, check datacoord state"] [stack="github.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase[...]).call\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:462\ngithub.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase[...]).Call\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:548\ngithub.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase[...]).ReCall\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:564\ngithub.com/milvus-io/milvus/internal/distributed/datacoord/client.wrapGrpcCall[...]\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/client/client.go:101\ngithub.com/milvus-io/milvus/internal/distributed/datacoord/client.(*Client).GetComponentStates\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/client/client.go:115\ngithub.com/milvus-io/milvus/internal/util/componentutil.WaitForComponentStates[...].func1\n\t/go/src/github.com/milvus-io/milvus/internal/util/componentutil/componentutil.go:37\ngithub.com/milvus-io/milvus/pkg/util/retry.Do\n\t/go/src/github.com/milvus-io/milvus/pkg/util/retry/retry.go:44\ngithub.com/milvus-io/milvus/internal/util/componentutil.WaitForComponentStates[...]\n\t/go/src/github.com/milvus-io/milvus/internal/util/componentutil/componentutil.go:61\ngithub.com/milvus-io/milvus/internal/util/componentutil.WaitForComponentHealthy[...]\n\t/go/src/github.com/milvus-io/milvus/internal/util/componentutil/componentutil.go:82\ngithub.com/milvus-io/milvus/internal/distributed/querycoord.(*Server).init\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/querycoord/service.go:187\ngithub.com/milvus-io/milvus/internal/distributed/querycoord.(*Server).Run\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/querycoord/service.go:100\ngithub.com/milvus-io/milvus/cmd/components.(*QueryCoord).Run\n\t/go/src/github.com/milvus-io/milvus/cmd/components/query_coord.go:53\ngithub.com/milvus-io/milvus/cmd/roles.runComponent[...].func1\n\t/go/src/github.com/milvus-io/milvus/cmd/roles/roles.go:115"]
[2024/01/07 17:16:03.372 +00:00] [WARN] [datacoord/segment_manager.go:236] ["failed to get ts from rootCoord for globalLastExpire"] []
[2024/01/07 17:16:03.372 +00:00] [INFO] [datacoord/server.go:377] ["init segment manager done"]
[2024/01/07 17:16:03.372 +00:00] [INFO] [datacoord/garbage_collector.go:76] ["GC with option"] [enabled=true] [interval=1h0m0s] [missingTolerance=1h0m0s] [dropTolerance=3h0m0s]
[2024/01/07 17:16:03.372 +00:00] [INFO] [datacoord/server.go:384] ["init datacoord done"] [nodeID=17] [Address=172.18.0.4:13333]
[2024/01/07 17:16:03.372 +00:00] [DEBUG] [datacoord/service.go:252] ["DataCoord init done ..."]
[2024/01/07 17:16:03.372 +00:00] [DEBUG] [sessionutil/session_util.go:432] ["service begin to register to etcd"] [serverName=indexcoord] [ServerID=17]
[2024/01/07 17:16:03.380 +00:00] [INFO] [sessionutil/session_util.go:462] ["put session key into etcd"] [key=by-dev/meta/session/indexcoord] [value="{\"ServerID\":17,\"ServerName\":\"indexcoord\",\"Address\":\"172.18.0.4:13333\",\"Exclusive\":true,\"TriggerKill\":true,\"Version\":\"2.3.4\",\"IndexEngineVersion\":{},\"LeaseID\":7587875862039163737,\"HostName\":\"2de1263f898b\"}"]
[2024/01/07 17:16:03.380 +00:00] [INFO] [sessionutil/session_util.go:472] ["Service registered successfully"] [ServerName=indexcoord] [serverID=17]
[2024/01/07 17:16:03.380 +00:00] [DEBUG] [sessionutil/session_util.go:432] ["service begin to register to etcd"] [serverName=datacoord] [ServerID=17]
[2024/01/07 17:16:03.387 +00:00] [INFO] [sessionutil/session_util.go:462] ["put session key into etcd"] [key=by-dev/meta/session/datacoord] [value="{\"ServerID\":17,\"ServerName\":\"datacoord\",\"Address\":\"172.18.0.4:13333\",\"Exclusive\":true,\"TriggerKill\":true,\"Version\":\"2.3.4\",\"IndexEngineVersion\":{},\"LeaseID\":7587875862039163740,\"HostName\":\"2de1263f898b\"}"]
[2024/01/07 17:16:03.387 +00:00] [INFO] [sessionutil/session_util.go:472] ["Service registered successfully"] [ServerName=datacoord] [serverID=17]
[2024/01/07 17:16:03.387 +00:00] [INFO] [datacoord/server.go:268] ["DataCoord Register Finished"]
[2024/01/07 17:16:03.388 +00:00] [INFO] [runtime/asm_amd64.s:1598] ["index builder schedule loop start"]
[2024/01/07 17:16:03.388 +00:00] [INFO] [sessionutil/session_util.go:1216] ["save server info into file"] [content="datacoord-17\n"] [filePath=/tmp/milvus/server_id_8]
[2024/01/07 17:16:03.388 +00:00] [INFO] [datacoord/index_service.go:91] ["start create index for segment loop..."]
[2024/01/07 17:16:03.388 +00:00] [INFO] [datacoord/server.go:398] ["DataCoord startup successfully"]
[2024/01/07 17:16:03.388 +00:00] [DEBUG] [datacoord/service.go:257] ["DataCoord start done ..."]
[2024/01/07 17:16:03.388 +00:00] [DEBUG] [components/data_coord.go:54] ["DataCoord successfully started"]
[2024/01/07 17:16:03.451 +00:00] [WARN] [retry/retry.go:44] ["grpc client is nil, maybe fail to get client in the retry state"] [client_role=datacoord] [error="empty grpc client: find no available datacoord, check datacoord state"]
[2024/01/07 17:16:03.451 +00:00] [WARN] [retry/retry.go:44] ["grpc client is nil, maybe fail to get client in the retry state"] [client_role=datacoord] [error="empty grpc client: find no available datacoord, check datacoord state"]
[2024/01/07 17:16:03.456 +00:00] [INFO] [sessionutil/session_util.go:908] ["register session success"] [role=datacoord] [key=by-dev/meta/session/datacoord]
[2024/01/07 17:16:03.456 +00:00] [DEBUG] [sessionutil/session_util.go:615] ["SessionUtil GetSessions"] [prefix=datacoord] [key=datacoord] [address=172.18.0.4:13333]
[2024/01/07 17:16:03.456 +00:00] [DEBUG] [sessionutil/session_util.go:615] ["SessionUtil GetSessions"] [prefix=datacoord] [key=datacoord] [address=172.18.0.4:13333]
[2024/01/07 17:16:03.858 +00:00] [DEBUG] [querycoord/service.go:195] ["QueryCoord report DataCoord ready"]
[2024/01/07 17:16:03.858 +00:00] [INFO] [querycoordv2/server.go:181] ["QueryCoord start init"] [meta-root-path=by-dev/meta] [address=172.18.0.4:19531]
[2024/01/07 17:16:03.858 +00:00] [INFO] [datanode/service.go:284] ["DataCoord client is ready for DataNode"]
[2024/01/07 17:16:03.858 +00:00] [DEBUG] [sessionutil/session_util.go:253] ["Session try to connect to etcd"]
[2024/01/07 17:16:03.858 +00:00] [INFO] [sync/once.go:74] ["DataNode server initializing"] [TimeTickChannelName=by-dev-datacoord-timetick-channel]
[2024/01/07 17:16:03.858 +00:00] [DEBUG] [sessionutil/session_util.go:253] ["Session try to connect to etcd"]
[2024/01/07 17:16:03.859 +00:00] [DEBUG] [sessionutil/session_util.go:268] ["Session connect to etcd success"]
[2024/01/07 17:16:03.859 +00:00] [DEBUG] [sessionutil/session_util.go:268] ["Session connect to etcd success"]
[2024/01/07 17:16:03.863 +00:00] [DEBUG] [sessionutil/session_util.go:311] [getServerID] [reuse=true]
[2024/01/07 17:16:03.863 +00:00] [INFO] [sessionutil/session_util.go:285] ["start server"] [name=datanode] [address=172.18.0.4:21124] [id=17]
[2024/01/07 17:16:03.863 +00:00] [INFO] [sessionutil/session_util.go:1216] ["save server info into file"] [content="datanode-17\n"] [filePath=/tmp/milvus/server_id_8]
[2024/01/07 17:16:03.863 +00:00] [INFO] [datanode/data_node.go:247] ["DataNode server init rateCollector done"] ["node ID"=17]
[2024/01/07 17:16:03.863 +00:00] [INFO] [datanode/data_node.go:250] ["DataNode server init dispatcher client done"] ["node ID"=17]
[2024/01/07 17:16:03.863 +00:00] [INFO] [dependency/factory.go:84] ["try to init mq"] [standalone=true] [mqType=rocksmq]
[2024/01/07 17:16:03.863 +00:00] [INFO] [msgstream/mq_factory.go:18] ["init rocksmq msgstream success"] [path=/var/lib/milvus/rdb_data]
[2024/01/07 17:16:03.864 +00:00] [INFO] [datanode/data_node.go:266] ["init datanode done"] [MsgChannelSubName=by-dev-dataNode] [nodeID=17] [Address=172.18.0.4:21124]
[2024/01/07 17:16:03.864 +00:00] [INFO] [datanode/service.go:296] ["current DataNode state"] [state=Initializing]
[2024/01/07 17:16:03.864 +00:00] [INFO] [datanode/service.go:191] ["DataNode gRPC services successfully initialized"]
[2024/01/07 17:16:03.864 +00:00] [INFO] [datanode/data_node.go:322] ["start id allocator done"] [role=datanode]
[2024/01/07 17:16:03.866 +00:00] [INFO] [storage/remote_chunk_manager.go:83] ["remote chunk manager init success."] [remote=aws] [bucketname=a-bucket] [root=files]
[2024/01/07 17:16:03.866 +00:00] [DEBUG] [sessionutil/session_util.go:432] ["service begin to register to etcd"] [serverName=datanode] [ServerID=17]
[2024/01/07 17:16:03.866 +00:00] [INFO] [datanode/data_node.go:301] ["DataNode Background GC Start"]
[2024/01/07 17:16:03.866 +00:00] [INFO] [datanode/event_manager.go:48] ["Start watch channel"] [prefix=channelwatch/17]
[2024/01/07 17:16:03.866 +00:00] [DEBUG] [sessionutil/session_util.go:311] [getServerID] [reuse=true]
[2024/01/07 17:16:03.866 +00:00] [INFO] [sessionutil/session_util.go:285] ["start server"] [name=querycoord] [address=172.18.0.4:19531] [id=17]
[2024/01/07 17:16:03.866 +00:00] [INFO] [querycoordv2/server.go:213] ["start init querycoord"] [State=Initializing]
[2024/01/07 17:16:03.866 +00:00] [INFO] [querycoordv2/server.go:217] ["query coordinator connecting to etcd."]
[2024/01/07 17:16:03.866 +00:00] [INFO] [querycoordv2/server.go:229] ["query coordinator successfully connected to etcd."]
[2024/01/07 17:16:03.873 +00:00] [INFO] [sessionutil/session_util.go:462] ["put session key into etcd"] [key=by-dev/meta/session/datanode-17] [value="{\"ServerID\":17,\"ServerName\":\"datanode\",\"Address\":\"172.18.0.4:21124\",\"TriggerKill\":true,\"Version\":\"2.3.4\",\"IndexEngineVersion\":{},\"LeaseID\":7587875862039163750,\"HostName\":\"2de1263f898b\"}"]
[2024/01/07 17:16:03.873 +00:00] [INFO] [sessionutil/session_util.go:472] ["Service registered successfully"] [ServerName=datanode] [serverID=17]
[2024/01/07 17:16:03.873 +00:00] [INFO] [datanode/data_node.go:187] ["DataNode Register Finished"]
[2024/01/07 17:16:03.873 +00:00] [DEBUG] [sessionutil/session_util.go:774] ["watch services"] ["add kv"="key:\"by-dev/meta/session/datanode-17\" create_revision:31909 mod_revision:31909 version:1 value:\"{\\\"ServerID\\\":17,\\\"ServerName\\\":\\\"datanode\\\",\\\"Address\\\":\\\"172.18.0.4:21124\\\",\\\"TriggerKill\\\":true,\\\"Version\\\":\\\"2.3.4\\\",\\\"IndexEngineVersion\\\":{},\\\"LeaseID\\\":7587875862039163750,\\\"HostName\\\":\\\"2de1263f898b\\\"}\" lease:7587875862039163750 "]
[2024/01/07 17:16:03.873 +00:00] [DEBUG] [sessionutil/session_util.go:802] [WatchService] ["event type"=SessionAddEvent]
[2024/01/07 17:16:03.873 +00:00] [INFO] [datacoord/server.go:885] ["received datanode register"] [address=172.18.0.4:21124] [serverID=17]
[2024/01/07 17:16:03.873 +00:00] [INFO] [datacoord/channel_manager.go:353] ["register node"] ["registered node"=17] [updates="[\"{type=Delete,nodeID=-9223372036854775808,channels=\\\"[by-dev-rootcoord-dml_0_446748065920713215v0]\\\"}\",\"{type=Add,nodeID=17,channels=\\\"[by-dev-rootcoord-dml_0_446748065920713215v0]\\\"}\"]"]
[2024/01/07 17:16:03.873 +00:00] [INFO] [datacoord/handler.go:62] [GetDataVChanPositions] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [numOfSegments=1]
[2024/01/07 17:16:03.873 +00:00] [INFO] [datacoord/handler.go:299] ["channel seek position set from channel checkpoint meta"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [posTs=446840488061042689] [posTime=2024/01/06 17:13:07.977 +00:00]
[2024/01/07 17:16:03.873 +00:00] [INFO] [datacoord/channel_checker.go:113] ["timer started"] ["watch state"=ToWatch] [nodeID=17] [channelName=by-dev-rootcoord-dml_0_446748065920713215v0] ["check interval"=5m0s]
[2024/01/07 17:16:03.876 +00:00] [INFO] [tso/tso.go:122] ["sync and save timestamp"] [last=2024/01/07 15:01:27.833 +00:00] [save=2024/01/07 17:16:06.869 +00:00] [next=2024/01/07 17:16:03.869 +00:00]
[2024/01/07 17:16:03.876 +00:00] [INFO] [querycoordv2/server.go:240] ["init ID allocator done"]
[2024/01/07 17:16:03.876 +00:00] [INFO] [querycoordv2/server.go:319] ["init meta"]
[2024/01/07 17:16:03.876 +00:00] [INFO] [querycoordv2/server.go:328] ["recover meta..."]
[2024/01/07 17:16:03.877 +00:00] [INFO] [datanode/service.go:196] ["DataNode gRPC services successfully started"]
[2024/01/07 17:16:03.877 +00:00] [DEBUG] [components/data_node.go:57] ["Datanode successfully started"]
[2024/01/07 17:16:03.879 +00:00] [INFO] [datanode/event_manager.go:123] ["DataNode is handling watchInfo PUT event"] [key=by-dev/meta/channelwatch/17/by-dev-rootcoord-dml_0_446748065920713215v0] ["watch state"=ToWatch]
[2024/01/07 17:16:03.879 +00:00] [INFO] [datacoord/channel_manager.go:750] ["tickle update, timer delay"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [progress=0]
[2024/01/07 17:16:03.880 +00:00] [INFO] [querycoordv2/server.go:329] ["recover collections and partitions from kv store"] [traceID=1704647763880481696]
[2024/01/07 17:16:03.880 +00:00] [INFO] [querycoordv2/server.go:335] ["recovering collections..."] [collections="[446748065920713215]"]
[2024/01/07 17:16:03.880 +00:00] [INFO] [datanode/data_sync_service.go:231] ["recover growing segments from checkpoints"] [vChannelName=by-dev-rootcoord-dml_0_446748065920713215v0] [segmentID=446748065920916737] [numRows=53]
[2024/01/07 17:16:03.880 +00:00] [INFO] [datanode/channel_meta.go:220] ["adding segment"] [type=Normal] [segmentID=446748065920916737] [collectionID=446748065920713215] [partitionID=446748065920713216] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [startPosition=<nil>] [endPosition="channel_name:\"by-dev-rootcoord-dml_0_446748065920713215v0\" msgID:\"\\035\\220\\314\\303\\312,3\\006\" msgGroup:\"datanode-6-by-dev-rootcoord-dml_0_446748065920713215v0-true\" timestamp:446751969091518465 "] [recoverTs=446840488061042689] [importing=false]
[2024/01/07 17:16:03.880 +00:00] [INFO] [datanode/channel_meta.go:386] ["begin to init pk bloom filter"] [segmentID=446748065920916737] [statsBinLogsLen=1]
[2024/01/07 17:16:03.881 +00:00] [INFO] [meta/replica_manager.go:132] ["recover replica"] [collectionID=446748065920713215] [replicaID=446748066061484033] [nodes="[16]"]
[2024/01/07 17:16:03.881 +00:00] [INFO] [meta/resource_manager.go:658] ["Recover resource group"] [rgName=__default_resource_group] [nodes="[13,5,2,11,12,1,15,3,14,4,16]"] [capacity=1000000]
[2024/01/07 17:16:03.881 +00:00] [INFO] [querycoordv2/server.go:360] ["QueryCoord server initMeta done"] [duration=4.655393ms]
[2024/01/07 17:16:03.881 +00:00] [INFO] [querycoordv2/server.go:252] ["init session"]
[2024/01/07 17:16:03.881 +00:00] [INFO] [querycoordv2/server.go:256] ["init schedulers"]
[2024/01/07 17:16:03.881 +00:00] [INFO] [querycoordv2/server.go:269] ["init dist controller"]
[2024/01/07 17:16:03.881 +00:00] [INFO] [querycoordv2/server.go:279] ["init all available balancer"]
[2024/01/07 17:16:03.881 +00:00] [INFO] [querycoordv2/server.go:288] ["use config balancer"] [balancer=ScoreBasedBalancer]
[2024/01/07 17:16:03.881 +00:00] [INFO] [querycoordv2/server.go:295] ["init checker controller"]
[2024/01/07 17:16:03.881 +00:00] [INFO] [querycoordv2/server.go:365] ["init observers"]
[2024/01/07 17:16:03.881 +00:00] [INFO] [querycoordv2/server.go:312] ["init querycoord done"] [nodeID=17] [Address=172.18.0.4:19531]
[2024/01/07 17:16:03.881 +00:00] [DEBUG] [querycoord/service.go:103] ["QueryCoord init done ..."]
[2024/01/07 17:16:03.881 +00:00] [DEBUG] [sessionutil/session_util.go:432] ["service begin to register to etcd"] [serverName=querycoord] [ServerID=17]
[2024/01/07 17:16:03.888 +00:00] [INFO] [sessionutil/session_util.go:462] ["put session key into etcd"] [key=by-dev/meta/session/querycoord] [value="{\"ServerID\":17,\"ServerName\":\"querycoord\",\"Address\":\"172.18.0.4:19531\",\"Exclusive\":true,\"TriggerKill\":true,\"Version\":\"2.3.4\",\"IndexEngineVersion\":{},\"LeaseID\":7587875862039163763,\"HostName\":\"2de1263f898b\"}"]
[2024/01/07 17:16:03.888 +00:00] [INFO] [sessionutil/session_util.go:472] ["Service registered successfully"] [ServerName=querycoord] [serverID=17]
[2024/01/07 17:16:03.889 +00:00] [INFO] [querycoordv2/server.go:411] ["start watcher..."]
[2024/01/07 17:16:03.889 +00:00] [INFO] [querycoordv2/server.go:794] ["some nodes are offline, remove them from replica"] [collectionID=446748065920713215] [replicaID=446748066061484033] [offlineNodes="[16]"] [toRemove="[16]"]
[2024/01/07 17:16:03.894 +00:00] [INFO] [querycoordv2/server.go:806] ["all old query node down, enable auto balance!"]
[2024/01/07 17:16:03.894 +00:00] [INFO] [querycoordv2/server.go:449] ["start cluster..."]
[2024/01/07 17:16:03.894 +00:00] [INFO] [querycoordv2/server.go:452] ["start observers..."]
[2024/01/07 17:16:03.894 +00:00] [INFO] [observers/target_observer.go:128] ["Start update next target loop"]
[2024/01/07 17:16:03.894 +00:00] [INFO] [observers/target_observer.go:200] ["observer trigger update next target"] [collectionID=446748065920713215]
[2024/01/07 17:16:03.894 +00:00] [INFO] [querycoordv2/server.go:459] ["start task scheduler..."]
[2024/01/07 17:16:03.894 +00:00] [INFO] [observers/resource_observer.go:66] ["Start check resource group loop"]
[2024/01/07 17:16:03.894 +00:00] [INFO] [querycoordv2/server.go:462] ["start checker controller..."]
[2024/01/07 17:16:03.894 +00:00] [INFO] [querycoordv2/server.go:465] ["start job scheduler..."]
[2024/01/07 17:16:03.894 +00:00] [INFO] [sessionutil/session_util.go:1216] ["save server info into file"] [content="querycoord-17\n"] [filePath=/tmp/milvus/server_id_8]
[2024/01/07 17:16:03.894 +00:00] [INFO] [observers/replica_observer.go:68] ["Start check replica loop"]
[2024/01/07 17:16:03.894 +00:00] [DEBUG] [meta/target_manager.go:179] ["start to pull next targets for collection"] [collectionID=446748065920713215] [chosenPartitionIDs="[446748065920713216]"]
[2024/01/07 17:16:03.894 +00:00] [INFO] [querycoordv2/server.go:405] ["QueryCoord started"]
[2024/01/07 17:16:03.894 +00:00] [DEBUG] [querycoord/service.go:108] ["QueryCoord start done ..."]
[2024/01/07 17:16:03.894 +00:00] [DEBUG] [components/query_coord.go:57] ["QueryCoord successfully started"]
[2024/01/07 17:16:03.894 +00:00] [INFO] [datacoord/service.go:328] ["get recovery info request received"] [collectionID=446748065920713215] [partitionIDs="[]"]
[2024/01/07 17:16:03.895 +00:00] [DEBUG] [datacoord/meta.go:182] ["meta update: add collection"] [collectionID=446748065920713215]
[2024/01/07 17:16:03.895 +00:00] [INFO] [datacoord/meta.go:187] ["meta update: add collection - complete"] [collectionID=446748065920713215]
[2024/01/07 17:16:03.895 +00:00] [INFO] [datacoord/handler.go:116] [GetQueryVChanPositions] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [numOfSegments=1] ["indexed segment"=0]
[2024/01/07 17:16:03.895 +00:00] [INFO] [datacoord/handler.go:299] ["channel seek position set from channel checkpoint meta"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [posTs=446840488061042689] [posTime=2024/01/06 17:13:07.977 +00:00]
[2024/01/07 17:16:03.895 +00:00] [INFO] [datacoord/service.go:328] ["datacoord append channelInfo in GetRecoveryInfo"] [collectionID=446748065920713215] [partitionIDs="[]"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] ["# of unflushed segments"=1] ["# of flushed segments"=0] ["# of dropped segments"=0] ["# of indexed segments"=0]
[2024/01/07 17:16:03.896 +00:00] [DEBUG] [meta/target_manager.go:120] ["finish to update next targets for collection"] [collectionID=446748065920713215] [PartitionIDs="[446748065920713216]"] [segments="[]"] [channels="[by-dev-rootcoord-dml_0_446748065920713215v0]"]
[2024/01/07 17:16:03.896 +00:00] [INFO] [observers/target_observer.go:204] ["channel not ready"] [collectionID=446748065920713215] [replicaNum=1] [readyReplicaNum=0] [channelName=by-dev-rootcoord-dml_0_446748065920713215v0]
[2024/01/07 17:16:03.896 +00:00] [INFO] [observers/target_observer.go:142] ["target observer init done"]
[2024/01/07 17:16:03.907 +00:00] [INFO] [datanode/channel_meta.go:470] ["Successfully load pk stats"] [segmentID=446748065920916737] [time=26.677921ms] [size=591]
[2024/01/07 17:16:03.907 +00:00] [INFO] [msgdispatcher/manager.go:67] ["create new dispatcherManager"] [role=datanode] [nodeID=17] [pchannel=by-dev-rootcoord-dml_0]
[2024/01/07 17:16:03.907 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_0] [subName=datanode-17-by-dev-rootcoord-dml_0_446748065920713215v0-true] [isMain=true]
[2024/01/07 17:16:03.907 +00:00] [INFO] [msgstream/mq_msgstream.go:521] ["Msg Stream state"] [can_produce=true]
[2024/01/07 17:16:03.907 +00:00] [DEBUG] [server/rocksmq_impl.go:520] ["Rocksmq create consumer group successfully "] [topic=by-dev-rootcoord-dml_0] [group=datanode-17-by-dev-rootcoord-dml_0_446748065920713215v0-true] [elapsed=0]
[2024/01/07 17:16:03.907 +00:00] [DEBUG] [server/rocksmq_impl.go:546] ["Rocksmq register consumer successfully "] [topic=by-dev-rootcoord-dml_0] [elapsed=0]
[2024/01/07 17:16:03.907 +00:00] [INFO] [msgdispatcher/manager.go:155] ["dispatcherManager is running..."] [role=datanode] [nodeID=17] [pchannel=by-dev-rootcoord-dml_0]
[2024/01/07 17:16:03.907 +00:00] [INFO] [msgstream/mq_msgstream.go:853] ["MsgStream begin to seek start msg: "] [channel=by-dev-rootcoord-dml_0] [MessageID="yuf8Gjh8MwY="]
[2024/01/07 17:16:03.908 +00:00] [DEBUG] [server/rocksmq_impl.go:919] ["successfully seek"] [topic=by-dev-rootcoord-dml_0] [group=datanode-17-by-dev-rootcoord-dml_0_446748065920713215v0-true] [msgId=446837368452605898]
[2024/01/07 17:16:03.908 +00:00] [INFO] [msgstream/mq_msgstream.go:863] ["MsgStream seek finished"] [channel=by-dev-rootcoord-dml_0]
[2024/01/07 17:16:03.908 +00:00] [INFO] [msgdispatcher/dispatcher.go:113] ["seek successfully"] [pchannel=by-dev-rootcoord-dml_0] [subName=datanode-17-by-dev-rootcoord-dml_0_446748065920713215v0-true] [isMain=true] [posTime=2024/01/06 17:13:07.977 +00:00] [tsLag=24h2m55.93174938s]
[2024/01/07 17:16:03.908 +00:00] [INFO] [msgdispatcher/dispatcher.go:149] ["add new target"] [vchannel=by-dev-rootcoord-dml_0_446748065920713215v0] [isMain=true]
[2024/01/07 17:16:03.908 +00:00] [INFO] [msgdispatcher/manager.go:102] ["add main dispatcher"] [role=datanode] [nodeID=17] [vchannel=by-dev-rootcoord-dml_0_446748065920713215v0]
[2024/01/07 17:16:03.908 +00:00] [INFO] [msgdispatcher/dispatcher.go:177] ["get signal"] [pchannel=by-dev-rootcoord-dml_0] [signal=start] [isMain=true]
[2024/01/07 17:16:03.908 +00:00] [INFO] [msgdispatcher/dispatcher.go:200] ["handle signal done"] [pchannel=by-dev-rootcoord-dml_0] [signal=start] [isMain=true]
[2024/01/07 17:16:03.908 +00:00] [INFO] [msgdispatcher/client.go:86] ["register done"] [role=datanode] [nodeID=17] [vchannel=by-dev-rootcoord-dml_0_446748065920713215v0]
[2024/01/07 17:16:03.908 +00:00] [INFO] [datanode/flow_graph_dmstream_input_node.go:53] ["datanode seek successfully when register to msgDispatcher"] [nodeID=17] [collectionID=446748065920713215] [vchannel=by-dev-rootcoord-dml_0_446748065920713215v0] [msgID="\ufffd\ufffd\ufffd\u001a8|3\u0006"] [tsTime=2024/01/06 17:13:07.977 +00:00] [tsLag=24h2m55.931824854s]
[2024/01/07 17:16:03.908 +00:00] [INFO] [datanode/flow_graph_dd_node.go:310] ["ddNode add sealed and growing segments"] [collectionID=446748065920713215] ["No. sealed segments"=0] ["No. growing segments"=1]
[2024/01/07 17:16:03.908 +00:00] [INFO] [datanode/data_sync_service.go:87] ["dataSyncService starting flow graph"] [collectionID=446748065920713215] [vChanName=by-dev-rootcoord-dml_0_446748065920713215v0]
[2024/01/07 17:16:03.908 +00:00] [INFO] [msgdispatcher/dispatcher.go:205] ["begin to work"] [pchannel=by-dev-rootcoord-dml_0] [isMain=true]
[2024/01/07 17:16:03.908 +00:00] [INFO] [datanode/event_manager.go:178] ["handle put event: new data sync service success"] [vChanName=by-dev-rootcoord-dml_0_446748065920713215v0]
[2024/01/07 17:16:03.912 +00:00] [INFO] [datanode/event_manager.go:210] ["handle put event success"] [key=channelwatch/17/by-dev-rootcoord-dml_0_446748065920713215v0] [state=WatchSuccess] [vChanName=by-dev-rootcoord-dml_0_446748065920713215v0]
[2024/01/07 17:16:03.912 +00:00] [INFO] [datacoord/channel_checker.go:167] ["stop timer for channel"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [timerCount=0]
[2024/01/07 17:16:03.912 +00:00] [INFO] [datanode/event_manager.go:112] ["DataNode received a PUT event with an end State"] [state=WatchSuccess]
[2024/01/07 17:16:03.912 +00:00] [INFO] [datacoord/channel_manager.go:654] ["datanode successfully watched channel"] [nodeID=17] [channelName=by-dev-rootcoord-dml_0_446748065920713215v0]
[2024/01/07 17:16:03.912 +00:00] [INFO] [datacoord/channel_checker.go:134] ["stop timer before timeout"] ["watch state"=ToWatch] [nodeID=17] [channelName=by-dev-rootcoord-dml_0_446748065920713215v0] ["timeout interval"=5m0s] [runningTimerCount=0]
[2024/01/07 17:16:03.948 +00:00] [DEBUG] [proxy/service.go:571] ["Proxy wait for RootCoord to be healthy done"]
[2024/01/07 17:16:03.948 +00:00] [DEBUG] [proxy/service.go:573] ["set RootCoord client for Proxy"]
[2024/01/07 17:16:03.948 +00:00] [DEBUG] [proxy/service.go:575] ["set RootCoord client for Proxy done"]
[2024/01/07 17:16:03.948 +00:00] [DEBUG] [proxy/service.go:579] ["create DataCoord client for Proxy"]
[2024/01/07 17:16:03.948 +00:00] [DEBUG] [sessionutil/session_util.go:253] ["Session try to connect to etcd"]
[2024/01/07 17:16:03.948 +00:00] [DEBUG] [sessionutil/session_util.go:268] ["Session connect to etcd success"]
[2024/01/07 17:16:03.948 +00:00] [DEBUG] [proxy/service.go:585] ["create DataCoord client for Proxy done"]
[2024/01/07 17:16:03.948 +00:00] [DEBUG] [proxy/service.go:588] ["Proxy wait for DataCoord to be healthy"]
[2024/01/07 17:16:03.949 +00:00] [DEBUG] [sessionutil/session_util.go:615] ["SessionUtil GetSessions"] [prefix=datacoord] [key=datacoord] [address=172.18.0.4:13333]
[2024/01/07 17:16:03.950 +00:00] [DEBUG] [proxy/service.go:593] ["Proxy wait for DataCoord to be healthy done"]
[2024/01/07 17:16:03.950 +00:00] [DEBUG] [proxy/service.go:595] ["set DataCoord client for Proxy"]
[2024/01/07 17:16:03.950 +00:00] [DEBUG] [proxy/service.go:597] ["set DataCoord client for Proxy done"]
[2024/01/07 17:16:03.950 +00:00] [DEBUG] [proxy/service.go:601] ["create QueryCoord client for Proxy"]
[2024/01/07 17:16:03.950 +00:00] [DEBUG] [sessionutil/session_util.go:253] ["Session try to connect to etcd"]
[2024/01/07 17:16:03.950 +00:00] [DEBUG] [sessionutil/session_util.go:268] ["Session connect to etcd success"]
[2024/01/07 17:16:03.950 +00:00] [DEBUG] [proxy/service.go:607] ["create QueryCoord client for Proxy done"]
[2024/01/07 17:16:03.950 +00:00] [DEBUG] [proxy/service.go:610] ["Proxy wait for QueryCoord to be healthy"]
[2024/01/07 17:16:03.950 +00:00] [DEBUG] [sessionutil/session_util.go:615] ["SessionUtil GetSessions"] [prefix=querycoord] [key=querycoord] [address=172.18.0.4:19531]
[2024/01/07 17:16:03.951 +00:00] [DEBUG] [proxy/service.go:615] ["Proxy wait for QueryCoord to be healthy done"]
[2024/01/07 17:16:03.951 +00:00] [DEBUG] [proxy/service.go:617] ["set QueryCoord client for Proxy"]
[2024/01/07 17:16:03.951 +00:00] [DEBUG] [proxy/service.go:619] ["set QueryCoord client for Proxy done"]
[2024/01/07 17:16:03.951 +00:00] [DEBUG] [proxy/service.go:621] ["update Proxy's state to Initializing"]
[2024/01/07 17:16:03.951 +00:00] [DEBUG] [proxy/service.go:624] ["init Proxy"]
[2024/01/07 17:16:03.951 +00:00] [INFO] [proxy/proxy.go:214] ["init session for Proxy"]
[2024/01/07 17:16:03.951 +00:00] [DEBUG] [sessionutil/session_util.go:253] ["Session try to connect to etcd"]
[2024/01/07 17:16:03.951 +00:00] [DEBUG] [sessionutil/session_util.go:268] ["Session connect to etcd success"]
[2024/01/07 17:16:03.954 +00:00] [DEBUG] [sessionutil/session_util.go:311] [getServerID] [reuse=true]
[2024/01/07 17:16:03.954 +00:00] [INFO] [sessionutil/session_util.go:285] ["start server"] [name=proxy] [address=172.18.0.4:19529] [id=17]
[2024/01/07 17:16:03.954 +00:00] [INFO] [sessionutil/session_util.go:1216] ["save server info into file"] [content="proxy-17\n"] [filePath=/tmp/milvus/server_id_8]
[2024/01/07 17:16:03.954 +00:00] [INFO] [proxy/proxy.go:219] ["init session for Proxy done"]
[2024/01/07 17:16:03.954 +00:00] [INFO] [dependency/factory.go:84] ["try to init mq"] [standalone=true] [mqType=rocksmq]
[2024/01/07 17:16:03.954 +00:00] [INFO] [msgstream/mq_factory.go:18] ["init rocksmq msgstream success"] [path=/var/lib/milvus/rdb_data]
[2024/01/07 17:16:03.954 +00:00] [INFO] [accesslog/global.go:47] ["Init access log success"]
[2024/01/07 17:16:03.954 +00:00] [DEBUG] [proxy/proxy.go:224] ["init access log for Proxy done"]
[2024/01/07 17:16:03.954 +00:00] [INFO] [proxy/proxy.go:230] ["Proxy init rateCollector done"] [nodeID=17]
[2024/01/07 17:16:03.954 +00:00] [DEBUG] [proxy/proxy.go:240] ["create id allocator done"] [role=proxy] [ProxyID=17]
[2024/01/07 17:16:03.954 +00:00] [DEBUG] [proxy/proxy.go:250] ["create timestamp allocator done"] [role=proxy] [ProxyID=17]
[2024/01/07 17:16:03.954 +00:00] [DEBUG] [proxy/proxy.go:261] ["create segment id assigner done"] [role=proxy] [ProxyID=17]
[2024/01/07 17:16:03.954 +00:00] [DEBUG] [proxy/proxy.go:266] ["create channels manager done"] [role=proxy]
[2024/01/07 17:16:03.954 +00:00] [INFO] [msgstream/common_mq_factory.go:31] ["Msg Stream state"] [can_produce=true]
[2024/01/07 17:16:03.955 +00:00] [WARN] [server/rocksmq_impl.go:398] ["rocksmq topic already exists "] [topic=by-dev-replicate-msg]
[2024/01/07 17:16:03.955 +00:00] [DEBUG] [proxy/proxy.go:284] ["create task scheduler done"] [role=proxy]
[2024/01/07 17:16:03.955 +00:00] [DEBUG] [proxy/proxy.go:288] ["create channels time ticker done"] [role=proxy] [syncTimeTickInterval=100ms]
[2024/01/07 17:16:03.955 +00:00] [DEBUG] [proxy/proxy.go:291] ["create metrics cache manager done"] [role=proxy]
[2024/01/07 17:16:03.955 +00:00] [DEBUG] [rootcoord/service.go:513] [PolicyList] [role=rootcoord] [in=]
[2024/01/07 17:16:03.956 +00:00] [DEBUG] [rootcoord/service.go:513] ["PolicyList success"] [role=rootcoord] [in=]
[2024/01/07 17:16:03.957 +00:00] [INFO] [v2@v2.44.2/enforcer.go:302] ["LoddPolicy update policyinfo"] [policyInfo="[{\"PType\":\"p\",\"V0\":\"public\",\"V1\":\"Collection-*.*\",\"V2\":\"PrivilegeIndexDetail\"},{\"PType\":\"p\",\"V0\":\"public\",\"V1\":\"Global-*.*\",\"V2\":\"PrivilegeDescribeCollection\"},{\"PType\":\"p\",\"V0\":\"public\",\"V1\":\"Global-*.*\",\"V2\":\"PrivilegeShowCollections\"}]"]
[2024/01/07 17:16:03.957 +00:00] [INFO] [v2@v2.44.2/enforcer.go:302] ["LoddPolicy update policyinfo"] [policyInfo="[{\"PType\":\"p\",\"V0\":\"public\",\"V1\":\"Collection-*.*\",\"V2\":\"PrivilegeIndexDetail\"},{\"PType\":\"p\",\"V0\":\"public\",\"V1\":\"Global-*.*\",\"V2\":\"PrivilegeDescribeCollection\"},{\"PType\":\"p\",\"V0\":\"public\",\"V1\":\"Global-*.*\",\"V2\":\"PrivilegeShowCollections\"}]"]
[2024/01/07 17:16:03.957 +00:00] [INFO] [proxy/meta_cache.go:235] ["success to init meta cache"] [policy_infos="[\"{\\\"PType\\\":\\\"p\\\",\\\"V0\\\":\\\"public\\\",\\\"V1\\\":\\\"Collection-*.*\\\",\\\"V2\\\":\\\"PrivilegeIndexDetail\\\"}\",\"{\\\"PType\\\":\\\"p\\\",\\\"V0\\\":\\\"public\\\",\\\"V1\\\":\\\"Global-*.*\\\",\\\"V2\\\":\\\"PrivilegeDescribeCollection\\\"}\",\"{\\\"PType\\\":\\\"p\\\",\\\"V0\\\":\\\"public\\\",\\\"V1\\\":\\\"Global-*.*\\\",\\\"V2\\\":\\\"PrivilegeShowCollections\\\"}\"]"]
[2024/01/07 17:16:03.957 +00:00] [DEBUG] [proxy/proxy.go:297] ["init meta cache done"] [role=proxy]
[2024/01/07 17:16:03.957 +00:00] [INFO] [proxy/proxy.go:299] ["init proxy done"] [nodeID=17] [Address=172.18.0.4:19529]
[2024/01/07 17:16:03.957 +00:00] [DEBUG] [proxy/service.go:629] ["init Proxy done"]
---Milvus Proxy successfully initialized and ready to serve!---
[2024/01/07 17:16:03.957 +00:00] [DEBUG] [proxy/service.go:403] ["init Proxy server done"]
[2024/01/07 17:16:03.957 +00:00] [DEBUG] [proxy/service.go:405] ["start Proxy server"]
[2024/01/07 17:16:03.957 +00:00] [DEBUG] [proxy/proxy.go:393] ["start task scheduler done"] [role=proxy]
[2024/01/07 17:16:03.957 +00:00] [DEBUG] [proxy/proxy.go:399] ["start id allocator done"] [role=proxy]
[2024/01/07 17:16:03.957 +00:00] [DEBUG] [proxy/proxy.go:405] ["start segment id assigner done"] [role=proxy]
[2024/01/07 17:16:03.957 +00:00] [DEBUG] [proxy/proxy.go:411] ["start channels time ticker done"] [role=proxy]
[2024/01/07 17:16:03.957 +00:00] [DEBUG] [proxy/proxy.go:420] ["update state code"] [role=proxy] [State=Healthy]
[2024/01/07 17:16:03.957 +00:00] [DEBUG] [sessionutil/session_util.go:432] ["service begin to register to etcd"] [serverName=proxy] [ServerID=17]
[2024/01/07 17:16:03.961 +00:00] [INFO] [sessionutil/session_util.go:908] ["register session success"] [role=querycoord] [key=by-dev/meta/session/querycoord]
[2024/01/07 17:16:03.974 +00:00] [INFO] [sessionutil/session_util.go:462] ["put session key into etcd"] [key=by-dev/meta/session/proxy-17] [value="{\"ServerID\":17,\"ServerName\":\"proxy\",\"Address\":\"172.18.0.4:19529\",\"TriggerKill\":true,\"Version\":\"2.3.4\",\"IndexEngineVersion\":{},\"LeaseID\":7587875862039163781,\"HostName\":\"2de1263f898b\"}"]
[2024/01/07 17:16:03.974 +00:00] [INFO] [sessionutil/session_util.go:472] ["Service registered successfully"] [ServerName=proxy] [serverID=17]
[2024/01/07 17:16:03.974 +00:00] [INFO] [proxy/proxy.go:166] ["Proxy Register Finished"]
[2024/01/07 17:16:03.974 +00:00] [DEBUG] [rootcoord/proxy_manager.go:157] ["received proxy put event with session"] [session="Session:<ServerID: 17, ServerName: proxy, Version: 2.3.4>"]
[2024/01/07 17:16:03.974 +00:00] [INFO] [rootcoord/timeticksync.go:233] ["Add session for timeticksync"] [serverID=17]
[2024/01/07 17:16:03.974 +00:00] [DEBUG] [sessionutil/session_util.go:253] ["Session try to connect to etcd"]
[2024/01/07 17:16:03.974 +00:00] [DEBUG] [sessionutil/session_util.go:268] ["Session connect to etcd success"]
[2024/01/07 17:16:03.974 +00:00] [INFO] [rootcoord/proxy_client_manager.go:120] ["succeed to create proxy client"] [address=172.18.0.4:19529] [serverID=17]
[2024/01/07 17:16:03.974 +00:00] [INFO] [proxy/service.go:649] ["start Proxy http server"]
[2024/01/07 17:16:03.975 +00:00] [DEBUG] [proxy/service.go:410] ["start Proxy server done"]
[2024/01/07 17:16:03.975 +00:00] [INFO] [components/proxy.go:56] ["Proxy successfully started"]
[2024/01/07 17:16:04.062 +00:00] [INFO] [sessionutil/session_util.go:908] ["register session success"] [role=proxy] [key=by-dev/meta/session/proxy-17]
[2024/01/07 17:16:04.367 +00:00] [DEBUG] [datanode/timetick_sender.go:180] ["timeTickSender send datanode timetick message"] [toSendMsgs=null] [sendLastTss={}]
I20240107 17:16:04.767038    27 MinioChunkManager.cpp:222] [SEGCORE][PreCheck][milvus] start to precheck chunk manager with configuration:[address=minio:9000, bucket_name=a-bucket, root_path=files, storage_type=remote, cloud_provider=aws, iam_endpoint=, log_level=fatal, region=, useSSL=false, useIAM=false, useVirtualHost=false, requestTimeoutMs=10000]
I20240107 17:16:04.771325    27 ChunkManagers.cpp:102] [SEGCORE][AwsChunkManager][milvus] init AwsChunkManager with parameter[endpoint: 'minio:9000', default_bucket_name:'a-bucket', root_path:'files', use_secure:'false']
I20240107 17:16:04.771392    27 ChunkCache.h:39] [SEGCORE][ChunkCache][milvus] Init ChunkCache with prefix: /var/lib/milvus/data/chunk_cache, read_ahead_policy: willneed
[2024/01/07 17:16:04.771 +00:00] [INFO] [querynodev2/server.go:245] ["InitChunkCache done"] [dir=/var/lib/milvus/data/chunk_cache] [policy=willneed]
[2024/01/07 17:16:04.771 +00:00] [INFO] [gc/gc_tuner.go:137] ["GC Helper initialized."] ["Initial GoGC"=100] [minimumGOGC=30] [maximumGOGC=200] [memoryThreshold=30229103001]
[2024/01/07 17:16:04.771 +00:00] [INFO] [querynodev2/server.go:381] ["query node init successfully"] [queryNodeID=17] [Address=172.18.0.4:21123]
[2024/01/07 17:16:04.771 +00:00] [DEBUG] [querynode/service.go:226] ["QueryNode init done ..."]
[2024/01/07 17:16:04.771 +00:00] [INFO] [tasks/concurrent_safe_scheduler.go:211] ["start execute loop"]
[2024/01/07 17:16:04.771 +00:00] [INFO] [querynodev2/server.go:402] ["query node start successfully"] [queryNodeID=17] [Address=172.18.0.4:21123] [mmapEnabled=false]
[2024/01/07 17:16:04.771 +00:00] [DEBUG] [sessionutil/session_util.go:432] ["service begin to register to etcd"] [serverName=querynode] [ServerID=17]
[2024/01/07 17:16:04.789 +00:00] [INFO] [sessionutil/session_util.go:462] ["put session key into etcd"] [key=by-dev/meta/session/querynode-17] [value="{\"ServerID\":17,\"ServerName\":\"querynode\",\"Address\":\"172.18.0.4:21123\",\"TriggerKill\":true,\"Version\":\"2.3.4\",\"IndexEngineVersion\":{\"CurrentIndexVersion\":1},\"LeaseID\":7587875862039163786,\"HostName\":\"2de1263f898b\"}"]
[2024/01/07 17:16:04.789 +00:00] [INFO] [sessionutil/session_util.go:472] ["Service registered successfully"] [ServerName=querynode] [serverID=17]
[2024/01/07 17:16:04.789 +00:00] [DEBUG] [sessionutil/session_util.go:774] ["watch services"] ["add kv"="key:\"by-dev/meta/session/querynode-17\" create_revision:31916 mod_revision:31916 version:1 value:\"{\\\"ServerID\\\":17,\\\"ServerName\\\":\\\"querynode\\\",\\\"Address\\\":\\\"172.18.0.4:21123\\\",\\\"TriggerKill\\\":true,\\\"Version\\\":\\\"2.3.4\\\",\\\"IndexEngineVersion\\\":{\\\"CurrentIndexVersion\\\":1},\\\"LeaseID\\\":7587875862039163786,\\\"HostName\\\":\\\"2de1263f898b\\\"}\" lease:7587875862039163786 "]
[2024/01/07 17:16:04.789 +00:00] [DEBUG] [sessionutil/session_util.go:774] ["watch services"] ["add kv"="key:\"by-dev/meta/session/querynode-17\" create_revision:31916 mod_revision:31916 version:1 value:\"{\\\"ServerID\\\":17,\\\"ServerName\\\":\\\"querynode\\\",\\\"Address\\\":\\\"172.18.0.4:21123\\\",\\\"TriggerKill\\\":true,\\\"Version\\\":\\\"2.3.4\\\",\\\"IndexEngineVersion\\\":{\\\"CurrentIndexVersion\\\":1},\\\"LeaseID\\\":7587875862039163786,\\\"HostName\\\":\\\"2de1263f898b\\\"}\" lease:7587875862039163786 "]
[2024/01/07 17:16:04.789 +00:00] [DEBUG] [sessionutil/session_util.go:802] [WatchService] ["event type"=SessionAddEvent]
[2024/01/07 17:16:04.789 +00:00] [DEBUG] [sessionutil/session_util.go:802] [WatchService] ["event type"=SessionAddEvent]
[2024/01/07 17:16:04.789 +00:00] [INFO] [datacoord/server.go:929] ["received querynode register"] [address=172.18.0.4:21123] [serverID=17]
[2024/01/07 17:16:04.789 +00:00] [INFO] [datacoord/index_engine_version_manager.go:65] ["addOrUpdate version"] [nodeId=17] [minimal=0] [current=1]
[2024/01/07 17:16:04.789 +00:00] [INFO] [querycoordv2/server.go:634] ["add node to NodeManager"] [nodeID=17] [nodeAddr=172.18.0.4:21123]
[2024/01/07 17:16:04.789 +00:00] [DEBUG] [sessionutil/session_util.go:253] ["Session try to connect to etcd"]
[2024/01/07 17:16:04.790 +00:00] [DEBUG] [sessionutil/session_util.go:268] ["Session connect to etcd success"]
[2024/01/07 17:16:04.790 +00:00] [DEBUG] [querynode/service.go:231] ["QueryNode start done ..."]
[2024/01/07 17:16:04.790 +00:00] [DEBUG] [components/query_node.go:57] ["QueryNode successfully started"]
[2024/01/07 17:16:04.790 +00:00] [INFO] [logutil/logutil.go:163] ["Log directory"] [configDir=]
[2024/01/07 17:16:04.790 +00:00] [INFO] [logutil/logutil.go:164] ["Set log file to "] [path=]
[2024/01/07 17:16:04.790 +00:00] [INFO] [tracer/tracer.go:78] ["Init tracer finished"] [Exporter=stdout]
[2024/01/07 17:16:04.791 +00:00] [INFO] [task/scheduler.go:230] ["add executor for new QueryNode"] [nodeID=17]
[2024/01/07 17:16:04.791 +00:00] [INFO] [dist/dist_handler.go:62] ["start dist handler"] [nodeID=17]
[2024/01/07 17:16:04.795 +00:00] [INFO] [meta/resource_manager.go:461] ["HandleNodeUp: add node to default resource group"] [rgName=__default_resource_group] [node=17]
[2024/01/07 17:16:04.795 +00:00] [INFO] [querycoordv2/server.go:723] ["HandleNodeUp: assign node to resource group"] [nodeID=17] [resourceGroup=__default_resource_group]
[2024/01/07 17:16:04.799 +00:00] [INFO] [utils/meta.go:181] ["assign node to replica"] [collectionID=446748065920713215] [replicaID=446748066061484033] [nodeID=17]
[2024/01/07 17:16:04.799 +00:00] [INFO] [balance/utils.go:114] ["create channel task"] [collection=446748065920713215] [replica=446748066061484033] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [from=-1] [to=17]
[2024/01/07 17:16:04.799 +00:00] [INFO] [task/scheduler.go:269] ["task added"] [task="[id=1704647763882] [type=Grow] [source=channel_checker] [reason=lacks of channel] [collectionID=446748065920713215] [replicaID=446748066061484033] [priority=High] [actionsCount=1] [actions={[type=Grow][node=17]}] [channel=by-dev-rootcoord-dml_0_446748065920713215v0]"]
[2024/01/07 17:16:04.867 +00:00] [INFO] [sessionutil/session_util.go:908] ["register session success"] [role=querynode] [key=by-dev/meta/session/querynode-17]
[2024/01/07 17:16:04.894 +00:00] [INFO] [observers/collection_observer.go:191] ["partition targets"] [collectionID=446748065920713215] [partitionID=446748065920713216] [segmentTargetNum=0] [channelTargetNum=1] [totalTargetNum=1] [replicaNum=1]
[2024/01/07 17:16:04.894 +00:00] [INFO] [balance/utils.go:114] ["create channel task"] [collection=446748065920713215] [replica=446748066061484033] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [from=-1] [to=17]
[2024/01/07 17:16:05.293 +00:00] [WARN] [dist/dist_handler.go:100] ["node last heart beat time lag too behind"] [now=2024/01/07 17:16:05.293 +00:00] [lastHeartBeatTime=1970/01/01 00:00:00.000 +00:00] [nodeID=17]
[2024/01/07 17:16:05.293 +00:00] [INFO] [task/scheduler.go:566] ["processed tasks"] [nodeID=17] [toProcessNum=1] [committedNum=1] [toRemoveNum=0]
[2024/01/07 17:16:05.293 +00:00] [INFO] [task/scheduler.go:572] ["process tasks related to node done"] [nodeID=17] [processingTaskNum=1] [waitingTaskNum=0] [segmentTaskNum=0] [channelTaskNum=1]
[2024/01/07 17:16:05.293 +00:00] [INFO] [task/executor.go:104] ["execute the action of task"] [taskID=1704647763882] [collectionID=446748065920713215] [replicaID=446748066061484033] [step=0] [source=channel_checker]
[2024/01/07 17:16:05.294 +00:00] [INFO] [datacoord/index_service.go:513] ["receive DescribeIndex request"] [traceID=bc1qugrtknpjz52vc4m559q7zumkc4268kp7skrsee] [collectionID=446748065920713215] [indexName=] [timestamp=0]
[2024/01/07 17:16:05.294 +00:00] [INFO] [datacoord/index_service.go:449] ["completeIndexInfo success"] [collectionID=446748065920713215] [indexID=446748065920713230] [totalRows=0] [indexRows=0] [pendingIndexRows=0] [state=Finished] [failReason=]
[2024/01/07 17:16:05.294 +00:00] [INFO] [datacoord/index_service.go:560] ["DescribeIndex success"] [traceID=bc1qugrtknpjz52vc4m559q7zumkc4268kp7skrsee] [collectionID=446748065920713215] [indexName=]
[2024/01/07 17:16:05.294 +00:00] [INFO] [task/executor.go:386] ["subscribe channel..."] [taskID=1704647763882] [collectionID=446748065920713215] [replicaID=446748066061484033] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [node=17] [source=channel_checker] [checkpoint=446840488061042689] [sinceCheckpoint=24h2m57.317871706s]
[2024/01/07 17:16:05.295 +00:00] [INFO] [querynodev2/services.go:204] ["received watch channel request"] [traceID=bc1qugrtknpjz52vc4m559q7zumkc4268kp7skrsee] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [currentNodeID=17] [version=1704647765294324585] [metricType=COSINE]
I20240107 17:16:05.297348    93 Collection.cpp:66] [SEGCORE][parseIndexMeta][milvus] index meta info : maxRowCount : {26658} FieldId : {101 IndexParams : { index_type : IVF_FLAT, metric_type : COSINE, nlist : 128,  }TypeParams : {dim : 1024, }}
[2024/01/07 17:16:05.297 +00:00] [INFO] [segments/collection.go:154] ["add partitions"] [collection=446748065920713215] [partitions="[446748065920713216]"]
[2024/01/07 17:16:05.297 +00:00] [INFO] [delegator/delegator.go:664] ["Init delta cache"] [traceID=bc1qugrtknpjz52vc4m559q7zumkc4268kp7skrsee] [collectionID=446748065920713215] [replicaID=446748066061484033] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [version=1704647765294324585] [startTs=446840488061042689] [maxSegmentCacheBuffer=10000000] [startTime=2024/01/06 17:13:07.977 +00:00]
[2024/01/07 17:16:05.297 +00:00] [INFO] [delegator/delegator.go:689] ["finish build new shardDelegator"] [traceID=bc1qugrtknpjz52vc4m559q7zumkc4268kp7skrsee] [collectionID=446748065920713215] [replicaID=446748066061484033] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [version=1704647765294324585] [startTs=446840488061042689]
[2024/01/07 17:16:05.297 +00:00] [INFO] [tsafe/manager.go:69] ["add tSafe done"] [traceID=bc1qugrtknpjz52vc4m559q7zumkc4268kp7skrsee] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [timestamp=2024/01/06 17:13:07.977 +00:00]
[2024/01/07 17:16:05.297 +00:00] [INFO] [pipeline/manager.go:66] ["start create pipeine"] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0]
[2024/01/07 17:16:05.297 +00:00] [INFO] [delegator/delegator_data.go:308] ["loading growing segments..."] [traceID=bc1qugrtknpjz52vc4m559q7zumkc4268kp7skrsee] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [replicaID=446748066061484033] [segmentIDs="[446748065920916737]"]
[2024/01/07 17:16:05.297 +00:00] [INFO] [segments/segment_loader.go:191] ["start loading..."] [traceID=bc1qugrtknpjz52vc4m559q7zumkc4268kp7skrsee] [collectionID=446748065920713215] [segmentType=Growing] [segmentNum=1] [afterFilter=1]
[2024/01/07 17:16:05.297 +00:00] [INFO] [segments/segment_loader.go:998] ["predict memory and disk usage while loading (in MiB)"] [traceID=bc1qugrtknpjz52vc4m559q7zumkc4268kp7skrsee] [collectionID=446748065920713215] [maxSegmentSize=0.49775123596191406] [concurrency=1] [committedMemSize=0] [memUsage=159.56640625] [committedDiskSize=0] [diskUsage=0] [predictMemUsage=160.0641574859619] [predictDiskUsage=0] [mmapEnabled=false]
[2024/01/07 17:16:05.297 +00:00] [INFO] [segments/segment_loader.go:408] ["request resource for loading segments (unit in MiB)"] [traceID=bc1qugrtknpjz52vc4m559q7zumkc4268kp7skrsee] [segmentIDs="[446748065920916737]"] [memory=0.49775123596191406] [committedMemory=0.49775123596191406] [disk=0] [committedDisk=0]
I20240107 17:16:05.297986    93 IndexConfigGenerator.cpp:32] [SEGCORE][VecIndexConfig][milvus]  VecIndexConfig:  origin_index_type_:IVF_FLAT index_type_: IVF_FLAT_CC metric_type_: COSINE
I20240107 17:16:05.298031    93 factory.cc:20] [KNOWHERE][Create][milvus] create knowhere index IVF_FLAT_CC with version 1
[2024/01/07 17:16:05.298 +00:00] [INFO] [segments/segment.go:189] ["create segment"] [traceID=bc1qugrtknpjz52vc4m559q7zumkc4268kp7skrsee] [collectionID=446748065920713215] [partitionID=446748065920713216] [segmentID=446748065920916737] [segmentType=Growing]
[2024/01/07 17:16:05.298 +00:00] [INFO] [segments/segment_loader.go:280] ["start to load segments in parallel"] [traceID=bc1qugrtknpjz52vc4m559q7zumkc4268kp7skrsee] [collectionID=446748065920713215] [segmentType=Growing] [segmentNum=1] [concurrencyLevel=1]
[2024/01/07 17:16:05.298 +00:00] [INFO] [segments/segment_loader.go:542] ["start loading segment files"] [traceID=bc1qugrtknpjz52vc4m559q7zumkc4268kp7skrsee] [collectionID=446748065920713215] [partitionID=446748065920713216] [shard=by-dev-rootcoord-dml_0_446748065920713215v0] [segmentID=446748065920916737] [rowNum=53] [segmentType=Growing]
I20240107 17:16:05.298388    93 ThreadPools.h:51] [SEGCORE][SetUpCoefficients][milvus] Init ThreadPools, high_priority_co:10, middle:5, low:1
I20240107 17:16:05.298403    93 ThreadPool.h:49] [SEGCORE][ThreadPool][milvus] Init thread pool:middle_priority_thread_pool with min worker num:12 and max worker num:60
I20240107 17:16:05.299439   110 ThreadPool.h:49] [SEGCORE][ThreadPool][milvus] Init thread pool:high_priority_thread_pool with min worker num:12 and max worker num:120
[2024/01/07 17:16:05.347 +00:00] [INFO] [segments/segment.go:654] ["load mutil field done"] [traceID=bc1qugrtknpjz52vc4m559q7zumkc4268kp7skrsee] [collectionID=446748065920713215] [partitionID=446748065920713216] [segmentID=446748065920916737] ["row count"=53] [segmentID=446748065920916737]
[2024/01/07 17:16:05.347 +00:00] [INFO] [segments/segment_loader.go:609] ["loading statslog..."] [traceID=bc1qugrtknpjz52vc4m559q7zumkc4268kp7skrsee] [collectionID=446748065920713215] [partitionID=446748065920713216] [shard=by-dev-rootcoord-dml_0_446748065920713215v0] [segmentID=446748065920916737]
[2024/01/07 17:16:05.369 +00:00] [INFO] [segments/segment_loader.go:774] ["Successfully load pk stats"] [traceID=bc1qugrtknpjz52vc4m559q7zumkc4268kp7skrsee] [segmentID=446748065920916737] [time=22.183955ms] [size=591]
[2024/01/07 17:16:05.369 +00:00] [INFO] [segments/segment_loader.go:617] ["loading delta..."] [traceID=bc1qugrtknpjz52vc4m559q7zumkc4268kp7skrsee] [collectionID=446748065920713215] [partitionID=446748065920713216] [shard=by-dev-rootcoord-dml_0_446748065920713215v0] [segmentID=446748065920916737]
[2024/01/07 17:16:05.369 +00:00] [INFO] [segments/segment_loader.go:803] ["there are no delta logs saved with segment, skip loading delete record"] [traceID=bc1qugrtknpjz52vc4m559q7zumkc4268kp7skrsee] [segmentID=446748065920916737] [segmentID=446748065920916737]
[2024/01/07 17:16:05.373 +00:00] [INFO] [gc/gc_tuner.go:90] ["GC Tune done"] ["previous GOGC"=100] ["heapuse "=29] ["total memory"=230] ["next GC"=48] ["new GOGC"=200] [gc-pause=76.405µs] [gc-pause-end=1704647765373021144]
[2024/01/07 17:16:05.374 +00:00] [INFO] [segments/segment_loader.go:271] ["load segment done"] [traceID=bc1qugrtknpjz52vc4m559q7zumkc4268kp7skrsee] [collectionID=446748065920713215] [segmentType=Growing] [segmentID=446748065920916737]
[2024/01/07 17:16:05.374 +00:00] [INFO] [segments/segment_loader.go:296] ["all segment load done"] [traceID=bc1qugrtknpjz52vc4m559q7zumkc4268kp7skrsee] [collectionID=446748065920713215] [segmentType=Growing]
[2024/01/07 17:16:05.377 +00:00] [INFO] [gc/gc_tuner.go:90] ["GC Tune done"] ["previous GOGC"=200] ["heapuse "=29] ["total memory"=228] ["next GC"=71] ["new GOGC"=200] [gc-pause=42.912µs] [gc-pause-end=1704647765377474022]
[2024/01/07 17:16:05.378 +00:00] [INFO] [delegator/delegator_data.go:316] ["load growing segments done"] [traceID=bc1qugrtknpjz52vc4m559q7zumkc4268kp7skrsee] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [replicaID=446748066061484033] [segmentIDs="[446748065920916737]"]
[2024/01/07 17:16:05.378 +00:00] [INFO] [delegator/delegator_data.go:297] ["add growing segments to delegator"] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [replicaID=446748066061484033] [segmentIDs="[446748065920916737]"]
[2024/01/07 17:16:05.378 +00:00] [INFO] [msgdispatcher/manager.go:67] ["create new dispatcherManager"] [role=querynode] [nodeID=17] [pchannel=by-dev-rootcoord-dml_0]
[2024/01/07 17:16:05.378 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_0] [subName=querynode-17-by-dev-rootcoord-dml_0_446748065920713215v0-true] [isMain=true]
[2024/01/07 17:16:05.378 +00:00] [INFO] [msgstream/mq_msgstream.go:116] ["Msg Stream state"] [can_produce=true]
[2024/01/07 17:16:05.378 +00:00] [INFO] [msgstream/mq_msgstream.go:853] ["MsgStream begin to seek start msg: "] [channel=by-dev-rootcoord-dml_0] [MessageID="yuf8Gjh8MwY="]
[2024/01/07 17:16:05.378 +00:00] [INFO] [msgdispatcher/manager.go:155] ["dispatcherManager is running..."] [role=querynode] [nodeID=17] [pchannel=by-dev-rootcoord-dml_0]
[2024/01/07 17:16:05.378 +00:00] [INFO] [msgstream/mq_msgstream.go:863] ["MsgStream seek finished"] [channel=by-dev-rootcoord-dml_0]
[2024/01/07 17:16:05.378 +00:00] [INFO] [msgdispatcher/dispatcher.go:113] ["seek successfully"] [pchannel=by-dev-rootcoord-dml_0] [subName=querynode-17-by-dev-rootcoord-dml_0_446748065920713215v0-true] [isMain=true] [posTime=2024/01/06 17:13:07.977 +00:00] [tsLag=24h2m57.401908379s]
[2024/01/07 17:16:05.378 +00:00] [INFO] [msgdispatcher/dispatcher.go:149] ["add new target"] [vchannel=by-dev-rootcoord-dml_0_446748065920713215v0] [isMain=true]
[2024/01/07 17:16:05.378 +00:00] [INFO] [msgdispatcher/manager.go:102] ["add main dispatcher"] [role=querynode] [nodeID=17] [vchannel=by-dev-rootcoord-dml_0_446748065920713215v0]
[2024/01/07 17:16:05.378 +00:00] [INFO] [msgdispatcher/dispatcher.go:177] ["get signal"] [pchannel=by-dev-rootcoord-dml_0] [signal=start] [isMain=true]
[2024/01/07 17:16:05.378 +00:00] [INFO] [msgdispatcher/dispatcher.go:200] ["handle signal done"] [pchannel=by-dev-rootcoord-dml_0] [signal=start] [isMain=true]
[2024/01/07 17:16:05.378 +00:00] [INFO] [msgdispatcher/client.go:86] ["register done"] [role=querynode] [nodeID=17] [vchannel=by-dev-rootcoord-dml_0_446748065920713215v0]
[2024/01/07 17:16:05.378 +00:00] [INFO] [msgdispatcher/dispatcher.go:205] ["begin to work"] [pchannel=by-dev-rootcoord-dml_0] [isMain=true]
[2024/01/07 17:16:05.378 +00:00] [INFO] [pipeline/stream_pipeline.go:79] ["stream pipeline seeks from position with msgDispatcher"] [pchannel=by-dev-rootcoord-dml_0] [vchannel=by-dev-rootcoord-dml_0_446748065920713215v0] [checkpointTs=2024/01/06 17:13:07.977 +00:00] [tsLag=24h2m57.401994543s] [elapse=555.146µs]
[2024/01/07 17:16:05.379 +00:00] [INFO] [querynodev2/services.go:344] ["watch dml channel success"] [traceID=bc1qugrtknpjz52vc4m559q7zumkc4268kp7skrsee] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [currentNodeID=17]
[2024/01/07 17:16:05.379 +00:00] [INFO] [task/executor.go:401] ["subscribe channel done"] [taskID=1704647763882] [collectionID=446748065920713215] [replicaID=446748066061484033] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [node=17] [source=channel_checker] [taskID=1704647763882] ["time taken"=85.864891ms]
[2024/01/07 17:16:05.793 +00:00] [INFO] [task/scheduler.go:768] ["task removed"] [taskID=1704647763882] [collectionID=446748065920713215] [replicaID=446748066061484033] [status=succeeded] [channel=by-dev-rootcoord-dml_0_446748065920713215v0]
[2024/01/07 17:16:05.793 +00:00] [INFO] [task/scheduler.go:566] ["processed tasks"] [nodeID=17] [toProcessNum=0] [committedNum=0] [toRemoveNum=1]
[2024/01/07 17:16:05.793 +00:00] [INFO] [task/scheduler.go:572] ["process tasks related to node done"] [nodeID=17] [processingTaskNum=0] [waitingTaskNum=0] [segmentTaskNum=0] [channelTaskNum=0]
[2024/01/07 17:16:05.894 +00:00] [INFO] [observers/collection_observer.go:191] ["partition targets"] [collectionID=446748065920713215] [partitionID=446748065920713216] [segmentTargetNum=0] [channelTargetNum=1] [totalTargetNum=1] [replicaNum=1]
[2024/01/07 17:16:05.894 +00:00] [INFO] [observers/collection_observer.go:214] ["partition load progress"] [collectionID=446748065920713215] [partitionID=446748065920713216] [subChannelCount=1] [loadSegmentCount=0]
[2024/01/07 17:16:05.894 +00:00] [WARN] [observers/collection_observer.go:228] ["failed to manual check current target, skip update load status"] [collectionID=446748065920713215] [partitionID=446748065920713216]
[2024/01/07 17:16:05.895 +00:00] [INFO] [datacoord/index_service.go:513] ["receive DescribeIndex request"] [traceID=ba749b8da63573df1092ca67b7a12677] [collectionID=446748065920713215] [indexName=] [timestamp=0]
[2024/01/07 17:16:05.895 +00:00] [INFO] [datacoord/index_service.go:449] ["completeIndexInfo success"] [collectionID=446748065920713215] [indexID=446748065920713230] [totalRows=0] [indexRows=0] [pendingIndexRows=0] [state=Finished] [failReason=]
[2024/01/07 17:16:05.895 +00:00] [INFO] [datacoord/index_service.go:560] ["DescribeIndex success"] [traceID=ba749b8da63573df1092ca67b7a12677] [collectionID=446748065920713215] [indexName=]
[2024/01/07 17:16:05.896 +00:00] [INFO] [querynodev2/services.go:1366] ["sync action"] [traceID=ce8ac5c3ed9e76e021c2d9e70c7ab44e] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [currentNodeID=17] [Action=UpdateVersion] [TargetVersion=1704647763894163033]
[2024/01/07 17:16:05.896 +00:00] [INFO] [delegator/distribution.go:294] ["Update readable segment version"] [oldVersion=0] [newVersion=1704647763894163033] [growingSegmentNum=1] [sealedSegmentNum=0]
[2024/01/07 17:16:05.896 +00:00] [INFO] [observers/target_observer.go:473] ["observer trigger update current target"] [collectionID=446748065920713215]
[2024/01/07 17:16:05.896 +00:00] [INFO] [datacoord/services.go:757] ["get recovery info request received"] [traceID=60159ab2bf079d7dc3ee8ff0b4f37197] [collectionID=446748065920713215] [partitionIDs="[]"]
[2024/01/07 17:16:05.896 +00:00] [INFO] [datacoord/handler.go:116] [GetQueryVChanPositions] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [numOfSegments=1] ["indexed segment"=0]
[2024/01/07 17:16:05.896 +00:00] [INFO] [datacoord/handler.go:299] ["channel seek position set from channel checkpoint meta"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [posTs=446840488061042689] [posTime=2024/01/06 17:13:07.977 +00:00]
[2024/01/07 17:16:05.896 +00:00] [INFO] [datacoord/services.go:772] ["datacoord append channelInfo in GetRecoveryInfo"] [traceID=60159ab2bf079d7dc3ee8ff0b4f37197] [collectionID=446748065920713215] [partitionIDs="[]"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] ["# of unflushed segments"=1] ["# of flushed segments"=0] ["# of dropped segments"=0] ["# of indexed segments"=0]
[2024/01/07 17:16:06.894 +00:00] [INFO] [observers/collection_observer.go:191] ["partition targets"] [collectionID=446748065920713215] [partitionID=446748065920713216] [segmentTargetNum=0] [channelTargetNum=1] [totalTargetNum=1] [replicaNum=1]
[2024/01/07 17:16:06.894 +00:00] [INFO] [observers/collection_observer.go:214] ["partition load progress"] [collectionID=446748065920713215] [partitionID=446748065920713216] [subChannelCount=1] [loadSegmentCount=0]
[2024/01/07 17:16:06.902 +00:00] [INFO] [observers/collection_observer.go:237] ["load status updated"] [collectionID=446748065920713215] [partitionID=446748065920713216] [partitionLoadPercentage=100] [collectionLoadPercentage=100]
[2024/01/07 17:16:13.895 +00:00] [INFO] [datacoord/index_service.go:513] ["receive DescribeIndex request"] [traceID=0299b456f7653b293b4d077659850a30] [collectionID=446748065920713215] [indexName=] [timestamp=0]
[2024/01/07 17:16:13.895 +00:00] [INFO] [datacoord/index_service.go:449] ["completeIndexInfo success"] [collectionID=446748065920713215] [indexID=446748065920713230] [totalRows=0] [indexRows=0] [pendingIndexRows=0] [state=Finished] [failReason=]
[2024/01/07 17:16:13.895 +00:00] [INFO] [datacoord/index_service.go:560] ["DescribeIndex success"] [traceID=0299b456f7653b293b4d077659850a30] [collectionID=446748065920713215] [indexName=]
[2024/01/07 17:16:13.895 +00:00] [INFO] [querynodev2/services.go:1366] ["sync action"] [traceID=bc1qugrtknpjz52vc4m559q7zumkc4268kp7skrsee] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [currentNodeID=17] [Action=UpdateVersion] [TargetVersion=1704647765896337942]
[2024/01/07 17:16:13.895 +00:00] [INFO] [delegator/distribution.go:294] ["Update readable segment version"] [oldVersion=1704647763894163033] [newVersion=1704647765896337942] [growingSegmentNum=1] [sealedSegmentNum=0]
[2024/01/07 17:16:13.896 +00:00] [INFO] [observers/target_observer.go:473] ["observer trigger update current target"] [collectionID=446748065920713215]
[2024/01/07 17:16:13.896 +00:00] [INFO] [datacoord/services.go:757] ["get recovery info request received"] [traceID=bb6893ed6e56add23e239d70e324c7f2] [collectionID=446748065920713215] [partitionIDs="[]"]
[2024/01/07 17:16:13.896 +00:00] [INFO] [datacoord/handler.go:116] [GetQueryVChanPositions] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [numOfSegments=1] ["indexed segment"=0]
[2024/01/07 17:16:13.896 +00:00] [INFO] [datacoord/handler.go:299] ["channel seek position set from channel checkpoint meta"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [posTs=446840488061042689] [posTime=2024/01/06 17:13:07.977 +00:00]
[2024/01/07 17:16:13.896 +00:00] [INFO] [datacoord/services.go:772] ["datacoord append channelInfo in GetRecoveryInfo"] [traceID=bb6893ed6e56add23e239d70e324c7f2] [collectionID=446748065920713215] [partitionIDs="[]"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] ["# of unflushed segments"=1] ["# of flushed segments"=0] ["# of dropped segments"=0] ["# of indexed segments"=0]
[2024/01/07 17:16:23.895 +00:00] [INFO] [datacoord/index_service.go:513] ["receive DescribeIndex request"] [traceID=f00ff4521f995a35a69c6f88ca373ed8] [collectionID=446748065920713215] [indexName=] [timestamp=0]
[2024/01/07 17:16:23.895 +00:00] [INFO] [datacoord/index_service.go:449] ["completeIndexInfo success"] [collectionID=446748065920713215] [indexID=446748065920713230] [totalRows=0] [indexRows=0] [pendingIndexRows=0] [state=Finished] [failReason=]
[2024/01/07 17:16:23.895 +00:00] [INFO] [datacoord/index_service.go:560] ["DescribeIndex success"] [traceID=f00ff4521f995a35a69c6f88ca373ed8] [collectionID=446748065920713215] [indexName=]
[2024/01/07 17:16:23.895 +00:00] [INFO] [querynodev2/services.go:1366] ["sync action"] [traceID=ac0c0ff3ab31d3704d16dc07c85bcb55] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [currentNodeID=17] [Action=UpdateVersion] [TargetVersion=1704647773896051637]
[2024/01/07 17:16:23.895 +00:00] [INFO] [delegator/distribution.go:294] ["Update readable segment version"] [oldVersion=1704647765896337942] [newVersion=1704647773896051637] [growingSegmentNum=1] [sealedSegmentNum=0]
[2024/01/07 17:16:23.896 +00:00] [INFO] [observers/target_observer.go:473] ["observer trigger update current target"] [collectionID=446748065920713215]
[2024/01/07 17:16:23.896 +00:00] [INFO] [datacoord/services.go:757] ["get recovery info request received"] [traceID=7f01d5cd14eb5ae1814b827c714f82a7] [collectionID=446748065920713215] [partitionIDs="[]"]
[2024/01/07 17:16:23.896 +00:00] [INFO] [datacoord/handler.go:116] [GetQueryVChanPositions] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [numOfSegments=1] ["indexed segment"=0]
[2024/01/07 17:16:23.896 +00:00] [INFO] [datacoord/handler.go:299] ["channel seek position set from channel checkpoint meta"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [posTs=446840488061042689] [posTime=2024/01/06 17:13:07.977 +00:00]
[2024/01/07 17:16:23.896 +00:00] [INFO] [datacoord/services.go:772] ["datacoord append channelInfo in GetRecoveryInfo"] [traceID=7f01d5cd14eb5ae1814b827c714f82a7] [collectionID=446748065920713215] [partitionIDs="[]"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] ["# of unflushed segments"=1] ["# of flushed segments"=0] ["# of dropped segments"=0] ["# of indexed segments"=0]
[2024/01/07 17:16:31.967 +00:00] [INFO] [pipeline/insert_node.go:80] ["pipeline fetch insert msg"] [collectionID=446748065920713215] [segmentID=446748065920916737] [insertRowNum=1] [timestampMin=446840488087257092] [timestampMax=446840488087257092]
[2024/01/07 17:16:33.895 +00:00] [INFO] [datacoord/index_service.go:513] ["receive DescribeIndex request"] [traceID=a7e1ea2bba26dafba3a564675dd6c6c3] [collectionID=446748065920713215] [indexName=] [timestamp=0]
[2024/01/07 17:16:33.895 +00:00] [INFO] [datacoord/index_service.go:449] ["completeIndexInfo success"] [collectionID=446748065920713215] [indexID=446748065920713230] [totalRows=0] [indexRows=0] [pendingIndexRows=0] [state=Finished] [failReason=]
[2024/01/07 17:16:33.895 +00:00] [INFO] [datacoord/index_service.go:560] ["DescribeIndex success"] [traceID=a7e1ea2bba26dafba3a564675dd6c6c3] [collectionID=446748065920713215] [indexName=]
[2024/01/07 17:16:33.896 +00:00] [INFO] [querynodev2/services.go:1366] ["sync action"] [traceID=bc1qugrtknpjz52vc4m559q7zumkc4268kp7skrsee] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [currentNodeID=17] [Action=UpdateVersion] [TargetVersion=1704647783896069713]
[2024/01/07 17:16:33.896 +00:00] [INFO] [delegator/distribution.go:294] ["Update readable segment version"] [oldVersion=1704647773896051637] [newVersion=1704647783896069713] [growingSegmentNum=1] [sealedSegmentNum=0]
[2024/01/07 17:16:33.896 +00:00] [INFO] [observers/target_observer.go:473] ["observer trigger update current target"] [collectionID=446748065920713215]
[2024/01/07 17:16:33.897 +00:00] [INFO] [datacoord/services.go:757] ["get recovery info request received"] [traceID=6380f4effae935b2397f3cfea974131b] [collectionID=446748065920713215] [partitionIDs="[]"]
[2024/01/07 17:16:33.897 +00:00] [INFO] [datacoord/handler.go:116] [GetQueryVChanPositions] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [numOfSegments=1] ["indexed segment"=0]
[2024/01/07 17:16:33.897 +00:00] [INFO] [datacoord/handler.go:299] ["channel seek position set from channel checkpoint meta"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [posTs=446840488061042689] [posTime=2024/01/06 17:13:07.977 +00:00]
[2024/01/07 17:16:33.897 +00:00] [INFO] [datacoord/services.go:772] ["datacoord append channelInfo in GetRecoveryInfo"] [traceID=6380f4effae935b2397f3cfea974131b] [collectionID=446748065920713215] [partitionIDs="[]"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] ["# of unflushed segments"=1] ["# of flushed segments"=0] ["# of dropped segments"=0] ["# of indexed segments"=0]
[2024/01/07 17:16:33.900 +00:00] [INFO] [gc/gc_tuner.go:90] ["GC Tune done"] ["previous GOGC"=200] ["heapuse "=41] ["total memory"=263] ["next GC"=77] ["new GOGC"=200] [gc-pause=49.144µs] [gc-pause-end=1704647793898818616]
[2024/01/07 17:16:36.359 +00:00] [INFO] [datanode/channel_meta.go:608] ["updated segment num row"] [segmentID=446748065920916737] [addedNumRows=1] [numRowsSum=54]
[2024/01/07 17:16:36.360 +00:00] [INFO] [datanode/channel_meta.go:634] ["updated segment memorySize"] [segmentID=446748065920916737] [memorySize=4652]
[2024/01/07 17:16:36.360 +00:00] [INFO] [datanode/flow_graph_insert_buffer_node.go:286] ["segment buffer status"] [no.=0] [segmentID=446748065920916737] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [size=1] [limit=3623] [memorySize=4652]
[2024/01/07 17:16:36.360 +00:00] [INFO] [datanode/segment_sync_policy.go:58] ["sync segment periodically"] [segmentIDs="[446748065920916737]"]
[2024/01/07 17:16:36.360 +00:00] [INFO] [datanode/flow_graph_insert_buffer_node.go:402] ["sync segments"] [vChannel=by-dev-rootcoord-dml_0_446748065920713215v0] [segIDs="[446748065920916737]"]
[2024/01/07 17:16:36.360 +00:00] [INFO] [datanode/flow_graph_insert_buffer_node.go:411] ["merging sync task, updating flushed flag"] [segmentID=446748065920916737] [flushed=false] [dropped=false]
[2024/01/07 17:16:36.360 +00:00] [INFO] [datanode/flow_graph_insert_buffer_node.go:478] ["insertBufferNode start syncing bufferData"] [segmentID=446748065920916737] [flushed=false] [dropped=false] [auto=false] [position="channel_name:\"by-dev-rootcoord-dml_0_446748065920713215v0\" msgID:\"v\\000\\224\\214\\262\\2233\\006\" msgGroup:\"datanode-17-by-dev-rootcoord-dml_0_446748065920713215v0-true\" timestamp:446863189351333890 "] [channel=by-dev-rootcoord-dml_0_446748065920713215v0]
[2024/01/07 17:16:36.365 +00:00] [INFO] [gc/gc_tuner.go:90] ["GC Tune done"] ["previous GOGC"=200] ["heapuse "=39] ["total memory"=267] ["next GC"=84] ["new GOGC"=200] [gc-pause=34.616µs] [gc-pause-end=1704647796365024586]
[2024/01/07 17:16:36.387 +00:00] [INFO] [gc/gc_tuner.go:90] ["GC Tune done"] ["previous GOGC"=200] ["heapuse "=51] ["total memory"=301] ["next GC"=110] ["new GOGC"=200] [gc-pause=33.665µs] [gc-pause-end=1704647796386974957]
[2024/01/07 17:16:36.393 +00:00] [INFO] [datanode/flush_manager.go:292] ["handling insert task"] [segmentID=446748065920916737] [flushed=false] [dropped=false] [position="channel_name:\"by-dev-rootcoord-dml_0_446748065920713215v0\" msgID:\"v\\000\\224\\214\\262\\2233\\006\" msgGroup:\"datanode-17-by-dev-rootcoord-dml_0_446748065920713215v0-true\" timestamp:446863189351333890 "]
[2024/01/07 17:16:36.393 +00:00] [INFO] [datanode/flush_manager.go:146] ["new flush task runner created and initialized"] [segmentID=446748065920916737] ["pos message ID"="v\u0000\ufffd\ufffd\ufffd\ufffd3\u0006"]
[2024/01/07 17:16:36.393 +00:00] [INFO] [datanode/flush_task.go:136] ["running flush insert task"] [segmentID=446748065920916737] [flushed=false] [dropped=false] [position="channel_name:\"by-dev-rootcoord-dml_0_446748065920713215v0\" msgID:\"v\\000\\224\\214\\262\\2233\\006\" msgGroup:\"datanode-17-by-dev-rootcoord-dml_0_446748065920713215v0-true\" timestamp:446863189351333890 "] [PosTime=2024/01/07 17:16:26.527 +00:00]
[2024/01/07 17:16:36.393 +00:00] [INFO] [datanode/channel_meta.go:493] ["roll pk stats"] [segmentID=446748065920916737]
[2024/01/07 17:16:36.393 +00:00] [INFO] [datanode/flow_graph_insert_buffer_node.go:536] ["insertBufferNode finish submitting syncing bufferData"] [segmentID=446748065920916737] [flushed=false] [dropped=false] [auto=false] [position="channel_name:\"by-dev-rootcoord-dml_0_446748065920713215v0\" msgID:\"v\\000\\224\\214\\262\\2233\\006\" msgGroup:\"datanode-17-by-dev-rootcoord-dml_0_446748065920713215v0-true\" timestamp:446863189351333890 "] [channel=by-dev-rootcoord-dml_0_446748065920713215v0]
[2024/01/07 17:16:36.393 +00:00] [INFO] [datanode/flow_graph_delete_node.go:118] ["DeleteNode receives flush message"] [segIDs="[446748065920916737]"] [vChannelName=by-dev-rootcoord-dml_0_446748065920713215v0] [posTime=2024/01/07 17:16:26.527 +00:00]
[2024/01/07 17:16:36.393 +00:00] [INFO] [datanode/flush_manager.go:319] ["handling delete task"] [segmentID=446748065920916737]
[2024/01/07 17:16:39.891 +00:00] [WARN] [storage/remote_chunk_manager.go:128] ["failed to put object"] [bucket=a-bucket] [path=files/insert_log/446748065920713215/446748065920713216/446748065920916737/101/446863183117025457] [error="Resource requested is unreadable, please reduce your request rate"]
[2024/01/07 17:16:39.891 +00:00] [WARN] [datanode/flush_manager.go:690] ["failed to flush insert data"] [error="Resource requested is unreadable, please reduce your request rate"]
[2024/01/07 17:16:39.891 +00:00] [ERROR] [retry/retry.go:46] ["retry func failed"] ["retry time"=0] [error="Resource requested is unreadable, please reduce your request rate"] [stack="github.com/milvus-io/milvus/pkg/util/retry.Do\n\t/go/src/github.com/milvus-io/milvus/pkg/util/retry/retry.go:46\ngithub.com/milvus-io/milvus/internal/datanode.(*flushTaskRunner).runFlushInsert.func1.1\n\t/go/src/github.com/milvus-io/milvus/internal/datanode/flush_task.go:144"]
[2024/01/07 17:16:43.895 +00:00] [INFO] [datacoord/index_service.go:513] ["receive DescribeIndex request"] [traceID=bcc914a46a03854a701f47129391debe] [collectionID=446748065920713215] [indexName=] [timestamp=0]
[2024/01/07 17:16:43.895 +00:00] [INFO] [datacoord/index_service.go:449] ["completeIndexInfo success"] [collectionID=446748065920713215] [indexID=446748065920713230] [totalRows=0] [indexRows=0] [pendingIndexRows=0] [state=Finished] [failReason=]
[2024/01/07 17:16:43.895 +00:00] [INFO] [datacoord/index_service.go:560] ["DescribeIndex success"] [traceID=bcc914a46a03854a701f47129391debe] [collectionID=446748065920713215] [indexName=]
[2024/01/07 17:16:43.896 +00:00] [INFO] [querynodev2/services.go:1366] ["sync action"] [traceID=fff8be6669c9f3e02d7380881cc867bd] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [currentNodeID=17] [Action=UpdateVersion] [TargetVersion=1704647793896753148]
[2024/01/07 17:16:43.896 +00:00] [INFO] [delegator/distribution.go:294] ["Update readable segment version"] [oldVersion=1704647783896069713] [newVersion=1704647793896753148] [growingSegmentNum=1] [sealedSegmentNum=0]
[2024/01/07 17:16:43.896 +00:00] [INFO] [observers/target_observer.go:473] ["observer trigger update current target"] [collectionID=446748065920713215]
[2024/01/07 17:16:43.896 +00:00] [INFO] [datacoord/services.go:757] ["get recovery info request received"] [traceID=f64007190e0da4a4ad003d27d5e0f391] [collectionID=446748065920713215] [partitionIDs="[]"]
[2024/01/07 17:16:43.896 +00:00] [INFO] [datacoord/handler.go:116] [GetQueryVChanPositions] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [numOfSegments=1] ["indexed segment"=0]
[2024/01/07 17:16:43.896 +00:00] [INFO] [datacoord/handler.go:299] ["channel seek position set from channel checkpoint meta"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [posTs=446840488061042689] [posTime=2024/01/06 17:13:07.977 +00:00]
[2024/01/07 17:16:43.896 +00:00] [INFO] [datacoord/services.go:772] ["datacoord append channelInfo in GetRecoveryInfo"] [traceID=f64007190e0da4a4ad003d27d5e0f391] [collectionID=446748065920713215] [partitionIDs="[]"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] ["# of unflushed segments"=1] ["# of flushed segments"=0] ["# of dropped segments"=0] ["# of indexed segments"=0]
[2024/01/07 17:16:44.263 +00:00] [WARN] [storage/remote_chunk_manager.go:128] ["failed to put object"] [bucket=a-bucket] [path=files/insert_log/446748065920713215/446748065920713216/446748065920916737/101/446863183117025457] [error="Resource requested is unreadable, please reduce your request rate"]
[2024/01/07 17:16:44.263 +00:00] [WARN] [datanode/flush_manager.go:690] ["failed to flush insert data"] [error="Resource requested is unreadable, please reduce your request rate"]
[2024/01/07 17:16:48.968 +00:00] [WARN] [storage/remote_chunk_manager.go:128] ["failed to put object"] [bucket=a-bucket] [path=files/insert_log/446748065920713215/446748065920713216/446748065920916737/101/446863183117025457] [error="Resource requested is unreadable, please reduce your request rate"]
[2024/01/07 17:16:48.968 +00:00] [WARN] [datanode/flush_manager.go:690] ["failed to flush insert data"] [error="Resource requested is unreadable, please reduce your request rate"]
[2024/01/07 17:16:49.763 +00:00] [INFO] [gc/gc_tuner.go:90] ["GC Tune done"] ["previous GOGC"=200] ["heapuse "=40] ["total memory"=305] ["next GC"=78] ["new GOGC"=200] [gc-pause=61.637µs] [gc-pause-end=1704647809762425509]
[2024/01/07 17:16:53.895 +00:00] [INFO] [datacoord/index_service.go:513] ["receive DescribeIndex request"] [traceID=8091262aa5c478a2ff7d0e8c3cc429d1] [collectionID=446748065920713215] [indexName=] [timestamp=0]
[2024/01/07 17:16:53.895 +00:00] [INFO] [datacoord/index_service.go:449] ["completeIndexInfo success"] [collectionID=446748065920713215] [indexID=446748065920713230] [totalRows=0] [indexRows=0] [pendingIndexRows=0] [state=Finished] [failReason=]
[2024/01/07 17:16:53.895 +00:00] [INFO] [datacoord/index_service.go:560] ["DescribeIndex success"] [traceID=8091262aa5c478a2ff7d0e8c3cc429d1] [collectionID=446748065920713215] [indexName=]
[2024/01/07 17:16:53.895 +00:00] [INFO] [querynodev2/services.go:1366] ["sync action"] [traceID=c830aa7841f456ee2ac43f125d5deaef] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [currentNodeID=17] [Action=UpdateVersion] [TargetVersion=1704647803896542741]
[2024/01/07 17:16:53.896 +00:00] [INFO] [delegator/distribution.go:294] ["Update readable segment version"] [oldVersion=1704647793896753148] [newVersion=1704647803896542741] [growingSegmentNum=1] [sealedSegmentNum=0]
[2024/01/07 17:16:53.896 +00:00] [INFO] [observers/target_observer.go:473] ["observer trigger update current target"] [collectionID=446748065920713215]
[2024/01/07 17:16:53.896 +00:00] [INFO] [datacoord/services.go:757] ["get recovery info request received"] [traceID=98a12416b9f2121619200abd1da8f6f9] [collectionID=446748065920713215] [partitionIDs="[]"]
[2024/01/07 17:16:53.896 +00:00] [INFO] [datacoord/handler.go:116] [GetQueryVChanPositions] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [numOfSegments=1] ["indexed segment"=0]
[2024/01/07 17:16:53.896 +00:00] [INFO] [datacoord/handler.go:299] ["channel seek position set from channel checkpoint meta"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [posTs=446840488061042689] [posTime=2024/01/06 17:13:07.977 +00:00]
[2024/01/07 17:16:53.896 +00:00] [INFO] [datacoord/services.go:772] ["datacoord append channelInfo in GetRecoveryInfo"] [traceID=98a12416b9f2121619200abd1da8f6f9] [collectionID=446748065920713215] [partitionIDs="[]"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] ["# of unflushed segments"=1] ["# of flushed segments"=0] ["# of dropped segments"=0] ["# of indexed segments"=0]
[2024/01/07 17:16:54.833 +00:00] [WARN] [storage/remote_chunk_manager.go:128] ["failed to put object"] [bucket=a-bucket] [path=files/insert_log/446748065920713215/446748065920713216/446748065920916737/101/446863183117025457] [error="Resource requested is unreadable, please reduce your request rate"]
[2024/01/07 17:16:54.833 +00:00] [WARN] [datanode/flush_manager.go:690] ["failed to flush insert data"] [error="Resource requested is unreadable, please reduce your request rate"]
[2024/01/07 17:17:01.332 +00:00] [WARN] [storage/remote_chunk_manager.go:128] ["failed to put object"] [bucket=a-bucket] [path=files/insert_log/446748065920713215/446748065920713216/446748065920916737/101/446863183117025457] [error="Resource requested is unreadable, please reduce your request rate"]
[2024/01/07 17:17:01.332 +00:00] [WARN] [datanode/flush_manager.go:690] ["failed to flush insert data"] [error="Resource requested is unreadable, please reduce your request rate"]
[2024/01/07 17:17:01.332 +00:00] [ERROR] [retry/retry.go:46] ["retry func failed"] ["retry time"=4] [error="Resource requested is unreadable, please reduce your request rate"] [stack="github.com/milvus-io/milvus/pkg/util/retry.Do\n\t/go/src/github.com/milvus-io/milvus/pkg/util/retry/retry.go:46\ngithub.com/milvus-io/milvus/internal/datanode.(*flushTaskRunner).runFlushInsert.func1.1\n\t/go/src/github.com/milvus-io/milvus/internal/datanode/flush_task.go:144"]
[2024/01/07 17:17:03.895 +00:00] [INFO] [datacoord/index_service.go:513] ["receive DescribeIndex request"] [traceID=c3fe4b3e62b8b7e59b4757054201e03a] [collectionID=446748065920713215] [indexName=] [timestamp=0]
[2024/01/07 17:17:03.895 +00:00] [INFO] [datacoord/index_service.go:449] ["completeIndexInfo success"] [collectionID=446748065920713215] [indexID=446748065920713230] [totalRows=0] [indexRows=0] [pendingIndexRows=0] [state=Finished] [failReason=]
[2024/01/07 17:17:03.895 +00:00] [INFO] [datacoord/index_service.go:560] ["DescribeIndex success"] [traceID=c3fe4b3e62b8b7e59b4757054201e03a] [collectionID=446748065920713215] [indexName=]
[2024/01/07 17:17:03.895 +00:00] [INFO] [querynodev2/services.go:1366] ["sync action"] [traceID=ccc5abbdd503b287ae359379bf77f721] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [currentNodeID=17] [Action=UpdateVersion] [TargetVersion=1704647813896161268]
[2024/01/07 17:17:03.895 +00:00] [INFO] [delegator/distribution.go:294] ["Update readable segment version"] [oldVersion=1704647803896542741] [newVersion=1704647813896161268] [growingSegmentNum=1] [sealedSegmentNum=0]
[2024/01/07 17:17:03.895 +00:00] [INFO] [observers/target_observer.go:473] ["observer trigger update current target"] [collectionID=446748065920713215]
[2024/01/07 17:17:03.896 +00:00] [INFO] [datacoord/services.go:757] ["get recovery info request received"] [traceID=76c63dc075387a67d50a4d0ac600ecd9] [collectionID=446748065920713215] [partitionIDs="[]"]
[2024/01/07 17:17:03.896 +00:00] [INFO] [datacoord/handler.go:116] [GetQueryVChanPositions] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [numOfSegments=1] ["indexed segment"=0]
[2024/01/07 17:17:03.896 +00:00] [INFO] [datacoord/handler.go:299] ["channel seek position set from channel checkpoint meta"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [posTs=446840488061042689] [posTime=2024/01/06 17:13:07.977 +00:00]
[2024/01/07 17:17:03.896 +00:00] [INFO] [datacoord/services.go:772] ["datacoord append channelInfo in GetRecoveryInfo"] [traceID=76c63dc075387a67d50a4d0ac600ecd9] [collectionID=446748065920713215] [partitionIDs="[]"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] ["# of unflushed segments"=1] ["# of flushed segments"=0] ["# of dropped segments"=0] ["# of indexed segments"=0]
[2024/01/07 17:17:07.803 +00:00] [WARN] [storage/remote_chunk_manager.go:128] ["failed to put object"] [bucket=a-bucket] [path=files/insert_log/446748065920713215/446748065920713216/446748065920916737/101/446863183117025457] [error="Resource requested is unreadable, please reduce your request rate"]
[2024/01/07 17:17:07.803 +00:00] [WARN] [datanode/flush_manager.go:690] ["failed to flush insert data"] [error="Resource requested is unreadable, please reduce your request rate"]
[2024/01/07 17:17:13.895 +00:00] [INFO] [datacoord/index_service.go:513] ["receive DescribeIndex request"] [traceID=c94bfdc0e648fa2d073562cdb68d06c3] [collectionID=446748065920713215] [indexName=] [timestamp=0]
[2024/01/07 17:17:13.895 +00:00] [INFO] [datacoord/index_service.go:449] ["completeIndexInfo success"] [collectionID=446748065920713215] [indexID=446748065920713230] [totalRows=0] [indexRows=0] [pendingIndexRows=0] [state=Finished] [failReason=]
[2024/01/07 17:17:13.895 +00:00] [INFO] [datacoord/index_service.go:560] ["DescribeIndex success"] [traceID=c94bfdc0e648fa2d073562cdb68d06c3] [collectionID=446748065920713215] [indexName=]
[2024/01/07 17:17:13.896 +00:00] [INFO] [querynodev2/services.go:1366] ["sync action"] [traceID=8a8d4ac5a9c3bcf53b580bb4eaea1833] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [currentNodeID=17] [Action=UpdateVersion] [TargetVersion=1704647823895838505]
[2024/01/07 17:17:13.896 +00:00] [INFO] [delegator/distribution.go:294] ["Update readable segment version"] [oldVersion=1704647813896161268] [newVersion=1704647823895838505] [growingSegmentNum=1] [sealedSegmentNum=0]
[2024/01/07 17:17:13.896 +00:00] [INFO] [observers/target_observer.go:473] ["observer trigger update current target"] [collectionID=446748065920713215]
[2024/01/07 17:17:13.896 +00:00] [INFO] [datacoord/services.go:757] ["get recovery info request received"] [traceID=40ab784735f6efa0922a738ff7f6e221] [collectionID=446748065920713215] [partitionIDs="[]"]
[2024/01/07 17:17:13.896 +00:00] [INFO] [datacoord/handler.go:116] [GetQueryVChanPositions] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [numOfSegments=1] ["indexed segment"=0]
[2024/01/07 17:17:13.896 +00:00] [INFO] [datacoord/handler.go:299] ["channel seek position set from channel checkpoint meta"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [posTs=446840488061042689] [posTime=2024/01/06 17:13:07.977 +00:00]
[2024/01/07 17:17:13.896 +00:00] [INFO] [datacoord/services.go:772] ["datacoord append channelInfo in GetRecoveryInfo"] [traceID=40ab784735f6efa0922a738ff7f6e221] [collectionID=446748065920713215] [partitionIDs="[]"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] ["# of unflushed segments"=1] ["# of flushed segments"=0] ["# of dropped segments"=0] ["# of indexed segments"=0]
[2024/01/07 17:17:14.704 +00:00] [WARN] [storage/remote_chunk_manager.go:128] ["failed to put object"] [bucket=a-bucket] [path=files/insert_log/446748065920713215/446748065920713216/446748065920916737/101/446863183117025457] [error="Resource requested is unreadable, please reduce your request rate"]
[2024/01/07 17:17:14.704 +00:00] [WARN] [datanode/flush_manager.go:690] ["failed to flush insert data"] [error="Resource requested is unreadable, please reduce your request rate"]
[2024/01/07 17:17:23.070 +00:00] [WARN] [storage/remote_chunk_manager.go:128] ["failed to put object"] [bucket=a-bucket] [path=files/insert_log/446748065920713215/446748065920713216/446748065920916737/101/446863183117025457] [error="Resource requested is unreadable, please reduce your request rate"]
[2024/01/07 17:17:23.070 +00:00] [WARN] [datanode/flush_manager.go:690] ["failed to flush insert data"] [error="Resource requested is unreadable, please reduce your request rate"]
[2024/01/07 17:17:23.895 +00:00] [INFO] [datacoord/index_service.go:513] ["receive DescribeIndex request"] [traceID=bc6dafcd36a86fb0574f2bf80907304a] [collectionID=446748065920713215] [indexName=] [timestamp=0]
[2024/01/07 17:17:23.895 +00:00] [INFO] [datacoord/index_service.go:449] ["completeIndexInfo success"] [collectionID=446748065920713215] [indexID=446748065920713230] [totalRows=0] [indexRows=0] [pendingIndexRows=0] [state=Finished] [failReason=]
[2024/01/07 17:17:23.895 +00:00] [INFO] [datacoord/index_service.go:560] ["DescribeIndex success"] [traceID=bc6dafcd36a86fb0574f2bf80907304a] [collectionID=446748065920713215] [indexName=]
[2024/01/07 17:17:23.896 +00:00] [INFO] [querynodev2/services.go:1366] ["sync action"] [traceID=ce877f6a7821e896aff0af661b60f0c2] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [currentNodeID=17] [Action=UpdateVersion] [TargetVersion=1704647833896275750]
[2024/01/07 17:17:23.896 +00:00] [INFO] [delegator/distribution.go:294] ["Update readable segment version"] [oldVersion=1704647823895838505] [newVersion=1704647833896275750] [growingSegmentNum=1] [sealedSegmentNum=0]
[2024/01/07 17:17:23.896 +00:00] [INFO] [observers/target_observer.go:473] ["observer trigger update current target"] [collectionID=446748065920713215]
[2024/01/07 17:17:23.896 +00:00] [INFO] [datacoord/services.go:757] ["get recovery info request received"] [traceID=82aabe62d9a3a4a61033de89f0d9197b] [collectionID=446748065920713215] [partitionIDs="[]"]
[2024/01/07 17:17:23.896 +00:00] [INFO] [datacoord/handler.go:116] [GetQueryVChanPositions] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [numOfSegments=1] ["indexed segment"=0]
[2024/01/07 17:17:23.896 +00:00] [INFO] [datacoord/handler.go:299] ["channel seek position set from channel checkpoint meta"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [posTs=446840488061042689] [posTime=2024/01/06 17:13:07.977 +00:00]
[2024/01/07 17:17:23.896 +00:00] [INFO] [datacoord/services.go:772] ["datacoord append channelInfo in GetRecoveryInfo"] [traceID=82aabe62d9a3a4a61033de89f0d9197b] [collectionID=446748065920713215] [partitionIDs="[]"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] ["# of unflushed segments"=1] ["# of flushed segments"=0] ["# of dropped segments"=0] ["# of indexed segments"=0]
[2024/01/07 17:17:31.389 +00:00] [WARN] [storage/remote_chunk_manager.go:128] ["failed to put object"] [bucket=a-bucket] [path=files/insert_log/446748065920713215/446748065920713216/446748065920916737/101/446863183117025457] [error="Resource requested is unreadable, please reduce your request rate"]
[2024/01/07 17:17:31.389 +00:00] [WARN] [datanode/flush_manager.go:690] ["failed to flush insert data"] [error="Resource requested is unreadable, please reduce your request rate"]
[2024/01/07 17:17:31.389 +00:00] [ERROR] [retry/retry.go:46] ["retry func failed"] ["retry time"=8] [error="Resource requested is unreadable, please reduce your request rate"] [stack="github.com/milvus-io/milvus/pkg/util/retry.Do\n\t/go/src/github.com/milvus-io/milvus/pkg/util/retry/retry.go:46\ngithub.com/milvus-io/milvus/internal/datanode.(*flushTaskRunner).runFlushInsert.func1.1\n\t/go/src/github.com/milvus-io/milvus/internal/datanode/flush_task.go:144"]
[2024/01/07 17:17:33.361 +00:00] [INFO] [gc/gc_tuner.go:90] ["GC Tune done"] ["previous GOGC"=200] ["heapuse "=66] ["total memory"=279] ["next GC"=79] ["new GOGC"=200] [gc-pause=63.01µs] [gc-pause-end=1704647853361271101]
[2024/01/07 17:17:33.895 +00:00] [INFO] [datacoord/index_service.go:513] ["receive DescribeIndex request"] [traceID=a7ecafe8beff9df91f624f294fd63594] [collectionID=446748065920713215] [indexName=] [timestamp=0]
[2024/01/07 17:17:33.895 +00:00] [INFO] [datacoord/index_service.go:449] ["completeIndexInfo success"] [collectionID=446748065920713215] [indexID=446748065920713230] [totalRows=0] [indexRows=0] [pendingIndexRows=0] [state=Finished] [failReason=]
[2024/01/07 17:17:33.895 +00:00] [INFO] [datacoord/index_service.go:560] ["DescribeIndex success"] [traceID=a7ecafe8beff9df91f624f294fd63594] [collectionID=446748065920713215] [indexName=]
[2024/01/07 17:17:33.896 +00:00] [INFO] [querynodev2/services.go:1366] ["sync action"] [traceID=f04ae97571d7739015acbaf0a082aaf4] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [currentNodeID=17] [Action=UpdateVersion] [TargetVersion=1704647843896395502]
[2024/01/07 17:17:33.896 +00:00] [INFO] [delegator/distribution.go:294] ["Update readable segment version"] [oldVersion=1704647833896275750] [newVersion=1704647843896395502] [growingSegmentNum=1] [sealedSegmentNum=0]
[2024/01/07 17:17:33.896 +00:00] [INFO] [observers/target_observer.go:473] ["observer trigger update current target"] [collectionID=446748065920713215]
[2024/01/07 17:17:33.896 +00:00] [INFO] [datacoord/services.go:757] ["get recovery info request received"] [traceID=641c25679cb6e29594ff6d1d0c8a5b8d] [collectionID=446748065920713215] [partitionIDs="[]"]
[2024/01/07 17:17:33.896 +00:00] [INFO] [datacoord/handler.go:116] [GetQueryVChanPositions] [collectionID=446748065920713215] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [numOfSegments=1] ["indexed segment"=0]
[2024/01/07 17:17:33.896 +00:00] [INFO] [datacoord/handler.go:299] ["channel seek position set from channel checkpoint meta"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] [posTs=446840488061042689] [posTime=2024/01/06 17:13:07.977 +00:00]
[2024/01/07 17:17:33.896 +00:00] [INFO] [datacoord/services.go:772] ["datacoord append channelInfo in GetRecoveryInfo"] [traceID=641c25679cb6e29594ff6d1d0c8a5b8d] [collectionID=446748065920713215] [partitionIDs="[]"] [channel=by-dev-rootcoord-dml_0_446748065920713215v0] ["# of unflushed segments"=1] ["# of flushed segments"=0] ["# of dropped segments"=0] ["# of indexed segments"=0]
[2024/01/07 17:17:37.866 +00:00] [WARN] [storage/remote_chunk_manager.go:128] ["failed to put object"] [bucket=a-bucket] [path=files/insert_log/446748065920713215/446748065920713216/446748065920916737/101/446863183117025457] [error="Resource requested is unreadable, please reduce your request rate"]
[2024/01/07 17:17:37.866 +00:00] [WARN] [datanode/flush_manager.go:690] ["failed to flush insert data"] [error="Resource requested is unreadable, please reduce your request rate"]
[2024/01/07 17:17:40.867 +00:00] [WARN] [datanode/flush_task.go:232] ["flush task error detected"] [error="attempt #0: Resource requested is unreadable, please reduce your request rate: attempt #1: Resource requested is unreadable, please reduce your request rate: attempt #2: Resource requested is unreadable, please reduce your request rate: attempt #3: Resource requested is unreadable, please reduce your request rate: attempt #4: Resource requested is unreadable, please reduce your request rate: attempt #5: Resource requested is unreadable, please reduce your request rate: attempt #6: Resource requested is unreadable, please reduce your request rate: attempt #7: Resource requested is unreadable, please reduce your request rate: attempt #8: Resource requested is unreadable, please reduce your request rate: attempt #9: Resource requested is unreadable, please reduce your request rate"] []
[2024/01/07 17:17:40.867 +00:00] [ERROR] [datanode/flush_manager.go:860] ["flush pack with error, DataNode quit now"] [segmentID=446748065920916737] [collectionID=446748065920713215] [vchannel=by-dev-rootcoord-dml_0_446748065920713215v0] [error="execution failed"] [errorVerbose="execution failed\n(1) attached stack trace\n  -- stack trace:\n  | github.com/milvus-io/milvus/internal/datanode.(*flushTaskRunner).getFlushPack\n  | \t/go/src/github.com/milvus-io/milvus/internal/datanode/flush_task.go:233\n  | github.com/milvus-io/milvus/internal/datanode.(*flushTaskRunner).waitFinish\n  | \t/go/src/github.com/milvus-io/milvus/internal/datanode/flush_task.go:190\n  | runtime.goexit\n  | \t/usr/local/go/src/runtime/asm_amd64.s:1598\nWraps: (2) execution failed\nError types: (1) *withstack.withStack (2) *errutil.leafError"] [stack="github.com/milvus-io/milvus/internal/datanode.flushNotifyFunc.func1\n\t/go/src/github.com/milvus-io/milvus/internal/datanode/flush_manager.go:860\ngithub.com/milvus-io/milvus/internal/datanode.(*flushTaskRunner).waitFinish\n\t/go/src/github.com/milvus-io/milvus/internal/datanode/flush_task.go:206"]

yanliang567 commented 8 months ago

it seems that milvus keeps failing in reading&writing to the volumes. @congqixia could you please help to double check that? /assign @congqixia /unassign

xiaofan-luan commented 8 months ago

failed to flush insert data"] [error="Resource requested is unreadable, please reduce your request rate]

how many collections you have? is it S3, minio or other storage? seems there is a io limitation

devasheeshG commented 8 months ago

I have only one collection and standard installation of milvus locally on unraid. If you want I can share a zip of volume folder.

Leoeeeeeeea commented 7 months ago

I also have the same questions , do you have a solution ？

yanliang567 commented 7 months ago

Could you please refer this doc to export the whole Milvus logs for investigation? For Milvus installed with docker-compose, you can use docker-compose logs > milvus.log to export the logs.

devasheeshG commented 7 months ago

This is not fixed yet. My docker compose file looks like this

version: '3.5'

services:
  etcd:
    container_name: milvus-etcd
    image: quay.io/coreos/etcd:v3.5.5
    privileged: true
    environment:
      - ETCD_AUTO_COMPACTION_MODE=revision
      - ETCD_AUTO_COMPACTION_RETENTION=1000
      - ETCD_QUOTA_BACKEND_BYTES=4294967296
      - ETCD_SNAPSHOT_COUNT=50000
#      - TZ=Asia/Kolkata
#      - TZ=UTC+5:30
    volumes:
      - ${DOCKER_VOLUME_DIRECTORY:-.}/volumes/etcd:/etcd
    command: etcd -advertise-client-urls=http://127.0.0.1:2379 -listen-client-urls http://0.0.0.0:2379 --data-dir /etcd
    healthcheck:
      test: ["CMD", "etcdctl", "endpoint", "health"]
      interval: 30s
      timeout: 20s
      retries: 3

  minio:
    container_name: milvus-minio
    image: minio/minio:RELEASE.2023-03-20T20-16-18Z
    privileged: true
    environment:
#      TZ: Asia/Kolkata
#      TZ: UTC+5:30
      MINIO_ACCESS_KEY: minioadmin
      MINIO_SECRET_KEY: minioadmin
    ports:
      - "9001:9001"
      - "9000:9000"
    volumes:
      - ${DOCKER_VOLUME_DIRECTORY:-.}/volumes/minio:/minio_data
    command: minio server /minio_data --console-address ":9001"
    healthcheck:
      test: ["CMD", "curl", "-f", "http://localhost:9000/minio/health/live"]
      interval: 30s
      timeout: 20s
      retries: 3

  standalone:
    container_name: milvus-standalone
    image: milvusdb/milvus:v2.3.5
    command: ["milvus", "run", "standalone"]
    privileged: true
    security_opt:
      - seccomp:unconfined
    environment:
#      TZ: Asia/Kolkata
#      TZ: UTC+5:30
      ETCD_ENDPOINTS: etcd:2379
      MINIO_ADDRESS: minio:9000
    volumes:
      - ${DOCKER_VOLUME_DIRECTORY:-.}/volumes/milvus:/var/lib/milvus
    healthcheck:
      test: ["CMD", "curl", "-f", "http://localhost:9091/healthz"]
      interval: 30s
      start_period: 90s
      timeout: 20s
      retries: 3
    ports:
      - "19530:19530"
      - "9091:9091"
    depends_on:
      - "etcd"
      - "minio"

networks:
  default:
    name: milvus

Leoeeeeeeea commented 7 months ago

你好，请问有没有解决办法呢？

yanliang567 commented 7 months ago

any one can share the full logs of milvus? we cannot tell the solutions without knowing what was hanppening. please refer this doc to export the whole Milvus logs for investigation? For Milvus installed with docker-compose, you can use docker-compose logs > milvus.log to export the logs.

Leoeeeeeeea commented 7 months ago

我跟题主的报错完全一样，请问有解决方法了吗

xiaofan-luan commented 7 months ago

I thought

[2024/01/07 17:17:37.866 +00:00] [WARN] [storage/remote_chunk_manager.go:128] ["failed to put object"] [bucket=a-bucket] [path=files/insert_log/446748065920713215/446748065920713216/446748065920916737/101/446863183117025457] [error="Resource requested is unreadable, please reduce your request rate"] [2024/01/07 17:17:37.866 +00:00] [WARN] [datanode/flush_manager.go:690] ["failed to flush insert data"] [error="Resource requested is unreadable, please reduce your request rate"]

is the main problem.

The minio is unreadable for some reason. Did you check your disk usage from both iops and disk space? Milvus can not flush because minio did rate limit, that is the main reason mivlus abort itself

xiaofan-luan commented 7 months ago

@congqixia in the 2.4 branch, shall we hold all flush request and retry later?

xiaofan-luan commented 7 months ago

@yanliang567 I guess this is reproducible on a large pod -> 32 core and above and with a slow disk(like hdds). The load is gonna to be super slow -> which is expected but milvus should not crash.

xiaofan-luan commented 7 months ago

Environment
- Milvus version: 2.3.4
- Deployment mode(standalone or cluster): standalone
- MQ type(rocksmq, pulsar or kafka):    
- SDK version(e.g. pymilvus v2.0.0rc2):
- OS(Ubuntu or CentOS): Unraid OS v6.12.6
- CPU/Memory: Ryzen5 3600x / 48GB
- GPU: 2 x Tesla P60 (but running CPU version)
- Others: Docker version 20.10.24, build 297e128 | Docker Compose version v2.21.0
Current Behavior

container milvus-standalone automatically exits after loading a collection.

Milvus Log

github.com/panjf2000/ants/v2.(goWorker).run.func1() /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:63 +0x7b fp=0xc0044d5fe0 sp=0xc0044d5f88 pc=0x3396e1b runtime.goexit() /usr/local/go/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc0044d5fe8 sp=0xc0044d5fe0 pc=0x1a609e1 created by github.com/panjf2000/ants/v2.(goWorker).run /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:48 +0x65

goroutine 9740 [chan receive, 1 minutes, locked to thread]: runtime.gopark(0x730d868?, 0x4faff38?, 0x0?, 0x0?, 0x8?) /usr/local/go/src/runtime/proc.go:381 +0xd6 fp=0xc0043cced0 sp=0xc0043cceb0 pc=0x1a2a116 runtime.chanrecv(0xc001f4c780, 0xc0043ccfa8, 0x1) /usr/local/go/src/runtime/chan.go:583 +0x49d fp=0xc0043ccf60 sp=0xc0043cced0 pc=0x19f25fd runtime.chanrecv2(0xc001ce6460?, 0xc002d59770?) /usr/local/go/src/runtime/chan.go:447 +0x18 fp=0xc0043ccf88 sp=0xc0043ccf60 pc=0x19f2138 github.com/panjf2000/ants/v2.(goWorker).run.func1() /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:63 +0x7b fp=0xc0043ccfe0 sp=0xc0043ccf88 pc=0x3396e1b runtime.goexit() /usr/local/go/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc0043ccfe8 sp=0xc0043ccfe0 pc=0x1a609e1 created by github.com/panjf2000/ants/v2.(goWorker).run /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:48 +0x65

goroutine 9741 [chan receive, 1 minutes, locked to thread]: runtime.gopark(0x730d868?, 0x4faff38?, 0x0?, 0x0?, 0x8?) /usr/local/go/src/runtime/proc.go:381 +0xd6 fp=0xc003bc1ed0 sp=0xc003bc1eb0 pc=0x1a2a116 runtime.chanrecv(0xc001f4c7e0, 0xc003bc1fa8, 0x1) /usr/local/go/src/runtime/chan.go:583 +0x49d fp=0xc003bc1f60 sp=0xc003bc1ed0 pc=0x19f25fd runtime.chanrecv2(0xc001ce6460?, 0xc002d59830?) /usr/local/go/src/runtime/chan.go:447 +0x18 fp=0xc003bc1f88 sp=0xc003bc1f60 pc=0x19f2138 github.com/panjf2000/ants/v2.(goWorker).run.func1() /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:63 +0x7b fp=0xc003bc1fe0 sp=0xc003bc1f88 pc=0x3396e1b runtime.goexit() /usr/local/go/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc003bc1fe8 sp=0xc003bc1fe0 pc=0x1a609e1 created by github.com/panjf2000/ants/v2.(goWorker).run /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:48 +0x65

goroutine 9742 [chan receive, 1 minutes, locked to thread]: runtime.gopark(0x730d868?, 0x4faff38?, 0x0?, 0x0?, 0x8?) /usr/local/go/src/runtime/proc.go:381 +0xd6 fp=0xc0033fded0 sp=0xc0033fdeb0 pc=0x1a2a116 runtime.chanrecv(0xc001f4c840, 0xc0033fdfa8, 0x1) /usr/local/go/src/runtime/chan.go:583 +0x49d fp=0xc0033fdf60 sp=0xc0033fded0 pc=0x19f25fd runtime.chanrecv2(0xc001ce6460?, 0xc002d598f0?) /usr/local/go/src/runtime/chan.go:447 +0x18 fp=0xc0033fdf88 sp=0xc0033fdf60 pc=0x19f2138 github.com/panjf2000/ants/v2.(goWorker).run.func1() /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:63 +0x7b fp=0xc0033fdfe0 sp=0xc0033fdf88 pc=0x3396e1b runtime.goexit() /usr/local/go/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc0033fdfe8 sp=0xc0033fdfe0 pc=0x1a609e1 created by github.com/panjf2000/ants/v2.(goWorker).run /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:48 +0x65

goroutine 9743 [chan receive, 1 minutes, locked to thread]: runtime.gopark(0x730d868?, 0x4faff38?, 0x0?, 0x0?, 0x8?) /usr/local/go/src/runtime/proc.go:381 +0xd6 fp=0xc002395ed0 sp=0xc002395eb0 pc=0x1a2a116 runtime.chanrecv(0xc001f4c8a0, 0xc002395fa8, 0x1) /usr/local/go/src/runtime/chan.go:583 +0x49d fp=0xc002395f60 sp=0xc002395ed0 pc=0x19f25fd runtime.chanrecv2(0xc001ce6460?, 0xc002d599b0?) /usr/local/go/src/runtime/chan.go:447 +0x18 fp=0xc002395f88 sp=0xc002395f60 pc=0x19f2138 github.com/panjf2000/ants/v2.(goWorker).run.func1() /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:63 +0x7b fp=0xc002395fe0 sp=0xc002395f88 pc=0x3396e1b runtime.goexit() /usr/local/go/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc002395fe8 sp=0xc002395fe0 pc=0x1a609e1 created by github.com/panjf2000/ants/v2.(goWorker).run /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:48 +0x65

goroutine 12460 [chan receive]: runtime.gopark(0xc00401a120?, 0xc0024bd7a8?, 0x0?, 0x0?, 0xc003dc8712?) /usr/local/go/src/runtime/proc.go:381 +0xd6 fp=0xc000594ed0 sp=0xc000594eb0 pc=0x1a2a116 runtime.chanrecv(0xc001fb7560, 0xc000594fa8, 0x1) /usr/local/go/src/runtime/chan.go:583 +0x49d fp=0xc000594f60 sp=0xc000594ed0 pc=0x19f25fd runtime.chanrecv2(0xc001065040?, 0xc0027b98f0?) /usr/local/go/src/runtime/chan.go:447 +0x18 fp=0xc000594f88 sp=0xc000594f60 pc=0x19f2138 github.com/panjf2000/ants/v2.(goWorker).run.func1() /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:63 +0x7b fp=0xc000594fe0 sp=0xc000594f88 pc=0x3396e1b runtime.goexit() /usr/local/go/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc000594fe8 sp=0xc000594fe0 pc=0x1a609e1 created by github.com/panjf2000/ants/v2.(goWorker).run /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:48 +0x65

goroutine 12663 [chan receive]: runtime.gopark(0x6332affbd4c01ff?, 0xc00276cf18?, 0x0?, 0x0?, 0xc000e91230?) /usr/local/go/src/runtime/proc.go:381 +0xd6 fp=0xc00276ced0 sp=0xc00276ceb0 pc=0x1a2a116 runtime.chanrecv(0xc001bbede0, 0xc00276cfa8, 0x1) /usr/local/go/src/runtime/chan.go:583 +0x49d fp=0xc00276cf60 sp=0xc00276ced0 pc=0x19f25fd runtime.chanrecv2(0xc0003b9220?, 0xc0056a4390?) /usr/local/go/src/runtime/chan.go:447 +0x18 fp=0xc00276cf88 sp=0xc00276cf60 pc=0x19f2138 github.com/panjf2000/ants/v2.(goWorker).run.func1() /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:63 +0x7b fp=0xc00276cfe0 sp=0xc00276cf88 pc=0x3396e1b runtime.goexit() /usr/local/go/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc00276cfe8 sp=0xc00276cfe0 pc=0x1a609e1 created by github.com/panjf2000/ants/v2.(goWorker).run /go/pkg/mod/github.com/panjf2000/ants/v2@v2.7.2/worker.go:48 +0x65

我跟题主的报错完全一样，请问有解决方法了吗

Did you check your disk iops? what kind of disk you are using as data directory?

C-rawler commented 7 months ago

I also have the same questions , do you have a solution ？Or does this have something to do with the long-term loading of collections when I deploy the interface?

huyang19881115 commented 6 months ago

一样的报错 [Uploading milvcus_error.log…]()

yanliang567 commented 6 months ago

一样的报错 Uploading milvcus_error.log…

not able to donwload the log file

huyang19881115 commented 6 months ago

sorry, i have solve this error.

compare the config ,find rootCoord without address ，so it can n't connect the rootCoord Service。 Since chage the config ，it works correct. address: localhost

修复了这个问题，就是配置文件里面少了一些配置导致的。

@.***

From: yanliang567 Date: 2024-03-20 15:57 To: milvus-io/milvus CC: 胡洋; Comment Subject: Re: [milvus-io/milvus] [Bug]: In milvus-standalone docker container. Issue related to goroutine, automaticly exits with code 134 after sometime. If no collection is loaded, no problem is caused. (Issue #29744) 一样的报错 Uploading milvcus_error.log… not able to donwload the log file — Reply to this email directly, view it on GitHub, or unsubscribe. You are receiving this because you commented.Message ID: @.***>

stale[bot] commented 3 months ago

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.

likhitha283 commented 2 months ago

/reopen

sre-ci-robot commented 2 months ago

@likhitha283: You can't reopen an issue/PR unless you authored it or you are a collaborator.

In response to [this](https://github.com/milvus-io/milvus/issues/29744#issuecomment-2233736040): >/reopen > Instructions for interacting with me using PR comments are available [here](https://git.k8s.io/community/contributors/guide/pull-requests.md). If you have questions or suggestions related to my behavior, please file an issue against the [kubernetes/test-infra](https://github.com/kubernetes/test-infra/issues/new?title=Prow%20issue:) repository.

yanliang567 commented 2 months ago

I guess this is reproducible on a large pod -> 32 core and above and with a slow disk(like hdds). The load is gonna to be super slow -> which is expected but milvus should not crash.

@likhitha283 do you have the same situation above above?

NamNX1409 commented 1 week ago

I have the same problem as the author. Can you guys help me to solve it? Here is my log: milvus.log

NamNX1409 commented 1 week ago

/reopen

sre-ci-robot commented 1 week ago

@NamNX1409: You can't reopen an issue/PR unless you authored it or you are a collaborator.

In response to [this](https://github.com/milvus-io/milvus/issues/29744#issuecomment-2333222462): >/reopen > Instructions for interacting with me using PR comments are available [here](https://git.k8s.io/community/contributors/guide/pull-requests.md). If you have questions or suggestions related to my behavior, please file an issue against the [kubernetes/test-infra](https://github.com/kubernetes/test-infra/issues/new?title=Prow%20issue:) repository.

xiaofan-luan commented 1 week ago

I have the same problem as the author. Can you guys help me to solve it? Here is my log: milvus.log

files/insert_log/452337435696709883/452337435696709884/452337435696909953/102/452354935055712590: IO failed[key=files/insert_log/452337435696709883/452337435696709884/452337435696909953/102/452354935055712590]: Resource requested is unreadable, please reduce your request rate [recovered]

i think you got this error becasue your minio/S3 is rated limited. are you doing some kind of manual flush or some other operations?

milvus-io / milvus