Zone alarms vs monitor alarms via websocket JSON output

[hahobson]

The websocket output randomly or with great delay sends a message. I cannot ascertain which at the moment.

[kitkat]

Maybe the is ES firing off some sort of detection script or servicing a hook before it sends out the notification?

[hahobson]

Do I need a hook? Do I want a hook? I wonder what I can turn off that could simplify and speed things up. All I want is that JSON output that tells me which monitor has an alarm. There are no zone alarms, but a monitor alarm may be enough for what I am doing. Thanks Kitkat!

[hahobson]

If I run the Python script for say 5 to 10 minutes, then dangle my fingers in front of the camera to cause an alarm, a couple of seconds later I get that output that makes me salivate.

[kitkat]

Do I need a hook? Do I want a hook?

I don't know - Do you? :unsure:

I suspect you probably don't though, or at least at the moment anyway but maybe the time will come when you'll write something that pulls the information you want from the database and sends it as part of the notification?

There are probably settings somewhere for that sort of what to run and when to run it stuff.

If I run the Python script for say 5 to 10 minutes, then dangle my fingers in front of the camera to cause an alarm, a couple of seconds later I get that output that makes me salivate.

So no significant delay? It sounds like you've pretty much cracked the communication part and it's all about the notification content now

[hahobson]

I will write a listener today that will poll the websocket every second to see what happens.

I will look at the .ini file and turnoff the hooks.

The current script seems to only work after 10 minutes. The delay of the alarm is 3 seconds or so.

[hahobson]

Code: Select all

import json
from websocket import create_connection
from time import sleep
ws = create_connection("ws://127.0.0.1:9000")
ws.send(json.dumps({"event":"auth","data":{"user":"admin","password":"admin"}}))
result =  ws.recv()
print (result)
while True:
   ws.send(json.dumps({"event":"control","data":{"type":"filter","monlist":"4", "intlist":"0"}}))
   result =  ws.recv()
   print (result)
   sleep(1.05)
ws.close()

There is no rhyme or reason as to why or when the websocket will report an alarm. It appears to be completely random. I noticed that the web GUI reports an alarm, but does on increment the Event ID.

[hahobson]

The Event ID is not incrementing often. Like it takes minutes.

[hahobson]

Code: Select all

{"events":[{"Cause":"End:Motion: lowerleft, upperRight","EventId":"4707","MonitorId":"4","DetectionJson":[],"RulesObject":{},"Name":"1"}],"type":"","status":"Success","event":"alarm"}

lowerleft and upperRight are actual zones. That's really good news, as it satisfies my requirement fully

[kitkat]

Excellent news about the Zones

Have you tried putting the control:filter command outside of the loop? I reckon you probably only need to send it once.

And curious about the ws.recv() thing... Have you tried putting another print() in the loop, just to output "I'm alive" messages or something? That'd show whether recv() is waiting for something ('hanging') or not. (I expect it to wait, and that you therefore won't need the sleep() command.)

And I was browsing about earlier (as you do) and it looks like the .ini file distributed with the ES contains use_hooks = yes, which might be worth investigating.

[hahobson]

Thanks Kitkat, Zones seem to pop up randomly.

There is this on the .ini file:
# Interval, in seconds, to reload known monitors (default: 300).
monitor_reload_interval = 300

That is 5 minutes. Wonder if that effects reporting over the websocket and the event ID.

event_check_interval = 5 ,, That would be nice if that was reflected in the websocket reporting.

Moved the ws.recv() outside the loop. No positive change.

Got rid of the sleep()

The loop is waiting for result = ws.recv()

[asker]

That is 5 minutes. Wonder if that effects reporting over the websocket and the event ID.

No, it does not.

event_check_interval = 5 ,, That would be nice if that was reflected in the websocket reporting.

What are you referring to when you say if it was reflected? The ES will poll ZM every 5 seconds (if the setting is 5) for new events. If you are curious how things work, please read the docs, specifically the key principles

Moved the ws.recv() outside the loop. No positive change.

Zones seem to pop up randomly.

Zones are reported only if ZM makes them available in the notes.

I'd recommend instead of guessing, just enable DEBUG logs and watch the output as events get created. You'll see where time is spent, what steps are taken. Take a look at my signature for links.

[hahobson]

Thanks Asker,

"Cause":"End:Motion: lowerleft, upperRight is every helpful in my and other's applications. Still seeing if I can get the alarm ID to increment a bit faster.

[hahobson]

Below, it references 192.168.0.103. Not sure why it does that. The machine's address is 192.168.0.100.

Code: Select all

harry@harry-4300-SFF-PC:~$ sudo -u www-data /var/lib/zmeventnotification/bin/zm_detect.py --config /etc/zm/objectconfig.ini  --eventid 5290 --monitorid 4 --debug
12/07/21 10:06:37 zmesdetect_m4[5707] INF ZMLog.py:292 [Setting up signal handler for logs]

12/07/21 10:06:37 zmesdetect_m4[5707] INF ZMLog.py:301 [Switching global logger to ZMLog]

12/07/21 10:06:38 zmesdetect_m4[5707] INF zm_detect.py:284 [---------| app:6.1.27, pyzm:0.3.55, ES:6.1.27
 , OpenCV:4.5.4-dev|------------]

12/07/21 10:06:38 zmesdetect_m4[5707] INF utils.py:405 [Reading config from: /etc/zm/objectconfig.ini]

12/07/21 10:06:38 zmesdetect_m4[5707] INF utils.py:410 [Reading secrets from: /etc/zm/secrets.ini]

12/07/21 10:06:38 zmesdetect_m4[5707] DBG2 utils.py:382 [Secret token found in config: !ZM_PORTAL]

12/07/21 10:06:38 zmesdetect_m4[5707] DBG2 utils.py:382 [Secret token found in config: !ZM_USER]

12/07/21 10:06:38 zmesdetect_m4[5707] DBG2 utils.py:382 [Secret token found in config: !ZM_PASSWORD]

12/07/21 10:06:38 zmesdetect_m4[5707] DBG2 utils.py:382 [Secret token found in config: !ZM_API_PORTAL]

12/07/21 10:06:38 zmesdetect_m4[5707] DBG2 utils.py:382 [Secret token found in config: !ML_USER]

12/07/21 10:06:38 zmesdetect_m4[5707] DBG2 utils.py:382 [Secret token found in config: !ML_PASSWORD]

12/07/21 10:06:38 zmesdetect_m4[5707] DBG2 utils.py:382 [Secret token found in config: !PLATEREC_ALPR_KEY]

12/07/21 10:06:38 zmesdetect_m4[5707] DBG1 utils.py:445 [allowing self-signed certs to work...]

12/07/21 10:06:38 zmesdetect_m4[5707] DBG2 utils.py:455 [Now checking for monitor overrides]

12/07/21 10:06:38 zmesdetect_m4[5707] DBG3 utils.py:522 [Finally, doing parameter substitution]

12/07/21 10:06:38 zmesdetect_m4[5707] INF zm_detect.py:309 [Importing local classes for Object/Face]

12/07/21 10:06:38 zmesdetect_m4[5707] INF zm_detect.py:334 [Connecting with ZM APIs]

12/07/21 10:06:38 zmesdetect_m4[5707] DBG2 api.py:72 [API SSL certificate check has been disbled]

12/07/21 10:06:38 zmesdetect_m4[5707] DBG1 api.py:181 [using username/password for login]

12/07/21 10:06:39 zmesdetect_m4[5707] FAT zm_detect.py:561 [Unrecoverable error:HTTPSConnectionPool(host='192.168.0.103', port=443): Max retries exceeded with url: /zm/api/host/login.json (Caused by NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x7fae3e215c40>: Failed to establish a new connection: [Errno 111] Connection refused')) Traceback:Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/urllib3/connection.py", line 159, in _new_conn
    conn = connection.create_connection(
  File "/usr/lib/python3/dist-packages/urllib3/util/connection.py", line 84, in create_connection
    raise err
  File "/usr/lib/python3/dist-packages/urllib3/util/connection.py", line 74, in create_connection
    sock.connect(sa)
ConnectionRefusedError: [Errno 111] Connection refused

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/urllib3/connectionpool.py", line 665, in urlopen
    httplib_response = self._make_request(
  File "/usr/lib/python3/dist-packages/urllib3/connectionpool.py", line 376, in _make_request
    self._validate_conn(conn)
  File "/usr/lib/python3/dist-packages/urllib3/connectionpool.py", line 996, in _validate_conn
    conn.connect()
  File "/usr/lib/python3/dist-packages/urllib3/connection.py", line 314, in connect
    conn = self._new_conn()
  File "/usr/lib/python3/dist-packages/urllib3/connection.py", line 171, in _new_conn
    raise NewConnectionError(
urllib3.exceptions.NewConnectionError: <urllib3.connection.VerifiedHTTPSConnection object at 0x7fae3e215c40>: Failed to establish a new connection: [Errno 111] Connection refused

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/requests/adapters.py", line 439, in send
    resp = conn.urlopen(
  File "/usr/lib/python3/dist-packages/urllib3/connectionpool.py", line 719, in urlopen
    retries = retries.increment(
  File "/usr/lib/python3/dist-packages/urllib3/util/retry.py", line 436, in increment
    raise MaxRetryError(_pool, url, error or ResponseError(cause))
urllib3.exceptions.MaxRetryError: HTTPSConnectionPool(host='192.168.0.103', port=443): Max retries exceeded with url: /zm/api/host/login.json (Caused by NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x7fae3e215c40>: Failed to establish a new connection: [Errno 111] Connection refused'))

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/var/lib/zmeventnotification/bin/zm_detect.py", line 556, in <module>
    main_handler()
  File "/var/lib/zmeventnotification/bin/zm_detect.py", line 335, in main_handler
    zmapi = zmapi.ZMApi(options=api_options)
  File "/usr/local/lib/python3.8/dist-packages/pyzm/api.py", line 80, in __init__
    self._login()
  File "/usr/local/lib/python3.8/dist-packages/pyzm/api.py", line 193, in _login
    r = self.session.post(url, data=data)
  File "/usr/lib/python3/dist-packages/requests/sessions.py", line 581, in post
    return self.request('POST', url, data=data, json=json, **kwargs)
  File "/usr/lib/python3/dist-packages/requests/sessions.py", line 533, in request
    resp = self.send(prep, **send_kwargs)
  File "/usr/lib/python3/dist-packages/requests/sessions.py", line 646, in send
    r = adapter.send(request, **kwargs)
  File "/usr/lib/python3/dist-packages/requests/adapters.py", line 516, in send
    raise ConnectionError(e, request=request)
requests.exceptions.ConnectionError: HTTPSConnectionPool(host='192.168.0.103', port=443): Max retries exceeded with url: /zm/api/host/login.json (Caused by NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x7fae3e215c40>: Failed to establish a new connection: [Errno 111] Connection refused'))
]

I changed the presets to fast and sensitive. That has helped.
Here are the debugging logs from sudo tail -F /var/log/zm/zmesdetect*.log /var/log/zm/zmeventnotification.log

Code: Select all

12/07/2021 10:56:48.217459 zmeventnotification[4810].DBG [main:1038] [PARENT: checkEvents() new events found=1]
12/07/2021 10:56:48.217581 zmeventnotification[4810].DBG [main:1038] [PARENT: There are 1 new Events to process]
12/07/2021 10:56:48.221885 zmeventnotification[4810].DBG [main:1038] [PARENT: ---------->Tick END (active forks:1, total forks:22, active hooks: 0)<--------------]
12/07/2021 10:56:48.222097 zmeventnotification[6375].DBG [ZoneMinder::Logger:293] [LogOpts: level=DBG/DBG, screen=INF, database=INF, logfile=DBG->/var/log/zm/zmeventnotification.log, syslog=INF]
12/07/2021 10:56:48.222307 zmeventnotification[6375].DBG [main:1038] [PARENT: Forked process:6375 to handle alarm eid:5299]
12/07/2021 10:56:48.222933 zmeventnotification[6375].INF [main:1050] [|----> FORK:1 (4), eid:5299 use hooks/start hook not being used, going to directly send out a notification if checks pass]
12/07/2021 10:56:50.418939 zmeventnotification[6375].DBG [main:1038] [|----> FORK:1 (4), eid:5299 rules: Checking rules for alarm caused by eid:5299, monitor:4, at: Tue Dec  7 10:56:50 2021 with cause:Motion lowerleft,]
12/07/2021 10:56:50.419103 zmeventnotification[6375].DBG [main:1038] [|----> FORK:1 (4), eid:5299 rules: No rules found for Monitor, allowing:4]
12/07/2021 10:56:50.419298 zmeventnotification[6375].DBG [main:1038] [|----> FORK:1 (4), eid:5299 Matching alarm to connection rules...]
12/07/2021 10:56:50.419487 zmeventnotification[6375].DBG [main:1038] [|----> FORK:1 (4), eid:5299 Checking alarm conditions for 127.0.0.1:45698]
12/07/2021 10:56:50.419691 zmeventnotification[6375].DBG [main:1038] [|----> FORK:1 (4), eid:5299 Monitor 4 event: should send out as  912.337120056152 is >= interval of 0]
12/07/2021 10:56:50.419809 zmeventnotification[6375].DBG [main:1038] [|----> FORK:1 (4), eid:5299 token is unique, shouldSendEventToConn returned true, so calling sendEvent]
12/07/2021 10:56:50.420018 zmeventnotification[6375].DBG [main:1038] [|----> FORK:1 (4), eid:5299 isAllowedChannel: got type:event_start resCode:0]
12/07/2021 10:56:50.420320 zmeventnotification[6375].INF [main:1050] [|----> FORK:1 (4), eid:5299 Sending event_start notification for EID:5299over web]
12/07/2021 10:56:50.517310 zmeventnotification[6375].DBG [main:1038] [|----> FORK:1 (4), eid:5299 Child: posting job to send out message to id:1638846364.81792->127.0.0.1:45698]
12/07/2021 10:56:50.517548 zmeventnotification[6375].DBG [main:1038] [|----> FORK:1 (4), eid:5299 child finished writing to parent]
12/07/2021 10:56:53.079055 zmeventnotification[4810].DBG [main:1038] [PARENT: ----------> Tick START (active forks:1, total forks:22, active hooks: 0 running for:111 min)<--------------]
12/07/2021 10:56:53.079309 zmeventnotification[4810].DBG [main:1038] [PARENT: After tick: TOTAL: 1,  ES_CONTROL: 1, FCM+WEB: 0, FCM: 0, WEB: 1, MQTT:0, invalid WEB: 0, PENDING: 0]
12/07/2021 10:56:53.080234 zmeventnotification[4810].DBG [main:1038] [PARENT: RAW TEXT-->message--TYPE--1638846364.81792--SPLIT--{"events":[{"RulesObject":{},"Name":"1","Cause":"Motion lowerleft,","EventId":"5299","DetectionJson":[],"MonitorId":"4"}],"event":"alarm","type":"","status":"Success"}]
12/07/2021 10:56:53.080414 zmeventnotification[4810].DBG [main:1038] [PARENT: GOT JOB==>To: 1638846364.81792, message: {"events":[{"RulesObject":{},"Name":"1","Cause":"Motion lowerleft,","EventId":"5299","DetectionJson":[],"MonitorId":"4"}],"event":"alarm","type":"","status":"Success"}]
12/07/2021 10:56:53.080571 zmeventnotification[4810].DBG [main:1038] [PARENT: Sending child message to 127.0.0.1:45698...]
12/07/2021 10:56:53.081305 zmeventnotification[4810].DBG [main:1038] [PARENT: RAW TEXT-->timestamp--TYPE--1638846364.81792--SPLIT--4--SPLIT--1638849410.41988]
12/07/2021 10:56:53.081540 zmeventnotification[4810].DBG [main:1038] [PARENT: Job: Update last sent timestamp of monitor:4 to 1638849410.41988 for id:1638846364.81792]
12/07/2021 10:56:53.081684 zmeventnotification[4810].DBG [main:1038] [PARENT: There are 1 active child forks & 0 zm_detect processes running...]
12/07/2021 10:56:53.082078 zmeventnotification[4810].DBG [main:1038] [PARENT: We've already worked on Monitor:4, Event:5299, not doing anything more]
12/07/2021 10:56:53.082183 zmeventnotification[4810].DBG [main:1038] [PARENT: checkEvents() new events found=0]
12/07/2021 10:56:53.082304 zmeventnotification[4810].DBG [main:1038] [PARENT: There are 0 new Events to process]
12/07/2021 10:56:53.082425 zmeventnotification[4810].DBG [main:1038] [PARENT: ---------->Tick END (active forks:1, total forks:22, active hooks: 0)<--------------]
12/07/2021 10:56:58.079038 zmeventnotification[4810].DBG [main:1038] [PARENT: ----------> Tick START (active forks:1, total forks:22, active hooks: 0 running for:111 min)<--------------]
12/07/2021 10:56:58.079214 zmeventnotification[4810].DBG [main:1038] [PARENT: After tick: TOTAL: 1,  ES_CONTROL: 1, FCM+WEB: 0, FCM: 0, WEB: 1, MQTT:0, invalid WEB: 0, PENDING: 0]
12/07/2021 10:56:58.079355 zmeventnotification[4810].DBG [main:1038] [PARENT: There are 1 active child forks & 0 zm_detect processes running...]
12/07/2021 10:56:58.079678 zmeventnotification[4810].DBG [main:1038] [PARENT: We've already worked on Monitor:4, Event:5299, not doing anything more]
12/07/2021 10:56:58.079769 zmeventnotification[4810].DBG [main:1038] [PARENT: checkEvents() new events found=0]
12/07/2021 10:56:58.079903 zmeventnotification[4810].DBG [main:1038] [PARENT: There are 0 new Events to process]
12/07/2021 10:56:58.080046 zmeventnotification[4810].DBG [main:1038] [PARENT: ---------->Tick END (active forks:1, total forks:22, active hooks: 0)<--------------]
12/07/2021 10:57:03.079043 zmeventnotification[4810].DBG [main:1038] [PARENT: ----------> Tick START (active forks:1, total forks:22, active hooks: 0 running for:111 min)<--------------]
12/07/2021 10:57:03.079231 zmeventnotification[4810].DBG [main:1038] [PARENT: After tick: TOTAL: 1,  ES_CONTROL: 1, FCM+WEB: 0, FCM: 0, WEB: 1, MQTT:0, invalid WEB: 0, PENDING: 0]
12/07/2021 10:57:03.079394 zmeventnotification[4810].DBG [main:1038] [PARENT: There are 1 active child forks & 0 zm_detect processes running...]
12/07/2021 10:57:03.079774 zmeventnotification[4810].DBG [main:1038] [PARENT: We've already worked on Monitor:4, Event:5299, not doing anything more]
12/07/2021 10:57:03.079885 zmeventnotification[4810].DBG [main:1038] [PARENT: checkEvents() new events found=0]
12/07/2021 10:57:03.080004 zmeventnotification[4810].DBG [main:1038] [PARENT: There are 0 new Events to process]
12/07/2021 10:57:03.080139 zmeventnotification[4810].DBG [main:1038] [PARENT: ---------->Tick END (active forks:1, total forks:22, active hooks: 0)<--------------]
12/07/2021 10:57:08.079993 zmeventnotification[4810].DBG [main:1038] [PARENT: ----------> Tick START (active forks:1, total forks:22, active hooks: 0 running for:111 min)<--------------]
12/07/2021 10:57:08.080149 zmeventnotification[4810].DBG [main:1038] [PARENT: After tick: TOTAL: 1,  ES_CONTROL: 1, FCM+WEB: 0, FCM: 0, WEB: 1, MQTT:0, invalid WEB: 0, PENDING: 0]
12/07/2021 10:57:08.080281 zmeventnotification[4810].DBG [main:1038] [PARENT: There are 1 active child forks & 0 zm_detect processes running...]
12/07/2021 10:57:08.080633 zmeventnotification[4810].DBG [main:1038] [PARENT: We've already worked on Monitor:4, Event:5299, not doing anything more]
12/07/2021 10:57:08.080744 zmeventnotification[4810].DBG [main:1038] [PARENT: checkEvents() new events found=0]
12/07/2021 10:57:08.080889 zmeventnotification[4810].DBG [main:1038] [PARENT: There are 0 new Events to process]
12/07/2021 10:57:08.081021 zmeventnotification[4810].DBG [main:1038] [PARENT: ---------->Tick END (active forks:1, total forks:22, active hooks: 0)<--------------]
12/07/2021 10:57:13.079043 zmeventnotification[4810].DBG [main:1038] [PARENT: ----------> Tick START (active forks:1, total forks:22, active hooks: 0 running for:111 min)<--------------]
12/07/2021 10:57:13.079189 zmeventnotification[4810].DBG [main:1038] [PARENT: After tick: TOTAL: 1,  ES_CONTROL: 1, FCM+WEB: 0, FCM: 0, WEB: 1, MQTT:0, invalid WEB: 0, PENDING: 0]
12/07/2021 10:57:13.079320 zmeventnotification[4810].DBG [main:1038] [PARENT: There are 1 active child forks & 0 zm_detect processes running...]
12/07/2021 10:57:13.079630 zmeventnotification[4810].DBG [main:1038] [PARENT: We've already worked on Monitor:4, Event:5299, not doing anything more]
12/07/2021 10:57:13.079738 zmeventnotification[4810].DBG [main:1038] [PARENT: checkEvents() new events found=0]
12/07/2021 10:57:13.079850 zmeventnotification[4810].DBG [main:1038] [PARENT: There are 0 new Events to process]
12/07/2021 10:57:13.079988 zmeventnotification[4810].DBG [main:1038] [PARENT: ---------->Tick END (active forks:1, total forks:22, active hooks: 0)<--------------]
12/07/2021 10:57:18.079827 zmeventnotification[4810].DBG [main:1038] [PARENT: ----------> Tick START (active forks:1, total forks:22, active hooks: 0 running for:111 min)<--------------]
12/07/2021 10:57:18.080006 zmeventnotification[4810].DBG [main:1038] [PARENT: After tick: TOTAL: 1,  ES_CONTROL: 1, FCM+WEB: 0, FCM: 0, WEB: 1, MQTT:0, invalid WEB: 0, PENDING: 0]
12/07/2021 10:57:18.080140 zmeventnotification[4810].DBG [main:1038] [PARENT: There are 1 active child forks & 0 zm_detect processes running...]
12/07/2021 10:57:18.080420 zmeventnotification[4810].DBG [main:1038] [PARENT: We've already worked on Monitor:4, Event:5299, not doing anything more]
12/07/2021 10:57:18.080531 zmeventnotification[4810].DBG [main:1038] [PARENT: checkEvents() new events found=0]
12/07/2021 10:57:18.080648 zmeventnotification[4810].DBG [main:1038] [PARENT: There are 0 new Events to process]
12/07/2021 10:57:18.080802 zmeventnotification[4810].DBG [main:1038] [PARENT: ---------->Tick END (active forks:1, total forks:22, active hooks: 0)<--------------]
12/07/2021 10:57:20.521271 zmeventnotification[6375].DBG [main:1038] [|----> FORK:1 (4), eid:5299 For 4 (1), SHM says: state=0, eid=5299]
12/07/2021 10:57:20.521602 zmeventnotification[6375].INF [main:1050] [|----> FORK:1 (4), eid:5299 Event 5299 for Monitor 4 has finished]
12/07/2021 10:57:20.659163 zmeventnotification[6375].DBG [main:1038] [|----> FORK:1 (4), eid:5299 Event end object is: state=>pending with cause=>Motion: lowerleft, upperRight] 

Nothing odd here from what I can see.

[asker]

Code: Select all

sudo -u www-data /var/lib/zmeventnotification/bin/zm_detect.py --config /etc/zm/objectconfig.ini  --eventid 5290 --monitorid 4 --debug

What that command does is only run the detection process on a past event. It is unrelated to your report on delayed websocket notifications
That command is also failing, it would have likely picked up 192.168.0.103 from your config, or secrets.ini, check both. It won't be picking it up unless they are present there.

Back to your original note:

Code: Select all

12/07/2021 10:56:48.222307 zmeventnotification[6375].DBG [main:1038] [PARENT: Forked process:6375 to handle alarm eid:5299]
12/07/2021 10:56:50.420320 zmeventnotification[6375].INF [main:1050] [|----> FORK:1 (4), eid:5299 Sending event_start notification for EID:5299over web]

This shows the ES received notification of an event at 10:56:48 AM and send out the websockets notification 2 seconds later.

Maybe your concern isn't represented in these logs/or did I miss something?