[SERVER-1273] Puppet Server doesn't log backtraces from exceptions in functions Created: 2016/04/19  Updated: 2016/05/19  Resolved: 2016/05/13

Status: Closed
Project: Puppet Server
Component/s: Puppet Server
Affects Version/s: SERVER 2.1.0, SERVER 2.3.1
Fix Version/s: SERVER 2.4.0

Type: Bug Priority: Major
Reporter: Charlie Sharpsteen Assignee: John Duarte
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Template:
Sub-team: emerald
Story Points: 2
Sprint: Server Emerald 2016-05-18
CS Priority: Needs Priority
QA Contact: Erik Dasher

 Description   

When an exception is raised inside of the Ruby implementation of a function, Puppet Server logs the exception but not the Ruby backtrace that shows where the exception was raised. Puppet Server always runs with Ruby backtraces enabled, but explicitly setting trace = true in the master section of puppet.conf doesn't help.

Reproduction Case

  • Install PE 2015.2.2 or later.
  • Set up two test nodes, which each invoke a 3.x or 4.x function that raises an exception:

mkdir -p /etc/puppetlabs/code/environments/production/modules/raise_error/lib/puppet/functions
mkdir -p /etc/puppetlabs/code/environments/production/modules/raise_error/lib/puppet/parser/functions
 
cat <<'EOS' > /etc/puppetlabs/code/environments/production/modules/raise_error/lib/puppet/functions/raise_error_4x.rb
Puppet::Functions.create_function(:raise_error_4x) do
  def raise_error_4x
    raise 'Boom!'
  end
end
EOS
 
cat <<'EOS' > /etc/puppetlabs/code/environments/production/modules/raise_error/lib/puppet/parser/functions/raise_error_3x.rb
Puppet::Parser::Functions.newfunction(:raise_error_3x) do |args|
  raise 'Bam!'
end
EOS
 
cat <<'EOS' > /etc/puppetlabs/code/environments/production/manifests/raise_error.pp
node '3x.node' {
  raise_error_3x()
}
 
node '4x.node' {
  raise_error_4x()
}
EOS
 
puppet cert generate 3x.node
puppet cert generate 4x.node
 
# Ensure trace is enabled
puppet config set --section master trace true

  • Run puppet agent -t --certname 3x.node and puppet agent -t --certname 4x.node and inspect the Puppet Server logs.

Outcome

Puppet Server logs no Ruby backtraces for either exception:

# /opt/puppetlabs/server/bin/puppetserver foreground
OpenJDK 64-Bit Server VM warning: ignoring option MaxPermSize=96m; support was removed in 8.0
OpenJDK 64-Bit Server VM warning: ignoring option PermSize=64m; support was removed in 8.0
2016-04-19 17:06:38,178 INFO  [main] [o.e.j.u.log] Logging initialized @10291ms
2016-04-19 17:06:41,277 INFO  [async-dispatch-2] [p.t.s.w.jetty9-service] Initializing web server(s).
 
...
 
2016-04-19 17:07:39,986 INFO  [qtp346289202-19] [puppet-server] Puppet Caching node for 3x.node
2016-04-19 17:07:40,297 INFO  [qtp346289202-20] [puppet-server] mount[pe_packages] allowing * access
2016-04-19 17:07:40,297 INFO  [qtp346289202-20] [puppet-server] mount[pe_modules] allowing * access
2016-04-19 17:07:41,651 INFO  [qtp346289202-20] [puppet-server] Puppet 'replace_facts' command for 3x.node submitted to PuppetDB with UUID af512dcd-4a3e-4173-8ec9-89dfa9b78568
2016-04-19 17:07:42,024 INFO  [qtp346289202-20] [puppet-server] Puppet Caching node for 3x.node
2016-04-19 17:07:42,195 ERROR [qtp346289202-20] [puppet-server] Puppet Evaluation Error: Error while evaluating a Function Call, Bam!
2016-04-19 17:07:42,197 ERROR [qtp346289202-20] [puppet-server] Puppet Evaluation Error: Error while evaluating a Function Call, Bam! at /etc/puppetlabs/code/environments/production/manifests/raise_error.pp:2:3 on node 3x.node
2016-04-19 17:07:42,197 ERROR [qtp346289202-20] [puppet-server] Puppet Evaluation Error: Error while evaluating a Function Call, Bam!
2016-04-19 17:07:42,389 INFO  [qtp346289202-21] [puppet-server] Puppet 'store_report' command for 3x.node submitted to PuppetDB with UUID 2de1c5b3-f459-45d8-a0c0-d03b9fe58e55
 
2016-04-19 17:07:46,745 INFO  [qtp346289202-19] [puppet-server] Puppet Caching node for 4x.node
2016-04-19 17:07:47,697 INFO  [qtp346289202-22] [puppet-server] Puppet 'replace_facts' command for 4x.node submitted to PuppetDB with UUID 7c2b8d1c-1ad6-4a8c-ab03-af7f61d3aaf5
2016-04-19 17:07:47,991 INFO  [qtp346289202-22] [puppet-server] Puppet Caching node for 4x.node
2016-04-19 17:07:48,049 ERROR [qtp346289202-22] [puppet-server] Puppet Evaluation Error: Error while evaluating a Function Call, Boom!
2016-04-19 17:07:48,049 ERROR [qtp346289202-22] [puppet-server] Puppet Evaluation Error: Error while evaluating a Function Call, Boom! at /etc/puppetlabs/code/environments/production/manifests/raise_error.pp:6:3 on node 4x.node
2016-04-19 17:07:48,049 ERROR [qtp346289202-22] [puppet-server] Puppet Evaluation Error: Error while evaluating a Function Call, Boom!
2016-04-19 17:07:48,091 INFO  [qtp346289202-23] [puppet-server] Puppet 'store_report' command for 4x.node submitted to PuppetDB with UUID 5b7bc240-f10b-4e6b-95c9-adb23cb8c98b

Expected Outcome

Puppet Server logs Ruby backtraces at ERROR level like Rack-based puppet masters:

# /opt/puppetlabs/puppet/bin/puppet master --no-daemonize
Warning: The WEBrick Puppet master server is deprecated and will be removed in a future release. Please use Puppet Server instead. See http://links.puppetlabs.com/deprecate-rack-webrick-servers for more information.
   (at /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application/master.rb:210:in `main'; /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application/master.rb:165:in `run_command'; /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application.rb:344:in `block in run'; /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:540:in `exit_on_fail'; /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application.rb:344:in `run'; /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/command_line.rb:128:in `run'; /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/command_line.rb:72:in `execute'; /opt/puppetlabs/puppet/bin/puppet:5:in `<main>')
Notice: Starting Puppet master version 4.4.2
 
 
Error: Evaluation Error: Error while evaluating a Function Call, Bam! at /etc/puppetlabs/code/environments/production/manifests/raise_error.pp:2:3 on node 3x.node
/etc/puppetlabs/code/environments/production/modules/raise_error/lib/puppet/parser/functions/raise_error_3x.rb:2:in `block in <top (required)>'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/functions.rb:174:in `block (2 levels) in newfunction'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler/around_profiler.rb:58:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler.rb:51:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/functions.rb:167:in `block in newfunction'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/runtime3_support.rb:281:in `call_function'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:873:in `call_function_with_block'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:853:in `eval_CallNamedFunctionExpression'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/visitor.rb:46:in `block in visit_this'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/visitor.rb:42:in `each'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/visitor.rb:42:in `visit_this'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/visitor.rb:69:in `visit_this_1'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:77:in `evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:589:in `block in eval_BlockExpression'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:589:in `each'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:589:in `eval_BlockExpression'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/visitor.rb:67:in `visit_this_1'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:77:in `evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/parser/evaluating_parser.rb:63:in `evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/ast/pops_bridge.rb:32:in `evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/ast.rb:31:in `safeevaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/resource/type.rb:182:in `evaluate_code'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/resource.rb:84:in `block in evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler/around_profiler.rb:58:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler.rb:51:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/resource.rb:76:in `evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:559:in `evaluate_ast_node'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:183:in `block (2 levels) in compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler/around_profiler.rb:58:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler.rb:51:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:183:in `block in compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/context.rb:65:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet.rb:240:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:167:in `compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:35:in `compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/indirector/catalog/compiler.rb:265:in `block (2 levels) in compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler/around_profiler.rb:58:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler.rb:51:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/indirector/catalog/compiler.rb:263:in `block in compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:223:in `block in benchmark'
/opt/puppetlabs/puppet/lib/ruby/2.1.0/benchmark.rb:294:in `realtime'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:222:in `benchmark'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/indirector/catalog/compiler.rb:261:in `compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/indirector/catalog/compiler.rb:53:in `find'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/indirector/indirection.rb:194:in `find'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/api/indirected_routes.rb:134:in `do_find'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/api/indirected_routes.rb:48:in `block in call'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/context.rb:65:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet.rb:240:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/api/indirected_routes.rb:47:in `call'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/route.rb:82:in `block in process'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/route.rb:81:in `each'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/route.rb:81:in `process'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/route.rb:87:in `process'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/route.rb:87:in `process'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/handler.rb:60:in `block in process'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler/around_profiler.rb:58:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler.rb:51:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/handler.rb:58:in `process'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/webrick/rest.rb:49:in `block in service'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/webrick/rest.rb:48:in `synchronize'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/webrick/rest.rb:48:in `service'
/opt/puppetlabs/puppet/lib/ruby/2.1.0/webrick/httpserver.rb:138:in `service'
/opt/puppetlabs/puppet/lib/ruby/2.1.0/webrick/httpserver.rb:94:in `run'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/webrick.rb:33:in `block (2 levels) in listen'
/opt/puppetlabs/puppet/lib/ruby/2.1.0/webrick/server.rb:295:in `call'
/opt/puppetlabs/puppet/lib/ruby/2.1.0/webrick/server.rb:295:in `block in start_thread'
Error: Evaluation Error: Error while evaluating a Function Call, Bam! at /etc/puppetlabs/code/environments/production/manifests/raise_error.pp:2:3 on node 3x.node
Error: Evaluation Error: Error while evaluating a Function Call, Bam! at /etc/puppetlabs/code/environments/production/manifests/raise_error.pp:2:3 on node 3x.node
/etc/puppetlabs/code/environments/production/modules/raise_error/lib/puppet/parser/functions/raise_error_3x.rb:2:in `block in <top (required)>'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/functions.rb:174:in `block (2 levels) in newfunction'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler/around_profiler.rb:58:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler.rb:51:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/functions.rb:167:in `block in newfunction'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/runtime3_support.rb:281:in `call_function'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:873:in `call_function_with_block'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:853:in `eval_CallNamedFunctionExpression'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/visitor.rb:46:in `block in visit_this'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/visitor.rb:42:in `each'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/visitor.rb:42:in `visit_this'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/visitor.rb:69:in `visit_this_1'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:77:in `evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:589:in `block in eval_BlockExpression'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:589:in `each'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:589:in `eval_BlockExpression'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/visitor.rb:67:in `visit_this_1'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:77:in `evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/parser/evaluating_parser.rb:63:in `evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/ast/pops_bridge.rb:32:in `evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/ast.rb:31:in `safeevaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/resource/type.rb:182:in `evaluate_code'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/resource.rb:84:in `block in evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler/around_profiler.rb:58:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler.rb:51:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/resource.rb:76:in `evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:559:in `evaluate_ast_node'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:183:in `block (2 levels) in compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler/around_profiler.rb:58:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler.rb:51:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:183:in `block in compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/context.rb:65:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet.rb:240:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:167:in `compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:35:in `compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/indirector/catalog/compiler.rb:265:in `block (2 levels) in compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler/around_profiler.rb:58:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler.rb:51:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/indirector/catalog/compiler.rb:263:in `block in compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:223:in `block in benchmark'
/opt/puppetlabs/puppet/lib/ruby/2.1.0/benchmark.rb:294:in `realtime'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:222:in `benchmark'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/indirector/catalog/compiler.rb:261:in `compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/indirector/catalog/compiler.rb:53:in `find'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/indirector/indirection.rb:194:in `find'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/api/indirected_routes.rb:134:in `do_find'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/api/indirected_routes.rb:48:in `block in call'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/context.rb:65:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet.rb:240:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/api/indirected_routes.rb:47:in `call'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/route.rb:82:in `block in process'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/route.rb:81:in `each'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/route.rb:81:in `process'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/route.rb:87:in `process'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/route.rb:87:in `process'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/handler.rb:60:in `block in process'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler/around_profiler.rb:58:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler.rb:51:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/handler.rb:58:in `process'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/webrick/rest.rb:49:in `block in service'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/webrick/rest.rb:48:in `synchronize'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/webrick/rest.rb:48:in `service'
/opt/puppetlabs/puppet/lib/ruby/2.1.0/webrick/httpserver.rb:138:in `service'
/opt/puppetlabs/puppet/lib/ruby/2.1.0/webrick/httpserver.rb:94:in `run'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/webrick.rb:33:in `block (2 levels) in listen'
/opt/puppetlabs/puppet/lib/ruby/2.1.0/webrick/server.rb:295:in `call'
/opt/puppetlabs/puppet/lib/ruby/2.1.0/webrick/server.rb:295:in `block in start_thread'
 
 
Error: Evaluation Error: Error while evaluating a Function Call, Boom! at /etc/puppetlabs/code/environments/production/manifests/raise_error.pp:6:3 on node 4x.node
/etc/puppetlabs/code/environments/production/modules/raise_error/lib/puppet/functions/raise_error_4x.rb:3:in `raise_error_4x'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/functions/dispatch.rb:45:in `invoke'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/functions/dispatcher.rb:35:in `dispatch'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/functions/function.rb:44:in `call'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/runtime3_support.rb:272:in `block in call_function'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler/around_profiler.rb:58:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler.rb:51:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/runtime3_support.rb:271:in `call_function'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:873:in `call_function_with_block'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:853:in `eval_CallNamedFunctionExpression'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/visitor.rb:67:in `visit_this_1'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:77:in `evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:589:in `block in eval_BlockExpression'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:589:in `each'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:589:in `eval_BlockExpression'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/visitor.rb:67:in `visit_this_1'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:77:in `evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/parser/evaluating_parser.rb:63:in `evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/ast/pops_bridge.rb:32:in `evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/ast.rb:31:in `safeevaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/resource/type.rb:182:in `evaluate_code'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/resource.rb:84:in `block in evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler/around_profiler.rb:58:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler.rb:51:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/resource.rb:76:in `evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:559:in `evaluate_ast_node'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:183:in `block (2 levels) in compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler/around_profiler.rb:58:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler.rb:51:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:183:in `block in compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/context.rb:65:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet.rb:240:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:167:in `compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:35:in `compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/indirector/catalog/compiler.rb:265:in `block (2 levels) in compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler/around_profiler.rb:58:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler.rb:51:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/indirector/catalog/compiler.rb:263:in `block in compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:223:in `block in benchmark'
/opt/puppetlabs/puppet/lib/ruby/2.1.0/benchmark.rb:294:in `realtime'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:222:in `benchmark'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/indirector/catalog/compiler.rb:261:in `compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/indirector/catalog/compiler.rb:53:in `find'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/indirector/indirection.rb:194:in `find'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/api/indirected_routes.rb:134:in `do_find'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/api/indirected_routes.rb:48:in `block in call'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/context.rb:65:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet.rb:240:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/api/indirected_routes.rb:47:in `call'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/route.rb:82:in `block in process'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/route.rb:81:in `each'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/route.rb:81:in `process'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/route.rb:87:in `process'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/route.rb:87:in `process'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/handler.rb:60:in `block in process'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler/around_profiler.rb:58:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler.rb:51:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/handler.rb:58:in `process'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/webrick/rest.rb:49:in `block in service'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/webrick/rest.rb:48:in `synchronize'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/webrick/rest.rb:48:in `service'
/opt/puppetlabs/puppet/lib/ruby/2.1.0/webrick/httpserver.rb:138:in `service'
/opt/puppetlabs/puppet/lib/ruby/2.1.0/webrick/httpserver.rb:94:in `run'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/webrick.rb:33:in `block (2 levels) in listen'
/opt/puppetlabs/puppet/lib/ruby/2.1.0/webrick/server.rb:295:in `call'
/opt/puppetlabs/puppet/lib/ruby/2.1.0/webrick/server.rb:295:in `block in start_thread'
Error: Evaluation Error: Error while evaluating a Function Call, Boom! at /etc/puppetlabs/code/environments/production/manifests/raise_error.pp:6:3 on node 4x.node
Error: Evaluation Error: Error while evaluating a Function Call, Boom! at /etc/puppetlabs/code/environments/production/manifests/raise_error.pp:6:3 on node 4x.node
/etc/puppetlabs/code/environments/production/modules/raise_error/lib/puppet/functions/raise_error_4x.rb:3:in `raise_error_4x'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/functions/dispatch.rb:45:in `invoke'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/functions/dispatcher.rb:35:in `dispatch'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/functions/function.rb:44:in `call'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/runtime3_support.rb:272:in `block in call_function'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler/around_profiler.rb:58:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler.rb:51:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/runtime3_support.rb:271:in `call_function'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:873:in `call_function_with_block'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:853:in `eval_CallNamedFunctionExpression'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/visitor.rb:67:in `visit_this_1'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:77:in `evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:589:in `block in eval_BlockExpression'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:589:in `each'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:589:in `eval_BlockExpression'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/visitor.rb:67:in `visit_this_1'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:77:in `evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/parser/evaluating_parser.rb:63:in `evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/ast/pops_bridge.rb:32:in `evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/ast.rb:31:in `safeevaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/resource/type.rb:182:in `evaluate_code'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/resource.rb:84:in `block in evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler/around_profiler.rb:58:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler.rb:51:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/resource.rb:76:in `evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:559:in `evaluate_ast_node'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:183:in `block (2 levels) in compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler/around_profiler.rb:58:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler.rb:51:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:183:in `block in compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/context.rb:65:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet.rb:240:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:167:in `compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:35:in `compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/indirector/catalog/compiler.rb:265:in `block (2 levels) in compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler/around_profiler.rb:58:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler.rb:51:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/indirector/catalog/compiler.rb:263:in `block in compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:223:in `block in benchmark'
/opt/puppetlabs/puppet/lib/ruby/2.1.0/benchmark.rb:294:in `realtime'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:222:in `benchmark'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/indirector/catalog/compiler.rb:261:in `compile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/indirector/catalog/compiler.rb:53:in `find'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/indirector/indirection.rb:194:in `find'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/api/indirected_routes.rb:134:in `do_find'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/api/indirected_routes.rb:48:in `block in call'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/context.rb:65:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet.rb:240:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/api/indirected_routes.rb:47:in `call'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/route.rb:82:in `block in process'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/route.rb:81:in `each'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/route.rb:81:in `process'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/route.rb:87:in `process'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/route.rb:87:in `process'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/handler.rb:60:in `block in process'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler/around_profiler.rb:58:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/profiler.rb:51:in `profile'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/handler.rb:58:in `process'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/webrick/rest.rb:49:in `block in service'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/webrick/rest.rb:48:in `synchronize'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/webrick/rest.rb:48:in `service'
/opt/puppetlabs/puppet/lib/ruby/2.1.0/webrick/httpserver.rb:138:in `service'
/opt/puppetlabs/puppet/lib/ruby/2.1.0/webrick/httpserver.rb:94:in `run'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/webrick.rb:33:in `block (2 levels) in listen'
/opt/puppetlabs/puppet/lib/ruby/2.1.0/webrick/server.rb:295:in `call'
/opt/puppetlabs/puppet/lib/ruby/2.1.0/webrick/server.rb:295:in `block in start_thread'



 Comments   
Comment by Chris Price [ 2016/04/28 ]

This seems pretty bad, and seems like it shouldn't be hard to fix. We should bring it in and have someone look at it in the next sprint.

Comment by Chris Price [ 2016/05/05 ]

I suspect that this has something to do with this commit:

https://github.com/puppetlabs/puppet/commit/6debe89bd935d56e2ec424900ad6f573bbf45552

In that commit, it looks like it becomes critical to call `to_s` on the log object, rather than just `message`. The syslog destination was already calling `to_s`, which probably explains why it works there. The Puppet Server logback destination does not do this, so it may be a matter of just changing that. Will try it shortly.

FYI, though, it looks like some of the other ruby destinations do not call `to_s`, so if it is important for this stuff to be surfaced in non-syslog destinations, we will probably need to audit / fix the other destinations as well. Treating that as out-of-scope for this ticket for the moment.

Comment by Chris Price [ 2016/05/05 ]

Confirmed that calling `to_s` in the puppetserver log destination seems to fix this.

Generated at Tue Jan 28 07:48:35 PST 2020 using JIRA 7.7.1#77002-sha1:e75ca93d5574d9409c0630b81c894d9065296414.