-
Notifications
You must be signed in to change notification settings - Fork 123
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Print authentication error stack-trace in INFO level #2070
Conversation
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This should also be reviewed by the @cyberark/security-architects , but this would still not be the default behavior, correct? The Conjur system admin still needs to elevate the log level to INFO
?
break if line.include?("2.5.0/gems") | ||
logger.info(line) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
It should be possible to get the full output in the debug logs without a code change, so something like (pseudo-code):
line.include?("2.5.0/gems") ? logger.debug(line) : logger.info(line)
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I agree with this but wouldn't you just wrap Oren's new break
statement in something like (pseudocode) unless LOGLEVEL == 'debug'
?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I agree with this but wouldn't you just wrap Oren's new break statement in something like (pseudocode) unless LOGLEVEL == 'debug'?
I think that would probably functionality accomplish the same outcome, and that was actually what I was initially going to comment here. However, I thought it was it was awkward to read:
if ... DEBUG ...
logger.info
When that's was logger.debug
is for. I thought the suggestion above was more clear about the distinction of what was DEBUG level output and what was INFO.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
you are both correct. please see the updated code.
Do you think this is good enough for us to push? if so i will create an issue and a changelog entry
@@ -200,7 +200,8 @@ def handle_authentication_error(err) | |||
|
|||
def log_backtrace(err) | |||
err.backtrace.each do |line| | |||
logger.debug(line) | |||
break if line.include?("2.5.0/gems") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Add empty line after guard clause.
7082393
to
a2f9c68
Compare
# We want to print a minimal stack trace in INFO level so that it is easier | ||
# to understand the issue. We still want to print the full stack trace | ||
# (including the ryb gems code) so we print it in DEBUG level | ||
line.include?("2.5.0/gems") ? logger.debug(line) : logger.info(line) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I don't think I have any security concerns here. However, are we setting ourselves up to break this when we update Ruby versions? Can we dynamically get this string at runtime somehow?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Hey @orenbm, it looks like the GEM_HOME
environment variable would be a good way to provide this in a maintainable way.
That is currently /var/lib/ruby/lib/ruby/gems/2.5.0
.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
thanks, fixed the code to use that.
a2f9c68
to
d4deeb7
Compare
d4deeb7
to
04a42f6
Compare
logger.debug(line) | ||
# We want to print a minimal stack trace in INFO level so that it is easier | ||
# to understand the issue. We still want to print the full stack trace | ||
# (including the ryb gems code) so we print it in DEBUG level |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
# (including the ryb gems code) so we print it in DEBUG level | |
# (including the ruby gems code) so we print it in DEBUG level |
It might also be helpful to elaborate in the comment that this filters the trace output to only Conjur application code, and not code from the Gem dependencies.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Done
04a42f6
to
dd87330
Compare
We would like to enhance our supportability by printing a minimal stack trace that can help the reader understand the issue, without adding clutter to the log.
dd87330
to
ce3d0b2
Compare
Code Climate has analyzed commit ce3d0b2 and detected 0 issues on this pull request. The test coverage on the diff in this pull request is 100.0% (50% is the threshold). This pull request will bring the total coverage in the repository to 89.4% (0.0% change). View more on Code Climate. |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
LGTM! Thanks, @orenbm! 😄
What does this PR do?
We have a lot of cases where the customer has an authentication error
and the log level is set to INFO. In such cases, the log will show the
following:
Although we print the actual error, it sometimes doesn't help enough and we want to view the
stack trace. This requires the customer to set the log level to DEBUG and re-run the request.
Also - sometimes it adds another cycle in which we ask for debug logs.
Furthermore, the stack trace that is written in DEBUG logs is quite hard to read:
The output above actually includes 2 stack traces - one of the original error, and one of the error that we raise
in the authenticate_controller and is printed in the application_controller. We can improve our supportability by
printing the original stack trace in info level:
Still, this has some clutter and we would not want the info log (which is the default one) to include so many
lines. However, we can achieve a better output by printing only the stack trace of our app, beginning in our
code. This can be done by stopping to print the stack trace once we hit the ruby gems level. Such a log will
look like this:
The output above has the authentication error, it has a minimal stack trace that can help us (or the customer) understand the
issue easily, and it is not very long and thus doesn't add too much to the defaut INFO log.
What ticket does this PR close?
Resolves #2080
Checklists
Change log
Test coverage
Documentation
API Changes