lib/web: add package-level logger (gravitational#4645)

* lib/web: update logging to go through a package-level logger.
Updates gravitational#4110.
* Unify uses of package-level logger. Update e
* Fix linter warning and tests
* Address review comments

.gitignore

@@ -11,6 +11,7 @@ darwin
 
 # editors
 .vscode
+*.swp
 
 # Compiled binaries, Object files, Static and Dynamic libs (Shared Objects)
 out

lib/web/apiserver_test.go

@@ -282,6 +282,9 @@ func (s *WebSuite) SetUpTest(c *C) {
 	addr := utils.MustParseAddr(s.webServer.Listener.Addr().String())
 	handler.handler.cfg.ProxyWebAddr = *addr
 	handler.handler.cfg.ProxySSHAddr = *proxyAddr
+	_, sshPort, err := net.SplitHostPort(proxyAddr.String())
+	c.Assert(err, IsNil)
+	handler.handler.sshPort = sshPort
 }
 
 func (s *WebSuite) TearDownTest(c *C) {
@@ -1001,6 +1004,10 @@ func (s *WebSuite) TestWebsocketPingLoop(c *C) {
 	ws, err := s.makeTerminal(s.authPack(c, "foo"))
 	c.Assert(err, IsNil)
 
+	// flush out raw event (pty texts)
+	err = s.waitForRawEvent(ws, 5*time.Second)
+	c.Assert(err, IsNil)
+
 	var numPings int
 	start := time.Now()
 	for {

lib/web/apps.go

@@ -39,7 +39,6 @@ import (
 	"github.com/gravitational/trace"
 
 	"github.com/julienschmidt/httprouter"
-	log "github.com/sirupsen/logrus"
 )
 
 // siteAppsGet returns a list of applications in a form the UI can present.
@@ -100,7 +99,7 @@ func (h *Handler) createAppSession(w http.ResponseWriter, r *http.Request, p htt
 		return nil, trace.Wrap(err, "Unable to resolve FQDN: %v", req.FQDN)
 	}
 
-	log.Debugf("Creating application web session for %v in %v.", result.PublicAddr, result.ClusterName)
+	h.log.Debugf("Creating application web session for %v in %v.", result.PublicAddr, result.ClusterName)
 
 	// Get an auth client connected with the users identity.
 	authClient, err := ctx.GetClient()

lib/web/saml.go

@@ -29,11 +29,11 @@ import (
 	"github.com/gravitational/form"
 	"github.com/gravitational/trace"
 	"github.com/julienschmidt/httprouter"
-	log "github.com/sirupsen/logrus"
 )
 
-func (m *Handler) samlSSO(w http.ResponseWriter, r *http.Request, p httprouter.Params) (interface{}, error) {
-	log.Debugf("samlSSO start")
+func (h *Handler) samlSSO(w http.ResponseWriter, r *http.Request, p httprouter.Params) (interface{}, error) {
+	logger := h.log.WithField("auth", "saml")
+	logger.Debug("SSO start.")
 
 	query := r.URL.Query()
 	clientRedirectURL := query.Get("redirect_url")
@@ -47,11 +47,11 @@ func (m *Handler) samlSSO(w http.ResponseWriter, r *http.Request, p httprouter.P
 
 	csrfToken, err := csrf.ExtractTokenFromCookie(r)
 	if err != nil {
-		log.Warningf("unable to extract CSRF token from cookie %v", err)
+		logger.WithError(err).Warn("Unable to extract CSRF token from cookie.")
 		return nil, trace.AccessDenied("access denied")
 	}
 
-	response, err := m.cfg.ProxyClient.CreateSAMLAuthRequest(
+	response, err := h.cfg.ProxyClient.CreateSAMLAuthRequest(
 		services.SAMLAuthRequest{
 			ConnectorID:       connectorID,
 			CSRFToken:         csrfToken,
@@ -66,16 +66,16 @@ func (m *Handler) samlSSO(w http.ResponseWriter, r *http.Request, p httprouter.P
 	return nil, nil
 }
 
-func (m *Handler) samlSSOConsole(w http.ResponseWriter, r *http.Request, p httprouter.Params) (interface{}, error) {
-	log.Debugf("samlSSOConsole start")
+func (h *Handler) samlSSOConsole(w http.ResponseWriter, r *http.Request, p httprouter.Params) (interface{}, error) {
+	h.log.WithField("auth", "saml").Debug("SSO console start.")
 	req := new(client.SSOLoginConsoleReq)
 	if err := httplib.ReadJSON(r, req); err != nil {
 		return nil, trace.Wrap(err)
 	}
 	if err := req.CheckAndSetDefaults(); err != nil {
 		return nil, trace.Wrap(err)
 	}
-	response, err := m.cfg.ProxyClient.CreateSAMLAuthRequest(
+	response, err := h.cfg.ProxyClient.CreateSAMLAuthRequest(
 		services.SAMLAuthRequest{
 			ConnectorID:       req.ConnectorID,
 			ClientRedirectURL: req.RedirectURL,
@@ -91,18 +91,18 @@ func (m *Handler) samlSSOConsole(w http.ResponseWriter, r *http.Request, p httpr
 	return &client.SSOLoginConsoleResponse{RedirectURL: response.RedirectURL}, nil
 }
 
-func (m *Handler) samlACS(w http.ResponseWriter, r *http.Request, p httprouter.Params) (interface{}, error) {
+func (h *Handler) samlACS(w http.ResponseWriter, r *http.Request, p httprouter.Params) (interface{}, error) {
 	var samlResponse string
 	err := form.Parse(r, form.String("SAMLResponse", &samlResponse, form.Required()))
 	if err != nil {
 		return nil, trace.Wrap(err)
 	}
 
-	l := log.WithFields(log.Fields{trace.Component: "SAML"})
+	logger := h.log.WithField("auth", "saml")
 
-	response, err := m.cfg.ProxyClient.ValidateSAMLResponse(samlResponse)
+	response, err := h.cfg.ProxyClient.ValidateSAMLResponse(samlResponse)
 	if err != nil {
-		log.Warningf("error while processing callback: %v", err)
+		logger.WithError(err).Warn("Error while processing callback.")
 
 		message := "Unable to process callback from SAML provider."
 		// for not implemented errors it's ok to provide a more specific
@@ -122,18 +122,18 @@ func (m *Handler) samlACS(w http.ResponseWriter, r *http.Request, p httprouter.P
 
 	// if we created web session, set session cookie and redirect to original url
 	if response.Req.CreateWebSession {
-		log.Debugf("redirecting to web browser")
+		logger.Debug("Redirecting to web browser.")
 		err = csrf.VerifyToken(response.Req.CSRFToken, r)
 		if err != nil {
-			l.Warningf("unable to verify CSRF token: %v", err)
+			logger.WithError(err).Warn("Unable to verify CSRF token.")
 			return nil, trace.AccessDenied("access denied")
 		}
 		if err := SetSession(w, response.Username, response.Session.GetName()); err != nil {
 			return nil, trace.Wrap(err)
 		}
 		return nil, httplib.SafeRedirect(w, r, response.Req.ClientRedirectURL)
 	}
-	l.Debugf("samlCallback redirecting to console login")
+	logger.Debug("Callback redirecting to console login.")
 	if len(response.Req.PublicKey) == 0 {
 		return nil, trace.BadParameter("not a web or console oidc login request")
 	}

lib/web/sessions.go

@@ -41,7 +41,7 @@ import (
 	"github.com/gravitational/ttlmap"
 
 	"github.com/jonboulle/clockwork"
-	log "github.com/sirupsen/logrus"
+	"github.com/sirupsen/logrus"
 	"github.com/tstranex/u2f"
 )
 
@@ -51,7 +51,7 @@ import (
 // to the auth server on every page hit
 type SessionContext struct {
 	sync.Mutex
-	*log.Entry
+	logrus.FieldLogger
 	sess      services.WebSession
 	user      string
 	clt       auth.ClientI
@@ -329,6 +329,7 @@ func newSessionCache(proxyClient auth.ClientI, servers []utils.NetAddr, cipherSu
 		authServers:  servers,
 		closer:       utils.NewCloseBroadcaster(),
 		cipherSuites: cipherSuites,
+		log:          newPackageLogger(),
 	}
 	// periodically close expired and unused sessions
 	go cache.expireSessions()
@@ -338,6 +339,7 @@ func newSessionCache(proxyClient auth.ClientI, servers []utils.NetAddr, cipherSu
 // sessionCache handles web session authentication,
 // and holds in memory contexts associated with each session
 type sessionCache struct {
+	log logrus.FieldLogger
 	sync.Mutex
 	proxyClient auth.ClientI
 	contexts    *ttlmap.TTLMap
@@ -351,22 +353,22 @@ type sessionCache struct {
 
 // Close closes all allocated resources and stops goroutines
 func (s *sessionCache) Close() error {
-	log.Infof("[WEB] closing session cache")
+	s.log.Info("Closing session cache.")
 	return s.closer.Close()
 }
 
 // closeContext is called when session context expires from
 // cache and will clean up connections
 func closeContext(key string, val interface{}) {
 	go func() {
-		log.Infof("[WEB] closing context %v", key)
+		log.Infof("Closing context %v.", key)
 		ctx, ok := val.(*SessionContext)
 		if !ok {
-			log.Warningf("warning, not valid value type %T", val)
+			log.Warnf("Invalid value type %T.", val)
 			return
 		}
 		if err := ctx.Close(); err != nil {
-			log.Infof("failed to close context: %v", err)
+			log.Warnf("Failed to close context: %v.", err)
 		}
 	}()
 }
@@ -390,7 +392,7 @@ func (s *sessionCache) clearExpiredSessions() {
 	defer s.Unlock()
 	expired := s.contexts.RemoveExpired(10)
 	if expired != 0 {
-		log.Infof("[WEB] removed %v expired sessions", expired)
+		log.Infof("Removed %v expired sessions.", expired)
 	}
 }
 
@@ -588,11 +590,11 @@ func (s *sessionCache) ValidateSession(user, sid string) (*SessionContext, error
 		user:      user,
 		sess:      sess,
 		parent:    s,
+		FieldLogger: log.WithFields(logrus.Fields{
+			"user": user,
+			"sess": sess.GetShortName(),
+		}),
 	}
-	c.Entry = log.WithFields(log.Fields{
-		"user": user,
-		"sess": sess.GetShortName(),
-	})
 
 	ttl := utils.ToTTL(clockwork.NewRealClock(), sess.GetBearerTokenExpiryTime())
 	out, err := s.insertContext(user, sid, c, ttl)

lib/web/static.go

@@ -27,8 +27,6 @@ import (
 	"strconv"
 	"strings"
 
-	log "github.com/sirupsen/logrus"
-
 	"github.com/gravitational/teleport"
 	"github.com/gravitational/trace"
 
@@ -78,7 +76,7 @@ func NewStaticFileSystem(debugMode bool) (http.FileSystem, error) {
 				return nil, trace.Wrap(err)
 			}
 		}
-		log.Infof("[Web] Using filesystem for serving web assets: %s", debugAssetsPath)
+		log.Infof("Using filesystem for serving web assets: %s.", debugAssetsPath)
 		return http.Dir(debugAssetsPath), nil
 	}
 
@@ -198,14 +196,14 @@ func (rsc *resource) Stat() (os.FileInfo, error) {
 }
 
 func (rsc *resource) Close() (err error) {
-	log.Debugf("[web] zip::Close(%s)", rsc.file.FileInfo().Name())
+	log.Debugf("zip::Close(%s).", rsc.file.FileInfo().Name())
 	return rsc.reader.Close()
 }
 
 type ResourceMap map[string]*zip.File
 
 func (rm ResourceMap) Open(name string) (http.File, error) {
-	log.Debugf("[web] GET zip:%s", name)
+	log.Debugf("GET zip:%s.", name)
 	f, ok := rm[strings.Trim(name, "/")]
 	if !ok {
 		return nil, trace.Wrap(os.ErrNotExist)
@@ -214,5 +212,8 @@ func (rm ResourceMap) Open(name string) (http.File, error) {
 	if err != nil {
 		return nil, trace.Wrap(err)
 	}
-	return &resource{reader, f, 0}, nil
+	return &resource{
+		reader: reader,
+		file:   f,
+	}, nil
 }

lib/web/terminal.go

@@ -224,9 +224,9 @@ func (t *TerminalHandler) handler(ws *websocket.Conn) {
 	// the terminal.
 	tc, err := t.makeClient(ws)
 	if err != nil {
-		er := t.writeError(err, ws)
-		if er != nil {
-			t.log.Warnf("Unable to send error to terminal: %v: %v.", err, er)
+		writeErr := t.writeError(err, ws)
+		if writeErr != nil {
+			t.log.WithError(err).Warnf("Unable to send error to terminal: %v.", writeErr)
 		}
 		return
 	}
@@ -324,7 +324,7 @@ func (t *TerminalHandler) startPingLoop(ws *websocket.Conn) {
 				return
 			}
 		case <-t.terminalContext.Done():
-			t.log.Debugf("Terminating websocket ping loop.")
+			t.log.Debug("Terminating websocket ping loop.")
 			return
 		}
 	}
@@ -344,7 +344,7 @@ func (t *TerminalHandler) streamTerminal(ws *websocket.Conn, tc *client.Teleport
 	// Make connecting by UUID the default instead of the fallback.
 	//
 	if err != nil && strings.Contains(err.Error(), teleport.NodeIsAmbiguous) {
-		t.log.Debugf("Ambiguous hostname %q, attempting to connect by UUID (%q)", t.hostName, t.hostUUID)
+		t.log.Debugf("Ambiguous hostname %q, attempting to connect by UUID (%q).", t.hostName, t.hostUUID)
 		tc.Host = t.hostUUID
 		// We don't technically need to zero the HostPort, but future version won't look up
 		// HostPort when connecting by UUID, so its best to keep behavior consistent.
@@ -398,8 +398,9 @@ func (t *TerminalHandler) streamEvents(ws *websocket.Conn, tc *client.TeleportCl
 		// Send push events that come over the events channel to the web client.
 		case event := <-tc.EventsChannel():
 			data, err := json.Marshal(event)
+			logger := t.log.WithField("event", event.GetType())
 			if err != nil {
-				t.log.Errorf("Unable to marshal audit event %v: %v.", event.GetType(), err)
+				logger.Errorf("Unable to marshal audit event: %v.", err)
 				continue
 			}
 
@@ -408,7 +409,7 @@ func (t *TerminalHandler) streamEvents(ws *websocket.Conn, tc *client.TeleportCl
 			// UTF-8 encode the error message and then wrap it in a raw envelope.
 			encodedPayload, err := t.encoder.String(string(data))
 			if err != nil {
-				t.log.Debugf("Unable to send audit event %v to web client: %v.", event.GetType(), err)
+				logger.Debugf("Unable to send audit event to web client: %v.", err)
 				continue
 			}
 			envelope := &Envelope{
@@ -418,14 +419,14 @@ func (t *TerminalHandler) streamEvents(ws *websocket.Conn, tc *client.TeleportCl
 			}
 			envelopeBytes, err := proto.Marshal(envelope)
 			if err != nil {
-				t.log.Debugf("Unable to send audit event %v to web client: %v.", event.GetType(), err)
+				logger.Debugf("Unable to send audit event to web client: %v.", err)
 				continue
 			}
 
 			// Send bytes over the websocket to the web client.
 			err = websocket.Message.Send(ws, envelopeBytes)
 			if err != nil {
-				t.log.Errorf("Unable to send audit event %v to web client: %v.", event.GetType(), err)
+				logger.Errorf("Unable to send audit event to web client: %v.", err)
 				continue
 			}
 		// Once the terminal stream is over (and the close envelope has been sent),

lib/web/web.go

@@ -0,0 +1,34 @@
+/*
+Copyright 2020 Gravitational, Inc.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package web
+
+import (
+	"github.com/gravitational/teleport"
+
+	"github.com/gravitational/trace"
+
+	"github.com/sirupsen/logrus"
+)
+
+var log = newPackageLogger()
+
+// newPackageLogger returns a new instance of the logger
+// configured for the package
+func newPackageLogger(subcomponents ...string) logrus.FieldLogger {
+	return logrus.WithField(trace.Component,
+		teleport.Component(append([]string{teleport.ComponentWeb}, subcomponents...)...))
+}