From b04e23934461ddae1becd59f41e8efdd32135066 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=EA=B9=80=EC=84=B1=EA=B2=BD?= Date: Wed, 12 Aug 2026 13:21:47 +0900 Subject: [PATCH] =?UTF-8?q?refactor:=20=ED=81=AC=EB=A1=A4=EB=A7=81/?= =?UTF-8?q?=EC=97=85=EB=A1=9C=EB=93=9C=20=EB=A1=9C=EA=B7=B8=EB=A5=BC=20?= =?UTF-8?q?=EC=9A=94=EC=B2=AD=EB=8B=B9=201=EC=A4=84=20=EC=9A=94=EC=95=BD?= =?UTF-8?q?=EC=9C=BC=EB=A1=9C=20=EC=B6=95=EC=86=8C?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - 단계별 진행 로그를 삭제하고 계측치를 SUCCESS 한 줄에 통합 - 실패 경로(error/warning/exception) 로그는 그대로 유지 - gpt_status 를 locals() 검사 대신 초기화 후 직접 참조 --- app/home/api/routers/v1/home.py | 103 +++++++++++++------------------- 1 file changed, 41 insertions(+), 62 deletions(-) diff --git a/app/home/api/routers/v1/home.py b/app/home/api/routers/v1/home.py index 950c1ee..42d9515 100644 --- a/app/home/api/routers/v1/home.py +++ b/app/home/api/routers/v1/home.py @@ -258,12 +258,22 @@ async def autocomplete_crawling( async def _crawling_logic(url: str, session: AsyncSession): request_start = time.perf_counter() - logger.info("[crawling] ========== START ==========") - logger.info(f"[crawling] URL: {url[:80]}...") + + # 요청당 1줄 요약 로그에 쓰이는 값들. 각 Step 이 실제로 실행될 때 채워진다. + customer_name = "" + region = "" + category = "" + industry = "" + owner_count = 0 + extra_count = 0 + filter_summary = "n/a" + gpt_status = "completed" + step2_elapsed = 0.0 + step3_elapsed = 0.0 + step4_elapsed = 0.0 # ========== Step 1: 네이버 지도 크롤링 ========== step1_start = time.perf_counter() - logger.info("[crawling] Step 1: 네이버 지도 크롤링 시작...") try: scraper = NvMapScraper(url) @@ -298,14 +308,11 @@ async def _crawling_logic(url: str, session: AsyncSession): ) step1_elapsed = (time.perf_counter() - step1_start) * 1000 - logger.info( - f"[crawling] Step 1 완료 - 업체사진 {len(scraper.owner_images or [])}개, " - f"보충사진 {len(scraper.extra_photo_urls or [])}개 ({step1_elapsed:.1f}ms)" - ) + owner_count = len(scraper.owner_images or []) + extra_count = len(scraper.extra_photo_urls or []) # ========== Step 2: 정보 가공 (industry 선행 계산) ========== step2_start = time.perf_counter() - logger.info("[crawling] Step 2: 정보 가공 시작...") processed_info = None marketing_analysis = None @@ -340,10 +347,6 @@ async def _crawling_logic(url: str, session: AsyncSession): ) step2_elapsed = (time.perf_counter() - step2_start) * 1000 - logger.info( - f"[crawling] Step 2 완료 - {customer_name}, {region}, " - f"category={category!r}, industry={industry!r} ({step2_elapsed:.1f}ms)" - ) # ========== Step 3: 이미지 마케팅 적합성 필터링 ========== # 업체 사진이 SUPPLEMENT_THRESHOLD(30장) 이상이면 보충이 불필요하므로 @@ -358,10 +361,7 @@ async def _crawling_logic(url: str, session: AsyncSession): # 수집 자체는 NvMapScraper.BIZ_MAX_PAGES가 상한이며 도달 시 scraper가 warning을 남긴다). scraper.image_link_list = list(owner_images) step3_elapsed = (time.perf_counter() - step3_start) * 1000 - logger.info( - f"[crawling] Step 3 SKIP - 업체 사진 {len(owner_images)}장 " - f"≥ {NvMapScraper.SUPPLEMENT_THRESHOLD}장 → 방문자 사진 필터링 생략, 업체 사진만 사용" - ) + filter_summary = f"skip(owner>={NvMapScraper.SUPPLEMENT_THRESHOLD})" else: try: extra_pass_flags = await filter_marketing_images( @@ -381,11 +381,7 @@ async def _crawling_logic(url: str, session: AsyncSession): ) passed_count = sum(extra_pass_flags) step3_elapsed = (time.perf_counter() - step3_start) * 1000 - logger.info( - f"[crawling] Step 3 완료 - 방문자 사진 {len(extra_photo_urls)}장 중 " - f"{passed_count}장 통과 → 최종 이미지 {len(scraper.image_link_list)}장 " - f"({step3_elapsed:.1f}ms)" - ) + filter_summary = f"{len(extra_photo_urls)}→{passed_count}" if not scraper.image_link_list: logger.warning( "[crawling] Step 3 - 필터링 후 사용 가능 이미지가 0장입니다." @@ -393,7 +389,6 @@ async def _crawling_logic(url: str, session: AsyncSession): # ========== Step 4: ChatGPT 마케팅 분석 ========== step4_start = time.perf_counter() - logger.info("[crawling] Step 4: ChatGPT 마케팅 분석 시작...") try: # Step 4-1: ChatGPT 서비스 초기화 및 입력 데이터 구성 @@ -435,9 +430,6 @@ async def _crawling_logic(url: str, session: AsyncSession): ) step4_elapsed = (time.perf_counter() - step4_start) * 1000 - logger.info( - f"[crawling] Step 4 완료 - 마케팅 분석 성공 ({step4_elapsed:.1f}ms)" - ) except ChatGPTResponseError as e: step4_elapsed = (time.perf_counter() - step4_start) * 1000 @@ -464,18 +456,17 @@ async def _crawling_logic(url: str, session: AsyncSession): # ========== 완료 ========== total_elapsed = (time.perf_counter() - request_start) * 1000 - logger.info("[crawling] ========== COMPLETE ==========") - logger.info(f"[crawling] 총 소요시간: {total_elapsed:.1f}ms") - logger.info(f"[crawling] - Step 1 (크롤링): {step1_elapsed:.1f}ms") - if scraper.base_info: - logger.info(f"[crawling] - Step 2 (정보가공): {step2_elapsed:.1f}ms") - if "step3_elapsed" in locals(): - logger.info(f"[crawling] - Step 3 (이미지 필터링): {step3_elapsed:.1f}ms") - if "step4_elapsed" in locals(): - logger.info(f"[crawling] - Step 4 (GPT 분석): {step4_elapsed:.1f}ms") + logger.info( + f"[crawling] SUCCESS - url: {url[:80]}, name: {customer_name!r}, " + f"region: {region!r}, category: {category!r}, industry: {industry!r}, " + f"owner: {owner_count}, extra: {extra_count}, filter: {filter_summary}, " + f"images: {len(scraper.image_link_list or [])}, gpt: {gpt_status}, " + f"timing(ms): s1={step1_elapsed:.1f} s2={step2_elapsed:.1f} " + f"s3={step3_elapsed:.1f} s4={step4_elapsed:.1f} total={total_elapsed:.1f}" + ) return { - "status": gpt_status if "gpt_status" in locals() else "completed", + "status": gpt_status, "image_list": scraper.image_link_list, "image_count": len(scraper.image_link_list) if scraper.image_link_list else 0, "processed_info": processed_info, @@ -780,11 +771,6 @@ async def upload_images_blob( task_id = await generate_task_id() existing_images = [] - logger.info( - f"[upload_images_blob] START - task_id: {task_id}, " - f"continuation: {is_continuation}, finalize: {finalize}" - ) - # ========== Stage 1: 입력 검증 (세션 없음, 파일 전체 메모리 적재 없음) ========== has_images_json = images_json is not None and images_json.strip() != "" has_files = files is not None and len(files) > 0 @@ -864,11 +850,6 @@ async def upload_images_blob( ) stage1_time = time.perf_counter() - logger.info( - f"[upload_images_blob] Stage 1 done - urls: {len(url_images)}, " - f"files: {len(valid_files_data)}, bytes: {actual_total_size}, " - f"elapsed: {(stage1_time - request_start) * 1000:.1f}ms" - ) # ========== Stage 2: Azure Blob 청크 업로드 (세션 없음) ========== # (원본명, 공개 URL, Azure 저장 파일명) @@ -998,15 +979,12 @@ async def upload_images_blob( ) stage2_time = time.perf_counter() - logger.info( - f"[upload_images_blob] Stage 2 done - blob uploads: " - f"{len(blob_upload_results)}, skipped: {len(skipped_files)}, " - f"elapsed: {(stage2_time - stage1_time) * 1000:.1f}ms" - ) # ========== Stage 3: DB 저장 (새 세션으로 빠르게 처리) ========== - logger.info("[upload_images_blob] Stage 3 starting - DB save...") all_images: list[Image] = [] + # 요약 로그용. 커밋이 끝난 뒤 실제 값으로 덮어쓴다. + stage3_time = stage2_time + added_count = 0 commit_started = False try: @@ -1078,11 +1056,7 @@ async def upload_images_blob( commit_started = True await session.commit() stage3_time = time.perf_counter() - logger.info( - f"[upload_images_blob] Stage 3 done - " - f"task total: {len(all_images)}, added: {len(new_images)}, " - f"elapsed: {(stage3_time - stage2_time) * 1000:.1f}ms" - ) + added_count = len(new_images) except asyncio.CancelledError as e: await compensate_after_cancellation(commit_started, e) @@ -1114,14 +1088,13 @@ async def upload_images_blob( saved_count = len(result_images) image_urls = [img.img_url for img in result_images] + tagging_summary = "deferred" if finalize: - logger.info(f"[image_tagging] START - task_id: {task_id}") await tagging_images(image_urls, industry=industry, clear_old_tags=True) - logger.info(f"[image_tagging] Done - task_id: {task_id}") # 마지막 분할 요청에서 누적된 전체 이미지의 적합성을 확인합니다. taged_image_list = await get_image_tags_by_task_id(task_id) - logger.info(f"태깅된 이미지: {len(taged_image_list)}개 - task_id: {task_id}") + tagging_summary = f"tagged={len(taged_image_list)}" if not taged_image_list: logger.error( f"[image_tagging] 영상 생성에 적합한 이미지가 없음 - task_id: {task_id}" @@ -1133,13 +1106,19 @@ async def upload_images_blob( "다른 이미지로 다시 업로드해주세요." ), ) - else: - logger.info(f"[image_tagging] DEFERRED - task_id: {task_id}") total_time = time.perf_counter() - request_start logger.info( f"[upload_images_blob] SUCCESS - task_id: {task_id}, " - f"total: {saved_count}, total_time: {total_time * 1000:.1f}ms" + f"cont: {is_continuation}, finalize: {finalize}, " + f"urls: {len(url_images)}, files: {len(valid_files_data)}, " + f"bytes: {actual_total_size}, blobs: {len(blob_upload_results)}, " + f"skipped: {len(skipped_files)}, added: {added_count}, " + f"task_total: {saved_count}, tagging: {tagging_summary}, " + f"timing(ms): s1={(stage1_time - request_start) * 1000:.1f} " + f"blob={(stage2_time - stage1_time) * 1000:.1f} " + f"db={(stage3_time - stage2_time) * 1000:.1f} " + f"total={total_time * 1000:.1f}" ) return ImageUploadResponse(