From 72c01880719fd619b81591527f06c81017044e3e Mon Sep 17 00:00:00 2001 From: William P Date: Sun, 18 May 2025 18:25:17 -0400 Subject: [PATCH] expand logging --- api/api.go | 13 ++++++++++- api/auth.go | 6 +++++ api/db.go | 60 ++++++++++++++++++++++++++++++++++++++++---------- api/message.go | 52 +++++++++++++++++++++++++++++++++++-------- api/user.go | 37 ++++++++++++++++++++++++++----- db/scylla.go | 4 ++-- log/log.go | 31 ++++++++++++++++++++++++++ main.go | 8 +++---- 8 files changed, 178 insertions(+), 33 deletions(-) create mode 100644 log/log.go diff --git a/api/api.go b/api/api.go index 99e8736..da2aab2 100644 --- a/api/api.go +++ b/api/api.go @@ -3,6 +3,7 @@ package api import ( "flag" "fmt" + "log/slog" "net/http" "git.dubyatp.xyz/chat-api-server/db" @@ -14,6 +15,16 @@ import ( var routes = flag.Bool("routes", false, "Generate API route documentation") +func RequestLog(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + slog.Debug("api: request received", + "request_uri", r.RequestURI, + "source_ip", r.RemoteAddr, + "user_agent", r.UserAgent()) + next.ServeHTTP(w, r) + }) +} + func Start() { db.InitScyllaDB() @@ -24,7 +35,7 @@ func Start() { r := chi.NewRouter() r.Use(middleware.RequestID) - //r.Use(middleware.Logger) + r.Use(RequestLog) r.Use(middleware.Recoverer) r.Use(middleware.URLFormat) r.Use(render.SetContentType(render.ContentTypeJSON)) diff --git a/api/auth.go b/api/auth.go index 424f23d..d0a2818 100644 --- a/api/auth.go +++ b/api/auth.go @@ -2,6 +2,7 @@ package api import ( "context" + "log/slog" "net/http" "time" @@ -45,6 +46,7 @@ func Login(w http.ResponseWriter, r *http.Request) { Secure: false, }) + slog.Info("auth: login successful", "user", user.Name) w.Write([]byte("Login successful")) } @@ -67,6 +69,7 @@ func Logout(w http.ResponseWriter, r *http.Request) { cookie.Expires = time.Now() http.SetCookie(w, cookie) + slog.Debug("auth: logout successful", "user", username) w.Write([]byte(username + " has been logged out")) } @@ -82,6 +85,7 @@ func CreateSession(username string) string { Username: username, } dbAddSession(&session) + slog.Debug("auth: new session created", "user", session.Username) return session.Token.String() } @@ -95,6 +99,7 @@ func ValidateSession(sessionToken string) (string, bool) { if err != nil { return "", false } + slog.Debug("auth: session validated", "user", session.Username) return session.Username, true } @@ -111,6 +116,7 @@ func DeleteSession(sessionToken string) (string, bool) { dbDeleteSession(session.Token) } + slog.Debug("auth: session deleted", "user", session.Username) return session.Username, true } diff --git a/api/db.go b/api/db.go index cc3dfe1..fc3844a 100644 --- a/api/db.go +++ b/api/db.go @@ -3,6 +3,7 @@ package api import ( "errors" "fmt" + "log/slog" "git.dubyatp.xyz/chat-api-server/db" "github.com/gocql/gocql" @@ -13,25 +14,34 @@ func dbGetUser(id string) (*User, error) { query := `SELECT id, name, password FROM users WHERE id = ?` var user User err := db.Session.Query(query, id).Scan(&user.ID, &user.Name, &user.Password) + if err == gocql.ErrNotFound { + slog.Debug("db: user not found", "userid", id) return nil, errors.New("User not found") } else if err != nil { - return nil, fmt.Errorf("failed to query user: %v", err) + slog.Error("db: failed to query user", "error", err) + return nil, fmt.Errorf("failed to query user") } + + slog.Debug("db: user found", "userid", user.ID, "username", user.Name) return &user, nil } func dbGetUserByName(username string) (*User, error) { + // This will be deprecated soon after implementing https://git.dubyatp.xyz/williamp/chatservice_concept/issues/1 query := `SELECT id, name, password FROM users WHERE name = ? ALLOW FILTERING` var user User err := db.Session.Query(query, username).Scan(&user.ID, &user.Name, &user.Password) if err == gocql.ErrNotFound { + slog.Debug("db: user not found", "username", username) return nil, errors.New("User not found") } else if err != nil { - return nil, fmt.Errorf("failed to query user: %v", err) + slog.Error("db: failed to query user", "error", err) + return nil, fmt.Errorf("failed to query user") } + slog.Debug("db: user found", "userid", user.ID, "username", user.Name) return &user, nil } @@ -50,13 +60,16 @@ func dbGetAllUsers() ([]*User, error) { } if err := iter.Close(); err != nil { - return nil, fmt.Errorf("failed to iterate users: %v", err) + slog.Error("db: failed to iterate users", "error", err) + return nil, fmt.Errorf("failed to iterate users") } if len(users) == 0 { + slog.Debug("db: no users found") return nil, errors.New("no users found") } + slog.Debug("db: user list returned") return users, nil } @@ -70,11 +83,14 @@ func dbGetMessage(id string) (*Message, error) { &message.Timestamp, &message.UserID) if err == gocql.ErrNotFound { + slog.Debug("db: message not found", "messageid", id) return nil, errors.New("Message not found") } else if err != nil { - return nil, fmt.Errorf("failed to query message: %v", err) + slog.Error("db: failed to query message", "error", err) + return nil, fmt.Errorf("failed to query message") } + slog.Debug("db: message found", "messageid", message.ID) return &message, nil } @@ -98,13 +114,16 @@ func dbGetAllMessages() ([]*Message, error) { } if err := iter.Close(); err != nil { - return nil, fmt.Errorf("failed to iterate messages: %v", err) + slog.Error("db: failed to iterate messages", "error", err) + return nil, fmt.Errorf("failed to iterate messages") } if len(messages) == 0 { + slog.Debug("db: no messages found") return nil, errors.New("no messages found") } + slog.Debug("db: message list returned") return messages, nil } @@ -112,8 +131,11 @@ func dbAddSession(session *Session) error { query := `INSERT INTO sessions (session_token, username) VALUES (?, ?)` err := db.Session.Query(query, session.Token, session.Username).Exec() if err != nil { - return fmt.Errorf("failed to add session: %v", err) + slog.Error("db: failed to add session", "error", err) + return fmt.Errorf("failed to add session") } + + slog.Debug("db: session added", "username", session.Username) return nil } @@ -124,9 +146,11 @@ func dbGetSession(id uuid.UUID) (*Session, error) { &session.Token, &session.Username) if err == gocql.ErrNotFound { + slog.Debug("db: session not found") return nil, errors.New("Session not found") } else if err != nil { - return nil, fmt.Errorf("failed to query session: %v", err) + slog.Error("db: failed to query session", "error", err) + return nil, fmt.Errorf("failed to query session") } return &session, nil @@ -138,9 +162,11 @@ func dbDeleteSession(id uuid.UUID) error { err := db.Session.Query(query, id).Exec() if err != nil { - return fmt.Errorf("failed to delete session: %v", err) + slog.Error("db: failed to delete session") + return fmt.Errorf("failed to delete session") } + slog.Debug("db: session deleted") return nil } @@ -148,8 +174,11 @@ func dbAddUser(user *User) error { query := `INSERT INTO users (id, name, password) VALUES (?, ?, ?)` err := db.Session.Query(query, user.ID, user.Name, user.Password).Exec() if err != nil { - return fmt.Errorf("failed to add user: %v", err) + slog.Error("db: failed to add user", "error", err, "userid", user.ID, "username", user.Name) + return fmt.Errorf("failed to add user") } + + slog.Debug("db: user added", "userid", user.ID, "username", user.Name) return nil } @@ -163,8 +192,11 @@ func dbAddMessage(message *Message) error { message.Timestamp, message.UserID).Exec() if err != nil { - return fmt.Errorf("failed to add message: %v", err) + slog.Error("db: failed to add message", "error", err, "messageid", message.ID) + return fmt.Errorf("failed to add message") } + + slog.Debug("db: message added", "messageid", message.ID) return nil } @@ -187,9 +219,11 @@ func dbUpdateMessage(updatedMessage *Message) error { updatedMessage.ID).Exec() if err != nil { - return fmt.Errorf("failed to update message: %v", err) + slog.Error("db: failed to update message", "error", err, "messageid", updatedMessage.ID) + return fmt.Errorf("failed to update message") } + slog.Debug("db: message updated", "messageid", updatedMessage.ID) return nil } @@ -200,8 +234,10 @@ func dbDeleteMessage(id string) error { err := db.Session.Query(query, id).Exec() if err != nil { - return fmt.Errorf("failed to delete message: %v", err) + slog.Error("db: failed to delete message", "error", err, "messageid", id) + return fmt.Errorf("failed to delete message") } + slog.Debug("db: message deleted", "messageid", id) return nil } diff --git a/api/message.go b/api/message.go index bbc0a19..512129e 100644 --- a/api/message.go +++ b/api/message.go @@ -3,6 +3,7 @@ package api import ( "context" "encoding/json" + "log/slog" "net/http" "github.com/go-chi/chi/v5" @@ -15,91 +16,125 @@ import ( func MessageCtx(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + slog.Debug("message: entering MessageCtx middleware") var message *Message var err error if messageID := chi.URLParam(r, "messageID"); messageID != "" { + slog.Debug("message: fetching message", "messageID", messageID) message, err = dbGetMessage(messageID) } else { + slog.Error("message: messageID not found in URL parameters") render.Render(w, r, ErrNotFound) return } if err != nil { + slog.Error("message: failed to fetch message", "messageID", chi.URLParam(r, "messageID"), "error", err) render.Render(w, r, ErrNotFound) return } + slog.Debug("message: successfully fetched message", "messageID", message.ID) ctx := context.WithValue(r.Context(), messageKey{}, message) next.ServeHTTP(w, r.WithContext(ctx)) }) } + func GetMessage(w http.ResponseWriter, r *http.Request) { + slog.Debug("message: entering GetMessage handler") message, ok := r.Context().Value(messageKey{}).(*Message) if !ok || message == nil { + slog.Error("message: message not found in context") render.Render(w, r, ErrNotFound) return } + slog.Debug("message: rendering message", "messageID", message.ID) if err := render.Render(w, r, NewMessageResponse(message)); err != nil { + slog.Error("message: failed to render message response", "messageID", message.ID, "error", err) render.Render(w, r, ErrRender(err)) return } - } func EditMessage(w http.ResponseWriter, r *http.Request) { + slog.Debug("message: entering EditMessage handler") message, ok := r.Context().Value(messageKey{}).(*Message) if !ok || message == nil { + slog.Error("message: message not found in context") render.Render(w, r, ErrNotFound) return } err := r.ParseMultipartForm(64 << 10) if err != nil { + slog.Error("message: failed to parse multipart form", "error", err) http.Error(w, "Unable to parse form", http.StatusBadRequest) return } body := r.FormValue("body") if body == "" { + slog.Error("message: message body is empty") http.Error(w, "Message body cannot be empty", http.StatusBadRequest) return } + slog.Debug("message: updating message", "messageID", message.ID) message.Body = body editedTime := time.Now() message.Edited = &editedTime err = dbUpdateMessage(message) if err != nil { + slog.Error("message: failed to update message", "messageID", message.ID, "error", err) render.Render(w, r, ErrRender(err)) return } + slog.Debug("message: successfully updated message", "messageID", message.ID) if err := render.Render(w, r, NewMessageResponse(message)); err != nil { + slog.Error("message: failed to render updated message response", "messageID", message.ID, "error", err) render.Render(w, r, ErrRender(err)) return } } func DeleteMessage(w http.ResponseWriter, r *http.Request) { + slog.Debug("message: entering DeleteMessage handler") message, ok := r.Context().Value(messageKey{}).(*Message) if !ok || message == nil { + slog.Error("message: message not found in context") render.Render(w, r, ErrNotFound) return } - dbDeleteMessage(message.ID.String()) + + slog.Debug("message: deleting message", "messageID", message.ID) + err := dbDeleteMessage(message.ID.String()) + if err != nil { + slog.Error("message: failed to delete message", "messageID", message.ID, "error", err) + render.Render(w, r, ErrRender(err)) + return + } + + slog.Debug("message: successfully deleted message", "messageID", message.ID) if err := render.Render(w, r, NewMessageResponse(message)); err != nil { + slog.Error("message: failed to render deleted message response", "messageID", message.ID, "error", err) render.Render(w, r, ErrRender(err)) return } } func ListMessages(w http.ResponseWriter, r *http.Request) { + slog.Debug("message: entering ListMessages handler") dbMessages, err := dbGetAllMessages() if err != nil { + slog.Error("message: failed to fetch messages", "error", err) render.Render(w, r, ErrRender(err)) return } + + slog.Debug("message: successfully fetched messages", "count", len(dbMessages)) if err := render.RenderList(w, r, NewMessageListResponse(dbMessages)); err != nil { + slog.Error("message: failed to render message list response", "error", err) render.Render(w, r, ErrRender(err)) return } @@ -110,23 +145,19 @@ func newMessageID() uuid.UUID { } func NewMessage(w http.ResponseWriter, r *http.Request) { + slog.Debug("message: entering NewMessage handler") err := r.ParseMultipartForm(64 << 10) if err != nil { + slog.Error("message: failed to parse multipart form", "error", err) http.Error(w, "Unable to parse form", http.StatusBadRequest) return } - // userID := r.FormValue("user_id") - //if userID == "" { - // http.Error(w, "Invalid user ID", http.StatusBadRequest) - // return - //} - var user = r.Context().Value(userKey{}).(*User) - body := r.FormValue("body") if body == "" { + slog.Error("message: message body is empty") http.Error(w, "Invalid body", http.StatusBadRequest) return } @@ -138,12 +169,15 @@ func NewMessage(w http.ResponseWriter, r *http.Request) { Timestamp: time.Now(), } + slog.Debug("message: creating new message", "messageID", msg.ID) err = dbAddMessage(&msg) if err != nil { + slog.Error("message: failed to add new message", "messageID", msg.ID, "error", err) render.Render(w, r, ErrRender(err)) return } + slog.Debug("message: successfully created new message", "messageID", msg.ID) render.Render(w, r, NewMessageResponse(&msg)) } diff --git a/api/user.go b/api/user.go index f859441..9ef32ab 100644 --- a/api/user.go +++ b/api/user.go @@ -2,6 +2,7 @@ package api import ( "context" + "log/slog" "net/http" "github.com/go-chi/chi/v5" @@ -11,79 +12,96 @@ import ( func UserCtx(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + slog.Debug("user: entering UserCtx middleware") var user *User var err error if userID := chi.URLParam(r, "userID"); userID != "" { + slog.Debug("user: fetching user", "userID", userID) user, err = dbGetUser(userID) } else { + slog.Error("user: userID not found in URL parameters") render.Render(w, r, ErrNotFound) return } if err != nil { + slog.Error("user: failed to fetch user", "userID", user.ID, "error", err) render.Render(w, r, ErrNotFound) return } + slog.Debug("user: successfully fetched user", "userID", user.ID) ctx := context.WithValue(r.Context(), userKey{}, user) next.ServeHTTP(w, r.WithContext(ctx)) }) } func Whoami(w http.ResponseWriter, r *http.Request) { + slog.Debug("user: entering Whoami handler") user, ok := r.Context().Value(userKey{}).(*User) if !ok || user == nil { - // Anonymous user + slog.Debug("user: anonymous user") w.Write([]byte("anonymous")) return } + slog.Debug("user: returning user name", "userID", user.ID, "userName", user.Name) w.Write([]byte(user.Name)) } func LoginCtx(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - // Try to retrieve username from context + slog.Debug("user: entering LoginCtx middleware") username, ok := r.Context().Value(usernameKey).(string) if !ok || username == "" { - // No username provided, assume it's an anonymous user + slog.Debug("user: no username provided, assuming anonymous user") next.ServeHTTP(w, r) return } - // Lookup user in the database + slog.Debug("user: fetching user by username", "username", username) user, err := dbGetUserByName(username) if err != nil { - // If user is specified and not found, throw an error + slog.Error("user: failed to fetch user by username", "username", username, "error", err) render.Render(w, r, ErrNotFound) return } + slog.Debug("user: successfully fetched user", "userID", user.ID, "username", user.Name) ctx := context.WithValue(r.Context(), userKey{}, user) next.ServeHTTP(w, r.WithContext(ctx)) }) } func GetUser(w http.ResponseWriter, r *http.Request) { + slog.Debug("user: entering GetUser handler") user, ok := r.Context().Value(userKey{}).(*User) if !ok || user == nil { + slog.Error("user: user not found in context") render.Render(w, r, ErrNotFound) return } + slog.Debug("user: rendering user", "userID", user.ID, "userName", user.Name) if err := render.Render(w, r, NewUserPayloadResponse(user)); err != nil { + slog.Error("user: failed to render user response", "userID", user.ID, "error", err) render.Render(w, r, ErrRender(err)) return } } func ListUsers(w http.ResponseWriter, r *http.Request) { + slog.Debug("user: entering ListUsers handler") dbUsers, err := dbGetAllUsers() if err != nil { + slog.Error("user: failed to fetch users", "error", err) render.Render(w, r, ErrRender(err)) return } + + slog.Debug("user: successfully fetched users", "count", len(dbUsers)) if err := render.RenderList(w, r, NewUserListResponse(dbUsers)); err != nil { + slog.Error("user: failed to render user list response", "error", err) render.Render(w, r, ErrRender(err)) return } @@ -94,8 +112,10 @@ func newUserID() uuid.UUID { } func NewUser(w http.ResponseWriter, r *http.Request) { + slog.Debug("user: entering NewUser handler") err := r.ParseMultipartForm(64 << 10) if err != nil { + slog.Error("user: failed to parse multipart form", "error", err) http.Error(w, "Unable to parse form", http.StatusBadRequest) return } @@ -103,13 +123,17 @@ func NewUser(w http.ResponseWriter, r *http.Request) { newUserName := r.FormValue("name") password := r.FormValue("password") if newUserName == "" || password == "" { + slog.Error("user: username or password is empty") http.Error(w, "Username and password cannot be empty", http.StatusBadRequest) return } + slog.Debug("user: hashing password for new user", "userName", newUserName) hashedPassword, err := hashPassword(password) if err != nil { + slog.Error("user: failed to hash password", "error", err) http.Error(w, "Unable to hash password", http.StatusInternalServerError) + return } newUser := User{ @@ -118,12 +142,15 @@ func NewUser(w http.ResponseWriter, r *http.Request) { Password: hashedPassword, } + slog.Debug("user: adding new user to database", "userID", newUser.ID, "userName", newUser.Name) err = dbAddUser(&newUser) if err != nil { + slog.Error("user: failed to add new user", "userID", newUser.ID, "userName", newUser.Name, "error", err) render.Render(w, r, ErrRender(err)) return } + slog.Debug("user: successfully added new user", "userID", newUser.ID, "userName", newUser.Name) render.Render(w, r, NewUserPayloadResponse(&newUser)) } diff --git a/db/scylla.go b/db/scylla.go index f296988..299af8e 100644 --- a/db/scylla.go +++ b/db/scylla.go @@ -1,7 +1,6 @@ package db import ( - "log" "log/slog" "os" @@ -17,7 +16,8 @@ func InitScyllaDB() { session, err := cluster.CreateSession() if err != nil { - log.Fatalf("Failed to connect to ScyllaDB: %v", err) + slog.Error("Failed to connect to ScyllaDB", "error", err) + os.Exit(1) } Session = session slog.Info("Connected to ScyllaDB") diff --git a/log/log.go b/log/log.go new file mode 100644 index 0000000..c5f06b2 --- /dev/null +++ b/log/log.go @@ -0,0 +1,31 @@ +package log + +import ( + "flag" + "log/slog" + "os" +) + +func Logger() { + // Get logger arguments + var loglevelStr string + flag.StringVar(&loglevelStr, "loglevel", "ERROR", "set log level") + flag.Parse() + + loglevel := new(slog.LevelVar) + if loglevelStr == "DEBUG" { + loglevel.Set(slog.LevelDebug) + } else if loglevelStr == "INFO" { + loglevel.Set(slog.LevelInfo) + } else if loglevelStr == "WARN" { + loglevel.Set(slog.LevelWarn) + } else { + loglevel.Set(slog.LevelError) + } + // Start logger + logger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{ + Level: loglevel, + })) + slog.SetDefault(logger) + slog.Debug("Logging started", "level", loglevel) +} diff --git a/main.go b/main.go index 1e33613..d40588e 100644 --- a/main.go +++ b/main.go @@ -5,6 +5,7 @@ import ( "os" "git.dubyatp.xyz/chat-api-server/api" + "git.dubyatp.xyz/chat-api-server/log" "github.com/joho/godotenv" ) @@ -19,16 +20,15 @@ func checkEnvVars(keys []string) (bool, []string) { } func main() { - // Start logger - logger := slog.New(slog.NewJSONHandler(os.Stdout, nil)) - slog.SetDefault(logger) + + log.Logger() // initialize logger requiredEnvVars := []string{"SCYLLA_CLUSTER", "SCYLLA_KEYSPACE"} // Initialize dotenv file err := godotenv.Load() if err != nil { - logger.Info("No .env file loaded, will try OS environment variables") + slog.Info("No .env file loaded, will try OS environment variables") } // Check if environment variables were defined by the OS before erroring out