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

            jsd-sla-details-panel

              People

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

                Dates

                • Created:
                  Updated:
                  Resolved: