having issues getting hooks going

[asker]

Yes, correct. I've made that change.

[lorenjz]

Any thoughts as to why neither event_start_hook_notify_userscript or event_end_hook_notify_userscript are getting called. I double checked both scripts (I copied the example.py and renamed it and have the end userscript variable pointing to it) are owned by www-data and are executable. I also did a test run manually executing the script and it inserted the line into the log. Neither executed when motion was triggered by a camera. Thoughts?

[asker]

Any thoughts as to why neither event_start_hook_notify_userscript or event_end_hook_notify_userscript are getting called. I double checked both scripts (I copied the example.py and renamed it and have the end userscript variable pointing to it) are owned by www-data and are executable. I also did a test run manually executing the script and it inserted the line into the log. Neither executed when motion was triggered by a camera. Thoughts?

Can't say without seeing zmeventnotification logs (with debug level enabled) on what happens when an applicable event triggers. My guess would be if hooks are on, no objects are detected.

[lorenjz]

I had a little more time this morning to try and troubleshoot this. I can see where the logs say that they start example.py and lzhomeseer.py. Both scripts run without any errors when executed manually as the www-data user. example.py hasn't been changed. lzhomeseer.py is a copy of example.py with a few lines to send a push notification to my phone via pushover.

Attached is a log that I saved according to the guidance on the wiki page. It should contain all of event 10099 on monitor 12. Any help or insight that you could provide at your earliest convenience would certainly be appreciated. If I need to clarify any details or add more information I'm happy to do so. Again many thanks for all of your help and guidance!

Loren

[asker]

I don't quite understand the issue. Both your event start and event end scripts are being called according to your logs.

Code: Select all

08/30/2020 09:39:17.171694 zmeventnotification[9887].DBG [main:935] [|----> FORK:Small Room Sub (12), eid:10099 invoking user start notification script '/var/lib/zmeventnotification/contrib/example.py' 1 10099 12 "Small Room Sub" "" "[]"  "/var/cache/zoneminder/events/12/2020-08-30/10099"]
08/30/2020 09:39:21.239339 zmeventnotification[9887].DBG [main:935] [|----> FORK:Small Room Sub (12), eid:10099 invoking user end notification script '/var/lib/zmeventnotification/contrib/lzHomeseer.py' 0 10099 12 "Small Room Sub" "Motion: All" "[]"  "/var/cache/zoneminder/events/12/2020-08-30/10099"]

Note however, this log:

Code: Select all

08/30/2020 09:39:19.219835 zmeventnotification[9887].DBG [main:935] [|----> FORK:Small Room Sub (12), eid:10099 should NOT send alarm as Monitor 12 is excluded]

I don't know what your script are doing, but summary:
a) They are being called
b) the ES itself is not sending a push as Monitor 12 is excluded (likely not selected in zmNinja)

[lorenjz]

I don't quite understand the issue. Both your event start and event end scripts are being called according to your logs.

Code: Select all

08/30/2020 09:39:17.171694 zmeventnotification[9887].DBG [main:935] [|----> FORK:Small Room Sub (12), eid:10099 invoking user start notification script '/var/lib/zmeventnotification/contrib/example.py' 1 10099 12 "Small Room Sub" "" "[]"  "/var/cache/zoneminder/events/12/2020-08-30/10099"]
08/30/2020 09:39:21.239339 zmeventnotification[9887].DBG [main:935] [|----> FORK:Small Room Sub (12), eid:10099 invoking user end notification script '/var/lib/zmeventnotification/contrib/lzHomeseer.py' 0 10099 12 "Small Room Sub" "Motion: All" "[]"  "/var/cache/zoneminder/events/12/2020-08-30/10099"]

Note however, this log:

Code: Select all

08/30/2020 09:39:19.219835 zmeventnotification[9887].DBG [main:935] [|----> FORK:Small Room Sub (12), eid:10099 should NOT send alarm as Monitor 12 is excluded]

I don't know what your script are doing, but summary:
a) They are being called

There is an entry in the log that says they are being called. However zmeventnotification_userscript_example.log has no evidence that they are (aside from the two manual attempts that I made today). Thoughts?

example.py looks like this fyi:

Code: Select all

import sys
import pyzm.ZMLog as zmlog
import http.client, urllib
import json

# Arguments:
# All scripts invoked with the xxx_userscript tags
# get the following args passed
#   ARG1: Hook result - 0 if object was detected, 1 if not.
#         Always check this FIRST  as the json/text string
#         will be empty if this is 1
#
#   ARG2: Event ID
#   ARG3: Monitor ID
#   ARG4: Monitor Name
#   ARG5: object detection string
#   ARG6: object detection JSON string
#   ARG7: event path (if hook_pass_image_path is yes)




zmlog.init(name='zmeventnotification_userscript_example')
zmlog.Info ("This is a dummy script. Only for your testing. I got {} as arguments".format(sys.argv[1:]))

and zmeventnotification_userscript_example.log:

Code: Select all

08/30/20 17:12:04 zmeventnotification_userscript_example[6066] INF example.py:25 [This is a dummy script. Only for your testing. I got ['0', '1', '2', '3', '4', '5', '6', '7'] as arguments]
08/30/20 17:13:56 zmeventnotification_userscript_example[6160] INF example.py:24 [This is a dummy script. Only for your testing. I got ['0', '1', '2', '3', '4', '5', '6', '7'] as arguments]

[asker]

There could be several things.

1. I noticed your script doesn't have "#!/usr/bin/python" or wherever python is located at the top
2. When running in daemon mode, make sure your script has permissions of www-data.
3. When you executed it manually, what was the exact command you used?
4. Make sure your script has execute permissions

the ES will call the script. The rest is upto your script and how it behaves.

[lorenjz]

1. I noticed your script doesn't have "#!/usr/bin/python" or wherever python is located at the top

Good catch. That was it Again thanks a ton!

[eriol]

Hi
I can not get what is going wrong, so need some help.

The server runs fine when manually executed, but fails when run in daemon mode.
Using

Code: Select all

sudo -u http /usr/bin/zmeventnotification.pl --debug

(yes, the user is http) everything runs fine, I even get zmNinja notifications. I tryed to follow the solution provided and did

Code: Select all

chown -R http:http /var/lib/zmeventnotification/push

, but nothing changes.
So tryed also to check the value of wait in objectconfig.ini , but it was already set to 5 (and, anyway, I do not think that the problem relies there, as it works, when running server manually. Am I wrong?).
Activating debug lead me to see that is something that is not working, because

Code: Select all

tail -F  /var/log/zoneminder/zmesdetect*.log

shows me that files are not updated when an event occurs, but I do not understand what.

This, instead, is the output of

Code: Select all

tail -f /var/log/zoneminder/zmeventnotification.log

when an event occurs.

Code: Select all

5/12/2020 11:55:32.462774 zmeventnotification[617].DBG [main:964] [PARENT: checkEvents() new events found=1]
05/12/2020 11:55:32.462796 zmeventnotification[617].DBG [main:964] [PARENT: There are 1 new Events to process]
05/12/2020 11:55:32.463656 zmeventnotification[617].DBG [main:964] [PARENT: ---------->Tick END<--------------]
05/12/2020 11:55:32.466944 zmeventnotification[1351].DBG [main:964] [PARENT: Forked process:1351 to handle alarm eid:21055]
05/12/2020 11:55:32.467343 zmeventnotification[1351].DBG [ZoneMinder::Object:115] [Loading ZoneMinder::Event from Events WHERE Id = 21055]
05/12/2020 11:55:32.468685 zmeventnotification[1351].DBG [main:964] [|----> FORK:Interno-1 (2), eid:21055 Adding event path:/var/lib/zoneminder/events/2/2020-12-05/21055 to hook for image storage]
05/12/2020 11:55:32.468723 zmeventnotification[1351].DBG [main:964] [|----> FORK:Interno-1 (2), eid:21055 Invoking hook on event start:'/var/lib/zmeventnotification/bin/zm_event_start.sh' 21055 2 "Interno-1" "Motion Ingresso-1" "/var/lib/zoneminder/events/2/2020-12-05/21055"]
05/12/2020 11:55:32.626111 zmeventnotification[1351].DBG [main:964] [|----> FORK:Interno-1 (2), eid:21055 parse of hook: and []]
05/12/2020 11:55:32.626179 zmeventnotification[1351].DBG [main:964] [|----> FORK:Interno-1 (2), eid:21055 hook start returned with text: json:[] exit:1]
05/12/2020 11:55:32.626268 zmeventnotification[1351].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139910178562048 for 2]
05/12/2020 11:55:32.626413 zmeventnotification[1351].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 2: 1]
05/12/2020 11:55:34.627035 zmeventnotification[1351].DBG [main:964] [|----> FORK:Interno-1 (2), eid:21055 rules: Checking rules for alarm caused by eid:21055, monitor:2, at: Sat Dec  5 11:55:34 2020 with cause:Motion Ingresso-1]
05/12/2020 11:55:34.627141 zmeventnotification[1351].DBG [main:964] [|----> FORK:Interno-1 (2), eid:21055 rules: No rules found for Monitor, allowing:2]
05/12/2020 11:55:34.627250 zmeventnotification[1351].DBG [main:964] [|----> FORK:Interno-1 (2), eid:21055 Matching alarm to connection rules...]
05/12/2020 11:55:34.627399 zmeventnotification[1351].DBG [main:964] [|----> FORK:Interno-1 (2), eid:21055 Checking alarm conditions for token ending in:...stRS-Lnn6v]
05/12/2020 11:55:34.627598 zmeventnotification[1351].DBG [main:964] [|----> FORK:Interno-1 (2), eid:21055 Monitor 2 event: should send out as  39.5858800411224 is >= interval of 0]
05/12/2020 11:55:34.627661 zmeventnotification[1351].DBG [main:964] [|----> FORK:Interno-1 (2), eid:21055 shouldSendEventToConn returned true, so calling sendEvent]
05/12/2020 11:55:34.628256 zmeventnotification[1351].DBG [main:964] [|----> FORK:Interno-1 (2), eid:21055 isAllowedChannel: got type:event_start resCode:1]
05/12/2020 11:55:34.628777 zmeventnotification[1351].INF [main:976] [|----> FORK:Interno-1 (2), eid:21055 Not sending over FCM as notify filters are on_success:all and on_fail:none]
05/12/2020 11:55:34.966403 zmeventnotification[1351].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139910178562048 for 2]
05/12/2020 11:55:34.966646 zmeventnotification[1351].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 2: 1]
05/12/2020 11:55:36.966829 zmeventnotification[1351].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139910178562048 for 2]
05/12/2020 11:55:36.966917 zmeventnotification[1351].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 2: 1]
05/12/2020 11:55:37.239375 zmeventnotification[617].DBG [main:964] [PARENT: ---------->Tick START<--------------]
05/12/2020 11:55:37.239728 zmeventnotification[617].DBG [main:964] [PARENT: After tick: TOTAL: 1,  ES_CONTROL: 0, FCM+WEB: 0, FCM: 1, WEB: 0, MQTT:0, invalid WEB: 0, PENDING: 0]
05/12/2020 11:55:37.241008 zmeventnotification[617].DBG [main:964] [PARENT: RAW TEXT-->timestamp--TYPE--1607165491.91697--SPLIT--2--SPLIT--1607165734.62769]
05/12/2020 11:55:37.241245 zmeventnotification[617].DBG [main:964] [PARENT: Job: Update last sent timestamp of monitor:2 to 1607165734.62769 for id:1607165491.91697]
05/12/2020 11:55:37.241451 zmeventnotification[617].DBG [main:964] [PARENT: There are 1 active child forks...]
05/12/2020 11:55:37.241693 zmeventnotification[617].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139910178562048 for 2]
05/12/2020 11:55:37.242032 zmeventnotification[617].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 2: 1]
05/12/2020 11:55:37.242566 zmeventnotification[617].DBG [main:964] [PARENT: We've already worked on Monitor:2, Event:21055, not doing anything more]
05/12/2020 11:55:37.242697 zmeventnotification[617].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139910178541568 for 7]
05/12/2020 11:55:37.242880 zmeventnotification[617].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 7: 1]
05/12/2020 11:55:37.243156 zmeventnotification[617].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139910178557952 for 3]
05/12/2020 11:55:37.243332 zmeventnotification[617].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 3: 1]
05/12/2020 11:55:37.243593 zmeventnotification[617].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139910178549760 for 5]
05/12/2020 11:55:37.243765 zmeventnotification[617].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 5: 1]
05/12/2020 11:55:37.243968 zmeventnotification[617].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139910178553856 for 4]
05/12/2020 11:55:37.244137 zmeventnotification[617].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 4: 1]
05/12/2020 11:55:37.244369 zmeventnotification[617].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 139910178545664 for 6]
05/12/2020 11:55:37.244533 zmeventnotification[617].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 6: 1]
05/12/2020 11:55:37.244761 zmeventnotification[617].DBG [main:964] [PARENT: checkEvents() new events found=0]

[asker]

Try this

Code: Select all

sudo -u http '/var/lib/zmeventnotification/bin/zm_event_start.sh' 21055 2 "Interno-1" "Motion Ingresso-1" "/var/lib/zoneminder/events/2/2020-12-05/21055"

And see what the error is.

[eriol]

Code: Select all

sudo -u http '/var/lib/zmeventnotification/bin/zm_event_start.sh' 21055 2 "Interno-1" "Motion Ingresso-1" "/var/lib/zoneminder/events/2/2020-12-05/21055"
[a] detected:truck:39% --SPLIT--[{"type": "object", "label": "truck", "box": [802, 539, 1006, 675], "confidence": "38.84%"}]

That is all the output

[eriol]

Any other hint for me to find where is the problem? Something more that I can check?

[eriol]

Added some "echo" in zm_event_start.sh to understand what was going wrong and found that, when zm_detect.py was run from the daemon, it gave the "no module cv2" error.
As a quick fix I added

Code: Select all

export PYTHONPATH=$PYTHONPATH:/usr/local/lib/python3.9/site-packages/

at top of zm_event_start.sh and now it works.
I think did not install openCV properly.

[asker]

That should have been logged in zmesdetect logs. Were they not?
Where did you add the echo exactly?

[eriol]

The steps that lead me to my problems were the following:
- I compiled and installed openCV
- I found that import cv2 did not work
- I added cv2 to PYTHONPATH adding PYTHONPATH=$PYTHONPATH:/usr/local/lib/python3.9/site-packages/ to /etc/environment
Then executing zm_detect.py and zmeventnotification.pl worked fine.

That should have been logged in zmesdetect logs. Were they not?

No. /var/log/zoneminder/zmesdetect*.log were not updated at all, when running in daemon mode.

Where did you add the echo exactly?

I added more then one, to log some informations (for example, the output of whoami, the hour in which the script is runned, and the values of the various variables). The one that made me understand the problem was this:

Code: Select all

...
DETECTION_SCRIPT=(/var/lib/zmeventnotification/bin/zm_detect.py --monitorid $2 --eventid $1 --config "${CONFIG_FILE}" --eventpath "${EVENT_PATH}" --reason "${REASON}"  )
DS_OUTPUT=$("${DETECTION_SCRIPT[@]}" 2>&1)
echo "$DS_OUTPUT" >> $LOGFILE
RESULTS=$("${DETECTION_SCRIPT[@]}" | grep "detected:")
...

So, as far as I can understand, the problem is that the variables stored in /etc/environment are not seen by daemons... (ergo, I did not install openCV properly).