[Bug]: flush failed with message failed to call flush to data coordinator: channel not found after milvus recovered from standalone pod kill chaos test

[zhuwenxing]

Is there an existing issue for this?

• I have searched the existing issues

Environment

- Milvus version:master-20250106-f0cddfd1-amd64
- Deployment mode(standalone or cluster):standalone
- MQ type(rocksmq, pulsar or kafka):rocksmq
- SDK version(e.g. pymilvus v2.0.0rc2):
- OS(Ubuntu or CentOS): 
- CPU/Memory: 
- GPU: 
- Others:

Current Behavior

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:10 - INFO - ci_test]: [initialize_milvus] Log cleaned up, start testing... (conftest.py:233)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:10 - INFO - ci_test]: [setup_class] Start setup class... (client_base.py:41)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:10 - INFO - ci_test]: *********************************** setup *********************************** (client_base.py:47)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:10 - INFO - ci_test]: pymilvus version: 2.6.0rc44 (client_base.py:48)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:10 - INFO - ci_test]: [setup_method] Start setup test case test_milvus_default. (client_base.py:49)

[2025-01-06T07:23:03.682Z] ------------------------------ Captured log call -------------------------------

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:10 - DEBUG - ci_test]: (api_request)  : [FieldSchema] args: ['int64', <DataType.INT64: 5>, ''], kwargs: {'is_primary': False, 'is_partition_key': False, 'nullable': False} (api_request.py:52)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:10 - DEBUG - ci_test]: (api_response) : {'name': 'int64', 'description': '', 'type': <DataType.INT64: 5>}  (api_request.py:27)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:10 - DEBUG - ci_test]: (api_request)  : [FieldSchema] args: ['varchar', <DataType.VARCHAR: 21>, ''], kwargs: {'max_length': 65535, 'is_primary': False, 'is_partition_key': False, 'nullable': False} (api_request.py:52)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:10 - DEBUG - ci_test]: (api_response) : {'name': 'varchar', 'description': '', 'type': <DataType.VARCHAR: 21>, 'params': {'max_length': 65535}}  (api_request.py:27)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:10 - DEBUG - ci_test]: (api_request)  : [FieldSchema] args: ['float_vector', <DataType.FLOAT_VECTOR: 101>, ''], kwargs: {'dim': 128, 'is_primary': False, 'nullable': False} (api_request.py:52)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:10 - DEBUG - ci_test]: (api_response) : {'name': 'float_vector', 'description': '', 'type': <DataType.FLOAT_VECTOR: 101>, 'params': {'dim': 128}}  (api_request.py:27)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:10 - DEBUG - ci_test]: (api_request)  : [FieldSchema] args: ['float', <DataType.FLOAT: 10>, ''], kwargs: {'is_primary': False, 'nullable': False} (api_request.py:52)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:10 - DEBUG - ci_test]: (api_response) : {'name': 'float', 'description': '', 'type': <DataType.FLOAT: 10>}  (api_request.py:27)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:10 - DEBUG - ci_test]: (api_request)  : [FieldSchema] args: ['json_field', <DataType.JSON: 23>, ''], kwargs: {'is_primary': False, 'nullable': False} (api_request.py:52)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:10 - DEBUG - ci_test]: (api_response) : {'name': 'json_field', 'description': '', 'type': <DataType.JSON: 23>}  (api_request.py:27)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:10 - DEBUG - ci_test]: (api_request)  : [CollectionSchema] args: [[{'name': 'int64', 'description': '', 'type': <DataType.INT64: 5>}, {'name': 'float', 'description': '', 'type': <DataType.FLOAT: 10>}, {'name': 'varchar', 'description': '', 'type': <DataType.VARCHAR: 21>, 'params': {'max_length': 65535}}, {'name': 'json_field', 'description': '', 'type': <DataTyp......, kwargs: {'primary_field': 'int64', 'auto_id': False, 'enable_dynamic_field': False} (api_request.py:52)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:10 - DEBUG - ci_test]: (api_response) : {'auto_id': False, 'description': '', 'fields': [{'name': 'int64', 'description': '', 'type': <DataType.INT64: 5>, 'is_primary': True, 'auto_id': False}, {'name': 'float', 'description': '', 'type': <DataType.FLOAT: 10>}, {'name': 'varchar', 'description': '', 'type': <DataType.VARCHAR: 21>, 'params......  (api_request.py:27)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:10 - DEBUG - ci_test]: (api_request)  : [Connections.has_connection] args: ['default'], kwargs: {} (api_request.py:52)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:10 - DEBUG - ci_test]: (api_response) : False  (api_request.py:27)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:10 - DEBUG - ci_test]: (api_request)  : [Connections.connect] args: ['default', '', '', 'default', ''], kwargs: {'host': '10.255.33.41', 'port': 19530} (api_request.py:52)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:10 - DEBUG - ci_test]: (api_response) : None  (api_request.py:27)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:10 - INFO - ci_test]: server version: f0cddfd (client_base.py:166)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:10 - DEBUG - ci_test]: (api_request)  : [Collection] args: ['e2e__kzSqxnsx', {'auto_id': False, 'description': '', 'fields': [{'name': 'int64', 'description': '', 'type': <DataType.INT64: 5>, 'is_primary': True, 'auto_id': False}, {'name': 'float', 'description': '', 'type': <DataType.FLOAT: 10>}, {'name': 'varchar', 'description': '', 'type': <DataType.VAR......, kwargs: {'consistency_level': 'Strong'} (api_request.py:52)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:10 - DEBUG - ci_test]: (api_response) : <Collection>:

[2025-01-06T07:23:03.682Z] -------------

[2025-01-06T07:23:03.682Z] <name>: e2e__kzSqxnsx

[2025-01-06T07:23:03.682Z] <description>: 

[2025-01-06T07:23:03.682Z] <schema>: {'auto_id': False, 'description': '', 'fields': [{'name': 'int64', 'description': '', 'type': <DataType.INT64: 5>, 'is_primary': True, 'auto_id': False}, {'name': 'float', 'description': '', 'type': <DataType.FLOAT: 10>}, {'......  (api_request.py:27)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:10 - DEBUG - ci_test]: (api_request)  : [Collection.create_index] args: ['float_vector', {'index_type': 'IVF_SQ8', 'params': {'nlist': 64}, 'metric_type': 'L2'}, 1200], kwargs: {'index_name': 'test_v4yYbDkS'} (api_request.py:52)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:11 - DEBUG - ci_test]: (api_response) : Status(code=0, message=)  (api_request.py:27)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:11 - INFO - ci_test]: [test][2025-01-06T07:20:10Z] [0.51501962s] e2e__kzSqxnsx create_index -> Status(code=0, message=) (wrapper.py:30)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:11 - DEBUG - ci_test]: (api_request)  : [Collection.create_index] args: ['varchar', {}, 1200], kwargs: {'index_name': 'test_IUT2kq1g'} (api_request.py:52)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:12 - DEBUG - ci_test]: (api_response) : Status(code=0, message=)  (api_request.py:27)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:12 - INFO - ci_test]: [test][2025-01-06T07:20:11Z] [0.51257469s] e2e__kzSqxnsx create_index -> Status(code=0, message=) (wrapper.py:30)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:12 - INFO - ci_test]: assert index: 1.0279631614685059 (test_e2e.py:34)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:20:12 - DEBUG - ci_test]: (api_request)  : [Collection.flush] args: [], kwargs: {'timeout': 180} (api_request.py:52)

[2025-01-06T07:23:03.682Z] [2025-01-06 07:23:03 - ERROR - ci_test]: Traceback (most recent call last):

[2025-01-06T07:23:03.682Z]   File "/home/jenkins/agent/workspace/tests/python_client/utils/api_request.py", line 22, in inner_wrapper

[2025-01-06T07:23:03.682Z]     res = func(*args, **_kwargs)

[2025-01-06T07:23:03.682Z]   File "/home/jenkins/agent/workspace/tests/python_client/utils/api_request.py", line 53, in api_request

[2025-01-06T07:23:03.682Z]     return func(*arg, **kwargs)

[2025-01-06T07:23:03.682Z]   File "/usr/local/lib/python3.10/dist-packages/pymilvus/orm/collection.py", line 318, in flush

[2025-01-06T07:23:03.682Z]     conn.flush([self.name], timeout=timeout, **kwargs)

[2025-01-06T07:23:03.682Z]   File "/usr/local/lib/python3.10/dist-packages/pymilvus/decorators.py", line 141, in handler

[2025-01-06T07:23:03.682Z]     raise e from e

[2025-01-06T07:23:03.682Z]   File "/usr/local/lib/python3.10/dist-packages/pymilvus/decorators.py", line 137, in handler

[2025-01-06T07:23:03.682Z]     return func(*args, **kwargs)

[2025-01-06T07:23:03.682Z]   File "/usr/local/lib/python3.10/dist-packages/pymilvus/decorators.py", line 176, in handler

[2025-01-06T07:23:03.682Z]     return func(self, *args, **kwargs)

[2025-01-06T07:23:03.682Z]   File "/usr/local/lib/python3.10/dist-packages/pymilvus/decorators.py", line 116, in handler

[2025-01-06T07:23:03.682Z]     raise e from e

[2025-01-06T07:23:03.682Z]   File "/usr/local/lib/python3.10/dist-packages/pymilvus/decorators.py", line 86, in handler

[2025-01-06T07:23:03.683Z]     return func(*args, **kwargs)

[2025-01-06T07:23:03.683Z]   File "/usr/local/lib/python3.10/dist-packages/pymilvus/client/grpc_handler.py", line 1520, in flush

[2025-01-06T07:23:03.683Z]     check_status(response.status)

[2025-01-06T07:23:03.683Z]   File "/usr/local/lib/python3.10/dist-packages/pymilvus/client/utils.py", line 63, in check_status

[2025-01-06T07:23:03.683Z]     raise MilvusException(status.code, status.reason, status.error_code)

[2025-01-06T07:23:03.683Z] pymilvus.exceptions.MilvusException: <MilvusException: (code=65535, message=failed to call flush to data coordinator: channel not found[channel=by-dev-rootcoord-dml_2_455120639571255819v0])>

[2025-01-06T07:23:03.683Z]  (api_request.py:35)

[2025-01-06T07:23:03.683Z] [2025-01-06 07:23:03 - ERROR - ci_test]: (api_response) : <MilvusException: (code=65535, message=failed to call flush to data coordinator: channel not found[channel=by-dev-rootcoord-dml_2_455120639571255819v0])> (api_request.py:36)

Expected Behavior

No response

Steps To Reproduce

No response

Milvus Log

failed job: https://qa-jenkins.milvus.io/blue/organizations/jenkins/chaos-test-cron/detail/chaos-test-cron/20054/pipeline

log:

artifacts-standalone-pod-kill-20054-server-logs.tar.gz

cluster: 4am
ns: chaos-testing
pod info

+ kubectl get pods -o wide
 + grep standalone-pod-kill-20054
 standalone-pod-kill-20054-etcd-0                                  1/1     Running                  0                  44m     10.104.23.253   4am-node27   <none>           <none>
 standalone-pod-kill-20054-etcd-1                                  1/1     Running                  0                  44m     10.104.32.174   4am-node39   <none>           <none>
 standalone-pod-kill-20054-etcd-2                                  1/1     Running                  0                  44m     10.104.21.34    4am-node24   <none>           <none>
 standalone-pod-kill-20054-milvus-standalone-66b9896f59-22wgw      1/1     Running                  3 (23m ago)        24m     10.104.23.44    4am-node27   <none>           <none>
 standalone-pod-kill-20054-minio-ffb5fd49f-g6bpt                   1/1     Running                  0                  44m     10.104.23.250   4am-node27   <none>           <none>

Anything else?

No response

[yanliang567]

/assign @weiliu1031
/unassign

[weiliu1031]

only register/unregister dispatcher for pchannel by-dev-rootcoord-dml_2 stuck forever, and other pchannel's operation executes successfully. so there exist a deadlock for specified pchannel

the reason for dead lock is still in investigating

[xiaofan-luan]

From the log, it's highly unlikely key lock has a dead lock.
Why can't it be ch, err := manager.Add(ctx, streamConfig) that blocks for a very long time?

[weiliu1031]

From the log, it's highly unlikely key lock has a dead lock. Why can't it be ch, err := manager.Add(ctx, streamConfig) that blocks for a very long time?

manager.Add(ctx, streamConfig) just execute creating dispatcher for vchannel, and create dispatcher for other pchannel still success after add dispatcher for pchannel by-dev-rootcoord-dml_2 stuck, which can be verified by log creating dispatcher...

[xiaofan-luan]

From the log, it's highly unlikely key lock has a dead lock. Why can't it be ch, err := manager.Add(ctx, streamConfig) that blocks for a very long time?

manager.Add(ctx, streamConfig) just execute creating dispatcher for vchannel, and create dispatcher for other pchannel still success after add dispatcher for pchannel by-dev-rootcoord-dml_2 stuck, which can be verified by log creating dispatcher...

but they are different topics right? is there a pprof at that moment? for pulsar/kafka sdk

[weiliu1031]

From the log, it's highly unlikely key lock has a dead lock. Why can't it be ch, err := manager.Add(ctx, streamConfig) that blocks for a very long time?

manager.Add(ctx, streamConfig) just execute creating dispatcher for vchannel, and create dispatcher for other pchannel still success after add dispatcher for pchannel by-dev-rootcoord-dml_2 stuck, which can be verified by log creating dispatcher...

but they are different topics right? is there a pprof at that moment? for pulsar/kafka sdk

yes, they are different pchannels, but only the keylock lock one pchannel, the others lock for all pchannel.
it doesn't reproduce recently, no chance to pprof