diff --git a/cortex/context.py b/cortex/context.py index 17cd22a..75f9ede 100644 --- a/cortex/context.py +++ b/cortex/context.py @@ -24,6 +24,7 @@ from neomem_client import NeoMemClient INTAKE_API_URL = os.getenv("INTAKE_API_URL", "http://intake:7080") NEOMEM_API = os.getenv("NEOMEM_API", "http://neomem-api:8000") RELEVANCE_THRESHOLD = float(os.getenv("RELEVANCE_THRESHOLD", "0.4")) +VERBOSE_DEBUG = os.getenv("VERBOSE_DEBUG", "false").lower() == "true" # Tools available for future autonomy features TOOLS_AVAILABLE = ["RAG", "WEB", "WEATHER", "CODEBRAIN", "POKERBRAIN"] @@ -36,6 +37,31 @@ SESSION_STATE: Dict[str, Dict[str, Any]] = {} # Logger logger = logging.getLogger(__name__) +# Set logging level based on VERBOSE_DEBUG +if VERBOSE_DEBUG: + logger.setLevel(logging.DEBUG) + + # Console handler + console_handler = logging.StreamHandler() + console_handler.setFormatter(logging.Formatter( + '%(asctime)s [CONTEXT] %(levelname)s: %(message)s', + datefmt='%H:%M:%S' + )) + logger.addHandler(console_handler) + + # File handler - append to log file + try: + os.makedirs('/app/logs', exist_ok=True) + file_handler = logging.FileHandler('/app/logs/cortex_verbose_debug.log', mode='a') + file_handler.setFormatter(logging.Formatter( + '%(asctime)s [CONTEXT] %(levelname)s: %(message)s', + datefmt='%Y-%m-%d %H:%M:%S' + )) + logger.addHandler(file_handler) + logger.debug("VERBOSE_DEBUG mode enabled for context.py - logging to file") + except Exception as e: + logger.debug(f"VERBOSE_DEBUG mode enabled for context.py - file logging failed: {e}") + # ----------------------------- # Session initialization @@ -236,17 +262,30 @@ async def collect_context(session_id: str, user_prompt: str) -> Dict[str, Any]: if session_id not in SESSION_STATE: SESSION_STATE[session_id] = _init_session(session_id) logger.info(f"Initialized new session: {session_id}") + if VERBOSE_DEBUG: + logger.debug(f"[COLLECT_CONTEXT] New session state: {SESSION_STATE[session_id]}") state = SESSION_STATE[session_id] + if VERBOSE_DEBUG: + logger.debug(f"[COLLECT_CONTEXT] Session {session_id} - User prompt: {user_prompt[:100]}...") + # B. Calculate time delta now = datetime.now() time_delta_seconds = (now - state["last_timestamp"]).total_seconds() minutes_since_last_msg = round(time_delta_seconds / 60.0, 2) + if VERBOSE_DEBUG: + logger.debug(f"[COLLECT_CONTEXT] Time since last message: {minutes_since_last_msg:.2f} minutes") + # C. Gather Intake context (multilevel summaries) intake_data = await _get_intake_context(session_id) + if VERBOSE_DEBUG: + import json + logger.debug(f"[COLLECT_CONTEXT] Intake data retrieved:") + logger.debug(json.dumps(intake_data, indent=2, default=str)) + # D. Search NeoMem for relevant memories rag_results = await _search_neomem( query=user_prompt, @@ -254,6 +293,13 @@ async def collect_context(session_id: str, user_prompt: str) -> Dict[str, Any]: limit=5 ) + if VERBOSE_DEBUG: + logger.debug(f"[COLLECT_CONTEXT] NeoMem search returned {len(rag_results)} results") + for idx, result in enumerate(rag_results, 1): + score = result.get("score", 0) + data_preview = str(result.get("payload", {}).get("data", ""))[:100] + logger.debug(f" [{idx}] Score: {score:.3f} - {data_preview}...") + # E. Update session state state["last_user_message"] = user_prompt state["last_timestamp"] = now @@ -279,6 +325,13 @@ async def collect_context(session_id: str, user_prompt: str) -> Dict[str, Any]: f"{minutes_since_last_msg:.1f} minutes since last message" ) + if VERBOSE_DEBUG: + logger.debug(f"[COLLECT_CONTEXT] Final context state assembled:") + logger.debug(f" - Message count: {state['message_count']}") + logger.debug(f" - Mode: {state['mode']}, Mood: {state['mood']}") + logger.debug(f" - Active project: {state['active_project']}") + logger.debug(f" - Tools available: {TOOLS_AVAILABLE}") + return context_state diff --git a/cortex/persona/speak.py b/cortex/persona/speak.py index 9d4abe2..0d5c00a 100644 --- a/cortex/persona/speak.py +++ b/cortex/persona/speak.py @@ -1,10 +1,39 @@ # speak.py import os +import logging from llm.llm_router import call_llm # Module-level backend selection SPEAK_BACKEND = os.getenv("SPEAK_LLM", "PRIMARY").upper() SPEAK_TEMPERATURE = float(os.getenv("SPEAK_TEMPERATURE", "0.6")) +VERBOSE_DEBUG = os.getenv("VERBOSE_DEBUG", "false").lower() == "true" + +# Logger +logger = logging.getLogger(__name__) + +if VERBOSE_DEBUG: + logger.setLevel(logging.DEBUG) + + # Console handler + console_handler = logging.StreamHandler() + console_handler.setFormatter(logging.Formatter( + '%(asctime)s [SPEAK] %(levelname)s: %(message)s', + datefmt='%H:%M:%S' + )) + logger.addHandler(console_handler) + + # File handler + try: + os.makedirs('/app/logs', exist_ok=True) + file_handler = logging.FileHandler('/app/logs/cortex_verbose_debug.log', mode='a') + file_handler.setFormatter(logging.Formatter( + '%(asctime)s [SPEAK] %(levelname)s: %(message)s', + datefmt='%Y-%m-%d %H:%M:%S' + )) + logger.addHandler(file_handler) + logger.debug("VERBOSE_DEBUG mode enabled for speak.py - logging to file") + except Exception as e: + logger.debug(f"VERBOSE_DEBUG mode enabled for speak.py - file logging failed: {e}") # ============================================================ @@ -68,6 +97,15 @@ async def speak(final_answer: str) -> str: backend = SPEAK_BACKEND + if VERBOSE_DEBUG: + logger.debug(f"\n{'='*80}") + logger.debug("[SPEAK] Full prompt being sent to LLM:") + logger.debug(f"{'='*80}") + logger.debug(prompt) + logger.debug(f"{'='*80}") + logger.debug(f"Backend: {backend}, Temperature: {SPEAK_TEMPERATURE}") + logger.debug(f"{'='*80}\n") + try: lyra_output = await call_llm( prompt, @@ -75,12 +113,26 @@ async def speak(final_answer: str) -> str: temperature=SPEAK_TEMPERATURE, ) + if VERBOSE_DEBUG: + logger.debug(f"\n{'='*80}") + logger.debug("[SPEAK] LLM Response received:") + logger.debug(f"{'='*80}") + logger.debug(lyra_output) + logger.debug(f"{'='*80}\n") + if lyra_output: return lyra_output.strip() + if VERBOSE_DEBUG: + logger.debug("[SPEAK] Empty response, returning neutral answer") + return final_answer except Exception as e: # Hard fallback: return neutral answer instead of dying - print(f"[speak.py] Persona backend '{backend}' failed: {e}") + logger.error(f"[speak.py] Persona backend '{backend}' failed: {e}") + + if VERBOSE_DEBUG: + logger.debug("[SPEAK] Falling back to neutral answer due to error") + return final_answer diff --git a/cortex/reasoning/reasoning.py b/cortex/reasoning/reasoning.py index 7ffb8d5..6c87ed0 100644 --- a/cortex/reasoning/reasoning.py +++ b/cortex/reasoning/reasoning.py @@ -1,6 +1,7 @@ # reasoning.py import os import json +import logging from llm.llm_router import call_llm @@ -9,6 +10,34 @@ from llm.llm_router import call_llm # ============================================================ CORTEX_LLM = os.getenv("CORTEX_LLM", "PRIMARY").upper() GLOBAL_TEMP = float(os.getenv("LLM_TEMPERATURE", "0.7")) +VERBOSE_DEBUG = os.getenv("VERBOSE_DEBUG", "false").lower() == "true" + +# Logger +logger = logging.getLogger(__name__) + +if VERBOSE_DEBUG: + logger.setLevel(logging.DEBUG) + + # Console handler + console_handler = logging.StreamHandler() + console_handler.setFormatter(logging.Formatter( + '%(asctime)s [REASONING] %(levelname)s: %(message)s', + datefmt='%H:%M:%S' + )) + logger.addHandler(console_handler) + + # File handler + try: + os.makedirs('/app/logs', exist_ok=True) + file_handler = logging.FileHandler('/app/logs/cortex_verbose_debug.log', mode='a') + file_handler.setFormatter(logging.Formatter( + '%(asctime)s [REASONING] %(levelname)s: %(message)s', + datefmt='%Y-%m-%d %H:%M:%S' + )) + logger.addHandler(file_handler) + logger.debug("VERBOSE_DEBUG mode enabled for reasoning.py - logging to file") + except Exception as e: + logger.debug(f"VERBOSE_DEBUG mode enabled for reasoning.py - file logging failed: {e}") async def reason_check( @@ -147,10 +176,26 @@ async def reason_check( # -------------------------------------------------------- # Call the LLM using the module-specific backend # -------------------------------------------------------- + if VERBOSE_DEBUG: + logger.debug(f"\n{'='*80}") + logger.debug("[REASONING] Full prompt being sent to LLM:") + logger.debug(f"{'='*80}") + logger.debug(prompt) + logger.debug(f"{'='*80}") + logger.debug(f"Backend: {CORTEX_LLM}, Temperature: {GLOBAL_TEMP}") + logger.debug(f"{'='*80}\n") + draft = await call_llm( prompt, backend=CORTEX_LLM, temperature=GLOBAL_TEMP, ) + if VERBOSE_DEBUG: + logger.debug(f"\n{'='*80}") + logger.debug("[REASONING] LLM Response received:") + logger.debug(f"{'='*80}") + logger.debug(draft) + logger.debug(f"{'='*80}\n") + return draft diff --git a/cortex/reasoning/refine.py b/cortex/reasoning/refine.py index 7e57c4e..bbcc6a4 100644 --- a/cortex/reasoning/refine.py +++ b/cortex/reasoning/refine.py @@ -15,11 +15,36 @@ logger = logging.getLogger(__name__) REFINER_TEMPERATURE = float(os.getenv("REFINER_TEMPERATURE", "0.3")) REFINER_MAX_TOKENS = int(os.getenv("REFINER_MAX_TOKENS", "768")) REFINER_DEBUG = os.getenv("REFINER_DEBUG", "false").lower() == "true" +VERBOSE_DEBUG = os.getenv("VERBOSE_DEBUG", "false").lower() == "true" # These come from root .env REFINE_LLM = os.getenv("REFINE_LLM", "").upper() CORTEX_LLM = os.getenv("CORTEX_LLM", "PRIMARY").upper() +if VERBOSE_DEBUG: + logger.setLevel(logging.DEBUG) + + # Console handler + console_handler = logging.StreamHandler() + console_handler.setFormatter(logging.Formatter( + '%(asctime)s [REFINE] %(levelname)s: %(message)s', + datefmt='%H:%M:%S' + )) + logger.addHandler(console_handler) + + # File handler + try: + os.makedirs('/app/logs', exist_ok=True) + file_handler = logging.FileHandler('/app/logs/cortex_verbose_debug.log', mode='a') + file_handler.setFormatter(logging.Formatter( + '%(asctime)s [REFINE] %(levelname)s: %(message)s', + datefmt='%Y-%m-%d %H:%M:%S' + )) + logger.addHandler(file_handler) + logger.debug("VERBOSE_DEBUG mode enabled for refine.py - logging to file") + except Exception as e: + logger.debug(f"VERBOSE_DEBUG mode enabled for refine.py - file logging failed: {e}") + # =============================================== # Prompt builder @@ -103,6 +128,15 @@ async def refine_answer( # backend priority: REFINE_LLM → CORTEX_LLM → PRIMARY backend = REFINE_LLM or CORTEX_LLM or "PRIMARY" + if VERBOSE_DEBUG: + logger.debug(f"\n{'='*80}") + logger.debug("[REFINE] Full prompt being sent to LLM:") + logger.debug(f"{'='*80}") + logger.debug(prompt) + logger.debug(f"{'='*80}") + logger.debug(f"Backend: {backend}, Temperature: {REFINER_TEMPERATURE}") + logger.debug(f"{'='*80}\n") + try: refined = await call_llm( prompt, @@ -110,6 +144,13 @@ async def refine_answer( temperature=REFINER_TEMPERATURE, ) + if VERBOSE_DEBUG: + logger.debug(f"\n{'='*80}") + logger.debug("[REFINE] LLM Response received:") + logger.debug(f"{'='*80}") + logger.debug(refined) + logger.debug(f"{'='*80}\n") + return { "final_output": refined.strip() if refined else draft_output, "used_backend": backend, @@ -119,6 +160,9 @@ async def refine_answer( except Exception as e: logger.error(f"refine.py backend {backend} failed: {e}") + if VERBOSE_DEBUG: + logger.debug("[REFINE] Falling back to draft output due to error") + return { "final_output": draft_output, "used_backend": backend, diff --git a/cortex/reasoning/reflection.py b/cortex/reasoning/reflection.py index 4b1a0f5..df49315 100644 --- a/cortex/reasoning/reflection.py +++ b/cortex/reasoning/reflection.py @@ -2,8 +2,37 @@ import json import os import re +import logging from llm.llm_router import call_llm +# Logger +VERBOSE_DEBUG = os.getenv("VERBOSE_DEBUG", "false").lower() == "true" +logger = logging.getLogger(__name__) + +if VERBOSE_DEBUG: + logger.setLevel(logging.DEBUG) + + # Console handler + console_handler = logging.StreamHandler() + console_handler.setFormatter(logging.Formatter( + '%(asctime)s [REFLECTION] %(levelname)s: %(message)s', + datefmt='%H:%M:%S' + )) + logger.addHandler(console_handler) + + # File handler + try: + os.makedirs('/app/logs', exist_ok=True) + file_handler = logging.FileHandler('/app/logs/cortex_verbose_debug.log', mode='a') + file_handler.setFormatter(logging.Formatter( + '%(asctime)s [REFLECTION] %(levelname)s: %(message)s', + datefmt='%Y-%m-%d %H:%M:%S' + )) + logger.addHandler(file_handler) + logger.debug("VERBOSE_DEBUG mode enabled for reflection.py - logging to file") + except Exception as e: + logger.debug(f"VERBOSE_DEBUG mode enabled for reflection.py - file logging failed: {e}") + async def reflect_notes(intake_summary: str, identity_block: dict | None) -> dict: """ @@ -46,8 +75,23 @@ async def reflect_notes(intake_summary: str, identity_block: dict | None) -> dic # ----------------------------- # Call the selected LLM backend # ----------------------------- + if VERBOSE_DEBUG: + logger.debug(f"\n{'='*80}") + logger.debug("[REFLECTION] Full prompt being sent to LLM:") + logger.debug(f"{'='*80}") + logger.debug(prompt) + logger.debug(f"{'='*80}") + logger.debug(f"Backend: {backend}") + logger.debug(f"{'='*80}\n") + raw = await call_llm(prompt, backend=backend) - print("[Reflection-Raw]:", raw) + + if VERBOSE_DEBUG: + logger.debug(f"\n{'='*80}") + logger.debug("[REFLECTION] LLM Response received:") + logger.debug(f"{'='*80}") + logger.debug(raw) + logger.debug(f"{'='*80}\n") # ----------------------------- # Try direct JSON @@ -55,9 +99,12 @@ async def reflect_notes(intake_summary: str, identity_block: dict | None) -> dic try: parsed = json.loads(raw.strip()) if isinstance(parsed, dict) and "notes" in parsed: + if VERBOSE_DEBUG: + logger.debug(f"[REFLECTION] Parsed {len(parsed['notes'])} notes from JSON") return parsed except: - pass + if VERBOSE_DEBUG: + logger.debug("[REFLECTION] Direct JSON parsing failed, trying extraction...") # ----------------------------- # Try JSON extraction diff --git a/cortex/router.py b/cortex/router.py index 37bb2a7..4bce5cf 100644 --- a/cortex/router.py +++ b/cortex/router.py @@ -1,5 +1,7 @@ # router.py +import os +import logging from fastapi import APIRouter, HTTPException from pydantic import BaseModel @@ -11,6 +13,36 @@ from persona.identity import load_identity from ingest.intake_client import IntakeClient from context import collect_context, update_last_assistant_message +# ----------------------------- +# Debug configuration +# ----------------------------- +VERBOSE_DEBUG = os.getenv("VERBOSE_DEBUG", "false").lower() == "true" +logger = logging.getLogger(__name__) + +if VERBOSE_DEBUG: + logger.setLevel(logging.DEBUG) + + # Console handler + console_handler = logging.StreamHandler() + console_handler.setFormatter(logging.Formatter( + '%(asctime)s [ROUTER] %(levelname)s: %(message)s', + datefmt='%H:%M:%S' + )) + logger.addHandler(console_handler) + + # File handler + try: + os.makedirs('/app/logs', exist_ok=True) + file_handler = logging.FileHandler('/app/logs/cortex_verbose_debug.log', mode='a') + file_handler.setFormatter(logging.Formatter( + '%(asctime)s [ROUTER] %(levelname)s: %(message)s', + datefmt='%Y-%m-%d %H:%M:%S' + )) + logger.addHandler(file_handler) + logger.debug("VERBOSE_DEBUG mode enabled for router.py - logging to file") + except Exception as e: + logger.debug(f"VERBOSE_DEBUG mode enabled for router.py - file logging failed: {e}") + # ----------------------------- # Router (NOT FastAPI app) # ----------------------------- @@ -35,12 +67,30 @@ class ReasonRequest(BaseModel): @cortex_router.post("/reason") async def run_reason(req: ReasonRequest): + if VERBOSE_DEBUG: + logger.debug(f"\n{'='*80}") + logger.debug(f"[PIPELINE START] Session: {req.session_id}") + logger.debug(f"[PIPELINE START] User prompt: {req.user_prompt[:200]}...") + logger.debug(f"{'='*80}\n") + # 0. Collect unified context from all sources + if VERBOSE_DEBUG: + logger.debug("[STAGE 0] Collecting unified context...") + context_state = await collect_context(req.session_id, req.user_prompt) + if VERBOSE_DEBUG: + logger.debug(f"[STAGE 0] Context collected - {len(context_state.get('rag', []))} RAG results") + # 0.5. Load identity block + if VERBOSE_DEBUG: + logger.debug("[STAGE 0.5] Loading identity block...") + identity_block = load_identity(req.session_id) + if VERBOSE_DEBUG: + logger.debug(f"[STAGE 0.5] Identity loaded: {identity_block.get('name', 'Unknown')}") + # 1. Extract Intake summary for reflection # Use L20 (Session Overview) as primary summary for reflection intake_summary = "(no context available)" @@ -51,14 +101,30 @@ async def run_reason(req: ReasonRequest): elif isinstance(l20_summary, str): intake_summary = l20_summary + if VERBOSE_DEBUG: + logger.debug(f"[STAGE 1] Intake summary extracted (L20): {intake_summary[:150]}...") + # 2. Reflection + if VERBOSE_DEBUG: + logger.debug("[STAGE 2] Running reflection...") + try: reflection = await reflect_notes(intake_summary, identity_block=identity_block) reflection_notes = reflection.get("notes", []) - except Exception: + + if VERBOSE_DEBUG: + logger.debug(f"[STAGE 2] Reflection complete - {len(reflection_notes)} notes generated") + for idx, note in enumerate(reflection_notes, 1): + logger.debug(f" Note {idx}: {note}") + except Exception as e: reflection_notes = [] + if VERBOSE_DEBUG: + logger.debug(f"[STAGE 2] Reflection failed: {e}") # 3. First-pass reasoning draft + if VERBOSE_DEBUG: + logger.debug("[STAGE 3] Running reasoning (draft)...") + draft = await reason_check( req.user_prompt, identity_block=identity_block, @@ -67,7 +133,14 @@ async def run_reason(req: ReasonRequest): context=context_state ) + if VERBOSE_DEBUG: + logger.debug(f"[STAGE 3] Draft answer ({len(draft)} chars):") + logger.debug(f"--- DRAFT START ---\n{draft}\n--- DRAFT END ---") + # 4. Refinement + if VERBOSE_DEBUG: + logger.debug("[STAGE 4] Running refinement...") + result = await refine_answer( draft_output=draft, reflection_notes=reflection_notes, @@ -76,12 +149,32 @@ async def run_reason(req: ReasonRequest): ) final_neutral = result["final_output"] + if VERBOSE_DEBUG: + logger.debug(f"[STAGE 4] Refined answer ({len(final_neutral)} chars):") + logger.debug(f"--- REFINED START ---\n{final_neutral}\n--- REFINED END ---") + # 5. Persona layer + if VERBOSE_DEBUG: + logger.debug("[STAGE 5] Applying persona layer...") + persona_answer = await speak(final_neutral) + if VERBOSE_DEBUG: + logger.debug(f"[STAGE 5] Persona answer ({len(persona_answer)} chars):") + logger.debug(f"--- PERSONA START ---\n{persona_answer}\n--- PERSONA END ---") + # 6. Update session state with assistant's response + if VERBOSE_DEBUG: + logger.debug("[STAGE 6] Updating session state...") + update_last_assistant_message(req.session_id, persona_answer) + if VERBOSE_DEBUG: + logger.debug(f"\n{'='*80}") + logger.debug(f"[PIPELINE COMPLETE] Session: {req.session_id}") + logger.debug(f"[PIPELINE COMPLETE] Final answer length: {len(persona_answer)} chars") + logger.debug(f"{'='*80}\n") + # 7. Return full bundle return { "draft": draft,