From f96e58b9bca9bf7c53891233febe9ffa70c0ff8f Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Juan=20Jos=C3=A9=20Mata?= <juanjo.mata@gmail.com>
Date: Sat, 7 Mar 2026 01:35:47 +0100
Subject: [PATCH] Enhance logging in `search_family_files.rb` for vector store
 debugging (#1033)
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

* Enhance logging in search_family_files.rb

Added logging for search parameters and results in SearchFamilyFiles.

Signed-off-by: Juan José Mata <juanjo.mata@gmail.com>

* Log level should be `debug` not `warn` here

* Unguarded `trace&.update` patterns

* API concernts from CodeRabbit

---------

Signed-off-by: Juan José Mata <juanjo.mata@gmail.com>
---
 .../assistant/function/search_family_files.rb | 91 +++++++++++++++----
 1 file changed, 71 insertions(+), 20 deletions(-)

diff --git a/app/models/assistant/function/search_family_files.rb b/app/models/assistant/function/search_family_files.rb
index 2c0e5bf37..c9c917f0a 100644
--- a/app/models/assistant/function/search_family_files.rb
+++ b/app/models/assistant/function/search_family_files.rb
@@ -53,7 +53,10 @@ class Assistant::Function::SearchFamilyFiles < Assistant::Function
     query = params["query"]
     max_results = (params["max_results"] || 10).to_i.clamp(1, 20)
 
+    Rails.logger.debug("[SearchFamilyFiles] query=#{query.inspect} max_results=#{max_results} family_id=#{family.id}")
+
     unless family.vector_store_id.present?
+      Rails.logger.debug("[SearchFamilyFiles] family #{family.id} has no vector_store_id")
       return {
         success: false,
         error: "no_documents",
@@ -64,6 +67,7 @@ class Assistant::Function::SearchFamilyFiles < Assistant::Function
     adapter = VectorStore.adapter
 
     unless adapter
+      Rails.logger.debug("[SearchFamilyFiles] no VectorStore adapter configured")
       return {
         success: false,
         error: "provider_not_configured",
@@ -71,48 +75,95 @@ class Assistant::Function::SearchFamilyFiles < Assistant::Function
       }
     end
 
+    store_id = family.vector_store_id
+    Rails.logger.debug("[SearchFamilyFiles] searching store_id=#{store_id} via #{adapter.class.name}")
+
+    trace = create_langfuse_trace(
+      name: "search_family_files",
+      input: { query: query, max_results: max_results, store_id: store_id }
+    )
+
     response = adapter.search(
-      store_id: family.vector_store_id,
+      store_id: store_id,
       query: query,
       max_results: max_results
     )
 
     unless response.success?
+      error_msg = response.error&.message
+      Rails.logger.debug("[SearchFamilyFiles] search failed: #{error_msg}")
+      begin
+        langfuse_client&.trace(id: trace.id, output: { error: error_msg }, level: "ERROR") if trace
+      rescue => e
+        Rails.logger.debug("[SearchFamilyFiles] Langfuse trace update failed: #{e.class}: #{e.message}\n#{e.backtrace&.first(5)&.join("\n")}")
+      end
       return {
         success: false,
         error: "search_failed",
-        message: "Failed to search documents: #{response.error&.message}"
+        message: "Failed to search documents: #{error_msg}"
       }
     end
 
     results = response.data
 
-    if results.empty?
-      return {
-        success: true,
-        results: [],
-        message: "No matching documents found for the query."
-      }
+    Rails.logger.debug("[SearchFamilyFiles] #{results.size} chunk(s) returned")
+
+    results.each_with_index do |r, i|
+      Rails.logger.debug(
+        "[SearchFamilyFiles] chunk[#{i}] score=#{r[:score]} file=#{r[:filename].inspect} " \
+        "content_length=#{r[:content]&.length} preview=#{r[:content]&.truncate(10).inspect}"
+      )
     end
 
-    {
-      success: true,
-      query: query,
-      result_count: results.size,
-      results: results.map do |result|
-        {
-          content: result[:content],
-          filename: result[:filename],
-          score: result[:score]
-        }
+    mapped = results.map do |result|
+      { content: result[:content], filename: result[:filename], score: result[:score] }
+    end
+
+    output = if mapped.empty?
+      { success: true, results: [], message: "No matching documents found for the query." }
+    else
+      { success: true, query: query, result_count: mapped.size, results: mapped }
+    end
+
+    begin
+      if trace
+        langfuse_client&.trace(id: trace.id, output: {
+          result_count: mapped.size,
+          chunks: mapped.map { |r| { filename: r[:filename], score: r[:score], content_length: r[:content]&.length } }
+        })
       end
-    }
+    rescue => e
+      Rails.logger.debug("[SearchFamilyFiles] Langfuse trace update failed: #{e.class}: #{e.message}\n#{e.backtrace&.first(5)&.join("\n")}")
+    end
+
+    output
   rescue => e
-    Rails.logger.error("SearchFamilyFiles error: #{e.class.name} - #{e.message}")
+    Rails.logger.error("[SearchFamilyFiles] error: #{e.class.name} - #{e.message}")
     {
       success: false,
       error: "search_failed",
       message: "An error occurred while searching documents: #{e.message.truncate(200)}"
     }
   end
+
+  private
+    def langfuse_client
+      return unless ENV["LANGFUSE_PUBLIC_KEY"].present? && ENV["LANGFUSE_SECRET_KEY"].present?
+
+      @langfuse_client ||= Langfuse.new
+    end
+
+    def create_langfuse_trace(name:, input:)
+      return unless langfuse_client
+
+      langfuse_client.trace(
+        name: name,
+        input: input,
+        user_id: user.id&.to_s,
+        environment: Rails.env
+      )
+    rescue => e
+      Rails.logger.debug("[SearchFamilyFiles] Langfuse trace creation failed: #{e.class}: #{e.message}\n#{e.backtrace&.first(5)&.join("\n")}")
+      nil
+    end
 end