[Bug]: Flush hangs when running hello_milvus.py after pulsar recovered from pod kill chaos

[zhuwenxing]

Is there an existing issue for this?

• I have searched the existing issues

Environment

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

Current Behavior

The action has timed out when running hello_milvus.py
Outputting duplicate logs in proxy pod

[2022/06/12 18:57:51.851 +00:00] [INFO] [impl.go:3587] ["received get flush state response"] [response="status:<> "]
[2022/06/12 18:57:52.355 +00:00] [INFO] [impl.go:3573] ["received get flush state request"] [request="segmentIDs:433864038933069825 segmentIDs:433864038933069826 "]
[2022/06/12 18:57:52.356 +00:00] [INFO] [impl.go:3587] ["received get flush state response"] [response="status:<> "]
[2022/06/12 18:57:52.861 +00:00] [INFO] [impl.go:3573] ["received get flush state request"] [request="segmentIDs:433864038933069825 segmentIDs:433864038933069826 "]
[2022/06/12 18:57:52.866 +00:00] [INFO] [impl.go:3587] ["received get flush state response"] [response="status:<> "]
[2022/06/12 18:57:53.370 +00:00] [INFO] [impl.go:3573] ["received get flush state request"] [request="segmentIDs:433864038933069825 segmentIDs:433864038933069826 "]
[2022/06/12 18:57:53.370 +00:00] [INFO] [impl.go:3587] ["received get flush state response"] [response="status:<> "]
[2022/06/12 18:57:53.873 +00:00] [INFO] [impl.go:3573] ["received get flush state request"] [request="segmentIDs:433864038933069825 segmentIDs:433864038933069826 "]
[2022/06/12 18:57:53.877 +00:00] [INFO] [impl.go:3587] ["received get flush state response"] [response="status:<> "]
[2022/06/12 18:57:54.379 +00:00] [INFO] [impl.go:3573] ["received get flush state request"] [request="segmentIDs:433864038933069825 segmentIDs:433864038933069826 "]
[2022/06/12 18:57:54.381 +00:00] [INFO] [impl.go:3587] ["received get flush state response"] [response="status:<> "]
[2022/06/12 18:57:54.884 +00:00] [INFO] [impl.go:3573] ["received get flush state request"] [request="segmentIDs:433864038933069825 segmentIDs:433864038933069826 "]
[2022/06/12 18:57:54.885 +00:00] [INFO] [impl.go:3587] ["received get flush state response"] [response="status:<> "]

Expected Behavior

all test cases passed

Steps To Reproduce

see https://github.com/milvus-io/milvus/runs/6851761481?check_suite_focus=true

Milvus Log

failed job: https://github.com/milvus-io/milvus/runs/6851761481?check_suite_focus=true
log: https://github.com/milvus-io/milvus/suites/6898913792/artifacts/267696164

Anything else?

No response

[yanliang567]

@XuanYang-cn one more flush hang issue...
/assign @XuanYang-cn
/unassign

[XuanYang-cn]

may related to #17335, working on it

[XuanYang-cn]

/assign @zhuwenxing
Could you please have another try with the latest master commit?

[zhuwenxing]

It still happened in version master-20220613-e6225d92
Your PR is merged in the version

failed job: https://github.com/zhuwenxing/milvus/runs/6857375279?check_suite_focus=true
but the log is not collected due to the job is timeout, not the failure

I will try it again

[zhuwenxing]

failed job: https://github.com/zhuwenxing/milvus/runs/6858068872?check_suite_focus=true
log: https://github.com/zhuwenxing/milvus/suites/6904892315/artifacts/268116140

In GitHub action, this issue seems stable reproduced

[zhuwenxing]

It also failed in Jenkins pipeline。
failed job: http://10.100.32.144:8080/blue/organizations/jenkins/chaos-test/detail/chaos-test/6447/pipeline
log: artifacts-pulsar-pod-kill-6447-server-logs.tar.gz

[XuanYang-cn]

15143 time="2022-06-13T10:27:40Z" level=info msg="[Connected consumer]" consumerID=2 name=rmflb subscription=by-dev-dataNode-11-433878722880733185 topic="persistent://public/default/by-dev-rootcoord-dml_2"
15144 time="2022-06-13T10:27:40Z" level=warning msg="Closed connection unable add consumer with id=2" local_addr="10.97.4.243:47140" remote_addr="pulsar://pulsar-pod-kill-6447-proxy:6650"
15145 time="2022-06-13T10:27:40Z" level=info msg="[Reconnected consumer to broker]" consumerID=2 name=rmflb subscription=by-dev-dataNode-11-433878722880733185 topic="persistent://public/default/by-dev-rootcoord-dml_2"
15146 time="2022-06-13T10:27:40Z" level=warning msg="Connection closed unable register listener id=24" local_addr="10.97.4.243:47140" remote_addr="pulsar://pulsar-pod-kill-6447-proxy:6650"

The same reason as #14577, this time it's DataNode's consumer didn't reconnected with pulsar

Related issues:

apache/pulsar-client-go#785

apache/pulsar-client-go#733

apache/pulsar-client-go#698

[XuanYang-cn]

/assign @xige-16

[XuanYang-cn]

failed job: https://github.com/zhuwenxing/milvus/runs/6858068872?check_suite_focus=true log: https://github.com/zhuwenxing/milvus/suites/6904892315/artifacts/268116140

In GitHub action, this issue seems stable reproduced

 3955 time="2022-06-13T09:06:13Z" level=info msg="[Connected consumer]" consumerID=2 name=tiuxt subscription=by-dev-dataNode-10-433877445462920513 topic="persistent://public/default/by-dev-rootcoord-dml_0"
 3956 time="2022-06-13T09:06:13Z" level=warning msg="Closed connection unable add consumer with id=2" local_addr="10.244.0.8:39730" remote_addr="pulsar://test-pulsar-pod-kill-proxy:6650"
 3957 time="2022-06-13T09:06:13Z" level=info msg="[Reconnected consumer to broker]" consumerID=2 name=tiuxt subscription=by-dev-dataNode-10-433877445462920513 topic="persistent://public/default/by-dev-rootcoord-dml_0"
 3958 time="2022-06-13T09:06:13Z" level=info msg="[Connected consumer]" consumerID=46 name=cierj subscription=by-dev-dataNode-10-433877462149496833 topic="persistent://public/default/by-dev-rootcoord-dml_45"
 3959 time="2022-06-13T09:06:13Z" level=warning msg="Closed connection unable add consumer with id=46" local_addr="10.244.0.8:39730" remote_addr="pulsar://test-pulsar-pod-kill-proxy:6650"

[XuanYang-cn]

/unassign @xige-16 @XuanYang-cn
/assign @sunby

Please help to fix this

[zhuwenxing]

Flush hangs when running verify_all_collections.py after chaos

failed job:https://github.com/zhuwenxing/milvus/runs/6886845770?check_suite_focus=true
log: https://github.com/zhuwenxing/milvus/suites/6932123471/artifacts/269859110

[sunby]

/assign @zhuwenxing
please verify it.

[zhuwenxing]

failed job: https://github.com/zhuwenxing/milvus/runs/6936878605?check_suite_focus=true

/assign @sunby
Please take a look

[sunby]

Fixed in #17642

[xiaofan-luan]

@zhuwenxing pls help on verifying it

[zhuwenxing]

/assign @sunby
version master-20220621-746aeea3
failed job: http://10.100.32.144:8080/blue/organizations/jenkins/chaos-test/detail/chaos-test/6943/pipeline
log: artifacts-pulsar-pod-kill-6943-server-logs.tar.gz

[sunby]

There is a bug in datacoord. Consider this situation, a segment is allocated by datacoord and the proxy tries to insert some records to it. But pulsar is killed at this moment and this segment is still empty. After calling Flush on proxy, datacoord will retrun a segment list containing segments that are waiting to be flushed. But datacoord won't flush empty segment, so this segment's state is always Sealed and the flush hang.

I will fix it by setting the state of segment to Dropped if datacoord find this segment is empty. And the GetFlushState will check the segment whether is empty.

Thanks for the great job. @zhuwenxing

[sunby]

/unassign

[sunby]

/assign @zhuwenxing please verify

[zhuwenxing]

Not reproduced yet, remove the critical label.

[stale]

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.

[xiaofan-luan]

I have one question about this issue.
By flushing(we should definitely name it as sync, flush is more like seal the segment), user want to ensure all the inserted data is synced to Minio.
After the change the semantic has been breaked, we have no guarantee that inserted data is on minio, which may cause data loss when you do backup or migration.
My suggestion is:

1. Flush should still return all known segment list related
2. Handle the case of empty segment flush to avoid hang, any thoughts?