[Bug]: flush timeout after milvus recovered from pulsar pod kill chaos test

[zhuwenxing]

[Bug]: flush timeout after milvus recovered from pulsar pod kill chaos test

[yanliang567]

/assign @weiliu1031
/unassign

[xiaofan-luan]

/assign @bigsheeper
please help on it

[XuanYang-cn]

segment 450758977781515919 's data is lost from pulsar.

after DN recovering and seek to 17:31:42, the msg in between 17:31:42 are lost cpTime=2024/06/27 17:46:30.521 are lost.

so the flush is timeout.

[2024/06/27 17:46:21.202 +00:00] [INFO] [datanode/flow_graph_dmstream_input_node.go:53] ["datanode seek successfully when register to msgDispatcher"] [nodeID=13] [collectionID=450758977781515635] [vchannel=by-dev-rootcoord-dml_10_450758977781515635v1] [msgID="\u0008\n\u0010\ufffd\u0006\u0018\u0000 \u0000"] [tsTime=2024/06/27 17:31:42.121 +00:00] [tsLag=14m39.081598088s]
[2024/06/27 17:46:21.202 +00:00] [INFO] [datanode/data_sync_service.go:93] ["dataSyncService starting flow graph"] [collectionID=450758977781515635] [vChanName=by-dev-rootcoord-dml_10_450758977781515635v1]
[2024/06/27 17:46:21.202 +00:00] [INFO] [datanode/channel_manager.go:379] ["Stop timer for ToWatch operation succeeded"] [channel=by-dev-rootcoord-dml_10_450758977781515635v1] [opID=450758977782726625] [timeout=5m0s]
[2024/06/27 17:46:21.202 +00:00] [INFO] [datanode/channel_manager.go:194] ["Success to watch"] [opID=450758977782726625] [channel=by-dev-rootcoord-dml_10_450758977781515635v1] [State=WatchSuccess]
[2024/06/27 17:46:21.344 +00:00] [INFO] [msgdispatcher/manager.go:198] ["start merging..."] [role=datanode] [nodeID=13] [vchannel="{\"by-dev-rootcoord-dml_10_450758977781515635v1\":{}}"]
[2024/06/27 17:46:21.344 +00:00] [INFO] [msgdispatcher/dispatcher.go:149] ["add new target"] [vchannel=by-dev-rootcoord-dml_10_450758977781515635v1] [isMain=true]
[2024/06/27 17:46:21.373 +00:00] [INFO] [msgdispatcher/manager.go:218] ["merge done"] [role=datanode] [nodeID=13] [vchannel="{\"by-dev-rootcoord-dml_10_450758977781515635v1\":{}}"]
[2024/06/27 17:46:21.784 +00:00] [INFO] [datanode/services.go:381] ["DataNode receives CheckChannelOperationProgress"] [traceID=c4cc98513456be9c1824b08d196f446a] [channel=by-dev-rootcoord-dml_10_450758977781515635v1] [operation=ToWatch]
[2024/06/27 17:47:00.720 +00:00] [DEBUG] [writebuffer/write_buffer.go:291] ["checkpoint from latest consumed msg"] [collectionID=450758977781515635] [channel=by-dev-rootcoord-dml_10_450758977781515635v1] [cpTimestamp=450759331812737025]
[2024/06/27 17:47:02.392 +00:00] [DEBUG] [datanode/flow_graph_time_tick_node.go:122] ["UpdateChannelCheckpoint success"] [channel=by-dev-rootcoord-dml_10_450758977781515635v1] [cpTs=450759331812737025] [cpTime=2024/06/27 17:46:30.521 +00:00]

 5977 [2024/06/27 17:55:51.734 +00:00] [INFO] [datacoord/services.go:1241] ["DataCoord receive GetFlushState request, Flushed is false"] [traceID=9cc685a95c1cfb1ffd54f70ba951b85b] [collection=450758977781515635] [flushTs=2024/06/27 17:55:42.671 +00:00] [unflushed="[450758977781515919]"] [len=1]

[bigsheeper]

segment 450758977781515919 's data is lost from pulsar.

after DN recovering and seek to 17:31:42, the msg in between 17:31:42 are lost cpTime=2024/06/27 17:46:30.521 are lost.

so the flush is timeout.

[2024/06/27 17:46:21.202 +00:00] [INFO] [datanode/flow_graph_dmstream_input_node.go:53] ["datanode seek successfully when register to msgDispatcher"] [nodeID=13] [collectionID=450758977781515635] [vchannel=by-dev-rootcoord-dml_10_450758977781515635v1] [msgID="\u0008\n\u0010\ufffd\u0006\u0018\u0000 \u0000"] [tsTime=2024/06/27 17:31:42.121 +00:00] [tsLag=14m39.081598088s]
[2024/06/27 17:46:21.202 +00:00] [INFO] [datanode/data_sync_service.go:93] ["dataSyncService starting flow graph"] [collectionID=450758977781515635] [vChanName=by-dev-rootcoord-dml_10_450758977781515635v1]
[2024/06/27 17:46:21.202 +00:00] [INFO] [datanode/channel_manager.go:379] ["Stop timer for ToWatch operation succeeded"] [channel=by-dev-rootcoord-dml_10_450758977781515635v1] [opID=450758977782726625] [timeout=5m0s]
[2024/06/27 17:46:21.202 +00:00] [INFO] [datanode/channel_manager.go:194] ["Success to watch"] [opID=450758977782726625] [channel=by-dev-rootcoord-dml_10_450758977781515635v1] [State=WatchSuccess]
[2024/06/27 17:46:21.344 +00:00] [INFO] [msgdispatcher/manager.go:198] ["start merging..."] [role=datanode] [nodeID=13] [vchannel="{\"by-dev-rootcoord-dml_10_450758977781515635v1\":{}}"]
[2024/06/27 17:46:21.344 +00:00] [INFO] [msgdispatcher/dispatcher.go:149] ["add new target"] [vchannel=by-dev-rootcoord-dml_10_450758977781515635v1] [isMain=true]
[2024/06/27 17:46:21.373 +00:00] [INFO] [msgdispatcher/manager.go:218] ["merge done"] [role=datanode] [nodeID=13] [vchannel="{\"by-dev-rootcoord-dml_10_450758977781515635v1\":{}}"]
[2024/06/27 17:46:21.784 +00:00] [INFO] [datanode/services.go:381] ["DataNode receives CheckChannelOperationProgress"] [traceID=c4cc98513456be9c1824b08d196f446a] [channel=by-dev-rootcoord-dml_10_450758977781515635v1] [operation=ToWatch]
[2024/06/27 17:47:00.720 +00:00] [DEBUG] [writebuffer/write_buffer.go:291] ["checkpoint from latest consumed msg"] [collectionID=450758977781515635] [channel=by-dev-rootcoord-dml_10_450758977781515635v1] [cpTimestamp=450759331812737025]
[2024/06/27 17:47:02.392 +00:00] [DEBUG] [datanode/flow_graph_time_tick_node.go:122] ["UpdateChannelCheckpoint success"] [channel=by-dev-rootcoord-dml_10_450758977781515635v1] [cpTs=450759331812737025] [cpTime=2024/06/27 17:46:30.521 +00:00]

 5977 [2024/06/27 17:55:51.734 +00:00] [INFO] [datacoord/services.go:1241] ["DataCoord receive GetFlushState request, Flushed is false"] [traceID=9cc685a95c1cfb1ffd54f70ba951b85b] [collection=450758977781515635] [flushTs=2024/06/27 17:55:42.671 +00:00] [unflushed="[450758977781515919]"] [len=1]

Yes, after the datanode restart, the flowgraph did not receive insert data of segment 450758977781515919. There are several possible reasons for this:

1. The channel checkpoint was incorrectly advanced past segment 450758977781515919 (without flush/sync).
2. The insert data consumed was incorrectly skipped.
3. Data was lost in Pulsar (although data was present in Pulsar before the datanode restart).

[zhuwenxing]

it is not a stable reproduced issue. so it is a bit hard to verify and reproduce

[bigsheeper]

it is not a stable reproduced issue. so it is a bit hard to verify and reproduce

Try to add some key logs; we'll look into it if it happens again.

[zhuwenxing]

There is a reproduced case in 2.4-20240708-f6cd8416-amd64
failed job: https://qa-jenkins.milvus.io/blue/organizations/jenkins/chaos-test-for-release-cron/detail/chaos-test-for-release-cron/14352/pipeline

log:
artifacts-pulsar-pod-kill-14352-server-logs.tar.gz

[2024-07-08T21:33:29.882Z] <name>: SearchChecker__GGsK0j2n

[2024-07-08T21:33:29.882Z] <description>: 

[2024-07-08T21:33:29.882Z] <schema>: {'auto_id': False, 'description': '', 'fields': [{'name': 'int64', 'description': '', 'type': <DataType.INT64: 5>, 'is_primary': True, 'auto_id': False}, {'name': 'float', 'description': '', 'type': <DataType.FLOAT......  (api_request.py:37)

[2024-07-08T21:33:29.882Z] [2024-07-08 21:30:21 - DEBUG - ci_test]: (api_request)  : [Collection.flush] args: [], kwargs: {'timeout': 180} (api_request.py:62)

[2024-07-08T21:33:29.882Z] [2024-07-08 21:33:21 - WARNING - pymilvus.decorators]: Retry timeout: 180s (decorators.py:106)

[2024-07-08T21:33:29.882Z] [2024-07-08 21:33:21 - ERROR - pymilvus.decorators]: RPC error: [flush], <MilvusException: (code=1, message=Retry timeout: 180s, message=wait for flush timeout, collection: SearchChecker__GGsK0j2n, flusht_ts: 451011994230456324)>, <Time:{'RPC start': '2024-07-08 21:30:21.415697', 'RPC error': '2024-07-08 21:33:21.580120'}> (decorators.py:146)

[2024-07-08T21:33:29.882Z] [2024-07-08 21:33:21 - ERROR - ci_test]: Traceback (most recent call last):

[2024-07-08T21:33:29.882Z]   File "/home/jenkins/agent/workspace/tests/python_client/utils/api_request.py", line 32, in inner_wrapper

[2024-07-08T21:33:29.882Z]     res = func(*args, **_kwargs)

[2024-07-08T21:33:29.882Z]   File "/home/jenkins/agent/workspace/tests/python_client/utils/api_request.py", line 63, in api_request

[2024-07-08T21:33:29.882Z]     return func(*arg, **kwargs)

[2024-07-08T21:33:29.882Z]   File "/usr/local/lib/python3.8/dist-packages/pymilvus/orm/collection.py", line 319, in flush

[2024-07-08T21:33:29.882Z]     conn.flush([self.name], timeout=timeout, **kwargs)

[2024-07-08T21:33:29.882Z]   File "/usr/local/lib/python3.8/dist-packages/pymilvus/decorators.py", line 147, in handler

[2024-07-08T21:33:29.882Z]     raise e from e

[2024-07-08T21:33:29.882Z]   File "/usr/local/lib/python3.8/dist-packages/pymilvus/decorators.py", line 143, in handler

[2024-07-08T21:33:29.882Z]     return func(*args, **kwargs)

[2024-07-08T21:33:29.882Z]   File "/usr/local/lib/python3.8/dist-packages/pymilvus/decorators.py", line 182, in handler

[2024-07-08T21:33:29.882Z]     return func(self, *args, **kwargs)

[2024-07-08T21:33:29.882Z]   File "/usr/local/lib/python3.8/dist-packages/pymilvus/decorators.py", line 107, in handler

[2024-07-08T21:33:29.882Z]     raise MilvusException(

[2024-07-08T21:33:29.882Z] pymilvus.exceptions.MilvusException: <MilvusException: (code=1, message=Retry timeout: 180s, message=wait for flush timeout, collection: SearchChecker__GGsK0j2n, flusht_ts: 451011994230456324)>

[2024-07-08T21:33:29.882Z]  (api_request.py:45)

[2024-07-08T21:33:29.882Z] [2024-07-08 21:33:21 - ERROR - ci_test]: (api_response) : <MilvusException: (code=1, message=Retry timeout: 180s, message=wait for flush timeout, collection: SearchChecker__GGsK0j2n, flusht_ts: 451011994230456324)> (api_request.py:46)

[zhuwenxing]

reproduced in master-20240709-eeb03a0d-amd64 datanode chaos test

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

log:artifacts-datanode-pod-kill-15588-server-logs.tar.gz

[bigsheeper]

The cause of this issue is different; it's due to tt delay:

[bigsheeper]

reproduced in master-20240709-eeb03a0d-amd64 datanode chaos test

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

log:artifacts-datanode-pod-kill-15588-server-logs.tar.gz

dispatcher merged by mistake, the insert data consumed was incorrectly skipped:

[bigsheeper]

/assign @zhuwenxing
should be fixed

[bigsheeper]

/unassign

[zhuwenxing]

verified and not reproduced in master-20240713-2c462d38-amd64