Skip to content
This repository has been archived by the owner on Dec 7, 2020. It is now read-only.

Zap logging #237

Merged
merged 3 commits into from
Jun 12, 2017
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,7 @@ FEATURES
* added the --enable-encrypted-token option to enable encrypting the access token:wq
* added the --skip-client-id option to permit skipping the verification of the auduence against client in token [#PR236](https://github.com/gambol99/keycloak-proxy/pull/236)
* updated the base image to apline 3.6 in commit [0fdebaf821](https://github.com/gambol99/keycloak-proxy/pull/236/commits/0fdebaf8215e9480896f01ec7ab2ef7caa242da1)
* moved to use zap for the logging [#PR237](https://github.com/gambol99/keycloak-proxy/pull/237)

BREAKING CHANGES:
* the proxy no longer uses prefixes for resources, if you wish to use wildcard urls you need
Expand Down
77 changes: 48 additions & 29 deletions Godeps/Godeps.json

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

3 changes: 3 additions & 0 deletions doc.go
Original file line number Diff line number Diff line change
Expand Up @@ -236,6 +236,9 @@ type Config struct {
ForwardingPassword string `json:"forwarding-password" yaml:"forwarding-password" usage:"password to use when logging into the openid provider"`
// ForwardingDomains is a collection of domains to signs
ForwardingDomains []string `json:"forwarding-domains" yaml:"forwarding-domains" usage:"list of domains which should be signed; everything else is relayed unsigned"`

// DisableAllLogging indicates no logging at all
DisableAllLogging bool `json:"disable-all-logging" yaml:"disable-all-logging" usage:"disables all logging to stdout and stderr"`
}

// getVersion returns the proxy version
Expand Down
91 changes: 36 additions & 55 deletions forwarding.go
Original file line number Diff line number Diff line change
Expand Up @@ -20,10 +20,10 @@ import (
"net/http"
"time"

log "github.com/Sirupsen/logrus"
"github.com/gambol99/go-oidc/jose"
"github.com/gambol99/go-oidc/oidc"
"github.com/labstack/echo"
"go.uber.org/zap"
)

// proxyMiddleware is responsible for handles reverse proxy request to the upstream endpoint
Expand All @@ -39,9 +39,9 @@ func (r *oauthProxy) proxyMiddleware() echo.MiddlewareFunc {

// step: is this connection upgrading?
if isUpgradedConnection(cx.Request()) {
log.Debugf("upgrading the connnection to %s", cx.Request().Header.Get(headerUpgrade))
r.log.Debug("upgrading the connnection", zap.String("client_ip", cx.RealIP()))
if err := tryUpdateConnection(cx.Request(), cx.Response().Writer, r.endpoint); err != nil {
log.WithFields(log.Fields{"error": err.Error()}).Errorf("failed to upgrade the connection")
r.log.Error("failed to upgrade connection", zap.Error(err))
cx.NoContent(http.StatusInternalServerError)
return nil
}
Expand Down Expand Up @@ -73,9 +73,7 @@ func (r *oauthProxy) forwardProxyHandler() func(*http.Request, *http.Response) {
// step: create oauth client
client, err := r.client.OAuthClient()
if err != nil {
log.WithFields(log.Fields{
"error": err.Error(),
}).Fatal("failed to create an oauth client")
r.log.Fatal("failed to create oauth client", zap.Error(err))
}

// step: the loop state
Expand All @@ -102,17 +100,13 @@ func (r *oauthProxy) forwardProxyHandler() func(*http.Request, *http.Response) {

// step: do we have a access token
if state.login {
log.WithFields(log.Fields{
"username": r.config.ForwardingUsername,
}).Infof("requesting access token for user")
r.log.Info("requesting access token for user",
zap.String("username", r.config.ForwardingUsername))

// step: login into the service
resp, err := client.UserCredsToken(r.config.ForwardingUsername, r.config.ForwardingPassword)
if err != nil {
log.WithFields(log.Fields{
"error": err.Error(),
}).Error("failed to login to authentication service")

r.log.Error("failed to login to authentication service", zap.Error(err))
// step: back-off and reschedule
<-time.After(time.Duration(5) * time.Second)
continue
Expand All @@ -121,10 +115,7 @@ func (r *oauthProxy) forwardProxyHandler() func(*http.Request, *http.Response) {
// step: parse the token
token, identity, err := parseToken(resp.AccessToken)
if err != nil {
log.WithFields(log.Fields{
"error": err.Error(),
}).Errorf("failed to parse the access token")

r.log.Error("failed to parse the access token", zap.Error(err))
// step: we should probably hope and reschedule here
<-time.After(time.Duration(5) * time.Second)
continue
Expand All @@ -138,40 +129,34 @@ func (r *oauthProxy) forwardProxyHandler() func(*http.Request, *http.Response) {
state.login = false
state.refresh = resp.RefreshToken

log.WithFields(log.Fields{
"subject": state.identity.ID,
"email": state.identity.Email,
"expires": state.expiration.Format(time.RFC3339),
}).Infof("successfully retrieved access token for subject")
r.log.Info("successfully retrieved access token for subject",
zap.String("subject", state.identity.ID),
zap.String("email", state.identity.Email),
zap.String("expires", state.expiration.Format(time.RFC3339)))

} else {
log.WithFields(log.Fields{
"subject": state.identity.ID,
"email": state.identity.Email,
}).Infof("access token is about to expiry")
r.log.Info("access token is about to expiry",
zap.String("subject", state.identity.ID),
zap.String("email", state.identity.Email))

// step: if we a have a refresh token, we need to login again
if state.refresh != "" {
log.WithFields(log.Fields{
"subject": state.identity.ID,
"email": state.identity.Email,
"expires": state.expiration.Format(time.RFC3339),
}).Infof("attempting to refresh the access token")
r.log.Info("attempting to refresh the access token",
zap.String("subject", state.identity.ID),
zap.String("email", state.identity.Email),
zap.String("expires", state.expiration.Format(time.RFC3339)))

// step: attempt to refresh the access
token, expiration, err := getRefreshedToken(r.client, state.refresh)
if err != nil {
state.login = true
switch err {
case ErrRefreshTokenExpired:
log.WithFields(log.Fields{
"subject": state.identity.ID,
"email": state.identity.Email,
}).Warningf("the refresh token has expired, need to login again")
r.log.Warn("the refresh token has expired, need to login again",
zap.String("subject", state.identity.ID),
zap.String("email", state.identity.Email))
default:
log.WithFields(log.Fields{
"error": err.Error(),
}).Errorf("failed to refresh the access token")
r.log.Error("failed to refresh the access token", zap.Error(err))
}
continue
}
Expand All @@ -183,33 +168,29 @@ func (r *oauthProxy) forwardProxyHandler() func(*http.Request, *http.Response) {
state.login = false

// step: add some debugging
log.WithFields(log.Fields{
"subject": state.identity.ID,
"email": state.identity.Email,
"expires": state.expiration.Format(time.RFC3339),
}).Infof("successfully refreshed the access token")
r.log.Info("successfully refreshed the access token",
zap.String("subject", state.identity.ID),
zap.String("email", state.identity.Email),
zap.String("expires", state.expiration.Format(time.RFC3339)))

} else {
log.WithFields(log.Fields{
"subject": state.identity.ID,
"email": state.identity.Email,
}).Infof("session does not support refresh token, acquiring new token")
r.log.Info("session does not support refresh token, acquiring new token",
zap.String("subject", state.identity.ID),
zap.String("email", state.identity.Email))

// step: we don't have a refresh token, we must perform a login again
// we don't have a refresh token, we must perform a login again
state.wait = false
state.login = true
}
}

// step: wait for an expiration to come close
// wait for an expiration to come close
if state.wait {
// step: set the expiration of the access token within a random 85% of actual expiration
// set the expiration of the access token within a random 85% of actual expiration
duration := getWithin(state.expiration, 0.85)

log.WithFields(log.Fields{
"token_expiration": state.expiration.Format(time.RFC3339),
"renewel_duration": duration.String(),
}).Infof("waiting for expiration of access token")
r.log.Info("waiting for expiration of access token",
zap.String("token_expiration", state.expiration.Format(time.RFC3339)),
zap.String("renewel_duration", duration.String()))

<-time.After(duration)
}
Expand Down
Loading