Improve logging: add structured logs, enrich logs with useful info.

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{}

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
 }

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{}

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)
 	}
 

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)
+		logFormat, err := core.NormalizeLogFormat(config.App.LogFormat)
-		logrus.Debugf("Final config: %+v", config)
+		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)")
 }

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 {

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
 	}
 

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)

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)
 }

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)",
+			WithRequestEngine(ctx, cb.name).
-				cb.name, cb.failureCount, cb.config.RecoveryTimeout)
+				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")
 	}
 }
 

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(context.Background())
-	cb.RecordFailure()
+	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(context.Background())
-	cb.RecordFailure()
+	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 {

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 {
+type loggerContextKey string
-	logrus.TextFormatter
+
+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) {
+func WithRequestID(ctx context.Context, requestID string) context.Context {
-	message := entry.Message
+	requestID = strings.TrimSpace(requestID)
-
+	if requestID == "" {
-	// Check if engine name is provided as a field
+		return EnsureContext(ctx)
-	engineName := ""
-	if engine, exists := entry.Data["engine"]; exists {
-		if engineStr, ok := engine.(string); ok {
-			engineName = engineStr
-		}
 	}
-
+	return context.WithValue(EnsureContext(ctx), requestIDContextKey, requestID)
-	// 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
 }
 
-// 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 = strings.ToLower(strings.TrimSpace(engine))
-		engine: engine,
+	return &EngineLogger{engine: engine, entry: logrus.WithField("engine", engine)}
-		logger: 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
+	rest := make([]string, 0, len(entry.Data))
-func (el *EngineLogger) Debug(message string, args ...interface{}) {
+	for k := range entry.Data {
-	el.logger.Debugf(message, args...)
+		if !written[k] {
-}
+			rest = append(rest, k)
-
+		}
-// 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...)
 	}
+	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) {
+// quoteIfNeeded wraps s in double-quotes if it contains spaces.
-	logrus.SetFormatter(&customFormatter{logrus.TextFormatter{
+func quoteIfNeeded(s string) string {
-		FullTimestamp:          true,
+	if strings.ContainsAny(s, " \t") {
-		TimestampFormat:        "2006-01-02 15:04:05",
+		return `"` + strings.ReplaceAll(s, `"`, `\"`) + `"`
-		ForceColors:            true,
+	}
-		DisableLevelTruncation: true,
+	return s
-	}})
+}
 
-	if isVerbose {
+func InitLogger(isVerbose, isDebug bool, format string) {
-		logrus.SetLevel(logrus.DebugLevel)
+	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")
+			fmt.Fprintf(os.Stderr, "Failed to open logs file ./logs.txt: %v\n", err)
-			panic(err)
+			logrus.SetOutput(io.MultiWriter(os.Stdout))
+		} else {
+			logrus.SetOutput(io.MultiWriter(f, os.Stdout))
 		}
-
+		logrus.SetReportCaller(false)
-		logrus.SetOutput(io.MultiWriter(f, os.Stdout))
-		logrus.SetLevel(logrus.DebugLevel)
 	}
+
+	level := logrus.InfoLevel
+	if isVerbose {
+		level = logrus.DebugLevel
+	}
+	if isDebug {
+		level = logrus.TraceLevel
+	}
+	logrus.SetLevel(level)
 }

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(),
+			"method": c.Method(),
-			"path":    c.Path(),
+			"path":   c.Path(),
-			"status":  status,
+			"status": status,
-			"latency": latency.String(),
+			"ip":     c.IP(),
-			"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

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)
+}

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

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(context.Background(), "http://proxy1:8080")
-	registry.ReportFailure("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(context.Background(), "http://proxy2:8080")
-	registry.ReportFailure("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.ReportFailure(context.Background(), "http://proxy1:8080")
-	registry.ReportSuccess("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)

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() {
+		engineCtx := WithEngine(ctx, engine.Name())
-			logrus.Infof("[Resilient] Skipping %s in megasearch (circuit open)", 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() {
+		engineCtx := WithEngine(ctx, engine.Name())
-			logrus.Infof("[Resilient] Skipping %s in megaimage (circuit open)", 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")

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{

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

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)

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{}

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{}

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
 }

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)
 	}

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{}

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
 }