Update main.py

main.py

@@ -1098,58 +1098,70 @@ def approve_project_plan(project_id):
         return jsonify({'error': 'Project not found or access denied'}), 404
 
     selected_option = request.json.get('selectedOption')
+    logger.info(f"[PROJECT APPROVAL] Selected option: {selected_option}")
 
+    # Image download and processing timing
+    image_download_start = time.time()
     try:
         response = requests.get(project_data['userImageURL'], timeout=30)
         response.raise_for_status()
+    except requests.RequestException as e:
+        logger.error(f"[PROJECT APPROVAL] ERROR: Image download failed: {e}")
+        return jsonify({'error': 'Failed to download project image'}), 500
+
+    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()
+    try:
         pil_image = Image.open(io.BytesIO(response.content)).convert('RGB')
     except Exception as e:
-        logger.error(f"[PROJECT APPROVAL] Image download/processing failed: {e}")
+        logger.error(f"[PROJECT APPROVAL] ERROR: Image processing failed: {e}")
         return jsonify({'error': 'Failed to process project image'}), 500
 
+    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']}'."
     )
 
-    # ------------------------------------------------------------------
-    # Expanded system prompt for 2026 – covers fashion, electronics, etc.
-    # ------------------------------------------------------------------
     detailed_prompt = f"""
-    You are Alfred, a world-class DIY and lifestyle expert. The user wants to proceed with the
-    project titled "{project_data['projectTitle']}" in the category "{project_data.get('category', 'DIY')}".
+    You are a DIY expert. The user wants to proceed with the project titled "{project_data['projectTitle']}".
     {context}
-
-    Provide a detailed, practical guide. For EVERY step you MUST provide a clear illustrative image
-    that shows the action being performed.
-
-    Category-specific guidance:
-    - Fashion & Clothing Repair: specify stitch type, thread colour, needle gauge, and fabric handling tips.
-    - Electronics & PCB Repair: include ESD safety warnings, soldering temperatures, and component reference numbers.
-    - Beauty & Personal Care DIY: note skin-type suitability and patch-test reminders.
-    - Furniture Restoration: mention wood grain direction, sanding grits, and cure times.
-    - All categories: prioritise safety, sustainability, and locally available materials.
-
+    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 or Material A
-    - Tool or Material B
-    STEPS (Maximum 5 steps):
+    - Tool A
+    - Material B
+    STEPS(Maximum 5 steps):
     1. First step instructions.
-    2. Second 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:
-        chat     = client.chats.create(
+        # 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() - start_time
+        ai_time = time.time() - ai_start
         logger.info(f"[PROJECT APPROVAL] AI generation completed in {ai_time:.3f}s")
 
-        gen_parts     = full_resp.candidates[0].content.parts
+        # Response parsing timing
+        parsing_start = time.time()
+        gen_parts = full_resp.candidates[0].content.parts
+
         combined_text = ""
         inline_images = []
         for part in gen_parts:
@@ -1160,57 +1172,140 @@ 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")
 
-        tools_match = re.search(
-            r"TOOLS AND MATERIALS:\s*(.*?)\s*(?=STEPS\s*[\(\:]|$)",
-            combined_text, re.DOTALL | re.IGNORECASE
-        )
-        steps_match = re.search(
-            r"STEPS\s*\([^)]*\):\s*(.*)|STEPS\s*:\s*(.*)",
-            combined_text, re.DOTALL | re.IGNORECASE
-        )
+        # Text extraction timing with robust error handling
+        extraction_start = time.time()
+
+        logger.info(f"[PROJECT APPROVAL] AI Response structure check:")
+        logger.info(f"[PROJECT APPROVAL] Full response length: {len(combined_text)}")
+        logger.info(f"[PROJECT APPROVAL] Contains 'TOOLS AND MATERIALS': {'TOOLS AND MATERIALS' in combined_text.upper()}")
+        logger.info(f"[PROJECT APPROVAL] Contains 'STEPS': {'STEPS' in combined_text.upper()}")
+        logger.info(f"[PROJECT APPROVAL] Response preview: {combined_text[:300]}...")
+
+        tools_match = re.search(r"TOOLS AND MATERIALS:\s*(.*?)\s*(?=STEPS\s*\(|STEPS\s*:|$)", combined_text, re.DOTALL | re.IGNORECASE)
+        steps_match = re.search(r"STEPS\s*\([^)]*\):\s*(.*)|STEPS\s*:\s*(.*)", combined_text, re.DOTALL | re.IGNORECASE)
+
+        if not tools_match:
+            logger.error(f"[PROJECT APPROVAL] ERROR: Could not find TOOLS AND MATERIALS section in AI response")
+            logger.error(f"[PROJECT APPROVAL] AI Response full text: {combined_text}")
+            return jsonify({'error': 'AI response format error: Could not parse tools section'}), 500
 
-        if not tools_match or not steps_match:
-            logger.error(f"[PROJECT APPROVAL] Parse error. Response: {combined_text[:500]}")
-            return jsonify({'error': 'AI response format error – could not parse sections'}), 500
+        if not steps_match:
+            logger.error(f"[PROJECT APPROVAL] ERROR: Could not find STEPS section in AI response")
+            logger.error(f"[PROJECT APPROVAL] AI Response full text: {combined_text}")
+            return jsonify({'error': 'AI response format error: Could not parse steps section'}), 500
 
         tools_section = tools_match.group(1).strip()
-        steps_section = (steps_match.group(1) or steps_match.group(2)).strip()
+        steps_section = (steps_match.group(1) or steps_match.group(2)).strip() if steps_match else ""
 
-        tools_list  = []
-        seen        = set()
-        for line in tools_section.split('\n'):
-            item = line.strip("- ").strip()
-            if item and item not in seen:
-                seen.add(item)
-                tools_list.append(item)
+        if not tools_section:
+            logger.error(f"[PROJECT APPROVAL] ERROR: Empty tools section found")
+            return jsonify({'error': 'AI response format error: Empty tools section'}), 500
+
+        if not steps_section:
+            logger.error(f"[PROJECT APPROVAL] ERROR: Empty steps section found")
+            return jsonify({'error': 'AI response format error: Empty steps section'}), 500
+
+        tools_list = [line.strip("- ").strip() for line in tools_section.split('\n') if line.strip() and not line.strip().startswith('-')]
+        dash_tools = [line.strip("- ").strip() for line in tools_section.split('\n') if line.strip().startswith('-')]
+        tools_list.extend(dash_tools)
+
+        # Remove duplicates while preserving order
+        seen = set()
+        tools_list = [x for x in tools_list if not (x in seen or seen.add(x))]
 
         parsed_steps = parse_numbered_steps(steps_section)
 
-        if not tools_list or not parsed_steps:
-            return jsonify({'error': 'AI response format error – empty tools or steps'}), 500
+        if not tools_list:
+            logger.error(f"[PROJECT APPROVAL] ERROR: No tools parsed from response")
+            logger.error(f"[PROJECT APPROVAL] Tools section was: {tools_section}")
+            return jsonify({'error': 'AI response format error: No tools found'}), 500
+
+        if not parsed_steps:
+            logger.error(f"[PROJECT APPROVAL] ERROR: No steps parsed from response")
+            logger.error(f"[PROJECT APPROVAL] Steps section was: {steps_section}")
+            return jsonify({'error': 'AI response format error: No steps found'}), 500
+
+        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):
-            min_len      = min(len(parsed_steps), len(inline_images))
-            parsed_steps = parsed_steps[:min_len]
-            inline_images = inline_images[:min_len]
-            if min_len == 0:
-                return jsonify({'error': 'AI response mismatch – no valid steps found'}), 500
-
-        final_steps = []
-        for i, step_info in enumerate(parsed_steps):
+            logger.error(f"[PROJECT APPROVAL] ERROR: AI response mismatch - Steps: {len(parsed_steps)}, Images: {len(inline_images)}")
+            min_length = min(len(parsed_steps), len(inline_images))
+            if min_length > 0:
+                logger.info(f"[PROJECT APPROVAL] Attempting to proceed with {min_length} steps/images")
+                parsed_steps = parsed_steps[:min_length]
+                inline_images = inline_images[:min_length]
+            else:
+                return jsonify({'error': 'AI response mismatch: No valid steps and images found.'}), 500
+
+        # ---------------------------------------------------------------
+        # Step processing – image upload and TTS run IN PARALLEL per step
+        # using ThreadPoolExecutor so Nano Banana 2's longer generation
+        # time doesn't stack on top of Deepgram latency.
+        # ---------------------------------------------------------------
+        import concurrent.futures
+
+        step_processing_start = time.time()
+        final_steps = [None] * len(parsed_steps)
+        total_upload_time = 0
+        total_tts_time = 0
+
+        def process_single_step(args):
+            """Runs image upload and TTS concurrently for one step, returns completed step_info."""
+            i, step_info, pil_img = args
+            result = dict(step_info)  # shallow copy so we don't mutate shared state
+            img_url       = ""
+            narration_url = ""
+
             try:
+                # Encode JPEG in this thread before spawning sub-futures
                 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')
-                narration_url = generate_tts_audio_and_upload(step_info['text'], uid, project_id, i + 1)
-                step_info.update({"imageUrl": img_url, "narrationUrl": narration_url, "isDone": False, "notes": ""})
+                pil_img.save(img_byte_arr, format='JPEG', optimize=True, quality=70)
+                img_bytes_val = img_byte_arr.getvalue()
+                img_path      = f"users/{uid}/projects/{project_id}/steps/step_{i+1}_image.jpg"
+
+                # Fire image upload and TTS simultaneously
+                with concurrent.futures.ThreadPoolExecutor(max_workers=2) as inner_pool:
+                    img_upload_start = time.time()
+                    tts_start        = time.time()
+
+                    img_future = inner_pool.submit(upload_to_storage, img_bytes_val, img_path, 'image/jpeg')
+                    tts_future = inner_pool.submit(generate_tts_audio_and_upload, result['text'], uid, project_id, i + 1)
+
+                    img_url       = img_future.result()
+                    img_upload_time = time.time() - img_upload_start
+                    logger.info(f"[PROJECT APPROVAL] Step {i+1} image upload completed in {img_upload_time:.3f}s")
+
+                    narration_url = tts_future.result()
+                    tts_time      = time.time() - tts_start
+                    logger.info(f"[PROJECT APPROVAL] Step {i+1} TTS generation completed in {tts_time:.3f}s")
+
             except Exception as e:
-                logger.error(f"[PROJECT APPROVAL] Error processing step {i+1}: {e}")
-                step_info.update({"imageUrl": "", "narrationUrl": "", "isDone": False, "notes": ""})
-            final_steps.append(step_info)
+                logger.error(f"[PROJECT APPROVAL] ERROR processing step {i+1}: {e}")
+
+            result.update({
+                "imageUrl":     img_url,
+                "narrationUrl": narration_url,
+                "isDone":       False,
+                "notes":        ""
+            })
+            return i, result
 
+        # Process all steps in parallel (up to 5 steps × 2 sub-tasks each)
+        step_args = [(i, parsed_steps[i], inline_images[i]) for i in range(len(parsed_steps))]
+
+        with concurrent.futures.ThreadPoolExecutor(max_workers=len(parsed_steps)) as outer_pool:
+            for i, completed_step in outer_pool.map(process_single_step, step_args):
+                final_steps[i] = completed_step
+
+        step_processing_time = time.time() - step_processing_start
+        logger.info(f"[PROJECT APPROVAL] All steps processing completed in {step_processing_time:.3f}s")
+
+        # Database update timing
+        db_update_start = time.time()
         update_data = {
             "status":         "ready",
             "toolsList":      tools_list,
@@ -1218,17 +1313,46 @@ def approve_project_plan(project_id):
             "selectedOption": selected_option or ""
         }
         project_ref.update(update_data)
-        user_ref.update({'credits': user_data.get('credits', 0) - 5})
+        logger.info(f"[PROJECT APPROVAL] Updating data in db: {len(update_data)} fields")
+        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 in {total_time:.3f}s")
+        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]   - 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 (Nano Banana 2): {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 (threaded): {step_processing_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:
-        logger.error(f"[PROJECT APPROVAL] Exception: {traceback.format_exc()}")
+        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}")
+        logger.error(f"[PROJECT APPROVAL] Full traceback: {traceback.format_exc()}")
         return jsonify({'error': f'Internal server error: {str(e)}'}), 500