Skip to content

fix: send high priority fcm messages#85

Open
d2weber wants to merge 1 commit into
chatmail:mainfrom
d2weber:high_priority
Open

fix: send high priority fcm messages#85
d2weber wants to merge 1 commit into
chatmail:mainfrom
d2weber:high_priority

Conversation

@d2weber
Copy link
Copy Markdown
Contributor

@d2weber d2weber commented May 31, 2026

I noticed that gplay push notifications are not reliable when the device has been locked for some minutes. My suspicion is this happens because of "Doze". I tried to reproduce the issue with a fairphone 3 by setting force-idle, which makes notifications stop working.

As far as I understand the docs about fcm data messages the default priority is "normal" and thus does not wake up the device from "Doze", so I created this PR.

I would need help testing this to check if it has the desired effect.

@link2xt
Copy link
Copy Markdown
Contributor

link2xt commented Jun 1, 2026

This looks reasonable, but the documentation also says this at https://firebase.google.com/docs/cloud-messaging/android-message-priority#deprioritize:

High priority messages on Android are meant for time sensitive, user visible content, and should result in user-facing notifications. If FCM detects a pattern in which messages don't result in user-facing notifications, your messages may be deprioritized to normal priority or delegated for handling by Google Play services.

Not every notification results in user visible message, e.g. for read receipts or duplicate messages (arriving in case of using multiple relays) nothing is shown. So it looks like Android may still detect this and then convert high priority into normal priority.

On the other hand, if this works at least sometimes in your testing, it is an improvement.

@d2weber
Copy link
Copy Markdown
Contributor Author

d2weber commented Jun 1, 2026

To me it seems to work in principle, so setting high-prio seems to improve reliability.

What I did:

  • adb shell dumpsys battery unplug (I'm connected to the device via usb, this makes the device think it's not charging)
  • adb shell dumpsys deviceidle force-idle
  • send dc message to profile on the device
  • trigger high-prio notification with curl

Only after the high-prio fcm message is sent, a notification comes through. (see log: ActivityManager: Background started FGS: Allowed: [...] reason:high-prio FCM)

I can see in the logs that DeltaChat continuously tries to fetch messages but fails due to network timeout (this happens even if no notification is received at all). Then, when the high-prio FCM allows for a wakeup, it still takes some seconds to recover from this fail-cycle until the fetch succeeds. But sometimes it never succeds and no notification is generated, even after high-prio fcm message. I suspect that receiving the high-prio message opens a time window where foreground activity is allowed, when we fail to fetch messages in that windows the notification is missed. Here is the logcat from the point in time where the high-prio fcm message is received:

$ adb logcat -s FcmReceiveService AlarmManager ActivityManager DeltaChat
06-01 12:33:02.469  2509 11711 I AlarmManager: setExactAndAllowWhileIdle [name: GCM_HB_ALARM type: 2 triggerAtMillis: 15052854]
06-01 12:33:02.480  2509 11758 I AlarmManager: setExactAndAllowWhileIdle [name: FcmRetry type: 2 triggerAtMillis: 14332864]
06-01 12:33:02.496  6404  6424 I DeltaChat: ++++++++++++++++++ NetworkCallback.onBlockedStatusChanged() #26
06-01 12:33:02.508  2509 11711 I AlarmManager: setExactAndAllowWhileIdle [name: GCM_HB_ALARM type: 2 triggerAtMillis: 15052893]
06-01 12:33:02.508  6404 11774 I FcmReceiveService: FCM push notification received
06-01 12:33:02.513  1388  8265 I ActivityManager: Background started FGS: Allowed [callingPackage: chat.delta; callingUid: 10156; uidState: SVC ; intent: Intent { cmp=chat.delta/org.thoughtcrime.securesms.service.FetchForegroundService }; code:PUSH_MESSAGING; tempAllowListReason:<broadcast:u0a84:com.google.android.c2dm.intent.RECEIVE,reason:high-prio FCM,reasonCode:PUSH_MESSAGING,duration:20000,callingUid:10084>; targetSdkVersion:36; callerTargetSdkVersion:36; startForegroundCount:0; bindFromPackage:null]
06-01 12:33:02.523  1388  2904 W ActivityManager: Foreground service started from background can not have location/camera/microphone access: service chat.delta/org.thoughtcrime.securesms.service.FetchForegroundService
06-01 12:33:02.525  6404  6426 I DeltaChat: [accId=0] Starting background fetch for 1 accounts.
06-01 12:33:02.526  6404  6426 I DeltaChat: [accId=1] src/context.rs:611: background_fetch started fetching gwlvoz2hy@nine.testrun.org.
06-01 12:33:02.527  6404  6426 I DeltaChat: [accId=1] src/scheduler.rs:740: SMTP fake idle interrupted.
06-01 12:33:02.528  6404  6426 I DeltaChat: [accId=1] src/smtp.rs:522: Selected rows from SMTP queue: [].
06-01 12:33:02.528  6404  6426 I DeltaChat: [accId=1] src/smtp.rs:639: Sending MDNs.
06-01 12:33:02.530  6404  6426 I DeltaChat: [accId=1] src/scheduler.rs:708: SMTP fake idle started.
06-01 12:33:02.531  6404  6426 I DeltaChat: [accId=1] src/scheduler.rs:736: SMTP has no messages to retry, waiting for interrupt.
06-01 12:33:04.440  6404  6426 W DeltaChat: [accId=1] src/imap/client.rs:151: IMAP failed to connect to nine.testrun.org (116.202.233.236:993): Connection failure: Connection refused (os error 111).
06-01 12:33:13.361  5086  5212 W DeltaChat: [accId=1] src/imap/client.rs:151: IMAP failed to connect to nine.testrun.org (128.140.126.197:143): Connection to 128.140.126.197:143 failed: Connection timed out (os error 110).
06-01 12:33:13.361  5086  5212 W DeltaChat: [accId=1] src/imap/client.rs:151: IMAP failed to connect to nine.testrun.org (77.42.49.41:143): Connection to 77.42.49.41:143 failed: Connection timed out (os error 110).
06-01 12:33:14.641  5086  5212 W DeltaChat: [accId=1] src/imap/client.rs:151: IMAP failed to connect to nine.testrun.org (216.144.228.100:143): Connection to 216.144.228.100:143 failed: Connection timed out (os error 110).
06-01 12:33:15.281  6404  6426 W DeltaChat: [accId=1] src/imap/client.rs:151: IMAP failed to connect to nine.testrun.org (128.140.126.197:993): Connection failure: Connection timed out (os error 110).
06-01 12:33:15.921  6404  6426 W DeltaChat: [accId=1] src/imap/client.rs:151: IMAP failed to connect to nine.testrun.org (77.42.49.41:993): Connection failure: Connection timed out (os error 110).
06-01 12:33:16.560  6404  6426 W DeltaChat: [accId=1] src/imap/client.rs:151: IMAP failed to connect to nine.testrun.org (216.144.228.100:993): Connection failure: Connection timed out (os error 110).
06-01 12:33:16.561  6404  6426 W DeltaChat: [accId=1] src/imap.rs:371: IMAP failed to connect to nine.testrun.org:993:tls: Connection failure: Network is unreachable (os error 101).
06-01 12:33:16.561  6404  6426 W DeltaChat: [accId=1] src/scheduler.rs:378: Transport 1: Failed to prepare inbox connection: IMAP failed to connect to nine.testrun.org:143:starttls: Connection failure: Network is unreachable (os error 101).
06-01 12:33:16.561  6404  6426 I DeltaChat: [accId=1] src/scheduler.rs:372: Transport 1: Preparing new IMAP session for inbox.
06-01 12:33:16.561  6404  6426 I DeltaChat: [accId=1] src/imap.rs:343: Connecting to IMAP server.
06-01 12:33:16.565  6404  6426 I DeltaChat: [accId=1] src/imap.rs:358: IMAP trying to connect to nine.testrun.org:143:starttls.
06-01 12:33:16.565  6404  6426 I DeltaChat: [accId=1] src/net/dns.rs:134: Using memory-cached DNS resolution for nine.testrun.org.
06-01 12:33:16.565  6404  6426 I DeltaChat: [accId=1] src/net/dns.rs:180: Resolved nine.testrun.org into 77.42.49.41.
06-01 12:33:16.568  6404  6426 I DeltaChat: [accId=1] src/net/dns.rs:180: Resolved nine.testrun.org into 2a01:4f9:fff1:59::1.
06-01 12:33:16.573  6404  6426 I DeltaChat: [accId=1] src/imap/client.rs:122: Attempting IMAP connection to nine.testrun.org (77.42.49.41:143).
06-01 12:33:16.811  6404  6426 I DeltaChat: [accId=1] src/imap.rs:396: Logging into IMAP server with LOGIN.
06-01 12:33:16.959  6404  6426 I DeltaChat: [accId=1] src/imap.rs:439: Successfully logged into IMAP server.
06-01 12:33:16.959  6404  6426 I DeltaChat: [accId=1] src/scheduler.rs:385: Transport 1: Prepared new IMAP session for inbox.
06-01 12:33:16.960  6404  6426 I DeltaChat: [accId=1] src/quota.rs:128: Transport 1: Updating quota.
06-01 12:33:17.008  6404  6426 I DeltaChat: [accId=1] src/quota.rs:171: Transport 1: Updated quota.
06-01 12:33:17.060  6404  6426 I DeltaChat: [accId=1] src/imap/select_folder.rs:82: Transport 1: Selected folder "INBOX".
06-01 12:33:17.061  6404  6426 I DeltaChat: [accId=1] src/imap.rs:614: fetch_new_msg_batch(INBOX): UIDVALIDITY=1780169462, UIDNEXT=38.
06-01 12:33:17.114  6404  6426 I DeltaChat: [accId=1] src/imap.rs:747: "a3dd386c-4d49-4b4c-8013-ee5c35e72f9e@localhost" is not a post-message.
06-01 12:33:17.114  6404  6426 I DeltaChat: [accId=1] src/imap.rs:1328: Starting UID FETCH of message set "38".
06-01 12:33:17.160  6404  6426 I DeltaChat: [accId=1] src/imap.rs:1418: Passing message UID 38 to receive_imf().
06-01 12:33:17.193  6404  6426 I DeltaChat: [accId=1] src/receive_imf.rs:523: Receiving message "a3dd386c-4d49-4b4c-8013-ee5c35e72f9e@localhost", seen=false...
06-01 12:33:17.197  6404  6426 I DeltaChat: [accId=1] src/receive_imf.rs:1459: Non-group reply. num_recipients=1. from_id=Contact#10. Chat assignment = OneOneChat.
06-01 12:33:17.208  6404  6426 I DeltaChat: [accId=1] src/receive_imf.rs:2375: Message has 1 parts and is assigned to chat #Chat#12, timestamp=1780309971.
06-01 12:33:17.209  6404  6426 I DeltaChat: [accId=1] src/contact.rs:2159: Recently seen loop waiting for 0h 9m 34s or interrupt
06-01 12:33:17.252  6404  6426 I DeltaChat: [accId=1] src/imap.rs:1463: Successfully received 1 UIDs.
06-01 12:33:17.252  6404  6426 I DeltaChat: [accId=1] src/imap.rs:819: 1 mails read from "INBOX".
06-01 12:33:17.252  6404  6426 I DeltaChat: [accId=1] src/imap.rs:828: available_post_msgs: 0, download_later: 0.
06-01 12:33:17.269  6404  6426 I DeltaChat: [accId=1] src/imap/idle.rs:47: Transport 1: Skip IDLE in "INBOX" because we got interrupt.
06-01 12:33:17.270  6404  6426 I DeltaChat: [accId=1] src/imap.rs:576: Transport 1: No new emails in folder "INBOX".
06-01 12:33:17.318  6404  6426 I DeltaChat: [accId=1] src/context.rs:653: background_fetch done for gwlvoz2hy@nine.testrun.org took 14.791118432s.
06-01 12:33:17.318  6404  6426 I DeltaChat: [accId=0] Finished background fetch for 1 accounts.
06-01 12:33:17.367  6404  6426 I DeltaChat: [accId=1] src/imap/idle.rs:67: Transport 1: IDLE entering wait-on-remote state in folder "INBOX".
06-01 12:33:18.478  5086  5212 W DeltaChat: [accId=1] src/imap/client.rs:151: IMAP failed to connect to nine.testrun.org (116.202.233.236:143): Connection to 116.202.233.236:143 failed: Connection timed out (os error 110).
06-01 12:33:18.478  5086  5212 W DeltaChat: [accId=1] src/imap.rs:368: IMAP failed to connect to nine.testrun.org:143:starttls: All connection attempts failed: Connection to [2a01:4f9:fff1:59::1]:143 failed: Network is unreachable (os error 101); Connection to [2a01:4f8:241:4ce8::2]:143 failed: Network is unreachable (os error 101); Connection to [2001:41d0:701:1100::8ab1]:143 failed: Network is unreachable (os error 101); Connection to 128.140.126.197:143 failed: Connection timed out (os error 110); Connection to 77.42.49.41:143 failed: Connection timed out (os error 110); Connection to 216.144.228.100:143 failed: Connection timed out (os error 110); Connection to 116.202.233.236:143 failed: Connection timed out (os error 110).
06-01 12:33:18.479  5086  5212 I DeltaChat: [accId=1] src/imap.rs:355: IMAP trying to connect to nine.testrun.org:443:tls.
06-01 12:33:18.479  5086  5212 I DeltaChat: [accId=1] src/net/dns.rs:134: Using memory-cached DNS resolution for nine.testrun.org.
06-01 12:33:18.479  5086  5212 I DeltaChat: [accId=1] src/net/dns.rs:180: Resolved nine.testrun.org into 77.42.49.41.
06-01 12:33:18.480  5086  5212 I DeltaChat: [accId=1] src/net/dns.rs:180: Resolved nine.testrun.org into 2a01:4f9:fff1:59::1.
06-01 12:33:18.483  5086  5212 I DeltaChat: [accId=1] src/imap/client.rs:122: Attempting IMAP connection to nine.testrun.org (77.42.49.41:443).
06-01 12:33:18.785  5086  5212 I DeltaChat: [accId=1] src/imap/client.rs:122: Attempting IMAP connection to nine.testrun.org ([2a01:4f9:fff1:59::1]:443).
06-01 12:33:18.793  5086  5212 W DeltaChat: [accId=1] src/imap/client.rs:151: IMAP failed to connect to nine.testrun.org ([2a01:4f9:fff1:59::1]:443): Connection to [2a01:4f9:fff1:59::1]:443 failed: Network is unreachable (os error 101).
06-01 12:33:18.797  5086  5212 I DeltaChat: [accId=1] src/imap/client.rs:122: Attempting IMAP connection to nine.testrun.org (216.144.228.100:443).
06-01 12:33:19.484  5086  5212 I DeltaChat: [accId=1] src/imap/client.rs:122: Attempting IMAP connection to nine.testrun.org (128.140.126.197:443).

I tested with "Force background connection" off (when it's on, notifications arrived even with force-idle).

I also tried to trigger the conversion to "normal priority" by posting to /notify 300 times while never creating any user visible effect, but I never saw the conversion "normal priority".

Tested with FP3 on Android 13 and FP5 on Android 15.

@link2xt
Copy link
Copy Markdown
Contributor

link2xt commented Jun 1, 2026

I also tried to trigger the conversion to "normal priority" by posting to /notify 300 times while never creating any user visible effect, but I never saw the conversion "normal priority".

Documentation says "FCM uses 7 days of message behavior when determining whether to deprioritize or proxy messages; it makes this determination independently for every instance of your application. If, in response to high priority messages, notifications are displayed in a way that is visible to the user, then your future high-priority messages won't be affected.", so if this is correct, it will not happen immediately, but after 7 days of such usage.

@r10s
Copy link
Copy Markdown
Contributor

r10s commented Jun 1, 2026

thanks a lot for looking closely, this is a minefield, probably.

i checked our source code - and we show smth user-visible in all cases it seems: https://github.com/deltachat/deltachat-android/blob/main/src/gplay/java/org/thoughtcrime/securesms/notifications/FcmReceiveService.java#L90 - for "priority high" we open FetchForegroundService which will display a notification during fetching at least. maybe that is sufficient

i wanted to check what signal is doing there but got lost somehow. that would indeed be interesting what others are doing in these cases, it is not only us who have to deal with eg. muted chats that are known to the client only

cc @adbenitez @wchen342

Copy link
Copy Markdown
Contributor

@link2xt link2xt left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we can deploy it in any case, even if FCM later deprioritizes it to normal it's not worse than before.

On deltachat-android side we maybe need to always ask for "disable battery optimization" even on non-chatmail and when FCM is available since we currently have no way to distinguish between low and high priority.

Or we will need to expose whether the message is high priority unencrypted to distinguish actual messages from read receipts. And even then, there are duplicates, so we will need to increase debouncing interval, otherwise if messages do not arrive exactly at the same time we are still notifying duplicates with high priority and they will not create notifications. EDIT: I wrote this before message from @r10 above, displaying "Downloading messages..." and then removing it likely should indeed be good enough.

@d2weber
Copy link
Copy Markdown
Contributor Author

d2weber commented Jun 1, 2026

Then, when the high-prio FCM allows for a wakeup, it still takes some seconds to recover from this fail-cycle until the fetch succeeds. But sometimes it never succeds and no notification is generated, even after high-prio fcm message.

To make it work also in this case, it might make sense to stop and restart io in onBlockedStatusChanged. That would make it possible to fetch messages immediately after the high-prio fcm message and avoid this problem (because we would not have to wait for the network timeout and the following retry). I can try to sketch a PR to do this, or I open an issue first if you prefer.

@link2xt
Copy link
Copy Markdown
Contributor

link2xt commented Jun 1, 2026

To make it work also in this case, it might make sense to stop and restart io in onBlockedStatusChanged. That would make it possible to fetch messages immediately after the high-prio fcm message and avoid this problem (because we would not have to wait for the network timeout and the following retry). I can try to sketch a PR to do this, or I open an issue first if you prefer.

Probably better open an issue in https://github.com/deltachat/deltachat-android first, it's indeed a bug that we call maybe_network when the network is blocked. Restarting I/O should not be needed as it closes all the connections and opens them, but maybe_network is better called only when the network is known to be unblocked.

@p1gp1g (author of deltachat/deltachat-android#4251, #53) also previously pointed me to https://codeberg.org/UnifiedPush/android-distributor/src/commit/966808bb164536a87be8cd4de7f1cbd2008a5236/distributor/src/main/java/org/unifiedpush/android/distributor/callback/NetworkCallback.kt, there is additional logic to keep track of VPN status and it is debugged already, maybe makes sense to use it as a reference.

@p1gp1g
Copy link
Copy Markdown
Contributor

p1gp1g commented Jun 2, 2026

Regarding deprioritization: as the Google Play Services are opaque, we don't know when the application may be deprioritized.

Especially:

  • The Foreground Service notification is usually shown once, so what happen when we receive another push notif, when the Foreground Service notification is already shown?
  • Often, applications start a foreground service to fetch new messages, and show that notification for the time of the process. If this notification lives for a short time, like a few seconds, but we can't be sure short-live notifications are accounted to avoid deprioritization.

In my opinion, it would be great to either, or both:

  • Have a way to follow how many apps are deprioritized. I think that's accessible on the Firebase Console
  • When the app is deprioritzed (getPriority() != getOriginalPriority()), ask the permission to allow the app to run in the background without restrictions.

As deprioritized notifs set the priority to normal, which is the current priority, this PR seems reasonable to me.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants