search

ZoneMinder / zmeventnotification

Machine Learning powered Secure Websocket & MQTT based ZoneMinder event notification server
412 stars 128 forks source link

multiple notifications #367

Closed lucasnz closed 3 years ago

lucasnz commented 3 years ago

Event Server version 6.1.14

Hooks version (if you are using Object Detection) app:6.1.14, pyzm:0.3.36

The version of ZoneMinder you are using: 1.34.23

What is the nature of your issue Multiple notifications received occasionally.

Details I've finally managed to capture multiple notifications with debug logs running. It appears to me that active_connections has the event in it twice. See snippet of debug log below. I have a copy of the complete log that I'm happy to email to you. Do we need to check if an eid is already in active_connections before adding it (again)?

Debug Logs 

03/06/21 10:23:03.693430 zmeventnotification[16580].DBG [main:997] [|----> FORK:Driveway (2), eid:720 rules: Checking rules for alarm caused by eid:720, monitor:2, at: Sat Mar  6 10:23:03 2021 with cause:[s] detected:car:96%  Motion Driveway]
03/06/21 10:23:03.693536 zmeventnotification[16580].DBG [main:997] [|----> FORK:Driveway (2), eid:720 rules: No rules found for Monitor, allowing:2]
03/06/21 10:23:03.693602 zmeventnotification[16580].DBG [main:997] [|----> FORK:Driveway (2), eid:720 Matching alarm to connection rules...]
03/06/21 10:23:03.693691 zmeventnotification[16580].DBG [main:997] [|----> FORK:Driveway (2), eid:720 Checking alarm conditions for token ending in:...E7BE7_x_vc]
03/06/21 10:23:03.693771 zmeventnotification[16580].DBG [main:997] [|----> FORK:Driveway (2), eid:720 Monitor 2 event: last time not found, so should send]
03/06/21 10:23:03.693818 zmeventnotification[16580].DBG [main:997] [|----> FORK:Driveway (2), eid:720 shouldSendEventToConn returned true, so calling sendEvent]
03/06/21 10:23:03.693920 zmeventnotification[16580].DBG [main:997] [|----> FORK:Driveway (2), eid:720 isAllowedChannel: got type:event_start resCode:0]
03/06/21 10:23:03.694559 zmeventnotification[16580].INF [main:1009] [|----> FORK:Driveway (2), eid:720 Sending event_start notification over FCM]
03/06/21 10:23:03.700888 zmeventnotification[16580].DBG [main:997] [|----> FORK:Driveway (2), eid:720 fcmv1: Snapshot frame matched, changing picture url to:https://zm.brdbnt.com/zm/index.php?view=image&eid=720&fid=objdetect_jpg&width=600&username=zm-api&password=xxx ]
03/06/21 10:23:03.701050 zmeventnotification[16580].DBG [main:997] [|----> FORK:Driveway (2), eid:720 setting channel to zmninja]
03/06/21 10:23:03.701150 zmeventnotification[16580].DBG [main:997] [|----> FORK:Driveway (2), eid:720 fcmv1: Final JSON using FCMV1 being sent is: {"android":{"icon":"ic_stat_notification","priority":"high","channel":"zmninja"},"image_url":"https://zm.brdbnt.com/zm/index.php?view=image&eid=720&fid=objdetect_jpg&width=600&username=zm-api&password=xxx","badge":2,"title":"Driveway Alarm (720)","body":"[s] detected:car:96%  Motion Driveway at 10:23 AM, 06-Mar","sound":"default","token":"xxx","data":{"mid":"2","notification_foreground":"true","eid":"720"}} to token: ...7_x_vc]
03/06/21 10:23:03.938346 zmeventnotification[14798].DBG [main:997] [PARENT: ---------->onConnect START<--------------]
03/06/21 10:23:03.938735 zmeventnotification[14798].DBG [main:997] [PARENT: got a websocket connection from 0.0.0.0 (2) active connections]
03/06/21 10:23:03.939075 zmeventnotification[14798].DBG [main:997] [PARENT: ---------->onConnect END<--------------]
03/06/21 10:23:03.939286 zmeventnotification[14798].DBG [main:997] [PARENT: ---------->onConnect:disconnect START<--------------]
03/06/21 10:23:03.939574 zmeventnotification[14798].DBG [main:997] [PARENT: Websocket remotely disconnected from 0.0.0.0]
03/06/21 10:23:03.939847 zmeventnotification[14798].DBG [main:997] [PARENT: Invaliding websocket, but NOT Marking 0.0.0.0 for deletion as token xxx active]
03/06/21 10:23:03.940014 zmeventnotification[14798].DBG [main:997] [PARENT: Invaliding websocket, but NOT Marking 0.0.0.0 for deletion as token xxx active]
03/06/21 10:23:03.940123 zmeventnotification[14798].DBG [main:997] [PARENT: ---------->onConnect:disconnect END<--------------]
03/06/21 10:23:04.353683 zmeventnotification[16580].DBG [main:997] [|----> FORK:Driveway (2), eid:720 fcmv1: FCM push message returned a 200 with body {"Success":"projects/ninja-1105/messages/0:1614979384210502%311426be311426be"}]
03/06/21 10:23:04.353818 zmeventnotification[16580].DBG [main:997] [|----> FORK:Driveway (2), eid:720 child finished writing to parent]
03/06/21 10:23:04.353872 zmeventnotification[16580].DBG [main:997] [|----> FORK:Driveway (2), eid:720 Checking alarm conditions for token ending in:...E7BE7_x_vc]
03/06/21 10:23:04.353961 zmeventnotification[16580].DBG [main:997] [|----> FORK:Driveway (2), eid:720 Monitor 2 event: last time not found, so should send]
03/06/21 10:23:04.353968 zmeventnotification[16580].DBG [main:997] [|----> FORK:Driveway (2), eid:720 shouldSendEventToConn returned true, so calling sendEvent]
03/06/21 10:23:04.354080 zmeventnotification[16580].DBG [main:997] [|----> FORK:Driveway (2), eid:720 isAllowedChannel: got type:event_start resCode:0]
03/06/21 10:23:04.354645 zmeventnotification[16580].INF [main:1009] [|----> FORK:Driveway (2), eid:720 Sending event_start notification over FCM]
03/06/21 10:23:04.356201 zmeventnotification[16580].DBG [main:997] [|----> FORK:Driveway (2), eid:720 fcmv1: Snapshot frame matched, changing picture url to:https://zm.brdbnt.com/zm/index.php?view=image&eid=720&fid=objdetect_jpg&width=600&username=zm-api&password=xxx ]
03/06/21 10:23:04.356308 zmeventnotification[16580].DBG [main:997] [|----> FORK:Driveway (2), eid:720 setting channel to zmninja]
03/06/21 10:23:04.356389 zmeventnotification[16580].DBG [main:997] [|----> FORK:Driveway (2), eid:720 fcmv1: Final JSON using FCMV1 being sent is: {"body":"[s] detected:car:96%  Motion Driveway at 10:23 AM, 06-Mar","data":{"notification_foreground":"true","eid":"720","mid":"2"},"sound":"default","token":"xxx","badge":2,"image_url":"https://zm.brdbnt.com/zm/index.php?view=image&eid=720&fid=objdetect_jpg&width=600&username=zm-api&password=xxx","android":{"icon":"ic_stat_notification","priority":"high","channel":"zmninja"},"title":"Driveway Alarm (720)"} to token: ...7_x_vc]
03/06/21 10:23:04.910152 zmeventnotification[16580].DBG [main:997] [|----> FORK:Driveway (2), eid:720 fcmv1: FCM push message returned a 200 with body {"Success":"projects/ninja-1105/messages/0:1614979384729980%311426be311426be"}]
03/06/21 10:23:04.910268 zmeventnotification[16580].DBG [main:997] [|----> FORK:Driveway (2), eid:720 child finished writing to parent]
03/06/21 10:23:04.910316 zmeventnotification[16580].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139640549871616 for 2]
03/06/21 10:23:04.910387 zmeventnotification[16580].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 2: 1]
pliablepixels commented 3 years ago

I've finally managed to capture multiple notifications with debug logs running. It appears to me that active_connections has the event in it twice. See snippet of debug log below. I have a copy of the complete log that I'm happy to email to you. Do we need to check if an eid is already in active_connections before adding it (again)?

Active connections actually is a list of 'connections' (Web, tokens, mqtt) events need to be sent to and not related to eids. What might be happening here is that token is first loaded from tokens.txt. Then the same device owning that token connects to the ES. What should be happening is the old connection is updated with the new details. It is possible there is something wrong going on there under a specific condition that we need to track down. I don't see it happening here, but it is possible a combination of events is causing that. If you are able to nail down a set of conditions that triggers this, it would be super useful.

lucasnz commented 3 years ago

Any suggestions on how to go about this? Delete the tokens file then restart ES? A couple of points:

  1. The token file only seems to have one token in it (see below)
  2. Once it starts happening, it continues to occur. Sometime it increases up to 4 notifications
{"tokens":{"removed":{"pushstate":"enabled","appversion":"1.6.007","intlist":"0,0,0","invocations":{"count":"135","at":"2"},"platform":"android","monlist":"1,2,3"}}}
pliablepixels commented 3 years ago

Yes, maybe try this:

  1. Start with no tokens, restart ES
  2. Load zmN on one device
  3. Make sure token registers
  4. Generate push make sure you get it
  5. Kill zmNinja
  6. Generate push, make sure you get it without the app running
  7. Start zmNinja, don't exit
  8. Generate push
  9. See if you get one or two

If you get only one, then switch to the next device if you are using multiple

Basically, trying to see when does it put two of the same tokens in the list

lucasnz commented 3 years ago

I'm only using a single device. I'll delete the token file and restart ES. It seems to take a few hours before multiple notifications start appearing though...

lucasnz commented 3 years ago

I'm not really sure what to report. I left the service running for about a week and got up to about 24 notifications per event today. I've just restarted (after upgrading ES and websockets). Is there an event I can grep for that is likely triggering when this occurs, or can I add some logging (where would you put it)? Cheers, Luke

pliablepixels commented 3 years ago

That is completely nuts. I have 0 events recurring. Let me look at the logs I print to see what we can pinpoint on.

lucasnz commented 3 years ago

So, it been two days since the last comment (when I upgraded ES and websockets) and I haven't touched anything else - I've not had a single duplicate notification. Could it have been an issue with the version of websockets I had installed?? Or did you change something in ES that may have fixed it? So weird. I'll keep monitoring, but given it's working I'm afraid to touch it much now...

pliablepixels commented 3 years ago

You may want to try https://github.com/pliablepixels/zmeventnotification/tree/duplicate_tokens -> I've added logs to print out when tokens are duplicated in active_connections. The correct situation should be that once in a while you may duplicate tokens (especially in zmNinja connects) but it should then clear them up. If you see this building up, then lets look at what triggers led to this situation looking at previous logs. https://github.com/pliablepixels/zmeventnotification/commit/3c23336fed7b6371cb29c5f7897210ef14f1d2ad

If there are no duplicate tokens, you will not see a log. This is set to debug level 4.

lucasnz commented 3 years ago

I updated to the latest master on 21 Mar (which seems to include the above commit). I've now been running for 11 days without duplicate (9 days with the 21 March commit) without a single duplicate. Perhaps it's time to close out this issue. No idea what has resolved it.

pliablepixels commented 3 years ago

That may be because I added duplicate token check (which shouldn't happen in the first place). If you are seeing occurs: <X> times in your logs, then duplicates are still occurring and I am removing them. I'd love to see history logs if this happens.

lucasnz commented 3 years ago

I have debug logs (/var/log/zm/zmeventnotification.log*) going back until the 24th. The word "occurs" does not appear in the logs. I'll keep looking. It seemed to resolve on the 18th - when I installed the ES update that warned I had an old version of websockets, before the duplicate tokens commit.

pliablepixels commented 3 years ago

Hmm, interesting. Anyway, I'll leave it to you to decide when to close it.

lucasnz commented 3 years ago

Issue has not reoccurred. Closing...