[chef] Re: Re: Re: Re: Re: Re: Templates sends notification even when nothing changes

[Arthur Kalmenson < >]

I'm getting closer to figuring this out.

$ diff /var/lib/chef/backup/usr/local/hubot/package.json.chef-20120222132548 package.json

17a18

>     "hubot-irc": ">= 0.0.1",

19c20

<     "hubot-scripts": ">=2.0.4",

---

>     "hubot-scripts": "2.0.5",

23d23

<

So it looks like what's happening is each time the script runs, it overwrites the existing files (the ones that the template applies) with the default ones in the tarball. But, the bash block explicitly doesn't execute if the current version is there.

bash "install hubot" do

  user hubot_user

  group hubot_group

  environment ({'HOME' => "#{install_dir}" })

  cwd install_dir_parent

  code <<-EOH

    tar xzf /tmp/hubot-#{version}.tar.gz && \

    cd hubot && \

    npm install

  EOH

  not_if "#{install_dir}/bin/hubot -v 2>&1 | grep '#{version}'"

end

I tried to remove a file, and after running chef-client, it's back. How is Chef doing this? It looks like it's doing partial parts of the bash block.

The -l debug output looks like this:

[Wed, 22 Feb 2012 13:53:25 -0500] INFO: Processing remote_file[/tmp/hubot-2.1.3.tar.gz] action create_if_missing (hubot:

:default line 45)

[Wed, 22 Feb 2012 13:53:25 -0500] DEBUG: remote_file[/tmp/hubot-2.1.3.tar.gz] exists, taking no action.

[Wed, 22 Feb 2012 13:53:25 -0500] DEBUG: Processing bash[install hubot] on devchat

[Wed, 22 Feb 2012 13:53:25 -0500] INFO: Processing bash[install hubot] action run (hubot::default line 52)

[Wed, 22 Feb 2012 13:53:25 -0500] DEBUG: sh(/usr/local/hubot/bin/hubot -v 2>&1 | grep '2.1.3')

[Wed, 22 Feb 2012 13:53:26 -0500] INFO: bash[install hubot] sh("bash"  "/tmp/chef-script20120222-31157-1xpyj8g-0")

[Wed, 22 Feb 2012 13:53:26 -0500] INFO: bash[install hubot] ran successfully

[Wed, 22 Feb 2012 13:53:26 -0500] DEBUG: Processing template[/usr/local/hubot/package.json] on devchat

[Wed, 22 Feb 2012 13:53:26 -0500] INFO: Processing template[/usr/local/hubot/package.json] action create (hubot::default line 66)

[Wed, 22 Feb 2012 13:53:26 -0500] DEBUG: Not fetching cookbooks/hubot/templates/default/package.json.erb, as the cache is up to date.

[Wed, 22 Feb 2012 13:53:26 -0500] DEBUG: current checksum: 3316d39b799cfbbac45fb4736a214d08; manifest checksum: 3316d39b799cfbbac45fb4736a214d08)

[Wed, 22 Feb 2012 13:53:26 -0500] DEBUG: Current content's checksum:  bef5e0424347cf48d2db07e8cccc4b0a34dba2d9737062b7190ec74f3663ac3d

[Wed, 22 Feb 2012 13:53:26 -0500] DEBUG: Rendered content's checksum: 5466626ccfdd892963301bab5bc584e7a6329b34329754039104640f7c4ff42d

[Wed, 22 Feb 2012 13:53:26 -0500] INFO: template[/usr/local/hubot/package.json] backed up to /var/lib/chef/backup/usr/local/hubot/package.json.chef-20120222135326

[Wed, 22 Feb 2012 13:53:26 -0500] INFO: template[/usr/local/hubot/package.json] removed backup at /var/lib/chef/backup/./usr/local/hubot/package.json.chef-20120222131830

[Wed, 22 Feb 2012 13:53:26 -0500] INFO: template[/usr/local/hubot/package.json] owner changed to 1001

[Wed, 22 Feb 2012 13:53:26 -0500] INFO: template[/usr/local/hubot/package.json] group changed to 1001

[Wed, 22 Feb 2012 13:53:26 -0500] INFO: template[/usr/local/hubot/package.json] mode changed to 644

[Wed, 22 Feb 2012 13:53:26 -0500] INFO: template[/usr/local/hubot/package.json] updated content

Thanks again everyone for all your help.

--
Arthur Kalmenson

On Wed, Feb 22, 2012 at 1:13 PM, Arthur Kalmenson < "> > wrote:

Hi Adam,

I was thinking that too, but the template doesn't give any indication that it should render different:  https://gist.github.com/1886413 

The only pieces that are replaced is the versions, and those are attributes that don't change.

--
Arthur Kalmenson

On Wed, Feb 22, 2012 at 12:10 PM, Adam Jacob < " target="_blank"> > wrote:

Well, the debug output is also indicating that you have changed the
contents of the file. Are you rendering the JSON in a way that is
consistently formatted, or does it differ slightly every time? (for
example, hash ordering may not be unique).

Adam

On Wed, Feb 22, 2012 at 8:55 AM, Arthur Kalmenson < " target="_blank"> > wrote:
> Hi Jesse,
>
> I don't think the application (hubot) is changing the permission and
> ownership of the package.json file. It seems to stay stable at 0644 and the
> user and group is always hubot.
>
> --
> Arthur Kalmenson
>
>
>
> On Tue, Feb 21, 2012 at 4:49 PM, Jesse Campbell < " target="_blank"> > wrote:
>>
>> One option would be to figure out what owner/group/mode is set by the
>> external application, then have those be what chef defines.
>> I've had lots of success doing that with the puppet manifests that I
>> haven't yet converted, I imagine the same will work for chef.
>>
>> -Jesse
>>
>> On Tue, Feb 21, 2012 at 13:10, Arthur Kalmenson < " target="_blank"> >
>> wrote:
>> > Jesse,
>> >
>> > $ chef-client -v
>> > Chef: 0.10.8
>> >
>> > Daniel,
>> >
>> > It looks like you're right. Sorry, the full logs are below. What do I do
>> > about those chmod and chown changes? Those files are there and there's
>> > no
>> > reason to continue changing the ownership, no?
>> >
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO: Processing group[hubot] action
>> > create (hubot::default line 20)
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO: Processing user[hubot] action
>> > create
>> > (hubot::default line 23)
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO: Processing
>> > directory[/usr/local/hubot] action create (hubot::default line 30)
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO: Processing package[libexpat1]
>> > action
>> > install (hubot::default line 39)
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO: Processing
>> > package[libexpat1-dev]
>> > action install (hubot::default line 39)
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO: Processing
>> > remote_file[/tmp/hubot-2.1.3.tar.gz] action create_if_missing
>> > (hubot::default line 45)
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO: Processing bash[install hubot]
>> > action run (hubot::default line 52)
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO: bash[install hubot] sh("bash"
>> >  "/tmp/chef-script20120221-11973-mu2hna-0")
>> >
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO: bash[install hubot] ran
>> > successfully
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO: Processing
>> > template[/usr/local/hubot/package.json] action create (hubot::default
>> > line
>> > 66)
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO:
>> > template[/usr/local/hubot/package.json] backed up to
>> > /var/lib/chef/backup/usr/local/hubot/package.json.chef-20120221130628
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO:
>> > template[/usr/local/hubot/package.json] removed backup at
>> > /var/lib/chef/backup/./usr/local/hubot/package.json.chef-20120221103932
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO:
>> > template[/usr/local/hubot/package.json] owner changed to 1001
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO:
>> > template[/usr/local/hubot/package.json] group changed to 1001
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO:
>> > template[/usr/local/hubot/package.json] mode changed to 644
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO:
>> > template[/usr/local/hubot/package.json] updated content
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO: Processing
>> > template[/usr/local/hubot/hubot-scripts.json] action create
>> > (hubot::default
>> > line 74)
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO:
>> > template[/usr/local/hubot/hubot-scripts.json] backed up to
>> >
>> > /var/lib/chef/backup/usr/local/hubot/hubot-scripts.json.chef-20120221130628
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO:
>> > template[/usr/local/hubot/hubot-scripts.json] removed backup at
>> >
>> > /var/lib/chef/backup/./usr/local/hubot/hubot-scripts.json.chef-20120221103932
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO:
>> > template[/usr/local/hubot/hubot-scripts.json] owner changed to 1001
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO:
>> > template[/usr/local/hubot/hubot-scripts.json] group changed to 1001
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO:
>> > template[/usr/local/hubot/hubot-scripts.json] mode changed to 644
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO:
>> > template[/usr/local/hubot/hubot-scripts.json] updated content
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO:
>> > template[/usr/local/hubot/hubot-scripts.json] not queuing delayed action
>> > restart on service[hubot] (delayed), as it's already been queued
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO: Processing
>> > template[/usr/local/hubot/bin/hubot-wrapper] action create
>> > (hubot::default
>> > line 82)
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO: Processing
>> > template[/etc/init.d/hubot] action create (hubot::default line 93)
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO: Processing service[hubot] action
>> > enable (hubot::default line 100)
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO: Processing service[hubot] action
>> > start (hubot::default line 100)
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO: Processing package[redis-server]
>> > action install (redis::package line 21)
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO: Processing service[redis] action
>> > start (redis::package line 23)
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO: Processing
>> > template[/etc/redis/redis.conf] action create (redis::package line 30)
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO:
>> > template[/usr/local/hubot/package.json] sending restart action to
>> > service[hubot] (delayed)
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO: Processing service[hubot] action
>> > restart (hubot::default line 100)
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO: service[hubot] restarted
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO: Chef Run complete in 1.55091
>> > seconds
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO: Running report handlers
>> > [Tue, 21 Feb 2012 13:06:28 -0500] INFO: Report handlers complete
>> >
>> >
>> >
>> >
>> > --
>> > Arthur Kalmenson
>> >
>> >
>> >
>> > On Tue, Feb 21, 2012 at 11:46 AM, Daniel DeLeo < " target="_blank"> >
>> > wrote:
>> >>
>> >>
>> >>
>> >> On Tuesday, February 21, 2012 at 7:33 AM, Arthur Kalmenson wrote:
>> >>
>> >> > Hello everyone,
>> >> >
>> >> > I have a template resource that notifies the service to restart. It
>> >> > looks as follows:
>> >> >
>> >> > # apply configurations
>> >> > template "#{install_dir}/package.json" do
>> >> > source "package.json.erb"
>> >> > owner hubot_user
>> >> > group hubot_group
>> >> > mode "0644"
>> >> > notifies :restart, "service[hubot]"
>> >> > end
>> >> >
>> >> > template "#{install_dir}/hubot-scripts.json" do
>> >> > source "hubot-scripts.json.erb"
>> >> > owner hubot_user
>> >> > group hubot_group
>> >> > mode "0644"
>> >> > notifies :restart, "service[hubot]"
>> >> > end
>> >> >
>> >> > It's my understanding that the notification will only get called when
>> >> > the template renders differently. However, even when nothing has
>> >> > changed,
>> >> > every time chef-client runs, the restart happens.
>> >> >
>> >> > ...
>> >> > [Tue, 21 Feb 2012 10:25:53 -0500] INFO: Processing
>> >> > template[/etc/init.d/hubot] action create (hubot::default line 93)
>> >> > [Tue, 21 Feb 2012 10:25:53 -0500] INFO: Processing service[hubot]
>> >> > action
>> >> > enable (hubot::default line 100)
>> >> > [Tue, 21 Feb 2012 10:25:53 -0500] INFO: Processing service[hubot]
>> >> > action
>> >> > start (hubot::default line 100)
>> >> > [Tue, 21 Feb 2012 10:25:53 -0500] INFO: Processing
>> >> > package[redis-server]
>> >> > action install (redis::package line 21)
>> >> > [Tue, 21 Feb 2012 10:25:53 -0500] INFO: Processing service[redis]
>> >> > action
>> >> > start (redis::package line 23)
>> >> > [Tue, 21 Feb 2012 10:25:53 -0500] INFO: Processing
>> >> > template[/etc/redis/redis.conf] action create (redis::package line
>> >> > 30)
>> >> > [Tue, 21 Feb 2012 10:25:53 -0500] INFO:
>> >> > template[/usr/local/hubot/package.json] sending restart action to
>> >> > service[hubot] (delayed)
>> >> > [Tue, 21 Feb 2012 10:25:53 -0500] INFO: Processing service[hubot]
>> >> > action
>> >> > restart (hubot::default line 100)
>> >> > [Tue, 21 Feb 2012 10:25:53 -0500] INFO: service[hubot] restarted
>> >> > [Tue, 21 Feb 2012 10:25:53 -0500] INFO: Chef Run complete in 2.929228
>> >> > seconds
>> >> > [Tue, 21 Feb 2012 10:25:53 -0500] INFO: Running report handlers
>> >> > [Tue, 21 Feb 2012 10:25:53 -0500] INFO: Report handlers complete
>> >> >
>> >> > Does anyone know why this is happening? Thank you in advance.
>> >> The log message indicates that
>> >> `template[/usr/local/hubot/package.json]`
>> >> is triggering the restart, but you've elided the log messages from that
>> >> one
>> >> so we can't see what's going on.
>> >>
>> >> Someone had a similar issue which was caused by a separate process
>> >> chmod-ing the file.
>> >>
>> >> >
>> >> > All the best,
>> >> > --
>> >> > Arthur Kalmenson
>> >>
>> >>
>> >>
>> >> --
>> >> Dan DeLeo
>> >>
>> >>
>> >>
>> >
>
>

--
Opscode, Inc.
Adam Jacob, Chief Customer Officer
T: (206) 619-7151 E: " target="_blank">