Improve logging of NSS errors that do not map to network errors.

Improve logging of NSS errors that do not map to network errors.

BUG=
R=jar@chromium.org

Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=259205

[Ryan Sleevi, 2014-03-21 07:40:58]

Can you explain the motivation? Was this spawned by a particular bug?

We generally try to be economical with logs - they won't be elided - and it
does not seem like this is adding any new information.

If there are errors we should be mapping, I would rather map them directly.
On Mar 21, 2014 12:38 AM, <tsniatowski@opera.com> wrote:

> Reviewers: jar, Ryan Sleevi,
>
> Description:
> Improve logging of NSS errors that do not map to network errors.
>
> BUG=
> R=jar@chromium.org
>
> Please review this at https://codereview.chromium.org/207583003/
>
> SVN Base: https://chromium.googlesource.com/chromium/src.git@master
>
> Affected files (+6, -2 lines):
>   M net/socket/nss_ssl_util.cc
>
>
> Index: net/socket/nss_ssl_util.cc
> diff --git a/net/socket/nss_ssl_util.cc b/net/socket/nss_ssl_util.cc
> index 20911d5a67bdb8da8f0fb6d2b89109950a9adb61..
> 4811e46f3934ed701f25b91c08769c2c090485cf 100644
> --- a/net/socket/nss_ssl_util.cc
> +++ b/net/socket/nss_ssl_util.cc
> @@ -357,12 +357,16 @@ int MapNSSError(PRErrorCode err) {
>        return ERR_SSL_INAPPROPRIATE_FALLBACK;
>
>      default: {
> +      const char* pr_error = PR_ErrorToName(err);
> +      if (pr_error == NULL)
> +        pr_error = "";
>        if (IS_SSL_ERROR(err)) {
> -        LOG(WARNING) << "Unknown SSL error " << err
> +        LOG(WARNING) << "Unknown SSL error " << err << " (" << pr_error
> << ")"
>                       << " mapped to net::ERR_SSL_PROTOCOL_ERROR";
>          return ERR_SSL_PROTOCOL_ERROR;
>        }
> -      LOG(WARNING) << "Unknown error " << err << " mapped to
> net::ERR_FAILED";
> +      LOG(WARNING) << "Unknown error " << err << " (" << pr_error << ")"
> +                   << " mapped to net::ERR_FAILED";
>        return ERR_FAILED;
>      }
>    }
>
>
>

To unsubscribe from this group and stop receiving emails from it, send an email
to chromium-reviews+unsubscribe@chromium.org.

[tsniatowski, 2014-03-21 07:53:27]

On 2014/03/21 07:40:58, Ryan Sleevi wrote:
> Can you explain the motivation? Was this spawned by a particular bug?
> 
> We generally try to be economical with logs - they won't be elided - and it
> does not seem like this is adding any new information.
> 
> If there are errors we should be mapping, I would rather map them directly.

The general motivation is to have a slightly more useful log in the default case
when there is no good mapping, otherwise it's necessary to dive into nss headers
to understand what could be going wrong. It's already an unconditional warning
log, and the id-to-name function is handy.

The particular error in question was SSL_ERROR_NO_CERTIFICATE caused, iirc, by a
mis-configured cert store on an embedded device. This new log ensures that in
such cases the log will contain that name and not just "-12285", which was
rather unhelpful. There's no crbug since this was a config error locally, but it
would take less time to understand with that log already in place.

[Ryan Sleevi, 2014-03-21 18:27:52]

On 2014/03/21 07:53:27, tsniatowski wrote:
> On 2014/03/21 07:40:58, Ryan Sleevi wrote:
> > Can you explain the motivation? Was this spawned by a particular bug?
> > 
> > We generally try to be economical with logs - they won't be elided - and it
> > does not seem like this is adding any new information.
> > 
> > If there are errors we should be mapping, I would rather map them directly.
> 
> The general motivation is to have a slightly more useful log in the default
case
> when there is no good mapping, otherwise it's necessary to dive into nss
headers
> to understand what could be going wrong. It's already an unconditional warning
> log, and the id-to-name function is handy.
> 
> The particular error in question was SSL_ERROR_NO_CERTIFICATE caused, iirc, by
a
> mis-configured cert store on an embedded device. This new log ensures that in
> such cases the log will contain that name and not just "-12285", which was
> rather unhelpful. There's no crbug since this was a config error locally, but
it
> would take less time to understand with that log already in place.

Can you do an optimized/release mode comparison on (!Linux, !ChromeOS)

When I looked back in Chrome 6 (yes, quite some time ago), Chrome was able to
optimize out including all the error string tables on Win/Mac. That was during
the WPO/dead code process, but I think the dead code elimination should still
stand.

I agree that it's generally helpful to include more context in logs, but for
such exceptional situations (and really, these should never happen unless
there's bugs, as you noted), we don't want to put a penalty hit for all the
normal users.

It's the natural tension between logging-on-the-client and waiting for debug :)

[tsniatowski, 2014-03-24 11:07:59]

On 2014/03/21 18:27:52, Ryan Sleevi wrote:
> Can you do an optimized/release mode comparison on (!Linux, !ChromeOS)
> 
> When I looked back in Chrome 6 (yes, quite some time ago), Chrome was able to
> optimize out including all the error string tables on Win/Mac. That was during
> the WPO/dead code process, but I think the dead code elimination should still
> stand.
> 
> I agree that it's generally helpful to include more context in logs, but for
> such exceptional situations (and really, these should never happen unless
> there's bugs, as you noted), we don't want to put a penalty hit for all the
> normal users.
> 
> It's the natural tension between logging-on-the-client and waiting for debug
:)

I had a Mac release build done, results are as follows, pre-patch\npost-patch,
based on master@cc84e7c / r258888:
139976536 Mar 24 10:18 Chromium.app/Contents/Versions/35.0.1907.0/Chromium
Framework.framework/Chromium Framework
139976648 Mar 24 10:47 Chromium.app/Contents/Versions/35.0.1907.0/Chromium
Framework.framework/Chromium Framework
i.e. a net increase of 112 bytes. For reference it's mostly the same on Linux,
137935992 - 137935880 = 112 extra bytes.

[Ryan Sleevi, 2014-03-24 17:17:49]

LGTM, just keep an eye on the sizes bots just in case.

cc wtc as FYI

[tsniatowski, 2014-03-25 06:03:38]

The CQ bit was checked by tsniatowski@opera.com

[commit-bot: I haz the power, 2014-03-25 06:03:40]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/tsniatowski@opera.com/207583003/1

[commit-bot: I haz the power, 2014-03-25 06:07:29]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2014-03-25 06:07:29]

Try jobs failed on following builders:
  tryserver.chromium on win_chromium_compile_dbg

[tsniatowski, 2014-03-25 06:19:10]

The CQ bit was checked by tsniatowski@opera.com

[commit-bot: I haz the power, 2014-03-25 06:19:21]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/tsniatowski@opera.com/207583003/1

[commit-bot: I haz the power, 2014-03-25 12:50:15]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/tsniatowski@opera.com/207583003/1

[wtc, 2014-03-25 15:29:40]

Patch set 1 LGTM. You can make the suggested change after the commit queue
commits this CL.

https://codereview.chromium.org/207583003/diff/1/net/socket/nss_ssl_util.cc
File net/socket/nss_ssl_util.cc (right):

https://codereview.chromium.org/207583003/diff/1/net/socket/nss_ssl_util.cc#n...
net/socket/nss_ssl_util.cc:360: const char* pr_error = PR_ErrorToName(err);

This variable should be named "err_name" because it is the symbolic name of
|err|.

[commit-bot: I haz the power, 2014-03-25 15:32:46]

Change committed as 259205

[wtc, 2014-03-25 15:36:05]

On 2014/03/21 07:53:27, tsniatowski wrote:
>
> The general motivation is to have a slightly more useful log in the default
case
> when there is no good mapping, otherwise it's necessary to dive into nss
headers
> to understand what could be going wrong.

I see. NSS error codes are documented in a web page that you can find by a web
search for "NSS error codes". However, I found that that web page is now on
http://www-archive.mozilla.org and the version is a very old snapshot. I will
look into how to fix that.

In any case, -12285 is documented on that page and you can use that page to look
up NSS error codes in the future.