Puppet catalog transfer often gets truncated (Could not intern from pson: error)

[Jeff B]

I've been hitting this issue for a long time. well over a year and I guess it's time to start pushing it to try to find the root cause.  I've seen this reported several times in the past but I've never seen a resolution found for this exact problems.  There are other root causes for pson errors that have been resolved, but not for the ones describing my problem.

What we're finding is that often times the catalog is getting chopped off at some seemingly random point in the file.  If you run puppet agent multiple times in a row each time it will cut off at always different parts.

The error manifests itself like this:

Debug: node supports formats: b64_zlib_yaml pson raw yaml; using pson

Debug: Using cached certificate for ca

Debug: Using cached certificate for ds0.lab.avere.net

Debug: Using cached certificate_revocation_list for ca

Info: Retrieving plugin

Debug: file_metadata supports formats: b64_zlib_yaml pson raw yaml; using pson

Debug: Finishing transaction 70037484276920

Info: Loading facts in /var/lib/puppet/lib/facter/serialports.rb

Debug: catalog supports formats: b64_zlib_yaml dot pson raw yaml; using pson

Error: Could not retrieve catalog from remote server: Could not intern from pson: expected value in object at '"Ssh_authorized_key['!

Warning: Not using cache on failed catalog

Error: Could not retrieve catalog; skipping run

It's not uncommon to run this 'puppet agent -t' 8 times in a row, and getting a different quoted error part until one time it completes.

Here is a repro where I ran it one after another, the first 2 worked,  3 failed, and the 6th worked.

[root@host0 ~]# puppet agent -t

Info: Retrieving plugin

Info: Loading facts in /var/lib/puppet/lib/facter/serialports.rb

Info: Caching catalog for ds0.lab.avere.net

Info: Applying configuration version '1366164490'

Notice: Finished catalog run in 13.20 seconds

[root@host0 ~]# puppet agent -t

Info: Retrieving plugin

Info: Loading facts in /var/lib/puppet/lib/facter/serialports.rb

Info: Caching catalog for ds0.lab.avere.net

Info: Applying configuration version '1366164490'

Notice: Finished catalog run in 12.32 seconds

[root@host0 ~]# puppet agent -t

Info: Retrieving plugin

Info: Loading facts in /var/lib/puppet/lib/facter/serialports.rb

Error: Could not retrieve catalog from remote server: Could not intern from pson: expected ',' or ']' in array at ''!

Warning: Not using cache on failed catalog

Error: Could not retrieve catalog; skipping run

[root@host0 ~]# puppet agent -t

Info: Retrieving plugin

Info: Loading facts in /var/lib/puppet/lib/facter/serialports.rb

Error: Could not retrieve catalog from remote server: Could not intern from pson: expected value in object at '"File[/usr/lib64/ope'!

Warning: Not using cache on failed catalog

Error: Could not retrieve catalog; skipping run

[root@host0 ~]# puppet agent -t

Info: Retrieving plugin

Info: Loading facts in /var/lib/puppet/lib/facter/serialports.rb

Error: Could not retrieve catalog from remote server: Could not intern from pson: expected value in object at '"Class[Os-p'!

Warning: Not using cache on failed catalog

Error: Could not retrieve catalog; skipping run

[root@host0 ~]# puppet agent -t

Info: Retrieving plugin

Info: Loading facts in /var/lib/puppet/lib/facter/serialports.rb

Info: Caching catalog for ds0.lab.avere.net

Info: Applying configuration version '1366164490'

Notice: Finished catalog run in 13.34 seconds 

Other vital stats:

[root@host0 ~]# cat /etc/redhat-release

CentOS release 6.4 (Final)

[root@host0 ~]# rpm -qa|grep puppet

puppet-3.1.1-1.el6.noarch

[root@host0 ~]# cat /etc/yum.repos.d/puppet.repo

[puppet]

name=Puppet Packages for Enterprise Linux $releasever - $basearch

baseurl=http://yum.puppetlabs.com/el/$releasever/products/$basearch

enabled=1

gpgcheck=1

gpgkey=file:// 

Please let me know if there is a resolution for this and I've missed it.  and if there is no resolution I'll be happy to gather more data as instructed.   One question that I do have is how to I see the contents of what is sent over pson?   Specifically to get a handle on what is happening here:

Debug: catalog supports formats: b64_zlib_yaml dot pson raw yaml; using pson

Error: Could not retrieve catalog from remote server: Could not intern from pson: expected value in object at '"Ssh_authorized_key['!

Thanks,

 

[Matthew Burgess]

On Mon, Apr 22, 2013 at 4:56 PM, Jeff B <jeffb...@gmail.com> wrote:

I've been hitting this issue for a long time. well over a year and I guess it's time to start pushing it to try to find the root cause.  I've seen this reported several times in the past but I've never seen a resolution found for this exact problems.  There are other root causes for pson errors that have been resolved, but not for the ones describing my problem.

What we're finding is that often times the catalog is getting chopped off at some seemingly random point in the file.  If you run puppet agent multiple times in a row each time it will cut off at always different parts.

Hi Jeff,

At the risk of this looking like a "when all you have is a hammer, everything looks like a nail" type response, whenever I've seen random failures like this, it's because the puppetmaster can't cope with the load being driven to it.  Are you running your puppetmaster behind a web server such as Apache/Passenger or nginx/Passenger?  If not, and dependent on the number of clients and their runinterval, you may be hitting a bottleneck caused by Puppet's internal webserver's (Webrick's) single-threaded nature.

Regards,

Matt.

[Jeff B]

Thanks for the tip this sounds quite plausible and it looks like something I'll need sooner or later.

[jcbollinger]

A fundamental characteristic of being single-threaded is that Puppet / webrick always finishes processing any current request before it starts work on the next. Therefore, if Puppet's responses are truncated when it has additional requests queued then that is not merely a loading issue -- it is a genuine and fairly serious bug.  It probably indicates that Puppet does not properly flush / close the response stream when it reaches the end of the response (or the like), though I cannot guess whether that would be a flaw in Puppet's own code or one in webrick.  If in Puppet itself, then it may manifest in other ways and in other contexts, too, so I urge you to file a ticket.


John

[Jeff B]

Thanks John,

Ticket has been created:  https://projects.puppetlabs.com/issues/20350  

I'll be happy to help debug this problem as needed.

 

[Daniel]

I am also getting this problem. Did running the puppet master within Apache/Passenger or nginx/Passenger help at all?

I was thinking it could be to do with a non ascii character making its way into my code somewhere as that seems to cause dodgy stuff but that's not it. I've seen lots of suggestions but I get the feeling it must be a bug with puppet.

Not able to view the ticket as it looks like projects.puppetlabs.com is down currently.

I am using opensource:

ruby-1.8.7.352-13.el6.x86_64

puppet-2.7.25-2.el6.noarch

puppet-server-2.7.25-2.el6.noarch

Dan

[Felix Frank]

On 07/15/2014 01:47 PM, Daniel wrote:
> I am also getting this problem. Did running the puppet master
> within Apache/Passenger or nginx/Passenger help at all?
>
> I was thinking it could be to do with a non ascii character making its
> way into my code somewhere as that seems to cause dodgy stuff but
> that's not it. I've seen lots of suggestions but I get the feeling it
> must be a bug with puppet.
>
> Not able to view the ticket as it looks like projects.puppetlabs.com
> is down currently.
>
> I am using opensource:
>
> ruby-1.8.7.352-13.el6.x86_64
> puppet-2.7.25-2.el6.noarch
> puppet-server-2.7.25-2.el6.noarch
>
> Dan

Wow, that issue is *old* :-) Hasn't been migrated to Jira, either.

According to Redmine, moving to Passenger has helped at least one user,
apparently.

HTH,
Felix

[Henrik Lindberg]

This is probably the Webrick threading issues that were fixed for 3.6.2
- IIRC that could cause truncated catalogs.

--

Visit my Blog "Puppet on the Edge"
http://puppet-on-the-edge.blogspot.se/