milvus [Bug]: [null & default] Datanode is crashed when flush the nullable enable collection with Null data after run the case to verify the expr cache

Is there an existing issue for this?

[X] I have searched the existing issues

Environment

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

Current Behavior

Datanode is crashed when flush the nullable enable collection with Null data after run the case to verify the expr cache

c9dd576d-1209-4ad4-b248-b8541f2d72e0

Expected Behavior

MIlvus is not crashed

Steps To Reproduce

    @pytest.mark.tags(CaseLabel.L1)
    def test_search_none_data_expr_cache(self, is_flush):
        """
        target: test search case with none data to test expr cache
        method: 1. create collection with double datatype as nullable field
                2. search with expr "nullableFid == 0"
                3. drop this collection
                4. create collection with same collection name and same field name but modify the type of nullable field
                   as varchar datatype
                5. search with expr "nullableFid == 0" again
        expected: 1. search successfully with limit(topK) for the first collection
                  2. report error for the second collection with the same name
        """
        # 1. initialize with data
        collection_w, _, _, insert_ids, time_stamp = \
            self.init_collection_general(prefix, True, is_flush=is_flush,
                                         nullable_fields={ct.default_float_field_name: 0.5})[0:5]
        collection_name = collection_w.name
        # 2. generate search data
        vectors = cf.gen_vectors_based_on_vector_type(default_nq, default_dim)
        # 3. search with expr "nullableFid == 0"
        search_exp = f"{ct.default_float_field_name} == 0"
        output_fields = [default_int64_field_name, default_float_field_name]
        collection_w.search(vectors[:default_nq], default_search_field,
                            default_search_params, default_limit,
                            search_exp,
                            output_fields=output_fields,
                            check_task=CheckTasks.check_search_results,
                            check_items={"nq": default_nq,
                                         "ids": insert_ids,
                                         "limit": default_limit,
                                         "output_fields": output_fields})
        # 4. drop collection
        collection_w.drop()
        # 5. create the same collection name with same field name but varchar field type
        int64_field = cf.gen_int64_field(is_primary=True)
        string_field = cf.gen_string_field(ct.default_float_field_name, nullable=True)
        json_field = cf.gen_json_field()
        float_vector_field = cf.gen_float_vec_field()
        fields = [int64_field, string_field, json_field, float_vector_field]
        schema = cf.gen_collection_schema(fields)
        collection_w = self.init_collection_wrap(name=collection_name, schema=schema)
        int64_values = pd.Series(data=[i for i in range(default_nb)])
        string_values = pd.Series(data=[str(i) for i in range(default_nb)], dtype="string")
        json_values = [{"number": i, "string": str(i), "bool": bool(i),
                        "list": [j for j in range(i, i + ct.default_json_list_length)]} for i in range(default_nb)]
        float_vec_values = cf.gen_vectors(default_nb, default_dim)
        df = pd.DataFrame({
            ct.default_int64_field_name: int64_values,
            ct.default_float_field_name: None,
            ct.default_json_field_name: json_values,
            ct.default_float_vec_field_name: float_vec_values
        })
        collection_w.insert(df)
        collection_w.create_index(ct.default_float_vec_field_name, ct.default_flat_index)
        collection_w.load()
        collection_w.flush()
        collection_w.search(vectors[:default_nq], default_search_field,
                            default_search_params, default_limit,
                            search_exp,
                            output_fields=output_fields,
                            check_task=CheckTasks.err_res,
                            check_items={"err_code": 1100,
                                         "err_msg": "failed to create query plan: cannot parse expression: float == 0, "
                                                    "error: comparisons between VarChar and Int64 are not supported: "
                                                    "invalid parameter"})

Milvus Log

https://grafana-4am.zilliz.cc/explore?orgId=1&panes=%7B%226W8%22:%7B%22datasource%22:%22vhI6Vw67k%22,%22queries%22:%5B%7B%22refId%22:%22A%22,%22expr%22:%22%7Bcluster%3D%5C%22devops%5C%22,namespace%3D%5C%22chaos-testing%5C%22,pod%3D~%5C%22test-null-master-cjqsw.%2A%5C%22%7D%22,%22datasource%22:%7B%22type%22:%22loki%22,%22uid%22:%22vhI6Vw67k%22%7D%7D%5D,%22range%22:%7B%22from%22:%22now-1h%22,%22to%22:%22now%22%7D%7D%7D&schemaVersion=1

Anything else?

No response

Nov 08 '24 08:11 binbinlv

The case actually runs two cases (is_flush=False, and True)， and milvus is crashed when is_flush=True.

But if only run one case (is_flush=True), milvus is not crash.
Only when run both the two cases, run is_flush=False firstly, it passes. And run the case of is_flush = True, milvus is crashed.

Nov 08 '24 08:11 binbinlv

It seems this crash is not Nullable case related only, when set nullable=False, it is crash too. But it needs to run case for several times. The reproduce rate is not higher than Nullable case.

1565ed23-2fe1-49fb-842b-80e85dfa7161

case:

    @pytest.mark.tags(CaseLabel.L1)
    # @pytest.mark.skip(reason="issue #37547")
    def test_search_none_data_expr_cache(self, is_flush):
        """
        target: test search case with none data to test expr cache
        method: 1. create collection with double datatype as nullable field
                2. search with expr "nullableFid == 0"
                3. drop this collection
                4. create collection with same collection name and same field name but modify the type of nullable field
                   as varchar datatype
                5. search with expr "nullableFid == 0" again
        expected: 1. search successfully with limit(topK) for the first collection
                  2. report error for the second collection with the same name
        """
        # 1. initialize with data
        collection_w, _, _, insert_ids, time_stamp = \
            self.init_collection_general(prefix, True, is_flush=is_flush)[0:5]
        collection_name = collection_w.name
        # 2. generate search data
        vectors = cf.gen_vectors_based_on_vector_type(default_nq, default_dim)
        # 3. search with expr "nullableFid == 0"
        search_exp = f"{ct.default_float_field_name} == 0"
        output_fields = [default_int64_field_name, default_float_field_name]
        collection_w.search(vectors[:default_nq], default_search_field,
                            default_search_params, default_limit,
                            search_exp,
                            output_fields=output_fields,
                            check_task=CheckTasks.check_search_results,
                            check_items={"nq": default_nq,
                                         "ids": insert_ids,
                                         "limit": 1,
                                         "output_fields": output_fields})
        # 4. drop collection
        collection_w.drop()
        # 5. create the same collection name with same field name but varchar field type
        int64_field = cf.gen_int64_field(is_primary=True)
        string_field = cf.gen_string_field(ct.default_float_field_name)
        json_field = cf.gen_json_field()
        float_vector_field = cf.gen_float_vec_field()
        fields = [int64_field, string_field, json_field, float_vector_field]
        schema = cf.gen_collection_schema(fields)
        collection_w = self.init_collection_wrap(name=collection_name, schema=schema)
        int64_values = pd.Series(data=[i for i in range(default_nb)])
        string_values = pd.Series(data=[str(i) for i in range(default_nb)], dtype="string")
        json_values = [{"number": i, "string": str(i), "bool": bool(i),
                        "list": [j for j in range(i, i + ct.default_json_list_length)]} for i in range(default_nb)]
        float_vec_values = cf.gen_vectors(default_nb, default_dim)
        df = pd.DataFrame({
            ct.default_int64_field_name: int64_values,
            ct.default_float_field_name: string_values,
            ct.default_json_field_name: json_values,
            ct.default_float_vec_field_name: float_vec_values
        })
        collection_w.insert(df)
        collection_w.create_index(ct.default_float_vec_field_name, ct.default_flat_index)
        collection_w.load()
        collection_w.flush()
        collection_w.search(vectors[:default_nq], default_search_field,
                            default_search_params, default_limit,
                            search_exp,
                            output_fields=output_fields,
                            check_task=CheckTasks.err_res,
                            check_items={"err_code": 1100,
                                         "err_msg": "failed to create query plan: cannot parse expression: float == 0, "
                                                    "error: comparisons between VarChar and Int64 are not supported: "
                                                    "invalid parameter"})

Nov 08 '24 09:11 binbinlv

When flushing the collection with the same name, an error message is reported: **ConsumerBusy: Exclusive consumer is already connected**. It's seems the consumer of the old collection has not yet closed, and new collection with same name use the old information to create a consumer. As a result, Pulsar reports this error and the datanode panics.

Nov 08 '24 09:11 smellthemoon

@tedxu could you help to have a look?

Nov 08 '24 09:11 smellthemoon

/assign @chyezh

could you help on verifying this?

Nov 08 '24 21:11 xiaofan-luan

Our msgstream implementation of pulsar use a named-subscription with exclusive option. So when concurrent create same subscription of pulsar consumer will report this error. Found that the datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false subscription is repeatly created at pulsar broker.

2024-11-08 11:27:14.471	2024-11-08T03:27:14,470+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-true
2024-11-08 11:27:14.481	2024-11-08T03:27:14,481+0000 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11] There are no replicated subscriptions on the topic
2024-11-08 11:27:14.481	2024-11-08T03:27:14,481+0000 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-true] Created new subscription for 12
2024-11-08 11:27:14.481	2024-11-08T03:27:14,481+0000 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Created subscription on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-true
2024-11-08 11:27:14.483	2024-11-08T03:27:14,483+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.Consumer - Disconnecting consumer: Consumer{subscription=PersistentSubscription{topic=persistent://public/default/by-dev-rootcoord-dml_11, name=datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-true}, consumerId=12, consumerName=izkwe, address=/10.102.5.67:48916}
2024-11-08 11:27:14.483	2024-11-08T03:27:14,483+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.AbstractDispatcherSingleActiveConsumer - Removing consumer Consumer{subscription=PersistentSubscription{topic=persistent://public/default/by-dev-rootcoord-dml_11, name=datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-true}, consumerId=12, consumerName=izkwe, address=/10.102.5.67:48916}
2024-11-08 11:27:14.483	2024-11-08T03:27:14,483+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.persistent.PersistentSubscription - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-true] Successfully disconnected consumers from subscription, proceeding with cursor reset
2024-11-08 11:27:14.485	2024-11-08T03:27:14,485+0000 [BookKeeperClientWorker-OrderedExecutor-4-0] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-true] Reset subscription to message id 11:0
2024-11-08 11:27:14.592	2024-11-08T03:27:14,592+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-true
2024-11-08 11:27:14.593	2024-11-08T03:27:14,593+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11] There are no replicated subscriptions on the topic
2024-11-08 11:27:14.593	2024-11-08T03:27:14,593+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-true] Created new subscription for 12
2024-11-08 11:27:14.593	2024-11-08T03:27:14,593+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Created subscription on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-true
2024-11-08 11:27:20.411	2024-11-08T03:27:20,410+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:27:20.421	2024-11-08T03:27:20,421+0000 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11] There are no replicated subscriptions on the topic
2024-11-08 11:27:20.421	2024-11-08T03:27:20,421+0000 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] Created new subscription for 13
2024-11-08 11:27:20.421	2024-11-08T03:27:20,421+0000 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Created subscription on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:27:20.423	2024-11-08T03:27:20,423+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.Consumer - Disconnecting consumer: Consumer{subscription=PersistentSubscription{topic=persistent://public/default/by-dev-rootcoord-dml_11, name=datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false}, consumerId=13, consumerName=defzk, address=/10.102.5.67:48916}
2024-11-08 11:27:20.423	2024-11-08T03:27:20,423+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.AbstractDispatcherSingleActiveConsumer - Removing consumer Consumer{subscription=PersistentSubscription{topic=persistent://public/default/by-dev-rootcoord-dml_11, name=datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false}, consumerId=13, consumerName=defzk, address=/10.102.5.67:48916}
2024-11-08 11:27:20.423	2024-11-08T03:27:20,423+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.persistent.PersistentSubscription - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] Successfully disconnected consumers from subscription, proceeding with cursor reset
2024-11-08 11:27:20.426	2024-11-08T03:27:20,426+0000 [BookKeeperClientWorker-OrderedExecutor-5-0] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] Reset subscription to message id 67:16
2024-11-08 11:27:20.543	2024-11-08T03:27:20,543+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:27:20.543	2024-11-08T03:27:20,543+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11] There are no replicated subscriptions on the topic
2024-11-08 11:27:20.543	2024-11-08T03:27:20,543+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] Created new subscription for 13
2024-11-08 11:27:20.543	2024-11-08T03:27:20,543+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Created subscription on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:32:17.471	2024-11-08T03:32:17,471+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:32:17.472	2024-11-08T03:32:17,472+0000 [pulsar-io-4-71] WARN  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] Consumer 14 gomkn already connected
2024-11-08 11:32:17.677	2024-11-08T03:32:17,677+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:32:17.678	2024-11-08T03:32:17,678+0000 [pulsar-io-4-71] WARN  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] Consumer 15 bnqnl already connected
2024-11-08 11:32:18.081	2024-11-08T03:32:18,081+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:32:18.082	2024-11-08T03:32:18,082+0000 [pulsar-io-4-71] WARN  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] Consumer 16 cuklz already connected
2024-11-08 11:32:18.886	2024-11-08T03:32:18,886+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:32:18.886	2024-11-08T03:32:18,886+0000 [pulsar-io-4-71] WARN  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] Consumer 17 itfav already connected
2024-11-08 11:32:20.490	2024-11-08T03:32:20,489+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:32:20.490	2024-11-08T03:32:20,490+0000 [pulsar-io-4-71] WARN  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] Consumer 18 lukyc already connected
2024-11-08 11:32:23.694	2024-11-08T03:32:23,694+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:32:23.694	2024-11-08T03:32:23,694+0000 [pulsar-io-4-71] WARN  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] Consumer 19 fhnyg already connected
2024-11-08 11:32:28.698	2024-11-08T03:32:28,698+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:32:28.698	2024-11-08T03:32:28,698+0000 [pulsar-io-4-71] WARN  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] Consumer 20 otwcv already connected
2024-11-08 11:32:33.703	2024-11-08T03:32:33,702+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:32:33.703	2024-11-08T03:32:33,703+0000 [pulsar-io-4-71] WARN  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] Consumer 21 afuiv already connected
2024-11-08 11:32:38.706	2024-11-08T03:32:38,706+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:32:38.706	2024-11-08T03:32:38,706+0000 [pulsar-io-4-71] WARN  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] Consumer 22 tgjan already connected
2024-11-08 11:32:43.711	2024-11-08T03:32:43,710+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:32:43.711	2024-11-08T03:32:43,711+0000 [pulsar-io-4-71] WARN  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] Consumer 23 fnoya already connected
2024-11-08 11:32:48.830	2024-11-08T03:32:48,830+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:32:48.830	2024-11-08T03:32:48,830+0000 [pulsar-io-4-71] WARN  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] Consumer 24 wnsbv already connected
2024-11-08 11:32:53.834	2024-11-08T03:32:53,834+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:32:53.834	2024-11-08T03:32:53,834+0000 [pulsar-io-4-71] WARN  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] Consumer 25 tlztc already connected
2024-11-08 11:32:58.838	2024-11-08T03:32:58,838+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:32:58.838	2024-11-08T03:32:58,838+0000 [pulsar-io-4-71] WARN  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] Consumer 26 mlvmf already connected
2024-11-08 11:33:03.842	2024-11-08T03:33:03,842+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:33:03.842	2024-11-08T03:33:03,842+0000 [pulsar-io-4-71] WARN  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] Consumer 27 qnzzd already connected
2024-11-08 11:33:08.846	2024-11-08T03:33:08,845+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:33:08.846	2024-11-08T03:33:08,846+0000 [pulsar-io-4-71] WARN  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] Consumer 28 oaqay already connected
2024-11-08 11:33:13.849	2024-11-08T03:33:13,849+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:33:13.849	2024-11-08T03:33:13,849+0000 [pulsar-io-4-71] WARN  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] Consumer 29 zoaut already connected
2024-11-08 11:33:18.852	2024-11-08T03:33:18,852+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:33:18.853	2024-11-08T03:33:18,853+0000 [pulsar-io-4-71] WARN  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] Consumer 30 kyutn already connected
2024-11-08 11:33:23.857	2024-11-08T03:33:23,857+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:33:23.857	2024-11-08T03:33:23,857+0000 [pulsar-io-4-71] WARN  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] Consumer 31 mfvlv already connected
2024-11-08 11:33:28.862	2024-11-08T03:33:28,861+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:33:28.862	2024-11-08T03:33:28,862+0000 [pulsar-io-4-71] WARN  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] Consumer 32 ubygt already connected
2024-11-08 11:33:33.865	2024-11-08T03:33:33,865+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:48916] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:33:33.865	2024-11-08T03:33:33,865+0000 [pulsar-io-4-71] WARN  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] Consumer 33 abtfx already connected
2024-11-08 11:33:38.868	panic: Failed to create consumer by-dev-rootcoord-dml_11, errors = server error: ConsumerBusy: Exclusive consumer is already connected
2024-11-08 11:33:40.730	2024-11-08T03:33:40,730+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.AbstractDispatcherSingleActiveConsumer - Removing consumer Consumer{subscription=PersistentSubscription{topic=persistent://public/default/by-dev-rootcoord-dml_11, name=datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false}, consumerId=13, consumerName=defzk, address=/10.102.5.67:48916}
2024-11-08 11:33:40.730	2024-11-08T03:33:40,730+0000 [pulsar-io-4-71] INFO  org.apache.pulsar.broker.service.AbstractDispatcherSingleActiveConsumer - Removing consumer Consumer{subscription=PersistentSubscription{topic=persistent://public/default/by-dev-rootcoord-dml_11, name=datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-true}, consumerId=12, consumerName=izkwe, address=/10.102.5.67:48916}
2024-11-08 11:33:46.731	2024-11-08T03:33:46,731+0000 [pulsar-msg-expiry-monitor-27-1] INFO  org.apache.pulsar.broker.service.persistent.PersistentMessageExpiryMonitor - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] Starting message expiry check, ttl= 259200 seconds
2024-11-08 11:33:46.731	2024-11-08T03:33:46,731+0000 [pulsar-msg-expiry-monitor-27-1] INFO  org.apache.pulsar.broker.service.persistent.PersistentMessageExpiryMonitor - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-true] Starting message expiry check, ttl= 259200 seconds
2024-11-08 11:34:02.530	2024-11-08T03:34:02,530+0000 [pulsar-io-4-75] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:39190] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-7-by-dev-rootcoord-dml_11_453764290321215082v0-true
2024-11-08 11:34:02.541	2024-11-08T03:34:02,541+0000 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11] There are no replicated subscriptions on the topic
2024-11-08 11:34:02.541	2024-11-08T03:34:02,541+0000 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-7-by-dev-rootcoord-dml_11_453764290321215082v0-true] Created new subscription for 3
2024-11-08 11:34:02.541	2024-11-08T03:34:02,541+0000 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:39190] Created subscription on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-7-by-dev-rootcoord-dml_11_453764290321215082v0-true
2024-11-08 11:34:02.545	2024-11-08T03:34:02,545+0000 [pulsar-io-4-75] INFO  org.apache.pulsar.broker.service.Consumer - Disconnecting consumer: Consumer{subscription=PersistentSubscription{topic=persistent://public/default/by-dev-rootcoord-dml_11, name=datanode-7-by-dev-rootcoord-dml_11_453764290321215082v0-true}, consumerId=3, consumerName=fjxqc, address=/10.102.5.67:39190}
2024-11-08 11:34:02.545	2024-11-08T03:34:02,545+0000 [pulsar-io-4-75] INFO  org.apache.pulsar.broker.service.AbstractDispatcherSingleActiveConsumer - Removing consumer Consumer{subscription=PersistentSubscription{topic=persistent://public/default/by-dev-rootcoord-dml_11, name=datanode-7-by-dev-rootcoord-dml_11_453764290321215082v0-true}, consumerId=3, consumerName=fjxqc, address=/10.102.5.67:39190}
2024-11-08 11:34:02.545	2024-11-08T03:34:02,545+0000 [pulsar-io-4-75] INFO  org.apache.pulsar.broker.service.persistent.PersistentSubscription - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-7-by-dev-rootcoord-dml_11_453764290321215082v0-true] Successfully disconnected consumers from subscription, proceeding with cursor reset
2024-11-08 11:34:02.548	2024-11-08T03:34:02,547+0000 [BookKeeperClientWorker-OrderedExecutor-8-0] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:39190] [persistent://public/default/by-dev-rootcoord-dml_11][datanode-7-by-dev-rootcoord-dml_11_453764290321215082v0-true] Reset subscription to message id 11:0
2024-11-08 11:34:02.655	2024-11-08T03:34:02,655+0000 [pulsar-io-4-75] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:39190] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-7-by-dev-rootcoord-dml_11_453764290321215082v0-true
2024-11-08 11:34:02.655	2024-11-08T03:34:02,655+0000 [pulsar-io-4-75] INFO  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11] There are no replicated subscriptions on the topic
2024-11-08 11:34:02.655	2024-11-08T03:34:02,655+0000 [pulsar-io-4-75] INFO  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-7-by-dev-rootcoord-dml_11_453764290321215082v0-true] Created new subscription for 3
2024-11-08 11:34:02.655	2024-11-08T03:34:02,655+0000 [pulsar-io-4-75] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:39190] Created subscription on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-7-by-dev-rootcoord-dml_11_453764290321215082v0-true
2024-11-08 11:34:05.756	2024-11-08T03:34:05,756+0000 [pulsar-io-4-75] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:39190] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-7-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:34:05.770	2024-11-08T03:34:05,770+0000 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11] There are no replicated subscriptions on the topic
2024-11-08 11:34:05.770	2024-11-08T03:34:05,770+0000 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-7-by-dev-rootcoord-dml_11_453764290321215082v0-false] Created new subscription for 5
2024-11-08 11:34:05.770	2024-11-08T03:34:05,770+0000 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:39190] Created subscription on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-7-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:34:05.771	2024-11-08T03:34:05,771+0000 [pulsar-io-4-75] INFO  org.apache.pulsar.broker.service.Consumer - Disconnecting consumer: Consumer{subscription=PersistentSubscription{topic=persistent://public/default/by-dev-rootcoord-dml_11, name=datanode-7-by-dev-rootcoord-dml_11_453764290321215082v0-false}, consumerId=5, consumerName=qkrhp, address=/10.102.5.67:39190}
2024-11-08 11:34:05.771	2024-11-08T03:34:05,771+0000 [pulsar-io-4-75] INFO  org.apache.pulsar.broker.service.AbstractDispatcherSingleActiveConsumer - Removing consumer Consumer{subscription=PersistentSubscription{topic=persistent://public/default/by-dev-rootcoord-dml_11, name=datanode-7-by-dev-rootcoord-dml_11_453764290321215082v0-false}, consumerId=5, consumerName=qkrhp, address=/10.102.5.67:39190}
2024-11-08 11:34:05.771	2024-11-08T03:34:05,771+0000 [pulsar-io-4-75] INFO  org.apache.pulsar.broker.service.persistent.PersistentSubscription - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-7-by-dev-rootcoord-dml_11_453764290321215082v0-false] Successfully disconnected consumers from subscription, proceeding with cursor reset
2024-11-08 11:34:05.774	2024-11-08T03:34:05,774+0000 [BookKeeperClientWorker-OrderedExecutor-10-0] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:39190] [persistent://public/default/by-dev-rootcoord-dml_11][datanode-7-by-dev-rootcoord-dml_11_453764290321215082v0-false] Reset subscription to message id 67:1883
2024-11-08 11:34:05.876	2024-11-08T03:34:05,876+0000 [pulsar-io-4-75] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:39190] Subscribing on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-7-by-dev-rootcoord-dml_11_453764290321215082v0-false
2024-11-08 11:34:05.877	2024-11-08T03:34:05,877+0000 [pulsar-io-4-75] INFO  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11] There are no replicated subscriptions on the topic
2024-11-08 11:34:05.877	2024-11-08T03:34:05,877+0000 [pulsar-io-4-75] INFO  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/by-dev-rootcoord-dml_11][datanode-7-by-dev-rootcoord-dml_11_453764290321215082v0-false] Created new subscription for 5
2024-11-08 11:34:05.877	2024-11-08T03:34:05,877+0000 [pulsar-io-4-75] INFO  org.apache.pulsar.broker.service.ServerCnx - [/10.102.5.67:39190] Created subscription on topic persistent://public/default/by-dev-rootcoord-dml_11 / datanode-7-by-dev-rootcoord-dml_11_453764290321215082v0-false

Nov 11 '24 02:11 chyezh

Duplicate create found at milvus msgstream dispatcher.

2024-11-08 11:16:00.468	[2024/11/08 03:16:00.468 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_10] [subName=datanode-6-by-dev-rootcoord-dml_10_453764290321208660v0-true] [isMain=true]
2024-11-08 11:16:20.552	[2024/11/08 03:16:20.552 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_10] [subName=querynode-3-by-dev-rootcoord-dml_10_453764290321208660v0-true] [isMain=true]
2024-11-08 11:27:14.468	[2024/11/08 03:27:14.468 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_11] [subName=datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-true] [isMain=true]
2024-11-08 11:27:20.408	[2024/11/08 03:27:20.408 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_11] [subName=datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] [isMain=false]
2024-11-08 11:32:17.468	[2024/11/08 03:32:17.468 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_11] [subName=datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false] [isMain=false]
2024-11-08 11:34:02.468	[2024/11/08 03:34:02.468 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_11] [subName=datanode-7-by-dev-rootcoord-dml_11_453764290321215082v0-true] [isMain=true]
2024-11-08 11:34:02.469	[2024/11/08 03:34:02.469 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_5] [subName=datanode-7-by-dev-rootcoord-dml_5_453764290320920094v0-true] [isMain=true]
2024-11-08 11:34:02.469	[2024/11/08 03:34:02.469 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_8] [subName=datanode-7-by-dev-rootcoord-dml_8_453764290320921675v0-true] [isMain=true]
2024-11-08 11:34:02.480	[2024/11/08 03:34:02.480 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_10] [subName=datanode-7-by-dev-rootcoord-dml_10_453764290321208660v0-true] [isMain=true]
2024-11-08 11:34:05.753	[2024/11/08 03:34:05.753 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_11] [subName=datanode-7-by-dev-rootcoord-dml_11_453764290321215082v0-false] [isMain=false]
2024-11-08 11:39:04.468	[2024/11/08 03:39:04.468 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_11] [subName=datanode-7-by-dev-rootcoord-dml_11_453764290321215082v0-false] [isMain=false]
2024-11-08 11:40:55.468	[2024/11/08 03:40:55.468 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_11] [subName=datanode-8-by-dev-rootcoord-dml_11_453764290321215082v0-true] [isMain=true]
2024-11-08 11:40:55.469	[2024/11/08 03:40:55.469 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_5] [subName=datanode-8-by-dev-rootcoord-dml_5_453764290320920094v0-true] [isMain=true]
2024-11-08 11:40:55.470	[2024/11/08 03:40:55.469 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_8] [subName=datanode-8-by-dev-rootcoord-dml_8_453764290320921675v0-true] [isMain=true]
2024-11-08 11:40:56.063	[2024/11/08 03:40:56.063 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_10] [subName=datanode-8-by-dev-rootcoord-dml_10_453764290321208660v0-true] [isMain=true]
2024-11-08 11:40:59.710	[2024/11/08 03:40:59.710 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_11] [subName=datanode-8-by-dev-rootcoord-dml_11_453764290321215082v0-false] [isMain=false]
2024-11-08 11:45:58.468	[2024/11/08 03:45:58.468 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_11] [subName=datanode-8-by-dev-rootcoord-dml_11_453764290321215082v0-false] [isMain=false]
2024-11-08 11:47:49.469	[2024/11/08 03:47:49.469 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_11] [subName=datanode-9-by-dev-rootcoord-dml_11_453764290321215082v0-true] [isMain=true]
2024-11-08 11:47:49.470	[2024/11/08 03:47:49.469 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_5] [subName=datanode-9-by-dev-rootcoord-dml_5_453764290320920094v0-true] [isMain=true]
2024-11-08 11:47:49.470	[2024/11/08 03:47:49.470 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_8] [subName=datanode-9-by-dev-rootcoord-dml_8_453764290320921675v0-true] [isMain=true]
2024-11-08 11:47:49.481	[2024/11/08 03:47:49.481 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_10] [subName=datanode-9-by-dev-rootcoord-dml_10_453764290321208660v0-true] [isMain=true]
2024-11-08 11:47:52.798	[2024/11/08 03:47:52.798 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_11] [subName=datanode-9-by-dev-rootcoord-dml_11_453764290321215082v0-false] [isMain=false]
2024-11-08 11:50:03.468	[2024/11/08 03:50:03.468 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_12] [subName=datanode-9-by-dev-rootcoord-dml_12_453764290321222304v0-true] [isMain=true]
2024-11-08 11:50:43.551	[2024/11/08 03:50:43.551 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_12] [subName=querynode-3-by-dev-rootcoord-dml_12_453764290321222304v0-true] [isMain=true]
2024-11-08 11:50:48.469	[2024/11/08 03:50:48.469 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_13] [subName=datanode-9-by-dev-rootcoord-dml_13_453764290321225183v0-true] [isMain=true]
2024-11-08 11:51:20.551	[2024/11/08 03:51:20.551 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_13] [subName=querynode-3-by-dev-rootcoord-dml_13_453764290321225183v0-true] [isMain=true]
2024-11-08 11:51:25.469	[2024/11/08 03:51:25.469 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_14] [subName=datanode-9-by-dev-rootcoord-dml_14_453764290321228030v0-true] [isMain=true]
2024-11-08 11:51:57.552	[2024/11/08 03:51:57.552 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_14] [subName=querynode-3-by-dev-rootcoord-dml_14_453764290321228030v0-true] [isMain=true]
2024-11-08 11:52:02.470	[2024/11/08 03:52:02.470 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_15] [subName=datanode-9-by-dev-rootcoord-dml_15_453764290321230775v0-true] [isMain=true]
2024-11-08 11:52:42.051	[2024/11/08 03:52:42.051 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_15] [subName=querynode-3-by-dev-rootcoord-dml_15_453764290321230775v0-true] [isMain=true]
2024-11-08 11:52:47.469	[2024/11/08 03:52:47.469 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_0] [subName=datanode-9-by-dev-rootcoord-dml_0_453764290321233558v0-true] [isMain=true]
2024-11-08 11:52:51.468	[2024/11/08 03:52:51.468 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_11] [subName=datanode-9-by-dev-rootcoord-dml_11_453764290321215082v0-false] [isMain=false]
2024-11-08 11:53:14.551	[2024/11/08 03:53:14.551 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_0] [subName=querynode-3-by-dev-rootcoord-dml_0_453764290321233558v0-true] [isMain=true]
2024-11-08 11:53:19.470	[2024/11/08 03:53:19.469 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_1] [subName=datanode-9-by-dev-rootcoord-dml_1_453764290321236381v0-true] [isMain=true]
2024-11-08 11:53:51.052	[2024/11/08 03:53:51.052 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_1] [subName=querynode-3-by-dev-rootcoord-dml_1_453764290321236381v0-true] [isMain=true]
2024-11-08 11:53:55.469	[2024/11/08 03:53:55.469 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_2] [subName=datanode-9-by-dev-rootcoord-dml_2_453764290321239218v0-true] [isMain=true]
2024-11-08 11:55:00.472	[2024/11/08 03:55:00.472 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_11] [subName=datanode-10-by-dev-rootcoord-dml_11_453764290321215082v0-true] [isMain=true]
2024-11-08 11:55:00.472	[2024/11/08 03:55:00.472 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_2] [subName=datanode-10-by-dev-rootcoord-dml_2_453764290321239218v0-true] [isMain=true]
2024-11-08 11:55:00.472	[2024/11/08 03:55:00.472 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_8] [subName=datanode-10-by-dev-rootcoord-dml_8_453764290320921675v0-true] [isMain=true]
2024-11-08 11:55:00.473	[2024/11/08 03:55:00.473 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_5] [subName=datanode-10-by-dev-rootcoord-dml_5_453764290320920094v0-true] [isMain=true]
2024-11-08 11:55:00.483	[2024/11/08 03:55:00.483 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_10] [subName=datanode-10-by-dev-rootcoord-dml_10_453764290321208660v0-true] [isMain=true]
2024-11-08 11:55:03.839	[2024/11/08 03:55:03.839 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_11] [subName=datanode-10-by-dev-rootcoord-dml_11_453764290321215082v0-false] [isMain=false]
2024-11-08 11:55:15.552	[2024/11/08 03:55:15.552 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_2] [subName=querynode-3-by-dev-rootcoord-dml_2_453764290321239218v0-true] [isMain=true]
2024-11-08 11:55:20.468	[2024/11/08 03:55:20.468 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_3] [subName=datanode-10-by-dev-rootcoord-dml_3_453764290321243221v0-true] [isMain=true]
2024-11-08 11:55:51.052	[2024/11/08 03:55:51.052 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_3] [subName=querynode-3-by-dev-rootcoord-dml_3_453764290321243221v0-true] [isMain=true]
2024-11-08 11:55:55.470	[2024/11/08 03:55:55.470 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_4] [subName=datanode-10-by-dev-rootcoord-dml_4_453764290321245954v0-true] [isMain=true]
2024-11-08 11:56:27.051	[2024/11/08 03:56:27.051 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_4] [subName=querynode-3-by-dev-rootcoord-dml_4_453764290321245954v0-true] [isMain=true]
2024-11-08 11:56:31.469	[2024/11/08 03:56:31.469 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_6] [subName=datanode-10-by-dev-rootcoord-dml_6_453764290321248790v0-true] [isMain=true]
2024-11-08 11:56:56.553	[2024/11/08 03:56:56.553 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_6] [subName=querynode-3-by-dev-rootcoord-dml_6_453764290321248790v0-true] [isMain=true]
2024-11-08 11:57:00.469	[2024/11/08 03:57:00.469 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_7] [subName=datanode-10-by-dev-rootcoord-dml_7_453764290321251592v0-true] [isMain=true]
2024-11-08 11:57:26.052	[2024/11/08 03:57:26.052 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_7] [subName=querynode-3-by-dev-rootcoord-dml_7_453764290321251592v0-true] [isMain=true]
2024-11-08 11:57:33.469	[2024/11/08 03:57:33.469 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_9] [subName=datanode-10-by-dev-rootcoord-dml_9_453764290321254371v0-true] [isMain=true]
2024-11-08 11:57:59.051	[2024/11/08 03:57:59.051 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_9] [subName=querynode-3-by-dev-rootcoord-dml_9_453764290321254371v0-true] [isMain=true]
2024-11-08 11:58:03.470	[2024/11/08 03:58:03.469 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_12] [subName=datanode-10-by-dev-rootcoord-dml_12_453764290321257081v0-true] [isMain=true]
2024-11-08 11:58:32.551	[2024/11/08 03:58:32.551 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_12] [subName=querynode-3-by-dev-rootcoord-dml_12_453764290321257081v0-true] [isMain=true]
2024-11-08 11:58:37.469	[2024/11/08 03:58:37.469 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_13] [subName=datanode-10-by-dev-rootcoord-dml_13_453764290321259905v0-true] [isMain=true]
2024-11-08 11:59:05.551	[2024/11/08 03:59:05.551 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_13] [subName=querynode-3-by-dev-rootcoord-dml_13_453764290321259905v0-true] [isMain=true]
2024-11-08 11:59:10.469	[2024/11/08 03:59:10.469 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_14] [subName=datanode-10-by-dev-rootcoord-dml_14_453764290321262742v0-true] [isMain=true]
2024-11-08 11:59:35.051	[2024/11/08 03:59:35.051 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_14] [subName=querynode-3-by-dev-rootcoord-dml_14_453764290321262742v0-true] [isMain=true]
2024-11-08 11:59:39.469	[2024/11/08 03:59:39.469 +00:00] [INFO] [msgdispatcher/dispatcher.go:93] ["creating dispatcher..."] [pchannel=by-dev-rootcoord-dml_15] [subName=datanode-10-by-dev-rootcoord-dml_15_453764290321265442v0-true] [isMain=true]

      2 by-dev-rootcoord-dml_11	datanode-6-by-dev-rootcoord-dml_11_453764290321215082v0-false
      2 by-dev-rootcoord-dml_11	datanode-7-by-dev-rootcoord-dml_11_453764290321215082v0-false
      2 by-dev-rootcoord-dml_11	datanode-8-by-dev-rootcoord-dml_11_453764290321215082v0-false
      2 by-dev-rootcoord-dml_11	datanode-9-by-dev-rootcoord-dml_11_453764290321215082v0-false
      1 by-dev-rootcoord-dml_0	datanode-9-by-dev-rootcoord-dml_0_453764290321233558v0-true
      1 by-dev-rootcoord-dml_0	querynode-3-by-dev-rootcoord-dml_0_453764290321233558v0-true
      1 by-dev-rootcoord-dml_10	datanode-10-by-dev-rootcoord-dml_10_453764290321208660v0-true

Nov 11 '24 02:11 chyezh

There're two issues in milvus.

The NewDataSyncService operation is not Idempotent. Once the following operation is failed, channel that is regsitered into msgstream dispatcher can not be cleared (resource leak here). The NewDataSyncService operation's retry make the double creation of same subscription of pulsar consumer.
The bm25 construction operation is failed when create channel watch, so the channel cannot be watched, leads to the double creation and panic.

@smellthemoon please help to check the issue 2, here's the error log in milvus. I will fix the issue 1 by make NewDataSyncService Idempotent.

[2024/11/08 03:27:14.602 +00:00] [WARN] [channel/channel_manager.go:428] ["failed to watch channel"] [channel=by-dev-rootcoord-dml_11_453764290321215082v0] [opID=453764296335163424] [error="failed to create tokenizer, C Runtime Exception: invalid tokenizer parameters
: segcore error[segcoreCode=2001]"] [errorVerbose="failed to create tokenizer, C Runtime Exception: invalid tokenizer parameters: segcore error[segcoreCode=2001]
(1) attached stack trace
  -- stack trace:
  | github.com/milvus-io/milvus/pkg/util/merr.WrapErrSegcore
  | \t/workspace/source/pkg/util/merr/utils.go:1006
  | github.com/milvus-io/milvus/internal/util/ctokenizer.HandleCStatus
  | \t/workspace/source/internal/util/ctokenizer/helper.go:36
  | github.com/milvus-io/milvus/internal/util/ctokenizer.NewTokenizer
  | \t/workspace/source/internal/util/ctokenizer/c_tokenizer_factory.go:23
  | github.com/milvus-io/milvus/internal/util/function.NewBM25FunctionRunner
  | \t/workspace/source/internal/util/function/bm25_function.go:76
  | github.com/milvus-io/milvus/internal/util/function.NewFunctionRunner
  | \t/workspace/source/internal/util/function/function.go:37
  | github.com/milvus-io/milvus/internal/flushcommon/pipeline.newEmbeddingNode
  | \t/workspace/source/internal/flushcommon/pipeline/flow_graph_embedding_node.go:66
  | github.com/milvus-io/milvus/internal/flushcommon/pipeline.getServiceWithChannel
  | \t/workspace/source/internal/flushcommon/pipeline/data_sync_service.go:294
  | github.com/milvus-io/milvus/internal/flushcommon/pipeline.NewDataSyncService
  | \t/workspace/source/internal/flushcommon/pipeline/data_sync_service.go:361
  | github.com/milvus-io/milvus/internal/datanode/channel.executeWatch
  | \t/workspace/source/internal/datanode/channel/channel_manager.go:520
  | github.com/milvus-io/milvus/internal/datanode/channel.(*opRunner).watchWithTimer.func2
  | \t/workspace/source/internal/datanode/channel/channel_manager.go:426
  | runtime.goexit
  | \t/go/pkg/mod/golang.org/[email protected]/src/runtime/asm_amd64.s:1695
Wraps: (2) failed to create tokenizer, C Runtime Exception: invalid tokenizer parameters
Wraps: (3) segcore error[segcoreCode=2001]
Error types: (1) *withstack.withStack (2) *errutil.withPrefix (3) merr.milvusError"]

Nov 11 '24 02:11 chyezh

I discussed this with @aoiasd offline. The tokenizer should not be initialized before bm25 or match is turned on. The instance may ran full text match before(@binbinlv ), which may triggered the false tokenizer init and caused the watch to fail repeatedly, which has resolved in #37478 .

Nov 11 '24 07:11 smellthemoon

/assign @binbinlv

Nov 14 '24 04:11 liliu-z

working on verification.

Nov 15 '24 02:11 binbinlv

Verified and fixed:

milvus: master-20241115-d1596297-amd64 pymilvus: 2.5.0rc121

there is no crash now.

Nov 16 '24 02:11 binbinlv

milvus milvus copied to clipboard

[Bug]: [null & default] Datanode is crashed when flush the nullable enable collection with Null data after run the case to verify the expr cache

Is there an existing issue for this?

Environment

Current Behavior

Expected Behavior

Steps To Reproduce

Milvus Log

Anything else?

milvus
milvus copied to clipboard