Fix flaky capture service start #20024

zbud-msft · 2024-08-27T00:48:43Z

Why I did it

Dropping control character (message sent when XSUB connects to XPUB as part of ZMQ Proxy setup to notify that subscription has been made) in do capture has been flaky since control character is not guaranteed to be the first message sent if there are events (like event-down-ctr) being published to XSUB.

Scenarios

Control character is sent and is first message when starting capture service

eventd#eventd#eventd: :- heartbeat_ctrl: Set heartbeat_ctrl pause=1
eventd#eventd#eventd: :- do_capture: Received subscription message when XSUB connects to XPUB

Events like event-down ctr is sent before control character

eventd#eventd#eventd: :- run: Dropping Message: 22 serialization::archive 18 17 sonic-events-host
eventd#eventd#eventd: :- run: Dropping Message: 22 serialization::archive 18 0 0 4 0 0 0 1 d 103 {"sonic-events-host:event-stopped-ctr":{"ctr_name":"EVENTD","timestamp":"2024-08-27T00:02:51.407518Z"}} 1 r 36 3357542f-bae1-458f-a804-660e620d21f5 1 s 1 9 1 t 19 1724716971407591080
heartbeat_ctrl: Set heartbeat_ctrl pause=1
do_capture: Received subscription message when XSUB connects to XPUB

Control character is not sent at all

eventd#eventd#eventd: :- heartbeat_ctrl: Set heartbeat_ctrl pause=1

Control character is delayed and not caught when starting capture service, but is then caught after causing deserialize error.

do_capture: Receiving event from source: 22 serialization::archive 18 17 sonic-events-host, will read second part of event
deserialize: deserialize Failed: input stream errorstr[0:64]:(#001) data type: std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&
zmq_read_part: Failed to deserialize part rc=-2
zmq_read_part: last:errno=11
zmq_message_read: Failure to read part1 rc=-2
zmq_message_read: last:errno=11

We can cover these scenarios by just dropping the control character inside zmq_message_read as part of events_common in swsscommon (different PR). In this PR we will remove such handling logic and make sure that empty events that will be sent by control character are ignored.

Work item tracking

Microsoft ADO (number only):28728116

How I did it

Remove logic for handling control character

How to verify it

UT and sonic-mgmt test cases.

Which release branch to backport (provide reason below if selected)

Tested branch (Please provide the tested image version)

Description for the changelog

Link to config_db schema for YANG module changes

A picture of a cute animal (not mandatory but encouraged)

linux-foundation-easycla · 2024-08-27T00:48:47Z

The committers listed above are authorized under a signed CLA.

✅ login: zbud-msft / name: Zain Budhwani (dc2e7bc, 3d5f62d, 967caa8, afa2e6b)

liuh-80 · 2024-08-27T01:48:05Z

src/sonic-eventd/src/eventd.cpp

+            int more = 0;
+            size_t more_size = sizeof(more);
+            zmq_getsockopt(cap_sub_sock, ZMQ_RCVMORE, &more, &more_size);
+            if(more) {


Do we need a loop here to read all message?

Also, if there is an ADO please update the PR description.

Changed logic to not account for capture service capturing control character. Will be done in zmq_read_part

sonic-net/sonic-swss-common#906

liuh-80 · 2024-08-27T01:55:21Z

src/sonic-eventd/src/eventd.cpp

+
+
+        if(rc == 1) { // Expected case to receive subscription message as very first message
+            SWSS_LOG_INFO("Received subscription message when XSUB connects to XPUB");


If there are too much "received subscription message" log, suggest change to SWSS_LOG_DEBUG.

This will happen only once during process lifetime.

zbud-msft · 2024-08-27T22:03:51Z

Relies on sonic-net/sonic-swss-common#906

zbud-msft · 2024-08-30T18:46:59Z

@StormLiangMS Can we backport this to 202311?

#### Why I did it Dropping control character (message sent when XSUB connects to XPUB as part of ZMQ Proxy setup to notify that subscription has been made) in do capture has been flaky since control character is not guaranteed to be the first message sent if there are events (like event-down-ctr) being published to XSUB. Scenarios 1) Control character is sent and is first message when starting capture service `eventd#eventd#eventd: :- heartbeat_ctrl: Set heartbeat_ctrl pause=1` `eventd#eventd#eventd: :- do_capture: Received subscription message when XSUB connects to XPUB` 2) Events like event-down ctr is sent before control character `eventd#eventd#eventd: :- run: Dropping Message: 22 serialization::archive 18 17 sonic-events-host` `eventd#eventd#eventd: :- run: Dropping Message: 22 serialization::archive 18 0 0 4 0 0 0 1 d 103 {"sonic-events-host:event-stopped-ctr":{"ctr_name":"EVENTD","timestamp":"2024-08-27T00:02:51.407518Z"}} 1 r 36 3357542f-bae1-458f-a804-660e620d21f5 1 s 1 9 1 t 19 1724716971407591080` `heartbeat_ctrl: Set heartbeat_ctrl pause=1` `do_capture: Received subscription message when XSUB connects to XPUB` 3) Control character is not sent at all `eventd#eventd#eventd: :- heartbeat_ctrl: Set heartbeat_ctrl pause=1` 4) Control character is delayed and not caught when starting capture service, but is then caught after causing deserialize error. `do_capture: Receiving event from source: 22 serialization::archive 18 17 sonic-events-host, will read second part of event` `deserialize: deserialize Failed: input stream errorstr[0:64]:(sonic-net#1) data type: std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&` `zmq_read_part: Failed to deserialize part rc=-2` `zmq_read_part: last:errno=11` `zmq_message_read: Failure to read part1 rc=-2` `zmq_message_read: last:errno=11` We can cover these scenarios by just dropping the control character inside zmq_message_read as part of events_common in swsscommon (different PR). In this PR we will remove such handling logic and make sure that empty events that will be sent by control character are ignored. ##### Work item tracking - Microsoft ADO **(number only)**:28728116 #### How I did it Remove logic for handling control character #### How to verify it UT and sonic-mgmt test cases.

mssonicbld · 2024-09-04T15:51:30Z

Cherry-pick PR to 202311: #20130

#### Why I did it Dropping control character (message sent when XSUB connects to XPUB as part of ZMQ Proxy setup to notify that subscription has been made) in do capture has been flaky since control character is not guaranteed to be the first message sent if there are events (like event-down-ctr) being published to XSUB. Scenarios 1) Control character is sent and is first message when starting capture service `eventd#eventd#eventd: :- heartbeat_ctrl: Set heartbeat_ctrl pause=1` `eventd#eventd#eventd: :- do_capture: Received subscription message when XSUB connects to XPUB` 2) Events like event-down ctr is sent before control character `eventd#eventd#eventd: :- run: Dropping Message: 22 serialization::archive 18 17 sonic-events-host` `eventd#eventd#eventd: :- run: Dropping Message: 22 serialization::archive 18 0 0 4 0 0 0 1 d 103 {"sonic-events-host:event-stopped-ctr":{"ctr_name":"EVENTD","timestamp":"2024-08-27T00:02:51.407518Z"}} 1 r 36 3357542f-bae1-458f-a804-660e620d21f5 1 s 1 9 1 t 19 1724716971407591080` `heartbeat_ctrl: Set heartbeat_ctrl pause=1` `do_capture: Received subscription message when XSUB connects to XPUB` 3) Control character is not sent at all `eventd#eventd#eventd: :- heartbeat_ctrl: Set heartbeat_ctrl pause=1` 4) Control character is delayed and not caught when starting capture service, but is then caught after causing deserialize error. `do_capture: Receiving event from source: 22 serialization::archive 18 17 sonic-events-host, will read second part of event` `deserialize: deserialize Failed: input stream errorstr[0:64]:(sonic-net#1) data type: std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&` `zmq_read_part: Failed to deserialize part rc=-2` `zmq_read_part: last:errno=11` `zmq_message_read: Failure to read part1 rc=-2` `zmq_message_read: last:errno=11` We can cover these scenarios by just dropping the control character inside zmq_message_read as part of events_common in swsscommon (different PR). In this PR we will remove such handling logic and make sure that empty events that will be sent by control character are ignored. ##### Work item tracking - Microsoft ADO **(number only)**:28728116 #### How I did it Remove logic for handling control character #### How to verify it UT and sonic-mgmt test cases.

mssonicbld · 2024-09-04T15:52:53Z

Cherry-pick PR to 202405: #20131

#### Why I did it Dropping control character (message sent when XSUB connects to XPUB as part of ZMQ Proxy setup to notify that subscription has been made) in do capture has been flaky since control character is not guaranteed to be the first message sent if there are events (like event-down-ctr) being published to XSUB. Scenarios 1) Control character is sent and is first message when starting capture service `eventd#eventd#eventd: :- heartbeat_ctrl: Set heartbeat_ctrl pause=1` `eventd#eventd#eventd: :- do_capture: Received subscription message when XSUB connects to XPUB` 2) Events like event-down ctr is sent before control character `eventd#eventd#eventd: :- run: Dropping Message: 22 serialization::archive 18 17 sonic-events-host` `eventd#eventd#eventd: :- run: Dropping Message: 22 serialization::archive 18 0 0 4 0 0 0 1 d 103 {"sonic-events-host:event-stopped-ctr":{"ctr_name":"EVENTD","timestamp":"2024-08-27T00:02:51.407518Z"}} 1 r 36 3357542f-bae1-458f-a804-660e620d21f5 1 s 1 9 1 t 19 1724716971407591080` `heartbeat_ctrl: Set heartbeat_ctrl pause=1` `do_capture: Received subscription message when XSUB connects to XPUB` 3) Control character is not sent at all `eventd#eventd#eventd: :- heartbeat_ctrl: Set heartbeat_ctrl pause=1` 4) Control character is delayed and not caught when starting capture service, but is then caught after causing deserialize error. `do_capture: Receiving event from source: 22 serialization::archive 18 17 sonic-events-host, will read second part of event` `deserialize: deserialize Failed: input stream errorstr[0:64]:(#1) data type: std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&` `zmq_read_part: Failed to deserialize part rc=-2` `zmq_read_part: last:errno=11` `zmq_message_read: Failure to read part1 rc=-2` `zmq_message_read: last:errno=11` We can cover these scenarios by just dropping the control character inside zmq_message_read as part of events_common in swsscommon (different PR). In this PR we will remove such handling logic and make sure that empty events that will be sent by control character are ignored. ##### Work item tracking - Microsoft ADO **(number only)**:28728116 #### How I did it Remove logic for handling control character #### How to verify it UT and sonic-mgmt test cases.

#### Why I did it Dropping control character (message sent when XSUB connects to XPUB as part of ZMQ Proxy setup to notify that subscription has been made) in do capture has been flaky since control character is not guaranteed to be the first message sent if there are events (like event-down-ctr) being published to XSUB. Scenarios 1) Control character is sent and is first message when starting capture service `eventd#eventd#eventd: :- heartbeat_ctrl: Set heartbeat_ctrl pause=1` `eventd#eventd#eventd: :- do_capture: Received subscription message when XSUB connects to XPUB` 2) Events like event-down ctr is sent before control character `eventd#eventd#eventd: :- run: Dropping Message: 22 serialization::archive 18 17 sonic-events-host` `eventd#eventd#eventd: :- run: Dropping Message: 22 serialization::archive 18 0 0 4 0 0 0 1 d 103 {"sonic-events-host:event-stopped-ctr":{"ctr_name":"EVENTD","timestamp":"2024-08-27T00:02:51.407518Z"}} 1 r 36 3357542f-bae1-458f-a804-660e620d21f5 1 s 1 9 1 t 19 1724716971407591080` `heartbeat_ctrl: Set heartbeat_ctrl pause=1` `do_capture: Received subscription message when XSUB connects to XPUB` 3) Control character is not sent at all `eventd#eventd#eventd: :- heartbeat_ctrl: Set heartbeat_ctrl pause=1` 4) Control character is delayed and not caught when starting capture service, but is then caught after causing deserialize error. `do_capture: Receiving event from source: 22 serialization::archive 18 17 sonic-events-host, will read second part of event` `deserialize: deserialize Failed: input stream errorstr[0:64]:(sonic-net#1) data type: std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&` `zmq_read_part: Failed to deserialize part rc=-2` `zmq_read_part: last:errno=11` `zmq_message_read: Failure to read part1 rc=-2` `zmq_message_read: last:errno=11` We can cover these scenarios by just dropping the control character inside zmq_message_read as part of events_common in swsscommon (different PR). In this PR we will remove such handling logic and make sure that empty events that will be sent by control character are ignored. ##### Work item tracking - Microsoft ADO **(number only)**:28728116 #### How I did it Remove logic for handling control character #### How to verify it UT and sonic-mgmt test cases.

Why I did it Fixes #21140 In #20024 and sonic-net/sonic-swss-common#906, we made the change that when a control character is read, zmq_message_read will return with rc 0, which will create an empty internal event. As part of eventd design, empty structured events are dropped, which leads to control characters being a no-op which is the expected behavior. In UT, we are still always expecting a control character to be the first message to be read by zmq which is not the case as described in #20024. We are also not ignoring empty events that are read which is being done by eventd. With this change, control characters are properly ignored if it does after the first test event. How I did it Ignore empty structured events and not expect first zmq_message_read to be control character. How to verify it Manual test/pipeline

Why I did it Fixes sonic-net#21140 In sonic-net#20024 and sonic-net/sonic-swss-common#906, we made the change that when a control character is read, zmq_message_read will return with rc 0, which will create an empty internal event. As part of eventd design, empty structured events are dropped, which leads to control characters being a no-op which is the expected behavior. In UT, we are still always expecting a control character to be the first message to be read by zmq which is not the case as described in sonic-net#20024. We are also not ignoring empty events that are read which is being done by eventd. With this change, control characters are properly ignored if it does after the first test event. How I did it Ignore empty structured events and not expect first zmq_message_read to be control character. How to verify it Manual test/pipeline

Why I did it Fixes #21140 In #20024 and sonic-net/sonic-swss-common#906, we made the change that when a control character is read, zmq_message_read will return with rc 0, which will create an empty internal event. As part of eventd design, empty structured events are dropped, which leads to control characters being a no-op which is the expected behavior. In UT, we are still always expecting a control character to be the first message to be read by zmq which is not the case as described in #20024. We are also not ignoring empty events that are read which is being done by eventd. With this change, control characters are properly ignored if it does after the first test event. How I did it Ignore empty structured events and not expect first zmq_message_read to be control character. How to verify it Manual test/pipeline

Initial commit

dc2e7bc

zbud-msft added 2 commits August 27, 2024 00:53

Remove failure from initial do_capture read

3d5f62d

Drop messages until proxy is setup

967caa8

zbud-msft force-pushed the capture_service_logic_fix branch from fe2cf8d to 967caa8 Compare August 27, 2024 00:54

zbud-msft marked this pull request as ready for review August 27, 2024 00:54

zbud-msft requested a review from lguohan as a code owner August 27, 2024 00:54

zbud-msft added Request for 202311 Branch Request for 202405 Branch labels Aug 27, 2024

qiluo-msft requested a review from liuh-80 August 27, 2024 01:29

liuh-80 reviewed Aug 27, 2024

View reviewed changes

Remove control character tracking from do_capture

afa2e6b

liuh-80 approved these changes Aug 29, 2024

View reviewed changes

qiluo-msft approved these changes Aug 29, 2024

View reviewed changes

qiluo-msft merged commit a5a2cf1 into sonic-net:master Aug 29, 2024
23 checks passed

qiluo-msft added the Request for 202305 Branch label Aug 29, 2024

yxieca added Approved for 202311 Branch Approved for 202405 Branch labels Sep 4, 2024

mssonicbld mentioned this pull request Sep 4, 2024

[action] [PR:20024] Fix flaky capture service start (#20024) #20130

Merged

mssonicbld added the Created PR to 202311 Branch label Sep 4, 2024

mssonicbld mentioned this pull request Sep 4, 2024

[action] [PR:20024] Fix flaky capture service start (#20024) #20131

Merged

mssonicbld added the Created PR to 202405 Branch label Sep 4, 2024

mssonicbld added Included in 202311 Branch and removed Created PR to 202311 Branch labels Sep 4, 2024

mssonicbld added Included in 202405 Branch and removed Created PR to 202405 Branch labels Sep 4, 2024

arista-hpandya mentioned this pull request Sep 23, 2024

ERR eventd#eventd: :- deserialize: deserialize Failed: input stream error #20246

Closed

sonic-otn mentioned this pull request Oct 14, 2024

The eventd.proxy test occasionally fails #20494

Open

zbud-msft mentioned this pull request Dec 17, 2024

[eventd] Ignore control character event if it comes in UT #21200

Merged

11 tasks

mssonicbld mentioned this pull request Dec 24, 2024

[action] [PR:21200] Ignore control character event if it comes (#21200) #21275

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix flaky capture service start #20024

Fix flaky capture service start #20024

zbud-msft commented Aug 27, 2024 •

edited

Loading

linux-foundation-easycla bot commented Aug 27, 2024 •

edited

Loading

liuh-80 Aug 27, 2024

zbud-msft Aug 27, 2024

liuh-80 Aug 28, 2024

liuh-80 Aug 27, 2024

zbud-msft Aug 27, 2024

liuh-80 Aug 27, 2024

zbud-msft commented Aug 27, 2024

zbud-msft commented Aug 30, 2024

mssonicbld commented Sep 4, 2024

mssonicbld commented Sep 4, 2024



		if(rc == 1) { // Expected case to receive subscription message as very first message
		SWSS_LOG_INFO("Received subscription message when XSUB connects to XPUB");

Fix flaky capture service start #20024

Fix flaky capture service start #20024

Conversation

zbud-msft commented Aug 27, 2024 • edited Loading

Why I did it

Work item tracking

How I did it

How to verify it

Which release branch to backport (provide reason below if selected)

Tested branch (Please provide the tested image version)

Description for the changelog

Link to config_db schema for YANG module changes

A picture of a cute animal (not mandatory but encouraged)

linux-foundation-easycla bot commented Aug 27, 2024 • edited Loading

liuh-80 Aug 27, 2024

Choose a reason for hiding this comment

zbud-msft Aug 27, 2024

Choose a reason for hiding this comment

liuh-80 Aug 28, 2024

Choose a reason for hiding this comment

liuh-80 Aug 27, 2024

Choose a reason for hiding this comment

zbud-msft Aug 27, 2024

Choose a reason for hiding this comment

liuh-80 Aug 27, 2024

Choose a reason for hiding this comment

zbud-msft commented Aug 27, 2024

zbud-msft commented Aug 30, 2024

mssonicbld commented Sep 4, 2024

mssonicbld commented Sep 4, 2024

zbud-msft commented Aug 27, 2024 •

edited

Loading

linux-foundation-easycla bot commented Aug 27, 2024 •

edited

Loading