Puppet

I am going to try and reproduce this issue on my setup.

After running my agent:

root@master:~# puppet agent --test
info: Caching catalog for master.hightower.org
info: Applying configuration version '1314140379'
notice: Finished catalog run in 0.02 seconds

I received the following email:

From: report@master.hightower.org
Subject: Puppet Report for master.hightower.org
To: kelsey.hightower@gmail.com
Message-Id: <20110823225940.363555E87B@master.hightower.org>
Date: Tue, 23 Aug 2011 18:59:40 -0400 (EDT)
Tue Aug 23 18:59:39 -0400 2011 Puppet (info): Caching catalog for master.hightower.org
Tue Aug 23 18:59:39 -0400 2011 Puppet (info): Applying configuration version '1314140379'
Tue Aug 23 18:59:39 -0400 2011 Puppet (notice): Finished catalog run in 0.02 seconds

My /etc/puppet/tagmail.conf

all: kelsey.hightower@gmail.com

This happens because of that message about the configuration version. We get this too and it would be cool if that message was bumped down to debug or didn’t trigger a report. (This throws off our custom reports as well).

From the comments in the source:

... there is an `all` tag that will always match all log messages.

This could be a change from the from the 2.6.x series. Checking now.

Code looks the same in the 2.6.x branch as well. If anything shows up in the logs, then it will go out in an email if “all” is used in tagmail.conf

Kelsey,

I’ve found that puppet agent —test will always send an email even on 2.6.8, but on 2.6.8, a normal puppet run (not —test) would not send an email for the “Finished catalog run” email. I don’t know if it’s an unintended feature of Faces that the “Finished catalog run” notice gets captured by the report or if there’s something else causing this. I’ve begun hunting through the code to figure out what changed it, and that’s my current best guess but I am not familiar with the codebase.

Kelsey Hightower wrote:

Code looks the same in the 2.6.x branch as well. If anything shows up in the logs, then it will go out in an email if “all” is used in tagmail.conf

I’m seeing the same thing on my hosts as well and only seeing the “finished catalog” text.

Wed Aug 24 17:01:46 +0000 2011 //foo.example.org/Puppet (notice): Finished catalog run in 9.62 seconds

Wed Aug 24 17:02:41 +0000 2011 //bar.example.org/Puppet (notice): Finished catalog run in 0.66 seconds

So my patch results in the follow output in the logs:

Aug 24 23:52:44 master puppet-agent[7485]: Caching catalog for master.lab.org
Aug 24 23:52:44 master puppet-agent[7485]: Applying configuration version '1314244364'
Aug 24 23:52:44 master puppet-agent[7485]: Finished catalog run in 0.03 seconds
Aug 24 23:52:44 master puppet-master[7446]: Handling request: PUT /production/report/master.lab.org
Aug 24 23:52:44 master puppet-master[7446]: Recieved report to process from master.lab.org
Aug 24 23:52:44 master puppet-master[7446]: Processing report from master.lab.org with processor Puppet::Reports::Store
Aug 24 23:52:45 master puppet-master[7446]: Processing report from master.lab.org with processor Puppet::Reports::Http
Aug 24 23:52:45 master puppet-master[7446]: Processing report from master.lab.org with processor Puppet::Reports::Tagmail
Aug 24 23:52:45 master puppet-master[7446]: Not sending tagmail report; no changes

Notice the last line: “Not sending tagmail report; no changes”. This patch also prevents the tagmail report (email) from being sent if the status of the puppet run is “unchanged”.

Tests¶

I could not figure out a good way to test this patch so I have created a pending example in spec/unit/reports/tagmail_spec.rb.

I tested your patch and I confirmed it works. Thanks!

This is a major change in behaviour because you also don’t get any mail if you do all your puppetruns with the noop flag.

I think I should be able to rework the patch to check if we are in noop as well.

I’m sure everyone knows this, but it’s still an issue with 2.6.11 as well. Quite a shock after upgrading from 2.6.6.

How can I get this patch to apply?

I should have an updated patch that works for noop sometime tomorrow. At the point I would be happy if you can test this out for me.

I found your patch by googling around a bit, and it works for me. I’d love to see one that supports noop, and will happily test for you.

Yeah, most of the time you can find the current patch in the “branch” section of the ticket, towards the top.

Kelsey Hightower wrote:

Yeah, most of the time you can find the current patch in the “branch” section of the ticket, towards the top.

Hm, looks like it doesn’t work for me with 2.7.5.

We were seeing this as well, and I dodged the problem by making a local change to puppet/reports/tagmail.rb (on the puppet server) to throw those lines away. A terrible kludge, but my mailbox was happier. Hope someone finds this useful. Thanks – cheers! John

% diff -c ./puppet-2.7.5/lib/puppet/reports/tagmail.rb.orig ./puppet-2.7.5/lib/puppet/reports/tagmail.rb
*** ./puppet-2.7.5/lib/puppet/reports/tagmail.rb.orig        Fri Sep 30 13:51:10 2011
--- ./puppet-2.7.5/lib/puppet/reports/tagmail.rb     Thu Oct  6 14:45:01 2011
***************
*** 59,64 ****
--- 59,70 ----
          true if neg.detect do |tag| log.tagged?(tag) end
        end

+       # Now remove any lines like this
+       # Puppet (notice): Finished catalog run in 14.14 seconds
+       messages = messages.reject do |log|
+         true if log.to_s =~ /Finished catalog run in .* seconds/
+       end
+
        if messages.empty?
          Puppet.info "No messages to report to #{emails.join(",")}"
          next

So, I am picking this back up today, the goal is to make a patch that address the following:

• When there are no changes, do not send emails in normal or no-op mode
• When there are changes, send emails in normal or no-op mode

Looks like using metrics maybe the best way to detect changes during normal and no-op modes. Checking for resources that are either “Out of Sync”, “Restarted”, or “Changed” should work.

I hit this bug today as well. And it is not that just

Tue Feb 07 14:57:59 +0100 2012 Puppet (notice): Finished catalog run in 6.78 seconds

Bothers me. All the plugin/fact synchronisation will be put in the report, too. This will trigger a messagestorm whenever I change a plugin.

...
Tue Feb 07 14:57:25 +0100 2012 /File[/var/puppet/lib/puppet]/ensure (notice): created
Tue Feb 07 14:57:25 +0100 2012 /File[/var/puppet/lib/puppet/feature]/ensure (notice): created
Tue Feb 07 14:57:25 +0100 2012 /File[/var/puppet/lib/puppet/feature/nokogiri.rb]/ensure (notice): defined content as '{md5}70eeab3b73df6089eb87f4f760b31bbf'
Tue Feb 07 14:57:25 +0100 2012 /File[/var/puppet/lib/puppet/parser]/ensure (notice): created
Tue Feb 07 14:57:25 +0100 2012 /File[/var/puppet/lib/puppet/parser/functions]/ensure (notice): created
Tue Feb 07 14:57:26 +0100 2012 /File[/var/puppet/lib/puppet/parser/functions/downcase.rb]/ensure (notice): defined content as '{md5}9204a04c2a168375a38d502db8811bbe'
...

Worth noticing:

• I’ll not get any messages if a 2.6.1 agent is talking to a 2.6.11 server
• I’ll get the pluginsync messages if a 2.611 agent is talking to a 2.6.11 server

So a fix must address the agent side and most probably not tagmail.rb itself (which runs on the server side).

I tracked down the commit that caused the change in behaviour (pluginsync appears in reports and the »Finished catalog run« appears in reports): commit:98ba407

Hey Kelsey – I know you’re really busy but do you have a status on this? Thanks!