Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[firebase_messaging] App remains functional but no notifications are received until app is force killed and restarted #3052

Closed
wesQ3 opened this issue Jul 28, 2020 · 2 comments · Fixed by #4012

Comments

@wesQ3
Copy link

wesQ3 commented Jul 28, 2020

Describe the bug
I have a functioning Flutter firebase_messaging app using FCM data messages and flutter_local_notifications to render high priority notifications. Both foreground and background messages are functioning and result in a notification shown to the user. However, on some user devices, the app eventually stops receiving notifications, even if the user opens and interacts with the (still functioning) app. The device that exhibits the behavior most is a Bullitt Group Cat S61.

  • I use Amazon SNS to send the FCM messages. Cloudwatch logs confirm that all messages are passed to FCM successfully and a success response is received from FCM.
  • I use FLog to log received FCM messages in their handlers so each message is visible in the logs. These missed messages do not show anything in the logs which leads me to believe the messages are not arriving to the app at all.
  • The app is exempted from user-visible background restriction and battery optimization
  • After a Force-kill and restart, the app begins receiving messages again.

I understand that an app that has been killed is unable to receive broadcasts and aggressive OEM battery optimization can kill apps prematurely. That isn't the case here where the app is exempted from battery & background processing limits. Additionally, once in this state the app does not appear to receive FCMs in the foreground or after recent use.

To Reproduce
Repro steps are hard to describe. My tester reports getting dozens of messages successfully over 24 hours or so until they stop and none are received until the app is force killed and restarted. The point at which the messages stop does not seem to match up with app usage time. Of course this state does not occur running from the debugger.

Expected behavior
I expect each FCM message to trigger either of the onMessage or onBackgroundMessage callbacks.

Additional Questions
How can I determine if this is an issue with my app or with the operating system / some OEM "feature"?
Is there a way to confirm that the FCM push is delivered to the phone (outside of my app logs, which do not show it)?
Is there a way to log from the firebase_messaging plugin to determine if the FlutterFirebaseMessagingService is being called correctly?

Flutter doctor

[✓] Flutter (Channel master, 1.20.0-1.0.pre, on Linux, locale en_US.UTF-8)
    • Flutter version 1.20.0-1.0.pre at /home/wes/code/flutter
    • Framework revision 248d746575 (6 weeks ago), 2020-06-15 14:46:09 -0700
    • Engine revision 965fbbed17
    • Dart version 2.9.0 (build 2.9.0-14.0.dev 2b917f5b6a)

[✓] Android toolchain - develop for Android devices (Android SDK version 29.0.2)
    • Android SDK at /home/wes/Android/Sdk
    • Platform android-29, build-tools 29.0.2
    • Java binary at: /opt/android-studio/jre/bin/java
    • Java version OpenJDK Runtime Environment (build 1.8.0_242-release-1644-b3-6222593)
    • All Android licenses accepted.

[✓] Android Studio (version 4.0)
    • Android Studio at /opt/android-studio
    • Flutter plugin version 47.1.2
    • Dart plugin version 193.7361
    • Java version OpenJDK Runtime Environment (build 1.8.0_242-release-1644-b3-6222593)

[✓] VS Code (version 1.47.2)
    • VS Code at /usr/share/code
    • Flutter extension version 3.12.2

[!] Connected device
    ! No devices available
@wesQ3
Copy link
Author

wesQ3 commented Jul 29, 2020

The FCM diagnostics view available at *#*#426#*#* confirms that the FCM messages are arriving on the device.*

I can't copy the logs out of the text control for some reason but I see lines for

Received <PACKAGE_ID> <MESSAGE_ID>
Successful broadcast to <PACKAGE_ID> <MESSAGE_ID>
Acked <PACKAGE_ID> <MESSAGE_ID>

But this message did not appear in my Flutter app, either in onMessage or onBackgroundMessage. My current thought is that the message is sent to the app but it is not making the jump from FirebaseMessagingPlugin to my Dart handlers. As no logging is present in the plugin I am going to fork the plugin to add it.

* The FCM logs do show an error when a message is received for a force-killed app. Failed to broadcast to stopped app <PACKAGE_ID>

@wesQ3
Copy link
Author

wesQ3 commented Jul 31, 2020

The extra logs I added to FlutterFirebaseMessagingService.java have been helpful. Android has killed the app, and the newly spawned background isolate cannot pass a message back to the main isolate to handle it.

I am using a ReceivePort/SendPort pair to pass messages from the background message isolate to the main isolate. As the documentation for ReceivePort states:

Together with SendPort, the only means of communication between isolates.

my ReceivePort message handler

In my remote message class, instantiated from main.dart:

final ReceivePort bgMsgPort = ReceivePort();
// ...
IsolateNameServer.registerPortWithName(bgMsgPort.sendPort, bgMsgIsolateName);
bgMsgPort.listen(onBgIsolateMessage); // logs the message received and displays a LocalNotification

And the callback passed as onBackgroundMessage:

Future<dynamic> onBackgroundMessage(Map<String, dynamic> message) async {
  final port = IsolateNameServer.lookupPortByName(bgMsgIsolateName);
  if (port == null) {
    print('No port found in lookup on IsolateNameServer!');
    return Future.value(true);
  }
  port.send(message);
}

In a successful background message display, I can see in the logs the message arriving at the background handler, passing through the SendPort and the main isolate handling the message, displaying the notification and sending a http confirmation to my backend.

a successful background message
07-31 10:07:17.958 21538 21538 D FlutterFcmService: onCreate: service init complete
07-31 10:07:17.971 21538 22871 D FlutterFcmService: oMR: application is NOT in foreground
07-31 10:07:17.971 21538 22871 D FlutterFcmService: oMR: bg isolate is running, executeDartCallbackInBackgroundIsolate
07-31 10:07:17.971 21538 21538 D FlutterFcmService: executeDartCallbackInBackgroundIsolate
07-31 10:07:17.971 21538 21538 D FlutterFcmService: latch is not null, get LatchResult
07-31 10:07:17.972 21538 21538 D FlutterFcmService: invoke background message handler
07-31 10:07:17.975 21538 22871 D FlutterFcmService: oMR: bg isolate callback complete, latch released
07-31 10:07:17.996 21538 21648 I flutter : onBackgroundMessage : recv bg msg: {data: {id: 154784, body: okok , title: test message, click_action: FLUTTER_NOTIFICATION_CLICK}}
... message handling continues successfully

On a failure I get no response from my app and no logs (since only the main isolate can log with FLog). But the extra logging I added to the plugin service reveal the problem:

07-31 08:25:29.990 18534 18534 D FlutterFcmService: onCreate: service init complete
07-31 08:25:29.991 18534 18534 D FlutterFcmService: onCreate: bg isolate is not running yet
07-31 08:25:30.001 18534 18534 D FlutterFcmService: startBgI: bg isolate starting
07-31 08:25:30.133 18534 18534 D FlutterFcmService: startBgI: bg isolate started with backgroundFlutterView
07-31 08:25:30.134 18534 18534 D FlutterFcmService: onCreate: bg isolate started
07-31 08:25:30.146 18534 18569 D FlutterFcmService: oMR: application is NOT in foreground
07-31 08:25:30.146 18534 18569 D FlutterFcmService: oMR: bg isolate is not running yet, queue message
07-31 08:25:43.720 18534 18534 D FlutterFcmService: onInit: bg isolate marked as running
07-31 08:25:43.720 18534 18534 D FlutterFcmService: onInit: clear messages already queued
07-31 08:25:43.721 18534 18534 D FlutterFcmService: onInit: handle queued message
07-31 08:25:43.721 18534 18534 D FlutterFcmService: executeDartCallbackInBackgroundIsolate
07-31 08:25:43.721 18534 18534 D FlutterFcmService: invoke background message handler
07-31 08:25:43.722 18534 18534 D FlutterFcmService: onInit: backgroundMessageQueue cleared
07-31 08:25:43.729 18534 18559 I flutter : No port found in lookup on IsolateNameServer!

The main isolate is gone, and its ReceivePort is missing! I cannot pass a message to the main isolate. How can I process this message without any app state or plugins in the background handler?

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants