Uploaded image for project: 'Puppet'
  1. Puppet
  2. PUP-6536

Puppet agent does not start properly with systemd the first time

          Details

          • Type: Bug
          • Status: Closed
          • Priority: Normal
          • Resolution: Fixed
          • Affects Version/s: PUP 3.8.5
          • Fix Version/s: None
          • Component/s: None
          • Labels:
            None
          • Environment:

            Ubuntu 16.04.01

          • Template:

            Description

            Hi,

            When using Foreman to provision a VM, on first boot, the puppet agent times out with the following error in journalctl

            Jul 22 15:05:10 cfw-2-server systemd[1]: Starting Puppet agent...
            		 
            Jul 22 15:05:10 cfw-2-server systemd[1]: Starting LSB: Set the CPU Frequency Scaling governor to "ondemand"...
            		 
            Jul 22 15:05:10 cfw-2-server cron[1677]: (CRON) INFO (pidfile fd = 3)
            		 
            Jul 22 15:05:10 cfw-2-server systemd[1]: Starting LSB: Record successful boot for GRUB...
            		 
            Jul 22 15:05:10 cfw-2-server systemd[1]: Started D-Bus System Message Bus.
            		 
            Jul 22 15:05:10 cfw-2-server cron[1677]: (CRON) INFO (Running @reboot jobs)
            		 
            Jul 22 15:05:10 cfw-2-server dhclient[1675]: Internet Systems Consortium DHCP Client 4.3.3
            		 
            Jul 22 15:05:10 cfw-2-server sh[1628]: Internet Systems Consortium DHCP Client 4.3.3
            		 
            Jul 22 15:05:10 cfw-2-server sh[1628]: Copyright 2004-2015 Internet Systems Consortium.
            		 
            Jul 22 15:05:10 cfw-2-server sh[1628]: All rights reserved.
            		 
            Jul 22 15:05:10 cfw-2-server sh[1628]: For info, please visit https://www.isc.org/software/dhcp/
            		 
            Jul 22 15:05:10 cfw-2-server dhclient[1675]: Copyright 2004-2015 Internet Systems Consortium.
            		 
            Jul 22 15:05:10 cfw-2-server dhclient[1675]: All rights reserved.
            		 
            Jul 22 15:05:10 cfw-2-server dhclient[1675]: For info, please visit https://www.isc.org/software/dhcp/
            		 
            Jul 22 15:05:10 cfw-2-server dhclient[1675]:
            		 
            Jul 22 15:05:10 cfw-2-server dbus[1691]: [system] AppArmor D-Bus mediation is enabled
            		 
            Jul 22 15:05:10 cfw-2-server systemd[1]: Starting System Security Services Daemon...
            		 
            Jul 22 15:05:10 cfw-2-server systemd[1]: Starting System Logging Service...
            		 
            Jul 22 15:05:10 cfw-2-server systemd[1]: Started Daily Cleanup of Temporary Directories.
            		 
            Jul 22 15:05:10 cfw-2-server systemd[1]: Reached target Timers.
            		 
            Jul 22 15:05:10 cfw-2-server systemd[1]: Found device Virtio network device.
            		 
            Jul 22 15:05:10 cfw-2-server dhclient[1675]: Listening on LPF/ens3/00:1a:4a:e5:12:94
            		 
            Jul 22 15:05:10 cfw-2-server sh[1628]: Listening on LPF/ens3/00:1a:4a:e5:12:94
            		 
            Jul 22 15:05:10 cfw-2-server sh[1628]: Sending on   LPF/ens3/00:1a:4a:e5:12:94
            		 
            Jul 22 15:05:10 cfw-2-server sh[1628]: Sending on   Socket/fallback
            		 
            Jul 22 15:05:10 cfw-2-server sh[1628]: DHCPDISCOVER on ens3 to 255.255.255.255 port 67 interval 3 (xid=0x1e3bf50a)
            		 
            Jul 22 15:05:10 cfw-2-server dhclient[1675]: Sending on   LPF/ens3/00:1a:4a:e5:12:94
            		 
            Jul 22 15:05:10 cfw-2-server dhclient[1675]: Sending on   Socket/fallback
            		 
            Jul 22 15:05:10 cfw-2-server dhclient[1675]: DHCPDISCOVER on ens3 to 255.255.255.255 port 67 interval 3 (xid=0x1e3bf50a)
            		 
            Jul 22 15:05:10 cfw-2-server systemd[1]: Started System Logging Service.
            		 
            Jul 22 15:05:10 cfw-2-server dhclient[1675]: DHCPREQUEST of 10.79.2.242 on ens3 to 255.255.255.255 port 67 (xid=0xaf53b1e)
            		 
            Jul 22 15:05:10 cfw-2-server sh[1628]: DHCPREQUEST of 10.79.2.242 on ens3 to 255.255.255.255 port 67 (xid=0xaf53b1e)
            		 
            Jul 22 15:05:10 cfw-2-server sh[1628]: DHCPOFFER of 10.79.2.242 from 10.79.2.46
            		 
            Jul 22 15:05:10 cfw-2-server dhclient[1675]: DHCPOFFER of 10.79.2.242 from 10.79.2.46
            		 
            Jul 22 15:05:10 cfw-2-server dhclient[1675]: DHCPACK of 10.79.2.242 from 10.79.2.46
            		 
            Jul 22 15:05:10 cfw-2-server sh[1628]: DHCPACK of 10.79.2.242 from 10.79.2.46
            		 
            Jul 22 15:05:10 cfw-2-server systemd[1]: Started LSB: Set the CPU Frequency Scaling governor to "ondemand".
            		 
            Jul 22 15:05:10 cfw-2-server systemd[1]: Started LSB: Record successful boot for GRUB.
            		 
            Jul 22 15:05:10 cfw-2-server kernel: snd_hda_codec_generic hdaudioC0D0: autoconfig for Generic: line_outs=1 (0x3/0x0/0x0/0x0/0x0) type:line
            		 
            Jul 22 15:05:10 cfw-2-server kernel: snd_hda_codec_generic hdaudioC0D0:    speaker_outs=0 (0x0/0x0/0x0/0x0/0x0)
            		 
            Jul 22 15:05:10 cfw-2-server kernel: snd_hda_codec_generic hdaudioC0D0:    hp_outs=0 (0x0/0x0/0x0/0x0/0x0)
            		 
            Jul 22 15:05:10 cfw-2-server kernel: snd_hda_codec_generic hdaudioC0D0:    mono: mono_out=0x0
            		 
            Jul 22 15:05:10 cfw-2-server kernel: snd_hda_codec_generic hdaudioC0D0:    inputs:
            		 
            Jul 22 15:05:10 cfw-2-server kernel: snd_hda_codec_generic hdaudioC0D0:      Line=0x5
            		 
            Jul 22 15:05:10 cfw-2-server dhclient[1675]: bound to 10.79.2.242 -- renewal in 17159 seconds.
            		 
            Jul 22 15:05:10 cfw-2-server sh[1628]: bound to 10.79.2.242 -- renewal in 17159 seconds.
            		 
            Jul 22 15:05:10 cfw-2-server systemd[1]: Started Set console font and keymap.
            		 
            Jul 22 15:05:10 cfw-2-server systemd[1]: Created slice system-getty.slice.
            		 
            Jul 22 15:05:10 cfw-2-server kernel: AVX version of gcm_enc/dec engaged.
            		 
            Jul 22 15:05:10 cfw-2-server kernel: AES CTR mode by8 optimization enabled
            		 
            Jul 22 15:05:10 cfw-2-server sh[1628]: ifup: interface ens3 already configured
            		 
            Jul 22 15:05:10 cfw-2-server systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch.
            		 
            Jul 22 15:05:10 cfw-2-server sssd[2125]: Starting up
            		 
            Jul 22 15:05:10 cfw-2-server kernel: intel_rapl: no valid rapl domains found in package 0
            		 
            Jul 22 15:05:10 cfw-2-server systemd[1]: Reached target Sound Card.
            		 
            Jul 22 15:05:10 cfw-2-server kernel: ppdev: user-space parallel port driver
            		 
            Jul 22 15:05:10 cfw-2-server kernel: intel_rapl: no valid rapl domains found in package 0
            		 
            Jul 22 15:05:10 cfw-2-server sssd[be[2238]: Starting up
            		 
            Jul 22 15:05:10 cfw-2-server kernel: intel_rapl: no valid rapl domains found in package 0
            		 
            Jul 22 15:05:10 cfw-2-server sssd[2243]: Starting up
            		 
            Jul 22 15:05:10 cfw-2-server sssd[2242]: Starting up
            		 
            Jul 22 15:05:10 cfw-2-server sssd[2240]: Starting up
            		 
            Jul 22 15:05:10 cfw-2-server sssd[2241]: Starting up
            		 
            Jul 22 15:05:10 cfw-2-server sssd[2244]: Starting up
            		 
            Jul 22 15:05:11 cfw-2-server systemd[1]: Started System Security Services Daemon.
            		 
            Jul 22 15:05:11 cfw-2-server systemd[1]: Reached target User and Group Name Lookups.
            		 
            Jul 22 15:05:11 cfw-2-server systemd[1]: Starting Login Service...
            		 
            Jul 22 15:05:11 cfw-2-server systemd[1]: Starting Accounts Service...
            		 
            Jul 22 15:05:11 cfw-2-server systemd[1]: Starting Permit User Sessions...
            		 
            Jul 22 15:05:11 cfw-2-server systemd[1]: Started Permit User Sessions.
            		 
            Jul 22 15:05:11 cfw-2-server systemd[1]: Starting Set console scheme...
            		 
            Jul 22 15:05:11 cfw-2-server systemd[1]: Started Login Service.
            		 
            Jul 22 15:05:11 cfw-2-server systemd-logind[2251]: New seat seat0.
            		 
            Jul 22 15:05:11 cfw-2-server systemd-logind[2251]: Watching system buttons on /dev/input/event0 (Power Button)
            		 
            Jul 22 15:05:11 cfw-2-server systemd[1]: Started Set console scheme.
            		 
            Jul 22 15:05:11 cfw-2-server accounts-daemon[2253]: started daemon version 0.6.40
            		 
            Jul 22 15:05:11 cfw-2-server systemd[1]: Started Accounts Service.
            		 
            Jul 22 15:05:11 cfw-2-server sssd_be[2238]: GSSAPI client step 1
            		 
            Jul 22 15:05:11 cfw-2-server sssd_be[2238]: GSSAPI client step 1
            		 
            Jul 22 15:05:12 cfw-2-server sssd_be[2238]: GSSAPI client step 1
            		 
            Jul 22 15:05:13 cfw-2-server sssd_be[2238]: GSSAPI client step 2
            		 
            Jul 22 15:05:13 cfw-2-server systemd[1]: Started Raise network interfaces.
            		 
            Jul 22 15:05:13 cfw-2-server systemd[1]: Reached target Network.
            		 
            Jul 22 15:05:13 cfw-2-server systemd[1]: Starting OpenBSD Secure Shell server...
            		 
            Jul 22 15:05:13 cfw-2-server systemd[1]: Started privileged operations for unprivileged applications.
            		 
            Jul 22 15:05:13 cfw-2-server systemd[1]: Starting Certificate monitoring and PKI enrollment...
            		 
            Jul 22 15:05:13 cfw-2-server systemd[1]: Reached target Network is Online.
            		 
            Jul 22 15:05:13 cfw-2-server systemd[1]: Starting LSB: Start NTP daemon...
            		 
            Jul 22 15:05:13 cfw-2-server systemd[1]: Starting /etc/rc.local Compatibility...
            		 
            Jul 22 15:05:13 cfw-2-server systemd[1]: Started /etc/rc.local Compatibility.
            		 
            Jul 22 15:05:13 cfw-2-server systemd[1]: Started Getty on tty1.
            		 
            Jul 22 15:05:13 cfw-2-server ntp[2300]:  * Starting NTP server ntpd
            		 
            Jul 22 15:05:13 cfw-2-server systemd[1]: Reached target Login Prompts.
            		 
            Jul 22 15:05:13 cfw-2-server sshd[2294]: Server listening on 0.0.0.0 port 22.
            		 
            Jul 22 15:05:13 cfw-2-server sshd[2294]: Server listening on :: port 22.
            		 
            Jul 22 15:05:13 cfw-2-server systemd[1]: Started OpenBSD Secure Shell server.
            		 
            Jul 22 15:05:13 cfw-2-server ntpd[2312]: ntpd 4.2.8p4@1.3265-o Fri Apr  8 20:58:07 UTC 2016 (1): Starting
            		 
            Jul 22 15:05:13 cfw-2-server ntpd[2312]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 109:113
            		 
            Jul 22 15:05:13 cfw-2-server ntp[2300]:    ...done.
            		 
            Jul 22 15:05:13 cfw-2-server systemd[1]: Started LSB: Start NTP daemon.
            		 
            Jul 22 15:05:13 cfw-2-server ntpd[2314]: proto: precision = 0.064 usec (-24)
            		 
            Jul 22 15:05:13 cfw-2-server ntpd[2314]: Listen and drop on 0 v6wildcard [::]:123
            		 
            Jul 22 15:05:13 cfw-2-server ntpd[2314]: Listen and drop on 1 v4wildcard 0.0.0.0:123
            		 
            Jul 22 15:05:13 cfw-2-server ntpd[2314]: Listen normally on 2 lo 127.0.0.1:123
            		 
            Jul 22 15:05:13 cfw-2-server ntpd[2314]: Listen normally on 3 ens3 10.79.2.242:123
            		 
            Jul 22 15:05:13 cfw-2-server ntpd[2314]: Listen normally on 4 lo [::1]:123
            		 
            Jul 22 15:05:13 cfw-2-server ntpd[2314]: Listen normally on 5 ens3 [fe80::21a:4aff:fee5:1294%2]:123
            		 
            Jul 22 15:05:13 cfw-2-server ntpd[2314]: Listening on routing socket on fd #22 for interface updates
            		 
            Jul 22 15:05:13 cfw-2-server systemd[1]: Started Certificate monitoring and PKI enrollment.
            		 
            Jul 22 15:05:13 cfw-2-server ipa-submit[2321]: GSSAPI client step 1
            		 
            Jul 22 15:05:13 cfw-2-server ipa-submit[2321]: GSSAPI client step 1
            		 
            Jul 22 15:05:13 cfw-2-server ipa-submit[2321]: GSSAPI client step 1
            		 
            Jul 22 15:05:13 cfw-2-server ipa-submit[2321]: GSSAPI client step 1
            		 
            Jul 22 15:05:14 cfw-2-server ntpd[2314]: Soliciting pool server 46.29.177.23
            		 
            Jul 22 15:05:14 cfw-2-server ipa-submit[2321]: GSSAPI client step 2
            		 
            Jul 22 15:05:15 cfw-2-server ntpd[2314]: Soliciting pool server 213.167.241.72
            		 
            Jul 22 15:05:14 cfw-2-server systemd[1]: Time has been changed
            		 
            Jul 22 15:05:14 cfw-2-server systemd[1]: apt-daily.timer: Adding 10h 44min 16.971854s random time.
            		 
            Jul 22 15:05:14 cfw-2-server ntpd[2314]: Soliciting pool server 80.92.86.18
            		 
            Jul 22 15:05:15 cfw-2-server ntpd[2314]: Soliciting pool server 46.29.183.183
            		 
            Jul 22 15:05:15 cfw-2-server ntpd[2314]: Soliciting pool server 80.92.86.19
            		 
            Jul 22 15:05:16 cfw-2-server ntpd[2314]: Soliciting pool server 46.29.177.19
            		 
            Jul 22 15:05:16 cfw-2-server ntpd[2314]: Soliciting pool server 46.29.177.18
            		 
            Jul 22 15:05:17 cfw-2-server ntpd[2314]: Soliciting pool server 2001:67c:12ac:200:2001:67c:12ac:200
            		 
            Jul 22 15:05:17 cfw-2-server ntpd[2314]: Soliciting pool server 91.189.89.198
            		 
            Jul 22 15:05:18 cfw-2-server ntpd[2314]: Soliciting pool server 91.189.94.4
            		 
            Jul 22 15:06:40 cfw-2-server systemd[1]: puppet.service: Start operation timed out. Terminating.
            		 
            Jul 22 15:06:40 cfw-2-server systemd[1]: Failed to start Puppet agent.
            		 
            Jul 22 15:06:40 cfw-2-server systemd[1]: puppet.service: Unit entered failed state.
            		 
            Jul 22 15:06:40 cfw-2-server systemd[1]: puppet.service: Failed with result 'timeout'.

            After a normal reboot, the agent starts fine (even though it takes couple seconds to start).

            Is there something I don't see?

              Attachments

                Activity

                Ascending order - Click to sort in descending order
                Hide
                Permalink
                Trefex Christophe Trefois added a comment -

                Here is the template that was used to built the VM using Foreman on oVirt 3.6

                apt-get update
                		 
                apt-get install -y puppet
                		 
                 
                		 
                cat > /etc/puppet/puppet.conf << EOF
                		 
                 
                		 
                 
                		 
                [main]
                		 
                vardir = /var/lib/puppet
                		 
                logdir = /var/log/puppet
                		 
                rundir = /var/run/puppet
                		 
                ssldir = \$vardir/ssl
                		 
                 
                		 
                [agent]
                		 
                pluginsync      = true
                		 
                report          = true
                		 
                ignoreschedules = true
                		 
                ca_server       = lcsb-foreman-server.uni.lu
                		 
                certname        = cfw-2-server.lcsb.uni.lu
                		 
                environment     = production
                		 
                server          = lcsb-foreman-server.uni.lu
                		 
                 
                		 
                EOF
                		 
                 
                		 
                if [ -f "/etc/default/puppet" ]
                		 
                then
                		 
                /bin/sed -i 's/^START=no/START=yes/' /etc/default/puppet
                		 
                fi
                		 
                /usr/bin/puppet agent --enable
                		 
                 
                		 
                # 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
                		 
                /usr/bin/puppet agent --config /etc/puppet/puppet.conf --onetime --tags no_such_tag --server lcsb-foreman-server.uni.lu --no-daemonize
                		 
                 
                		 
                 
                		 
                 
                		 
                 
                		 
                 
                		 
                real=`ip -o link | grep 00:1a:4a:e5:12:94 | awk '{print $2;}' | sed s/://`
                		 
                cat << EOF > /etc/network/interfaces
                		 
                #loopback
                		 
                auto lo
                		 
                iface lo inet loopback
                		 
                 
                		 
                #ens3
                		 
                auto $real
                		 
                allow-hotplug $real
                		 
                iface $real inet dhcp
                		 
                 
                		 
                EOF
                		 
                 
                		 
                 
                		 
                 
                		 
                /usr/bin/wget --no-proxy --quiet --output-document=/dev/null --no-check-certificate http://lcsb-foreman-server.uni.lu/unattended/built

                Show
                Trefex Christophe Trefois added a comment - Here is the template that was used to built the VM using Foreman on oVirt 3.6 apt-get update apt-get install -y puppet   cat > /etc/puppet/puppet.conf << EOF     [main] vardir = /var/lib/puppet logdir = /var/log/puppet rundir = /var/run/puppet ssldir = \$vardir/ssl   [agent] pluginsync = true report = true ignoreschedules = true ca_server = lcsb-foreman-server.uni.lu certname = cfw-2-server.lcsb.uni.lu environment = production server = lcsb-foreman-server.uni.lu   EOF   if [ -f "/etc/default/puppet" ] then /bin/sed -i 's/^START=no/START=yes/' /etc/default/puppet fi /usr/bin/puppet agent --enable   # 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 /usr/bin/puppet agent --config /etc/puppet/puppet.conf --onetime --tags no_such_tag --server lcsb-foreman-server.uni.lu --no-daemonize           real=`ip -o link | grep 00:1a:4a:e5:12:94 | awk '{print $2;}' | sed s/://` cat << EOF > /etc/network/interfaces #loopback auto lo iface lo inet loopback   #ens3 auto $real allow-hotplug $real iface $real inet dhcp   EOF       /usr/bin/wget --no-proxy --quiet --output-document=/dev/null --no-check-certificate http://lcsb-foreman-server.uni.lu/unattended/built
                Hide
                Permalink
                nick.fagerlund Nicholas Fagerlund added a comment -

                Thank you for reporting this.

                So, we think this issue is probably fixed in newer versions of Puppet, especially since nobody else has reported or commented on this bug. We're going to close it as fixed, but if you still experience this issue against the current version of Puppet, could you add a comment to this ticket with your reproduction scenario?

                Show
                nick.fagerlund Nicholas Fagerlund added a comment - Thank you for reporting this. So, we think this issue is probably fixed in newer versions of Puppet, especially since nobody else has reported or commented on this bug. We're going to close it as fixed, but if you still experience this issue against the current version of Puppet, could you add a comment to this ticket with your reproduction scenario?

                  People

                  • Assignee:
                    Unassigned
                    Reporter:
                    Trefex Christophe Trefois
                  • Votes:
                    0 Vote for this issue
                    Watchers:
                    2 Start watching this issue

                    Dates

                    • Created:
                      Updated:
                      Resolved:

                      Zendesk Support