Skip to content

ca: more informational error messages and debug logs#1912

Merged
LK4D4 merged 2 commits into
moby:masterfrom
cyli:ca-more-friendly-error-messages
Feb 2, 2017
Merged

ca: more informational error messages and debug logs#1912
LK4D4 merged 2 commits into
moby:masterfrom
cyli:ca-more-friendly-error-messages

Conversation

@cyli
Copy link
Copy Markdown
Contributor

@cyli cyli commented Feb 1, 2017

This checks the format of the swarm token so that there would be a more obvious error if the token were mis-typed (for instance, copy-pasting the join token but leaving off the last character).

This also prints out more debugging information if a node certificate fails to validate (such as the issuer, and the "not before" and "not after" dates, making certificate expiry errors easier to debug.

cc @thaJeztah

…ot certificate so

it's more obvious whether a swarm token is mistyped (for instance, copy-and-pasted wrong).

Signed-off-by: cyli <ying.li@docker.com>
Comment thread ca/config.go Outdated
if _, err := X509Cert.Verify(opts); err != nil {
fmtString := "Jan 02 15:04:05 2006 MST"
log.G(ctx).WithError(err).Debugf("invalid certificate issued by %s (not before %s, not after %s)",
X509Cert.Issuer.CommonName, X509Cert.NotBefore.Format(fmtString), X509Cert.NotAfter.Format(fmtString))
Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it would be great to compare NotBefore / NotAfter to the current wall clock time, and include the current time in the error message if it looks like a factor. It may not be obvious when a clock is out of sync.

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Actually, this suggestion is a bit silly for the log message, since it will include a timestamp automatically. But I still like the idea of including this information in the user-facing error message.

Comment thread ca/config.go Outdated
// Check to see if this certificate was signed by our CA, and isn't expired
if _, err := X509Cert.Verify(opts); err != nil {
fmtString := "Jan 02 15:04:05 2006 MST"
log.G(ctx).WithError(err).Debugf("invalid certificate issued by %s (not before %s, not after %s)",
Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd think this should be an error or warning log rather than a debug log. This information should be made very visible.

Ideally, we should include most useful information in the error that gets bubbled up to the user, so checking the logs is a last resort. Including NotBefore / NotAfter and the current system time in the user-facing error when time seems like a factor may be a good idea here.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Have removed the log message, since it gets logged elsewhere, and am just returning the timestamps in the error.

@cyli cyli force-pushed the ca-more-friendly-error-messages branch 3 times, most recently from 0030297 to 5ac3fc2 Compare February 1, 2017 21:36
@cyli
Copy link
Copy Markdown
Contributor Author

cyli commented Feb 1, 2017

err.Error() now looks like: certificate expires at Wed, 01 Feb 2017 20:39:27 UTC, and it is currently Wed, 01 Feb 2017 21:39:27 UTC: x509: certificate has expired or is not yet valid

Comment thread ca/certificates.go Outdated
now := time.Now().UTC()
if now.Before(cert.NotBefore) {
return errors.Wrap(err, fmt.Sprintf("certificate not valid before %s, and it is currently %s",
cert.NotBefore.UTC().Format(time.RFC1123), now.Format(time.RFC1123)))
Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You can use errors.Wrapf to simplify this slightly.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah right, thanks, not sure why I forgot about that function. :)

Comment thread ca/certificates.go Outdated
cert.NotBefore.UTC().Format(time.RFC1123), now.Format(time.RFC1123)))
}
return errors.Wrap(err, fmt.Sprintf("certificate expires at %s, and it is currently %s",
cert.NotAfter.UTC().Format(time.RFC1123), now.Format(time.RFC1123)))
Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You can use errors.Wrapf to simplify this slightly.

… with an expiry error.

Signed-off-by: cyli <ying.li@docker.com>
@cyli cyli force-pushed the ca-more-friendly-error-messages branch from 5ac3fc2 to aefc3e9 Compare February 1, 2017 22:49
Comment thread ca/certificates.go
// whether a certificate is not yet valid or expired, we also need to perform the expiry checks ourselves.
func verifyCertificate(cert *x509.Certificate, opts x509.VerifyOptions) error {
_, err := cert.Verify(opts)
if invalidErr, ok := err.(x509.CertificateInvalidError); ok && invalidErr.Reason == x509.Expired {
Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just want to confirm that x509.Expired is returned when NotBefore is violated as well as the NotAfter case.

Copy link
Copy Markdown
Contributor Author

@cyli cyli Feb 1, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks

@aaronlehmann
Copy link
Copy Markdown
Collaborator

LGTM

Comment thread ca/config.go
split := strings.Split(token, "-")
if len(split) != 4 || split[0] != "SWMTKN" || split[1] != "1" {
if len(split) != 4 || split[0] != "SWMTKN" || split[1] != "1" || len(split[2]) != base36DigestLen || len(split[3]) != maxGeneratedSecretLength {
return "", errors.New("invalid join token")
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Perhaps not for this PR, but should we mention what it's expected to look like?

"token should start with SWMTKN, followed by a 36 character alphanumeric code"

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I wonder whether that may be too much information to give in an error message, just because the the swarm token is: SWMTKN-<version>-<other data>, and depending on what version the token is, the rest of the token may be different.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Although at this point, there is only 1 version, so maybe we can deal with messaging other versions later :)

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, I wasn't sure either; also not if that should be done in swarmkit, or "prettied" in docker

@aaronlehmann
Copy link
Copy Markdown
Collaborator

aaronlehmann commented Feb 2, 2017 via email

@LK4D4 LK4D4 merged commit aefc3e9 into moby:master Feb 2, 2017
@cyli cyli deleted the ca-more-friendly-error-messages branch February 3, 2017 00:35
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants