IcngaDB fails with: Prepared statement contains too many placeholders - Overdue indicators not chunked

[dmitriy-terzeman]

Description

In high loaded environment i'm facing IcngaDB crash with the following errors:

Mar 31 08:56:44 p3i212t4-idb systemd: Started Icinga DB.
Mar 31 08:56:44 p3i212t4-idb icingadb: time="2020-03-31T08:56:44-07:00" level=info msg="Connecting to Redis"
Mar 31 08:56:44 p3i212t4-idb icingadb: time="2020-03-31T08:56:44-07:00" level=info msg="Connecting to MySQL"
Mar 31 08:56:44 p3i212t4-idb icingadb: time="2020-03-31T08:56:44-07:00" level=info msg="Redis connection established"
Mar 31 08:56:44 p3i212t4-idb icingadb: time="2020-03-31T08:56:44-07:00" level=info msg="Starting heartbeat listener"
Mar 31 08:56:44 p3i212t4-idb icingadb: time="2020-03-31T08:56:44-07:00" level=info msg="SQL connection established"
Mar 31 08:56:44 p3i212t4-idb icingadb: time="2020-03-31T08:56:44-07:00" level=info msg="Got initial environment." UUID=e727d600-79fe-4cfb-b636-83e5a7ccd7a8 context=HA environment=da39a3ee5e6b4b0d3255bfef95601890afd80709
Mar 31 08:56:44 p3i212t4-idb icingadb: time="2020-03-31T08:56:44-07:00" level=info msg="Taking over." UUID=e727d600-79fe-4cfb-b636-83e5a7ccd7a8 context=HA environment=da39a3ee5e6b4b0d3255bfef95601890afd80709
Mar 31 08:56:46 p3i212t4-idb icingadb: time="2020-03-31T08:56:46-07:00" level=fatal msg="Error 1390: Prepared statement contains too many placeholders"
Mar 31 08:56:46 p3i212t4-idb systemd: icingadb.service: main process exited, code=exited, status=1/FAILURE
Mar 31 08:56:46 p3i212t4-idb systemd: Unit icingadb.service entered failed state.
Mar 31 08:56:46 p3i212t4-idb systemd: icingadb.service failed.

How to reproduce:

Currently i have lack of info for deeper diagnostics and not able to reproduce it, error occurs randomly on high loaded environment with 100k services per minute.

Environment:

Standalone icinga2 master: 8 cores / 16 GB ram
2 Satellite zones in HA(4 icinga2 instances as satellites): 8 cores / 16 GB ram
1 IcingaDB + Redis on dedicated host: 8 cores / 16 GB ram
MySQL cluster on dedicated hosts: 8 cores / 16 GB ram
CentOS Linux release 7.7.1908 (Core) on each server
Amount of active services: 102010 services per minute

Please let me know if i can provide any additional debug information for you.
With best regards,
Dmitriy.

[N-o-X]

Hey @dmitriy-terzeman, thank you for reporting!

The best thing you can do to help, is to enable debug logging in /etc/icingadb/icingadb.ini:

[logging]
level="debug"

Cheers
Noah

[dmitriy-terzeman]

Hello @N-o-X , sorry for the delay with reply, i've played around with it and was able to finally reproduce the bug.

for reproduction you need a really high loaded environment, 100k services with 1 minute frequency or more.
In my case i need only to restart / reload icinga2 master to cause this crash on icingadb

I think it's related with the redis stream queue and limitation for insert in MySQL(in a single transaction), due to the long icinga2 master restart/reload a lot of services misses actual state and icingadb try to update it in bulk, on high load you are getting too big queue.

Also i've did some research on the error name and looks like it related to mysql driver, also found some good topics on https://stackoverflow.com/questions/18100782/import-of-50k-records-in-mysql-gives-general-error-1390-prepared-statement-con

Need to checkout how we slice array of messages to not reach the limit:

icingadb/connection/mysql.go

Line 693 in 49891df

finalRows := make([]Row, 0)

Debug log is not readable in this case:

,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,
Apr 21 10:09:35 p3i212t4-idb icingadb: ?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)"
Apr 21 10:09:35 p3i212t4-idb icingadb: time="2020-04-21T10:09:35-07:00" level=debug msg="1 service state will be synced"
Apr 21 10:09:35 p3i212t4-idb icingadb: time="2020-04-21T10:09:35-07:00" level=debug msg="1 state history entries will be synced"
Apr 21 10:09:35 p3i212t4-idb icingadb: time="2020-04-21T10:09:35-07:00" level=fatal msg="Error 1390: Prepared statement contains too many placeholders"

the first line is really big i inserted only part of it to show how it looks, i can send full debug log if you interested in inspecting it.

With best regards,
Dmitriy

[mwaldmueller]

Same problem here:

Apr 23 08:36:13 idb3.localdomain icingadb[1596]: ?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,
Apr 23 08:36:13 idb3.localdomain icingadb[1596]: time="2020-04-23T08:36:12+02:00" level=debug msg="Finished Exec" affected_rows=2 args="{[[166 10 221 9 183 213 50 89 2
Apr 23 08:36:13 idb3.localdomain icingadb[1596]: time="2020-04-23T08:36:12+02:00" level=debug msg="Finished Exec" affected_rows=1 args="{[[238 253 152 43 91 196 70 110
Apr 23 08:36:13 idb3.localdomain icingadb[1596]: time="2020-04-23T08:36:12+02:00" level=debug msg="Finished Exec" affected_rows=1000 args="{[[20 23 121 134 121 189 127
Apr 23 08:36:13 idb3.localdomain icingadb[1596]: 50 99 237 190 232 77 79 251 249 0 25 234] [27 97 139 9 126 179 56 72 124 147 10 244 253 116 159 45 134 208 110 67] [27
Apr 23 08:36:13 idb3.localdomain icingadb[1596]: time="2020-04-23T08:36:13+02:00" level=debug msg="Finished Exec" affected_rows=2 args="{[[109 184 130 238 156 189 176
Apr 23 08:36:13 idb3.localdomain icingadb[1596]: time="2020-04-23T08:36:13+02:00" level=debug msg="Finished Exec" affected_rows=1 args="{[[81 93 177 24 39 47 65 32 143
Apr 23 08:36:13 idb3.localdomain icingadb[1596]: time="2020-04-23T08:36:13+02:00" level=fatal msg="Error 1390: Prepared statement contains too many placeholders"
Apr 23 08:36:13 idb3.localdomain systemd[1]: icingadb.service: Main process exited, code=exited, status=1/FAILURE
Apr 23 08:36:13 idb3.localdomain systemd[1]: icingadb.service: Failed with result 'exit-code'.

Versions:
icinga2: v2.12.0-rc1
icingadb: v1.0.0-rc1
icingaweb2: v2.8.0-rc1
icingadb-web: v1.0.0-rc1
mariadb Ver 15.1 Distrib 10.3.22-MariaDB, for debian-linux-gnu (x86_64) using readline 5.2

[mwaldmueller]

It only happens with a huge amount of objects (I played around with 25.000 Hosts/250.000 Services). But neither a restart of icingadb.service, a reboot of the entire system or reducing the objects (e.g. to 1 Host/10 Services) don't solve the problem. The icingadb.service still denies to start with the prior error message.

[lippserd]

We'll fix this asap.

[N-o-X]

@dmitriy-terzeman @mwaldmueller could you, if possible, please test this PR (#165)?

Packages:

• CentOS 7: https://git.icinga.com/packaging/rpm-icingadb/-/jobs/48125/artifacts/browse/build/RPMS/x86_64/
• Debian 10: https://git.icinga.com/packaging/deb-icingadb/-/jobs/48122/artifacts/browse/build/

Thanks in advance!

[dmitriy-terzeman]

Hello @N-o-X,
does those packages include fix in #165 or only #65 ?
should i re-import MySQL schema to apply changes?

With best regards,
Dmitriy

[N-o-X]

@dmitriy-terzeman sorry, I did mean #165 not #65 :D

[dmitriy-terzeman]

ohh, ok :D
Will try to provide test results next week

With best regards,
Dmitriy

[mwaldmueller]

Thanks, but I still got the error:

Apr 24 11:39:18 idb3.localdomain icingadb[989]: time="2020-04-24T11:39:18+02:00" level=fatal msg="Error 1390: Prepared statement contains too many placeholders"
Apr 24 11:39:18 idb3.localdomain systemd[1]: icingadb.service: Main process exited, code=exited, status=1/FAILURE
Apr 24 11:39:18 idb3.localdomain systemd[1]: icingadb.service: Failed with result 'exit-code'.

root@idb3:~# dpkg -l | grep icingadb
ii  icingadb                             1.0.0+rc1.17.gfbdd034.20200423.1434+buster-0 amd64        database connector for Icinga 2
ii  icingadb-redis                       1.0.0+rc1.17.gfbdd034.20200423.1434+buster-0 amd64        Redis service for Icinga DB

[N-o-X]

Okay, please try the following:

1. Disable all Icinga 2 objects and restart Icinga 2
   => Still crashes? Could be state related
2. Clear your state streams in Redis (del icinga:state:stream:host icinga:state:stream:service) (still all objects disabled)
   => Still crashes? Could be history related
3. Clear your history streams in Redis (del icinga:history:stream:flapping icinga:history:stream:state icinga:history:stream:notification icinga:history:stream:usernotification icinga:history:stream:downtime icinga:history:stream:comment icinga:history:stream:acknowledgement) (still all objects disabled)

If it still crashes after that, we'll need to dig deeper. Thanks for helping!

[dmitriy-terzeman]

@N-o-X what should be done to check if its Overdue related? i saw a lot of updates on that front

[N-o-X]

@dmitriy-terzeman that could really be it! Try the following:

1. Stop Icinga 2 & Icinga DB
2. Disable all services/hosts
3. Delete all overdue related keys in Redis (icinga-redis-cli): del icinga:nextupdate:host icinga:nextupdate:service icingadb:overdue:host icingadb:overdue:service
4. Start Icinga 2 & Icinga DB

Our overdue code doesn't have any chunking mechanism, so it's something that can break for sure.

[dmitriy-terzeman]

And its most "updated" part as i can see now, since i don't have too much state changes or history (most of the checks that i have - dummy checks, i use them for simple load tests)

P.S. I use 1min frequency checks, and server reload on the big environment can take more then 1min

[mwaldmueller]

@dmitriy-terzeman that could really be it! Try the following:

1. Stop Icinga 2 & Icinga DB
2. Disable all services/hosts
3. Delete all overdue related keys in Redis (icinga-redis-cli): del icinga:nextupdate:host icinga:nextupdate:service icingadb:overdue:host icingadb:overdue:service
4. Start Icinga 2 & Icinga DB

Our overdue code doesn't have any chunking mechanism, so it's some that can break for sure.

works in my case 👍

[dmitriy-terzeman]

have no chance to test it right now(i destroyed cluster where i tested it)

I have some ideas how to provide additional testing with this one
next steps will be a clear indication that its Overdue problem:

1# Crush emulation with restore:

1. Set frequency as low as possible to speedup overdue generation (30 sec would be nice i think)
2. Configure Icinga2 to operate normally
3. Emulate crush with reloading icinga2 at big env
4. Check amount of messages in redis and write it down somewhere.
   i assume icingadb:overdue:host icingadb:overdue:service would help with investigation
5. Try to restart IcingaDB, it should crush again
6. Check amount of messages in redis again(in my personal case after few restarts IcingaDB restored and operated normally again, so i assume that IcingaDB able to make some inserts before it will actually crush, and few restarts helps to cleanup the queue).
7. Remove messages with solution proposed by @N-o-X and start IcingaDB again, it should not crash

2# Emulate normal work of Icinga2:

1. Set frequency as low as possible to speedup overdue generation
2. Create a script that will check the queue in redis, print it somewhere and remove it after that, this function should be executed in loop with 1sec period (that way we have some debug info and not allow redis to generate too big queue)
3. Configure Icinga2 to operate normally
4. Start script
5. Try to emulate crush with reloading icinga2 at big env
6. There should be no crash ;)

any thoughts on this one? @N-o-X

[N-o-X]

Hi @dmitriy-terzeman, sorry for the late reply.

Thanks for your ideas! I've used your testing methods and changed them up a bit. Two points on this:

• We actually don't need an environment that takes long to reload. The only thing we really need, is a large amount of hosts or services. We can just stop Icinga 2 and wait until everything should be overdue (check interval + latency) and then start Icinga DB without Icinga 2
• To get Icinga DB going, we can fake a Icinga 2 heartbeat in Redis:

XADD icinga:stats * "IcingaApplication" "{\"status\":{\"icingaapplication\":{\"app\":{\"endpoint_id\":\"fbcb5351576fe5d258c76055228690229a846f2c\",\"environment\":\"\"}}}}" "config_dump_in_progress" "false" "timestamp" "0"

In the end I came up with the following test procedure:

Config:

numHosts = 100000 // We need a lot of hosts or services to reach the limit of 65536 placeholders
for (hid in range(numHosts)) {
        object Host "TestHost - " + hid use (hid) {
                check_command = "random"
                max_check_attempts = 1
                check_interval = 5m // My machine can't handle 100k hosts with intervals < 5m
        }
}

Steps

1. Start Icinga 2 & Icinga DB
2. Wait until everything is synced and nothing is overdue (SCARD icingadb:overdue:host should return 0)
3. Stop Icinga 2 & Icinga DB
4. Wait for at least 5 minutes (my check interval) so all hosts should be overdue
5. Start Icinga DB and fake Icinga 2 heartbeat:

XADD icinga:stats * "IcingaApplication" "{\"status\":{\"icingaapplication\":{\"app\":{\"endpoint_id\":\"fbcb5351576fe5d258c76055228690229a846f2c\",\"environment\":\"\"}}}}" "config_dump_in_progress" "false" "timestamp" "0"

6. Icinga DB should crash without fix
7. Install fixed version, start Icinga DB (Don't clear anything in Redis) and fake heartbeat again
8. Icinga DB should not crash and sync many overdue indicators (you can trigger this again with DEL icingadb:overdue:host which should result in msg="Synced some host and service overdue indicators" host=100146 period=20s)

@dmitriy-terzeman @mwaldmueller I've prepared packages (based on #168) that should fix those issues. Please test them, if you got time and a working setup.

• CentOS 7: https://git.icinga.com/packaging/rpm-icingadb/-/jobs/48483/artifacts/browse/build/RPMS/x86_64/
• Debian 10: https://git.icinga.com/packaging/deb-icingadb/-/jobs/48479/artifacts/browse/build/

Thanks for your help!

[mwaldmueller]

I can't reproduce it anymore with 1.0.0+rc1.21. Instead I got #164 and after a restart of icingadb I got #170. Not sure if it's related...

[dmitriy-terzeman]

@N-o-X by the way for what reasons Overdue pushed to the database, i don't see it like a state change or providing any historical or reporting information, instead it can cause to a lot of unnecessary updates in the database.

Example: if i'll have a lot of checks with 10sec interval, they will be pushed to the database every 20 sec (double time of interval as i expect), it can cause a big load for "nothing", if it does not provide historical reporting but only "current status", does it make sense to disable pushing Overdues to the database and let IcingaWeb to grab that info directly from Redis?

With best regards,
Dmitriy.

[N-o-X]

@dmitriy-terzeman if your monitoring system is healthy, the should be very few database updates caused by our overdue handling. Please correct me on that, if I'm wrong.

In my opinion, everything that's an important change, should be updated in the database. Overdue is one of those things - at least for me.

I'm also not sure, why you would have overdue indicators synced every 20 seconds?

Greetings
Noah