Jira (PUP-10150) Ruby stacktraces no longer interleave Puppet Code stacktraces

0 views
Skip to first unread message

Justin Stoller (JIRA)

unread,
Nov 21, 2019, 1:52:04 PM11/21/19
to puppe...@googlegroups.com
Justin Stoller updated an issue
 
Puppet / Bug PUP-10150
Ruby stacktraces no longer interleave Puppet Code stacktraces
Change By: Justin Stoller
Summary: Ruby stacktraces no longer interleave Puppet Stack Trace is cleared before exception handlers can query it Code stacktraces
Add Comment Add Comment
 
This message was sent by Atlassian JIRA (v7.7.1#77002-sha1:e75ca93)
Atlassian logo

Justin Stoller (JIRA)

unread,
Nov 21, 2019, 1:56:04 PM11/21/19
to puppe...@googlegroups.com
Justin Stoller commented on Bug PUP-10150
 
Re: Ruby stacktraces no longer interleave Puppet Code stacktraces

I've updated the title with what I think is the user facing effect.

wrt the concern about not having a puppet stack available at the time of error formatting I think we could updated `ExternalFileError` to store the `PuppetStack.stacktrace` on creation and then extend the formatting to either print the puppet stack, ruby stack, or interleave them based on configuration.

I'm unsure how valuable different parts of that work are, so I've also brought this ticket up to the Puppet community mailing list.

Glenn Sarti (JIRA)

unread,
Nov 21, 2019, 10:39:04 PM11/21/19
to puppe...@googlegroups.com
Glenn Sarti commented on Bug PUP-10150

I'll add some more context as to how I found this. The VSCode extension offers a debugging facility. As part of that, when an exception occurs it queries the current call stack. Internally in the Debug Server, I've monkey patched the compiler so I can trap the exception and then query the available Puppet Stack.

As per my original ticket title, because the PuppetStack is popped BEFORE the exception is handled I couldn't get access to the Puppet call stack. This behaviour is different to a regular Ruby Stack, where the call stack is not modified.

Now I know that my use case is far from normal, and that I'm using monkey patches and private APIs, so any breakages aren't really a Puppet problem. The missing tracing information in the stacktrace as all I could think of from a regular user point of view.

Given this nested manifest

class nest1 {
  fail('somethinng')
}
 
class nest2 {
  include nest1
}
 
include nest2

And some basic puts debugging ....

STACK PUSH - An object is pushed onto the PuppetStack
STACK CALLING - PuppetStack is calling the actual code.
STACK POP - An object is popped onto the PuppetStack

So you can see the stack calling the evaluator, then the include function twice, and finally the fail function

C:\Source\puppet [master ≡ +0 ~4 -0 !]> be puppet apply tmp\test.pp
Warning: Facter: Fact resolution fact='puppet_classes', resolution='<anonymous>' resolved to an invalid value: Expected all to be one of [Integer, Float, TrueClass, FalseClass, NilClass, String, Array, Hash], but was Symbol
STACK PUSH
STACK CALLING #<Puppet::Pops::Evaluator::EvaluatorImpl:0x00000000076eb778 @migration_checker=#<Puppet::Pops::Migration::MigrationChecker:0x00000000076eb110>>.evaluate  Puppet::Pops::Evaluator::EvaluatorImpl
STACK PUSH
STACK CALLING #<#<Class:0x00000000076dbe18>:0x00000000076dba30 @closure_scope=nil, @loader=(ModuleLoader::FileBased 'puppet_system' '')>.call  include
STACK PUSH
STACK CALLING #<#<Class:0x00000000076dbe18>:0x00000000076dba30 @closure_scope=nil, @loader=(ModuleLoader::FileBased 'puppet_system' '')>.call  include
STACK PUSH
STACK CALLING #<#<Class:0x00000000076a2578>:0x00000000076a2230 @closure_scope=nil, @loader=(ModuleLoader::FileBased 'puppet_system' '')>.call  fail
CALLING function 3x function_fail
STACK POP
Puppet::Pops::Evaluator   RESCUE Puppet::ParseError                <--------- This is where the exception object is created
Puppet::Pops::Evaluator   RESCUE Puppet::PreformattedError
STACK POP
Puppet::Pops::Evaluator   RESCUE Puppet::PreformattedError
Puppet::Pops::Evaluator   RESCUE Puppet::PreformattedError
STACK POP
Puppet::Pops::Evaluator   RESCUE Puppet::PreformattedError
Puppet::Pops::Evaluator   RESCUE Puppet::PreformattedError
STACK POP
Puppet::Pops::Evaluator   RESCUE Puppet::PreformattedError
 
<--------- This is where the exception can be trapped
 
Error: Evaluation Error: Error while evaluating a Function Call, somethinng (file: C:/Source/puppet/tmp/test.pp, line: 2, column: 3) on node glenn.sarti-r90qu2hx

You can see that the exception object is created at the beginning, but by the time the compiler can actually trapped/rescued, the PuppetStack stack has been modified. Therefore the exception is out-of-sync with the Puppetstack. Previously this wasn't a problem because the ruby call stack is preserved for us.

Glenn Sarti (JIRA)

unread,
Nov 21, 2019, 10:45:03 PM11/21/19
to puppe...@googlegroups.com
Glenn Sarti commented on Bug PUP-10150

I like the idea of extending ExternalFileError class

I did a quick proof of concept for it

C:\Source\puppet [master ≡ +0 ~4 -0 !]> be puppet apply tmp\test.pp
Warning: Facter: Fact resolution fact='puppet_classes', resolution='<anonymous>' resolved to an invalid value: Expected all to be one of [Integer, Float, TrueClass, FalseClass, NilClass, String, Array, Hash], but was Symbol
STACK PUSH
STACK CALLING #<Puppet::Pops::Evaluator::EvaluatorImpl:0x00000000076b4a70 @migration_checker=#<Puppet::Pops::Migration::MigrationChecker:0x00000000076b4408>>.evaluate  Puppet::Pops::Evaluator::EvaluatorImpl
STACK PUSH
STACK CALLING #<#<Class:0x00000000076a50e8>:0x00000000076a4d00 @closure_scope=nil, @loader=(ModuleLoader::FileBased 'puppet_system' '')>.call  include
STACK PUSH
STACK CALLING #<#<Class:0x00000000076a50e8>:0x00000000076a4d00 @closure_scope=nil, @loader=(ModuleLoader::FileBased 'puppet_system' '')>.call  include
STACK PUSH
STACK CALLING #<#<Class:0x00000000076877f0>:0x00000000076874a8 @closure_scope=nil, @loader=(ModuleLoader::FileBased 'puppet_system' '')>.call  fail
CALLING function 3x function_fail
STACK POP
Puppet::Pops::Evaluator   RESCUE Puppet::ParseError
Puppet::Pops::Evaluator   RESCUE Puppet::PreformattedError
STACK POP
Puppet::Pops::Evaluator   RESCUE Puppet::PreformattedError
Puppet::Pops::Evaluator   RESCUE Puppet::PreformattedError
STACK POP
Puppet::Pops::Evaluator   RESCUE Puppet::PreformattedError
Puppet::Pops::Evaluator   RESCUE Puppet::PreformattedError
STACK POP
Puppet::Pops::Evaluator   RESCUE Puppet::PreformattedError
Error: Evaluation Error: Error while evaluating a Function Call, somethinng (file: C:/Source/puppet/tmp/test.pp, line: 2, column: 3) on node glenn.sarti-r90qu2hx
CURRENT PUPPET_STACK []
PUPPET STACK IN EXCEPTION [["C:/Source/puppet/tmp/test.pp", 6], ["C:/Source/puppet/tmp/test.pp", 9], ["C:/Source/puppet/tmp/test.pp", 0]]

Note that the exception based stack does show the include functions, but not the fail call. Again, this is due to the Stack being popped BEFORE a rescue can be done.

Which raises a question, Does the stack pop call need to be in an ensure?

Glenn Sarti (JIRA)

unread,
Nov 21, 2019, 11:03:04 PM11/21/19
to puppe...@googlegroups.com
Glenn Sarti commented on Bug PUP-10150

As for the questions in the puppet-dev email:

> Is interleaving the Puppet stack trace into the Ruby stack trace valuable to most users (and should go back to being the default)?

It's very useful as a Puppet developer, and for Customer Support escalating to engineering.
But as a beginner/intermediate user, the stack trace from ruby is over-whelming.

> Are there workflows where you'd like to see just one (the Puppet stack), the other (Ruby), or both (ie, do we need more trace options, and if so how important are they relative to each other)?

Debugging Control Repos, seeing which manifests call others, is very useful.

Justin Stoller (JIRA)

unread,
Nov 21, 2019, 11:48:03 PM11/21/19
to puppe...@googlegroups.com

re: the last puppet function isn't in the stack with the extension of ExternalFileError. I have a hunch that the error which `fail` is throwing (which is a ParseError and should contain the correct PuppetStack) is being caught, wrapped, and re-thrown between the fail throwing it and the last include being called. Maybe in AST.safeevaluate? I think that is a solvable problem though w/o removing the ensure and I'd be happy to do more spelunking after we get some more comment from the community.

Justin Stoller (JIRA)

unread,
Nov 21, 2019, 11:49:04 PM11/21/19
to puppe...@googlegroups.com

Debugging Control Repos, seeing which manifests call others, is very useful.

Is that the value in a Puppet only stack or both interleaved?

Glenn Sarti (JIRA)

unread,
Nov 22, 2019, 12:10:05 AM11/22/19
to puppe...@googlegroups.com
Glenn Sarti commented on Bug PUP-10150

> Is that the value in a Puppet only stack or both interleaved?

Puppet stack probably.

Maybe more complicated but perhaps `-debug` shows puppet stack and `-trace` shows interleaved?

Glenn Sarti (JIRA)

unread,
Nov 22, 2019, 12:48:04 AM11/22/19
to puppe...@googlegroups.com
Glenn Sarti commented on Bug PUP-10150

Something else I noticed is that the new Stack uses line number 0 for the entrypoint into a manifest which is a change of behaviour.  This is important because Puppet uses Base 1 line numbers so a line number of 0 isn't valid.

 

Perhaps nil? or even ignore it?

Henrik Lindberg (JIRA)

unread,
Nov 22, 2019, 3:22:04 AM11/22/19
to puppe...@googlegroups.com

Glenn Sarti Are you saying all reported lines are off by one? (IIRC it used file == "" for the special case of "don't know the file", and line == 0 for "there are no lines or line information" or "before even getting to the first line". IIRC the reason for using 0 instead of for example nil is because the Ruby stack needed an integer value there.

Glenn Sarti (JIRA)

unread,
Nov 22, 2019, 3:58:03 AM11/22/19
to puppe...@googlegroups.com
Glenn Sarti commented on Bug PUP-10150

Glenn Sarti Are you saying all reported lines are off by one? 

No. the stack had an extra entry in it, compared to Puppet 6.10.  Using the example in the ticket description I'm seeing this in the Puppet::Pops::PuppetStack.stacktrace

[ ['C:/Source/puppet/tmp/test.pp', 9], ['/C:/Source/puppet/tmp/test.pp', 6], ['C:/Source/puppet/tmp/test.pp', 2], ['C:/Source/puppet/tmp/test.pp', 0] ]
 

In 6.10, the only stack entries that had line numbers were the 9,6 and 2 ones.

This Line Number 0 stack entry is new and I believe it's coming from here:

https://github.com/puppetlabs/puppet/blob/aaebc6cd3769c937f7da59320daadfa68ca8da23/lib/puppet/pops/evaluator/evaluator_impl.rb#L732-L744

  def eval_Program(o, scope)
    begin
      file = o.locator.file
      line = 0
      # Add stack frame for "top scope" logic. See Puppet::Pops::PuppetStack
      return Puppet::Pops::PuppetStack.stack(file, line, self, 'evaluate', [o.body, scope])
      #evaluate(o.body, scope)
    rescue Puppet::Pops::Evaluator::PuppetStopIteration => ex
      # breaking out of a file level program is not allowed
      #TRANSLATOR break() is a method that should not be translated
      raise Puppet::ParseError.new(_("break() from context where this is illegal"), ex.file, ex.line)
    end
  end

Henrik Lindberg (JIRA)

unread,
Nov 22, 2019, 4:14:04 AM11/22/19
to puppe...@googlegroups.com

That was added for PUP-4643 so the 0 has been there since February 2016 to denote that the call is coming from the "outside" as it is technically not even on the first line yet. Why you are seeing this now, and not earlier is a different question (maybe a bug in the earlier implementation?)

Glenn Sarti (JIRA)

unread,
Nov 22, 2019, 4:23:03 AM11/22/19
to puppe...@googlegroups.com
Glenn Sarti commented on Bug PUP-10150

Ahh ok.... I think (Could be wrong here) is that line number 0s aren't output in the error message which is why I see

C:/Source/puppet/lib/puppet/pops/evaluator/evaluator_impl.rb:81:in `evaluate'
C:/Source/puppet/tmp/test.pp:in `stack'
C:/Source/puppet/lib/puppet/pops/puppet_stack.rb:33:in `eval'

Glenn Sarti (JIRA)

unread,
Nov 22, 2019, 4:27:04 AM11/22/19
to puppe...@googlegroups.com
Glenn Sarti commented on Bug PUP-10150

Ahh ok found it!!

https://github.com/puppetlabs/puppet/blob/6.10.1/lib/puppet/pops/puppet_stack.rb#L21

PP_ENTRY_PATTERN = /^(.*\.pp)?:([0-9]+):in (`stack'|`block in call_function'|`<eval>')/

The regex wouldn't match it therefore in 6.10.1 it doesn't appear in the Puppet::Pops::PuppetStack.stacktrace call.

Josh Cooper (JIRA)

unread,
Dec 12, 2019, 12:21:04 AM12/12/19
to puppe...@googlegroups.com

Justin Stoller (JIRA)

unread,
Jan 2, 2020, 2:01:03 PM1/2/20
to puppe...@googlegroups.com
Justin Stoller commented on Bug PUP-10150
 
Re: Ruby stacktraces no longer interleave Puppet Code stacktraces

Okay, I'm going to get started on this.

Just to clarify though, the entry with a zero as the line number was supposed to be there but wasn't being output due to a bug in the previous implementation, correct? I'm going to assume that it provides some additional information and that it can stay in the new implementation. Let me know if my understanding is incorrect or if this new implementation has to be bug-for-bug compatible.

Justin Stoller (JIRA)

unread,
Jan 2, 2020, 2:12:03 PM1/2/20
to puppe...@googlegroups.com

Since I never received any community feedback regarding how to fix this I'm inclined to do this:

Add a puppet_trace setting. Then update the logging to the effect of

if Puppet[:trace]
    interleave_ruby_and_puppet_stacks()
elsif Puppet[:puppet_trace]
    just_output_puppet_stack()
else
    output_error_without_stack_info()
end

That's based on the assumption that with the new implementation of PuppetStack the expensive thing is getting the Ruby stacktrace, so it isn't a big deal to interleave if we have to get the Ruby stack anyways (and signal to noise wise I dont think it hurts). But by adding the puppet_trace flag users can see just the Puppet code that's problematic which should be both faster and have a better signal to noise level for the average Puppet author.

Let me know if those are incorrect assumption - maybe the puppet_trace bit is just yagni??

Justin Stoller (JIRA)

unread,
Jan 2, 2020, 7:33:04 PM1/2/20
to puppe...@googlegroups.com

I opened a wip pr here https://github.com/puppetlabs/puppet/pull/7899/files that always interleaves the ruby and puppet stacks. Let me know if those stacks look right, Glen.

Glenn Sarti (JIRA)

unread,
Jan 3, 2020, 1:23:03 AM1/3/20
to puppe...@googlegroups.com
Glenn Sarti commented on Bug PUP-10150

Looks good so far... what about the other puppet stack entries?

Justin Stoller (JIRA)

unread,
Jan 3, 2020, 5:08:04 PM1/3/20
to puppe...@googlegroups.com

I've gotten the just-puppet stack trace printing in that branch now. From the CLI it looks like:

puppet (bug/5.5.x/PUP-10150_stacks *$%) :: be puppet apply broken.pp --puppet_trace       
Warning: Facter: Could not find a default route. Using first non-loopback interface                       
Error: Evaluation Error: Error while evaluating a Function Call, somethinng (file: /Users/justin/Backup/code/work/puppet/broken.pp, line: 2, column: 3) on node localhost                                                                                                                                                       
/Users/justin/Backup/code/work/puppet/broken.pp:2                                                                                                               
/Users/justin/Backup/code/work/puppet/broken.pp:6                                                                                                               
/Users/justin/Backup/code/work/puppet/broken.pp:9                                                                                                               
/Users/justin/Backup/code/work/puppet/broken.pp:0

Maggie Dreyer (JIRA)

unread,
Jan 6, 2020, 5:33:05 PM1/6/20
to puppe...@googlegroups.com

Maggie Dreyer (JIRA)

unread,
Jan 6, 2020, 5:34:03 PM1/6/20
to puppe...@googlegroups.com
Maggie Dreyer updated an issue
Change By: Maggie Dreyer
Fix Version/s: PUP 6.4.5
Fix Version/s: PUP 5.5.18

Maggie Dreyer (JIRA)

unread,
Jan 6, 2020, 5:35:04 PM1/6/20
to puppe...@googlegroups.com

Maggie Dreyer (JIRA)

unread,
Jan 6, 2020, 5:37:03 PM1/6/20
to puppe...@googlegroups.com
Maggie Dreyer updated an issue
Change By: Maggie Dreyer
Release Notes Summary: Fixes a bug where stacktraces from errors no longer had the Ruby stack frames interleaved with the Puppet stack frames when using `trace`.

Also introduces a new setting `puppet_trace`, that will cause the Puppet stack to be printed without the Ruby frames interleaved. If `trace` is enabled, it overrides the value of `puppet_trace`.

Josh Cooper (JIRA)

unread,
Jan 7, 2020, 5:06:04 PM1/7/20
to puppe...@googlegroups.com

Josh Cooper (JIRA)

unread,
Jan 7, 2020, 5:06:04 PM1/7/20
to puppe...@googlegroups.com

Jean Bond (JIRA)

unread,
Jan 8, 2020, 2:59:04 PM1/8/20
to puppe...@googlegroups.com
Jean Bond updated an issue
 
Change By: Jean Bond
Release Notes Summary: Fixes This release fixes a bug where stacktraces from errors no longer had the Ruby stack frames interleaved with the Puppet stack frames when using `trace`.

Also This release also introduces a new setting , `puppet_trace`, that will cause which prints the Puppet stack to be printed without the Ruby frames interleaved. If the `trace` setting is enabled, it overrides the value of `puppet_trace`.

Josh Cooper (JIRA)

unread,
Jan 9, 2020, 2:55:03 PM1/9/20
to puppe...@googlegroups.com

Kate Medred (JIRA)

unread,
Jan 11, 2020, 5:03:04 PM1/11/20
to puppe...@googlegroups.com
Kate Medred updated an issue
 
Change By: Kate Medred
Labels: resolved-issue-added
Reply all
Reply to author
Forward
0 new messages