High load after zone reconnect due to execution of redundant checks

Description

Overview

In a HA setup, when the masters have been both disconnected from a satellite HA pair for longer than about two minutes, the hosts, which are managed by these satellites, will run a disproportionate number of checks after the masters reconnect, which, in case the clients aren't too powerful CPU-wise, may sometimes lead to a complete lockup of the system due to high load.

Detailled description

The two masters in HA mode are running in an office, using a DSL internet connection. Both are connecting to two data centers which are running two satellites in HA node each, which in turn are monitoring the hosts in their respective data center. Since the DSL connectivity isn't the best, we had a lot of disconnects in the past and I've noticed many times that the load on the hosts would get considerably high once the masters reconnect after a DSL failure.

In order to investigate this I build another system with the same characteristics, and indeed, once the masters are disconnected for at least two minutes from the satellites, all hosts which are monitored by these satellites are showing a significant load increase, often locking up the hosts.

In particular, when masters are being reconnected to the internet/satellites, monitored hosts start to receive many event::ExecuteCommand from the satellites, spawning a corresponding high number of check processes which in turn can cause considerable load. Here's one example for the scheduling on one of the hosts:

[2025-04-28 15:46:21 +0000] debug/CheckerComponent: Scheduling info for
    checkable 'node-12.it-sys-ce.de!linux-nic-dummy0' (2025-04-28 15:45:25 +0000):
    Object 'node-12.it-sys-ce.de!linux-nic-dummy0', Next Check: 2025-04-28 15:45:25 +0000(1.74586e+09).

The thing here appears to be that checks which have been scheduled for a time in the past, in this case for 15:45:25, are scheduled although we're already past this time. This will also happen for a lot of other checks from the past.

Here's the full example. First, normal operation for a (single) check which runs every 10 seconds. I'm pulling the internet connection at 15:44:00:

[2025-04-28 15:43:31 +0000] … Next Check: 2025-04-28 15:43:27 +0000(1.74586e+09).
[2025-04-28 15:43:40 +0000] … Next Check: 2025-04-28 15:43:40 +0000(1.74586e+09).
[2025-04-28 15:43:50 +0000] … Next Check: 2025-04-28 15:43:50 +0000(1.74586e+09).
[2025-04-28 15:43:59 +0000] … Next Check: 2025-04-28 15:43:59 +0000(1.74586e+09).
[2025-04-28 15:44:09 +0000] … Next Check: 2025-04-28 15:44:09 +0000(1.74586e+09).
[2025-04-28 15:44:18 +0000] … Next Check: 2025-04-28 15:44:18 +0000(1.74586e+09).
[2025-04-28 15:44:28 +0000] … Next Check: 2025-04-28 15:44:28 +0000(1.74586e+09).
[2025-04-28 15:44:37 +0000] … Next Check: 2025-04-28 15:44:37 +0000(1.74586e+09).
[2025-04-28 15:44:47 +0000] … Next Check: 2025-04-28 15:44:47 +0000(1.74586e+09).
[2025-04-28 15:44:56 +0000] … Next Check: 2025-04-28 15:44:56 +0000(1.74586e+09).
[2025-04-28 15:45:06 +0000] … Next Check: 2025-04-28 15:45:06 +0000(1.74586e+09).
[2025-04-28 15:45:15 +0000] … Next Check: 2025-04-28 15:45:15 +0000(1.74586e+09).
[2025-04-28 15:45:25 +0000] … Next Check: 2025-04-28 15:45:25 +0000(1.74586e+09).
[2025-04-28 15:45:34 +0000] … Next Check: 2025-04-28 15:45:34 +0000(1.74586e+09).
[2025-04-28 15:45:44 +0000] … Next Check: 2025-04-28 15:45:44 +0000(1.74586e+09).
[2025-04-28 15:45:54 +0000] … Next Check: 2025-04-28 15:45:54 +0000(1.74586e+09).
[2025-04-28 15:46:04 +0000] … Next Check: 2025-04-28 15:46:04 +0000(1.74586e+09).
[2025-04-28 15:46:14 +0000] … Next Check: 2025-04-28 15:46:14 +0000(1.74586e+09).

Checks have been scheduled in a regular fashion, although the masters are both disconnected, so far everything's fine. At 15:46:15 I'm reconnecting both masters:

[2025-04-28 15:46:21 +0000] … Next Check: 2025-04-28 15:45:15 +0000(1.74586e+09).
[2025-04-28 15:46:21 +0000] … Next Check: 2025-04-28 15:45:15 +0000(1.74586e+09).
[2025-04-28 15:46:21 +0000] … Next Check: 2025-04-28 15:45:15 +0000(1.74586e+09).
[2025-04-28 15:46:21 +0000] … Next Check: 2025-04-28 15:45:25 +0000(1.74586e+09).
[2025-04-28 15:46:21 +0000] … Next Check: 2025-04-28 15:45:25 +0000(1.74586e+09).
[2025-04-28 15:46:21 +0000] … Next Check: 2025-04-28 15:45:25 +0000(1.74586e+09).
[2025-04-28 15:46:21 +0000] … Next Check: 2025-04-28 15:45:34 +0000(1.74586e+09).
[2025-04-28 15:46:22 +0000] … Next Check: 2025-04-28 15:45:44 +0000(1.74586e+09).
[2025-04-28 15:46:22 +0000] … Next Check: 2025-04-28 15:45:54 +0000(1.74586e+09).
[2025-04-28 15:46:22 +0000] … Next Check: 2025-04-28 15:46:04 +0000(1.74586e+09).
[2025-04-28 15:46:23 +0000] … Next Check: 2025-04-28 15:45:34 +0000(1.74586e+09).
[2025-04-28 15:46:23 +0000] … Next Check: 2025-04-28 15:46:14 +0000(1.74586e+09).
[2025-04-28 15:46:23 +0000] … Next Check: 2025-04-28 15:46:14 +0000(1.74586e+09).
[2025-04-28 15:46:24 +0000] … Next Check: 2025-04-28 15:45:44 +0000(1.74586e+09).
[2025-04-28 15:46:25 +0000] … Next Check: 2025-04-28 15:45:54 +0000(1.74586e+09).
[2025-04-28 15:46:25 +0000] … Next Check: 2025-04-28 15:46:04 +0000(1.74586e+09).
[2025-04-28 15:46:26 +0000] … Next Check: 2025-04-28 15:46:14 +0000(1.74586e+09).
[2025-04-28 15:46:26 +0000] … Next Check: 2025-04-28 15:46:24 +0000(1.74586e+09).
[2025-04-28 15:46:27 +0000] … Next Check: 2025-04-28 15:45:54 +0000(1.74586e+09).
[2025-04-28 15:46:28 +0000] … Next Check: 2025-04-28 15:46:04 +0000(1.74586e+09).
[2025-04-28 15:46:30 +0000] … Next Check: 2025-04-28 15:46:14 +0000(1.74586e+09).
[2025-04-28 15:46:31 +0000] … Next Check: 2025-04-28 15:46:24 +0000(1.74586e+09).
[2025-04-28 15:46:32 +0000] … Next Check: 2025-04-28 15:45:44 +0000(1.74586e+09).
[2025-04-28 15:46:34 +0000] … Next Check: 2025-04-28 15:45:54 +0000(1.74586e+09).
[2025-04-28 15:46:34 +0000] … Next Check: 2025-04-28 15:45:54 +0000(1.74586e+09).
[2025-04-28 15:46:35 +0000] … Next Check: 2025-04-28 15:46:04 +0000(1.74586e+09).
[2025-04-28 15:46:37 +0000] … Next Check: 2025-04-28 15:46:14 +0000(1.74586e+09).
[2025-04-28 15:46:38 +0000] … Next Check: 2025-04-28 15:46:24 +0000(1.74586e+09).
[2025-04-28 15:46:38 +0000] … Next Check: 2025-04-28 15:46:24 +0000(1.74586e+09).
[2025-04-28 15:47:02 +0000] … Next Check: 2025-04-28 15:47:02 +0000(1.74586e+09).

As soon as the connection is re-established, a lot of checks from the past are scheduled again, leading to a massive increase in checks running in parallel (especially since the example above only shows scheduling for a single service and there are some more).

[2025-04-28 15:47:12 +0000] … Next Check: 2025-04-28 15:47:12 +0000(1.74586e+09).
[2025-04-28 15:47:21 +0000] … Next Check: 2025-04-28 15:47:21 +0000(1.74586e+09).
[2025-04-28 15:47:31 +0000] … Next Check: 2025-04-28 15:47:31 +0000(1.74586e+09).
[2025-04-28 15:47:40 +0000] … Next Check: 2025-04-28 15:47:40 +0000(1.74586e+09).
[2025-04-28 15:47:50 +0000] … Next Check: 2025-04-28 15:47:50 +0000(1.74586e+09).
[2025-04-28 15:47:59 +0000] … Next Check: 2025-04-28 15:47:59 +0000(1.74586e+09).
[2025-04-28 15:48:09 +0000] … Next Check: 2025-04-28 15:48:09 +0000(1.74586e+09).
[2025-04-28 15:48:18 +0000] … Next Check: 2025-04-28 15:48:18 +0000(1.74586e+09).
[2025-04-28 15:48:28 +0000] … Next Check: 2025-04-28 15:48:28 +0000(1.74586e+09).
[2025-04-28 15:48:37 +0000] … Next Check: 2025-04-28 15:48:37 +0000(1.74586e+09).
[2025-04-28 15:48:47 +0000] … Next Check: 2025-04-28 15:48:47 +0000(1.74586e+09).
[2025-04-28 15:48:56 +0000] … Next Check: 2025-04-28 15:48:56 +0000(1.74586e+09).
[2025-04-28 15:49:06 +0000] … Next Check: 2025-04-28 15:49:06 +0000(1.74586e+09).

Later on, the system shows normal behavior again: Checks are scheduled every ten seconds.

To Reproduce

Interrupting the connection for more than two minutes, about 2:15, is enough (at least in this environment).

Expected behavior

Checks scheduled for times in the past shouldn't be run, or at least only one check for each service at a time (as during normal operations).

Environment

• Version used (icinga2 --version):

    icinga2 - The Icinga 2 network monitoring daemon (version: r2.14.5-1)
    
    Copyright (c) 2012-2025 Icinga GmbH (https://icinga.com/)
    License GPLv2+: GNU GPL version 2 or later <https://gnu.org/licenses/gpl2.html>
    This is free software: you are free to change and redistribute it.
    There is NO WARRANTY, to the extent permitted by law.
    
    System information:
      Platform: Debian GNU/Linux
      Platform version: 11 (bullseye)
      Kernel: Linux
      Kernel version: 6.1.0-0.deb11.21-amd64
      Architecture: x86_64
    
    Build information:
      Compiler: GNU 10.2.1
      Build host: runner-hh8q3bz2-project-575-concurrent-0
      OpenSSL version: OpenSSL 1.1.1w  11 Sep 2023
    
    Application information:
    
    General paths:
      Config directory: /etc/icinga2
      Data directory: /var/lib/icinga2
      Log directory: /var/log/icinga2
      Cache directory: /var/cache/icinga2
      Spool directory: /var/spool/icinga2
      Run directory: /run/icinga2
    
    Old paths (deprecated):
      Installation root: /usr
      Sysconf directory: /etc
      Run directory (base): /run
      Local state directory: /var
    
    Internal paths:
      Package data directory: /usr/share/icinga2
      State path: /var/lib/icinga2/icinga2.state
      Modified attributes path: /var/lib/icinga2/modified-attributes.conf
      Objects path: /var/cache/icinga2/icinga2.debug
      Vars path: /var/cache/icinga2/icinga2.vars
      PID path: /run/icinga2/icinga2.pid
  

• Operating System and version is Debian 11 bullseye, uname -a gives:

    Linux medusa 6.1.0-0.deb11.21-amd64 #1 SMP PREEMPT_DYNAMIC Debian 6.1.90-1~bpo11+1 (2024-05-06) x86_64 GNU/Linux
  

• Enabled features (icinga2 feature list):

    Disabled features: command compatlog debuglog elasticsearch gelf graphite icingadb influxdb2 journald livestatus opentsdb perfdata statusdata
    Enabled features: api checker ido-pgsql influxdb mainlog notification syslog
  

• Config validation (icinga2 daemon -C):

    [2025-04-28 20:29:04 +0200] information/cli: Icinga application loader (version: r2.14.5-1)
    [2025-04-28 20:29:04 +0200] information/cli: Loading configuration file(s).
    [2025-04-28 20:29:04 +0200] information/ConfigItem: Committing config item(s).
    [2025-04-28 20:29:04 +0200] information/ApiListener: My API identity: medusa.nf.it-sys-ce.de
    [2025-04-28 20:29:04 +0200] warning/ApplyRule: Apply rule 'smtp' (in /etc/icinga2/zones.d/global-templates/services.conf: 342:1-342:20) for type 'Service' does not match anywhere!
    [2025-04-28 20:29:04 +0200] information/ConfigItem: Instantiated 2 NotificationCommands.
    [2025-04-28 20:29:04 +0200] information/ConfigItem: Instantiated 1044 Notifications.
    [2025-04-28 20:29:04 +0200] information/ConfigItem: Instantiated 1 IcingaApplication.
    [2025-04-28 20:29:04 +0200] information/ConfigItem: Instantiated 2 HostGroups.
    [2025-04-28 20:29:04 +0200] information/ConfigItem: Instantiated 35 Hosts.
    [2025-04-28 20:29:04 +0200] information/ConfigItem: Instantiated 64 Downtimes.
    [2025-04-28 20:29:04 +0200] information/ConfigItem: Instantiated 1 SyslogLogger.
    [2025-04-28 20:29:04 +0200] information/ConfigItem: Instantiated 1 FileLogger.
    [2025-04-28 20:29:04 +0200] information/ConfigItem: Instantiated 18 Zones.
    [2025-04-28 20:29:04 +0200] information/ConfigItem: Instantiated 1 InfluxdbWriter.
    [2025-04-28 20:29:04 +0200] information/ConfigItem: Instantiated 1 CheckerComponent.
    [2025-04-28 20:29:04 +0200] information/ConfigItem: Instantiated 1 IdoPgsqlConnection.
    [2025-04-28 20:29:04 +0200] information/ConfigItem: Instantiated 18 Endpoints.
    [2025-04-28 20:29:04 +0200] information/ConfigItem: Instantiated 1 ApiUser.
    [2025-04-28 20:29:04 +0200] information/ConfigItem: Instantiated 2 Users.
    [2025-04-28 20:29:04 +0200] information/ConfigItem: Instantiated 1 ApiListener.
    [2025-04-28 20:29:04 +0200] information/ConfigItem: Instantiated 1 NotificationComponent.
    [2025-04-28 20:29:04 +0200] information/ConfigItem: Instantiated 266 CheckCommands.
    [2025-04-28 20:29:04 +0200] information/ConfigItem: Instantiated 3 TimePeriods.
    [2025-04-28 20:29:04 +0200] information/ConfigItem: Instantiated 487 Services.
    [2025-04-28 20:29:04 +0200] information/ScriptGlobal: Dumping variables to file '/var/cache/icinga2/icinga2.vars'
    [2025-04-28 20:29:04 +0200] information/cli: Finished validating the configuration file(s).
  

Start with the CheckerComponent behavior around event::ExecuteCommand after the masters reconnect, using the supplied scheduling logs and the more-than-two-minute interruption to reproduce the issue. Trace why checks whose scheduled times are in the past are dispatched in parallel, then verify that reconnection no longer causes redundant executions or excessive load while normal ten-second scheduling continues.