puppet-load forbidden request to /catalog/*

[Matthew Burgess]

Hi,

To try and cut a long story short, foreman is telling us that anywhere
between 15-30 of our ~130 nodes are failing to check-in within the
last 35 minutes. Hosts that fail to check in continue to fail for
roughly 1.5 hours, then check in successfully. The group of failing
nodes seems to rotate around the server estate, so the problem doesn't
look host specific. I suspect this is a load issue, and therefore am
trying to run puppet-load to verify this.

I've followed the instructions at http://www.masterzen.fr/2010/10/18/benchmarking-puppetmaster-stacks/
and am running:

./puppet-load.rb --debug --verbose --node server.domain.com --server
master.domain.com --factsdir=/var/lib/puppet/yaml/facts --cert /var/
lib/puppet/ssl/certs/puppet-load.domain.com.pem --key /var/lib/puppet/
ssl/private_keys/puppet-load.domain.com.pem

I see the following output:

1 requests finished in 0.04288 s
1 requests failed
<snip timing stats>

The following appears in /var/log/messages:

Denying access: Forbidden request: master.domain.com(10.x.x.x) access
to /catalog/server.domain.com [find] at line 99
Forbidden request: master.domain.com(10.x.x.x) access to /catalog/
server.domain.com [find] at line 99

I'm using puppet-2.7.14 running on RHEL-5.8 with Ruby-1.8.7 RPMs from
aegisco. In case it matters, Foreman is 0.4.2.

Thanks for any help, either in being able to get puppet-load to load
test our environment, or in letting me know what might cause our
clients to fail to check in reliably if it's not a load issue.

Thanks,

Matt.

[Ryan Coleman]

On Tue, May 22, 2012 at 2:56 AM, Matthew Burgess
<matthew....@googlemail.com> wrote:
> Thanks for any help, either in being able to get puppet-load to load
> test our environment, or in letting me know what might cause our
> clients to fail to check in reliably if it's not a load issue.
>

Hi Matt,

I ran into this as well, it seems as though puppet-load isn't properly
authenticating with its agent certificate to the master. To work
around this for now, assuming the client running puppet-load has a
certificate named centos6.puppetlabs.vm, insert the following
statement into auth.conf

path /catalog/centos6.puppetlabs.vm
method find
allow centos6.puppetlabs.vm
auth any

This statement allows your node to find its catalog. It's the 'auth
any' bit that makes it work, I just chose to make it a separate
statement so you don't allow unauthenticated clients to grab catalogs.

Reference: http://docs.puppetlabs.com/guides/rest_auth_conf.html

HTH,

--Ryan

[Matthew Burgess]

On Tue, May 22, 2012 at 5:43 PM, Ryan Coleman <ry...@puppetlabs.com> wrote:
> On Tue, May 22, 2012 at 2:56 AM, Matthew Burgess
> <matthew....@googlemail.com> wrote:
>> Thanks for any help, either in being able to get puppet-load to load
>> test our environment, or in letting me know what might cause our
>> clients to fail to check in reliably if it's not a load issue.
>>
>
> Hi Matt,
>
> I ran into this as well, it seems as though puppet-load isn't properly
> authenticating with its agent certificate to the master. To work
> around this for now, assuming the client running puppet-load has a
> certificate named centos6.puppetlabs.vm, insert the following
> statement into auth.conf
>
> path /catalog/centos6.puppetlabs.vm
> method find
> allow centos6.puppetlabs.vm
> auth any

Apologies for taking so long to get back about this, more pressing
matters took precedence. So, back on this, I think I must be doing
something really daft then, as I've made that change to my auth.conf
file and still get the same forbidden errors.

I also missed some potentially important information from my original
message, which is that we're running puppet behind mod_passenger due
to already hitting scalability issues with Webrick. We've now also
had to turn on storeconfigs to handle some external resources, and
therefore have pointed foreman at the same MySQL DB to gather its
hosts, facts and reports from. Foreman is also running under
mod_passenger. puppet, foreman and mysql are all on the same server;
a virtual machine running on a VMWare ESXi host.

Having not been able to get any info out of puppet-load to date, I
decided to bump the number of vCPUs up to 4, from 1, and increase its
RAM from 2GB to 4GB, but that hasn't helped any. So, I'm now
wondering whether apache/mod_passenger is configured correctly in
terms of launching enough worker threads/puppetmasterd children.

One other concern is that foreman shows a roughly even split of load
across the 30 minute time window (~10 hosts every 3 minutes), except
for one spike where 28 clients decide to hit it in one 3 minute
interval. Should puppet not be telling these clients to back off a
bit? I have a hunch that if I could get the clients all averaged out
(~14 hosts per 3 minute window) things may go a little smoother. That
said, I would have thought that the hardware I've thrown at this is
already sufficient to handle what I'd imagine is a fairly small
environment compared to others out there?

Thanks,

Matt.

[Matthew Burgess]

> Apologies for taking so long to get back about this, more pressing
> matters took precedence.  So, back on this, I think I must be doing
> something really daft then, as I've made that change to my auth.conf
> file and still get the same forbidden errors.

Indeed, I was doing something really daft. I'd added the changes to
the bottom of auth.conf. 2 things were wrong in doing that:

a) Adding anything below the 'path /' stanza isn't going to be picked
up, I don't think (I noticed this when trying to get 'puppet kick' to
work and got
similar 403 errors when trying to access /run)
b) There's already a 'path ~ ^/catalog/([^/]+)$' stanza in the default
auth.conf file, so the settings there were being hit before my new
stanza at the bottom
of the file. By adding 'allow master.domain.com' and 'auth any' to
the default stanza the 403s have disappeared.

Now though, is my next problem. puppet-load works fine with
concurrency set to 1. As soon as I increase that number though, I get
the following error:

undefined method `>' for ["2.7.14", "2.7.14"]:Array on node master.domain.com

Is this an issue with my Ruby version (1.8.7.299-7), or is it a bug in the code?

Cheers,

Matt.

[Ryan Coleman]

On Wed, May 30, 2012 at 8:32 AM, Matthew Burgess
<matthew....@googlemail.com> wrote:
> Indeed, I was doing something really daft.  I'd added the changes to
> the bottom of auth.conf.  2 things were wrong in doing that:

Glad you got that sorted!

> Now though, is my next problem.  puppet-load works fine with
> concurrency set to 1.  As soon as I increase that number though, I get
> the following error:
>
> undefined method `>' for ["2.7.14", "2.7.14"]:Array on node master.domain.com
>
> Is this an issue with my Ruby version (1.8.7.299-7), or is it a bug in the code?

Could you please post the puppet-load command you're using? I've not
encountered any issues increasing the concurrency. Perhaps its a
mishandled syntax error.

--Ryan

[Matthew Burgess]

On Wed, May 30, 2012 at 4:36 PM, Ryan Coleman <ry...@puppetlabs.com> wrote:

> Could you please post the puppet-load command you're using? I've not
> encountered any issues increasing the concurrency. Perhaps its a
> mishandled syntax error.

cd /usr/share/puppet/ext
./puppet-load.rb --node master.domain.com --server master.domain.com
--factsdir /var/lib/puppet/yaml/facts --cert
master.domain.com.cert.pem --key master.domain.com.private.pem
--concurrency 2

Thanks,

Matt.

[Brice Figureau]

Hi Matthew,

As the original author of puppet-load (and the aforementioned blog
post), I'm sorry to answer so late to this thread.

Where do you get this error?
Is it from puppet-load or your current master stack?
Is there any stack trace printed?

Can you add --debug and --trace to the puppet-load command line?
This should print more information to the console and we'll certainly be
able to find what's wrong.

> Is this an issue with my Ruby version (1.8.7.299-7), or is it a bug in the code?

I'd tend to say a bug in the code :)
--
Brice Figureau
Follow the latest Puppet Community evolutions on www.planetpuppet.org!

[Matthew Burgess]

The error appears in /var/log/messages and is being spit out by the
puppet master.

> Can you add --debug and --trace to the puppet-load command line?

I've added --debug, but there's no --trace option.

debug just shows the facts file being picked up, then both clients
finishing with an HTTP code 400. No stack trace is printed.

I've also added --debug to the puppetmaster's config.ru file. That's
printing lots of stuff about access lists, expiring the nodes and then
caching the node, then I get the undefined method error. Again, no
stack trace :-(

So, I took mod_passenger out of the equation and ran 'puppetmasterd
--no-daemonize --debug --verbose --logdest /tmp/puppet-error.log' and
get the following:

Wed May 30 18:02:22 +0100 2012 Puppet (info): Expiring the node cache
of master.domain.com
Wed May 30 18:02:22 +0100 2012 Puppet (info): Expiring the node cache
of master.domain.com
Wed May 30 18:02:23 +0100 2012 Puppet (info): Not using expired node
for master.domain.com from cache; expired at Wed May 30 18:01:22 +0100
2012
Wed May 30 18:02:23 +0100 2012 Puppet (info): Not using expired node
for master.domain.com from cache; expired at Wed May 30 18:01:22 +0100
2012
Wed May 30 18:02:23 +0100 2012 Puppet (debug): Executing
'/etc/puppet/enc.pl master.domain.com'
Wed May 30 18:02:23 +0100 2012 Puppet (debug): Executing
'/etc/puppet/enc.pl master.domain.com'
Wed May 30 18:02:24 +0100 2012 Puppet (debug): Using cached facts for
master.domain.com
Wed May 30 18:02:24 +0100 2012 Puppet (debug): Using cached facts for
master.domain.com
Wed May 30 18:02:24 +0100 2012 Puppet (info): Caching node for master.domain.com
Wed May 30 18:02:24 +0100 2012 Puppet (info): Caching node for master.domain.com
Wed May 30 18:02:24 +0100 2012 Puppet (err): undefined method `>' for

["2.7.14", "2.7.14"]:Array on node master.domain.com

Wed May 30 18:02:24 +0100 2012 Puppet (err): undefined method `>' for

["2.7.14", "2.7.14"]:Array on node master.domain.com

Wed May 30 18:02:24 +0100 2012 Puppet (err): undefined method `>' for

["2.7.14", "2.7.14"]:Array on node master.domain.com

Wed May 30 18:02:24 +0100 2012 Puppet (err): undefined method `>' for

["2.7.14", "2.7.14"]:Array on node master.domain.com

Wed May 30 18:02:32 +0100 2012 Puppet (notice): Caught INT; calling stop

Now, interestingly, I guess, is that every other run of puppet-load is
triggering this issue, so adding '--repeat 2' to my puppet-load
command line will trigger the issue consistently for me (as in 2
requests will succeed, 2 will fail). If you want full debug logs of
that type of run, I'll be more than happy to provide them.

Regards,

Matt.

[Brice Figureau]

My bad, there is no --trace in puppet-load. But there is one for puppet
master. Running your master with --debug and --trace will definitely
print a stack trace.

From there, I believe I should be able to understand what really happens.

My gut feeling right now is that the facts puppet-load sends to the
master are somehow not correct, but I can be wrong of course.

Probably that the stacktrace you'll get with --trace will be enough for
the moment. Also if you can cat the facts file (feel free to obfuscate
the private data you might have in there), that might help.

--
Brice Figureau
My Blog: http://www.masterzen.fr/

[Matthew Burgess]

OK. so another buglet here is that if you have '--debug --verbose
--trace' on the puppetmaster command line, you get no stacktrace. As
soon as I take '--verbose' out, I get the attached stacktrace.
puppet-load's logging has a similar issue in that '--verbose' seems to
override '--debug' so I get no debug output if both options are
specified.

Anyway, attached are the debug log from the puppet master and the
facts file suitably obfuscated.

The commands I used were:

puppetmasterd --no-daemonize --debug --trace --logdest /tmp/puppet-error.log
./puppet-load.rb --debug --node master.domain.com --server

master.domain.com --factsdir /var/lib/puppet/yaml/facts --cert
master.domain.com.cert.pem --key master.domain.com.private.pem

--concurrency 4

Thanks,

Matt.

[Brice Figureau]

On Thu, 2012-05-31 at 10:38 +0100, Matthew Burgess wrote:
> On Wed, May 30, 2012 at 6:58 PM, Brice Figureau
> <brice-...@daysofwonder.com> wrote:
>
> > Probably that the stacktrace you'll get with --trace will be enough for
> > the moment. Also if you can cat the facts file (feel free to obfuscate
> > the private data you might have in there), that might help.
>
> OK. so another buglet here is that if you have '--debug --verbose
> --trace' on the puppetmaster command line, you get no stacktrace. As
> soon as I take '--verbose' out, I get the attached stacktrace.
> puppet-load's logging has a similar issue in that '--verbose' seems to
> override '--debug' so I get no debug output if both options are
> specified.

Yes, the order is important, and --verbose will override --debug.

> Anyway, attached are the debug log from the puppet master and the
> facts file suitably obfuscated.
>

Can you run your master on the console (add --no-daemonize to the
command-line)?

Because due to how Puppet reports errors during compilation, the full
stacktrace is only printed on the console, and I'm missing the important
bits :)

Thanks,

[Matthew Burgess]

On Thu, May 31, 2012 at 2:09 PM, Brice Figureau
<brice-...@daysofwonder.com> wrote:

> Can you run your master on the console (add --no-daemonize to the
> command-line)?
>
> Because due to how Puppet reports errors during compilation, the full
> stacktrace is only printed on the console, and I'm missing the important
> bits :)

Thanks for you help and patience with this. Here's the log as
captured on the command line.

It's a bit bigger than the last one, and looks as if it's got a bit
more at the very start of the stack trace. Here's hoping it's what
you were looking for!

Regards,

Matt.

[Brice Figureau]

That's perfect!

Apparently the client_version fact is not correct (it contains an
array).
One thing you might want to do, is to modify manually the
master.domain.com.yaml file to remove the "clientversion" fact
altogether to see if that fixes it or not.

I'm not sure what makes this fact an array, but I'll have a deeper look.

[Matthew Burgess]

On Thu, May 31, 2012 at 4:31 PM, Brice Figureau
<brice-...@daysofwonder.com> wrote:

> That's perfect!
>
> Apparently the client_version fact is not correct (it contains an
> array).
> One thing you might want to do, is to modify manually the
> master.domain.com.yaml file to remove the "clientversion" fact
> altogether to see if that fixes it or not.
>
> I'm not sure what makes this fact an array, but I'll have a deeper look.

So, hopefully I'm not barking up completely the wrong tree here but:

I removed the clientversion fact, but that triggered other issues as
puppet then decided it had to go into compatibility mode, and none of
my manifests have been written to handle that. I then put the
clientversion fact back and just changed parser/resource.rb to return
false rather than it try and check the array-based fact it was
getting.

That's now a little better, but it causes one of my manifests to fail,
which is doing some string manipulation on the ipaddress fact. That
in turn appears to have been turned into an array, which funnily
enough, my .erb wasn't expecting :-)

So, it appears to my completely untrained eye as if all/most facts are
being stored or passed as arrays when the concurrency parameter is
increased.

Thanks,

Matt.

[Brice Figureau]

Your findings are very interesting, and we're now definitely closer to
the real issue.

I'll run a test over the week-end to see if I can reproduce the issue
with 2.7.14. It's possible something changed in the puppet codebase and
puppet-load doesn't properly encode the facts it sends to the master,
which in turn doesn't get unserialized as they should.

I'll keep you posted,
Thanks,

[Matthew Burgess]

Just as a hunch, I wonder whether, given the problems I had getting
compatible versions of various gems installed it may be a problem
there (I'm on an air-gapped environment, so had to download, transfer
and install the individual .gem files). In case it's useful, here's
the output of 'gem list':

activemodel (3.0.12)
activerecord (3.0.12)
activesupport (3.0.12)
addressable (2.2.8)
arel (2.0.10)
builder (3.0.0, 2.1.2)
cookiejar (0.3.0)
daemon_controller (0.2.5)
em-http-request (1.0.2)
em-socksify (0.2.0)
eventmachine (1.0.0.beta.4)
fastthread (1.0.7)
http_parser.rb (0.5.3)
i18n (0.6.0, 0.5.0)
json (1.4.3)
mime-types (1.16)
multi_json (1.3.5)
mysql (2.8.1)
passenger (3.0.12)
rack (1.1.0)
rake (0.8.7)
rest-client (1.6.1)
sqlite3-ruby (1.2.4)
tzinfo (0.3.33)

Cheers,

Matt.

[Brice Figureau]

On 01/06/12 12:41, Matthew Burgess wrote:
> On Thu, May 31, 2012 at 6:07 PM, Brice Figureau
> <brice-...@daysofwonder.com> wrote:
>
>> I'll run a test over the week-end to see if I can reproduce the issue
>> with 2.7.14. It's possible something changed in the puppet codebase and
>> puppet-load doesn't properly encode the facts it sends to the master,
>> which in turn doesn't get unserialized as they should.

Unfortunately, I wasn't able to reproduce the issue with your fact file.

On my side, I noticed that I'm running:
addressable (2.2.6)
cookiejar (0.3.0)
em-http-request (0.2.15)
em-socksify (0.1.0)
eventmachine (1.0.0.beta.4)
facter (1.6.2)
http_parser.rb (0.5.3)
rake (0.8.7)

So I tried to upgrade to em-http-request 1.2.0 like you, and ran into
many authentification trouble (like the SSL connection wasn't open with
the specified cert and key).

So my suggestion would be to:
gem uninstall em-http-request
gem install -v 0.2.5 em-http-request

and try if that helps,

[Matthew Burgess]

Thanks Brice. I'm not back in the office until Wednesday, but will
try a downgrade then.

Regards,

Matt.

[Matthew Burgess]

> On Sat, Jun 2, 2012 at 2:27 PM, Brice Figureau
> <brice-...@daysofwonder.com> wrote:
>>
>> So my suggestion would be to:
>> gem uninstall em-http-request
>> gem install -v 0.2.5 em-http-request

Unfortunately, that hasn't had any effect either. I've now got the
same versions of gems installed as you, including downgrading facter
1.6.2. I'm still getting the 400 error caused by it interpreting the
clientversion fact as an array.

Thanks,

Matt.