Stop hiding critical debug info in helpers (#988) #997

alex-harvey-z3q · 2021-04-06T15:25:57Z

Before this, the catch_exceptions (decorator) function would catch a
range of exceptions and then hide all but the error message from the
caller.

Over the years, this has caused some of us a lot of lost time, as it is
consequently not always clear what actually caused Sceptre to fail.

Simply re-raising the original exception provides valuable information
to allow users of Sceptre to debug their failing code.

This changes the function to re-raise in debug mode only.

PR Checklist

Wrote a good commit message & description [see guide below].
Commit message starts with [Resolve #issue-number].
Added/Updated unit tests.
Added/Updated integration tests (if applicable).
All unit tests (make test) are passing.
Used the same coding conventions as the rest of the project.
The new code passes flake8 (make lint) checks.
The PR relates to only one subject with a clear title.
and description in grammatically correct, complete sentences.

Approver/Reviewer Checklist

Before merge squash related commits.

Other Information

Guide to writing a good commit

alex-harvey-z3q · 2021-04-07T06:59:04Z

I am not able to see why the build is failing here but make lint and make test work fine for me.

zaro0508 · 2021-04-07T17:40:57Z

build fixed with PR #998

zaro0508 · 2021-04-08T16:04:37Z

I'm not sure doing this across the board is better than the existing functionality. For example when i run scpeptre (ver 2.4.0) with an invalid profile i get this..

➜ sceptre --var "profile=my-invalid-profile" --var "region=us-east-1" --ignore-dependencies launch develop/docker-runner.yaml
Do you want to launch 'develop/docker-runner.yaml' [y/N]: y
[2021-04-08 08:42:20] - develop/docker-runner - Launching Stack
"The config profile (my-invalid-profile) could not be found"

when i run with this change I get this..

invalid profile console out

➜  sceptre --var "profile=my-invalid-profile" --var "region=us-east-1" --ignore-dependencies launch develop/docker-runner.yaml
Do you want to launch 'develop/docker-runner.yaml' [y/N]: y
[2021-04-08 08:41:07] - develop/docker-runner - Launching Stack
"The config profile (my-invalid-profile) could not be found"
Traceback (most recent call last):
	File "/Users/zaro0508/.virtualenvs/bla9/bin/sceptre", line 8, in <module>
		sys.exit(cli())
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/click/core.py", line 829, in __call__
		return self.main(*args, **kwargs)
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/click/core.py", line 782, in main
		rv = self.invoke(ctx)
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/click/core.py", line 1259, in invoke
		return _process_result(sub_ctx.command.invoke(sub_ctx))
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/click/core.py", line 1066, in invoke
		return ctx.invoke(self.callback, **ctx.params)
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/click/core.py", line 610, in invoke
		return callback(*args, **kwargs)
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/click/decorators.py", line 21, in new_func
		return f(get_current_context(), *args, **kwargs)
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/sceptre/cli/helpers.py", line 35, in decorated
		return func(*args, **kwargs)
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/sceptre/cli/launch.py", line 38, in launch_command
		responses = plan.launch()
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/sceptre/plan/plan.py", line 130, in launch
		return self._execute(*args)
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/sceptre/plan/plan.py", line 40, in _execute
		return executor.execute(*args)
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/sceptre/plan/executor.py", line 55, in execute
		stack, status = future.result()
	File "/usr/local/var/pyenv/versions/3.8.6/lib/python3.8/concurrent/futures/_base.py", line 432, in result
		return self.__get_result()
	File "/usr/local/var/pyenv/versions/3.8.6/lib/python3.8/concurrent/futures/_base.py", line 388, in __get_result
		raise self._exception
	File "/usr/local/var/pyenv/versions/3.8.6/lib/python3.8/concurrent/futures/thread.py", line 57, in run
		result = self.fn(*self.args, **self.kwargs)
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/sceptre/plan/executor.py", line 62, in _execute
		result = getattr(actions, self.command)(*args)
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/sceptre/hooks/__init__.py", line 104, in decorated
		response = func(self, *args, **kwargs)
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/sceptre/plan/actions.py", line 192, in launch
		existing_status = self._get_status()
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/sceptre/plan/actions.py", line 748, in _get_status
		status = self._describe()["Stacks"][0]["StackStatus"]
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/sceptre/plan/actions.py", line 740, in _describe
		return self.connection_manager.call(
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/sceptre/connection_manager.py", line 51, in decorated
		return func(*args, **kwargs)
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/sceptre/connection_manager.py", line 252, in call
		client = self._get_client(service, region, profile, stack_name, iam_role)
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/sceptre/connection_manager.py", line 216, in _get_client
		self._clients[key] = self._get_session(
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/sceptre/connection_manager.py", line 144, in _get_session
		session = boto3.session.Session(**config)
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/boto3/session.py", line 80, in __init__
		self._setup_loader()
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/boto3/session.py", line 120, in _setup_loader
		self._loader = self._session.get_component('data_loader')
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/botocore/session.py", line 685, in get_component
		return self._components.get_component(name)
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/botocore/session.py", line 924, in get_component
		self._components[name] = factory()
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/botocore/session.py", line 158, in <lambda>
		lambda:  create_loader(self.get_config_variable('data_path')))
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/botocore/session.py", line 240, in get_config_variable
		return self.get_component('config_store').get_config_variable(
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/botocore/configprovider.py", line 313, in get_config_variable
		return provider.provide()
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/botocore/configprovider.py", line 410, in provide
		value = provider.provide()
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/botocore/configprovider.py", line 471, in provide
		scoped_config = self._session.get_scoped_config()
	File "/Users/zaro0508/.virtualenvs/bla9/lib/python3.8/site-packages/botocore/session.py", line 340, in get_scoped_config
		raise ProfileNotFound(profile=profile_name)
botocore.exceptions.ProfileNotFound: The config profile (my-invalid-profile) could not be found

Would it make sense to pinpoint the problem you were having in issue #988 first then determine a fix that's more targeted? Also would you not get more debug info if you simply pass in the sceptre --debug flag?

alex-harvey-z3q · 2021-04-08T16:51:21Z

Would it make sense to pinpoint the problem you were having in issue #988 first then determine a fix that's more targeted? Also would you not get more debug info if you simply pass in the sceptre --debug flag?

We do use --debug and that does not really help. I solved the issue in #988 although it took me a while because the stack trace was hidden. When I finally figured out how to unhide the stack trace, it then became obvious what the problem was. (In that case, it was because I didn't have IAM permissions in the account it was trying to read a stack_output_external from.)

I think users should not lose development time just to make output look prettier when an exception is raised. If pretty output is required, I personally think the specific exception where pretty output is required should be handled.

craighurley · 2021-04-08T20:51:10Z

If --debug is not displaying the exception, maybe that's the change that should be made?

alex-harvey-z3q · 2021-04-08T23:31:22Z

If --debug is not displaying the exception, maybe that's the change that should be made?

@craighurley Yes true. Would you like me to refactor and only show the stack trace in debug mode?

zxiiro · 2021-04-10T12:54:30Z

I agree with making --debug display more information including the stack trace. If it's not passed displaying less information.

craighurley · 2021-04-26T10:28:07Z

Hi @alexharv074 , I think refactoring to only show the strace in debug would be great, but we should consider addressing the root cause as @zaro0508 mentioned.

alex-harvey-z3q · 2021-04-26T16:27:52Z

Hi @alexharv074 , I think refactoring to only show the strace in debug would be great, but we should consider addressing the root cause as @zaro0508 mentioned.

@craighurley Could you clarify what you mean by fixing the "root cause"? The root cause was that I did not have permission to read from an S3 bucket.

craighurley · 2021-04-27T04:13:00Z

Hi @alexharv074 , for the root cause what I meant was that if the error you were getting in #988 was not helpful, could it be caught with better matching and print something more useful for you (without --debug), for example:

sceptre/sceptre/template.py

Lines 262 to 269 in 881c6bd

    
           except botocore.exceptions.ClientError as exp: 
        
               if exp.response["Error"]["Message"] == "Not Found": 
        
                   self.logger.debug( 
        
                       "%s - %s bucket not found.", self.name, bucket_name 
        
                   ) 
        
                   return False 
        
               else: 
        
                   raise

That plus adding the stack trace as you described once --debug is used.

What do you think?

craighurley · 2021-05-03T11:16:23Z

Also relates to #897

alex-harvey-z3q · 2021-05-20T16:02:37Z

Hi @craighurley I agree with all your comments above. However, perhaps handling the specific exception that led me to this PR in the first place is something that belongs in a separate PR, perhaps even the one you linked just above? I say that because realistically I have forgotten how to reproduce the original issue and I am never going to find time to reproduce it. Whereas, simply refactoring this PR to only hide stack traces when mode != debug is something we can and should get merged quickly. Thoughts?

craighurley · 2021-05-21T02:36:37Z

Whereas, simply refactoring this PR to only hide stack traces when mode != debug is something we can and should get merged quickly. Thoughts?

I agree.

ngfgrant · 2021-06-02T08:11:37Z

I agree more useful debugging and errors is definitely something the project needs (I think there are plenty of open issues about this).

The main issue with this change is that users may well (and probably) do rely on status exit codes on the CLI. Removing the status code and replacing it with a dump of the stack trace isn't going to be a good solution.

Instead - better debug logging statements will help imo.

alex-harvey-z3q · 2021-06-26T02:14:23Z

Whereas, simply refactoring this PR to only hide stack traces when mode != debug is something we can and should get merged quickly. Thoughts?

I agree.

@craighurley I have a bit of time this weekend, but catch_exceptions is a decorator, and I don't know how to make the logger available inside a decorator. Any ideas?

sceptre/cli/helpers.py

Before this, the catch_exceptions function in cli/helpers would catch a range of exceptions and then hide all but the error message from the caller. Over the years, this has caused myself and others quite a lot of lost time, as it is now often quite unclear what caused Sceptre to fail. Simply re-raising the original exception provides valuable information to allow users of Sceptre to debug their failing code.

alex-harvey-z3q · 2021-10-16T03:36:02Z

@craighurley how is this version?

sceptre/cli/helpers.py

jfalkenstein

I think logging the exception might be a better approach... but I don't care too much either way.

alex-harvey-z3q · 2021-10-18T04:31:15Z

Here are some before and after examples I have collected just in the last few days to illustrate why I am keen to get this merged:

Example 1

Before

sceptre --merge-vars --dir=iam-service-jenkins-sceptre --var-file=/env/common-env.yaml --var-file=/env/iam-service-jenkins-sceptre.yaml list outputs iam-service-jenkins-sceptre.yaml --export=envvar 
"'dict object' has no attribute 'ServiceName'"

To the caller, it is really not obvious what ServiceName is, what the dict object is, whether this is a bug in Sceptre or in their own code.

After

  File "iam-service-jenkins-sceptre/config/iam-service-jenkins-sceptre.yaml", line 6, in top-level template code
    service_name: {{ var.ServiceName }}
jinja2.exceptions.UndefinedError: 'dict object' has no attribute 'ServiceName'

Now the caller knows:

This is a Jinja2 issue
The exact line in the exact file where the issue occurred.

Example 2

Before

sceptre --dir=iam-service-jenkins-sceptre --var-file=/env/common-env.yaml --var-file=/env/iam-service-jenkins-sceptre.yaml launch iam-service-jenkins-sceptre.yaml
Do you want to launch 'iam-service-jenkins-sceptre.yaml' [y/N]: y
[2021-10-18 15:04:51] - iam-service-jenkins-sceptre - Launching Stack
[2021-10-18 15:04:51] - iam-service-jenkins-sceptre - Stack is in the CREATE_COMPLETE state
[2021-10-18 15:04:51] - iam-service-jenkins-sceptre - Updating Stack
"Handler of type \"None\" not found"

After

  File "/usr/local/lib/python3.6/dist-packages/sceptre/template.py", line 335, in _get_handler_of_type                                                                            
    raise TemplateHandlerNotFoundError('Handler of type "{0}" not found'.format(type))
sceptre.exceptions.TemplateHandlerNotFoundError: Handler of type "None" not found

Ok, I can now see this is a bug or not implemented feature in Sceptre.

Example 3

Before

sceptre  --dir=iam-service-jenkins-sceptre --var-file=/env/common-env.yaml --var-file=/env/iam-service-jenkins-sceptre.yaml launch iam-service-jenkins-sceptre.yaml
Do you want to launch 'iam-service-jenkins-sceptre.yaml' [y/N]: y
[2021-10-18 15:27:38] - iam-service-jenkins-sceptre - Launching Stack
[2021-10-18 15:27:38] - iam-service-jenkins-sceptre - Stack is in the CREATE_COMPLETE state
[2021-10-18 15:27:38] - iam-service-jenkins-sceptre - Updating Stack
"iam-service-jenkins-sceptre.template.yaml.j2"

After

  File "/usr/local/lib/python3.6/dist-packages/sceptre/template_handlers/file.py", line 51, in handle                                                                             
    raise e                                                                              
  File "/usr/local/lib/python3.6/dist-packages/sceptre/template_handlers/file.py", line 38, in handle                                                                             
    {"sceptre_user_data": self.sceptre_user_data}                                   
  File "/usr/local/lib/python3.6/dist-packages/sceptre/template_handlers/helper.py", line 131, in render_jinja_template                                                           
    template = env.get_template(filename)                                                
  File "/usr/local/lib/python3.6/dist-packages/jinja2/environment.py", line 883, in get_template                                                                                  
    return self._load_template(name, self.make_globals(globals))                   
  File "/usr/local/lib/python3.6/dist-packages/jinja2/environment.py", line 857, in _load_template                                                                                
    template = self.loader.load(self, name, globals)                               
  File "/usr/local/lib/python3.6/dist-packages/jinja2/loaders.py", line 115, in load
    source, filename, uptodate = self.get_source(environment, name)               
  File "/usr/local/lib/python3.6/dist-packages/jinja2/loaders.py", line 197, in get_source                                                                                        
    raise TemplateNotFound(template)                                                                                                                                              
jinja2.exceptions.TemplateNotFound: iam-service-jenkins-sceptre.template.yaml.j2

alex-harvey-z3q force-pushed the alexharvey/improvement-re-issue-988 branch 3 times, most recently from 4df0a08 to fef7870 Compare April 7, 2021 04:31

alex-harvey-z3q force-pushed the alexharvey/improvement-re-issue-988 branch from 97af6ac to 391fbc3 Compare April 7, 2021 17:56

jfalkenstein reviewed Sep 12, 2021

View reviewed changes

sceptre/cli/helpers.py Outdated Show resolved Hide resolved

alex-harvey-z3q force-pushed the alexharvey/improvement-re-issue-988 branch 3 times, most recently from 944596c to 93a15e8 Compare October 3, 2021 10:01

jfalkenstein reviewed Oct 3, 2021

View reviewed changes

sceptre/cli/helpers.py Outdated Show resolved Hide resolved

jfalkenstein reviewed Oct 4, 2021

View reviewed changes

sceptre/cli/helpers.py Outdated Show resolved Hide resolved

alex-harvey-z3q and others added 3 commits October 16, 2021 01:54

Refactor according to Jon's suggestion

eaf0a1b

Refactor to implement Craig Hurley's suggestion

d0b8e7d

alex-harvey-z3q force-pushed the alexharvey/improvement-re-issue-988 branch from 93a15e8 to d0b8e7d Compare October 15, 2021 16:17

Restore master version of tests

1764fe3

alex-harvey-z3q requested review from zxiiro, jfalkenstein and craighurley October 16, 2021 03:33

Add unit tests

f290f68

jfalkenstein reviewed Oct 16, 2021

View reviewed changes

sceptre/cli/helpers.py Show resolved Hide resolved

jfalkenstein approved these changes Oct 17, 2021

View reviewed changes

craighurley merged commit 2b3c1d5 into Sceptre:master Oct 18, 2021

This was referenced Oct 18, 2021

Providing Meaning Errors when launching a stack group #640

Closed

Sceptre is silencing 3rd party exceptions #507

Closed

alex-harvey-z3q mentioned this pull request Oct 4, 2024

[Resolve #1519] Improve error message #1522

Closed

9 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Stop hiding critical debug info in helpers (#988) #997

Stop hiding critical debug info in helpers (#988) #997

alex-harvey-z3q commented Apr 6, 2021 •

edited

Loading

alex-harvey-z3q commented Apr 7, 2021

zaro0508 commented Apr 7, 2021

zaro0508 commented Apr 8, 2021 •

edited

Loading

alex-harvey-z3q commented Apr 8, 2021 •

edited

Loading

craighurley commented Apr 8, 2021

alex-harvey-z3q commented Apr 8, 2021

zxiiro commented Apr 10, 2021

craighurley commented Apr 26, 2021 •

edited

Loading

alex-harvey-z3q commented Apr 26, 2021

craighurley commented Apr 27, 2021 •

edited

Loading

craighurley commented May 3, 2021

alex-harvey-z3q commented May 20, 2021

craighurley commented May 21, 2021

ngfgrant commented Jun 2, 2021

alex-harvey-z3q commented Jun 26, 2021

alex-harvey-z3q commented Oct 16, 2021

jfalkenstein left a comment

alex-harvey-z3q commented Oct 18, 2021

Stop hiding critical debug info in helpers (#988) #997

Stop hiding critical debug info in helpers (#988) #997

Conversation

alex-harvey-z3q commented Apr 6, 2021 • edited Loading

PR Checklist

Approver/Reviewer Checklist

Other Information

alex-harvey-z3q commented Apr 7, 2021

zaro0508 commented Apr 7, 2021

zaro0508 commented Apr 8, 2021 • edited Loading

alex-harvey-z3q commented Apr 8, 2021 • edited Loading

craighurley commented Apr 8, 2021

alex-harvey-z3q commented Apr 8, 2021

zxiiro commented Apr 10, 2021

craighurley commented Apr 26, 2021 • edited Loading

alex-harvey-z3q commented Apr 26, 2021

craighurley commented Apr 27, 2021 • edited Loading

craighurley commented May 3, 2021

alex-harvey-z3q commented May 20, 2021

craighurley commented May 21, 2021

ngfgrant commented Jun 2, 2021

alex-harvey-z3q commented Jun 26, 2021

alex-harvey-z3q commented Oct 16, 2021

jfalkenstein left a comment

Choose a reason for hiding this comment

alex-harvey-z3q commented Oct 18, 2021

Example 1

Before

After

Example 2

Before

After

Example 3

Before

After

alex-harvey-z3q commented Apr 6, 2021 •

edited

Loading

zaro0508 commented Apr 8, 2021 •

edited

Loading

alex-harvey-z3q commented Apr 8, 2021 •

edited

Loading

craighurley commented Apr 26, 2021 •

edited

Loading

craighurley commented Apr 27, 2021 •

edited

Loading