diff --git a/baidu/search.go b/baidu/search.go index cb26993..54e0f2d 100644 --- a/baidu/search.go +++ b/baidu/search.go @@ -73,11 +73,16 @@ func (baid *Baidu) isTimeout(page *rod.Page) bool { // Search executes a Baidu web search and returns normalized search results. // It may return core.ErrCaptcha or core.ErrSearchTimeout. func (baid *Baidu) Search(ctx context.Context, query core.Query) (results []core.SearchResult, err error) { - ctx = core.EnsureContext(ctx) + ctx = core.WithEngine(core.EnsureContext(ctx), baid.Name()) + ctx = core.WithQueryHash(ctx, core.QueryHashFromQuery(query)) + scoped := *baid + scoped.logger = baid.logger.WithRequest(ctx) + baid = &scoped + baid.logger.Debug("Starting search, query: %+v", query) defer func() { if recovered := recover(); recovered != nil { - err = core.RecoverEnginePanic(baid.Name(), recovered, baid.logger) + err = core.RecoverEnginePanicWithContext(ctx, baid.Name(), recovered, baid.logger) results = nil } }() @@ -171,7 +176,12 @@ func (baid *Baidu) Search(ctx context.Context, query core.Query) (results []core // SearchImage executes a Baidu image search and returns normalized image // results. It may return core.ErrCaptcha or core.ErrSearchTimeout. func (baid *Baidu) SearchImage(ctx context.Context, query core.Query) ([]core.SearchResult, error) { - ctx = core.EnsureContext(ctx) + ctx = core.WithEngine(core.EnsureContext(ctx), baid.Name()) + ctx = core.WithQueryHash(ctx, core.QueryHashFromQuery(query)) + scoped := *baid + scoped.logger = baid.logger.WithRequest(ctx) + baid = &scoped + baid.logger.Debug("Starting image search, query: %+v", query) searchResults := []core.SearchResult{} diff --git a/baidu/search_raw.go b/baidu/search_raw.go index c8e174b..7aa58a5 100644 --- a/baidu/search_raw.go +++ b/baidu/search_raw.go @@ -2,6 +2,7 @@ package baidu import ( "context" + "fmt" "net/http" "strings" @@ -86,15 +87,19 @@ func baiduResultParser(response *http.Response) ([]core.SearchResult, error) { } } - logrus.Tracef("Baidu search document size: %d", len(doc.Text())) + logrus.WithField("document_size", len(doc.Text())).Trace( + fmt.Sprintf("Baidu search document size: %d", len(doc.Text())), + ) return results, err } func Search(ctx context.Context, query core.Query) (results []core.SearchResult, err error) { ctx = core.EnsureContext(ctx) + ctx = core.WithEngine(ctx, "baidu") + ctx = core.WithQueryHash(ctx, core.QueryHashFromQuery(query)) defer func() { if recovered := recover(); recovered != nil { - err = core.RecoverEnginePanic("baidu", recovered, nil) + err = core.RecoverEnginePanicWithContext(ctx, "baidu", recovered, nil) results = nil } }() @@ -103,14 +108,16 @@ func Search(ctx context.Context, query core.Query) (results []core.SearchResult, if err != nil { return nil, err } - logrus.Debugf("Baidu URL built: %s", googleURL) + core.WithRequest(ctx).WithField("url", googleURL).Debug(fmt.Sprintf("Baidu URL built: %s", googleURL)) res, err := baiduRequest(ctx, googleURL, query) if err != nil { return nil, err } defer core.DrainAndCloseResponse(res) - logrus.Debugf("Baidu Raw response: code=%d", res.StatusCode) + core.WithRequest(ctx).WithField("status_code", res.StatusCode).Debug( + fmt.Sprintf("Baidu Raw response: code=%d", res.StatusCode), + ) parsedResults, err := baiduResultParser(res) if err != nil { @@ -121,7 +128,9 @@ func Search(ctx context.Context, query core.Query) (results []core.SearchResult, parsedResults[i].Rank = query.Start + i + 1 } } - logrus.Debugf("Baidu Raw results : %v", parsedResults) + core.WithRequest(ctx).WithField("results_count", len(parsedResults)).Debug( + fmt.Sprintf("Baidu Raw results : %v", parsedResults), + ) return core.DeduplicateResults(parsedResults), nil } diff --git a/bing/search.go b/bing/search.go index b7657ff..f0acdb4 100644 --- a/bing/search.go +++ b/bing/search.go @@ -97,11 +97,16 @@ func (bing *Bing) acceptCookies(ctx context.Context, page *rod.Page) error { // Search executes a Bing web search and returns normalized search results. // It may return core.ErrCaptcha or core.ErrSearchTimeout. func (bing *Bing) Search(ctx context.Context, query core.Query) (results []core.SearchResult, err error) { - ctx = core.EnsureContext(ctx) + ctx = core.WithEngine(core.EnsureContext(ctx), bing.Name()) + ctx = core.WithQueryHash(ctx, core.QueryHashFromQuery(query)) + scoped := *bing + scoped.logger = bing.logger.WithRequest(ctx) + bing = &scoped + bing.logger.Debug("Starting search, query: %+v", query) defer func() { if recovered := recover(); recovered != nil { - err = core.RecoverEnginePanic(bing.Name(), recovered, bing.logger) + err = core.RecoverEnginePanicWithContext(ctx, bing.Name(), recovered, bing.logger) results = nil } }() @@ -268,7 +273,12 @@ type BingImageData struct { // SearchImage executes a Bing image search and returns normalized image // results. It may return core.ErrCaptcha or core.ErrSearchTimeout. func (bing *Bing) SearchImage(ctx context.Context, query core.Query) ([]core.SearchResult, error) { - ctx = core.EnsureContext(ctx) + ctx = core.WithEngine(core.EnsureContext(ctx), bing.Name()) + ctx = core.WithQueryHash(ctx, core.QueryHashFromQuery(query)) + scoped := *bing + scoped.logger = bing.logger.WithRequest(ctx) + bing = &scoped + bing.logger.Debug("Starting image search, query: %+v", query) searchResults := []core.SearchResult{} diff --git a/bing/url.go b/bing/url.go index 67d1d9d..e224d84 100644 --- a/bing/url.go +++ b/bing/url.go @@ -33,7 +33,7 @@ func BuildURL(q core.Query) (string, error) { text += " filetype:" + q.Filetype } - logrus.Tracef("Query text: %s", text) + logrus.WithField("query_hash", core.QueryHash(text)).Trace(fmt.Sprintf("Query text: %s", text)) params.Add("q", text) } diff --git a/cmd/root.go b/cmd/root.go index 1253784..411e219 100644 --- a/cmd/root.go +++ b/cmd/root.go @@ -57,6 +57,7 @@ type AppConfig struct { IsLeaveHead bool `mapstructure:"leave_head"` IsLeakless bool `mapstructure:"leakless"` IsStealth bool `mapstructure:"stealth"` + LogFormat string `mapstructure:"log_format"` } type EngineConfig struct { @@ -117,6 +118,7 @@ var flagToConfigKey = map[string]string{ "cb_failures": "circuit_breaker.failures", "cb_recovery": "circuit_breaker.recovery_seconds", "cb_successes": "circuit_breaker.successes", + "log_format": "app.log_format", } var RootCmd = &cobra.Command{ @@ -131,8 +133,14 @@ var RootCmd = &cobra.Command{ return err } - core.InitLogger(config.Server.IsVerbose, config.Server.IsDebug) - logrus.Debugf("Final config: %+v", config) + logFormat, err := core.NormalizeLogFormat(config.App.LogFormat) + if err != nil { + return err + } + config.App.LogFormat = logFormat + + core.InitLogger(config.Server.IsVerbose, config.Server.IsDebug, config.App.LogFormat) + logrus.WithField("config", fmt.Sprintf("%+v", config)).Debug("Final config") return nil }, } @@ -146,13 +154,13 @@ func bindFlags(cmd *cobra.Command, vpr *viper.Viper) { } if err := vpr.BindPFlag(configName, flg); err != nil { - logrus.Errorf("Unable to bind flag %s: %v", flg.Name, err) + logrus.WithError(err).Error(fmt.Sprintf("Unable to bind flag %s: %v", flg.Name, err)) } if flg.Changed { val, err := parseFlagValue(flg) if err != nil { - logrus.Errorf("Unable to parse flag %s: %v", flg.Name, err) + logrus.WithError(err).Error(fmt.Sprintf("Unable to parse flag %s: %v", flg.Name, err)) return } vpr.Set(configName, val) @@ -206,7 +214,7 @@ func initializeConfig(cmd *cobra.Command) error { envKey := envPrefix + "_" + strings.ToUpper(strings.ReplaceAll(key, ".", "_")) err := v.BindEnv(key, envKey) if err != nil { - logrus.Errorf("Unable to bind ENV valye: %v", err) + logrus.WithError(err).Error(fmt.Sprintf("Unable to bind ENV valye: %v", err)) } } @@ -302,6 +310,7 @@ func setConfigDefaults(v *viper.Viper) { v.SetDefault("server.verbose", false) v.SetDefault("server.raw_requests", false) v.SetDefault("server.insecure", false) + v.SetDefault("app.log_format", "") v.SetDefault("app.timeout", 30) v.SetDefault("app.browser_path", "") @@ -325,7 +334,7 @@ func setConfigDefaults(v *viper.Viper) { v.SetDefault("cors.enabled", true) v.SetDefault("cors.allow_origins", "*") v.SetDefault("cors.allow_methods", "GET, POST, OPTIONS") - v.SetDefault("cors.allow_headers", "Origin, Content-Type, Accept, Authorization, X-Use-Proxy") + v.SetDefault("cors.allow_headers", "Origin, Content-Type, Accept, Authorization, X-Use-Proxy, X-Request-ID, X-Tenant") v.SetDefault("cors.max_age", 86400) v.SetDefault("captcha.solver_enabled", false) } @@ -353,4 +362,5 @@ func init() { RootCmd.PersistentFlags().IntVar(&config.CircuitBreaker.Failures, "cb_failures", 5, "Consecutive failures before circuit breaker opens") RootCmd.PersistentFlags().IntVar(&config.CircuitBreaker.RecoverySeconds, "cb_recovery", 60, "Seconds before retrying an engine with open circuit") RootCmd.PersistentFlags().IntVar(&config.CircuitBreaker.Successes, "cb_successes", 2, "Consecutive successful half-open checks needed to close circuit") + RootCmd.PersistentFlags().StringVar(&config.App.LogFormat, "log_format", "", "Log format: json or text (default: json in production, text in debug)") } diff --git a/cmd/search.go b/cmd/search.go index 2527c66..1523b3a 100644 --- a/cmd/search.go +++ b/cmd/search.go @@ -37,7 +37,7 @@ func search(cmd *cobra.Command, args []string) { captchaSolverEnabled, captchaSolverAPIKey, err := resolveCaptchaSolverConfig() if err != nil { - logrus.Errorf("Error validating captcha solver config: %v", err) + logrus.WithError(err).Error(fmt.Sprintf("Error validating captcha solver config: %v", err)) os.Exit(1) } @@ -48,7 +48,7 @@ func search(cmd *cobra.Command, args []string) { proxyCfg, err := buildNormalizedProxyConfig(proxyRuntime) if err != nil { - logrus.Errorf("Error validating proxy config: %v", err) + logrus.WithError(err).Error(fmt.Sprintf("Error validating proxy config: %v", err)) return } @@ -56,7 +56,7 @@ func search(cmd *cobra.Command, args []string) { selectedProxy, err := selectCLIProxy(proxyCfg, policy) if err != nil { - logrus.Errorf("Error selecting proxy for %s: %v", engineType, err) + logrus.WithError(err).Error(fmt.Sprintf("Error selecting proxy for %s: %v", engineType, err)) return } @@ -64,23 +64,29 @@ func search(cmd *cobra.Command, args []string) { query.ProxyURL = selectedProxy } - logrus.Infof("Starting SERP search request using %s engine for query: %s", engineType, query.Text) + logrus.WithFields(logrus.Fields{ + "engine": engineType, + "query_hash": core.QueryHashFromQuery(query), + }).Info(fmt.Sprintf("Starting SERP search request using %s engine for query: %s", engineType, query.Text)) var results []core.SearchResult if config.Server.IsRawRequests { - logrus.Infof("Using raw requests mode for %s search", engineType) + logrus.WithField("engine", engineType).Info(fmt.Sprintf("Using raw requests mode for %s search", engineType)) results, err = searchRaw(engineType, query) } else { - logrus.Infof("Using browser mode for %s search", engineType) + logrus.WithField("engine", engineType).Info(fmt.Sprintf("Using browser mode for %s search", engineType)) results, err = searchBrowser(engineType, query, selectedProxy, captchaSolverEnabled, captchaSolverAPIKey) } if err != nil { - logrus.Errorf("Error during %s search: %s", engineType, err) + logrus.WithError(err).WithField("engine", engineType).Error(fmt.Sprintf("Error during %s search: %s", engineType, err)) return } - logrus.Infof("Successfully completed SERP search using %s engine, returned %d results", engineType, len(results)) + logrus.WithFields(logrus.Fields{ + "engine": engineType, + "results_count": len(results), + }).Info(fmt.Sprintf("Successfully completed SERP search using %s engine, returned %d results", engineType, len(results))) b, err := json.MarshalIndent(results, "", " ") if err != nil { diff --git a/cmd/serve.go b/cmd/serve.go index c249533..067e893 100644 --- a/cmd/serve.go +++ b/cmd/serve.go @@ -84,7 +84,7 @@ func serve(cmd *cobra.Command, args []string) { proxyCfg, err := buildNormalizedProxyConfig(proxyRuntime) if err != nil { - logrus.Errorf("invalid proxy configuration: %v", err) + logrus.WithError(err).Error(fmt.Sprintf("invalid proxy configuration: %v", err)) return } diff --git a/config.yaml b/config.yaml index 48da0f4..100f88d 100644 --- a/config.yaml +++ b/config.yaml @@ -7,6 +7,8 @@ server: insecure: true # Allow insecure TLS connections app: + # json|text. Empty means auto: text in debug mode, json otherwise. + log_format: "text" timeout: 15 # Browser/search timeout in seconds browser_path: "" # Custom browser binary path (chrome/chromium/edge..) head: false # Show browser UI (headful mode) diff --git a/core/browser.go b/core/browser.go index 4c84f4d..cbec094 100644 --- a/core/browser.go +++ b/core/browser.go @@ -71,7 +71,7 @@ type Browser struct { // Browser wrapper configured with proxy and captcha solver settings. func NewBrowser(opts BrowserOpts) (*Browser, error) { opts.Check() - logrus.Debugf("Browser options: %+v", opts) + logrus.WithField("browser_options", fmt.Sprintf("%+v", opts)).Debug("Browser options") path, err := resolveBrowserBinaryPath(opts.BrowserPath, launcher.LookPath) if err != nil { @@ -82,7 +82,7 @@ func NewBrowser(opts BrowserOpts) (*Browser, error) { l := launcher.New().Leakless(opts.IsLeakless).Headless(opts.IsHeadless).Set("disable-blink-features", "AutomationControlled"). Delete("enable-automation") if path != "" { - logrus.Debugf("Using browser binary: %s", path) + logrus.WithField("browser_path", path).Debug("Using browser binary") l = l.Bin(path) } @@ -102,13 +102,16 @@ func NewBrowser(opts BrowserOpts) (*Browser, error) { // Chrome's proxy-server flag must not contain credentials. // Auth (if needed) is handled separately via DevTools auth callbacks. proxyStr := proxyURLForBrowserLaunch(proxyUrl) - logrus.Debugf("Setting up proxy: %s", MaskProxyURL(proxyStr)) + logrus.WithField("proxy", MaskProxyURL(proxyStr)).Debug("Setting up proxy") l = l.Proxy(proxyStr) // Check if proxy has auth credentials if proxyUrl.User != nil { username := proxyUrl.User.Username() - logrus.Debugf("Proxy credentials configured for %s proxy: %s:****", proxyUrl.Scheme, username) + logrus.WithFields(logrus.Fields{ + "proxy_scheme": proxyUrl.Scheme, + "proxy_username": username, + }).Debugf("Proxy credentials configured for %s proxy: %s:****", proxyUrl.Scheme, username) } } @@ -187,7 +190,7 @@ func (b *Browser) Navigate(ctx context.Context, URL string) (*rod.Page, error) { return nil, err } - logrus.Debug("Navigate to: ", URL) + WithRequest(ctx).WithField("url", URL).Debug("Navigate to") browser := rod.New().ControlURL(b.browserAddr).Timeout(b.Timeout) if err := browser.Connect(); err != nil { @@ -214,7 +217,7 @@ func (b *Browser) Navigate(ctx context.Context, URL string) (*rod.Page, error) { // Launch auth handler before any navigation occurs go func() { if err := b.browser.HandleAuth(username, password)(); err != nil { - logrus.Debugf("Proxy auth handler stopped: %v", err) + WithRequest(ctx).WithError(err).Debug("Proxy auth handler stopped") } }() } else if proxyUrl.User != nil && (proxyUrl.Scheme == "socks5" || proxyUrl.Scheme == "socks5h") { @@ -252,7 +255,7 @@ func (b *Browser) Navigate(ctx context.Context, URL string) (*rod.Page, error) { // when the caller context is canceled or navigation fails. closeOnErr := func() { if cerr := page.Close(); cerr != nil { - logrus.Debugf("Close page after navigate error failed: %v", cerr) + WithRequest(ctx).WithError(cerr).Debug("Close page after navigate error failed") } } @@ -291,9 +294,11 @@ func (b *Browser) Navigate(ctx context.Context, URL string) (*rod.Page, error) { if errors.Is(werr, context.DeadlineExceeded) { // Some engines keep loading background resources while the DOM is already usable. // Treat load timeout as non-fatal and let engine-specific selector timeouts decide. - logrus.Debugf("WaitLoad timed out after %s; continuing with partial page state", b.Timeout) + WithRequest(ctx).WithField("timeout", b.Timeout.String()).Debug( + fmt.Sprintf("WaitLoad timed out after %s; continuing with partial page state", b.Timeout), + ) } else { - logrus.Debugf("WaitLoad returned early: %v", werr) + WithRequest(ctx).WithError(werr).Debug("WaitLoad returned early") } } @@ -331,11 +336,15 @@ func ClosePageWithTimeout(ctx context.Context, page *rod.Page, timeout time.Dura // RecoverEnginePanic converts recovered panics to a typed engine error and // logs stack trace with engine context. func RecoverEnginePanic(engine string, recovered interface{}, logger *EngineLogger) error { + return RecoverEnginePanicWithContext(nil, engine, recovered, logger) +} + +func RecoverEnginePanicWithContext(ctx context.Context, engine string, recovered interface{}, logger *EngineLogger) error { stack := debug.Stack() if logger != nil { logger.Error("Recovered panic in %s Search: panic=%v\n%s", engine, recovered, string(stack)) } else { - logrus.Errorf("Recovered panic in %s Search: panic=%v\n%s", engine, recovered, string(stack)) + WithRequestEngine(ctx, engine).Errorf("Recovered panic in %s Search: panic=%v\n%s", engine, recovered, string(stack)) } return fmt.Errorf("%w: %s", ErrEngineInternal, engine) } diff --git a/core/circuit_breaker.go b/core/circuit_breaker.go index 3303bff..3be0930 100644 --- a/core/circuit_breaker.go +++ b/core/circuit_breaker.go @@ -1,11 +1,10 @@ package core import ( + "context" "fmt" "sync" "time" - - "github.com/sirupsen/logrus" ) type CircuitState int @@ -64,7 +63,7 @@ func NewCircuitBreaker(name string, cfg CircuitBreakerConfig) *CircuitBreaker { } } -func (cb *CircuitBreaker) AllowRequest() bool { +func (cb *CircuitBreaker) AllowRequest(ctx context.Context) bool { cb.mu.Lock() defer cb.mu.Unlock() @@ -74,7 +73,7 @@ func (cb *CircuitBreaker) AllowRequest() bool { case CircuitOpen: if time.Since(cb.lastFailureTime) >= cb.config.RecoveryTimeout { cb.setState(CircuitHalfOpen) - logrus.Infof("[CircuitBreaker][%s] Recovery timeout elapsed, moving to half-open", cb.name) + WithRequestEngine(ctx, cb.name).Info("Recovery timeout elapsed, moving to half-open") return true } return false @@ -85,7 +84,7 @@ func (cb *CircuitBreaker) AllowRequest() bool { } } -func (cb *CircuitBreaker) RecordSuccess() { +func (cb *CircuitBreaker) RecordSuccess(ctx context.Context) { cb.mu.Lock() defer cb.mu.Unlock() @@ -96,14 +95,14 @@ func (cb *CircuitBreaker) RecordSuccess() { cb.setState(CircuitClosed) cb.failureCount = 0 cb.successCount = 0 - logrus.Infof("[CircuitBreaker][%s] Recovered, circuit closed", cb.name) + WithRequestEngine(ctx, cb.name).Info("Circuit recovered, closed") } case CircuitClosed: cb.failureCount = 0 } } -func (cb *CircuitBreaker) RecordFailure() { +func (cb *CircuitBreaker) RecordFailure(ctx context.Context) { cb.mu.Lock() defer cb.mu.Unlock() @@ -114,13 +113,15 @@ func (cb *CircuitBreaker) RecordFailure() { cb.failureCount++ if cb.failureCount >= cb.config.FailureThreshold { cb.setState(CircuitOpen) - logrus.Warnf("[CircuitBreaker][%s] Circuit OPENED after %d consecutive failures (will retry in %s)", - cb.name, cb.failureCount, cb.config.RecoveryTimeout) + WithRequestEngine(ctx, cb.name). + WithField("failure_count", cb.failureCount). + WithField("recovery_timeout", cb.config.RecoveryTimeout.String()). + Warn("Circuit opened after consecutive failures") } case CircuitHalfOpen: cb.setState(CircuitOpen) cb.successCount = 0 - logrus.Warnf("[CircuitBreaker][%s] Failed during half-open, circuit re-opened", cb.name) + WithRequestEngine(ctx, cb.name).Warn("Failed during half-open, circuit re-opened") } } diff --git a/core/circuit_breaker_test.go b/core/circuit_breaker_test.go index 91b09bb..e676f1b 100644 --- a/core/circuit_breaker_test.go +++ b/core/circuit_breaker_test.go @@ -1,6 +1,7 @@ package core import ( + "context" "testing" "time" ) @@ -20,17 +21,17 @@ func TestCircuitBreaker_OpensAfterThreshold(t *testing.T) { } cb := newTestCircuitBreaker(t, cfg) - cb.RecordFailure() - cb.RecordFailure() + cb.RecordFailure(context.Background()) + cb.RecordFailure(context.Background()) if cb.State() != CircuitClosed { t.Fatalf("expected closed after 2 failures, got: %s", cb.State()) } - cb.RecordFailure() + cb.RecordFailure(context.Background()) if cb.State() != CircuitOpen { t.Fatalf("expected open after %d failures, got: %s", cfg.FailureThreshold, cb.State()) } - if cb.AllowRequest() { + if cb.AllowRequest(context.Background()) { t.Error("expected request blocked in open state") } } @@ -45,14 +46,14 @@ func TestCircuitBreaker_RecoveryToHalfOpen(t *testing.T) { } cb := newTestCircuitBreaker(t, cfg) - cb.RecordFailure() - cb.RecordFailure() + cb.RecordFailure(context.Background()) + cb.RecordFailure(context.Background()) if cb.State() != CircuitOpen { t.Fatal("expected open") } time.Sleep(60 * time.Millisecond) - if !cb.AllowRequest() { + if !cb.AllowRequest(context.Background()) { t.Error("should allow request after recovery timeout") } if cb.State() != CircuitHalfOpen { @@ -70,25 +71,25 @@ func TestCircuitBreaker_HalfOpenSuccessClosesCircuit(t *testing.T) { } cb := newTestCircuitBreaker(t, cfg) - cb.RecordFailure() + cb.RecordFailure(context.Background()) if cb.State() != CircuitOpen { t.Fatalf("expected open, got: %s", cb.State()) } time.Sleep(30 * time.Millisecond) - if !cb.AllowRequest() { + if !cb.AllowRequest(context.Background()) { t.Fatal("expected request to pass in recovery window") } if cb.State() != CircuitHalfOpen { t.Fatalf("expected half-open after recovery timeout, got: %s", cb.State()) } - cb.RecordSuccess() + cb.RecordSuccess(context.Background()) if cb.State() != CircuitHalfOpen { t.Fatalf("expected to stay half-open until success threshold reached, got: %s", cb.State()) } - cb.RecordSuccess() + cb.RecordSuccess(context.Background()) if cb.State() != CircuitClosed { t.Fatalf("expected closed after success threshold reached, got: %s", cb.State()) } @@ -104,16 +105,16 @@ func TestCircuitBreaker_HalfOpenFailureReopens(t *testing.T) { } cb := newTestCircuitBreaker(t, cfg) - cb.RecordFailure() + cb.RecordFailure(context.Background()) time.Sleep(30 * time.Millisecond) - if !cb.AllowRequest() { + if !cb.AllowRequest(context.Background()) { t.Fatal("expected probe request in half-open") } if cb.State() != CircuitHalfOpen { t.Fatalf("expected half-open, got: %s", cb.State()) } - cb.RecordFailure() + cb.RecordFailure(context.Background()) if cb.State() != CircuitOpen { t.Fatalf("expected open after failed half-open probe, got: %s", cb.State()) } @@ -123,7 +124,7 @@ func TestCircuitBreaker_HalfOpenFailureReopens(t *testing.T) { // only when breaker is open. func TestCircuitBreaker_Stats(t *testing.T) { cb := NewCircuitBreaker("test-engine", DefaultCircuitBreakerConfig()) - cb.RecordFailure() + cb.RecordFailure(context.Background()) stats := cb.Stats() if stats["engine"] != "test-engine" { @@ -141,7 +142,7 @@ func TestCircuitBreaker_Stats(t *testing.T) { openCfg := CircuitBreakerConfig{FailureThreshold: 1, RecoveryTimeout: time.Second, SuccessThreshold: 1} openCB := NewCircuitBreaker("open-engine", openCfg) - openCB.RecordFailure() + openCB.RecordFailure(context.Background()) openStats := openCB.Stats() retryIn, ok := openStats["retry_in"].(int64) if !ok { diff --git a/core/logger.go b/core/logger.go index 49b4ad1..9dc44cc 100644 --- a/core/logger.go +++ b/core/logger.go @@ -1,132 +1,274 @@ package core import ( + "bytes" + "context" + "crypto/md5" + "encoding/hex" "fmt" "io" "os" + "sort" "strings" + "time" "github.com/sirupsen/logrus" ) -type customFormatter struct { - logrus.TextFormatter +type loggerContextKey string + +const ( + requestIDContextKey loggerContextKey = "request_id" + tenantContextKey loggerContextKey = "tenant" + engineContextKey loggerContextKey = "engine" + queryHashContextKey loggerContextKey = "query_hash" + + LogFormatJSON = "json" + LogFormatText = "text" +) + +func NormalizeLogFormat(raw string) (string, error) { + format := strings.ToLower(strings.TrimSpace(raw)) + if format == "" { + return LogFormatText, nil + } + switch format { + case LogFormatJSON, LogFormatText: + return format, nil + default: + return "", fmt.Errorf("invalid logging.format %q: expected json or text", raw) + } } -func (f *customFormatter) Format(entry *logrus.Entry) ([]byte, error) { - message := entry.Message - - // Check if engine name is provided as a field - engineName := "" - if engine, exists := entry.Data["engine"]; exists { - if engineStr, ok := engine.(string); ok { - engineName = engineStr - } +func WithRequestID(ctx context.Context, requestID string) context.Context { + requestID = strings.TrimSpace(requestID) + if requestID == "" { + return EnsureContext(ctx) } - - // Format: [timestamp][level][engine] message - if engineName != "" { - return []byte(fmt.Sprintf("[%s][%s][%s] %s\n", - entry.Time.Format(f.TimestampFormat), - strings.ToUpper(entry.Level.String()), - engineName, - message)), nil - } - - // Format: [timestamp][level] message (no engine) - return []byte(fmt.Sprintf("[%s][%s] %s\n", - entry.Time.Format(f.TimestampFormat), - strings.ToUpper(entry.Level.String()), - message)), nil + return context.WithValue(EnsureContext(ctx), requestIDContextKey, requestID) } -// EngineLogger provides simplified logging for search engines +func WithTenant(ctx context.Context, tenant string) context.Context { + tenant = strings.TrimSpace(tenant) + if tenant == "" { + return EnsureContext(ctx) + } + return context.WithValue(EnsureContext(ctx), tenantContextKey, tenant) +} + +func WithEngine(ctx context.Context, engine string) context.Context { + engine = strings.TrimSpace(engine) + if engine == "" { + return EnsureContext(ctx) + } + return context.WithValue(EnsureContext(ctx), engineContextKey, engine) +} + +func WithQueryHash(ctx context.Context, queryHash string) context.Context { + queryHash = strings.TrimSpace(queryHash) + if queryHash == "" { + return EnsureContext(ctx) + } + return context.WithValue(EnsureContext(ctx), queryHashContextKey, queryHash) +} + +func RequestIDFromContext(ctx context.Context) string { + value, _ := EnsureContext(ctx).Value(requestIDContextKey).(string) + return strings.TrimSpace(value) +} + +func WithRequest(ctx context.Context) *logrus.Entry { + ctx = EnsureContext(ctx) + fields := logrus.Fields{} + + if requestID, ok := ctx.Value(requestIDContextKey).(string); ok && strings.TrimSpace(requestID) != "" { + fields["request_id"] = strings.TrimSpace(requestID) + } + if tenant, ok := ctx.Value(tenantContextKey).(string); ok && strings.TrimSpace(tenant) != "" { + fields["tenant"] = strings.TrimSpace(tenant) + } + if engine, ok := ctx.Value(engineContextKey).(string); ok && strings.TrimSpace(engine) != "" { + fields["engine"] = strings.TrimSpace(engine) + } + if queryHash, ok := ctx.Value(queryHashContextKey).(string); ok && strings.TrimSpace(queryHash) != "" { + fields["query_hash"] = strings.TrimSpace(queryHash) + } + + return logrus.WithFields(fields) +} + +func WithRequestEngine(ctx context.Context, engine string) *logrus.Entry { + return WithRequest(WithEngine(ctx, engine)) +} + +func QueryHash(raw string) string { + normalized := strings.TrimSpace(strings.ToLower(raw)) + if normalized == "" { + return "" + } + hash := md5.Sum([]byte(normalized)) + return hex.EncodeToString(hash[:]) +} + +func QueryHashFromQuery(q Query) string { + raw := strings.Join([]string{ + q.Text, + q.Site, + q.Filetype, + q.LangCode, + q.DateInterval, + }, "|") + return QueryHash(raw) +} + +func formatMessage(message string, args ...any) string { + if len(args) == 0 { + return message + } + return fmt.Sprintf(message, args...) +} + +// EngineLogger provides structured logging for search engines with a fixed engine field. type EngineLogger struct { engine string - logger *logrus.Entry + entry *logrus.Entry } -// NewEngineLogger creates a new logger for a specific search engine func NewEngineLogger(engine string) *EngineLogger { - return &EngineLogger{ - engine: engine, - logger: logrus.WithField("engine", engine), + engine = strings.ToLower(strings.TrimSpace(engine)) + return &EngineLogger{engine: engine, entry: logrus.WithField("engine", engine)} +} + +func (el *EngineLogger) WithRequest(ctx context.Context) *EngineLogger { + return &EngineLogger{engine: el.engine, entry: WithRequestEngine(ctx, el.engine)} +} + +// Fields returns a new EngineLogger with additional structured fields merged in. +func (el *EngineLogger) Fields(fields logrus.Fields) *EngineLogger { + return &EngineLogger{engine: el.engine, entry: el.entry.WithFields(fields)} +} + +func (el *EngineLogger) Debug(message string, args ...any) { + el.entry.Debug(formatMessage(message, args...)) +} + +func (el *EngineLogger) Info(message string, args ...any) { + el.entry.Info(formatMessage(message, args...)) +} + +func (el *EngineLogger) Warn(message string, args ...any) { + el.entry.Warn(formatMessage(message, args...)) +} + +func (el *EngineLogger) Error(message string, args ...any) { + el.entry.Error(formatMessage(message, args...)) +} + +func (el *EngineLogger) Fatal(message string, args ...any) { + el.entry.Fatal(formatMessage(message, args...)) +} + +func (el *EngineLogger) Panic(message string, args ...any) { + el.entry.Panic(formatMessage(message, args...)) +} + +// bracketFormatter emits bracket-delimited fields: +// +// [time][level][engine=..][request_id=..][query_hash=..][extra fields sorted][msg] +// +// request_id is truncated to last 8 chars; query_hash to first 12. +type bracketFormatter struct { + TimestampFormat string +} + +func (f *bracketFormatter) Format(entry *logrus.Entry) ([]byte, error) { + ts := entry.Time.Format(f.TimestampFormat) + + var buf bytes.Buffer + fmt.Fprintf(&buf, "[%s][%s]", ts, entry.Level.String()) + + // Context identity fields in fixed order, then remaining fields sorted, then msg last. + priority := []string{"engine", "tenant", "request_id", "query_hash"} + written := make(map[string]bool, len(entry.Data)) + + for _, key := range priority { + val, ok := entry.Data[key] + if !ok { + continue + } + s := fmt.Sprintf("%v", val) + switch key { + case "request_id": + if len(s) > 8 { + s = s[len(s)-8:] + } + case "query_hash": + if len(s) > 12 { + s = s[:12] + } + } + fmt.Fprintf(&buf, "[%s=%s]", key, quoteIfNeeded(s)) + written[key] = true } -} -// Debug logs a debug message -func (el *EngineLogger) Debug(message string, args ...interface{}) { - el.logger.Debugf(message, args...) -} - -// Info logs an info message -func (el *EngineLogger) Info(message string, args ...interface{}) { - el.logger.Infof(message, args...) -} - -// Warn logs a warning message -func (el *EngineLogger) Warn(message string, args ...interface{}) { - el.logger.Warnf(message, args...) -} - -// Error logs an error message -func (el *EngineLogger) Error(message string, args ...interface{}) { - el.logger.Errorf(message, args...) -} - -// Fatal logs a fatal message -func (el *EngineLogger) Fatal(message string, args ...interface{}) { - el.logger.Fatalf(message, args...) -} - -// Panic logs a panic message -func (el *EngineLogger) Panic(message string, args ...interface{}) { - el.logger.Panicf(message, args...) -} - -// LogWithEngine logs a message with engine information (deprecated - use EngineLogger instead) -func LogWithEngine(level logrus.Level, engine, message string, args ...interface{}) { - entry := logrus.WithField("engine", engine) - switch level { - case logrus.DebugLevel: - entry.Debugf(message, args...) - case logrus.InfoLevel: - entry.Infof(message, args...) - case logrus.WarnLevel: - entry.Warnf(message, args...) - case logrus.ErrorLevel: - entry.Errorf(message, args...) - case logrus.FatalLevel: - entry.Fatalf(message, args...) - case logrus.PanicLevel: - entry.Panicf(message, args...) + rest := make([]string, 0, len(entry.Data)) + for k := range entry.Data { + if !written[k] { + rest = append(rest, k) + } } + sort.Strings(rest) + for _, k := range rest { + fmt.Fprintf(&buf, "[%s=%s]", k, quoteIfNeeded(fmt.Sprintf("%v", entry.Data[k]))) + } + + // Message last so context fields are scannable without scrolling past a long msg. + if entry.Message != "" { + fmt.Fprintf(&buf, "[%s]", quoteIfNeeded(entry.Message)) + } + + buf.WriteByte('\n') + return buf.Bytes(), nil } -func InitLogger(isVerbose, isDebug bool) { - logrus.SetFormatter(&customFormatter{logrus.TextFormatter{ - FullTimestamp: true, - TimestampFormat: "2006-01-02 15:04:05", - ForceColors: true, - DisableLevelTruncation: true, - }}) +// quoteIfNeeded wraps s in double-quotes if it contains spaces. +func quoteIfNeeded(s string) string { + if strings.ContainsAny(s, " \t") { + return `"` + strings.ReplaceAll(s, `"`, `\"`) + `"` + } + return s +} - if isVerbose { - logrus.SetLevel(logrus.DebugLevel) +func InitLogger(isVerbose, isDebug bool, format string) { + switch format { + case LogFormatText: + logrus.SetFormatter(&bracketFormatter{TimestampFormat: "2006-01-02 15:04:05"}) + case LogFormatJSON: + logrus.SetFormatter(&logrus.JSONFormatter{ + TimestampFormat: time.RFC3339Nano, + }) } if isDebug { logrus.SetOutput(io.MultiWriter(os.Stdout)) - logrus.SetLevel(logrus.TraceLevel) logrus.SetReportCaller(true) } else { f, err := os.OpenFile("./logs.txt", os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644) if err != nil { - fmt.Println("Failed to create logsfile: ./logs.txt") - panic(err) + fmt.Fprintf(os.Stderr, "Failed to open logs file ./logs.txt: %v\n", err) + logrus.SetOutput(io.MultiWriter(os.Stdout)) + } else { + logrus.SetOutput(io.MultiWriter(f, os.Stdout)) } - - logrus.SetOutput(io.MultiWriter(f, os.Stdout)) - logrus.SetLevel(logrus.DebugLevel) + logrus.SetReportCaller(false) } + + level := logrus.InfoLevel + if isVerbose { + level = logrus.DebugLevel + } + if isDebug { + level = logrus.TraceLevel + } + logrus.SetLevel(level) } diff --git a/core/middleware.go b/core/middleware.go index a087e36..37c8d04 100644 --- a/core/middleware.go +++ b/core/middleware.go @@ -6,6 +6,7 @@ import ( "time" "github.com/gofiber/fiber/v2" + "github.com/google/uuid" "github.com/sirupsen/logrus" ) @@ -26,11 +27,33 @@ func DefaultCORSConfig() CORSConfig { return CORSConfig{ AllowOrigins: "*", AllowMethods: "GET, POST, OPTIONS", - AllowHeaders: "Origin, Content-Type, Accept, Authorization, X-Use-Proxy", + AllowHeaders: "Origin, Content-Type, Accept, Authorization, X-Use-Proxy, X-Request-ID, X-Tenant", MaxAge: 86400, } } +func RequestContextMiddleware() fiber.Handler { + return func(c *fiber.Ctx) error { + requestID := strings.TrimSpace(c.Get("X-Request-ID")) + if requestID == "" { + id, err := uuid.NewV7() + if err != nil { + requestID = uuid.NewString() + } else { + requestID = id.String() + } + } + + requestCtx := WithRequestID(c.UserContext(), requestID) + requestCtx = WithTenant(requestCtx, strings.TrimSpace(c.Get("X-Tenant"))) + requestCtx = WithQueryHash(requestCtx, QueryHash(c.Query("text"))) + c.SetUserContext(requestCtx) + + c.Set("X-Request-ID", requestID) + return c.Next() + } +} + func CORSMiddleware(cfg CORSConfig) fiber.Handler { cfg = normalizeCORSConfig(cfg) @@ -83,23 +106,23 @@ func RequestLoggerMiddleware() fiber.Handler { } logFields := logrus.Fields{ - "method": c.Method(), - "path": c.Path(), - "status": status, - "latency": latency.String(), - "ip": c.IP(), + "method": c.Method(), + "path": c.Path(), + "status": status, + "ip": c.IP(), } + logFields["latency_ms"] = latency.Milliseconds() if query := c.Query("text"); query != "" { - logFields["query"] = query + logFields["query_hash"] = QueryHash(query) } - entry := logrus.WithFields(logFields) + entry := WithRequest(c.UserContext()).WithFields(logFields) if status >= 500 { - entry.Errorf("%s - request failed", c.Path()) + entry.Error("request failed") } else if status >= 400 { - entry.Warnf("%s - request error", c.Path()) + entry.Warn("request error") } else { - entry.Infof("%s - request completed", c.Path()) + entry.Info("request completed") } return err diff --git a/core/middleware_test.go b/core/middleware_test.go index 1bf10f1..356cf80 100644 --- a/core/middleware_test.go +++ b/core/middleware_test.go @@ -1,6 +1,7 @@ package core import ( + "io" "net/http" "net/http/httptest" "strings" @@ -107,3 +108,57 @@ func TestDefaultCORSConfig_IncludesProxyOverrideHeader(t *testing.T) { t.Fatalf("expected allow_headers to include X-Use-Proxy, got %q", got) } } + +func TestRequestContextMiddleware_EchoesProvidedRequestID(t *testing.T) { + app := fiber.New() + app.Use(RequestContextMiddleware()) + app.Get("/id", func(c *fiber.Ctx) error { + return c.SendString(RequestIDFromContext(c.UserContext())) + }) + + req := httptest.NewRequest(http.MethodGet, "/id", nil) + req.Header.Set("X-Request-ID", "foo") + resp, err := app.Test(req, -1) + if err != nil { + t.Fatalf("request failed: %v", err) + } + + if got := resp.Header.Get("X-Request-ID"); got != "foo" { + t.Fatalf("expected response X-Request-ID=foo, got %q", got) + } + if got := readBody(t, resp); got != "foo" { + t.Fatalf("expected context request id to be echoed, got %q", got) + } +} + +func TestRequestContextMiddleware_GeneratesRequestID(t *testing.T) { + app := fiber.New() + app.Use(RequestContextMiddleware()) + app.Get("/id", func(c *fiber.Ctx) error { + return c.SendString(RequestIDFromContext(c.UserContext())) + }) + + req := httptest.NewRequest(http.MethodGet, "/id", nil) + resp, err := app.Test(req, -1) + if err != nil { + t.Fatalf("request failed: %v", err) + } + + requestID := resp.Header.Get("X-Request-ID") + if requestID == "" { + t.Fatal("expected generated X-Request-ID") + } + if got := readBody(t, resp); got != requestID { + t.Fatalf("expected request id in context to match header: body=%q header=%q", got, requestID) + } +} + +func readBody(t *testing.T, resp *http.Response) string { + t.Helper() + defer resp.Body.Close() + body, err := io.ReadAll(resp.Body) + if err != nil { + t.Fatalf("read body failed: %v", err) + } + return string(body) +} diff --git a/core/proxy.go b/core/proxy.go index 5a9edbd..03074b0 100644 --- a/core/proxy.go +++ b/core/proxy.go @@ -1,6 +1,7 @@ package core import ( + "context" "errors" "fmt" "net/url" @@ -351,6 +352,10 @@ func NewProxyRegistry(entries []ProxyEntryConfig, failureThreshold int) (*ProxyR } func (r *ProxyRegistry) NextByTag(tag string) string { + return r.NextByTagWithContext(nil, tag) +} + +func (r *ProxyRegistry) NextByTagWithContext(ctx context.Context, tag string) string { tag = normalizeTag(tag) if tag == "" { return "" @@ -365,7 +370,9 @@ func (r *ProxyRegistry) NextByTag(tag string) string { } if r.allDisabledLocked(urls) { - logrus.Warnf("Proxy tag pool exhausted for %q, re-enabling tagged proxies", tag) + WithRequest(ctx).WithField("proxy_tag", tag).Warn( + fmt.Sprintf("Proxy tag pool exhausted for %q, re-enabling tagged proxies", tag), + ) for _, proxyURL := range urls { state := r.states[proxyURL] state.disabled = false @@ -383,14 +390,17 @@ func (r *ProxyRegistry) NextByTag(tag string) string { } r.nextByTag[tag] = (idx + 1) % len(urls) - logrus.Debugf("Selected proxy for tag=%s: %s", tag, MaskProxyURL(proxyURL)) + WithRequest(ctx).WithFields(logrus.Fields{ + "proxy_tag": tag, + "proxy": MaskProxyURL(proxyURL), + }).Debugf("Selected proxy for tag=%s: %s", tag, MaskProxyURL(proxyURL)) return proxyURL } return "" } -func (r *ProxyRegistry) ReportFailure(proxyURL string) { +func (r *ProxyRegistry) ReportFailure(ctx context.Context, proxyURL string) { proxyURL, err := NormalizeProxyURL(proxyURL) if err != nil || proxyURL == "" { return @@ -407,11 +417,14 @@ func (r *ProxyRegistry) ReportFailure(proxyURL string) { state.failures++ if state.failures >= r.failureThreshold { state.disabled = true - logrus.Warnf("Disabled proxy after %d failures: %s", state.failures, MaskProxyURL(proxyURL)) + WithRequest(ctx).WithFields(logrus.Fields{ + "failure_count": state.failures, + "proxy": MaskProxyURL(proxyURL), + }).Warnf("Disabled proxy after %d failures: %s", state.failures, MaskProxyURL(proxyURL)) } } -func (r *ProxyRegistry) ReportSuccess(proxyURL string) { +func (r *ProxyRegistry) ReportSuccess(_ context.Context, proxyURL string) { proxyURL, err := NormalizeProxyURL(proxyURL) if err != nil || proxyURL == "" { return diff --git a/core/proxy_test.go b/core/proxy_test.go index f504af2..fbf9f13 100644 --- a/core/proxy_test.go +++ b/core/proxy_test.go @@ -1,6 +1,7 @@ package core import ( + "context" "fmt" "io" "log" @@ -141,20 +142,20 @@ func TestProxyRegistryRoundRobinAndFailureRecovery(t *testing.T) { t.Fatalf("expected second proxy2, got %s", got) } - registry.ReportFailure("http://proxy1:8080") - registry.ReportFailure("http://proxy1:8080") + registry.ReportFailure(context.Background(), "http://proxy1:8080") + registry.ReportFailure(context.Background(), "http://proxy1:8080") if got := registry.NextByTag("default"); got != "http://proxy2:8080" { t.Fatalf("expected proxy2 while proxy1 disabled, got %s", got) } - registry.ReportFailure("http://proxy2:8080") - registry.ReportFailure("http://proxy2:8080") + registry.ReportFailure(context.Background(), "http://proxy2:8080") + registry.ReportFailure(context.Background(), "http://proxy2:8080") if got := registry.NextByTag("default"); got != "http://proxy1:8080" { t.Fatalf("expected tag pool reset to proxy1 after exhaustion, got %s", got) } - registry.ReportFailure("http://proxy1:8080") - registry.ReportSuccess("http://proxy1:8080") + registry.ReportFailure(context.Background(), "http://proxy1:8080") + registry.ReportSuccess(context.Background(), "http://proxy1:8080") stats := registry.BuildStats() if stats.UnhealthyCount != 0 { t.Fatalf("expected no unhealthy proxies after success recovery, got %d", stats.UnhealthyCount) diff --git a/core/resilient.go b/core/resilient.go index 0ac3757..0d890a4 100644 --- a/core/resilient.go +++ b/core/resilient.go @@ -47,7 +47,7 @@ func DefaultResilientConfig() ResilientConfig { func NewResilientSearcher(engines []SearchEngine, cfg ResilientConfig) *ResilientSearcher { proxyCfg, err := NormalizeProxyConfig(cfg.Proxy) if err != nil { - logrus.Errorf("Invalid proxy config, using defaults: %v", err) + logrus.WithError(err).Error("Invalid proxy config, using defaults") proxyCfg = DefaultProxyConfig() proxyCfg, _ = NormalizeProxyConfig(proxyCfg) } @@ -110,18 +110,18 @@ func (rs *ResilientSearcher) searchWithFallback(ctx context.Context, primaryEngi return nil, primaryEngine.Name(), proxyMeta, ctx.Err() } if errors.Is(err, ErrProxyUnavailable) { - logrus.Warnf("[Resilient] Primary engine %s proxy policy failed closed: %s", primaryEngine.Name(), err) + WithRequestEngine(ctx, primaryEngine.Name()).WithError(err).Warn("Proxy policy failed closed") return nil, primaryEngine.Name(), proxyMeta, err } - action := "failed" successMessage := "Fallback to %s succeeded with %d results" if isImage { - action = "image search failed" successMessage = "Image fallback to %s succeeded with %d results" } - logrus.Warnf("[Resilient] Primary engine %s %s: %s. Trying fallback engines...", primaryEngine.Name(), action, err) + WithRequestEngine(ctx, primaryEngine.Name()). + WithError(err). + Warn("Primary engine failed, trying fallbacks") for _, fallbackEngine := range rs.engines { if ctx.Err() != nil { return nil, primaryEngine.Name(), proxyMeta, ctx.Err() @@ -132,10 +132,12 @@ func (rs *ResilientSearcher) searchWithFallback(ctx context.Context, primaryEngi results, fallbackMeta, fallbackErr := rs.searchWithProtection(ctx, fallbackEngine, q, isImage) if fallbackErr == nil { - logrus.Infof("[Resilient] "+successMessage, fallbackEngine.Name(), len(results)) + WithRequestEngine(ctx, fallbackEngine.Name()). + WithField("results_count", len(results)). + Infof(successMessage, fallbackEngine.Name(), len(results)) return results, fallbackEngine.Name(), fallbackMeta, nil } - logrus.Warnf("[Resilient] Fallback engine %s also failed: %s", fallbackEngine.Name(), fallbackErr) + WithRequestEngine(ctx, fallbackEngine.Name()).WithError(fallbackErr).Debug("Fallback engine also failed") } return nil, primaryEngine.Name(), proxyMeta, ErrAllEnginesFailed @@ -148,7 +150,8 @@ func (rs *ResilientSearcher) searchWithProtection(ctx context.Context, engine Se return nil, ProxyExecutionMeta{}, ctx.Err() } cb := rs.cbManager.Get(engine.Name()) - if !cb.AllowRequest() { + engineCtx := WithEngine(ctx, engine.Name()) + if !cb.AllowRequest(engineCtx) { return nil, ProxyExecutionMeta{}, ErrCircuitOpen } @@ -173,7 +176,7 @@ func (rs *ResilientSearcher) searchWithProtection(ctx context.Context, engine Se attemptQuery.ProxyURL = "" attemptMeta.Used = "direct" case ProxyModeTagPool: - proxyURL = rs.selectProxyForQuery(policy, q) + proxyURL = rs.selectProxyForQuery(policy, q, engineCtx) if proxyURL == "" { return nil, fmt.Errorf("%w: no healthy proxy available for tag %q", ErrProxyUnavailable, policy.Tag) } @@ -193,7 +196,7 @@ func (rs *ResilientSearcher) searchWithProtection(ctx context.Context, engine Se } if reportToRegistry { - rs.reportProxyAttempt(proxyURL, err) + rs.reportProxyAttempt(engineCtx, proxyURL, err) } return results, err @@ -201,12 +204,12 @@ func (rs *ResilientSearcher) searchWithProtection(ctx context.Context, engine Se if result.Err != nil { if !errors.Is(result.Err, ErrProxyUnavailable) { - cb.RecordFailure() + cb.RecordFailure(engineCtx) } return nil, attemptMeta, result.Err } - cb.RecordSuccess() + cb.RecordSuccess(engineCtx) return result.Results, attemptMeta, nil } @@ -225,8 +228,9 @@ func (rs *ResilientSearcher) SearchAllParallel(ctx context.Context, q Query, eng if !engine.IsInitialized() { continue } - if !rs.cbManager.Get(engine.Name()).AllowRequest() { - logrus.Infof("[Resilient] Skipping %s in megasearch (circuit open)", engine.Name()) + engineCtx := WithEngine(ctx, engine.Name()) + if !rs.cbManager.Get(engine.Name()).AllowRequest(engineCtx) { + WithRequest(engineCtx).Debug("Skipping engine in megasearch: circuit open") continue } @@ -268,8 +272,9 @@ func (rs *ResilientSearcher) SearchAllImageParallel(ctx context.Context, q Query if !engine.IsInitialized() { continue } - if !rs.cbManager.Get(engine.Name()).AllowRequest() { - logrus.Infof("[Resilient] Skipping %s in megaimage (circuit open)", engine.Name()) + engineCtx := WithEngine(ctx, engine.Name()) + if !rs.cbManager.Get(engine.Name()).AllowRequest(engineCtx) { + WithRequest(engineCtx).Debug("Skipping engine in megaimage: circuit open") continue } @@ -424,27 +429,27 @@ func (rs *ResilientSearcher) effectivePolicyForQuery(engineName string, q Query) } } -func (rs *ResilientSearcher) selectProxyForTag(tag string) string { +func (rs *ResilientSearcher) selectProxyForTag(ctx context.Context, tag string) string { if rs.proxyRegistry == nil { return "" } - return rs.proxyRegistry.NextByTag(tag) + return rs.proxyRegistry.NextByTagWithContext(ctx, tag) } -func (rs *ResilientSearcher) reportProxyAttempt(proxyURL string, err error) { +func (rs *ResilientSearcher) reportProxyAttempt(ctx context.Context, proxyURL string, err error) { if rs.proxyRegistry == nil || proxyURL == "" { return } if err != nil { - rs.proxyRegistry.ReportFailure(proxyURL) + rs.proxyRegistry.ReportFailure(ctx, proxyURL) return } - rs.proxyRegistry.ReportSuccess(proxyURL) + rs.proxyRegistry.ReportSuccess(ctx, proxyURL) } -func (rs *ResilientSearcher) selectProxyForQuery(policy ProxyPolicy, q Query) string { +func (rs *ResilientSearcher) selectProxyForQuery(policy ProxyPolicy, q Query, ctx context.Context) string { if policy.Mode != ProxyModeTagPool { return "" } @@ -453,7 +458,7 @@ func (rs *ResilientSearcher) selectProxyForQuery(policy ProxyPolicy, q Query) st return global } } - return rs.selectProxyForTag(policy.Tag) + return rs.selectProxyForTag(ctx, policy.Tag) } var ErrAllEnginesFailed = fmt.Errorf("all search engines failed") diff --git a/core/retry.go b/core/retry.go index 942836d..0839338 100644 --- a/core/retry.go +++ b/core/retry.go @@ -38,7 +38,8 @@ type RetryResult struct { // RetryableSearch executes searchFn with exponential backoff retries. // CAPTCHA, parser, engine-internal, and proxy-unavailable errors are not retried. func RetryableSearch(ctx context.Context, cfg RetryConfig, engineName string, searchFn func(context.Context) ([]SearchResult, error)) RetryResult { - ctx = EnsureContext(ctx) + ctx = WithEngine(EnsureContext(ctx), engineName) + logger := WithRequest(ctx) if cfg.BackoffFactor <= 0 { cfg.BackoffFactor = 2.0 } @@ -55,7 +56,10 @@ func RetryableSearch(ctx context.Context, cfg RetryConfig, engineName string, se if attempt > 0 { backoff := calculateBackoff(cfg, attempt) - logrus.Warnf("[%s] Retry attempt %d/%d after %s", engineName, attempt, cfg.MaxRetries, backoff) + logger.WithFields(logrus.Fields{ + "attempt": attempt, + "backoff": backoff.String(), + }).Warnf("Retry %d/%d after %s", attempt, cfg.MaxRetries, backoff) if err := SleepContext(ctx, backoff); err != nil { return RetryResult{ Err: err, @@ -67,9 +71,6 @@ func RetryableSearch(ctx context.Context, cfg RetryConfig, engineName string, se results, err := searchFn(ctx) if err == nil { - if attempt > 0 { - logrus.Infof("[%s] Succeeded on retry attempt %d", engineName, attempt) - } return RetryResult{ Results: results, Attempts: attempt + 1, @@ -79,7 +80,7 @@ func RetryableSearch(ctx context.Context, cfg RetryConfig, engineName string, se lastErr = err if errors.Is(err, ErrCaptcha) { - logrus.Warnf("[%s] CAPTCHA detected, skipping retries", engineName) + logger.Warn("CAPTCHA detected, skipping retries") return RetryResult{ Err: err, Attempts: attempt + 1, @@ -87,7 +88,7 @@ func RetryableSearch(ctx context.Context, cfg RetryConfig, engineName string, se } } if errors.Is(err, ErrProxyUnavailable) { - logrus.Warnf("[%s] Proxy unavailable, skipping retries", engineName) + logger.Warn("Proxy unavailable, skipping retries") return RetryResult{ Err: err, Attempts: attempt + 1, @@ -95,7 +96,7 @@ func RetryableSearch(ctx context.Context, cfg RetryConfig, engineName string, se } } if errors.Is(err, ErrParser) { - logrus.Warnf("[%s] Parser failure, skipping retries", engineName) + logger.Warn("Parser failure, skipping retries") return RetryResult{ Err: err, Attempts: attempt + 1, @@ -103,7 +104,7 @@ func RetryableSearch(ctx context.Context, cfg RetryConfig, engineName string, se } } if errors.Is(err, ErrEngineInternal) { - logrus.Warnf("[%s] Engine panic recovered, skipping retries", engineName) + logger.Warn("Engine panic recovered, skipping retries") return RetryResult{ Err: err, Attempts: attempt + 1, @@ -111,7 +112,7 @@ func RetryableSearch(ctx context.Context, cfg RetryConfig, engineName string, se } } if IsContextDone(err) { - logrus.Warnf("[%s] Context canceled/deadline exceeded, skipping retries", engineName) + logger.Warn("Context canceled/deadline exceeded, skipping retries") return RetryResult{ Err: err, Attempts: attempt + 1, @@ -119,7 +120,7 @@ func RetryableSearch(ctx context.Context, cfg RetryConfig, engineName string, se } } - logrus.Warnf("[%s] Attempt %d failed: %s", engineName, attempt+1, err) + logger.WithField("attempt", attempt+1).Debugf("Attempt %d failed: %s", attempt+1, err) } return RetryResult{ diff --git a/core/server.go b/core/server.go index b9b6848..364e0de 100644 --- a/core/server.go +++ b/core/server.go @@ -104,9 +104,13 @@ func NewServerWithOptions(host string, port int, opts ServerOptions, searchEngin } if opts.CacheTTL > 0 && opts.CacheMaxSize > 0 { serv.cache = NewResponseCache(opts.CacheTTL, opts.CacheMaxSize) - logrus.Infof("Response cache enabled: TTL=%s, MaxSize=%d", opts.CacheTTL, opts.CacheMaxSize) + logrus.WithFields(logrus.Fields{ + "cache_ttl": opts.CacheTTL.String(), + "cache_max_size": opts.CacheMaxSize, + }).Info("Response cache enabled") } + app.Use(RequestContextMiddleware()) if opts.EnableCORS { app.Use(CORSMiddleware(opts.CORS)) } @@ -146,17 +150,25 @@ func NewServerWithOptions(host string, port int, opts ServerOptions, searchEngin } func (s *Server) handleDedicatedEndpoint(c *fiber.Ctx, engine SearchEngine, isImage bool) error { + requestCtx := WithEngine(c.UserContext(), engine.Name()) + c.SetUserContext(requestCtx) + q := Query{} if err := q.InitFromContext(c); err != nil { - logrus.Errorf("Error while setting %s query: %s", engine.Name(), err) + WithRequest(c.UserContext()).WithError(err).Error("Invalid query parameters") return err } + requestCtx = WithQueryHash(c.UserContext(), QueryHashFromQuery(q)) + c.SetUserContext(requestCtx) + action := "search" if isImage { action = "image" } - logrus.Infof("Starting SERP %s request using %s engine for query: %s", action, engine.Name(), q.Text) + WithRequest(requestCtx). + WithField("action", action). + Debugf("Starting %s request for query: %s", action, q.Text) if hit, err := s.tryServeCacheHit( c, @@ -177,15 +189,15 @@ func (s *Server) handleDedicatedEndpoint(c *fiber.Ctx, engine SearchEngine, isIm if isImage { if s.opts.AllowEndpointFallback { - res, usedEngine, proxyMeta, searchErr = s.resilient.SearchImageWithFallback(c.UserContext(), engine, q) + res, usedEngine, proxyMeta, searchErr = s.resilient.SearchImageWithFallback(requestCtx, engine, q) } else { - res, usedEngine, proxyMeta, searchErr = s.resilient.SearchImagePrimary(c.UserContext(), engine, q) + res, usedEngine, proxyMeta, searchErr = s.resilient.SearchImagePrimary(requestCtx, engine, q) } } else { if s.opts.AllowEndpointFallback { - res, usedEngine, proxyMeta, searchErr = s.resilient.SearchWithFallback(c.UserContext(), engine, q) + res, usedEngine, proxyMeta, searchErr = s.resilient.SearchWithFallback(requestCtx, engine, q) } else { - res, usedEngine, proxyMeta, searchErr = s.resilient.SearchPrimary(c.UserContext(), engine, q) + res, usedEngine, proxyMeta, searchErr = s.resilient.SearchPrimary(requestCtx, engine, q) } } s.applyProxyHeaders(c, proxyMeta) @@ -204,7 +216,10 @@ func (s *Server) handleDedicatedEndpoint(c *fiber.Ctx, engine SearchEngine, isIm case errors.Is(searchErr, ErrProxyUnavailable): errToReturn = fmt.Errorf("%s", searchErr) } - logrus.Errorf("Error during resilient %s %s: %s", engine.Name(), action, searchErr) + WithRequest(requestCtx). + WithFields(logrus.Fields{"action": action}). + WithError(searchErr). + Error("Search failed") return fiber.NewError(fiber.StatusServiceUnavailable, errToReturn.Error()) } @@ -231,7 +246,13 @@ func (s *Server) handleDedicatedEndpoint(c *fiber.Ctx, engine SearchEngine, isIm c.Set("X-Fallback-Engine", usedEngine) } - logrus.Infof("Successfully completed SERP %s using %s, returned %d results", action, usedEngine, len(res)) + completionCtx := requestCtx + if usedEngine != "" { + completionCtx = WithEngine(completionCtx, usedEngine) + } + WithRequest(completionCtx). + WithFields(logrus.Fields{"action": action, "results_count": len(res)}). + Info("Search completed") return c.JSON(res) } @@ -355,11 +376,16 @@ func (s *Server) handleMegaImage(c *fiber.Ctx) error { } func (s *Server) handleMegaEndpoint(c *fiber.Ctx, action string, run func(context.Context, Query, []SearchEngine) []MegaSearchResult) error { + requestCtx := WithEngine(c.UserContext(), "mega") + c.SetUserContext(requestCtx) + q := Query{} if err := q.InitFromContext(c); err != nil { - logrus.Errorf("Error while setting mega %s query: %s", action, err) + WithRequest(c.UserContext()).WithError(err).Error("Invalid query parameters") return err } + requestCtx = WithQueryHash(c.UserContext(), QueryHashFromQuery(q)) + c.SetUserContext(requestCtx) enginesToUse := s.resolveEngines(c.Query("engines", "")) if len(enginesToUse) == 0 { @@ -372,7 +398,10 @@ func (s *Server) handleMegaEndpoint(c *fiber.Ctx, action string, run func(contex } engineNamesJoined := strings.Join(engineNames, ",") s.applyProxyHeaders(c, s.resilient.ResolveMegaProxyMeta(q, enginesToUse)) - logrus.Infof("Starting SERP mega %s request using engines: %s for query: %s", action, engineNamesJoined, q.Text) + WithRequest(requestCtx).WithFields(logrus.Fields{ + "action": action, + "engines": engineNamesJoined, + }).Debugf("Starting mega %s request for query: %s", action, q.Text) cacheHitCandidates := []cacheHitCandidate{ { @@ -391,14 +420,18 @@ func (s *Server) handleMegaEndpoint(c *fiber.Ctx, action string, run func(contex return err } - results := run(c.UserContext(), q, enginesToUse) + results := run(requestCtx, q, enginesToUse) dedupedResults := s.deduplicateMegaResults(results) if s.cache != nil { c.Set("X-Cache", s.cacheMegaResults(action, enginesToUse, q, dedupedResults)) } - logrus.Infof("Successfully completed SERP mega %s using %d engines, returned %d deduplicated results", action, len(enginesToUse), len(dedupedResults)) + WithRequest(requestCtx).WithFields(logrus.Fields{ + "action": action, + "engines_count": len(enginesToUse), + "results_count": len(dedupedResults), + }).Info("Mega search completed") return c.JSON(dedupedResults) } @@ -491,7 +524,7 @@ func (s *Server) tryServeCacheHit(c *fiber.Ctx, candidates ...cacheHitCandidate) } c.Set("Content-Type", "application/json") c.Set("X-Cache", "HIT") - logrus.Info(candidate.logMessage) + WithRequest(c.UserContext()).Debug(candidate.logMessage) return true, c.Send(cached) } return false, nil diff --git a/core/server_test.go b/core/server_test.go index 1952269..dd446f6 100644 --- a/core/server_test.go +++ b/core/server_test.go @@ -12,6 +12,7 @@ import ( "testing" "time" + "github.com/google/uuid" "golang.org/x/time/rate" ) @@ -74,6 +75,36 @@ func requestWithHeader(t *testing.T, s *Server, path string, header string, valu return resp } +func TestRequestIDHeaderIsEchoedWhenProvided(t *testing.T) { + engine := &engineMock{name: "google", initialized: true} + srv := NewServerWithOptions("127.0.0.1", 7110, DefaultServerOptions(), engine) + + resp := requestWithHeader(t, srv, "/google/search?text=golang", "X-Request-ID", "foo") + if resp.StatusCode != http.StatusOK { + t.Fatalf("expected request to succeed, got %d", resp.StatusCode) + } + if got := resp.Header.Get("X-Request-ID"); got != "foo" { + t.Fatalf("expected X-Request-ID=foo, got %q", got) + } +} + +func TestRequestIDHeaderIsGeneratedWhenMissing(t *testing.T) { + engine := &engineMock{name: "google", initialized: true} + srv := NewServerWithOptions("127.0.0.1", 7111, DefaultServerOptions(), engine) + + resp := request(t, srv, "/google/search?text=golang") + if resp.StatusCode != http.StatusOK { + t.Fatalf("expected request to succeed, got %d", resp.StatusCode) + } + requestID := resp.Header.Get("X-Request-ID") + if requestID == "" { + t.Fatal("expected non-empty X-Request-ID header") + } + if _, err := uuid.Parse(requestID); err != nil { + t.Fatalf("expected X-Request-ID to be a UUID, got %q (%v)", requestID, err) + } +} + func TestOpenAPISpecEndpoint(t *testing.T) { engine := &engineMock{name: "google", initialized: true} srv := NewServerWithOptions("127.0.0.1", 7107, DefaultServerOptions(), engine) diff --git a/duckduckgo/search.go b/duckduckgo/search.go index 985ba64..fe06ae9 100644 --- a/duckduckgo/search.go +++ b/duckduckgo/search.go @@ -174,11 +174,16 @@ func (ddg *DuckDuckGo) parseResults(results rod.Elements, pageNum int) []core.Se // Search executes a DuckDuckGo web search and returns normalized search // results. It may return core.ErrCaptcha or core.ErrSearchTimeout. func (ddg *DuckDuckGo) Search(ctx context.Context, query core.Query) (results []core.SearchResult, err error) { - ctx = core.EnsureContext(ctx) + ctx = core.WithEngine(core.EnsureContext(ctx), ddg.Name()) + ctx = core.WithQueryHash(ctx, core.QueryHashFromQuery(query)) + scoped := *ddg + scoped.logger = ddg.logger.WithRequest(ctx) + ddg = &scoped + ddg.logger.Debug("Starting search, query: %+v", query) defer func() { if recovered := recover(); recovered != nil { - err = core.RecoverEnginePanic(ddg.Name(), recovered, ddg.logger) + err = core.RecoverEnginePanicWithContext(ctx, ddg.Name(), recovered, ddg.logger) results = nil } }() @@ -292,7 +297,12 @@ func (ddg *DuckDuckGo) Search(ctx context.Context, query core.Query) (results [] // SearchImage executes a DuckDuckGo image search and returns normalized image // results. It may return core.ErrCaptcha or core.ErrSearchTimeout. func (ddg *DuckDuckGo) SearchImage(ctx context.Context, query core.Query) ([]core.SearchResult, error) { - ctx = core.EnsureContext(ctx) + ctx = core.WithEngine(core.EnsureContext(ctx), ddg.Name()) + ctx = core.WithQueryHash(ctx, core.QueryHashFromQuery(query)) + scoped := *ddg + scoped.logger = ddg.logger.WithRequest(ctx) + ddg = &scoped + ddg.logger.Debug("Starting image search, query: %+v", query) searchResults := []core.SearchResult{} diff --git a/google/search.go b/google/search.go index b83aaee..a6c1767 100644 --- a/google/search.go +++ b/google/search.go @@ -173,11 +173,16 @@ func (gogl *Google) acceptCookies(page *rod.Page) { // Search executes a Google web search and returns normalized search results. // It may return core.ErrCaptcha or core.ErrSearchTimeout. func (gogl *Google) Search(ctx context.Context, query core.Query) (results []core.SearchResult, err error) { - ctx = core.EnsureContext(ctx) + ctx = core.WithEngine(core.EnsureContext(ctx), gogl.Name()) + ctx = core.WithQueryHash(ctx, core.QueryHashFromQuery(query)) + scoped := *gogl + scoped.logger = gogl.logger.WithRequest(ctx) + gogl = &scoped + gogl.logger.Debug("Starting search, query: %+v", query) defer func() { if recovered := recover(); recovered != nil { - err = core.RecoverEnginePanic(gogl.Name(), recovered, gogl.logger) + err = core.RecoverEnginePanicWithContext(ctx, gogl.Name(), recovered, gogl.logger) results = nil } }() @@ -421,7 +426,12 @@ func (gogl *Google) Search(ctx context.Context, query core.Query) (results []cor // SearchImage executes a Google image search and returns normalized image // results. It may return core.ErrCaptcha or core.ErrSearchTimeout. func (gogl *Google) SearchImage(ctx context.Context, query core.Query) ([]core.SearchResult, error) { - ctx = core.EnsureContext(ctx) + ctx = core.WithEngine(core.EnsureContext(ctx), gogl.Name()) + ctx = core.WithQueryHash(ctx, core.QueryHashFromQuery(query)) + scoped := *gogl + scoped.logger = gogl.logger.WithRequest(ctx) + gogl = &scoped + gogl.logger.Debug("Starting image search, query: %+v", query) searchResultsMap := map[string]core.SearchResult{} diff --git a/google/search_raw.go b/google/search_raw.go index aa99111..e114579 100644 --- a/google/search_raw.go +++ b/google/search_raw.go @@ -2,6 +2,7 @@ package google import ( "context" + "fmt" "net/http" "strings" @@ -97,15 +98,19 @@ func googleResultParser(response *http.Response) ([]core.SearchResult, error) { } } - logrus.Tracef("Google search document size: %d", len(doc.Text())) + logrus.WithField("document_size", len(doc.Text())).Trace( + fmt.Sprintf("Google search document size: %d", len(doc.Text())), + ) return core.DeduplicateResults(results), err } func Search(ctx context.Context, query core.Query) (results []core.SearchResult, err error) { ctx = core.EnsureContext(ctx) + ctx = core.WithEngine(ctx, "google") + ctx = core.WithQueryHash(ctx, core.QueryHashFromQuery(query)) defer func() { if recovered := recover(); recovered != nil { - err = core.RecoverEnginePanic("google", recovered, nil) + err = core.RecoverEnginePanicWithContext(ctx, "google", recovered, nil) results = nil } }() @@ -114,14 +119,16 @@ func Search(ctx context.Context, query core.Query) (results []core.SearchResult, if err != nil { return nil, err } - logrus.Debugf("Google URL built: %s", googleURL) + core.WithRequest(ctx).WithField("url", googleURL).Debug(fmt.Sprintf("Google URL built: %s", googleURL)) res, err := googleRequest(ctx, googleURL, query) if err != nil { return nil, err } defer core.DrainAndCloseResponse(res) - logrus.Debugf("Google Raw response: code=%d", res.StatusCode) + core.WithRequest(ctx).WithField("status_code", res.StatusCode).Debug( + fmt.Sprintf("Google Raw response: code=%d", res.StatusCode), + ) parsedResults, err := googleResultParser(res) if err != nil { @@ -133,7 +140,9 @@ func Search(ctx context.Context, query core.Query) (results []core.SearchResult, parsedResults[i].Rank = query.Start + i + 1 } } - logrus.Debugf("Google Raw results : %v", parsedResults) + core.WithRequest(ctx).WithField("results_count", len(parsedResults)).Debug( + fmt.Sprintf("Google Raw results : %v", parsedResults), + ) return parsedResults, nil } diff --git a/google/url.go b/google/url.go index fb7a617..a4c2a39 100644 --- a/google/url.go +++ b/google/url.go @@ -237,7 +237,7 @@ func BuildURL(q core.Query) (string, error) { text += " filetype:" + q.Filetype } - logrus.Tracef("Query text: %s", text) + logrus.WithField("query_hash", core.QueryHash(text)).Trace(fmt.Sprintf("Query text: %s", text)) params.Add("q", text) params.Add("oq", text) } diff --git a/yandex/search.go b/yandex/search.go index 75756a7..2881490 100644 --- a/yandex/search.go +++ b/yandex/search.go @@ -127,11 +127,16 @@ func (yand *Yandex) parseResults(results rod.Elements, pageNum int) []core.Searc // Search executes a Yandex web search and returns normalized search results. // It may return core.ErrCaptcha or core.ErrSearchTimeout. func (yand *Yandex) Search(ctx context.Context, query core.Query) (results []core.SearchResult, err error) { - ctx = core.EnsureContext(ctx) + ctx = core.WithEngine(core.EnsureContext(ctx), yand.Name()) + ctx = core.WithQueryHash(ctx, core.QueryHashFromQuery(query)) + scoped := *yand + scoped.logger = yand.logger.WithRequest(ctx) + yand = &scoped + yand.logger.Debug("Starting search, query: %+v", query) defer func() { if recovered := recover(); recovered != nil { - err = core.RecoverEnginePanic(yand.Name(), recovered, yand.logger) + err = core.RecoverEnginePanicWithContext(ctx, yand.Name(), recovered, yand.logger) results = nil } }() @@ -221,7 +226,12 @@ func (yand *Yandex) Search(ctx context.Context, query core.Query) (results []cor // SearchImage executes a Yandex image search and returns normalized image // results. It may return core.ErrCaptcha or core.ErrSearchTimeout. func (yand *Yandex) SearchImage(ctx context.Context, query core.Query) ([]core.SearchResult, error) { - ctx = core.EnsureContext(ctx) + ctx = core.WithEngine(core.EnsureContext(ctx), yand.Name()) + ctx = core.WithQueryHash(ctx, core.QueryHashFromQuery(query)) + scoped := *yand + scoped.logger = yand.logger.WithRequest(ctx) + yand = &scoped + yand.logger.Debug("Starting image search, query: %+v", query) searchResults := []core.SearchResult{} diff --git a/yandex/search_raw.go b/yandex/search_raw.go index baae3e5..f4bc2c4 100644 --- a/yandex/search_raw.go +++ b/yandex/search_raw.go @@ -2,6 +2,7 @@ package yandex import ( "context" + "fmt" "net/http" "strings" @@ -85,15 +86,19 @@ func yandexResultParser(response *http.Response) ([]core.SearchResult, error) { } } - logrus.Tracef("Yandex search document size: %d", len(doc.Text())) + logrus.WithField("document_size", len(doc.Text())).Trace( + fmt.Sprintf("Yandex search document size: %d", len(doc.Text())), + ) return core.DeduplicateResults(results), err } func Search(ctx context.Context, query core.Query) (results []core.SearchResult, err error) { ctx = core.EnsureContext(ctx) + ctx = core.WithEngine(ctx, "yandex") + ctx = core.WithQueryHash(ctx, core.QueryHashFromQuery(query)) defer func() { if recovered := recover(); recovered != nil { - err = core.RecoverEnginePanic("yandex", recovered, nil) + err = core.RecoverEnginePanicWithContext(ctx, "yandex", recovered, nil) results = nil } }() @@ -107,14 +112,16 @@ func Search(ctx context.Context, query core.Query) (results []core.SearchResult, if err != nil { return nil, err } - logrus.Debugf("Yandex URL built: %s", googleURL) + core.WithRequest(ctx).WithField("url", googleURL).Debug(fmt.Sprintf("Yandex URL built: %s", googleURL)) res, err := yandexRequest(ctx, googleURL, query) if err != nil { return nil, err } defer core.DrainAndCloseResponse(res) - logrus.Debugf("Yandex Raw response: code=%d", res.StatusCode) + core.WithRequest(ctx).WithField("status_code", res.StatusCode).Debug( + fmt.Sprintf("Yandex Raw response: code=%d", res.StatusCode), + ) parsedResults, err := yandexResultParser(res) if err != nil { @@ -133,7 +140,9 @@ func Search(ctx context.Context, query core.Query) (results []core.SearchResult, parsedResults[i].Rank = query.Start + i + 1 } } - logrus.Debugf("Yandex Raw results : %v", parsedResults) + core.WithRequest(ctx).WithField("results_count", len(parsedResults)).Debug( + fmt.Sprintf("Yandex Raw results : %v", parsedResults), + ) return parsedResults, nil }