Getting erroneous push notifications (still)

[cliffjao]

I previously reported that this was fixed in https://github.com/pliablepixels/zmeventnotification/issues/321 but it turns out I'm still getting the issue - sorry about that. Attaching some debug logs:

CONSOLE INF:2020-10-24,17:01:02 PARENT: Push enabled via FCM
10/24/20 17:01:02.409226 zmeventnotification[1195].INF [main:968] [PARENT: Push enabled via FCM]
CONSOLE DBG-2:2020-10-24,17:01:02 PARENT: fcmv1: --> FCM V1 APIs: 1
CONSOLE INF:2020-10-24,17:01:02 PARENT: MQTT Disabled
10/24/20 17:01:02.410956 zmeventnotification[1195].INF [main:968] [PARENT: MQTT Disabled]
CONSOLE INF:2020-10-24,17:01:02 PARENT: |------- Starting ES version: 6.0.5 ---------|
10/24/20 17:01:02.412856 zmeventnotification[1195].INF [main:968] [PARENT: |------- Starting ES version: 6.0.5 ---------|]
CONSOLE DBG-1:2020-10-24,17:01:02 PARENT: Started with: perl:/usr/bin/perl and command:/usr/bin/zmeventnotification.pl
Can't ignore signal CHLD, forcing to default.
CONSOLE DBG-1:2020-10-24,17:01:02 PARENT: ES invoked manually. Will handle restarts ourselves
CONSOLE DBG-2:2020-10-24,17:01:02 PARENT: Parent<--Child pipe ready
CONSOLE INF:2020-10-24,17:01:02 PARENT: Event Notification daemon v 6.0.5 starting

10/24/20 17:01:02.541921 zmeventnotification[1195].INF [main:968] [PARENT: Event Notification daemon v 6.0.5 starting]
CONSOLE DBG-1:2020-10-24,17:01:02 PARENT: Initializing FCM tokens...
CONSOLE DBG-1:2020-10-24,17:01:02 PARENT: Total event client connections: 2

CONSOLE DBG-1:2020-10-24,17:01:02 PARENT: -->checkNewEvents: Connection 1: ID->1603584062.54353 IP->(none) Token->:...qUKvS8tTMD Plat:android Push:enabled
CONSOLE DBG-1:2020-10-24,17:01:02 PARENT: -->checkNewEvents: Connection 2: ID->1603584062.54357 IP->(none) Token->:...HAUpkTFk_G Plat:android Push:enabled
CONSOLE INF:2020-10-24,17:01:02 PARENT: Re-loading monitors
10/24/20 17:01:02.544062 zmeventnotification[1195].INF [main:968] [PARENT: Re-loading monitors]
...
CONSOLE DBG-2:2020-10-24,17:10:07 PARENT: ---------->Tick START<--------------
CONSOLE DBG-2:2020-10-24,17:10:07 PARENT: RAW TEXT-->active_event_delete--TYPE--5--SPLIT--73913
CONSOLE DBG-2:2020-10-24,17:10:07 PARENT: Job: Deleting active_event eid:73913, mid:5
CONSOLE DBG-2:2020-10-24,17:10:07 PARENT: There are 0 active child forks...
CONSOLE INF:2020-10-24,17:10:07 PARENT: New event 73914 reported for Monitor:8 (Name:Street) Motion Street[last processed eid:]
10/24/20 17:10:07.558412 zmeventnotification[1195].INF [main:968] [PARENT: New event 73914 reported for Monitor:8 (Name:Street) Motion Street[last processed eid:]]
CONSOLE DBG-2:2020-10-24,17:10:07 PARENT: checkEvents() new events found=1
CONSOLE DBG-2:2020-10-24,17:10:07 PARENT: There are 1 new Events to process
CONSOLE DBG-2:2020-10-24,17:10:07 PARENT: ---------->Tick END<--------------
CONSOLE DBG-1:2020-10-24,17:10:07 PARENT: Forked process:1655 to handle alarm eid:73914
CONSOLE DBG-2:2020-10-24,17:10:07 |----> FORK:Street (8), eid:73914 Adding event path:/var/cache/zoneminder/events/8/2020-10-24/73914 to hook for image storage
CONSOLE DBG-1:2020-10-24,17:10:07 |----> FORK:Street (8), eid:73914 Invoking hook on event start:'/config/hook/zm_event_start.custom.sh' 73914 8 "Street" "Motion Street" "/var/cache/zoneminder/events/8/2020-10-24/73914"
CONSOLE DBG-2:2020-10-24,17:10:08 PARENT: ---------->Tick START<--------------
CONSOLE DBG-2:2020-10-24,17:10:08 PARENT: There are 1 active child forks...
CONSOLE DBG-2:2020-10-24,17:10:08 PARENT: We've already worked on Monitor:8, Event:73914, not doing anything more
CONSOLE DBG-2:2020-10-24,17:10:08 PARENT: checkEvents() new events found=0
CONSOLE DBG-2:2020-10-24,17:10:08 PARENT: There are 0 new Events to process
CONSOLE DBG-2:2020-10-24,17:10:08 PARENT: ---------->Tick END<--------------
CONSOLE DBG-2:2020-10-24,17:10:09 PARENT: ---------->Tick START<--------------
CONSOLE DBG-2:2020-10-24,17:10:09 PARENT: There are 1 active child forks...
CONSOLE DBG-2:2020-10-24,17:10:09 PARENT: We've already worked on Monitor:8, Event:73914, not doing anything more
CONSOLE DBG-2:2020-10-24,17:10:09 PARENT: checkEvents() new events found=0
CONSOLE DBG-2:2020-10-24,17:10:09 PARENT: There are 0 new Events to process
CONSOLE DBG-2:2020-10-24,17:10:09 PARENT: ---------->Tick END<--------------
CONSOLE DBG-2:2020-10-24,17:10:10 PARENT: ---------->Tick START<--------------
CONSOLE DBG-2:2020-10-24,17:10:10 PARENT: There are 1 active child forks...
CONSOLE DBG-2:2020-10-24,17:10:10 PARENT: We've already worked on Monitor:8, Event:73914, not doing anything more
CONSOLE DBG-2:2020-10-24,17:10:10 PARENT: checkEvents() new events found=0
CONSOLE DBG-2:2020-10-24,17:10:10 PARENT: There are 0 new Events to process
CONSOLE DBG-2:2020-10-24,17:10:10 PARENT: ---------->Tick END<--------------
CONSOLE DBG-2:2020-10-24,17:10:10 |----> FORK:Street (8), eid:73914 parse of hook:[a] detected:car:99%  and [{"type": "object", "label": "car", "box": [1006, 192, 1204, 280], "confidence": "98.80%"}]
CONSOLE DBG-1:2020-10-24,17:10:10 |----> FORK:Street (8), eid:73914 hook start returned with text:[a] detected:car:99%  json:[{"type": "object", "label": "car", "box": [1006, 192, 1204, 280], "confidence": "98.80%"}] exit:0
CONSOLE DBG-2:2020-10-24,17:10:11 PARENT: ---------->Tick START<--------------
CONSOLE DBG-2:2020-10-24,17:10:11 PARENT: RAW TEXT-->active_event_update--TYPE--8--SPLIT--73914--SPLIT--Start--SPLIT--Cause--SPLIT--[a] detected:car:99%  Motion Street--JSON--
CONSOLE DBG-2:2020-10-24,17:10:11 PARENT: Job: Update active_event eid:73914, mid:8, type:Start, field:Cause to: [a] detected:car:99%  Motion Street--JSON--
CONSOLE DBG-2:2020-10-24,17:10:11 PARENT: RAW TEXT-->event_description--TYPE--8--SPLIT--73914--SPLIT--[a] detected:car:99% 
CONSOLE DBG-2:2020-10-24,17:10:11 PARENT: Job: Update monitor 8 description:[a] detected:car:99% 
CONSOLE DBG-1:2020-10-24,17:10:11 PARENT: updating Notes clause for Event:73914 with:[a] detected:car:99%  
CONSOLE DBG-2:2020-10-24,17:10:11 PARENT: There are 1 active child forks...
CONSOLE DBG-2:2020-10-24,17:10:11 PARENT: We've already worked on Monitor:8, Event:73914, not doing anything more
CONSOLE DBG-2:2020-10-24,17:10:11 PARENT: checkEvents() new events found=0
CONSOLE DBG-2:2020-10-24,17:10:11 PARENT: There are 0 new Events to process
CONSOLE DBG-2:2020-10-24,17:10:11 PARENT: ---------->Tick END<--------------
CONSOLE DBG-2:2020-10-24,17:10:12 PARENT: ---------->Tick START<--------------
CONSOLE DBG-2:2020-10-24,17:10:12 PARENT: There are 1 active child forks...
CONSOLE DBG-2:2020-10-24,17:10:12 PARENT: We've already worked on Monitor:8, Event:73914, not doing anything more
CONSOLE DBG-2:2020-10-24,17:10:12 PARENT: checkEvents() new events found=0
CONSOLE DBG-2:2020-10-24,17:10:12 PARENT: There are 0 new Events to process
CONSOLE DBG-2:2020-10-24,17:10:12 PARENT: ---------->Tick END<--------------
CONSOLE DBG-2:2020-10-24,17:10:12 |----> FORK:Street (8), eid:73914 rules: Checking rules for alarm caused by eid:73914, monitor:8, at: Sat Oct 24 17:10:12 2020 with cause:[a] detected:car:99%  Motion Street
CONSOLE DBG-1:2020-10-24,17:10:12 |----> FORK:Street (8), eid:73914 rules: No rules found for Monitor, allowing:8
CONSOLE DBG-1:2020-10-24,17:10:12 |----> FORK:Street (8), eid:73914 Matching alarm to connection rules...
CONSOLE DBG-1:2020-10-24,17:10:12 |----> FORK:Street (8), eid:73914 Checking alarm conditions for token ending in:...qUKvS8tTMD
CONSOLE DBG-1:2020-10-24,17:10:12 |----> FORK:Street (8), eid:73914 should NOT send alarm as Monitor 8 is excluded
CONSOLE DBG-1:2020-10-24,17:10:12 |----> FORK:Street (8), eid:73914 Checking alarm conditions for token ending in:...HAUpkTFk_G
CONSOLE DBG-1:2020-10-24,17:10:12 |----> FORK:Street (8), eid:73914 Monitor 8 event: last time not found, so should send
CONSOLE DBG-1:2020-10-24,17:10:12 |----> FORK:Street (8), eid:73914 shouldSendEventToConn returned true, so calling sendEvent
CONSOLE DBG-2:2020-10-24,17:10:12 |----> FORK:Street (8), eid:73914 isAllowedChannel: got type:event_start resCode:0
CONSOLE INF:2020-10-24,17:10:12 |----> FORK:Street (8), eid:73914 Sending event_start notification over FCM
10/24/20 17:10:12.729501 zmeventnotification[1655].INF [main:968] [|----> FORK:Street (8), eid:73914 Sending event_start notification over FCM]
CONSOLE DBG-2:2020-10-24,17:10:12 |----> FORK:Street (8), eid:73914 fcmv1: Alarm frame matched, changing picture url to:https://home.cliffjao.com:8443/zm/index.php?view=image&eid=73914&fid=snapshot&width=600&username=admin&password=xxx 
CONSOLE DBG-2:2020-10-24,17:10:12 |----> FORK:Street (8), eid:73914 setting channel to zmninja
CONSOLE DBG-2:2020-10-24,17:10:12 |----> FORK:Street (8), eid:73914 fcmv1: Final JSON using FCMV1 being sent is: {"body":"[a] detected:car:99%  Motion Street at 05:10 PM, 24-Oct","token":"cea7K1LlRzey8vcO1fVQQp:APA91bEaW7RhZEUciqzB1utjTFzQxzKeSy8g4BjLqbsMxB32ayMy-A2INAfqqYH4vCBELcOeFVnr68SUeiTy87B2qCmn4YIImMeYN_jxzaXN4EhsZAXgON1MOEoeBRxxYqHAUpkTFk_G","sound":"default","data":{"mid":"8","eid":"73914","notification_foreground":"true"},"title":"Street Alarm (73914)","android":{"priority":"high","tag":"zmninjapush","channel":"zmninja","icon":"ic_stat_notification"},"image_url":"https://home.cliffjao.com:8443/zm/index.php?view=image&eid=73914&fid=snapshot&width=600&username=admin&password=xxx} to token: ...kTFk_G
CONSOLE DBG-1:2020-10-24,17:10:13 |----> FORK:Street (8), eid:73914 fcmv1: FCM push message returned a 200 with body {"Success":"projects/ninja-1105/messages/0:1603584612948368%311426be311426be"}

CONSOLE INF:2020-10-24,17:10:13 |----> FORK:Street (8), eid:73914 Event 73914 for Monitor 8 has finished
10/24/20 17:10:13.009007 zmeventnotification[1655].INF [main:968] [|----> FORK:Street (8), eid:73914 Event 73914 for Monitor 8 has finished]
CONSOLE DBG-2:2020-10-24,17:10:13 PARENT: ---------->Tick START<--------------
CONSOLE DBG-2:2020-10-24,17:10:13 PARENT: RAW TEXT-->fcm_notification--TYPE--cea7K1LlRzey8vcO1fVQQp:APA91bEaW7RhZEUciqzB1utjTFzQxzKeSy8g4BjLqbsMxB32ayMy-A2INAfqqYH4vCBELcOeFVnr68SUeiTy87B2qCmn4YIImMeYN_jxzaXN4EhsZAXgON1MOEoeBRxxYqHAUpkTFk_G--SPLIT--2--SPLIT--7--SPLIT--9
CONSOLE DBG-2:2020-10-24,17:10:13 PARENT: GOT JOB==> update badge to 2, count to 7 for: cea7K1LlRzey8vcO1fVQQp:APA91bEaW7RhZEUciqzB1utjTFzQxzKeSy8g4BjLqbsMxB32ayMy-A2INAfqqYH4vCBELcOeFVnr68SUeiTy87B2qCmn4YIImMeYN_jxzaXN4EhsZAXgON1MOEoeBRxxYqHAUpkTFk_G, at: 9
CONSOLE DBG-2:2020-10-24,17:10:13 PARENT: RAW TEXT-->timestamp--TYPE--1603584454.14629--SPLIT--8--SPLIT--1603584612.72909
CONSOLE DBG-2:2020-10-24,17:10:13 PARENT: Job: Update last sent timestamp of monitor:8 to 1603584612.72909 for id:1603584454.14629
CONSOLE DBG-2:2020-10-24,17:10:13 PARENT: There are 1 active child forks...
CONSOLE DBG-2:2020-10-24,17:10:13 PARENT: checkEvents() new events found=0
CONSOLE DBG-2:2020-10-24,17:10:13 PARENT: There are 0 new Events to process
CONSOLE DBG-2:2020-10-24,17:10:13 PARENT: ---------->Tick END<--------------
CONSOLE DBG-2:2020-10-24,17:10:14 PARENT: ---------->Tick START<--------------
CONSOLE DBG-2:2020-10-24,17:10:14 PARENT: There are 1 active child forks...
CONSOLE DBG-2:2020-10-24,17:10:14 PARENT: checkEvents() new events found=0
CONSOLE DBG-2:2020-10-24,17:10:14 PARENT: There are 0 new Events to process
CONSOLE DBG-2:2020-10-24,17:10:14 PARENT: ---------->Tick END<--------------
CONSOLE DBG-2:2020-10-24,17:10:15 |----> FORK:Street (8), eid:73914 DB Event notes contain detection text, all good
CONSOLE DBG-2:2020-10-24,17:10:15 |----> FORK:Street (8), eid:73914 Adding event path:/var/cache/zoneminder/events/8/2020-10-24/73914 to hook for image storage
CONSOLE DBG-1:2020-10-24,17:10:15 |----> FORK:Street (8), eid:73914 Invoking hook on event end:'/var/lib/zmeventnotification/bin/zm_event_end.sh' 73914 8 "Street" "[a] detected:car:99%  Motion: Street" "/var/cache/zoneminder/events/8/2020-10-24/73914"
CONSOLE DBG-2:2020-10-24,17:10:15 |----> FORK:Street (8), eid:73914 parse of hook:[a] detected:car:99%  Motion: Street and []
CONSOLE DBG-1:2020-10-24,17:10:15 |----> FORK:Street (8), eid:73914 hook end returned with text:[a] detected:car:99%  Motion: Street  json:[] exit:0
CONSOLE DBG-2:2020-10-24,17:10:15 PARENT: ---------->Tick START<--------------
CONSOLE DBG-2:2020-10-24,17:10:15 PARENT: There are 1 active child forks...
CONSOLE DBG-2:2020-10-24,17:10:15 PARENT: checkEvents() new events found=0
CONSOLE DBG-2:2020-10-24,17:10:15 PARENT: There are 0 new Events to process
CONSOLE DBG-2:2020-10-24,17:10:15 PARENT: ---------->Tick END<--------------
CONSOLE DBG-2:2020-10-24,17:10:16 PARENT: ---------->Tick START<--------------
CONSOLE DBG-2:2020-10-24,17:10:16 PARENT: There are 1 active child forks...
CONSOLE DBG-2:2020-10-24,17:10:16 PARENT: checkEvents() new events found=0
CONSOLE DBG-2:2020-10-24,17:10:16 PARENT: There are 0 new Events to process
CONSOLE DBG-2:2020-10-24,17:10:16 PARENT: ---------->Tick END<--------------
CONSOLE DBG-2:2020-10-24,17:10:17 |----> FORK:Street (8), eid:73914 rules: Checking rules for alarm caused by eid:73914, monitor:8, at: Sat Oct 24 17:10:17 2020 with cause:[a] detected:car:99%  Motion Street
CONSOLE DBG-1:2020-10-24,17:10:17 |----> FORK:Street (8), eid:73914 rules: No rules found for Monitor, allowing:8
CONSOLE DBG-1:2020-10-24,17:10:17 |----> FORK:Street (8), eid:73914 Matching alarm to connection rules...
CONSOLE DBG-1:2020-10-24,17:10:17 |----> FORK:Street (8), eid:73914 Skipping FCM notification as Monitor:Street(8) is excluded from zmNinja monitor list
CONSOLE INF:2020-10-24,17:10:17 |----> FORK:Street (8), eid:73914 Not sending event end notification as send_event_end_notification is no
10/24/20 17:10:17.019072 zmeventnotification[1655].INF [main:968] [|----> FORK:Street (8), eid:73914 Not sending event end notification as send_event_end_notification is no]
CONSOLE DBG-2:2020-10-24,17:10:17 PARENT: ---------->Tick START<--------------
CONSOLE DBG-2:2020-10-24,17:10:17 PARENT: There are 1 active child forks...
CONSOLE DBG-2:2020-10-24,17:10:17 PARENT: checkEvents() new events found=0
CONSOLE DBG-2:2020-10-24,17:10:17 PARENT: There are 0 new Events to process
CONSOLE DBG-2:2020-10-24,17:10:17 PARENT: ---------->Tick END<--------------
CONSOLE DBG-2:2020-10-24,17:10:18 PARENT: ---------->Tick START<--------------
CONSOLE DBG-2:2020-10-24,17:10:18 PARENT: There are 1 active child forks...
CONSOLE DBG-2:2020-10-24,17:10:18 PARENT: checkEvents() new events found=0
CONSOLE DBG-2:2020-10-24,17:10:18 PARENT: There are 0 new Events to process
CONSOLE DBG-2:2020-10-24,17:10:18 PARENT: ---------->Tick END<--------------
CONSOLE DBG-2:2020-10-24,17:10:19 PARENT: ---------->Tick START<--------------
CONSOLE DBG-2:2020-10-24,17:10:19 PARENT: There are 1 active child forks...
CONSOLE DBG-2:2020-10-24,17:10:19 PARENT: checkEvents() new events found=0
CONSOLE DBG-2:2020-10-24,17:10:19 PARENT: There are 0 new Events to process
CONSOLE DBG-2:2020-10-24,17:10:19 PARENT: ---------->Tick END<--------------
CONSOLE DBG-2:2020-10-24,17:10:20 PARENT: ---------->Tick START<--------------
CONSOLE DBG-2:2020-10-24,17:10:20 PARENT: There are 1 active child forks...
CONSOLE DBG-2:2020-10-24,17:10:20 PARENT: checkEvents() new events found=0
CONSOLE DBG-2:2020-10-24,17:10:20 PARENT: There are 0 new Events to process
CONSOLE DBG-2:2020-10-24,17:10:20 PARENT: ---------->Tick END<--------------
CONSOLE DBG-1:2020-10-24,17:10:21 |----> FORK:Street (8), eid:73914 exiting
CONSOLE DBG-1:2020-10-24,17:10:21 |----> FORK:Street (8), eid:73914 Ending process:1655 to handle alarms
CONSOLE DBG-2:2020-10-24,17:10:21 PARENT: ---------->Tick START<--------------
CONSOLE DBG-2:2020-10-24,17:10:21 PARENT: RAW TEXT-->active_event_delete--TYPE--8--SPLIT--73914
CONSOLE DBG-2:2020-10-24,17:10:21 PARENT: Job: Deleting active_event eid:73914, mid:8
CONSOLE DBG-2:2020-10-24,17:10:21 PARENT: There are 0 active child forks...
CONSOLE DBG-2:2020-10-24,17:10:21 PARENT: checkEvents() new events found=0
CONSOLE DBG-2:2020-10-24,17:10:21 PARENT: There are 0 new Events to process
CONSOLE DBG-2:2020-10-24,17:10:21 PARENT: ---------->Tick END<--------------

Note that I have 2 devices that both have the same set of monitors selected. Here is my tokens.txt file:

{"tokens":{"cea7K1LlRzey8vcO1fVQQp:APA91bEaW7RhZEUciqzB1utjTFzQxzKeSy8g4BjLqbsMxB32ayMy-A2INAfqqYH4vCBELcOeFVnr68SUeiTy87B2qCmn4YIImMeYN_jxzaXN4EhsZAXgON1MOEoeBRxxYqHAUpkTFk_G":{"invocations":{"at":"9","count":"7"},"monlist":"3,4,5,6,7","platform":"android","appversion":"1.6.000","intlist":"0,0,0,0,0","pushstate":"enabled"},"crYTuAjPQyI:APA91bGoudselQLNwWDXvTA2SNOP5XzwEd_UMvDlcg8UfzEdBxYqe1IsPCgIEzFTmnMYrwjX6AKMH6m1Zeum96k7jDj_3X4eVVi-fIuVz6lKsHjxqKxYaMzaJls5S555j3qUKvS8tTMD":{"pushstate":"enabled","invocations":{"count":"2","at":"9"},"monlist":"3,4,5,6,7","platform":"android","intlist":"0,0,0,0,0","appversion":"1.6.000"}}}

Both have the same monlist that excludes monitor 8. However, relevant lines in debug log above shows that it was excluded for 1 but not the other:

CONSOLE DBG-1:2020-10-24,17:10:12 |----> FORK:Street (8), eid:73914 Checking alarm conditions for token ending in:...qUKvS8tTMD
CONSOLE DBG-1:2020-10-24,17:10:12 |----> FORK:Street (8), eid:73914 should NOT send alarm as Monitor 8 is excluded
CONSOLE DBG-1:2020-10-24,17:10:12 |----> FORK:Street (8), eid:73914 Checking alarm conditions for token ending in:...HAUpkTFk_G
CONSOLE DBG-1:2020-10-24,17:10:12 |----> FORK:Street (8), eid:73914 Monitor 8 event: last time not found, so should send
CONSOLE DBG-1:2020-10-24,17:10:12 |----> FORK:Street (8), eid:73914 shouldSendEventToConn returned true, so calling sendEvent

[cliffjao]

I watched the logs as I loaded zmNinja on my phone and saw the following that looks suspicious:

CONSOLE DBG-2:2020-10-24,19:20:50 PARENT: ---------->onConnect START<--------------
CONSOLE DBG-1:2020-10-24,19:20:50 PARENT: got a websocket connection from 192.168.1.1 (2) active connections
CONSOLE DBG-2:2020-10-24,19:20:50 PARENT: ---------->onConnect STOP<--------------
CONSOLE DBG-2:2020-10-24,19:20:50 PARENT: ---------->onConnect:handshake START<--------------
CONSOLE DBG-1:2020-10-24,19:20:50 PARENT: Websockets: New Connection Handshake requested from 192.168.1.1:46334 state=pending auth, id=1603592450.41553
CONSOLE DBG-2:2020-10-24,19:20:50 PARENT: ---------->onConnect:handshake END<--------------
CONSOLE DBG-2:2020-10-24,19:20:50 PARENT: ---------->onConnect msg START<--------------
CONSOLE DBG-2:2020-10-24,19:20:50 PARENT: Comparing using bcrypt $2a$10$qKn.d9Qc1cdXAX0x0fwvVOmtapWfuhzxu/hnJNyoNa4Kqk2Bq.dgS to $2a$10$qKn.d9Qc1cdXAX0x0fwvVOmtapWfuhzxu/hnJNyoNa4Kqk2Bq.dgS
CONSOLE INF:2020-10-24,19:20:50 PARENT: Correct authentication provided by 192.168.1.1
CONSOLE DBG-2:2020-10-24,19:20:50 PARENT: ---------->onConnect msg STOP<--------------
CONSOLE DBG-2:2020-10-24,19:20:50 PARENT: ---------->onConnect msg START<--------------
CONSOLE DBG-2:2020-10-24,19:20:50 PARENT: JOB: token matched but connection did not
CONSOLE DBG-1:2020-10-24,19:20:50 PARENT: JOB: Duplicate token found: marking ...HAUpkTFk_G to be deleted
CONSOLE DBG-2:2020-10-24,19:20:50 PARENT: JOB: connection matched but token did not. first registration?
CONSOLE DBG-1:2020-10-24,19:20:50 PARENT: JOB: Storing token ...HAUpkTFk_G,monlist:-1,intlist:-1,pushstate:enabled

CONSOLE DBG-2:2020-10-24,19:20:50 PARENT: SaveTokens called with:monlist=-1, intlist=-1, platform=android, push=enabled
CONSOLE DBG-2:2020-10-24,19:20:50 PARENT: ---------->onConnect msg STOP<--------------

As best I can tell, it works initially but at some point onConnect happens and the monlist gets nuked. This explains why I thought it was originally fixed.

[pliablepixels]

Could you try with the latest master and post logs?

[cliffjao]

So far so good after a few hours, but I haven't seen the onConnect function run yet either. I'm not sure what causes that to happen. I'll keep this running with logs for a day or so and report back.

[pliablepixels]

I think it happens if you start zmNinja.

[cliffjao]

That doesn't seem to be the case every time for some reason. I've tried Force Stop and then starting zmNinja, and I've also rebooted my phone and then starting. Both didn't trigger onConnect.

[pliablepixels]

onConnect triggers every time zmNinja makes a websocket connection to the ES (when it first starts). If you are not seeing onConnect in ES when zmNinja first starts, zmNinja can't reach the ES via port 9000 or the ES is disabled in zmN

[cliffjao]

Interesting. For some reason, zmeventnotification.pl from master doesn't actually listen on port 9000 despite no error messages suggesting otherwise:

CONSOLE DBG-2:2020-10-25,11:43:36 PARENT: About to start listening to socket
CONSOLE INF:2020-10-25,11:43:36 PARENT: Secure WS(WSS) is enabled...
10/25/20 11:43:36.909780 zmeventnotification[1077].INF [main:968] [PARENT: Secure WS(WSS) is enabled...]
CONSOLE INF:2020-10-25,11:43:36 PARENT: Web Socket Event Server listening on port 9000
10/25/20 11:43:36.911392 zmeventnotification[1077].INF [main:968] [PARENT: Web Socket Event Server listening on port 9000]
CONSOLE DBG-2:2020-10-25,11:43:37 PARENT: ---------->Tick START<--------------
CONSOLE DBG-2:2020-10-25,11:43:37 PARENT: There are 0 active child forks...
CONSOLE DBG-2:2020-10-25,11:43:37 PARENT: checkEvents() new events found=0
CONSOLE DBG-2:2020-10-25,11:43:37 PARENT: There are 0 new Events to process
CONSOLE DBG-2:2020-10-25,11:43:37 PARENT: ---------->Tick END<--------------

cjao@cjao-mbp ~ % telnet eagle 9000
Trying 192.168.1.190...
telnet: connect to address 192.168.1.190: Connection refused
telnet: Unable to connect to remote host

Running the original zmeventnotification.pl from dlandon/zoneminder docker container (6.0.5) results in port 9000 opening fine:

cjao@cjao-mbp ~ % telnet eagle 9000
Trying 192.168.1.190...
Connected to eagle.cliffjao.com.
Escape character is '^]'.

[pliablepixels]

Yes, master does listen on 9000. I am running it. You probably have other processes listening on 9000, or have configured a different port in your master zmeventnotification.ini

[cliffjao]

This change on zmeventnotification.pl seems to make the difference for me:

107c107
<   DEFAULT_ADDRESS            => '0.0.0.0',
---
>   DEFAULT_ADDRESS            => '[::]',

With this change, it connects and results in the following:

CONSOLE DBG-2:2020-10-25,12:22:43 PARENT: ---------->onConnect START<--------------
CONSOLE DBG-1:2020-10-25,12:22:43 PARENT: got a websocket connection from 192.168.1.1 (2) active connections
CONSOLE DBG-2:2020-10-25,12:22:43 PARENT: ---------->onConnect STOP<--------------
CONSOLE DBG-2:2020-10-25,12:22:43 PARENT: ---------->onConnect:handshake START<--------------
CONSOLE DBG-1:2020-10-25,12:22:43 PARENT: Websockets: New Connection Handshake requested from 192.168.1.1:37014 state=pending auth, id=1603653763.03107
CONSOLE DBG-2:2020-10-25,12:22:43 PARENT: ---------->onConnect:handshake END<--------------
CONSOLE DBG-2:2020-10-25,12:22:43 PARENT: ---------->onConnect msg START<--------------
CONSOLE DBG-2:2020-10-25,12:22:43 PARENT: Comparing using bcrypt
CONSOLE INF:2020-10-25,12:22:43 PARENT: Correct authentication provided by 192.168.1.1
10/25/20 12:22:43.130452 zmeventnotification[1532].INF [main:972] [PARENT: Correct authentication provided by 192.168.1.1]
CONSOLE DBG-2:2020-10-25,12:22:43 PARENT: ---------->onConnect msg STOP<--------------
CONSOLE DBG-2:2020-10-25,12:22:43 PARENT: ---------->onConnect msg START<--------------
CONSOLE DBG-2:2020-10-25,12:22:43 PARENT: JOB: new token matched existing token: (HAUpkTFk_G <==> HAUpkTFk_G) but connection did not (192.168.1.1:37014 <==> undefined)
CONSOLE DBG-1:2020-10-25,12:22:43 PARENT: JOB: Duplicate token found: marking ...HAUpkTFk_G to be deleted
CONSOLE DBG-2:2020-10-25,12:22:43 PARENT: JOB: connection matched (192.168.1.1:37014 <==> 192.168.1.1:37014) but token did not (HAUpkTFk_G <==> ). first registration?
CONSOLE DBG-1:2020-10-25,12:22:43 PARENT: JOB: Storing token ...HAUpkTFk_G,monlist:3,4,5,6,7,intlist:0,0,0,0,0,pushstate:enabled

CONSOLE DBG-2:2020-10-25,12:22:43 PARENT: SaveTokens called with:monlist=3,4,5,6,7, intlist=0,0,0,0,0, platform=android, push=enabled
CONSOLE DBG-2:2020-10-25,12:22:43 PARENT: ---------->onConnect msg STOP<--------------

[pliablepixels]

You can change the ip in the config instead of code. https://github.com/pliablepixels/zmeventnotification/blob/59f2368a8e910a201fcb5eed77ce9f55fd92f110/zmeventnotification.ini#L42

The logs look good to me.

[cliffjao]

And after that onConnect, here's some output from the monitor I was having problems with:

CONSOLE DBG-2:2020-10-25,12:31:20 |----> FORK:Street (8), eid:74261 rules: Checking rules for alarm caused by eid:74261, monitor:8, at: Sun Oct 25 12:31:20 2020 with cause:[a] detected:dog:71
%  Motion Street                                                                                                                                                                               
CONSOLE DBG-1:2020-10-25,12:31:20 |----> FORK:Street (8), eid:74261 rules: No rules found for Monitor, allowing:8                                                                              
CONSOLE DBG-1:2020-10-25,12:31:20 |----> FORK:Street (8), eid:74261 Matching alarm to connection rules...                                                                                      
CONSOLE DBG-1:2020-10-25,12:31:20 |----> FORK:Street (8), eid:74261 Checking alarm conditions for token ending in:...qUKvS8tTMD                                                                
CONSOLE DBG-1:2020-10-25,12:31:20 |----> FORK:Street (8), eid:74261 should NOT send alarm as Monitor 8 is excluded                                                                             
CONSOLE DBG-1:2020-10-25,12:31:20 |----> FORK:Street (8), eid:74261 Checking alarm conditions for token ending in:...HAUpkTFk_G                                                                
CONSOLE DBG-1:2020-10-25,12:31:20 |----> FORK:Street (8), eid:74261 should NOT send alarm as Monitor 8 is excluded
CONSOLE INF:2020-10-25,12:31:20 |----> FORK:Street (8), eid:74261 Event 74261 for Monitor 8 has finished

It appears that both of my tokens properly registered as excluded, which is great.

I'll keep this setup running for the rest of the day and report back.

[cliffjao]

Seems to have been good all day. Thanks for the fix!