ZoneMinder / zmeventnotification

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

FCMv1: FCM push message Error:500 Internal Server Error #314

Closed hgregorian closed 4 years ago

hgregorian commented 4 years ago

Event Server version

6.0.1

Hooks version

n/a (not using)

The version of ZoneMinder you are using:

1.34.21

What is the nature of your issue

Bug

Details

Using a fresh 6.0.1 configuration, when FCMv1 is enabled (use_fcmv1 = yes), no push notifications are sent. Log states:

FCM push message Error:500 Internal Server Error

Setting use_fcmv1 = no allows for push notifications to be sent and subsequently received.

Debug Logs (if applicable)

2020-10-15 13:12:50 | zmeventnotification |   | 1122 | INF | \|----> FORK:Side Entrance (8), eid:618275 Not sending event end notification as send_event_end_notification is no | zmeventnotification.pl |  
-- | -- | -- | -- | -- | -- | -- | --
2020-10-15 13:12:50 | zmeventnotification |   | 1122 | INF | \|----> FORK:Side Entrance (8), eid:618275 Not sending event end notification as send_event_end_notification is no | zmeventnotification.pl |  
2020-10-15 13:12:48 | zmeventnotification |   | 1122 | INF | \|----> FORK:Side Entrance (8), eid:618275 end hooks/use hooks not being used, going to directly send out a notification if checks pass | zmeventnotification.pl |  
2020-10-15 13:12:46 | zmeventnotification |   | 1122 | INF | \|----> FORK:Side Entrance (8), eid:618275 Event 618275 for Monitor 8 has finished | zmeventnotification.pl |  
2020-10-15 13:12:38 | zmeventnotification |   | 1122 | ERR | \|----> FORK:Side Entrance (8), eid:618275 fcmv1: FCM push message Error:500 Internal Server Error | zmeventnotification.pl |  
2020-10-15 13:12:37 | zmeventnotification |   | 1122 | INF | \|----> FORK:Side Entrance (8), eid:618275 Sending event_start notification for EID:618275 over MQTT | zmeventnotification.pl |  
2020-10-15 13:12:37 | zmeventnotification |   | 1122 | INF | \|----> FORK:Side Entrance (8), eid:618275 Sending event_start notification over FCM | zmeventnotification.pl |  
2020-10-15 13:12:35 | zmeventnotification |   | 397 | INF | PARENT: New event 618275 reported for Monitor:8 (Name:Side Entrance) Motion Driveway[last processed eid:618273] | zmeventnotification.pl |  
2020-10-15 13:12:35 | zmeventnotification |   | 1122 | INF | \|----> FORK:Side Entrance (8), eid:618275 use hooks/start hook not being used, going to directly send out a notification if checks pass | zmeventnotification.pl |  
2020-10-15 13:12:15 | zmeventnotification |   | 397 | INF | PARENT: Correct authentication provided by 192.168.1.1 | zmeventnotification.pl |  
2020-10-15 13:11:50 | zmeventnotification |   | 642 | INF | \|----> FORK:Side Entrance (8), eid:618273 Not sending event end notification as send_event_end_notification is no | zmeventnotification.pl |  
2020-10-15 13:11:48 | zmeventnotification |   | 642 | INF | \|----> FORK:Side Entrance (8), eid:618273 end hooks/use hooks not being used, going to directly send out a notification if checks pass | zmeventnotification.pl |  
2020-10-15 13:11:46 | zmeventnotification |   | 642 | INF | \|----> FORK:Side Entrance (8), eid:618273 Event 618273 for Monitor 8 has finished | zmeventnotification.pl |  
2020-10-15 13:11:32 | zmeventnotification |   | 642 | INF | \|----> FORK:Side Entrance (8), eid:618273 Sending event_start notification for EID:618273 over MQTT | zmeventnotification.pl |  
2020-10-15 13:11:30 | zmeventnotification |   | 642 | INF | \|----> FORK:Side Entrance (8), eid:618273 use hooks/start hook not being used, going to directly send out a notification if checks pass | zmeventnotification.pl |  
2020-10-15 13:11:30 | zmeventnotification |   | 397 | INF | PARENT: New event 618273 reported for Monitor:8 (Name:Side Entrance) Motion Driveway[last processed eid:] | zmeventnotification.pl |  
2020-10-15 13:10:50 | zmeventnotification |   | 397 | INF | PARENT: Web Socket Event Server listening on port 9000 | zmeventnotification.pl |  
2020-10-15 13:10:50 | zmeventnotification |   | 397 | INF | PARENT: Secure WS(WSS) is enabled... | zmeventnotification.pl |  
2020-10-15 13:10:50 | zmeventnotification |   | 397 | INF | PARENT: Re-loading monitors | zmeventnotification.pl |  
2020-10-15 13:10:50 | zmeventnotification |   | 397 | INF | PARENT: Initializing MQTT with auth connection... | zmeventnotification.pl |  
2020-10-15 13:10:50 | zmeventnotification |   | 397 | INF | PARENT: Event Notification daemon v 6.0.1 starting | zmeventnotification.pl |  
2020-10-15 13:10:50 | zmeventnotification |   | 397 | INF | PARENT: \|------- Starting ES version: 6.0.1 ---------\| | zmeventnotification.pl |  
2020-10-15 13:10:50 | zmeventnotification |   | 397 | INF | PARENT: MQTT Enabled | zmeventnotification.pl |  
2020-10-15 13:10:50 | zmeventnotification |   | 397 | INF | PARENT: Push enabled via FCM | zmeventnotification.pl |  
2020-10-15 13:10:50 | zmeventnotification |   | 397 | INF | PARENT: using secrets file: /etc/zm/secrets.ini | zmeventnotification.pl |  
2020-10-15 13:10:50 | zmeventnotification |   | 397 | INF | PARENT: using config file: /etc/zm/zmeventnotification.ini | zmeventnotification.pl

Thanks!

pliablepixels commented 4 years ago

Make sure you are on zmNinja 1.6 also, please post debug logs around the 500 error from the ES

hgregorian commented 4 years ago

Yes, I'm on zmNinja 1.6 (which is what prompted me to go to 6.0.1). Sorry, how am I getting the debug logs? I've set the es_debug_level param to 9, but that's all I see in the console.

pliablepixels commented 4 years ago

https://zmeventnotification.readthedocs.io/en/latest/guides/es_faq.html#es-hooks-logging

You won't see debug logs on console. It will be in /var/lib/zm/zmeventnotification.log

hgregorian commented 4 years ago

When I follow that setup (which doesn't reference anything about zmeventnotification.ini, i.e. console_logs, es_debug_level), /var/log/zm/zmeventnotification.log is no longer present. With that said however, it does appear that /var/log/zm/zm_debug.log.* contains zmeventnotification messages.

10/15/20 16:17:52.111898 zmeventnotification[944].DBG [main:943] [PARENT: Forked process:944 to handle alarm eid:618461]
10/15/20 16:17:52.112572 zmeventnotification[944].INF [main:952] [|----> FORK:Side Entrance (8), eid:618461 use hooks/start hook not being used, going to directly send out a notification if checks pass]
10/15/20 16:17:52.115005 zmeventnotification[944].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140544598839296 for 8]
10/15/20 16:17:52.115250 zmeventnotification[944].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 8: 1]
10/15/20 16:17:54.116050 zmeventnotification[944].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618461 rules: Checking rules for alarm caused by eid:618461, monitor:8, at: Thu Oct 15 16:17:54 2020 with cause:Motion Driveway]
10/15/20 16:17:54.116181 zmeventnotification[944].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618461 rules: No rules found for Monitor, allowing:8]
10/15/20 16:17:54.116307 zmeventnotification[944].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618461 Matching alarm to connection rules...]
10/15/20 16:17:54.116451 zmeventnotification[944].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618461 Checking alarm conditions for MQTT 192.168.1.20]
10/15/20 16:17:54.116600 zmeventnotification[944].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618461 Monitor 8 event: should send out as  59.8813099861145 is >= interval of ]
10/15/20 16:17:54.116642 zmeventnotification[944].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618461 shouldSendEventToConn returned true, so calling sendEvent]
10/15/20 16:17:54.117358 zmeventnotification[944].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618461 isAllowedChannel: got type:event_start resCode:0]
10/15/20 16:17:54.117655 zmeventnotification[944].INF [main:952] [|----> FORK:Side Entrance (8), eid:618461 Sending event_start notification for EID:618461 over MQTT]
10/15/20 16:17:54.120663 zmeventnotification[944].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618461 requesting MQTT Publishing Job for EID:618461]
10/15/20 16:17:54.120795 zmeventnotification[944].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618461 Checking alarm conditions for token ending in:...pIP0Zm_kkc]
10/15/20 16:17:54.120866 zmeventnotification[944].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618461 Monitor 8 event: last time not found, so should send]
10/15/20 16:17:54.120921 zmeventnotification[944].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618461 shouldSendEventToConn returned true, so calling sendEvent]
10/15/20 16:17:54.121144 zmeventnotification[944].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618461 isAllowedChannel: got type:event_start resCode:0]
10/15/20 16:17:54.121356 zmeventnotification[944].INF [main:952] [|----> FORK:Side Entrance (8), eid:618461 Sending event_start notification over FCM]
10/15/20 16:17:54.123727 zmeventnotification[944].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618461 fcmv1: FCM called when there is no start hook/or hooks are disabled, so making sure we do not use objdetect in url]
10/15/20 16:17:54.124276 zmeventnotification[944].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618461 setting channel to zmninja]
10/15/20 16:17:54.124571 zmeventnotification[944].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618461 fcmv1: Final JSON using FCMV1 being sent is: {"token":"en3OYrrIa1M:APA91bGqL_nw0K2OfOGKJqEwfbBWGi7zAlrSXBmf-anMBBbi-xhOzJUyB6KwW3IXDmeCc54dLrzpl-j_ROmmnGlhfdYgTw4aktZkk4_KB1JH5EdwqP89bmmP7NIbY6EMS8pIP0Zm_kkc","data":{"eid":618461,"mid":8,"notification_foreground":"true"},"sound":"default","android":{"channel":"zmninja"},"ios":{"thread_id":"zmninja_alarm","headers":{"apns-priority":"10","apns-push-type":"alert"}},"body":"Motion Driveway at 04:17 PM, 15-Oct","title":"Side Entrance Alarm (618461)","badge":2} to token: ...Zm_kkc]
10/15/20 16:17:54.510819 zmeventnotification[944].ERR [main:968] [|----> FORK:Side Entrance (8), eid:618461 fcmv1: FCM push message Error:500 Internal Server Error]
10/15/20 16:17:54.514137 zmeventnotification[944].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140544598839296 for 8]
10/15/20 16:17:54.514352 zmeventnotification[944].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 8: 1]
10/15/20 16:17:56.514618 zmeventnotification[944].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140544598839296 for 8]
10/15/20 16:17:56.514842 zmeventnotification[944].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 8: 1]
pliablepixels commented 4 years ago

There is something off. Why does the message have both android and iOS? Can you check what tokens.txt contains for this token? What happens if you stop the ES, delete tokens.txt, restart ES and then run zmNinja? Does push work after that?

hgregorian commented 4 years ago

Wiped it, restarted, let a few events pass, here's tokens.txt

$ cat /var/lib/zmeventnotification/push/tokens.txt 
{"tokens":{"en3OYrrIa1M:APA91bGqL_nw0K2OfOGKJqEwfbBWGi7zAlrSXBmf-anMBBbi-xhOzJUyB6KwW3IXDmeCc54dLrzpl-j_ROmmnGlhfdYgTw4aktZkk4_KB1JH5EdwqP89bmmP7NIbY6EMS8pIP0Zm_kkc":{"platform":"ios","appversion":"1.6.000","invocations":{"at":"9","count":"7"},"pushstate":"enabled"}}}

And here are the 500's in the log:

grep '500 Internal' /var/log/zm/zm_debug.log.413 
10/15/20 17:45:06.442805 zmeventnotification[2994].ERR [main:968] [|----> FORK:Side Entrance (8), eid:618582 fcmv1: FCM push message Error:500 Internal Server Error]
10/15/20 17:45:30.601017 zmeventnotification[3136].ERR [main:968] [|----> FORK:Side Entrance (8), eid:618584 fcmv1: FCM push message Error:500 Internal Server Error]
10/15/20 17:47:01.411524 zmeventnotification[3639].ERR [main:968] [|----> FORK:Side Entrance (8), eid:618588 fcmv1: FCM push message Error:500 Internal Server Error]
10/15/20 17:47:01.450282 zmeventnotification[3640].ERR [main:968] [|----> FORK:Street / Driveway (20), eid:618586 fcmv1: FCM push message Error:500 Internal Server Error]
10/15/20 17:47:41.409142 zmeventnotification[3962].ERR [main:968] [|----> FORK:Side Entrance (8), eid:618594 fcmv1: FCM push message Error:500 Internal Server Error]
10/15/20 17:47:41.424301 zmeventnotification[3963].ERR [main:968] [|----> FORK:Street / Driveway (20), eid:618591 fcmv1: FCM push message Error:500 Internal Server Error]
10/15/20 17:47:49.061692 zmeventnotification[3975].ERR [main:968] [|----> FORK:Front Door (hi-res) (22), eid:618593 fcmv1: FCM push message Error:500 Internal Server Error]

All JSON looks similar to this:

10/15/20 17:47:41.157413 zmeventnotification[3962].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618594 fcmv1: Final JSON using FCMV1 being sent is: {"badge":6,"title":"Side Entrance Alarm (618594)","body":"Motion Street at 05:47 PM, 15-Oct","sound":"default","data":{"eid":618594,"notification_foreground":"true","mid":8},"android":{"channel":"zmninja"},"ios":{"headers":{"apns-push-type":"alert","apns-priority":"10"},"thread_id":"zmninja_alarm"},"token":"en3OYrrIa1M:APA91bGqL_nw0K2OfOGKJqEwfbBWGi7zAlrSXBmf-anMBBbi-xhOzJUyB6KwW3IXDmeCc54dLrzpl-j_ROmmnGlhfdYgTw4aktZkk4_KB1JH5EdwqP89bmmP7NIbY6EMS8pIP0Zm_kkc"} to token: ...Zm_kkc]

Also note, I don't have any android devices connecting via zmNinja.

lainy commented 4 years ago

I have also been experiencing this exact issue, except for me push notifications sometimes succeed. It has been going on since I upgraded to ES 6.0.1 yesterday.

Before finding this thread I had also already stopped ES, wiped out tokens.txt, and restarted ES and run zmNinja multiple times with no success.

zmNinja version 1.6 (Android) ES version 6.0.1 ZoneMinder version 1.34.21 (Arch Linux)

Enabled debug logging according to https://github.com/pliablepixels/zmeventnotification/issues/314#issuecomment-709617153 and restarted zoneminder.

After forcing an alarm on one of our cameras, I got a 500 error. Here's the relevant portion of /var/log/zoneminder/zm_debug.log.305670:

10/15/2020 19:23:06.787726 zmeventnotification[306002].DBG [main:943] [|----> FORK:Frontyard (1), eid:1346659 rules: Checking rules for alarm caused by eid:1346659, monitor:1, at: Thu Oct 15 19:23:06 2020 with cause:Forced Web: ]
10/15/2020 19:23:06.787788 zmeventnotification[306002].DBG [main:943] [|----> FORK:Frontyard (1), eid:1346659 rules: No rules found for Monitor, allowing:1]
10/15/2020 19:23:06.787838 zmeventnotification[306002].DBG [main:943] [|----> FORK:Frontyard (1), eid:1346659 Matching alarm to connection rules...]
10/15/2020 19:23:06.787909 zmeventnotification[306002].DBG [main:943] [|----> FORK:Frontyard (1), eid:1346659 Checking alarm conditions for token ending in:...VtkKhQOIOv]
10/15/2020 19:23:06.787997 zmeventnotification[306002].DBG [main:943] [|----> FORK:Frontyard (1), eid:1346659 Monitor 1 event: last time not found, so should send]
10/15/2020 19:23:06.788016 zmeventnotification[306002].DBG [main:943] [|----> FORK:Frontyard (1), eid:1346659 shouldSendEventToConn returned true, so calling sendEvent]
10/15/2020 19:23:06.788090 zmeventnotification[306002].DBG [main:943] [|----> FORK:Frontyard (1), eid:1346659 isAllowedChannel: got type:event_start resCode:1]
10/15/2020 19:23:06.788194 zmeventnotification[306002].INF [main:952] [|----> FORK:Frontyard (1), eid:1346659 Sending event_start notification over FCM]
10/15/2020 19:23:06.811798 zmeventnotification[306002].DBG [main:943] [|----> FORK:Frontyard (1), eid:1346659 fcmv1: FCM called when hook failed, so making sure we do not use objdetect in url]
10/15/2020 19:23:06.812179 zmeventnotification[306002].DBG [main:943] [|----> FORK:Frontyard (1), eid:1346659 setting channel to zmninja]
10/15/2020 19:23:06.812353 zmeventnotification[306002].DBG [main:943] [|----> FORK:Frontyard (1), eid:1346659 fcmv1: Final JSON using FCMV1 being sent is: {"badge":1,"image_url":"http://10.20.0.201:8095/index.php?view=image&eid=1346659&fid=snapshot&width=600&username=zmuser&password=xxx},"sound":"default","title":"Frontyard Alarm (1346659)","data":{"notification_foreground":"true","mid":"1","eid":"1346659"},"token":"REDACTED","body":"Forced Web at 07:23 PM, 15-Oct"} to token: ...hQOIOv]
10/15/2020 19:23:07.083153 zmeventnotification[306002].ERR [main:968] [|----> FORK:Frontyard (1), eid:1346659 fcmv1: FCM push message Error:500 Internal Server Error]
10/15/2020 19:23:07.105637 zmeventnotification[306002].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139841768689664 for 1]
10/15/2020 19:23:07.105775 zmeventnotification[306002].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 1: 1]
10/15/2020 19:23:09.106392 zmeventnotification[306002].DBG [main:943] [|----> FORK:Frontyard (1), eid:1346659 Adding event path:/data/zoneminder/events/1/2020-10-15/1346659 to hook for image storage]
10/15/2020 19:23:09.106454 zmeventnotification[306002].DBG [main:943] [|----> FORK:Frontyard (1), eid:1346659 Invoking hook on event end:'/var/lib/zmeventnotification/bin/zm_event_end.sh' 1346659 1 "Frontyard" "Forced Web: " "/data/zoneminder/events/1/2020-10-15/1346659"]
10/15/2020 19:23:09.115939 zmeventnotification[306002].DBG [main:943] [|----> FORK:Frontyard (1), eid:1346659 parse of hook:Forced Web:  and []]
10/15/2020 19:23:09.116068 zmeventnotification[306002].DBG [main:943] [|----> FORK:Frontyard (1), eid:1346659 hook end returned with text:Forced Web:   json:[] exit:0]
10/15/2020 19:23:09.116158 zmeventnotification[306002].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139841768689664 for 1]
10/15/2020 19:23:09.116286 zmeventnotification[306002].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 1: 1]
pliablepixels commented 4 years ago

Are the pushes being delivered now?

hgregorian commented 4 years ago

Yes!

10/16/20 08:53:59.141403 zmeventnotification[15179].DBG [main:943] [PARENT: Forked process:15179 to handle alarm eid:618981]
10/16/20 08:53:59.141880 zmeventnotification[15179].INF [main:952] [|----> FORK:Side Entrance (8), eid:618981 use hooks/start hook not being used, going to directly send out a notification if checks pass]
10/16/20 08:53:59.144509 zmeventnotification[15179].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139874871111680 for 8]
10/16/20 08:53:59.144693 zmeventnotification[15179].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 8: 1]
10/16/20 08:54:01.145361 zmeventnotification[15179].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618981 rules: Checking rules for alarm caused by eid:618981, monitor:8, at: Fri Oct 16 08:54:01 2020 with cause:Motion Street]
10/16/20 08:54:01.145491 zmeventnotification[15179].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618981 rules: No rules found for Monitor, allowing:8]
10/16/20 08:54:01.145610 zmeventnotification[15179].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618981 Matching alarm to connection rules...]
10/16/20 08:54:01.145770 zmeventnotification[15179].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618981 Checking alarm conditions for MQTT 192.168.1.20]
10/16/20 08:54:01.145954 zmeventnotification[15179].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618981 Monitor 8 event: should send out as  24.8519198894501 is >= interval of ]
10/16/20 08:54:01.145994 zmeventnotification[15179].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618981 shouldSendEventToConn returned true, so calling sendEvent]
10/16/20 08:54:01.146868 zmeventnotification[15179].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618981 isAllowedChannel: got type:event_start resCode:0]
10/16/20 08:54:01.147139 zmeventnotification[15179].INF [main:952] [|----> FORK:Side Entrance (8), eid:618981 Sending event_start notification for EID:618981 over MQTT]
10/16/20 08:54:01.150537 zmeventnotification[15179].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618981 requesting MQTT Publishing Job for EID:618981]
10/16/20 08:54:01.150720 zmeventnotification[15179].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618981 Checking alarm conditions for token ending in:...pIP0Zm_kkc]
10/16/20 08:54:01.150869 zmeventnotification[15179].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618981 Monitor 8 event: should send out as  24.8481199741364 is >= interval of -1]
10/16/20 08:54:01.150947 zmeventnotification[15179].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618981 shouldSendEventToConn returned true, so calling sendEvent]
10/16/20 08:54:01.151197 zmeventnotification[15179].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618981 isAllowedChannel: got type:event_start resCode:0]
10/16/20 08:54:01.151470 zmeventnotification[15179].INF [main:952] [|----> FORK:Side Entrance (8), eid:618981 Sending event_start notification over FCM]
10/16/20 08:54:01.154379 zmeventnotification[15179].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618981 fcmv1: FCM called when there is no start hook/or hooks are disabled, so making sure we do not use objdetect in url]
10/16/20 08:54:01.154882 zmeventnotification[15179].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618981 setting channel to zmninja]
10/16/20 08:54:01.155238 zmeventnotification[15179].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618981 fcmv1: Final JSON using FCMV1 being sent is: {"data":{"mid":8,"eid":618981,"notification_foreground":"true"},"android":{"channel":"zmninja"},"token":"en3OYrrIa1M:APA91bGqL_nw0K2OfOGKJqEwfbBWGi7zAlrSXBmf-anMBBbi-xhOzJUyB6KwW3IXDmeCc54dLrzpl-j_ROmmnGlhfdYgTw4aktZkk4_KB1JH5EdwqP89bmmP7NIbY6EMS8pIP0Zm_kkc","ios":{"thread_id":"zmninja_alarm","headers":{"apns-push-type":"alert","apns-priority":"10"}},"title":"Side Entrance Alarm (618981)","badge":3,"sound":"default","body":"Motion Street at 08:54 AM, 16-Oct"} to token: ...Zm_kkc]
10/16/20 08:54:01.711717 zmeventnotification[15179].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618981 fcmv1: FCM push message returned a 200 with body {"Success":"projects/ninja-1105/messages/1602863641494594"}]
10/16/20 08:54:01.712289 zmeventnotification[15179].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139874871111680 for 8]
10/16/20 08:54:01.712421 zmeventnotification[15179].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 8: 1]
10/16/20 08:54:03.712675 zmeventnotification[15179].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139874871111680 for 8]
10/16/20 08:54:03.712885 zmeventnotification[15179].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 8: 1]
10/16/20 08:54:05.713143 zmeventnotification[15179].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139874871111680 for 8]
10/16/20 08:54:05.713366 zmeventnotification[15179].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 8: 1]
10/16/20 08:54:07.713583 zmeventnotification[15179].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139874871111680 for 8]
10/16/20 08:54:07.713804 zmeventnotification[15179].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 8: 1]
10/16/20 08:54:07.714117 zmeventnotification[15179].INF [main:952] [|----> FORK:Side Entrance (8), eid:618981 Event 618981 for Monitor 8 has finished]
10/16/20 08:54:09.718697 zmeventnotification[15179].INF [main:952] [|----> FORK:Side Entrance (8), eid:618981 end hooks/use hooks not being used, going to directly send out a notification if checks pass]
10/16/20 08:54:09.720931 zmeventnotification[15179].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139874871111680 for 8]
10/16/20 08:54:09.721062 zmeventnotification[15179].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 8: 1]
10/16/20 08:54:11.721430 zmeventnotification[15179].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618981 rules: Checking rules for alarm caused by eid:618981, monitor:8, at: Fri Oct 16 08:54:11 2020 with cause:Motion: Street]
10/16/20 08:54:11.721514 zmeventnotification[15179].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618981 rules: No rules found for Monitor, allowing:8]
10/16/20 08:54:11.721575 zmeventnotification[15179].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618981 Matching alarm to connection rules...]
10/16/20 08:54:11.721804 zmeventnotification[15179].INF [main:952] [|----> FORK:Side Entrance (8), eid:618981 Not sending event end notification as send_event_end_notification is no]
10/16/20 08:54:11.724740 zmeventnotification[15179].INF [main:952] [|----> FORK:Side Entrance (8), eid:618981 Not sending event end notification as send_event_end_notification is no]
10/16/20 08:54:11.727001 zmeventnotification[15179].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139874871111680 for 8]
10/16/20 08:54:11.727136 zmeventnotification[15179].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 8: 1]
10/16/20 08:54:13.727392 zmeventnotification[15179].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139874871111680 for 8]
10/16/20 08:54:13.727567 zmeventnotification[15179].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 8: 1]
10/16/20 08:54:15.727806 zmeventnotification[15179].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618981 exiting]
10/16/20 08:54:15.727925 zmeventnotification[15179].DBG [main:943] [|----> FORK:Side Entrance (8), eid:618981 Ending process:15179 to handle alarms]

Are the pushes being delivered now?

lainy commented 4 years ago

Are the pushes being delivered now?

Yes, it seems to be working now. Haven't seen any 500 errors today.