Puppet: System Administration Automated

Support

Ticket #1143 (new defect)

Opened 6 months ago

Last modified 5 months ago

Sporadic error messages in puppetmaster log related to undefined method '<' and private method 'split'

Reported by: digant Assigned to: community
Priority: high Milestone: 0.24.4
Component: settings Version: 0.23.2
Severity: normal Keywords:
Cc: Triage Stage: Accepted
Attached Patches: None Complexity: Hard

Description

We had mentioned to Luke that our puppetmaster logs often had weird error messages like 'err: Could not call: private method split' called for nil:NilClass' and 'err: undefined method <' for nil:NilClass' but we had never been able to capture traces. Here is a snapshot from logs of one of our puppetmaster instances spewing some trace information around the time of these errors. Hope this helps. 

info: No messages to report to puppet-reports@lists.stanford.edu
info: Processing reports tagmail, lastcheck, logcache for rhel-afs-test04.stanford.edu
info: No messages to report to puppet-reports@lists.stanford.edu
info: Processing reports tagmail, lastcheck, logcache for webmail-dev.stanford.edu
info: No messages to report to puppet-reports@lists.stanford.edu
notice: mount[dist]: File source /var/lib/puppet/dist/clients/sunet-systems/ntp/ntp.conf.toad does not exist
notice: mount[dist]: File source /var/lib/puppet/dist/clients/sunet-systems/ntp/ntp.conf.netdb-demo does not exist
notice: mount[s_pobox]: File source /var/lib/puppet/services/s_pobox/files/etc/tivoli/nodes.pobox12 does not exist
/usr/lib/ruby/1.8/puppet/module.rb:12:in `modulepath'
info: Processing reports tagmail, lastcheck, logcache for ldap-test3.stanford.edu/usr/lib/ruby/1.8/puppet/module.rb:32:in `find'

/usr/lib/ruby/1.8/puppet/network/handler/fileserver.rb:394:in `splitpath'
/usr/lib/ruby/1.8/puppet/network/handler/fileserver.rb:218:in `convert'
/usr/lib/ruby/1.8/puppet/network/handler/fileserver.rb:40:in `describe'
/usr/lib/ruby/1.8/rubygems/custom_require.rb:27:in `to_proc'
info: No messages to report to puppet-reports@lists.stanford.edu/usr/lib/ruby/1.8/puppet/network/xmlrpc/processor.rb:52:in `call'

/usr/lib/ruby/1.8/puppet/network/xmlrpc/processor.rb:52:in `protect_service'
/usr/lib/ruby/1.8/puppet/network/xmlrpc/processor.rb:85:in `setup_processor'
/usr/lib/ruby/1.8/xmlrpc/server.rb:336:in `call'
/usr/lib/ruby/1.8/xmlrpc/server.rb:336:in `dispatch'
/usr/lib/ruby/1.8/xmlrpc/server.rb:323:in `each'
/usr/lib/ruby/1.8/xmlrpc/server.rb:323:in `dispatch'
/usr/lib/ruby/1.8/xmlrpc/server.rb:366:in `call_method'
/usr/lib/ruby/1.8/xmlrpc/server.rb:378:in `handle'
/usr/lib/ruby/1.8/puppet/network/xmlrpc/processor.rb:44:in `process'
/usr/lib/ruby/1.8/puppet/network/server/mongrel.rb:106:in `process'
/usr/lib/ruby/1.8/mongrel.rb:419:in `start'
/usr/lib/ruby/1.8/puppet/network/server/mongrel.rb:103:in `process'
/usr/lib/ruby/1.8/mongrel.rb:618:in `process_client'
/usr/lib/ruby/1.8/mongrel.rb:617:in `each'
/usr/lib/ruby/1.8/mongrel.rb:617:in `process_client'
/usr/lib/ruby/1.8/mongrel.rb:736:in `run'
/usr/lib/ruby/1.8/mongrel.rb:736:in `initialize'
/usr/lib/ruby/1.8/mongrel.rb:736:in `new'
/usr/lib/ruby/1.8/mongrel.rb:736:in `run'
/usr/lib/ruby/1.8/mongrel.rb:720:in `initialize'
/usr/lib/ruby/1.8/mongrel.rb:720:in `new'
/usr/lib/ruby/1.8/mongrel.rb:720:in `run'
/usr/sbin/puppetmasterd:300
err: Could not call: private method `split' called for nil:NilClass
info: Found smtp-roam2 in /var/lib/puppet/manifests/nodes.pp
notice: Compiled configuration for smtp-roam2.stanford.edu in 54.76 seconds
notice: Reloading files
info: Found ldap-dev1 in /var/lib/puppet/manifests/nodes.pp
info: Autoloaded module s_ldap
info: Autoloaded file s_ldap/slapd_conf from module s_ldap
notice: Compiled configuration for ldap-dev1.stanford.edu in 5.11 seconds
info: Parsed manifest in 30.73 seconds
info: Found inspect2-mgmt in /var/lib/puppet/manifests/nodes.pp
info: Autoloaded module afs
info: Autoloaded module kerberos
info: Autoloaded module nagiosclient
info: Autoloaded module remctl
info: Autoloaded module ntp
info: Autoloaded module os
info: Autoloaded file os from module os
info: Autoloaded file os/debian from module os
info: Autoloaded module postfix
info: Autoloaded module ssh
info: Autoloaded module sysctl
info: Autoloaded module tmpclean
info: Autoloaded module s_nessus
info: Autoloaded module s_nessus
notice: Compiled configuration for inspect2-mgmt.stanford.edu in 34.71 seconds
err: undefined method `<' for nil:NilClass
info: Found www3 in /var/lib/puppet/manifests/nodes.pp
info: Autoloaded module s_www
info: Autoloaded file s_www from module s_www
info: Autoloaded module s_www
info: Autoloaded module apache
info: Autoloaded module webauth
info: Autoloaded file webauth from module webauth
info: Autoloaded module lbcd
info: Autoloaded module chroot
info: Autoloaded file chroot from module chroot
notice: Compiled configuration for www3.stanford.edu in 38.38 seconds
info: Processing reports tagmail, lastcheck, logcache for r7-app2-prod.stanford.edu
info: No messages to report to puppet-reports@lists.stanford.edu
info: Processing reports tagmail, lastcheck, logcache for argus.stanford.edu
info: No messages to report to puppet-reports@lists.stanford.edu
/usr/lib/ruby/1.8/puppet/util/loadedfile.rb:19:in `changed?'
/usr/lib/ruby/1.8/puppet/network/handler/fileserver.rb:246:in `readconfig'
/usr/lib/ruby/1.8/puppet/network/handler/fileserver.rb:214:in `convert'
/usr/lib/ruby/1.8/puppet/network/handler/fileserver.rb:40:in `describe'
/usr/lib/ruby/1.8/rubygems/custom_require.rb:27:in `to_proc'
/usr/lib/ruby/1.8/puppet/network/xmlrpc/processor.rb:52:in `call'
/usr/lib/ruby/1.8/puppet/network/xmlrpc/processor.rb:52:in `protect_service'
/usr/lib/ruby/1.8/puppet/network/xmlrpc/processor.rb:85:in `setup_processor'
/usr/lib/ruby/1.8/xmlrpc/server.rb:336:in `call'
/usr/lib/ruby/1.8/xmlrpc/server.rb:336:in `dispatch'
/usr/lib/ruby/1.8/xmlrpc/server.rb:323:in `each'
/usr/lib/ruby/1.8/xmlrpc/server.rb:323:in `dispatch'
/usr/lib/ruby/1.8/xmlrpc/server.rb:366:in `call_method'
/usr/lib/ruby/1.8/xmlrpc/server.rb:378:in `handle'
/usr/lib/ruby/1.8/puppet/network/xmlrpc/processor.rb:44:in `process'
/usr/lib/ruby/1.8/puppet/network/server/mongrel.rb:106:in `process'
/usr/lib/ruby/1.8/mongrel.rb:419:in `start'
/usr/lib/ruby/1.8/puppet/network/server/mongrel.rb:103:in `process'
/usr/lib/ruby/1.8/mongrel.rb:618:in `process_client'
/usr/lib/ruby/1.8/mongrel.rb:617:in `each'
/usr/lib/ruby/1.8/mongrel.rb:617:in `process_client'
/usr/lib/ruby/1.8/mongrel.rb:736:in `run'
/usr/lib/ruby/1.8/mongrel.rb:736:in `initialize'
/usr/lib/ruby/1.8/mongrel.rb:736:in `new'
/usr/lib/ruby/1.8/mongrel.rb:736:in `run'
/usr/lib/ruby/1.8/mongrel.rb:720:in `initialize'
/usr/lib/ruby/1.8/mongrel.rb:720:in `new'
/usr/lib/ruby/1.8/mongrel.rb:720:in `run'
/usr/sbin/puppetmasterd:300
err: Could not call: undefined method `<' for nil:NilClass
info: Processing reports tagmail, lastcheck, logcache for yen3.stanford.edu
info: No messages to report to puppet-reports@lists.stanford.edu
notice: Reloading files
notice: Reloading files
info: Parsed manifest in 43.68 seconds
info: Parsed manifest in 42.48 seconds
info: Found snsr1 in /var/lib/puppet/manifests/nodes.pp
info: Autoloaded module afs
info: Autoloaded module kerberos
info: Autoloaded module nagiosclient
info: Autoloaded module remctl
info: Autoloaded module ntp
info: Autoloaded module os
info: Autoloaded file os from module os
info: Autoloaded file os/debian from module os
info: Autoloaded module postfix
info: Autoloaded module ssh
info: Autoloaded module sysctl
info: Autoloaded module tmpclean
info: Autoloaded module apache
info: Autoloaded module webauth
info: Autoloaded file webauth from module webauth
notice: Compiled configuration for snsr1.stanford.edu in 1.70 seconds
notice: Denying authenticated client itlab-bc-ldap.stanford.edu(172.26.7.19) access to fileserver.describe
/usr/lib/ruby/1.8/puppet/network/xmlrpc/processor.rb:42:in `process'
/usr/lib/ruby/1.8/puppet/network/server/mongrel.rb:106:in `process'
/usr/lib/ruby/1.8/mongrel.rb:419:in `start'
/usr/lib/ruby/1.8/puppet/network/server/mongrel.rb:103:in `process'
/usr/lib/ruby/1.8/mongrel.rb:618:in `process_client'
/usr/lib/ruby/1.8/mongrel.rb:617:in `each'
/usr/lib/ruby/1.8/mongrel.rb:617:in `process_client'
/usr/lib/ruby/1.8/mongrel.rb:736:in `run'
/usr/lib/ruby/1.8/mongrel.rb:736:in `initialize'
/usr/lib/ruby/1.8/mongrel.rb:736:in `new'
/usr/lib/ruby/1.8/mongrel.rb:736:in `run'
/usr/lib/ruby/1.8/mongrel.rb:720:in `initialize'
/usr/lib/ruby/1.8/mongrel.rb:720:in `new'
/usr/lib/ruby/1.8/mongrel.rb:720:in `run'
/usr/sbin/puppetmasterd:300
notice: mount[dist]: File source /var/lib/puppet/dist/clients/sunet-systems/ntp/ntp.conf.shadow does not exist
/usr/lib/ruby/1.8/puppet/util/loadedfile.rb:19:in `changed?'
/usr/lib/ruby/1.8/puppet/parser/interpreter.rb:595:in `checkfiles'
/usr/lib/ruby/1.8/puppet/util/feature.rb:24:in `find'
/usr/lib/ruby/1.8/puppet/parser/interpreter.rb:595:in `each'
/usr/lib/ruby/1.8/puppet/parser/interpreter.rb:595:in `find'
/usr/lib/ruby/1.8/puppet/parser/interpreter.rb:595:in `checkfiles'
/usr/lib/ruby/1.8/puppet/parser/interpreter.rb:608:in `parsefiles'
/usr/lib/ruby/1.8/puppet/parser/interpreter.rb:543:in `parsedate'
/usr/lib/ruby/1.8/puppet/network/handler/master.rb:80:in `freshness'
/usr/lib/ruby/1.8/rubygems/custom_require.rb:27:in `to_proc'
/usr/lib/ruby/1.8/puppet/network/xmlrpc/processor.rb:52:in `call'
/usr/lib/ruby/1.8/puppet/network/xmlrpc/processor.rb:52:in `protect_service'
/usr/lib/ruby/1.8/puppet/network/xmlrpc/processor.rb:85:in `setup_processor'
/usr/lib/ruby/1.8/xmlrpc/server.rb:336:in `call'
/usr/lib/ruby/1.8/xmlrpc/server.rb:336:in `dispatch'
/usr/lib/ruby/1.8/xmlrpc/server.rb:323:in `each'
/usr/lib/ruby/1.8/xmlrpc/server.rb:323:in `dispatch'
/usr/lib/ruby/1.8/xmlrpc/server.rb:366:in `call_method'
/usr/lib/ruby/1.8/xmlrpc/server.rb:378:in `handle'
/usr/lib/ruby/1.8/puppet/network/xmlrpc/processor.rb:44:in `process'
/usr/lib/ruby/1.8/puppet/network/server/mongrel.rb:106:in `process'
/usr/lib/ruby/1.8/mongrel.rb:419:in `start'
/usr/lib/ruby/1.8/puppet/network/server/mongrel.rb:103:in `process'
/usr/lib/ruby/1.8/mongrel.rb:618:in `process_client'
/usr/lib/ruby/1.8/mongrel.rb:617:in `each'
/usr/lib/ruby/1.8/mongrel.rb:617:in `process_client'
/usr/lib/ruby/1.8/mongrel.rb:736:in `run'
/usr/lib/ruby/1.8/mongrel.rb:736:in `initialize'
/usr/lib/ruby/1.8/mongrel.rb:736:in `new'
/usr/lib/ruby/1.8/mongrel.rb:736:in `run'
/usr/lib/ruby/1.8/mongrel.rb:720:in `initialize'
/usr/lib/ruby/1.8/mongrel.rb:720:in `new'
/usr/lib/ruby/1.8/mongrel.rb:720:in `run'
/usr/sbin/puppetmasterd:300
err: Could not call: undefined method `<' for nil:NilClass
info: Found newsfeed in /var/lib/puppet/manifests/nodes.pp
/usr/lib/ruby/1.8/puppet/util/config.rb:878:in `convert'
/usr/lib/ruby/1.8/puppet/util/config.rb:873:in `gsub'
/usr/lib/ruby/1.8/puppet/util/config.rb:873:in `convert'
/usr/lib/ruby/1.8/puppet/util/config.rb:970:in `value'
/usr/lib/ruby/1.8/puppet/util/config.rb:27:in `[]'
/usr/lib/ruby/1.8/puppet.rb:92:in `[]'
/usr/lib/ruby/1.8/puppet/util/autoload.rb:144:in `searchpath'
/usr/lib/ruby/1.8/puppet/util/autoload.rb:136:in `eachdir'
/usr/lib/ruby/1.8/puppet/util/autoload.rb:71:in `load'
/usr/lib/ruby/1.8/puppet/metatype/manager.rb:119:in `type'
/usr/lib/ruby/1.8/puppet/parser/resource/reference.rb:22:in `builtintype'
/usr/lib/ruby/1.8/puppet/parser/resource/reference.rb:60:in `typeclass'
/usr/lib/ruby/1.8/puppet/parser/resource.rb:233:in `paramcheck'
/usr/lib/ruby/1.8/puppet/parser/resource.rb:263:in `set'
/usr/lib/ruby/1.8/puppet/parser/resource.rb:163:in `initialize'
/usr/lib/ruby/1.8/puppet/parser/resource.rb:161:in `each'
/usr/lib/ruby/1.8/puppet/parser/resource.rb:161:in `initialize'
/usr/lib/ruby/1.8/puppet/parser/ast/resourcedef.rb:100:in `new'
/usr/lib/ruby/1.8/puppet/parser/ast/resourcedef.rb:100:in `evaluate'
/usr/lib/ruby/1.8/puppet/util/errors.rb:25:in `exceptwrap'
/usr/lib/ruby/1.8/puppet/parser/ast/resourcedef.rb:92:in `evaluate'
/usr/lib/ruby/1.8/puppet/parser/ast/resourcedef.rb:91:in `collect'
/usr/lib/ruby/1.8/puppet/parser/ast/resourcedef.rb:91:in `evaluate'
/usr/lib/ruby/1.8/puppet/parser/ast.rb:82:in `safeevaluate'
/usr/lib/ruby/1.8/puppet/parser/ast/astarray.rb:54:in `evaluate'
/usr/lib/ruby/1.8/puppet/parser/ast/astarray.rb:53:in `collect'
/usr/lib/ruby/1.8/puppet/parser/ast/astarray.rb:53:in `evaluate'
/usr/lib/ruby/1.8/puppet/parser/ast/hostclass.rb:57:in `evaluate'
/usr/lib/ruby/1.8/puppet/parser/ast.rb:82:in `safeevaluate'
/usr/lib/ruby/1.8/puppet/parser/scope.rb:194:in `evalclasses'
/usr/lib/ruby/1.8/puppet/parser/scope.rb:192:in `each'
/usr/lib/ruby/1.8/puppet/parser/scope.rb:192:in `evalclasses'
/usr/lib/ruby/1.8/puppet/parser/functions.rb:112:in `function_include'
/usr/lib/ruby/1.8/puppet/parser/ast/function.rb:20:in `send'
/usr/lib/ruby/1.8/puppet/parser/ast/function.rb:20:in `evaluate'
/usr/lib/ruby/1.8/puppet/parser/ast.rb:82:in `safeevaluate'
/usr/lib/ruby/1.8/puppet/parser/ast/astarray.rb:54:in `evaluate'
/usr/lib/ruby/1.8/puppet/parser/ast/astarray.rb:53:in `collect'
/usr/lib/ruby/1.8/puppet/parser/ast/astarray.rb:53:in `evaluate'
/usr/lib/ruby/1.8/puppet/parser/ast/hostclass.rb:57:in `evaluate'
/usr/lib/ruby/1.8/puppet/parser/ast.rb:82:in `safeevaluate'
/usr/lib/ruby/1.8/puppet/parser/scope.rb:194:in `evalclasses'
/usr/lib/ruby/1.8/puppet/parser/scope.rb:192:in `each'
/usr/lib/ruby/1.8/puppet/parser/scope.rb:192:in `evalclasses'
/usr/lib/ruby/1.8/puppet/parser/functions.rb:112:in `function_include'
/usr/lib/ruby/1.8/puppet/parser/ast/function.rb:20:in `send'
/usr/lib/ruby/1.8/puppet/parser/ast/function.rb:20:in `evaluate'
/usr/lib/ruby/1.8/puppet/parser/ast.rb:82:in `safeevaluate'
/usr/lib/ruby/1.8/puppet/parser/ast/astarray.rb:54:in `evaluate'
/usr/lib/ruby/1.8/puppet/parser/ast/astarray.rb:53:in `collect'
/usr/lib/ruby/1.8/puppet/parser/ast/astarray.rb:53:in `evaluate'
/usr/lib/ruby/1.8/puppet/parser/ast.rb:82:in `safeevaluate'
/usr/lib/ruby/1.8/puppet/parser/ast/node.rb:40:in `evaluate'
/usr/lib/ruby/1.8/puppet/parser/ast.rb:82:in `safeevaluate'
/usr/lib/ruby/1.8/puppet/parser/ast/node.rb:23:in `evaluate'
/usr/lib/ruby/1.8/puppet/parser/ast.rb:82:in `safeevaluate'
/usr/lib/ruby/1.8/puppet/parser/interpreter.rb:172:in `evalnode'
/usr/lib/ruby/1.8/puppet/parser/interpreter.rb:202:in `evaluate'
/usr/lib/ruby/1.8/puppet/parser/interpreter.rb:563:in `run'
/usr/lib/ruby/1.8/puppet/network/handler/master.rb:185:in `getconfig'
/usr/lib/ruby/1.8/puppet/util.rb:212:in `benchmark'
/usr/lib/ruby/1.8/benchmark.rb:293:in `measure'
/usr/lib/ruby/1.8/benchmark.rb:307:in `realtime'
/usr/lib/ruby/1.8/puppet/util.rb:211:in `benchmark'
/usr/lib/ruby/1.8/puppet/network/handler/master.rb:183:in `getconfig'
/usr/lib/ruby/1.8/rubygems/custom_require.rb:27:in `to_proc'
/usr/lib/ruby/1.8/puppet/network/xmlrpc/processor.rb:52:in `call'
/usr/lib/ruby/1.8/puppet/network/xmlrpc/processor.rb:52:in `protect_service'
/usr/lib/ruby/1.8/puppet/network/xmlrpc/processor.rb:85:in `setup_processor'
/usr/lib/ruby/1.8/xmlrpc/server.rb:336:in `call'
/usr/lib/ruby/1.8/xmlrpc/server.rb:336:in `dispatch'
/usr/lib/ruby/1.8/xmlrpc/server.rb:323:in `each'
/usr/lib/ruby/1.8/xmlrpc/server.rb:323:in `dispatch'
/usr/lib/ruby/1.8/xmlrpc/server.rb:366:in `call_method'
/usr/lib/ruby/1.8/xmlrpc/server.rb:378:in `handle'
/usr/lib/ruby/1.8/puppet/network/xmlrpc/processor.rb:44:in `process'
/usr/lib/ruby/1.8/puppet/network/server/mongrel.rb:106:in `process'
/usr/lib/ruby/1.8/mongrel.rb:419:in `start'
/usr/lib/ruby/1.8/puppet/network/server/mongrel.rb:103:in `process'
/usr/lib/ruby/1.8/mongrel.rb:618:in `process_client'
/usr/lib/ruby/1.8/mongrel.rb:617:in `each'
/usr/lib/ruby/1.8/mongrel.rb:617:in `process_client'
/usr/lib/ruby/1.8/mongrel.rb:736:in `run'
/usr/lib/ruby/1.8/mongrel.rb:736:in `initialize'
/usr/lib/ruby/1.8/mongrel.rb:736:in `new'
/usr/lib/ruby/1.8/mongrel.rb:736:in `run'
/usr/lib/ruby/1.8/mongrel.rb:720:in `initialize'
/usr/lib/ruby/1.8/mongrel.rb:720:in `new'
/usr/lib/ruby/1.8/mongrel.rb:720:in `run'
/usr/sbin/puppetmasterd:300
err: Could not find value for #<Puppet::Util::Config:0x2ba7dd5703b8> at /var/lib/puppet/modules/remctl/manifests/init.pp:16

Change History

03/20/08 20:06:42 changed by luke

  • priority changed from normal to high.
  • complexity changed from Unknown to Easy.
  • stage changed from Unreviewed to Accepted.
  • milestone set to 0.24.4.

03/21/08 05:13:08 changed by luke

  • complexity changed from Easy to Hard.

These problems all point to missing values in the internal settings. This server is clearly 0.23.2, at the latest, given the existence of the util/config.rb file, but looking through it, I'm still having trouble figuring out how those parameters could ever be set to nil. Even theorizing a race condition when reparsing the configuration file (which seems unlikely given no mention of reparsing in this log), you'd still just get the default value, not nil.

Is there any more information you can give me about this problem, such as maybe frequency on a given machine, how many machines it happens on (is it only the server?), etc?

03/21/08 06:51:46 changed by luke

By the way, is anyone else having this problem?

04/24/08 07:21:55 changed by luke

  • component changed from server to settings.