nfv database migration failed as file lock over nfs cannot be acquired

[Bin Qian]

This is an intermittent issue happens a few times during 22.06->22.12 Debian upgrade.
nfv-vim-manage db-load-data -d /opt/platform/nfv/vim/22.12 -f /mnt/db_dump/upgrade/vim.data
command to create vim database for 22.12 release on nfs mount device during upgrade failed.

manually run the command results:
sudo nfv-vim-manage db-load-data -d /opt/platform/nfv/vim/22.12 -f /mnt/db_dump/upgrade/vim.data
(sqlite3.OperationalError) database is locked
(Background on this error at: http://sqlalche.me/e/13/e3q8)
sysadmin@controller-1:~$ echo $?
1

and strace shows that it failed to acquire file rdlock.
fcntl(3, F_SETLK, {l_type=F_RDLCK, l_whence=SEEK_SET, l_start=1073741824, l_len=1})

Error log:
2022-09-16T14:43:32.000 controller-1 upgrade_controller: info 2022-09-16 14:43:32.577 3746 INFO controllerconfig.upgrades.controller [-] Executing import command: nfv-vim-manage db-load-data -d /opt/platform/nfv/vim/22.12 -f /mnt/db_dump/upgrade/vim.data
2022-09-16T14:43:38.000 controller-1 upgrade_controller: err 2022-09-16 14:43:38.604 3746 ERROR controllerconfig.upgrades.controller [-] Failed to execute command: 'nfv-vim-manage db-load-data -d /opt/platform/nfv/vim/22.12 -f /mnt/db_dump/upgrade/vim.data' during upgrade processing, return code: 1: subprocess.CalledProcessError: Command '['nfv-vim-manage db-load-data -d /opt/platform/nfv/vim/22.12 -f /mnt/db_dump/upgrade/vim.data']' returned non-zero exit status 1.
2022-09-16 14:43:38.604 3746 ERROR controllerconfig.upgrades.controller Traceback (most recent call last):
2022-09-16 14:43:38.604 3746 ERROR controllerconfig.upgrades.controller File "/usr/lib/python3/dist-packages/controllerconfig/upgrades/controller.py", line 542, in import_databases
2022-09-16 14:43:38.604 3746 ERROR controllerconfig.upgrades.controller subprocess.check_call([cmd[1]],
2022-09-16 14:43:38.604 3746 ERROR controllerconfig.upgrades.controller File "/usr/lib/python3.9/subprocess.py", line 373, in check_call
2022-09-16 14:43:38.604 3746 ERROR controllerconfig.upgrades.controller raise CalledProcessError(retcode, cmd)
2022-09-16 14:43:38.604 3746 ERROR controllerconfig.upgrades.controller subprocess.CalledProcessError: Command '['nfv-vim-manage db-load-data -d /opt/platform/nfv/vim/22.12 -f /mnt/db_dump/upgrade/vim.data']' returned non-zero exit status 1.
2022-09-16 14:43:38.604 3746 ERROR controllerconfig.upgrades.controller
2022-09-16T14:43:38.000 controller-1 upgrade_controller: err 2022-09-16 14:43:38.605 3746 ERROR controllerconfig.upgrades.controller [-] Command '['nfv-vim-manage db-load-data -d /opt/platform/nfv/vim/22.12 -f /mnt/db_dump/upgrade/vim.data']' returned non-zero exit status 1.: subprocess.CalledProcessError: Command '['nfv-vim-manage db-load-data -d /opt/platform/nfv/vim/22.12 -f /mnt/db_dump/upgrade/vim.data']' returned non-zero exit status 1.
2022-09-16 14:43:38.605 3746 ERROR controllerconfig.upgrades.controller Traceback (most recent call last):
2022-09-16 14:43:38.605 3746 ERROR controllerconfig.upgrades.controller File "/usr/lib/python3/dist-packages/controllerconfig/upgrades/controller.py", line 1142, in main
2022-09-16 14:43:38.605 3746 ERROR controllerconfig.upgrades.controller upgrade_controller(from_release, to_release)
2022-09-16 14:43:38.605 3746 ERROR controllerconfig.upgrades.controller File "/usr/lib/python3/dist-packages/controllerconfig/upgrades/controller.py", line 930, in upgrade_controller
2022-09-16 14:43:38.605 3746 ERROR controllerconfig.upgrades.controller import_databases(from_release, to_release)
2022-09-16 14:43:38.605 3746 ERROR controllerconfig.upgrades.controller File "/usr/lib/python3/dist-packages/controllerconfig/upgrades/controller.py", line 542, in import_databases
2022-09-16 14:43:38.605 3746 ERROR controllerconfig.upgrades.controller subprocess.check_call([cmd[1]],
2022-09-16 14:43:38.605 3746 ERROR controllerconfig.upgrades.controller File "/usr/lib/python3.9/subprocess.py", line 373, in check_call
2022-09-16 14:43:38.605 3746 ERROR controllerconfig.upgrades.controller raise CalledProcessError(retcode, cmd)
2022-09-16 14:43:38.605 3746 ERROR controllerconfig.upgrades.controller subprocess.CalledProcessError: Command '['nfv-vim-manage db-load-data -d /opt/platform/nfv/vim/22.12 -f /mnt/db_dump/upgrade/vim.data']' returned non-zero exit status 1.
2022-09-16 14:43:38.605 3746 ERROR controllerconfig.upgrades.controller

[Al Bailey (albailey1974)]

From what I can read, since this is happening during the load-data command, the issue that that there are extra sqlite connections
ie:
https://stackoverflow.com/questions/3172929/operationalerror-database-is-locked

Check to see if something else is trying to connect to sqlite at the same time.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/c/starlingx/config/+/859298

[Bin Qian (bqian20)]

Thanks @Al, in this case, it not likely the database is accessed by anything else, as the database is being created when the failure occurs.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/starlingx/config/+/859298
Committed: https://opendev.org/starlingx/config/commit/2a84c3659fd3ad9cdd1bdcd7e9c199c907595344
Submitter: "Zuul (22348)"
Branch: master

commit 2a84c3659fd3ad9cdd1bdcd7e9c199c907595344
Author: Bin Qian <email address hidden>
Date: Fri Sep 23 17:29:54 2022 +0000

    create vim_db locally and move to nfs device

    This change is to avoid intermittent file lock error when
    creating vim database directly on nfs device.

    As a safer (and more efficient) way is to create the database
    on local temp directory and copy it to the nfs mount path.

    Also add an audit code to determine if the database copied to
    nfs still has the file lock issue and report in log.

    Note that the database does not need to be opened over nfs mount,
    so the file lock failure issue would not impact the system.

    TCs:
       passed DX upgrade 22.06 to 22.12 Debian completed.

    Closes-Bug: 1990544
    Change-Id: Ib3f1dee3df4f0c240c919b3f5c3414a6b807b1de
    Signed-off-by: Bin Qian <email address hidden>