Skip to content

Commit 66dea0b

Browse files
committed
revised logging, more to come... thanks, @ofkm/arcane !
1 parent f4b26b4 commit 66dea0b

7 files changed

Lines changed: 197 additions & 73 deletions

File tree

cmd/dxcluster-client/main.go

Lines changed: 20 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -84,17 +84,21 @@ func RunApplication(ctx context.Context, args []string) int {
8484
if v := os.Getenv("LOG_LEVEL"); v != "" {
8585
lvl := strings.ToLower(strings.TrimSpace(v))
8686
switch lvl {
87-
case "error", "err", "e", "0":
87+
case "crit", "critical", "c", "0":
88+
logging.SetLevel(logging.LevelCrit)
89+
case "error", "err", "e", "1":
8890
logging.SetLevel(logging.LevelError)
89-
case "warn", "warning", "w", "1":
91+
case "warn", "warning", "w", "2":
9092
logging.SetLevel(logging.LevelWarn)
91-
case "info", "i", "2":
93+
case "notice", "n", "3":
94+
logging.SetLevel(logging.LevelNotice)
95+
case "info", "i", "4":
9296
logging.SetLevel(logging.LevelInfo)
93-
case "debug", "d", "3":
97+
case "debug", "d", "5":
9498
logging.SetLevel(logging.LevelDebug)
9599
default:
96100
// Unknown value; emit a warning via leveled logger and keep default
97-
logging.Warn("Unrecognized LOG_LEVEL=%q; valid: error,warn,info,debug or 0-3. Using default.", v)
101+
logging.Warn("Unrecognized LOG_LEVEL=%q; valid: crit,error,warn,notice,info,debug or 0-5. Using default (NOTICE).", v)
98102
}
99103
}
100104

@@ -147,7 +151,11 @@ func RunApplication(ctx context.Context, args []string) int {
147151
if len(cfg.Clusters) > 0 {
148152
logging.Info("DX Clusters configured: %d", len(cfg.Clusters))
149153
for i, cluster := range cfg.Clusters {
150-
logging.Info(" Cluster %d: %s:%s callsign=%s", i+1, cluster.Host, cluster.Port, cluster.Callsign)
154+
sotaFlag := "no"
155+
if cluster.SOTA {
156+
sotaFlag = "yes"
157+
}
158+
logging.Info(" Cluster %d: %s:%s callsign=%s sota=%s", i+1, cluster.Host, cluster.Port, cluster.Callsign, sotaFlag)
151159
}
152160
} else {
153161
logging.Warn("No DX Clusters configured.")
@@ -317,8 +325,12 @@ func RunApplication(ctx context.Context, args []string) int {
317325
// --- 7. Create Spot Cache and Set up HTTP API BEFORE connecting spot sources ---
318326
centralSpotCache := newSpotCache(cfg.MaxCache)
319327

320-
router := gin.Default()
321-
router.SetTrustedProxies(nil) // To prevent "x-forwarded-for" issues if not behind a proxy
328+
// Create Gin router with our custom logging (not gin.Default())
329+
gin.SetMode(gin.ReleaseMode) // Suppress gin's startup messages
330+
router := gin.New()
331+
router.Use(logging.GinRecovery()) // Our recovery middleware
332+
router.Use(logging.GinLogger()) // Our logging middleware
333+
router.SetTrustedProxies(nil) // To prevent "x-forwarded-for" issues if not behind a proxy
322334

323335
// Middleware to handle BaseURL prefix if configured
324336
if cfg.BaseURL != "/" && cfg.BaseURL != "" {

internal/cluster/client.go

Lines changed: 6 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -206,14 +206,14 @@ func (c *Client) connectOnce(ctx context.Context) error {
206206
ctx = context.Background()
207207
}
208208
addr := net.JoinHostPort(c.cfg.Host, c.cfg.Port)
209-
logging.Info("[%s] Attempting to connect to DX cluster %s...", time.Now().Format(time.RFC3339), addr)
209+
logging.Info("Attempting to connect to DX cluster %s...", addr)
210210

211211
conn, err := net.DialTimeout("tcp", addr, 10*time.Second) // Connection timeout
212212
if err != nil {
213213
return fmt.Errorf("failed to connect to %s: %w", addr, err)
214214
}
215215
c.conn = conn
216-
logging.Info("[%s] Connected to DX cluster %s.", time.Now().Format(time.RFC3339), addr)
216+
logging.Info("Connected to DX cluster %s.", addr)
217217

218218
c.statusMutex.Lock()
219219
c.isConnected = true
@@ -241,7 +241,7 @@ func (c *Client) connectOnce(ctx context.Context) error {
241241
c.conn = nil
242242
}
243243
c.statusMutex.Unlock()
244-
logging.Info("[%s] Connection to DX cluster %s closed.", time.Now().Format(time.RFC3339), addr)
244+
logging.Info("Connection to DX cluster %s closed.", addr)
245245

246246
// Determine if readLoop exited due to error or graceful shutdown
247247
select {
@@ -396,7 +396,7 @@ func (c *Client) readLoop(ctx context.Context) {
396396
// Respect cancellation quickly by checking context before attempting a read.
397397
select {
398398
case <-ctx.Done():
399-
logging.Info("[%s] Read loop for %s cancelled by context.", time.Now().Format(time.RFC3339), net.JoinHostPort(c.cfg.Host, c.cfg.Port))
399+
logging.Info("Read loop for %s cancelled by context.", net.JoinHostPort(c.cfg.Host, c.cfg.Port))
400400
return
401401
default:
402402
}
@@ -427,7 +427,7 @@ func (c *Client) readLoop(ctx context.Context) {
427427
continue
428428
}
429429
if err == io.EOF {
430-
logging.Info("[%s] Reader for %s exited gracefully (EOF).", time.Now().Format(time.RFC3339), net.JoinHostPort(c.cfg.Host, c.cfg.Port))
430+
logging.Info("Reader for %s exited gracefully (EOF).", net.JoinHostPort(c.cfg.Host, c.cfg.Port))
431431
return
432432
}
433433
c.safeSendError(fmt.Errorf("error reading from DX cluster %s: %w", net.JoinHostPort(c.cfg.Host, c.cfg.Port), err))
@@ -444,7 +444,7 @@ func (c *Client) readLoop(ctx context.Context) {
444444
c.safeSendError(fmt.Errorf("error sending callsign to %s: %w", c.cfg.Host, err))
445445
return // Exit readLoop, trigger reconnection
446446
}
447-
logging.Debug("[%s] Sent callsign to %s.", time.Now().Format(time.RFC3339), net.JoinHostPort(c.cfg.Host, c.cfg.Port))
447+
logging.Debug("Sent callsign to %s.", net.JoinHostPort(c.cfg.Host, c.cfg.Port))
448448
awaitingLogin = false
449449
continue
450450
}
@@ -490,17 +490,6 @@ func (c *Client) parseDX(ctx context.Context, dxString string) {
490490
freqStr := m[3]
491491
message := m[5]
492492

493-
// Some cluster lines omit an explicit message and place a single token
494-
// (e.g., "FIRST") where the message would be. In those cases the
495-
// regex captures that token as the 'spotted' group and leaves message
496-
// empty. Tests expect that token to be used as the message. If the
497-
// message capture is empty, shift the spotted token into message and
498-
// clear spotted.
499-
if strings.TrimSpace(message) == "" && strings.TrimSpace(spotted) != "" {
500-
message = spotted
501-
spotted = ""
502-
}
503-
504493
frequency, err := ParseFrequency(freqStr)
505494
if err != nil {
506495
c.safeSendError(fmt.Errorf("failed to parse frequency '%s' from DX string '%s' from %s: %w", freqStr, dxString, c.cfg.Host, err))

internal/dxcc/client.go

Lines changed: 12 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -582,7 +582,7 @@ func (c *Client) StartUpdater(ctx context.Context) {
582582

583583
// fetchAndStoreData downloads the cty.xml.gz, parses it, and replaces data in the database.
584584
func (c *Client) fetchAndStoreData(ctx context.Context) {
585-
logging.Info("[%s] Fetching DXCC data...", time.Now().Format(time.RFC3339))
585+
logging.Info("Fetching DXCC data...")
586586
var (
587587
data []byte
588588
err error
@@ -623,7 +623,7 @@ func (c *Client) fetchAndStoreData(ctx context.Context) {
623623
}
624624
}
625625
if err != nil {
626-
logging.Warn("[%s] Club Log download failed after retries: %v. Falling back to GitHub URL.", time.Now().Format(time.RFC3339), err)
626+
logging.Warn("Club Log download failed after retries: %v. Falling back to GitHub URL.", err)
627627
// Fallback to GitHub
628628
// Use Config override for fallback if present
629629
fallback := config.FallbackGitHubURL
@@ -649,10 +649,10 @@ func (c *Client) fetchAndStoreData(ctx context.Context) {
649649
}
650650
}
651651
if err != nil {
652-
logging.Error("[%s] Both Club Log and GitHub DXCC downloads failed after retries: %v", time.Now().Format(time.RFC3339), err)
652+
logging.Error("Both Club Log and GitHub DXCC downloads failed after retries: %v", err)
653653
return
654654
}
655-
logging.Info("[%s] Successfully downloaded DXCC data from GitHub fallback.", time.Now().Format(time.RFC3339))
655+
logging.Info("Successfully downloaded DXCC data from GitHub fallback.")
656656
// Debug: show a small diagnostic about the fetched payload to help tests
657657
gz := false
658658
if len(data) >= 2 && data[0] == 0x1f && data[1] == 0x8b {
@@ -666,35 +666,35 @@ func (c *Client) fetchAndStoreData(ctx context.Context) {
666666
head = string(data)
667667
}
668668
}
669-
logging.Debug("[%s] DXCC fallback download diagnostics: bytes=%d gzipped=%t head=%q", time.Now().Format(time.RFC3339), len(data), gz, head)
669+
logging.Debug("DXCC fallback download diagnostics: bytes=%d gzipped=%t head=%q", len(data), gz, head)
670670
} else {
671-
logging.Info("[%s] Successfully downloaded DXCC data from Club Log.", time.Now().Format(time.RFC3339))
671+
logging.Info("Successfully downloaded DXCC data from Club Log.")
672672
}
673673

674674
xmlData, err := c.decompressAndParseXML(data)
675675
if err != nil {
676-
logging.Error("[%s] Failed to decompress/parse DXCC XML: %v", time.Now().Format(time.RFC3339), err)
676+
logging.Error("Failed to decompress/parse DXCC XML: %v", err)
677677
return
678678
}
679679

680680
if err := c.replaceDataInDB(ctx, xmlData); err != nil {
681-
logging.Error("[%s] Failed to store DXCC data in DB: %v", time.Now().Format(time.RFC3339), err)
681+
logging.Error("Failed to store DXCC data in DB: %v", err)
682682
} else {
683-
logging.Info("[%s] DXCC data update completed. Reloading in-memory maps.", time.Now().Format(time.RFC3339))
683+
logging.Info("DXCC data update completed. Reloading in-memory maps.")
684684

685685
// Force a WAL checkpoint to ensure data is flushed to disk immediately
686686
if _, err := c.dbClient.GetDB().ExecContext(ctx, "PRAGMA wal_checkpoint(FULL);"); err != nil {
687-
logging.Warn("[%s] Failed to checkpoint WAL after DXCC update: %v", time.Now().Format(time.RFC3339), err)
687+
logging.Warn("Failed to checkpoint WAL after DXCC update: %v", err)
688688
}
689689

690690
// Record the successful download
691691
if err := c.updateLastDownloadTime(ctx, sourceURL, len(data)); err != nil {
692-
logging.Warn("[%s] Failed to update DXCC download metadata: %v", time.Now().Format(time.RFC3339), err)
692+
logging.Warn("Failed to update DXCC download metadata: %v", err)
693693
}
694694

695695
// Reload in-memory maps after DB update
696696
if err := c.loadMapsFromDB(ctx); err != nil {
697-
logging.Error("[%s] Failed to reload DXCC maps after update: %v", time.Now().Format(time.RFC3339), err)
697+
logging.Error("Failed to reload DXCC maps after update: %v", err)
698698
}
699699
}
700700
}

internal/logging/gin_middleware.go

Lines changed: 62 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,62 @@
1+
package logging
2+
3+
import (
4+
"fmt"
5+
"time"
6+
7+
"github.com/gin-gonic/gin"
8+
)
9+
10+
// GinLogger returns a gin.HandlerFunc middleware that logs requests using our logger
11+
func GinLogger() gin.HandlerFunc {
12+
return func(c *gin.Context) {
13+
// Start timer
14+
start := time.Now()
15+
path := c.Request.URL.Path
16+
raw := c.Request.URL.RawQuery
17+
18+
// Process request
19+
c.Next()
20+
21+
// Calculate latency
22+
latency := time.Since(start)
23+
24+
// Get status code
25+
statusCode := c.Writer.Status()
26+
27+
// Build the query string if present
28+
if raw != "" {
29+
path = path + "?" + raw
30+
}
31+
32+
// Determine log level based on status code
33+
msg := fmt.Sprintf("%s %s - %d (%v) - %s",
34+
c.Request.Method,
35+
path,
36+
statusCode,
37+
latency,
38+
c.ClientIP(),
39+
)
40+
41+
if statusCode >= 500 {
42+
Error(msg)
43+
} else if statusCode >= 400 {
44+
Warn(msg)
45+
} else {
46+
Debug(msg) // HTTP requests are debug level
47+
}
48+
}
49+
}
50+
51+
// GinRecovery returns a gin.HandlerFunc middleware that recovers from panics
52+
func GinRecovery() gin.HandlerFunc {
53+
return func(c *gin.Context) {
54+
defer func() {
55+
if err := recover(); err != nil {
56+
Crit("PANIC recovered: %v", err)
57+
c.AbortWithStatus(500)
58+
}
59+
}()
60+
c.Next()
61+
}
62+
}

internal/logging/logger.go

Lines changed: 77 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -1,54 +1,115 @@
11
package logging
22

33
import (
4+
"fmt"
5+
"io"
46
"log"
57
"os"
8+
"time"
69
)
710

8-
// Log levels (higher number = more verbose)
11+
// ANSI color codes
912
const (
10-
LevelError = iota // 0
11-
LevelWarn // 1
12-
LevelInfo // 2
13-
LevelDebug // 3
13+
colorReset = "\033[0m"
14+
colorRed = "\033[31m"
15+
colorYellow = "\033[33m"
16+
colorBlue = "\033[34m"
17+
colorCyan = "\033[36m"
18+
colorGray = "\033[90m"
19+
colorWhite = "\033[97m"
20+
)
21+
22+
// Log levels
23+
const (
24+
LevelCrit = iota // 0 - Critical errors (fatal, app should stop)
25+
LevelError // 1 - Errors (non-fatal but important)
26+
LevelWarn // 2 - Warnings
27+
LevelNotice // 3 - Important info (startup, shutdown, config)
28+
LevelInfo // 4 - General info
29+
LevelDebug // 5 - Debug details
1430
)
1531

1632
var (
1733
// Logger is the package-level logger used across the project.
18-
Logger = log.New(os.Stdout, "", log.LstdFlags)
19-
// Level controls verbosity. Default to WARN for sane production defaults.
20-
Level = LevelWarn
34+
Logger = log.New(os.Stdout, "", 0) // We'll handle our own formatting
35+
// Level controls verbosity. Default to NOTICE for sane production defaults.
36+
Level = LevelNotice
37+
UseColors = true // Enable colors by default
38+
TimeFormat = "Jan 02 15:04:05.000" // Kyle's format: "Oct 14 13:16:37.788"
2139
)
2240

2341
// SetLevel sets the logger verbosity level.
2442
func SetLevel(l int) {
2543
Level = l
2644
}
2745

28-
// Error logs error-level messages (always important).
46+
// SetOutput sets the output destination for logs
47+
func SetOutput(w io.Writer) {
48+
Logger.SetOutput(w)
49+
}
50+
51+
// DisableColors disables color output
52+
func DisableColors() {
53+
UseColors = false
54+
}
55+
56+
// formatLog formats a log message with timestamp, colored level (3-letter), and message
57+
func formatLog(levelAbbrev, color, message string) string {
58+
timestamp := time.Now().Format(TimeFormat)
59+
60+
if UseColors {
61+
// Format: "Oct 14 13:16:37.788 INF message"
62+
return fmt.Sprintf("%s %s%s%s %s", timestamp, color, levelAbbrev, colorReset, message)
63+
}
64+
65+
// No colors
66+
return fmt.Sprintf("%s %s %s", timestamp, levelAbbrev, message)
67+
}
68+
69+
// Crit logs critical errors (application should stop)
70+
func Crit(format string, v ...interface{}) {
71+
if Level >= LevelCrit {
72+
msg := fmt.Sprintf(format, v...)
73+
Logger.Print(formatLog("CRT", colorRed, msg))
74+
}
75+
}
76+
77+
// Error logs error-level messages (non-fatal but important)
2978
func Error(format string, v ...interface{}) {
3079
if Level >= LevelError {
31-
Logger.Printf("| ERROR | "+format, v...)
80+
msg := fmt.Sprintf(format, v...)
81+
Logger.Print(formatLog("ERR", colorRed, msg))
3282
}
3383
}
3484

35-
// Warn logs warning-level messages.
85+
// Warn logs warning-level messages
3686
func Warn(format string, v ...interface{}) {
3787
if Level >= LevelWarn {
38-
Logger.Printf("| WARN | "+format, v...)
88+
msg := fmt.Sprintf(format, v...)
89+
Logger.Print(formatLog("WRN", colorYellow, msg))
90+
}
91+
}
92+
93+
// Notice logs important informational messages (startup, config, shutdown)
94+
func Notice(format string, v ...interface{}) {
95+
if Level >= LevelNotice {
96+
msg := fmt.Sprintf(format, v...)
97+
Logger.Print(formatLog("NOT", colorCyan, msg))
3998
}
4099
}
41100

42-
// Info logs informational messages (less noisy).
101+
// Info logs general informational messages
43102
func Info(format string, v ...interface{}) {
44103
if Level >= LevelInfo {
45-
Logger.Printf("| INFO | "+format, v...)
104+
msg := fmt.Sprintf(format, v...)
105+
Logger.Print(formatLog("INF", colorWhite, msg))
46106
}
47107
}
48108

49-
// Debug logs very verbose diagnostic messages.
109+
// Debug logs very verbose diagnostic messages
50110
func Debug(format string, v ...interface{}) {
51111
if Level >= LevelDebug {
52-
Logger.Printf("| DEBUG | "+format, v...)
112+
msg := fmt.Sprintf(format, v...)
113+
Logger.Print(formatLog("DBG", colorGray, msg))
53114
}
54115
}

0 commit comments

Comments
 (0)