Event listener fails to receive redfish event immediately

[hardikspanchal]

Redfish event listener is being ran on local machine. A listener is receiving each event after 30s. System(server) log was analyzed, observed that system was failed to receive a response and enter into retrial mode. Identified an issue about connection. After each response from listener to system(server), connection must be closed and a signal for closing a connection should come form listener. I checked in POST method section, https://github.com/DMTF/Redfish-Event-Listener/blob/master/RedfishEventListener_v1.py#L122-L123, Status code is sent as response only. Response need to has "Connection: close" message as general-header with status code. I applied the change to this file in my local machine and tested, a connection was closed successfully after response complete.

Applied changed in RedfishEventListener_v1.py:

diff --git a/RedfishEventListener_v1.py b/RedfishEventListener_v1.py
index 40662bc..43c4cdd 100644
--- a/RedfishEventListener_v1.py
+++ b/RedfishEventListener_v1.py
@@ -119,8 +119,10 @@ def process_data(newsocketconn, fromaddr):
                 if config['contextdetail'] is not None and outdata.get('Context', None) != config['contextdetail']:
                     my_logger.info("Context ({}) does not match with the server ({})."
                           .format(outdata.get('Context', None), config['contextdetail']))
-                StatusCode = """HTTP/1.1 200 OK\r\n\r\n"""
-                connstreamout.send(bytes(StatusCode, 'UTF-8'))
+                res = "HTTP/1.1 200 OK\r\n" \
+                      "Connection: close\r\n" \
+                      "\r\n"
+                connstreamout.send(res.encode())

System log after fix:

Apr 05 05:11:47 obmc bmcweb[396]: (2022-04-05 05:11:47) [DEBUG "http_client.hpp":165] SSL Handshake successfull
Apr 05 05:11:47 obmc bmcweb[396]: (2022-04-05 05:11:47) [DEBUG "http_client.hpp":189] sendMessage() bytes transferred: 618
Apr 05 05:11:47 obmc bmcweb[396]: (2022-04-05 05:11:47) [DEBUG "http_client.hpp":224] recvMessage() bytes transferred: 38
Apr 05 05:11:47 obmc bmcweb[396]: (2022-04-05 05:11:47) [DEBUG "http_client.hpp":240] recvMessage() Header Response Code: 200
**Apr 05 05:11:47 obmc bmcweb[396]: (2022-04-05 05:11:47) [DEBUG "http_client.hpp":263] recvMessage() keepalive : 0**
**Apr 05 05:11:47 obmc bmcweb[396]: (2022-04-05 05:11:47) [INFO "http_client.hpp":323] doClose(): Connection closed by server.**
**Apr 05 05:11:47 obmc bmcweb[396]: (2022-04-05 05:11:47) [DEBUG "http_client.hpp":459] requestDataQueue is empty**

System log Before fix

Mar 30 01:05:23 obmc bmcweb[402]: Event subscription added(Id: 1696563194)
Mar 30 01:05:23 obmc bmcweb[402]: (2022-03-30 01:05:23) [DEBUG "http_response.hpp":128] completion handler was valid
Mar 30 01:05:23 obmc bmcweb[402]: (2022-03-30 01:05:23) [INFO "http_connection.hpp":444] Response: 0xdf7128 /redfish/v1/EventService/Subscriptions 201 keepalive=1
Mar 30 01:05:23 obmc bmcweb[402]: (2022-03-30 01:05:23) [DEBUG "http_connection.hpp":641] 0xdf7128 doWrite
Mar 30 01:05:23 obmc bmcweb[402]: (2022-03-30 01:05:23) [DEBUG "http_connection.hpp":650] 0xdf7128 async_write 900 bytes
Mar 30 01:05:23 obmc bmcweb[402]: (2022-03-30 01:05:23) [DEBUG "http_connection.hpp":668] 0xdf7128 Clearing response
Mar 30 01:05:23 obmc bmcweb[402]: (2022-03-30 01:05:23) [DEBUG "http_response.hpp":106] 0xdf9400 Clearing response containers
Mar 30 01:05:23 obmc bmcweb[402]: (2022-03-30 01:05:23) [DEBUG "http_connection.hpp":536] 0xdf7128 doReadHeaders
Mar 30 01:05:23 obmc bmcweb[402]: (2022-03-30 01:05:23) [ERROR "event_service_manager.hpp":862] Map size Before Delete : 1
Mar 30 01:05:23 obmc bmcweb[402]: (2022-03-30 01:05:23) [ERROR "event_service_manager.hpp":917] Map size After Delete : 1
Mar 30 01:05:23 obmc bmcweb[402]: (2022-03-30 01:05:23) [DEBUG "http_client.hpp":96] Trying to resolve: <LISTENER-IP>:5008
Mar 30 01:05:23 obmc bmcweb[402]: (2022-03-30 01:05:23) [DEBUG "async_resolve.hpp":27] Trying to resolve: <LISTENER-IP>:5008
Mar 30 01:05:23 obmc bmcweb[402]: (2022-03-30 01:05:23) [DEBUG "async_resolve.hpp":42] ResolveHostname returned: <LISTENER-IP>:786945
Mar 30 01:05:23 obmc bmcweb[402]: (2022-03-30 01:05:23) [DEBUG "async_resolve.hpp":51] ipv4 address
Mar 30 01:05:23 obmc bmcweb[402]: (2022-03-30 01:05:23) [DEBUG "async_resolve.hpp":86] resolved endpoint is : <LISTENER-IP>:5008
Mar 30 01:05:23 obmc bmcweb[402]: (2022-03-30 01:05:23) [DEBUG "http_client.hpp":110] Resolved
Mar 30 01:05:23 obmc bmcweb[402]: (2022-03-30 01:05:23) [DEBUG "http_client.hpp":122] Trying to connect to: <LISTENER-IP>:5008
Mar 30 01:05:23 obmc bmcweb[402]: (2022-03-30 01:05:23) [DEBUG "http_client.hpp":135] Connected to: <LISTENER-IP>:5008
Mar 30 01:05:24 obmc bmcweb[402]: (2022-03-30 01:05:24) [DEBUG "http_client.hpp":165] SSL Handshake successfull
Mar 30 01:05:24 obmc bmcweb[402]: (2022-03-30 01:05:24) [DEBUG "http_client.hpp":189] sendMessage() bytes transferred: 636
Mar 30 01:05:24 obmc bmcweb[402]: (2022-03-30 01:05:24) [DEBUG "http_client.hpp":224] recvMessage() bytes transferred: 19
Mar 30 01:05:24 obmc bmcweb[402]: (2022-03-30 01:05:24) [DEBUG "http_client.hpp":240] recvMessage() Header Response Code: 200
**Mar 30 01:05:24 obmc bmcweb[402]: (2022-03-30 01:05:24) [DEBUG "http_client.hpp":263] recvMessage() keepalive : 1**
**Mar 30 01:05:24 obmc bmcweb[402]: (2022-03-30 01:05:24) [DEBUG "http_client.hpp":490] requestDataQueue is empty**
Mar 30 01:05:59 obmc bmcweb[402]: (2022-03-30 01:05:59) [ERROR "event_service_manager.hpp":862] Map size Before Delete : 1
Mar 30 01:05:59 obmc bmcweb[402]: (2022-03-30 01:05:59) [ERROR "event_service_manager.hpp":917] Map size After Delete : 1
**Mar 30 01:05:59 obmc bmcweb[402]: (2022-03-30 01:05:59) [DEBUG "http_client.hpp":189] sendMessage() bytes transferred: 618**
**Mar 30 01:05:59 obmc bmcweb[402]: (2022-03-30 01:05:59) [DEBUG "http_client.hpp":224] recvMessage() bytes transferred: 0**
**Mar 30 01:05:59 obmc bmcweb[402]: (2022-03-30 01:05:59) [ERROR "http_client.hpp":232] recvMessage() parser failed to receive response**
**Mar 30 01:05:59 obmc bmcweb[402]: (2022-03-30 01:05:59) [DEBUG "http_client.hpp":408] Attempt retry after 30 seconds. RetryCount = 1**
**Mar 30 01:06:29 obmc bmcweb[402]: (2022-03-30 01:06:29) [ERROR "http_client.hpp":322] doClose() failed: Broken pipe**
Mar 30 01:06:29 obmc bmcweb[402]: (2022-03-30 01:06:29) [DEBUG "http_client.hpp":96] Trying to resolve: <LISTENER-IP>:5008
Mar 30 01:06:29 obmc bmcweb[402]: (2022-03-30 01:06:29) [DEBUG "async_resolve.hpp":27] Trying to resolve: <LISTENER-IP>:5008
Mar 30 01:06:29 obmc bmcweb[402]: (2022-03-30 01:06:29) [DEBUG "async_resolve.hpp":42] ResolveHostname returned: <LISTENER-IP>:786945
Mar 30 01:06:29 obmc bmcweb[402]: (2022-03-30 01:06:29) [DEBUG "async_resolve.hpp":51] ipv4 address
Mar 30 01:06:29 obmc bmcweb[402]: (2022-03-30 01:06:29) [DEBUG "async_resolve.hpp":86] resolved endpoint is : <LISTENER-IP>:5008
Mar 30 01:06:29 obmc bmcweb[402]: (2022-03-30 01:06:29) [DEBUG "http_client.hpp":110] Resolved
Mar 30 01:06:29 obmc bmcweb[402]: (2022-03-30 01:06:29) [DEBUG "http_client.hpp":122] Trying to connect to: <LISTENER-IP>:5008
Mar 30 01:06:29 obmc bmcweb[402]: (2022-03-30 01:06:29) [DEBUG "http_client.hpp":135] Connected to: <LISTENER-IP>:5008
Mar 30 01:06:30 obmc bmcweb[402]: (2022-03-30 01:06:30) [DEBUG "http_client.hpp":165] SSL Handshake successfull
Mar 30 01:06:30 obmc bmcweb[402]: (2022-03-30 01:06:30) [DEBUG "http_client.hpp":189] sendMessage() bytes transferred: 618
Mar 30 01:06:30 obmc bmcweb[402]: (2022-03-30 01:06:30) [DEBUG "http_client.hpp":224] recvMessage() bytes transferred: 19
Mar 30 01:06:30 obmc bmcweb[402]: (2022-03-30 01:06:30) [DEBUG "http_client.hpp":240] recvMessage() Header Response Code: 200
**Mar 30 01:06:30 obmc bmcweb[402]: (2022-03-30 01:06:30) [DEBUG "http_client.hpp":263] recvMessage() keepalive : 1**
**Mar 30 01:06:30 obmc bmcweb[402]: (2022-03-30 01:06:30) [DEBUG "http_client.hpp":490] requestDataQueue is empty**

Here, I need to push these changes on github, but I do not have a permission for this repo. Can I please get a permission to push a change for this repo? Or Can it be please applied by authorized contributors on this repo?

[mraineri]

I would recommend making a fork and then a pull request from your fork back to the project; this is how other communities manage contributions. We also have this outlined in CONTRIBUTING.md.

[hardikspanchal]

Thanks @mraineri I forked a repo and raised a Pull request.

[hardikspanchal]

My PR on fork repo:https://github.com/hardikspanchal/Redfish-Event-Listener/pull/1

[mraineri]

You should be able to make it a pull request coming back into this repository; I see you opened one yesterday, but then closed it. What you have open right now is a pull request back into your own forked repository.

I reopened the pull request (#19) so it can be merged back here.

[hardikspanchal]

Hi @mraineri, So a PR on fork repo does not need to be merged in my forked repo. Fork repo was needed to be created to allow myself to raise a PR only. Correct me if I am wrong please. I added my teammate as reviewer on fork repo PR. In #19 I am unable to add any reviewer. Can you please suggest how can I add reviewers and who could be they? Can I get approval on fork PR and mention that link on #19 before merging?

[hardikspanchal]

Hi @mraineri , I got an approval from my teammate on PR #19. Please help to enable merge pull request option.

[mraineri]

You're correct; you don't need to perform a PR back into your forked repository; you can make a PR directly from your fork back to here. The open source communities I've worked in tend to not let non-admins add reviewers directly using the "add reviewer" function, but anyone can add their own review without this. I would recommend tagging people you want to notify in the description of the pull request.

The changes you made look good to me, and we'll review this as a group during our weekly call for formal approval; it'll likely be merged this afternoon.

[hardikspanchal]

Thanks @mraineri