Update main.py

main.py

@@ -619,7 +619,7 @@ def create_project():
         }
         db_ref.child(f'projects/{project_id}').set(project_data)
 
-        user_ref.update({'credits': user_data.get('credits', 1) - 1})
+        user_ref.update({'credits': user_data.get('credits', 0) - 1})
         return jsonify(project_data), 201
 
     except Exception as e:
@@ -629,19 +629,54 @@ def create_project():
 
 @app.route('/api/projects/<string:project_id>/approve', methods=['PUT'])
 def approve_project_plan(project_id):
+    start_time = time.time()
+    logger.info(f"[PROJECT APPROVAL] Starting approval process for project: {project_id}")
+    
+    # Authorization timing
+    auth_start = time.time()
     uid = verify_token(request.headers.get('Authorization'))
     if not uid:
+        logger.error(f"[PROJECT APPROVAL] ERROR: Unauthorized access attempt for project: {project_id}")
         return jsonify({'error': 'Unauthorized'}), 401
+    auth_time = time.time() - auth_start
+    logger.info(f"[PROJECT APPROVAL] Authorization completed in {auth_time:.3f}s for user: {uid}")
+
+    # User data fetch timing
+    user_fetch_start = time.time()
+    user_ref = db_ref.child(f'users/{uid}')
+    user_data = user_ref.get()
+    if not user_data or user_data.get('credits', 0) < 5:
+        logger.error(f"[PROJECT APPROVAL] ERROR: Insufficient credits for user: {uid}, credits: {user_data.get('credits', 0) if user_data else 0}")
+        return jsonify({'error': 'Insufficient credits'}), 402
+    user_fetch_time = time.time() - user_fetch_start
+    logger.info(f"[PROJECT APPROVAL] User data fetch completed in {user_fetch_time:.3f}s, credits: {user_data.get('credits', 0)}")
 
+    # Project data fetch timing
+    project_fetch_start = time.time()
     project_ref = db_ref.child(f'projects/{project_id}')
     project_data = project_ref.get()
     if not project_data or project_data.get('uid') != uid:
+        logger.error(f"[PROJECT APPROVAL] ERROR: Project not found or access denied - project_id: {project_id}, uid: {uid}")
         return jsonify({'error': 'Project not found or access denied'}), 404
+    project_fetch_time = time.time() - project_fetch_start
+    logger.info(f"[PROJECT APPROVAL] Project data fetch completed in {project_fetch_time:.3f}s for project: {project_data.get('projectTitle', 'Unknown')}")
 
+    # Image download and processing timing
     selected_option = request.json.get('selectedOption')
+    logger.info(f"[PROJECT APPROVAL] Selected option: {selected_option}")
+    
+    image_download_start = time.time()
     response = requests.get(project_data['userImageURL'])
+    image_download_time = time.time() - image_download_start
+    logger.info(f"[PROJECT APPROVAL] Image download completed in {image_download_time:.3f}s, size: {len(response.content)} bytes")
+    
+    image_processing_start = time.time()
     pil_image = Image.open(io.BytesIO(response.content)).convert('RGB')
+    image_processing_time = time.time() - image_processing_start
+    logger.info(f"[PROJECT APPROVAL] Image processing completed in {image_processing_time:.3f}s")
 
+    # Context preparation timing
+    context_start = time.time()
     context = (
         f"The user chose the upcycling project: '{selected_option}'."
         if selected_option
@@ -662,13 +697,24 @@ def approve_project_plan(project_id):
     1. First step instructions.
     2. Second step instructions...
     """
+    context_time = time.time() - context_start
+    logger.info(f"[PROJECT APPROVAL] Context preparation completed in {context_time:.3f}s")
 
     try:
+        # AI generation timing
+        ai_start = time.time()
+        logger.info(f"[PROJECT APPROVAL] Starting AI generation with model: {GENERATION_MODEL}")
+        
         chat = client.chats.create(
             model=GENERATION_MODEL,
             config=types.GenerateContentConfig(response_modalities=["Text", "Image"])
         )
         full_resp = chat.send_message([detailed_prompt, pil_image])
+        ai_time = time.time() - ai_start
+        logger.info(f"[PROJECT APPROVAL] AI generation completed in {ai_time:.3f}s")
+        
+        # Response parsing timing
+        parsing_start = time.time()
         gen_parts = full_resp.candidates[0].content.parts
 
         combined_text = ""
@@ -681,24 +727,49 @@ def approve_project_plan(project_id):
                 inline_images.append(img)
 
         combined_text = combined_text.strip()
+        parsing_time = time.time() - parsing_start
+        logger.info(f"[PROJECT APPROVAL] Response parsing completed in {parsing_time:.3f}s, found {len(inline_images)} images")
 
+        # Text extraction timing
+        extraction_start = time.time()
         tools_section = re.search(r"TOOLS AND MATERIALS:\s*(.*?)\s*STEPS:", combined_text, re.DOTALL).group(1).strip()
         steps_section = re.search(r"STEPS:\s*(.*)", combined_text, re.DOTALL).group(1).strip()
 
         tools_list = [line.strip("- ").strip() for line in tools_section.split('\n') if line.strip()]
         parsed_steps = parse_numbered_steps(steps_section)
+        extraction_time = time.time() - extraction_start
+        logger.info(f"[PROJECT APPROVAL] Text extraction completed in {extraction_time:.3f}s, tools: {len(tools_list)}, steps: {len(parsed_steps)}")
 
         if len(parsed_steps) != len(inline_images):
+            logger.error(f"[PROJECT APPROVAL] ERROR: AI response mismatch - Steps: {len(parsed_steps)}, Images: {len(inline_images)}")
             return jsonify({'error': 'AI response mismatch: Steps and images do not match.'}), 500
 
+        # Step processing timing
+        step_processing_start = time.time()
         final_steps = []
+        total_upload_time = 0
+        total_tts_time = 0
+        
         for i, step_info in enumerate(parsed_steps):
+            logger.info(f"[PROJECT APPROVAL] Processing step {i+1}/{len(parsed_steps)}")
+            
+            # Image upload timing
+            image_upload_start = time.time()
             img_byte_arr = io.BytesIO()
             inline_images[i].save(img_byte_arr, format='JPEG', optimize=True, quality=70)
             img_path = f"users/{uid}/projects/{project_id}/steps/step_{i+1}_image.jpg"
             img_url = upload_to_storage(img_byte_arr.getvalue(), img_path, 'image/jpeg')
+            image_upload_time = time.time() - image_upload_start
+            total_upload_time += image_upload_time
+            logger.info(f"[PROJECT APPROVAL] Step {i+1} image upload completed in {image_upload_time:.3f}s")
 
+            # TTS generation timing
+            tts_start = time.time()
             narration_url = generate_tts_audio_and_upload(step_info['text'], uid, project_id, i + 1)
+            tts_time = time.time() - tts_start
+            total_tts_time += tts_time
+            logger.info(f"[PROJECT APPROVAL] Step {i+1} TTS generation completed in {tts_time:.3f}s")
+            
             step_info.update({
                 "imageUrl": img_url,
                 "narrationUrl": narration_url,
@@ -707,6 +778,12 @@ def approve_project_plan(project_id):
             })
             final_steps.append(step_info)
 
+        step_processing_time = time.time() - step_processing_start
+        logger.info(f"[PROJECT APPROVAL] All steps processing completed in {step_processing_time:.3f}s")
+        logger.info(f"[PROJECT APPROVAL] Total upload time: {total_upload_time:.3f}s, Total TTS time: {total_tts_time:.3f}s")
+
+        # Database update timing
+        db_update_start = time.time()
         update_data = {
             "status": "ready",
             "toolsList": tools_list,
@@ -714,14 +791,51 @@ def approve_project_plan(project_id):
             "selectedOption": selected_option or ""
         }
         project_ref.update(update_data)
+        db_update_time = time.time() - db_update_start
+        logger.info(f"[PROJECT APPROVAL] Database update completed in {db_update_time:.3f}s")
 
-        # ✅ Fetch and return the full updated project
+        # Final project fetch timing
+        final_fetch_start = time.time()
         updated_project = project_ref.get()
         updated_project["projectId"] = project_id
-
+        final_fetch_time = time.time() - final_fetch_start
+        logger.info(f"[PROJECT APPROVAL] Final project fetch completed in {final_fetch_time:.3f}s")
+
+        # Credits deduction timing
+        credits_update_start = time.time()
+        user_ref.update({'credits': user_data.get('credits', 0) - 5})
+        credits_update_time = time.time() - credits_update_start
+        logger.info(f"[PROJECT APPROVAL] Credits update completed in {credits_update_time:.3f}s")
+
+        # Total time calculation
+        total_time = time.time() - start_time
+        logger.info(f"[PROJECT APPROVAL] SUCCESS: Project approval completed in {total_time:.3f}s")
+        logger.info(f"[PROJECT APPROVAL] TIMING BREAKDOWN:")
+        logger.info(f"[PROJECT APPROVAL]   - Authorization: {auth_time:.3f}s")
+        logger.info(f"[PROJECT APPROVAL]   - User fetch: {user_fetch_time:.3f}s")
+        logger.info(f"[PROJECT APPROVAL]   - Project fetch: {project_fetch_time:.3f}s")
+        logger.info(f"[PROJECT APPROVAL]   - Image download: {image_download_time:.3f}s")
+        logger.info(f"[PROJECT APPROVAL]   - Image processing: {image_processing_time:.3f}s")
+        logger.info(f"[PROJECT APPROVAL]   - Context prep: {context_time:.3f}s")
+        logger.info(f"[PROJECT APPROVAL]   - AI generation: {ai_time:.3f}s")
+        logger.info(f"[PROJECT APPROVAL]   - Response parsing: {parsing_time:.3f}s")
+        logger.info(f"[PROJECT APPROVAL]   - Text extraction: {extraction_time:.3f}s")
+        logger.info(f"[PROJECT APPROVAL]   - Step processing: {step_processing_time:.3f}s")
+        logger.info(f"[PROJECT APPROVAL]     - Total uploads: {total_upload_time:.3f}s")
+        logger.info(f"[PROJECT APPROVAL]     - Total TTS: {total_tts_time:.3f}s")
+        logger.info(f"[PROJECT APPROVAL]   - DB update: {db_update_time:.3f}s")
+        logger.info(f"[PROJECT APPROVAL]   - Final fetch: {final_fetch_time:.3f}s")
+        logger.info(f"[PROJECT APPROVAL]   - Credits update: {credits_update_time:.3f}s")
+        
         return jsonify(updated_project)
 
     except Exception as e:
+        total_time = time.time() - start_time
+        logger.error(f"[PROJECT APPROVAL] ERROR: Exception occurred after {total_time:.3f}s: {e}")
+        logger.error(f"[PROJECT APPROVAL] Error type: {type(e).__name__}")
+        logger.error(f"[PROJECT APPROVAL] Project ID: {project_id}, User ID: {uid}")
+        import traceback
+        logger.error(f"[PROJECT APPROVAL] Full traceback: {traceback.format_exc()}")
         return jsonify({'error': str(e)}), 500
 
 @app.route('/api/projects', methods=['GET'])