Problem/Motivation
All DAM operations around the site started failing with a WSOD for a specific user but no other accounts. Found the root cause was an expired (see note below) unauthorized access token via the following error when attempting to click the "Remove Acquia DAM authorization" checkbox and save user profile:
The website encountered an unexpected error. Please try again later.
GuzzleHttp\Exception\ClientException: Client error: `POST redacted domain/api/rest/oauth/logout` resulted in a `404 Not Found` response: {"error":"Not Found","description":"Access token not found."} in GuzzleHttp\Exception\RequestException::create() (line 113 of /var/www/vendor/guzzlehttp/guzzle/src/Exception/RequestException.php).
GuzzleHttp\Middleware::GuzzleHttp\{closure}(Object) (Line: 204)
GuzzleHttp\Promise\Promise::callHandler(1, Object, NULL) (Line: 153)
GuzzleHttp\Promise\Promise::GuzzleHttp\Promise\{closure}() (Line: 48)
GuzzleHttp\Promise\TaskQueue->run(1) (Line: 248)
GuzzleHttp\Promise\Promise->invokeWaitFn() (Line: 224)
GuzzleHttp\Promise\Promise->waitIfPending() (Line: 269)
GuzzleHttp\Promise\Promise->invokeWaitList() (Line: 226)
GuzzleHttp\Promise\Promise->waitIfPending() (Line: 62)
GuzzleHttp\Promise\Promise->wait() (Line: 182)
GuzzleHttp\Client->request('post', 'redacted domain/api/rest/oauth/logout', Array) (Line: 95)
GuzzleHttp\Client->__call('post', Array) (Line: 105)
Drupal\media_acquiadam\AcquiadamAuthService::cancel('redacted token') (Line: 85)
media_acquiadam_unauthorize(Array, Object)
call_user_func_array('media_acquiadam_unauthorize', Array) (Line: 114)
Drupal\Core\Form\FormSubmitter->executeSubmitHandlers(Array, Object) (Line: 52)
Drupal\Core\Form\FormSubmitter->doSubmitForm(Array, Object) (Line: 601)
Drupal\Core\Form\FormBuilder->processForm('user_form', Array, Object) (Line: 320)
Drupal\Core\Form\FormBuilder->buildForm(Object, Object) (Line: 73)
Drupal\Core\Controller\FormController->getContentResult(Object, Object) (Line: 39)
Drupal\layout_builder\Controller\LayoutBuilderHtmlEntityFormController->getContentResult(Object, Object)
call_user_func_array(Array, Array) (Line: 123)
Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber->Drupal\Core\EventSubscriber\{closure}() (Line: 564)
Drupal\Core\Render\Renderer->executeInRenderContext(Object, Object) (Line: 124)
Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber->wrapControllerExecutionInRenderContext(Array, Array) (Line: 97)
Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber->Drupal\Core\EventSubscriber\{closure}() (Line: 158)
Symfony\Component\HttpKernel\HttpKernel->handleRaw(Object, 1) (Line: 80)
Symfony\Component\HttpKernel\HttpKernel->handle(Object, 1, 1) (Line: 58)
Drupal\Core\StackMiddleware\Session->handle(Object, 1, 1) (Line: 48)
Drupal\Core\StackMiddleware\KernelPreHandle->handle(Object, 1, 1) (Line: 106)
Drupal\page_cache\StackMiddleware\PageCache->pass(Object, 1, 1) (Line: 85)
Drupal\page_cache\StackMiddleware\PageCache->handle(Object, 1, 1) (Line: 265)
Drupal\shield\ShieldMiddleware->bypass(Object, 1, 1) (Line: 132)
Drupal\shield\ShieldMiddleware->handle(Object, 1, 1) (Line: 48)
Drupal\Core\StackMiddleware\ReverseProxyMiddleware->handle(Object, 1, 1) (Line: 51)
Drupal\Core\StackMiddleware\NegotiationMiddleware->handle(Object, 1, 1) (Line: 23)
Stack\StackedHttpKernel->handle(Object, 1, 1) (Line: 708)
Drupal\Core\DrupalKernel->handle(Object) (Line: 19)Steps to reproduce
- Authorize Acquia DAM for an account to obtain a token.
- Wait for token to expire* (see note below)
- Attempt to use "Remove Acquia DAM authorization" functionality
I'll note here that, since the expiration time for tokens could be a while, you could approximate this behavior for testing the handling of the response error by simply passing a garbage token instead of an expired one. The response from the API does not note the token is expired, just that it is "not found". So passing a bad token would get this same response and you could then test the error handling needed, as noted below.
Proposed resolution
So, tracing this out, this issue comes from the API returning a 401 if the given token is found to be invalid. Specifically, in media_acquiadam/media_acquiadam.module in the media_acquiadam_unauthorize() function.
Relevant code:
...
// Cancel the user token on Acquia DAM.
$cancelled = AcquiadamAuthService::cancel($acquiadam_account['acquiadam_token']);
// Remove the Acquia DAM data (mainly the token) from the user account.
if ($cancelled) {
\Drupal::service('user.data')
->set('media_acquiadam', $user->id(), 'account', []);
}
...
The issue is that, with an expired* token, the cancel() call receives a 401 Unauthorized and throws an error, causing a WSOD noting that the provided access token was not found.
My temporary workaround to unblock the user was to comment out the call to the cancel() function and also the if statement around the user.data service line. Leaving only the line that clears out the related Acquia account information.
To account for this edge case, that code should be updated to handle the 401 error and determine if the "access token not found" error was the cause. If it was, the code should continue into the if($cancelled) block to remove the bad token from the user.
It is worth noting that I did not create a patch for this because I am unaware of what other cases could cause an error here and will need to be handled. This cannot simply catch a PHP error and unlink the accounts without inspecting the error reported by the API because it may be unrelated to the token, e.g. if the service is temporarily unavailable.
Update: Created a patch for this and added it below. After some more thought, it seems that within this cancel() function, a 401 error would only be caused by a bad token being used.
Alternatively, this could also be handled a level deeper with some error handling around the post() call in Drupal\media_acquiadam\AcquiadamAuthService::cancel()
Update: Now that I have patched this, catching this error in the .module file is a more appropriate and cleaner place to address this.
A Note on the token being "Expired"
My initial assumption was that the token had expired and that was causing this issue but that may be incorrect. Where we are seeing this issue is in an active dev environment where the database is still being copied and replaced between environments when necessary. Given that, this may not be caused by a token expiration but may, instead, be a function of those databases being out of sync and having different tokens.
That point is a bit moot, however, as this bug where an invalid token creates a situation where the user cannot clear their authentication and reauthenticate to get a new token should be handled.
| Comment | File | Size | Author |
|---|---|---|---|
| #12 | 3301392-9_comparison-of-different-tokens-of-widen_redacted.png | 52.03 KB | baluertl |
| #3 | media_acquiadam_3301392.patch | 65 bytes | amitchell-p2 |
Issue fork media_acquiadam-3301392
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
Comment #2
amitchell-p2 commentedComment #3
amitchell-p2 commentedThis patch sets $cancelled = TRUE when the cancel function receives a 401 Unauthorized response, which implies that the token we are trying to cancel was already removed or cancelled. This avoids the WSOD and then allows the subsequent code to remove the bad token from the database.
Without this patch, a 401 Unauthorized response causes a WSOD before the token is removed from the database producing this bug. In that case, there is no way to remove the token and the user is stuck being unable to reauthorize with the DAM to receive an updated token.
Comment #4
amitchell-p2 commentedComment #5
amitchell-p2 commentedComment #6
chakkche commentedI will review this.
Comment #7
chakkche commentedAble to replicate this issue.
Replicating steps:
Manually modified the token and tried to remove the authorization. Getting the mentioned error.
After applying the patch able to remove the authorization.
Comment #9
baluertlI feel it worth to clarify that the issue is about the Drupal user's authentication token (marked with green) and not the site's one (marked with red):
However, by following the described steps I could not reproduce the WSOD issue as expected on the
2.xbranch. My testing steps were in order:users_datatable of the DB find your actual user account's row. Modify itsvaluefield by replacing the alphanumeric string under the serializedacquiadam_tokenkey to something non-sense (like0123456789abcdef0123456789abcdef). Ensure that the complete JSON value still starts with the term “wat_…” (acronym of Widen Access Token).Conclusion:
Because this module is being declared as “Minimally maintained & No further development” I would refrain from introducing changes on this scale in such cardinal logic as authentication is. Two factors, a two-year-old issue and an active development of an external system (the Widen software behind the Acquia DAM service) together can easily result that this issue is not present anymore. The decision is of course up to the module maintainers.
Comment #10
baluertlComment #11
baluertlComment #12
baluertlComment #13
baluertlUpdate: I just realised that my testing procedure described in #9 above is unrelated to this original issue starting from step #4. The unauthentication link needs to be clicked on the /user/{UID}/edit page instead, and then WSOD happens indeed. Sorry for the confuse.
Comment #15
baluertlComment #18
japerry