It's a common pattern for clients to attempt a request with an access token, and if it responds with a 401 HTTP status code, refresh and try again. Currently this module logs these as errors, which is probably log spam in the sense that it's not a very actionable error for administrators on the server-side.

Generating proper response codes is handled in #2840205: Error messages/codes should be more helpful & match spec. - this issue is for the logging component.

Command icon Show commands

Start within a Git clone of the project using the version control instructions.

Or, if you do not have SSH keys set up on git.drupalcode.org:

Comments

bradjones1 created an issue. See original summary.

e0ipso’s picture

OAuth2 logo Thank you so much for the effort you have been putting into improving this module. It helps a lot, and doesn't go unnoticed. ❤️
gueguerreiro’s picture

Status: Active » Needs review
StatusFileSize
new2.83 KB

From what I understand, these error logs come from SimpleOauthAuthenticationProvider's authenticate() function.

  public function authenticate(Request $request) {
    // Update the request with the OAuth information.
    try {
      $auth_request = $this->resourceServer->validateAuthenticatedRequest($request);
    }
    catch (OAuthServerException $exception) {
      // Procedural code here is hard to avoid.
      watchdog_exception('simple_oauth', $exception);

      return NULL;
    }

The validateAuthenticatedRequest() function from League's Oauth2 package, at least on version 7.1, which is the one this module is using, will always throw an OAuthServerException::accessDenied() exception:

public function validateAuthenticatedRequest(ServerRequestInterface $request)
    {
        return $this->getAuthorizationValidator()->validateAuthorization($request);
    }

And validateAuthorization():

    public function validateAuthorization(ServerRequestInterface $request)
    {
        if ($request->hasHeader('authorization') === false) {
            throw OAuthServerException::accessDenied('Missing "Authorization" header');
        }

        $header = $request->getHeader('authorization');
        $jwt = trim((string) preg_replace('/^(?:\s+)?Bearer\s/', '', $header[0]));

        try {
            // Attempt to parse and validate the JWT
            $token = (new Parser())->parse($jwt);
            try {
                if ($token->verify(new Sha256(), $this->publicKey->getKeyPath()) === false) {
                    throw OAuthServerException::accessDenied('Access token could not be verified');
                }
            } catch (BadMethodCallException $exception) {
                throw OAuthServerException::accessDenied('Access token is not signed', null, $exception);
            }

            // Ensure access token hasn't expired
            $data = new ValidationData();
            $data->setCurrentTime(time());

            if ($token->validate($data) === false) {
                throw OAuthServerException::accessDenied('Access token is invalid');
            }

            // Check if token has been revoked
            if ($this->accessTokenRepository->isAccessTokenRevoked($token->getClaim('jti'))) {
                throw OAuthServerException::accessDenied('Access token has been revoked');
            }

            // Return the request with additional attributes
            return $request
                ->withAttribute('oauth_access_token_id', $token->getClaim('jti'))
                ->withAttribute('oauth_client_id', $token->getClaim('aud'))
                ->withAttribute('oauth_user_id', $token->getClaim('sub'))
                ->withAttribute('oauth_scopes', $token->getClaim('scopes'));
        } catch (InvalidArgumentException $exception) {
            // JWT couldn't be parsed so return the request as is
            throw OAuthServerException::accessDenied($exception->getMessage(), null, $exception);
        } catch (RuntimeException $exception) {
            //JWR couldn't be parsed so return the request as is
            throw OAuthServerException::accessDenied('Error while decoding to JSON', null, $exception);
        }
    }

With that being the case, it seems that these can be reduced to a notice log instead? Some of those messages could still prove useful for debugging, so I don't think the logging should be outright removed.

Let me know if my assumptions are correct here. I'm providing a patch with the change to a notice level log for now. It should apply on both the 8.x-3.x and 8.x-4.x branches, as the class was unaffected by the sub-module merge.

bradjones1’s picture

Status: Needs review » Needs work
Issue tags: +DrupalCon Amsterdam 2019
rachel_norfolk’s picture

Issue tags: -DrupalCon Amsterdam 2019 +Amsterdam2019

retagging

matt_paz’s picture

segi’s picture

StatusFileSize
new740 bytes

My solution is much more simple maybe isn't enough but we are using in our project, maybe it would be useful to someone.

segi’s picture

StatusFileSize
new1.12 KB
new1.12 KB
matt_paz’s picture

The technique used by @segi is interesting and something I think we should consider/evaluate. One thing that was nice about the other patch by @gueguerreiro was that it removed the procedural code logging as well, which might be advantageous?

bradjones1’s picture

Version: 8.x-3.x-dev » 5.x-dev

3.x is no longer supported, needs to reroll/rebase against 5.x.

bradjones1’s picture

Version: 5.x-dev » 5.2.x-dev

Definitely all for removing functional calls to the logger.

simonbaese’s picture

StatusFileSize
new15.44 KB

The following patch does:
- Injects the (new) simple_oauth logger channel.
- Logs a notice with the message and hint from the OAuthServerException.
- Throws a UnauthorizedHttpException, which provides a WWW-Authenticate challenge for the requester (e.g. frontend).
- Catches the exception and forwards the response with the (new) event subscriber UnauthorizedExceptionSubscriber before Drupal logging is triggered.
- Adjust the unit test for the SimpleOauthAuthenticationProvider

Out of the scope of this issue:
- Replaces watchdog_exception() calls throughout the module with the injections of the simple_oauth logger channel.

Some thoughts:
Intercepting the authentication with an exception is actually a smart way to provide some information to the user, but we should decide where to direct this information. In my opinion it is more important to let the frontend know, that the authentication failed. Hence, I introduced the new header in the response. Further, the Drupal log should not be flooded with exceptions, if we are already passing on the notice. Introducing an event subscriber might be overkill - but we throw the exception in the first place and should also handle it.
Further, we should really consider, if logging a notice in the backend is really necessary. I can see that it might has some benefit when debugging, but in production it does not really hold any value. Maybe, we could even introduce a setting.

simonbaese’s picture

After further inspection, I think it would also be good to handle exceptions thrown by the OAuthToken controller (see line 83).

But, by now, I am convinced, it would be nice to have an adapter for the OAuthServerException to handle the errors comprehensively. I will give it a shot, when there is some time.

bradjones1’s picture

Status: Needs work » Active

Rebased #12 on 5.2.x and switched to MR workflow.

bradjones1’s picture

bradjones1’s picture

Made a few changes, including renaming the logger service to fit the usual convention, and also removing the proposed EventSubscriber in favor of decorating core's exception logging subscriber. Main reason is that we don't want to be responsible for setting the response, particularly since core does/can do things like content-type negotiation for the payload.

Another reason for #3304981: JSON and other serialization formats now handle non-4xx exceptions in core (but this is not dependent on that patch.)

bradjones1’s picture

bradjones1’s picture

Status: Needs work » Needs review
segi’s picture

StatusFileSize
new740 bytes

I re-rolled my patch if somebody use it. I have check the MR and it looks promising and it covers my little "fix" as well.

Update: This patch contains a bug. I forgot to include the RfcLogLevel class. I don't upload the new version because it's just confusing who see the issue first time.

bradjones1’s picture

Thanks, although to be clear the MR is the code that is under review, the patch is outdated and is not the subject of the issue any longer.

Arnaud Kali’s picture

@bradjones1 I don't seem to be able to review/test that patch from #12. I cant apply the patch to 5.2.x either as the code seems to be outdated. I'm seeing the merge request and actually needing it on one of my projects, I'd guess it's about to be merged and released?

bradjones1’s picture

I don't seem to be able to review/test that patch from #12. I cant apply the patch to 5.2.x either as the code seems to be outdated.

Yes, I'd consider that patch to be outdated so I can't help you here and not sure why you're trying to apply it.

I'm seeing the merge request and actually needing it on one of my projects, I'd guess it's about to be merged and released?

It will get released when it gets to RTBC, so I welcome the effort to review it. Feel free to apply the diff from the MR to your project and tell me how it goes. The fact it's an MR doesn't mean anything regarding its timeline to release. Patches are going away imminently on drupal.org, anyway.

Arnaud Kali’s picture

Thanks for your comment @bradjones1 - Even if I kinda know after I've been around on d.o for such a long time, I'm just never sure about the way to proceed. I'm re-rolling the patch against 5.2.x as I need an online link to be able to test on my platform (which already has an online API from which I need to test that code).
Thanks! I'll keep you informed of my findings.

Arnaud Kali’s picture

StatusFileSize
new15.6 KB

Missed including new files. Re-renerating the patch.

artis.bajars made their first commit to this issue’s fork.

trevorbradley’s picture

Adding a request to also look at this issue for the new 6.x branch.

Would love to have a little more control over the >3,000 daily simple_oauth errors in the logs on our high volume site.

dieterholvoet made their first commit to this issue’s fork.

dieterholvoet’s picture

I created a MR based on 6.0.x.

bojan_dev made their first commit to this issue’s fork.

bojan_dev’s picture

Status: Needs review » Needs work

Please address the phpcs issues on the MR.

dieterholvoet’s picture

Status: Needs work » Needs review

Done!

bojan_dev’s picture

Status: Needs review » Fixed
bojan_dev’s picture

Status: Fixed » Closed (fixed)

Automatically closed - issue fixed for 2 weeks with no activity.