milvus icon indicating copy to clipboard operation
milvus copied to clipboard

[Bug]: Search raise error with message `[UnexpectedError] Assert "false" at /go/src/github.com/milvus-io/milvus/internal/core/src/query/SearchOnSealed.cpp:56` after standalone pod kill for 2.1 branch

Open zhuwenxing opened this issue 2 years ago • 4 comments

Is there an existing issue for this?

  • [X] I have searched the existing issues

Environment

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

Current Behavior

collection name: Checker__IEtjaysh

[2022-09-21T09:32:13.307Z] [2022-09-21 09:32:12 - ERROR - pymilvus.decorators]: RPC error: [search], <MilvusException: (code=1, message=fail to search on all shard leaders, err=fail to Search, QueryNode ID=120, reason=Search 120 failed, reason [UnexpectedError] Assert "false" at /go/src/github.com/milvus-io/milvus/internal/core/src/query/SearchOnSealed.cpp:56
[2022-09-21T09:32:13.307Z]  => Error in void knowhere::CheckIntegerRange(const Config&, const string&, int64_t, int64_t) at ConfAdapter.cpp:53: Param 'nprobe' not exist err %!w(<nil>))>, <Time:{'RPC start': '2022-09-21 09:32:12.346867', 'RPC error': '2022-09-21 09:32:12.704574'}> (decorators.py:100)
[2022-09-21T09:32:13.307Z] [2022-09-21 09:32:12 - ERROR - ci_test]: Traceback (most recent call last):
[2022-09-21T09:32:13.307Z]   File "/home/jenkins/agent/workspace/tests/python_client/utils/api_request.py", line 26, in inner_wrapper
[2022-09-21T09:32:13.307Z]     res = func(*args, **_kwargs)
[2022-09-21T09:32:13.307Z]   File "/home/jenkins/agent/workspace/tests/python_client/utils/api_request.py", line 57, in api_request
[2022-09-21T09:32:13.307Z]     return func(*arg, **kwargs)
[2022-09-21T09:32:13.307Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/orm/collection.py", line 718, in search
[2022-09-21T09:32:13.307Z]     partition_names, output_fields, round_decimal, timeout=timeout, schema=schema_dict, **kwargs)
[2022-09-21T09:32:13.307Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/decorators.py", line 101, in handler
[2022-09-21T09:32:13.307Z]     raise e
[2022-09-21T09:32:13.307Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/decorators.py", line 97, in handler
[2022-09-21T09:32:13.307Z]     return func(*args, **kwargs)
[2022-09-21T09:32:13.307Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/decorators.py", line 127, in handler
[2022-09-21T09:32:13.307Z]     ret = func(self, *args, **kwargs)
[2022-09-21T09:32:13.307Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/decorators.py", line 79, in handler
[2022-09-21T09:32:13.307Z]     raise e
[2022-09-21T09:32:13.307Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/decorators.py", line 50, in handler
[2022-09-21T09:32:13.307Z]     return func(self, *args, **kwargs)
[2022-09-21T09:32:13.307Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/client/grpc_handler.py", line 472, in search
[2022-09-21T09:32:13.307Z]     return self._execute_search_requests(requests, timeout, **_kwargs)
[2022-09-21T09:32:13.307Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/client/grpc_handler.py", line 436, in _execute_search_requests
[2022-09-21T09:32:13.307Z]     raise pre_err
[2022-09-21T09:32:13.307Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/client/grpc_handler.py", line 427, in _execute_search_requests
[2022-09-21T09:32:13.307Z]     raise MilvusException(response.status.error_code, response.status.reason)
[2022-09-21T09:32:13.307Z] pymilvus.exceptions.MilvusException: <MilvusException: (code=1, message=fail to search on all shard leaders, err=fail to Search, QueryNode ID=120, reason=Search 120 failed, reason [UnexpectedError] Assert "false" at /go/src/github.com/milvus-io/milvus/internal/core/src/query/SearchOnSealed.cpp:56
[2022-09-21T09:32:13.307Z]  => Error in void knowhere::CheckIntegerRange(const Config&, const string&, int64_t, int64_t) at ConfAdapter.cpp:53: Param 'nprobe' not exist err %!w(<nil>))>
[2022-09-21T09:32:13.307Z]  (api_request.py:39)

Expected Behavior

all test cases passed

Steps To Reproduce

No response

Milvus Log

failed job:https://qa-jenkins.milvus.io/blue/organizations/jenkins/chaos-test-for-release/detail/chaos-test-for-release/737/pipeline/245

log: artifacts-standalone-pod-kill-737-server-logs.tar.gz

artifacts-standalone-pod-kill-737-pytest-logs.tar.gz

Anything else?

No response

zhuwenxing avatar Sep 21 '22 10:09 zhuwenxing

/assign @jiaoew1991 /unassign

yanliang567 avatar Sep 21 '22 11:09 yanliang567

It's a parameter checker in Knowhere, if search params is wrong the error is reasonable

jiaoew1991 avatar Sep 22 '22 09:09 jiaoew1991

@cydrain please take a look

jiaoew1991 avatar Sep 22 '22 10:09 jiaoew1991

It's a parameter checker in Knowhere, if search params is wrong the error is reasonable

The parameter should be correct because it works well before for the same test code.

zhuwenxing avatar Sep 22 '22 10:09 zhuwenxing

chaos type: pod-kill image tag: 2.1.0-20220923-0375e802 target pod: standalone

failed job: https://qa-jenkins.milvus.io/blue/organizations/jenkins/chaos-test-for-release-debug/detail/chaos-test-for-release-debug/8/pipeline

log: artifacts-standalone-pod-kill-8-server-logs.tar.gz artifacts-standalone-pod-kill-8-pytest-logs.tar.gz

zhuwenxing avatar Sep 23 '22 06:09 zhuwenxing

The test script is: https://github.com/milvus-io/milvus/blob/master/tests/python_client/chaos/testcases/test_verify_all_collections.py

The code for search is

    @trace()
    def search(self):
        res, result = self.c_wrap.search(
            data=cf.gen_vectors(5, ct.default_dim),
            anns_field=ct.default_float_vec_field_name,
            param={"nprobe": 32},
            limit=1,
            timeout=timeout,
            check_task=CheckTasks.check_nothing
        )
        return res, result

zhuwenxing avatar Sep 23 '22 06:09 zhuwenxing

It also reproduced after querynode pod kill

failed job: https://qa-jenkins.milvus.io/blue/organizations/jenkins/chaos-test-for-release-debug/detail/chaos-test-for-release-debug/10/pipeline

log: artifacts-querynode-pod-kill-10-server-logs.tar.gz

artifacts-querynode-pod-kill-10-pytest-logs.tar.gz

zhuwenxing avatar Sep 23 '22 07:09 zhuwenxing

hi @jiaoew1991 , I dump out the config before knowhere API is called, you can see "nprobe" setting is already missing. You need check what causes "nprobe" setting missing from config. artifacts-standalone-pod-kill-14-server-logs.tar.gz

CYD - Search config: {"k":1,"metric_type":"L2"}
[2022/09/24 05:25:54.766 +00:00] [DEBUG] [querynode/segment.go:333] ["do search on segment done"] [msgID=436206828880273991] [segmentID=436206691044818945] [segmentType=Sealed] [loadIndex=false]
[2022/09/24 05:25:54.766 +00:00] [DEBUG] [querynode/segment.go:316] ["start do search on segment"] [msgID=436206828880273991] [segmentID=436206684648505348] [segmentType=Sealed] [loadIndex=false]
Assert "false" at /go/src/github.com/milvus-io/milvus/internal/core/src/query/SearchOnSealed.cpp:59
 => Error in void knowhere::CheckIntegerRange(const Config&, const string&, int64_t, int64_t) at ConfAdapter.cpp:53: Param 'nprobe' not exist
[2022/09/24 05:25:54.766 +00:00] [DEBUG] [querynode/segment.go:316] ["start do search on segment"] [msgID=436206828880273991] [segmentID=436206716512108548] [segmentType=Sealed] [loadIndex=false]
[2022/09/24 05:25:54.766 +00:00] [WARN] [querynode/cgo_helper.go:57] ["Search failed, C Runtime Exception: [UnexpectedError] Assert \"false\" at /go/src/github.com/milvus-io/milvus/internal/core/src/query/SearchOnSealed.cpp:59\n => Error in void knowhere::CheckIntegerRange(const Config&, const string&, int64_t, int64_t) at ConfAdapter.cpp:53: Param 'nprobe' not exist\n"]

cydrain avatar Sep 25 '22 05:09 cydrain

@zhuwenxing the param is wrong, you should pass search_params like this image https://milvus.io/api-reference/pymilvus/v2.1.2/Collection/search().md

jiaoew1991 avatar Sep 26 '22 06:09 jiaoew1991

/unassign /assign @zhuwenxing

jiaoew1991 avatar Sep 26 '22 06:09 jiaoew1991

I think it is not the root cause, because, with the param in my code, It works well at the beginning time, but after some time, then it raises the error.

[2022-09-24T05:06:13.288Z] testcases/test_verify_all_collections.py::TestOperations::test_operations[DeleteChecker__89VbCBJT] 
[2022-09-24T05:06:13.288Z] -------------------------------- live log setup --------------------------------
[2022-09-24T05:06:13.288Z] [2022-09-24 05:06:13 - INFO - ci_test]: ################################################################################ (conftest.py:189)
[2022-09-24T05:06:13.288Z] [2022-09-24 05:06:13 - INFO - ci_test]: [initialize_milvus] Log cleaned up, start testing... (conftest.py:190)
[2022-09-24T05:06:13.288Z] [2022-09-24 05:06:13 - INFO - ci_test]: connect to milvus successfully (test_verify_all_collections.py:66)
[2022-09-24T05:06:13.288Z] -------------------------------- live log call ---------------------------------
[2022-09-24T05:06:13.288Z] [2022-09-24 05:06:13 - INFO - ci_test]: *********************Test Start********************** (test_verify_all_collections.py:87)
[2022-09-24T05:06:13.288Z] [2022-09-24 05:06:13 - INFO - ci_test]: {'address': '10.101.118.11:19530', 'user': ''} (test_verify_all_collections.py:88)
[2022-09-24T05:06:39.805Z] [2022-09-24 05:06:36 - INFO - ci_test]: *********************Request Load Start********************** (test_verify_all_collections.py:92)
[2022-09-24T05:06:49.735Z] [2022-09-24 05:06:48 - INFO - ci_test]: InsertChecker, succ_rate: 1.00, total: 012, average_time: 0.0115, max_time: 0.0197, min_time: 0.0082 (checker.py:126)
[2022-09-24T05:06:49.735Z] [2022-09-24 05:06:48 - INFO - ci_test]: FlushChecker, succ_rate: 1.00, total: 003, average_time: 2.5340, max_time: 2.5384, min_time: 2.5259 (checker.py:126)
[2022-09-24T05:06:49.735Z] [2022-09-24 05:06:48 - INFO - ci_test]: IndexChecker, succ_rate: 1.00, total: 002, average_time: 3.8509, max_time: 4.6118, min_time: 3.0901 (checker.py:126)
[2022-09-24T05:06:49.735Z] [2022-09-24 05:06:48 - INFO - ci_test]: SearchChecker, succ_rate: 1.00, total: 010, average_time: 0.2106, max_time: 0.3726, min_time: 0.1578 (checker.py:126)
[2022-09-24T05:06:49.735Z] [2022-09-24 05:06:48 - INFO - ci_test]: QueryChecker, succ_rate: 1.00, total: 010, average_time: 0.2091, max_time: 0.3166, min_time: 0.1649 (checker.py:126)
[2022-09-24T05:06:49.735Z] [2022-09-24 05:06:48 - INFO - ci_test]: DeleteChecker, succ_rate: 1.00, total: 012, average_time: 0.0053, max_time: 0.0213, min_time: 0.0023 (checker.py:126)
[2022-09-24T05:07:01.893Z] [2022-09-24 05:07:00 - INFO - ci_test]: InsertChecker, succ_rate: 1.00, total: 024, average_time: 0.0128, max_time: 0.0378, min_time: 0.0075 (checker.py:126)
[2022-09-24T05:07:01.893Z] [2022-09-24 05:07:00 - INFO - ci_test]: FlushChecker, succ_rate: 1.00, total: 006, average_time: 2.7017, max_time: 3.0437, min_time: 2.5259 (checker.py:126)
[2022-09-24T05:07:01.893Z] [2022-09-24 05:07:00 - INFO - ci_test]: IndexChecker, succ_rate: 1.00, total: 005, average_time: 3.3793, max_time: 4.6118, min_time: 3.0481 (checker.py:126)
[2022-09-24T05:07:01.893Z] [2022-09-24 05:07:00 - INFO - ci_test]: SearchChecker, succ_rate: 1.00, total: 020, average_time: 0.2043, max_time: 0.3726, min_time: 0.1578 (checker.py:126)
[2022-09-24T05:07:01.893Z] [2022-09-24 05:07:00 - INFO - ci_test]: QueryChecker, succ_rate: 1.00, total: 020, average_time: 0.2042, max_time: 0.3166, min_time: 0.1649 (checker.py:126)
[2022-09-24T05:07:01.893Z] [2022-09-24 05:07:00 - INFO - ci_test]: DeleteChecker, succ_rate: 1.00, total: 024, average_time: 0.0046, max_time: 0.0213, min_time: 0.0022 (checker.py:126)
[2022-09-24T05:07:14.048Z] [2022-09-24 05:07:12 - INFO - ci_test]: InsertChecker, succ_rate: 1.00, total: 036, average_time: 0.0138, max_time: 0.0378, min_time: 0.0075 (checker.py:126)
[2022-09-24T05:07:14.048Z] [2022-09-24 05:07:12 - INFO - ci_test]: FlushChecker, succ_rate: 1.00, total: 010, average_time: 2.6861, max_time: 3.0437, min_time: 2.5220 (checker.py:126)
[2022-09-24T05:07:14.048Z] [2022-09-24 05:07:12 - INFO - ci_test]: IndexChecker, succ_rate: 1.00, total: 008, average_time: 3.5776, max_time: 5.1134, min_time: 3.0481 (checker.py:126)
[2022-09-24T05:07:14.048Z] [2022-09-24 05:07:12 - INFO - ci_test]: SearchChecker, succ_rate: 1.00, total: 030, average_time: 0.2137, max_time: 0.3989, min_time: 0.1578 (checker.py:126)
[2022-09-24T05:07:14.048Z] [2022-09-24 05:07:12 - INFO - ci_test]: QueryChecker, succ_rate: 1.00, total: 030, average_time: 0.2052, max_time: 0.3166, min_time: 0.1649 (checker.py:126)
[2022-09-24T05:07:14.048Z] [2022-09-24 05:07:12 - INFO - ci_test]: DeleteChecker, succ_rate: 1.00, total: 036, average_time: 0.0046, max_time: 0.0213, min_time: 0.0022 (checker.py:126)
[2022-09-24T05:07:26.205Z] [2022-09-24 05:07:24 - ERROR - pymilvus.decorators]: RPC error: [search], <MilvusException: (code=1, message=fail to search on all shard leaders, err=fail to Search, QueryNode ID=124, reason=Search 124 failed, reason [UnexpectedError] Assert "false" at /go/src/github.com/milvus-io/milvus/internal/core/src/query/SearchOnSealed.cpp:59
[2022-09-24T05:07:26.205Z]  => Error in void knowhere::CheckIntegerRange(const Config&, const string&, int64_t, int64_t) at ConfAdapter.cpp:53: Param 'nprobe' not exist err %!w(<nil>))>, <Time:{'RPC start': '2022-09-24 05:07:24.217823', 'RPC error': '2022-09-24 05:07:24.412447'}> (decorators.py:100)
[2022-09-24T05:07:26.205Z] [2022-09-24 05:07:24 - ERROR - ci_test]: Traceback (most recent call last):
[2022-09-24T05:07:26.205Z]   File "/home/jenkins/agent/workspace/tests/python_client/utils/api_request.py", line 26, in inner_wrapper
[2022-09-24T05:07:26.205Z]     res = func(*args, **_kwargs)
[2022-09-24T05:07:26.205Z]   File "/home/jenkins/agent/workspace/tests/python_client/utils/api_request.py", line 57, in api_request
[2022-09-24T05:07:26.205Z]     return func(*arg, **kwargs)
[2022-09-24T05:07:26.205Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/orm/collection.py", line 718, in search
[2022-09-24T05:07:26.205Z]     partition_names, output_fields, round_decimal, timeout=timeout, schema=schema_dict, **kwargs)
[2022-09-24T05:07:26.205Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/decorators.py", line 101, in handler
[2022-09-24T05:07:26.205Z]     raise e
[2022-09-24T05:07:26.205Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/decorators.py", line 97, in handler
[2022-09-24T05:07:26.205Z]     return func(*args, **kwargs)
[2022-09-24T05:07:26.205Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/decorators.py", line 127, in handler
[2022-09-24T05:07:26.205Z]     ret = func(self, *args, **kwargs)
[2022-09-24T05:07:26.205Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/decorators.py", line 79, in handler
[2022-09-24T05:07:26.205Z]     raise e
[2022-09-24T05:07:26.206Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/decorators.py", line 50, in handler
[2022-09-24T05:07:26.206Z]     return func(self, *args, **kwargs)
[2022-09-24T05:07:26.206Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/client/grpc_handler.py", line 472, in search
[2022-09-24T05:07:26.206Z]     return self._execute_search_requests(requests, timeout, **_kwargs)
[2022-09-24T05:07:26.206Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/client/grpc_handler.py", line 436, in _execute_search_requests
[2022-09-24T05:07:26.206Z]     raise pre_err
[2022-09-24T05:07:26.206Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/client/grpc_handler.py", line 427, in _execute_search_requests
[2022-09-24T05:07:26.206Z]     raise MilvusException(response.status.error_code, response.status.reason)
[2022-09-24T05:07:26.206Z] pymilvus.exceptions.MilvusException: <MilvusException: (code=1, message=fail to search on all shard leaders, err=fail to Search, QueryNode ID=124, reason=Search 124 failed, reason [UnexpectedError] Assert "false" at /go/src/github.com/milvus-io/milvus/internal/core/src/query/SearchOnSealed.cpp:59
[2022-09-24T05:07:26.206Z]  => Error in void knowhere::CheckIntegerRange(const Config&, const string&, int64_t, int64_t) at ConfAdapter.cpp:53: Param 'nprobe' not exist err %!w(<nil>))>
[2022-09-24T05:07:26.206Z]  (api_request.py:39)
[2022-09-24T05:07:26.206Z] [2022-09-24 05:07:24 - ERROR - ci_test]: (api_response) : <MilvusException: (code=1, message=fail to search on all shard leaders, err=fail to Search, QueryNode ID=124, reason=Search 124 failed, reason [UnexpectedError] Assert "false" at /go/src/github.com/milvus-io/milvus/internal/core/src/query/SearchOnSealed.cpp:59
[2022-09-24T05:07:26.206Z]  => Error in void knowhere::CheckIntege...... (api_request.py:40)
[2022-09-24T05:07:26.206Z] [2022-09-24 05:07:24 - INFO - ci_test]: InsertChecker, succ_rate: 1.00, total: 048, average_time: 0.0129, max_time: 0.0378, min_time: 0.0075 (checker.py:126)
[2022-09-24T05:07:26.206Z] [2022-09-24 05:07:24 - INFO - ci_test]: FlushChecker, succ_rate: 1.00, total: 013, average_time: 2.6496, max_time: 3.0437, min_time: 2.5198 (checker.py:126)
[2022-09-24T05:07:26.206Z] [2022-09-24 05:07:24 - INFO - ci_test]: IndexChecker, succ_rate: 1.00, total: 010, average_time: 3.5819, max_time: 5.1134, min_time: 3.0481 (checker.py:126)
[2022-09-24T05:07:26.206Z] [2022-09-24 05:07:24 - INFO - ci_test]: SearchChecker, succ_rate: 0.97, total: 040, average_time: 0.2121, max_time: 0.3989, min_time: 0.1578 (checker.py:126)
[2022-09-24T05:07:26.206Z] [2022-09-24 05:07:24 - INFO - ci_test]: QueryChecker, succ_rate: 1.00, total: 040, average_time: 0.2063, max_time: 0.3166, min_time: 0.1649 (checker.py:126)
[2022-09-24T05:07:26.206Z] [2022-09-24 05:07:24 - INFO - ci_test]: DeleteChecker, succ_rate: 1.00, total: 048, average_time: 0.0044, max_time: 0.0213, min_time: 0.0022 (checker.py:126)
[2022-09-24T05:07:26.206Z] [2022-09-24 05:07:25 - ERROR - pymilvus.decorators]: RPC error: [search], <MilvusException: (code=1, message=fail to search on all shard leaders, err=fail to Search, QueryNode ID=124, reason=Search 124 failed, reason [UnexpectedError] Assert "false" at /go/src/github.com/milvus-io/milvus/internal/core/src/query/SearchOnSealed.cpp:59
[2022-09-24T05:07:26.206Z]  => Error in void knowhere::CheckIntegerRange(const Config&, const string&, int64_t, int64_t) at ConfAdapter.cpp:53: Param 'nprobe' not exist err %!w(<nil>))>, <Time:{'RPC start': '2022-09-24 05:07:25.416948', 'RPC error': '2022-09-24 05:07:25.611036'}> (decorators.py:100)
[2022-09-24T05:07:26.206Z] [2022-09-24 05:07:25 - ERROR - ci_test]: Traceback (most recent call last):
[2022-09-24T05:07:26.206Z]   File "/home/jenkins/agent/workspace/tests/python_client/utils/api_request.py", line 26, in inner_wrapper
[2022-09-24T05:07:26.206Z]     res = func(*args, **_kwargs)
[2022-09-24T05:07:26.206Z]   File "/home/jenkins/agent/workspace/tests/python_client/utils/api_request.py", line 57, in api_request
[2022-09-24T05:07:26.206Z]     return func(*arg, **kwargs)
[2022-09-24T05:07:26.206Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/orm/collection.py", line 718, in search
[2022-09-24T05:07:26.206Z]     partition_names, output_fields, round_decimal, timeout=timeout, schema=schema_dict, **kwargs)
[2022-09-24T05:07:26.206Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/decorators.py", line 101, in handler
[2022-09-24T05:07:26.206Z]     raise e
[2022-09-24T05:07:26.206Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/decorators.py", line 97, in handler
[2022-09-24T05:07:26.206Z]     return func(*args, **kwargs)
[2022-09-24T05:07:26.206Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/decorators.py", line 127, in handler
[2022-09-24T05:07:26.206Z]     ret = func(self, *args, **kwargs)
[2022-09-24T05:07:26.206Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/decorators.py", line 79, in handler
[2022-09-24T05:07:26.206Z]     raise e
[2022-09-24T05:07:26.206Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/decorators.py", line 50, in handler
[2022-09-24T05:07:26.206Z]     return func(self, *args, **kwargs)
[2022-09-24T05:07:26.206Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/client/grpc_handler.py", line 472, in search
[2022-09-24T05:07:26.206Z]     return self._execute_search_requests(requests, timeout, **_kwargs)
[2022-09-24T05:07:26.206Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/client/grpc_handler.py", line 436, in _execute_search_requests
[2022-09-24T05:07:26.206Z]     raise pre_err
[2022-09-24T05:07:26.206Z]   File "/usr/local/lib/python3.7/dist-packages/pymilvus/client/grpc_handler.py", line 427, in _execute_search_requests
[2022-09-24T05:07:26.206Z]     raise MilvusException(response.status.error_code, response.status.reason)
[2022-09-24T05:07:26.206Z] pymilvus.exceptions.MilvusException: <MilvusException: (code=1, message=fail to search on all shard leaders, err=fail to Search, QueryNode ID=124, reason=Search 124 failed, reason [UnexpectedError] Assert "false" at /go/src/github.com/milvus-io/milvus/internal/core/src/query/SearchOnSealed.cpp:59
[2022-09-24T05:07:26.206Z]  => Error in void knowhere::CheckIntegerRange(const Config&, const string&, int64_t, int64_t) at ConfAdapter.cpp:53: Param 'nprobe' not exist err %!w(<nil>))>
[2022-09-24T05:07:26.206Z]  (api_request.py:39)

zhuwenxing avatar Sep 26 '22 08:09 zhuwenxing

When the search param is complete like {"metric_type": "L2", "params": {"nprobe": 16}}, this issue not reproduced.

[2022-09-26T09:22:53.312Z] testcases/test_verify_all_collections.py::TestOperations::test_operations[Checker__zhFxZeE7] 

[2022-09-26T09:22:53.312Z] -------------------------------- live log setup --------------------------------

[2022-09-26T09:22:53.312Z] [2022-09-26 09:22:52 - INFO - ci_test]: connect to milvus successfully (test_verify_all_collections.py:66)

[2022-09-26T09:22:53.312Z] -------------------------------- live log call ---------------------------------

[2022-09-26T09:22:53.312Z] [2022-09-26 09:22:52 - INFO - ci_test]: *********************Test Start********************** (test_verify_all_collections.py:87)

[2022-09-26T09:22:53.312Z] [2022-09-26 09:22:52 - INFO - ci_test]: {'address': '10.101.141.144:19530', 'user': ''} (test_verify_all_collections.py:88)

[2022-09-26T09:23:25.311Z] [2022-09-26 09:23:22 - INFO - ci_test]: *********************Request Load Start********************** (test_verify_all_collections.py:92)

[2022-09-26T09:23:35.233Z] [2022-09-26 09:23:34 - INFO - ci_test]: InsertChecker, succ_rate: 1.00, total: 012, average_time: 0.0119, max_time: 0.0303, min_time: 0.0068 (checker.py:126)

[2022-09-26T09:23:35.233Z] [2022-09-26 09:23:34 - INFO - ci_test]: FlushChecker, succ_rate: 1.00, total: 003, average_time: 2.8687, max_time: 3.0752, min_time: 2.5172 (checker.py:126)

[2022-09-26T09:23:35.233Z] [2022-09-26 09:23:34 - INFO - ci_test]: IndexChecker, succ_rate: 1.00, total: 001, average_time: 6.6271, max_time: 6.6271, min_time: 6.6271 (checker.py:126)

[2022-09-26T09:23:35.233Z] [2022-09-26 09:23:34 - INFO - ci_test]: SearchChecker, succ_rate: 1.00, total: 010, average_time: 0.2873, max_time: 0.4087, min_time: 0.1647 (checker.py:126)

[2022-09-26T09:23:35.233Z] [2022-09-26 09:23:34 - INFO - ci_test]: QueryChecker, succ_rate: 1.00, total: 010, average_time: 0.2855, max_time: 0.4722, min_time: 0.1345 (checker.py:126)

[2022-09-26T09:23:35.233Z] [2022-09-26 09:23:34 - INFO - ci_test]: DeleteChecker, succ_rate: 1.00, total: 012, average_time: 0.0029, max_time: 0.0093, min_time: 0.0019 (checker.py:126)

[2022-09-26T09:23:47.383Z] [2022-09-26 09:23:46 - INFO - ci_test]: InsertChecker, succ_rate: 1.00, total: 024, average_time: 0.0109, max_time: 0.0303, min_time: 0.0066 (checker.py:126)

[2022-09-26T09:23:47.383Z] [2022-09-26 09:23:46 - INFO - ci_test]: FlushChecker, succ_rate: 1.00, total: 006, average_time: 2.8612, max_time: 3.0752, min_time: 2.5172 (checker.py:126)

[2022-09-26T09:23:47.383Z] [2022-09-26 09:23:46 - INFO - ci_test]: IndexChecker, succ_rate: 1.00, total: 003, average_time: 6.0328, max_time: 6.6271, min_time: 5.7341 (checker.py:126)

[2022-09-26T09:23:47.383Z] [2022-09-26 09:23:46 - INFO - ci_test]: SearchChecker, succ_rate: 1.00, total: 019, average_time: 0.2882, max_time: 0.4455, min_time: 0.1628 (checker.py:126)

[2022-09-26T09:23:47.383Z] [2022-09-26 09:23:46 - INFO - ci_test]: QueryChecker, succ_rate: 1.00, total: 019, average_time: 0.2603, max_time: 0.4722, min_time: 0.1345 (checker.py:126)

[2022-09-26T09:23:47.383Z] [2022-09-26 09:23:46 - INFO - ci_test]: DeleteChecker, succ_rate: 1.00, total: 024, average_time: 0.0028, max_time: 0.0093, min_time: 0.0015 (checker.py:126)

[2022-09-26T09:23:59.534Z] [2022-09-26 09:23:58 - INFO - ci_test]: InsertChecker, succ_rate: 1.00, total: 036, average_time: 0.0105, max_time: 0.0303, min_time: 0.0057 (checker.py:126)

[2022-09-26T09:23:59.534Z] [2022-09-26 09:23:58 - INFO - ci_test]: FlushChecker, succ_rate: 1.00, total: 009, average_time: 2.8624, max_time: 3.0752, min_time: 2.5154 (checker.py:126)

[2022-09-26T09:23:59.534Z] [2022-09-26 09:23:58 - INFO - ci_test]: IndexChecker, succ_rate: 1.00, total: 005, average_time: 5.8727, max_time: 6.6271, min_time: 5.1134 (checker.py:126)

[2022-09-26T09:23:59.534Z] [2022-09-26 09:23:58 - INFO - ci_test]: SearchChecker, succ_rate: 1.00, total: 027, average_time: 0.3218, max_time: 0.4984, min_time: 0.1628 (checker.py:126)

[2022-09-26T09:23:59.534Z] [2022-09-26 09:23:58 - INFO - ci_test]: QueryChecker, succ_rate: 1.00, total: 029, average_time: 0.2621, max_time: 0.4722, min_time: 0.1345 (checker.py:126)

[2022-09-26T09:23:59.534Z] [2022-09-26 09:23:58 - INFO - ci_test]: DeleteChecker, succ_rate: 1.00, total: 036, average_time: 0.0029, max_time: 0.0125, min_time: 0.0015 (checker.py:126)

[2022-09-26T09:24:11.689Z] [2022-09-26 09:24:10 - INFO - ci_test]: InsertChecker, succ_rate: 1.00, total: 048, average_time: 0.0106, max_time: 0.0303, min_time: 0.0057 (checker.py:126)

[2022-09-26T09:24:11.689Z] [2022-09-26 09:24:10 - INFO - ci_test]: FlushChecker, succ_rate: 1.00, total: 012, average_time: 2.8251, max_time: 3.0752, min_time: 2.5140 (checker.py:126)

[2022-09-26T09:24:11.689Z] [2022-09-26 09:24:10 - INFO - ci_test]: IndexChecker, succ_rate: 1.00, total: 007, average_time: 5.8293, max_time: 6.6271, min_time: 5.1134 (checker.py:126)

[2022-09-26T09:24:11.689Z] [2022-09-26 09:24:10 - INFO - ci_test]: SearchChecker, succ_rate: 1.00, total: 036, average_time: 0.3307, max_time: 0.4984, min_time: 0.1628 (checker.py:126)

[2022-09-26T09:24:11.689Z] [2022-09-26 09:24:10 - INFO - ci_test]: QueryChecker, succ_rate: 1.00, total: 038, average_time: 0.2667, max_time: 0.4722, min_time: 0.1345 (checker.py:126)

[2022-09-26T09:24:11.689Z] [2022-09-26 09:24:10 - INFO - ci_test]: DeleteChecker, succ_rate: 1.00, total: 048, average_time: 0.0034, max_time: 0.0143, min_time: 0.0015 (checker.py:126)

[2022-09-26T09:24:23.849Z] [2022-09-26 09:24:22 - INFO - ci_test]: InsertChecker, succ_rate: 1.00, total: 060, average_time: 0.0155, max_time: 0.2388, min_time: 0.0056 (checker.py:126)

[2022-09-26T09:24:23.849Z] [2022-09-26 09:24:22 - INFO - ci_test]: FlushChecker, succ_rate: 1.00, total: 015, average_time: 2.8697, max_time: 3.1065, min_time: 2.5140 (checker.py:126)

[2022-09-26T09:24:23.849Z] [2022-09-26 09:24:22 - INFO - ci_test]: IndexChecker, succ_rate: 1.00, total: 008, average_time: 5.8711, max_time: 6.6271, min_time: 5.1134 (checker.py:126)

[2022-09-26T09:24:23.849Z] [2022-09-26 09:24:22 - INFO - ci_test]: SearchChecker, succ_rate: 1.00, total: 046, average_time: 0.3202, max_time: 0.4984, min_time: 0.1628 (checker.py:126)

[2022-09-26T09:24:23.849Z] [2022-09-26 09:24:22 - INFO - ci_test]: QueryChecker, succ_rate: 1.00, total: 048, average_time: 0.2649, max_time: 0.4722, min_time: 0.1345 (checker.py:126)

[2022-09-26T09:24:23.849Z] [2022-09-26 09:24:22 - INFO - ci_test]: DeleteChecker, succ_rate: 1.00, total: 060, average_time: 0.0033, max_time: 0.0143, min_time: 0.0015 (checker.py:126)

[2022-09-26T09:24:36.007Z] [2022-09-26 09:24:34 - INFO - ci_test]: InsertChecker, succ_rate: 1.00, total: 071, average_time: 0.0218, max_time: 0.2388, min_time: 0.0056 (checker.py:126)

[2022-09-26T09:24:36.007Z] [2022-09-26 09:24:34 - INFO - ci_test]: FlushChecker, succ_rate: 1.00, total: 018, average_time: 2.9345, max_time: 4.2132, min_time: 2.5140 (checker.py:126)

[2022-09-26T09:24:36.007Z] [2022-09-26 09:24:34 - INFO - ci_test]: IndexChecker, succ_rate: 1.00, total: 009, average_time: 5.9544, max_time: 6.6271, min_time: 5.1134 (checker.py:126)

[2022-09-26T09:24:36.007Z] [2022-09-26 09:24:34 - INFO - ci_test]: SearchChecker, succ_rate: 1.00, total: 054, average_time: 0.3348, max_time: 0.5121, min_time: 0.1628 (checker.py:126)

[2022-09-26T09:24:36.007Z] [2022-09-26 09:24:34 - INFO - ci_test]: QueryChecker, succ_rate: 1.00, total: 057, average_time: 0.2648, max_time: 0.4722, min_time: 0.1345 (checker.py:126)

[2022-09-26T09:24:36.007Z] [2022-09-26 09:24:34 - INFO - ci_test]: DeleteChecker, succ_rate: 1.00, total: 072, average_time: 0.0033, max_time: 0.0143, min_time: 0.0015 (checker.py:126)

[2022-09-26T09:24:48.161Z] [2022-09-26 09:24:46 - INFO - ci_test]: InsertChecker, succ_rate: 1.00, total: 082, average_time: 0.0315, max_time: 0.3768, min_time: 0.0056 (checker.py:126)

[2022-09-26T09:24:48.161Z] [2022-09-26 09:24:46 - INFO - ci_test]: FlushChecker, succ_rate: 1.00, total: 020, average_time: 3.1033, max_time: 6.1207, min_time: 2.5140 (checker.py:126)

[2022-09-26T09:24:48.161Z] [2022-09-26 09:24:46 - INFO - ci_test]: IndexChecker, succ_rate: 1.00, total: 011, average_time: 6.5832, max_time: 9.8440, min_time: 5.1134 (checker.py:126)

[2022-09-26T09:24:48.161Z] [2022-09-26 09:24:46 - INFO - ci_test]: SearchChecker, succ_rate: 1.00, total: 064, average_time: 0.3263, max_time: 0.5121, min_time: 0.1628 (checker.py:126)

[2022-09-26T09:24:48.161Z] [2022-09-26 09:24:46 - INFO - ci_test]: QueryChecker, succ_rate: 1.00, total: 067, average_time: 0.2666, max_time: 0.4722, min_time: 0.1345 (checker.py:126)

[2022-09-26T09:24:48.161Z] [2022-09-26 09:24:46 - INFO - ci_test]: DeleteChecker, succ_rate: 1.00, total: 084, average_time: 0.0032, max_time: 0.0143, min_time: 0.0015 (checker.py:126)

[2022-09-26T09:25:00.310Z] [2022-09-26 09:24:58 - INFO - ci_test]: InsertChecker, succ_rate: 1.00, total: 094, average_time: 0.0287, max_time: 0.3768, min_time: 0.0056 (checker.py:126)

[2022-09-26T09:25:00.310Z] [2022-09-26 09:24:58 - INFO - ci_test]: FlushChecker, succ_rate: 1.00, total: 023, average_time: 3.1034, max_time: 6.1207, min_time: 2.5140 (checker.py:126)

[2022-09-26T09:25:00.310Z] [2022-09-26 09:24:58 - INFO - ci_test]: IndexChecker, succ_rate: 1.00, total: 012, average_time: 6.5525, max_time: 9.8440, min_time: 5.1134 (checker.py:126)

[2022-09-26T09:25:00.310Z] [2022-09-26 09:24:58 - INFO - ci_test]: SearchChecker, succ_rate: 1.00, total: 072, average_time: 0.3333, max_time: 0.5121, min_time: 0.1628 (checker.py:126)

[2022-09-26T09:25:00.310Z] [2022-09-26 09:24:58 - INFO - ci_test]: QueryChecker, succ_rate: 1.00, total: 075, average_time: 0.2794, max_time: 0.4873, min_time: 0.1345 (checker.py:126)

[2022-09-26T09:25:00.310Z] [2022-09-26 09:24:58 - INFO - ci_test]: DeleteChecker, succ_rate: 1.00, total: 096, average_time: 0.0032, max_time: 0.0143, min_time: 0.0015 (checker.py:126)

[2022-09-26T09:25:10.292Z] [2022-09-26 09:25:10 - INFO - ci_test]: InsertChecker, succ_rate: 1.00, total: 106, average_time: 0.0266, max_time: 0.3768, min_time: 0.0056 (checker.py:126)

[2022-09-26T09:25:10.292Z] [2022-09-26 09:25:10 - INFO - ci_test]: FlushChecker, succ_rate: 1.00, total: 026, average_time: 3.0584, max_time: 6.1207, min_time: 2.5140 (checker.py:126)

[2022-09-26T09:25:10.292Z] [2022-09-26 09:25:10 - INFO - ci_test]: IndexChecker, succ_rate: 1.00, total: 014, average_time: 6.4954, max_time: 9.8440, min_time: 5.1134 (checker.py:126)

[2022-09-26T09:25:10.292Z] [2022-09-26 09:25:10 - INFO - ci_test]: SearchChecker, succ_rate: 1.00, total: 081, average_time: 0.3404, max_time: 0.5121, min_time: 0.1628 (checker.py:126)

[2022-09-26T09:25:10.292Z] [2022-09-26 09:25:10 - INFO - ci_test]: QueryChecker, succ_rate: 1.00, total: 085, average_time: 0.2771, max_time: 0.4873, min_time: 0.1345 (checker.py:126)

[2022-09-26T09:25:10.292Z] [2022-09-26 09:25:10 - INFO - ci_test]: DeleteChecker, succ_rate: 1.00, total: 108, average_time: 0.0035, max_time: 0.0211, min_time: 0.0015 (checker.py:126)

[2022-09-26T09:25:22.447Z] [2022-09-26 09:25:22 - INFO - ci_test]: InsertChecker, succ_rate: 1.00, total: 118, average_time: 0.0251, max_time: 0.3768, min_time: 0.0056 (checker.py:126)

[2022-09-26T09:25:22.447Z] [2022-09-26 09:25:22 - INFO - ci_test]: FlushChecker, succ_rate: 1.00, total: 030, average_time: 2.9993, max_time: 6.1207, min_time: 2.5140 (checker.py:126)

[2022-09-26T09:25:22.447Z] [2022-09-26 09:25:22 - INFO - ci_test]: IndexChecker, succ_rate: 1.00, total: 016, average_time: 6.5224, max_time: 9.8440, min_time: 5.1134 (checker.py:126)

[2022-09-26T09:25:22.447Z] [2022-09-26 09:25:22 - INFO - ci_test]: SearchChecker, succ_rate: 1.00, total: 090, average_time: 0.3442, max_time: 0.5121, min_time: 0.1628 (checker.py:126)

[2022-09-26T09:25:22.447Z] [2022-09-26 09:25:22 - INFO - ci_test]: QueryChecker, succ_rate: 1.00, total: 094, average_time: 0.2846, max_time: 0.4873, min_time: 0.1345 (checker.py:126)

[2022-09-26T09:25:22.447Z] [2022-09-26 09:25:22 - INFO - ci_test]: DeleteChecker, succ_rate: 1.00, total: 120, average_time: 0.0034, max_time: 0.0211, min_time: 0.0015 (checker.py:126)

[2022-09-26T09:25:22.447Z] [2022-09-26 09:25:22 - INFO - ci_test]: ******assert after chaos deleted:  (test_verify_all_collections.py:102)

[2022-09-26T09:25:22.447Z] [2022-09-26 09:25:22 - INFO - ci_test]: Expect Succ: Op.insert succ rate 1.0, total: 118, average time: 0.0251 (chaos_commons.py:87)

[2022-09-26T09:25:22.447Z] [2022-09-26 09:25:22 - INFO - ci_test]: Expect Succ: Op.flush succ rate 1.0, total: 30, average time: 2.9993 (chaos_commons.py:87)

[2022-09-26T09:25:22.447Z] [2022-09-26 09:25:22 - INFO - ci_test]: Expect Succ: Op.index succ rate 1.0, total: 16, average time: 6.5224 (chaos_commons.py:87)

[2022-09-26T09:25:22.447Z] [2022-09-26 09:25:22 - INFO - ci_test]: Expect Succ: Op.search succ rate 1.0, total: 90, average time: 0.3442 (chaos_commons.py:87)

[2022-09-26T09:25:22.447Z] [2022-09-26 09:25:22 - INFO - ci_test]: Expect Succ: Op.query succ rate 1.0, total: 94, average time: 0.2846 (chaos_commons.py:87)

[2022-09-26T09:25:22.447Z] [2022-09-26 09:25:22 - INFO - ci_test]: Expect Succ: Op.delete succ rate 1.0, total: 120, average time: 0.0034 (chaos_commons.py:87)

[2022-09-26T09:25:22.447Z] [2022-09-26 09:25:22 - INFO - ci_test]: *********************Test Completed********************** (test_verify_all_collections.py:105)

[2022-09-26T09:25:22.447Z] PASSED

zhuwenxing avatar Sep 26 '22 09:09 zhuwenxing