Icinga/icingaweb2-module-vspheredb

Error Refreshing Rule Problems failed: Failed to load object

slalomsk8er opened this issue · 14 comments

Expected Behavior

No Errors.

Current Behavior

$ journalctl -f -p err
-- Logs begin at Sun 2022-11-20 20:50:18 CET. --
Nov 23 12:45:52 icinga icinga-vspheredb[35529]: [db] Refreshing Rule Problems failed: Failed to load object "b4855e0e-304e-5427-bd31-ac0b3253e0b"
Nov 23 13:05:12 icinga icinga-vspheredb[35529]: [db] Refreshing Rule Problems failed: Failed to load object "21197b0e-9733-5d77-b61f-2e10e53437e"
Nov 23 13:08:14 icinga icinga-vspheredb[35529]: [db] Refreshing Rule Problems failed: Failed to load object "28b6db72-1d07-5fa9-967e-511768d6e06"
Nov 23 13:11:16 icinga icinga-vspheredb[35529]: [db] Refreshing Rule Problems failed: Failed to load object "6a872825-d74d-5abe-9902-f415d27bd9b"
Nov 23 13:27:54 icinga icinga-vspheredb[35529]: [db] Refreshing Rule Problems failed: Failed to load object "defab1c0-de29-573f-959e-687fc0502b6"
Nov 23 13:30:46 icinga icinga-vspheredb[35529]: [db] Refreshing Rule Problems failed: Failed to load object "5f27ae46-2753-582b-9599-b8cf72a7b41"
Nov 23 13:36:46 icinga icinga-vspheredb[35529]: [db] Refreshing Rule Problems failed: Failed to load object "5469e0fa-ba9f-590b-9789-8fc5bb6e277"
Nov 23 13:40:03 icinga icinga-vspheredb[35529]: [db] Refreshing Rule Problems failed: Failed to load object "cd348ade-3c86-56ef-b177-3f0f8fb2de0"
Nov 23 13:53:22 icinga icinga-vspheredb[35529]: [db] Refreshing Rule Problems failed: Failed to load object "9d856860-c13c-59d7-93d9-a68613ab055"
Nov 23 13:59:22 icinga icinga-vspheredb[35529]: [db] Refreshing Rule Problems failed: Failed to load object "b648e69e-d8d9-597b-aa0a-371083e2a07"
Nov 23 14:18:46 icinga icinga-vspheredb[35529]: [db] Refreshing Rule Problems failed: Failed to load object "3ebfa7de-0449-5fdf-ab79-34a2a479a1ec"
Nov 23 14:21:51 icinga icinga-vspheredb[35529]: [db] Refreshing Rule Problems failed: Failed to load object "8e6dc6b4-239d-5b70-9e4a-21de56e5db1b"
Nov 23 14:24:46 icinga icinga-vspheredb[35529]: [db] Refreshing Rule Problems failed: Failed to load object "3d6e1221-efb9-53d8-8b94-f6e9529b6147"

Your Environment

Version 1.5.0

Please share the output of the following query...

SELECT
  moref,
  level,
  object_name,
  object_type,
  vc.name as vcenter,
  vc.id AS vcenter_id
FROM object o
LEFT JOIN vcenter vc ON o.vcenter_uuid = vc.instance_uuid
WHERE uuid =  UNHEX('3d6e1221efb953d88b94f6e9529b6147');

...and anonymize the object_name and vcenter column if necessary.

MariaDB [icinga_vspheredb]> SELECT
    ->   moref,
    ->   level,
    ->   object_name,
    ->   object_type,
    ->   vc.name as vcenter,
    ->   vc.id AS vcenter_id
    -> FROM object o
    -> LEFT JOIN vcenter vc ON o.vcenter_uuid = vc.instance_uuid
    -> WHERE uuid =  UNHEX('3d6e1221efb953d88b94f6e9529b6147');
Empty set (0.00 sec)

Next ones please:

SELECT COUNT(*)
  FROM host_system hs
  JOIN object o ON hs.uuid = o.uuid
  WHERE o.uuid IS NULL;

SELECT COUNT(*)
  FROM virtual_machine vm
  JOIN object o ON vm.uuid = o.uuid
  WHERE o.uuid IS NULL;

SELECT COUNT(*)
  FROM datastore ds
  JOIN object o ON ds.uuid = o.uuid
  WHERE o.uuid IS NULL;
MariaDB [icinga_vspheredb]> SELECT COUNT(*)
    ->   FROM host_system hs
    ->   JOIN object o ON hs.uuid = o.uuid
    ->   WHERE o.uuid IS NULL;
ERROR 2006 (HY000): MySQL server has gone away
No connection. Trying to reconnect...
Connection id:    25398443
Current database: icinga_vspheredb

+----------+
| COUNT(*) |
+----------+
|        0 |
+----------+
1 row in set (0.05 sec)

MariaDB [icinga_vspheredb]> 
MariaDB [icinga_vspheredb]> SELECT COUNT(*)
    ->   FROM virtual_machine vm
    ->   JOIN object o ON vm.uuid = o.uuid
    ->   WHERE o.uuid IS NULL;
+----------+
| COUNT(*) |
+----------+
|        0 |
+----------+
1 row in set (0.00 sec)

MariaDB [icinga_vspheredb]> 
MariaDB [icinga_vspheredb]> SELECT COUNT(*)
    ->   FROM datastore ds
    ->   JOIN object o ON ds.uuid = o.uuid
    ->   WHERE o.uuid IS NULL;
+----------+
| COUNT(*) |
+----------+
|        0 |
+----------+
1 row in set (0.00 sec)

I'm sorry, wrong queries. Please try these ones:

SELECT COUNT(*)
  FROM host_system hs
  LEFT JOIN object o ON hs.uuid = o.uuid
  WHERE o.uuid IS NULL;

SELECT COUNT(*)
  FROM virtual_machine vm
  LEFT JOIN object o ON vm.uuid = o.uuid
  WHERE o.uuid IS NULL;

SELECT COUNT(*)
  FROM datastore ds
  LEFT JOIN object o ON ds.uuid = o.uuid
  WHERE o.uuid IS NULL;
MariaDB [icinga_vspheredb]> SELECT COUNT(*)
    ->   FROM host_system hs
    ->   LEFT JOIN object o ON hs.uuid = o.uuid
    ->   WHERE o.uuid IS NULL;
ERROR 2006 (HY000): MySQL server has gone away
No connection. Trying to reconnect...
Connection id:    21320142
Current database: icinga_vspheredb

+----------+
| COUNT(*) |
+----------+
|        0 |
+----------+
1 row in set (0.04 sec)

MariaDB [icinga_vspheredb]> 
MariaDB [icinga_vspheredb]> SELECT COUNT(*)
    ->   FROM virtual_machine vm
    ->   LEFT JOIN object o ON vm.uuid = o.uuid
    ->   WHERE o.uuid IS NULL;
+----------+
| COUNT(*) |
+----------+
|        0 |
+----------+
1 row in set (0.02 sec)

MariaDB [icinga_vspheredb]> 
MariaDB [icinga_vspheredb]> SELECT COUNT(*)
    ->   FROM datastore ds
    ->   LEFT JOIN object o ON ds.uuid = o.uuid
    ->   WHERE o.uuid IS NULL;
+----------+
| COUNT(*) |
+----------+
|        0 |
+----------+
1 row in set (0.01 sec)

Strange... and the error still occurs, or did it stop?

Got 33 more of the same error in the meantime.

The uuid looks like a new one per error.
Can this be triggered by VDs that got destroyed?

What are destroyed VDs?

We now use "instant clones". This are virtual desktops that get destroyed after logout.
So a lot more objects could pop in and out of existence.

Sounds plausible. Could you share some more log lines, not only errors? Is it showing statistics related to created/removed VMs?

18:28:46: [api vcap01 (id=11)] Enqueued 24786 data points for VirtualNetworkAdapter
18:28:39: [api vcap01 (id=11)] Enqueued 5958 data points for HostNetworkAdapter
18:28:34: [api vdivclp01 (id=3)] VM Quick Stats: 1 new, 7355 modified, 1 deleted (got 7356 from DB, 7356 from API)
18:28:33: [api vdivclp01 (id=3)] Enqueued 2592 data points for HostNetworkAdapter
18:28:32: [api vcap01 (id=11)] Task 'Events' is already running, skipping
18:28:32: [api vdivclp01 (id=3)] Task 'Events' is already running, skipping
18:28:29: [api vcap01 (id=11)] Task 'Events' is already running, skipping
18:28:29: [api vdivclp01 (id=3)] Task 'Events' is already running, skipping
18:28:17: Changed log level to 'info'
Nov 23 18:28:34 icinga icinga-vspheredb[35529]: [api vdivclp01 (id=3)] VM Quick Stats: 1 new, 7355 modified, 1 deleted (got 7356 from DB, 7356 from API)
Nov 23 18:28:55 icinga icinga-vspheredb[35529]: [api vdivclp01 (id=3)] Virtual Machines: 2 new, 22 modified, 1 deleted (got 7355 from DB, 7356 from API)
Nov 23 18:30:34 icinga icinga-vspheredb[35529]: [api vdivclp01 (id=3)] VM Quick Stats: 0 new, 7355 modified, 1 deleted (got 7356 from DB, 7355 from API)
Nov 23 18:31:24 icinga icinga-vspheredb[35529]: [api vdivclp01 (id=3)] VM Hardware: 56 new, 0 modified, 70 deleted (got 109040 from DB, 109026 from API)
Nov 23 18:31:24 icinga icinga-vspheredb[35529]: [api vcap01 (id=11)] VM Disk Usage: 1 new, 101 modified, 1 deleted (got 5283 from DB, 5283 from API)
Nov 23 18:31:26 icinga icinga-vspheredb[35529]: [api vdivclp01 (id=3)] VM Disk Usage: 2 new, 48 modified, 4 deleted (got 6916 from DB, 6914 from API)
Nov 23 18:31:26 icinga icinga-vspheredb[35529]: [api vdivclp01 (id=3)] Managed Object References: 0 new, 0 modified, 2 deleted (got 7666 from DB, 7664 from API)
Nov 23 18:31:27 icinga icinga-vspheredb[35529]: [api vdivclp01 (id=3)] VM Datastore Usage: 1 new, 92 modified, 5 deleted (got 8014 from DB, 8010 from API)
Nov 23 18:31:43 icinga icinga-vspheredb[35529]: [api vdivclp01 (id=3)] VM Quick Stats: 0 new, 7354 modified, 1 deleted (got 7355 from DB, 7354 from API)
Nov 23 18:31:55 icinga icinga-vspheredb[35529]: [api vdivclp01 (id=3)] Virtual Machines: 0 new, 7 modified, 2 deleted (got 7356 from DB, 7354 from API)
Nov 23 18:32:38 icinga icinga-vspheredb[35529]: [api vdivclp01 (id=3)] VM Quick Stats: 1 new, 7353 modified, 1 deleted (got 7354 from DB, 7354 from API)
Nov 23 18:33:39 icinga icinga-vspheredb[35529]: [api vdivclp01 (id=3)] VM Quick Stats: 0 new, 7353 modified, 1 deleted (got 7354 from DB, 7353 from API)
Nov 23 18:34:02 icinga icinga-vspheredb[35529]: [api vdivclp01 (id=3)] VM Disk Usage: 1 new, 42 modified, 12 deleted (got 6914 from DB, 6903 from API)
Nov 23 18:34:03 icinga icinga-vspheredb[35529]: [api vdivclp01 (id=3)] Managed Object References: 1 new, 0 modified, 6 deleted (got 7664 from DB, 7659 from API)
Nov 23 18:34:04 icinga icinga-vspheredb[35529]: [api vdivclp01 (id=3)] VM Datastore Usage: 1 new, 398 modified, 11 deleted (got 8010 from DB, 8000 from API)
Nov 23 18:34:33 icinga icinga-vspheredb[35529]: [api vdivclp01 (id=3)] VM Quick Stats: 0 new, 7349 modified, 4 deleted (got 7353 from DB, 7349 from API)
Nov 23 18:34:35 icinga icinga-vspheredb[35529]: [api vdivclp01 (id=3)] Virtual Machines: 1 new, 5 modified, 6 deleted (got 7354 from DB, 7349 from API)
Nov 23 18:36:41 icinga icinga-vspheredb[35529]: [api vdivclp01 (id=3)] VM Disk Usage: 5 new, 47 modified, 1 deleted (got 6902 from DB, 6906 from API)