Unexpected behavior of hooks mechanism #778

pilyon3 · 2021-04-12T10:04:38Z

Expected Behavior

Hooks should be trigger for each occurrence configured

Current Behavior

Hooks triggerd randomly

Possible Solution

May be this behavior is inherent to job queue mechanism but some hooks appears to be definitively lost which is not terrific. If this analyze is right, could it be possible to have the possibility to prioritize some hooks that can't be delayed or ever less forgotten ?
For information, expired_jobs of 14 days by default has not been modified nor default backend daemon's workers parameters like timeout or tasks.

Steps to Reproduce (for bugs)

Configure hooks for by example discover event sending data into a temporarily log file called "test.log"
Schedule discover for a device each minute to have better visibility
Active debug level for logs
Hooks are logged into netdisco-backend log file, but hooks not triggerd each time into test.log file

Context

New device or discovered devices not present/refreshed into local monitoring application

Your Environment

Netdisco version used: 2.47.5
SNMP::Info version used: 3.70

Config info (deployment.yml)

hooks:

type: 'exec'
event: 'discover'
with:
cmd: '/bin/echo $(command date) "https://superview.XXX/oxidized/reload" >> /home/netdisco/logs/test.log'
type: 'exec'
event: 'discover'
with:
cmd: '/bin/echo $(command date) "https://superview.XXX/webservices/discovery.php?ip=[% ip %]&action=discover" >> /home/netdisco/logs/test.log'

schedule:
discover_specific:
action: 'discover'
when: '*/1 * * * *'
device: '192.168.100.6'

Device information

All devices impacted

Logs into netdisco-backend.log (parsed for specific device 192.168.100.6). Seems to be as expected (hooks triggerd every minutes):

[113785] 2021-04-12 09:23:12 debug [192.168.100.6] hooks - 2 queued
[113789] 2021-04-12 09:23:36 debug [192.168.100.6] hooks - 2 queued
[113790] 2021-04-12 09:25:34 debug [192.168.100.6] hooks - 2 queued
[113791] 2021-04-12 09:24:19 debug [192.168.100.6] hooks - 2 queued
[114374] 2021-04-12 09:26:50 debug [192.168.100.6] hooks - 2 queued
[114375] 2021-04-12 09:27:31 debug [192.168.100.6] hooks - 2 queued
[114376] 2021-04-12 09:28:55 debug [192.168.100.6] hooks - 2 queued
[114377] 2021-04-12 09:29:39 debug [192.168.100.6] hooks - 2 queued
[114378] 2021-04-12 09:30:44 debug [192.168.100.6] hooks - 2 queued
[114828] 2021-04-12 09:31:43 debug [192.168.100.6] hooks - 2 queued
[114843] 2021-04-12 09:32:26 debug [192.168.100.6] hooks - 2 queued
[114916] 2021-04-12 09:33:42 debug [192.168.100.6] hooks - 2 queued
[114968] 2021-04-12 09:34:40 debug [192.168.100.6] hooks - 2 queued
[115272] 2021-04-12 09:35:38 debug [192.168.100.6] hooks - 2 queued
[115445] 2021-04-12 09:36:38 debug [192.168.100.6] hooks - 2 queued
[115448] 2021-04-12 09:37:43 debug [192.168.100.6] hooks - 2 queued
[115451] 2021-04-12 09:38:41 debug [192.168.100.6] hooks - 2 queued
[115452] 2021-04-12 09:39:52 debug [192.168.100.6] hooks - 2 queued
[115461] 2021-04-12 09:40:40 debug [192.168.100.6] hooks - 2 queued
[116260] 2021-04-12 09:41:22 debug [192.168.100.6] hooks - 2 queued
[116263] 2021-04-12 09:42:33 debug [192.168.100.6] hooks - 2 queued
[116264] 2021-04-12 09:43:28 debug [192.168.100.6] hooks - 2 queued

Logs into test.log

ollyg · 2021-07-14T12:10:56Z

thanks for the bug report @pilyon3

I think what is happening is that Netdisco is seeing duplicate jobs and deleting/cancelling them. This is sensible for things like macsuck and discover but not sensible for Hooks, I guess (or we could introduce a new flag to control the behaviour).

Are you able to explore the database and see if you have entries in the "admin" table saying something like "...duplicate of..." in the log field?

In any case I will have a think about a good way to resolve and deal with this.

ollyg · 2021-07-14T12:13:04Z

ah! I have discovered a bug
Exec jobs are not classed as high priority (only HTTP ones). Whoops.

I will release a fix and we can see if this helps.

pilyon3 · 2021-07-19T12:02:24Z

Hi ollyg,

Thanks for your work, and sorry for delayed reaction. We'll try your fix asap and report to you.

pilyon3 · 2021-07-19T13:17:48Z

After few tests, it seems to be better, and hooks works as expected. Reusing setup as mentionned in this issue, we have now:

Logs into netdisco-backend.log

[89405] 2021-07-19 14:30:59 debug [discover] hooks - 192.168.100.6 queued
[89405] 2021-07-19 14:30:59 debug [discover] hooks - 192.168.100.6 queued
[89836] 2021-07-19 14:31:35 debug [discover] hooks - 192.168.100.6 queued
[89836] 2021-07-19 14:31:35 debug [discover] hooks - 192.168.100.6 queued
[89847] 2021-07-19 14:32:37 debug [discover] hooks - 192.168.100.6 queued
[89847] 2021-07-19 14:32:37 debug [discover] hooks - 192.168.100.6 queued
[89850] 2021-07-19 14:33:32 debug [discover] hooks - 192.168.100.6 queued
[89850] 2021-07-19 14:33:32 debug [discover] hooks - 192.168.100.6 queued
[89984] 2021-07-19 14:34:48 debug [discover] hooks - 192.168.100.6 queued
[89984] 2021-07-19 14:34:48 debug [discover] hooks - 192.168.100.6 queued
[90301] 2021-07-19 14:35:32 debug [discover] hooks - 192.168.100.6 queued
[90301] 2021-07-19 14:35:32 debug [discover] hooks - 192.168.100.6 queued
[90611] 2021-07-19 14:36:44 debug [discover] hooks - 192.168.100.6 queued
[90611] 2021-07-19 14:36:44 debug [discover] hooks - 192.168.100.6 queued
[90614] 2021-07-19 14:37:26 debug [discover] hooks - 192.168.100.6 queued
[90614] 2021-07-19 14:37:26 debug [discover] hooks - 192.168.100.6 queued
[90617] 2021-07-19 14:38:42 debug [discover] hooks - 192.168.100.6 queued
[90617] 2021-07-19 14:38:42 debug [discover] hooks - 192.168.100.6 queued
[90626] 2021-07-19 14:39:54 debug [discover] hooks - 192.168.100.6 queued
[90626] 2021-07-19 14:39:54 debug [discover] hooks - 192.168.100.6 queued
[90647] 2021-07-19 14:40:31 debug [discover] hooks - 192.168.100.6 queued
[90647] 2021-07-19 14:40:31 debug [discover] hooks - 192.168.100.6 queued
[91207] 2021-07-19 14:41:27 debug [discover] hooks - 192.168.100.6 queued
[91207] 2021-07-19 14:41:27 debug [discover] hooks - 192.168.100.6 queued
[91210] 2021-07-19 14:42:55 debug [discover] hooks - 192.168.100.6 queued
[91210] 2021-07-19 14:42:55 debug [discover] hooks - 192.168.100.6 queued
[91211] 2021-07-19 14:43:41 debug [discover] hooks - 192.168.100.6 queued
[91211] 2021-07-19 14:43:41 debug [discover] hooks - 192.168.100.6 queued
[91215] 2021-07-19 14:44:44 debug [discover] hooks - 192.168.100.6 queued
[91215] 2021-07-19 14:44:44 debug [discover] hooks - 192.168.100.6 queued
[91228] 2021-07-19 14:45:30 debug [discover] hooks - 192.168.100.6 queued
[91228] 2021-07-19 14:45:30 debug [discover] hooks - 192.168.100.6 queued

Logs into test.log

We can see that each hook triggerd is well executed, sometimes with a little delayed time because a macwalk occurs.

Just a question. Fix seems to be just a add into config.yml file: is the parameter "job_prio" overridable into deployment.yml ? It's not mentionned into wiki.

ollyg · 2021-10-04T13:17:56Z

Hi @pilyon3 sorry for the slow answer, yes job_prio is overridable but is not documented.

ollyg added a commit that referenced this issue Jul 14, 2021

#778 exec hooks were not configured to be high priority

8509cd9

ollyg closed this as completed Oct 4, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Unexpected behavior of hooks mechanism #778

Unexpected behavior of hooks mechanism #778

pilyon3 commented Apr 12, 2021

ollyg commented Jul 14, 2021

ollyg commented Jul 14, 2021

pilyon3 commented Jul 19, 2021 •

edited

pilyon3 commented Jul 19, 2021 •

edited

ollyg commented Oct 4, 2021

Unexpected behavior of hooks mechanism #778

Unexpected behavior of hooks mechanism #778

Comments

pilyon3 commented Apr 12, 2021

Expected Behavior

Current Behavior

Possible Solution

Steps to Reproduce (for bugs)

Context

Your Environment

Config info (deployment.yml)

Device information

Logs into netdisco-backend.log (parsed for specific device 192.168.100.6). Seems to be as expected (hooks triggerd every minutes):

Logs into test.log

ollyg commented Jul 14, 2021

ollyg commented Jul 14, 2021

pilyon3 commented Jul 19, 2021 • edited

pilyon3 commented Jul 19, 2021 • edited

Logs into netdisco-backend.log

Logs into test.log

ollyg commented Oct 4, 2021

pilyon3 commented Jul 19, 2021 •

edited

pilyon3 commented Jul 19, 2021 •

edited