Browse Source

implement logger

master
Silberengel 4 weeks ago
parent
commit
052a7dc074
  1. 26
      cmd/server/main.go
  2. 1
      go.mod
  3. 3
      go.sum
  4. 101
      internal/logger/logger.go
  5. 47
      internal/nostr/client.go
  6. 16
      internal/nostr/ebooks.go
  7. 27
      internal/nostr/feed.go
  8. 8
      internal/nostr/profile.go
  9. 115
      internal/nostr/wiki.go
  10. 20
      internal/server/handlers.go
  11. 10
      internal/server/server.go

26
cmd/server/main.go

@ -3,12 +3,12 @@ package main
import ( import (
"context" "context"
"flag" "flag"
"log"
"time" "time"
"gitcitadel-online/internal/cache" "gitcitadel-online/internal/cache"
"gitcitadel-online/internal/config" "gitcitadel-online/internal/config"
"gitcitadel-online/internal/generator" "gitcitadel-online/internal/generator"
"gitcitadel-online/internal/logger"
"gitcitadel-online/internal/nostr" "gitcitadel-online/internal/nostr"
"gitcitadel-online/internal/server" "gitcitadel-online/internal/server"
) )
@ -16,20 +16,28 @@ import (
func main() { func main() {
configPath := flag.String("config", "config.yaml", "Path to configuration file") configPath := flag.String("config", "config.yaml", "Path to configuration file")
devMode := flag.Bool("dev", false, "Enable development mode") devMode := flag.Bool("dev", false, "Enable development mode")
logLevel := flag.String("log-level", "info", "Log level (debug, info, warn, error)")
flag.Parse() flag.Parse()
// Initialize logger
if *devMode {
logger.Init("debug", true)
} else {
logger.Init(*logLevel, false)
}
// Load configuration // Load configuration
cfg, err := config.LoadConfig(*configPath) cfg, err := config.LoadConfig(*configPath)
if err != nil { if err != nil {
log.Fatalf("Failed to load config: %v", err) logger.Fatalf("Failed to load config: %v", err)
} }
if err := cfg.Validate(); err != nil { if err := cfg.Validate(); err != nil {
log.Fatalf("Invalid config: %v", err) logger.Fatalf("Invalid config: %v", err)
} }
if *devMode { if *devMode {
log.Println("Development mode enabled") logger.Info("Development mode enabled")
} }
// Initialize caches // Initialize caches
@ -40,7 +48,7 @@ func main() {
nostrClient := nostr.NewClient(cfg.Relays.Primary, cfg.Relays.Fallback, cfg.Relays.AdditionalFallback) nostrClient := nostr.NewClient(cfg.Relays.Primary, cfg.Relays.Fallback, cfg.Relays.AdditionalFallback)
ctx := context.Background() ctx := context.Background()
if err := nostrClient.Connect(ctx); err != nil { if err := nostrClient.Connect(ctx); err != nil {
log.Printf("Warning: Failed to connect to relays: %v", err) logger.Warnf("Failed to connect to relays: %v", err)
} }
// Initialize services // Initialize services
@ -65,7 +73,7 @@ func main() {
nostrClient, nostrClient,
) )
if err != nil { if err != nil {
log.Fatalf("Failed to initialize HTML generator: %v", err) logger.Fatalf("Failed to initialize HTML generator: %v", err)
} }
// Initialize cache rewarming // Initialize cache rewarming
@ -93,12 +101,12 @@ func main() {
// Start server in goroutine // Start server in goroutine
go func() { go func() {
if err := httpServer.Start(); err != nil { if err := httpServer.Start(); err != nil {
log.Fatalf("Server failed: %v", err) logger.Fatalf("Server failed: %v", err)
} }
}() }()
log.Printf("Server started on port %d", cfg.Server.Port) logger.Infof("Server started on port %d", cfg.Server.Port)
log.Println("Waiting for initial cache population...") logger.Info("Waiting for initial cache population...")
// Wait a bit for initial cache // Wait a bit for initial cache
time.Sleep(5 * time.Second) time.Sleep(5 * time.Second)

1
go.mod

@ -4,6 +4,7 @@ go 1.22.2
require ( require (
github.com/nbd-wtf/go-nostr v0.27.0 github.com/nbd-wtf/go-nostr v0.27.0
github.com/sirupsen/logrus v1.9.3
gopkg.in/yaml.v3 v3.0.1 gopkg.in/yaml.v3 v3.0.1
) )

3
go.sum

@ -92,6 +92,8 @@ github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZb
github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
github.com/puzpuzpuz/xsync/v2 v2.5.1 h1:mVGYAvzDSu52+zaGyNjC+24Xw2bQi3kTr4QJ6N9pIIU= github.com/puzpuzpuz/xsync/v2 v2.5.1 h1:mVGYAvzDSu52+zaGyNjC+24Xw2bQi3kTr4QJ6N9pIIU=
github.com/puzpuzpuz/xsync/v2 v2.5.1/go.mod h1:gD2H2krq/w52MfPLE+Uy64TzJDVY7lP2znR9qmR35kU= github.com/puzpuzpuz/xsync/v2 v2.5.1/go.mod h1:gD2H2krq/w52MfPLE+Uy64TzJDVY7lP2znR9qmR35kU=
github.com/sirupsen/logrus v1.9.3 h1:dueUQJ1C2q9oE3F7wvmSGAaVtTmUizReu6fjN8uqzbQ=
github.com/sirupsen/logrus v1.9.3/go.mod h1:naHLuLoDiP4jHNo9R0sCBMtWGeIprob74mVsIT4qYEQ=
github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4= github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4=
github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg= github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
@ -126,6 +128,7 @@ golang.org/x/sys v0.0.0-20191120155948-bd437916bb0e/go.mod h1:h1NjWce9XRLGQEsW7w
golang.org/x/sys v0.0.0-20200323222414-85ca7c5b95cd/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20200323222414-85ca7c5b95cd/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
golang.org/x/sys v0.0.0-20200519105757-fe76b779f299/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20200519105757-fe76b779f299/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
golang.org/x/sys v0.0.0-20200814200057-3d37ad5750ed/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20200814200057-3d37ad5750ed/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
golang.org/x/sys v0.0.0-20220715151400-c0bba94af5f8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
golang.org/x/sys v0.0.0-20221010170243-090e33056c14/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20221010170243-090e33056c14/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
golang.org/x/sys v0.8.0 h1:EBmGv8NaZBZTWvrbjNoL6HVt+IVy3QDQpJs7VRIw3tU= golang.org/x/sys v0.8.0 h1:EBmGv8NaZBZTWvrbjNoL6HVt+IVy3QDQpJs7VRIw3tU=

101
internal/logger/logger.go

@ -0,0 +1,101 @@
package logger
import (
"os"
"github.com/sirupsen/logrus"
)
var (
// Logger is the global logger instance
Logger *logrus.Logger
)
// Init initializes the logger with the specified log level
func Init(level string, devMode bool) {
Logger = logrus.New()
// Set output to stdout
Logger.SetOutput(os.Stdout)
// Set formatter - use JSON in production, text in dev
if devMode {
Logger.SetFormatter(&logrus.TextFormatter{
FullTimestamp: true,
ForceColors: true,
})
} else {
Logger.SetFormatter(&logrus.JSONFormatter{
TimestampFormat: "2006-01-02T15:04:05.000Z07:00",
})
}
// Parse and set log level
logLevel, err := logrus.ParseLevel(level)
if err != nil {
// Default to INFO if invalid level
logLevel = logrus.InfoLevel
Logger.Warnf("Invalid log level '%s', defaulting to INFO", level)
}
Logger.SetLevel(logLevel)
}
// Debug logs a debug message
func Debug(args ...interface{}) {
Logger.Debug(args...)
}
// Debugf logs a formatted debug message
func Debugf(format string, args ...interface{}) {
Logger.Debugf(format, args...)
}
// Info logs an info message
func Info(args ...interface{}) {
Logger.Info(args...)
}
// Infof logs a formatted info message
func Infof(format string, args ...interface{}) {
Logger.Infof(format, args...)
}
// Warn logs a warning message
func Warn(args ...interface{}) {
Logger.Warn(args...)
}
// Warnf logs a formatted warning message
func Warnf(format string, args ...interface{}) {
Logger.Warnf(format, args...)
}
// Error logs an error message
func Error(args ...interface{}) {
Logger.Error(args...)
}
// Errorf logs a formatted error message
func Errorf(format string, args ...interface{}) {
Logger.Errorf(format, args...)
}
// Fatal logs a fatal message and exits
func Fatal(args ...interface{}) {
Logger.Fatal(args...)
}
// Fatalf logs a formatted fatal message and exits
func Fatalf(format string, args ...interface{}) {
Logger.Fatalf(format, args...)
}
// WithField creates an entry with a single field
func WithField(key string, value interface{}) *logrus.Entry {
return Logger.WithField(key, value)
}
// WithFields creates an entry with multiple fields
func WithFields(fields logrus.Fields) *logrus.Entry {
return Logger.WithFields(fields)
}

47
internal/nostr/client.go

@ -3,10 +3,11 @@ package nostr
import ( import (
"context" "context"
"fmt" "fmt"
"log"
"sync" "sync"
"time" "time"
"gitcitadel-online/internal/logger"
"github.com/nbd-wtf/go-nostr" "github.com/nbd-wtf/go-nostr"
) )
@ -73,12 +74,17 @@ func (c *Client) FetchEvent(ctx context.Context, filter nostr.Filter) (*nostr.Ev
wg.Add(1) wg.Add(1)
go func(url string) { go func(url string) {
defer wg.Done() defer wg.Done()
log.Printf("Querying relay %s with filter: Kinds=%v, Authors=%v, IDs=%v, Tags=%v", logger.WithFields(map[string]interface{}{
url, filter.Kinds, filter.Authors, filter.IDs, filter.Tags) "relay": url,
"kinds": filter.Kinds,
"authors": filter.Authors,
"ids": filter.IDs,
"tags": filter.Tags,
}).Debug("Querying relay")
relay, err := c.connectToRelay(queryCtx, url) relay, err := c.connectToRelay(queryCtx, url)
if err != nil { if err != nil {
log.Printf("Relay %s: connection failed: %v", url, err) logger.WithField("relay", url).Debugf("Connection failed: %v", err)
results <- result{relay: url, events: nil, err: err} results <- result{relay: url, events: nil, err: err}
return return
} }
@ -86,12 +92,15 @@ func (c *Client) FetchEvent(ctx context.Context, filter nostr.Filter) (*nostr.Ev
events, err := relay.QuerySync(queryCtx, filter) events, err := relay.QuerySync(queryCtx, filter)
if err != nil { if err != nil {
log.Printf("Relay %s: query failed: %v", url, err) logger.WithField("relay", url).Debugf("Query failed: %v", err)
results <- result{relay: url, events: nil, err: err} results <- result{relay: url, events: nil, err: err}
return return
} }
log.Printf("Relay %s: returned %d event(s)", url, len(events)) logger.WithFields(map[string]interface{}{
"relay": url,
"events": len(events),
}).Debug("Relay returned events")
results <- result{relay: url, events: events, err: nil} results <- result{relay: url, events: events, err: nil}
}(relayURL) }(relayURL)
} }
@ -130,7 +139,10 @@ func (c *Client) FetchEvent(ctx context.Context, filter nostr.Filter) (*nostr.Ev
} }
} }
log.Printf("Selected newest event (created_at: %d) from %d total events across all relays", newest.CreatedAt, len(allEvents)) logger.WithFields(map[string]interface{}{
"created_at": newest.CreatedAt,
"total": len(allEvents),
}).Debug("Selected newest event from all relays")
return newest, nil return newest, nil
} }
@ -159,12 +171,18 @@ func (c *Client) FetchEvents(ctx context.Context, filter nostr.Filter) ([]*nostr
wg.Add(1) wg.Add(1)
go func(url string) { go func(url string) {
defer wg.Done() defer wg.Done()
log.Printf("Querying relay %s with filter: Kinds=%v, Authors=%v, IDs=%v, Tags=%v, Limit=%d", logger.WithFields(map[string]interface{}{
url, filter.Kinds, filter.Authors, filter.IDs, filter.Tags, filter.Limit) "relay": url,
"kinds": filter.Kinds,
"authors": filter.Authors,
"ids": filter.IDs,
"tags": filter.Tags,
"limit": filter.Limit,
}).Debug("Querying relay")
relay, err := c.connectToRelay(queryCtx, url) relay, err := c.connectToRelay(queryCtx, url)
if err != nil { if err != nil {
log.Printf("Relay %s: connection failed: %v", url, err) logger.WithField("relay", url).Debugf("Connection failed: %v", err)
results <- result{relay: url, events: nil, err: err} results <- result{relay: url, events: nil, err: err}
return return
} }
@ -172,12 +190,15 @@ func (c *Client) FetchEvents(ctx context.Context, filter nostr.Filter) ([]*nostr
events, err := relay.QuerySync(queryCtx, filter) events, err := relay.QuerySync(queryCtx, filter)
if err != nil { if err != nil {
log.Printf("Relay %s: query failed: %v", url, err) logger.WithField("relay", url).Debugf("Query failed: %v", err)
results <- result{relay: url, events: nil, err: err} results <- result{relay: url, events: nil, err: err}
return return
} }
log.Printf("Relay %s: returned %d event(s)", url, len(events)) logger.WithFields(map[string]interface{}{
"relay": url,
"events": len(events),
}).Debug("Relay returned events")
results <- result{relay: url, events: events, err: nil} results <- result{relay: url, events: events, err: nil}
}(relayURL) }(relayURL)
} }
@ -217,7 +238,7 @@ func (c *Client) FetchEvents(ctx context.Context, filter nostr.Filter) ([]*nostr
events = append(events, event) events = append(events, event)
} }
log.Printf("Returning %d unique event(s) from all relays", len(events)) logger.WithField("events", len(events)).Debug("Returning unique events from all relays")
return events, nil return events, nil
} }

16
internal/nostr/ebooks.go

@ -3,9 +3,9 @@ package nostr
import ( import (
"context" "context"
"fmt" "fmt"
"log"
"github.com/nbd-wtf/go-nostr" "github.com/nbd-wtf/go-nostr"
"gitcitadel-online/internal/logger"
) )
// EBooksService handles fetching top-level 30040 events // EBooksService handles fetching top-level 30040 events
@ -58,7 +58,10 @@ func (es *EBooksService) FetchTopLevelIndexEvents(ctx context.Context) ([]EBookI
return nil, fmt.Errorf("failed to query events: %w", err) return nil, fmt.Errorf("failed to query events: %w", err)
} }
log.Printf("Fetched %d index events from %s", len(events), es.relayURL) logger.WithFields(map[string]interface{}{
"events": len(events),
"relay": es.relayURL,
}).Debug("Fetched index events")
// Build a set of all referenced kind:pubkey:dtag from 'a' tags // Build a set of all referenced kind:pubkey:dtag from 'a' tags
referencedSet := make(map[string]bool) referencedSet := make(map[string]bool)
@ -71,7 +74,7 @@ func (es *EBooksService) FetchTopLevelIndexEvents(ctx context.Context) ([]EBookI
} }
} }
log.Printf("Found %d referenced index events", len(referencedSet)) logger.WithField("count", len(referencedSet)).Debug("Found referenced index events")
// Filter to only top-level events (not referenced in any other event) // Filter to only top-level events (not referenced in any other event)
var topLevelEvents []*nostr.Event var topLevelEvents []*nostr.Event
@ -96,7 +99,7 @@ func (es *EBooksService) FetchTopLevelIndexEvents(ctx context.Context) ([]EBookI
} }
} }
log.Printf("Found %d top-level index events", len(topLevelEvents)) logger.WithField("count", len(topLevelEvents)).Info("Found top-level index events")
// Convert to EBookInfo // Convert to EBookInfo
ebooks := make([]EBookInfo, 0, len(topLevelEvents)) ebooks := make([]EBookInfo, 0, len(topLevelEvents))
@ -157,7 +160,10 @@ func (es *EBooksService) FetchTopLevelIndexEvents(ctx context.Context) ([]EBookI
naddr, err := CreateNaddr(es.indexKind, ebook.Author, ebook.DTag, relays) naddr, err := CreateNaddr(es.indexKind, ebook.Author, ebook.DTag, relays)
if err != nil { if err != nil {
log.Printf("Failed to create naddr for ebook %s: %v", ebook.DTag, err) logger.WithFields(map[string]interface{}{
"ebook": ebook.DTag,
"error": err,
}).Warn("Failed to create naddr for ebook, using fallback format")
// Fallback to kind:pubkey:dtag format // Fallback to kind:pubkey:dtag format
ebook.Naddr = fmt.Sprintf("%d:%s:%s", es.indexKind, ebook.Author, ebook.DTag) ebook.Naddr = fmt.Sprintf("%d:%s:%s", es.indexKind, ebook.Author, ebook.DTag)
} else { } else {

27
internal/nostr/feed.go

@ -3,9 +3,10 @@ package nostr
import ( import (
"context" "context"
"fmt" "fmt"
"log"
"time" "time"
"gitcitadel-online/internal/logger"
"github.com/nbd-wtf/go-nostr" "github.com/nbd-wtf/go-nostr"
) )
@ -41,7 +42,11 @@ func (fs *FeedService) FetchFeedItems(ctx context.Context, feedRelay string, max
// Retry up to 3 times for the configured feed relay only // Retry up to 3 times for the configured feed relay only
for attempt := 1; attempt <= maxRetries; attempt++ { for attempt := 1; attempt <= maxRetries; attempt++ {
if attempt > 1 { if attempt > 1 {
log.Printf("Retrying feed relay %s (attempt %d/%d)", feedRelay, attempt, maxRetries) logger.WithFields(map[string]interface{}{
"relay": feedRelay,
"attempt": attempt,
"max": maxRetries,
}).Debug("Retrying feed relay")
// Wait a bit before retrying (exponential backoff: 1s, 2s) // Wait a bit before retrying (exponential backoff: 1s, 2s)
waitTime := time.Duration(attempt-1) * time.Second waitTime := time.Duration(attempt-1) * time.Second
time.Sleep(waitTime) time.Sleep(waitTime)
@ -53,7 +58,11 @@ func (fs *FeedService) FetchFeedItems(ctx context.Context, feedRelay string, max
// Connect to the relay // Connect to the relay
relayConn, err := fs.client.ConnectToRelay(attemptCtx, feedRelay) relayConn, err := fs.client.ConnectToRelay(attemptCtx, feedRelay)
if err != nil { if err != nil {
log.Printf("Failed to connect to feed relay %s (attempt %d/%d): %v", feedRelay, attempt, maxRetries, err) logger.WithFields(map[string]interface{}{
"relay": feedRelay,
"attempt": attempt,
"max": maxRetries,
}).Debugf("Failed to connect to feed relay: %v", err)
lastErr = err lastErr = err
cancel() cancel()
continue // Try next attempt continue // Try next attempt
@ -65,7 +74,11 @@ func (fs *FeedService) FetchFeedItems(ctx context.Context, feedRelay string, max
cancel() cancel()
if err != nil { if err != nil {
log.Printf("Failed to fetch feed events from %s (attempt %d/%d): %v", feedRelay, attempt, maxRetries, err) logger.WithFields(map[string]interface{}{
"relay": feedRelay,
"attempt": attempt,
"max": maxRetries,
}).Debugf("Failed to fetch feed events: %v", err)
lastErr = err lastErr = err
continue // Try next attempt continue // Try next attempt
} }
@ -82,7 +95,11 @@ func (fs *FeedService) FetchFeedItems(ctx context.Context, feedRelay string, max
items = append(items, item) items = append(items, item)
} }
log.Printf("Successfully fetched %d feed items from %s (attempt %d/%d)", len(items), feedRelay, attempt, maxRetries) logger.WithFields(map[string]interface{}{
"relay": feedRelay,
"items": len(items),
"attempt": attempt,
}).Info("Successfully fetched feed items")
return items, nil return items, nil
} }

8
internal/nostr/profile.go

@ -4,7 +4,8 @@ import (
"context" "context"
"encoding/json" "encoding/json"
"fmt" "fmt"
"log"
"gitcitadel-online/internal/logger"
"github.com/nbd-wtf/go-nostr" "github.com/nbd-wtf/go-nostr"
"github.com/nbd-wtf/go-nostr/nip19" "github.com/nbd-wtf/go-nostr/nip19"
@ -79,7 +80,10 @@ func (c *Client) FetchProfile(ctx context.Context, npub string) (*Profile, error
Limit: 1, Limit: 1,
} }
log.Printf("Fetching profile for npub %s (pubkey: %s)", npub, pubkey) logger.WithFields(map[string]interface{}{
"npub": npub,
"pubkey": pubkey,
}).Debug("Fetching profile")
// Fetch the event // Fetch the event
event, err := c.FetchEvent(ctx, filter) event, err := c.FetchEvent(ctx, filter)

115
internal/nostr/wiki.go

@ -3,15 +3,22 @@ package nostr
import ( import (
"context" "context"
"fmt" "fmt"
"log"
"gitcitadel-online/internal/logger"
"github.com/nbd-wtf/go-nostr" "github.com/nbd-wtf/go-nostr"
) )
// logFilter logs the exact filter being used for debugging // logFilter logs the exact filter being used for debugging
func logFilter(filter nostr.Filter, context string) { func logFilter(filter nostr.Filter, context string) {
log.Printf("FILTER [%s]: Kinds=%v, Authors=%v, IDs=%v, Tags=%v, Limit=%d", logger.WithFields(map[string]interface{}{
context, filter.Kinds, filter.Authors, filter.IDs, filter.Tags, filter.Limit) "context": context,
"kinds": filter.Kinds,
"authors": filter.Authors,
"ids": filter.IDs,
"tags": filter.Tags,
"limit": filter.Limit,
}).Debug("Nostr filter")
} }
// WikiService handles wiki-specific operations // WikiService handles wiki-specific operations
@ -84,7 +91,10 @@ func (ws *WikiService) FetchWikiEvents(ctx context.Context, index *IndexEvent) (
// If event ID is specified, use it for more reliable fetching // If event ID is specified, use it for more reliable fetching
if item.EventID != "" { if item.EventID != "" {
filter.IDs = []string{item.EventID} filter.IDs = []string{item.EventID}
log.Printf("Using event ID %s for %s", item.EventID[:16]+"...", item.DTag) logger.WithFields(map[string]interface{}{
"event_id": item.EventID[:16] + "...",
"dtag": item.DTag,
}).Debug("Using event ID for wiki event")
} }
logFilter(filter, fmt.Sprintf("wiki event %s", item.DTag)) logFilter(filter, fmt.Sprintf("wiki event %s", item.DTag))
@ -94,7 +104,10 @@ func (ws *WikiService) FetchWikiEvents(ctx context.Context, index *IndexEvent) (
var err error var err error
if item.RelayHint != "" { if item.RelayHint != "" {
// Connect to the relay hint // Connect to the relay hint
log.Printf("Trying relay hint %s for %s", item.RelayHint, item.DTag) logger.WithFields(map[string]interface{}{
"relay_hint": item.RelayHint,
"dtag": item.DTag,
}).Debug("Trying relay hint")
relay, relayErr := ws.client.ConnectToRelay(ctx, item.RelayHint) relay, relayErr := ws.client.ConnectToRelay(ctx, item.RelayHint)
if relayErr == nil { if relayErr == nil {
events, queryErr := relay.QuerySync(ctx, filter) events, queryErr := relay.QuerySync(ctx, filter)
@ -102,27 +115,40 @@ func (ws *WikiService) FetchWikiEvents(ctx context.Context, index *IndexEvent) (
if queryErr == nil { if queryErr == nil {
if len(events) > 0 { if len(events) > 0 {
event = events[0] event = events[0]
log.Printf("Successfully fetched %s from relay hint %s", item.DTag, item.RelayHint) logger.WithFields(map[string]interface{}{
"dtag": item.DTag,
"relay_hint": item.RelayHint,
}).Debug("Successfully fetched from relay hint")
} else { } else {
log.Printf("Relay hint %s returned 0 events for %s (event ID: %v)", item.RelayHint, item.DTag, item.EventID != "") logger.WithFields(map[string]interface{}{
"relay_hint": item.RelayHint,
"dtag": item.DTag,
"has_event_id": item.EventID != "",
}).Debug("Relay hint returned 0 events")
} }
} else { } else {
log.Printf("Error querying relay hint %s for %s: %v", item.RelayHint, item.DTag, queryErr) logger.WithFields(map[string]interface{}{
"relay_hint": item.RelayHint,
"dtag": item.DTag,
}).Debugf("Error querying relay hint: %v", queryErr)
} }
} else { } else {
log.Printf("Error connecting to relay hint %s for %s: %v", item.RelayHint, item.DTag, relayErr) logger.WithFields(map[string]interface{}{
"relay_hint": item.RelayHint,
"dtag": item.DTag,
}).Debugf("Error connecting to relay hint: %v", relayErr)
} }
} }
// Fallback to default client relays if relay hint failed or wasn't provided // Fallback to default client relays if relay hint failed or wasn't provided
// Client now queries all three relays automatically // Client now queries all three relays automatically
if event == nil { if event == nil {
log.Printf("Querying all relays for %s", item.DTag) logger.WithField("dtag", item.DTag).Debug("Querying all relays")
event, err = ws.client.FetchEvent(ctx, filter) event, err = ws.client.FetchEvent(ctx, filter)
if err != nil { if err != nil {
// If still not found and event ID was specified, try without event ID to get latest replaceable event // If still not found and event ID was specified, try without event ID to get latest replaceable event
if item.EventID != "" { if item.EventID != "" {
log.Printf("Trying without event ID for %s to get latest replaceable event", item.DTag) logger.WithField("dtag", item.DTag).Debug("Trying without event ID to get latest replaceable event")
filterWithoutID := nostr.Filter{ filterWithoutID := nostr.Filter{
Kinds: []int{ws.wikiKind}, Kinds: []int{ws.wikiKind},
Authors: []string{item.Pubkey}, Authors: []string{item.Pubkey},
@ -133,16 +159,20 @@ func (ws *WikiService) FetchWikiEvents(ctx context.Context, index *IndexEvent) (
logFilter(filterWithoutID, fmt.Sprintf("wiki event %s (without event ID)", item.DTag)) logFilter(filterWithoutID, fmt.Sprintf("wiki event %s (without event ID)", item.DTag))
event, err = ws.client.FetchEvent(ctx, filterWithoutID) event, err = ws.client.FetchEvent(ctx, filterWithoutID)
if err == nil { if err == nil {
log.Printf("Successfully fetched %s (latest) from all relays", item.DTag) logger.WithField("dtag", item.DTag).Debug("Successfully fetched latest from all relays")
} }
} }
} else { } else {
log.Printf("Successfully fetched %s from all relays", item.DTag) logger.WithField("dtag", item.DTag).Debug("Successfully fetched from all relays")
} }
if event == nil { if event == nil {
// Log error but continue with other events // Log error but continue with other events
log.Printf("Error fetching wiki event for %s (pubkey: %s, event ID: %v): %v", item.DTag, item.Pubkey, item.EventID != "", err) logger.WithFields(map[string]interface{}{
"dtag": item.DTag,
"pubkey": item.Pubkey,
"has_event_id": item.EventID != "",
}).Warnf("Error fetching wiki event: %v", err)
continue continue
} }
} }
@ -150,7 +180,9 @@ func (ws *WikiService) FetchWikiEvents(ctx context.Context, index *IndexEvent) (
// Parse the wiki event // Parse the wiki event
wiki, err := ParseWikiEvent(event, ws.wikiKind) wiki, err := ParseWikiEvent(event, ws.wikiKind)
if err != nil { if err != nil {
log.Printf("Error parsing wiki event for %s: %v", item.DTag, err) logger.WithFields(map[string]interface{}{
"dtag": item.DTag,
}).Warnf("Error parsing wiki event: %v", err)
continue continue
} }
@ -158,7 +190,7 @@ func (ws *WikiService) FetchWikiEvents(ctx context.Context, index *IndexEvent) (
} }
if len(wikiEvents) == 0 && len(index.Items) > 0 { if len(wikiEvents) == 0 && len(index.Items) > 0 {
log.Printf("Warning: No wiki events could be fetched from %d index items", len(index.Items)) logger.WithField("items", len(index.Items)).Warn("No wiki events could be fetched from index items")
// Return empty slice instead of error to allow landing page generation // Return empty slice instead of error to allow landing page generation
} }
@ -222,25 +254,44 @@ func (ws *WikiService) FetchIndexEvents(ctx context.Context, index *IndexEvent,
if len(relayEvents) > 0 { if len(relayEvents) > 0 {
event = relayEvents[0] event = relayEvents[0]
} else { } else {
log.Printf("Relay hint %s returned 0 events for %s (kind %d, event ID: %v)", item.RelayHint, item.DTag, targetKind, item.EventID != "") logger.WithFields(map[string]interface{}{
"relay_hint": item.RelayHint,
"dtag": item.DTag,
"kind": targetKind,
"has_event_id": item.EventID != "",
}).Debug("Relay hint returned 0 events")
} }
} else { } else {
log.Printf("Error querying relay hint %s for %s (kind %d): %v", item.RelayHint, item.DTag, targetKind, queryErr) logger.WithFields(map[string]interface{}{
"relay_hint": item.RelayHint,
"dtag": item.DTag,
"kind": targetKind,
}).Debugf("Error querying relay hint: %v", queryErr)
} }
} else { } else {
log.Printf("Error connecting to relay hint %s for %s (kind %d): %v", item.RelayHint, item.DTag, targetKind, relayErr) logger.WithFields(map[string]interface{}{
"relay_hint": item.RelayHint,
"dtag": item.DTag,
"kind": targetKind,
}).Debugf("Error connecting to relay hint: %v", relayErr)
} }
} }
// Fallback to default client relays if relay hint failed or wasn't provided // Fallback to default client relays if relay hint failed or wasn't provided
// Client now queries all three relays automatically // Client now queries all three relays automatically
if event == nil { if event == nil {
log.Printf("Querying all relays for %s (kind %d)", item.DTag, targetKind) logger.WithFields(map[string]interface{}{
"dtag": item.DTag,
"kind": targetKind,
}).Debug("Querying all relays")
event, err = ws.client.FetchEvent(ctx, filter) event, err = ws.client.FetchEvent(ctx, filter)
if err != nil { if err != nil {
// If still not found and event ID was specified, try without event ID to get latest replaceable event // If still not found and event ID was specified, try without event ID to get latest replaceable event
if item.EventID != "" { if item.EventID != "" {
log.Printf("Trying without event ID for %s (kind %d) to get latest replaceable event", item.DTag, targetKind) logger.WithFields(map[string]interface{}{
"dtag": item.DTag,
"kind": targetKind,
}).Debug("Trying without event ID to get latest replaceable event")
filterWithoutID := nostr.Filter{ filterWithoutID := nostr.Filter{
Kinds: []int{targetKind}, Kinds: []int{targetKind},
Authors: []string{item.Pubkey}, Authors: []string{item.Pubkey},
@ -251,16 +302,27 @@ func (ws *WikiService) FetchIndexEvents(ctx context.Context, index *IndexEvent,
logFilter(filterWithoutID, fmt.Sprintf("index event kind %d %s (without event ID)", targetKind, item.DTag)) logFilter(filterWithoutID, fmt.Sprintf("index event kind %d %s (without event ID)", targetKind, item.DTag))
event, err = ws.client.FetchEvent(ctx, filterWithoutID) event, err = ws.client.FetchEvent(ctx, filterWithoutID)
if err == nil { if err == nil {
log.Printf("Successfully fetched %s (kind %d, latest) from all relays", item.DTag, targetKind) logger.WithFields(map[string]interface{}{
"dtag": item.DTag,
"kind": targetKind,
}).Debug("Successfully fetched latest from all relays")
} }
} }
} else { } else {
log.Printf("Successfully fetched %s (kind %d) from all relays", item.DTag, targetKind) logger.WithFields(map[string]interface{}{
"dtag": item.DTag,
"kind": targetKind,
}).Debug("Successfully fetched from all relays")
} }
if event == nil { if event == nil {
// Log error but continue with other events // Log error but continue with other events
log.Printf("Error fetching event for %s (kind %d, pubkey: %s, event ID: %v): %v", item.DTag, targetKind, item.Pubkey, item.EventID != "", err) logger.WithFields(map[string]interface{}{
"dtag": item.DTag,
"kind": targetKind,
"pubkey": item.Pubkey,
"has_event_id": item.EventID != "",
}).Warnf("Error fetching event: %v", err)
continue continue
} }
} }
@ -269,7 +331,10 @@ func (ws *WikiService) FetchIndexEvents(ctx context.Context, index *IndexEvent,
} }
if len(events) == 0 && len(index.Items) > 0 { if len(events) == 0 && len(index.Items) > 0 {
log.Printf("Warning: No events of kind %d could be fetched from %d index items", targetKind, len(index.Items)) logger.WithFields(map[string]interface{}{
"kind": targetKind,
"items": len(index.Items),
}).Warn("No events could be fetched from index items")
} }
return events, nil return events, nil

20
internal/server/handlers.go

@ -4,7 +4,6 @@ import (
"context" "context"
"encoding/json" "encoding/json"
"fmt" "fmt"
"log"
"net/http" "net/http"
"strings" "strings"
"time" "time"
@ -13,6 +12,7 @@ import (
"gitcitadel-online/internal/cache" "gitcitadel-online/internal/cache"
"gitcitadel-online/internal/generator" "gitcitadel-online/internal/generator"
"gitcitadel-online/internal/logger"
"gitcitadel-online/internal/nostr" "gitcitadel-online/internal/nostr"
) )
@ -115,7 +115,7 @@ func (s *Server) handleContact(w http.ResponseWriter, r *http.Request) {
if s.repoAnnouncement != "" { if s.repoAnnouncement != "" {
repoAnnouncement, err = s.issueService.FetchRepoAnnouncement(ctx, s.repoAnnouncement) repoAnnouncement, err = s.issueService.FetchRepoAnnouncement(ctx, s.repoAnnouncement)
if err != nil { if err != nil {
log.Printf("Failed to fetch repo announcement for contact page: %v", err) logger.Warnf("Failed to fetch repo announcement for contact page: %v", err)
// Continue without repo announcement - form will show error // Continue without repo announcement - form will show error
} }
} }
@ -126,7 +126,7 @@ func (s *Server) handleContact(w http.ResponseWriter, r *http.Request) {
if s.nostrClient != nil { if s.nostrClient != nil {
profile, err = s.nostrClient.FetchProfile(ctx, npub) profile, err = s.nostrClient.FetchProfile(ctx, npub)
if err != nil { if err != nil {
log.Printf("Failed to fetch profile for contact page: %v", err) logger.Warnf("Failed to fetch profile for contact page: %v", err)
// Continue without profile - not critical // Continue without profile - not critical
} }
} }
@ -190,7 +190,7 @@ func (s *Server) handleContact(w http.ResponseWriter, r *http.Request) {
repoAnnouncement, err := s.issueService.FetchRepoAnnouncement(ctx, s.repoAnnouncement) repoAnnouncement, err := s.issueService.FetchRepoAnnouncement(ctx, s.repoAnnouncement)
if err != nil { if err != nil {
log.Printf("Failed to fetch repo announcement: %v", err) logger.Errorf("Failed to fetch repo announcement: %v", err)
formData := map[string]string{ formData := map[string]string{
"subject": subject, "subject": subject,
"content": content, "content": content,
@ -212,7 +212,7 @@ func (s *Server) handleContact(w http.ResponseWriter, r *http.Request) {
// Publish issue (using anonymous key - server generates random key) // Publish issue (using anonymous key - server generates random key)
eventID, err := s.issueService.PublishIssue(ctx, repoAnnouncement, issueReq, "") eventID, err := s.issueService.PublishIssue(ctx, repoAnnouncement, issueReq, "")
if err != nil { if err != nil {
log.Printf("Failed to publish issue: %v", err) logger.Errorf("Failed to publish issue: %v", err)
formData := map[string]string{ formData := map[string]string{
"subject": subject, "subject": subject,
"content": content, "content": content,
@ -265,7 +265,7 @@ func (s *Server) handleContactAPI(w http.ResponseWriter, r *http.Request) {
eventID, err := s.issueService.PublishSignedIssue(ctx, req.Event) eventID, err := s.issueService.PublishSignedIssue(ctx, req.Event)
if err != nil { if err != nil {
log.Printf("Failed to publish signed issue: %v", err) logger.Errorf("Failed to publish signed issue: %v", err)
w.Header().Set("Content-Type", "application/json") w.Header().Set("Content-Type", "application/json")
w.WriteHeader(http.StatusInternalServerError) w.WriteHeader(http.StatusInternalServerError)
fmt.Fprintf(w, `{"error": "Failed to publish issue: %s"}`, err.Error()) fmt.Fprintf(w, `{"error": "Failed to publish issue: %s"}`, err.Error())
@ -367,9 +367,13 @@ func (s *Server) middleware(next http.Handler) http.Handler {
// CSP header - allow unpkg.com for Lucide icons // CSP header - allow unpkg.com for Lucide icons
w.Header().Set("Content-Security-Policy", "default-src 'self'; script-src 'self' 'unsafe-inline' https://unpkg.com; style-src 'self' 'unsafe-inline'; img-src 'self' data: https:; font-src 'self' data:;") w.Header().Set("Content-Security-Policy", "default-src 'self'; script-src 'self' 'unsafe-inline' https://unpkg.com; style-src 'self' 'unsafe-inline'; img-src 'self' data: https:; font-src 'self' data:;")
// Log request // Log request (only in debug mode to reduce noise)
start := time.Now() start := time.Now()
next.ServeHTTP(w, r) next.ServeHTTP(w, r)
log.Printf("%s %s %v", r.Method, r.URL.Path, time.Since(start)) logger.WithFields(map[string]interface{}{
"method": r.Method,
"path": r.URL.Path,
"duration": time.Since(start),
}).Debug("HTTP request")
}) })
} }

10
internal/server/server.go

@ -3,7 +3,6 @@ package server
import ( import (
"context" "context"
"fmt" "fmt"
"log"
"net/http" "net/http"
"os" "os"
"os/signal" "os/signal"
@ -14,6 +13,7 @@ import (
"gitcitadel-online/internal/cache" "gitcitadel-online/internal/cache"
"gitcitadel-online/internal/generator" "gitcitadel-online/internal/generator"
"gitcitadel-online/internal/logger"
"gitcitadel-online/internal/nostr" "gitcitadel-online/internal/nostr"
) )
@ -72,7 +72,7 @@ func NewServer(port int, pageCache *cache.Cache, feedCache *cache.FeedCache, iss
// Start starts the HTTP server // Start starts the HTTP server
func (s *Server) Start() error { func (s *Server) Start() error {
log.Printf("Starting server on port %d", s.port) logger.Infof("Starting server on port %d", s.port)
return s.httpServer.ListenAndServe() return s.httpServer.ListenAndServe()
} }
@ -86,16 +86,16 @@ func (s *Server) WaitForShutdown() {
quit := make(chan os.Signal, 1) quit := make(chan os.Signal, 1)
signal.Notify(quit, syscall.SIGINT, syscall.SIGTERM) signal.Notify(quit, syscall.SIGINT, syscall.SIGTERM)
<-quit <-quit
log.Println("Shutting down server...") logger.Info("Shutting down server...")
ctx, cancel := context.WithTimeout(context.Background(), 30*time.Second) ctx, cancel := context.WithTimeout(context.Background(), 30*time.Second)
defer cancel() defer cancel()
if err := s.Shutdown(ctx); err != nil { if err := s.Shutdown(ctx); err != nil {
log.Fatal("Server forced to shutdown:", err) logger.Fatal("Server forced to shutdown:", err)
} }
log.Println("Server exited") logger.Info("Server exited")
} }
// convertFeedItemsToInfo converts cache.FeedItem to generator.FeedItemInfo // convertFeedItemsToInfo converts cache.FeedItem to generator.FeedItemInfo

Loading…
Cancel
Save