Brief Description
-----------------
The following command hung indefinitely. The command was issued:
2020-05-26T22:02:57.000 controller-0 -sh: info HISTORY: PID=2755566 UID=42425 openstack server migrate --live-migration b657ba58-aa77-4945-979b-8e2b9d9a8111
And was still hanging 4 hours later. Initial debugging indicates the nfv-vim process seems to no longer be functioning (no logs generated) despite the nfv-vim processes showing to be alive via the ps -ef |grep nfv command.
Severity
--------
Major - VM or any operations that go through the nfv-vim process no longer function.
Steps to Reproduce
------------------
Unknown.
The system was installed on May 21 and left mostly idle over the next 5 days.
On May 26 3 VMs were launched via Horizon.
VM migration from CLI resulted in command hanging:
[sysadmin@controller-0 ~(keystone_admin)]$ openstack server migrate --live-migration b657ba58-aa77-4945-979b-8e2b9d9a8111
Expected Behavior
------------------
VM migration should have been attempted and CLI returned with pass or fail result.
Actual Behavior
----------------
CLI command hung indefinitely.
Reproducibility
---------------
Seen once
System Configuration
--------------------
AIO-DX
Branch/Pull Time/Commit
-----------------------
2020-05-18_20-00-00
Last Pass
---------
n/a
Timestamp/Logs
--------------
CLI command was run at:
2020-05-26T22:02:57.000 controller-0 -sh: info HISTORY: PID=2755566 UID=42425 openstack server migrate --live-migration b657ba58-aa77-4945-979b-8e2b9d9a8111
But last nfv-vim logs were from 7 hours earlier:
2020-05-26T07:17:42.712 controller-0 VIM_Thread[776005] INFO _vim_nfvi_audits.py.873 Audit instances called, timer_id=15.
2020-05-26T07:18:30.970 controller-0 VIM_Thread[776005] INFO _task_worker_pool.py.73 Timeout worker BlockStorage-Worker-0
2020-05-26T07:18:31.978 controller-0 VIM_Thread[776005] ERROR _task.py.200 Task(get_volume) work (get_volume) timed out, id=215342.
2020-05-26T07:18:31.981 controller-0 VIM_Thread[776005] ERROR _vim_nfvi_audits.py.1153 Audit-Volume callback, not completed, response={'completed': False, 'reason': ''}.
2020-05-26T07:18:38.207 controller-0 VIM_Thread[776005] ERROR (raised as a result of Query-invoked autoflush; consider using a session.no_autoflush block if this flush is occurring prematurely) (sqlite3.OperationalError) unable to open database file [SQL: u'UPDATE hosts_v6 SET uptime=?, elapsed_time_in_state=? WHERE hosts_v6.uuid = ?'] [parameters: (371994, 364573, u'3ff0ded8-6de9-4928-a2c1-2269527c98ef')]
Traceback (most recent call last):
File "/usr/lib64/python2.7/site-packages/nfv_vim/vim.py", line 167, in process_main
File "/usr/lib64/python2.7/site-packages/nfv_common/selobj/_selobj_module.py", line 105, in selobj_dispatch
File "/usr/lib64/python2.7/site-packages/nfv_common/tasks/_task_scheduler.py", line 332, in task_work_complete
File "/usr/lib64/python2.7/site-packages/nfv_common/tasks/_task.py", line 193, in task_work_complete
File "/usr/lib64/python2.7/site-packages/nfv_plugins/nfvi_plugins/nfvi_infrastructure_api.py", line 495, in get_hosts
File "/usr/lib64/python2.7/site-packages/nfv_vim/audits/_vim_nfvi_audits.py", line 148, in _audit_nfvi_hosts_callback
File "/usr/lib64/python2.7/site-packages/nfv_vim/objects/_host.py", line 721, in nfvi_host_update
File "/usr/lib64/python2.7/site-packages/nfv_vim/objects/_host.py", line 863, in _persist
File "/usr/lib64/python2.7/site-packages/nfv_vim/database/_database_infrastructure_module.py", line 68, in database_host_add
File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2755, in first
File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2547, in __getitem__
File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2854, in __iter__
File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 1407, in _autoflush
File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/compat.py", line 203, in raise_from_cause
File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 1397, in _autoflush
File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 2171, in flush
File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 2291, in _flush
File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/langhelpers.py", line 66, in __exit__
File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 2255, in _flush
File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 389, in execute
File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 548, in execute
File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 177, in save_obj
File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 737, in _emit_update_statements
File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 945, in execute
File "/usr/lib64/python2.7/site-packages/sqlalchemy/sql/elements.py", line 263, in _execute_on_connection
File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1053, in _execute_clauseelement
File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1189, in _execute_context
File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1402, in _handle_dbapi_exception
File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/compat.py", line 203, in raise_from_cause
File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1182, in _execute_context
File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 470, in do_execute
OperationalError: (raised as a result of Query-invoked autoflush; consider using a session.no_autoflush block if this flush is occurring prematurely) (sqlite3.OperationalError) unable to open database file [SQL: u'UPDATE hosts_v6 SET uptime=?, elapsed_time_in_state=? WHERE hosts_v6.uuid = ?'] [parameters: (371994, 364573, u'3ff0ded8-6de9-4928-a2c1-2269527c98ef')]
2020-05-26T07:20:18.198 controller-0 VIM_BlockStorage-Worker-0_Thread[2931601] INFO _timer_scheduler.py.57 Not scheduling on time, elapsed=127281 ms.
2020-05-26T07:20:18.203 controller-0 VIM_BlockStorage-Worker-0_Thread[2931601] INFO _thread.py.218 Thread BlockStorage-Worker-0: not scheduling on time
2020-05-26T07:20:18.203 controller-0 VIM_BlockStorage-Worker-0_Thread[2931601] INFO _thread.py.218 Thread BlockStorage-Worker-0: not scheduling on time
2020-05-26T07:20:18.203 controller-0 VIM_BlockStorage-Worker-0_Thread[2931601] INFO _thread.py.232 Thread BlockStorage-Worker-0: shutting down.
2020-05-26T07:20:18.204 controller-0 VIM_BlockStorage-Worker-0_Thread[2931601] INFO _thread.py.236 Thread BlockStorage-Worker-0: shutdown.
Test Activity
-------------
Regular use
Workaround
----------
Unknown - killing the nfv-vim process may result in it recovering.
Logs captured and uploaded here: /files. starlingx. kube.cengn. ca/launchpad/ 1880777
https:/