Missing information about reason for OpenID login failure

Subscribe

This is a good start, but additionally, in the case that openid_verify_assertion() returns FALSE, would be nice to know why. openid_verify_assertion_nonce() already watchdogs different failure conditions, but the rest of openid_verify_assertion() and the functions it calls do not.

I rerolled Gábor's patch from #2 after the introduction of the /core directory.

I added extra watchdog logging to all of the various points in the openid_complete call where the $response can be returned as false.

Setting to needs review to kick off the testbot.

That patch file in #5 was empty. Attaching a patch file with actual code in it.

Added two more watchdogs to openid_association.

This looks great to me. Minor nits:

+++ b/core/modules/openid/openid.module
@@ -609,11 +620,13 @@ function openid_association($op_endpoint) {
+      watchdog('openid', 'The Openid endpoint association cannot be reached because of error @error.', array('@error' => $assoc_result->code . ' ' . $assoc_result->error), WATCHDOG_WARNING);
...
+      watchdog('openid', 'The Openid endpoint association returned an error mode.', array(), WATCHDOG_WARNING);
...
+        watchdog('openid', 'Openid direct verification failed because the request is not valid.', array(), WATCHDOG_WARNING);
...
+      watchdog('openid', 'Openid direct verification http request failed because of error @error.', array('@error' => $result->code . ' ' . $result->error), WATCHDOG_WARNING);

s/Openid/OpenID/

+++ b/core/modules/openid/openid.module
@@ -890,8 +907,10 @@ function openid_verify_assertion_signature($service, $association, $response) {
   $keys_to_sign = explode(',', $response['openid.signed']);
-
+  // Verify that the number of mandatory keys is not greater than the number
+  // of keys to sign.

Why remove the blank line?

+++ b/core/modules/openid/openid.module
@@ -980,7 +999,10 @@ function openid_verify_assertion_return_url($service, $response) {
+    watchdog('openid', 'Failed to verify the assertion return url. The return to path @return does not equal the current path @current.', array('@return' => $response['openid.return_to'], '@current' => $base_url_parts['scheme'] .'://'. $base_url_parts['host'] . request_uri()), WATCHDOG_WARNING);
...
+      watchdog('openid', 'Failed to verify the assertion return url query parameters for the property @name and the value @value.', array('@name' => $name, '@value' => $value), WATCHDOG_WARNING);

s/url/URL/

I also did not add any code to actually log these messages. We can do that in openid_authentication_page() if you think that would be a good idea.

Hm, so now we have 3 situations:

• HEAD currently watchdogs within openid_verify_assertion_nonce(), which is part of the openid_complete() sequence.
• #8 adds more watchdogs within the openid_verify_assertion() sequence.
• But other failures within openid_complete() are not watchdogged, and instead merely returned, with the statement from Gabor that if they are to be logged, they should be logged in openid_authentication_page() rather than openid_complete().

How can we apply some consistency to where logging should happen? Should we redo all of this via throwing exceptions instead, allowing the caller to have full control of whether to log or not?

I think we should replace the $messages with a general error message for the end user and replace them with watchdogs for developers. I'll propose this change in an updated patch.

I removed the messages in openid_complete and replaced them with watchdog logs. Reporting a failure to the end user is accomplished in openid.pages.inc, openid_authentication_page.

Updated the watchdog messages in openid_verify_assertion_return_url to be more explicit about what caused the error.

Small text updates after a review from Gabor. One of the watchdog strings couldn't be properly translated because of the way the variables were manipulated.

+++ b/core/modules/openid/openid.module
@@ -337,6 +337,7 @@ function openid_complete($response = array()) {
+        watchdog('openid', 'OpenID process cancelled by the service provider @service.', array('@service' => $service), WATCHDOG_WARNING);

$service is an array here, so can't be passed as a variable to watchdog().

+++ b/core/modules/openid/openid.module
@@ -989,6 +1017,15 @@ function openid_verify_assertion_return_url($service, $response) {
+      if (!isset($_GET[$name])) {
+        watchdog('openid', 'The assertion return URL query parameter "@ret_name" is not present among the request url parameters.', array('@ret_name' => $name), WATCHDOG_WARNING);
+      }
+      // Log if a return_to query parameter does not equal the value of the
+      // same parameter in the request query.
+      elseif ($_GET[$name] != $value) {
+        watchdog('openid', 'Failed to assert that the return URL query parameter "@ret_name" with the value "@ret_value" equals the request url parameter "@name" with the value "@value".', array('@ret_name' => $name, '@ret_value' => $value, '@name' => $name, '@value' => $_GET[$name]), WATCHDOG_WARNING);
+      }

I think in general in Drupal, we try to avoid truncated names like 'ret' instead of 'return'. Since this will appear in translation interfaces, I think @return_name, @return_value would be better. Also, looks like @return_name is the same as @name, so do we need them to use different tokens?

Fixed the first issue with $service by referencing $service['uri'].

For issue two, I renamed the replacement tokens to $return_value and $return_name. I assumed that the number of replacement tokens in the string needs to equal the number of replacement values in the proceeding arguments array. The docs for watchdog don't make this explicit, so I went with a cautious approach.

1. The log messages can be shortened.

2. Most of these should not be WATCHDOG_WARNINGs - only use a higher severity than the default (notice) if the logged message should matter for the site owner. I don't think that's the case in most or all of these cases.

Good points Sun. I'll get this rerolled.

1. I shortened the messages as much as possible without losing their value. The longest one at line 1089 actually helped me debug a very sticky issue with the overlay and for this reason I'd like to maintain its length.
2. I changed WATCHDOG_WARNINGs to WATCHDOG_NOTICEs

Rolled for D7 as well.

Grrr, I removed a stray carriage return in the openid_verbose_logging-1078476-17.patch and added it as another attachment, deselecting the original to list, but it showed up anyway. In any case, the second openid_verbose_logging-1078476-17.patch is the right one. The two only differ by a carriage return in the commit message to the patch.

Some messages mentions the @endpoint, and some don't. Of course we cannot provide a lot of context, but right now the level of context seems a little random. Would it make sense to include e.g. the Claimed ID in all messages?

+        watchdog('openid', 'OpenID process cancelled by the service provider at @service.', array('@service' => $service['uri']), WATCHDOG_NOTICE);

We usually refer to service provides as OpenID providers.

Endpoint URIs are referred to as @provider, @service and @endpoint. I suggest we stick to the latter.

+                watchdog('openid', 'Provider, @provider, not authorized to respond.', array('@provider' => $service['uri']), WATCHDOG_NOTICE);
...
+    watchdog('openid', 'Failed to verify that the assertion return URL "@return" equals the current URL "@current".', array('@return' => $return_to_parts['scheme'] . '://' . $return_to_parts['host'] . $return_to_parts['path'], '@current' => $current_parts['scheme'] .'://'. $current_parts['host'] . $current_parts['path']), WATCHDOG_NOTICE);

Instead of surroundings @foo with comma or quotes, I suggest you use %foo.

     if (!isset($_GET[$name]) || $_GET[$name] != $value) {
+      // Log if a return_to query parameter is not present in the request query.
+      if (!isset($_GET[$name])) {
+        watchdog('openid', 'The assertion return URL query parameter "@return_name" is not present among the request url parameters.', array('@return_name' => $name), WATCHDOG_NOTICE);
+      }
+      // Log if a return_to query parameter does not equal the value of the
+      // same parameter in the request query.
+      elseif ($_GET[$name] != $value) {
+        watchdog('openid', 'Failed to assert that the return URL query parameter "@return_name" with the value "@return_value" equals the request url parameter "@name" with the value "@value".', array('@return_name' => $name, '@return_value' => $value, '@name' => $name, '@value' => $_GET[$name]), WATCHDOG_NOTICE);
+      }
       return FALSE;
     }

I suggest you remove the outer if wrapper and instead return FALSE after each watchdog call. No need to check for the same thing twice.

Likewise in openid_complete() when checking for $_SESSION['openid']['service']['uri'] and $_SESSION['openid']['service']['claimed_id']: If you want to check for the two values independently rather having one combined error message (something like “service and/or claimed_id missing”), I suggest you the two checks to the top and return early if they fail. This keeps the error message immediately below the detection of the error, and by returning early we can get rid of the very deep nesting of if clauses – both of these should make the code easier to read.

I.e. instead of doing this:

if (foo) {
  // ... many lines of code ...
}
else {
  watchdog();
};
return FALSE;

I suggest we do this:

if (!foo) {
  watchdog();
  return FALSE;
}
// ... many lines of code ...

This may sound like a big change, but it is basically just moving existing code around, combined with a lot of indentation changes. What do you think of this?

               if (!in_array($service['uri'], $uris)) {
+                watchdog('openid', 'Provider, @provider, not authorized to respond.', array('@provider' => $service['uri']), WATCHDOG_NOTICE);

This error message is not quite accurate if the openid_discovery() call right above failed (e.g. if the remote server temporarily failed to respond). In fact, in that case $uri is undefined, so this is a bug in the current code. But it would be nice if you could make two separate error messages for this event. Also, I think this specific error messages should include both $service['uri'] and $claimed_id.

@c960657, you should definitely propose the changes in a patch rather than text descriptions. It'll get them closer to being committed faster!

It looks like this bugfix is relevant for D7 so bumping back to there because of https://www.drupal.org/node/2116417. The D7 patch from #20 still applies.