Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Notifications for events from unchecked monitor. #1022

Closed
hugalafutro opened this issue Dec 10, 2020 · 24 comments
Closed

Notifications for events from unchecked monitor. #1022

hugalafutro opened this issue Dec 10, 2020 · 24 comments
Labels

Comments

@hugalafutro
Copy link

The version of zmNinja you are reporting:

1.6.000

The version and OS of ZoneMinder you are using:

1.34.22, docker dlandon/zoneminder:latest

Platform zmNinja is running on

oneplus 6t, android 10

Did you build the package from source code yourself?
N

Describe the bug
I got 2 cameras in ZM, outside, inside. In zmninja settings/event server I have outside unchecked and inside checked.

I set up the whole thing, ZM, eventserver, object detect, installed zmninja on phone/tablet and all is well, however, every morning I wake up, or every break at work, on the phone I will get notifications for detected events, but they are for outside camera that's unchecked in event server settings. It is not every event, it's just some of events with detected objects

I cleared API cache, I cleared the whole app data and set the app from the ground and it still happens. I also have zmninja set up with the exact same settings on android 9 tablet and there I only receive notifications from the enabled monitor

It is not consistent it happens randomly. For whatever reason also the tablet tends to get the notifications always earlier, sometimes by up to a minute or two.

Debug logs

I don't have logs as it happens randomly and I only notice after few hours
@welcome
Copy link

welcome bot commented Dec 10, 2020

👋 Thanks for opening your first issue here! If you're reporting a 🐞 bug, please make sure you follow the issue template or I may not respond.

@pliablepixels
Copy link
Member

Check if the monitors specified in mon_list inside /var/lib/zmeventnotification/push/tokens.txt reflect what you think is unchecked (it should not be there)

@hugalafutro
Copy link
Author

hugalafutro commented Dec 12, 2020

Hi,
mon_list only has 2 (which is correct, camera id 1 is outside, 2 is inside. I even previously deleted the file and it gets recreated with the same info).

There were 14 events recorded tonight, 4 of them had object detected. I received a notification for 2 events, 1 of them with object detected 1 without.

It's no biggie really, just strange why it's happening.

@pliablepixels
Copy link
Member

Okay. You may want to enable Debug logs for a few days if you want us to dive into what is going on. If not, feel free to close this.

@hugalafutro
Copy link
Author

I enabled debug logs in the app on the phone, after I get unmonitored notification is there anything specific I'm looking for? I'll upload them here in any case.

@pliablepixels
Copy link
Member

Yes, we are looking for logs from zmeventnotification.log from the time an alarm hits the logs till the time it is sent out via push (for a monitor ID that should not be sent out)

@hugalafutro
Copy link
Author

hugalafutro commented Dec 14, 2020

Of course 1st day after enabling debug logs it doesn't happen. I'll keep an eye on it, but I was wondering I see these in the log:

12/14/20 23:10:37.895644 zmeventnotification[1098].DBG [main:959] [PARENT: ---------->Tick START<--------------]
12/14/20 23:10:37.895760 zmeventnotification[1098].DBG [main:959] [PARENT: There are 0 active child forks...]
12/14/20 23:10:37.895809 zmeventnotification[1098].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139884235452416 for 1]
12/14/20 23:10:37.895889 zmeventnotification[1098].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 1: 1]
12/14/20 23:10:37.895976 zmeventnotification[1098].DBG [main:959] [PARENT: checkEvents() new events found=0]
12/14/20 23:10:37.896021 zmeventnotification[1098].DBG [main:959] [PARENT: There are 0 new Events to process]
12/14/20 23:10:37.896062 zmeventnotification[1098].DBG [main:959] [PARENT: ---------->Tick END<--------------]

Why is it talking about monitor 1? That's the unselected one. Shouldn't it be talking about monitor 2 as that is what mon_list has inside it? If i look inside zmninja logs I can se it reads mon_list as having 2 only:

Dec 14, 2020 10:50:57:587 PM DEBUG EventSever: sendMessage: received->{"event":"auth","data":{"user":"admin",<password removed>,"monlist":"2","intlist":"0","appversion":"1.6.004"},"token":"<token removed>"}

Apologies if I'm misunderstanding how it all works.

@hugalafutro
Copy link
Author

hugalafutro commented Dec 15, 2020

managed to get the logs. while at work I got 3 notifications for outside camera (in the time I was at work there were 18 events recorded in ZM). The full log is humongous 11M txt file, if you need it I can upload it somewhere, but the 3 events that prompted the unwanted notifications all look like this just the event number changes:

event 489 @ 13:28

12/15/20 13:28:00.663683 zmeventnotification[1064].DBG [main:959] [PARENT: ---------->Tick START<--------------]
12/15/20 13:28:00.663805 zmeventnotification[1064].DBG [main:959] [PARENT: There are 0 active child forks...]
12/15/20 13:28:00.663855 zmeventnotification[1064].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139855631327232 for 1]
12/15/20 13:28:00.663936 zmeventnotification[1064].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 1: 1]
12/15/20 13:28:00.664143 zmeventnotification[1064].INF [main:968] [PARENT: New event 489 reported for Monitor:1 (Name:Outside Front) Motion door[last processed eid:488]]
12/15/20 13:28:00.668936 zmeventnotification[1064].DBG [main:959] [PARENT: checkEvents() new events found=1]
12/15/20 13:28:00.669013 zmeventnotification[1064].DBG [main:959] [PARENT: There are 1 new Events to process]
12/15/20 13:28:00.670064 zmeventnotification[1064].DBG [main:959] [PARENT: ---------->Tick END<--------------]
12/15/20 13:28:00.673031 zmeventnotification[25194].DBG [main:959] [PARENT: Forked process:25194 to handle alarm eid:489]
12/15/20 13:28:00.673281 zmeventnotification[25194].DBG [ZoneMinder::Object:115] [Loading ZoneMinder::Event from Events WHERE Id = 489]
12/15/20 13:28:00.674298 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 Adding event path:/var/cache/zoneminder/events/1/2020-12-15/489 to hook for image storage]
12/15/20 13:28:00.674356 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 Invoking hook on event start:'/var/lib/zmeventnotification/bin/zm_event_start.sh' 489 1 "Outside Front" "Motion door" "/var/cache/zoneminder/events/1/2020-12-15/489"]
12/15/20 13:28:05.663679 zmeventnotification[1064].DBG [main:959] [PARENT: ---------->Tick START<--------------]
12/15/20 13:28:05.664007 zmeventnotification[1064].DBG [main:959] [PARENT: There are 1 active child forks...]
12/15/20 13:28:05.664109 zmeventnotification[1064].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139855631327232 for 1]
12/15/20 13:28:05.664261 zmeventnotification[1064].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 1: 1]
12/15/20 13:28:05.664393 zmeventnotification[1064].DBG [main:959] [PARENT: We've already worked on Monitor:1, Event:489, not doing anything more]
12/15/20 13:28:05.664444 zmeventnotification[1064].DBG [main:959] [PARENT: checkEvents() new events found=0]
12/15/20 13:28:05.664486 zmeventnotification[1064].DBG [main:959] [PARENT: There are 0 new Events to process]
12/15/20 13:28:05.664535 zmeventnotification[1064].DBG [main:959] [PARENT: ---------->Tick END<--------------]
12/15/20 13:28:06.053902 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 parse of hook:[a] detected:person:86%  and [{"type": "object", "label": "person", "box": [1068, 56, 1148, 130], "confidence": "86.19%"}]]
12/15/20 13:28:06.054001 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 hook start returned with text:[a] detected:person:86%  json:[{"type": "object", "label": "person", "box": [1068, 56, 1148, 130], "confidence": "86.19%"}] exit:0]
12/15/20 13:28:06.054151 zmeventnotification[25194].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139855631327232 for 1]
12/15/20 13:28:06.054282 zmeventnotification[25194].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 1: 1]
12/15/20 13:28:08.054827 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 rules: Checking rules for alarm caused by eid:489, monitor:1, at: Tue Dec 15 13:28:08 2020 with cause:[a] detected:person:86%  Motion door]
12/15/20 13:28:08.054914 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 rules: No rules found for Monitor, allowing:1]
12/15/20 13:28:08.054998 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 Matching alarm to connection rules...]
12/15/20 13:28:08.055083 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 Checking alarm conditions for token ending in:...yfRRa3KtpQ]
12/15/20 13:28:08.055145 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 should NOT send alarm as Monitor 1 is excluded]
12/15/20 13:28:08.055202 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 Checking alarm conditions for MQTT 192.168.1.101]
12/15/20 13:28:08.055290 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 Monitor 1 event: should send out as  8376.01311993599 is >= interval of ]
12/15/20 13:28:08.055350 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 shouldSendEventToConn returned true, so calling sendEvent]
12/15/20 13:28:08.055453 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 isAllowedChannel: got type:event_start resCode:0]
12/15/20 13:28:08.055763 zmeventnotification[25194].INF [main:968] [|----> FORK:Outside Front (1), eid:489 Sending event_start notification for EID:489 over MQTT]
12/15/20 13:28:08.060077 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 requesting MQTT Publishing Job for EID:489]
12/15/20 13:28:08.060230 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 Checking alarm conditions for token ending in:...iCOFXNUhPP]
12/15/20 13:28:08.060329 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 Monitor 1 event: last time not found, so should send]
12/15/20 13:28:08.060407 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 shouldSendEventToConn returned true, so calling sendEvent]
12/15/20 13:28:08.060510 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 isAllowedChannel: got type:event_start resCode:0]
12/15/20 13:28:08.060684 zmeventnotification[25194].INF [main:968] [|----> FORK:Outside Front (1), eid:489 Sending event_start notification over FCM]
12/15/20 13:28:08.063659 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 setting channel to zmninja]
12/15/20 13:28:08.063885 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 fcmv1: Final JSON using FCMV1 being sent is: {"title":"Outside Front Alarm (489)","sound":"default","data":{"eid":"489","notification_foreground":"true","mid":"1"},"image_url":"http>
12/15/20 13:28:08.585388 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 fcmv1: FCM push message returned a 200 with body {"Success":"projects/ninja-1105/messages/0:1608038888505079%311426be311426be"}]
12/15/20 13:28:08.585952 zmeventnotification[25194].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139855631327232 for 1]
12/15/20 13:28:08.586095 zmeventnotification[25194].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 1: 1]
12/15/20 13:28:10.586362 zmeventnotification[25194].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139855631327232 for 1]
12/15/20 13:28:10.586590 zmeventnotification[25194].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 1: 1]
12/15/20 13:28:10.664008 zmeventnotification[1064].DBG [main:959] [PARENT: ---------->Tick START<--------------]
12/15/20 13:28:10.664403 zmeventnotification[1064].DBG [main:959] [PARENT: RAW TEXT-->active_event_update--TYPE--1--SPLIT--489--SPLIT--Start--SPLIT--Cause--SPLIT--[a] detected:person:86%  Motion door--JSON--]
12/15/20 13:28:10.664483 zmeventnotification[1064].DBG [main:959] [PARENT: Job: Update active_event eid:489, mid:1, type:Start, field:Cause to: [a] detected:person:86%  Motion door--JSON--]
12/15/20 13:28:10.664648 zmeventnotification[1064].DBG [main:959] [PARENT: RAW TEXT-->event_description--TYPE--1--SPLIT--489--SPLIT--[a] detected:person:86% ]
12/15/20 13:28:10.664695 zmeventnotification[1064].DBG [main:959] [PARENT: Job: Update monitor 1 description:[a] detected:person:86% ]
12/15/20 13:28:10.664744 zmeventnotification[1064].DBG [main:959] [PARENT: updating Notes clause for Event:489 with:[a] detected:person:86%  ]
12/15/20 13:28:10.671227 zmeventnotification[1064].DBG [main:959] [PARENT: RAW TEXT-->mqtt_publish--TYPE----SPLIT--zoneminder/1--SPLIT--{"monitor":"1","hookvalue":"0","name":"Outside Front:(489) detected:person:86%  Motion door","detection":[{"box":[1068,56,1148,130],"confidence":"86.19%>
12/15/20 13:28:10.671312 zmeventnotification[1064].DBG [main:959] [PARENT: Job: MQTT Publish on topic: zoneminder/1]
12/15/20 13:28:10.671372 zmeventnotification[1064].DBG [main:959] [PARENT: Job: MQTT Publish]
12/15/20 13:28:10.671771 zmeventnotification[1064].DBG [main:959] [PARENT: RAW TEXT-->timestamp--TYPE----SPLIT--1--SPLIT--1608038888.05538]
12/15/20 13:28:10.671835 zmeventnotification[1064].DBG [main:959] [PARENT: Job: Update last sent timestamp of monitor:1 to 1608038888.05538 for id:]
12/15/20 13:28:10.672150 zmeventnotification[1064].DBG [main:959] [PARENT: RAW TEXT-->fcm_notification--TYPE--<token removed>--SPLIT--1--SPL>
12/15/20 13:28:10.672215 zmeventnotification[1064].DBG [main:959] [PARENT: GOT JOB==> update badge to 1, count to 44 for: <token removed>, a>
12/15/20 13:28:10.672385 zmeventnotification[1064].DBG [main:959] [PARENT: RAW TEXT-->timestamp--TYPE--1608037920.5196--SPLIT--1--SPLIT--1608038888.06045]
12/15/20 13:28:10.672435 zmeventnotification[1064].DBG [main:959] [PARENT: Job: Update last sent timestamp of monitor:1 to 1608038888.06045 for id:1608037920.5196]
12/15/20 13:28:10.672490 zmeventnotification[1064].DBG [main:959] [PARENT: There are 1 active child forks...]
12/15/20 13:28:10.672530 zmeventnotification[1064].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139855631327232 for 1]
12/15/20 13:28:10.672617 zmeventnotification[1064].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 1: 1]
12/15/20 13:28:10.672709 zmeventnotification[1064].DBG [main:959] [PARENT: We've already worked on Monitor:1, Event:489, not doing anything more]
12/15/20 13:28:10.672751 zmeventnotification[1064].DBG [main:959] [PARENT: checkEvents() new events found=0]
12/15/20 13:28:10.672792 zmeventnotification[1064].DBG [main:959] [PARENT: There are 0 new Events to process]
12/15/20 13:28:10.672832 zmeventnotification[1064].DBG [main:959] [PARENT: ---------->Tick END<--------------]

what immediately jumps at me is first it correctly says 12/15/20 13:28:08.055145 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 should NOT send alarm as Monitor 1 is excluded],
but then few lines later it sends it anyway
12/15/20 13:28:08.055290 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 Monitor 1 event: should send out as 8376.01311993599 is >= interval of ]

forgot to add that only the phone received these notifications, none on the tablet

@pliablepixels
Copy link
Member

pliablepixels commented Dec 16, 2020

This block:


12/15/20 13:28:08.055083 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 Checking alarm conditions for token ending in:...yfRRa3KtpQ]
12/15/20 13:28:08.055145 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 should NOT send alarm as Monitor 1 is excluded]
12/15/20 13:28:08.055202 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 Checking alarm conditions for MQTT 192.168.1.101]
12/15/20 13:28:08.055290 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 Monitor 1 event: should send out as  8376.01311993599 is >= interval of ]
12/15/20 13:28:08.055350 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 shouldSendEventToConn returned true, so calling sendEvent]
12/15/20 13:28:08.055453 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 isAllowedChannel: got type:event_start resCode:0]
12/15/20 13:28:08.055763 zmeventnotification[25194].INF [main:968] [|----> FORK:Outside Front (1), eid:489 Sending event_start notification for EID:489 over MQTT]
12/15/20 13:28:08.060077 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 requesting MQTT Publishing Job for EID:489]

It is not sending a notification via FCM. It is sending a message via MQTT - two completely different things. I'm not sure what happens after MQTT is sent - if some MQTT broker is further sending a push, then its out of scope. My guess is you've used zmNinja to disable that monitor. That only applies for FCM tokens. zmNinja has no idea about anything else except for FCM.

Next up:

12/15/20 13:28:08.060230 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 Checking alarm conditions for token ending in:...iCOFXNUhPP]
12/15/20 13:28:08.060329 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 Monitor 1 event: last time not found, so should send]
12/15/20 13:28:08.060407 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 shouldSendEventToConn returned true, so calling sendEvent]
12/15/20 13:28:08.060510 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 isAllowedChannel: got type:event_start resCode:0]
12/15/20 13:28:08.060684 zmeventnotification[25194].INF [main:968] [|----> FORK:Outside Front (1), eid:489 Sending event_start notification over FCM]
12/15/20 13:28:08.063659 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 setting channel to zmninja]
12/15/20 13:28:08.063885 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 fcmv1: Final JSON using FCMV1 being sent is: {"title":"Outside Front Alarm (489)","sound":"default","data":{"eid":"489","notification_foreground":"true","mid":"1"},"image_url":"http>
12/15/20 13:28:08.585388 zmeventnotification[25194].DBG [main:959] [|----> FORK:Outside Front (1), eid:489 fcmv1: FCM push message returned a 200 with body {"Success":"projects/ninja-1105/messages/0:1608038888505079%311426be311426be"}]

This is for a different token, so different device.

@hugalafutro
Copy link
Author

It's not the mqtt, as I tried disabling it via setting

[mqtt]
enable = no

in zmeventnotification.ini to no avail

However I believe I narrowed it down to hook processing, as if I disable hooks, everything starts working as it should, with the unfortunate side effect of the zmninja notifications not having a picture now.

Did some testing by generating ZM events on inside camera and I only got zmninja notification when an object is detected. I tested this by walking in front of the inside camera twice, both times both devices got notification from zmninja that a person was detected on inside camera. Then I slid my chair across the room twice, and while ZM recorded the event, no notification was generated.

This lead me to the hooks, after I disabled those everything started working as I want, i.e. no notifications from outside, all of the notifications from the inside.

This tells me I probably misconfigured something in the hooks, but I can't figure what. Obviously that's likely not the case, but were you to ask me I'd swear I haven't edited the files in months until trying to debug this issue few weeks back. I'll attach my inis below:

zmeventnotification.ini (only change from usual ini is mqtt and hooks turned off) https://pastebin.com/raw/LsWjsw7X
objectconfig.ini https://pastebin.com/raw/s0vR73kG

I'll leave it with mqtt and hooks off overnight and see if I get any unwanted notifications tomorrow.

@hugalafutro
Copy link
Author

hugalafutro commented Dec 17, 2020

OK, I'm getting really lost now. After the yesterdays changes, what happens now is, the phone doesn't receive notifications from the unchecked monitor, but now the tablet started receiving them...

this is from the logs for one such event (with mqtt and hooks still off)

12/17/20 09:00:27.687672 zmeventnotification[1056].DBG [main:959] [PARENT: ---------->Tick START<--------------]
12/17/20 09:00:27.687774 zmeventnotification[1056].DBG [main:959] [PARENT: There are 0 active child forks...]
12/17/20 09:00:27.687820 zmeventnotification[1056].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140338946355200 for 2]
12/17/20 09:00:27.687895 zmeventnotification[1056].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 2: 1]
12/17/20 09:00:27.687971 zmeventnotification[1056].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140338946359296 for 1]
12/17/20 09:00:27.688038 zmeventnotification[1056].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 1: 1]
12/17/20 09:00:27.688217 zmeventnotification[1056].INF [main:968] [PARENT: New event 565 reported for Monitor:1 (Name:Outside Front) Motion door[last processed eid:564]]
12/17/20 09:00:27.693765 zmeventnotification[1056].DBG [main:959] [PARENT: checkEvents() new events found=1]
12/17/20 09:00:27.693829 zmeventnotification[1056].DBG [main:959] [PARENT: There are 1 new Events to process]
12/17/20 09:00:27.694808 zmeventnotification[1056].DBG [main:959] [PARENT: ---------->Tick END<--------------]
12/17/20 09:00:27.697398 zmeventnotification[33536].DBG [main:959] [PARENT: Forked process:33536 to handle alarm eid:565]
12/17/20 09:00:27.697760 zmeventnotification[33536].INF [main:968] [|----> FORK:Outside Front (1), eid:565 use hooks/start hook not being used, going to directly send out a notification if checks pass]
12/17/20 09:00:27.702417 zmeventnotification[33536].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140338946359296 for 1]
12/17/20 09:00:27.702608 zmeventnotification[33536].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 1: 1]
12/17/20 09:00:29.703088 zmeventnotification[33536].DBG [main:959] [|----> FORK:Outside Front (1), eid:565 rules: Checking rules for alarm caused by eid:565, monitor:1, at: Thu Dec 17 09:00:29 2020 with cause:Motion door]
12/17/20 09:00:29.703171 zmeventnotification[33536].DBG [main:959] [|----> FORK:Outside Front (1), eid:565 rules: No rules found for Monitor, allowing:1]
12/17/20 09:00:29.703250 zmeventnotification[33536].DBG [main:959] [|----> FORK:Outside Front (1), eid:565 Matching alarm to connection rules...]
12/17/20 09:00:29.703331 zmeventnotification[33536].DBG [main:959] [|----> FORK:Outside Front (1), eid:565 Checking alarm conditions for token ending in:...iCOFXNUhPP]
12/17/20 09:00:29.703382 zmeventnotification[33536].DBG [main:959] [|----> FORK:Outside Front (1), eid:565 should NOT send alarm as Monitor 1 is excluded]
12/17/20 09:00:29.703425 zmeventnotification[33536].DBG [main:959] [|----> FORK:Outside Front (1), eid:565 Checking alarm conditions for token ending in:...yfRRa3KtpQ]
12/17/20 09:00:29.703499 zmeventnotification[33536].DBG [main:959] [|----> FORK:Outside Front (1), eid:565 Monitor 1 event: should send out as  3419.29364991188 is >= interval of -1]
12/17/20 09:00:29.703563 zmeventnotification[33536].DBG [main:959] [|----> FORK:Outside Front (1), eid:565 shouldSendEventToConn returned true, so calling sendEvent]
12/17/20 09:00:29.703663 zmeventnotification[33536].DBG [main:959] [|----> FORK:Outside Front (1), eid:565 isAllowedChannel: got type:event_start resCode:0]
12/17/20 09:00:29.703800 zmeventnotification[33536].INF [main:968] [|----> FORK:Outside Front (1), eid:565 Sending event_start notification over FCM]
12/17/20 09:00:29.707370 zmeventnotification[33536].DBG [main:959] [|----> FORK:Outside Front (1), eid:565 fcmv1: FCM called when there is no start hook/or hooks are disabled, so making sure we do not use objdetect in url]
12/17/20 09:00:29.707593 zmeventnotification[33536].DBG [main:959] [|----> FORK:Outside Front (1), eid:565 setting channel to zmninja]
12/17/20 09:00:29.707694 zmeventnotification[33536].DBG [main:959] [|----> FORK:Outside Front (1), eid:565 fcmv1: Final JSON using FCMV1 being sent is: {"android":{"priority":"high","icon":"ic_stat_notification","channel":"zmninja"},"title":"Outside Front Alarm (565)","body":"Motion door>
12/17/20 09:00:30.212389 zmeventnotification[33536].DBG [main:959] [|----> FORK:Outside Front (1), eid:565 fcmv1: FCM push message returned a 200 with body {"Success":"projects/ninja-1105/messages/0:1608195630093670%311426be311426be"}]
12/17/20 09:00:30.212522 zmeventnotification[33536].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140338946359296 for 1]
12/17/20 09:00:30.212598 zmeventnotification[33536].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 1: 1]
12/17/20 09:00:32.212763 zmeventnotification[33536].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140338946359296 for 1]
12/17/20 09:00:32.212919 zmeventnotification[33536].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 1: 1]
12/17/20 09:00:32.691683 zmeventnotification[1056].DBG [main:959] [PARENT: ---------->Tick START<--------------]
12/17/20 09:00:32.692213 zmeventnotification[1056].DBG [main:959] [PARENT: RAW TEXT-->fcm_notification--TYPE--f0KUtJyqAjY:APA91bF0ekUPMgbKiIdn3eUP047L6izW_JMIapBRbfH6ugWN2epBYmaLqRbM_tB3R_md1wUC0Fwi6YUhUhK0A9ZkKqLqbB-1SwCJn4cJ6Du_fySqFXVraET2BkUdzB7kmCyfRRa3KtpQ--SPLIT--16--SPLIT--27--SP>
12/17/20 09:00:32.692297 zmeventnotification[1056].DBG [main:959] [PARENT: GOT JOB==> update badge to 16, count to 27 for: f0KUtJyqAjY:APA91bF0ekUPMgbKiIdn3eUP047L6izW_JMIapBRbfH6ugWN2epBYmaLqRbM_tB3R_md1wUC0Fwi6YUhUhK0A9ZkKqLqbB-1SwCJn4cJ6Du_fySqFXVraET2BkUdzB7kmCyfRRa3KtpQ, at: 11]
12/17/20 09:00:32.692466 zmeventnotification[1056].DBG [main:959] [PARENT: RAW TEXT-->timestamp--TYPE--1608160402.57047--SPLIT--1--SPLIT--1608195629.7036]
12/17/20 09:00:32.692524 zmeventnotification[1056].DBG [main:959] [PARENT: Job: Update last sent timestamp of monitor:1 to 1608195629.7036 for id:1608160402.57047]
12/17/20 09:00:32.692584 zmeventnotification[1056].DBG [main:959] [PARENT: There are 1 active child forks...]
12/17/20 09:00:32.692653 zmeventnotification[1056].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140338946355200 for 2]
12/17/20 09:00:32.692739 zmeventnotification[1056].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 2: 1]
12/17/20 09:00:32.692825 zmeventnotification[1056].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140338946359296 for 1]
12/17/20 09:00:32.692872 zmeventnotification[1056].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 1: 1]
12/17/20 09:00:32.692957 zmeventnotification[1056].DBG [main:959] [PARENT: We've already worked on Monitor:1, Event:565, not doing anything more]
12/17/20 09:00:32.692997 zmeventnotification[1056].DBG [main:959] [PARENT: checkEvents() new events found=0]
12/17/20 09:00:32.693034 zmeventnotification[1056].DBG [main:959] [PARENT: There are 0 new Events to process]
12/17/20 09:00:32.693071 zmeventnotification[1056].DBG [main:959] [PARENT: ---------->Tick END<--------------]

edit:
I don't get why it treats one of the tokens as having monitor 1 enabled

12/17/20 09:00:29.703331 zmeventnotification[33536].DBG [main:959] [|----> FORK:Outside Front (1), eid:565 Checking alarm conditions for token ending in:...iCOFXNUhPP]
12/17/20 09:00:29.703382 zmeventnotification[33536].DBG [main:959] [|----> FORK:Outside Front (1), eid:565 should NOT send alarm as Monitor 1 is excluded]
12/17/20 09:00:29.703425 zmeventnotification[33536].DBG [main:959] [|----> FORK:Outside Front (1), eid:565 Checking alarm conditions for token ending in:...yfRRa3KtpQ]
12/17/20 09:00:29.703499 zmeventnotification[33536].DBG [main:959] [|----> FORK:Outside Front (1), eid:565 Monitor 1 event: should send out as  3419.29364991188 is >= interval of -1]
12/17/20 09:00:29.703563 zmeventnotification[33536].DBG [main:959] [|----> FORK:Outside Front (1), eid:565 shouldSendEventToConn returned true, so calling sendEvent]

I doublechecked zmninja on both devices and the push/tokens,txt and both zmnijnjas have monitor 1 unselected and in the tokens.txt both have only 2 in mon_list.

@hugalafutro
Copy link
Author

1 day after turning off hooks tablet stopped receiving notification from disabled monitor. 2 days after turning hooks no device received any notification from disabled monitor. Turned on hooks yesterday, this morning phone started getting notifications from disabled monitor.

@pliablepixels
Copy link
Member

I need to see logs that reflect your observations. The last logs you posted which I responded to showed MQTT messages being sent off. Can you post new logs, with MQTT off and showing the problem?

@hugalafutro
Copy link
Author

In the post from 4 days ago I posted logs where both mqtt and hooks were off

@pliablepixels
Copy link
Member

Can you post tokens.txt?

@hugalafutro
Copy link
Author

{"tokens":{"f0KUtJyqAjY:APA91bF0ekUPMgbKiIdn3eUP047L6izW_JMIapBRbfH6ugWN2epBYmaLqRbM_tB3R_md1wUC0Fwi6YUhUhK0A9ZkKqLqbB-1SwCJn4cJ6Du_fySqFXVraET2BkUdzB7kmCyfRRa3KtpQ":{"invocations":{"count":"48","at":"11"},"platform":"android","intlist":"0","monlist":"2","appversion":"1.6.004","pushstate":"enabled"},"c43rY4iFRvakJEVdRgYbj-:APA91bHqFD7usaTpjWcf9F3LkbuI-cw-L7bEya3pdR3ctEh0CxFB1K2d5HTDbl0rUOJkPKMLHX95z3gu0yNAgz6F_FtzDwPL7CP4bXZhnhOM165kU6W6ii916D8qr4VkPAiCOFXNUhPP":{"appversion":"1.6.004","monlist":"2","intlist":"0","platform":"android","invocations":{"count":"84","at":"11"},"pushstate":"enabled"}}}

@pliablepixels
Copy link
Member

This seems like a bug for now. Will look into it.

@pliablepixels
Copy link
Member

I've added some logs and made some fixes to zmeventnotification.pl - please try master and post logs

@hugalafutro
Copy link
Author

I think I'll have to wait till the changes make it into stable docker ZM image as that's what I'm using.

@pliablepixels
Copy link
Member

Can't you just overwrite zmeventnotification.pl with the new one and test?

@hugalafutro
Copy link
Author

Oh I thought full master install was needed. I went inside the container in portainer, made a backup of /usr/bin/zmeventnotification.pl, spent 5 minutes googling how the heck you make vi actually act as text editor and then finally replaced the contents of /usr/bin/zmeventnotification.pl with contents of https://github.com/pliablepixels/zmeventnotification/blob/master/zmeventnotification.pl

Will enable hooks and restart the container and report back when I catch some logs.

@pliablepixels
Copy link
Member

pliablepixels commented Dec 22, 2020

I don't use docker, but not sure if your changes will persist if you restart the container. Instead:

  1. ssh into the contain
  2. sudo zmdc.pl stop zmeventnotification.pl
  3. Make a backup (you already have)
  4. move the new zmeventnotification.pl to /usr/bin
  5. run sudo -u www-data /usr/bin/zmeventnotification.pl --debug | tee log.txt

@hugalafutro
Copy link
Author

You're right of course (I ain't that great with docker myself I just like the portability of it). I ran the commands you suggested after I changed the file without restarting the container:

-rwxrwxrwx 1 1000 users 136274 Oct 22 22:53 /usr/bin/zmeventnotification.bak
-rwxr-xr-x 1 root root  137780 Dec 22 16:18 /usr/bin/zmeventnotification.pl

and I verified the log.txt is receiving the debug log.
I believe 12/22/20 16:20:42.531886 zmeventnotification[1815].INF [main:969] [PARENT: Event Notification daemon v 6.0.7 starting] indicates it's the new version as the old one was 6.0.5 iirc.

@hugalafutro
Copy link
Author

This is no longer happening with latest ES and the dlandon/zoneminder image was also updated to latest ES version and everything works fine.

Many thanks for the fixes!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

2 participants