[SERVER-2517] puppetserver logs the same error twice Created: 2019/04/10  Updated: 2019/10/02

Status: Accepted
Project: Puppet Server
Component/s: Puppet Server
Affects Version/s: SERVER 5.3.7, SERVER 6.0.3
Fix Version/s: None

Type: Bug Priority: Normal
Reporter: Thomas Kishel Assignee: Unassigned
Resolution: Unresolved Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Text File double.txt    
Template: PUP Bug Template
Team: Server
Method Found: Customer Feedback
QA Risk Assessment: Needs Assessment

 Description   

Puppet Version: 5.5.10
Puppet Server Version: 2018.1.0.109

Desired Behavior:

puppetserver logs the same error once

Actual Behavior:

puppetserver logs the same error twice, complicating the use of report processors like jamtur01/puppet-snmp

Reproduction:

Declare non-existent class for an agent:

[root@pe-201817-master ~]# cat /etc/puppetlabs/code/environments/production/manifests/site.pp 
node 'pe-201817-agent.puppetdebug.vlan' {
  include role::bad
}

Run puppet on the agent:

[root@pe-201817-agent ~]# puppet agent -t
Info: Using configured environment 'production'
Info: Retrieving pluginfacts
Info: Retrieving plugin
Info: Retrieving locales
Info: Loading facts
Error: Could not retrieve catalog from remote server: Error 500 on SERVER: Server Error: Evaluation Error: Error while evaluating a Function Call, Could not find class ::role::bad for pe-201817-agent.puppetdebug.vlan (file: /etc/puppetlabs/code/environments/production/manifests/site.pp, line: 4, column: 3) on node pe-201817-agent.puppetdebug.vlan
Warning: Not using cache on failed catalog
Error: Could not retrieve catalog; skipping run

"Puppet Evaluation Error" is logged twice (not including the "Puppet Server Error") identically:

[root@pe-201902-master ~]#  tail -f /var/log/puppetlabs/puppetserver/puppetserver.log | grep "Error"
2019-04-10T22:36:14.180Z ERROR [qtp338004690-79] [puppetserver] Puppet Evaluation Error: Error while evaluating a Function Call, Could not find class ::role::bad ...
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:373:in `block in evaluate_classes'
...
2019-04-10T22:36:14.180Z ERROR [qtp338004690-79] [puppetserver] Puppet Evaluation Error: Error while evaluating a Function Call, Could not find class ::role::bad ...
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:373:in `block in evaluate_classes'
...
2019-04-10T22:36:14.181Z ERROR [qtp338004690-79] [puppetserver] Puppet Server Error: Evaluation Error: Error while evaluating a Function Call, Could not find class ::role::bad for pe-201902-agent.puppetdebug.vlan (file: /etc/puppetlabs/code/environments/production/manifests/site.pp, line: 4, column: 3) on node pe-201902-agent.puppetdebug.vlan

See attached for the log with puppetserver with loglevel=debug



 Comments   
Comment by Maggie Dreyer [ 2019/04/10 ]

Confirmed that this can still be repro'd on the latest version as well. Digging in a bit more now.

Comment by Thomas Kishel [ 2019/04/11 ]

This exists in 2016.4.x and 2017.3.x:

[root@pe-2016415-master ~]# puppet agent -t
Info: Using configured environment 'production'
Info: Retrieving pluginfacts
Info: Retrieving plugin
Info: Loading facts
Error: Could not retrieve catalog from remote server: Error 500 on SERVER: Server Error: Evaluation Error: Error while evaluating a Function Call, Could not find class ::role::bad for pe-2016415-master.puppetdebug.vlan at /etc/puppetlabs/code/environments/production/manifests/site.pp:4:3 on node pe-2016415-master.puppetdebug.vlan
Warning: Not using cache on failed catalog
Error: Could not retrieve catalog; skipping run
 
[root@pe-2016415-master ~]# cat /var/log/puppetlabs/puppetserver/puppetserver.log 
2019-04-11 15:33:45,139 ERROR [qtp264732565-64] [puppetserver] Puppet Evaluation Error: Error while evaluating a Function Call, Could not find class ::role::bad for pe-2016415-master.puppetdebug.vlan at /etc/puppetlabs/code/environments/production/manifests/site.pp:4:3 on node pe-2016415-master.puppetdebug.vlan
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:386:in `evaluate_classes'
...
2019-04-11 15:33:45,139 ERROR [qtp264732565-64] [puppetserver] Puppet Evaluation Error: Error while evaluating a Function Call, Could not find class ::role::bad for pe-2016415-master.puppetdebug.vlan at /etc/puppetlabs/code/environments/production/manifests/site.pp:4:3 on node pe-2016415-master.puppetdebug.vlan
2019-04-11 15:33:45,140 ERROR [qtp264732565-64] [puppetserver] Puppet Server Error: Evaluation Error: Error while evaluating a Function Call, Could not find class ::role::bad for pe-2016415-master.puppetdebug.vlan at /etc/puppetlabs/code/environments/production/manifests/site.pp:4:3 on node pe-2016415-master.puppetdebug.vlan
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:386:in `evaluate_classes'
...

[root@pe-201738-master ~]# puppet agent -t
Info: Using configured environment 'production'
Info: Retrieving pluginfacts
Info: Retrieving plugin
Info: Retrieving locales
Info: Loading facts
Error: Could not retrieve catalog from remote server: Error 500 on SERVER: Server Error: Evaluation Error: Error while evaluating a Function Call, Could not find class ::role::bad for pe-201738-master.puppetdebug.vlan (file: /etc/puppetlabs/code/environments/production/manifests/site.pp, line: 4, column: 3) on node pe-201738-master.puppetdebug.vlan
Warning: Not using cache on failed catalog
Error: Could not retrieve catalog; skipping run

[root@pe-201738-master ~]# cat /var/log/puppetlabs/puppetserver/puppetserver.log
2019-04-11 15:51:34,730 ERROR [qtp2068474644-72] [puppetserver] Puppet Evaluation Error: Error while evaluating a Function Call, Could not find class ::role::bad for pe-201738-master.puppetdebug.vlan (file: /etc/puppetlabs/code/environments/production/manifests/site.pp, line: 4, column: 3) on node pe-201738-master.puppetdebug.vlan
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:371:in `evaluate_classes'
...
2019-04-11 15:51:34,730 ERROR [qtp2068474644-72] [puppetserver] Puppet Evaluation Error: Error while evaluating a Function Call, Could not find class ::role::bad for pe-201738-master.puppetdebug.vlan (file: /etc/puppetlabs/code/environments/production/manifests/site.pp, line: 4, column: 3) on node pe-201738-master.puppetdebug.vlan
2019-04-11 15:51:34,730 ERROR [qtp2068474644-72] [puppetserver] Puppet Server Error: Evaluation Error: Error while evaluating a Function Call, Could not find class ::role::bad for pe-201738-master.puppetdebug.vlan (file: /etc/puppetlabs/code/environments/production/manifests/site.pp, line: 4, column: 3) on node pe-201738-master.puppetdebug.vlan
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:371:in `evaluate_classes'
...

 

Comment by Henrik Lindberg [ 2019/04/12 ]

When running an apply, the error is only logged once:

$> puppet apply -e 'node default { include module::bad }'
Error: Evaluation Error: Error while evaluating a Function Call, Could not find class ::module::bad for localhost (line: 1, column: 16) on node localhost

The compiler logs all errors and warnings (up to the max cap, default 10), and raises one exception from validation of the parsed source (the original error, or one stating that there were too many errors if there are more than one), then during evaluation, it logs exceptions and raises an error.

I suspect the extra message comes from the terminus as it may not trust that a raised exception has been logged already. it may need to differentiate the behavior depending on what kind of error it is.

Generated at Thu Nov 21 02:41:03 PST 2019 using JIRA 7.7.1#77002-sha1:e75ca93d5574d9409c0630b81c894d9065296414.