use a custom logger

api/rest.go

@@ -6,7 +6,6 @@ import (
 	"encoding/json"
 	"fmt"
 	"io"
-	"log"
 	"net/http"
 	"os"
 	"path/filepath"
@@ -16,6 +15,7 @@ import (
 	"github.com/ClusterCockpit/cc-backend/config"
 	"github.com/ClusterCockpit/cc-backend/graph"
 	"github.com/ClusterCockpit/cc-backend/graph/model"
+	"github.com/ClusterCockpit/cc-backend/log"
 	"github.com/ClusterCockpit/cc-backend/metricdata"
 	"github.com/ClusterCockpit/cc-backend/schema"
 	sq "github.com/Masterminds/squirrel"
@@ -181,7 +181,8 @@ func (api *RestApi) tagJob(rw http.ResponseWriter, r *http.Request) {
 // there are optional here (e.g. `jobState` defaults to "running").
 func (api *RestApi) startJob(rw http.ResponseWriter, r *http.Request) {
 	if user := auth.GetUser(r.Context()); user != nil && !user.HasRole(auth.RoleApi) {
-		http.Error(rw, "Missing 'api' role", http.StatusForbidden)
+		log.Warnf("user '%s' used /api/jobs/start_job/ without having the API role")
+		http.Error(rw, "missing 'api' role", http.StatusForbidden)
 		return
 	}
 
@@ -223,7 +224,8 @@ func (api *RestApi) startJob(rw http.ResponseWriter, r *http.Request) {
 
 	req.RawResources, err = json.Marshal(req.Resources)
 	if err != nil {
-		log.Fatal(err)
+		http.Error(rw, "while parsing resources: "+err.Error(), http.StatusBadRequest)
+		return
 	}
 
 	res, err := api.DB.NamedExec(`INSERT INTO job (
@@ -234,6 +236,7 @@ func (api *RestApi) startJob(rw http.ResponseWriter, r *http.Request) {
 		:exclusive, :monitoring_status, :smt, :job_state, :start_time, :duration, :resources, :meta_data
 	);`, req)
 	if err != nil {
+		log.Errorf("insert into job table failed: %s", err.Error())
 		http.Error(rw, err.Error(), http.StatusInternalServerError)
 		return
 	}
@@ -244,7 +247,7 @@ func (api *RestApi) startJob(rw http.ResponseWriter, r *http.Request) {
 		return
 	}
 
-	log.Printf("new job (id: %d): cluster=%s, jobId=%d, user=%s, startTime=%d\n", id, req.Cluster, req.JobID, req.User, req.StartTime)
+	log.Printf("new job (id: %d): cluster=%s, jobId=%d, user=%s, startTime=%d", id, req.Cluster, req.JobID, req.User, req.StartTime)
 	rw.Header().Add("Content-Type", "application/json")
 	rw.WriteHeader(http.StatusCreated)
 	json.NewEncoder(rw).Encode(StartJobApiRespone{
@@ -313,7 +316,7 @@ func (api *RestApi) stopJob(rw http.ResponseWriter, r *http.Request) {
 		job.Duration = int32(req.StopTime - job.StartTime.Unix())
 		jobMeta, err := metricdata.ArchiveJob(job, ctx)
 		if err != nil {
-			log.Printf("archiving job (dbid: %d) failed: %s\n", job.ID, err.Error())
+			log.Errorf("archiving job (dbid: %d) failed: %s", job.ID, err.Error())
 			return err
 		}
 
@@ -341,20 +344,20 @@ func (api *RestApi) stopJob(rw http.ResponseWriter, r *http.Request) {
 
 		sql, args, err := stmt.ToSql()
 		if err != nil {
-			log.Printf("archiving job (dbid: %d) failed: %s\n", job.ID, err.Error())
+			log.Errorf("archiving job (dbid: %d) failed: %s", job.ID, err.Error())
 			return err
 		}
 
 		if _, err := api.DB.Exec(sql, args...); err != nil {
-			log.Printf("archiving job (dbid: %d) failed: %s\n", job.ID, err.Error())
+			log.Errorf("archiving job (dbid: %d) failed: %s", job.ID, err.Error())
 			return err
 		}
 
-		log.Printf("job stopped and archived (dbid: %d)\n", job.ID)
+		log.Printf("job stopped and archived (dbid: %d)", job.ID)
 		return nil
 	}
 
-	log.Printf("archiving job... (dbid: %d): cluster=%s, jobId=%d, user=%s, startTime=%s\n", job.ID, job.Cluster, job.JobID, job.User, job.StartTime)
+	log.Printf("archiving job... (dbid: %d): cluster=%s, jobId=%d, user=%s, startTime=%s", job.ID, job.Cluster, job.JobID, job.User, job.StartTime)
 	if api.AsyncArchiving {
 		rw.Header().Add("Content-Type", "application/json")
 		rw.WriteHeader(http.StatusOK)
@@ -399,23 +402,19 @@ func (api *RestApi) getJobMetrics(rw http.ResponseWriter, r *http.Request) {
 
 	data, err := api.Resolver.Query().JobMetrics(r.Context(), id, metrics, scopes)
 	if err != nil {
-		if err := json.NewEncoder(rw).Encode(Respone{
+		json.NewEncoder(rw).Encode(Respone{
 			Error: &struct {
 				Message string "json:\"message\""
 			}{Message: err.Error()},
-		}); err != nil {
-			log.Println(err.Error())
-		}
+		})
 		return
 	}
 
-	if err := json.NewEncoder(rw).Encode(Respone{
+	json.NewEncoder(rw).Encode(Respone{
 		Data: &struct {
 			JobMetrics []*model.JobMetricWithName "json:\"jobMetrics\""
 		}{JobMetrics: data},
-	}); err != nil {
-		log.Println(err.Error())
-	}
+	})
 }
 
 func (api *RestApi) putMachineState(rw http.ResponseWriter, r *http.Request) {

auth/auth.go

@@ -9,11 +9,11 @@ import (
 	"encoding/json"
 	"errors"
 	"fmt"
-	"log"
 	"net/http"
 	"os"
 	"strings"
 
+	"github.com/ClusterCockpit/cc-backend/log"
 	"github.com/ClusterCockpit/cc-backend/templates"
 	sq "github.com/Masterminds/squirrel"
 	"github.com/golang-jwt/jwt/v4"
@@ -72,7 +72,7 @@ func Init(db *sqlx.DB, ldapConfig *LdapConfig) error {
 
 	sessKey := os.Getenv("SESSION_KEY")
 	if sessKey == "" {
-		log.Println("warning: environment variable 'SESSION_KEY' not set (will use non-persistent random key)")
+		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 {
 			return err
@@ -88,7 +88,7 @@ func Init(db *sqlx.DB, ldapConfig *LdapConfig) error {
 
 	pubKey, privKey := os.Getenv("JWT_PUBLIC_KEY"), os.Getenv("JWT_PRIVATE_KEY")
 	if pubKey == "" || privKey == "" {
-		log.Println("warning: environment variables 'JWT_PUBLIC_KEY' or 'JWT_PRIVATE_KEY' not set (token based authentication will not work)")
+		log.Warn("environment variables 'JWT_PUBLIC_KEY' or 'JWT_PRIVATE_KEY' not set (token based authentication will not work)")
 	} else {
 		bytes, err := base64.StdEncoding.DecodeString(pubKey)
 		if err != nil {
@@ -143,7 +143,7 @@ func AddUserToDB(db *sqlx.DB, arg string) error {
 	if err != nil {
 		return err
 	}
-	log.Printf("new user '%s' added (roles: %s)\n", parts[0], roles)
+	log.Infof("new user %#v added (roles: %s)", parts[0], roles)
 	return nil
 }
 
@@ -188,7 +188,7 @@ func Login(db *sqlx.DB) http.Handler {
 		}
 
 		if err != nil {
-			log.Printf("login failed: %s\n", err.Error())
+			log.Warnf("login of user %#v failed: %s", username, err.Error())
 			rw.WriteHeader(http.StatusUnauthorized)
 			templates.Render(rw, r, "login.html", &templates.Page{
 				Title: "Login failed",
@@ -201,7 +201,7 @@ func Login(db *sqlx.DB) http.Handler {
 
 		session, err := sessionStore.New(r, "session")
 		if err != nil {
-			log.Printf("session creation failed: %s\n", err.Error())
+			log.Errorf("session creation failed: %s", err.Error())
 			http.Error(rw, err.Error(), http.StatusInternalServerError)
 			return
 		}
@@ -210,12 +210,12 @@ func Login(db *sqlx.DB) http.Handler {
 		session.Values["username"] = user.Username
 		session.Values["roles"] = user.Roles
 		if err := sessionStore.Save(r, rw, session); err != nil {
-			log.Printf("session save failed: %s\n", err.Error())
+			log.Errorf("session save failed: %s", err.Error())
 			http.Error(rw, err.Error(), http.StatusInternalServerError)
 			return
 		}
 
-		log.Printf("login successfull: user: %#v (roles: %v)\n", user.Username, user.Roles)
+		log.Infof("login successfull: user: %#v (roles: %v)", user.Username, user.Roles)
 		http.Redirect(rw, r, "/", http.StatusTemporaryRedirect)
 	})
 }
@@ -269,7 +269,7 @@ func Auth(next http.Handler) http.Handler {
 	return http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) {
 		user, err := authViaToken(r)
 		if err == ErrTokenInvalid {
-			log.Printf("authentication failed: invalid token\n")
+			log.Warn("authentication failed: invalid token")
 			http.Error(rw, err.Error(), http.StatusUnauthorized)
 			return
 		}
@@ -288,7 +288,7 @@ func Auth(next http.Handler) http.Handler {
 		}
 
 		if session.IsNew {
-			log.Printf("authentication failed: no session or jwt found\n")
+			log.Warn("authentication failed: no session or jwt found")
 
 			rw.WriteHeader(http.StatusUnauthorized)
 			templates.Render(rw, r, "login.html", &templates.Page{

auth/ldap.go

@@ -3,11 +3,11 @@ package auth
 import (
 	"crypto/tls"
 	"errors"
-	"fmt"
-	"log"
 	"os"
 	"strings"
 
+	"github.com/ClusterCockpit/cc-backend/log"
+
 	"github.com/go-ldap/ldap/v3"
 	"github.com/jmoiron/sqlx"
 )
@@ -28,7 +28,7 @@ var ldapAdminPassword string
 func initLdap(config *LdapConfig) error {
 	ldapAdminPassword = os.Getenv("LDAP_ADMIN_PASSWORD")
 	if ldapAdminPassword == "" {
-		log.Println("warning: environment variable 'LDAP_ADMIN_PASSWORD' not set (ldap sync or authentication will not work)")
+		log.Warn("environment variable 'LDAP_ADMIN_PASSWORD' not set (ldap sync or authentication will not work)")
 	}
 
 	ldapConfig = config
@@ -138,13 +138,13 @@ func SyncWithLDAP(db *sqlx.DB) error {
 
 	for username, where := range users {
 		if where == IN_DB {
-			fmt.Printf("ldap-sync: remove '%s' (does not show up in LDAP anymore)\n", username)
+			log.Infof("ldap-sync: remove %#v (does not show up in LDAP anymore)", username)
 			if _, err := db.Exec(`DELETE FROM user WHERE user.username = ?`, username); err != nil {
 				return err
 			}
 		} else if where == IN_LDAP {
 			name := newnames[username]
-			fmt.Printf("ldap-sync: add '%s' (name: '%s', roles: [], ldap: true)\n", username, name)
+			log.Infof("ldap-sync: add %#v (name: %#v, roles: [], ldap: true)", username, name)
 			if _, err := db.Exec(`INSERT INTO user (username, ldap, name, roles) VALUES (?, ?, ?, ?)`,
 				username, 1, name, "[]"); err != nil {
 				return err

log/log.go

@@ -0,0 +1,107 @@
+// Provides a simple way of logging with different levels.
+// Time/Data are not logged on purpose because systemd adds
+// them for us.
+package log
+
+import (
+	"fmt"
+	"io"
+	"os"
+)
+
+var DebugWriter io.Writer = os.Stderr
+var InfoWriter io.Writer = os.Stderr
+var WarnWriter io.Writer = os.Stderr
+var ErrorWriter io.Writer = os.Stderr
+
+func init() {
+	if lvl, ok := os.LookupEnv("LOGLEVEL"); ok {
+		switch lvl {
+		case "err", "fatal":
+			WarnWriter = io.Discard
+			fallthrough
+		case "warn":
+			InfoWriter = io.Discard
+			fallthrough
+		case "info":
+			DebugWriter = io.Discard
+		case "debug":
+			// Nothing to do...
+		default:
+			Warnf("environment variable LOGLEVEL has invalid value %#v", lvl)
+		}
+	}
+}
+
+func Debug(v ...interface{}) {
+	if DebugWriter != io.Discard {
+		v = append([]interface{}{"[DEBUG]"}, v...)
+		fmt.Fprintln(DebugWriter, v...)
+	}
+}
+
+func Info(v ...interface{}) {
+	if InfoWriter != io.Discard {
+		v = append([]interface{}{"[INFO]"}, v...)
+		fmt.Fprintln(InfoWriter, v...)
+	}
+}
+
+func Print(v ...interface{}) {
+	Info(v...)
+}
+
+func Warn(v ...interface{}) {
+	if WarnWriter != io.Discard {
+		v = append([]interface{}{"[WARNING]"}, v...)
+		fmt.Fprintln(WarnWriter, v...)
+	}
+}
+
+func Error(v ...interface{}) {
+	if ErrorWriter != io.Discard {
+		v = append([]interface{}{"[ERROR]"}, v...)
+		fmt.Fprintln(ErrorWriter, v...)
+	}
+}
+
+func Fatal(v ...interface{}) {
+	if ErrorWriter != io.Discard {
+		v = append([]interface{}{"[FATAL]"}, v...)
+		fmt.Fprintln(ErrorWriter, v...)
+	}
+}
+
+func Debugf(format string, v ...interface{}) {
+	if DebugWriter != io.Discard {
+		fmt.Fprintf(DebugWriter, "[DEBUG] "+format+"\n", v...)
+	}
+}
+
+func Infof(format string, v ...interface{}) {
+	if InfoWriter != io.Discard {
+		fmt.Fprintf(InfoWriter, "[INFO] "+format+"\n", v...)
+	}
+}
+
+func Printf(format string, v ...interface{}) {
+	Infof(format, v...)
+}
+
+func Warnf(format string, v ...interface{}) {
+	if WarnWriter != io.Discard {
+		fmt.Fprintf(WarnWriter, "[WARNING] "+format+"\n", v...)
+	}
+}
+
+func Errorf(format string, v ...interface{}) {
+	if ErrorWriter != io.Discard {
+		fmt.Fprintf(ErrorWriter, "[ERROR] "+format+"\n", v...)
+	}
+}
+
+func Fatalf(format string, v ...interface{}) {
+	if ErrorWriter != io.Discard {
+		fmt.Fprintf(ErrorWriter, "[FATAL] "+format+"\n", v...)
+	}
+}

server.go

@@ -8,7 +8,6 @@ import (
 	"errors"
 	"flag"
 	"fmt"
-	"log"
 	"net"
 	"net/http"
 	"net/url"
@@ -29,6 +28,7 @@ import (
 	"github.com/ClusterCockpit/cc-backend/config"
 	"github.com/ClusterCockpit/cc-backend/graph"
 	"github.com/ClusterCockpit/cc-backend/graph/generated"
+	"github.com/ClusterCockpit/cc-backend/log"
 	"github.com/ClusterCockpit/cc-backend/metricdata"
 	"github.com/ClusterCockpit/cc-backend/schema"
 	"github.com/ClusterCockpit/cc-backend/templates"
@@ -201,7 +201,7 @@ func main() {
 			}
 
 			if !user.HasRole(auth.RoleApi) {
-				log.Println("warning: that user does not have the API role")
+				log.Warn("that user does not have the API role")
 			}
 
 			jwt, err := auth.ProvideJWT(user)
@@ -212,7 +212,7 @@ func main() {
 			fmt.Printf("JWT for '%s': %s\n", user.Username, jwt)
 		}
 	} else if flagNewUser != "" || flagDelUser != "" {
-		log.Fatalln("arguments --add-user and --del-user can only be used if authentication is enabled")
+		log.Fatal("arguments --add-user and --del-user can only be used if authentication is enabled")
 	}
 
 	if err := config.Init(db, !programConfig.DisableAuthentication, programConfig.UiDefaults, programConfig.JobArchive); err != nil {
@@ -316,7 +316,7 @@ func main() {
 	handler := handlers.CORS(
 		handlers.AllowedHeaders([]string{"X-Requested-With", "Content-Type", "Authorization"}),
 		handlers.AllowedMethods([]string{"GET", "POST", "HEAD", "OPTIONS"}),
-		handlers.AllowedOrigins([]string{"*"}))(handlers.LoggingHandler(os.Stdout, handlers.CompressHandler(r)))
+		handlers.AllowedOrigins([]string{"*"}))(handlers.LoggingHandler(log.InfoWriter, handlers.CompressHandler(r)))
 
 	var wg sync.WaitGroup
 	server := http.Server{