fix(push): 完善厂商推送排障日志 (#202)

Co-authored-by: exinglang <exinglang@qq.com>
Reviewed-on: #202
Co-authored-by: zuochenyong <zuochenyong@wonderable.ai>
Co-committed-by: zuochenyong <zuochenyong@wonderable.ai>

app/admin/routers/feedback.py

@@ -1,6 +1,7 @@
 """admin 反馈工单:列表筛选 + 审核采纳/拒绝(带金币发放与审计)。"""
 from __future__ import annotations
 
+import logging
 from datetime import datetime
 from typing import Annotated
 
@@ -25,6 +26,8 @@ from app.models.feedback import Feedback
 from app.repositories import wallet as wallet_repo
 from app.services import notification_events
 
+logger = logging.getLogger("shagua.admin.feedback")
+
 router = APIRouter(
     prefix="/admin/api/feedbacks",
     tags=["admin-feedback"],
@@ -46,10 +49,24 @@ def _approve_feedback(
     *,
     bulk: bool = False,
 ) -> FeedbackOut:
+    logger.info(
+        "feedback approve started feedback_id=%s admin_id=%s bulk=%s",
+        feedback_id, admin.id, bulk,
+    )
     fb = db.get(Feedback, feedback_id, with_for_update=True)
     if fb is None:
+        logger.warning(
+            "feedback approve rejected not found feedback_id=%s admin_id=%s bulk=%s",
+            feedback_id, admin.id, bulk,
+        )
         raise HTTPException(status_code=404, detail="反馈不存在")
-    _ensure_pending(fb)
+    if fb.status not in {"pending", "new"}:
+        logger.warning(
+            "feedback approve rejected invalid status feedback_id=%s user_id=%s "
+            "admin_id=%s status=%s bulk=%s",
+            feedback_id, fb.user_id, admin.id, fb.status, bulk,
+        )
+        _ensure_pending(fb)
 
     before = fb.status
     mutations.review_feedback(
@@ -91,8 +108,18 @@ def _approve_feedback(
     )
     db.commit()
     db.refresh(fb)
+    logger.info(
+        "feedback approve committed feedback_id=%s user_id=%s admin_id=%s "
+        "before=%s after=%s reward_coins=%s bulk=%s",
+        feedback_id, fb.user_id, admin.id, before, fb.status, payload.reward_coins, bulk,
+    )
     out = FeedbackOut.model_validate(fb)
     notification_events.notify_feedback_reward(db, fb)
+    logger.info(
+        "feedback approve notification dispatch returned feedback_id=%s user_id=%s "
+        "admin_id=%s notification_type=feedback_reward bulk=%s",
+        feedback_id, fb.user_id, admin.id, bulk,
+    )
     return out
 
 
@@ -105,10 +132,24 @@ def _reject_feedback(
     *,
     bulk: bool = False,
 ) -> FeedbackOut:
+    logger.info(
+        "feedback reject started feedback_id=%s admin_id=%s bulk=%s",
+        feedback_id, admin.id, bulk,
+    )
     fb = db.get(Feedback, feedback_id, with_for_update=True)
     if fb is None:
+        logger.warning(
+            "feedback reject rejected not found feedback_id=%s admin_id=%s bulk=%s",
+            feedback_id, admin.id, bulk,
+        )
         raise HTTPException(status_code=404, detail="反馈不存在")
-    _ensure_pending(fb)
+    if fb.status not in {"pending", "new"}:
+        logger.warning(
+            "feedback reject rejected invalid status feedback_id=%s user_id=%s "
+            "admin_id=%s status=%s bulk=%s",
+            feedback_id, fb.user_id, admin.id, fb.status, bulk,
+        )
+        _ensure_pending(fb)
 
     before = fb.status
     mutations.review_feedback(
@@ -142,8 +183,18 @@ def _reject_feedback(
     )
     db.commit()
     db.refresh(fb)
+    logger.info(
+        "feedback reject committed feedback_id=%s user_id=%s admin_id=%s "
+        "before=%s after=%s bulk=%s",
+        feedback_id, fb.user_id, admin.id, before, fb.status, bulk,
+    )
     out = FeedbackOut.model_validate(fb)
     notification_events.notify_feedback_reply(db, fb)
+    logger.info(
+        "feedback reject notification dispatch returned feedback_id=%s user_id=%s "
+        "admin_id=%s notification_type=feedback_reply bulk=%s",
+        feedback_id, fb.user_id, admin.id, bulk,
+    )
     return out
 
 
@@ -201,6 +252,10 @@ def bulk_approve_feedbacks(
     admin: Annotated[AdminUser, Depends(require_role("operator"))],
     db: AdminDb,
 ) -> FeedbackBulkResult:
+    logger.info(
+        "feedback bulk approve started admin_id=%s item_count=%s",
+        admin.id, len(body.ids),
+    )
     results: list[FeedbackBulkItemResult] = []
     ip = get_client_ip(request)
     for feedback_id in body.ids:
@@ -209,11 +264,24 @@ def bulk_approve_feedbacks(
             results.append(FeedbackBulkItemResult(id=feedback_id, ok=True, status=out.status))
         except HTTPException as exc:
             db.rollback()
+            logger.warning(
+                "feedback bulk approve item failed feedback_id=%s admin_id=%s error=%s",
+                feedback_id, admin.id, exc.detail,
+            )
             results.append(FeedbackBulkItemResult(id=feedback_id, ok=False, error=str(exc.detail)))
         except Exception:  # noqa: BLE001 - 单笔失败不打断整批
             db.rollback()
+            logger.exception(
+                "feedback bulk approve item failed feedback_id=%s admin_id=%s",
+                feedback_id, admin.id,
+            )
             results.append(FeedbackBulkItemResult(id=feedback_id, ok=False, error="系统异常"))
-    return _bulk_result(results)
+    result = _bulk_result(results)
+    logger.info(
+        "feedback bulk approve completed admin_id=%s total=%s success=%s failed=%s",
+        admin.id, result.total, result.success, result.failed,
+    )
+    return result
 
 
 @router.post("/bulk/reject", response_model=FeedbackBulkResult, summary="批量拒绝采纳反馈")
@@ -223,6 +291,10 @@ def bulk_reject_feedbacks(
     admin: Annotated[AdminUser, Depends(require_role("operator"))],
     db: AdminDb,
 ) -> FeedbackBulkResult:
+    logger.info(
+        "feedback bulk reject started admin_id=%s item_count=%s",
+        admin.id, len(body.ids),
+    )
     results: list[FeedbackBulkItemResult] = []
     ip = get_client_ip(request)
     for feedback_id in body.ids:
@@ -231,11 +303,24 @@ def bulk_reject_feedbacks(
             results.append(FeedbackBulkItemResult(id=feedback_id, ok=True, status=out.status))
         except HTTPException as exc:
             db.rollback()
+            logger.warning(
+                "feedback bulk reject item failed feedback_id=%s admin_id=%s error=%s",
+                feedback_id, admin.id, exc.detail,
+            )
             results.append(FeedbackBulkItemResult(id=feedback_id, ok=False, error=str(exc.detail)))
         except Exception:  # noqa: BLE001 - 单笔失败不打断整批
             db.rollback()
+            logger.exception(
+                "feedback bulk reject item failed feedback_id=%s admin_id=%s",
+                feedback_id, admin.id,
+            )
             results.append(FeedbackBulkItemResult(id=feedback_id, ok=False, error="系统异常"))
-    return _bulk_result(results)
+    result = _bulk_result(results)
+    logger.info(
+        "feedback bulk reject completed admin_id=%s total=%s success=%s failed=%s",
+        admin.id, result.total, result.success, result.failed,
+    )
+    return result
 
 
 @router.post("/{feedback_id}/handle", response_model=OkResponse, summary="标记反馈已处理")
@@ -258,7 +343,16 @@ def approve_feedback(
     admin: Annotated[AdminUser, Depends(require_role("operator"))],
     db: AdminDb,
 ) -> FeedbackOut:
-    return _approve_feedback(db, admin, feedback_id, payload, get_client_ip(request))
+    try:
+        return _approve_feedback(db, admin, feedback_id, payload, get_client_ip(request))
+    except HTTPException:
+        raise
+    except Exception:
+        logger.exception(
+            "feedback approve failed feedback_id=%s admin_id=%s",
+            feedback_id, admin.id,
+        )
+        raise
 
 
 @router.post("/{feedback_id}/reject", response_model=FeedbackOut, summary="拒绝采纳反馈")
@@ -269,4 +363,13 @@ def reject_feedback(
     admin: Annotated[AdminUser, Depends(require_role("operator"))],
     db: AdminDb,
 ) -> FeedbackOut:
-    return _reject_feedback(db, admin, feedback_id, payload, get_client_ip(request))
+    try:
+        return _reject_feedback(db, admin, feedback_id, payload, get_client_ip(request))
+    except HTTPException:
+        raise
+    except Exception:
+        logger.exception(
+            "feedback reject failed feedback_id=%s admin_id=%s",
+            feedback_id, admin.id,
+        )
+        raise

app/integrations/vendor_push.py

@@ -347,6 +347,25 @@ def _response_summary(resp: Any, parsed: Any | None = None) -> str:
     return _raw_log_summary(getattr(resp, "text", ""))
 
 
+def _vendor_response_failed(vendor: str, data: dict[str, Any]) -> bool:
+    """识别 HTTP 200 中明确的厂商业务失败，避免将失败请求记录成 success。"""
+    if data.get("error") or data.get("success") is False:
+        return True
+    if vendor == "xiaomi":
+        code = data.get("code")
+        result = str(data.get("result", "ok")).lower()
+        return code not in (0, "0", None) or result not in ("ok", "success")
+    if vendor == "oppo" and data.get("code") is not None:
+        return int(data["code"]) != 0
+    if vendor == "vivo" and data.get("result") is not None:
+        return int(data["result"]) != 0
+    if vendor == "honor" and data.get("code") is not None:
+        return int(data["code"]) != 200
+    if vendor == "huawei" and data.get("code") is not None:
+        return str(data["code"]) != "80000000"
+    return False
+
+
 def _request_json(
     method: str,
     url: str,
@@ -410,13 +429,16 @@ def _request_json(
             _elapsed_ms(started),
         )
         raise VendorPushError(f"push invalid json: {resp.text[:200]}") from e
-    logger.info(
+    vendor_failed = _vendor_response_failed(vendor, data)
+    log = logger.warning if vendor_failed else logger.info
+    log(
         "vendor push http completed vendor=%s operation=%s method=%s endpoint=%s "
-        "outcome=success http_status=%s request=%s response=%s elapsed_ms=%.1f",
+        "outcome=%s http_status=%s request=%s response=%s elapsed_ms=%.1f",
         vendor,
         operation,
         method,
         _endpoint_for_log(url),
+        "vendor_error" if vendor_failed else "success",
         resp.status_code,
         request_summary,
         _response_summary(resp, data),
@@ -792,18 +814,21 @@ def _send_xiaomi(token: str, title: str, body: str, extras: dict[str, str]) -> d
 
 def _send_xiaomi_data(token: str, payload: dict[str, str]) -> dict[str, Any]:
     app_secret = _require(settings.XIAOMI_PUSH_APP_SECRET, "XIAOMI_PUSH_APP_SECRET")
+    form = {
+        "registration_id": token,
+        "restricted_package_name": settings.ANDROID_PACKAGE_NAME,
+        "payload": json.dumps(payload, ensure_ascii=False),
+        "pass_through": "1",
+        "time_to_live": str(settings.PUSH_TIME_TO_LIVE_SEC * 1000),
+    }
+    if settings.XIAOMI_PUSH_CHANNEL_ID.strip():
+        form["extra.channel_id"] = settings.XIAOMI_PUSH_CHANNEL_ID.strip()
     data = _request_form(
         "POST",
         settings.XIAOMI_PUSH_SEND_ENDPOINT,
         vendor="xiaomi",
         operation="send_data_event",
-        data={
-            "registration_id": token,
-            "restricted_package_name": settings.ANDROID_PACKAGE_NAME,
-            "payload": json.dumps(payload, ensure_ascii=False),
-            "pass_through": "1",
-            "time_to_live": str(settings.PUSH_TIME_TO_LIVE_SEC * 1000),
-        },
+        data=form,
         headers={"Authorization": f"key={app_secret}"},
     )
     code = data.get("code")

app/services/notification_events.py

@@ -85,6 +85,10 @@ def _dispatch(
     push_vars: dict[str, str] | None = None,
 ) -> Notification | None:
     """落一条站内消息并向该用户设备直推。返回落库行;去重命中/失败返回 None。"""
+    logger.info(
+        "notification dispatch started user_id=%s type=%s dedup_key=%s",
+        user_id, type_key, dedup_key,
+    )
     try:
         row = notif_repo.create_notification(
             db,
@@ -111,6 +115,10 @@ def _dispatch(
             logger.exception("rollback after notification failure also failed")
         return None
 
+    logger.info(
+        "notification created user_id=%s type=%s notification_id=%s dedup_key=%s",
+        user_id, type_key, row.id, dedup_key,
+    )
     _push_to_user_devices(db, row, push_vars)
     return row
 
@@ -124,17 +132,44 @@ def _push_to_user_devices(db: Session, row: Notification, push_vars: dict[str, s
         extras.update({str(k): str(v) for k, v in (row.extra or {}).items()})
         extras["notificationId"] = str(row.id)
 
-        for dev in device_repo.list_push_targets(db, user_id=row.user_id):
+        targets = device_repo.list_push_targets(db, user_id=row.user_id)
+        logger.info(
+            "push targets resolved user_id=%s type=%s notification_id=%s target_count=%s",
+            row.user_id, row.type, row.id, len(targets),
+        )
+        if not targets:
+            logger.warning(
+                "push skipped no targets user_id=%s type=%s notification_id=%s",
+                row.user_id, row.type, row.id,
+            )
+            return
+
+        sent = failed = skipped = data_sent = data_failed = 0
+        for dev in targets:
             vendor = vendor_push.normalize_vendor(dev.push_vendor)
             if not vendor or vendor not in vendor_push.SUPPORTED_VENDORS:
-                continue
-            if vendor_push.missing_settings(vendor):
-                # 本地/测试环境凭据不齐 → 只落站内消息,不发真推送(与 push/vendors 的报缺口径一致)
-                logger.info(
-                    "skip push (vendor %s not configured) user_id=%s type=%s",
-                    vendor, row.user_id, row.type,
+                skipped += 1
+                logger.warning(
+                    "push target skipped unsupported vendor user_id=%s type=%s "
+                    "notification_id=%s device_id=%s raw_vendor=%s normalized_vendor=%s",
+                    row.user_id, row.type, row.id, dev.device_id, dev.push_vendor, vendor,
                 )
                 continue
+            missing = vendor_push.missing_settings(vendor)
+            if missing:
+                skipped += 1
+                # 本地/测试环境凭据不齐 → 只落站内消息,不发真推送(与 push/vendors 的报缺口径一致)
+                logger.warning(
+                    "push target skipped vendor not configured user_id=%s type=%s "
+                    "notification_id=%s device_id=%s vendor=%s missing_settings=%s",
+                    row.user_id, row.type, row.id, dev.device_id, vendor, missing,
+                )
+                continue
+            logger.info(
+                "push send started user_id=%s type=%s notification_id=%s "
+                "device_id=%s vendor=%s",
+                row.user_id, row.type, row.id, dev.device_id, vendor,
+            )
             try:
                 response = vendor_push.send_notification(
                     vendor, dev.push_token, title=title, body=body, extras=extras
@@ -148,26 +183,44 @@ def _push_to_user_devices(db: Session, row: Notification, push_vars: dict[str, s
                         row.user_id, row.type, row.id, response,
                     )
                 logger.info(
-                    "push sent user_id=%s type=%s vendor=%s notification_id=%s",
-                    row.user_id, row.type, vendor, row.id,
+                    "push sent user_id=%s type=%s vendor=%s notification_id=%s device_id=%s",
+                    row.user_id, row.type, vendor, row.id, dev.device_id,
                 )
+                sent += 1
             except vendor_push.VendorPushError as e:
+                failed += 1
                 logger.warning(
-                    "push failed user_id=%s type=%s vendor=%s: %s", row.user_id, row.type, vendor, e
+                    "push failed user_id=%s type=%s vendor=%s notification_id=%s "
+                    "device_id=%s error=%s",
+                    row.user_id, row.type, vendor, row.id, dev.device_id, e,
                 )
             try:
-                vendor_push.send_data_event(
+                data_response = vendor_push.send_data_event(
                     vendor,
                     dev.push_token,
                     event=vendor_push.DATA_EVENT_NOTIFICATION_CREATED,
                     notification_id=str(row.id),
                 )
+                data_sent += 1
+                logger.info(
+                    "push data event completed user_id=%s type=%s vendor=%s "
+                    "notification_id=%s device_id=%s response=%s",
+                    row.user_id, row.type, vendor, row.id, dev.device_id, data_response,
+                )
             except vendor_push.VendorPushError as e:
+                data_failed += 1
                 # 透传只负责前台铃铛实时刷新，失败不能影响通知栏消息或站内消息。
                 logger.warning(
-                    "push data event failed user_id=%s type=%s vendor=%s: %s",
-                    row.user_id, row.type, vendor, e,
+                    "push data event failed user_id=%s type=%s vendor=%s notification_id=%s "
+                    "device_id=%s error=%s",
+                    row.user_id, row.type, vendor, row.id, dev.device_id, e,
                 )
+        logger.info(
+            "push dispatch completed user_id=%s type=%s notification_id=%s targets=%s "
+            "sent=%s failed=%s skipped=%s data_sent=%s data_failed=%s",
+            row.user_id, row.type, row.id, len(targets),
+            sent, failed, skipped, data_sent, data_failed,
+        )
     except Exception:  # noqa: BLE001 — 渲染/查设备等意外失败同样不外抛
         logger.exception("push notification failed user_id=%s type=%s", row.user_id, row.type)