ZoneMinder / zmeventnotification

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

FCM push message Error:500 Server closed connection without sending any data back #112

Closed vandalon closed 5 years ago

vandalon commented 5 years ago

Event Server version 3.5

Hooks version 2.2.8

The version of ZoneMinder you are using:

(example only, please edit this line) 1.33.6

What is the nature of your issue

When FCM tries to push a message the remote server returns a 500. This sounds to me like it's an issue with the FCM server, but i might be wrong :)

2019-04-22 17:36:09 zmeventnotification   2840 INF   Ending process:2840 to handle alarms   zmeventnotification.pl  
2019-04-22 17:36:09 zmeventnotification   2840 INF   FCM push message Error:500 Server closed connection without sending any data back   zmeventnotification.pl
pliablepixels commented 5 years ago

May be. If it self resolves in a day or so, its an intermittent FCM issue. If it persists, it may even be an issue with the token.

  1. Look at zmES logs in debug mode - see trouble shooting guide in the docs.
  2. If everything looks good, uninstall/re-install the app
  3. If you are not sure if everything looks good, please post detailed logs.
vandalon commented 5 years ago

Hi again, Everything seems fin ein terms of settings and all.

This is what I get in logging:

Apr 30 13:55:20 marvin zmeventnotification[11806]: INF [Reloading Monitors...]
Apr 30 13:55:20 marvin zmeventnotification[11806]: INF [Loading monitors]
Apr 30 13:55:20 marvin zmeventnotification[11806]: INF [Secure WS is disabled...]
Apr 30 13:55:20 marvin zmeventnotification[11806]: INF [Web Socket Event Server listening on port 9000]
Apr 30 13:56:04 marvin zmeventnotification[11806]: INF [New event 3233 reported for Voordeur Motion All]
Apr 30 13:56:04 marvin zmeventnotification[12012]: INF [Forking process:12012 to handle 1 alarms]
Apr 30 13:56:04 marvin zmeventnotification[12012]: INF [processAlarms: EID:3233 Monitor:Voordeur (id):1 cause:Motion All]
Apr 30 13:56:04 marvin zmeventnotification[12012]: INF [Adding event path:/var/cache/zoneminder/events/1/2019-04-30/3233 to hook for image storage]
Apr 30 13:56:04 marvin zmeventnotification[12012]: INF [Invoking hook:'/usr/bin/detect_wrapper.sh' 3233 1 "Voordeur" "Motion All" "/var/cache/zoneminder/events/1/2019-04-30/3233"]
Apr 30 13:56:04 marvin detect:[12016][monitor_m1]: DEBUG [Using model: yolo with /var/lib/zmeventnotification/images/3233-alarm.jpg]
Apr 30 13:56:04 marvin detect:[12016][monitor_m1]: DEBUG [config:/var/lib/zmeventnotification/models/yolov3/yolov3.cfg, weights:/var/lib/zmeventnotification/models/yolov3/yolov3.weights]
Apr 30 13:56:06 marvin detect:[12016][monitor_m1]: DEBUG [match found in /var/lib/zmeventnotification/images/3233-alarm.jpg, breaking file loop...]
Apr 30 13:56:06 marvin detect:[12016][monitor_m1]: DEBUG [Writing out debug bounding box image to /var/lib/zmeventnotification/images/3233-alarm-bbox.jpg...]
Apr 30 13:56:06 marvin zmeventnotification[12012]: INF [hook script returned with text:[a] detected:person:100% exit:0]
Apr 30 13:56:06 marvin zmeventnotification[12012]: INF [Matching alarm to connection rules...]
Apr 30 13:56:06 marvin zmeventnotification[12012]: INF [Checking alarm rules for token ending in:...p-nwGroOq_]
Apr 30 13:56:06 marvin zmeventnotification[12012]: INF [Monitor 1 event: last time not found, so should send]
Apr 30 13:56:06 marvin zmeventnotification[12012]: INF [Sending notification over FCM]
Apr 30 13:56:22 marvin zmeventnotification[11806]: INF [Total event client connections: 2]
Apr 30 13:56:22 marvin zmeventnotification[11806]: INF [Reloading Monitors...]
Apr 30 13:56:22 marvin zmeventnotification[11806]: INF [Loading monitors]
Apr 30 13:57:24 marvin zmeventnotification[11806]: INF [Total event client connections: 2]
Apr 30 13:57:24 marvin zmeventnotification[11806]: INF [Reloading Monitors...]
Apr 30 13:57:24 marvin zmeventnotification[11806]: INF [Loading monitors]
Apr 30 13:58:26 marvin zmeventnotification[11806]: INF [Total event client connections: 2]
Apr 30 13:58:26 marvin zmeventnotification[11806]: INF [Reloading Monitors...]
Apr 30 13:58:26 marvin zmeventnotification[11806]: INF [Loading monitors]
Apr 30 13:59:28 marvin zmeventnotification[11806]: INF [Total event client connections: 2]
Apr 30 13:59:28 marvin zmeventnotification[11806]: INF [Reloading Monitors...]
Apr 30 13:59:28 marvin zmeventnotification[11806]: INF [Loading monitors]
Apr 30 14:00:06 marvin zmeventnotification[12012]: INF [FCM push message Error:500 Server closed connection without sending any data back]
Apr 30 14:00:06 marvin zmeventnotification[12012]: INF [Checking alarm rules for MQTT 127.0.0.1]
Apr 30 14:00:06 marvin zmeventnotification[12012]: INF [Monitor 1 event: last time not found, so should send]
Apr 30 14:00:06 marvin zmeventnotification[12012]: INF [Sending notification over MQTT]
Apr 30 14:00:06 marvin zmeventnotification[12012]: INF [Ending process:12012 to handle alarms]
pliablepixels commented 5 years ago

Please run it in manual/verbose mode as explained in the troubleshooting FAQ - so I can see the actual message that is being sent. In addition, Please add this line right after https://github.com/pliablepixels/zmeventnotification/blob/master/zmeventnotification.pl#L978

printInfo("FCM push message Error Content:".$res->content);

stale[bot] commented 5 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

rhaamo commented 5 years ago

I am having the same issue, I added the printInfo at the required spot but it doesn't seems to be much useful:

05/15/2019 17:06:26.268525 zmeventnotification[18720].INF [main:533] [Monitor 7 event: should send out as  14.7288599014282 is >= interval of 0]
05/15/2019 17:06:26.310217 zmeventnotification[18720].INF [main:533] [Sending notification over FCM]
05/15/2019 17:08:56.608592 zmeventnotification[18268].INF [main:533] [FCM push message Error:500 Server closed connection without sending any data back]
05/15/2019 17:08:56.648547 zmeventnotification[18268].INF [main:533] [FCM push message Error Content:Server closed connection without sending any data back at /usr/share/perl5/Net/HTTP/Methods.pm line 391.]
05/15/2019 17:08:56.715398 zmeventnotification[18268].INF [main:533] [Ending process:18268 to handle alarms]
pliablepixels commented 5 years ago

Same response as above. Run manually in debug mode, post verbose logs.

rhaamo commented 5 years ago

Ok tried it with console_logs and verbose thingy and I get:

05/15/2019 17:27:44.730500 zmeventnotification[23961].INF [main:533] [Sending notification over FCM]
CONSOLE DEBUG:2019-05-15,17:27:44 Final JSON being sent is: {"data":{"myMessageId":1,"eid":"207388","summaryText":"207388","image_url_jpg":"https://zm.xxx/zm/index.php?view=image&eid=207388&fid=snapshot&width=600&username=xxx&password=xxx","mid":"7"},"notification":{"body":" at 05:27 PM, 15-May","title":"Jardin Alarm (207388)","sound":"default","badge":"1"},"mutable_content":true,"to":"eq-xxx:xxx"}
CONSOLE DEBUG:2019-05-15,17:27:49 ---------->Tick START<--------------
CONSOLE DEBUG:2019-05-15,17:27:49 After tick: TOTAL: 1, FCM+WEB: 0, FCM: 1, WEB: 0, MQTT:0, invalid WEB: 0, PENDING: 0
CONSOLE DEBUG:2019-05-15,17:27:49 PARENT GOT RAW TEXT-->badge--TYPE--1557934033.6618--SPLIT--1
CONSOLE DEBUG:2019-05-15,17:27:49 GOT JOB==> Update badge to:1 for id:1557934033.6618
CONSOLE DEBUG:2019-05-15,17:27:49 Empty job queue
CONSOLE DEBUG:2019-05-15,17:27:49 Alarm 207388 for monitor:7 has ended 
CONSOLE DEBUG:2019-05-15,17:27:49 HOOK: 207388 NOT writing hook to DB as hook text was empty
CONSOLE DEBUG:2019-05-15,17:27:49 checkEvents() events found=0
CONSOLE DEBUG:2019-05-15,17:27:49 ---------->Tick END<--------------
CONSOLE DEBUG:2019-05-15,17:27:54 ---------->Tick START<--------------
CONSOLE DEBUG:2019-05-15,17:27:54 After tick: TOTAL: 1, FCM+WEB: 0, FCM: 1, WEB: 0, MQTT:0, invalid WEB: 0, PENDING: 0
CONSOLE DEBUG:2019-05-15,17:27:54 Empty job queue
CONSOLE DEBUG:2019-05-15,17:27:54 checkEvents() events found=0
CONSOLE DEBUG:2019-05-15,17:27:54 ---------->Tick END<--------------
... more tick tick here ...
CONSOLE DEBUG:2019-05-15,17:31:44 ---------->Tick START<--------------
CONSOLE DEBUG:2019-05-15,17:31:44 After tick: TOTAL: 1, FCM+WEB: 0, FCM: 1, WEB: 0, MQTT:0, invalid WEB: 0, PENDING: 0
CONSOLE DEBUG:2019-05-15,17:31:44 Empty job queue
CONSOLE DEBUG:2019-05-15,17:31:44 checkEvents() events found=0
CONSOLE DEBUG:2019-05-15,17:31:44 ---------->Tick END<--------------
CONSOLE INFO:2019-05-15,17:31:44 FCM push message Error:500 Server closed connection without sending any data back
05/15/2019 17:31:44.960358 zmeventnotification[23961].INF [main:533] [FCM push message Error:500 Server closed connection without sending any data back]
CONSOLE INFO:2019-05-15,17:31:45 FCM push message Error Content:Server closed connection without sending any data back at /usr/share/perl5/Net/HTTP/Methods.pm line 391.

05/15/2019 17:31:45.027955 zmeventnotification[23961].INF [main:533] [FCM push message Error Content:Server closed connection without sending any data back at /usr/share/perl5/Net/HTTP/Methods.pm line 391.]
CONSOLE INFO:2019-05-15,17:31:45 Ending process:23961 to handle alarms
05/15/2019 17:31:45.061780 zmeventnotification[23961].INF [main:533] [Ending process:23961 to handle alarms]
pliablepixels commented 5 years ago

Do you happen to have some form of network proxy? If you do, can you check if its causing issues? I found this link https://www.perlmonks.org/?node_id=1084505

rhaamo commented 5 years ago

nope no proxy, direct internet access.

not all calls fails, and when they fails there is a delay between the "sending notification" and the weird "error:500 + closed connection"

pliablepixels commented 5 years ago

that's odd. I don't have an answer tbh. How often does this happen? If its once in a while, then it might just be a FCM server issue at google. If not, then I'm a bit clueless.

stale[bot] commented 5 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.