PostgreSQL: HA exited with an error 011error="HA aborted: can't perform "INSERT INTO icingadb_instance"

[IPB-DevOps]

Describe the bug

We have two identical icinga test clusters and this issue occurs in both.

Each Setup (Virtual Machines):

• icinga01 node (icinga, icingadb, icingadb-redis)
• icinga02 node (icinga, icingadb, icingadb-redis)
• icingaweb node (icingaweb, postgresql)

The issue occurs randomly and can't be reproduce:

icinga01 node

2026-06-22T12:34:40.955726+00:00 ipb-dev-int-icinga01 icingadb[20703]: high-availability: Continuing being the active instance
2026-06-22T12:39:43.956663+00:00 ipb-dev-int-icinga01 icingadb[20703]: high-availability: Continuing being the active instance
2026-06-22T12:44:19.399559+00:00 ipb-dev-int-icinga01 icingadb[20703]: runtime-updates: Upserted 1 ServiceState items
2026-06-22T12:44:20.967376+00:00 ipb-dev-int-icinga01 icingadb[20703]: history-sync: Synced 1 state history items
2026-06-22T12:44:39.399416+00:00 ipb-dev-int-icinga01 icingadb[20703]: runtime-updates: Upserted 1 ServiceState items
2026-06-22T12:44:40.966626+00:00 ipb-dev-int-icinga01 icingadb[20703]: history-sync: Synced 1 state history items
2026-06-22T12:44:43.955238+00:00 ipb-dev-int-icinga01 icingadb[20703]: high-availability: Continuing being the active instance
2026-06-22T12:45:39.399647+00:00 ipb-dev-int-icinga01 icingadb[20703]: runtime-updates: Upserted 2 ServiceState items
2026-06-22T12:45:40.967039+00:00 ipb-dev-int-icinga01 icingadb[20703]: history-sync: Synced 2 state history items
2026-06-22T12:49:40.955640+00:00 ipb-dev-int-icinga01 icingadb[20703]: high-availability: Continuing being the active instance
2026-06-22T12:54:43.956059+00:00 ipb-dev-int-icinga01 icingadb[20703]: high-availability: Continuing being the active instance
2026-06-22T12:59:40.955815+00:00 ipb-dev-int-icinga01 icingadb[20703]: high-availability: Continuing being the active instance
2026-06-22T13:04:40.955958+00:00 ipb-dev-int-icinga01 icingadb[20703]: high-availability: Continuing being the active instance
2026-06-22T13:09:40.955656+00:00 ipb-dev-int-icinga01 icingadb[20703]: high-availability: Continuing being the active instance
2026-06-22T13:14:04.958739+00:00 ipb-dev-int-icinga01 icingadb[20703]: HA exited with an error#011error="HA aborted: can't perform \"INSERT INTO \\\"icingadb_instance\\\" (\\\"id\\\", \\\"endpoint_id\\\", \\\"responsible\\\", \\\"icinga2_version\\\", \\\"icinga2_notifications_enabled\\\", \\\"icinga2_active_host_checks_enabled\\\", \\\"icinga2_event_handlers_enabled\\\", \\\"icinga2_flap_detection_enabled\\\", \\\"icingadb_version\\\", \\\"icinga2_start_time\\\", \\\"icinga2_active_service_checks_enabled\\\", \\\"icinga2_performance_data_enabled\\\", \\\"environment_id\\\", \\\"heartbeat\\\") VALUES (:id,:endpoint_id,:responsible,:icinga2_version,:icinga2_notifications_enabled,:icinga2_active_host_checks_enabled,:icinga2_event_handlers_enabled,:icinga2_flap_detection_enabled,:icingadb_version,:icinga2_start_time,:icinga2_active_service_checks_enabled,:icinga2_performance_data_enabled,:environment_id,:heartbeat) ON CONFLICT ON CONSTRAINT pk_icingadb_instance DO UPDATE SET \\\"id\\\" = EXCLUDED.\\\"id\\\",\\\"endpoint_id\\\" = EXCLUDED.\\\"endpoint_id\\\",\\\"responsible\\\" = EXCLUDED.\\\"responsible\\\",\\\"icinga2_version\\\" = EXCLUDED.\\\"icinga2_version\\\",\\\"icinga2_notifications_enabled\\\" = EXCLUDED.\\\"icinga2_notifications_enabled\\\",\\\"icinga2_active_host_checks_enabled\\\" = EXCLUDED.\\\"icinga2_active_host_checks_enabled\\\",\\\"icinga2_event_handlers_enabled\\\" = EXCLUDED.\\\"icinga2_event_handlers_enabled\\\",\\\"icinga2_flap_detection_enabled\\\" = EXCLUDED.\\\"icinga2_flap_detection_enabled\\\",\\\"icingadb_version\\\" = EXCLUDED.\\\"icingadb_version\\\",\\\"icinga2_start_time\\\" = EXCLUDED.\\\"icinga2_start_time\\\",\\\"icinga2_active_service_checks_enabled\\\" = EXCLUDED.\\\"icinga2_active_service_checks_enabled\\\",\\\"icinga2_performance_data_enabled\\\" = EXCLUDED.\\\"icinga2_performance_data_enabled\\\",\\\"environment_id\\\" = EXCLUDED.\\\"environment_id\\\",\\\"heartbeat\\\" = EXCLUDED.\\\"heartbeat\\\"\": pq: canceling statement due to user request"

icinga02 node

2026-06-22T12:57:24.853760+00:00 ipb-dev-int-icinga02 icingadb[1080058]: high-availability: Another instance is active
2026-06-22T13:02:24.854544+00:00 ipb-dev-int-icinga02 icingadb[1080058]: high-availability: Another instance is active
2026-06-22T13:07:24.854749+00:00 ipb-dev-int-icinga02 icingadb[1080058]: high-availability: Another instance is active
2026-06-22T13:12:24.854142+00:00 ipb-dev-int-icinga02 icingadb[1080058]: high-availability: Another instance is active
2026-06-22T13:14:03.855457+00:00 ipb-dev-int-icinga02 icingadb[1080058]: high-availability: Instance update/insert exceeded heartbeat expiration time#011error="context deadline exceeded"
2026-06-22T13:14:23.238653+00:00 ipb-dev-int-icinga02 icingadb[1080058]: Taking over
2026-06-22T13:14:23.239005+00:00 ipb-dev-int-icinga02 icingadb[1080058]: Starting config sync
2026-06-22T13:14:23.239471+00:00 ipb-dev-int-icinga02 icingadb[1080058]: Starting overdue sync
2026-06-22T13:14:23.239641+00:00 ipb-dev-int-icinga02 icingadb[1080058]: Starting initial state sync
2026-06-22T13:14:23.331337+00:00 ipb-dev-int-icinga02 icingadb[1080058]: config-sync: Updating 25 items of type host state
2026-06-22T13:14:23.334545+00:00 ipb-dev-int-icinga02 icingadb[1080058]: config-sync: Updating 23 items of type dependency edge state
2026-06-22T13:14:23.343667+00:00 ipb-dev-int-icinga02 icingadb[1080058]: Starting config runtime updates sync
2026-06-22T13:14:23.353213+00:00 ipb-dev-int-icinga02 icingadb[1080058]: config-sync: Finished config sync in 113.956296ms
2026-06-22T13:14:23.386114+00:00 ipb-dev-int-icinga02 icingadb[1080058]: config-sync: Updating 356 items of type service state
2026-06-22T13:14:23.745654+00:00 ipb-dev-int-icinga02 icingadb[1080058]: config-sync: Finished initial state sync in 506.535779ms
2026-06-22T13:14:23.746019+00:00 ipb-dev-int-icinga02 icingadb[1080058]: Starting history retention
2026-06-22T13:14:23.746316+00:00 ipb-dev-int-icinga02 icingadb[1080058]: Starting state runtime updates sync
2026-06-22T13:14:24.858652+00:00 ipb-dev-int-icinga02 icingadb[1080058]: history-sync: Synced 6 state history items
2026-06-22T13:14:43.746855+00:00 ipb-dev-int-icinga02 icingadb[1080058]: runtime-updates: Upserted 4 ServiceState items
2026-06-22T13:14:44.858140+00:00 ipb-dev-int-icinga02 icingadb[1080058]: history-sync: Synced 4 state history items
2026-06-22T13:15:03.746991+00:00 ipb-dev-int-icinga02 icingadb[1080058]: runtime-updates: Upserted 3 ServiceState items
2026-06-22T13:15:04.858985+00:00 ipb-dev-int-icinga02 icingadb[1080058]: history-sync: Synced 3 state history items
2026-06-22T13:17:03.747647+00:00 ipb-dev-int-icinga02 icingadb[1080058]: runtime-updates: Upserted 1 ServiceState items
2026-06-22T13:17:04.858443+00:00 ipb-dev-int-icinga02 icingadb[1080058]: history-sync: Synced 1 state history items
2026-06-22T13:17:24.854271+00:00 ipb-dev-int-icinga02 icingadb[1080058]: high-availability: Continuing being the active instance
2026-06-22T13:19:03.747373+00:00 ipb-dev-int-icinga02 icingadb[1080058]: runtime-updates: Upserted 1 ServiceState items
2026-06-22T13:19:04.858439+00:00 ipb-dev-int-icinga02 icingadb[1080058]: history-sync: Synced 1 state history items
2026-06-22T13:22:24.853446+00:00 ipb-dev-int-icinga02 icingadb[1080058]: high-availability: Continuing being the active instance
2026-06-22T13:27:24.853735+00:00 ipb-dev-int-icinga02 icingadb[1080058]: high-availability: Continuing being the active instance
2026-06-22T13:32:24.854304+00:00 ipb-dev-int-icinga02 icingadb[1080058]: high-availability: Continuing being the active instance
2026-06-22T13:37:24.854324+00:00 ipb-dev-int-icinga02 icingadb[1080058]: high-availability: Continuing being the active instance
2026-06-22T13:42:24.853864+00:00 ipb-dev-int-icinga02 icingadb[1080058]: high-availability: Continuing being the active instance
2026-06-22T13:47:24.854090+00:00 ipb-dev-int-icinga02 icingadb[1080058]: high-availability: Continuing being the active instance
2026-06-22T13:52:24.853636+00:00 ipb-dev-int-icinga02 icingadb[1080058]: high-availability: Continuing being the active instance
2026-06-22T13:57:24.853426+00:00 ipb-dev-int-icinga02 icingadb[1080058]: high-availability: Continuing being the active instance

icingaweb node

2026-06-22 12:31:25.680 UTC [434115] LOG:  checkpoint complete: wrote 5 buffers (0.0%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.503 s, sync=0.003 s, total=0.513 s; sync files=3, longest=0.002 s, average=0.001 s; distance=70 kB, estimate=74 kB; lsn=0/21B7B868, redo lsn=0/21B7B810
2026-06-22 12:36:25.775 UTC [434115] LOG:  checkpoint starting: time
2026-06-22 12:36:26.286 UTC [434115] LOG:  checkpoint complete: wrote 5 buffers (0.0%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.503 s, sync=0.003 s, total=0.512 s; sync files=3, longest=0.002 s, average=0.001 s; distance=73 kB, estimate=74 kB; lsn=0/21B96128, redo lsn=0/21B8DCB0
2026-06-22 12:41:25.385 UTC [434115] LOG:  checkpoint starting: time
2026-06-22 12:41:25.896 UTC [434115] LOG:  checkpoint complete: wrote 5 buffers (0.0%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.503 s, sync=0.003 s, total=0.512 s; sync files=3, longest=0.002 s, average=0.001 s; distance=76 kB, estimate=76 kB; lsn=0/21BA0D80, redo lsn=0/21BA0D28
2026-06-22 12:43:43.954 UTC [434122] icingadb@db_icingadb ERROR:  could not serialize access due to read/write dependencies among transactions
2026-06-22 12:43:43.954 UTC [434122] icingadb@db_icingadb DETAIL:  Reason code: Canceled on identification as a pivot, during write.
2026-06-22 12:43:43.954 UTC [434122] icingadb@db_icingadb HINT:  The transaction might succeed if retried.
2026-06-22 12:43:43.954 UTC [434122] icingadb@db_icingadb STATEMENT:  INSERT INTO "icingadb_instance" ("id", "endpoint_id", "responsible", "icinga2_version", "icinga2_notifications_enabled", "icinga2_active_host_checks_enabled", "icinga2_event_handlers_enabled", "icinga2_flap_detection_enabled", "icingadb_version", "
icinga2_start_time", "icinga2_active_service_checks_enabled", "icinga2_performance_data_enabled", "environment_id", "heartbeat") VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14) ON CONFLICT ON CONSTRAINT pk_icingadb_instance DO UPDATE SET "id" = EXCLUDED."id","endpoint_id" = EXCLUDED."endpoint_id","responsible
" = EXCLUDED."responsible","icinga2_version" = EXCLUDED."icinga2_version","icinga2_notifications_enabled" = EXCLUDED."icinga2_notifications_enabled","icinga2_active_host_checks_enabled" = EXCLUDED."icinga2_active_host_checks_enabled","icinga2_event_handlers_enabled" = EXCLUDED."icinga2_event_handlers_enabled","icinga
2_flap_detection_enabled" = EXCLUDED."icinga2_flap_detection_enabled","icingadb_version" = EXCLUDED."icingadb_version","icinga2_start_time" = EXCLUDED."icinga2_start_time","icinga2_active_service_checks_enabled" = EXCLUDED."icinga2_active_service_checks_enabled","icinga2_performance_data_enabled" = EXCLUDED."icinga2_
performance_data_enabled","environment_id" = EXCLUDED."environment_id","heartbeat" = EXCLUDED."heartbeat"
2026-06-22 12:46:25.996 UTC [434115] LOG:  checkpoint starting: time
2026-06-22 12:46:31.324 UTC [434115] LOG:  checkpoint complete: wrote 53 buffers (0.3%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=5.317 s, sync=0.005 s, total=5.329 s; sync files=32, longest=0.001 s, average=0.001 s; distance=330 kB, estimate=330 kB; lsn=0/21BF84B8, redo lsn=0/21BF3838
2026-06-22 12:51:25.425 UTC [434115] LOG:  checkpoint starting: time
2026-06-22 12:51:25.939 UTC [434115] LOG:  checkpoint complete: wrote 5 buffers (0.0%), wrote 2 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.504 s, sync=0.004 s, total=0.515 s; sync files=3, longest=0.002 s, average=0.002 s; distance=67 kB, estimate=304 kB; lsn=0/21C04770, redo lsn=0/21C04718
2026-06-22 12:56:26.035 UTC [434115] LOG:  checkpoint starting: time
2026-06-22 12:56:26.547 UTC [434115] LOG:  checkpoint complete: wrote 5 buffers (0.0%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.504 s, sync=0.003 s, total=0.513 s; sync files=3, longest=0.002 s, average=0.001 s; distance=73 kB, estimate=281 kB; lsn=0/21C1DDF8, redo lsn=0/21C16D48
2026-06-22 13:01:26.647 UTC [434115] LOG:  checkpoint starting: time
2026-06-22 13:01:27.160 UTC [434115] LOG:  checkpoint complete: wrote 5 buffers (0.0%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.504 s, sync=0.003 s, total=0.513 s; sync files=3, longest=0.002 s, average=0.001 s; distance=73 kB, estimate=260 kB; lsn=0/21C294A0, redo lsn=0/21C29448
2026-06-22 13:06:26.259 UTC [434115] LOG:  checkpoint starting: time
2026-06-22 13:06:26.773 UTC [434115] LOG:  checkpoint complete: wrote 5 buffers (0.0%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.505 s, sync=0.003 s, total=0.514 s; sync files=3, longest=0.002 s, average=0.001 s; distance=72 kB, estimate=241 kB; lsn=0/21C426D0, redo lsn=0/21C3B590
2026-06-22 13:11:26.855 UTC [434115] LOG:  checkpoint starting: time
2026-06-22 13:11:27.369 UTC [434115] LOG:  checkpoint complete: wrote 5 buffers (0.0%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.504 s, sync=0.003 s, total=0.514 s; sync files=3, longest=0.002 s, average=0.001 s; distance=72 kB, estimate=224 kB; lsn=0/21C4D7B0, redo lsn=0/21C4D758
2026-06-22 13:14:04.956 UTC [434122] icingadb@db_icingadb ERROR:  canceling statement due to user request
2026-06-22 13:14:04.956 UTC [434122] icingadb@db_icingadb CONTEXT:  while locking tuple (0,43) in relation "icingadb_instance"
2026-06-22 13:14:04.956 UTC [434122] icingadb@db_icingadb STATEMENT:  INSERT INTO "icingadb_instance" ("id", "endpoint_id", "responsible", "icinga2_version", "icinga2_notifications_enabled", "icinga2_active_host_checks_enabled", "icinga2_event_handlers_enabled", "icinga2_flap_detection_enabled", "icingadb_version", "
icinga2_start_time", "icinga2_active_service_checks_enabled", "icinga2_performance_data_enabled", "environment_id", "heartbeat") VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14) ON CONFLICT ON CONSTRAINT pk_icingadb_instance DO UPDATE SET "id" = EXCLUDED."id","endpoint_id" = EXCLUDED."endpoint_id","responsible
" = EXCLUDED."responsible","icinga2_version" = EXCLUDED."icinga2_version","icinga2_notifications_enabled" = EXCLUDED."icinga2_notifications_enabled","icinga2_active_host_checks_enabled" = EXCLUDED."icinga2_active_host_checks_enabled","icinga2_event_handlers_enabled" = EXCLUDED."icinga2_event_handlers_enabled","icinga
2_flap_detection_enabled" = EXCLUDED."icinga2_flap_detection_enabled","icingadb_version" = EXCLUDED."icingadb_version","icinga2_start_time" = EXCLUDED."icinga2_start_time","icinga2_active_service_checks_enabled" = EXCLUDED."icinga2_active_service_checks_enabled","icinga2_performance_data_enabled" = EXCLUDED."icinga2_
performance_data_enabled","environment_id" = EXCLUDED."environment_id","heartbeat" = EXCLUDED."heartbeat"
2026-06-22 13:16:26.455 UTC [434115] LOG:  checkpoint starting: time
2026-06-22 13:16:46.729 UTC [434115] LOG:  checkpoint complete: wrote 202 buffers (1.2%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=20.263 s, sync=0.005 s, total=20.275 s; sync files=48, longest=0.002 s, average=0.001 s; distance=1355 kB, estimate=1355 kB; lsn=0/21DA23D8, redo lsn=0/21DA
04C0
2026-06-22 13:21:26.826 UTC [434115] LOG:  checkpoint starting: time
2026-06-22 13:21:31.554 UTC [434115] LOG:  checkpoint complete: wrote 47 buffers (0.3%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=4.717 s, sync=0.004 s, total=4.728 s; sync files=23, longest=0.003 s, average=0.001 s; distance=267 kB, estimate=1246 kB; lsn=0/21DE3870, redo lsn=0/21DE32F0
2026-06-22 13:26:26.651 UTC [434115] LOG:  checkpoint starting: time
2026-06-22 13:26:27.164 UTC [434115] LOG:  checkpoint complete: wrote 5 buffers (0.0%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.503 s, sync=0.003 s, total=0.513 s; sync files=3, longest=0.002 s, average=0.001 s; distance=44 kB, estimate=1126 kB; lsn=0/21DEE620, redo lsn=0/21DEE590
2026-06-22 13:31:26.195 UTC [434115] LOG:  checkpoint starting: time
2026-06-22 13:31:26.709 UTC [434115] LOG:  checkpoint complete: wrote 5 buffers (0.0%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.504 s, sync=0.003 s, total=0.514 s; sync files=3, longest=0.002 s, average=0.001 s; distance=47 kB, estimate=1018 kB; lsn=0/21E01330, redo lsn=0/21DFA200
2026-06-22 13:36:26.800 UTC [434115] LOG:  checkpoint starting: time

Sometimes the second node fails also which results in complete failed cluster (from icingaweb view).

Your Environment

Include as many relevant details about the environment you experienced the problem in

• Icinga DB version: v1.5.1
• Icinga 2 version: r2.16.1-1
• Operating System and version: Ubuntu 26.04 LTS

Best regards!

[oxzi]

Thank you for reporting this issue and providing the logs, especially the database logs. We had seen similar behavior internally, but were unable to debug it properly. We are going to take a closer look and work on a fix.

[oxzi]

Thanks once again for creating this issue. As we had this in the past and I was curious, I have successfully distracted myself from my current work and debugged it once more. The following contains a semi-structured analysis with a hopefully fix, which I am going to submit as a PR later.

---

2026-06-22 13:14:04.956 UTC [434122] icingadb@db_icingadb ERROR:  canceling statement due to user request
2026-06-22 13:14:04.956 UTC [434122] icingadb@db_icingadb CONTEXT:  while locking tuple (0,43) in relation "icingadb_instance"
2026-06-22 13:14:04.956 UTC [434122] icingadb@db_icingadb STATEMENT:  INSERT INTO "icingadb_instance" ("id", "endpoint_id", "responsible", "icinga2_version", "icinga2_notifications_enabled", "icinga2_active_host_checks_enabled", "icinga2_event_handlers_enabled", "icinga2_flap_detection_enabled", "icingadb_version", "
icinga2_start_time", "icinga2_active_service_checks_enabled", "icinga2_performance_data_enabled", "environment_id", "heartbeat") VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14) ON CONFLICT ON CONSTRAINT pk_icingadb_instance DO UPDATE SET "id" = EXCLUDED."id","endpoint_id" = EXCLUDED."endpoint_id","responsible
" = EXCLUDED."responsible","icinga2_version" = EXCLUDED."icinga2_version","icinga2_notifications_enabled" = EXCLUDED."icinga2_notifications_enabled","icinga2_active_host_checks_enabled" = EXCLUDED."icinga2_active_host_checks_enabled","icinga2_event_handlers_enabled" = EXCLUDED."icinga2_event_handlers_enabled","icinga
2_flap_detection_enabled" = EXCLUDED."icinga2_flap_detection_enabled","icingadb_version" = EXCLUDED."icingadb_version","icinga2_start_time" = EXCLUDED."icinga2_start_time","icinga2_active_service_checks_enabled" = EXCLUDED."icinga2_active_service_checks_enabled","icinga2_performance_data_enabled" = EXCLUDED."icinga2_
performance_data_enabled","environment_id" = EXCLUDED."environment_id","heartbeat" = EXCLUDED."heartbeat"

The quoted PostgreSQL log complains about a lock for the UPSERT query on the icingadb_instance table. This query is only fired in the HA realization logic, within an SQL transaction.

icingadb/pkg/icingadb/ha.go

Lines 366 to 369 in 12f8c6e

	stmt, _ := h.db.BuildUpsertStmt(i)
	if _, err := tx.NamedExecContext(ctx, stmt, i); err != nil {
	return database.CantPerformQuery(err, stmt)
	}

---

2026-06-22T13:14:04.958739+00:00 ipb-dev-int-icinga01 icingadb[20703]: HA exited with an error#011error="HA aborted: can't perform \"INSERT INTO \\\"icingadb_instance\\\" (\\\"id\\\", \\\"endpoint_id\\\", \\\"responsible\\\", \\\"icinga2_version\\\", \\\"icinga2_notifications_enabled\\\", \\\"icinga2_active_host_checks_enabled\\\", \\\"icinga2_event_handlers_enabled\\\", \\\"icinga2_flap_detection_enabled\\\", \\\"icingadb_version\\\", \\\"icinga2_start_time\\\", \\\"icinga2_active_service_checks_enabled\\\", \\\"icinga2_performance_data_enabled\\\", \\\"environment_id\\\", \\\"heartbeat\\\") VALUES (:id,:endpoint_id,:responsible,:icinga2_version,:icinga2_notifications_enabled,:icinga2_active_host_checks_enabled,:icinga2_event_handlers_enabled,:icinga2_flap_detection_enabled,:icingadb_version,:icinga2_start_time,:icinga2_active_service_checks_enabled,:icinga2_performance_data_enabled,:environment_id,:heartbeat) ON CONFLICT ON CONSTRAINT pk_icingadb_instance DO UPDATE SET \\\"id\\\" = EXCLUDED.\\\"id\\\",\\\"endpoint_id\\\" = EXCLUDED.\\\"endpoint_id\\\",\\\"responsible\\\" = EXCLUDED.\\\"responsible\\\",\\\"icinga2_version\\\" = EXCLUDED.\\\"icinga2_version\\\",\\\"icinga2_notifications_enabled\\\" = EXCLUDED.\\\"icinga2_notifications_enabled\\\",\\\"icinga2_active_host_checks_enabled\\\" = EXCLUDED.\\\"icinga2_active_host_checks_enabled\\\",\\\"icinga2_event_handlers_enabled\\\" = EXCLUDED.\\\"icinga2_event_handlers_enabled\\\",\\\"icinga2_flap_detection_enabled\\\" = EXCLUDED.\\\"icinga2_flap_detection_enabled\\\",\\\"icingadb_version\\\" = EXCLUDED.\\\"icingadb_version\\\",\\\"icinga2_start_time\\\" = EXCLUDED.\\\"icinga2_start_time\\\",\\\"icinga2_active_service_checks_enabled\\\" = EXCLUDED.\\\"icinga2_active_service_checks_enabled\\\",\\\"icinga2_performance_data_enabled\\\" = EXCLUDED.\\\"icinga2_performance_data_enabled\\\",\\\"environment_id\\\" = EXCLUDED.\\\"environment_id\\\",\\\"heartbeat\\\" = EXCLUDED.\\\"heartbeat\\\"\": pq: canceling statement due to user request"

This is how the active node went down. Within this exhausting line, there is

1. the same query as above as the failing one,
2. and the PostgreSQL error canceling statement due to user request.

The PostgreSQL error has the number 57014 and was the same one a colleague of mine had.

Backtracking this in the code, brings us to:

1. A non-context error returned from the HA realization.
   

   icingadb/pkg/icingadb/ha.go

   Lines 221 to 223 in 12f8c6e

   	if err != nil {
   	h.abort(err)
   	}

2. And again to the same query as above.
   

   icingadb/pkg/icingadb/ha.go

   Lines 366 to 369 in 12f8c6e

   	stmt, _ := h.db.BuildUpsertStmt(i)
   	if _, err := tx.NamedExecContext(ctx, stmt, i); err != nil {
   	return database.CantPerformQuery(err, stmt)
   	}

---

Considering two concurrent transactions from both nodes:

1. The inactive node locks the row of the active node during its transaction:
   

   icingadb/pkg/icingadb/ha.go

   Lines 302 to 306 in 12f8c6e

   	query := h.db.Rebind("SELECT id, heartbeat FROM icingadb_instance " +
   	"WHERE environment_id = ? AND responsible = ? AND id <> ? FOR UPDATE")
   	instance := &v1.IcingadbInstance{}
   	errQuery := tx.QueryRowxContext(ctx, query, envId, "y", h.instanceId).StructScan(instance)

   
   It detects the other node and continues with UPSERTing its own row.
2. The active node runs the same query, gets no result and continues with the UPSERT of its own row - locked in the other transaction and maybe take a while until the lock was removed. However, the lock never disappears, but we have a canceling statement due to user request error.

---

Note: Everything so far were observations from the logs and the code. The following are assumptions.

How can we get to a "user" cancellation? The database transaction is bound to a Go context, which has a deadline in this case, being bound to the heartbeat.

1. icingadb/pkg/icingadb/ha.go

   Line 289 in 12f8c6e

   tx, errBegin := h.db.BeginTxx(ctx, &sql.TxOptions{Isolation: isoLvl})

2. icingadb/pkg/icingadb/ha.go

   Lines 210 to 211 in 12f8c6e

   	realizeCtx, cancelRealizeCtx := context.WithDeadline(h.ctx, m.ExpiryTime())
   	err = h.realize(realizeCtx, s, envId, infoLogRoutineEvents)

When the context finishes during the UPSERT query - which might take longer due to the lock -, the query (and the transaction) fails. The error is a pq.Error, being wrapped via database.CantPerformQuery, returned to the retry.WithBackoff loop.

https://github.com/Icinga/icinga-go-library/blob/faef23cbd4c9c5f2adffaaed1bfd6ff54afe6777/retry/retry.go#L65-L78

There, it will directly be returned as ctx.Err() == context.DeadlineExceeded, but, for reasons documented there, the original error will be returned instead, and not context.DeadlineExceeded, where the later code would act upon.

Btw, while an HA setup makes this issue more likely, this might also happen for a single node setup, when the deadline exceeds during the transaction.

When those assumptions are correct, a fix could be as simple as:

diff --git a/pkg/icingadb/ha.go b/pkg/icingadb/ha.go
index 3305b8b1..ce2b99a6 100644
--- a/pkg/icingadb/ha.go
+++ b/pkg/icingadb/ha.go
@@ -210,7 +210,7 @@ func (h *HA) controller() {
                                realizeCtx, cancelRealizeCtx := context.WithDeadline(h.ctx, m.ExpiryTime())
                                err = h.realize(realizeCtx, s, envId, infoLogRoutineEvents)
                                cancelRealizeCtx()
-                               if errors.Is(err, context.DeadlineExceeded) {
+                               if errors.Is(err, context.DeadlineExceeded) || errors.Is(realizeCtx.Err(), context.DeadlineExceeded) {
                                        h.logger.Warnw("Instance update/insert exceeded heartbeat expiration time", zap.Error(err))
                                        h.signalHandover("instance update/insert deadline exceeded heartbeat expiry time")

To ensure that the context.CancelFunc does not mess up, I have mocked this in the Go Playground. Now, I am going to create a PR.

[IPB-DevOps]

I'm very glad to hear from you again, very thanks for the detailed infomration.
Thanks for this very quick repsonse!

Best regards!

[yhabteab]

Hi, thanks for reporting again!

The referenced PR is going to fix this but since we can't reproduce it, we couldn't verify the fix. So if your issue is still not fixed after the next Icinga DB release, feel free to reopen this issue again.