Merge branch 'master' into 40_45_82_update_roles

internal/auth/auth.go

@@ -185,30 +185,20 @@ func Init(db *sqlx.DB,
 	configs map[string]interface{}) (*Authentication, error) {
 	auth := &Authentication{}
 	auth.db = db
-	_, err := db.Exec(`
-	CREATE TABLE IF NOT EXISTS user (
-		username varchar(255) PRIMARY KEY NOT NULL,
-		password varchar(255) DEFAULT NULL,
-		ldap     tinyint      NOT NULL DEFAULT 0, /* col called "ldap" for historic reasons, fills the "AuthSource" */
-		name     varchar(255) DEFAULT NULL,
-		roles    varchar(255) NOT NULL DEFAULT "[]",
-		email    varchar(255) DEFAULT NULL,
-		projects varchar(255) NOT NULL DEFAULT "[]");`)
-	if err != nil {
-		return nil, err
-	}
 
 	sessKey := os.Getenv("SESSION_KEY")
 	if sessKey == "" {
 		log.Warn("environment variable 'SESSION_KEY' not set (will use non-persistent random key)")
 		bytes := make([]byte, 32)
 		if _, err := rand.Read(bytes); err != nil {
+			log.Error("Error while initializing authentication -> failed to generate random bytes for session key")
 			return nil, err
 		}
 		auth.sessionStore = sessions.NewCookieStore(bytes)
 	} else {
 		bytes, err := base64.StdEncoding.DecodeString(sessKey)
 		if err != nil {
+			log.Error("Error while initializing authentication -> decoding session key failed")
 			return nil, err
 		}
 		auth.sessionStore = sessions.NewCookieStore(bytes)
@@ -216,12 +206,14 @@ func Init(db *sqlx.DB,
 
 	auth.LocalAuth = &LocalAuthenticator{}
 	if err := auth.LocalAuth.Init(auth, nil); err != nil {
+		log.Error("Error while initializing authentication -> localAuth init failed")
 		return nil, err
 	}
 	auth.authenticators = append(auth.authenticators, auth.LocalAuth)
 
 	auth.JwtAuth = &JWTAuthenticator{}
 	if err := auth.JwtAuth.Init(auth, configs["jwt"]); err != nil {
+		log.Error("Error while initializing authentication -> jwtAuth init failed")
 		return nil, err
 	}
 	auth.authenticators = append(auth.authenticators, auth.JwtAuth)
@@ -229,6 +221,7 @@ func Init(db *sqlx.DB,
 	if config, ok := configs["ldap"]; ok {
 		auth.LdapAuth = &LdapAuthenticator{}
 		if err := auth.LdapAuth.Init(auth, config); err != nil {
+			log.Error("Error while initializing authentication -> ldapAuth init failed")
 			return nil, err
 		}
 		auth.authenticators = append(auth.authenticators, auth.LdapAuth)
@@ -243,6 +236,7 @@ func (auth *Authentication) AuthViaSession(
 
 	session, err := auth.sessionStore.Get(r, "session")
 	if err != nil {
+		log.Error("Error while getting session store")
 		return nil, err
 	}
 
@@ -272,7 +266,7 @@ func (auth *Authentication) Login(
 		user := (*User)(nil)
 		if username != "" {
 			if user, _ = auth.GetUser(username); err != nil {
-				// log.Warnf("login of unkown user %#v", username)
+				// log.Warnf("login of unkown user %v", username)
 				_ = err
 			}
 		}
@@ -284,7 +278,7 @@ func (auth *Authentication) Login(
 
 			user, err = authenticator.Login(user, rw, r)
 			if err != nil {
-				log.Warnf("login failed: %s", err.Error())
+				log.Warnf("user '%s' login failed: %s", user.Username, err.Error())
 				onfailure(rw, r, err)
 				return
 			}
@@ -303,7 +297,7 @@ func (auth *Authentication) Login(
 			session.Values["projects"] = user.Projects
 			session.Values["roles"] = user.Roles
 			if err := auth.sessionStore.Save(r, rw, session); err != nil {
-				log.Errorf("session save failed: %s", err.Error())
+				log.Warnf("session save failed: %s", err.Error())
 				http.Error(rw, err.Error(), http.StatusInternalServerError)
 				return
 			}

internal/auth/jwt.go

@@ -45,11 +45,13 @@ func (ja *JWTAuthenticator) Init(auth *Authentication, conf interface{}) error {
 	} else {
 		bytes, err := base64.StdEncoding.DecodeString(pubKey)
 		if err != nil {
+			log.Warn("Could not decode JWT public key")
 			return err
 		}
 		ja.publicKey = ed25519.PublicKey(bytes)
 		bytes, err = base64.StdEncoding.DecodeString(privKey)
 		if err != nil {
+			log.Warn("Could not decode JWT private key")
 			return err
 		}
 		ja.privateKey = ed25519.PrivateKey(bytes)
@@ -58,6 +60,7 @@ func (ja *JWTAuthenticator) Init(auth *Authentication, conf interface{}) error {
 	if pubKey = os.Getenv("CROSS_LOGIN_JWT_HS512_KEY"); pubKey != "" {
 		bytes, err := base64.StdEncoding.DecodeString(pubKey)
 		if err != nil {
+			log.Warn("Could not decode cross login JWT HS512 key")
 			return err
 		}
 		ja.loginTokenKey = bytes
@@ -68,6 +71,7 @@ func (ja *JWTAuthenticator) Init(auth *Authentication, conf interface{}) error {
 	if keyFound && pubKeyCrossLogin != "" {
 		bytes, err := base64.StdEncoding.DecodeString(pubKeyCrossLogin)
 		if err != nil {
+			log.Warn("Could not decode cross login JWT public key")
 			return err
 		}
 		ja.publicKeyCrossLogin = ed25519.PublicKey(bytes)
@@ -123,13 +127,15 @@ func (ja *JWTAuthenticator) Login(
 		if t.Method == jwt.SigningMethodHS256 || t.Method == jwt.SigningMethodHS512 {
 			return ja.loginTokenKey, nil
 		}
-		return nil, fmt.Errorf("unkown signing method for login token: %s (known: HS256, HS512, EdDSA)", t.Method.Alg())
+		return nil, fmt.Errorf("AUTH/JWT > unkown signing method for login token: %s (known: HS256, HS512, EdDSA)", t.Method.Alg())
 	})
 	if err != nil {
+		log.Warn("Error while parsing jwt token")
 		return nil, err
 	}
 
 	if err := token.Claims.Valid(); err != nil {
+		log.Warn("jwt token claims are not valid")
 		return nil, err
 	}
 
@@ -151,6 +157,7 @@ func (ja *JWTAuthenticator) Login(
 	if user == nil {
 		user, err = ja.auth.GetUser(sub)
 		if err != nil && err != sql.ErrNoRows {
+			log.Errorf("Error while loading user '%v'", sub)
 			return nil, err
 		} else if user == nil {
 			user = &User{
@@ -159,6 +166,7 @@ func (ja *JWTAuthenticator) Login(
 				AuthSource: AuthViaToken,
 			}
 			if err := ja.auth.AddUser(user); err != nil {
+				log.Errorf("Error while adding user '%v' to auth from token", user.Username)
 				return nil, err
 			}
 		}
@@ -223,11 +231,13 @@ func (ja *JWTAuthenticator) Auth(
 		return ja.publicKey, nil
 	})
 	if err != nil {
+		log.Warn("Error while parsing token")
 		return nil, err
 	}
 
 	// Check token validity
 	if err := token.Claims.Valid(); err != nil {
+		log.Warn("jwt token claims are not valid")
 		return nil, err
 	}
 
@@ -276,7 +286,7 @@ func (ja *JWTAuthenticator) Auth(
 		session.Values["roles"] = roles
 
 		if err := ja.auth.sessionStore.Save(r, rw, session); err != nil {
-			log.Errorf("session save failed: %s", err.Error())
+			log.Warnf("session save failed: %s", err.Error())
 			http.Error(rw, err.Error(), http.StatusInternalServerError)
 			return nil, err
 		}

internal/auth/ldap.go

@@ -39,21 +39,23 @@ func (la *LdapAuthenticator) Init(
 	if la.config != nil && la.config.SyncInterval != "" {
 		interval, err := time.ParseDuration(la.config.SyncInterval)
 		if err != nil {
+			log.Warnf("Could not parse duration for sync interval: %v", la.config.SyncInterval)
 			return err
 		}
 
 		if interval == 0 {
+			log.Info("Sync interval is zero")
 			return nil
 		}
 
 		go func() {
 			ticker := time.NewTicker(interval)
 			for t := range ticker.C {
-				log.Printf("LDAP sync started at %s", t.Format(time.RFC3339))
+				log.Printf("sync started at %s", t.Format(time.RFC3339))
 				if err := la.Sync(); err != nil {
-					log.Errorf("LDAP sync failed: %s", err.Error())
+					log.Errorf("sync failed: %s", err.Error())
 				}
-				log.Print("LDAP sync done")
+				log.Print("sync done")
 			}
 		}()
 	}
@@ -76,12 +78,14 @@ func (la *LdapAuthenticator) Login(
 
 	l, err := la.getLdapConnection(false)
 	if err != nil {
+		log.Warn("Error while getting ldap connection")
 		return nil, err
 	}
 	defer l.Close()
 
 	userDn := strings.Replace(la.config.UserBind, "{username}", user.Username, -1)
 	if err := l.Bind(userDn, r.FormValue("password")); err != nil {
+		log.Error("Error while binding to ldap connection")
 		return nil, err
 	}
 
@@ -104,12 +108,14 @@ func (la *LdapAuthenticator) Sync() error {
 	users := map[string]int{}
 	rows, err := la.auth.db.Query(`SELECT username FROM user WHERE user.ldap = 1`)
 	if err != nil {
+		log.Warn("Error while querying LDAP users")
 		return err
 	}
 
 	for rows.Next() {
 		var username string
 		if err := rows.Scan(&username); err != nil {
+			log.Warnf("Error while scanning for user '%s'", username)
 			return err
 		}
 
@@ -118,6 +124,7 @@ func (la *LdapAuthenticator) Sync() error {
 
 	l, err := la.getLdapConnection(true)
 	if err != nil {
+		log.Error("LDAP connection error")
 		return err
 	}
 	defer l.Close()
@@ -126,6 +133,7 @@ func (la *LdapAuthenticator) Sync() error {
 		la.config.UserBase, ldap.ScopeWholeSubtree, ldap.NeverDerefAliases, 0, 0, false,
 		la.config.UserFilter, []string{"dn", "uid", "gecos"}, nil))
 	if err != nil {
+		log.Warn("LDAP search error")
 		return err
 	}
 
@@ -147,15 +155,17 @@ func (la *LdapAuthenticator) Sync() error {
 
 	for username, where := range users {
 		if where == IN_DB && la.config.SyncDelOldUsers {
-			log.Debugf("ldap-sync: remove %#v (does not show up in LDAP anymore)", username)
+			log.Debugf("sync: remove %v (does not show up in LDAP anymore)", username)
 			if _, err := la.auth.db.Exec(`DELETE FROM user WHERE user.username = ?`, username); err != nil {
+				log.Errorf("User '%s' not in LDAP anymore: Delete from DB failed", username)
 				return err
 			}
 		} else if where == IN_LDAP {
 			name := newnames[username]
-			log.Debugf("ldap-sync: add %#v (name: %#v, roles: [user], ldap: true)", username, name)
+			log.Debugf("sync: add %v (name: %v, roles: [user], ldap: true)", username, name)
 			if _, err := la.auth.db.Exec(`INSERT INTO user (username, ldap, name, roles) VALUES (?, ?, ?, ?)`,
 				username, 1, name, "[\""+RoleUser+"\"]"); err != nil {
+				log.Errorf("User '%s' new in LDAP: Insert into DB failed", username)
 				return err
 			}
 		}
@@ -170,12 +180,14 @@ func (la *LdapAuthenticator) getLdapConnection(admin bool) (*ldap.Conn, error) {
 
 	conn, err := ldap.DialURL(la.config.Url)
 	if err != nil {
+		log.Warn("LDAP URL dial failed")
 		return nil, err
 	}
 
 	if admin {
 		if err := conn.Bind(la.config.SearchDN, la.syncPassword); err != nil {
 			conn.Close()
+			log.Warn("LDAP connection bind failed")
 			return nil, err
 		}
 	}

internal/auth/local.go

@@ -39,7 +39,7 @@ func (la *LocalAuthenticator) Login(
 	r *http.Request) (*User, error) {
 
 	if e := bcrypt.CompareHashAndPassword([]byte(user.Password), []byte(r.FormValue("password"))); e != nil {
-		return nil, fmt.Errorf("user '%s' provided the wrong password (%w)", user.Username, e)
+		return nil, fmt.Errorf("AUTH/LOCAL > user '%s' provided the wrong password (%w)", user.Username, e)
 	}
 
 	return user, nil

internal/auth/users.go

@@ -25,6 +25,7 @@ func (auth *Authentication) GetUser(username string) (*User, error) {
 	if err := sq.Select("password", "ldap", "name", "roles", "email", "projects").From("user").
 		Where("user.username = ?", username).RunWith(auth.db).
 		QueryRow().Scan(&hashedPassword, &user.AuthSource, &name, &rawRoles, &email, &rawProjects); err != nil {
+		log.Warnf("Error while querying user '%v' from database", username)
 		return nil, err
 	}
 
@@ -33,6 +34,7 @@ func (auth *Authentication) GetUser(username string) (*User, error) {
 	user.Email = email.String
 	if rawRoles.Valid {
 		if err := json.Unmarshal([]byte(rawRoles.String), &user.Roles); err != nil {
+			log.Warn("Error while unmarshaling raw roles from DB")
 			return nil, err
 		}
 	}
@@ -64,6 +66,7 @@ func (auth *Authentication) AddUser(user *User) error {
 	if user.Password != "" {
 		password, err := bcrypt.GenerateFromPassword([]byte(user.Password), bcrypt.DefaultCost)
 		if err != nil {
+			log.Error("Error while encrypting new user password")
 			return err
 		}
 		cols = append(cols, "password")
@@ -71,6 +74,7 @@ func (auth *Authentication) AddUser(user *User) error {
 	}
 
 	if _, err := sq.Insert("user").Columns(cols...).Values(vals...).RunWith(auth.db).Exec(); err != nil {
+		log.Errorf("Error while inserting new user '%v' into DB", user.Username)
 		return err
 	}
 
@@ -81,6 +85,7 @@ func (auth *Authentication) AddUser(user *User) error {
 func (auth *Authentication) DelUser(username string) error {
 
 	_, err := auth.db.Exec(`DELETE FROM user WHERE user.username = ?`, username)
+	log.Errorf("Error while deleting user '%s' from DB", username)
 	return err
 }
 
@@ -93,6 +98,7 @@ func (auth *Authentication) ListUsers(specialsOnly bool) ([]*User, error) {
 
 	rows, err := q.RunWith(auth.db).Query()
 	if err != nil {
+		log.Warn("Error while querying user list")
 		return nil, err
 	}
 
@@ -104,10 +110,12 @@ func (auth *Authentication) ListUsers(specialsOnly bool) ([]*User, error) {
 		user := &User{}
 		var name, email sql.NullString
 		if err := rows.Scan(&user.Username, &name, &email, &rawroles, &rawprojects); err != nil {
+			log.Warn("Error while scanning user list")
 			return nil, err
 		}
 
 		if err := json.Unmarshal([]byte(rawroles), &user.Roles); err != nil {
+			log.Warn("Error while unmarshaling raw role list")
 			return nil, err
 		}
 
@@ -129,11 +137,12 @@ func (auth *Authentication) AddRole(
 
 	user, err := auth.GetUser(username)
 	if err != nil {
+		log.Warnf("Could not load user '%s'", username)
 		return err
 	}
 
 	if !IsValidRole(role) {
-		return fmt.Errorf("invalid user role: %#v", role)
+		return fmt.Errorf("Invalid user role: %v", role)
 	}
 
 	if user.HasRole(role) {
@@ -142,6 +151,7 @@ func (auth *Authentication) AddRole(
 
 	roles, _ := json.Marshal(append(user.Roles, role))
 	if _, err := sq.Update("user").Set("roles", roles).Where("user.username = ?", username).RunWith(auth.db).Exec(); err != nil {
+		log.Errorf("Error while adding new role for user '%s'", user.Username)
 		return err
 	}
 	return nil
@@ -150,11 +160,12 @@ func (auth *Authentication) AddRole(
 func (auth *Authentication) RemoveRole(ctx context.Context, username string, role string) error {
 	user, err := auth.GetUser(username)
 	if err != nil {
+		log.Warnf("Could not load user '%s'", username)
 		return err
 	}
 
 	if !IsValidRole(role) {
-		return fmt.Errorf("invalid user role: %#v", role)
+		return fmt.Errorf("Invalid user role: %#v", role)
 	}
 
 	if role == RoleManager && len(user.Projects) != 0 {
@@ -174,11 +185,12 @@ func (auth *Authentication) RemoveRole(ctx context.Context, username string, rol
 	if exists == true {
 		var mroles, _ = json.Marshal(newroles)
 		if _, err := sq.Update("user").Set("roles", mroles).Where("user.username = ?", username).RunWith(auth.db).Exec(); err != nil {
+			log.Errorf("Error while removing role for user '%s'", user.Username)
 			return err
 		}
 		return nil
 	} else {
-		return fmt.Errorf("user %#v already does not have role %#v", username, role)
+		return fmt.Errorf("User '%v' already does not have role: %v", username, role)
 	}
 }
 
@@ -259,9 +271,13 @@ func FetchUser(ctx context.Context, db *sqlx.DB, username string) (*model.User,
 	if err := sq.Select("name", "email").From("user").Where("user.username = ?", username).
 		RunWith(db).QueryRow().Scan(&name, &email); err != nil {
 		if err == sql.ErrNoRows {
+			/* This warning will be logged *often* for non-local users, i.e. users mentioned only in job-table or archive, */
+			/* since FetchUser will be called to retrieve full name and mail for every job in query/list									 */
+			// log.Warnf("User '%s' Not found in DB", username)
 			return nil, nil
 		}
 
+		log.Warnf("Error while fetching user '%s'", username)
 		return nil, err
 	}