feat(server): add colored logs, level rewards, hunting dispatch and fiend hunt

Persist claims, AP, teams and presets with session receipts and atomic request rollback. Read rewards and growth from GameData; replace fixed Fiend Hunt user state and preserve the account initialization contract.
2026-10-04 21:27:19 +08:00
parent abc8368d36
commit d04791dd31
43 changed files with 4670 additions and 62 deletions
@@ -0,0 +1,180 @@
+// Package logging configures the server's structured console logging.
+package logging
+
+import (
+	"bytes"
+	"context"
+	"fmt"
+	"io"
+	"log/slog"
+	"os"
+	"strings"
+)
+
+const LevelTrace slog.Level = -8
+
+type ColorMode string
+
+const (
+	ColorAuto   ColorMode = "auto"
+	ColorAlways ColorMode = "always"
+	ColorNever  ColorMode = "never"
+)
+
+type Options struct {
+	// Level defaults to INFO. A *slog.LevelVar supports changes at runtime.
+	Level slog.Leveler
+	// Color defaults to auto; always explicitly forces ANSI, including in pipes.
+	Color ColorMode
+}
+
+// OptionsFromEnv reads process-wide defaults for every server command.
+func OptionsFromEnv() (Options, error) {
+	options := Options{Level: slog.LevelInfo, Color: ColorAuto}
+	if value := os.Getenv("BD2_LOG_LEVEL"); value != "" {
+		level, err := ParseLevel(value)
+		if err != nil {
+			return Options{}, err
+		}
+		options.Level = level
+	}
+	if value := os.Getenv("BD2_LOG_COLOR"); value != "" {
+		color, err := ParseColorMode(value)
+		if err != nil {
+			return Options{}, err
+		}
+		options.Color = color
+	}
+	return options, nil
+}
+
+func ParseLevel(value string) (slog.Level, error) {
+	switch strings.ToLower(strings.TrimSpace(value)) {
+	case "trace":
+		return LevelTrace, nil
+	case "debug":
+		return slog.LevelDebug, nil
+	case "info":
+		return slog.LevelInfo, nil
+	case "warn", "warning":
+		return slog.LevelWarn, nil
+	case "error":
+		return slog.LevelError, nil
+	default:
+		return 0, fmt.Errorf("invalid log level %q (use trace, debug, info, warn, or error)", value)
+	}
+}
+
+func ParseColorMode(value string) (ColorMode, error) {
+	mode := ColorMode(strings.ToLower(strings.TrimSpace(value)))
+	if mode != ColorAuto && mode != ColorAlways && mode != ColorNever {
+		return "", fmt.Errorf("invalid log color %q (use auto, always, or never)", value)
+	}
+	return mode, nil
+}
+
+// Setup installs a logger as slog.Default, so existing slog callers use it too.
+func Setup(writer io.Writer, options Options) (*slog.Logger, error) {
+	handler, err := NewHandler(writer, options)
+	if err != nil {
+		return nil, err
+	}
+	logger := slog.New(handler)
+	slog.SetDefault(logger)
+	return logger, nil
+}
+
+// NewHandler retains slog's quoting, groups, LogValuer resolution and shared
+// write lock. Only the built-in level label is colored; attributes stay intact.
+func NewHandler(writer io.Writer, options Options) (slog.Handler, error) {
+	if writer == nil {
+		return nil, fmt.Errorf("log writer is nil")
+	}
+	mode := options.Color
+	if mode == "" {
+		mode = ColorAuto
+	}
+	if _, err := ParseColorMode(string(mode)); err != nil {
+		return nil, err
+	}
+	color := mode == ColorAlways
+	if mode == ColorAuto {
+		if file, ok := writer.(*os.File); ok && autoColorAllowed() {
+			color = terminalSupportsColor(file)
+		}
+	}
+	if color {
+		writer = levelColorWriter{writer}
+	}
+	return slog.NewTextHandler(writer, &slog.HandlerOptions{
+		Level: options.Level,
+		ReplaceAttr: func(groups []string, attr slog.Attr) slog.Attr {
+			if len(groups) == 0 && attr.Key == slog.LevelKey {
+				if level, ok := attr.Value.Any().(slog.Level); ok && level == LevelTrace {
+					return slog.String(slog.LevelKey, "TRACE")
+				}
+			}
+			return attr
+		},
+	}), nil
+}
+
+func autoColorAllowed() bool {
+	_, noColor := os.LookupEnv("NO_COLOR")
+	return !noColor && os.Getenv("TERM") != "dumb"
+}
+
+type levelColorWriter struct{ io.Writer }
+
+func (w levelColorWriter) Write(data []byte) (int, error) {
+	// TextHandler emits time, level, then msg. Search only before msg, so
+	// user attributes or messages containing "level=" cannot select a color.
+	end := bytes.Index(data, []byte(" msg="))
+	if end < 0 {
+		return w.Writer.Write(data)
+	}
+	start := bytes.Index(data[:end], []byte(" level="))
+	if start < 0 {
+		return w.Writer.Write(data)
+	}
+	start += len(" level=")
+	label := string(data[start:end])
+	var color string
+	switch {
+	case strings.HasPrefix(label, "TRACE"):
+		color = "\x1b[90m"
+	case strings.HasPrefix(label, "DEBUG"):
+		color = "\x1b[36m"
+	case strings.HasPrefix(label, "INFO"):
+		color = "\x1b[32m"
+	case strings.HasPrefix(label, "WARN"):
+		color = "\x1b[33m"
+	case strings.HasPrefix(label, "ERROR"):
+		color = "\x1b[31m"
+	default:
+		return w.Writer.Write(data)
+	}
+	output := make([]byte, 0, len(data)+len(color)+4)
+	output = append(output, data[:start]...)
+	output = append(output, color...)
+	output = append(output, data[start:end]...)
+	output = append(output, "\x1b[0m"...)
+	output = append(output, data[end:]...)
+	n, err := w.Writer.Write(output)
+	if err == nil && n != len(output) {
+		err = io.ErrShortWrite
+	}
+	if err != nil {
+		return 0, err
+	}
+	return len(data), nil
+}
+
+func Trace(message string, args ...any) { TraceContext(context.Background(), message, args...) }
+func TraceContext(ctx context.Context, message string, args ...any) {
+	slog.Log(ctx, LevelTrace, message, args...)
+}
+func Debug(message string, args ...any) { slog.Debug(message, args...) }
+func Info(message string, args ...any)  { slog.Info(message, args...) }
+func Warn(message string, args ...any)  { slog.Warn(message, args...) }
+func Error(message string, args ...any) { slog.Error(message, args...) }
@@ -0,0 +1,137 @@
+package logging
+
+import (
+	"bytes"
+	"context"
+	"io"
+	"log/slog"
+	"os"
+	"strings"
+	"sync"
+	"testing"
+)
+
+func TestLevelsAndColors(t *testing.T) {
+	for _, test := range []struct {
+		name, ansi string
+		level      slog.Level
+	}{
+		{"TRACE", "90", LevelTrace}, {"DEBUG", "36", slog.LevelDebug},
+		{"INFO", "32", slog.LevelInfo}, {"WARN", "33", slog.LevelWarn}, {"ERROR", "31", slog.LevelError},
+	} {
+		t.Run(test.name, func(t *testing.T) {
+			var out bytes.Buffer
+			h, err := NewHandler(&out, Options{Level: LevelTrace, Color: ColorAlways})
+			if err != nil {
+				t.Fatal(err)
+			}
+			slog.New(h).Log(context.Background(), test.level, "hello", "level", "ERROR", "text", "a\nb")
+			want := "level=\x1b[" + test.ansi + "m" + test.name + "\x1b[0m msg=hello level=ERROR text=\"a\\nb\""
+			if !strings.Contains(out.String(), want) {
+				t.Fatalf("output=%q want fragment=%q", out.String(), want)
+			}
+		})
+	}
+}
+
+func TestFilterAndDynamicLevel(t *testing.T) {
+	var out bytes.Buffer
+	var level slog.LevelVar
+	h, _ := NewHandler(&out, Options{Level: &level, Color: ColorNever})
+	logger := slog.New(h)
+	logger.Log(context.Background(), LevelTrace, "hidden")
+	logger.Debug("hidden")
+	logger.Info("visible")
+	if strings.Contains(out.String(), "hidden") {
+		t.Fatal(out.String())
+	}
+	level.Set(LevelTrace)
+	logger.Log(context.Background(), LevelTrace, "trace visible")
+	if !strings.Contains(out.String(), "level=TRACE msg=\"trace visible\"") {
+		t.Fatal(out.String())
+	}
+}
+
+func TestGroupsAndConcurrentDerivedLoggers(t *testing.T) {
+	var out bytes.Buffer
+	h, _ := NewHandler(&out, Options{Color: ColorAlways})
+	logger := slog.New(h).With("service", "server").WithGroup("request").With("id", 7)
+	var workers sync.WaitGroup
+	for i := 0; i < 50; i++ {
+		workers.Add(1)
+		go func() { defer workers.Done(); logger.Info("handled", slog.Group("result", "ok", true)) }()
+	}
+	workers.Wait()
+	lines := strings.Split(strings.TrimSpace(out.String()), "\n")
+	if len(lines) != 50 {
+		t.Fatalf("lines=%d", len(lines))
+	}
+	for _, line := range lines {
+		if !strings.Contains(line, "service=server request.id=7 request.result.ok=true") || strings.Count(line, "\x1b[0m") != 1 {
+			t.Fatalf("damaged record %q", line)
+		}
+	}
+}
+
+func TestAutoRedirectedOutputIsPlain(t *testing.T) {
+	file, err := os.CreateTemp(t.TempDir(), "log")
+	if err != nil {
+		t.Fatal(err)
+	}
+	defer file.Close()
+	h, _ := NewHandler(file, Options{})
+	slog.New(h).Warn("redirected")
+	if _, err := file.Seek(0, 0); err != nil {
+		t.Fatal(err)
+	}
+	data, err := io.ReadAll(file)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if bytes.Contains(data, []byte("\x1b")) {
+		t.Fatalf("ANSI in redirected log %q", data)
+	}
+	var out bytes.Buffer
+	h, _ = NewHandler(&out, Options{})
+	slog.New(h).Info("buffer")
+	if strings.Contains(out.String(), "\x1b") {
+		t.Fatal(out.String())
+	}
+}
+
+func TestEnvironmentAndValidation(t *testing.T) {
+	t.Setenv("BD2_LOG_LEVEL", "trace")
+	t.Setenv("BD2_LOG_COLOR", "never")
+	options, err := OptionsFromEnv()
+	if err != nil || options.Level.Level() != LevelTrace || options.Color != ColorNever {
+		t.Fatalf("options=%+v err=%v", options, err)
+	}
+	t.Setenv("BD2_LOG_LEVEL", "invalid")
+	if _, err := OptionsFromEnv(); err == nil {
+		t.Fatal("invalid level accepted")
+	}
+	if _, err := ParseColorMode("invalid"); err == nil {
+		t.Fatal("invalid color accepted")
+	}
+	if _, err := NewHandler(nil, Options{}); err == nil {
+		t.Fatal("nil writer accepted")
+	}
+}
+
+func TestAutoColorEnvironment(t *testing.T) {
+	t.Setenv("TERM", "xterm-256color")
+	t.Setenv("NO_COLOR", "")
+	if autoColorAllowed() {
+		t.Fatal("NO_COLOR presence must suppress auto color")
+	}
+	if err := os.Unsetenv("NO_COLOR"); err != nil {
+		t.Fatal(err)
+	}
+	if !autoColorAllowed() {
+		t.Fatal("ordinary terminal must allow auto color")
+	}
+	t.Setenv("TERM", "dumb")
+	if autoColorAllowed() {
+		t.Fatal("dumb terminal must suppress auto color")
+	}
+}
@@ -0,0 +1,10 @@
+//go:build !windows
+
+package logging
+
+import (
+	"github.com/mattn/go-isatty"
+	"os"
+)
+
+func terminalSupportsColor(file *os.File) bool { return isatty.IsTerminal(file.Fd()) }
@@ -0,0 +1,17 @@
+//go:build windows
+
+package logging
+
+import (
+	"golang.org/x/sys/windows"
+	"os"
+)
+
+func terminalSupportsColor(file *os.File) bool {
+	handle := windows.Handle(file.Fd())
+	var mode uint32
+	if windows.GetConsoleMode(handle, &mode) != nil {
+		return false
+	}
+	return windows.SetConsoleMode(handle, mode|windows.ENABLE_VIRTUAL_TERMINAL_PROCESSING) == nil
+}