Jira (PUP-4288) excessive logging of fail()

[garrett honeycutt (JIRA)]

garrett honeycutt created an issue

Puppet / PUP-4288 excessive logging of fail() Issue Type: Bug Affects Versions: PUP 3.7.4 Assignee: Unassigned Created: 2015/03/25 2:00 AM Priority: Normal Reporter: garrett honeycutt When using the fail() function, three extra entries are added to the logs. This code fail('logging fail') Would produce the following. Notice that there are three mentions of the error message along with the path to the offending code. Next we see the agent message and master message. Those initial three messages should not be logged. Mar 25 01:49:44 puppet puppet-agent[22226]: Retrieving pluginfacts Mar 25 01:49:44 puppet puppet-agent[22226]: Retrieving plugin Mar 25 01:49:45 puppet puppet-agent[22226]: Loading facts Mar 25 01:49:46 puppet puppet-master[12428]: logging fail at /etc/puppet/environments/production/modules/logtest/manifests/init.pp:9 on node puppet.learnpuppet.net Mar 25 01:49:46 puppet puppet-master[12428]: logging fail at /etc/puppet/environments/production/modules/logtest/manifests/init.pp:9 on node puppet.learnpuppet.net Mar 25 01:49:46 puppet puppet-master[12428]: logging fail at /etc/puppet/environments/production/modules/logtest/manifests/init.pp:9 on node puppet.learnpuppet.net Mar 25 01:49:46 puppet puppet-agent[22226]: Could not retrieve catalog from remote server: Error 400 on SERVER: logging fail at /etc/puppet/environments/production/modules/logtest/manifests/init.pp:9 on node puppet.learnpuppet.net Mar 25 01:49:46 puppet puppet-agent[22226]: Not using cache on failed catalog Mar 25 01:49:46 puppet puppet-agent[22226]: Could not retrieve catalog; skipping run Mar 25 01:49:46 puppet puppet-master[12428]: (//puppet.learnpuppet.net/Puppet) Could not retrieve catalog from remote server: Error 400 on SERVER: logging fail at /etc/puppet/environments/production/modules/logtest/manifests/init.pp:9 on node puppet.learnpuppet.net Mar 25 01:49:46 puppet puppet-master[12428]: (//puppet.learnpuppet.net/Puppet) Not using cache on failed catalog Mar 25 01:49:46 puppet puppet-master[12428]: (//puppet.learnpuppet.net/Puppet) Could not retrieve catalog; skipping run Add Comment

This message was sent by Atlassian JIRA (v6.3.10#6340-sha1:7ea293a)

[Scott Garman (JIRA)]

Scott Garman updated an issue

Puppet / PUP-4288 excessive logging of fail()

Change By: Scott Garman Labels: triaged

Add Comment

This message was sent by Atlassian JIRA (v6.4.14#64029-sha1:ae256fe)

[Moses Mendoza (JIRA)]

Moses Mendoza updated an issue

Puppet / PUP-4288 excessive logging of fail()

Change By: Moses Mendoza Labels: triaged

Add Comment

[Josh Cooper (JIRA)]

Josh Cooper updated an issue

Puppet / PUP-4288 excessive logging of fail()

Change By: Josh Cooper Team: Server

Add Comment

This message was sent by Atlassian JIRA (v7.7.1#77002-sha1:e75ca93)

[Josh Cooper (JIRA)]

Josh Cooper commented on PUP-4288

Re: excessive logging of fail() I still see this behavior with puppetserver. Put fail in site.pp and puppetserver's log will contain 3 entries relating to the error: 2018-06-26 20:27:03,863 ERROR [qtp1654283200-60] [puppetserver] Puppet Evaluation Error: Error while evaluating a Function Call, whoops (file: /etc/puppetlabs/code/environments/production/manifests/site.pp, line: 1, column: 1) on node foo /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/functions/fail.rb:3:in `real_function_fail' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/functions.rb:174:in `function_fail' /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 `function_fail' /etc/puppetlabs/code/environments/production/manifests/site.pp:1:in `stack' org/jruby/RubyKernel.java:1079:in `eval' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/puppet_stack.rb:33:in `stack' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/runtime3_support.rb:314:in `call_function' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:964:in `call_function_with_block' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:933:in `eval_CallNamedFunctionExpression' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/visitor.rb:48:in `visit_this' org/jruby/RubyArray.java:1613: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:92:in `visit_this_1' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:81:in `evaluate' /etc/puppetlabs/code/environments/production/manifests/site.pp:0:in `stack' org/jruby/RubyKernel.java:1079:in `eval' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/puppet_stack.rb:33:in `stack' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:737:in `eval_Program' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/visitor.rb:48:in `visit_this' org/jruby/RubyArray.java:1613: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:92:in `visit_this_1' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:81: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:125:in `evaluate' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/ast.rb:31:in `safeevaluate' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/ast/block_expression.rb:5:in `evaluate' org/jruby/RubyArray.java:1613:in `each' org/jruby/RubyEnumerable.java:849:in `inject' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/ast/block_expression.rb:5: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:136:in `evaluate_code' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/resource.rb:79: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:71:in `evaluate' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:592:in `evaluate_main' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:166: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:166:in `compile' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/context.rb:65:in `override' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet.rb:260:in `override' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:155: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:303: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:301:in `compile' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:232:in `benchmark' /opt/puppetlabs/server/apps/puppetserver/jruby-1_7.jar!/META-INF/jruby.home/lib/ruby/1.9/benchmark.rb:295:in `realtime' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:231:in `benchmark' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/indirector/catalog/compiler.rb:299:in `compile' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/indirector/catalog/compiler.rb:54:in `find' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/node/environment.rb:449:in `with_text_domain' /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:198:in `find' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/api/indirected_routes.rb:121:in `do_find' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/api/indirected_routes.rb:48:in `call' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/context.rb:65:in `override' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet.rb:260: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 `process' org/jruby/RubyArray.java:1613: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:64: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:62:in `process' file:/opt/puppetlabs/server/apps/puppetserver/puppet-server-release.jar!/puppetserver-lib/puppet/server/master.rb:42:in `handleRequest' Puppet$$Server$$Master_770338556.gen:13:in `handleRequest' request_handler_core.clj:273:in `invoke' jruby_request.clj:48:in `invoke' jruby_request.clj:33:in `invoke' request_handler_service.clj:47:in `handle_request' request_handler.clj:3:in `invoke' request_handler.clj:3:in `invoke' core.clj:2515:in `invoke' ring_middleware.clj:284:in `invoke' core.clj:168:in `invoke' core.clj:211:in `invoke' core.clj:45:in `invoke' core.clj:357:in `invoke' core.clj:51:in `invoke' ringutils.clj:83:in `invoke' master_core.clj:738:in `invoke' ring.cljc:25:in `invoke' ring.cljc:16:in `invoke' comidi.clj:245:in `invoke' http.clj:152:in `invoke' http.clj:152:in `invoke' http.clj:148:in `invoke' comidi.clj:332:in `invoke' jetty9_core.clj:433:in `invoke' normalized_uri_helpers.clj:74:in `invoke' 2018-06-26 20:27:03,863 ERROR [qtp1654283200-60] [puppetserver] Puppet Evaluation Error: Error while evaluating a Function Call, whoops (file: /etc/puppetlabs/code/environments/production/manifests/site.pp, line: 1, column: 1) on node foo 2018-06-26 20:27:03,865 ERROR [qtp1654283200-60] [puppetserver] Puppet Server Error: Evaluation Error: Error while evaluating a Function Call, whoops (file: /etc/puppetlabs/code/environments/production/manifests/site.pp, line: 1, column: 1) on node foo /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/functions/fail.rb:3:in `real_function_fail' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/functions.rb:174:in `function_fail' /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 `function_fail' /etc/puppetlabs/code/environments/production/manifests/site.pp:1:in `stack' org/jruby/RubyKernel.java:1079:in `eval' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/puppet_stack.rb:33:in `stack' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/runtime3_support.rb:314:in `call_function' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:964:in `call_function_with_block' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:933:in `eval_CallNamedFunctionExpression' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/visitor.rb:48:in `visit_this' org/jruby/RubyArray.java:1613: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:92:in `visit_this_1' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:81:in `evaluate' /etc/puppetlabs/code/environments/production/manifests/site.pp:0:in `stack' org/jruby/RubyKernel.java:1079:in `eval' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/puppet_stack.rb:33:in `stack' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:737:in `eval_Program' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/visitor.rb:48:in `visit_this' org/jruby/RubyArray.java:1613: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:92:in `visit_this_1' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/pops/evaluator/evaluator_impl.rb:81: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:125:in `evaluate' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/ast.rb:31:in `safeevaluate' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/ast/block_expression.rb:5:in `evaluate' org/jruby/RubyArray.java:1613:in `each' org/jruby/RubyEnumerable.java:849:in `inject' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/ast/block_expression.rb:5: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:136:in `evaluate_code' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/resource.rb:79: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:71:in `evaluate' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:592:in `evaluate_main' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:166: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:166:in `compile' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/context.rb:65:in `override' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet.rb:260:in `override' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/parser/compiler.rb:155: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:303: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:301:in `compile' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:232:in `benchmark' /opt/puppetlabs/server/apps/puppetserver/jruby-1_7.jar!/META-INF/jruby.home/lib/ruby/1.9/benchmark.rb:295:in `realtime' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:231:in `benchmark' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/indirector/catalog/compiler.rb:299:in `compile' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/indirector/catalog/compiler.rb:54:in `find' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/node/environment.rb:449:in `with_text_domain' /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:198:in `find' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/api/indirected_routes.rb:121:in `do_find' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/network/http/api/indirected_routes.rb:48:in `call' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/context.rb:65:in `override' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet.rb:260: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 `process' org/jruby/RubyArray.java:1613: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:64: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:62:in `process' file:/opt/puppetlabs/server/apps/puppetserver/puppet-server-release.jar!/puppetserver-lib/puppet/server/master.rb:42:in `handleRequest' Puppet$$Server$$Master_770338556.gen:13:in `handleRequest' request_handler_core.clj:273:in `invoke' jruby_request.clj:48:in `invoke' jruby_request.clj:33:in `invoke' request_handler_service.clj:47:in `handle_request' request_handler.clj:3:in `invoke' request_handler.clj:3:in `invoke' core.clj:2515:in `invoke' ring_middleware.clj:284:in `invoke' core.clj:168:in `invoke' core.clj:211:in `invoke' core.clj:45:in `invoke' core.clj:357:in `invoke' core.clj:51:in `invoke' ringutils.clj:83:in `invoke' master_core.clj:738:in `invoke' ring.cljc:25:in `invoke' ring.cljc:16:in `invoke' comidi.clj:245:in `invoke' http.clj:152:in `invoke' http.clj:152:in `invoke' http.clj:148:in `invoke' comidi.clj:332:in `invoke' jetty9_core.clj:433:in `invoke' normalized_uri_helpers.clj:74:in `invoke'

Add Comment

[Josh Cooper (Jira)]

Josh Cooper commented on PUP-4288

Re: excessive logging of fail()

I agree this is ugly and annoying, but we don't have plans on fixing this anytime soon. I'm going to close this, but feel free to reopen if you'd like to submit a pull request or see an easy way to fix this.

Add Comment

This message was sent by Atlassian Jira (v8.13.2#813002-sha1:c495a97)