[Starlingx-discuss] stx 6.0 in a VM / Saving config in sysinv database fails timeout

Outback Dingo outbackdingo at gmail.com
Mon May 9 11:46:45 UTC 2022


curiously, while trying to do some testing on pxe, i noticed starlingx
bootstrap times out in a VM, i found this in sysinv.log

TASK [bootstrap/persist-config : debug]
***********************************************************************************************************************
Monday 09 May 2022  11:27:51 +0000 (0:29:57.887)       0:39:28.205 ************
ok: [localhost] =>
  populate_result:
    changed: true
    failed: false
    failed_when_result: false
    msg: non-zero return code
    rc: 1
    stderr: |-
      Traceback (most recent call last):
        File "/tmp/.ansible-sysadmin/tmp/ansible-tmp-1652093873.31-134751541330122/populate_initial_config.py",
line 1119, in <module>
          inventory_config_complete_wait(client, controller)
        File "/tmp/.ansible-sysadmin/tmp/ansible-tmp-1652093873.31-134751541330122/populate_initial_config.py",
line 1073, in inventory_config_complete_wait
          wait_initial_inventory_complete(client, controller)
        File "/tmp/.ansible-sysadmin/tmp/ansible-tmp-1652093873.31-134751541330122/populate_initial_config.py",
line 1064, in wait_initial_inventory_complete
          raise ConfigFail('Timeout waiting for controller inventory '
      __main__.ConfigFail: Timeout waiting for controller inventory completion
    stderr_lines:
    - 'Traceback (most recent call last):'
    - '  File "/tmp/.ansible-sysadmin/tmp/ansible-tmp-1652093873.31-134751541330122/populate_initial_config.py",
line 1119, in <module>'
    - '    inventory_config_complete_wait(client, controller)'
    - '  File "/tmp/.ansible-sysadmin/tmp/ansible-tmp-1652093873.31-134751541330122/populate_initial_config.py",
line 1073, in inventory_config_complete_wait'
    - '    wait_initial_inventory_complete(client, controller)'
    - '  File "/tmp/.ansible-sysadmin/tmp/ansible-tmp-1652093873.31-134751541330122/populate_initial_config.py",
line 1064, in wait_initial_inventory_complete'
    - '    raise ConfigFail(''Timeout waiting for controller inventory '''
    - '__main__.ConfigFail: Timeout waiting for controller inventory completion'
    stdout: |-
      Populating system config...
      System config completed.
      Populating load config...
      Load config completed.
      Populating management network...
      Populating pxeboot network...
      Populating oam network...
      Populating multicast network...
      Populating cluster host network...
      Populating cluster pod network...
      Populating cluster service network...
      Network config completed.
      Populating/Updating DNS config...
      DNS config completed.
      Populating/Updating docker registry config...
      Docker registry config completed.
      Populating/Updating kubernetes san list...
      Populating/Updating kubernetes config...
      Kubernetes config completed.
      Management mac = 00:00:00:00:00:00
      Root fs device = /dev/disk/by-path/pci-0000:02:02.0-ata-2.0
      Boot device = /dev/disk/by-path/pci-0000:02:02.0-ata-2.0
      Console = tty0
      Tboot = false
      Install output = text
      Host values = {'tboot': 'false', 'install_output': 'text',
'rootfs_device': '/dev/disk/by-path/pci-0000:02:02.0-ata-2.0',
'boot_device': '/dev/disk/by-path/pci-0000:02:02.0-ata-2.0',
'availability': 'offline', 'mgmt_mac': '00:00:00:00:00:00', 'console':
'tty0', 'mgmt_ip': '192.168.204.2', 'hostname': 'controller-0',
'operational': 'disabled', 'invprovision': 'provisioning',
'administrative': 'locked', 'personality': 'controller'}
      Host controller-0 created.
      Failed to update the initial system config.
    stdout_lines:
    - Populating system config...
    - System config completed.
    - Populating load config...
    - Load config completed.
    - Populating management network...
    - Populating pxeboot network...
    - Populating oam network...
    - Populating multicast network...
    - Populating cluster host network...
    - Populating cluster pod network...
    - Populating cluster service network...
    - Network config completed.
    - Populating/Updating DNS config...
    - DNS config completed.
    - Populating/Updating docker registry config...
    - Docker registry config completed.
    - Populating/Updating kubernetes san list...
    - Populating/Updating kubernetes config...
    - Kubernetes config completed.
    - Management mac = 00:00:00:00:00:00
    - Root fs device = /dev/disk/by-path/pci-0000:02:02.0-ata-2.0
    - Boot device = /dev/disk/by-path/pci-0000:02:02.0-ata-2.0
    - Console = tty0
    - Tboot = false
    - Install output = text
    - 'Host values = {''tboot'': ''false'', ''install_output'':
''text'', ''rootfs_device'':
''/dev/disk/by-path/pci-0000:02:02.0-ata-2.0'', ''boot_device'':
''/dev/disk/by-path/pci-0000:02:02.0-ata-2.0'', ''availability'':
''offline'', ''mgmt_mac'': ''00:00:00:00:00:00'', ''console'':
''tty0'', ''mgmt_ip'': ''192.168.204.2'', ''hostname'':
''controller-0'', ''operational'': ''disabled'', ''invprovision'':
''provisioning'', ''administrative'': ''locked'', ''personality'':
''controller''}'
    - Host controller-0 created.
    - Failed to update the initial system config.

TASK [bootstrap/persist-config : Fail if populate config script throws
an exception] **************************************************************************
Monday 09 May 2022  11:27:51 +0000 (0:00:00.069)       0:39:28.275 ************
fatal: [localhost]: FAILED! => changed=false
  msg: Failed to provision initial system configuration.


will fail the timeout


sysinv 2022-05-09 11:24:21.703 98797 ERROR sysinv.conductor.kube_app
[-] Kubernetes is not configured. API operations will not be
available.: KubeNotConfigured: Kubernetes is not configured. API
operations will not be available.
sysinv 2022-05-09 11:25:03.484 91940 INFO sysinv.agent.manager [-]
_report_to_conductor initial_reports_required=set(['disk', 'lvg',
'pv', 'memory'])
sysinv 2022-05-09 11:25:03.485 91940 INFO sysinv.agent.manager [-]
Sysinv Agent audit running inv_get_and_report.
sysinv 2022-05-09 11:25:04.395 91940 WARNING sysinv.agent.pci [-]
Enabling device ens5 to query link speed: CalledProcessError: Command
'['query_pci_id', '-v 0x8086', '-d 0x100e']' returned non-zero exit
status 1
sysinv 2022-05-09 11:25:04.403 91940 WARNING sysinv.agent.pci [-] ATTR
speed unknown for: ens5 (flags: 0x1002): IOError: [Errno 22] Invalid
argument
sysinv 2022-05-09 11:25:04.404 91940 WARNING sysinv.agent.pci [-]
Disabling device ens5 after querying link speed: IOError: [Errno 22]
Invalid argument
sysinv 2022-05-09 11:25:04.527 98797 INFO sysinv.conductor.manager [-]
Updating platform data for host: 7be69b7e-5660-48d8-ad95-28af6222da2e
with: {u'first_report': True}
sysinv 2022-05-09 11:25:04.549 91940 INFO sysinv.agent.manager [-]
Sysinv Agent platform update by host: {'first_report': True}
sysinv 2022-05-09 11:25:04.549 91940 INFO sysinv.agent.manager [-]
Agent found matching ihost: 7be69b7e-5660-48d8-ad95-28af6222da2e
sysinv 2022-05-09 11:25:04.550 91940 INFO sysinv.agent.manager [-]
_report_to_conductor initial_reports_required=set(['disk', 'lvg',
'pv', 'memory'])
sysinv 2022-05-09 11:25:05.106 98797 INFO sysinv.conductor.manager [-]
port 852027ed-3a24-4658-aa62-6f8273ce39bb update attr: {'speed':
u'1000', 'sriov_vfs_pci_address': u'', 'sriov_totalvfs': None,
'sriov_vf_pdevice_id': None, 'dpdksupport': False, 'sriov_numvfs': 0,
'driver': u'e1000', 'sriov_vf_driver': None}
sysinv 2022-05-09 11:25:05.289 98797 INFO sysinv.conductor.manager [-]
port 8a1db02d-ad08-4eb2-b4a7-a42ca5bfcfef update attr: {'speed': None,
'sriov_vfs_pci_address': u'', 'sriov_totalvfs': None,
'sriov_vf_pdevice_id': None, 'dpdksupport': False, 'sriov_numvfs': 0,
'driver': u'e1000', 'sriov_vf_driver': None}
sysinv 2022-05-09 11:25:05.376 98797 INFO sysinv.conductor.manager [-]
update 0000:00:01.1 attr: {'sriov_numvfs': 0, 'driver': u'ata_piix',
'sriov_vf_driver': None, 'sriov_vf_pdevice_id': None, 'psvendor':
u'XenSource, Inc.', 'extra_info': None, 'pdevice_id': u'7010',
'pclass': u'IDE interface', 'psdevice': u'Device 0001',
'sriov_vfs_pci_address': u'', 'pvendor': u'Intel Corporation',
'pvendor_id': u'8086', 'pclass_id': u'010180', 'sriov_totalvfs': None}
sysinv 2022-05-09 11:25:05.404 98797 INFO sysinv.conductor.manager [-]
update 0000:00:01.2 attr: {'sriov_numvfs': 0, 'driver': u'uhci_hcd',
'sriov_vf_driver': None, 'sriov_vf_pdevice_id': None, 'psvendor':
u'XenSource, Inc.', 'extra_info': None, 'pdevice_id': u'7020',
'pclass': u'USB controller', 'psdevice': u'Device 0001',
'sriov_vfs_pci_address': u'', 'pvendor': u'Intel Corporation',
'pvendor_id': u'8086', 'pclass_id': u'0c0300', 'sriov_totalvfs': None}
sysinv 2022-05-09 11:25:05.432 98797 INFO sysinv.conductor.manager [-]
update 0000:00:02.0 attr: {'sriov_numvfs': 0, 'driver': None,
'sriov_vf_driver': None, 'sriov_vf_pdevice_id': None, 'psvendor':
u'Device 0001', 'extra_info': None, 'pdevice_id': u'1111', 'pclass':
u'VGA compatible controller', 'psdevice': u'Device 0001',
'sriov_vfs_pci_address': u'', 'pvendor': u'Vendor 1234', 'pvendor_id':
u'1234', 'pclass_id': u'030000', 'sriov_totalvfs': None}
sysinv 2022-05-09 11:25:05.460 98797 INFO sysinv.conductor.manager [-]
update 0000:00:03.0 attr: {'sriov_numvfs': 0, 'driver': None,
'sriov_vf_driver': None, 'sriov_vf_pdevice_id': None, 'psvendor':
u'XenSource, Inc.', 'extra_info': None, 'pdevice_id': u'0001',
'pclass': u'SCSI storage controller', 'psdevice': u'Xen Platform
Device', 'sriov_vfs_pci_address': u'', 'pvendor': u'XenSource, Inc.',
'pvendor_id': u'5853', 'pclass_id': u'010000', 'sriov_totalvfs': None}
sysinv 2022-05-09 11:25:05.545 98797 INFO sysinv.conductor.manager [-]
Already in db numa_node=0 mynuma_nodes=[0, 2, 4, 6, 8, 10, 12, 14]
sysinv 2022-05-09 11:25:05.545 98797 INFO sysinv.conductor.manager [-]
Already in db numa_node=2 mynuma_nodes=[0, 2, 4, 6, 8, 10, 12, 14]
sysinv 2022-05-09 11:25:05.545 98797 INFO sysinv.conductor.manager [-]
Already in db numa_node=4 mynuma_nodes=[0, 2, 4, 6, 8, 10, 12, 14]
sysinv 2022-05-09 11:25:05.546 98797 INFO sysinv.conductor.manager [-]
Already in db numa_node=6 mynuma_nodes=[0, 2, 4, 6, 8, 10, 12, 14]
sysinv 2022-05-09 11:25:05.548 98797 INFO sysinv.conductor.manager [-]
Already in db numa_node=8 mynuma_nodes=[0, 2, 4, 6, 8, 10, 12, 14]
sysinv 2022-05-09 11:25:05.548 98797 INFO sysinv.conductor.manager [-]
Already in db numa_node=10 mynuma_nodes=[0, 2, 4, 6, 8, 10, 12, 14]
sysinv 2022-05-09 11:25:05.549 98797 INFO sysinv.conductor.manager [-]
Already in db numa_node=12 mynuma_nodes=[0, 2, 4, 6, 8, 10, 12, 14]
sysinv 2022-05-09 11:25:05.549 98797 INFO sysinv.conductor.manager [-]
Already in db numa_node=14 mynuma_nodes=[0, 2, 4, 6, 8, 10, 12, 14]
sysinv 2022-05-09 11:25:05.598 98797 INFO sysinv.conductor.manager [-]
Logical CPU topology: host:controller-0
(controller,worker,lowlatency), sockets:8, cores/socket=1,
threads/core=1, reference:current (unchanged)
sysinv 2022-05-09 11:25:05.598 98797 INFO sysinv.conductor.manager [-]
   cpu_id :   0  1  2  3  4  5  6  7
sysinv 2022-05-09 11:25:05.599 98797 INFO sysinv.conductor.manager [-]
socket_id :   0  2  4  6  8 10 12 14
sysinv 2022-05-09 11:25:05.600 98797 INFO sysinv.conductor.manager [-]
  core_id :   0  0  0  0  0  0  0  0
sysinv 2022-05-09 11:25:05.601 98797 INFO sysinv.conductor.manager [-]
thread_id :   0  0  0  0  0  0  0  0
sysinv 2022-05-09 11:25:05.615 98797 INFO sysinv.conductor.manager [-]
update_grub_config, host uuid: (7be69b7e-5660-48d8-ad95-28af6222da2e),
force: (False)
sysinv 2022-05-09 11:25:05.616 98797 INFO sysinv.conductor.manager [-]
_config_update_hosts personalities=['controller', 'worker']
host_uuids=[u'7be69b7e-5660-48d8-ad95-28af6222da2e'] reboot=False
config_uuid=0fd14450-6057-43bc-a429-17de31115a16 tb=  File
"/usr/lib64/python2.7/site-packages/sysinv/conductor/manager.py", line
9644, in update_grub_config
    host_uuids=[host_uuid])
sysinv 2022-05-09 11:25:05.630 98797 INFO sysinv.conductor.manager [-]
Setting config target of host 'controller-0' to
'8fd14450-6057-43bc-a429-17de31115a16'.
sysinv 2022-05-09 11:25:05.662 98797 INFO sysinv.conductor.manager [-]
_config_update_hosts config_uuid=0fd14450-6057-43bc-a429-17de31115a16
sysinv 2022-05-09 11:25:05.668 98797 INFO sysinv.conductor.manager [-]
applying runtime manifest
config_uuid=0fd14450-6057-43bc-a429-17de31115a16, classes:
['platform::compute::grub::runtime',
'platform::compute::config::runtime']
sysinv 2022-05-09 11:25:05.685 98797 INFO sysinv.conductor.manager [-]
Cannot generate the configuration for controller-0, the host is not
inventoried yet.
sysinv 2022-05-09 11:25:05.685 98797 INFO sysinv.conductor.manager [-]
Evaluating apps reapply {'type': 'runtime-apply-puppet'}
sysinv 2022-05-09 11:25:05.685 98797 INFO sysinv.conductor.manager [-]
Apps reapply order: []
sysinv 2022-05-09 11:25:05.687 98797 INFO sysinv.agent.rpcapi [-]
config_apply_runtime_manifest: fanout_cast: sending config
0fd14450-6057-43bc-a429-17de31115a16 {'classes':
['platform::compute::grub::runtime',
'platform::compute::config::runtime'], 'force': False,
'personalities': ['controller', 'worker'], 'host_uuids':
[u'7be69b7e-5660-48d8-ad95-28af6222da2e']} to agent
sysinv 2022-05-09 11:25:05.699 91940 ERROR
sysinv.openstack.common.periodic_task [-] Error during
AgentManager._agent_audit: [Errno 2] No such file or directory:
'/sys/devices/system/node/node1/hugepages': OSError: [Errno 2] No such
file or directory: '/sys/devices/system/node/node1/hugepages'
2022-05-09 11:25:05.699 91940 ERROR
sysinv.openstack.common.periodic_task Traceback (most recent call
last):
2022-05-09 11:25:05.699 91940 ERROR
sysinv.openstack.common.periodic_task   File
"/usr/lib64/python2.7/site-packages/sysinv/openstack/common/periodic_task.py",
line 180, in run_periodic_tasks
2022-05-09 11:25:05.699 91940 ERROR
sysinv.openstack.common.periodic_task     task(self, context)
2022-05-09 11:25:05.699 91940 ERROR
sysinv.openstack.common.periodic_task   File
"/usr/lib64/python2.7/site-packages/sysinv/agent/manager.py", line
1253, in _agent_audit
2022-05-09 11:25:05.699 91940 ERROR
sysinv.openstack.common.periodic_task     force_updates=None)
2022-05-09 11:25:05.699 91940 ERROR
sysinv.openstack.common.periodic_task   File
"/usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py", line
328, in inner
2022-05-09 11:25:05.699 91940 ERROR
sysinv.openstack.common.periodic_task     return f(*args, **kwargs)
2022-05-09 11:25:05.699 91940 ERROR
sysinv.openstack.common.periodic_task   File
"/usr/lib64/python2.7/site-packages/sysinv/agent/manager.py", line
1272, in agent_audit
2022-05-09 11:25:05.699 91940 ERROR
sysinv.openstack.common.periodic_task
self.ihost_inv_get_and_report(icontext)
2022-05-09 11:25:05.699 91940 ERROR
sysinv.openstack.common.periodic_task   File
"/usr/lib64/python2.7/site-packages/sysinv/agent/manager.py", line
878, in ihost_inv_get_and_report
2022-05-09 11:25:05.699 91940 ERROR
sysinv.openstack.common.periodic_task     imemory =
self._inode_operator.inodes_get_imemory()
2022-05-09 11:25:05.699 91940 ERROR
sysinv.openstack.common.periodic_task   File
"/usr/lib64/python2.7/site-packages/sysinv/agent/node.py", line 566,
in inodes_get_imemory
2022-05-09 11:25:05.699 91940 ERROR
sysinv.openstack.common.periodic_task     imemory =
self._inode_get_memory_hugepages()
2022-05-09 11:25:05.699 91940 ERROR
sysinv.openstack.common.periodic_task   File
"/usr/lib64/python2.7/site-packages/sysinv/agent/node.py", line 347,
in _inode_get_memory_hugepages
2022-05-09 11:25:05.699 91940 ERROR
sysinv.openstack.common.periodic_task     subdirs =
self._get_immediate_subdirs(hugepages)
2022-05-09 11:25:05.699 91940 ERROR
sysinv.openstack.common.periodic_task   File
"/usr/lib64/python2.7/site-packages/sysinv/agent/node.py", line 279,
in _get_immediate_subdirs
2022-05-09 11:25:05.699 91940 ERROR
sysinv.openstack.common.periodic_task     return [name for name in
listdir(dir)
2022-05-09 11:25:05.699 91940 ERROR
sysinv.openstack.common.periodic_task OSError: [Errno 2] No such file
or directory: '/sys/devices/system/node/node1/hugepages'
2022-05-09 11:25:05.699 91940 ERROR sysinv.openstack.common.periodic_task
sysinv 2022-05-09 11:25:21.715 98797 ERROR sysinv.conductor.kube_app
[-] Kubernetes is not configured. API operations will not be
available.: KubeNotConfigured: Kubernetes is not configured. API
operations will not be available.



More information about the Starlingx-discuss mailing list