Competing HA takeover results in both instances becoming active #787
Assignees
Labels
Milestone
Comments
oxzi
added a commit
that referenced
this issue
Sep 5, 2024
A strange HA behavior was reported in [icingadb-787], resulting in both instances being active. The logs contained an entry of the previous active instance exiting the HA.realize() method successfully after 1m9s. This, however, should not be possible as the method's context is deadlined to a minute after the heartbeat was received. With introducing Settings.QuickContextExit for retry.WithBackoff in [icinga-go-library-69] and using it here, the function directly returns a context.DeadlineExceeded error the moment the context has expired. Doing so allows directly handing over, while the other instance can now take over due to the expired heartbeat in the database. As an related change, the HA.insertEnvironment() method was inlined into the retryable function to use the deadlined context. Otherwise, this might block afterwards, as it was used within HA.realize(), but without the passed context. In addition, the main loop select cases for hactx.Done() and ctx.Done() were unified, as hactx is a derived ctx. A closed ctx case may be lost as the hactx case could have been chosen. [icinga-go-library-69]: Icinga/icinga-go-library#69 [icingadb-787]: #787
oxzi
added a commit
that referenced
this issue
Sep 5, 2024
A strange HA behavior was reported in [icingadb-787], resulting in both instances being active. The logs contained an entry of the previous active instance exiting the HA.realize() method successfully after 1m9s. This, however, should not be possible as the method's context is deadlined to a minute after the heartbeat was received. With introducing Settings.QuickContextExit for retry.WithBackoff in [icinga-go-library-69] and using it here, the function directly returns a context.DeadlineExceeded error the moment the context has expired. Doing so allows directly handing over, while the other instance can now take over due to the expired heartbeat in the database. As a related change, the HA.insertEnvironment() method was inlined into the retryable function to use the deadlined context. Otherwise, this might block afterwards, as it was used within HA.realize(), but without the passed context. In addition, the main loop select cases for hactx.Done() and ctx.Done() were unified, as hactx is a derived ctx. A closed ctx case may be lost as the hactx case could have been chosen. [icinga-go-library-69]: Icinga/icinga-go-library#69 [icingadb-787]: #787
|
In the last days, I was digging both into the HA realization logic and the context lifecycle. Regarding In the context domain, there is unfortunately no direct relationship between the HA context and the used context for database interactions. Due to the architecture, it is not so easy to let all database queries honor a derived HA context, as I initially hoped when building Icinga/icinga-go-library#68 therefore. Details about the derived contexts
|
oxzi
added a commit
that referenced
this issue
Sep 10, 2024
A strange HA behavior was reported in [icingadb-787], resulting in both instances being active. The logs contained an entry of the previous active instance exiting the HA.realize() method successfully after 1m9s. This, however, should not be possible as the method's context is deadlined to a minute after the heartbeat was received. With introducing Settings.QuickContextExit for retry.WithBackoff in [icinga-go-library-69] and using it here, the function directly returns a context.DeadlineExceeded error the moment the context has expired. Doing so allows directly handing over, while the other instance can now take over due to the expired heartbeat in the database. As a related change, the HA.insertEnvironment() method was inlined into the retryable function to use the deadlined context. Otherwise, this might block afterwards, as it was used within HA.realize(), but without the passed context. In addition, the main loop select cases for hactx.Done() and ctx.Done() were unified, as hactx is a derived ctx. A closed ctx case may be lost as the hactx case could have been chosen. [icinga-go-library-69]: Icinga/icinga-go-library#69 [icingadb-787]: #787
oxzi
added a commit
that referenced
this issue
Sep 23, 2024
A strange HA behavior was reported in #787, resulting in both instances being active. The logs contained an entry of the previous active instance exiting the HA.realize() method successfully after 1m9s. This, however, should not be possible as the method's context is deadlined to a minute after the heartbeat was received. However, as it turns out, executing COMMIT on a database transaction is not bound to the transaction's context, allowing to survive longer. To mitigate this, another context watch was introduced. Doing so allows directly handing over, while the other instance can now take over due to the expired heartbeat in the database. As a related change, the HA.insertEnvironment() method was inlined into the retryable function to use the deadlined context. Otherwise, this might block afterwards, as it was used within HA.realize(), but without the passed context. Since the retryable HA function may be executed a few times before succeeding, the inserted heartbeat value will be directly outdated. The heartbeat logic was slightly altered to always use the latest heartbeat time value. In addition, the main loop select cases for hactx.Done() and ctx.Done() were unified, as hactx is a derived ctx. A closed ctx case may be lost as the hactx case could have been chosen.
oxzi
added a commit
that referenced
this issue
Sep 24, 2024
A strange HA behavior was reported in #787, resulting in both instances being active. The logs contained an entry of the previous active instance exiting the HA.realize() method successfully after 1m9s. This, however, should not be possible as the method's context is deadlined to a minute after the heartbeat was received. However, as it turns out, executing COMMIT on a database transaction is not bound to the transaction's context, allowing to survive longer. To mitigate this, another context watch was introduced. Doing so allows directly handing over, while the other instance can now take over due to the expired heartbeat in the database. As a related change, the HA.insertEnvironment() method was inlined into the retryable function to use the deadlined context. Otherwise, this might block afterwards, as it was used within HA.realize(), but without the passed context. Since the retryable HA function may be executed a few times before succeeding, the inserted heartbeat value will be directly outdated. The heartbeat logic was slightly altered to always use the latest heartbeat time value. In addition, the main loop select cases for hactx.Done() and ctx.Done() were unified, as hactx is a derived ctx. A closed ctx case may be lost as the hactx case could have been chosen.
oxzi
added a commit
that referenced
this issue
Oct 24, 2024
A strange HA behavior was reported in #787, resulting in both instances being active. The logs contained an entry of the previous active instance exiting the HA.realize() method successfully after 1m9s. This, however, should not be possible as the method's context is deadlined to a minute after the heartbeat was received. However, as it turns out, executing COMMIT on a database transaction is not bound to the transaction's context, allowing to survive longer. To mitigate this, another context watch was introduced. Doing so allows directly handing over, while the other instance can now take over due to the expired heartbeat in the database. As a related change, the HA.insertEnvironment() method was inlined into the retryable function to use the deadlined context. Otherwise, this might block afterwards, as it was used within HA.realize(), but without the passed context. Since the retryable HA function may be executed a few times before succeeding, the inserted heartbeat value will be directly outdated. The heartbeat logic was slightly altered to always use the latest heartbeat time value. In addition, the main loop select cases for hactx.Done() and ctx.Done() were unified, as hactx is a derived ctx. A closed ctx case may be lost as the hactx case could have been chosen.
oxzi
added a commit
that referenced
this issue
Oct 25, 2024
A strange HA behavior was reported in #787, resulting in both instances being active. The logs contained an entry of the previous active instance exiting the HA.realize() method successfully after 1m9s. This, however, should not be possible as the method's context is deadlined to a minute after the heartbeat was received. However, as it turns out, executing COMMIT on a database transaction is not bound to the transaction's context, allowing to survive longer. To mitigate this, another context watch was introduced. Doing so allows directly handing over, while the other instance can now take over due to the expired heartbeat in the database.
lippserd
added
the
dev-call
|
I'm probably having the same issue with 2 1st instance 2nd instance |
|
Hi @deric, thanks for reporting! Your logs actually look fine except for the last crash. Note that both instances are allowed to write history data concurrently, i.e. while the active instance logs |
|
@deric: Thanks for posting your logs and please excuse the trouble. If possible, please supply the logs with additional fields via journalctl's JSON output ( Even if #800 also has a MySQL spin, it addresses some general HA realization topics. Is it possible to deploy a custom build in your environment? There is also #830 with more PostgreSQL specifics. How often does this happen? Was this the first time or it this a more occasional event? Was there any additional load to the database during the event? |
|
@oxzi It happens quite frequently (e.g. daily), the database runs on a dedicated physical server. There's basically no load at all until queries from both icingadb version Yes, I can deploy a custom build. Do you have pre-release packages or should I compile it from a specific branch? yet another crash:
|
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Describe the bug
Apparently there is a race condition in our HA realize handlings that can occur from time to time, causing both Icinga DB instances to become active/responsible at the same time. It is possible for the following to happen if both instances access the
icingadb_instancetable at the same time.Since both instances are trying to update that table quite often1, it is to be expected that they will deadlock each other, as can be seen in the logs.
{ "_SOURCE_REALTIME_TIMESTAMP": "2024-07-25 11:57:43", "MESSAGE": "high-availability: Can't update or insert instance. Retrying", "ICINGADB_ERROR": "can't perform \"INSERT INTO \\\"icingadb_instance\\\"...: Error 1213 (40001): Deadlock found when trying to get lock; try restarting transaction" }However, this retry mechanism also prevents new heartbeat events from being consumed from the channel and results in such weird situation.
{ "_SOURCE_REALTIME_TIMESTAMP": "2024-07-25 11:57:41", "ICINGADB_PREVIOUS": "2024-07-25 11:57:38.433795293 +0200 CEST", "ICINGADB_CURRENT": "2024-07-25 11:57:41.433328734 +0200 CEST", "MESSAGE": "heartbeat: Previous heartbeat not read from channel", }In order to prevent it from being retried endlessly, though, we have a deadline2 for the entire HA realize thing.
icingadb/pkg/icingadb/ha.go
Lines 220 to 221 in f9ce7a5
Unfortunately, if all this retry error mess then lasts for exactly one minute, and barely manages to survive the context deadline, it becomes in the end a wasted time, as after this delay the heartbeat of a given instance is already outdated, but has nevertheless been written to the database. Obviously, the current instance remains responsible, it just has written an outdated heartbeat timestamp to the database because of the deadlocks. When the passive instance finally reads that timestamp, it thinks that the other instance is no longer available and takes over the HA responsibility.
icingadb/pkg/icingadb/ha.go
Lines 319 to 321 in f9ce7a5
Having two active instances, however, does not produce any good results and brings down one of the two services.
Active IcingaDB Instance
{ "_SOURCE_REALTIME_TIMESTAMP": "2024-07-25 11:58:32", "ICINGADB_PREVIOUS": "2024-07-25 11:58:29.433879058 +0200 CEST", "ICINGADB_CURRENT": "2024-07-25 11:58:32.433682676 +0200 CEST", "MESSAGE": "heartbeat: Previous heartbeat not read from channel", }, { "_SOURCE_REALTIME_TIMESTAMP": "2024-07-25 11:58:35", "ICINGADB_PREVIOUS": "2024-07-25 11:58:32.433682676 +0200 CEST", "ICINGADB_CURRENT": "2024-07-25 11:58:35.433895608 +0200 CEST", "MESSAGE": "heartbeat: Previous heartbeat not read from channel", }, { "_SOURCE_REALTIME_TIMESTAMP": "2024-07-25 11:58:38", "ICINGADB_PREVIOUS": "2024-07-25 11:58:35.433895608 +0200 CEST", "ICINGADB_CURRENT": "2024-07-25 11:58:38.432917241 +0200 CEST", "MESSAGE": "heartbeat: Previous heartbeat not read from channel", }, { "_SOURCE_REALTIME_TIMESTAMP": "2024-07-25 11:58:41", "MESSAGE": "high-availability: Instance updated/inserted successfully after error", "ICINGADB_AFTER": "1m9.144891965s", "ICINGADB_RECOVERED_ERROR": "can't perform \"INSERT INTO \\\"icingadb_instance\\\"...: Error 1213 (40001): Deadlock found when trying to get lock; try restarting transaction", }Take a closer look at the
ICINGADB_AFTERfield of the above log entry"ICINGADB_AFTER": "1m9.144891965s"originated from this part of the code.icingadb/pkg/icingadb/ha.go
Lines 410 to 413 in f9ce7a5
The other(passive) Instance uses the heartbeat timestamp of this Instance from the database to determine that this currently active Instance is absent, by verifying that our timestamp does not exceed the
1m+ grace period of 5s limit. However, this instance has spent over a minute and 5 seconds (to be precise, it took1m9.144891965s) to record the heartbeat, so that it immediately exceeded the aforementioned limit right after the upsert.icingadb/pkg/icingadb/ha.go
Line 319 in f9ce7a5
icingadb/pkg/icingadb/ha.go
Lines 25 to 28 in f9ce7a5
Subsequently, the other Instance takes over the HA responsibility, even though this one is actually still responsible.
Passive IcingaDB Instance
{ "_SOURCE_REALTIME_TIMESTAMP": "2024-07-25 11:58:33", "MESSAGE": "high-availability: Can't update or insert instance. Retrying", "ICINGADB_ERROR": "can't commit transaction: Error 1213 (40001): Deadlock found when trying to get lock; try restarting transaction" }, { "_SOURCE_REALTIME_TIMESTAMP": "2024-07-25 11:58:41", "ICINGADB_PREVIOUS": "2024-07-25 11:58:38.302404535 +0200 CEST", "ICINGADB_CURRENT": "2024-07-25 11:58:41.299007643 +0200 CEST", "MESSAGE": "heartbeat: Previous heartbeat not read from channel", }, { "_SOURCE_REALTIME_TIMESTAMP": "2024-07-25 11:58:43", "ICINGADB_HEARTBEAT": "2024-07-25 11:57:32.259000062 +0200 CEST", "ICINGADB_HEARTBEAT_AGE": "1m11.394978989s", "MESSAGE": "high-availability: Preparing to take over HA as other instance's heartbeat has expired", }, { "_SOURCE_REALTIME_TIMESTAMP": "2024-07-25 11:58:44", "ICINGADB_PREVIOUS": "2024-07-25 11:58:41.299007643 +0200 CEST", "ICINGADB_CURRENT": "2024-07-25 11:58:44.298509894 +0200 CEST", "MESSAGE": "heartbeat: Previous heartbeat not read from channel", }, { "_SOURCE_REALTIME_TIMESTAMP": "2024-07-25 11:59:15", "MESSAGE": "high-availability: Instance updated/inserted successfully after error", "ICINGADB_AFTER": "1m3.721497393s", "ICINGADB_RECOVERED_ERROR": "can't commit transaction: Error 1213 (40001): Deadlock found when trying to get lock; try restarting transaction", },Afterwards, the passive instance also becomes active and starts its initial config sync and encounters numerous duplicate key and deadlock errors until one of the queries exceeds the retry limit of
5mand crashes the Icinga DB process.{ "_SOURCE_REALTIME_TIMESTAMP": "2024-07-25 11:59:20", "MESSAGE": "dump-signals: Received dump signal from Redis", }, { "_SOURCE_REALTIME_TIMESTAMP": "2024-07-25 12:00:20", "MESSAGE": "database: Can't execute query. Retrying", "ICINGADB_ERROR": "can't perform \"INSERT INTO \\\"host_customvar\\\"...: Error 1062 (23000): Duplicate entry '\\xDE\\xF7i\\xF9\\x9A\\xFEz\\xF6\\x8B\\x107\\xAAE\\xF0\\xBE\\xFF\\xA1Z\\xD3...' for key 'PRIMARY'" }, { "_SOURCE_REALTIME_TIMESTAMP": "2024-07-25 12:00:20", "MESSAGE": "database: Can't execute query. Retrying", "ICINGADB_ERROR": "can't perform \"INSERT INTO \\\"notification_customvar\\\"...: Error 1062 (23000): Duplicate entry '~\\x1E\\xEB\\x8B\\x8D\\xC2g\\x07\\xE4\\x8A\\xA0^\\x13\\x14\\xE0l\\xD0\\x0F\\...' for key 'PRIMARY'" }, { "_SOURCE_REALTIME_TIMESTAMP": "2024-07-25 12:00:20", "MESSAGE": "database: Can't execute query. Retrying", "ICINGADB_ERROR": "can't perform \"INSERT INTO \\\"state_history\\\"...: Error 1213 (40001): Deadlock found when trying to get lock; try restarting transaction" }, { "_SOURCE_REALTIME_TIMESTAMP": "2024-07-25 12:00:20", "MESSAGE": "database: Query retried successfully after error", "ICINGADB_AFTER": "833.661486ms", "ICINGADB_RECOVERED_ERROR": "can't perform \"INSERT INTO \\\"state_history\\\"...: Error 1213 (40001): Deadlock found when trying to get lock; try restarting transaction", }, { "_SOURCE_REALTIME_TIMESTAMP": "2024-07-25 12:04:22", "MESSAGE": "Error 1062 (23000): Duplicate entry '\\xE9\\xF6\\xC3\\x12\\xA1\\xBE\\xBCo8`h\\xBCA3\\xD72rED\\xE0' for key 'PRIMARY'\ncan't perform \"INSERT INTO \\\"host_customvar\\\" (\\\"host_id\\\", \\\"customvar_id\\\", \\\"environment_id\\\", \\\"id\\\") VALUES (:host_id, :customvar_id, :environment_id, :id)\"\ngithub.com/icinga/icingadb/internal.CantPerformQuery\n\tgithub.com/icinga/icingadb/internal/internal.go:30\ngithub.com/icinga/icingadb/pkg/icingadb.(*DB).NamedBulkExec.func1.(*DB).NamedBulkExec.func1.1.2.1\n\tgithub.com/icinga/icingadb/pkg/icingadb/db.go:412\ngithub.com/icinga/icingadb/pkg/retry.WithBackoff\n\tgithub.com/icinga/icingadb/pkg/retry/retry.go:60\ngithub.com/icinga/icingadb/pkg/icingadb.(*DB).NamedBulkExec.func1.(*DB).NamedBulkExec.func1.1.2\n\tgithub.com/icinga/icingadb/pkg/icingadb/db.go:407\ngolang.org/x/sync/errgroup.(*Group).Go.func1\n\tgolang.org/x/[email protected]/errgroup/errgroup.go:78\nruntime.goexit\n\truntime/asm_amd64.s:1695\nretry deadline exceeded\ngithub.com/icinga/icingadb/pkg/retry.WithBackoff\n\tgithub.com/icinga/icingadb/pkg/retry/retry.go:95\ngithub.com/icinga/icingadb/pkg/icingadb.(*DB).NamedBulkExec.func1.(*DB).NamedBulkExec.func1.1.2\n\tgithub.com/icinga/icingadb/pkg/icingadb/db.go:407\ngolang.org/x/sync/errgroup.(*Group).Go.func1\n\tgolang.org/x/[email protected]/errgroup/errgroup.go:78\nruntime.goexit\n\truntime/asm_amd64.s:1695", }ref/IP/48748
Additional context
Footnotes
It's a well-known fact that the Icinga 2 heartbeats arrives in Redis every 1 second, but we only read them every
3seconds and these 3 seconds are the pacesetter for HA realize thing. ↩The overall Redis heartbeat timeout is set to
1m, i.e. if we do not receive an Icinga 2 heartbeat for more than one minute, we hand over the HA responsibility. Seemingly, that very same timeout is also used as a deadline for the HA transaction retry's. ↩The text was updated successfully, but these errors were encountered: