Bug #12215
Crash in tempfile.rb
| Status: | Closed | Start date: | 01/26/2012 | |
|---|---|---|---|---|
| Priority: | Normal | Due date: | ||
| Assignee: | - | % Done: | 0% |
|
| Category: | - | |||
| Target version: | - | |||
| Affected Puppet version: | 2.7.10 | Branch: | ||
| Keywords: | ||||
| Votes: | 2 |
Description
I was just building new Ubuntu 10.04 servers that have the new version of puppet (2.7.10) from the official apt repo. The master is also 2.7.10.
I’m getting this issue on all 4 of the new servers.
I get this from puppet agent --test --debug:
debug: file_metadata supports formats: b64_zlib_yaml marshal pson raw yaml; using pson
debug: Prefetching parsed resources for ssh_authorized_key
notice: /Stage[main]/Users::Admins/Users::Admin[joe]/Users::Normal[joe]/Ssh_authorized_key[ssh_auth_keys_joe]/user: user changed 'root' to 'joe'
debug: Finishing transaction 70331047200640
info: FileBucket got a duplicate file {md5}4823b62668593982394e5940425f7180
debug: Flushing ssh_authorized_key provider target /home/joe/.ssh/authorized_keys
/usr/lib/ruby/1.8/tempfile.rb:52:in `initialize'
/usr/lib/ruby/1.8/puppet/util/filetype.rb:107:in `new'
/usr/lib/ruby/1.8/puppet/util/filetype.rb:107:in `write'
/usr/lib/ruby/1.8/puppet/util/filetype.rb:56:in `real_write'
/usr/lib/ruby/1.8/puppet/util/filetype.rb:56:in `write'
/usr/lib/ruby/1.8/puppet/provider/parsedfile.rb:95:in `flush_target'
/usr/lib/ruby/1.8/puppet/provider/parsedfile.rb:69:in `flush'
/usr/lib/ruby/1.8/puppet/provider/parsedfile.rb:67:in `each'
/usr/lib/ruby/1.8/puppet/provider/parsedfile.rb:67:in `flush'
/usr/lib/ruby/1.8/puppet/provider/parsedfile.rb:341:in `flush'
/usr/lib/ruby/1.8/puppet/provider/ssh_authorized_key/parsed.rb:65:in `flush'
/usr/lib/ruby/1.8/puppet/util/suidmanager.rb:81:in `asuser'
/usr/lib/ruby/1.8/puppet/provider/ssh_authorized_key/parsed.rb:59:in `flush'
/usr/lib/ruby/1.8/puppet/type.rb:643:in `flush'
/usr/lib/ruby/1.8/puppet/transaction/resource_harness.rb:139:in `evaluate'
/usr/lib/ruby/1.8/puppet/transaction.rb:49:in `apply'
/usr/lib/ruby/1.8/puppet/transaction.rb:84:in `eval_resource'
/usr/lib/ruby/1.8/puppet/transaction.rb:104:in `evaluate'
/usr/lib/ruby/1.8/puppet/util.rb:476:in `thinmark'
/usr/lib/ruby/1.8/benchmark.rb:308:in `realtime'
/usr/lib/ruby/1.8/puppet/util.rb:475:in `thinmark'
/usr/lib/ruby/1.8/puppet/transaction.rb:104:in `evaluate'
/usr/lib/ruby/1.8/puppet/transaction.rb:386:in `traverse'
/usr/lib/ruby/1.8/puppet/transaction.rb:99:in `evaluate'
/usr/lib/ruby/1.8/puppet/resource/catalog.rb:141:in `apply'
/usr/lib/ruby/1.8/puppet/configurer.rb:121:in `retrieve_and_apply_catalog'
/usr/lib/ruby/1.8/puppet/util.rb:180:in `benchmark'
/usr/lib/ruby/1.8/benchmark.rb:308:in `realtime'
/usr/lib/ruby/1.8/puppet/util.rb:179:in `benchmark'
/usr/lib/ruby/1.8/puppet/configurer.rb:120:in `retrieve_and_apply_catalog'
/usr/lib/ruby/1.8/puppet/configurer.rb:151:in `run'
/usr/lib/ruby/1.8/puppet/agent.rb:46
/usr/lib/ruby/1.8/puppet/agent/locker.rb:11:in `lock'
/usr/lib/ruby/1.8/puppet/agent.rb:46
/usr/lib/ruby/1.8/sync.rb:230:in `synchronize'
/usr/lib/ruby/1.8/puppet/agent.rb:46
/usr/lib/ruby/1.8/puppet/agent.rb:110:in `with_client'
/usr/lib/ruby/1.8/puppet/agent.rb:44
/usr/lib/ruby/1.8/puppet/application.rb:172:in `call'
/usr/lib/ruby/1.8/puppet/application.rb:172:in `controlled_run'
/usr/lib/ruby/1.8/puppet/agent.rb:42:in `run'
/usr/lib/ruby/1.8/puppet/application/agent.rb:344:in `onetime'
/usr/lib/ruby/1.8/puppet/application/agent.rb:318:in `run_command'
/usr/lib/ruby/1.8/puppet/application.rb:309:in `run'
/usr/lib/ruby/1.8/puppet/application.rb:413:in `hook'
/usr/lib/ruby/1.8/puppet/application.rb:309:in `run'
/usr/lib/ruby/1.8/puppet/application.rb:404:in `exit_on_fail'
/usr/lib/ruby/1.8/puppet/application.rb:309:in `run'
/usr/lib/ruby/1.8/puppet/util/command_line.rb:69:in `execute'
/usr/bin/puppet:4
err: /Stage[main]/Users::Admins/Users::Admin[joe]/Users::Normal[joe]/Ssh_authorized_key[ssh_auth_keys_joe]: Could not evaluate: Puppet::Util::FileType::FileTypeFlat could not write /home/joe/.ssh/authorized_keys: cannot generate tempfile `/root/puppet20120126-10183-jdezsk-9'
History
Updated by Daniel Pittman 4 months ago
- Status changed from Unreviewed to Needs More Information
Are you running the puppet agent as root?
Can you show the permissions for /root?
Can you check that you have both disk blocks and inodes free for it? (df -h /root ; df -hi /root)
That is pretty low level for something other than a system specific issue, I think, especially since the same code will be used for other users SSH keys.
Updated by Joe Hillenbrand 4 months ago
It’s definitely not a permissions issue or anything specific to the /root directory. The error shows up as whatever the working directory is. That’s just where I happened to be when I ran it that time.
Here are the results anyway:
Filesystem Size Used Avail Use% Mounted on /dev/mapper/a5-root 27G 1.6G 24G 7% / Filesystem Inodes IUsed IFree IUse% Mounted on /dev/mapper/a5-root 1.7M 95K 1.6M 6% /
This also only happens for one of the users. The others keys install just fine.
The issue really makes no sense, and I’ve run out of obvious things to investigate, which is why I reported it as a bug.
What other things can I look at?
Updated by Daniel Pittman 4 months ago
Are you running the agent as a user other than root?
Can you, fun as it is, attach an strace of the process tracking file operations? The failing code is literally Tempfile.new("puppet"), which would put the bug most likely in the core of Ruby, which seems … well, plenty of other code uses that same path, so something odd is happening.
Specifically, I want strace -e trace=file over the agent run that demonstrates the problem.
Updated by Joe Hillenbrand 4 months ago
- Status changed from Needs More Information to Closed
The puppet agent is definitely running as root.
At any rate, I think I’ve solved the issue.
Despite the puppet agent running as root, and it was unable to change the ownership of “/home/joe/.ssh/authorized_keys”.
Manually changing the ownership of file fixed the issue. At least for now.
Thanks for your help.
Updated by Daniel Pittman 4 months ago
Joe Hillenbrand wrote:
The puppet agent is definitely running as root.
At any rate, I think I’ve solved the issue.
Despite the puppet agent running as root, and it was unable to change the ownership of “/home/joe/.ssh/authorized_keys”.
Manually changing the ownership of file fixed the issue. At least for now.
Thanks for your help.
Crazy. I would love to see that strace, if you could, just to better understand what is going on – but if the problem is solved that way, I would suggest having a dig around to see if you have file system corruption or something here. That totally /shouldn’t/ happen.
Updated by Peter Meier 3 months ago
- File strace_output.txt added
- Status changed from Closed to Re-opened
I can reproduce that problem on Debian squeeze, although I’m on 2.6.8 it is exactly the same problem. So here we go:
# cat test.pp
ssh_authorized_key{
'key_for_duritong':
key => 'AAAAB3NzaC1yc2EAAAABxxxxxx+/E+k/+f2z1es+.....',
type => 'ssh-rsa',
user => 'duritong',
}
# whoami
root
# echo $TMP
/tmp
# echo $TMPDIR
/tmp
# dpkg -l | egrep '(puppet|ruby)'
ii libaugeas-ruby1.8 0.3.0-1.1 Augeas bindings for the Ruby language
ii libruby 4.5 Libraries necessary to run Ruby 1.8.x
ii libruby1.8 1.8.7.302-2squeeze1 Libraries necessary to run Ruby 1.8
ii libshadow-ruby1.8 1.4.1-8 Interface of shadow password for Ruby 1.8
ii puppet 2.6.8-1~riseup+1 Centralized configuration management - agent startup and compatibility scripts
ii puppet-common 2.6.8-1~riseup+1 Centralized configuration management
ii ruby 4.5 An interpreter of object-oriented scripting language Ruby
ii ruby1.8 1.8.7.302-2squeeze1 Interpreter of object-oriented scripting language Ruby 1.8
ii ruby1.8-dev 1.8.7.302-2squeeze1 Header files for compiling extension modules for the Ruby 1.8
ii rubygems 1.3.7-3 package management framework for Ruby libraries/applications
ii rubygems1.8 1.3.7-3 package management framework for Ruby libraries/applications
# ls -l /home/duritong/.ssh/ -a
total 8
drwx------ 2 duritong duritong 4096 Feb 8 15:59 .
drwx------ 3 duritong duritong 4096 Feb 8 16:05 ..
# puppet apply --debug --trace test.pp
info: Loading facts in acpi_available
info: Loading facts in ekeyd
info: Loading facts in facter_dot_d
info: Loading facts in concat_basedir
info: Loading facts in mysql_version
info: Loading facts in root_home
info: Loading facts in strongswan_cert
info: Loading facts in mysql_exists
info: Loading facts in virtual_guests_count
info: Loading facts in mountpoints
info: Loading facts in configured_ntp_servers
info: Loading facts in interfaces
info: Loading facts in immerda_vpnip
info: Loading facts in virtual_guests
debug: Failed to load library 'selinux' for feature 'selinux'
debug: Creating default schedules
debug: Puppet::Type::User::ProviderUser_role_add: file roleadd does not exist
debug: Puppet::Type::User::ProviderDirectoryservice: file /usr/bin/dscl does not exist
debug: Puppet::Type::User::ProviderPw: file pw does not exist
debug: Puppet::Type::User::ProviderLdap: true value when expecting false
debug: Puppet::Type::File::ProviderMicrosoft_windows: feature microsoft_windows is missing
debug: Failed to load library 'ldap' for feature 'ldap'
debug: /File[/var/lib/puppet/state/last_run_summary.yaml]: Autorequiring File[/var/lib/puppet/state]
debug: /File[/var/lib/puppet/ssl/certificate_requests]: Autorequiring File[/var/lib/puppet/ssl]
debug: /File[/var/lib/puppet/state/classes.txt]: Autorequiring File[/var/lib/puppet/state]
debug: /File[/var/lib/puppet/facts]: Autorequiring File[/var/lib/puppet]
debug: /File[/var/lib/puppet/ssl]: Autorequiring File[/var/lib/puppet]
debug: /File[/var/lib/puppet/ssl/private]: Autorequiring File[/var/lib/puppet/ssl]
debug: /File[/var/lib/puppet/state/last_run_report.yaml]: Autorequiring File[/var/lib/puppet/state]
debug: /File[/var/lib/puppet/ssl/private_keys/tramp.glei.ch.pem]: Autorequiring File[/var/lib/puppet/ssl/private_keys]
debug: /File[/var/lib/puppet/ssl/public_keys/tramp.glei.ch.pem]: Autorequiring File[/var/lib/puppet/ssl/public_keys]
debug: /File[/var/lib/puppet/lib]: Autorequiring File[/var/lib/puppet]
debug: /File[/var/lib/puppet/state/state.yaml]: Autorequiring File[/var/lib/puppet/state]
debug: /File[/var/lib/puppet/ssl/certs/tramp.glei.ch.pem]: Autorequiring File[/var/lib/puppet/ssl/certs]
debug: /File[/var/lib/puppet/state/graphs]: Autorequiring File[/var/lib/puppet/state]
debug: /File[/var/lib/puppet/client_data]: Autorequiring File[/var/lib/puppet]
debug: /File[/var/lib/puppet/ssl/public_keys]: Autorequiring File[/var/lib/puppet/ssl]
debug: /File[/var/lib/puppet/ssl/certs/ca.pem]: Autorequiring File[/var/lib/puppet/ssl/certs]
debug: /File[/var/lib/puppet/clientbucket]: Autorequiring File[/var/lib/puppet]
debug: /File[/var/lib/puppet/ssl/private_keys]: Autorequiring File[/var/lib/puppet/ssl]
debug: /File[/var/lib/puppet/state]: Autorequiring File[/var/lib/puppet]
debug: /File[/var/lib/puppet/ssl/crl.pem]: Autorequiring File[/var/lib/puppet/ssl]
debug: /File[/var/lib/puppet/ssl/certs]: Autorequiring File[/var/lib/puppet/ssl]
debug: /File[/var/lib/puppet/client_yaml]: Autorequiring File[/var/lib/puppet]
debug: Finishing transaction -614169798
debug: Loaded state in 0.35 seconds
debug: Loaded state in 0.35 seconds
debug: Prefetching parsed resources for ssh_authorized_key
info: Applying configuration version '1328716938'
notice: /Stage[main]//Ssh_authorized_key[key_for_duritong]/ensure: created
debug: Flushing ssh_authorized_key provider target /home/duritong/.ssh/authorized_keys
/usr/lib/ruby/1.8/tempfile.rb:52:in `initialize'
/usr/lib/ruby/1.8/puppet/util/filetype.rb:107:in `new'
/usr/lib/ruby/1.8/puppet/util/filetype.rb:107:in `write'
/usr/lib/ruby/1.8/puppet/util/filetype.rb:56:in `real_write'
/usr/lib/ruby/1.8/puppet/util/filetype.rb:56:in `write'
/usr/lib/ruby/1.8/puppet/provider/parsedfile.rb:95:in `flush_target'
/usr/lib/ruby/1.8/puppet/provider/parsedfile.rb:69:in `flush'
/usr/lib/ruby/1.8/puppet/provider/parsedfile.rb:67:in `each'
/usr/lib/ruby/1.8/puppet/provider/parsedfile.rb:67:in `flush'
/usr/lib/ruby/1.8/puppet/provider/parsedfile.rb:341:in `flush'
/usr/lib/ruby/1.8/puppet/provider/ssh_authorized_key/parsed.rb:71:in `flush'
/usr/lib/ruby/1.8/puppet/util/suidmanager.rb:62:in `asuser'
/usr/lib/ruby/1.8/puppet/provider/ssh_authorized_key/parsed.rb:65:in `flush'
/usr/lib/ruby/1.8/puppet/type.rb:636:in `flush'
/usr/lib/ruby/1.8/puppet/transaction/resource_harness.rb:139:in `evaluate'
/usr/lib/ruby/1.8/puppet/transaction.rb:48:in `apply'
/usr/lib/ruby/1.8/puppet/transaction.rb:113:in `eval_children_and_apply_resource'
/usr/lib/ruby/1.8/puppet/transaction.rb:91:in `eval_resource'
/usr/lib/ruby/1.8/puppet/transaction.rb:142:in `evaluate'
/usr/lib/ruby/1.8/puppet/util.rb:429:in `thinmark'
/usr/lib/ruby/1.8/benchmark.rb:308:in `realtime'
/usr/lib/ruby/1.8/puppet/util.rb:428:in `thinmark'
/usr/lib/ruby/1.8/puppet/transaction.rb:141:in `evaluate'
/usr/lib/ruby/1.8/puppet/transaction.rb:134:in `each'
/usr/lib/ruby/1.8/puppet/transaction.rb:134:in `evaluate'
/usr/lib/ruby/1.8/puppet/resource/catalog.rb:144:in `apply'
/usr/lib/ruby/1.8/puppet/configurer.rb:150:in `run'
/usr/lib/ruby/1.8/puppet/util.rb:193:in `benchmark'
/usr/lib/ruby/1.8/benchmark.rb:308:in `realtime'
/usr/lib/ruby/1.8/puppet/util.rb:192:in `benchmark'
/usr/lib/ruby/1.8/puppet/configurer.rb:149:in `run'
/usr/lib/ruby/1.8/puppet/application/apply.rb:126:in `main'
/usr/lib/ruby/1.8/puppet/application/apply.rb:35:in `run_command'
/usr/lib/ruby/1.8/puppet/application.rb:305:in `run'
/usr/lib/ruby/1.8/puppet/application.rb:420:in `hook'
/usr/lib/ruby/1.8/puppet/application.rb:305:in `run'
/usr/lib/ruby/1.8/puppet/application.rb:411:in `exit_on_fail'
/usr/lib/ruby/1.8/puppet/application.rb:305:in `run'
/usr/lib/ruby/1.8/puppet/util/command_line.rb:62:in `execute'
/usr/bin/puppet:4
/usr/lib/ruby/1.8/puppet/util/filetype.rb:63:in `write'
/usr/lib/ruby/1.8/puppet/provider/parsedfile.rb:95:in `flush_target'
/usr/lib/ruby/1.8/puppet/provider/parsedfile.rb:69:in `flush'
/usr/lib/ruby/1.8/puppet/provider/parsedfile.rb:67:in `each'
/usr/lib/ruby/1.8/puppet/provider/parsedfile.rb:67:in `flush'
/usr/lib/ruby/1.8/puppet/provider/parsedfile.rb:341:in `flush'
/usr/lib/ruby/1.8/puppet/provider/ssh_authorized_key/parsed.rb:71:in `flush'
/usr/lib/ruby/1.8/puppet/util/suidmanager.rb:62:in `asuser'
/usr/lib/ruby/1.8/puppet/provider/ssh_authorized_key/parsed.rb:65:in `flush'
/usr/lib/ruby/1.8/puppet/type.rb:636:in `flush'
/usr/lib/ruby/1.8/puppet/transaction/resource_harness.rb:139:in `evaluate'
/usr/lib/ruby/1.8/puppet/transaction.rb:48:in `apply'
/usr/lib/ruby/1.8/puppet/transaction.rb:113:in `eval_children_and_apply_resource'
/usr/lib/ruby/1.8/puppet/transaction.rb:91:in `eval_resource'
/usr/lib/ruby/1.8/puppet/transaction.rb:142:in `evaluate'
/usr/lib/ruby/1.8/puppet/util.rb:429:in `thinmark'
/usr/lib/ruby/1.8/benchmark.rb:308:in `realtime'
/usr/lib/ruby/1.8/puppet/util.rb:428:in `thinmark'
/usr/lib/ruby/1.8/puppet/transaction.rb:141:in `evaluate'
/usr/lib/ruby/1.8/puppet/transaction.rb:134:in `each'
/usr/lib/ruby/1.8/puppet/transaction.rb:134:in `evaluate'
/usr/lib/ruby/1.8/puppet/resource/catalog.rb:144:in `apply'
/usr/lib/ruby/1.8/puppet/configurer.rb:150:in `run'
/usr/lib/ruby/1.8/puppet/util.rb:193:in `benchmark'
/usr/lib/ruby/1.8/benchmark.rb:308:in `realtime'
/usr/lib/ruby/1.8/puppet/util.rb:192:in `benchmark'
/usr/lib/ruby/1.8/puppet/configurer.rb:149:in `run'
/usr/lib/ruby/1.8/puppet/application/apply.rb:126:in `main'
/usr/lib/ruby/1.8/puppet/application/apply.rb:35:in `run_command'
/usr/lib/ruby/1.8/puppet/application.rb:305:in `run'
/usr/lib/ruby/1.8/puppet/application.rb:420:in `hook'
/usr/lib/ruby/1.8/puppet/application.rb:305:in `run'
/usr/lib/ruby/1.8/puppet/application.rb:411:in `exit_on_fail'
/usr/lib/ruby/1.8/puppet/application.rb:305:in `run'
/usr/lib/ruby/1.8/puppet/util/command_line.rb:62:in `execute'
/usr/bin/puppet:4
err: /Stage[main]//Ssh_authorized_key[key_for_duritong]: Could not evaluate: Puppet::Util::FileType::FileTypeFlat could not write /home/duritong/.ssh/authorized_keys: cannot generate tempfile `/root/puppet20120208-11503-1cyrao-9'
debug: Finishing transaction -614876308
debug: Storing state
debug: Stored state in 1.69 seconds
notice: Finished catalog run in 2.17 seconds
I displayed TMP and TMPDIR because Daniel Pitmann mentioned on http://www.puppetlogs.com/puppet/%23puppet-2011-06-02.log.html that they might be a problem related to that, but I get the same problem, either when they are empty or set to /tmp. In both ways puppet anyways tries to write the tmpfile to the directory I’m running puppet from. So if I run puppet from /tmp, they only thing that changes is the path of the tempfile (and obviously its name).
Also nothing changes if I touch the file (with the right permissions.
So, it looks like I can’t be able to workaround the problem… :/
Attached is also an strace run.
Updated by Daniel Pittman 3 months ago
Thanks for the update. It looks like Ruby is trying to create the temporary file in /root in there, and is bypassing the regular temporary directories. We will try and reproduce that with the supplied details.
Updated by Peter Meier 3 months ago
Daniel Pittman wrote:
Thanks for the update. It looks like Ruby is trying to create the temporary file in
/rootin there, and is bypassing the regular temporary directories. We will try and reproduce that with the supplied details.
Note: Ruby will try to create the tmp file in whatever directory I run puppet. So if I run puppet in /tmp it will try to create the tmp file there. And it will fail with the very same error, although the user is able to write to /tmp.
Updated by Peter Meier 3 months ago
Ok a little update, that now makes sense: Unfortunately my /tmp had for some unknown reasons not chmod 1777, which I didn’t see in the first case, so it is quite clear, why it also wasn’t able to write, while being in /tmp, as it would write the tmp file as the target user, which couldn’t write to /root nor /tmp at that time. Changing /tmp to chmod 1777 and running puppet apply from there work.
So what remains is that we have the problem that tempfile is trying to create the temporary files in the current working directory, instead at some more sane place, such as /tmp or the target directory itself. I assume that a lot of people will run from /root, or as cron jobs from /, which makes this quite an ugly issue. I have no idea, what the cwd of the daemon is, but probably not /tmp.
Updated by Joe Hillenbrand 3 months ago
I’ve found the cause and the solution!
It’s a permissions issue on /tmp
On the servers where this was failing, /tmp was set to root:root 755. Running chmod a+rwt /tmp fixes the issue.
EDIT: Sorry, I should have read the comment above before posting this. It’s been a long couple of weeks.
Updated by Daniel Pittman 3 months ago
- Status changed from Re-opened to Closed
Joe Hillenbrand wrote:
I’ve found the cause and the solution! It’s a permissions issue on
/tmp
Awesome. Glad this got tracked down in the end!