Expand backend debug logging

TODO.md

@@ -460,6 +460,18 @@
 - There is one known local commit that has not been pushed because the remote repo reported an unpacker error.
 
 ## Recent Change Log
+- Date: `2026-03-16`
+- What changed:
+  - Significantly increased backend debug logging volume and routed it into the existing WebSocket `debug` stream so the in-app `Logs` panel captures much deeper request, search, preview, Gemini, and ranking traces.
+  - Added request-start/request-done API middleware logs with request body and truncated response body snapshots.
+  - Added service-level debug hooks for SearXNG requests, collector activity, enrichment passes, Gemini translation/vision steps, ranking batch stats, and preview proxy/cache behavior.
+- Why it changed:
+  - The user wants to export detailed browser-visible log files and use them later for root-cause analysis instead of relying on sparse summaries.
+- How it was verified:
+  - code inspection of debug hook wiring from backend services to WebSocket `debug` broadcasts
+- What is still risky or incomplete:
+  - Very verbose logging can make the `Logs` panel noisier and larger, especially during long searches or preview playback.
+
 - Date: `2026-03-16`
 - What changed:
   - Removed per-batch Gemini fallback injection so empty Gemini sub-results no longer automatically turn into many `"Gemini Vision 응답이 부족해..."` items.

backend/handlers/api.go

@@ -2,6 +2,7 @@ package handlers
 
 import (
 	"bufio"
+	"bytes"
 	"crypto/sha1"
 	"database/sql"
 	"encoding/json"
@@ -90,7 +91,49 @@ type searchDebugSummary struct {
 	GeminiCandidateCap int              `json:"geminiCandidateCap,omitempty"`
 }
 
+type debugResponseWriter struct {
+	gin.ResponseWriter
+	body bytes.Buffer
+}
+
+func (w *debugResponseWriter) Write(data []byte) (int, error) {
+	if w.body.Len() < 4096 {
+		remaining := 4096 - w.body.Len()
+		if len(data) > remaining {
+			w.body.Write(data[:remaining])
+		} else {
+			w.body.Write(data)
+		}
+	}
+	return w.ResponseWriter.Write(data)
+}
+
 func RegisterRoutes(router *gin.Engine, app *App) {
+	router.Use(func(c *gin.Context) {
+		started := time.Now()
+		var requestBody string
+		if c.Request.Body != nil && (c.Request.Method == http.MethodPost || c.Request.Method == http.MethodPut || c.Request.Method == http.MethodPatch) {
+			raw, _ := io.ReadAll(io.LimitReader(c.Request.Body, 4096))
+			requestBody = string(raw)
+			c.Request.Body = io.NopCloser(bytes.NewReader(raw))
+		}
+		writer := &debugResponseWriter{ResponseWriter: c.Writer}
+		c.Writer = writer
+		app.debug("http:request:start", gin.H{
+			"method": c.Request.Method,
+			"path":   c.Request.URL.Path,
+			"query":  c.Request.URL.RawQuery,
+			"body":   truncateText(strings.TrimSpace(requestBody), 4000),
+		})
+		c.Next()
+		app.debug("http:request:done", gin.H{
+			"method":     c.Request.Method,
+			"path":       c.Request.URL.Path,
+			"status":     c.Writer.Status(),
+			"durationMs": time.Since(started).Milliseconds(),
+			"response":   truncateText(strings.TrimSpace(writer.body.String()), 4000),
+		})
+	})
 	router.GET("/healthz", func(c *gin.Context) {
 		c.JSON(http.StatusOK, gin.H{"status": "ok"})
 	})
@@ -104,6 +147,9 @@ func RegisterRoutes(router *gin.Engine, app *App) {
 }
 
 func (a *App) debug(message string, data any) {
+	if payload, err := json.Marshal(data); err == nil {
+		fmt.Printf("[debug] %s %s\n", message, string(payload))
+	}
 	a.Hub.Broadcast("debug", gin.H{"message": message, "data": data})
 }
 
@@ -154,20 +200,24 @@ func (a *App) streamPreview(c *gin.Context) {
 	req.Header.Set("User-Agent", "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36")
 	req.Header.Set("Accept-Language", "en-US,en;q=0.9")
 	req.Header.Set("Referer", inferPreviewReferer(target))
+	a.debug("preview:proxy:start", gin.H{"target": target, "referer": req.Header.Get("Referer")})
 
 	resp, err := a.SearchService.Client.Do(req)
 	if err != nil {
+		a.debug("preview:proxy:error", gin.H{"target": target, "error": err.Error()})
 		c.JSON(http.StatusBadGateway, gin.H{"error": err.Error()})
 		return
 	}
 	defer resp.Body.Close()
 
 	if resp.StatusCode >= 300 {
+		a.debug("preview:proxy:bad_status", gin.H{"target": target, "status": resp.StatusCode})
 		c.JSON(http.StatusBadGateway, gin.H{"error": fmt.Sprintf("preview source returned %d", resp.StatusCode)})
 		return
 	}
 
 	contentType := resp.Header.Get("Content-Type")
+	a.debug("preview:proxy:response", gin.H{"target": target, "contentType": contentType, "status": resp.StatusCode})
 	if strings.Contains(strings.ToLower(target), ".m3u8") || strings.Contains(strings.ToLower(contentType), "mpegurl") {
 		body, err := io.ReadAll(io.LimitReader(resp.Body, 2*1024*1024))
 		if err != nil {
@@ -175,6 +225,7 @@ func (a *App) streamPreview(c *gin.Context) {
 			return
 		}
 		rewritten := rewriteM3U8Playlist(string(body), target)
+		a.debug("preview:proxy:hls_rewritten", gin.H{"target": target, "bytes": len(body)})
 		c.Header("Content-Type", "application/vnd.apple.mpegurl")
 		c.String(http.StatusOK, rewritten)
 		return
@@ -182,9 +233,11 @@ func (a *App) streamPreview(c *gin.Context) {
 
 	if isCacheablePreview(target, contentType) {
 		if cachedPath, err := a.cachePreviewResponse(target, contentType, resp.Body); err == nil {
+			a.debug("preview:proxy:cache_hit_write", gin.H{"target": target, "cachedPath": cachedPath})
 			c.File(cachedPath)
 			return
 		}
+		a.debug("preview:proxy:cache_write_error", gin.H{"target": target, "error": err.Error()})
 	}
 
 	if contentType != "" {
@@ -673,6 +726,9 @@ func (a *App) cachePreviewResponse(target, contentType string, body io.Reader) (
 		ext = ".mp4"
 	}
 	path := filepath.Join(a.PreviewCacheDir, fmt.Sprintf("%x%s", sum, ext))
+	if _, err := os.Stat(path); err == nil {
+		return path, nil
+	}
 	file, err := os.Create(path)
 	if err != nil {
 		return "", err

backend/main.go

@@ -43,6 +43,12 @@ func main() {
 		GeminiService: services.NewGeminiService(os.Getenv("GEMINI_API_KEY")),
 		Hub:           handlers.NewHub(),
 	}
+	app.SearchService.Debug = func(message string, data any) {
+		app.Hub.Broadcast("debug", gin.H{"message": message, "data": data})
+	}
+	app.GeminiService.Debug = func(message string, data any) {
+		app.Hub.Broadcast("debug", gin.H{"message": message, "data": data})
+	}
 
 	router := gin.Default()
 	handlers.RegisterRoutes(router, app)

backend/services/cse.go

@@ -32,6 +32,7 @@ type SearchService struct {
 	WebEngine         string
 	Client            *http.Client
 	collectors        []searchCollector
+	Debug             func(message string, data any)
 }
 
 func NewSearchService(baseURL, googleVideoEngine, webEngine string) *SearchService {
@@ -58,6 +59,10 @@ func (s *SearchService) SearchMedia(queries []string, enabledPlatforms map[strin
 	if s.BaseURL == "" {
 		return nil, fmt.Errorf("searxng base url is not configured")
 	}
+	s.debug("search_service:start", map[string]any{
+		"queries":          queries,
+		"enabledPlatforms": enabledPlatforms,
+	})
 
 	seen := map[string]bool{}
 	sourceCounts := map[string]int{}
@@ -85,15 +90,32 @@ func (s *SearchService) SearchMedia(queries []string, enabledPlatforms map[strin
 				}
 				searchQueries := collector.BuildQueries(base)
 				shuffleStrings(searchQueries)
+				s.debug("search_service:collector_queries", map[string]any{
+					"collector":     collector.Name(),
+					"base":          base,
+					"onlyMissing":   onlyMissing,
+					"searchQueries": searchQueries,
+				})
 				for _, searchQuery := range searchQueries {
 					if sourceCounts[collector.Name()] >= collector.MaxResults() {
 						break
 					}
 					items, err := collector.Collect(s, searchQuery)
 					if err != nil {
+						s.debug("search_service:collector_error", map[string]any{
+							"collector": collector.Name(),
+							"query":     searchQuery,
+							"error":     err.Error(),
+						})
 						lastErr = err
 						continue
 					}
+					s.debug("search_service:collector_results", map[string]any{
+						"collector":   collector.Name(),
+						"query":       searchQuery,
+						"rawCount":    len(items),
+						"sourceCount": sourceCounts[collector.Name()],
+					})
 					for _, item := range items {
 						item = normalizeResultForCollector(collector.Name(), item)
 						if item.Link == "" || seen[item.Link] || !collector.Accept(item) {
@@ -123,6 +145,11 @@ func (s *SearchService) SearchMedia(queries []string, enabledPlatforms map[strin
 	sort.SliceStable(results, func(i, j int) bool {
 		return sourceWeight(results[i].Source) > sourceWeight(results[j].Source)
 	})
+	s.debug("search_service:complete", map[string]any{
+		"resultCount":  len(results),
+		"sourceCounts": sourceCounts,
+		"hadError":     lastErr != nil,
+	})
 	return s.EnrichResults(results), nil
 }
 
@@ -131,6 +158,10 @@ func (s *SearchService) EnrichResults(results []SearchResult) []SearchResult {
 	if limit == 0 {
 		return results
 	}
+	s.debug("search_service:enrich_start", map[string]any{
+		"total": len(results),
+		"limit": limit,
+	})
 
 	enriched := make([]SearchResult, len(results))
 	copy(enriched, results)
@@ -143,10 +174,24 @@ func (s *SearchService) EnrichResults(results []SearchResult) []SearchResult {
 			defer wg.Done()
 			sem <- struct{}{}
 			defer func() { <-sem }()
+			s.debug("search_service:enrich_item_start", map[string]any{
+				"index":  i,
+				"link":   enriched[i].Link,
+				"source": enriched[i].Source,
+			})
 			enriched[i] = s.enrichResult(enriched[i])
+			s.debug("search_service:enrich_item_done", map[string]any{
+				"index":     i,
+				"link":      enriched[i].Link,
+				"source":    enriched[i].Source,
+				"thumbnail": strings.TrimSpace(enriched[i].ThumbnailURL) != "",
+				"preview":   strings.TrimSpace(enriched[i].PreviewVideoURL) != "",
+				"title":     truncateForDebug(enriched[i].Title, 120),
+			})
 		}(idx)
 	}
 	wg.Wait()
+	s.debug("search_service:enrich_complete", map[string]any{"limit": limit})
 	return enriched
 }
 
@@ -163,10 +208,21 @@ func (s *SearchService) enrichResult(result SearchResult) SearchResult {
 }
 
 func (s *SearchService) searchWithFallback(query, categories, engine, source string) ([]SearchResult, error) {
+	s.debug("search_service:search_with_fallback", map[string]any{
+		"query":      query,
+		"categories": categories,
+		"engine":     engine,
+		"source":     source,
+	})
 	items, err := s.search(query, categories, engine, source)
 	if err == nil {
 		return items, nil
 	}
+	s.debug("search_service:search_with_fallback_primary_error", map[string]any{
+		"query":  query,
+		"engine": engine,
+		"error":  err.Error(),
+	})
 	if strings.TrimSpace(engine) == "" {
 		return nil, err
 	}
@@ -174,8 +230,10 @@ func (s *SearchService) searchWithFallback(query, categories, engine, source str
 }
 
 func (s *SearchService) enrichEnvato(result SearchResult) SearchResult {
+	s.debug("search_service:enrich_envato_start", map[string]any{"link": result.Link})
 	html, err := s.fetchText(result.Link)
 	if err != nil {
+		s.debug("search_service:enrich_envato_fetch_error", map[string]any{"link": result.Link, "error": err.Error()})
 		return result
 	}
 	videoMeta := extractVideoObjectJSONLD(html)
@@ -224,14 +282,21 @@ func (s *SearchService) enrichEnvato(result SearchResult) SearchResult {
 			)
 		}
 	}
+	s.debug("search_service:enrich_envato_done", map[string]any{
+		"link":      result.Link,
+		"thumbnail": strings.TrimSpace(result.ThumbnailURL) != "",
+		"preview":   strings.TrimSpace(result.PreviewVideoURL) != "",
+	})
 	return result
 }
 
 func (s *SearchService) enrichArtgrid(result SearchResult) SearchResult {
 	clipID := extractArtgridClipID(result.Link)
 	if clipID == "" {
+		s.debug("search_service:enrich_artgrid_skip", map[string]any{"link": result.Link, "reason": "missing clip id"})
 		return result
 	}
+	s.debug("search_service:enrich_artgrid_start", map[string]any{"link": result.Link, "clipId": clipID})
 
 	apiURL := "https://artgrid.io/api/clip/details?clipId=" + clipID
 	body, err := s.fetchJSONText(apiURL)
@@ -244,11 +309,15 @@ func (s *SearchService) enrichArtgrid(result SearchResult) SearchResult {
 			result.PreviewVideoURL = pickVideoURL(urls)
 		}
 	}
+	if err != nil {
+		s.debug("search_service:enrich_artgrid_api_error", map[string]any{"link": result.Link, "clipId": clipID, "error": err.Error()})
+	}
 
 	if result.ThumbnailURL == "" || result.PreviewVideoURL == "" {
 		html, err := s.fetchText(result.Link)
 		if err == nil {
 			if !isMatchingArtgridClipPage(html, clipID) {
+				s.debug("search_service:enrich_artgrid_html_mismatch", map[string]any{"link": result.Link, "clipId": clipID})
 				return result
 			}
 			result.Title = firstNonEmpty(
@@ -289,6 +358,12 @@ func (s *SearchService) enrichArtgrid(result SearchResult) SearchResult {
 			}
 		}
 	}
+	s.debug("search_service:enrich_artgrid_done", map[string]any{
+		"link":      result.Link,
+		"clipId":    clipID,
+		"thumbnail": strings.TrimSpace(result.ThumbnailURL) != "",
+		"preview":   strings.TrimSpace(result.PreviewVideoURL) != "",
+	})
 
 	return result
 }
@@ -307,6 +382,13 @@ func (s *SearchService) search(query, categories, engine, source string) ([]Sear
 	}
 
 	endpoint := s.BaseURL + "/search?" + values.Encode()
+	s.debug("search_service:searx_request", map[string]any{
+		"endpoint":   endpoint,
+		"query":      query,
+		"categories": categories,
+		"engine":     engine,
+		"source":     source,
+	})
 	resp, err := s.Client.Get(endpoint)
 	if err != nil {
 		return nil, err
@@ -332,6 +414,11 @@ func (s *SearchService) search(query, categories, engine, source string) ([]Sear
 	if err := json.NewDecoder(resp.Body).Decode(&payload); err != nil {
 		return nil, fmt.Errorf("searxng JSON decode failed for query %q: %w", query, err)
 	}
+	s.debug("search_service:searx_response", map[string]any{
+		"query":    query,
+		"source":   source,
+		"rawCount": len(payload.Results),
+	})
 
 	results := make([]SearchResult, 0, len(payload.Results))
 	for _, item := range payload.Results {
@@ -351,6 +438,20 @@ func (s *SearchService) search(query, categories, engine, source string) ([]Sear
 	return results, nil
 }
 
+func (s *SearchService) debug(message string, data any) {
+	if s != nil && s.Debug != nil {
+		s.Debug(message, data)
+	}
+}
+
+func truncateForDebug(text string, limit int) string {
+	trimmed := strings.TrimSpace(text)
+	if len(trimmed) <= limit {
+		return trimmed
+	}
+	return trimmed[:limit] + "..."
+}
+
 func buildGoogleVideoQueries(base string) []string {
 	return []string{
 		fmt.Sprintf(`"%s" ("stock footage" OR "b-roll" OR cinematic OR "establishing shot" OR editorial) -tutorial -"how to" -review -reaction -course -podcast -vlog -interview -breakdown -edit -editing`, base),

backend/services/gemini.go

@@ -22,6 +22,7 @@ type GeminiService struct {
 	Client            *http.Client
 	GenerateEndpoint  string
 	TranslateEndpoint string
+	Debug             func(message string, data any)
 }
 
 type AIRecommendation struct {
@@ -50,7 +51,13 @@ func NewGeminiService(apiKey string) *GeminiService {
 
 func (g *GeminiService) ExpandQuery(query string) ([]string, error) {
 	englishBase := g.TranslateQuery(query)
-	return buildSearchQueries(query, englishBase), nil
+	expanded := buildSearchQueries(query, englishBase)
+	g.debug("gemini:expand_query", map[string]any{
+		"original": query,
+		"english":  englishBase,
+		"expanded": expanded,
+	})
+	return expanded, nil
 }
 
 func (g *GeminiService) TranslateQuery(query string) string {
@@ -67,6 +74,7 @@ func (g *GeminiService) TranslateQuery(query string) string {
 	}
 
 	if g.APIKey != "" {
+		g.debug("gemini:translate_attempt", map[string]any{"mode": "gemini", "query": trimmed})
 		body := map[string]any{
 			"systemInstruction": map[string]any{
 				"parts": []map[string]string{
@@ -95,17 +103,25 @@ func (g *GeminiService) TranslateQuery(query string) string {
 		if err == nil {
 			translated := sanitizePlainEnglishLine(rawText)
 			if translated != "" && !strings.EqualFold(translated, trimmed) && !isOvercompressedTranslation(trimmed, translated) {
+				g.debug("gemini:translate_success", map[string]any{"mode": "gemini", "query": trimmed, "translated": translated})
 				return translated
 			}
 		}
+		if err != nil {
+			g.debug("gemini:translate_error", map[string]any{"mode": "gemini", "query": trimmed, "error": err.Error()})
+		}
 	}
 
+	g.debug("gemini:translate_attempt", map[string]any{"mode": "google", "query": trimmed})
 	if translated, err := g.translateViaGoogle(trimmed); err == nil && translated != "" && isLikelyEnglishQuery(translated) && !isOvercompressedTranslation(trimmed, translated) {
+		g.debug("gemini:translate_success", map[string]any{"mode": "google", "query": trimmed, "translated": translated})
 		return translated
 	}
 	if translated := translateKoreanMediaTerms(normalizedIntent); translated != "" && !strings.EqualFold(translated, trimmed) {
+		g.debug("gemini:translate_success", map[string]any{"mode": "dictionary", "query": trimmed, "translated": translated})
 		return translated
 	}
+	g.debug("gemini:translate_fallback_original", map[string]any{"query": trimmed, "normalized": normalizedIntent})
 	return strings.TrimSpace(normalizedIntent)
 }
 
@@ -148,6 +164,10 @@ func (g *GeminiService) Recommend(query string, candidates []SearchResult) ([]AI
 	if len(candidates) == 0 {
 		return []AIRecommendation{}, nil
 	}
+	g.debug("gemini:vision_start", map[string]any{
+		"query":          query,
+		"candidateCount": len(candidates),
+	})
 
 	type geminiPart map[string]any
 	parts := []geminiPart{
@@ -169,6 +189,12 @@ User query: ` + query,
 	for idx := 0; idx < maxImages; idx++ {
 		img, mimeType, err := fetchCandidateVisualInlineData(g.Client, candidates[idx])
 		if err != nil {
+			g.debug("gemini:vision_candidate_visual_error", map[string]any{
+				"index":  idx,
+				"link":   candidates[idx].Link,
+				"source": candidates[idx].Source,
+				"error":  err.Error(),
+			})
 			continue
 		}
 		visualCount++
@@ -180,6 +206,11 @@ User query: ` + query,
 	if visualCount == 0 {
 		return nil, fmt.Errorf("no candidate thumbnails or preview frames could be fetched for gemini vision")
 	}
+	g.debug("gemini:vision_visuals_prepared", map[string]any{
+		"query":       query,
+		"visualCount": visualCount,
+		"maxImages":   maxImages,
+	})
 
 	body := map[string]any{
 		"contents": []map[string]any{
@@ -254,10 +285,20 @@ User query: ` + query,
 			Recommended:     recommended,
 		})
 	}
+	g.debug("gemini:vision_complete", map[string]any{
+		"query":               query,
+		"recommendationCount": len(recommendations),
+	})
 
 	return recommendations, nil
 }
 
+func (g *GeminiService) debug(message string, data any) {
+	if g != nil && g.Debug != nil {
+		g.Debug(message, data)
+	}
+}
+
 func fetchImageAsInlineData(client *http.Client, imageURL, referer string) (string, string, error) {
 	if strings.TrimSpace(imageURL) == "" {
 		return "", "", fmt.Errorf("image url is empty")

backend/services/ranker.go

@@ -119,6 +119,14 @@ func EvaluateAllCandidatesWithGemini(service *GeminiService, query string, ranke
 	if len(batches) == 0 {
 		return []AIRecommendation{}, stats, nil
 	}
+	if service != nil && service.Debug != nil {
+		service.Debug("ranker:gemini_batches_created", map[string]any{
+			"query":     query,
+			"limit":     limit,
+			"batches":   len(batches),
+			"chunkSize": chunkSize,
+		})
+	}
 
 	results := make([]batchResult, len(batches))
 	var wg sync.WaitGroup
@@ -143,6 +151,12 @@ func EvaluateAllCandidatesWithGemini(service *GeminiService, query string, ranke
 	seen := map[string]bool{}
 	for _, batch := range results {
 		if batch.err != nil {
+			if service != nil && service.Debug != nil {
+				service.Debug("ranker:gemini_batch_error", map[string]any{
+					"batchIndex": batch.index,
+					"error":      batch.err.Error(),
+				})
+			}
 			recovered, recoveredErrs := recoverGeminiBatchSequentially(service, query, ranked, batch.index*chunkSize)
 			if len(recovered) > 0 {
 				stats.SequentialRetried++
@@ -180,6 +194,9 @@ func EvaluateAllCandidatesWithGemini(service *GeminiService, query string, ranke
 		}
 	}
 	stats.RecommendedCount = len(merged)
+	if service != nil && service.Debug != nil {
+		service.Debug("ranker:gemini_batches_complete", stats)
+	}
 
 	switch {
 	case len(merged) > 0 && stats.Failed == 0: