Understanding behaviour of "delay: up"

[candlerb]

# /opt/netdata/bin/netdata -v
netdata v1.42.0-153-g3bae63f27
# uname -a
Linux nuc2 5.4.0-162-generic #179-Ubuntu SMP Mon Aug 14 08:51:31 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

Hello,

I want to receive an alert if a condition remains true for a certain amount of time, and suppress the alert entirely if the condition clears within that time. For example, it's normal for the 15m load average to exceed 4 for a while when a box is doing a burst of activity, so I only want to be alerted if it remains stuck in this state for a long time.

I tried "delay: up 30m ...", like this:

    alarm: load_average_15
       on: system.load
    class: Utilization
     type: System
component: Load
       os: linux
    hosts: *
   lookup: max -1m unaligned of load15
     calc: ($load_cpu_number == nan) ? (nan) : ($this)
    units: load
    every: 1m
     warn: ($this * 100 / $load_cpu_number) > (($status >= $WARNING) ? 175 : 200)
    delay: up 30m down 15m multiplier 1.5 max 1h     # <<<< CHANGED THIS
     info: system fifteen-minute load average
       to: sysadmin

(This was edited using sudo /opt/netdata/etc/netdata/edit-config health.d/load.conf. I wasn't sure if that would reload the config, so I also did /opt/netdata/bin/netdatacli reload-health)

However, that doesn't seem to do what I thought - I still receive the alert immediately.

For example, today the 15m load average graph (blue) went above 4 at 07:12

and I got an alert E-mail immediately:

Date: Wed, 13 Dec 2023 07:13:00 +0000 (GMT)
...
Chart: system.load
Family: load
Raised to warning, for 0 second

On Wed Dec 13 07:12:59 GMT 2023

The graph dropped below 4 at 07:39

And the clear E-mail arrived at 07:57

Date: Wed, 13 Dec 2023 07:57:59 +0000 (GMT)
...
Chart: system.load
Family: load
Recovered from warning, (was warning for 30 minutes)

On Wed Dec 13 07:42:59 GMT 2023

I suppose I could achieve what I want like this:

  lookup: min -30m unaligned of load15

That is: if all the samples within the time window are above 4, then alert.

But I'd still like to know what "delay: up 30m" is intended for, and why it didn't do what I expected. The documentation says:

up U defines the delay to be applied to a notification for an alert that raised its status (i.e. CLEAR to WARNING, CLEAR to CRITICAL, WARNING to CRITICAL). For example, up 10s, the notification for this event will be sent 10 seconds after the actual event. This is used in hope the alert will get back to its previous state within the duration given. The default U is zero.

The status did go from clear to warning, and yet with delay: up 30m ... I still received the alert immediately, and that's what surprised me.

[MrZammler]

Hi @candlerb, you are not wrong, the delay should work as you described. We'll do some tests to verify, in the mean time though, is it possible maybe to update to the latest nightly version ? Although I'm not aware that we had such an issue then, it's always better to test on latest.

Btw, could you double check in http://localhost:19999/api/v1/alarms?all that the alert does have the delay_up_duration ok?

[candlerb]

I didn't receive any alert E-mail at all :-( Mail logs confirm that no mail has been sent since 07:57:59 this morning (it's now 12:20)

And yet clearly the alert is triggering:

Status from the API:

		"system.load.load_average_15": {
			"id": 1694076075,
			"config_hash_id": "8e4941bd-ae71-0ec6-05bc-cfa40d621973",
			"name": "load_average_15",
			"chart": "system.load",
			"family": "load",
			"class": "Unknown",
			"component": "Unknown",
			"type": "Unknown",
			"active": true,
			"disabled": false,
			"silenced": false,
			"exec": "/opt/netdata/usr/libexec/netdata/plugins.d/alarm-notify.sh",
			"recipient": "sysadmin",
			"source": "19@/opt/netdata/etc/netdata/health.d/load.conf",
			"units": "load",
			"info": "fifteen-minute load average",
			"status": "CRITICAL",
			"last_status_change": 1702464900,
			"last_updated": 1702470060,
			"next_update": 1702470120,
			"update_every": 60,
			"delay_up_duration": 0,
			"delay_down_duration": 900,
			"delay_max_duration": 3600,
			"delay_multiplier": 1.500000,
			"delay": 0,
			"delay_up_to_timestamp": 1702464900,
			"warn_repeat_every": "0",
			"crit_repeat_every": "0",
			"value_string": "12.5 load",
			"last_repeat": "0",
			"times_repeat": 0,
			"lookup_dimensions":"load15",
			"db_after": 1702470000,
			"db_before": 1702470055,
			"lookup_method": "max",
			"lookup_after": -60,
			"lookup_before": 0,
			"lookup_options": "unaligned",
			"warn":"$this > (($status >= $WARNING) ? (1.75 * $load_trigger) : (2 * $load_trigger))",
			"warn_parsed":"(${this} > ((${status} >= ${WARNING}) ? (1.75 * ${load_trigger}) : (2 * ${load_trigger})))",
			"crit":"$this > (($status == $CRITICAL) ? (3.5 * $load_trigger) : (4 * $load_trigger))",
			"crit_parsed":"(${this} > ((${status} == ${CRITICAL}) ? (3.5 * ${load_trigger}) : (4 * ${load_trigger})))",
			"green":null,
			"red":null,
			"value":12.52
		},

And the last status change was at:

# date --date='@1702464900'
Wed 13 Dec 10:55:00 GMT 2023

???

[candlerb]

Weird: I notice the API now shows "delay": 0 and "delay_up_duration": 0. And yet the config is the same:

root@nuc2:/opt/netdata# find . -name 'load.conf' | xargs ls -ld
-rw-r--r-- 1 netdata netdata 2184 Dec 12 09:18 ./etc/netdata/health.d/load.conf
-rw-r--r-- 1 root    root    2333 Dec 13 00:28 ./usr/lib/netdata/conf.d/health.d/load.conf

root@nuc2:/opt/netdata# cat etc/netdata/health.d/load.conf
...
# Send alarms if the load average is unusually high.
# These intentionally _do not_ calculate the average over the sampled
# time period because the values being checked already are averages.

    alarm: load_average_15
       on: system.load
    class: Utilization
     type: System
component: Load
       os: linux
    hosts: *
   lookup: max -1m unaligned of load15
     calc: ($load_cpu_number == nan) ? (nan) : ($this)
    units: load
    every: 1m
     warn: ($this * 100 / $load_cpu_number) > (($status >= $WARNING) ? 175 : 200)
    delay: up 30m down 15m multiplier 1.5 max 1h
     info: system fifteen-minute load average
       to: sysadmin
...

(This is the only alert in this file with "to: sysadmin". The others have "to: silent")

[MrZammler]

Definitely something weird here, I can also see class, component and type being Unknown, as well as the info in api is fifteen-minute load average instead of system fifteen-minute load average...

(Do also note during your tests, that if you have received already a warning or critical notification, if the next one is again the same status, you won't get a new notification.)

[MrZammler]

Could you please check, that you don't have 2 netdata instances running? The loaded alert seems like a very old load.conf config.

Please also try: Stop netdata all-together, then re-create load.conf by using edit-config script?

[candlerb]

Argh, you're right.

pstree
...
        |-netdata-+-apps.plugin---{apps.plugin}
        |         |-bash
        |         |-debugfs.plugin
        |         |-go.d.plugin---11*[{go.d.plugin}]
        |         |-netdata---{netdata}
        |         |-nfacct.plugin
        |         |-python3-+-postqueue
        |         |         `-3*[{python3}]
        |         `-54*[{netdata}]
        |-netdata-+-apps.plugin---{apps.plugin}
        |         |-bash
        |         |-debugfs.plugin
        |         |-ebpf.plugin---12*[{ebpf.plugin}]
        |         |-go.d.plugin---10*[{go.d.plugin}]
        |         |-netdata---{netdata}
        |         |-nfacct.plugin
        |         |-python3---3*[{python3}]
        |         `-55*[{netdata}]
...

The top ones being:

root@nuc2:/opt/netdata# ps -p 4178234 -uwww
USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
netdata  4178234  6.5  2.6 416172 212496 ?       SNl  Dec12 113:06 /opt/netdata/bin/srv/netdata version
root@nuc2:/opt/netdata# ps -p 312338 -uwww
USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
netdata   312338  6.3  2.5 442096 206064 ?       SNl  Sep15 8124:47 /opt/netdata/bin/srv/netdata

After killall netdata:

root@nuc2:/opt/netdata# ps auxwww | grep netdata
netdata   312338  6.3  2.5 410748 207796 ?       RNl  Sep15 8124:49 /opt/netdata/bin/srv/netdata
netdata   312347  0.0  0.0  21560   480 ?        SNl  Sep15   0:00 /opt/netdata/bin/srv/netdata --special-spawn-server
netdata   505582  0.0  0.0      0     0 ?        ZN   09:01   0:04 [debugfs.plugin] <defunct>
netdata   586338  0.1  0.0      0     0 ?        ZN   13:15   0:03 [bash] <defunct>
root      595295  0.0  0.0   6432   720 pts/2    S+   13:50   0:00 grep --color=auto netdata
netdata  4178234  6.5  2.5 385212 205664 ?       RNl  Dec12 113:09 /opt/netdata/bin/srv/netdata version
netdata  4178237  0.0  0.0  21332  1036 ?        SNl  Dec12   0:00 /opt/netdata/bin/srv/netdata --special-spawn-server
root     4178474  6.2  0.2 111636 23444 ?        SNl  Dec12 108:32 /opt/netdata/usr/libexec/netdata/plugins.d/ebpf.plugin 1
netdata  4178490  0.7  0.0      0     0 ?        ZN   Dec12  12:23 [python3] <defunct>
netdata  4178503 10.3  0.0      0     0 ?        ZN   Dec12 179:35 [apps.plugin] <defunct>

I had to kill -9 some of the shrapnel, before "systemctl start netdata"

I removed load.conf and used edit-config to recreate it, just changing the delay: and to: lines. /api/v1/alarms?all now shows:

		"system.load.load_average_15": {
			"id": 1694077794,
			"config_hash_id": "43b23075-635f-3d46-feb1-e5c1f4aa0f59",
			"name": "load_average_15",
			"chart": "system.load",
			"class": "Utilization",
			"component": "Load",
			"type": "System",
			"active": true,
			"disabled": false,
			"silenced": false,
			"exec": "/opt/netdata/usr/libexec/netdata/plugins.d/alarm-notify.sh",
			"recipient": "sysadmin",
			"source": "23@/opt/netdata/etc/netdata/health.d/load.conf",
			"units": "load",
			"summary": "Host load average (15 minutes)",
			"info": "System load average for the past 15 minutes",
			"status": "WARNING",
			"last_status_change": 1702475720,
			"last_updated": 1702475720,
			"next_update": 1702475780,
			"update_every": 60,
			"delay_up_duration": 1800,
			"delay_down_duration": 900,
			"delay_max_duration": 3600,
			"delay_multiplier": 1.500000,
			"delay": 1800,
			"delay_up_to_timestamp": 1702477520,
			"warn_repeat_every": "0",
			"crit_repeat_every": "0",
			"value_string": "10.3 load",
			"last_repeat": "0",
			"times_repeat": 0,
			"lookup_dimensions":"load15",
			"db_after": 1702475660,
			"db_before": 1702475715,
			"lookup_method": "max",
			"lookup_after": -60,
			"lookup_before": 0,
			"lookup_options": "unaligned",
			"calc":"($load_cpu_number == nan) ? (nan) : ($this)",
			"calc_parsed":"((${load_cpu_number} == nan) ? nan : ${this})",
			"warn":"($this * 100 / $load_cpu_number) > (($status >= $WARNING) ? 175 : 200)",
			"warn_parsed":"(((${this} * 100) / ${load_cpu_number}) > ((${status} >= ${WARNING}) ? 175 : 200))",
			"green":null,
			"red":null,
			"value":10.34
		},

I'll give it a a few hours for the alarm to fully clear, including down delay, before trying again.

[MrZammler]

It appears ok here, ie. your delay_up_to_timestamp - last_status_change is indeed 1800, let's see.

[candlerb]

Aside: I have another similar machine. It's running v1.42.1 and only a single copy is running. But when I try to update it:

root@nuc1:~# /opt/netdata/usr/libexec/netdata/netdata-updater.sh
Wed 13 Dec 13:58:31 GMT 2023 : INFO: netdata-updater.sh:  Checking if a newer version of the updater script is available.
Wed 13 Dec 13:58:33 GMT 2023 : INFO: netdata-updater.sh:  Entering /tmp/netdata-updater-BuH1PidW5M
Wed 13 Dec 13:58:33 GMT 2023 : INFO: netdata-updater.sh:  Current Version: 00104200100000
Wed 13 Dec 13:58:33 GMT 2023 : INFO: netdata-updater.sh:  Latest Version: 00104400000036
Wed 13 Dec 13:58:33 GMT 2023 : INFO: netdata-updater.sh:  Update available
Wed 13 Dec 13:58:34 GMT 2023 : FATAL: netdata-updater.sh: FAILED TO UPDATE NETDATA:  Static binary checksum validation failed. Stopping netdata installation and leaving binary in /tmp/netdata-updater-BuH1PidW5M
Usually this is a result of an older copy of the file being cached somewhere and can be resolved by simply retrying in an hour.

It was like this a couple of hours ago. I'll re-check tomorrow.

[MrZammler]

In the mean time, I did some tests, with the ram_in_use alert, I used 3 minutes delay on up and down.

The alert was raised at 16:42:33 :

And I got the notification at 16:47 :

Upon clearing, the notification was sent 3 minutes after.

I tried a couple of more times, with up/down this alert, it appears to behave correctly here, but let's still check the case!

[candlerb]

I've re-tested today, with a manual load (yes >/dev/null & six times)

• 15:18:48 - load exceeded 4.0
• 15:49:10 - E-mail sent

So it looks like a combination of the new Netdata version, and/or getting rid of the stuck one which was hanging around, has solved the problem. Thank you!