Troubleshoot Puppet run errors and slow runs in Puppet Enterprise by adding flags

When Puppet runs are failing or slow, add flags to get more information about connection and catalog issues. Use flags to help diagnose failed agent connections, refused connections, Server 500 error, slow Puppet runs, catalog application issues, and Ruby-based issues with custom code and Puppet component failures.

Version and installation information

PE version: All supported versions

Solution

You can get additional information about Puppet runs in the command line by adding flags. For example:

puppet agent -t --debug

However, if you get errors only during daemonized or automated runs, add flags by editing the agent service configuration.

Choose one or more flags based on the error or issue that you are experiencing. For clarity, most included examples use one flag.

Sending troubleshooting information to Support

If you need help troubleshooting, attach the output of your Puppet runs (and puppetserver.log, depending on the flag used) to a Support ticket, making sure to remove any sensitive information.

To direct output to a file named agent_debug.txt, for example, run:

puppet agent -td --evaltrace --profile > agent_debug.txt 2>&1

The file will be generated in the directory you're currently in, unless you specify otherwise.

I'm not sure what the problem is, and I need more information

The --debug flag enables verbose logging. It logs all diagnostic messages during a Puppet run. If you're not sure where to start, it's a great way to get more information. Use it to get more information about data used to gather Facter information, commands run by providers, and messages about failing resources.

Note: You can shorten this command to puppet agent -td

For example, puppet agent -t --debug gives output similar to:

Debug: Applying settings catalog for sections main, agent, ssl
Debug: Using settings: adding file resource 'confdir': 'File[/etc/puppetlabs/puppet]{:path=>"/etc/puppetlabs/puppet", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}'
Debug: Using settings: adding file resource 'codedir': 'File[/etc/puppetlabs/code]{:path=>"/etc/puppetlabs/code", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}'
Debug: Could not find library 'cfpropertylist' required to enable feature 'cfpropertylist'
Debug: Facter: There is no module named Centos
Debug: Facter: Resolving facts sequentially
Debug: Facter: resolving fact with user_query: operatingsystem
Debug: Facter: Searching fact: operatingsystem in file: operatingsystem.rb
Debug: Facter: Searching fact: operatingsystem in core facts and external facts
Debug: Facter: Loading all internal facts
[root@pe-server-5cd9df-0 ~]# man head
[root@pe-server-5cd9df-0 ~]# head -n 15 agentdebug.txt
Debug: Applying settings catalog for sections main, agent, ssl
Debug: Using settings: adding file resource 'confdir': 'File[/etc/puppetlabs/puppet]{:path=>"/etc/puppetlabs/puppet", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}'
Debug: Using settings: adding file resource 'codedir': 'File[/etc/puppetlabs/code]{:path=>"/etc/puppetlabs/code", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}'
Debug: Could not find library 'cfpropertylist' required to enable feature 'cfpropertylist'
Debug: Facter: There is no module named Centos
Debug: Facter: Resolving facts sequentially
Debug: Facter: resolving fact with user_query: operatingsystem
Debug: Facter: Searching fact: operatingsystem in file: operatingsystem.rb
Debug: Facter: Searching fact: operatingsystem in core facts and external facts
Debug: Facter: Loading all internal facts
Debug: Facter: List of resolvable facts: [#<Facter::SearchedFact:0x0000000003392a08 @name="operatingsystem", @fact_class=Facts::Rhel::Os::Name, @user_query="operatingsystem", @type=:legacy, @file=nil>]
Debug: Facter: Loading external facts
Debug: Facter: fact "operatingsystem" has resolved to: CentOS
Debug: Facter: resolving fact with user_query: operatingsystem
Debug: Facter: Searching fact: operatingsystem in file: operatingsystem.rb

Connection issues

Failed agent connection or connection refused messages

Use the --http_debug flag to diagnose failed agent connections and connection refused messages. This flag enables writing HTTP requests and responses to stderr.

For example: puppet agent -t --http_debug gives output similar to:

opening connection to pe-201732-server.puppetdebug.vlan:8140... opened starting SSL for pe-201732-server.puppetdebug.vlan:8140... SSL established <- "GET /puppet/v3/node/pe-201732-agent.puppetdebug.vlan?environment=production&transaction_uuid=06cf23f9-1864-4546-b7c3-94d2932d5d89&fail_on_404=true HTTP/1.1\r\nAccept: application/json, text/pson\r\nX-Puppet-Version: 5.3.3\r\nAccept-Encoding: gzip;q=1.0,deflate;q=0.6,identity;q=0.3\r\nUser-Agent: Puppet/5.3.3 Ruby/2.4.2-p198 (x86_64-linux)\r\nHost: pe-201732-server.puppetdebug.vlan:8140\r\n\r\n"

Error 500 on SERVER

After a failed run, an Error 500 on SERVER message on the agent in /var/log/messages indicates a communication issue with the node's primary server. In the primary server's puppetserver.log file (/var/log/puppetlabs/puppetserver/puppetserver.log), get more information by searching for the agent's certname and timestamps matching the errors.

For example:

2019-10-16T19:02:22.404Z ERROR [qtp330018347-72596] [c.p.h.c.i.PersistentSyncHttpClient] Error executing http request

java.net.ConnectException: Connection refused
	at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
	at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717)
	at org.apache.http.impl.nio.reactor.DefaultConnectingIOReactor.processEvent(DefaultConnectingIOReactor.java:171)
	at org.apache.http.impl.nio.reactor.DefaultConnectingIOReactor.processEvents(DefaultConnectingIOReactor.java:145)
	at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor.execute(AbstractMultiworkerIOReactor.java:348)
	at org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager.execute(PoolingNHttpClientConnectionManager.java:192)
	at org.apache.http.impl.nio.client.CloseableHttpAsyncClientBase$1.run(CloseableHttpAsyncClientBase.java:64)
	at java.lang.Thread.run(Thread.java:748)

2019-10-16T19:02:22.571Z WARN  [qtp330018347-72596] [puppetserver] Puppet Error connecting to pe-201818-server.puppetdebug.vlan on 8081 at route /pdb/cmd/v1?checksum=9179937ffb15357923bbf776f8d9ca5691275f52&version=5&certname=pe-201818-server.puppetdebug.vlan&command=replace_facts&producer-timestamp=2019-10-16T19:02:22.367Z, error message received was 'Error executing http request'. Failing over to the next PuppetDB server_url in the 'server_urls' list

2019-10-16T19:02:22.596Z ERROR [qtp330018347-72596] [puppetserver] Puppet Failed to execute '/pdb/cmd/v1?checksum=9179937ffb15357923bbf776f8d9ca5691275f52&version=5&certname=pe-201818-server.puppetdebug.vlan&command=replace_facts&producer-timestamp=2019-10-16T19:02:22.367Z' on at least 1 of the following 'server_urls': https://pe-201818-server.puppetdebug.vlan:8081

Slow Puppet runs

If Puppet runs take a long time, use the --profile flag to check for issues during catalog compilation and the --evaltrace and --debug flags to check for issues during catalog application. While troubleshooting, these flags are used together, for example: puppet agent -t --debug --profile --evaltrace. However, they are separate here so that you can understand what each one does.

The --profile flag

This flag adds PROFILE log entries to puppetserver.log showing how long calls to resources and functions on the server take. It helps find catalog creation issues and slow catalog compilation times.

Output from this flag is hard to read. Make it easy to read by using the puppet-profile-parser tool.

Note: We do not provide support for the puppet-profile-parser tool.

Here's an example of PROFILE output from the puppetserver.log:

2018-05-02 16:38:45,393 INFO  [qtp1575890414-3123] [puppetserver] Puppet PROFILE [3131934] 1.1.1.1.214 PuppetDB: Build events list (count: 0): took 0.0000 seconds
2018-05-02 16:38:45,394 INFO  [qtp1575890414-3123] [puppetserver] Puppet PROFILE [3131934] 1.1.1.1.215 PuppetDB: Build events list (count: 0): took 0.0010 seconds
2018-05-02 16:38:45,394 INFO  [qtp1575890414-3123] [puppetserver] Puppet PROFILE [3131934] 1.1.1.1.216 PuppetDB: Build events list (count: 0): took 0.0000 seconds

The --evaltrace flag

This flag helps you find resources that take a long time to be evaluated during a Puppet run, including complex custom facts, large package collections, and the last resource evaluated during an unresponsive Puppet run.

Example output:

 Info: Pe_repo::Repo[el-7-x86_64 2017.3.2]: Starting to evaluate the resource
 Info: Pe_repo::Repo[el-7-x86_64 2017.3.2]: Evaluated in 0.00 seconds
 Info: Pe_repo::El[el-7-x86_64]: Starting to evaluate the resource
 Info: Pe_repo::El[el-7-x86_64]: Evaluated in 0.00 seconds
 Info: Class[Pe_repo::Platform::El_7_x86_64]: Starting to evaluate the resource
 Info: Class[Pe_repo::Platform::El_7_x86_64]: Evaluated in 0.00 seconds

The --debug flag

This flag provides information about the agent during catalog application, including data used to gather Facter information, commands run by providers, and messages about failing resources.

Example output:

Debug: Applying settings catalog for sections main, agent, ssl
Debug: Caching environment 'production' (ttl = 0 sec)
Debug: Evicting cache entry for environment 'production'
Debug: Using settings: adding file resource 'confdir': 'File[/etc/puppetlabs/puppet]{:path=>"/etc/puppetlabs/puppet", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}'
Debug: Using settings: adding file resource 'codedir': 'File[/etc/puppetlabs/code]{:path=>"/etc/puppetlabs/code", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}'
Debug: Evicting cache entry for environment 'production'
Debug: Caching environment 'production' (ttl = 0 sec)

Ruby-based custom code and Puppet component failure

Use the --trace flag to get insight into issues with Ruby-based custom code (custom types, providers, and facts) and failures in Ruby-based components, such as the agent.

This flag outputs internal Ruby stacktraces interleaved with Puppet function frames.

For example puppet agent -t --trace gives output similar to:

Error: Failed to apply catalog: Property with key "include" outside of a section
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/inifile.rb:186:in `block in parse'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/inifile.rb:159:in `each_line'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/inifile.rb:159:in `parse'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/inifile.rb:141:in `read'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/inifile.rb:274:in `read'