diff --git a/internal/rpc/server_export_import_auto.go b/internal/rpc/server_export_import_auto.go index ad43ef38..cccf60bc 100644 --- a/internal/rpc/server_export_import_auto.go +++ b/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 diff --git a/internal/rpc/server_lifecycle_conn.go b/internal/rpc/server_lifecycle_conn.go index 18110316..5f1c61c8 100644 --- a/internal/rpc/server_lifecycle_conn.go +++ b/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") } } diff --git a/internal/rpc/server_routing_validation_diagnostics.go b/internal/rpc/server_routing_validation_diagnostics.go index 0ef192be..847eba0c 100644 --- a/internal/rpc/server_routing_validation_diagnostics.go +++ b/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)