Skip to content

Commit 2847b7c

Browse files
xuncvxuncv
committed
feat: 增加日志记录
1 parent d11ee51 commit 2847b7c

4 files changed

Lines changed: 197 additions & 21 deletions

File tree

‎server/internal/config/config.go‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,8 @@ type Config struct {
1313
UpstreamTimeout time.Duration
1414
MCPStateless bool
1515
MCPSessionTTL time.Duration
16+
LogDir string // log file directory; empty = stdout only
17+
LogLevel string // debug/info/warn/error
1618
}
1719

1820
func FromEnv() Config {
@@ -27,6 +29,8 @@ func FromEnv() Config {
2729
timeout := getenvDuration("UPSTREAM_TIMEOUT", 150*time.Second)
2830
mcpStateless := getenvBool("MCP_STATELESS", true)
2931
mcpSessionTTL := getenvDuration("MCP_SESSION_TTL", 10*time.Minute)
32+
logDir := getenv("LOG_DIR", "")
33+
logLevel := getenv("LOG_LEVEL", "info")
3034

3135
return Config{
3236
ListenAddr: listenAddr,
@@ -35,6 +39,8 @@ func FromEnv() Config {
3539
UpstreamTimeout: timeout,
3640
MCPStateless: mcpStateless,
3741
MCPSessionTTL: mcpSessionTTL,
42+
LogDir: logDir,
43+
LogLevel: logLevel,
3844
}
3945
}
4046

‎server/internal/logger/daily_rotate.go‎

Lines changed: 69 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,69 @@
1+
package logger
2+
3+
import (
4+
"fmt"
5+
"os"
6+
"path/filepath"
7+
"sync"
8+
"time"
9+
)
10+
11+
// DailyRotateWriter is an io.WriteCloser that writes to daily-rotated log files.
12+
// File name format: {dir}/{prefix}-{YYYY-MM-DD}.log
13+
type DailyRotateWriter struct {
14+
dir string
15+
prefix string
16+
17+
mu sync.Mutex
18+
current *os.File
19+
curDate string
20+
}
21+
22+
func NewDailyRotateWriter(dir, prefix string) *DailyRotateWriter {
23+
return &DailyRotateWriter{dir: dir, prefix: prefix}
24+
}
25+
26+
func (w *DailyRotateWriter) Write(p []byte) (int, error) {
27+
w.mu.Lock()
28+
defer w.mu.Unlock()
29+
30+
today := time.Now().Format("2006-01-02")
31+
if w.current == nil || today != w.curDate {
32+
if err := w.rotateLocked(today); err != nil {
33+
return 0, err
34+
}
35+
}
36+
return w.current.Write(p)
37+
}
38+
39+
func (w *DailyRotateWriter) Close() error {
40+
w.mu.Lock()
41+
defer w.mu.Unlock()
42+
if w.current != nil {
43+
err := w.current.Close()
44+
w.current = nil
45+
return err
46+
}
47+
return nil
48+
}
49+
50+
func (w *DailyRotateWriter) rotateLocked(date string) error {
51+
if w.current != nil {
52+
_ = w.current.Close()
53+
w.current = nil
54+
}
55+
56+
if err := os.MkdirAll(w.dir, 0o755); err != nil {
57+
return fmt.Errorf("create log dir: %w", err)
58+
}
59+
60+
name := filepath.Join(w.dir, fmt.Sprintf("%s-%s.log", w.prefix, date))
61+
f, err := os.OpenFile(name, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0o644)
62+
if err != nil {
63+
return fmt.Errorf("open log file: %w", err)
64+
}
65+
66+
w.current = f
67+
w.curDate = date
68+
return nil
69+
}

‎server/internal/services/tavily_proxy.go‎

Lines changed: 76 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -89,6 +89,14 @@ func (p *TavilyProxy) Do(ctx context.Context, req ProxyRequest) (ProxyResponse,
8989
const maxLogBytes = 32 * 1024
9090

9191
proxyReqID := uuid.NewString()
92+
startTime := time.Now()
93+
94+
p.logger.Info("proxy request started",
95+
"request_id", proxyReqID,
96+
"method", req.Method,
97+
"path", req.Path,
98+
"client_ip", req.ClientIP,
99+
)
92100

93101
loggingEnabled := p.logs != nil && p.isRequestLoggingEnabled(ctx)
94102
captureBodies := strings.EqualFold(req.Method, http.MethodPost) && req.Path == "/search"
@@ -148,6 +156,10 @@ func (p *TavilyProxy) Do(ctx context.Context, req ProxyRequest) (ProxyResponse,
148156
}
149157

150158
if len(candidates) == 0 {
159+
p.logger.Warn("no available keys",
160+
"request_id", proxyReqID,
161+
"path", req.Path,
162+
)
151163
if captureBodies {
152164
createdAt := time.Now()
153165
if loggingEnabled {
@@ -178,15 +190,32 @@ func (p *TavilyProxy) Do(ctx context.Context, req ProxyRequest) (ProxyResponse,
178190
resp, status, latencyMs, tavilyReqID, err := p.tryKey(ctx, key.ID, key.Key, req, proxyReqID)
179191

180192
if err != nil {
193+
p.logger.Warn("upstream request failed",
194+
"request_id", proxyReqID,
195+
"key_id", key.ID,
196+
"key_alias", key.Alias,
197+
"err", err,
198+
)
181199
lastErr = err
182200
continue
183201
}
184202

185203
switch status {
186204
case http.StatusUnauthorized:
205+
p.logger.Warn("key marked invalid",
206+
"request_id", proxyReqID,
207+
"key_id", key.ID,
208+
"key_alias", key.Alias,
209+
)
187210
_ = p.keys.MarkInvalid(ctx, key.ID)
188211
continue
189212
case http.StatusTooManyRequests, 432, 433:
213+
p.logger.Warn("key quota exhausted",
214+
"request_id", proxyReqID,
215+
"key_id", key.ID,
216+
"key_alias", key.Alias,
217+
"status", status,
218+
)
190219
_ = p.keys.MarkExhausted(ctx, key.ID)
191220
continue
192221
}
@@ -241,10 +270,21 @@ func (p *TavilyProxy) Do(ctx context.Context, req ProxyRequest) (ProxyResponse,
241270

242271
resp.ProxyRequestID = proxyReqID
243272
resp.TavilyRequestID = tavilyReqID
273+
p.logger.Info("proxy request completed",
274+
"request_id", proxyReqID,
275+
"key_id", key.ID,
276+
"status", status,
277+
"latency_ms", time.Since(startTime).Milliseconds(),
278+
)
244279
return resp, nil
245280
}
246281

247282
if captureBodies && lastErr != nil {
283+
p.logger.Error("all keys exhausted",
284+
"request_id", proxyReqID,
285+
"path", req.Path,
286+
"last_err", lastErr,
287+
)
248288
createdAt := time.Now()
249289
if loggingEnabled {
250290
_ = p.logs.Create(ctx, &models.RequestLog{
@@ -265,6 +305,11 @@ func (p *TavilyProxy) Do(ctx context.Context, req ProxyRequest) (ProxyResponse,
265305
if p.stats != nil {
266306
_ = p.stats.RecordRequest(ctx, req.Path, createdAt)
267307
}
308+
} else if lastErr == nil {
309+
p.logger.Error("all keys exhausted",
310+
"request_id", proxyReqID,
311+
"path", req.Path,
312+
)
268313
}
269314

270315
return ProxyResponse{}, ErrNoAvailableKeys
@@ -278,12 +323,12 @@ func truncateForLog(data []byte, maxBytes int) (string, bool) {
278323
}
279324

280325
func (p *TavilyProxy) tryKey(ctx context.Context, keyID uint, tavilyKey string, req ProxyRequest, proxyReqID string) (ProxyResponse, int, int64, string, error) {
281-
url := p.baseURL + req.Path
326+
targetURL := p.baseURL + req.Path
282327
if req.RawQuery != "" {
283-
url += "?" + req.RawQuery
328+
targetURL += "?" + req.RawQuery
284329
}
285330

286-
upstreamReq, err := http.NewRequestWithContext(ctx, req.Method, url, bytes.NewReader(req.Body))
331+
upstreamReq, err := http.NewRequestWithContext(ctx, req.Method, targetURL, bytes.NewReader(req.Body))
287332
if err != nil {
288333
return ProxyResponse{}, 0, 0, "", err
289334
}
@@ -296,16 +341,43 @@ func (p *TavilyProxy) tryKey(ctx context.Context, keyID uint, tavilyKey string,
296341
}
297342
upstreamReq.Header.Set("X-Proxy-Request-Id", proxyReqID)
298343

344+
p.logger.Debug("sending upstream request",
345+
"request_id", proxyReqID,
346+
"method", req.Method,
347+
"url", targetURL,
348+
"key_id", keyID,
349+
)
350+
299351
start := time.Now()
300352
upstreamResp, err := p.client.Do(upstreamReq)
301353
latencyMs := time.Since(start).Milliseconds()
302354
if err != nil {
355+
p.logger.Warn("upstream call error",
356+
"request_id", proxyReqID,
357+
"url", targetURL,
358+
"key_id", keyID,
359+
"latency_ms", latencyMs,
360+
"err", err,
361+
)
303362
return ProxyResponse{}, 0, latencyMs, "", err
304363
}
305364
defer upstreamResp.Body.Close()
306365

366+
p.logger.Debug("upstream response received",
367+
"request_id", proxyReqID,
368+
"status", upstreamResp.StatusCode,
369+
"latency_ms", latencyMs,
370+
"key_id", keyID,
371+
)
372+
307373
body, err := io.ReadAll(upstreamResp.Body)
308374
if err != nil {
375+
p.logger.Warn("upstream response read error",
376+
"request_id", proxyReqID,
377+
"key_id", keyID,
378+
"status", upstreamResp.StatusCode,
379+
"err", err,
380+
)
309381
return ProxyResponse{}, upstreamResp.StatusCode, latencyMs, "", err
310382
}
311383

@@ -396,6 +468,7 @@ func (p *TavilyProxy) GetUsage(ctx context.Context, tavilyKey string) (int, *int
396468

397469
resp, err := p.client.Do(req)
398470
if err != nil {
471+
p.logger.Warn("upstream usage request failed", "err", err)
399472
return 0, nil, err
400473
}
401474
defer resp.Body.Close()

‎server/main.go‎

Lines changed: 46 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -3,53 +3,78 @@ package main
33
import (
44
"context"
55
"embed"
6+
"io"
67
"log/slog"
78
"os"
89
"os/signal"
10+
"strings"
911
"syscall"
1012
"time"
1113

1214
"tavily-proxy/server/internal/config"
1315
"tavily-proxy/server/internal/db"
1416
"tavily-proxy/server/internal/httpserver"
1517
"tavily-proxy/server/internal/jobs"
18+
"tavily-proxy/server/internal/logger"
1619
"tavily-proxy/server/internal/services"
1720
)
1821

1922
//go:embed public
2023
var embeddedPublic embed.FS
2124

2225
func main() {
23-
logger := slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{Level: slog.LevelInfo}))
2426
cfg := config.FromEnv()
2527

28+
// Parse log level
29+
var level slog.Level
30+
switch strings.ToLower(cfg.LogLevel) {
31+
case "debug":
32+
level = slog.LevelDebug
33+
case "warn":
34+
level = slog.LevelWarn
35+
case "error":
36+
level = slog.LevelError
37+
default:
38+
level = slog.LevelInfo
39+
}
40+
41+
// Build writer (stdout + optional file)
42+
var w io.Writer = os.Stdout
43+
var fileWriter *logger.DailyRotateWriter
44+
if cfg.LogDir != "" {
45+
fileWriter = logger.NewDailyRotateWriter(cfg.LogDir, "proxy")
46+
w = io.MultiWriter(os.Stdout, fileWriter)
47+
}
48+
49+
slogLogger := slog.New(slog.NewTextHandler(w, &slog.HandlerOptions{Level: level}))
50+
2651
database, err := db.Open(cfg.DatabasePath)
2752
if err != nil {
28-
logger.Error("db open failed", "err", err)
53+
slogLogger.Error("db open failed", "err", err)
2954
os.Exit(1)
3055
}
3156

32-
masterKeyService := services.NewMasterKeyService(database, logger)
57+
masterKeyService := services.NewMasterKeyService(database, slogLogger)
3358
if err := masterKeyService.LoadOrCreate(context.Background()); err != nil {
34-
logger.Error("master key init failed", "err", err)
59+
slogLogger.Error("master key init failed", "err", err)
3560
os.Exit(1)
3661
}
3762

3863
settingsService := services.NewSettingsService(database)
39-
keyService := services.NewKeyService(database, logger)
40-
logService := services.NewLogService(database, logger)
64+
keyService := services.NewKeyService(database, slogLogger)
65+
logService := services.NewLogService(database, slogLogger)
4166
statsService := services.NewStatsService(database)
4267

4368
if err := statsService.BackfillFromLogsIfEmpty(context.Background()); err != nil {
44-
logger.Error("stats backfill failed", "err", err)
69+
slogLogger.Error("stats backfill failed", "err", err)
4570
}
4671

47-
tavilyProxy := services.NewTavilyProxy(cfg.TavilyBaseURL, cfg.UpstreamTimeout, keyService, logService, statsService, logger).
72+
tavilyProxy := services.NewTavilyProxy(cfg.TavilyBaseURL, cfg.UpstreamTimeout, keyService, logService, statsService, slogLogger).
4873
WithSettings(settingsService)
49-
cacheService := services.NewCacheService(database, logger)
74+
cacheService := services.NewCacheService(database, slogLogger)
5075
tavilyProxy.WithCache(cacheService)
51-
quotaSyncService := services.NewQuotaSyncService(keyService, tavilyProxy, logger)
52-
quotaSyncJob := services.NewQuotaSyncJobService(keyService, quotaSyncService, logger)
76+
quotaSyncService := services.NewQuotaSyncService(keyService, tavilyProxy, slogLogger)
77+
quotaSyncJob := services.NewQuotaSyncJobService(keyService, quotaSyncService, slogLogger)
5378

5479
srv := httpserver.New(httpserver.Dependencies{
5580
Config: cfg,
@@ -63,26 +88,29 @@ func main() {
6388
StatsService: statsService,
6489
CacheService: cacheService,
6590
TavilyProxy: tavilyProxy,
66-
Logger: logger,
91+
Logger: slogLogger,
6792
})
6893

6994
ctx, stop := signal.NotifyContext(context.Background(), os.Interrupt, syscall.SIGTERM)
7095
defer stop()
7196

72-
jobs.StartMonthlyReset(ctx, keyService, logger)
73-
jobs.StartAutoQuotaSync(ctx, settingsService, quotaSyncService, logger)
74-
jobs.StartLogCleanup(ctx, settingsService, logService, logger)
75-
jobs.StartCacheCleanup(ctx, cacheService, logger)
97+
jobs.StartMonthlyReset(ctx, keyService, slogLogger)
98+
jobs.StartAutoQuotaSync(ctx, settingsService, quotaSyncService, slogLogger)
99+
jobs.StartLogCleanup(ctx, settingsService, logService, slogLogger)
100+
jobs.StartCacheCleanup(ctx, cacheService, slogLogger)
76101

77102
go func() {
78-
logger.Info("server listening", "addr", cfg.ListenAddr)
103+
slogLogger.Info("server listening", "addr", cfg.ListenAddr)
79104
if err := srv.ListenAndServe(); err != nil {
80-
logger.Error("http server stopped", "err", err)
105+
slogLogger.Error("http server stopped", "err", err)
81106
}
82107
}()
83108

84109
<-ctx.Done()
85110
shutdownCtx, cancel := context.WithTimeout(context.Background(), 10*time.Second)
86111
defer cancel()
87112
_ = srv.Shutdown(shutdownCtx)
113+
if fileWriter != nil {
114+
_ = fileWriter.Close()
115+
}
88116
}

0 commit comments

Comments
 (0)