From 777568e5b9485a7465e172da2a8d6ef4c5de12f2 Mon Sep 17 00:00:00 2001 From: denis0001-dev Date: Wed, 8 Apr 2026 15:18:01 +0300 Subject: [PATCH] Add push debug code --- backend/services/main/push_service.py | 116 ++++++++++++++++++++-- backend/services/main/routes/messaging.py | 42 +++++++- 2 files changed, 144 insertions(+), 14 deletions(-) diff --git a/backend/services/main/push_service.py b/backend/services/main/push_service.py index cbcd463..abd2934 100644 --- a/backend/services/main/push_service.py +++ b/backend/services/main/push_service.py @@ -32,6 +32,12 @@ def _load_firebase_service_account_dict(cert_path: Path) -> dict: class PushNotificationService: + def _short_token(self, token: str) -> str: + value = (token or "").strip() + if len(value) <= 14: + return value + return f"...{value[-8:]}" + def __init__(self): self.vapid_private_key = os.getenv("VAPID_PRIVATE_KEY") self.vapid_public_key = os.getenv("VAPID_PUBLIC_KEY") @@ -87,16 +93,34 @@ class PushNotificationService: async def send_public_message_notification(self, db: Session, message: Message, exclude_user_id: Optional[int] = None): """Send push notification for a new public chat message""" + logger.info( + "send_public_message_notification start: message_id=%s sender_id=%s exclude_user=%s", + message.id, + message.user_id, + exclude_user_id, + ) try: # Get all users except the sender users = db.query(User).filter(User.id != message.user_id) if exclude_user_id: users = users.filter(User.id != exclude_user_id) + user_list = users.all() + logger.debug( + "send_public_message_notification targets=%s", + [user.id for user in user_list], + ) + logger.info( + "send_public_message_notification user_count=%s for message_id=%s", + len(user_list), + message.id, + ) - for user in users: + for user in user_list: # Check if user has push subscription before trying to send # Try all FCM tokens first (Android). If none or all fail, fall back to web push subscription. fcm_rows = db.query(FcmToken).filter(FcmToken.user_id == user.id).all() + if not fcm_rows: + logger.debug("No FCM tokens for user %s for message %s", user.id, message.id) payload_data = { "type": "public_message", "message_id": message.id, @@ -105,15 +129,41 @@ class PushNotificationService: } title = f"{message.author.username}" body = message.content[:100] + ("..." if len(message.content) > 100 else "") + logger.debug( + "send_public_message_notification: user=%s fcm_tokens=%d", + user.id, + len(fcm_rows), + ) if fcm_rows and self.firebase_initialized: for fcm in fcm_rows: try: - self._send_fcm_to_token(fcm.token, title, body, payload_data) + response = self._send_fcm_to_token( + fcm.token, + title, + body, + payload_data, + ) + logger.info( + "FCM public push sent user=%s token=%s response=%s", + user.id, + self._short_token(fcm.token), + response, + ) except Exception as e: - logger.error(f"Failed to send FCM to user {user.id} token {fcm.token}: {e}") + logger.error( + "Failed to send FCM to user %s token %s: %s", + user.id, + self._short_token(fcm.token), + e, + ) # Check if this is a permanent failure and clean up the token self._cleanup_failed_fcm_token(db, fcm, str(e)) + if fcm_rows and not self.firebase_initialized: + logger.warning( + "Firebase SDK not initialized, skipped FCM pushes for message %s", + message.id, + ) subscription = db.query(PushSubscription).filter(PushSubscription.user_id == user.id).first() if subscription: @@ -125,6 +175,12 @@ class PushNotificationService: async def send_dm_notification(self, db: Session, dm_envelope: DMEnvelope, sender: User): """Send push notification for a new DM""" + logger.info( + "send_dm_notification start: dm_id=%s sender_id=%s recipient=%s", + dm_envelope.id, + sender.id, + dm_envelope.recipient_id, + ) try: title = f"{sender.username}" body = "New direct message" @@ -136,14 +192,40 @@ class PushNotificationService: } fcm_rows = db.query(FcmToken).filter(FcmToken.user_id == dm_envelope.recipient_id).all() + logger.debug( + "send_dm_notification: recipient=%s fcm_tokens=%d", + dm_envelope.recipient_id, + len(fcm_rows), + ) if fcm_rows and self.firebase_initialized: for fcm in fcm_rows: try: - self._send_fcm_to_token(fcm.token, title, body, payload_data) + response = self._send_fcm_to_token( + fcm.token, + title, + body, + payload_data, + ) + logger.info( + "FCM dm push sent recipient=%s token=%s response=%s", + dm_envelope.recipient_id, + self._short_token(fcm.token), + response, + ) except Exception as e: - logger.error(f"Failed to send FCM to user {dm_envelope.recipient_id} token {fcm.token}: {e}") + logger.error( + "Failed to send FCM to user %s token %s: %s", + dm_envelope.recipient_id, + self._short_token(fcm.token), + e, + ) # Check if this is a permanent failure and clean up the token self._cleanup_failed_fcm_token(db, fcm, str(e)) + if fcm_rows and not self.firebase_initialized: + logger.warning( + "Firebase SDK not initialized, skipped FCM DM push for dm %s", + dm_envelope.id, + ) await self._send_notification_to_user( db, dm_envelope.recipient_id, title, body, sender.profile_picture, payload_data @@ -155,6 +237,8 @@ class PushNotificationService: """Send a push notification to a specific user""" try: subscription = db.query(PushSubscription).filter(PushSubscription.user_id == user_id).first() + if not subscription: + logger.debug("No web push subscription for user %s", user_id) if not subscription: return @@ -180,6 +264,7 @@ class PushNotificationService: vapid_private_key=self.vapid_private_key, vapid_claims=self.vapid_claims ) + logger.info("WebPush sent to user=%s", user_id) except WebPushException as e: logger.error(f"WebPush error for user {user_id}: {e}") @@ -210,9 +295,10 @@ class PushNotificationService: apns=firebase_messaging.APNSConfig(headers={"apns-priority": "10"}) ) resp = firebase_messaging.send(msg) + logger.debug("Firebase message queued token=%s", self._short_token(token)) return resp except Exception as e: - logger.error(f"Firebase Admin send failed for token {token}: {e}") + logger.error("Firebase Admin send failed for token %s: %s", self._short_token(token), e) raise def _cleanup_failed_fcm_token(self, db: Session, fcm_token_entry, error_message: str): @@ -228,13 +314,25 @@ class PushNotificationService: is_permanent = any(permanent_error in error_lower for permanent_error in permanent_errors) if is_permanent: - logger.info(f"Removing permanently failed FCM token for user {fcm_token_entry.user_id}: {fcm_token_entry.token}") + logger.info( + "Removing permanently failed FCM token for user %s: %s", + fcm_token_entry.user_id, + self._short_token(fcm_token_entry.token), + ) db.query(FcmToken).filter(FcmToken.id == fcm_token_entry.id).delete() db.commit() else: - logger.debug(f"Temporary FCM failure for token {fcm_token_entry.token}, keeping token: {error_message}") + logger.debug( + "Temporary FCM failure for token %s, keeping token: %s", + self._short_token(fcm_token_entry.token), + error_message, + ) except Exception as e: - logger.error(f"Failed to cleanup FCM token {fcm_token_entry.token}: {e}") + logger.error( + "Failed to cleanup FCM token for user %s: %s", + fcm_token_entry.user_id, + e, + ) try: db.rollback() except Exception: diff --git a/backend/services/main/routes/messaging.py b/backend/services/main/routes/messaging.py index 04b24f8..5335345 100644 --- a/backend/services/main/routes/messaging.py +++ b/backend/services/main/routes/messaging.py @@ -419,6 +419,12 @@ async def _send_message_internal( # Send push notifications for public messages try: + logger.info( + "Public message saved: id=%s user=%s content_length=%s", + new_message.id, + current_user.id, + len(new_message.content or ""), + ) await push_service.send_public_message_notification(db, new_message, exclude_user_id=current_user.id) except Exception as e: logger.error(f"Failed to send push notification for message {new_message.id}: {e}") @@ -504,7 +510,11 @@ async def register_fcm_token(request: Request, body: RegisterFcmRequest, current new = FcmToken(user_id=current_user.id, token=token) db.add(new) db.commit() - logger.info(f"Registered FCM token for user {current_user.id}: {token}") + logger.info( + "Registered FCM token for user %s: ...%s", + current_user.id, + token[-8:], + ) except Exception as e: try: db.rollback() @@ -521,9 +531,15 @@ async def unregister_fcm_token(request: Request, body: RegisterFcmRequest | None Unregister an FCM token. If `body.token` provided, remove only that token for the user. If no token provided, remove all tokens for the user. """ + token = body.token.strip() if body and body.token else None + logger.info( + "Unregister FCM request user=%s token=%s", + current_user.id, + f"...{token[-8:]}" if token else "ALL", + ) try: - if body and body.token: - db.query(FcmToken).filter(FcmToken.user_id == current_user.id, FcmToken.token == body.token.strip()).delete() + if token: + db.query(FcmToken).filter(FcmToken.user_id == current_user.id, FcmToken.token == token).delete() else: db.query(FcmToken).filter(FcmToken.user_id == current_user.id).delete() db.commit() @@ -546,6 +562,11 @@ async def push_test(request: Request, current_user: User = Depends(get_current_u fcm_rows = db.query(FcmToken).filter(FcmToken.user_id == current_user.id).all() if not fcm_rows: raise HTTPException(status_code=404, detail="No FCM token registered for user") + logger.info( + "push_test start: user=%s token_count=%s", + current_user.id, + len(fcm_rows), + ) title = "FromChat test" body = "This is a test push from the server" @@ -555,9 +576,20 @@ async def push_test(request: Request, current_user: User = Depends(get_current_u failures = [] for fcm in fcm_rows: try: - push_service._send_fcm_to_token(fcm.token, title, body, data) + response = push_service._send_fcm_to_token(fcm.token, title, body, data) + logger.info( + "push_test sent user=%s token=%s response=%s", + current_user.id, + f"{fcm.token[-8:]}", + response, + ) except Exception as e: - logger.error(f"Failed to send test push to user {current_user.id} token {fcm.token}: {e}") + logger.error( + "Failed to send test push to user %s token %s: %s", + current_user.id, + f"...{fcm.token[-8:]}", + e, + ) failures.append(str(e)) if failures and len(failures) == len(fcm_rows):