Update main.py

main.py

@@ -1087,72 +1087,206 @@ def calculate_cost(duration_seconds):
 @app.route('/api/projects/<project_id>/start-conversation', methods=['POST'])
 def start_conversation(project_id):
     """Start a conversational AI session for a project"""
-    t0 = time.time()
+    start_time = time.time()
+    logger.info(f"[CONVERSATION] Starting conversation process for project: {project_id}")
     
     try:
+        # Authorization timing
+        auth_start = time.time()
+        logger.info(f"[CONVERSATION] Starting authorization check for project: {project_id}")
         uid = verify_token(request.headers.get('Authorization'))
         if not uid:
+            logger.error(f"[CONVERSATION] ERROR: Unauthorized access attempt for project: {project_id}")
             return jsonify({'error': 'Unauthorized'}), 401
+        auth_time = time.time() - auth_start
+        logger.info(f"[CONVERSATION] Authorization completed in {auth_time:.3f}s for user: {uid}")
 
+        # User data fetch timing
+        user_fetch_start = time.time()
+        logger.info(f"[CONVERSATION] Fetching user data for uid: {uid}")
         user_ref = db_ref.child(f'users/{uid}')
         user = user_ref.get()
         if not user:
+            logger.error(f"[CONVERSATION] ERROR: User not found for uid: {uid}")
             return jsonify({'error': 'User not found'}), 404
+        user_fetch_time = time.time() - user_fetch_start
+        logger.info(f"[CONVERSATION] User data fetch completed in {user_fetch_time:.3f}s, credits: {user.get('credits', 0)}")
 
+        # Project data fetch timing
+        project_fetch_start = time.time()
+        logger.info(f"[CONVERSATION] Fetching project data for project_id: {project_id}")
         project = db_ref.child(f'projects/{project_id}').get()
-        if not project or project.get('uid') != uid:
+        if not project:
+            logger.error(f"[CONVERSATION] ERROR: Project not found for project_id: {project_id}")
             return jsonify({'error': 'Project not found'}), 404
+        if project.get('uid') != uid:
+            logger.error(f"[CONVERSATION] ERROR: Project access denied - project_id: {project_id}, project_uid: {project.get('uid')}, requesting_uid: {uid}")
+            return jsonify({'error': 'Project not found'}), 404
+        project_fetch_time = time.time() - project_fetch_start
+        logger.info(f"[CONVERSATION] Project data fetch completed in {project_fetch_time:.3f}s for project: {project.get('projectTitle', 'Unknown')}")
 
-        data = request.get_json()
-        initial_message = data.get('message', 'Hello, I need help with my DIY project.')
-
-        # Initialize conversational AI handler
-        ai_handler = ConversationalAIHandler()
+        # Request data parsing timing
+        data_parse_start = time.time()
+        logger.info(f"[CONVERSATION] Parsing request data")
+        try:
+            data = request.get_json()
+            if data is None:
+                logger.error(f"[CONVERSATION] ERROR: No JSON data received in request")
+                return jsonify({'error': 'No JSON data provided'}), 400
+            initial_message = data.get('message', 'Hello, I need help with my DIY project.')
+            logger.info(f"[CONVERSATION] Initial message: {initial_message[:100]}{'...' if len(initial_message) > 100 else ''}")
+        except Exception as e:
+            logger.error(f"[CONVERSATION] ERROR: Failed to parse request JSON: {str(e)}")
+            return jsonify({'error': 'Invalid JSON data'}), 400
+        data_parse_time = time.time() - data_parse_start
+        logger.info(f"[CONVERSATION] Request data parsing completed in {data_parse_time:.3f}s")
+
+        # AI Handler initialization timing
+        ai_init_start = time.time()
+        logger.info(f"[CONVERSATION] Initializing ConversationalAIHandler")
+        try:
+            ai_handler = ConversationalAIHandler()
+            logger.info(f"[CONVERSATION] ConversationalAIHandler initialized successfully")
+        except Exception as e:
+            logger.error(f"[CONVERSATION] ERROR: Failed to initialize ConversationalAIHandler: {str(e)}")
+            return jsonify({'error': 'Failed to initialize AI handler'}), 500
+        ai_init_time = time.time() - ai_init_start
+        logger.info(f"[CONVERSATION] AI handler initialization completed in {ai_init_time:.3f}s")
         
-        # Create or get existing agent
-        agent_id = ai_handler.create_or_get_agent(project_id, project)
+        # Agent creation/retrieval timing
+        agent_start = time.time()
+        logger.info(f"[CONVERSATION] Creating or getting agent for project: {project_id}")
+        try:
+            agent_id = ai_handler.create_or_get_agent(project_id, project)
+            logger.info(f"[CONVERSATION] Agent created/retrieved successfully: {agent_id}")
+        except Exception as e:
+            logger.error(f"[CONVERSATION] ERROR: Failed to create/get agent: {str(e)}")
+            return jsonify({'error': 'Failed to create AI agent'}), 500
+        agent_time = time.time() - agent_start
+        logger.info(f"[CONVERSATION] Agent creation/retrieval completed in {agent_time:.3f}s")
         
-        # Start conversation simulation
-        conversation_result = ai_handler.simulate_conversation(agent_id, initial_message)
+        # Conversation simulation timing
+        simulation_start = time.time()
+        logger.info(f"[CONVERSATION] Starting conversation simulation with agent: {agent_id}")
+        try:
+            conversation_result = ai_handler.simulate_conversation(agent_id, initial_message)
+            logger.info(f"[CONVERSATION] Conversation simulation completed successfully")
+            logger.info(f"[CONVERSATION] Simulation result type: {type(conversation_result)}")
+            if isinstance(conversation_result, dict):
+                logger.info(f"[CONVERSATION] Simulation result keys: {list(conversation_result.keys())}")
+        except Exception as e:
+            logger.error(f"[CONVERSATION] ERROR: Failed to simulate conversation: {str(e)}")
+            return jsonify({'error': 'Failed to simulate conversation'}), 500
+        simulation_time = time.time() - simulation_start
+        logger.info(f"[CONVERSATION] Conversation simulation completed in {simulation_time:.3f}s")
         
-        duration = time.time() - t0
-        cost = calculate_cost(duration)
-
-        # Check credits
-        if user.get('credits', 0) < cost:
+        # Duration and cost calculation timing
+        calc_start = time.time()
+        duration = time.time() - start_time
+        logger.info(f"[CONVERSATION] Total duration so far: {duration:.3f}s")
+        try:
+            cost = calculate_cost(duration)
+            logger.info(f"[CONVERSATION] Calculated cost: {cost} credits")
+        except Exception as e:
+            logger.error(f"[CONVERSATION] ERROR: Failed to calculate cost: {str(e)}")
+            return jsonify({'error': 'Failed to calculate cost'}), 500
+        calc_time = time.time() - calc_start
+        logger.info(f"[CONVERSATION] Cost calculation completed in {calc_time:.3f}s")
+
+        # Credit check timing
+        credit_check_start = time.time()
+        user_credits = user.get('credits', 0)
+        logger.info(f"[CONVERSATION] Checking credits - User has: {user_credits}, Cost: {cost}")
+        if user_credits < cost:
+            logger.error(f"[CONVERSATION] ERROR: Insufficient credits - User: {user_credits}, Needed: {cost}")
             return jsonify({'error': 'Insufficient credits', 'needed': cost}), 402
+        credit_check_time = time.time() - credit_check_start
+        logger.info(f"[CONVERSATION] Credit check completed in {credit_check_time:.3f}s")
 
-        # Deduct credits
-        new_credits = user['credits'] - cost
-        user_ref.update({'credits': new_credits})
-
-        # Log the conversation
-        conversation_id = f"{project_id}_{int(t0)}"
-        db_ref.child(f'conversations/{conversation_id}').set({
-            'project_id': project_id,
-            'uid': uid,
-            'agent_id': agent_id,
-            'initial_message': initial_message,
-            'result': conversation_result,
-            'duration_seconds': duration,
-            'credits_used': cost,
-            'created_at': int(t0)
-        })
-
-        logger.info(f"User {uid} started conversation for project {project_id}, "
-                   f"duration {duration:.1f}s, cost {cost} credits.")
+        # Credit deduction timing
+        deduction_start = time.time()
+        new_credits = user_credits - cost
+        logger.info(f"[CONVERSATION] Deducting {cost} credits, new balance: {new_credits}")
+        try:
+            user_ref.update({'credits': new_credits})
+            logger.info(f"[CONVERSATION] Credits updated successfully in database")
+        except Exception as e:
+            logger.error(f"[CONVERSATION] ERROR: Failed to update user credits: {str(e)}")
+            return jsonify({'error': 'Failed to update credits'}), 500
+        deduction_time = time.time() - deduction_start
+        logger.info(f"[CONVERSATION] Credit deduction completed in {deduction_time:.3f}s")
+
+        # Conversation logging timing
+        logging_start = time.time()
+        conversation_id = f"{project_id}_{int(start_time)}"
+        logger.info(f"[CONVERSATION] Logging conversation with ID: {conversation_id}")
+        try:
+            conversation_data = {
+                'project_id': project_id,
+                'uid': uid,
+                'agent_id': agent_id,
+                'initial_message': initial_message,
+                'result': conversation_result,
+                'duration_seconds': duration,
+                'credits_used': cost,
+                'created_at': int(start_time)
+            }
+            db_ref.child(f'conversations/{conversation_id}').set(conversation_data)
+            logger.info(f"[CONVERSATION] Conversation logged successfully to database")
+        except Exception as e:
+            logger.error(f"[CONVERSATION] ERROR: Failed to log conversation: {str(e)}")
+            return jsonify({'error': 'Failed to log conversation'}), 500
+        logging_time = time.time() - logging_start
+        logger.info(f"[CONVERSATION] Conversation logging completed in {logging_time:.3f}s")
+
+        # Response preparation timing
+        response_start = time.time()
+        total_duration = time.time() - start_time
+        logger.info(f"[CONVERSATION] Preparing response, total duration: {total_duration:.3f}s")
+        try:
+            response_data = {
+                'conversation_id': conversation_id,
+                'agent_id': agent_id,
+                'simulation_result': conversation_result,
+                'durationSeconds': round(total_duration, 1),
+                'creditsDeducted': cost,
+                'remainingCredits': new_credits
+            }
+            logger.info(f"[CONVERSATION] Response prepared successfully")
+        except Exception as e:
+            logger.error(f"[CONVERSATION] ERROR: Failed to prepare response: {str(e)}")
+            return jsonify({'error': 'Failed to prepare response'}), 500
+        response_time = time.time() - response_start
+        logger.info(f"[CONVERSATION] Response preparation completed in {response_time:.3f}s")
+
+        # Final success logging
+        logger.info(f"[CONVERSATION] SUCCESS: User {uid} started conversation for project {project_id}, "
+                   f"duration {total_duration:.1f}s, cost {cost} credits.")
+        
+        # Performance summary
+        logger.info(f"[CONVERSATION] PERFORMANCE BREAKDOWN:")
+        logger.info(f"[CONVERSATION] - Authorization: {auth_time:.3f}s")
+        logger.info(f"[CONVERSATION] - User fetch: {user_fetch_time:.3f}s")
+        logger.info(f"[CONVERSATION] - Project fetch: {project_fetch_time:.3f}s")
+        logger.info(f"[CONVERSATION] - Data parsing: {data_parse_time:.3f}s")
+        logger.info(f"[CONVERSATION] - AI init: {ai_init_time:.3f}s")
+        logger.info(f"[CONVERSATION] - Agent creation: {agent_time:.3f}s")
+        logger.info(f"[CONVERSATION] - Simulation: {simulation_time:.3f}s")
+        logger.info(f"[CONVERSATION] - Cost calc: {calc_time:.3f}s")
+        logger.info(f"[CONVERSATION] - Credit check: {credit_check_time:.3f}s")
+        logger.info(f"[CONVERSATION] - Credit deduction: {deduction_time:.3f}s")
+        logger.info(f"[CONVERSATION] - Conversation logging: {logging_time:.3f}s")
+        logger.info(f"[CONVERSATION] - Response prep: {response_time:.3f}s")
+        logger.info(f"[CONVERSATION] - TOTAL: {total_duration:.3f}s")
 
-        return jsonify({
-            'conversation_id': conversation_id,
-            'agent_id': agent_id,
-            'simulation_result': conversation_result,
-            'durationSeconds': round(duration, 1),
-            'creditsDeducted': cost,
-            'remainingCredits': new_credits
-        }), 200
+        return jsonify(response_data), 200
 
     except Exception as e:
-        logger.error(f"Error starting conversation: {str(e)}")
+        total_duration = time.time() - start_time
+        logger.error(f"[CONVERSATION] CRITICAL ERROR: Unhandled exception after {total_duration:.3f}s")
+        logger.error(f"[CONVERSATION] Exception type: {type(e).__name__}")
+        logger.error(f"[CONVERSATION] Exception message: {str(e)}")
+        logger.error(f"[CONVERSATION] Exception traceback:", exc_info=True)
         return jsonify({'error': 'Failed to start conversation'}), 500
 
 @app.route('/api/projects/<project_id>/continue-conversation', methods=['POST'])