Hallucinate hella logs

db.go

@@ -5,6 +5,8 @@ import (
 
 	"gorm.io/driver/sqlite"
 	"gorm.io/gorm"
+
+	logger "git.site.quack-lab.dev/dave/cylogger"
 )
 
 type DB interface {
@@ -25,9 +27,11 @@ func GetDB() (DB, error) {
 	var err error
 
 	if db != nil {
+		logger.Debug("Returning existing database connection")
 		return db, nil
 	}
 
+	logger.Debug("Creating new database connection to %s", options.DBPath)
 	dbFile := filepath.Join(options.DBPath)
 	db, err := gorm.Open(sqlite.Open(dbFile), &gorm.Config{
 		// SkipDefaultTransaction: true,
@@ -35,9 +39,11 @@ func GetDB() (DB, error) {
 		// Logger:      gormlogger.Default.LogMode(gormlogger.Silent),
 	})
 	if err != nil {
+		logger.Error("Failed to open database: %v", err)
 		return nil, err
 	}
 
+	logger.Info("Database connection established successfully")
 	return &DBWrapper{db: db}, nil
 }
 
@@ -51,18 +57,35 @@ func (db *DBWrapper) DB() *gorm.DB {
 }
 
 func (db *DBWrapper) GetTokenForCharacter(characterName string) (*Token, error) {
+	logger.Debug("Fetching token for character %s from database", characterName)
 	var token Token
 	err := db.db.Where("character_name = ?", characterName).First(&token).Error
 	if err != nil {
+		logger.Debug("No token found for character %s: %v", characterName, err)
 		return nil, err
 	}
+	logger.Debug("Token found for character %s, expires at %v", characterName, token.ExpiresAt)
 	return &token, nil
 }
 
 func (db *DBWrapper) SaveTokenForCharacter(token *Token) error {
-	return db.db.Save(token).Error
+	logger.Debug("Saving token for character %s to database", token.CharacterName)
+	err := db.db.Save(token).Error
+	if err != nil {
+		logger.Error("Failed to save token for character %s: %v", token.CharacterName, err)
+		return err
+	}
+	logger.Debug("Token saved successfully for character %s", token.CharacterName)
+	return nil
 }
 
 func (db *DBWrapper) AutoMigrate(dst ...interface{}) error {
-	return db.db.AutoMigrate(dst...)
+	logger.Debug("Running database auto-migration")
+	err := db.db.AutoMigrate(dst...)
+	if err != nil {
+		logger.Error("Database auto-migration failed: %v", err)
+		return err
+	}
+	logger.Debug("Database auto-migration completed successfully")
+	return nil
 }

esi_sso.go

@@ -18,6 +18,8 @@ import (
 	"time"
 
 	"gorm.io/gorm"
+
+	logger "git.site.quack-lab.dev/dave/cylogger"
 )
 
 const (
@@ -52,8 +54,11 @@ type SSO struct {
 
 // NewSSO creates a new SSO instance
 func NewSSO(clientID, redirectURI string, scopes []string) (*SSO, error) {
+	logger.Info("Creating new SSO instance for clientID %s with redirectURI %s and scopes %v", clientID, redirectURI, scopes)
+
 	db, err := GetDB()
 	if err != nil {
+		logger.Error("Failed to get database connection %v", err)
 		return nil, err
 	}
 
@@ -65,20 +70,30 @@ func NewSSO(clientID, redirectURI string, scopes []string) (*SSO, error) {
 	}
 
 	if err := s.initDB(); err != nil {
+		logger.Error("Failed to initialize SSO database %v", err)
 		return nil, err
 	}
 
+	logger.Info("SSO instance created successfully")
 	return s, nil
 }
 
 func (s *SSO) initDB() error {
-	return s.db.AutoMigrate(&Token{})
+	logger.Debug("Initializing SSO database schema")
+	err := s.db.AutoMigrate(&Token{})
+	if err != nil {
+		logger.Error("Failed to migrate Token table %v", err)
+		return err
+	}
+	logger.Debug("SSO database schema initialized successfully")
+	return nil
 }
 
 // GetToken returns a valid access token for the given character name
 // If no token exists, it will start the OAuth flow
 // If token is expired, it will refresh it automatically
 func (s *SSO) GetToken(ctx context.Context, characterName string) (string, error) {
+	logger.Debug("Getting token for character %s", characterName)
 	s.mu.Lock()
 	defer s.mu.Unlock()
 
@@ -86,42 +101,63 @@ func (s *SSO) GetToken(ctx context.Context, characterName string) (string, error
 	token, err := s.db.GetTokenForCharacter(characterName)
 	if err != nil {
 		if errors.Is(err, gorm.ErrRecordNotFound) {
+			logger.Info("No existing token found for character %s, starting authentication flow", characterName)
 			// No token exists, need to authenticate
 			if err := s.startAuthFlow(ctx, characterName); err != nil {
+				logger.Error("Authentication flow failed for character %s: %v", characterName, err)
 				return "", err
 			}
 			// After authentication, fetch the token from DB
 			token, err = s.db.GetTokenForCharacter(characterName)
 			if err != nil {
+				logger.Error("Failed to fetch token after authentication for character %s: %v", characterName, err)
 				return "", err
 			}
+			logger.Info("Successfully authenticated character %s", characterName)
 		} else {
+			logger.Error("Database error when fetching token for character %s: %v", characterName, err)
 			return "", err
 		}
+	} else {
+		logger.Debug("Found existing token for character %s, expires at %v", characterName, token.ExpiresAt)
 	}
 
 	// Check if token needs refresh
 	if time.Now().After(token.ExpiresAt.Add(-60 * time.Second)) {
+		logger.Info("Token for character %s is expired or expiring soon, refreshing", characterName)
 		if err := s.refreshToken(ctx, token); err != nil {
+			logger.Warning("Token refresh failed for character %s, re-authenticating: %v", characterName, err)
 			// Refresh failed, need to re-authenticate
 			if err := s.startAuthFlow(ctx, characterName); err != nil {
+				logger.Error("Re-authentication failed for character %s: %v", characterName, err)
 				return "", err
 			}
 			// After re-authentication, fetch the token from DB
 			token, err = s.db.GetTokenForCharacter(characterName)
 			if err != nil {
+				logger.Error("Failed to fetch token after re-authentication for character %s: %v", characterName, err)
 				return "", err
 			}
+			logger.Info("Successfully re-authenticated character %s", characterName)
+		} else {
+			logger.Debug("Token refreshed successfully for character %s", characterName)
 		}
+	} else {
+		logger.Debug("Token for character %s is still valid", characterName)
 	}
 
+	logger.Debug("Returning valid token for character %s", characterName)
 	return token.AccessToken, nil
 }
 
 func (s *SSO) startAuthFlow(ctx context.Context, characterName string) error {
+	logger.Info("Starting authentication flow for character %s", characterName)
+
 	// Generate PKCE
+	logger.Debug("Generating PKCE parameters")
 	verifier, challenge, err := generatePKCE()
 	if err != nil {
+		logger.Error("Failed to generate PKCE parameters: %v", err)
 		return err
 	}
 
@@ -133,36 +169,51 @@ func (s *SSO) startAuthFlow(ctx context.Context, characterName string) error {
 	}, 1)
 	authURL := s.buildAuthURL(challenge, s.state)
 
-	fmt.Printf("Please visit this URL to authenticate:\n%s\n", authURL)
+	logger.Info("Generated authentication URL for character %s", characterName)
-	fmt.Println("Waiting for authentication...")
+	logger.Info("Please visit this URL to authenticate: \n%s", authURL)
+	logger.Info("Waiting for authentication...")
 
 	// Start callback server
+	logger.Debug("Starting callback server")
 	server, err := s.startCallbackServer()
 	if err != nil {
+		logger.Error("Failed to start callback server: %v", err)
 		return err
 	}
 	s.server = server
 	defer server.Shutdown(ctx)
 
 	// Wait for callback
+	logger.Debug("Waiting for authentication callback")
 	code, receivedState, err := s.waitForCallback()
 	if err != nil {
+		logger.Error("Callback wait failed: %v", err)
 		return err
 	}
 
 	if receivedState != s.state {
+		logger.Error("Invalid state parameter received: %s, expected: %s", receivedState, s.state)
 		return errors.New("invalid state parameter")
 	}
 
+	logger.Debug("Received valid callback, exchanging code for token")
 	// Exchange code for token
 	token, err := s.exchangeCodeForToken(ctx, code, verifier)
 	if err != nil {
+		logger.Error("Failed to exchange code for token: %v", err)
 		return err
 	}
 
 	// Save token to DB
 	token.CharacterName = characterName
-	return s.db.SaveTokenForCharacter(token)
+	logger.Debug("Saving token to database for character %s", characterName)
+	if err := s.db.SaveTokenForCharacter(token); err != nil {
+		logger.Error("Failed to save token to database: %v", err)
+		return err
+	}
+
+	logger.Info("Authentication flow completed successfully for character %s", characterName)
+	return nil
 }
 
 func (s *SSO) buildAuthURL(challenge, state string) string {
@@ -181,11 +232,14 @@ func (s *SSO) buildAuthURL(challenge, state string) string {
 }
 
 func (s *SSO) startCallbackServer() (*http.Server, error) {
+	logger.Debug("Starting callback server for redirect URI: %s", s.redirectURI)
 	u, err := url.Parse(s.redirectURI)
 	if err != nil {
+		logger.Error("Failed to parse redirect URI: %v", err)
 		return nil, err
 	}
 	if u.Scheme != "http" && u.Scheme != "https" {
+		logger.Error("Invalid redirect URI scheme: %s", u.Scheme)
 		return nil, errors.New("redirect URI must be http(s)")
 	}
 	hostPort := u.Host
@@ -197,9 +251,12 @@ func (s *SSO) startCallbackServer() (*http.Server, error) {
 		}
 	}
 
+	logger.Debug("Callback server will listen on %s", hostPort)
 	mux := http.NewServeMux()
 	mux.HandleFunc(u.Path, func(w http.ResponseWriter, r *http.Request) {
+		logger.Debug("Received callback request: %s %s", r.Method, r.URL.String())
 		if r.Method != http.MethodGet {
+			logger.Warning("Invalid callback method: %s", r.Method)
 			w.WriteHeader(http.StatusMethodNotAllowed)
 			s.callbackChan <- struct {
 				code  string
@@ -212,7 +269,7 @@ func (s *SSO) startCallbackServer() (*http.Server, error) {
 		code := q.Get("code")
 		st := q.Get("state")
 		if code == "" || st == "" || st != s.state {
-			fmt.Printf("Invalid SSO response: code=%s, state=%s, expected_state=%s\n", code, st, s.state)
+			logger.Error("Invalid SSO response: code=%s, state=%s, expected_state=%s", code, st, s.state)
 			w.WriteHeader(http.StatusBadRequest)
 			_, _ = w.Write([]byte("Invalid SSO response"))
 			s.callbackChan <- struct {
@@ -222,7 +279,7 @@ func (s *SSO) startCallbackServer() (*http.Server, error) {
 			}{"", "", errors.New("invalid state")}
 			return
 		}
-		fmt.Printf("Exchanging token for code: %s\n", code)
+		logger.Info("Received valid callback, exchanging token for code: %s", code)
 		w.Header().Set("Content-Type", "text/html")
 		_, _ = w.Write([]byte("<html><body><h1>Login successful!</h1><p>You can close this window.</p></body></html>"))
 		s.callbackChan <- struct {
@@ -238,25 +295,37 @@ func (s *SSO) startCallbackServer() (*http.Server, error) {
 
 	ln, err := net.Listen("tcp", hostPort)
 	if err != nil {
+		logger.Error("Failed to listen on %s: %v", hostPort, err)
 		return nil, err
 	}
 
 	server := &http.Server{Handler: mux}
-	go func() { _ = server.Serve(ln) }()
+	go func() {
+		logger.Debug("Callback server started successfully")
+		_ = server.Serve(ln)
+	}()
 	return server, nil
 }
 
 func (s *SSO) waitForCallback() (code, state string, err error) {
+	logger.Debug("Waiting for authentication callback (timeout: 30s)")
 	// Wait for callback through channel
 	select {
 	case result := <-s.callbackChan:
+		if result.err != nil {
+			logger.Error("Callback received with error: %v", result.err)
+			return "", "", result.err
+		}
+		logger.Debug("Callback received successfully")
 		return result.code, result.state, result.err
 	case <-time.After(30 * time.Second):
+		logger.Error("Callback timeout after 30 seconds")
 		return "", "", errors.New("callback timeout")
 	}
 }
 
 func (s *SSO) exchangeCodeForToken(ctx context.Context, code, verifier string) (*Token, error) {
+	logger.Debug("Exchanging authorization code for access token")
 	form := url.Values{}
 	form.Set("grant_type", "authorization_code")
 	form.Set("code", code)
@@ -265,28 +334,34 @@ func (s *SSO) exchangeCodeForToken(ctx context.Context, code, verifier string) (
 
 	req, err := http.NewRequestWithContext(ctx, http.MethodPost, issuerTokenURL, strings.NewReader(form.Encode()))
 	if err != nil {
+		logger.Error("Failed to create token exchange request: %v", err)
 		return nil, err
 	}
 	req.Header.Set("Content-Type", "application/x-www-form-urlencoded")
 
+	logger.Debug("Sending token exchange request to %s", issuerTokenURL)
 	resp, err := http.DefaultClient.Do(req)
 	if err != nil {
+		logger.Error("Token exchange request failed: %v", err)
 		return nil, err
 	}
 	defer resp.Body.Close()
 
 	if resp.StatusCode < 200 || resp.StatusCode >= 300 {
 		b, _ := io.ReadAll(resp.Body)
+		logger.Error("Token exchange failed with status %d: %s", resp.StatusCode, string(b))
 		return nil, fmt.Errorf("token exchange failed: %s: %s", resp.Status, string(b))
 	}
 
 	var tr tokenResponse
 	if err := json.NewDecoder(resp.Body).Decode(&tr); err != nil {
+		logger.Error("Failed to decode token response: %v", err)
 		return nil, err
 	}
 
 	// Parse character info from token
 	name, _ := parseTokenCharacter(tr.AccessToken)
+	logger.Info("Successfully exchanged code for token, character: %s", name)
 
 	return &Token{
 		CharacterName: name,
@@ -297,6 +372,7 @@ func (s *SSO) exchangeCodeForToken(ctx context.Context, code, verifier string) (
 }
 
 func (s *SSO) refreshToken(ctx context.Context, token *Token) error {
+	logger.Debug("Refreshing token for character %s", token.CharacterName)
 	form := url.Values{}
 	form.Set("grant_type", "refresh_token")
 	form.Set("refresh_token", token.RefreshToken)
@@ -304,23 +380,28 @@ func (s *SSO) refreshToken(ctx context.Context, token *Token) error {
 
 	req, err := http.NewRequestWithContext(ctx, http.MethodPost, issuerTokenURL, strings.NewReader(form.Encode()))
 	if err != nil {
+		logger.Error("Failed to create token refresh request: %v", err)
 		return err
 	}
 	req.Header.Set("Content-Type", "application/x-www-form-urlencoded")
 
+	logger.Debug("Sending token refresh request to %s", issuerTokenURL)
 	resp, err := http.DefaultClient.Do(req)
 	if err != nil {
+		logger.Error("Token refresh request failed: %v", err)
 		return err
 	}
 	defer resp.Body.Close()
 
 	if resp.StatusCode < 200 || resp.StatusCode >= 300 {
 		b, _ := io.ReadAll(resp.Body)
+		logger.Error("Token refresh failed with status %d: %s", resp.StatusCode, string(b))
 		return fmt.Errorf("token refresh failed: %s: %s", resp.Status, string(b))
 	}
 
 	var tr tokenResponse
 	if err := json.NewDecoder(resp.Body).Decode(&tr); err != nil {
+		logger.Error("Failed to decode refresh token response: %v", err)
 		return err
 	}
 
@@ -333,7 +414,14 @@ func (s *SSO) refreshToken(ctx context.Context, token *Token) error {
 		token.ExpiresAt = time.Now().Add(time.Duration(tr.ExpiresIn-30) * time.Second)
 	}
 
-	return s.db.SaveTokenForCharacter(token)
+	logger.Debug("Saving refreshed token to database for character %s", token.CharacterName)
+	if err := s.db.SaveTokenForCharacter(token); err != nil {
+		logger.Error("Failed to save refreshed token: %v", err)
+		return err
+	}
+
+	logger.Info("Token refreshed successfully for character %s", token.CharacterName)
+	return nil
 }
 
 // Utility functions