Update bd-1048 with investigation findings

internal/rpc/server_export_import_auto.go

@@ -191,11 +191,10 @@ func (s *Server) checkAndAutoImportIfStale(req *Request) error {
 	// If import is already running, skip and let the request proceed (bd-8931)
 	// This prevents blocking RPC requests when import is in progress
 	if !s.importInProgress.CompareAndSwap(false, true) {
-		if os.Getenv("BD_DEBUG") != "" {
-			fmt.Fprintf(os.Stderr, "Debug: auto-import already in progress, skipping\n")
-		}
+		fmt.Fprintf(os.Stderr, "Debug: auto-import already in progress, skipping (bd-1048)\n")
 		return nil
 	}
+	fmt.Fprintf(os.Stderr, "Debug: acquired import lock, proceeding with auto-import (bd-1048)\n")
 
 	// Track whether we should release the lock via defer
 	// Set to false if we manually release early to avoid double-release bug
@@ -224,18 +223,20 @@ func (s *Server) checkAndAutoImportIfStale(req *Request) error {
 	}
 
 	// Double-check staleness after acquiring lock (another goroutine may have imported)
+	fmt.Fprintf(os.Stderr, "Debug: checking staleness after lock acquisition (bd-1048)\n")
 	isStale, err = autoimport.CheckStaleness(ctx, store, dbPath)
 	if err != nil || !isStale {
+		fmt.Fprintf(os.Stderr, "Debug: staleness check returned: stale=%v err=%v (bd-1048)\n", isStale, err)
 		return err
 	}
 
-	if os.Getenv("BD_DEBUG") != "" {
-		fmt.Fprintf(os.Stderr, "Debug: daemon detected stale JSONL, auto-importing with timeout...\n")
-	}
+	fmt.Fprintf(os.Stderr, "Debug: daemon detected stale JSONL, auto-importing with timeout... (bd-1048)\n")
 
-	// Create timeout context for import operation (bd-8931)
+	// Create timeout context for import operation (bd-8931, bd-1048)
 	// This prevents daemon from hanging if import gets stuck
-	importCtx, cancel := context.WithTimeout(ctx, 30*time.Second)
+	// Use shorter timeout (5s) to ensure client doesn't timeout waiting for response
+	// Client has 30s timeout, so import must complete well before that
+	importCtx, cancel := context.WithTimeout(ctx, 5*time.Second)
 	defer cancel()
 
 	// Perform actual import with timeout protection
@@ -289,7 +290,7 @@ func (s *Server) checkAndAutoImportIfStale(req *Request) error {
 	err = autoimport.AutoImportIfNewer(importCtx, store, dbPath, notify, importFunc, onChanged)
 	if err != nil {
 		if importCtx.Err() == context.DeadlineExceeded {
-			fmt.Fprintf(os.Stderr, "Error: auto-import timed out after 30s. Run 'bd import' manually.\n")
+			fmt.Fprintf(os.Stderr, "Error: auto-import timed out after 5s. Run 'bd import' manually.\n")
 			return fmt.Errorf("auto-import timed out")
 		}
 		// Log but don't fail the request - let it proceed with stale data

internal/rpc/server_lifecycle_conn.go

@@ -178,7 +178,11 @@ func (s *Server) handleSignals() {
 }
 
 func (s *Server) handleConnection(conn net.Conn) {
-	defer func() { _ = conn.Close() }()
+	fmt.Fprintf(os.Stderr, "Debug: handleConnection started (bd-1048)\n")
+	defer func() { 
+		fmt.Fprintf(os.Stderr, "Debug: handleConnection closing (bd-1048)\n")
+		_ = conn.Close() 
+	}()
 
 	// Recover from panics to prevent daemon crash (bd-1048)
 	defer func() {
@@ -192,15 +196,19 @@ func (s *Server) handleConnection(conn net.Conn) {
 	writer := bufio.NewWriter(conn)
 
 	for {
+		fmt.Fprintf(os.Stderr, "Debug: waiting for request (bd-1048)\n")
 		// Set read deadline for the next request
 		if err := conn.SetReadDeadline(time.Now().Add(s.requestTimeout)); err != nil {
+			fmt.Fprintf(os.Stderr, "Debug: SetReadDeadline error: %v (bd-1048)\n", err)
 			return
 		}
 
 		line, err := reader.ReadBytes('\n')
 		if err != nil {
+			fmt.Fprintf(os.Stderr, "Debug: ReadBytes error: %v (bd-1048)\n", err)
 			return
 		}
+		fmt.Fprintf(os.Stderr, "Debug: received request line (bd-1048)\n")
 
 		var req Request
 		if err := json.Unmarshal(line, &req); err != nil {
@@ -211,14 +219,18 @@ func (s *Server) handleConnection(conn net.Conn) {
 			s.writeResponse(writer, resp)
 			continue
 		}
+		fmt.Fprintf(os.Stderr, "Debug: parsed request operation: %s (bd-1048)\n", req.Operation)
 
 		// Set write deadline for the response
 		if err := conn.SetWriteDeadline(time.Now().Add(s.requestTimeout)); err != nil {
+			fmt.Fprintf(os.Stderr, "Debug: SetWriteDeadline error: %v (bd-1048)\n", err)
 			return
 		}
 
 		resp := s.handleRequest(&req)
+		fmt.Fprintf(os.Stderr, "Debug: handleRequest returned, writing response (bd-1048)\n")
 		s.writeResponse(writer, resp)
+		fmt.Fprintf(os.Stderr, "Debug: response written (bd-1048)\n")
 	}
 }
 

internal/rpc/server_routing_validation_diagnostics.go

@@ -103,6 +103,8 @@ func (s *Server) validateDatabaseBinding(req *Request) error {
 }
 
 func (s *Server) handleRequest(req *Request) Response {
+	fmt.Fprintf(os.Stderr, "Debug: handleRequest called for operation: %s (bd-1048)\n", req.Operation)
+	
 	// Track request timing
 	start := time.Now()
 
@@ -110,6 +112,7 @@ func (s *Server) handleRequest(req *Request) Response {
 	defer func() {
 		latency := time.Since(start)
 		s.metrics.RecordRequest(req.Operation, latency)
+		fmt.Fprintf(os.Stderr, "Debug: handleRequest completed for operation: %s in %v (bd-1048)\n", req.Operation, latency)
 	}()
 
 	// Validate database binding (skip for health/metrics to allow diagnostics)