Cloud-init does not install puppet but runs the final module and succeeds according cloud-init?

Problem:

During deployment cloud-init is called including the finral module. But for some reason the yum update and puppet install does not start. I have included a touch to /tmp/myfile in the provisioning template. This line is getting executed by the final module from cloud-init. The growpart, phone-home and reboot are executed also.

When we remove /var/lib/cloud and rerun cloud-init “cloud-init -d init” and run " cloud-init modules --mode config; cloud-init modules --mode final", everything works fine.

Expected outcome:
Cloud-init final module runs yum update and installs/configures puppet.

Foreman and Proxy versions:
foreman-proxy-2.1.0-1
foreman-2.1.0-1

Foreman and Proxy plugin versions:

foreman_hooks Plugin engine for Foreman that enables running custom hook scripts on Foreman events Dominic Cleal 0.3.16

Distribution and version:
CentOS 7.8.2003

Other relevant data:

Cloud init debug information from client. (Deployed server)

 -- Boot Record 01 --
The total time elapsed since completing an event is printed after the "@" character.
The time the event takes is printed after the "+" character.

Starting stage: init-local
|`->no cache found @00.01600s +00.00000s
|`->no local data found from DataSourceNoCloud @00.02400s +00.20300s
Finished stage: (init-local) 00.22800 seconds

Starting stage: init-network
|`->no cache found @07.16400s +00.00000s
|`->found network data from DataSourceNoCloudNet @07.17000s +00.42500s
|`->setting up datasource @07.64500s +00.00000s
|`->reading and applying user-data @07.74000s +00.05100s
|`->reading and applying vendor-data @07.79100s +00.00000s
|`->activating datasource @07.86200s +00.00500s
|`->config-bootcmd ran successfully @07.87500s +00.00400s
|`->config-growpart ran successfully @07.87900s +00.11000s
Finished stage: (init-network) 00.88600 seconds

Starting stage: modules-config
|`->config-runcmd ran successfully @08.92100s +00.00400s
|`->config-timezone ran successfully @08.92500s +00.00200s
Finished stage: (modules-config) 00.01600 seconds

Starting stage: modules-final
|`->config-scripts-per-once ran successfully @09.18600s +00.00100s
|`->config-scripts-per-boot ran successfully @09.18700s +00.00100s
|`->config-scripts-per-instance ran successfully @09.18800s +00.00100s
|`->running config-scripts-user with frequency once-per-instance @09.18900s +00.06700s
Finished stage: (modules-final) 00.08700 seconds

Total Time: 1.21700 seconds

-- Boot Record 02 --
The total time elapsed since completing an event is printed after the "@" character.
The time the event takes is printed after the "+" character.

Starting stage: init-local
|`->cache invalid in datasource: DataSourceNoCloudNet [seed=ds_config_seedfrom,http://foreman.xxxxxxxx/userdata/][dsmode=net] @00.00700s +00.00800s
|`->no local data found from DataSourceNoCloud @00.01900s +00.18000s
Finished stage: (init-local) 00.20500 seconds

Starting stage: init-network
|`->no cache found @01.49400s +00.00000s
|`->found network data from DataSourceNoCloudNet @01.50300s +00.40600s
|`->setting up datasource @01.98000s +00.00000s
|`->reading and applying user-data @02.05300s +00.02600s
|`->reading and applying vendor-data @02.07900s +00.00000s
|`->activating datasource @02.12200s +00.00500s
|`->config-bootcmd ran successfully @02.13300s +00.00000s
|`->config-growpart ran successfully @02.13400s +00.12100s
Finished stage: (init-network) 00.81900 seconds

Starting stage: modules-config
|`->config-runcmd previously ran @03.00800s +00.00000s
|`->config-timezone previously ran @03.00800s +00.00000s
Finished stage: (modules-config) 00.00700 seconds

Starting stage: modules-final
|`->config-scripts-per-once previously ran @03.24100s +00.00000s
|`->config-scripts-per-boot ran successfully @03.24200s +00.00000s
|`->config-scripts-per-instance previously ran @03.24200s +00.00000s
|`->config-scripts-user previously ran @03.24200s +00.00000s
|`->config-phone-home ran successfully @03.24300s +13.03200s
|`->config-power_state_change ran successfully @16.27600s +00.01300s
Finished stage: (modules-final) 13.05400 seconds

Total Time: 14.08500 seconds

-- Boot Record 03 --
The total time elapsed since completing an event is printed after the "@" character.
The time the event takes is printed after the "+" character.

Starting stage: init-local
|`->cache invalid in datasource: DataSourceNoCloudNet [seed=ds_config_seedfrom,http://foreman.xxxxx/userdata/][dsmode=net] @00.00700s +00.00500s
|`->no local data found from DataSourceNoCloud @00.01400s +00.17900s
Finished stage: (init-local) 00.19900 seconds

Starting stage: init-network
|`->no cache found @01.68800s +00.00000s
|`->found network data from DataSourceNoCloudNet @01.69700s +00.42900s
|`->setting up datasource @02.22000s +00.00000s
|`->reading and applying user-data @02.26800s +00.02700s
|`->reading and applying vendor-data @02.29500s +00.00100s
|`->activating datasource @02.33900s +00.00700s
|`->config-bootcmd ran successfully @02.35200s +00.00100s
|`->config-growpart ran successfully @02.35400s +00.12700s
Finished stage: (init-network) 00.86500 seconds

Starting stage: modules-config
|`->config-runcmd previously ran @03.41900s +00.00000s
|`->config-timezone previously ran @03.41900s +00.00000s
Finished stage: (modules-config) 00.00800 seconds

Starting stage: modules-final
|`->config-scripts-per-once previously ran @03.68800s +00.00000s
|`->config-scripts-per-boot ran successfully @03.68900s +00.00000s
|`->config-scripts-per-instance previously ran @03.68900s +00.00000s
|`->config-scripts-user previously ran @03.68900s +00.00000s
|`->config-phone-home previously ran @03.69000s +00.00000s
|`->config-power_state_change previously ran @03.69000s +00.00000s
Finished stage: (modules-final) 00.00800 seconds

Total Time: 1.08000 seconds

Template on host, according to Foreman

#cloud-config
hostname: test02.xxxxxxxx
fqdn: test02.xxxxxxxx
manage_etc_hosts: true
package_upgrade: true
users: {}

runcmd:
- [ touch, /tmp/myfile ]
# update all packages with yum
- yum clean all
- yum update -y


# install and configure puppet
- |
  
  rpm -Uvh https://yum.puppet.com/puppet6/puppet6-release-el-7.noarch.rpm

   
  
  if [ -f /usr/bin/dnf ]; then
    dnf -y install puppet-agent
  else
    yum -t -y install puppet-agent
  fi
  
  cat > /etc/puppetlabs/puppet/puppet.conf << EOF
  
  
  [main]
  vardir = /opt/puppetlabs/puppet/cache
  logdir = /var/log/puppetlabs/puppet
  rundir = /var/run/puppetlabs
  ssldir = /etc/puppetlabs/puppet/ssl
  
  [agent]
  pluginsync        = true
  report               = true
  ca_server         = foreman.xxxxxx
  certname          = test02.xxxxxx
  environment     = production
  server               = foreman.xxxxxxxxxx
  
  EOF
  
  
  puppet_unit=puppet
  /usr/bin/systemctl list-unit-files | grep -q puppetagent && puppet_unit=puppetagent
  /usr/bin/systemctl enable ${puppet_unit}
  
  # export a custom fact called 'is_installer' to allow detection of the installer environment in Puppet modules
  export FACTER_is_installer=true
  # passing a non-existent tag like "no_such_tag" to the puppet agent only initializes the node
  /opt/puppetlabs/bin/puppet agent --config /etc/puppetlabs/puppet/puppet.conf --onetime --tags no_such_tag --server foreman.xxxxxxxxxxx --no-daemonize
  /opt/puppetlabs/bin/puppet resource service puppet ensure=running

# use runcmd to grow the VG, LV and root filesystem, as cloud-init
# doesn't handle LVM resizing natively
- [ cloud-init-per, once, grow_pv, pvresize, /dev/sda2 ]
- [ cloud-init-per, once, grow_vg-lv, lvextend, --resizefs, -l, +100%FREE, /dev/mapper/vg-lv_root ]

# timezone: set the timezone for this instance
# the value of 'timezone' must exist in /usr/share/zoneinfo
timezone: Europe/Amsterdam

growpart:
  mode: growpart
  devices: ['/dev/sda2']

power_state:
  delay: "+5"
  mode: reboot
  message: Bye Bye
  timeout: 10
  condition: True

phone_home:
  url: http://foremanxxxxxxxx/unattended/built
  post: []
  tries: 10

Hello!

deployment where? OpenStack? EC2? VMWare?

This smells like an issue with your cloud-init which must be baked in the image. What kind of image is this? Is this an official image? Can you try with the official Fedora Cloud Image instead?

For some reason runcmd exits with a 1, instead of 0. I assume that modules-final/config-scripts-user refers to the RUNCMD part in this case. If I run runcmd by hand everything works fine

In the cloud-init log I notice.

2020-08-21 08:42:35,159 - util.py[DEBUG]: Running command ['/var/lib/cloud/instance/scripts/runcmd'] with allowed return codes [0] (shell=False, capture=False)
2020-08-21 08:42:35,961 - util.py[DEBUG]: Cloud-init 18.5 received SIGTERM, exiting...
  Filename: /usr/lib64/python3.6/subprocess.py
  Function: _try_wait
  Line number: 1424
    Filename: /usr/lib64/python3.6/subprocess.py
    Function: wait
    Line number: 1477
      Filename: /usr/lib64/python3.6/subprocess.py
      Function: communicate
      Line number: 855
2020-08-21 08:42:35,961 - handlers.py[DEBUG]: finish: modules-final/config-scripts-user: FAIL: running config-scripts-user with frequency once-per-instance
2020-08-21 08:42:35,962 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2020-08-21 08:42:35,962 - util.py[DEBUG]: Read 11 bytes from /proc/uptime
2020-08-21 08:42:35,962 - util.py[DEBUG]: cloud-init mode 'modules' took 0.880 seconds (0.88)
2020-08-21 08:42:35,962 - handlers.py[DEBUG]: finish: modules-final: FAIL: running modules for final

Output template host test02:

#cloud-config
hostname: test02
fqdn: test02
timezone: Europe/Amsterdam
manage_etc_hosts: true
package_upgrade: true
users: {}
runcmd:

- |
  
  rpm -Uvh https://yum.puppet.com/puppet6/puppet6-release-el-8.noarch.rpm

- |
  
  
  
  if [ -f /usr/bin/dnf ]; then
    dnf -y install puppet-agent
  else
    yum -t -y install puppet-agent
  fi
  
  cat > /etc/puppetlabs/puppet/puppet.conf << EOF
  
  
  [main]
  vardir = /opt/puppetlabs/puppet/cache
  logdir = /var/log/puppetlabs/puppet
  rundir = /var/run/puppetlabs
  ssldir = /etc/puppetlabs/puppet/ssl
  
  [agent]
  pluginsync      = true
  report          = true
  ca_server       = foreman
  certname        = test02
  environment     = production
  server          = foreman
  
  EOF
  
  
  puppet_unit=puppet
  /usr/bin/systemctl list-unit-files | grep -q puppetagent && puppet_unit=puppetagent
  /usr/bin/systemctl enable ${puppet_unit}
  
  # export a custom fact called 'is_installer' to allow detection of the installer environment in Puppet modules
  export FACTER_is_installer=true
  # passing a non-existent tag like "no_such_tag" to the puppet agent only initializes the node
  /opt/puppetlabs/bin/puppet agent --config /etc/puppetlabs/puppet/puppet.conf --onetime  --server foreman.xxx --no-daemonize
  /opt/puppetlabs/bin/puppet resource service puppet ensure=running


growpart:
  mode: growpart
  devices: ['/dev/sda2']

phone_home:
  url: http://xxx/unattended/built
  post: []
  tries: 10

power_state:
  delay: "+10"
  mode: reboot
  message: Bye Bye
  timeout: 10
  condition: True

Cloud-init-output.log:

Cloud-init v. 18.5 running 'init-local' at Fri, 21 Aug 2020 08:42:25 +0000. Up 10.51 seconds.
Cloud-init v. 18.5 running 'init' at Fri, 21 Aug 2020 08:42:33 +0000. Up 18.75 seconds.
ci-info: +++++++++++++++++++++++++++Net device info++++++++++++++++++++++++++++
ci-info: +--------+-------+-----------+-----------+-------+-------------------+
ci-info: | Device |   Up  |  Address  |    Mask   | Scope |     Hw-Address    |
ci-info: +--------+-------+-----------+-----------+-------+-------------------+
ci-info: | ens192 | False |     .     |     .     |   .   | 00:50:56:b3:6a:96 |
ci-info: |   lo   |  True | 127.0.0.1 | 255.0.0.0 |  host |         .         |
ci-info: |   lo   |  True |  ::1/128  |     .     |  host |         .         |
ci-info: +--------+-------+-----------+-----------+-------+-------------------+
ci-info: +++++++++++++++++++Route IPv6 info+++++++++++++++++++
ci-info: +-------+-------------+---------+-----------+-------+
ci-info: | Route | Destination | Gateway | Interface | Flags |
ci-info: +-------+-------------+---------+-----------+-------+
ci-info: +-------+-------------+---------+-----------+-------+
Cloud-init v. 18.5 running 'modules:config' at Fri, 21 Aug 2020 08:42:34 +0000. Up 19.90 seconds.
warning: /var/tmp/rpm-tmp.hxqyjM: Header V4 RSA/SHA256 Signature, key ID ef8d349f: NOKEY
Retrieving https://yum.puppet.com/puppet6/puppet6-release-el-8.noarch.rpm
Verifying...                          ########################################
Preparing...                          ########################################
Updating / installing...
puppet6-release-6.0.0-3.el8           ########################################
Cloud-init v. 18.5 running 'modules:final' at Fri, 21 Aug 2020 08:42:35 +0000. Up 20.33 seconds.
CentOS-8 - AppStream                             17 MB/s | 5.8 MB     00:00
CentOS-8 - Base                                  18 MB/s | 2.2 MB     00:00
CentOS-8 - Extras                               131 kB/s | 7.3 kB     00:00
Extra Packages for Enterprise Linux Modular 8 - 144 kB/s |  82 kB     00:00
Extra Packages for Enterprise Linux 8 - x86_64  7.9 MB/s | 7.8 MB     00:00
Cloud-init v. 18.5 running 'init-local' at Fri, 21 Aug 2020 08:42:59 +0000. Up 9.42 seconds.
Cloud-init v. 18.5 running 'init' at Fri, 21 Aug 2020 08:43:02 +0000. Up 12.35 seconds.
ci-info: ++++++++++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++++++++++
ci-info: +--------+------+-----------------------------+---------------+--------+-------------------+
ci-info: | Device |  Up  |           Address           |      Mask     | Scope  |     Hw-Address    |
ci-info: +--------+------+-----------------------------+---------------+--------+-------------------+
ci-info: | ens192 | True |        193.37.205.26        | 255.255.255.0 | global | 00:50:56:b3:6a:96 |
ci-info: | ens192 | True | fe80::250:56ff:feb3:6a96/64 |       .       |  link  | 00:50:56:b3:6a:96 |
ci-info: |   lo   | True |          127.0.0.1          |   255.0.0.0   |  host  |         .         |
ci-info: |   lo   | True |           ::1/128           |       .       |  host  |         .         |
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    | 193.37.205.1 |    0.0.0.0    |   ens192  |   UG  |
ci-info: |   1   | 193.37.205.0 |   0.0.0.0    | 255.255.255.0 |   ens192  |   U   |
ci-info: +-------+--------------+--------------+---------------+-----------+-------+
ci-info: +++++++++++++++++++Route IPv6 info+++++++++++++++++++
ci-info: +-------+-------------+---------+-----------+-------+
ci-info: | Route | Destination | Gateway | Interface | Flags |
ci-info: +-------+-------------+---------+-----------+-------+
ci-info: |   1   |  fe80::/64  |    ::   |   ens192  |   U   |
ci-info: |   3   |   ff00::/8  |    ::   |   ens192  |   U   |
ci-info: +-------+-------------+---------+-----------+-------+
Cloud-init v. 18.5 running 'modules:config' at Fri, 21 Aug 2020 08:43:04 +0000. Up 15.20 seconds.
Cloud-init v. 18.5 running 'modules:final' at Fri, 21 Aug 2020 08:43:05 +0000. Up 15.74 seconds.
2020-08-21 08:43:05,584 - util.py[WARNING]: /etc/ssh/ssh_host_dsa_key.pub: failed to open, can not phone home that data!
2020-08-21 08:43:45,923 - util.py[WARNING]: Failed to post phone home data to http://xxx/unattended/built?token=feb346ca-3965-4702-a7ca-1c9a7467ba04 in 10 tries

Part of Cloud-init.log:

2020-08-21 08:42:35,157 - stages.py[DEBUG]: Running module scripts-user (<module 'cloudinit.config.cc_scripts_user' from '/usr/lib/python3.6/site-packages/cloudinit/config/cc_scripts_user.py'>) with frequency once-per-instance
2020-08-21 08:42:35,158 - handlers.py[DEBUG]: start: modules-final/config-scripts-user: running config-scripts-user with frequency once-per-instance
2020-08-21 08:42:35,158 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-e408d89ae85c9a0b6d/sem/config_scripts_user - wb: [644] 25 bytes
2020-08-21 08:42:35,158 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/i-e408d89ae85c9a0b6d/sem/config_scripts_user (recursive=False)
2020-08-21 08:42:35,159 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/i-e408d89ae85c9a0b6d/sem/config_scripts_user (recursive=False)
2020-08-21 08:42:35,159 - helpers.py[DEBUG]: Running config-scripts-user using lock (<FileLock using file '/var/lib/cloud/instances/i-e408d89ae85c9a0b6d/sem/config_scripts_user'>)
2020-08-21 08:42:35,159 - util.py[DEBUG]: Running command ['/var/lib/cloud/instance/scripts/runcmd'] with allowed return codes [0] (shell=False, capture=False)
2020-08-21 08:42:35,961 - util.py[DEBUG]: Cloud-init 18.5 received SIGTERM, exiting...
  Filename: /usr/lib64/python3.6/subprocess.py
  Function: _try_wait
  Line number: 1424
    Filename: /usr/lib64/python3.6/subprocess.py
    Function: wait
    Line number: 1477
      Filename: /usr/lib64/python3.6/subprocess.py
      Function: communicate
      Line number: 855
2020-08-21 08:42:35,961 - handlers.py[DEBUG]: finish: modules-final/config-scripts-user: FAIL: running config-scripts-user with frequency once-per-instance
2020-08-21 08:42:35,962 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2020-08-21 08:42:35,962 - util.py[DEBUG]: Read 11 bytes from /proc/uptime
2020-08-21 08:42:35,962 - util.py[DEBUG]: cloud-init mode 'modules' took 0.880 seconds (0.88)
2020-08-21 08:42:35,962 - handlers.py[DEBUG]: finish: modules-final: FAIL: running modules for final
2020-08-21 08:42:59,251 - util.py[DEBUG]: Cloud-init v. 18.5 running 'init-local' at Fri, 21 Aug 2020 08:42:59 +0000. Up 9.42 seconds.
2020-08-21 08:42:59,253 - main.py[DEBUG]: No kernel command line url found.
2020-08-21 08:42:59,253 - main.py[DEBUG]: Closing stdin.
2020-08-21 08:42:59,253 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud (recursive=False)
2020-08-21 08:42:59,258 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/scripts (recursive=False)
2020-08-21 08:42:59,258 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/scripts/per-instance (recursive=False)

Regards,

Summarize:

CentOS8 image with cloud-init-18.5-12 the following part failed “modules-final/config-scripts-user”.
This problem also occurs using the default cloud-init template in Foreman.

I have no clue yet why runcmd is exiting with exit 1.

Running runcmd manually or executing cloudinit.util.runparts("/var/lib/cloud/instance/scripts/") with python gives no hint at all what is going on, under the hood.

Any idea`s are welcome.

The template shown below, without invoking snippets is running fine.

<%#
kind: cloud-init
name: CloudInit default
model: ProvisioningTemplate
oses:
- CentOS
- Fedora
- Debian
- Ubuntu
-%>
<%#
This template accepts the following parameters:
- force-puppet: boolean (default=false)
- enable-puppetlabs-repo: boolean (default=false)
- enable-puppetlabs-puppet5-repo: boolean (default=false)
- enable-puppetlabs-puppet6-repo: boolean (default=false)
-%>
<%
  pm_set = @host.puppetmaster.empty? ? false : true
  puppet_enabled = pm_set || host_param_true?('force-puppet')
-%>

#cloud-config
hostname: <%= @host.name %>
fqdn: <%= @host %>
manage_etc_hosts: true
users: {}
runcmd:

- [ touch, /tmp/test ]
- [ setenforce, 0 ]
- [ rpm, -Uvh ,"https://yum.puppet.com/puppet6/puppet6-release-el-8.noarch.rpm" ]

phone_home:
  url: <%= foreman_url('built') %>
  post: []
  tries: 10

I am trying to deploy a host with foreman and configure it with cloud-init using cloud-init and vmware user-data. It works like a charm for our CentOS7 deployment street. We are deploying on VMWare.

Strange enough we cannot get it working with CentOS 8. It worked in the past and stopped working after upgrading Foreman, we assume.

A simple template and only installing puppet repo works fine, after adding the following rule it immediately results in an exit 1.

  • [ dnf, -y, install, puppet-agent ]

If I run the script “runcmd” manually it works fine, If I execute runcmd the same way as cloud-init does, it also succeeds. Command used.

python3
>>> import cloudinit.util
>>> cloudinit.util.runparts("/var/lib/cloud/instance/scripts/")

We also have the same solution for our CentOS7 deployment street and that works fine. If we use the same templates that we use for CentOS7 on CentOS8 it also results in exit 1 codes.

The strange behaviour is that if we remove /var/lib/cloud after the first failure, afterwards it works fine. Except the auto signing of course, the host already phoned home.

Does anyone have some tip/ideas?

Client:

CentOS Linux release 8.2.2004 (Core)
cloud-init-18.5-12.el8_2.2.noarch

Foreman server:

foreman-proxy-2.1.0-1.el7.noarch
foreman-2.1.0-1.el7.noarch
And plugin https://github.com/theforeman/foreman_hooks

Template used:

<%#
kind: cloud-init
name: CloudInit default
model: ProvisioningTemplate
oses:
- CentOS
- Fedora
- Debian
- Ubuntu
-%>
<%#
This template accepts the following parameters:
- force-puppet: boolean (default=false)
- enable-puppetlabs-repo: boolean (default=false)
- enable-puppetlabs-puppet5-repo: boolean (default=false)
- enable-puppetlabs-puppet6-repo: boolean (default=false)
-%>
<%
  pm_set = @host.puppetmaster.empty? ? false : true
  puppet_enabled = pm_set || host_param_true?('force-puppet')
-%>

#cloud-config
hostname: <%= @host.name %>
fqdn: <%= @host %>
manage_etc_hosts: true
users: {}
runcmd:

- [ touch, /tmp/test ]
#- [ setenforce 0 ]
- [ rpm, -Uvh ,"https://yum.puppet.com/puppet6/puppet6-release-el-8.noarch.rpm" ]
- [ dnf, -y, install, puppet-agent ]

phone_home:
  url: <%= foreman_url('built') %>
  post: []
  tries: 10

Template on the host according foreman:

#cloud-config
hostname: test05
fqdn: testyr05
manage_etc_hosts: true
users: {}
runcmd:

- [ touch, /tmp/test ]
#- [ setenforce 0 ]
- [ rpm, -Uvh ,"https://yum.puppet.com/puppet6/puppet6-release-el-8.noarch.rpm" ]
- [ dnf, -y, install, puppet-agent ]

phone_home:
  url: http://xxxxxxx/unattended/built
  post: []
  tries: 10

Cloud-init output log:

cat /var/log/cloud-init-output.log
Cloud-init v. 18.5 running ‘init-local’ at Fri, 21 Aug 2020 13:24:25 +0000. Up 10.28 seconds.
Cloud-init v. 18.5 running ‘init’ at Fri, 21 Aug 2020 13:24:32 +0000. Up 17.25 seconds.
ci-info: ++++++++++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++++++++++
ci-info: ±-------±-----±----------------------------±--------------±-------±------------------+
ci-info: | Device | Up | Address | Mask | Scope | Hw-Address |
ci-info: ±-------±-----±----------------------------±--------------±-------±------------------+
ci-info: | ens192 | True | x.x.x.29 | 255.255.255.0 | global | 00:50:56:b3:88:42 |
ci-info: | ens192 | True | fe80::250:56ff:feb3:8842/64 | . | link | 00:50:56:b3:88:42 |
ci-info: | lo | True | 127.0.0.1 | 255.0.0.0 | host | . |
ci-info: | lo | True | ::1/128 | . | host | . |
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 | x.37.x.1 | 0.0.0.0 | ens192 | UG |
ci-info: | 1 | x.37.x.0 | 0.0.0.0 | 255.255.255.0 | ens192 | U |
ci-info: ±------±-------------±-------------±--------------±----------±------+
ci-info: +++++++++++++++++++Route IPv6 info+++++++++++++++++++
ci-info: ±------±------------±--------±----------±------+
ci-info: | Route | Destination | Gateway | Interface | Flags |
ci-info: ±------±------------±--------±----------±------+
ci-info: | 1 | fe80::/64 | :: | ens192 | U |
ci-info: | 3 | ff00::/8 | :: | ens192 | U |
ci-info: ±------±------------±--------±----------±------+
Cloud-init v. 18.5 running ‘modules:config’ at Fri, 21 Aug 2020 13:24:33 +0000. Up 18.27 seconds.
Cloud-init v. 18.5 running ‘modules:final’ at Fri, 21 Aug 2020 13:24:33 +0000. Up 18.69 seconds.
warning: /var/tmp/rpm-tmp.aFRp8w: Header V4 RSA/SHA256 Signature, key ID ef8d349f: NOKEY
Retrieving https://yum.puppet.com/puppet6/puppet6-release-el-8.noarch.rpm
Verifying… ########################################
warning: Unable to get systemd shutdown inhibition lock: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
Preparing… ########################################
Updating / installing…
puppet6-release-6.0.0-3.el8 ########################################
CentOS-8 - AppStream 11 MB/s | 5.8 MB 00:00
CentOS-8 - Base 6.8 MB/s | 2.2 MB 00:00
CentOS-8 - Extras 25 kB/s | 7.3 kB 00:00
Cloud-init v. 18.5 running ‘init-local’ at Fri, 21 Aug 2020 13:25:03 +0000. Up 8.97 seconds.
Cloud-init v. 18.5 running ‘init’ at Fri, 21 Aug 2020 13:25:06 +0000. Up 11.80 seconds.
ci-info: ++++++++++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++++++++++
ci-info: ±-------±-----±----------------------------±--------------±-------±------------------+
ci-info: | Device | Up | Address | Mask | Scope | Hw-Address |
ci-info: ±-------±-----±----------------------------±--------------±-------±------------------+
ci-info: | ens192 | True | x.x.x.x | 255.255.255.0 | global | 00:50:56:b3:88:42 |
ci-info: | ens192 | True | fe80::250:56ff:feb3:8842/64 | . | link | 00:50:56:b3:88:42 |
ci-info: | lo | True | 127.0.0.1 | 255.0.0.0 | host | . |
ci-info: | lo | True | ::1/128 | . | host | . |
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 | X.x.x.x | 0.0.0.0 | ens192 | UG |
ci-info: | 1 | x.x.x.0 | 0.0.0.0 | 255.255.255.0 | ens192 | U |
ci-info: ±------±-------------±-------------±--------------±----------±------+
ci-info: +++++++++++++++++++Route IPv6 info+++++++++++++++++++
ci-info: ±------±------------±--------±----------±------+
ci-info: | Route | Destination | Gateway | Interface | Flags |
ci-info: ±------±------------±--------±----------±------+
ci-info: | 1 | fe80::/64 | :: | ens192 | U |
ci-info: | 3 | ff00::/8 | :: | ens192 | U |
ci-info: ±------±------------±--------±----------±------+
Cloud-init v. 18.5 running ‘modules:config’ at Fri, 21 Aug 2020 13:25:09 +0000. Up 14.42 seconds.
Cloud-init v. 18.5 running ‘modules:final’ at Fri, 21 Aug 2020 13:25:09 +0000. Up 15.19 seconds.
2020-08-21 13:25:10,028 - util.py[WARNING]: /etc/ssh/ssh_host_dsa_key.pub: failed to open, can not phone home that data!
2020-08-21 13:25:50,400 - util.py[WARNING]: Failed to post phone home data to hxxxxxx 05a89adb4e2c in 10 tries

Part cloud-init.log

s_user (recursive=False)
2020-08-21 13:24:33,519 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/i-0486ffb0d9c84cf1c3/sem/config_script
s_user (recursive=False)
2020-08-21 13:24:33,519 - helpers.py[DEBUG]: Running config-scripts-user using lock (<FileLock using file '/var/lib/cloud/instances/
i-0486ffb0d9c84cf1c3/sem/config_scripts_user'>)
2020-08-21 13:24:33,519 - util.py[DEBUG]: Running command ['/var/lib/cloud/instance/scripts/runcmd'] with allowed return codes [0] (
shell=False, capture=False)
2020-08-21 13:24:33,894 - util.py[DEBUG]: Cloud-init 18.5 received SIGTERM, exiting...
  Filename: /usr/lib64/python3.6/subprocess.py
  Function: _try_wait
  Line number: 1424
    Filename: /usr/lib64/python3.6/subprocess.py
    Function: wait
    Line number: 1477
      Filename: /usr/lib64/python3.6/subprocess.py
      Function: communicate
      Line number: 855
2020-08-21 13:24:33,895 - handlers.py[DEBUG]: finish: modules-final/config-scripts-user: FAIL: running config-scripts-user with freq
uency once-per-instance
2020-08-21 13:24:33,895 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2020-08-21 13:24:33,895 - util.py[DEBUG]: Read 11 bytes from /proc/uptime
2020-08-21 13:24:33,895 - util.py[DEBUG]: cloud-init mode 'modules' took 0.446 seconds (0.45)
2020-08-21 13:24:33,895 - handlers.py[DEBUG]: finish: modules-final: FAIL: running modules for final

Runcmd script on the client

#!/bin/sh
'touch' '/tmp/test'
'rpm' '-Uvh' 'https://yum.puppet.com/puppet6/puppet6-release-el-8.noarch.rpm'
'dnf' '-y' 'install' 'puppet-agent'

Have you tried to install any other package? Forcing a cache flush with dnf clean may help. I’d also try to see if you can get the output of the dnf command. Perhaps in the dnf logs there’s more useful info.

Hi,

I added DNF clean again to the provisioning template and tried to instal package “sl” without success.

DNF logs:

2020-    08-24T07:32:49Z INFO --- logging initialized ---
    2020-08-24T07:32:49Z DDEBUG timer: config: 439 ms
    2020-08-24T07:32:49Z DEBUG Loaded plugins: builddep, changelog, config-manager, copr, debug, debuginfo-install, download, generate_completion_cache, needs-restarting, playground, repoclosure, repodiff, repograph, repomanage, reposync
    2020-08-24T07:32:49Z DEBUG DNF version: 4.2.17
    2020-08-24T07:32:49Z DDEBUG Command: dnf clean all
    2020-08-24T07:32:49Z DDEBUG Installroot: /
    2020-08-24T07:32:49Z DDEBUG Releasever: 8
    2020-08-24T07:32:49Z DEBUG cachedir: /var/cache/dnf
    2020-08-24T07:32:49Z DDEBUG Base command: clean
    2020-08-24T07:32:49Z DDEBUG Extra commands: ['clean', 'all']
    2020-08-24T07:32:49Z DEBUG Cleaning data: packages metadata dbcache
    2020-08-24T07:32:49Z INFO 0 files removed
    2020-08-24T07:32:49Z DDEBUG Cleaning up.
    2020-08-24T07:32:50Z INFO --- logging initialized ---
    2020-08-24T07:32:50Z DDEBUG timer: config: 6 ms
    2020-08-24T07:32:50Z DEBUG Loaded plugins: builddep, changelog, config-manager, copr, debug, debuginfo-install, download, generate_completion_cache, needs-restarting, playground, repoclosure, repodiff, repograph, repomanage, reposync
    2020-08-24T07:32:50Z DEBUG DNF version: 4.2.17
    2020-08-24T07:32:50Z DDEBUG Command: dnf -y install sl
    2020-08-24T07:32:50Z DDEBUG Installroot: /
    2020-08-24T07:32:50Z DDEBUG Releasever: 8
    2020-08-24T07:32:50Z DEBUG cachedir: /var/cache/dnf
    2020-08-24T07:32:50Z DDEBUG Base command: install
    2020-08-24T07:32:50Z DDEBUG Extra commands: ['-y', 'install', 'sl']
    2020-08-24T07:32:50Z DEBUG User-Agent: constructed: 'libdnf (CentOS Linux 8; generic; Linux.x86_64)'
    2020-08-24T07:32:50Z DEBUG repo: downloading from remote: AppStream
    2020-08-24T07:32:52Z DEBUG AppStream: using metadata from Wed 12 Aug 2020 08:22:34 PM CEST.
    2020-08-24T07:32:52Z DEBUG repo: downloading from remote: BaseOS
    2020-08-24T07:32:53Z DEBUG BaseOS: using metadata from Wed 12 Aug 2020 08:22:30 PM CEST.
    2020-08-24T07:32:53Z DEBUG repo: downloading from remote: extras
    2020-08-24T07:32:53Z DEBUG extras: using metadata from Wed 12 Aug 2020 05:28:24 PM CEST.
    2020-08-24T07:32:53Z DEBUG repo: downloading from remote: epel-modular
    2020-08-24T07:32:54Z DEBUG epel-modular: using metadata from Sun 23 Aug 2020 02:14:57 AM CEST.
    2020-08-24T07:32:54Z DEBUG repo: downloading from remote: epel
**dnf.rpm.log**
    2020-08-24T07:32:49Z INFO --- logging initialized ---
    2020-08-24T07:32:50Z INFO --- logging initialized ---

dnf.librepo.log

> 2020-08-24T07:32:49Z INFO Librepo version: 1.11.0 with CURL_GLOBAL_ACK_EINTR support (libcurl/7.61.1 OpenSSL/1.1.1c zlib/1.2.11 brotli/1.0.6 libidn2/2.2.0 libpsl/0.20.2 (+libidn2/2.0.5) libssh/0.9.0/openssl/zlib nghttp2/1.33.0)
> 2020-08-24T07:32:49Z INFO Librepo version: 1.11.0 with CURL_GLOBAL_ACK_EINTR support (libcurl/7.61.1 OpenSSL/1.1.1c zlib/1.2.11 brotli/1.0.6 libidn2/2.2.0 libpsl/0.20.2 (+libidn2/2.0.5) libssh/0.9.0/openssl/zlib nghttp2/1.33.0)
> 2020-08-24T07:32:50Z INFO Librepo version: 1.11.0 with CURL_GLOBAL_ACK_EINTR support (libcurl/7.61.1 OpenSSL/1.1.1c zlib/1.2.11 brotli/1.0.6 libidn2/2.2.0 libpsl/0.20.2 (+libidn2/2.0.5) libssh/0.9.0/openssl/zlib nghttp2/1.33.0)
> 2020-08-24T07:32:50Z INFO Librepo version: 1.11.0 with CURL_GLOBAL_ACK_EINTR support (libcurl/7.61.1 OpenSSL/1.1.1c zlib/1.2.11 brotli/1.0.6 libidn2/2.2.0 libpsl/0.20.2 (+libidn2/2.0.5) libssh/0.9.0/openssl/zlib nghttp2/1.33.0)
> 2020-08-24T07:32:50Z INFO Downloading: http://mirrorlist.centos.org/?release=8&arch=x86_64&repo=AppStream&infra=stock
> 2020-08-24T07:32:51Z INFO Downloading: http://mirror.mijn.host/centos/8.2.2004/AppStream/x86_64/os/repodata/repomd.xml
> 2020-08-24T07:32:51Z INFO Downloading: http://mirror.mijn.host/centos/8.2.2004/AppStream/x86_64/os/repodata/842a8af48b5dbd4307008f873dc8da10049f635e48fa77e853eefe095f51a7d8-primary.xml.gz
> 2020-08-24T07:32:51Z INFO Downloading: http://mirror.mijn.host/centos/8.2.2004/AppStream/x86_64/os/repodata/5a191e5b3d03f25c289e57e9357deb8690683f9308309189119bd12d79144f65-filelists.xml.gz
> 2020-08-24T07:32:51Z INFO Downloading: http://mirror.mijn.host/centos/8.2.2004/AppStream/x86_64/os/repodata/170e73cd06610ade5e6eb49a297e2edb60c2180a8522e41c9bec76bb4e1c697c-comps-AppStream.x86_64.xml.xz
> 2020-08-24T07:32:51Z INFO Downloading: http://mirror.mijn.host/centos/8.2.2004/AppStream/x86_64/os/repodata/3ad43c4e5efe4a30aaf17a4eb478c86119739745ec72bafad4dd77473b04d5d4-modules.yaml.gz
> 2020-08-24T07:32:52Z INFO Downloading: http://mirrorlist.centos.org/?release=8&arch=x86_64&repo=BaseOS&infra=stock
> 2020-08-24T07:32:52Z INFO Downloading: http://mirror.amsiohosting.net/centos.org/8.2.2004/BaseOS/x86_64/os/repodata/repomd.xml
> 2020-08-24T07:32:52Z INFO Downloading: http://mirror.amsiohosting.net/centos.org/8.2.2004/BaseOS/x86_64/os/repodata/f5d6fb7d212b85ad8559a715133cf5dcca2eb387945c136b4ef020af82dd455c-primary.xml.gz
> 2020-08-24T07:32:52Z INFO Downloading: http://mirror.amsiohosting.net/centos.org/8.2.2004/BaseOS/x86_64/os/repodata/76fb31fe1d174e1a30070d5e961fb5fa0721e8f569b64f9d8270d9a4163602c1-filelists.xml.gz
> 2020-08-24T07:32:52Z INFO Downloading: http://mirror.amsiohosting.net/centos.org/8.2.2004/BaseOS/x86_64/os/repodata/08a9add0907af002934460d81ea0edc8bb4154db679cdc113d4c51efcbddfce4-comps-BaseOS.x86_64.xml.xz
> 2020-08-24T07:32:53Z INFO Downloading: http://mirrorlist.centos.org/?release=8&arch=x86_64&repo=extras&infra=stock
> 2020-08-24T07:32:53Z INFO Downloading: http://ams.edge.kernel.org/centos/8.2.2004/extras/x86_64/os/repodata/repomd.xml
> 2020-08-24T07:32:53Z INFO Downloading: http://ams.edge.kernel.org/centos/8.2.2004/extras/x86_64/os/repodata/79acf322f125e0b0a0b7b1071eee9e0c34a542f999d331946ea50ec8ecd94c47-primary.xml.gz
> 2020-08-24T07:32:53Z INFO Downloading: http://ams.edge.kernel.org/centos/8.2.2004/extras/x86_64/os/repodata/0e0e3c572cc9ad44a69ba922d9d0f7a41ceea9155d5442f2f8508451066b1532-filelists.xml.gz
> 2020-08-24T07:32:53Z INFO Downloading: https://mirrors.fedoraproject.org/metalink?repo=epel-modular-8&arch=x86_64&infra=stock&content=centos
> 2020-08-24T07:32:54Z INFO Downloading: http://epel.mirror.wearetriple.com/8/Modular/x86_64/repodata/repomd.xml
> 2020-08-24T07:32:54Z INFO Downloading: http://epel.mirror.wearetriple.com/8/Modular/x86_64/repodata/f2ea5ea039968beba5a39a1fe1a3c9c44fefdd931c35d48135e3bfacdad331eb-primary.xml.gz
> 2020-08-24T07:32:54Z INFO Downloading: http://epel.mirror.wearetriple.com/8/Modular/x86_64/repodata/c752d3d153b676141ac43d892ad913432c882b6b7e2ae0b849f52ebd498d9f92-filelists.xml.gz
> 2020-08-24T07:32:54Z INFO Downloading: http://epel.mirror.wearetriple.com/8/Modular/x86_64/repodata/d3b5158d498d1186446e2c8c4ca7665c3bbbb4c392d80cf407bea6468671a2ce-modules.yaml.gz
> 2020-08-24T07:32:54Z INFO Downloading: http://epel.mirror.wearetriple.com/8/Modular/x86_64/repodata/b0ba5ca91fd6d9c0e615fb1014fb5ea3d8ffa072fc6ab6be2183f1452f4759f7-updateinfo.xml.xz
> 2020-08-24T07:32:54Z INFO Downloading: https://mirrors.fedoraproject.org/metalink?repo=epel-8&arch=x86_64&infra=stock&content=centos
> 2020-08-24T07:32:54Z INFO Downloading: https://mirror.wd6.net/epel/8/Everything/x86_64/repodata/repomd.xml
> 2020-08-24T07:32:54Z INFO Downloading: https://mirror.wd6.net/epel/8/Everything/x86_64/repodata/c19ef3b510235247381df269272dbcca13b5b7c26efeb90b09dfb5356115b530-primary.xml.gz
> 2020-08-24T07:32:54Z INFO Downloading: https://mirror.wd6.net/epel/8/Everything/x86_64/repodata/e7c0e67a5f72baddffa270fd37445a0ceb8057c463a8b012007701db061cd756-filelists.xml.gz
> 2020-08-24T07:32:54Z INFO Downloading: https://mirror.wd6.net/epel/8/Everything/x86_64/repodata/7566a18455054e4ce6b28bda7c181f66dd9958ed35c66f2b23612fa1f1f5c591-comps-Everything.x86_64.xml
> 2020-08-24T07:32:54Z INFO Downloading: https://mirror.wd6.net/epel/8/Everything/x86_64/repodata/1f6426b0d364ffeabc7fb7ab672504dc1b8c48356eae899e72373d653e23e93f-prestodelta.xml.xz
> 2020-08-24T07:32:54Z INFO Downloading: https://mirror.wd6.net/epel/8/Everything/x86_64/repodata/cba1c53634714afcae8462d05ab78df15f547c5edd37e409ccc7d6a8f98a64e2-updateinfo.xml.bz2

Regards,

One idea: I remember that DNF changed behavior from YUM in one important aspect:

  • yum -y install non_existing_package exists with zero
  • dnf -y install non_existing_package exists with non-zero (even if you do yum on EL8 it is actually dnf)

The DNF team tried to fix some flaw but this is quite breaking change which can do a lot of damage. Try to investigate this.

HI,

Already checked last week. The exit code when installing with dnf manually results in 0, if the package is not already installed. If the package is already installed it exits with 1.

Other ideas are always welcome :slight_smile:

Is this the root cause perhaps?

HI,

No this is not the root cause :frowning_face: I have no clue what direction I could search now.
I also updated cloud-init to cloud-init-19.4.

If the package is already installed and I remove /var/lib/cloud and reboot the server, it runs fine without issues as described earlier.

What else can I investigate?

HI,

Other strange thing is that when I have the config as below. I only find 6 count pings and not 20. Furthermore I do not see any record about installing package “SL” in the dnf logs . Any ideas?

Template according foreman
runcmd:
- setenforce 0
- echo “check permissve” >> /tmp/test
- getenforce | tee -a /tmp/test
- ping 8.8.8.8 -c 20 | tee -a /tmp/test
#- [ rpm, -Uvh ,“https://yum.puppet.com/puppet6/puppet6-release-el-8.noarch.rpm” ]
#- dnf clean all | tee -a /tmp/output.log
- dnf install -y sl | tee -a /tmp/test

phone_home:
  url: http://xxxx.xx.xxxx.xx/unattended/built
  post: []
  tries: 10

Regards,

It looks like that subprocess.py is not waiting for the tasks being completed at all, but I could be wrong of course. As you can see dnf is never executed.

^[[A[root@test03 ~]# cat /tmp/test
check permissive
Permissive
PING 8.8.8.8 (8.8.8.8) 56(84) bytes of data.
64 bytes from 8.8.8.8: icmp_seq=1 ttl=121 time=1.07 ms
64 bytes from 8.8.8.8: icmp_seq=2 ttl=121 time=1.40 ms
64 bytes from 8.8.8.8: icmp_seq=3 ttl=121 time=1.15 ms
64 bytes from 8.8.8.8: icmp_seq=4 ttl=121 time=1.18 ms
64 bytes from 8.8.8.8: icmp_seq=5 ttl=121 time=1.09 ms
64 bytes from 8.8.8.8: icmp_seq=6 ttl=121 time=1.20 ms
64 bytes from 8.8.8.8: icmp_seq=7 ttl=121 time=1.25 ms

@ekohl Do you have other suggestions maybe?

An idea, could selinux itself be the issue?

HI,

That is why i change to permissive mode before calling “DNF”, just to be sure. Furthermore I do not see anything in the audit.log related to this issue. Only something about vmware customization not allowed to write to a log file.

I know that not everything is logged to the audit.log but permissive mode should allow the action at least. I could disable it completely but I dont think at this point in time it is related to Selinux. No breadcrumbs pointing that direction.

Sometimes lets say, (Guessing) one of 100 tries results in installing SL.

I’ve never used cloud-init, but what if you use the native packages instead of a command? Perhaps you also need to use yum_repos.

Another is that runcmd mentions you need to quote. Perhaps YAML is interpreting the - as a list instead of an argument? So "-y".

Using native packages results in:

modules-config/config-package-update-upgrade-install: FAIL: running config-package-update-upgrade-install with frequency once-per-instance.

I`ll try to investigate, maybe this correlates to each other.

2020-08-24 15:53:11,314 - stages.py[DEBUG]: Running module package-update-upgrade-install (<module 'cloudinit.config.cc_package_update_upgrade_install' from '/usr/lib/python3.6/site-packages/cloudinit/config/cc_package_update_upgrade_install.py'>) with frequency once-pe
r-instance
2020-08-24 15:53:11,314 - handlers.py[DEBUG]: start: modules-config/config-package-update-upgrade-install: running config-package-update-upgrade-install with frequency once-per-instance
2020-08-24 15:53:11,314 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-9d94ce174298e08402/sem/config_package_update_upgrade_install - wb: [644] 24 bytes
2020-08-24 15:53:11,314 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/i-9d94ce174298e08402/sem/config_package_update_upgrade_install (recursive=False)
2020-08-24 15:53:11,315 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/i-9d94ce174298e08402/sem/config_package_update_upgrade_install (recursive=False)
2020-08-24 15:53:11,315 - helpers.py[DEBUG]: Running config-package-update-upgrade-install using lock (<FileLock using file '/var/lib/cloud/instances/i-9d94ce174298e08402/sem/config_package_update_upgrade_install'>)
2020-08-24 15:53:11,315 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-9d94ce174298e08402/sem/update_sources - wb: [644] 25 bytes
2020-08-24 15:53:11,316 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/i-9d94ce174298e08402/sem/update_sources (recursive=False)
2020-08-24 15:53:11,317 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/i-9d94ce174298e08402/sem/update_sources (recursive=False)
2020-08-24 15:53:11,317 - helpers.py[DEBUG]: Running update-sources using lock (<FileLock using file '/var/lib/cloud/instances/i-9d94ce174298e08402/sem/update_sources'>)
2020-08-24 15:53:11,317 - rhel.py[DEBUG]: Using DNF for package management
2020-08-24 15:53:11,317 - util.py[DEBUG]: Running command ['dnf', '-y', 'makecache'] with allowed return codes [0] (shell=False, capture=False)
2020-08-24 15:53:12,375 - util.py[DEBUG]: Cloud-init 19.4 received SIGTERM, exiting...
  Filename: /usr/lib64/python3.6/subprocess.py
  Function: _try_wait
  Line number: 1424
    Filename: /usr/lib64/python3.6/subprocess.py
    Function: wait
    Line number: 1477
      Filename: /usr/lib64/python3.6/subprocess.py
      Function: communicate
      Line number: 855
2020-08-24 15:53:12,376 - handlers.py[DEBUG]: finish: modules-config/config-package-update-upgrade-install: FAIL: running config-package-update-upgrade-install with frequency once-per-instance
2020-08-24 15:53:12,376 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2020-08-24 15:53:12,376 - util.py[DEBUG]: Read 11 bytes from /proc/uptime
2020-08-24 15:53:12,376 - util.py[DEBUG]: cloud-init mode 'modules' took 1.160 seconds (1.16)
2020-08-24 15:53:12,376 - handlers.py[DEBUG]: finish: modules-config: FAIL: running modules for config
2020-08-24 15:53:35,460 - util.py[DEBUG]: Cloud-init v. 19.4 running 'init-local' at Mon, 24 Aug 2020 15:53:35 +0000. Up 9.67 seconds.
2020-08-24 15:53:35,463 - main.py[DEBUG]: No kernel command line url found.
2020-08-24 15:53:35,463 - main.py[DEBUG]: Closing stdin.

Or maybe someone has the answer on forehand.

Perhaps the network takes a while to be available and it’s failing on that? Is there a repo which is unavailable?

HI,

There is network connectivity, otherwise the client would not be able to read the seed file from foreman itself. When I run it manually “sudo cloud-init single --name package-update-upgrade-install --frequency always” it works without any issues.

Strange bug aint it?

Regards,

@TimoGoebel Do you have some idea`s maybe?