throttling, abuse-protection & logging/monitoring pass

This commit is contained in:
2026-08-23 23:44:00 +03:30
parent cb18c93a3e
commit 80298b47b1
33 changed files with 4202 additions and 23 deletions

36
config/log_formatters.py Normal file
View File

@@ -0,0 +1,36 @@
"""
فرمت‌کننده‌ی سبکِ JSON برای خروجیِ logging — آماده‌سازیِ پروژه برای
جمع‌آوریِ متمرکزِ لاگ (مثلاً یک agentِ بیرونی مثلِ Promtail/Filebeat که
stdout رو می‌خونه و به Loki/ELK می‌فرسته) در آینده.
⚠️ توجه (محدوده‌ی این تغییر):
- این فایل فقط *فرمتِ* خروجیِ همون لاگ‌های موجودِ اپلیکیشن رو عوض می‌کنه
(یک شیِ JSON در هر خط، به‌جای متنِ ساده‌ی قبلی)؛ هیچ eventِ لاگِ جدیدی
اضافه نمی‌کنه و هیچ loggerِ موجودی رو تغییر نمی‌ده.
- فقط از فیلدهای استانداردِ خودِ LogRecord (زمان، سطح، نامِ logger، پیامِ
از قبل ساخته‌شده، و traceback در صورتِ وجود) استفاده می‌شه؛ یعنی همون
محافظت‌های حساسیتیِ قبلی (بدون OTP/token/رمزعبور/بدنه‌ی خامِ provider و
غیره در پیام‌ها) دست‌نخورده می‌مونه — این فرمت‌کننده چیزی به پیام اضافه
نمی‌کنه، فقط قالب‌بندیِ همون پیامِ از قبل امن رو تغییر می‌ده.
- هیچ وابستگیِ جدید (Elasticsearch/Loki/Grafana client) یا appِ جدید یا
ذخیره‌سازیِ دیتابیسی/APIِ لاگ اضافه نمی‌کنه؛ فقط stdlibِ logging + json.
"""
import json
import logging
from datetime import datetime, timezone
class JSONLogFormatter(logging.Formatter):
"""هر LogRecord رو به یک خطِ JSON (سازگار با collectorهای سبکِ Loki/ELK) تبدیل می‌کنه."""
def format(self, record: logging.LogRecord) -> str:
payload = {
'timestamp': datetime.fromtimestamp(record.created, tz=timezone.utc).isoformat(),
'level': record.levelname,
'logger': record.name,
'message': record.getMessage(),
}
if record.exc_info:
payload['exception'] = self.formatException(record.exc_info)
return json.dumps(payload, ensure_ascii=False)

91
config/middleware.py Normal file
View File

@@ -0,0 +1,91 @@
"""
میان‌افزارِ سبکِ لاگِ درخواست‌های API — سطحِ پروژه.
⚠️ افزوده شده: پروژه چند logger پراکنده‌ی اپلیکیشنی داشت (accounts.services،
ai_tutor.views، ...) اما هیچ لاگِ یکپارچه‌ای در سطحِ پروژه برای *همه‌ی*
درخواست‌های API وجود نداشت؛ یعنی درخواست‌های عادی، ناموفق، یا الگوهای
مشکوک (مثلاً یک IP/کاربر که پشتِ سرِ هم درخواستِ ناموفق می‌فرسته) به‌صورتِ
یکدست قابلِ ردیابی نبودن. این میان‌افزار فقط یک خط لاگِ خلاصه به‌ازای هر
درخواستِ زیرِ /api/ ثبت می‌کنه: متد، مسیر، کدِ وضعیتِ پاسخ، مدت‌زمان، و
شناسه‌ی کاربرِ احرازهویت‌شده (اگه وجود داشته باشه).
نکاتِ امنیتی/حریمِ خصوصی:
- هیچ‌وقت بدنه‌ی درخواست/پاسخ، query string، هدرها (از جمله Authorization،
Idempotency-Key و غیره)، رمزعبور/OTP، access/refresh token، کلیدِ API، یا
سکرتِ webhook لاگ نمی‌شه — فقط request.path (بدونِ query string) و
متادیتای بی‌ضررِ بالا.
- در صورتِ هر خطای غیرمنتظره در خودِ فرآیندِ لاگ‌کردن (مثلاً یک مقدارِ
غیرمنتظره برای user)، این میان‌افزار هیچ‌وقت نباید جریانِ درخواست/پاسخ
را بشکنه؛ به همین خاطر کل بخشِ لاگ داخلِ try/except قرار گرفته.
- ⚠️ اصلاح: قبلاً اگه self.get_response(request) خودش یک exceptionِ
دست‌نخورده (unhandled) بالا می‌آورد، اون exception قبل از رسیدن به بلوکِ
لاگ از __call__ خارج می‌شد؛ یعنی خطاهای ۵۰۰ اصلاً لاگ نمی‌شدن. حالا
self.get_response در try/except قرار گرفته: در صورتِ exception، یک خطِ
لاگِ سطحِ ERROR (با متد/مسیر/مدت/user_id، بدونِ جزئیاتِ حساس) ثبت می‌شه
و بعد همون exceptionِ اصلی بدونِ تغییر دوباره raise می‌شه (تا رفتارِ
مدیریتِ خطای Django/DRF دست‌نخورده بمونه).
- ⚠️ اصلاحِ این دور: پیامِ لاگِ مسیرِ exception از یک placeholderِ واقعیِ
status=%s استفاده می‌کنه (هم‌سو با مسیرِ موفق)، و status=500 حالا از
طریقِ آرگومانِ status به _log_safely() صریحاً پاس داده می‌شه، نه به‌صورتِ
متنِ ثابت داخلِ رشته. این هم پیام رو با مسیرِ موفق یکدست می‌کنه و هم از
ناهماهنگیِ تعدادِ آرگومان‌های % formatting جلوگیری می‌کنه.
"""
import logging
import time
logger = logging.getLogger(__name__)
# فقط مسیرهای API لاگ می‌شن؛ درخواست‌های استاتیک/غیرِ API (که این پروژه
# اصلاً مسیرِ URL جداگانه‌ای براشون در config/urls.py تعریف نکرده) عمداً
# نادیده گرفته می‌شن تا لاگ شلوغ/بی‌فایده تولید نشه.
_LOGGED_PATH_PREFIX = '/api/'
def _user_id_for_log(request):
"""شناسه‌ی کاربرِ احرازهویت‌شده برای لاگ، یا None (کاربرِ ناشناس/بدونِ user)."""
user = getattr(request, 'user', None)
return user.id if getattr(user, 'is_authenticated', False) else None
class APIRequestLoggingMiddleware:
"""میان‌افزارِ Django برای لاگِ خلاصه‌ی هر درخواستِ API (متد/مسیر/وضعیت/مدت/کاربر)."""
def __init__(self, get_response):
self.get_response = get_response
def __call__(self, request):
if not request.path.startswith(_LOGGED_PATH_PREFIX):
return self.get_response(request)
start = time.monotonic()
try:
response = self.get_response(request)
except Exception:
self._log_safely(
logger.error,
'api_request method=%s path=%s status=%s duration_ms=%.1f user_id=%s (unhandled exception)',
request, start, status=500,
)
raise
self._log_safely(
logger.info,
'api_request method=%s path=%s status=%s duration_ms=%.1f user_id=%s',
request, start, response.status_code,
)
return response
def _log_safely(self, log_func, message, request, start, status=None):
# لاگ‌کردن هیچ‌وقت نباید خودش دلیلِ شکستِ یک درخواست بشه (چه در
# مسیرِ موفق، چه در مسیرِ exception)؛ به همین خاطر کل بخشِ لاگ
# داخلِ try/except قرار گرفته.
try:
duration_ms = (time.monotonic() - start) * 1000
if status is None:
log_func(message, request.method, request.path, duration_ms, _user_id_for_log(request))
else:
log_func(message, request.method, request.path, status, duration_ms, _user_id_for_log(request))
except Exception:
logger.exception('api_request logging failed')

View File

@@ -90,6 +90,11 @@ MIDDLEWARE = [
'django.contrib.auth.middleware.AuthenticationMiddleware',
'django.contrib.messages.middleware.MessageMiddleware',
'django.middleware.clickjacking.XFrameOptionsMiddleware',
# ⚠️ افزوده شده: لاگِ سبکِ هر درخواستِ API (متد/مسیر/وضعیت/مدت/کاربر)؛
# عمداً آخرِ لیست قرار گرفته تا نزدیک‌ترین میان‌افزار به خودِ view باشه
# (مدت‌زمانِ دقیق‌تر، و request.user که توسطِ DRF authentication در
# حینِ پردازشِ view ست می‌شه، در دسترس باشه).
'config.middleware.APIRequestLoggingMiddleware',
]
ROOT_URLCONF = 'config.urls'
@@ -208,10 +213,44 @@ REST_FRAMEWORK = {
'DEFAULT_THROTTLE_CLASSES': [
'rest_framework.throttling.ScopedRateThrottle',
],
# ⚠️ اضافه شده (امنیتی): بدونِ NUM_PROXIES، DRF (SimpleRateThrottle.get_ident)
# هدرِ X-Forwarded-For رو - اگه در درخواست وجود داشته باشه - عیناً و
# بدون‌چک به‌عنوانِ IP کلاینت قبول می‌کنه؛ یعنی هر کلاینتِ ناشناس می‌تونست
# با فرستادنِ یک X-Forwarded-For دلخواه/تصادفی در هر درخواست، برای
# هر GuestAware*Throttle (content/ai_tutor/subscription/payment/discount/
# support/family/affiliate) یک IP-bucket تازه بگیره - دقیقاً همون
# bypassِ چرخشِ حساب مهمان که این throttle-classها قرار بود ببندن، فقط
# از طریقِ هدر به‌جای deviceId جدید.
# با NUM_PROXIES=1 (پیش‌فرض؛ برای دیپلویِ پشتِ یک لایه‌ی پراکسی/LB که
# خودش X-Forwarded-For رو ست/rewrite می‌کنه، نه پاس‌دادنِ مقدارِ
# کلاینت)، DRF از انتهای زنجیره‌ی XFF دقیقاً همون تعداد hop رو
# می‌خونه. اگه دیپلویِ پروداکشن تعداد لایه‌ی پراکسیِ دیگه‌ای داره
# (مثلاً Cloudflare + Nginx = ۲ لایه)، این مقدار باید با env
# NUM_PROXIES مطابقِ همون تعداد ست بشه، وگرنه یا IP واقعی اشتباه
# خونده می‌شه یا (اگه صفر باشه) دوباره همون مشکلِ بالا برمی‌گرده.
'NUM_PROXIES': int(os.environ.get('NUM_PROXIES', '1')),
'DEFAULT_THROTTLE_RATES': {
'otp_request': '5/hour',
'otp_login': '10/hour',
'guest_session': '20/hour',
'bazaar_verify': '10/hour',
'ai_ask': '20/hour',
'purchase': '10/hour',
'token_refresh': '30/hour',
'question_answer': '60/min',
'lesson_complete': '10/hour',
'support_create': '30/hour',
'offer_redeem': '10/hour',
'discount_validate': '20/hour',
'discount_redeem': '10/hour',
'family_invite_accept': '10/hour',
'family_invite_create': '5/hour',
# ⚠️ اضافه شده: چهار endpointی که در ممیزیِ throttleِ امروز بدونِ
# throttle_scope پیدا شدن (نگاه کنید به توضیحاتِ throttle_scope
# مربوطه در accounts/views.py، affiliate/views.py، payment/views.py).
'user_profile_write': '60/hour',
'affiliate_track': '10/hour',
'payment_webhook': '60/hour',
},
}
@@ -243,6 +282,23 @@ REFRESH_TOKEN_TTL_DAYS = 30
OTP_LOGIN_PHONE_MAX_ATTEMPTS = 10
OTP_LOGIN_PHONE_WINDOW_SECONDS = 3600
# محدودیتِ صدورِ/ارسالِ دوبارهِ OTP بر اساسِ شماره‌تلفن، مستقل از throttle
# IP-محورِ otp_request؛ جلوی flood کردنِ پیامک به یک شماره از طریق چند IP
# مختلف رو می‌گیره (فقط تعدادِ درخواست رو محدود می‌کنه، نه شماره‌ی IP رو).
OTP_REQUEST_PHONE_MAX_ATTEMPTS = 5
OTP_REQUEST_PHONE_WINDOW_SECONDS = 3600
# حداقل فاصله‌ی زمانی بین دو درخواستِ صدورِ OTP برای همون شماره. این مستقل
# از سقفِ ساعتیِ بالاست: سقفِ ساعتی جلویِ حجمِ کلی رو می‌گیره اما جلویِ
# burst رو نمی‌گیره (مثلاً هر ۵ تلاشِ مجاز در عرضِ کمتر از یک ثانیه). این
# cooldown دقیقاً همون burst رو هدف می‌گیره؛ نه جایگزینِ سقفِ ساعتیه، نه
# باهاش redundant — هر کدوم یک بُعدِ متفاوتِ سوءاستفاده رو می‌بندن.
# ⚠️ تصمیمِ محصول/امنیت: کاربر واقعاً باید هر ۲ دقیقه بتونه دوباره OTP
# بگیره؛ enforcement سمتِ سرور هم باید دقیقاً همین مقدار باشه — countdown
# سمتِ فرانت صرفاً UX هست و نباید مرجعِ امنیتی باشه، پس این مقدار همیشه
# باید با چیزی که فرانت به کاربر نشون می‌ده یکی باشه.
OTP_REQUEST_PHONE_COOLDOWN_SECONDS = 120
# در محیط dev، این کد OTP همیشه معتبر است تا بدون SMS واقعی تست شود.
# فقط وقتی DEBUG=True مقدار دارد؛ در پروداکشن None است.
DEV_MASTER_OTP = '0000' if DEBUG else None
@@ -307,3 +363,59 @@ BAZAAR_API_BASE = os.environ.get('BAZAAR_API_BASE', 'https://pardakht.cafebazaar
# https://docs.djangoproject.com/en/5.2/ref/settings/#default-auto-field
DEFAULT_AUTO_FIELD = 'django.db.models.BigAutoField'
# -----------------------------------------------------------------------
# Logging (آماده‌سازیِ لاگ‌های موجود برای جمع‌آوریِ متمرکز — Loki/ELK-style)
# -----------------------------------------------------------------------
# ⚠️ افزوده شده: پروژه از قبل چندین logger (config.middleware،
# accounts.services، ai_tutor.views، ...) با logging.getLogger(__name__)
# داشت، اما بدونِ یک LOGGING صریح در settings.py، اینا فقط به rootِ
# پیش‌فرضِ کتابخانه‌ی logging می‌رسیدن (که برای سطحِ INFO عملاً هیچ خروجی‌ای
# تولید نمی‌کنه). این تنظیم، بدونِ اضافه/حذفِ هیچ loggerِ اپلیکیشنی یا
# eventِ لاگی، همون پیام‌های موجود رو روی stdout و به‌صورتِ یک JSON در هر
# خط (فرمتِ سازگار با agentِ جمع‌آوریِ بیرونی مثلِ Promtail/Filebeat که
# بعداً می‌تونه به Loki/ELK بفرسته) چاپ می‌کنه. هیچ appِ جدید، ذخیره‌سازیِ
# دیتابیسی، API/UIِ لاگ، یا وابستگیِ Elasticsearch/Loki/Grafana به خودِ
# کدِ Django اضافه نشده.
LOGGING = {
'version': 1,
'disable_existing_loggers': False,
'formatters': {
'json': {
'()': 'config.log_formatters.JSONLogFormatter',
},
},
'handlers': {
'console': {
'class': 'logging.StreamHandler',
'formatter': 'json',
},
},
'root': {
'handlers': ['console'],
'level': 'INFO',
},
}
# ⚠️ افزوده شده (یکپارچه‌سازیِ Docker + Promtail/Loki/Grafana): وقتی
# env var LOG_DIR ست شده باشه (فقط داخلِ docker-compose.yml، روی یک
# ولومِ مشترک با کانتینرِ promtail)، همون خطوطِ JSON که از قبل روی
# stdout چاپ می‌شدن، *علاوه* بر stdout در یک فایل هم نوشته می‌شن؛
# Promtail همون فایل رو tail می‌کنه و به Loki می‌فرسته.
# این فقط یک هندلرِ خروجیِ اضافه با همون formatter (json) هست — نه
# پیام‌های لاگ، نه محافظت‌های حساسیتیِ موجود (بدونِ OTP/token/رمزعبور و
# غیره در پیام‌ها)، و نه هیچ loggerِ اپلیکیشنی تغییر نمی‌کنه.
# وقتی LOG_DIR ست نباشه (یعنی اجرای عادیِ خارج از Docker، طبق README)،
# رفتار دقیقاً همون چیزیه که از قبل بود: فقط stdout.
LOG_DIR = os.environ.get('LOG_DIR', '')
if LOG_DIR:
os.makedirs(LOG_DIR, exist_ok=True)
LOGGING['handlers']['file'] = {
'class': 'logging.handlers.RotatingFileHandler',
'filename': os.path.join(LOG_DIR, 'app.log'),
'maxBytes': 10 * 1024 * 1024, # 10MB در هر فایل، قبل از rotate
'backupCount': 5,
'formatter': 'json',
}
LOGGING['root']['handlers'].append('file')

View File

@@ -1,9 +1,16 @@
import importlib
import json
import logging
import os
from unittest.mock import patch
from django.core.exceptions import ImproperlyConfigured
from django.test import SimpleTestCase
from django.test import RequestFactory, SimpleTestCase, TestCase
from rest_framework.test import APIClient
from accounts.authentication import issue_access_token
from accounts.models import User
from config.middleware import APIRequestLoggingMiddleware
class SecretKeyFailClosedTests(SimpleTestCase):
@@ -116,3 +123,167 @@ class CacheUrlFailClosedTests(SimpleTestCase):
settings_module.CACHES['default']['BACKEND'],
'django.core.cache.backends.locmem.LocMemCache',
)
class APIRequestLoggingMiddlewareTests(TestCase):
"""
🔒 اثبات میان‌افزارِ جدیدِ لاگِ درخواستِ API (config.middleware.
APIRequestLoggingMiddleware): باید برای مسیرهای /api/ یک خطِ لاگِ خلاصه
(متد/مسیر/وضعیت/مدت/شناسه‌ی کاربر) ثبت کنه، بدونِ اینکه هیچ‌وقت بدنه/
هدر/سکرت رو لاگ کنه؛ و برای مسیرهای غیرِ /api/ (مثلِ /admin/) اصلاً
لاگ نکنه.
"""
def setUp(self):
self.client = APIClient()
def test_authenticated_api_request_is_logged_with_user_id_and_no_secrets(self):
user = User.objects.create(device_id='device-mw-log-1', is_guest=True, name='')
token = issue_access_token(user.id)
with self.assertLogs('config.middleware', level='INFO') as captured:
response = self.client.post(
'/api/user/grade',
{'gradeId': 10},
format='json',
HTTP_AUTHORIZATION=f'Bearer {token}',
)
self.assertEqual(response.status_code, 200)
self.assertEqual(len(captured.records), 1)
message = captured.records[0].getMessage()
self.assertIn('method=POST', message)
self.assertIn('path=/api/user/grade', message)
self.assertIn('status=200', message)
self.assertIn(f'user_id={user.id}', message)
# هیچ‌وقت نباید هیچ سکرتی در پیامِ لاگ باشه.
self.assertNotIn(token, message)
self.assertNotIn('Bearer', message)
self.assertNotIn('gradeId', message)
def test_anonymous_api_request_is_logged_with_null_user_id(self):
with self.assertLogs('config.middleware', level='INFO') as captured:
response = self.client.post(
'/api/auth/session',
{'type': 'guest', 'deviceId': 'device-mw-log-anon-1'},
format='json',
)
self.assertEqual(response.status_code, 200)
self.assertEqual(len(captured.records), 1)
message = captured.records[0].getMessage()
self.assertIn('method=POST', message)
self.assertIn('path=/api/auth/session', message)
self.assertIn('status=200', message)
self.assertIn('user_id=None', message)
def test_non_api_request_is_not_logged(self):
# /admin/ زیرِ /api/ نیست؛ میان‌افزار عمداً این‌جور مسیرها رو لاگ
# نمی‌کنه تا لاگِ اضافه/بی‌فایده تولید نشه.
logger = logging.getLogger('config.middleware')
handler = logging.Handler()
records = []
handler.emit = records.append
logger.addHandler(handler)
try:
self.client.get('/admin/login/')
finally:
logger.removeHandler(handler)
self.assertEqual(records, [])
def test_unhandled_exception_from_view_is_logged_as_error_and_reraised(self):
# 🔒 اثبات فیکسِ این دور: اگه self.get_response(request) خودش یک
# exceptionِ دست‌نخورده raise کنه، میان‌افزار باید همچنان یک خطِ
# لاگِ سطحِ ERROR (متد/مسیر/status=500/مدت/user_id، بدونِ جزئیاتِ
# حساس) ثبت کنه و بعد دقیقاً همون exceptionِ اصلی رو دوباره raise
# کنه — بدونِ اینکه هیچ رفتارِ Django/DRF یا exceptionِ دیگه‌ای رو
# تغییر بده. مستقیماً خودِ میان‌افزار (نه کلِ چرخه‌ی
# exception-handlingِ Django) تست می‌شه، چون همون لایه‌ای‌ست که این
# فیکس روش اعمال شده.
#
# ⚠️ اصلاح (باگِ خودِ تست، نه اپلیکیشن): قبلاً این تست فقط
# record.getMessage() رو چک می‌کرد. getMessage() خودش داخلی
# msg %% args رو انجام می‌ده، پس اگه شمارِ آرگومان‌ها با
# placeholderهای رشته جور نباشه، همون‌جا با یک exception (نه یک
# پیامِ نادرست) fail می‌شد و اصلاً به assertion نمی‌رسید. برای اینکه
# این تست واقعاً *صحتِ formatting* رو بسنجه (نه فقط اینکه یک‌جوری
# fail نشه)، حالا با logging.Formatter().format(record) دقیقاً
# همون مسیری که یک handlerِ واقعی (کنسول/فایل) طی می‌کنه رو صدا
# می‌زنیم و روی متنِ نهاییِ فرمت‌شده assert می‌کنیم.
request = RequestFactory().get('/api/some/failing/path')
def failing_get_response(inner_request):
raise ValueError('boom')
middleware = APIRequestLoggingMiddleware(failing_get_response)
with self.assertLogs('config.middleware', level='ERROR') as captured:
with self.assertRaises(ValueError):
middleware(request)
self.assertEqual(len(captured.records), 1)
record = captured.records[0]
self.assertEqual(record.levelname, 'ERROR')
formatted = logging.Formatter().format(record)
self.assertIn('method=GET', formatted)
self.assertIn('path=/api/some/failing/path', formatted)
self.assertIn('status=500', formatted)
self.assertIn('user_id=None', formatted)
class JSONLogFormatterTests(SimpleTestCase):
"""
🔒 اثبات فرمت‌کننده‌ی جدیدِ JSON (config.log_formatters.JSONLogFormatter)
که پروژه رو برای جمع‌آوریِ متمرکزِ لاگ (Loki/ELK-style) آماده می‌کنه:
خروجی باید یک JSON معتبر با فیلدهای timestamp/level/logger/message
باشه، و در صورتِ وجودِ exception، traceback هم به‌عنوانِ فیلدِ
"exception" اضافه بشه.
"""
def _make_record(self, level=logging.INFO, message='hello world', exc_info=None):
return logging.LogRecord(
name='some.logger',
level=level,
pathname=__file__,
lineno=1,
msg=message,
args=(),
exc_info=exc_info,
)
def test_basic_record_is_formatted_as_valid_json_with_expected_fields(self):
from config.log_formatters import JSONLogFormatter
record = self._make_record(level=logging.INFO, message='api_request method=GET path=/api/x status=200')
formatted = JSONLogFormatter().format(record)
payload = json.loads(formatted)
self.assertEqual(payload['level'], 'INFO')
self.assertEqual(payload['logger'], 'some.logger')
self.assertEqual(payload['message'], 'api_request method=GET path=/api/x status=200')
self.assertIn('timestamp', payload)
self.assertNotIn('exception', payload)
def test_record_with_exception_includes_traceback_field(self):
from config.log_formatters import JSONLogFormatter
try:
raise ValueError('boom')
except ValueError:
import sys
exc_info = sys.exc_info()
record = self._make_record(level=logging.ERROR, message='something failed', exc_info=exc_info)
formatted = JSONLogFormatter().format(record)
payload = json.loads(formatted)
self.assertEqual(payload['level'], 'ERROR')
self.assertEqual(payload['message'], 'something failed')
self.assertIn('exception', payload)
self.assertIn('ValueError: boom', payload['exception'])