From 3b28f49959060c30b4386b101d47003bfb6a7707 Mon Sep 17 00:00:00 2001 From: Akira Date: Tue, 2 Sep 2025 20:47:04 +0900 Subject: [PATCH] Add logs on API --- config/settings.py | 2 + rog/middleware.py | 183 +++++++++++++++++++++++++++++++++++++ rog/views_apis/api_play.py | 154 +++++++++++++++++++++++-------- 3 files changed, 299 insertions(+), 40 deletions(-) create mode 100644 rog/middleware.py diff --git a/config/settings.py b/config/settings.py index d063d23..92db086 100644 --- a/config/settings.py +++ b/config/settings.py @@ -70,6 +70,7 @@ INSTALLED_APPS = [ MIDDLEWARE = [ 'corsheaders.middleware.CorsMiddleware', # できるだけ上部に + 'rog.middleware.DetailedRequestLoggingMiddleware', # デバッグ用ログミドルウェア 'django.middleware.common.CommonMiddleware', 'django.middleware.security.SecurityMiddleware', @@ -79,6 +80,7 @@ MIDDLEWARE = [ 'django.contrib.auth.middleware.AuthenticationMiddleware', 'django.contrib.messages.middleware.MessageMiddleware', 'django.middleware.clickjacking.XFrameOptionsMiddleware', + 'rog.middleware.APIResponseEnhancementMiddleware', # レスポンス強化ミドルウェア ] ROOT_URLCONF = 'config.urls' diff --git a/rog/middleware.py b/rog/middleware.py new file mode 100644 index 0000000..5dfaa46 --- /dev/null +++ b/rog/middleware.py @@ -0,0 +1,183 @@ +""" +デバッグ用ミドルウェア +502エラーの原因を特定するためのリクエスト・レスポンス詳細ログ +""" +import logging +import time +import uuid +from django.utils import timezone +from django.http import JsonResponse +import traceback + +logger = logging.getLogger(__name__) + +class DetailedRequestLoggingMiddleware: + """ + すべてのリクエストとレスポンスを詳細にログ出力するミドルウェア + """ + + def __init__(self, get_response): + self.get_response = get_response + + def __call__(self, request): + # リクエスト開始時の処理 + request_id = str(uuid.uuid4())[:8] + start_time = time.time() + request_timestamp = timezone.now() + + # リクエスト情報をログ出力 + self.log_request(request, request_id, request_timestamp) + + # リクエスト処理 + try: + response = self.get_response(request) + + # レスポンス成功時の処理 + end_time = time.time() + duration = end_time - start_time + self.log_response(request, response, request_id, duration) + + return response + + except Exception as e: + # 例外発生時の詳細ログ + end_time = time.time() + duration = end_time - start_time + self.log_exception(request, e, request_id, duration) + + # 502エラーの場合は詳細なJSONレスポンスを返す + return JsonResponse({ + "status": "ERROR", + "message": "Internal Server Error", + "error_id": request_id, + "error_type": type(e).__name__, + "timestamp": request_timestamp.isoformat() + }, status=502) + + def log_request(self, request, request_id, timestamp): + """リクエスト詳細をログ出力""" + try: + logger.info(f"[MIDDLEWARE] 📥 REQUEST_IN - ID: {request_id}") + logger.info(f"[MIDDLEWARE] Time: {timestamp}") + logger.info(f"[MIDDLEWARE] Method: {request.method}") + logger.info(f"[MIDDLEWARE] Path: {request.path}") + logger.info(f"[MIDDLEWARE] Full URL: {request.build_absolute_uri()}") + logger.info(f"[MIDDLEWARE] Client IP: {self.get_client_ip(request)}") + logger.info(f"[MIDDLEWARE] User Agent: {request.META.get('HTTP_USER_AGENT', 'Unknown')[:200]}") + logger.info(f"[MIDDLEWARE] Content Type: {request.content_type}") + logger.info(f"[MIDDLEWARE] Content Length: {request.META.get('CONTENT_LENGTH', 'Unknown')}") + + # start_from_rogapp の場合は特別な処理 + if 'start_from_rogapp' in request.path: + logger.info(f"[MIDDLEWARE] 🎯 START_API_REQUEST - ID: {request_id}") + logger.info(f"[MIDDLEWARE] Request body length: {len(request.body) if request.body else 0}") + logger.info(f"[MIDDLEWARE] Raw body preview: {str(request.body)[:500]}...") + + # ヘッダーの詳細情報 + for header, value in request.META.items(): + if header.startswith('HTTP_'): + logger.info(f"[MIDDLEWARE] Header {header}: {value}") + + except Exception as e: + logger.error(f"[MIDDLEWARE] Error logging request: {str(e)}") + + def log_response(self, request, response, request_id, duration): + """レスポンス詳細をログ出力""" + try: + logger.info(f"[MIDDLEWARE] 📤 RESPONSE_OUT - ID: {request_id}") + logger.info(f"[MIDDLEWARE] Status: {response.status_code}") + logger.info(f"[MIDDLEWARE] Duration: {duration:.3f}s") + logger.info(f"[MIDDLEWARE] Content Type: {response.get('Content-Type', 'Unknown')}") + + # start_from_rogapp の場合は特別な処理 + if 'start_from_rogapp' in request.path: + logger.info(f"[MIDDLEWARE] 🎯 START_API_RESPONSE - ID: {request_id}") + logger.info(f"[MIDDLEWARE] Status Code: {response.status_code}") + + # レスポンス内容のプレビュー（最初の500文字） + if hasattr(response, 'content'): + content_preview = str(response.content)[:500] + logger.info(f"[MIDDLEWARE] Response preview: {content_preview}...") + + except Exception as e: + logger.error(f"[MIDDLEWARE] Error logging response: {str(e)}") + + def log_exception(self, request, exception, request_id, duration): + """例外詳細をログ出力""" + try: + logger.error(f"[MIDDLEWARE] 💥 EXCEPTION - ID: {request_id}") + logger.error(f"[MIDDLEWARE] Duration: {duration:.3f}s") + logger.error(f"[MIDDLEWARE] Exception Type: {type(exception).__name__}") + logger.error(f"[MIDDLEWARE] Exception Message: {str(exception)}") + logger.error(f"[MIDDLEWARE] Request Path: {request.path}") + logger.error(f"[MIDDLEWARE] Request Method: {request.method}") + logger.error(f"[MIDDLEWARE] Client IP: {self.get_client_ip(request)}") + logger.error(f"[MIDDLEWARE] User: {getattr(request, 'user', 'Unknown')}") + + # start_from_rogapp の場合は特別な処理 + if 'start_from_rogapp' in request.path: + logger.error(f"[MIDDLEWARE] 🎯 START_API_EXCEPTION - ID: {request_id}") + logger.error(f"[MIDDLEWARE] Request body: {str(request.body)}") + + # 完全なトレースバック + logger.error(f"[MIDDLEWARE] Full traceback:", exc_info=True) + + except Exception as e: + logger.error(f"[MIDDLEWARE] Error logging exception: {str(e)}") + + def get_client_ip(self, request): + """クライアントIPを取得""" + x_forwarded_for = request.META.get('HTTP_X_FORWARDED_FOR') + if x_forwarded_for: + ip = x_forwarded_for.split(',')[0] + else: + ip = request.META.get('REMOTE_ADDR') + return ip + + +class APIResponseEnhancementMiddleware: + """ + 502エラーレスポンスを強化するミドルウェア + """ + + def __init__(self, get_response): + self.get_response = get_response + + def __call__(self, request): + try: + response = self.get_response(request) + + # 502エラーの場合、より詳細な情報を追加 + if response.status_code == 502: + request_id = str(uuid.uuid4())[:8] + logger.error(f"[API_RESPONSE] 502 Bad Gateway detected - ID: {request_id}") + logger.error(f"[API_RESPONSE] Path: {request.path}") + logger.error(f"[API_RESPONSE] Method: {request.method}") + logger.error(f"[API_RESPONSE] Client: {request.META.get('REMOTE_ADDR', 'Unknown')}") + + # start_from_rogappの場合は追加ログ + if 'start_from_rogapp' in request.path: + logger.error(f"[API_RESPONSE] 🎯 START_API_502_ERROR - ID: {request_id}") + logger.error(f"[API_RESPONSE] Request body: {str(request.body)}") + + # カスタム502レスポンスを返す + return JsonResponse({ + "status": "ERROR", + "message": "スタート処理でサーバーエラーが発生しました", + "error_id": request_id, + "timestamp": timezone.now().isoformat(), + "path": request.path + }, status=502) + + return response + + except Exception as e: + request_id = str(uuid.uuid4())[:8] + logger.error(f"[API_RESPONSE] Middleware exception - ID: {request_id}: {str(e)}", exc_info=True) + + return JsonResponse({ + "status": "ERROR", + "message": "サーバーエラーが発生しました", + "error_id": request_id, + "timestamp": timezone.now().isoformat() + }, status=500) diff --git a/rog/views_apis/api_play.py b/rog/views_apis/api_play.py index 95824bb..a95c13a 100755 --- a/rog/views_apis/api_play.py +++ b/rog/views_apis/api_play.py @@ -14,6 +14,7 @@ from django.utils import timezone from datetime import datetime import uuid import time +from django.http import JsonResponse logger = logging.getLogger(__name__) @@ -237,53 +238,85 @@ def start_from_rogapp(request): request_time = timezone.now() request_id = str(uuid.uuid4())[:8] - logger.info(f"[COMPETITION_START] 🏁 API Request Started - ID: {request_id}, Time: {request_time}, Client IP: {client_ip}, User: {user_info}") - - # リクエストからパラメータを取得 - event_code = request.data.get('event_code') - team_name = request.data.get('team_name') - latitude = request.data.get('latitude', 0.0) - longitude = request.data.get('longitude', 0.0) - extra_data = request.data.get('extra_data', {}) - - logger.info(f"[COMPETITION_START] Request parameters - ID: {request_id}, event_code: '{event_code}', team_name: '{team_name}', GPS: ({latitude},{longitude}), user_agent: '{user_agent[:100]}'") - - # パラメータ検証 - if not all([event_code, team_name]): - logger.warning(f"[COMPETITION_START] ❌ Missing required parameters - ID: {request_id}, event_code: '{event_code}', team_name: '{team_name}', Client IP: {client_ip}") - return Response({ - "status": "ERROR", - "message": "イベントコードとチーム名が必要です" - }, status=status.HTTP_400_BAD_REQUEST) + # 初期ログ出力 + logger.info(f"[START_API] 🚀 REQUEST_START - ID: {request_id}") + logger.info(f"[START_API] Request details - Time: {request_time}, Client: {client_ip}, User: {user_info}") + logger.info(f"[START_API] Headers - User-Agent: {user_agent[:200]}") + logger.info(f"[START_API] Content-Type: {request.content_type}") + logger.info(f"[START_API] Method: {request.method}") try: + # リクエストデータの解析 + logger.info(f"[START_API] Raw request body type: {type(request.body)}") + logger.info(f"[START_API] Raw request body length: {len(request.body) if request.body else 0}") + + # リクエストからパラメータを取得 + logger.info(f"[START_API] Attempting to parse request data...") + event_code = request.data.get('event_code') + team_name = request.data.get('team_name') + latitude = request.data.get('latitude', 0.0) + longitude = request.data.get('longitude', 0.0) + extra_data = request.data.get('extra_data', {}) + + logger.info(f"[START_API] Parameters parsed - ID: {request_id}") + logger.info(f"[START_API] event_code: '{event_code}' (type: {type(event_code)})") + logger.info(f"[START_API] team_name: '{team_name}' (type: {type(team_name)})") + logger.info(f"[START_API] GPS: lat={latitude}, lon={longitude}") + logger.info(f"[START_API] extra_data: {extra_data}") + + # パラメータ検証 + if not event_code: + logger.warning(f"[START_API] ❌ Missing event_code - ID: {request_id}") + return Response({ + "status": "ERROR", + "message": "イベントコードが必要です" + }, status=status.HTTP_400_BAD_REQUEST) + + if not team_name: + logger.warning(f"[START_API] ❌ Missing team_name - ID: {request_id}") + return Response({ + "status": "ERROR", + "message": "チーム名が必要です" + }, status=status.HTTP_400_BAD_REQUEST) + + logger.info(f"[START_API] ✅ Parameter validation passed - ID: {request_id}") + + # データベース操作開始 + logger.info(f"[START_API] Starting database operations - ID: {request_id}") + # イベントの存在確認 + logger.info(f"[START_API] Searching for event: '{event_code}' - ID: {request_id}") event = NewEvent2.objects.filter(event_name=event_code).first() + if not event: - logger.warning(f"[COMPETITION_START] ❌ Event not found - ID: {request_id}, event_code: '{event_code}', Client IP: {client_ip}") + logger.warning(f"[START_API] ❌ Event not found - ID: {request_id}, event_code: '{event_code}'") return Response({ "status": "ERROR", "message": "指定されたイベントが見つかりません" }, status=status.HTTP_404_NOT_FOUND) - logger.info(f"[COMPETITION_START] ✅ Event found - ID: {request_id}, Event ID: {event.id}, Name: '{event.event_name}', Start: {event.start_datetime}, End: {event.end_datetime}") + logger.info(f"[START_API] ✅ Event found - ID: {request_id}, Event ID: {event.id}, Name: '{event.event_name}'") + logger.info(f"[START_API] Event details - Start: {event.start_datetime}, End: {event.end_datetime}") # チームの存在確認 + logger.info(f"[START_API] Searching for team: '{team_name}' in event: '{event_code}' - ID: {request_id}") entry = Entry.objects.filter( event=event, team_name=team_name ).first() if not entry: - logger.warning(f"[COMPETITION_START] ❌ Team not found - ID: {request_id}, team_name: '{team_name}', event_code: '{event_code}', Client IP: {client_ip}") + logger.warning(f"[START_API] ❌ Team not found - ID: {request_id}, team: '{team_name}', event: '{event_code}'") return Response({ "status": "ERROR", "message": "指定されたチームが見つかりません" }, status=status.HTTP_404_NOT_FOUND) - logger.info(f"[COMPETITION_START] ✅ Team found - ID: {request_id}, Entry ID: {entry.id}, Team: '{team_name}', Zekken: {entry.zekken_number}, Category: '{entry.category.category_name if entry.category else 'N/A'}', Owner: '{entry.owner.email if entry.owner else 'N/A'}')") + logger.info(f"[START_API] ✅ Team found - ID: {request_id}, Entry ID: {entry.id}") + logger.info(f"[START_API] Team details - Zekken: {entry.zekken_number}, Category: '{entry.category.category_name if entry.category else 'N/A'}'") - # 既にスタート済みかチェック（GpsLogでSTARTレコードを確認） + # 既にスタート済みかチェック + logger.info(f"[START_API] Checking if team already started - ID: {request_id}") existing_start = GpsLog.objects.filter( entry=entry, cp_number="START", @@ -291,45 +324,86 @@ def start_from_rogapp(request): ).first() if existing_start: - logger.warning(f"[COMPETITION_START] ⚠️ Team already started - ID: {request_id}, team_name: '{team_name}', zekken: {entry.zekken_number}, start_time: {existing_start.checkin_time}, Client IP: {client_ip}") + logger.warning(f"[START_API] ⚠️ Team already started - ID: {request_id}, start_time: {existing_start.checkin_time}") return Response({ "status": "WARNING", "message": "このチームは既にスタートしています", - "start_time": entry.start_info.start_time.strftime("%Y-%m-%d %H:%M:%S") + "start_time": existing_start.checkin_time.strftime("%Y-%m-%d %H:%M:%S") }) + logger.info(f"[START_API] ✅ Team not started yet - ID: {request_id}") + # トランザクション開始 + logger.info(f"[START_API] Starting database transaction - ID: {request_id}") with transaction.atomic(): # スタート情報をGpsLogとして登録 + logger.info(f"[START_API] Creating start record - ID: {request_id}") start_info = GpsLog.objects.create( entry=entry, - cp_number="START", # スタート専用のCP番号 - serial_number=0, # スタート記録の固定シリアル番号 - latitude=latitude if latitude else 0.0, - longitude=longitude if longitude else 0.0, + cp_number="START", + serial_number=0, + latitude=float(latitude) if latitude else 0.0, + longitude=float(longitude) if longitude else 0.0, checkin_time=timezone.now(), extra_data=extra_data ) + logger.info(f"[START_API] ✅ Start record created - ID: {request_id}, GpsLog ID: {start_info.id}") + # 統計情報取得 - total_checkpoints = Location2025.objects.filter(event=event).count() if hasattr(Location2025, 'event') else 0 + try: + total_checkpoints = Location2025.objects.filter(event=event).count() + logger.info(f"[START_API] Total checkpoints available: {total_checkpoints} - ID: {request_id}") + except Exception as e: + logger.warning(f"[START_API] Could not get checkpoint count: {str(e)} - ID: {request_id}") + total_checkpoints = 0 - logger.info(f"[COMPETITION_START] 🎉 SUCCESS - ID: {request_id}, Team: '{team_name}', Zekken: {entry.zekken_number}, Event: '{event_code}', Start Time: {start_info.checkin_time}, GPS: ({latitude},{longitude}), Total CPs Available: {total_checkpoints}, Client IP: {client_ip}, User: {user_info}") - - return Response({ + # 成功レスポンス準備 + response_data = { "status": "OK", "message": "スタート処理が完了しました", "team_name": team_name, "event_code": event_code, - "start_time": start_info.start_time.strftime("%Y-%m-%d %H:%M:%S") - }) + "start_time": start_info.checkin_time.strftime("%Y-%m-%d %H:%M:%S"), + "zekken_number": entry.zekken_number, + "entry_id": entry.id + } + + logger.info(f"[START_API] 🎉 SUCCESS - ID: {request_id}, Team: '{team_name}', Zekken: {entry.zekken_number}") + logger.info(f"[START_API] Response data: {response_data}") + + return Response(response_data) except Exception as e: - logger.error(f"[COMPETITION_START] 💥 CRITICAL ERROR - ID: {request_id}, team_name: '{team_name}', event_code: '{event_code}', Client IP: {client_ip}, Error: {str(e)}", exc_info=True) - return Response({ - "status": "ERROR", - "message": "サーバーエラーが発生しました" - }, status=status.HTTP_500_INTERNAL_SERVER_ERROR) + # 詳細なエラー情報をログに出力 + logger.error(f"[START_API] 💥 CRITICAL ERROR - ID: {request_id}") + logger.error(f"[START_API] Error type: {type(e).__name__}") + logger.error(f"[START_API] Error message: {str(e)}") + logger.error(f"[START_API] Request data: event_code='{event_code if 'event_code' in locals() else 'UNDEFINED'}', team_name='{team_name if 'team_name' in locals() else 'UNDEFINED'}'") + logger.error(f"[START_API] Client: {client_ip}, User: {user_info}") + logger.error(f"[START_API] Full traceback:", exc_info=True) + + # エラーレスポンス + try: + return Response({ + "status": "ERROR", + "message": "サーバーエラーが発生しました", + "error_id": request_id + }, status=status.HTTP_500_INTERNAL_SERVER_ERROR) + except Exception as response_error: + logger.error(f"[START_API] 💥 DOUBLE ERROR - Could not create error response: {str(response_error)}") + # 最後の手段として、シンプルなJSONレスポンスを返す + return JsonResponse({ + "status": "ERROR", + "message": "サーバーエラーが発生しました", + "error_id": request_id + }, status=500) + + finally: + # 処理完了ログ + end_time = timezone.now() + duration = (end_time - request_time).total_seconds() + logger.info(f"[START_API] 🏁 REQUEST_END - ID: {request_id}, Duration: {duration:.3f}s") """