Increase and standardize logging messages

server/keystore.go

@@ -202,14 +202,16 @@ func (s *KeyStore) Get(username, ssoTicket string) ([]byte, error) {
 }
 
 // Close the user's key store and wipe the associated unencrypted key
-// from memory.
-func (s *KeyStore) Close(username string) {
+// from memory. Returns true if a key was actually discarded.
+func (s *KeyStore) Close(username string) bool {
 	s.mx.Lock()
-	if k, ok := s.userKeys[username]; ok {
+	defer s.mx.Unlock()
+	k, ok := s.userKeys[username]
+	if ok {
 		wipeBytes(k.pkey)
 		delete(s.userKeys, username)
 	}
-	s.mx.Unlock()
+	return ok
 }
 
 func wipeBytes(b []byte) {

server/server.go

@@ -23,13 +23,13 @@ func (s *keyStoreServer) handleOpen(w http.ResponseWriter, r *http.Request) {
 
 	err := s.KeyStore.Open(r.Context(), req.Username, req.Password, req.TTL)
 	if err == errNoKeys {
-		log.Printf("no keys found for %s", req.Username)
+		log.Printf("Open(%s): no encrypted keys found in database", req.Username)
 	} else if err != nil {
-		log.Printf("Open(%s) error: %v", req.Username, err)
+		log.Printf("Open(%s): error: %v", req.Username, err)
 		http.Error(w, err.Error(), http.StatusInternalServerError)
 		return
 	} else {
-		log.Printf("decrypted key for %s, ttl=%d", req.Username, req.TTL)
+		log.Printf("Open(%s): decrypted key, ttl=%d", req.Username, req.TTL)
 	}
 
 	serverutil.EncodeJSONResponse(w, &emptyResponse)
@@ -44,20 +44,21 @@ func (s *keyStoreServer) handleGet(w http.ResponseWriter, r *http.Request) {
 	var resp keystore.GetResponse
 	key, err := s.KeyStore.Get(req.Username, req.SSOTicket)
 	if err == errNoKeys {
-		log.Printf("no keys for %s", req.Username)
+		log.Printf("Get(%s): no unlocked keys found in memory", req.Username)
 	} else if err != nil {
 		// Return an appropriate error code.
 		switch err {
 		case errUnauthorized, errBadUser:
 			http.Error(w, err.Error(), http.StatusForbidden)
 		default:
-			log.Printf("Get(%s) error: %v", req.Username, err)
+			log.Printf("Get(%s): error: %v", req.Username, err)
 			http.Error(w, err.Error(), http.StatusInternalServerError)
 		}
 		return
 	} else {
 		resp.HasKey = true
 		resp.Key = key
+		log.Printf("Get(%s): fetched key", req.Username)
 	}
 
 	serverutil.EncodeJSONResponse(w, &resp)
@@ -69,7 +70,9 @@ func (s *keyStoreServer) handleClose(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
-	s.KeyStore.Close(req.Username)
+	if s.KeyStore.Close(req.Username) {
+		log.Printf("Close(%s): discarded key", req.Username)
+	}
 
 	serverutil.EncodeJSONResponse(w, &emptyResponse)
 }