2.4.3 causes issue with 'apt-get update' not being run before build-essential gets processed during chef-client run

solarce commented 10 years ago

In a chef-client run of my wrapper cookbook, 2.4.3 was causing build-essential to error out during the catalog compilation with the error below.

I'm not entirely sure why, but I found a fix.

[2014-09-03T01:28:06+00:00] INFO: Run List is [recipe[lookout-zk::default]]
18:28:06            [2014-09-03T01:28:06+00:00] INFO: Run List expands to [lookout-zk::default]
18:28:06            [2014-09-03T01:28:06+00:00] INFO: Starting Chef Run for lookout-zk-bburton-0
18:28:06            [2014-09-03T01:28:06+00:00] INFO: Running start handlers
18:28:06            [2014-09-03T01:28:06+00:00] INFO: Start handlers complete.
18:28:07            [2014-09-03T01:28:07+00:00] INFO: HTTP Request Returned 404 Object Not Found:
18:28:07            [2014-09-03T01:28:07+00:00] INFO: Loading cookbooks [lookout-zk@0.1.5, users@1.4.0, sudo@2.7.0, apt@2.5.3, java@1.27.0, zookeeper@2.4.3, build-essential@2.0.6, runit@1.5.10, yum@3.2.4, yum-epel@0.4.0, zenoss_client@1.1.3, snmp@3.0.1, openssh@1.3.4, iptables@0.14.0, consul@0.4.0, ark@0.9.0, windows@1.34.2, chef_handler@1.1.6, 7-zip@1.0.2, golang@1.3.0, yum-repoforge@0.3.0, hostsfile@2.4.5]
18:28:07            [2014-09-03T01:28:07+00:00] INFO: Storing updated cookbooks/lookout-zk/recipes/default.rb in the cache.
18:28:07            [2014-09-03T01:28:07+00:00] INFO: WindowsPackage light-weight resource already initialized -- overriding!
18:28:08            [2014-09-03T01:28:07+00:00] INFO: Zookeeper light-weight provider already initialized -- overriding!
18:28:08            [2014-09-03T01:28:08+00:00] WARN: Cloning resource attributes for execute[apt-get-update] from prior resource (CHEF-3694)
18:28:08            [2014-09-03T01:28:08+00:00] WARN: Previous execute[apt-get-update]: /var/chef/cache/cookbooks/lookout-zk/recipes/default.rb:11:in `from_file'
18:28:08            [2014-09-03T01:28:08+00:00] WARN: Current execute[apt-get-update]: /var/chef/cache/cookbooks/apt/recipes/default.rb:40:in `from_file'
18:28:08            [2014-09-03T01:28:08+00:00] INFO: Processing package[autoconf] action install (build-essential::_debian line 108)
18:28:08            [2014-09-03T01:28:08+00:00] INFO: Processing package[binutils-doc] action install (build-essential::_debian line 108)
18:28:08            [2014-09-03T01:28:08+00:00] INFO: Processing package[bison] action install (build-essential::_debian line 108)
18:28:08            [2014-09-03T01:28:08+00:00] INFO: Processing package[build-essential] action install (build-essential::_debian line 108)
18:28:09            [0m
18:28:09            ================================================================================[0m
18:28:09            [31mError executing action `install` on resource 'package[build-essential]'[0m
18:28:09            ================================================================================[0m
18:28:09            
18:28:09            [0m
18:28:09            Mixlib::ShellOut::ShellCommandFailed[0m
18:28:09            ------------------------------------[0m
18:28:09            Expected process to exit with [0], but received '100'
18:28:09            ---- Begin output of apt-get -q -y install build-essential=11.5ubuntu2.1 ----
18:28:09            STDOUT: Reading package lists...
18:28:09            Building dependency tree...
18:28:09            Reading state information...
18:28:09            The following extra packages will be installed:
18:28:09            binutils cpp cpp-4.6 dpkg-dev fakeroot g++ g++-4.6 gcc gcc-4.6
18:28:09            libalgorithm-diff-perl libalgorithm-diff-xs-perl libalgorithm-merge-perl
18:28:09            libc-dev-bin libc6-dev libdpkg-perl libgomp1 libmpc2 libmpfr4 libquadmath0
18:28:09            libstdc++6-4.6-dev linux-libc-dev make manpages-dev
18:28:09            Suggested packages:
18:28:09            cpp-doc gcc-4.6-locales debian-keyring g++-multilib g++-4.6-multilib
18:28:09            gcc-4.6-doc libstdc++6-4.6-dbg gcc-multilib automake1.9 libtool flex gdb
18:28:09            gcc-doc gcc-4.6-multilib libmudflap0-4.6-dev libgcc1-dbg libgomp1-dbg
18:28:09            libquadmath0-dbg libmudflap0-dbg binutils-gold glibc-doc libstdc++6-4.6-doc
18:28:09            make-doc
18:28:09            The following NEW packages will be installed:
18:28:09            binutils build-essential cpp cpp-4.6 dpkg-dev fakeroot g++ g++-4.6 gcc
18:28:09            gcc-4.6 libalgorithm-diff-perl libalgorithm-diff-xs-perl
18:28:09            libalgorithm-merge-perl libc-dev-bin libc6-dev libdpkg-perl libgomp1 libmpc2
18:28:09            libmpfr4 libquadmath0 libstdc++6-4.6-dev linux-libc-dev make manpages-dev
18:28:09            0 upgraded, 24 newly installed, 0 to remove and 0 not upgraded.
18:28:09            Need to get 3,893 kB/30.6 MB of archives.
18:28:09            After this operation, 83.9 MB of additional disk space will be used.
18:28:09            Err http://us-west-2.ec2.archive.ubuntu.com/ubuntu/ precise-updates/main libc-dev-bin amd64 2.15-0ubuntu10.6
18:28:09            404 Not Found [IP: 91.189.91.14 80]
18:28:09            Err http://security.ubuntu.com/ubuntu/ precise-security/main libc-dev-bin amd64 2.15-0ubuntu10.6
18:28:09            404 Not Found [IP: 91.189.91.15 80]
18:28:09            Err http://security.ubuntu.com/ubuntu/ precise-security/main linux-libc-dev amd64 3.2.0-67.101
18:28:09            404 Not Found [IP: 91.189.91.15 80]
18:28:09            Err http://security.ubuntu.com/ubuntu/ precise-security/main libc6-dev amd64 2.15-0ubuntu10.6
18:28:09            404 Not Found [IP: 91.189.91.15 80]
18:28:09            STDERR: Failed to fetch http://security.ubuntu.com/ubuntu/pool/main/e/eglibc/libc-dev-bin_2.15-0ubuntu10.6_amd64.deb 404 Not Found [IP: 91.189.91.15 80]
18:28:09            Failed to fetch http://security.ubuntu.com/ubuntu/pool/main/l/linux/linux-libc-dev_3.2.0-67.101_amd64.deb 404 Not Found [IP: 91.189.91.15 80]
18:28:09            Failed to fetch http://security.ubuntu.com/ubuntu/pool/main/e/eglibc/libc6-dev_2.15-0ubuntu10.6_amd64.deb 404 Not Found [IP: 91.189.91.15 80]
18:28:09            E: Unable to fetch some archives, maybe run apt-get update or try with --fix-missing?
18:28:09            ---- End output of apt-get -q -y install build-essential=11.5ubuntu2.1 ----
18:28:09            Ran apt-get -q -y install build-essential=11.5ubuntu2.1 returned 100[0m
18:28:09            
18:28:09            [0m
18:28:09            Cookbook Trace:[0m
18:28:09            ---------------[0m
18:28:09            /var/chef/cache/cookbooks/build-essential/libraries/timing.rb:114:in `block in method_missing'
18:28:09            /var/chef/cache/cookbooks/build-essential/libraries/timing.rb:113:in `each'
18:28:09            /var/chef/cache/cookbooks/build-essential/libraries/timing.rb:113:in `method_missing'
18:28:09            /var/chef/cache/cookbooks/build-essential/recipes/_debian.rb:24:in `block in from_file'
18:28:09            /var/chef/cache/cookbooks/build-essential/libraries/timing.rb:104:in `instance_eval'
18:28:09            /var/chef/cache/cookbooks/build-essential/libraries/timing.rb:104:in `evaluate'
18:28:09            /var/chef/cache/cookbooks/build-essential/libraries/timing.rb:47:in `potentially_at_compile_time'
18:28:09            /var/chef/cache/cookbooks/build-essential/recipes/_debian.rb:20:in `from_file'
18:28:09            /var/chef/cache/cookbooks/build-essential/recipes/default.rb:21:in `from_file'
18:28:09            /var/chef/cache/cookbooks/zookeeper/recipes/install.rb:20:in `from_file'
18:28:09            /var/chef/cache/cookbooks/lookout-zk/recipes/install.rb:10:in `from_file'
18:28:09            /var/chef/cache/cookbooks/lookout-zk/recipes/default.rb:34:in `from_file'[0m

solarce commented 10 years ago

With the commit I just made the chef-client run converges successfully, but understanding what's happening is beyond my chef(ruby)-fu

[2014-09-03T01:35:00+00:00] INFO: Run List is [recipe[lookout-zk::default]]
[2014-09-03T01:35:00+00:00] INFO: Run List expands to [lookout-zk::default]
[2014-09-03T01:35:00+00:00] INFO: Starting Chef Run for lookout-zk-bburton-1
[2014-09-03T01:35:00+00:00] INFO: Running start handlers
[2014-09-03T01:35:00+00:00] INFO: Start handlers complete.
[2014-09-03T01:35:00+00:00] INFO: HTTP Request Returned 404 Object Not Found: 
[2014-09-03T01:35:01+00:00] INFO: Loading cookbooks [lookout-zk@0.1.5, users@1.4.0, sudo@2.7.0, apt@2.5.3, java@1.27.0, zookeeper@2.4.3, build-essential@2.0.6, runit@1.5.10, yum@3.2.4, yum-epel@0.4.0, zenoss_client@1.1.3, snmp@3.0.1, openssh@1.3.4, iptables@0.14.0, consul@0.4.0, ark@0.9.0, windows@1.34.2, chef_handler@1.1.6, 7-zip@1.0.2, golang@1.3.0, yum-repoforge@0.3.0, hostsfile@2.4.5]
[2014-09-03T01:35:01+00:00] INFO: Storing updated cookbooks/lookout-zk/recipes/default.rb in the cache.
[2014-09-03T01:35:01+00:00] INFO: Storing updated cookbooks/zookeeper/recipes/install.rb in the cache.
[2014-09-03T01:35:01+00:00] INFO: Storing updated cookbooks/zookeeper/Berksfile.lock in the cache.
[2014-09-03T01:35:01+00:00] INFO: WindowsPackage light-weight resource already initialized -- overriding!
[2014-09-03T01:35:01+00:00] INFO: Zookeeper light-weight provider already initialized -- overriding!
[2014-09-03T01:35:02+00:00] INFO: Processing package[autoconf] action install (build-essential::_debian line 108)
[2014-09-03T01:35:02+00:00] INFO: Processing package[binutils-doc] action install (build-essential::_debian line 108)
[2014-09-03T01:35:02+00:00] INFO: Processing package[bison] action install (build-essential::_debian line 108)
[2014-09-03T01:35:02+00:00] INFO: Processing package[build-essential] action install (build-essential::_debian line 108)
[2014-09-03T01:35:26+00:00] INFO: Processing package[flex] action install (build-essential::_debian line 108)
[2014-09-03T01:35:29+00:00] INFO: Processing package[gettext] action install (build-essential::_debian line 108)
[2014-09-03T01:35:36+00:00] INFO: Processing package[ncurses-dev] action install (build-essential::_debian line 108)
[2014-09-03T01:35:36+00:00] INFO: package[ncurses-dev] is a virtual package, actually acting on package[libncurses5-dev]
[2014-09-03T01:35:38+00:00] INFO: Processing package[openssh-client] action install (openssh::default line 26)
[2014-09-03T01:35:38+00:00] INFO: Processing package[openssh-server] action install (openssh::default line 26)
[2014-09-03T01:35:38+00:00] INFO: Processing service[ssh] action enable (openssh::default line 32)
[2014-09-03T01:35:38+00:00] INFO: Processing service[ssh] action start (openssh::default line 32)
[2014-09-03T01:35:39+00:00] INFO: Processing template[/etc/ssh/ssh_config] action create (openssh::default line 51)
[2014-09-03T01:35:39+00:00] INFO: Processing template[/etc/ssh/sshd_config] action create (openssh::default line 68)
[2014-09-03T01:35:39+00:00] INFO: Processing execute[apt-get-update] action run (apt::default line 40)
[2014-09-03T01:35:39+00:00] INFO: Processing execute[apt-get update] action nothing (apt::default line 48)
[2014-09-03T01:35:39+00:00] INFO: Processing execute[apt-get autoremove] action nothing (apt::default line 56)
[2014-09-03T01:35:39+00:00] INFO: Processing execute[apt-get autoclean] action nothing (apt::default line 63)
[2014-09-03T01:35:39+00:00] INFO: Processing package[update-notifier-common] action install (apt::default line 70)
[2014-09-03T01:35:39+00:00] INFO: Processing execute[apt-get-update-periodic] action run (apt::default line 75)
[2014-09-03T01:35:44+00:00] INFO: execute[apt-get-update-periodic] ran successfully

solarce commented 10 years ago

Actually, this may not be enough, some other fiddling i was doing may have fixed up apt, still working on it

solarce commented 10 years ago

I'll try to throw up a sample wrapper cookbook that shows the issue in test-kitchen, tomorrow

jakedavis commented 10 years ago

Yo @solarce, I think something else is up here. I got a couple debugging questions:

Does test-kitchen fail in the same way?
What version of the build-essential cookbook are you on?

Additionally, when the run succeeded, had you started on a fresh VM or was this the second run on the original VM?

If this is really blocking you, one mitigation is node.force_override[:'build-essential'][:compile_time] = true in the wrapper cookbook before calling this recipe. This is definitely weird though.

jakedavis commented 10 years ago

One thing that MIGHT be happening here is we need to call include_recipe 'apt::default' beforehand. That might be worth trying. It looks to me like it's just failing the apt lookup, which would make sense perhaps if we never apt-get updated.

solarce commented 10 years ago

Answers first,

1.) I hadn't tried in tk before since our wrapper cookbook is really meant to be deployed with a cluster, so I was testing with internal tools for deploying a three node cluster, that's what the output above is from 2.) build-essential 2.0.6 is what gets pulled in via berks from supermarket 3.) The run that succeed was because I had done a converge with 'zookeeper::install' commented out, so chef did a successful 'apt-get update', when I tried again with a fresh set of hosts it failed, hence comment 4 :)

So I went ahead and made a paired down version of our wrapper cookbook and published it at https://github.com/solarce/zk-wrapper, including a sample of the kitchen.yml file I used

You can see the same failure I was seeing last night in https://gist.github.com/solarce/d286fade3f0ecb1a43e4

jakedavis commented 10 years ago

Ahhhh okay so. Yikes. Here's what's happening:

Chef has a "compile" time and a "converge" time, in that order
At compile time, it sees it should run the apt recipe
However, we also told it it should install build-essential at compile time
Apt-get update is going to run, but not until converge time
Since the apt cache hasn't been updated, the build-essential lookup fails in apt
Chef fails

I'll have to think about this a bit. Worst case, we add:

execute 'apt-get update' do
  action :nothing
end.run_action(:run)

Before the build-essential business. This'll run at compile time and ensure the apt cache is up to date.

solarce commented 10 years ago

The workaround works in my sample wrapper cookbook: https://github.com/solarce/zk-wrapper/commit/b717ceccf9245b7e2da6dc26cb1c42e39e3b7920

I'm testing in our internal wrapper cookbook

solarce commented 10 years ago

It worked with our internal wrapper too

solarce commented 10 years ago

This whole issue brings up a question for me, why is https://github.com/SimpleFinance/chef-zookeeper/blob/2952e5ca842300ae66d4827051f8060969b61c29/recipes/install.rb#L18 set to true anyway?

jakedavis commented 10 years ago

That's a good question actually. It hails all the way back to https://github.com/SimpleFinance/chef-zookeeper/pull/35.

We might be able to remove it.

jeffbyrnes commented 10 years ago

@jakedavis you've got it exactly, what with the apt cookbook needing to be run during the compile phase.

solarce commented 10 years ago

So are we thinking drop the compile time for build-essential?

jakedavis commented 10 years ago

I'd want to see TK output because I'm not entirely convinced it'll Just Work™, but I have no philosophical reasons not to do it. I probably won't have time to get to this this week.

jeffbyrnes commented 9 years ago

There’s a nicer way to get apt-get update to run at compile time, using the apt cookbook:

case node['platform_family']
when 'debian'
  node.set['apt']['compile_time_update'] = true

  include_recipe 'apt'
end

Though hopefully, just including the apt recipe should do the trick, provided its included before build-essential, like so:

case node['platform_family']
when 'debian'
  include_recipe 'apt'
end

include_recipe 'build-essential'

This is a pattern we use all the time, and it works well.

evertrue / zookeeper-cookbook

2.4.3 causes issue with 'apt-get update' not being run before build-essential gets processed during chef-client run #103