Log authentication and login errors in info #1657

orenbm · 2020-06-29T11:47:01Z

Connected to #1377, #1655

What does this PR do?

Once an authentication or login request fails, we write the reason
to the log. We currently log it in DEBUG mode which is hard to filter
out. As this info is necessary, and customers would like to get it easily,
we would like to print it in INFO level, which is the default one.

Checklists

Change log

The CHANGELOG has been updated

Test coverage

We can't test this feature in Conjur as the log level in the tests are at DEBUG. However, this PR in the appliance will test it.

Documentation

Created this doc issue. It can be done once this PR is merged.

micahlee

Thanks for following up on this @orenbm!

I left a couple of small comments. This will probably also require an issue/PR for the appliance tests, correct?

micahlee · 2020-06-29T14:12:41Z

CHANGELOG.md

+- Print login and authentication error to the log in INFO level 
+  ([cyberark/conjur#1377](https://github.com/cyberark/conjur/issues/1377))


The guidance for changelog entries was recently updated. So these should now end with punctuation and not put the link in parens. For example:

Suggested change

- Print login and authentication error to the log in INFO level

([cyberark/conjur#1377](https://github.com/cyberark/conjur/issues/1377))

- Print login and authentication error to the log in INFO level.

[cyberark/conjur#1377](https://github.com/cyberark/conjur/issues/1377)

thanks, didn't know that.

micahlee · 2020-06-29T14:13:18Z

app/domain/authentication/security/validate_role_can_access_webservice.rb

+        validate_account_exists
+        validate_role_is_defined


It looks like these caused some rspec failures that will require test updates.

Done, thanks

Tovli

Another great enhancement :)

Tovli · 2020-06-30T05:04:40Z

app/controllers/authenticate_controller.rb

@@ -128,23 +128,24 @@ def k8s_inject_client_cert
  private

  def handle_login_error(err)
-    logger.debug("Login Error: #{err.inspect}")
+    logger.info("Login Error: #{err.inspect}")
    err.backtrace.each do |line|
      logger.debug(line)


Why do we print info level only for the first issue in the trace?

we print just the one line that customers will look for and can help them. This line prints the stack trace which is more for developers and thus is printed at DEBUG level.

Tovli · 2020-06-30T05:06:33Z

app/controllers/authenticate_controller.rb

@@ -128,23 +128,24 @@ def k8s_inject_client_cert
  private

  def handle_login_error(err)
-    logger.debug("Login Error: #{err.inspect}")
+    logger.info("Login Error: #{err.inspect}")


I think it is confusing to have a login error in INFO level. maybe it will be better to write login failed as this is the information you want to give.
Unless it is really an error and not a valid part of the business logic

it is not an error but customers (and SEs) already know to look for these messages so i don't want to change that.

Tovli · 2020-06-30T05:07:58Z

app/controllers/authenticate_controller.rb

      raise Unauthorized
    else
      raise err
    end
  end

  def handle_authentication_error(err)
-    logger.debug("Authentication Error: #{err.inspect}")
+    logger.info("Authentication Error: #{err.inspect}")
    err.backtrace.each do |line|
      logger.debug(line)


I see this is repeating itself, shouldn't we refactor this into a method?

Tovli · 2020-06-30T05:08:51Z

app/domain/authentication/security/validate_role_can_access_webservice.rb

        validate_webservice_exists
-        validate_user_is_defined
-        validate_user_has_access
+        validate_role_has_access


I wonder if moving from user to role does not create confusion for the future devs

orenbm · 2020-06-30T06:03:27Z

This will probably also require an issue/PR for the appliance tests, correct?

Yes @micahlee, I already created it and linked to it from the PR description.

Tovli

LGTM
Please see you don't have conflicts with #1656

Once an authentication or login request fails, we write the reason to the log. We currently log it in DEBUG mode which is hard to filter out. As this info is necessary, and customers would like to get it easily, we would like to print it in INFO level, which is the default one.

Previously we didn't verify that the user exists in authentication requests with the default authenticator. However, verifying this can lead to enhanced log supportability as in case a user doesn't exist it is better to log a `RoleNotFound` message rather than an `InvalidCredentials` message. Note: this message will not be returned in the response and will only be written to the log.

orenbm · 2020-06-30T09:38:21Z

@micahlee can you re-review please?

codeclimate · 2020-06-30T10:28:15Z

Code Climate has analyzed commit 5fb231d and detected 4 issues on this pull request.

Here's the issue category breakdown:

Category	Count
Complexity	4

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 86.1% (0.0% change).

View more on Code Climate.

orenbm self-assigned this Jun 29, 2020

orenbm added this to the PalmTree - sprint 2014 milestone Jun 29, 2020

This was linked to issues Jun 29, 2020

Log authentication and login failures at the info level, rather than debug #1377

Closed

Print proper message when user not exist in authn request #1655

Closed

orenbm changed the title ~~Log error in info~~ Log authentication and login errors in info Jun 29, 2020

orenbm mentioned this pull request Jun 29, 2020

Add design doc for logging #1555

Closed

orenbm requested a review from micahlee June 29, 2020 13:15

micahlee suggested changes Jun 29, 2020

View reviewed changes

Tovli suggested changes Jun 30, 2020

View reviewed changes

orenbm force-pushed the log-error-in-info branch from 3dd3c80 to 8256c34 Compare June 30, 2020 05:54

orenbm requested review from Tovli and micahlee June 30, 2020 06:05

Tovli previously approved these changes Jun 30, 2020

View reviewed changes

orenbm added 3 commits June 30, 2020 12:37

Extract error logging to separate method

5fb231d

orenbm dismissed Tovli’s stale review via 5fb231d June 30, 2020 09:37

orenbm force-pushed the log-error-in-info branch from e53788c to 5fb231d Compare June 30, 2020 09:37

micahlee approved these changes Jun 30, 2020

View reviewed changes

micahlee merged commit 0dc26b4 into master Jun 30, 2020

micahlee deleted the log-error-in-info branch June 30, 2020 13:22

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Log authentication and login errors in info #1657

Log authentication and login errors in info #1657

orenbm commented Jun 29, 2020 •

edited

micahlee left a comment

micahlee Jun 29, 2020

orenbm Jun 29, 2020

micahlee Jun 29, 2020

orenbm Jun 30, 2020

Tovli left a comment

Tovli Jun 30, 2020

orenbm Jun 30, 2020

Tovli Jun 30, 2020

orenbm Jun 30, 2020

Tovli Jun 30, 2020

orenbm Jun 30, 2020

Tovli Jun 30, 2020

orenbm commented Jun 30, 2020

Tovli left a comment

orenbm commented Jun 30, 2020

codeclimate bot commented Jun 30, 2020

		- Print login and authentication error to the log in INFO level
		([cyberark/conjur#1377](https://github.com/cyberark/conjur/issues/1377))

Log authentication and login errors in info #1657

Log authentication and login errors in info #1657

Conversation

orenbm commented Jun 29, 2020 • edited

What does this PR do?

Checklists

Change log

Test coverage

Documentation

micahlee left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Tovli left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

orenbm commented Jun 30, 2020

Tovli left a comment

Choose a reason for hiding this comment

orenbm commented Jun 30, 2020

codeclimate bot commented Jun 30, 2020

orenbm commented Jun 29, 2020 •

edited