Vm creation failed to finish deploy to foreman (foreman-userdata.sh) with cloud-init image based | foreman 1.16.1 | oVirt 4.2.2

Ale · May 22, 2018, 11:31am

Problem:
foreman-userdata.sh is not passed correctly to the vm

on ovirt 4.2.2:

create new vm (rhel7.5) in ovirt
register in rhn, update, install cloud-init, unregister. power-off vm
create template

on foreman 1.16.1:

go to infrastructure > Computer resources
Select ovirt resource / create new image from template
create new host using new image

new vm is created with proper hostname, ip, etc.
the problem is that it cannot run /tmp/foreman-userdata.sh due to:

/usr/bin/cloud-init-per: line 57: /tmp/foreman-userdata.sh: No such file or directory

logs:

[root@becky-ekman ~]# more /var/log/cloud-init-output.log 
Cloud-init v. 0.7.9 running 'init' at Tue, 22 May 2018 10:27:32 +0000. Up 12.46 seconds.
ci-info: ++++++++++++++++++++++++++++++Net device info++++++++++++++++++++++++++++++
ci-info: +--------+------+-------------+---------------+-------+-------------------+
ci-info: | Device |  Up  |   Address   |      Mask     | Scope |     Hw-Address    |
ci-info: +--------+------+-------------+---------------+-------+-------------------+
ci-info: |  lo:   | True |  127.0.0.1  |   255.0.0.0   |   .   |         .         |
ci-info: |  lo:   | True |      .      |       .       |   d   |         .         |
ci-info: | eth0:  | True | IP | 255.255.255.0 |   .   | 00:1a:4a:16:01:56 |
ci-info: | eth0:  | True |      .      |       .       |   d   | 00:1a:4a:16:01:56 |
ci-info: +--------+------+-------------+---------------+-------+-------------------+
ci-info: ++++++++++++++++++++++++++++++Route IPv4 info++++++++++++++++++++++++++++++
ci-info: +-------+-------------+---------------+---------------+-----------+-------+
ci-info: | Route | Destination |    Gateway    |    Genmask    | Interface | Flags |
ci-info: +-------+-------------+---------------+---------------+-----------+-------+
ci-info: |   0   |   0.0.0.0   | IP_GW |    0.0.0.0    |    eth0   |   UG  |
ci-info: |   1   | IP_NETWORK |    0.0.0.0    | 255.255.255.0 |    eth0   |   U   |
ci-info: +-------+-------------+---------------+---------------+-----------+-------+
Cloud-init v. 0.7.9 running 'modules:config' at Tue, 22 May 2018 10:27:34 +0000. Up 14.41 seconds.
Cloud-init v. 0.7.9 running 'modules:final' at Tue, 22 May 2018 10:27:35 +0000. Up 15.30 seconds.
/usr/bin/cloud-init-per: line 57: /tmp/foreman-userdata.sh: No such file or directory
2018-05-22 19:27:35,377 - util.py[WARNING]: Failed running /var/lib/cloud/instance/scripts/runcmd [127]
2018-05-22 19:27:35,386 - cc_scripts_user.py[WARNING]: Failed to run module scripts-user (scripts in /var/lib/cloud/instance/scripts)
2018-05-22 19:27:35,387 - util.py[WARNING]: Running module scripts-user (<module 'cloudinit.config.cc_scripts_user' from '/usr/lib/python2.7/site-packages/cloudinit/config/cc_scripts_user.pyc'>) failed
2018-05-22 19:27:35,454 - util.py[WARNING]: Configuration entry 'tries' is not an integer, using 10 instead
2018-05-22 19:27:35,456 - util.py[WARNING]: /etc/ssh/ssh_host_dsa_key.pub: failed to open, can not phone home that data!
Cloud-init v. 0.7.9 finished at Tue, 22 May 2018 10:26:57 +0000. Datasource DataSourceConfigDrive [local,ver=2][source=/dev/sr1].  Up 16.70 seconds
[root@becky-ekman ~]#

and /var/log/cloud-init.log:

...snip
2018-05-22 19:27:35,310 - util.py[DEBUG]: Cloud-init v. 0.7.9 running 'modules:final' at Tue, 22 May 2018 10:27:35 +0000. Up 15.30 seconds.
2018-05-22 19:27:35,334 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.rhel.Distro'>
2018-05-22 19:27:35,334 - stages.py[DEBUG]: Running module rightscale_userdata (<module 'cloudinit.config.cc_rightscale_userdata' from '/usr/lib/python2.7/site-packages/cloudinit/config/cc_rightscale_userdata.pyc'>) with frequency once-per-instance
2018-05-22 19:27:35,335 - handlers.py[DEBUG]: start: modules-final/config-rightscale_userdata: running config-rightscale_userdata with frequency once-per-instance
2018-05-22 19:27:35,335 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_rightscale_userdata - wb: [420] 20 bytes
2018-05-22 19:27:35,336 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_rightscale_userdata (recursive=False)
2018-05-22 19:27:35,336 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_rightscale_userdata (recursive=False)
2018-05-22 19:27:35,337 - helpers.py[DEBUG]: Running config-rightscale_userdata using lock (<FileLock using file '/var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_rightscale_userdata'>)
2018-05-22 19:27:35,337 - cc_rightscale_userdata.py[DEBUG]: Failed to get raw userdata in module rightscale_userdata
2018-05-22 19:27:35,337 - handlers.py[DEBUG]: finish: modules-final/config-rightscale_userdata: SUCCESS: config-rightscale_userdata ran successfully
2018-05-22 19:27:35,337 - stages.py[DEBUG]: Running module scripts-per-once (<module 'cloudinit.config.cc_scripts_per_once' from '/usr/lib/python2.7/site-packages/cloudinit/config/cc_scripts_per_once.pyc'>) with frequency once
2018-05-22 19:27:35,337 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-once: running config-scripts-per-once with frequency once
2018-05-22 19:27:35,337 - util.py[DEBUG]: Writing to /var/lib/cloud/sem/config_scripts_per_once.once - wb: [420] 20 bytes
2018-05-22 19:27:35,338 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/sem/config_scripts_per_once.once (recursive=False)
2018-05-22 19:27:35,338 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/sem/config_scripts_per_once.once (recursive=False)
2018-05-22 19:27:35,339 - helpers.py[DEBUG]: Running config-scripts-per-once using lock (<FileLock using file '/var/lib/cloud/sem/config_scripts_per_once.once'>)
2018-05-22 19:27:35,339 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-once: SUCCESS: config-scripts-per-once ran successfully
2018-05-22 19:27:35,339 - stages.py[DEBUG]: Running module scripts-per-boot (<module 'cloudinit.config.cc_scripts_per_boot' from '/usr/lib/python2.7/site-packages/cloudinit/config/cc_scripts_per_boot.pyc'>) with frequency always
2018-05-22 19:27:35,339 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-boot: running config-scripts-per-boot with frequency always
2018-05-22 19:27:35,339 - helpers.py[DEBUG]: Running config-scripts-per-boot using lock (<cloudinit.helpers.DummyLock object at 0x7f525fece690>)
2018-05-22 19:27:35,340 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-boot: SUCCESS: config-scripts-per-boot ran successfully
2018-05-22 19:27:35,340 - stages.py[DEBUG]: Running module scripts-per-instance (<module 'cloudinit.config.cc_scripts_per_instance' from '/usr/lib/python2.7/site-packages/cloudinit/config/cc_scripts_per_instance.pyc'>) with frequency once-per-instance
2018-05-22 19:27:35,340 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-instance: running config-scripts-per-instance with frequency once-per-instance
2018-05-22 19:27:35,340 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_scripts_per_instance - wb: [420] 20 bytes
2018-05-22 19:27:35,341 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_scripts_per_instance (recursive=False)
2018-05-22 19:27:35,341 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_scripts_per_instance (recursive=False)
2018-05-22 19:27:35,342 - helpers.py[DEBUG]: Running config-scripts-per-instance using lock (<FileLock using file '/var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_scripts_per_instance'>)
2018-05-22 19:27:35,342 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-instance: SUCCESS: config-scripts-per-instance ran successfully
2018-05-22 19:27:35,342 - stages.py[DEBUG]: Running module scripts-user (<module 'cloudinit.config.cc_scripts_user' from '/usr/lib/python2.7/site-packages/cloudinit/config/cc_scripts_user.pyc'>) with frequency once-per-instance
2018-05-22 19:27:35,342 - handlers.py[DEBUG]: start: modules-final/config-scripts-user: running config-scripts-user with frequency once-per-instance
2018-05-22 19:27:35,342 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_scripts_user - wb: [420] 20 bytes
2018-05-22 19:27:35,343 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_scripts_user (recursive=False)
2018-05-22 19:27:35,344 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_scripts_user (recursive=False)
2018-05-22 19:27:35,344 - helpers.py[DEBUG]: Running config-scripts-user using lock (<FileLock using file '/var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_scripts_user'>)
2018-05-22 19:27:35,344 - util.py[DEBUG]: Running command ['/var/lib/cloud/instance/scripts/runcmd'] with allowed return codes [0] (shell=False, capture=False)
2018-05-22 19:27:35,377 - util.py[WARNING]: Failed running /var/lib/cloud/instance/scripts/runcmd [127]
2018-05-22 19:27:35,377 - util.py[DEBUG]: Failed running /var/lib/cloud/instance/scripts/runcmd [127]
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/cloudinit/util.py", line 802, in runparts
    subp(prefix + [exe_path], capture=False)
  File "/usr/lib/python2.7/site-packages/cloudinit/util.py", line 1858, in subp
    cmd=args)
ProcessExecutionError: Unexpected error while running command.
Command: ['/var/lib/cloud/instance/scripts/runcmd']
Exit code: 127
Reason: -
Stdout: -
Stderr: -
2018-05-22 19:27:35,386 - cc_scripts_user.py[WARNING]: Failed to run module scripts-user (scripts in /var/lib/cloud/instance/scripts)
2018-05-22 19:27:35,387 - handlers.py[DEBUG]: finish: modules-final/config-scripts-user: FAIL: running config-scripts-user with frequency once-per-instance
2018-05-22 19:27:35,387 - util.py[WARNING]: Running module scripts-user (<module 'cloudinit.config.cc_scripts_user' from '/usr/lib/python2.7/site-packages/cloudinit/config/cc_scripts_user.pyc'>) failed
2018-05-22 19:27:35,387 - util.py[DEBUG]: Running module scripts-user (<module 'cloudinit.config.cc_scripts_user' from '/usr/lib/python2.7/site-packages/cloudinit/config/cc_scripts_user.pyc'>) failed
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/cloudinit/stages.py", line 777, in _run_modules
    freq=freq)
  File "/usr/lib/python2.7/site-packages/cloudinit/cloud.py", line 54, in run
    return self._runners.run(name, functor, args, freq, clear_on_fail)
  File "/usr/lib/python2.7/site-packages/cloudinit/helpers.py", line 187, in run
    results = functor(*args)
  File "/usr/lib/python2.7/site-packages/cloudinit/config/cc_scripts_user.py", line 45, in handle
    util.runparts(runparts_path)
  File "/usr/lib/python2.7/site-packages/cloudinit/util.py", line 809, in runparts
    % (len(failed), len(attempted)))
RuntimeError: Runparts: 1 failures in 1 attempted commands
2018-05-22 19:27:35,403 - stages.py[DEBUG]: Running module ssh-authkey-fingerprints (<module 'cloudinit.config.cc_ssh_authkey_fingerprints' from '/usr/lib/python2.7/site-packages/cloudinit/config/cc_ssh_authkey_fingerprints.pyc'>) with frequency once-per-instance
2018-05-22 19:27:35,403 - handlers.py[DEBUG]: start: modules-final/config-ssh-authkey-fingerprints: running config-ssh-authkey-fingerprints with frequency once-per-instance
2018-05-22 19:27:35,403 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_ssh_authkey_fingerprints - wb: [420] 19 bytes
2018-05-22 19:27:35,404 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_ssh_authkey_fingerprints (recursive=False)
2018-05-22 19:27:35,405 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_ssh_authkey_fingerprints (recursive=False)
2018-05-22 19:27:35,405 - helpers.py[DEBUG]: Running config-ssh-authkey-fingerprints using lock (<FileLock using file '/var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_ssh_authkey_fingerprints'>)
2018-05-22 19:27:35,406 - util.py[DEBUG]: Reading from /etc/ssh/sshd_config (quiet=False)
2018-05-22 19:27:35,406 - util.py[DEBUG]: Read 3906 bytes from /etc/ssh/sshd_config
2018-05-22 19:27:35,407 - util.py[DEBUG]: Restoring selinux mode for /home/cloud-user/.ssh (recursive=True)
2018-05-22 19:27:35,407 - util.py[DEBUG]: Reading from /home/cloud-user/.ssh/authorized_keys (quiet=False)
2018-05-22 19:27:35,407 - util.py[DEBUG]: Read 429 bytes from /home/cloud-user/.ssh/authorized_keys
2018-05-22 19:27:35,409 - handlers.py[DEBUG]: finish: modules-final/config-ssh-authkey-fingerprints: SUCCESS: config-ssh-authkey-fingerprints ran successfully
2018-05-22 19:27:35,409 - stages.py[DEBUG]: Running module keys-to-console (<module 'cloudinit.config.cc_keys_to_console' from '/usr/lib/python2.7/site-packages/cloudinit/config/cc_keys_to_console.pyc'>) with frequency once-per-instance
2018-05-22 19:27:35,409 - handlers.py[DEBUG]: start: modules-final/config-keys-to-console: running config-keys-to-console with frequency once-per-instance
2018-05-22 19:27:35,410 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_keys_to_console - wb: [420] 20 bytes
2018-05-22 19:27:35,410 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_keys_to_console (recursive=False)
2018-05-22 19:27:35,411 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_keys_to_console (recursive=False)
2018-05-22 19:27:35,411 - helpers.py[DEBUG]: Running config-keys-to-console using lock (<FileLock using file '/var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_keys_to_console'>)
2018-05-22 19:27:35,411 - util.py[DEBUG]: Running command ['/usr/libexec/cloud-init/write-ssh-key-fingerprints', '', 'ssh-dss'] with allowed return codes [0] (shell=False, capture=True)
2018-05-22 19:27:35,452 - handlers.py[DEBUG]: finish: modules-final/config-keys-to-console: SUCCESS: config-keys-to-console ran successfully
2018-05-22 19:27:35,452 - stages.py[DEBUG]: Running module phone-home (<module 'cloudinit.config.cc_phone_home' from '/usr/lib/python2.7/site-packages/cloudinit/config/cc_phone_home.pyc'>) with frequency once-per-instance
2018-05-22 19:27:35,452 - handlers.py[DEBUG]: start: modules-final/config-phone-home: running config-phone-home with frequency once-per-instance
2018-05-22 19:27:35,453 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_phone_home - wb: [420] 20 bytes
2018-05-22 19:27:35,453 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_phone_home (recursive=False)
2018-05-22 19:27:35,454 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_phone_home (recursive=False)
2018-05-22 19:27:35,454 - helpers.py[DEBUG]: Running config-phone-home using lock (<FileLock using file '/var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_phone_home'>)
2018-05-22 19:27:35,454 - util.py[WARNING]: Configuration entry 'tries' is not an integer, using 10 instead
2018-05-22 19:27:35,454 - util.py[DEBUG]: Configuration entry 'tries' is not an integer, using 10 instead
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/cloudinit/config/cc_phone_home.py", line 89, in handle
    tries = int(tries)
TypeError: int() argument must be a string or a number, not 'NoneType'
2018-05-22 19:27:35,456 - util.py[DEBUG]: Reading from /etc/ssh/ssh_host_ecdsa_key.pub (quiet=False)
2018-05-22 19:27:35,456 - util.py[DEBUG]: Read 162 bytes from /etc/ssh/ssh_host_ecdsa_key.pub
2018-05-22 19:27:35,456 - util.py[DEBUG]: Reading from /etc/ssh/ssh_host_rsa_key.pub (quiet=False)
2018-05-22 19:27:35,456 - util.py[DEBUG]: Read 382 bytes from /etc/ssh/ssh_host_rsa_key.pub
2018-05-22 19:27:35,456 - util.py[DEBUG]: Reading from /etc/ssh/ssh_host_dsa_key.pub (quiet=False)
2018-05-22 19:27:35,456 - util.py[WARNING]: /etc/ssh/ssh_host_dsa_key.pub: failed to open, can not phone home that data!
2018-05-22 19:27:35,456 - util.py[DEBUG]: /etc/ssh/ssh_host_dsa_key.pub: failed to open, can not phone home that data!
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/cloudinit/config/cc_phone_home.py", line 111, in handle
    all_keys[n] = util.load_file(path)
  File "/usr/lib/python2.7/site-packages/cloudinit/util.py", line 1278, in load_file
    with open(fname, 'rb') as ifh:
IOError: [Errno 2] No such file or directory: '/etc/ssh/ssh_host_dsa_key.pub'
2018-05-22 19:27:35,457 - url_helper.py[DEBUG]: [0/11] open 'http://HOSTNAME_FQDN:8000/unattended/built?token=00ec4ab5-841e-4c36-a78a-d6f9fef310c0' with {'url': 'http://HOSTNAME_FQDN:8000/unattended/built?token=00ec4ab5-841e-4c36-a78a
-d6f9fef310c0', 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}, 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0} configuration
2018-05-22 19:26:57,969 - url_helper.py[DEBUG]: Read from http://HOSTNAME_FQDN:8000/unattended/built?token=00ec4ab5-841e-4c36-a78a-d6f9fef310c0 (200, 0b) after 1 attempts
2018-05-22 19:26:57,969 - handlers.py[DEBUG]: finish: modules-final/config-phone-home: SUCCESS: config-phone-home ran successfully
2018-05-22 19:26:57,969 - stages.py[DEBUG]: Running module final-message (<module 'cloudinit.config.cc_final_message' from '/usr/lib/python2.7/site-packages/cloudinit/config/cc_final_message.pyc'>) with frequency always
2018-05-22 19:26:57,970 - handlers.py[DEBUG]: start: modules-final/config-final-message: running config-final-message with frequency always
2018-05-22 19:26:57,970 - helpers.py[DEBUG]: Running config-final-message using lock (<cloudinit.helpers.DummyLock object at 0x7f525ff03810>)
2018-05-22 19:26:57,970 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2018-05-22 19:26:57,971 - util.py[DEBUG]: Read 11 bytes from /proc/uptime
2018-05-22 19:26:57,975 - util.py[DEBUG]: Cloud-init v. 0.7.9 finished at Tue, 22 May 2018 10:26:57 +0000. Datasource DataSourceConfigDrive [local,ver=2][source=/dev/sr1].  Up 16.70 seconds
2018-05-22 19:26:57,976 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/boot-finished - wb: [420] 51 bytes
2018-05-22 19:26:57,977 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/boot-finished (recursive=False)
2018-05-22 19:26:57,978 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/boot-finished (recursive=False)
2018-05-22 19:26:57,978 - handlers.py[DEBUG]: finish: modules-final/config-final-message: SUCCESS: config-final-message ran successfully
2018-05-22 19:26:57,978 - stages.py[DEBUG]: Running module power-state-change (<module 'cloudinit.config.cc_power_state_change' from '/usr/lib/python2.7/site-packages/cloudinit/config/cc_power_state_change.pyc'>) with frequency once-per-instance
2018-05-22 19:26:57,979 - handlers.py[DEBUG]: start: modules-final/config-power-state-change: running config-power-state-change with frequency once-per-instance
2018-05-22 19:26:57,979 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_power_state_change - wb: [420] 20 bytes
2018-05-22 19:26:57,979 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_power_state_change (recursive=False)
2018-05-22 19:26:57,980 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_power_state_change (recursive=False)
2018-05-22 19:26:57,980 - helpers.py[DEBUG]: Running config-power-state-change using lock (<FileLock using file '/var/lib/cloud/instances/9557d55d-a279-4428-bc91-3f71edfd6954/sem/config_power_state_change'>)
2018-05-22 19:26:57,981 - cc_power_state_change.py[DEBUG]: no power_state provided. doing nothing
2018-05-22 19:26:57,981 - handlers.py[DEBUG]: finish: modules-final/config-power-state-change: SUCCESS: config-power-state-change ran successfully
2018-05-22 19:26:57,981 - main.py[DEBUG]: Ran 10 modules with 1 failures
2018-05-22 19:26:57,982 - util.py[DEBUG]: Creating symbolic link from '/run/cloud-init/result.json' => '../../var/lib/cloud/data/result.json'
2018-05-22 19:26:57,982 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2018-05-22 19:26:57,982 - util.py[DEBUG]: Read 11 bytes from /proc/uptime
2018-05-22 19:26:57,982 - util.py[DEBUG]: cloud-init mode 'modules' took -37.240 seconds (1.41)
2018-05-22 19:26:57,982 - handlers.py[DEBUG]: finish: modules-final: FAIL: running modules for final

Expected outcome:
/tmp/foreman-userdata.sh should be copied to the target vm and foreman finish deployment.

Foreman and Proxy versions:
1.16.1 latest

Foreman and Proxy plugin versions:
1.16.1 latest

Other relevant data:
I created a new vm from template within ovirt using run-once cloud-init with no issue.
related Feature #20590: Full cloud-init support with ovirt provider - Foreman ?

iNecas · May 22, 2018, 2:12pm

Could you share the user_data template you’re using?

I’m aware also of this issue Bug #20591: Support for multi-line runcmd cloudinit commands in oVirt - Foreman, that caused the multi-line runcmd commands not not work properly.

The patch is here https://github.com/abenari/rbovirt/commit/04997bc40b5fde6b7c94987da8eb237411acbb32, it was released in rbovirt 0.1.4. It was released in 1.17, you could try updating just this package (https://yum.theforeman.org/releases/1.17/el7/x86_64/tfm-rubygem-rbovirt-0.1.4-2.el7.noarch.rpm provided you’re running rpms). Again, not sure if that’s your issue, but that’s something I know was causing troubles in the past.

Ale · May 22, 2018, 2:41pm

Hi @iNecas,

thanks for quick reply and your links!

user_data template is the default one. I will check your links tomorrow morning (23:40 +9 here)

Cheers,

Ale · May 23, 2018, 1:59am

I tried to update but dependency failed:

[root@prov-01 ~]# yum update tfm-rubygem-rbovirt-0.1.4-2.el7.noarch.rpm 
Loaded plugins: product-id, search-disabled-repos, subscription-manager
Examining tfm-rubygem-rbovirt-0.1.4-2.el7.noarch.rpm: tfm-rubygem-rbovirt-0.1.4-2.el7.noarch
Marking tfm-rubygem-rbovirt-0.1.4-2.el7.noarch.rpm as an update to tfm-rubygem-rbovirt-0.1.3-1.el7.noarch
Resolving Dependencies
--> Running transaction check
---> Package tfm-rubygem-rbovirt.noarch 0:0.1.3-1.el7 will be updated
---> Package tfm-rubygem-rbovirt.noarch 0:0.1.4-2.el7 will be an update
--> Processing Dependency: rh-ruby24-ruby(release) for package: tfm-rubygem-rbovirt-0.1.4-2.el7.noarch
--> Processing Dependency: tfm-ror51-rubygem-nokogiri for package: tfm-rubygem-rbovirt-0.1.4-2.el7.noarch
--> Running transaction check
---> Package rh-ruby24-ruby-libs.x86_64 0:2.4.3-90.el7 will be installed
--> Processing Dependency: rh-ruby24-runtime for package: rh-ruby24-ruby-libs-2.4.3-90.el7.x86_64
---> Package tfm-rubygem-rbovirt.noarch 0:0.1.4-2.el7 will be an update
--> Processing Dependency: tfm-ror51-rubygem-nokogiri for package: tfm-rubygem-rbovirt-0.1.4-2.el7.noarch
--> Running transaction check
---> Package rh-ruby24-runtime.x86_64 0:2.4-2.el7 will be installed
---> Package tfm-rubygem-rbovirt.noarch 0:0.1.4-2.el7 will be an update
--> Processing Dependency: tfm-ror51-rubygem-nokogiri for package: tfm-rubygem-rbovirt-0.1.4-2.el7.noarch
--> Finished Dependency Resolution
Error: Package: tfm-rubygem-rbovirt-0.1.4-2.el7.noarch (/tfm-rubygem-rbovirt-0.1.4-2.el7.noarch)
           Requires: tfm-ror51-rubygem-nokogiri
**********************************************************************
yum can be configured to try to resolve such errors by temporarily enabling
disabled repos and searching for missing dependencies.
To enable this functionality please set 'notify_only=0' in /etc/yum/pluginconf.d/search-disabled-repos.conf
**********************************************************************

Error: Package: tfm-rubygem-rbovirt-0.1.4-2.el7.noarch (/tfm-rubygem-rbovirt-0.1.4-2.el7.noarch)
           Requires: tfm-ror51-rubygem-nokogiri
 You could try using --skip-broken to work around the problem
 You could try running: rpm -Va --nofiles --nodigest
[root@prov-01 ~]#

Also I copied the new vm.rb and the vm is created but fails to power up due to:

Failed to power up a compute metal01 (oVirt) instance ethel-sandell.example.com: undefined method `lines' for #<Array:0x0000000c9e8e30>

Any clue?

iNecas · May 23, 2018, 12:12pm

Oh, the problem is the scl changed between 1.16 and 1.17.

Another option is taking the patch https://github.com/abenari/rbovirt/commit/04997bc40b5fde6b7c94987da8eb237411acbb32.patch, applying it against the rbovirt and restarting the services. I think it’s worth trying, as it’s pretty simple change.

Ale · May 25, 2018, 6:42am

Hi @iNecas,

I just tried with fresh katello 3.6 fresh install and got same error:

Failed to power up a compute metal01 (oVirt) instance keri-honch.example.com: undefined method `lines' for #<Array:0x00007f7648fb2870>

Cheers,

iNecas · May 25, 2018, 1:20pm

Any backlog that would be available for this error?

Also could you share the used-data template you’re using?

dLobatog · May 26, 2018, 10:55am

@Ale

As far as I know this bug looks pretty much identical to Bug #23212: Changing power state gives: NameError: uninitialized constant Fog::Compute::Ovirt - Foreman

Could you try applying the patch directly to /usr/share/foreman/app/services/power_manager/virt.rb as you see here, https://github.com/theforeman/foreman/commit/394acb3252dfa28e7146ff38cc9c8e1060f88ce1 then restarting httpd?

Ale · May 28, 2018, 2:40am

Hi @iNecas and @dLobatog,

I applied the patch, restarted httpd but got same error:

Failed to power up a compute metal01 (oVirt) instance leigh-eppes.example.com: undefined method `lines' for #<Array:0x000000000abccd48>

Katello kickstart Default User Data: https://pastebin.com/nMypwemj

[root@prov-01 ~]# cd /var/log/
[root@prov-01 log]# grep -r eppes .
./foreman-proxy/proxy.log:E, [2018-05-28T10:57:28.781348 1f074eba] ERROR -- : Attempt to remove nonexistent client certificate for leigh-eppes.example.com
./foreman-proxy/proxy.log:I, [2018-05-28T10:57:28.782651 1f074eba]  INFO -- : FOREMAN_IP - - [28/May/2018:10:57:28 +0900] "DELETE /puppet/ca/leigh-eppes.example.com HTTP/1.1" 404 90 3.0161
./foreman-proxy/proxy.log:I, [2018-05-28T10:57:28.851910 1f074eba]  INFO -- : FOREMAN_IP - - [28/May/2018:10:57:28 +0900] "POST /puppet/ca/autosign/leigh-eppes.example.com HTTP/1.1" 200 - 0.0013
./foreman-proxy/proxy.log:I, [2018-05-28T10:57:44.787885 1f074eba]  INFO -- : FOREMAN_IP - - [28/May/2018:10:57:44 +0900] "DELETE /realm/REALM_DOMAIN/leigh-eppes.example.com HTTP/1.1" 200 161 0.4468
./foreman-proxy/proxy.log:I, [2018-05-28T10:57:45.059662 1f074eba]  INFO -- : FOREMAN_IP - - [28/May/2018:10:57:45 +0900] "DELETE /dns/leigh-eppes.example.com/A HTTP/1.1" 200 - 0.0901
./foreman-proxy/proxy.log:E, [2018-05-28T10:57:49.211259 1f074eba] ERROR -- : Attempt to remove nonexistent client certificate for leigh-eppes.example.com
./foreman-proxy/proxy.log:I, [2018-05-28T10:57:49.212685 1f074eba]  INFO -- : FOREMAN_IP - - [28/May/2018:10:57:49 +0900] "DELETE /puppet/ca/leigh-eppes.example.com HTTP/1.1" 404 90 3.0058
./foreman-proxy/proxy.log:I, [2018-05-28T10:57:49.281339 1f074eba]  INFO -- : FOREMAN_IP - - [28/May/2018:10:57:49 +0900] "DELETE /puppet/ca/autosign/leigh-eppes.example.com HTTP/1.1" 200 - 0.0016
./foreman/production.log:2018-05-28 10:56:51 3bde7f11 [app] [I]   Parameters: {"utf8"=>"✓", "authenticity_token"=>"xxpYRXWv5VTHO+a25MMyIAbmE7UHXxaSQsND22mtc8IUTia8H54knLvcFCPzXg/86pw6yTcDCe0I4Q+F/1iD1Q==", "host"=>{"name"=>"leigh-eppes", "organization_id"=>"1", "location_id"=>"2", "hostgroup_id"=>"2", "content_facet_attributes"=>{"lifecycle_environment_id"=>"", "content_view_id"=>"", "content_source_id"=>""}, "managed"=>"true", "progress_report_id"=>"[FILTERED]", "type"=>"Host::Managed", "interfaces_attributes"=>{"0"=>{"_destroy"=>"0", "type"=>"Nic::Managed", "mac"=>"", "identifier"=>"", "name"=>"leigh-eppes", "domain_id"=>"", "subnet_id"=>"", "ip"=>"", "ip6"=>"", "managed"=>"1", "primary"=>"1", "provision"=>"1", "execution"=>"1", "virtual"=>"0", "tag"=>"", "attached_to"=>""}}, "architecture_id"=>"", "provision_method"=>"build", "build"=>"1", "disk"=>"", "root_pass"=>"[FILTERED]", "is_owned_by"=>"4-Users", "enabled"=>"1", "model_id"=>"", "comment"=>"", "overwrite"=>"false"}, "fakepassword"=>"[FILTERED]", "bare_metal_capabilities"=>"build"}
./foreman/production.log:2018-05-28 10:56:53 30d48974 [app] [I]   Parameters: {"utf8"=>"✓", "authenticity_token"=>"N3TwE3F2P3Qsyij/dxK1aKoshvoksqyKVPZVtCd9w5jkII7qG0f+vFAt2mpgj4i0RlavhhTus/Ue1BnqsYgzjw==", "host"=>{"name"=>"leigh-eppes", "organization_id"=>"1", "location_id"=>"2", "hostgroup_id"=>"2", "compute_resource_id"=>"", "content_facet_attributes"=>{"lifecycle_environment_id"=>"2", "content_view_id"=>"2", "content_source_id"=>"1"}, "puppetclass_ids"=>[""], "managed"=>"true", "progress_report_id"=>"[FILTERED]", "type"=>"Host::Managed", "interfaces_attributes"=>{"0"=>{"_destroy"=>"0", "type"=>"Nic::Managed", "mac"=>"", "identifier"=>"", "name"=>"leigh-eppes", "domain_id"=>"1", "subnet_id"=>"1", "ip"=>"", "ip6"=>"", "managed"=>"1", "primary"=>"1", "provision"=>"1", "execution"=>"1", "virtual"=>"0", "tag"=>"", "attached_to"=>""}}, "architecture_id"=>"1", "operatingsystem_id"=>"1", "provision_method"=>"build", "build"=>"1", "medium_id"=>"9", "ptable_id"=>"90", "pxe_loader"=>"PXELinux BIOS", "disk"=>"", "root_pass"=>"[FILTERED]", "is_owned_by"=>"4-Users", "enabled"=>"1", "model_id"=>"", "comment"=>"", "overwrite"=>"false"}, "media_selector"=>"install_media", "fakepassword"=>"[FILTERED]", "bare_metal_capabilities"=>"build"}
./foreman/production.log:2018-05-28 10:56:55 2b32cc59 [app] [I]   Parameters: {"utf8"=>"✓", "authenticity_token"=>"N3TwE3F2P3Qsyij/dxK1aKoshvoksqyKVPZVtCd9w5jkII7qG0f+vFAt2mpgj4i0RlavhhTus/Ue1BnqsYgzjw==", "host"=>{"name"=>"leigh-eppes", "organization_id"=>"1", "location_id"=>"2", "hostgroup_id"=>"2", "compute_resource_id"=>"2", "content_facet_attributes"=>{"lifecycle_environment_id"=>"2", "content_view_id"=>"2", "content_source_id"=>"1"}, "puppetclass_ids"=>[""], "managed"=>"true", "progress_report_id"=>"[FILTERED]", "type"=>"Host::Managed", "interfaces_attributes"=>{"0"=>{"_destroy"=>"0", "type"=>"Nic::Managed", "mac"=>"", "identifier"=>"", "name"=>"leigh-eppes", "domain_id"=>"1", "subnet_id"=>"1", "ip"=>"NEW_VM_IP", "ip6"=>"", "managed"=>"1", "primary"=>"1", "provision"=>"1", "execution"=>"1", "virtual"=>"0", "tag"=>"", "attached_to"=>""}}, "architecture_id"=>"1", "operatingsystem_id"=>"1", "provision_method"=>"build", "build"=>"1", "medium_id"=>"9", "ptable_id"=>"90", "pxe_loader"=>"PXELinux BIOS", "disk"=>"", "root_pass"=>"[FILTERED]", "is_owned_by"=>"4-Users", "enabled"=>"1", "model_id"=>"", "comment"=>"", "overwrite"=>"false"}, "media_selector"=>"install_media", "fakepassword"=>"[FILTERED]", "bare_metal_capabilities"=>"build"}
./foreman/production.log:2018-05-28 10:56:57 1a146bf4 [app] [I]   Parameters: {"utf8"=>"✓", "authenticity_token"=>"N3TwE3F2P3Qsyij/dxK1aKoshvoksqyKVPZVtCd9w5jkII7qG0f+vFAt2mpgj4i0RlavhhTus/Ue1BnqsYgzjw==", "host"=>{"name"=>"leigh-eppes", "organization_id"=>"1", "location_id"=>"2", "hostgroup_id"=>"2", "compute_resource_id"=>"2", "content_facet_attributes"=>{"lifecycle_environment_id"=>"2", "content_view_id"=>"2", "content_source_id"=>"1"}, "puppetclass_ids"=>[""], "managed"=>"true", "progress_report_id"=>"[FILTERED]", "type"=>"Host::Managed", "interfaces_attributes"=>{"0"=>{"_destroy"=>"0", "type"=>"Nic::Managed", "mac"=>"", "identifier"=>"", "name"=>"leigh-eppes", "domain_id"=>"1", "subnet_id"=>"1", "ip"=>"NEW_VM_IP", "ip6"=>"", "managed"=>"1", "primary"=>"1", "provision"=>"1", "execution"=>"1", "virtual"=>"0", "tag"=>"", "attached_to"=>""}}, "compute_attributes"=>{"cluster"=>"f873df04-bb67-4230-9ca3-99a97d47cac8", "template"=>"", "instance_type"=>"", "cores"=>"", "memory"=>"", "start"=>"1"}, "architecture_id"=>"1", "operatingsystem_id"=>"1", "provision_method"=>"build", "build"=>"1", "medium_id"=>"9", "ptable_id"=>"90", "pxe_loader"=>"PXELinux BIOS", "disk"=>"", "root_pass"=>"[FILTERED]", "is_owned_by"=>"4-Users", "enabled"=>"1", "model_id"=>"", "comment"=>"", "overwrite"=>"false"}, "capabilities"=>"build image new_volume", "provider"=>"Ovirt", "media_selector"=>"install_media", "fakepassword"=>"[FILTERED]", "bare_metal_capabilities"=>"build"}
./foreman/production.log:2018-05-28 10:56:59 8a736216 [app] [I]   Parameters: {"utf8"=>"✓", "authenticity_token"=>"N3TwE3F2P3Qsyij/dxK1aKoshvoksqyKVPZVtCd9w5jkII7qG0f+vFAt2mpgj4i0RlavhhTus/Ue1BnqsYgzjw==", "host"=>{"name"=>"leigh-eppes", "organization_id"=>"1", "location_id"=>"2", "hostgroup_id"=>"2", "compute_resource_id"=>"2", "compute_profile_id"=>"4", "content_facet_attributes"=>{"lifecycle_environment_id"=>"2", "content_view_id"=>"2", "content_source_id"=>"1"}, "puppetclass_ids"=>[""], "managed"=>"true", "progress_report_id"=>"[FILTERED]", "type"=>"Host::Managed", "compute_attributes"=>{"cluster"=>"f873df04-bb67-4230-9ca3-99a97d47cac8", "template"=>"", "instance_type"=>"", "cores"=>"", "memory"=>"", "start"=>"1"}, "architecture_id"=>"1", "operatingsystem_id"=>"1", "provision_method"=>"build", "build"=>"1", "medium_id"=>"9", "ptable_id"=>"90", "pxe_loader"=>"PXELinux BIOS", "disk"=>"", "root_pass"=>"[FILTERED]", "is_owned_by"=>"4-Users", "enabled"=>"1", "model_id"=>"", "comment"=>"", "overwrite"=>"false"}, "capabilities"=>"build image new_volume", "provider"=>"Ovirt", "media_selector"=>"install_media", "fakepassword"=>"[FILTERED]", "bare_metal_capabilities"=>"build"}
./foreman/production.log:2018-05-28 10:57:01 52884cec [app] [I]   Parameters: {"utf8"=>"✓", "authenticity_token"=>"N3TwE3F2P3Qsyij/dxK1aKoshvoksqyKVPZVtCd9w5jkII7qG0f+vFAt2mpgj4i0RlavhhTus/Ue1BnqsYgzjw==", "host"=>{"name"=>"leigh-eppes", "organization_id"=>"1", "location_id"=>"2", "hostgroup_id"=>"2", "compute_resource_id"=>"2", "compute_profile_id"=>"4", "content_facet_attributes"=>{"lifecycle_environment_id"=>"2", "content_view_id"=>"2", "content_source_id"=>"1"}, "puppetclass_ids"=>[""], "managed"=>"true", "progress_report_id"=>"[FILTERED]", "type"=>"Host::Managed", "compute_attributes"=>{"cluster"=>"f873df04-bb67-4230-9ca3-99a97d47cac8", "template"=>"ffe6c56f-f250-4537-b765-201315e314a1", "instance_type"=>"", "cores"=>"2", "memory"=>"2147483648", "start"=>"1", "volumes_attributes"=>{"0"=>{"_delete"=>"", "size_gb"=>"50", "storage_domain"=>"c6a977a6-cd64-4999-8568-909a816c5927", "id"=>"", "preallocate"=>"0", "wipe_after_delete"=>"0", "interface"=>"virtio_scsi"}}}, "architecture_id"=>"1", "operatingsystem_id"=>"1", "provision_method"=>"build", "build"=>"1", "medium_id"=>"9", "ptable_id"=>"90", "pxe_loader"=>"PXELinux BIOS", "disk"=>"", "root_pass"=>"[FILTERED]", "is_owned_by"=>"4-Users", "enabled"=>"1", "model_id"=>"", "comment"=>"", "overwrite"=>"false"}, "capabilities"=>"build image new_volume", "provider"=>"Ovirt", "media_selector"=>"install_media", "fakepassword"=>"[FILTERED]", "bare_metal_capabilities"=>"build"}
./foreman/production.log:2018-05-28 10:57:13 e95c438e [app] [I]   Parameters: {"utf8"=>"✓", "authenticity_token"=>"N3TwE3F2P3Qsyij/dxK1aKoshvoksqyKVPZVtCd9w5jkII7qG0f+vFAt2mpgj4i0RlavhhTus/Ue1BnqsYgzjw==", "host"=>{"name"=>"leigh-eppes", "organization_id"=>"1", "location_id"=>"2", "hostgroup_id"=>"2", "compute_resource_id"=>"2", "compute_profile_id"=>"4", "content_facet_attributes"=>{"lifecycle_environment_id"=>"2", "content_view_id"=>"2", "content_source_id"=>"1"}, "puppetclass_ids"=>[""], "managed"=>"true", "progress_report_id"=>"[FILTERED]", "type"=>"Host::Managed", "interfaces_attributes"=>{"0"=>{"_destroy"=>"0", "type"=>"Nic::Managed", "mac"=>"", "identifier"=>"", "name"=>"leigh-eppes", "domain_id"=>"", "subnet_id"=>"", "ip"=>"", "ip6"=>"", "managed"=>"1", "primary"=>"1", "provision"=>"1", "execution"=>"1", "virtual"=>"0", "tag"=>"", "attached_to"=>"", "compute_attributes"=>{"name"=>"eth0", "network"=>"64372318-f8c5-4033-bb67-7cff69e36773"}}, "new_interfaces"=>{"_destroy"=>"1", "type"=>"Nic::Managed", "mac"=>"", "identifier"=>"", "name"=>"", "domain_id"=>"", "subnet_id"=>"", "ip"=>"", "ip6"=>"", "managed"=>"1", "primary"=>"0", "provision"=>"0", "execution"=>"0", "virtual"=>"0", "tag"=>"", "attached_to"=>"", "compute_attributes"=>{"name"=>"", "network"=>"b12c2a81-62d5-4b40-9e3b-77e97f109fe1"}}}, "compute_attributes"=>{"cluster"=>"f873df04-bb67-4230-9ca3-99a97d47cac8", "instance_type"=>"", "cores"=>"2", "memory"=>"2147483648", "start"=>"1", "volumes_attributes"=>{"new_volumes"=>{"_delete"=>"", "size_gb"=>"", "storage_domain"=>"c6a977a6-cd64-4999-8568-909a816c5927", "id"=>"", "preallocate"=>"0", "wipe_after_delete"=>"0", "interface"=>""}, "0"=>{"_delete"=>"", "size_gb"=>"50", "storage_domain"=>"c6a977a6-cd64-4999-8568-909a816c5927", "id"=>"", "preallocate"=>"0", "wipe_after_delete"=>"0", "interface"=>"virtio_scsi"}}, "image_id"=>"ffe6c56f-f250-4537-b765-201315e314a1"}, "architecture_id"=>"1", "operatingsystem_id"=>"1", "provision_method"=>"image", "build"=>"1", "medium_id"=>"9", "ptable_id"=>"90", "pxe_loader"=>"PXELinux BIOS", "disk"=>"", "root_pass"=>"[FILTERED]", "is_owned_by"=>"4-Users", "enabled"=>"1", "model_id"=>"", "comment"=>"", "overwrite"=>"false"}, "capabilities"=>"build image new_volume", "provider"=>"Ovirt", "media_selector"=>"install_media", "fakepassword"=>"[FILTERED]", "bare_metal_capabilities"=>"build", "provisioning"=>"image"}
./foreman/production.log:2018-05-28 10:57:23 476eb2d6 [app] [I]   Parameters: {"utf8"=>"✓", "authenticity_token"=>"N3TwE3F2P3Qsyij/dxK1aKoshvoksqyKVPZVtCd9w5jkII7qG0f+vFAt2mpgj4i0RlavhhTus/Ue1BnqsYgzjw==", "host"=>{"name"=>"leigh-eppes", "organization_id"=>"1", "location_id"=>"2", "hostgroup_id"=>"2", "compute_resource_id"=>"2", "compute_profile_id"=>"4", "content_facet_attributes"=>{"lifecycle_environment_id"=>"2", "content_view_id"=>"2", "content_source_id"=>"1"}, "puppetclass_ids"=>[""], "managed"=>"true", "progress_report_id"=>"[FILTERED]", "type"=>"Host::Managed", "interfaces_attributes"=>{"0"=>{"_destroy"=>"0", "type"=>"Nic::Managed", "mac"=>"", "identifier"=>"", "name"=>"leigh-eppes", "domain_id"=>"", "subnet_id"=>"", "ip"=>"", "ip6"=>"", "managed"=>"1", "primary"=>"1", "provision"=>"1", "execution"=>"1", "virtual"=>"0", "tag"=>"", "attached_to"=>"", "compute_attributes"=>{"name"=>"eth0", "network"=>"64372318-f8c5-4033-bb67-7cff69e36773"}}}, "compute_attributes"=>{"cluster"=>"f873df04-bb67-4230-9ca3-99a97d47cac8", "instance_type"=>"", "cores"=>"2", "memory"=>"2147483648", "start"=>"1", "volumes_attributes"=>{"0"=>{"_delete"=>"", "size_gb"=>"50", "storage_domain"=>"c6a977a6-cd64-4999-8568-909a816c5927", "id"=>"", "preallocate"=>"0", "wipe_after_delete"=>"0", "interface"=>"virtio_scsi"}}, "image_id"=>"ffe6c56f-f250-4537-b765-201315e314a1"}, "architecture_id"=>"1", "operatingsystem_id"=>"1", "provision_method"=>"image", "build"=>"1", "medium_id"=>"9", "ptable_id"=>"90", "pxe_loader"=>"PXELinux BIOS", "disk"=>"", "root_pass"=>"[FILTERED]", "is_owned_by"=>"4-Users", "enabled"=>"1", "model_id"=>"", "comment"=>"", "overwrite"=>"false"}, "capabilities"=>"build image new_volume", "provider"=>"Ovirt", "media_selector"=>"install_media", "bare_metal_capabilities"=>"build"}
./foreman/production.log:2018-05-28 10:57:24 476eb2d6 [app] [I] Rendering UserData template for leigh-eppes.example.com
./foreman/production.log:2018-05-28 10:57:25 476eb2d6 [app] [I] Remove puppet certificate for leigh-eppes.example.com
./foreman/production.log:2018-05-28 10:57:28 476eb2d6 [app] [I] Adding autosign entry for leigh-eppes.example.com
./foreman/production.log:2018-05-28 10:57:28 476eb2d6 [app] [I] Adding Compute instance for leigh-eppes.example.com
./foreman/production.log:2018-05-28 10:57:39 476eb2d6 [app] [I] Create DHCP reservation leigh-eppes.example.com for leigh-eppes.example.com-00:1a:4a:16:01:8c/NEW_VM_IP
./foreman/production.log:2018-05-28 10:57:39 476eb2d6 [app] [I] Add DNS A record for leigh-eppes.example.com/NEW_VM_IP
./foreman/production.log:2018-05-28 10:57:39 476eb2d6 [app] [I] Add DNS PTR record for NEW_VM_IP/leigh-eppes.example.com
./foreman/production.log:2018-05-28 10:57:39 476eb2d6 [app] [I] Add realm entry for new host leigh-eppes.example.com
./foreman/production.log:2018-05-28 10:57:40 476eb2d6 [app] [I] Powering up Compute instance for leigh-eppes.example.com
./foreman/production.log:2018-05-28 10:57:44 476eb2d6 [app] [W] Failed to power up a compute mdc-1-local-infra-1 (oVirt) instance leigh-eppes.example.com: undefined method `lines' for #<Array:0x000000000abccd48>
./foreman/production.log:2018-05-28 10:57:44 476eb2d6 [app] [W] Rolling back due to a problem: [#<Orchestration::Task:0x000000000885f860 @name="Power up compute instance leigh-eppes.example.com", @status="failed", @priority=1000, @action=[#<Host::Managed id: nil, name: "leigh-eppes.example.com", last_compile: nil, last_report: nil, updated_at: nil, created_at: nil, root_pass: "", architecture_id: 1, operatingsystem_id: 1, environment_id: 1, ptable_id: 90, medium_id: 9, build: true, comment: "", disk: "", installed_at: nil, model_id: nil, hostgroup_id: 2, owner_id: 4, owner_type: "User", enabled: true, puppet_ca_proxy_id: 1, managed: true, use_image: nil, image_file: nil, uuid: "20240a96-de46-4042-8478-f1880906f20f", compute_resource_id: 2, puppet_proxy_id: 1, certname: nil, image_id: 1, organization_id: 1, location_id: 2, type: "Host::Managed", otp: "6Qs~-|}$OXNOb]/gB&34*?", realm_id: 1, compute_profile_id: 4, provision_method: "image", grub_pass: "", content_view_id: nil, lifecycle_environment_id: nil, global_status: 0, lookup_value_matcher: "fqdn=leigh-eppes.example.com", pxe_loader: "PXELinux BIOS">, :setComputePowerUp], @timestamp=2018-05-28 01:57:44 UTC>]
./foreman/production.log:2018-05-28 10:57:44 476eb2d6 [app] [I] Delete realm entry for leigh-eppes.example.com
./foreman/production.log:2018-05-28 10:57:44 476eb2d6 [app] [I] Delete the DNS PTR record for NEW_VM_IP/leigh-eppes.example.com
./foreman/production.log:2018-05-28 10:57:44 476eb2d6 [app] [I] Delete the DNS A record for leigh-eppes.example.com/NEW_VM_IP
./foreman/production.log:2018-05-28 10:57:45 476eb2d6 [app] [I] Delete DHCP reservation leigh-eppes.example.com for leigh-eppes.example.com-00:1a:4a:16:01:8c/NEW_VM_IP
./foreman/production.log:2018-05-28 10:57:45 476eb2d6 [app] [I] Removing Compute instance for leigh-eppes.example.com
./foreman/production.log:2018-05-28 10:57:46 476eb2d6 [app] [I] Remove puppet certificate for leigh-eppes.example.com
./foreman/production.log:2018-05-28 10:57:49 476eb2d6 [app] [I] Delete the autosign entry for leigh-eppes.example.com
./foreman/production.log:2018-05-28 10:57:49 476eb2d6 [app] [E] Task 'Render user data template for leigh-eppes.example.com' *rollbacked*
./foreman/production.log:2018-05-28 10:57:49 476eb2d6 [app] [E] Task 'Set up compute instance leigh-eppes.example.com' *rollbacked*
./foreman/production.log:2018-05-28 10:57:49 476eb2d6 [app] [E] Task 'Query instance details for leigh-eppes.example.com' *rollbacked*
./foreman/production.log:2018-05-28 10:57:49 476eb2d6 [app] [E] Task 'Create DHCP Settings for leigh-eppes.example.com' *rollbacked*
./foreman/production.log:2018-05-28 10:57:49 476eb2d6 [app] [E] Task 'Create IPv4 DNS record for leigh-eppes.example.com' *rollbacked*
./foreman/production.log:2018-05-28 10:57:49 476eb2d6 [app] [E] Task 'Create Reverse IPv4 DNS record for leigh-eppes.example.com' *rollbacked*
./foreman/production.log:2018-05-28 10:57:49 476eb2d6 [app] [E] Task 'Create realm entry for leigh-eppes.example.com' *rollbacked*
./foreman/production.log:2018-05-28 10:57:49 476eb2d6 [app] [E] Task 'Power up compute instance leigh-eppes.example.com' *failed*
./foreman/production.log:2018-05-28 10:57:49 476eb2d6 [app] [I] Failed to save: Failed to power up a compute mdc-1-local-infra-1 (oVirt) instance leigh-eppes.example.com: undefined method `lines' for #<Array:0x000000000abccd48>
./messages:May 28 10:57:28 prov-01 smart-proxy: prov-01.example.com - - [28/May/2018:10:57:25 JST] "DELETE /puppet/ca/leigh-eppes.example.com HTTP/1.1" 404 90
./messages:May 28 10:57:28 prov-01 smart-proxy: - -> /puppet/ca/leigh-eppes.example.com
./messages:May 28 10:57:28 prov-01 smart-proxy: prov-01.example.com - - [28/May/2018:10:57:28 JST] "POST /puppet/ca/autosign/leigh-eppes.example.com HTTP/1.1" 200 0
./messages:May 28 10:57:28 prov-01 smart-proxy: - -> /puppet/ca/autosign/leigh-eppes.example.com
./messages:May 28 10:57:44 prov-01 smart-proxy: prov-01.example.com - - [28/May/2018:10:57:44 JST] "DELETE /realm/REALM_DOMAIN/leigh-eppes.example.com HTTP/1.1" 200 161
./messages:May 28 10:57:44 prov-01 smart-proxy: - -> /realm/REALM_DOMAIN/leigh-eppes.example.com
./messages:May 28 10:57:45 prov-01 smart-proxy: prov-01.example.com - - [28/May/2018:10:57:44 JST] "DELETE /dns/leigh-eppes.example.com/A HTTP/1.1" 200 0
./messages:May 28 10:57:45 prov-01 smart-proxy: - -> /dns/leigh-eppes.example.com/A
./messages:May 28 10:57:49 prov-01 smart-proxy: prov-01.example.com - - [28/May/2018:10:57:46 JST] "DELETE /puppet/ca/leigh-eppes.example.com HTTP/1.1" 404 90
./messages:May 28 10:57:49 prov-01 smart-proxy: - -> /puppet/ca/leigh-eppes.example.com
./messages:May 28 10:57:49 prov-01 smart-proxy: prov-01.example.com - - [28/May/2018:10:57:49 JST] "DELETE /puppet/ca/autosign/leigh-eppes.example.com HTTP/1.1" 200 0
./messages:May 28 10:57:49 prov-01 smart-proxy: - -> /puppet/ca/autosign/leigh-eppes.example.com
./secure:May 28 10:57:25 prov-01 sudo: foreman-proxy : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/opt/puppetlabs/bin/puppet cert --ssldir /etc/puppetlabs/puppet/ssl --clean leigh-eppes.example.com
./secure:May 28 10:57:46 prov-01 sudo: foreman-proxy : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/opt/puppetlabs/bin/puppet cert --ssldir /etc/puppetlabs/puppet/ssl --clean leigh-eppes.example.com
[root@prov-01 log]#

vdsm bulk log: https://pastebin.com/HmDbkxjS

relevant rows are, 58-101, 96-101, 118-125 and the ones that have 3332afe1-43d2-43e3-ba45-f32f0e1574fa and leigh-eppes.example.com

from vdsm logs relevant but not so much info:

2018-05-28 10:58:25,782+0900 INFO  (jsonrpc/6) [vdsm.api] START getQemuImageInfo(sdUUID=u'c6a977a6-cd64-4999-8568-909a816c5927', spUUID=u'a1229268-67e1-4f16-9e80-ea05efb9b0ec', imgUUID=u'f9f4e760-93a4-4e13-946a-3514379e5e3c', volUUID=u'3332afe1-43d2-43e3-ba45-f32f0e1574fa', options=None) from=::ffff:172.19.210.248,55022, flow_id=60932a13-4132-42b1-b8f6-198d0cf52b67, task_id=4b7002b6-28bb-483a-b23e-5063d8c2e0fe (api:46)
2018-05-28 10:58:25,916+0900 INFO  (jsonrpc/6) [vdsm.api] FINISH getQemuImageInfo return={'info': {'compat': u'1.1', 'clustersize': 65536, 'virtualsize': 53687091200, 'format': u'qcow2'}} from=::ffff:172.19.210.248,55022, flow_id=60932a13-4132-42b1-b8f6-198d0cf52b67, task_id=4b7002b6-28bb-483a-b23e-5063d8c2e0fe (api:52)
2018-05-28 10:58:25,918+0900 INFO  (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call Volume.getQemuImageInfo succeeded in 0.13 seconds (__init__:573)
2018-05-28 10:58:25,925+0900 INFO  (jsonrpc/1) [vdsm.api] START teardownImage(sdUUID=u'c6a977a6-cd64-4999-8568-909a816c5927', spUUID=u'a1229268-67e1-4f16-9e80-ea05efb9b0ec', imgUUID=u'f9f4e760-93a4-4e13-946a-3514379e5e3c', volUUID=None) from=::ffff:172.19.210.248,55022, flow_id=60932a13-4132-42b1-b8f6-198d0cf52b67, task_id=58e13d2c-1b92-4b05-8361-df5e2cbfcc9f (api:46)
2018-05-28 10:58:25,926+0900 INFO  (jsonrpc/1) [vdsm.api] FINISH teardownImage return=None from=::ffff:172.19.210.248,55022, flow_id=60932a13-4132-42b1-b8f6-198d0cf52b67, task_id=58e13d2c-1b92-4b05-8361-df5e2cbfcc9f (api:52)
2018-05-28 10:58:25,927+0900 INFO  (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call Image.teardown succeeded in 0.00 seconds (__init__:573)

Thanks guys!

iNecas · May 28, 2018, 7:39am

With the patch applied, and until Feature #20590: Full cloud-init support with ovirt provider - Foreman gets released, you should be able to use an alternative cloud-init template, that could look like this:

<%#
kind: user_data
name: oVirt Cloud-init
-%>
#cloud-config
hostname: <%= @host.shortname %>

<%# Allow user to specify additional SSH key as host paramter -%>
<% if @host.params['sshkey'].present? || @host.params['remote_execution_ssh_keys'].present? -%>
ssh_authorized_keys:
<% if @host.params['sshkey'].present? -%>
  - <%= @host.params['sshkey'] %>
<% end -%>
<% if @host.params['remote_execution_ssh_keys'].present? -%>
<% @host.params['remote_execution_ssh_keys'].each do |key| -%>
  - <%= key %>
<% end -%>
<% end -%>
<% end -%>
runcmd:
  - |
    #!/bin/bash
<%= indent 4 do
    snippet 'subscription_manager_registration'
end %>
<% if @host.info['parameters']['realm'] && @host.realm && @host.realm.realm_type == 'Red Hat Identity Management' -%>
  <%= indent 4 do
    snippet 'idm_register'
  end %>
<% end -%>
<% unless @host.operatingsystem.atomic? -%>
    # update all the base packages from the updates repository
    yum -t -y -e 0 update
<% end -%>
<%
    # safemode renderer does not support unary negation
    non_atomic = @host.operatingsystem.atomic? ? false : true
    pm_set = @host.puppetmaster.empty? ? false : true
    puppet_enabled = non_atomic && (pm_set || @host.params['force-puppet'])
%>
<% if puppet_enabled %>
    yum install -y puppet
    cat > /etc/puppet/puppet.conf << EOF
  <%= indent 4 do
    snippet 'puppet.conf'
  end %>
    EOF
    # Setup puppet to run on system reboot
    /sbin/chkconfig --level 345 puppet on

    /usr/bin/puppet agent --config /etc/puppet/puppet.conf --onetime --tags no_such_tag <%= @host.puppetmaster.blank? ? '' : "--server #{@host.puppetmaster}" %> --no-daemonize
    /sbin/service puppet start
<% end -%>
phone_home:
 url: <%= foreman_url('built') %>
 post: []
 tries: 10pp

Ale · June 1, 2018, 2:42am

Hi @iNecas and @dLobatog !

with all the patches applied from Feature #20590: Full cloud-init support with ovirt provider - Foreman and with default user_data template is working perfect!

Now I need to know how to add vm as client to FreeIPA/IdM but that is a different story

Cheers,

Alejandro