[PUP-2659] Puppet stops working with error 'Attempted to pop, but already at root of the context stack.' Created: 2014/05/24  Updated: 2019/04/04  Resolved: 2014/06/10

Status: Closed
Project: Puppet
Component/s: Modules
Affects Version/s: PUP 3.6.1
Fix Version/s: PUP 3.6.2

Type: Bug Priority: Major
Reporter: Wojciech Urbański Assignee: Mikael Barfred
Resolution: Done Votes: 18
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

CentOS 6.5


Attachments: File trace.tgz    
Issue Links:
Duplicate
is duplicated by PUP-2662 puppet fails to compile catalogs afte... Closed
is duplicated by PUP-1558 Serialize webrick request handlers Closed
Relates
relates to PUP-2610 Rack masters lose track of environmen... Closed
relates to DOCUMENT-134 Call out in the docs that Puppet requ... Closed
Template:
Story Points: 3
Sprint: Week 2014-5-21 to 2014-5-28, Week 2014-5-28 to 2014-6-4, Week 2014-6-4 to 2014-6-11
UX Priority: Critical

 Description   

After upgrading puppet to version 3.6.1, the following error occurs:

Attempted to pop, but already at root of the context stack.

And afterwards log is flooded with following message:

no 'environments' in {:root_environment=>#<Puppet::Node::Environment:0x7fe1930f5a38 @manifest="/", @modulepath=[], @name=:"*root*", @watching=true, @config_version=nil>, :current_environment=>#<Puppet::Node::Environment:0x7fe1930f5a38 @manifest="/", @modulepath=[], @name=:"*root*", @watching=true, @config_version=nil>} at top of [[0, nil, nil]]

This was not an issue in 3.6.0. Unfortunately this happens at seemingly random times, soon after starting the puppetmaster service.



 Comments   
Comment by Henrik Lindberg [ 2014/05/24 ]

Can you please supply information about your environment configuration - what have you configured, and in which section?

Comment by Wojciech Urbański [ 2014/05/25 ]

I've been using a configuration without environments for a while now. (I know that it's going to stop being supported soon, but I haven't migrated this configuration yet).
Some catalog runs pass, but then this error happens.

However, while typing this comment I have changed my configuration a bit, adding to master's config

[master]
...
environmentpath = $confdir/environments

and to agents

[agent]
...
environment=production

And moving manifests and modules to directory environments/production. The problem persists.

Comment by Rob Payne [ 2014/05/25 ]

Same thing happens, here. Two different puppet masters, both without any environment configured (other than the default 'production' environment).

# puppet master --configprint all |grep environment
environment = production
environment_timeout = 5
environmentpath = ""

Both masters were running fine (except for too-verbose warnings) on 3.6.0, but are now seeing this issue after updating to 3.6.1.

Comment by Henrik Lindberg [ 2014/05/26 ]

Are you using passenger or webrick ?
Any other add ons to puppet ?

It would be great to get a stack-trace of the "no environments found" error

Comment by Wojciech Urbański [ 2014/05/26 ]

tar-gzed stack trace,
Error was logged at 19:33:40

Comment by Wojciech Urbański [ 2014/05/26 ]

I am using no addons, clean puppet-only installation.

I have attached a stack trace. Sorry for the size, but this time the crash happened after a pretty long time.

Comment by Rob Payne [ 2014/05/26 ]

I am also using no add-ons, and webrick. I'm seeing it on CentOS 6 (puppet-server-3.6.1-1.el6.noarch)

Comment by Raffael Link [ 2014/05/26 ]

We have the same issue here on Debian Wheezy starting with Puppet 3.6.1. Also, the second error message looks a little bit different:

Error 400 on SERVER: no 'environments' in {:current_environment=>*root*, :root_environment=>*root*} at top of [[0, nil, nil]]

Comment by Henrik Lindberg [ 2014/05/26 ]

The trace I am interested in is the Ruby stacktrace that is logged as part of the 400 error being returned to the client.
In case you have trouble finding this, you may be able to reproduce this by running the master in non daemon mode (shut down the deamon first, then start master from command line), then look at the output. You can also try turning on --debug and --verbose, but I think errors are always shown without these.

Sorry I tricked you into doing a trace of the Ruby virtual machine

Comment by Sharon Tickell [ 2014/05/26 ]

I am seeing this issues as well: on Ubuntu 12.04, using webrick.
My environments are still set up with the old-style config file sections, and I had to delete the $confidir/environments directory on my puppetmaster to get puppet agents to connect successfully at all (as per http://www.clarksys.com/blog/2014/05/25/puppet-environment-errors/)

My currently installed versions of the puppet and puppetmaster packages are both 3.6.1-1puppetlabs1, and I'm running puppetdb 2.0.0-1puppetlabs1

Comment by Sharon Tickell [ 2014/05/26 ]

... and I've now updated my environment configuration to use directory environments, but am still seeing this issue.

I do notice, though, that for the first (successful) manual puppet with --verbose after restarting the puppetmaster, the output includes an info-level notification like "Could not retrieve ec2 metadata: 500 Internal Server Error", just after the "Retrieving plugin" line, and before any of the "Loading facts" notifications. I don't know if that's related, though, or is another bug that just happens to happen in the same version?

Comment by Anton Lindström [ 2014/05/27 ]

We're getting the following error:

Error: no 'environments' in {:current_environment=>*root*, :root_environment=>*root*} at top of [[0, nil, nil]]

Running the master in foreground with verbose and debug gives the following output:

Debug: Route /^\/v2\.0/
Debug: Route /.*/
Debug: Evaluating match for Route /^\/v2\.0/
Debug: Did not match path ("/production/file_metadata/modules/web/www/error_500.html")
Debug: Evaluating match for Route /.*/
Error: no 'environments' in {:current_environment=>*root*, :root_environment=>*root*} at top of [[0, nil, nil]]
 
Error: Attempted to pop, but already at root of the context stack. on node mynode.example.com
Error: Attempted to pop, but already at root of the context stack. on node mynode.example.com
Error: Attempted to pop, but already at root of the context stack.

Thanks!

Comment by Adrian Reber [ 2014/05/27 ]

We have the same error on Ubuntu 12.04 with 3.6.1-1puppetlabs1:

puppet-master[30471]: no 'environments' in {:root_environment=>#<Puppet::Node::Environment:0x7f20e04a7e70 @manifest="/", @modulepath=[], @watching=true, @config_version=nil, @name=:"*root*">, :current_environment=>#<Puppet::Node::Environment:0x7f20e04a7e70 @manifest="/", @modulepath=[], @watching=true, @config_version=nil, @name=:"*root*">} at top of [[0, nil, nil]]

Comment by Matthias Geerdsen [ 2014/05/27 ]

Hi,

we are seeing the same issue and log messages as Anton just posted. We are using Ubuntu 14.04 with Puppet version 3.6.1-1puppetlabs1 (obviously from the puppetlabs repos). Master has just been upgraded from 2.7, no environments where configured.

Log with --verbose --debug

May 27 10:44:37 puppet puppet-master[27776]: Compiled catalog for HOST.EXAMPLE.NET in environment production in 0.14 seconds
May 27 10:44:37 puppet puppet-master[27776]: Caching catalog for HOST.EXAMPLE.NET
May 27 10:44:37 puppet puppet-master[27776]: 'replace catalog' command for HOST.EXAMPLE.NET submitted to PuppetDB with UUID 43856084-7aa0-494b-9894-a6e08c8e265a
May 27 10:44:37 puppet puppet-master[27776]: catalog supports formats: pson msgpack yaml b64_zlib_yaml dot raw
May 27 10:44:37 puppet puppet-master[27776]: Attempted to pop, but already at root of the context stack.
May 27 10:44:37 puppet puppet-master[27776]: Routes Registered:
May 27 10:44:37 puppet puppet-master[27776]: Route /^\/v2\.0/
May 27 10:44:37 puppet puppet-master[27776]: Route /.*/
May 27 10:44:37 puppet puppet-master[27776]: Evaluating match for Route /^\/v2\.0/
May 27 10:44:37 puppet puppet-master[27776]: Did not match path ("/production/report/HOST.EXAMPLE.NET")
May 27 10:44:37 puppet puppet-master[27776]: Evaluating match for Route /.*/
May 27 10:44:37 puppet puppet-master[27776]: no 'environments' in {:current_environment=>*root*, :root_environment=>*root*} at top of [[0, nil, nil]]

masterhttp.log

[2014-05-27 10:44:36] DEBUG accept: IP_HOST.EXAMPLE.NET:60589
[2014-05-27 10:44:36] DEBUG Puppet::Network::HTTP::WEBrickREST is invoked.
[2014-05-27 10:44:37] IPOTHERHOST.EXAMPLE.NET - - [27/May/2014:10:44:36 CEST] "POST /production/catalog/OTHERHOST.EXAMPLE.NET HTTP/1.1" 200 51102
[2014-05-27 10:44:37] - -> /production/catalog/OTHERHOST.EXAMPLE.NET
[2014-05-27 10:44:37] DEBUG close: IPOTHERHOST.EXAMPLE.NET:38820
[2014-05-27 10:44:37] IP_HOST.EXAMPLE.NET - - [27/May/2014:10:44:36 CEST] "POST /production/catalog/HOST.EXAMPLE.NET HTTP/1.1" 400 59
[2014-05-27 10:44:37] - -> /production/catalog/HOST.EXAMPLE.NET
[2014-05-27 10:44:37] DEBUG close: IP_HOST.EXAMPLE.NET:60589

puppet config print

environment = production
environmentpath = 
environment_timeout = 5

Comment by Jason Fonseca [ 2014/05/27 ]

The same issue is occurring here, where we had a plain set up, and switched to directory environments with 3.6.0.

One client can access a 3.6.1 server with no issues. However, if more than one client connects at the same time, it triggers the "Attempted to pop, but already at root of the context stack." error. At this point the server is non-functional, producing the "no 'environments'" errors mentioned above until it is restarted.

Downgrading the server to 3.6.0 seems to resolve the issue.

Comment by Henrik Lindberg [ 2014/05/27 ]

There are other issues with Webrick in 3.6.0 that makes transactions start out for the wrong environment, and then switch in the middle of the transaction. The problems we are now seeing are due to the regression caused by the fix of that problem (PUP-2610)

Comment by Jason Normand [ 2014/05/27 ]

having the same issue on CentOS. We are using enc and were not using environments. However the issue still occurs after altering our configs to use a basic production environment. I can also confirm that this only happens when two nodes check in at the same time, other runs prior have no issue. However after the two nodes check in a puppetmaster restart is required to get it working again.

Comment by Henrik Lindberg [ 2014/05/27 ]

We think we have nailed this down to a Webrick concurrency issue and we can now reproduce the problem.

Comment by Nicholas Chappell [ 2014/05/27 ]

Just to add another data point, I get this with an Ubuntu 13.10 master running 3.6.1 with Webrick (no Apache or Nginx) and a mix of Ubuntu 13.10 and CentOS 6.5 Puppet 3.6.1 agents. Puppet master also has a local PuppetDB v2.0.0 instance installed and running.

My Puppet master has environmentpath = $confdir/environments in the [master] stanza of its puppet.conf. I have a single production environment, which the agents are using (not explicitly set on the agents, I'm just going with the default environment setting of production.

Oddly, the first few runs from agents work. After that, I get the no 'environments' in {:root_environment error on all agents. Restarting the Puppet master fixes the problem and I can get a few more Puppet runs before the error starts again.

Comment by Henrik Lindberg [ 2014/05/27 ]

As this is a concurrency issue any time two or more request happen to come with a particular interval, the processing of those requests will step on each others context and create a mess.

Comment by Andre Hurano [ 2014/05/27 ]

Oh God...me too. This is driving me insane!!

Warning: Error 400 on SERVER: no 'environments' in {:current_environment=>#<Puppet::Node::Environment:0x7fc2eac2cb58 @modulepath=[], @watching=true, @config_version=nil, @manifest="/", @name=:"root">, :root_environment=>#<Puppet::Node::Environment:0x7fc2eac2cb58 @modulepath=[], @watching=true, @config_version=nil, @manifest="/", @name=:"root">} at top of [[0, nil, nil]]

Comment by Sharon Tickell [ 2014/05/27 ]

Since Henrik Lindberg's comment that identified this as a webrick-specific issue, I switched my puppetmaster to use passenger instead, and can confirm that I am no longer receiving these errors. It's a heavy-handed workaround for only a couple of agent nodes, but it has allowed my puppet agents to work in advance of a proper patch.

Comment by Travis Collins [ 2014/05/28 ]

Getting this same error in Centos 6.5 using webricks.

Warning: Unable to fetch my node definition, but the agent run will continue:
Warning: Error 400 on SERVER: no 'environments' in {:root_environment=>#<Puppet::Node::Environment:0x7fe3541d94c8 @config_version=nil, @manifest="/", @modulepath=[], @watching=true, @name=:"root">, :current_environment=>#<Puppet::Node::Environment:0x7fe3541d94c8 @config_version=nil, @manifest="/", @modulepath=[], @watching=true, @name=:"root">} at top of [[0, nil, nil]]

Comment by Andre Hurano [ 2014/05/28 ]

I managed to solve all these errors and more by switching to passenger.

Comment by Henrik Lindberg [ 2014/05/30 ]

merged to stable: a4e404f

Comment by Henrik Lindberg [ 2014/05/30 ]

merged stable to master: d1723f8c38a4e075b2bce14556859be8dd8d8586

Comment by Ethan Brown [ 2014/06/02 ]

This has failed CI

See
tests/concurrency.ticket_2659_concurrent_catalog_requests.rb

https://jenkins.puppetlabs.com/view/Puppet%20FOSS/view/Stable/job/Puppet-Acceptance-Future-Parser-stable-vcloud-and-github/62/label=acc-coord,platform=fedora19/testReport/junit/(root)/tests_concurrency/ticket_2659_concurrent_catalog_requests_rb/

Comment by Andrew Parker [ 2014/06/02 ]

Tracked it down to the master running out of file handles (mistake in the tests). Pushed up two fixes for this and it is now running through again.

Comment by Kurt Wall [ 2014/06/05 ]

Verified in master at SHA=40024d87464c6a98d178ed5ce93fc70fb8139019. Using the setup in the spec test added for this bug, I changed the iterations from 1000.times to 10000000.times and ran the site.pp command in a 100-iteration loop. There was no error.

Comment by Dan Schaefer [ 2014/06/05 ]

Kurt Wall I seem to have encountered this issue in my environment when running Puppet Agent on 2 different nodes at the same time. Are you able to run your test with the 100-iteration loop on 2 different nodes with the same master? I encountered the issue after a recent puppetmaster restart.

Comment by Kurt Wall [ 2014/06/05 ]

Dan Schaefer Interesting. I didn't use two agents. Are you using the right bits? The patch hasn't been released.

Comment by Dan Schaefer [ 2014/06/05 ]

I have not updated Puppet with the patch. I am just reporting my findings with 3.6.1. I was wondering if the problem still occurs with the change AND having run the agent concurrently with 2 nodes.

Comment by Kurt Wall [ 2014/06/05 ]

Hi Dan. Okay, thanks for clarifying and thanks for asking. While I expect the patch to work for agent counts > 1, I will add a test case that addresses this specifically.

Comment by Alexander von Gluck IV [ 2014/06/09 ]

Is there a patch we can apply? Just deployed puppet and seeing these issues as well.

Comment by Alexander von Gluck IV [ 2014/06/09 ]

nevermind, applied the fix in this pull request and things seem to be working now:
https://github.com/puppetlabs/puppet/pull/2708

Comment by Kurt Wall [ 2014/06/09 ]

Alice reported seeing this bug even after the patch in Beaker testing. Alice Nodelman would you please attach a trace log and describe/attach the config? I'd like to try to reproduce it locally. Thanks!

Comment by Kurt Wall [ 2014/06/09 ]

URL to failure: http://jenkins-beaker.delivery.puppetlabs.net/job/FOSS%20Smoke%20Test/269/

Comment by Josh Cooper [ 2014/06/09 ]

Kurt Wall the acceptance test for this ticket failed, but in a way I don't think is related this to this issue.

Could not autoload puppet/type/notify: no such file to load -- /usr/lib/ruby/site_ruby/1.8/puppet/type/notify.rb on node xmqfplyo105kude.delivery.puppetlabs.net

That said, more investigation is required.

Comment by Kurt Wall [ 2014/06/09 ]

Re-closed. I was testing at the wrong SHA (lacked the test fix that followed the bug fix).

Comment by Joshua Partlow [ 2014/06/09 ]

Resetting to Resolved.

Comment by Melissa Stone [ 2014/06/10 ]

Released in Puppet 3.6.2

Comment by Francois Conil [ 2014/07/20 ]

I still have the exact same issue with puppet 3.6.2.

Running puppet master on ruby 2.1 and puma, on Debian Wheezy.

Jul 21 10:05:38 int-puppetmaster puppet-master[8442]: Attempted to pop, but already at root of the context stack. on node pm-mq-01
Jul 21 10:05:38 int-puppetmaster puppet-master[8442]: Attempted to pop, but already at root of the context stack. on node pm-mq-01
Jul 21 10:05:38 int-puppetmaster puppet-master[8442]: Attempted to pop, but already at root of the context stack.
Jul 21 10:05:38 int-puppetmaster puppet-master[8442]: Attempted to pop, but already at root of the context stack. on node int-redis-02
Jul 21 10:05:38 int-puppetmaster puppet-master[8442]: Attempted to pop, but already at root of the context stack. on node int-redis-02
Jul 21 10:05:38 int-puppetmaster puppet-master[8442]: Attempted to pop, but already at root of the context stack.
Jul 21 10:05:38 int-puppetmaster puppet-master[8442]: no 'environments' in {:current_environment=>#<Puppet::Node::Environment:0x007fd89e6e5270 @name=:"*root*", @modulepath=[], @manifest="/var/vhost/puppetmaster", @config_version=nil, @watching=true>, :root_environment=>#<Puppet::Node::Environment:0x007fd89e6e5270 @name=:"*root*", @modulepath=[], @manifest="/var/vhost/puppetmaster", @config_version=nil, @watching=true>} at top of [[0, nil, nil]]
Jul 21 10:05:38 int-puppetmaster puppet-master[8442]: no 'environments' in {:current_environment=>#<Puppet::Node::Environment:0x007fd89e6e5270 @name=:"*root*", @modulepath=[], @manifest="/var/vhost/puppetmaster", @config_version=nil, @watching=true>, :root_environment=>#<Puppet::Node::Environment:0x007fd89e6e5270 @name=:"*root*", @modulepath=[], @manifest="/var/vhost/puppetmaster", @config_version=nil, @watching=true>} at top of [[0, nil, nil]]

Comment by Joshua Partlow [ 2014/07/21 ]

Hi Francois,

Unfortunately Puppet doesn't supported multi-threaded rack servers like puma. You'll need to run with a multi-process server such as Passenger, Thin or Unicorn. I've opened a doc ticket Document-134 to address this in the docs. Sorry for the trouble,

Josh

Comment by Francois Conil [ 2014/07/21 ]

It's been working fine (and still does) on 3.4.3 for the past 6 months though.

Comment by Alice Nodelman [ 2014/07/21 ]

Unassigning from myself - this doesn't look like an Alice bug.

Comment by Joshua Partlow [ 2014/07/21 ]

Yes, there were changes in 3.5 and 3.6 which made the lack of thread safety more apparent.  Puppet has never supported running in threading environments, but there was some haphazard thread safety code which was removed to help clear up the codebase. This particular issue is related to context code changes made in 3.6.1 I believe.

Comment by Mikael Barfred [ 2015/03/02 ]

I still see this issue in v. 3.7.4 when using 'kick' to start an agent run.
It's consistently failing after 3-4 background 'puppet kick' runs (first few kicks are successful).
I initially saw it in a Foreman installation on Centos 6.6 (puppet 3.7.4, master under Passenger, agent under WEBrick) , but it's easy to reproduce it on a fresh plain install of puppet master and agent (both v. 3.7.4, and both under WEBrick) on a single server (a clean Centos 6.6) as well, as the following shows.
I took a clean Centos 6.6 and did:

rpm -ivh http://yum.puppetlabs.com/puppetlabs-release-el-6.noarch.rpm
yum -y install puppet-server puppet
# edit /etc/puppet/puppet.conf and /etc/puppet/auth.conf as shown below
# Generate server keys - hit CTRL-C after key creation:
puppet master --verbose --no-daemonize

I added this to auth.conf:

path    /run
method  save
auth    any
allow   puppetsandbox.corp.evenex.com

And I added this to agent section of puppet.conf:

server     = puppetsandbox.corp.evenex.com
listen      = true

No modules were added and no classes were assigned to any nodes.
I then started the two services puppetmaster and puppet. The certificate of the puppet agent were signed by the puppet master.
I can run any of these commands several times (at least 10 times) without seeing any errors:

puppet agent --test
puppet  kick --foreground --host puppetsandbox.corp.evenex.com
curl -k -X PUT -H "Content-Type: text/pson" -d "{}" https://puppetsandbox.corp.evenex.com:8139/production/run/no_key

However, if I run the following command several times, it will succeed at the initial and the second run, occasionally it may succeed at the third run and even the fouth run, but all subsequent runs will fail consistently.

puppet  kick --host puppetsandbox.corp.evenex.com

When it fails, the error message is:

Error: Host puppetsandbox.corp.evenex.com failed: Error 400 on SERVER: no 'environments' in {:root_environment=>#<Puppet::Node::Environment:0x7f30e3f36360 @name=:"*root*", @modulepath=[], @watching=true, @config_version=nil, @manifest=:no_manifest>, :current_environment=>#<Puppet::Node::Environment:0x7f30e3f36360 @name=:"*root*", @modulepath=[], @watching=true, @config_version=nil, @manifest=:no_manifest>} at top of [[0, nil, nil]]

And I also see this in the /var/log/messages:

Error: Could not run Puppet configuration client: Attempted to pop, but already at root of the context stack.

The agent (or the master-agent connection?) remains in this failing state until the puppet service is restarted, and the story repeats as above with 2-4 successful 'puppet kick' runs followed by consistently failing runs.
I will be happy to provide further details, traces, log files, or whatever you may need.

Comment by Henrik Lindberg [ 2015/03/02 ]

Puppet 'kick' is deprecated and is removed in Puppet 4.0.0. https://docs.puppetlabs.com/puppet/3.7/reference/deprecated_command.html#puppet-kick
It is not recommended for use as it has many issues.

Webrick is not recommended for use except for extremely simple non production scenarios.

We are not likely to fix any of these problems with kick/webrick, and suggest switching to a different approach.

Comment by Mikael Barfred [ 2015/03/02 ]

Thanks, Henrik Lindberg, for the fast response!
Yes, I knew about 'kick' being deprecated, but I hesitated to walk away from it because Foreman seemed to rely on it.
I've now been reading up on the configuration of Foreman's puppet management module, and learned that Foreman can be configured to use alternatives to the 'kick' feature, e.g. puppetssh or mcollective. I will pursue these alternatives and leave the 'kick' feature behind.

Comment by Henrik Lindberg [ 2015/03/02 ]

Mikael Barfred thanks for understanding and taking the the time to switch away from "puppet kick".

Generated at Sat Dec 14 18:18:20 PST 2019 using JIRA 7.7.1#77002-sha1:e75ca93d5574d9409c0630b81c894d9065296414.