refactor: 크롤링/업로드 로그를 요청당 1줄 요약으로 축소

- 단계별 진행 로그를 삭제하고 계측치를 SUCCESS 한 줄에 통합
- 실패 경로(error/warning/exception) 로그는 그대로 유지
- gpt_status 를 locals() 검사 대신 초기화 후 직접 참조
This commit is contained in:
김성경 2026-08-12 13:21:47 +09:00
parent f87cd07d5e
commit b04e239344

View File

@ -258,12 +258,22 @@ async def autocomplete_crawling(
async def _crawling_logic(url: str, session: AsyncSession): async def _crawling_logic(url: str, session: AsyncSession):
request_start = time.perf_counter() 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: 네이버 지도 크롤링 ========== # ========== Step 1: 네이버 지도 크롤링 ==========
step1_start = time.perf_counter() step1_start = time.perf_counter()
logger.info("[crawling] Step 1: 네이버 지도 크롤링 시작...")
try: try:
scraper = NvMapScraper(url) scraper = NvMapScraper(url)
@ -298,14 +308,11 @@ async def _crawling_logic(url: str, session: AsyncSession):
) )
step1_elapsed = (time.perf_counter() - step1_start) * 1000 step1_elapsed = (time.perf_counter() - step1_start) * 1000
logger.info( owner_count = len(scraper.owner_images or [])
f"[crawling] Step 1 완료 - 업체사진 {len(scraper.owner_images or [])}개, " extra_count = len(scraper.extra_photo_urls or [])
f"보충사진 {len(scraper.extra_photo_urls or [])}개 ({step1_elapsed:.1f}ms)"
)
# ========== Step 2: 정보 가공 (industry 선행 계산) ========== # ========== Step 2: 정보 가공 (industry 선행 계산) ==========
step2_start = time.perf_counter() step2_start = time.perf_counter()
logger.info("[crawling] Step 2: 정보 가공 시작...")
processed_info = None processed_info = None
marketing_analysis = None marketing_analysis = None
@ -340,10 +347,6 @@ async def _crawling_logic(url: str, session: AsyncSession):
) )
step2_elapsed = (time.perf_counter() - step2_start) * 1000 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: 이미지 마케팅 적합성 필터링 ========== # ========== Step 3: 이미지 마케팅 적합성 필터링 ==========
# 업체 사진이 SUPPLEMENT_THRESHOLD(30장) 이상이면 보충이 불필요하므로 # 업체 사진이 SUPPLEMENT_THRESHOLD(30장) 이상이면 보충이 불필요하므로
@ -358,10 +361,7 @@ async def _crawling_logic(url: str, session: AsyncSession):
# 수집 자체는 NvMapScraper.BIZ_MAX_PAGES가 상한이며 도달 시 scraper가 warning을 남긴다). # 수집 자체는 NvMapScraper.BIZ_MAX_PAGES가 상한이며 도달 시 scraper가 warning을 남긴다).
scraper.image_link_list = list(owner_images) scraper.image_link_list = list(owner_images)
step3_elapsed = (time.perf_counter() - step3_start) * 1000 step3_elapsed = (time.perf_counter() - step3_start) * 1000
logger.info( filter_summary = f"skip(owner>={NvMapScraper.SUPPLEMENT_THRESHOLD})"
f"[crawling] Step 3 SKIP - 업체 사진 {len(owner_images)}장 "
f"≥ {NvMapScraper.SUPPLEMENT_THRESHOLD}장 → 방문자 사진 필터링 생략, 업체 사진만 사용"
)
else: else:
try: try:
extra_pass_flags = await filter_marketing_images( 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) passed_count = sum(extra_pass_flags)
step3_elapsed = (time.perf_counter() - step3_start) * 1000 step3_elapsed = (time.perf_counter() - step3_start) * 1000
logger.info( filter_summary = f"{len(extra_photo_urls)}→{passed_count}"
f"[crawling] Step 3 완료 - 방문자 사진 {len(extra_photo_urls)}장 중 "
f"{passed_count}장 통과 → 최종 이미지 {len(scraper.image_link_list)}장 "
f"({step3_elapsed:.1f}ms)"
)
if not scraper.image_link_list: if not scraper.image_link_list:
logger.warning( logger.warning(
"[crawling] Step 3 - 필터링 후 사용 가능 이미지가 0장입니다." "[crawling] Step 3 - 필터링 후 사용 가능 이미지가 0장입니다."
@ -393,7 +389,6 @@ async def _crawling_logic(url: str, session: AsyncSession):
# ========== Step 4: ChatGPT 마케팅 분석 ========== # ========== Step 4: ChatGPT 마케팅 분석 ==========
step4_start = time.perf_counter() step4_start = time.perf_counter()
logger.info("[crawling] Step 4: ChatGPT 마케팅 분석 시작...")
try: try:
# Step 4-1: ChatGPT 서비스 초기화 및 입력 데이터 구성 # Step 4-1: ChatGPT 서비스 초기화 및 입력 데이터 구성
@ -435,9 +430,6 @@ async def _crawling_logic(url: str, session: AsyncSession):
) )
step4_elapsed = (time.perf_counter() - step4_start) * 1000 step4_elapsed = (time.perf_counter() - step4_start) * 1000
logger.info(
f"[crawling] Step 4 완료 - 마케팅 분석 성공 ({step4_elapsed:.1f}ms)"
)
except ChatGPTResponseError as e: except ChatGPTResponseError as e:
step4_elapsed = (time.perf_counter() - step4_start) * 1000 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 total_elapsed = (time.perf_counter() - request_start) * 1000
logger.info("[crawling] ========== COMPLETE ==========") logger.info(
logger.info(f"[crawling] 총 소요시간: {total_elapsed:.1f}ms") f"[crawling] SUCCESS - url: {url[:80]}, name: {customer_name!r}, "
logger.info(f"[crawling] - Step 1 (크롤링): {step1_elapsed:.1f}ms") f"region: {region!r}, category: {category!r}, industry: {industry!r}, "
if scraper.base_info: f"owner: {owner_count}, extra: {extra_count}, filter: {filter_summary}, "
logger.info(f"[crawling] - Step 2 (정보가공): {step2_elapsed:.1f}ms") f"images: {len(scraper.image_link_list or [])}, gpt: {gpt_status}, "
if "step3_elapsed" in locals(): f"timing(ms): s1={step1_elapsed:.1f} s2={step2_elapsed:.1f} "
logger.info(f"[crawling] - Step 3 (이미지 필터링): {step3_elapsed:.1f}ms") f"s3={step3_elapsed:.1f} s4={step4_elapsed:.1f} total={total_elapsed:.1f}"
if "step4_elapsed" in locals(): )
logger.info(f"[crawling] - Step 4 (GPT 분석): {step4_elapsed:.1f}ms")
return { return {
"status": gpt_status if "gpt_status" in locals() else "completed", "status": gpt_status,
"image_list": scraper.image_link_list, "image_list": scraper.image_link_list,
"image_count": len(scraper.image_link_list) if scraper.image_link_list else 0, "image_count": len(scraper.image_link_list) if scraper.image_link_list else 0,
"processed_info": processed_info, "processed_info": processed_info,
@ -780,11 +771,6 @@ async def upload_images_blob(
task_id = await generate_task_id() task_id = await generate_task_id()
existing_images = [] existing_images = []
logger.info(
f"[upload_images_blob] START - task_id: {task_id}, "
f"continuation: {is_continuation}, finalize: {finalize}"
)
# ========== Stage 1: 입력 검증 (세션 없음, 파일 전체 메모리 적재 없음) ========== # ========== Stage 1: 입력 검증 (세션 없음, 파일 전체 메모리 적재 없음) ==========
has_images_json = images_json is not None and images_json.strip() != "" has_images_json = images_json is not None and images_json.strip() != ""
has_files = files is not None and len(files) > 0 has_files = files is not None and len(files) > 0
@ -864,11 +850,6 @@ async def upload_images_blob(
) )
stage1_time = time.perf_counter() 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 청크 업로드 (세션 없음) ========== # ========== Stage 2: Azure Blob 청크 업로드 (세션 없음) ==========
# (원본명, 공개 URL, Azure 저장 파일명) # (원본명, 공개 URL, Azure 저장 파일명)
@ -998,15 +979,12 @@ async def upload_images_blob(
) )
stage2_time = time.perf_counter() 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 저장 (새 세션으로 빠르게 처리) ========== # ========== Stage 3: DB 저장 (새 세션으로 빠르게 처리) ==========
logger.info("[upload_images_blob] Stage 3 starting - DB save...")
all_images: list[Image] = [] all_images: list[Image] = []
# 요약 로그용. 커밋이 끝난 뒤 실제 값으로 덮어쓴다.
stage3_time = stage2_time
added_count = 0
commit_started = False commit_started = False
try: try:
@ -1078,11 +1056,7 @@ async def upload_images_blob(
commit_started = True commit_started = True
await session.commit() await session.commit()
stage3_time = time.perf_counter() stage3_time = time.perf_counter()
logger.info( added_count = len(new_images)
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"
)
except asyncio.CancelledError as e: except asyncio.CancelledError as e:
await compensate_after_cancellation(commit_started, e) await compensate_after_cancellation(commit_started, e)
@ -1114,14 +1088,13 @@ async def upload_images_blob(
saved_count = len(result_images) saved_count = len(result_images)
image_urls = [img.img_url for img in result_images] image_urls = [img.img_url for img in result_images]
tagging_summary = "deferred"
if finalize: if finalize:
logger.info(f"[image_tagging] START - task_id: {task_id}")
await tagging_images(image_urls, industry=industry, clear_old_tags=True) 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) 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: if not taged_image_list:
logger.error( logger.error(
f"[image_tagging] 영상 생성에 적합한 이미지가 없음 - task_id: {task_id}" 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 total_time = time.perf_counter() - request_start
logger.info( logger.info(
f"[upload_images_blob] SUCCESS - task_id: {task_id}, " 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( return ImageUploadResponse(