diff --git a/src/knowledge_base/slack/bot.py b/src/knowledge_base/slack/bot.py index a8e5ab2..5f674ce 100644 --- a/src/knowledge_base/slack/bot.py +++ b/src/knowledge_base/slack/bot.py @@ -569,6 +569,8 @@ async def async_call(func, *args, **kwargs): await async_call(say, "Please ask a question!", thread_ts=thread_ts) return + logger.info(f"Processing question: '{text[:80]}'") + # Get user info try: user_info = await async_call(client.users_info, user=user_id) @@ -577,13 +579,30 @@ async def async_call(func, *args, **kwargs): username = user_id # Send "thinking" message - thinking_msg = await async_call(say, "Thinking...", thread_ts=thread_ts) + try: + thinking_msg = await async_call(say, "Thinking...", thread_ts=thread_ts) + logger.info(f"Posted 'Thinking...' message ts={thinking_msg.get('ts', 'unknown')}") + except Exception as e: + logger.error(f"Failed to post 'Thinking...' message: {e}", exc_info=True) + # Try direct chat.postMessage as fallback + try: + thinking_msg = await async_call( + client.chat_postMessage, + channel=channel, + thread_ts=thread_ts, + text="Thinking...", + ) + logger.info(f"Posted 'Thinking...' via fallback, ts={thinking_msg.get('ts', 'unknown')}") + except Exception as e2: + logger.error(f"Fallback 'Thinking...' also failed: {e2}", exc_info=True) + return # Get conversation history for this thread conversation_history = _get_conversation_history(thread_ts) # Search for relevant chunks chunks = await _search_chunks(text) + logger.info(f"Search returned {len(chunks)} chunks") # Record access for each chunk for chunk in chunks: @@ -595,6 +614,7 @@ async def async_call(func, *args, **kwargs): # Generate answer with conversation context answer = await _generate_answer(text, chunks, conversation_history) + logger.info(f"Generated answer: {len(answer)} chars") # Store this exchange in conversation history _add_to_conversation(thread_ts, "user", text) @@ -616,17 +636,23 @@ async def async_call(func, *args, **kwargs): # Truncate fallback text for Slack's message limit (40k chars) fallback_text = answer[:4000] if len(answer) > 4000 else answer + thinking_ts = thinking_msg.get("ts") + if not thinking_ts: + logger.error("No timestamp in thinking message response, cannot update") + return + # Update thinking message with answer try: response = await async_call( client.chat_update, channel=channel, - ts=thinking_msg["ts"], + ts=thinking_ts, text=fallback_text, blocks=blocks, ) + logger.info("Updated message with answer") except Exception as e: - logger.error(f"Failed to update message: {e}") + logger.error("Failed to update message", exc_info=True) # Fallback: post answer as a new message so the user still gets a response try: await async_call( @@ -636,8 +662,9 @@ async def async_call(func, *args, **kwargs): text=fallback_text, blocks=blocks, ) + logger.info("Posted answer as new message (fallback)") except Exception as e2: - logger.error(f"Failed to post fallback message: {e2}") + logger.error("Failed to post fallback message", exc_info=True) # Always add feedback buttons (even for "no results" responses) try: @@ -645,18 +672,19 @@ async def async_call(func, *args, **kwargs): client.chat_postMessage, channel=channel, thread_ts=thread_ts, - blocks=_create_feedback_buttons(thinking_msg["ts"]), + blocks=_create_feedback_buttons(thinking_ts), text="Was this helpful?", ) + logger.info("Posted feedback buttons") # Store chunk IDs for feedback (empty list if no results) chunk_ids = [c.chunk_id for c in chunks] if chunks else [] - pending_feedback[thinking_msg["ts"]] = chunk_ids + pending_feedback[thinking_ts] = chunk_ids - # Record bot response for behavioral tracking (Phase 10.5) + # Record bot response for behavioral tracking try: await record_bot_response( - response_ts=thinking_msg["ts"], + response_ts=thinking_ts, thread_ts=thread_ts, channel_id=channel, user_id=user_id, @@ -728,7 +756,7 @@ async def _handle_feedback_action(body: dict, client: WebClient) -> None: view=modal_view, ) - logger.info(f"Opened {feedback_type} feedback modal for user {user_id}") + logger.info(f"Opened {feedback_type} feedback modal") return # Modal submission handler will handle the rest except Exception as e: @@ -984,12 +1012,19 @@ def main() -> None: args = parser.parse_args() + # force=True is required because Settings() triggers logging.warning() + # during import, which implicitly calls basicConfig() with default + # level=WARNING. Without force=True, our explicit call is a no-op + # and all INFO-level logs are silently dropped. logging.basicConfig( level=logging.INFO, - format="%(asctime)s - %(name)s - %(levelname)s - %(message)s", + format="%(levelname)s:%(name)s:%(message)s", + force=True, ) logging.getLogger().addFilter(SecretRedactingFilter()) + logger.info("Slack bot starting (logging configured at INFO level)") + if args.http: run_http_mode(port=args.port) elif args.socket: