Update main.py

main.py

@@ -758,67 +758,96 @@ 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] Starting approval process for project: {project_id}")
-    
-    # Authorization timing
-    auth_start = time.time()
+    logger.info(f"[PROJECT APPROVAL] ▶️  Begin process  • project={project_id}")
+
+    # ───────────────────────────────────────────────────────────
+    # 1. AUTH
+    # ───────────────────────────────────────────────────────────
+    auth_t0 = 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}")
+        logger.error(f"[PROJECT APPROVAL] ❌  Unauthorized  • 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}")
+    auth_time = time.time() - auth_t0
+    logger.info(f"[TIMING] auth={auth_time:.3f}s  • uid={uid}")
 
-    # User data fetch timing
-    user_fetch_start = time.time()
+    # ───────────────────────────────────────────────────────────
+    # 2. USER / CREDIT CHECK
+    # ───────────────────────────────────────────────────────────
+    uc_t0 = 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}")
+    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}")
         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)}")
+    uc_time = time.time() - uc_t0
+    logger.info(f"[TIMING] user_fetch={uc_time:.3f}s  • credits={credits}")
 
-    # Project data fetch timing
-    project_fetch_start = time.time()
+    # ───────────────────────────────────────────────────────────
+    # 3. PROJECT FETCH
+    # ───────────────────────────────────────────────────────────
+    pf_t0 = 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}")
+        logger.error(f"[PROJECT APPROVAL] ❌  Not found / access denied  • project={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
+    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()
     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 = (
+    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 = (
         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}
+    {context_line}
     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
@@ -828,146 +857,98 @@ 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 = ""
-        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 ""
-        }
-        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
+    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
 
 @app.route('/api/projects', methods=['GET'])
 def list_projects():