Node-Agentd corrupt yum database #679

privateVoit · 2021-03-31T07:49:40Z

privateVoit
Mar 31, 2021

Hi there!

We are having some issues with YumDBs. They get corrupted from time to time. Once this happens, the node-agent becomes unresponsive or crashes.

This issue is widespread. We need to go through every node and rebuild the yum dbs before making changes to the orbiter yaml.

Here's the output when I try to check for yum updates.

[orbiter@master03 ~]$ sudo yum check-update
error: rpmdb: BDB0113 Thread/process 4830/140310845814848 failed: BDB1507 Thread died in Berkeley DB library
error: db5 error(-30973) from dbenv->failchk: BDB0087 DB_RUNRECOVERY: Fatal error, run database recovery
error: cannot open Packages index using db5 -  (-30973)
error: cannot open Packages database in /var/lib/rpm
CRITICAL:yum.main:

Error: rpmdb open failed

Here's the node-agentd log entries:

Mar 31 06:30:56 master01 node-agent[90324]: ts="2021-03-31T06:30:56+02:00" msg="Iteration done"
Mar 31 06:31:13 master01 node-agent[90324]: ts="2021-03-31T06:31:13+02:00" msg="Iteration done"
Mar 31 06:31:32 master01 node-agent[90324]: ts="2021-03-31T06:31:32+02:00" msg="Iteration done"
Mar 31 06:31:49 master01 node-agent[90324]: ts="2021-03-31T06:31:49+02:00" msg="Iteration done"
Mar 31 06:32:00 master01 node-agent[90324]: refreshing installed packages failed: waiting for list packages command failed: signal: killed
Mar 31 06:32:00 master01 systemd[1]: node-agentd.service: main process exited, code=exited, status=1/FAILURE
Mar 31 06:32:00 master01 systemd[1]: Unit node-agentd.service entered failed state.
Mar 31 06:32:00 master01 systemd[1]: node-agentd.service failed.
Mar 31 06:32:11 master01 systemd[1]: node-agentd.service holdoff time over, scheduling restart.
Mar 31 06:32:11 master01 systemd[1]: Stopped Node Agent.
Mar 31 06:32:11 master01 systemd[1]: Started Node Agent.
Mar 31 06:32:11 master01 node-agent[115512]: ts="2021-03-31T06:32:11+02:00" msg="Node Agent is starting" commit="744ecfd88280cdc85479bddf488099ffabfb1be6" nodeAgentID="master01" verbose="false" version="v3.0.5"
Mar 31 06:32:12 master01 node-agent[115512]: updating packages failed%!(EXTRA dep.Packages=REMBased): installing yum package yum-utils failed with stderr error: rpmdb: BDB0113 Thread/process 115334/140331070978112 failed: BDB1507 Thread died in Berkeley DB library
Mar 31 06:32:12 master01 node-agent[115512]: error: db5 error(-30973) from dbenv->failchk: BDB0087 DB_RUNRECOVERY: Fatal error, run database recovery
Mar 31 06:32:12 master01 node-agent[115512]: error: cannot open Packages index using db5 -  (-30973)
Mar 31 06:32:12 master01 node-agent[115512]: error: cannot open Packages database in /var/lib/rpm
Mar 31 06:32:12 master01 node-agent[115512]: CRITICAL:yum.main:
Mar 31 06:32:12 master01 node-agent[115512]: Error: rpmdb open failed
Mar 31 06:32:12 master01 node-agent[115512]: : exit status 1
Mar 31 06:32:12 master01 systemd[1]: node-agentd.service: main process exited, code=exited, status=1/FAILURE
Mar 31 06:32:12 master01 systemd[1]: Unit node-agentd.service entered failed state.
Mar 31 06:32:12 master01 systemd[1]: node-agentd.service failed.
Mar 31 06:32:22 master01 systemd[1]: node-agentd.service holdoff time over, scheduling restart.
Mar 31 06:32:22 master01 systemd[1]: Stopped Node Agent.
Mar 31 06:32:22 master01 systemd[1]: Started Node Agent.
Mar 31 06:32:22 master01 node-agent[115730]: ts="2021-03-31T06:32:22+02:00" msg="Node Agent is starting" commit="744ecfd88280cdc85479bddf488099ffabfb1be6" nodeAgentID="master01" verbose="false" version="v3.0.5"
Mar 31 06:32:22 master01 node-agent[115730]: updating packages failed%!(EXTRA dep.Packages=REMBased): installing yum package yum-utils failed with stderr error: rpmdb: BDB0113 Thread/process 115334/140331070978112 failed: BDB1507 Thread died in Berkeley DB library
Mar 31 06:32:22 master01 node-agent[115730]: error: db5 error(-30973) from dbenv->failchk: BDB0087 DB_RUNRECOVERY: Fatal error, run database recovery
Mar 31 06:32:22 master01 node-agent[115730]: error: cannot open Packages index using db5 -  (-30973)
Mar 31 06:32:22 master01 node-agent[115730]: error: cannot open Packages database in /var/lib/rpm
Mar 31 06:32:22 master01 node-agent[115730]: CRITICAL:yum.main:
Mar 31 06:32:22 master01 node-agent[115730]: Error: rpmdb open failed
Mar 31 06:32:22 master01 node-agent[115730]: : exit status 1

The yum log doesn't show any entries for that date. The last ones were two weeks old.

Mar 20 03:57:16 Updated: 1:dmidecode-3.2-5.el7_9.1.x86_64
Mar 20 03:57:16 Updated: python-perf-3.10.0-1160.21.1.el7.x86_64
Mar 20 03:57:29 Installed: kernel-3.10.0-1160.21.1.el7.x86_64
Mar 20 03:57:30 Updated: open-vm-tools-11.0.5-3.el7_9.2.x86_64

We've removed yum-crons from each and every node. It has caused such problems in the past. This issue still occurs without it installed.

Dou you have an idea on whats going wrong here?

If you need more information from us, do not hesitate to ask!

Informations about our clusters
Kubernetes Version: v1.18.0 & v1.18.0
ORBOS Version: v2.1.0 & v3.0.5
Provider: Static Provider with CentOS 7

Answered by thesephirot

Apr 7, 2021

Hi Cédric,

thanks for the issue.

This condition that can occur when yum updates the complete system via cronjob and nodeagent tries to update its packages at the same time.

We are already aware of this issue and will release a fix soon.

Cheers,

Christian

View full answer

thesephirot · 2021-04-07T10:46:02Z

thesephirot
Apr 7, 2021

Hi Cédric,

thanks for the issue.

This condition that can occur when yum updates the complete system via cronjob and nodeagent tries to update its packages at the same time.

We are already aware of this issue and will release a fix soon.

Cheers,

Christian

10 replies

fforootd May 5, 2021
Maintainer

Ok, well then let's wait 😁

privateVoit May 20, 2021
Author

Hi @fforootd. Two weeks ago we've built two new clusters with ORBOS v4.1.4. Unfortunately the Yum DBs are already corrupted on all 3 workers. 😭 The node-agentd is stuck at "Starting iteration". So there's not much to show here.
If you need more informations from us, don't hesitate to ask.

thesephirot May 21, 2021

Hi Cédric,

that is strange. From our perspective the only reason for this could be concurring processes that try to perform yum/rpm operations at the same time. (therefore we got rid of yum-cron).

Can you find out which iteration was the last that yum performed with:

yum history list

And can you doublecheck if another process is stuck or running that uses yum/rpm?

ps -ef | egrep "yum|rpm"

Cheers,

Christian

privateVoit May 21, 2021
Author

Hey Christian!

Thank you for your answer! Here's the information you've requested.

Blocking processes
In the old versions of ORBOS the yum db was locked by the process yum itself. In this case it's always the node-agent.

[orbiter@worker01 ~]$ sudo yum check-update
Loaded plugins: fastestmirror, versionlock
Existing lock /var/run/yum.pid: another copy is running as pid 4685.
Another app is currently holding the yum lock; waiting for it to exit...
  The other application is: node-agent
    Memory : 137 M RSS (967 MB VSZ)
    Started: Wed May 12 11:55:58 2021 - 9 day(s) 4:07:59 ago
    State  : Sleeping, pid: 4685

By stopping the node-agent with systemctl the error shows up.

[orbiter@worker01 ~]$ sudo systemctl stop node-agentd
[orbiter@worker01 ~]$ sudo yum check-update
error: rpmdb: BDB0113 Thread/process 4685/139738237167424 failed: BDB1507 Thread died in Berkeley DB library
error: db5 error(-30973) from dbenv->failchk: BDB0087 DB_RUNRECOVERY: Fatal error, run database recovery
error: cannot open Packages index using db5 -  (-30973)
error: cannot open Packages database in /var/lib/rpm
CRITICAL:yum.main:

Error: rpmdb open failed

Here's the history list:

^C[orbiter@worker01 ~]$ sudyum history list
Loaded plugins: fastestmirror, versionlock
ID     | Login user               | Date and time    | Action(s)      | Altered
-------------------------------------------------------------------------------
    17 | System <unset>           | 2021-05-11 09:33 | Install        |    2
    16 | System <unset>           | 2021-05-11 09:33 | Install        |    1
    15 | System <unset>           | 2021-05-11 09:33 | Install        |    7
    14 | System <unset>           | 2021-05-11 09:31 | Install        |    1 EE
    13 | System <unset>           | 2021-05-11 09:31 | Install        |    4
    12 | System <unset>           | 2021-05-11 09:31 | Install        |    3
    11 | System <unset>           | 2021-05-11 09:30 | Install        |    9 EE
    10 | System <unset>           | 2021-05-11 09:30 | Update         |    3
     9 | System <unset>           | 2021-05-11 09:30 | Install        |    1
     8 | kubernetes ... <orbiter> | 2021-03-30 14:12 | I, O, U        |  185 EE
     7 | root <root>              | 2019-11-11 14:49 | Erase          |    1
     6 | root <root>              | 2019-11-11 14:23 | I, U           |  176 EE
     5 | root <root>              | 2019-09-04 12:55 | I, U           |   46
     4 | root <root>              | 2019-09-04 12:47 | Install        |   27
     3 | root <root>              | 2019-09-04 12:38 | Install        |   11
     2 | root <root>              | 2019-09-04 12:37 | Install        |   25
     1 | System <unset>           | 2019-09-04 10:47 | Install        |  303
history list

And here's the list of processes (there aren't any)

[orbiter@worker01 ~]$ ps -ef | egrep "yum|rpm"
orbiter     955 112301  0 16:14 pts/0    00:00:00 grep -E --color=auto yum|rpm

The logs from node-agent when the issue occured (This one wasn't stuck at "starting iteration)"

May 12 10:09:13 worker01 node-agent[2120]: ts="2021-05-12T10:09:13+02:00" msg="Starting iteration"
May 12 10:09:18 worker01 node-agent[2120]: ts="2021-05-12T10:09:18+02:00" msg="Iteration done"
May 12 10:09:28 worker01 node-agent[2120]: ts="2021-05-12T10:09:28+02:00" msg="Starting update"
May 12 10:09:51 worker01 node-agent[2120]: ts="2021-05-12T10:09:51+02:00" err="updating packages failed: updating packages REMBased failed: updating yum packages failed with stderr : signal: killed" src="/home/runner/work/orbos/orbos/cmd
May 12 10:09:51 worker01 node-agent[2120]: ts="2021-05-12T10:09:51+02:00" msg="Starting iteration"
May 12 10:09:52 worker01 node-agent[2120]: refreshing installed packages failed: waiting for list packages command failed: exit status 1
May 12 10:09:52 worker01 systemd[1]: node-agentd.service: main process exited, code=exited, status=1/FAILURE
May 12 10:09:52 worker01 systemd[1]: Unit node-agentd.service entered failed state.
May 12 10:09:52 worker01 systemd[1]: node-agentd.service failed.
May 12 10:10:02 worker01 systemd[1]: node-agentd.service holdoff time over, scheduling restart.
May 12 10:10:02 worker01 systemd[1]: Stopped Node Agent.
May 12 10:10:02 worker01 systemd[1]: Started Node Agent.
May 12 10:10:02 worker01 node-agent[5346]: ts="2021-05-12T10:10:02+02:00" msg="Node Agent is starting" commit="6df1093f7255c029c01655d660ef93db7968b056" nodeAgentID="worker01" verbose="false" version="v4.1.4"
May 12 10:10:02 worker01 node-agent[5346]: ts="2021-05-12T10:10:02+02:00" msg="Starting iteration"
May 12 10:10:03 worker01 node-agent[5346]: initializing packages REMBased failed: installing yum package yum-utils failed with stderr error: rpmdb: BDB0113 Thread/process 4685/139738237167424 failed: BDB1507 Thread died in Berkeley DB li
May 12 10:10:03 worker01 node-agent[5346]: error: db5 error(-30973) from dbenv->failchk: BDB0087 DB_RUNRECOVERY: Fatal error, run database recovery
May 12 10:10:03 worker01 node-agent[5346]: error: cannot open Packages index using db5 -  (-30973)
May 12 10:10:03 worker01 node-agent[5346]: error: cannot open Packages database in /var/lib/rpm
May 12 10:10:03 worker01 node-agent[5346]: CRITICAL:yum.main:
May 12 10:10:03 worker01 node-agent[5346]: Error: rpmdb open failed
May 12 10:10:03 worker01 node-agent[5346]: : exit status 1
May 12 10:10:03 worker01 systemd[1]: node-agentd.service: main process exited, code=exited, status=1/FAILURE
May 12 10:10:03 worker01 systemd[1]: Unit node-agentd.service entered failed state.
May 12 10:10:03 worker01 systemd[1]: node-agentd.service failed.
May 12 10:10:13 worker01 systemd[1]: node-agentd.service holdoff time over, scheduling restart.
May 12 10:10:13 worker01 systemd[1]: Stopped Node Agent.
May 12 10:10:13 worker01 systemd[1]: Started Node Agent.
May 12 10:10:13 worker01 node-agent[5528]: ts="2021-05-12T10:10:13+02:00" msg="Node Agent is starting" commit="6df1093f7255c029c01655d660ef93db7968b056" nodeAgentID="worker01" verbose="false" version="v4.1.4"
May 12 10:10:13 worker01 node-agent[5528]: ts="2021-05-12T10:10:13+02:00" msg="Starting iteration"
May 12 10:10:13 worker01 node-agent[5528]: initializing packages REMBased failed: installing yum package yum-utils failed with stderr error: rpmdb: BDB0113 Thread/process 4685/139738237167424 failed: BDB1507 Thread died in Berkeley DB li
May 12 10:10:13 worker01 node-agent[5528]: error: db5 error(-30973) from dbenv->failchk: BDB0087 DB_RUNRECOVERY: Fatal error, run database recovery
May 12 10:10:13 worker01 node-agent[5528]: error: cannot open Packages index using db5 -  (-30973)
May 12 10:10:13 worker01 node-agent[5528]: error: cannot open Packages database in /var/lib/rpm
May 12 10:10:13 worker01 node-agent[5528]: CRITICAL:yum.main:
May 12 10:10:13 worker01 node-agent[5528]: Error: rpmdb open failed
May 12 10:10:13 worker01 node-agent[5528]: : exit status 1

Regards,
Cédric

eliobischof May 29, 2021

Fixing #706 possibly solves your problem too. We'll address this asap.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Node-Agentd corrupt yum database #679

Uh oh!

{{title}}

Uh oh!

Replies: 1 comment 10 replies

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Uh oh!

{{title}}

Uh oh!

Select a reply

Uh oh!

Node-Agentd corrupt yum database #679

Uh oh!

privateVoit Mar 31, 2021

Replies: 1 comment · 10 replies

Uh oh!

Uh oh!

thesephirot Apr 7, 2021

Uh oh!

fforootd May 5, 2021 Maintainer

Uh oh!

Uh oh!

privateVoit May 20, 2021 Author

Uh oh!

thesephirot May 21, 2021

Uh oh!

Uh oh!

privateVoit May 21, 2021 Author

Uh oh!

eliobischof May 29, 2021

privateVoit
Mar 31, 2021

Replies: 1 comment 10 replies

thesephirot
Apr 7, 2021

fforootd May 5, 2021
Maintainer

privateVoit May 20, 2021
Author

privateVoit May 21, 2021
Author