From f8ad53caf0825fa2f7e960eacb7ad4e3e020322d Mon Sep 17 00:00:00 2001 From: Lou Knauer Date: Thu, 27 Jan 2022 10:35:26 +0100 Subject: [PATCH] use a custom logger --- api/rest.go | 33 ++++++++-------- auth/auth.go | 20 +++++----- auth/ldap.go | 10 ++--- log/log.go | 107 +++++++++++++++++++++++++++++++++++++++++++++++++++ server.go | 8 ++-- 5 files changed, 142 insertions(+), 36 deletions(-) create mode 100644 log/log.go diff --git a/api/rest.go b/api/rest.go index 80ee93c..7b75fae 100644 --- a/api/rest.go +++ b/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) { diff --git a/auth/auth.go b/auth/auth.go index 7a5c6df..30f2a94 100644 --- a/auth/auth.go +++ b/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{ diff --git a/auth/ldap.go b/auth/ldap.go index 3994c8c..9228e07 100644 --- a/auth/ldap.go +++ b/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 diff --git a/log/log.go b/log/log.go new file mode 100644 index 0000000..85ef206 --- /dev/null +++ b/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...) + } +} diff --git a/server.go b/server.go index 7695d18..0c8579a 100644 --- a/server.go +++ b/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{