Update main.py

main.py

@@ -758,197 +758,216 @@ def create_project():
         return jsonify({'error': f"An error occurred: {e}"}), 500
 
 
-# --------------------------------------------------------
 @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] ▶️  Begin process  • project={project_id}")
-
-    # ───────────────────────────────────────────────────────────
-    # 1. AUTH
-    # ───────────────────────────────────────────────────────────
-    auth_t0 = 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] ❌  Unauthorized  • project={project_id}")
+        logger.error(f"[PROJECT APPROVAL] ERROR: Unauthorized access attempt for project: {project_id}")
         return jsonify({'error': 'Unauthorized'}), 401
-    auth_time = time.time() - auth_t0
-    logger.info(f"[TIMING] auth={auth_time:.3f}s  • uid={uid}")
+    auth_time = time.time() - auth_start
+    logger.info(f"[PROJECT APPROVAL] Authorization completed in {auth_time:.3f}s for user: {uid}")
 
-    # ───────────────────────────────────────────────────────────
-    # 2. USER / CREDIT CHECK
-    # ───────────────────────────────────────────────────────────
-    uc_t0 = time.time()
+    # User data fetch timing
+    user_fetch_start = time.time()
     user_ref = db_ref.child(f'users/{uid}')
     user_data = user_ref.get()
-    credits = user_data.get('credits', 0) if user_data else 0
-    if credits < 5:
-        logger.error(f"[PROJECT APPROVAL] ❌  Insufficient credits  • uid={uid}  credits={credits}")
+    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
-    uc_time = time.time() - uc_t0
-    logger.info(f"[TIMING] user_fetch={uc_time:.3f}s  • credits={credits}")
+    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)}")
 
-    # ───────────────────────────────────────────────────────────
-    # 3. PROJECT FETCH
-    # ───────────────────────────────────────────────────────────
-    pf_t0 = time.time()
+    # 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] ❌  Not found / access denied  • project={project_id}  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
-    pf_time = time.time() - pf_t0
-    logger.info(f"[TIMING] project_fetch={pf_time:.3f}s  • title='{project_data.get('projectTitle','?')}'")
-
-    # ───────────────────────────────────────────────────────────
-    # 4. DOUBLE-APPROVAL GUARD
-    # ───────────────────────────────────────────────────────────
-    if project_data.get('status') == 'ready':
-        logger.warning(f"[PROJECT APPROVAL] ⏹  Already approved  • project={project_id}")
-        return jsonify({'error': 'Project is already approved'}), 409
-
-    # ───────────────────────────────────────────────────────────
-    # 5. VALIDATE selectedOption
-    # ───────────────────────────────────────────────────────────
-    val_t0 = time.time()
+    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')
-    upcycling_options = project_data.get('upcyclingOptions', [])
-
-    if upcycling_options:                                   # choice required
-        if not selected_option:
-            logger.error(f"[PROJECT APPROVAL] ❌  Option required but missing • project={project_id}")
-            return jsonify({'error': 'You must choose an option before approving.'}), 400
-        if selected_option not in upcycling_options:
-            logger.error(f"[PROJECT APPROVAL] ❌  Invalid option  • chosen='{selected_option}'")
-            return jsonify({'error': 'Invalid option selected.'}), 400
-    else:                                                   # no options at all
-        selected_option = None
-    val_time = time.time() - val_t0
-    logger.info(f"[TIMING] validation={val_time:.3f}s  • selected='{selected_option}'  options={len(upcycling_options)}")
-
-    # ───────────────────────────────────────────────────────────
-    # 6. IMAGE DOWNLOAD / PROCESSING
-    # ───────────────────────────────────────────────────────────
-    img_dl_t0 = time.time()
-    resp = requests.get(project_data['userImageURL'])
-    pil_image = Image.open(io.BytesIO(resp.content)).convert('RGB')
-    img_dl_time = time.time() - img_dl_t0
-    logger.info(f"[TIMING] image_download+proc={img_dl_time:.3f}s  • bytes={len(resp.content)}")
-
-    # ───────────────────────────────────────────────────────────
-    # 7. PROMPT + AI GENERATION
-    # ───────────────────────────────────────────────────────────
-    prompt_t0 = time.time()
-    context_line = (
+    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
         else f"The user has approved the plan for '{project_data['projectTitle']}'."
     )
+
     detailed_prompt = f"""
     You are a DIY expert. The user wants to proceed with the project titled "{project_data['projectTitle']}".
-    {context_line}
+    {context}
     Provide a detailed guide. For each step, you MUST provide a simple, clear illustrative image.
-
+    Format your response EXACTLY like this:
     TOOLS AND MATERIALS:
     - Tool A
     - Material B
-
     STEPS(Maximum 5 steps):
     1. First step instructions.
     2. Second step instructions...
     """
-    chat = client.chats.create(
-        model=GENERATION_MODEL,
-        config=types.GenerateContentConfig(response_modalities=["Text", "Image"])
-    )
-    full_resp = chat.send_message([detailed_prompt, pil_image])
-    prompt_time = time.time() - prompt_t0
-    logger.info(f"[TIMING] ai_generation={prompt_time:.3f}s")
-
-    # ───────────────────────────────────────────────────────────
-    # 8. PARSE AI RESPONSE
-    # ───────────────────────────────────────────────────────────
-    parse_t0 = time.time()
-    gen_parts = full_resp.candidates[0].content.parts
-    combined_text, inline_images = "", []
-    for part in gen_parts:
-        if part.text:
-            combined_text += part.text + "\n"
-        if part.inline_data:
-            inline_images.append(Image.open(io.BytesIO(part.inline_data.data)).convert('RGB'))
-    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 = [ln.strip("- ").strip() for ln in tools_section.split('\n') if ln.strip()]
-    parsed_steps = parse_numbered_steps(steps_section)
-    if len(parsed_steps) != len(inline_images):
-        logger.error("[PROJECT APPROVAL] ❌  Steps/images mismatch")
-        return jsonify({'error': 'AI response mismatch: Steps and images do not match.'}), 500
-    parse_time = time.time() - parse_t0
-    logger.info(f"[TIMING] parse_response={parse_time:.3f}s  • steps={len(parsed_steps)}  imgs={len(inline_images)}")
-
-    # ───────────────────────────────────────────────────────────
-    # 9. STEP PROCESSING (uploads + TTS)
-    # ───────────────────────────────────────────────────────────
-    steps_t0 = time.time()
-    total_upload, total_tts, final_steps = 0.0, 0.0, []
-    for idx, step_info in enumerate(parsed_steps, 1):
-        # image upload
-        up_t0 = time.time()
-        buf = io.BytesIO()
-        inline_images[idx-1].save(buf, format='JPEG', optimize=True, quality=70)
-        img_path = f"users/{uid}/projects/{project_id}/steps/step_{idx}_image.jpg"
-        img_url = upload_to_storage(buf.getvalue(), img_path, 'image/jpeg')
-        total_upload += time.time() - up_t0
-
-        # TTS
-        tts_t0 = time.time()
-        narr_url = generate_tts_audio_and_upload(step_info['text'], uid, project_id, idx)
-        total_tts += time.time() - tts_t0
-
-        step_info.update({
-            "imageUrl": img_url,
-            "narrationUrl": narr_url,
-            "isDone": False,
-            "notes": ""
-        })
-        final_steps.append(step_info)
-    steps_time = time.time() - steps_t0
-    logger.info(f"[TIMING] steps_process={steps_time:.3f}s  • uploads={total_upload:.3f}s  tts={total_tts:.3f}s")
-
-    # ───────────────────────────────────────────────────────────
-    # 10. DATABASE UPDATE  (clear menu!)
-    # ───────────────────────────────────────────────────────────
-    db_t0 = time.time()
-    project_ref.update({
-        "status": "ready",
-        "selectedOption": selected_option or "",
-        "upcyclingOptions": [],            # => gone forever
-        "toolsList": tools_list,
-        "steps": final_steps
-    })
-    db_time = time.time() - db_t0
-    logger.info(f"[TIMING] db_update={db_time:.3f}s")
-
-    # credits deduction
-    credits_t0 = time.time()
-    user_ref.update({'credits': credits - 5})
-    credits_time = time.time() - credits_t0
-    logger.info(f"[TIMING] credits_update={credits_time:.3f}s  • new_credits={credits-5}")
-
-    # ───────────────────────────────────────────────────────────
-    # 11. FINAL FETCH & RETURN
-    # ───────────────────────────────────────────────────────────
-    final_fetch_t0 = time.time()
-    updated_project = project_ref.get()
-    updated_project["projectId"] = project_id
-    fetch_time = time.time() - final_fetch_t0
-
-    total_time = time.time() - start_time
-    logger.info(
-        f"[PROJECT APPROVAL] ✅  SUCCESS  • total={total_time:.3f}s  "
-        f"(fetch_final={fetch_time:.3f}s)"
-    )
-    return jsonify(updated_project), 200
+    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 = ""
+        inline_images = []
+        for part in gen_parts:
+            if part.text is not None:
+                combined_text += part.text + "\n"
+            if part.inline_data is not None:
+                img = Image.open(io.BytesIO(part.inline_data.data)).convert('RGB')
+                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,
+                "isDone": False,
+                "notes": ""
+            })
+            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,
+            "steps": final_steps,
+            "selectedOption": selected_option or "",
+            #update upcycling options to ensure only selected option persists
+            "upcyclingOptions": [selected_option] if selected_option else []
+        }
+        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")
+
+        # 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'])
 def list_projects():