firebase / flutterfire

πŸ”₯ A collection of Firebase plugins for Flutter apps.
https://firebase.google.com/docs/flutter/setup
BSD 3-Clause "New" or "Revised" License
8.58k stars 3.94k forks source link

πŸ› [firestore] Firestore snapshot.exists occassionaly gives false negative #10331

Closed jimmyff closed 3 months ago

jimmyff commented 1 year ago

Bug report

docSnapshot.exists == flase when listening to shapshot changes and I know this to be untrue.

I launched a new app late last year and this issue has been causing issues for my app ever since launch. For a small percantage of my users receive a doc snapshot reporting the document does not exist. My apps behavior up until now was to log the user out, assuming their account had been removed. I've just updated my behavior (yesterday) to ignore snapshot updates that say the document doesn't exist. I'm monitoring it at the moment and yet to gauge customer feedback as if this has resolved the issue for them. When this happens, I have a number of other snapshot listeners that all seem to trigger with the same issue, reporting the document does not exist.

This also happened during the November 2022 Firestore outage. The snapshot stream received a snapshot and exits == false. This resulted in my app logging everyone out that was using the app during the outage.

This could be happening if the firestore http request fails or connection drops?

Steps to reproduce

It's hard to reproduce as my app has a lot of users and this isn't affecting everyone (although enough people to drive my app review score in the ground). I do have Crashlytics logging and can confirm that the firestore documents do exist at the time of the error.

Here is my implementation:

  Future _listenForAccountUpdates(String uid) async {
    if (_accountStream != null) {
      return;
    }
    log.fine('Listening to account updates for UID: $uid');
    _accountStream = FirebaseFirestore.instance
        .collection('account')
        .doc(uid)
        .snapshots()
        .listen(
            (docSnapshot) async {

              // This is problematic - gives false negatives
              if (!docSnapshot.exists) {
                await FirebaseCrashlytics.instance.recordError(
                    Exception(
                        'Ignoring: Account ${uid} not found in snapshot listener AuthUID: ${user?.uid}'),
                    null,
                    fatal: false);
                return;
              } 
             // My app does stuff here...
            },
            onDone: () => FirebaseCrashlytics.instance
                .log('listenForAccountUpdates onDone.'),
            cancelOnError: false,
            onError: (e) => FirebaseCrashlytics.instance
                  .recordError(e, null, reason: 'listenForAccountUpdates')
            );
    log.fine('Listening for account updates $uid');
  }

Example of captued error report:

# Crashlytics - Stack trace
# Platform: android
# Version: 1.2.22 (82)
# Issue: 523b11e89e94997a5911e86cec99100a
# Session: 63D215A602C200015884EF3568F8772F_DNE_0_v2
# Date: Thu Jan 26 2023 06:00:29 GMT+0000 (Greenwich Mean Time)

Non-fatal Exception: io.flutter.plugins.firebase.crashlytics.FlutterError: Exception: Ignoring: Account 902dfe92-d571-50a2-a9d8-b67c66720779 not found in snapshot listener AuthUID: ha7OPddnPdWwJaHP8iy6YpgDtax1. Error thrown null.
       at FirebaseCrashlytics.recordError(firebase_crashlytics.dart:117)
       at FbAuth._listenForAccountUpdates.<fn>(fb_auth.dart:569)

Yet here you can see that this document does exist and has existed since September: image

You can also see that the pinged and notified timestamps are after the crashlytics report suggesting ignoring this report perhaps was the correct thing to do and the customer might not have noticed the issue.

The issue I have is that I shouldn't have to ignore .exsits this is valuable piece of information but only when it can be relied upon.

Thanks


Flutter doctor

Click To Expand ``` [βœ“] Flutter (Channel stable, 3.3.8, on macOS 12.6.2 21G320 darwin-arm, locale en-GB) β€’ Flutter version 3.3.8 on channel stable at /Users/jimmyff/sdks/flutter β€’ Upstream repository https://github.com/flutter/flutter.git β€’ Framework revision 52b3dc25f6 (3 months ago), 2022-11-09 12:09:26 +0800 β€’ Engine revision 857bd6b74c β€’ Dart version 2.18.4 β€’ DevTools version 2.15.0 [βœ“] Android toolchain - develop for Android devices (Android SDK version 33.0.0) β€’ Android SDK at /Users/jimmyff/Library/Android/sdk β€’ Platform android-33, build-tools 33.0.0 β€’ Java binary at: /Applications/Android Studio.app/Contents/jre/Contents/Home/bin/java β€’ Java version OpenJDK Runtime Environment (build 11.0.12+0-b1504.28-7817840) β€’ All Android licenses accepted. [βœ“] Xcode - develop for iOS and macOS (Xcode 14.2) β€’ Xcode at /Applications/Xcode.app/Contents/Developer β€’ Build 14C18 β€’ CocoaPods version 1.11.3 [βœ“] Chrome - develop for the web β€’ Chrome at /Applications/Google Chrome.app/Contents/MacOS/Google Chrome [βœ“] Android Studio (version 2021.2) β€’ Android Studio at /Applications/Android Studio.app/Contents β€’ Flutter plugin can be installed from: πŸ”¨ https://plugins.jetbrains.com/plugin/9212-flutter β€’ Dart plugin can be installed from: πŸ”¨ https://plugins.jetbrains.com/plugin/6351-dart β€’ Java version OpenJDK Runtime Environment (build 11.0.12+0-b1504.28-7817840) [βœ“] VS Code (version 1.74.3) β€’ VS Code at /Applications/Visual Studio Code.app/Contents β€’ Flutter extension version 3.58.0 [βœ“] Connected device (4 available) β€’ Pixel 5 (mobile) β€’ 09021FDD40027X β€’ android-arm64 β€’ Android 13 (API 33) β€’ sdk gphone64 arm64 (mobile) β€’ emulator-5554 β€’ android-arm64 β€’ Android 13 (API 33) (emulator) β€’ macOS (desktop) β€’ macos β€’ darwin-arm64 β€’ macOS 12.6.2 21G320 darwin-arm β€’ Chrome (web) β€’ chrome β€’ web-javascript β€’ Google Chrome 109.0.5414.119 [βœ“] HTTP Host Availability β€’ All required HTTP hosts are available β€’ No issues found! ```

Flutter dependencies

Click To Expand ``` Dart SDK 2.18.4 Flutter SDK 3.3.8 onesceneapp 1.2.22+82 dependencies: - animate_countdown_text 1.1.3 [flutter animate_do] - animated_text_kit 4.2.2 [flutter characters] - audioplayers 1.0.1 [audioplayers_android audioplayers_darwin audioplayers_linux audioplayers_platform_interface audioplayers_web audioplayers_windows flutter http path_provider uuid] - badges 2.0.3 [flutter] - blurhash_dart 1.1.0 [image] - carousel_slider 4.1.1 [flutter] - chroma 0.1.2 [vector_math logging image] - cloud_firestore 3.3.0 [cloud_firestore_platform_interface cloud_firestore_web collection firebase_core firebase_core_platform_interface flutter meta] - cloud_firestore_platform_interface 5.6.0 [collection firebase_core flutter meta plugin_platform_interface] - collection 1.16.0 - confetti 0.7.0 [flutter vector_math] - crypto 3.0.2 [typed_data] - csv 5.0.1 - cupertino_icons 1.0.5 - device_info 2.0.3 [flutter device_info_platform_interface] - dotted_border 2.0.0+2 [flutter path_drawing] - encrypt 5.0.1 [args asn1lib clock collection crypto pointycastle] - equatable 2.0.3 [collection meta] - exif 3.1.1 [args collection convert json_annotation sprintf] - firebase_analytics 9.2.0 [firebase_analytics_platform_interface firebase_analytics_web firebase_core firebase_core_platform_interface flutter] - firebase_app_check 0.0.6+17 [firebase_app_check_platform_interface firebase_app_check_web firebase_core firebase_core_platform_interface flutter] - firebase_auth 3.4.2 [firebase_auth_platform_interface firebase_auth_web firebase_core firebase_core_platform_interface flutter meta] - firebase_core 1.19.2 [firebase_core_platform_interface firebase_core_web flutter meta] - firebase_crashlytics 2.8.7 [firebase_core firebase_core_platform_interface firebase_crashlytics_platform_interface flutter stack_trace] - firebase_messaging 12.0.0 [firebase_core firebase_core_platform_interface firebase_messaging_platform_interface firebase_messaging_web flutter meta] - firebase_remote_config 2.0.12 [firebase_core firebase_core_platform_interface firebase_remote_config_platform_interface firebase_remote_config_web flutter] - firebase_storage 10.3.2 [firebase_core firebase_core_platform_interface firebase_storage_platform_interface firebase_storage_web flutter] - flutter 0.0.0 [characters collection material_color_utilities meta vector_math sky_engine] - flutter_facebook_auth 4.4.0+1 [flutter flutter_facebook_auth_platform_interface flutter_facebook_auth_web] - flutter_image 4.1.3 [flutter] - flutter_local_notifications 9.7.0 [clock flutter flutter_local_notifications_linux flutter_local_notifications_platform_interface timezone] - flutter_localizations 0.0.0 [flutter intl characters clock collection material_color_utilities meta path vector_math] - flutter_markdown 0.6.10+2 [flutter markdown meta path] - flutter_placeholder_textlines 1.1.2 [flutter] - flutter_redux 0.10.0 [redux flutter] - flutter_redux_navigation 0.7.1 [flutter redux] - geolocator 9.0.1 [flutter geolocator_platform_interface geolocator_android geolocator_apple geolocator_web geolocator_windows] - google_maps_flutter 2.2.2 [flutter google_maps_flutter_android google_maps_flutter_ios google_maps_flutter_platform_interface] - google_sign_in 5.4.0 [flutter google_sign_in_android google_sign_in_ios google_sign_in_platform_interface google_sign_in_web] - http 0.13.4 [async http_parser meta path] - image 3.2.0 [archive meta xml] - image_cropper 2.0.3 [flutter image_cropper_platform_interface image_cropper_for_web] - image_picker 0.8.5+3 [flutter image_picker_android image_picker_for_web image_picker_ios image_picker_platform_interface] - in_app_purchase 3.0.6 [flutter in_app_purchase_android in_app_purchase_platform_interface in_app_purchase_storekit] - infinite_scroll_pagination 3.2.0 [flutter sliver_tools] - ink_page_indicator 0.2.1 [flutter meta] - intl 0.17.0 [clock path] - intl_phone_number_input 0.7.0+2 [flutter meta libphonenumber_plugin equatable collection] - jovial_svg 1.1.5 [xml collection args vector_math jovial_misc http meta flutter] - loading_indicator 3.1.0 [flutter async collection] - logging 1.0.2 - lottie 1.3.0 [archive flutter path vector_math] - material_design_icons_flutter 5.0.6996 [flutter] - meta 1.8.0 - onescene_brand 1.0.0 [flutter os_core lottie] - open_store 0.3.1 [flutter url_launcher talker] - os_core 0.0.1 [redux redux_logging copy_with_extension quiver_hashcode intl uuid http encrypt built_value built_collection quiver archive recase logging json_annotation] - package_info 2.0.2 [flutter] - package_info_plus 1.4.3+1 [flutter package_info_plus_platform_interface package_info_plus_linux package_info_plus_macos package_info_plus_windows package_info_plus_web] - page_transition 2.0.9 [flutter] - palette_generator 0.3.3+1 [collection flutter path] - path_provider 2.0.11 [flutter path_provider_android path_provider_ios path_provider_linux path_provider_macos path_provider_platform_interface path_provider_windows] - photofilters 3.0.1 [flutter image meta path_provider] - pinch_zoom 1.0.0 [flutter] - pinput 2.2.11 [flutter smart_auth] - quiver 3.1.0 [matcher] - recase 4.0.0 - redux 5.0.0 - redux_logging 0.5.0 [redux logging] - redux_thunk 0.4.0 [redux] - reorderables 0.5.0 [flutter] - settings_ui 2.0.2 [flutter] - shared_preferences 2.0.15 [flutter shared_preferences_android shared_preferences_ios shared_preferences_linux shared_preferences_macos shared_preferences_platform_interface shared_preferences_web shared_preferences_windows] - shimmer 2.0.0 [flutter] - sign_in_with_apple 4.1.0 [flutter meta sign_in_with_apple_platform_interface sign_in_with_apple_web] - store_redirect 2.0.1 [flutter] - transparent_image 2.0.0 - url_launcher 6.1.5 [flutter url_launcher_android url_launcher_ios url_launcher_linux url_launcher_macos url_launcher_platform_interface url_launcher_web url_launcher_windows] - uuid 3.0.6 [crypto] dev dependencies: - flutter_lints 2.0.1 [lints] - flutter_test 0.0.0 [flutter test_api path fake_async clock stack_trace vector_math async boolean_selector characters collection matcher material_color_utilities meta source_span stream_channel string_scanner term_glyph] transitive dependencies: - animate_do 2.1.0 [flutter] - ansicolor 2.0.1 - archive 3.3.0 [crypto path] - args 2.3.1 - asn1lib 1.1.0 - async 2.9.0 [collection meta] - audioplayers_android 1.0.1 [audioplayers_platform_interface flutter] - audioplayers_darwin 1.0.1 [audioplayers_platform_interface flutter] - audioplayers_linux 1.0.0 [audioplayers_platform_interface flutter] - audioplayers_platform_interface 1.0.0 [flutter plugin_platform_interface] - audioplayers_web 1.0.0 [audioplayers_platform_interface flutter flutter_web_plugins] - audioplayers_windows 1.0.0 [audioplayers_platform_interface flutter] - boolean_selector 2.1.0 [source_span string_scanner] - built_collection 5.1.1 - built_value 8.4.0 [built_collection collection fixnum meta] - characters 1.2.1 - charcode 1.3.1 - clock 1.1.1 - cloud_firestore_web 2.7.0 [cloud_firestore_platform_interface collection firebase_core firebase_core_web flutter flutter_web_plugins js] - convert 3.0.2 [typed_data] - copy_with_extension 4.0.4 - cross_file 0.3.3+1 [js meta] - dbus 0.7.6 [args ffi meta xml] - device_info_platform_interface 2.0.1 [flutter meta plugin_platform_interface] - fake_async 1.3.1 [clock collection] - ffi 2.0.1 - file 6.1.2 [meta path] - firebase_analytics_platform_interface 3.2.0 [firebase_core flutter meta plugin_platform_interface] - firebase_analytics_web 0.4.1 [firebase_analytics_platform_interface firebase_core firebase_core_web flutter flutter_web_plugins js] - firebase_app_check_platform_interface 0.0.4+11 [firebase_core flutter meta plugin_platform_interface] - firebase_app_check_web 0.0.6 [firebase_app_check_platform_interface firebase_core firebase_core_web flutter flutter_web_plugins js] - firebase_auth_platform_interface 6.3.2 [firebase_core flutter meta plugin_platform_interface] - firebase_auth_web 4.0.0 [firebase_auth_platform_interface firebase_core firebase_core_web flutter flutter_web_plugins http_parser intl js meta] - firebase_core_platform_interface 4.5.0 [collection flutter flutter_test meta plugin_platform_interface] - firebase_core_web 1.7.0 [firebase_core_platform_interface flutter flutter_web_plugins js meta] - firebase_crashlytics_platform_interface 3.2.13 [collection firebase_core flutter meta plugin_platform_interface] - firebase_messaging_platform_interface 4.0.0 [firebase_core flutter meta plugin_platform_interface] - firebase_messaging_web 3.0.0 [firebase_core firebase_core_web firebase_messaging_platform_interface flutter flutter_web_plugins js meta] - firebase_remote_config_platform_interface 1.1.11 [firebase_core flutter meta plugin_platform_interface] - firebase_remote_config_web 1.1.0 [firebase_core firebase_core_web firebase_remote_config_platform_interface flutter flutter_web_plugins js] - firebase_storage_platform_interface 4.1.11 [collection firebase_core flutter meta plugin_platform_interface] - firebase_storage_web 3.3.0 [async firebase_core firebase_core_web firebase_storage_platform_interface flutter flutter_web_plugins http js meta] - fixnum 1.0.1 - flutter_facebook_auth_platform_interface 3.2.0 [flutter plugin_platform_interface] - flutter_facebook_auth_web 3.2.0 [flutter flutter_web_plugins js flutter_facebook_auth_platform_interface] - flutter_local_notifications_linux 0.5.0+1 [flutter flutter_local_notifications_platform_interface dbus path xdg_directories] - flutter_local_notifications_platform_interface 5.0.0 [flutter plugin_platform_interface] - flutter_plugin_android_lifecycle 2.0.7 [flutter] - flutter_web_plugins 0.0.0 [flutter js characters collection material_color_utilities meta vector_math] - geolocator_android 4.0.1 [flutter geolocator_platform_interface] - geolocator_apple 2.2.1 [flutter geolocator_platform_interface] - geolocator_platform_interface 4.0.6 [flutter plugin_platform_interface vector_math meta] - geolocator_web 2.1.6 [flutter flutter_web_plugins geolocator_platform_interface] - geolocator_windows 0.1.1 [flutter geolocator_platform_interface] - google_maps_flutter_android 2.4.0 [flutter flutter_plugin_android_lifecycle google_maps_flutter_platform_interface stream_transform] - google_maps_flutter_ios 2.1.12 [flutter google_maps_flutter_platform_interface stream_transform] - google_maps_flutter_platform_interface 2.2.4 [collection flutter plugin_platform_interface stream_transform] - google_sign_in_android 6.0.1 [flutter google_sign_in_platform_interface] - google_sign_in_ios 5.4.0 [flutter google_sign_in_platform_interface] - google_sign_in_platform_interface 2.2.0 [flutter quiver] - google_sign_in_web 0.10.2 [flutter flutter_web_plugins google_sign_in_platform_interface js] - http_parser 4.0.1 [collection source_span string_scanner typed_data] - image_cropper_for_web 0.0.4 [flutter flutter_web_plugins image_cropper_platform_interface js] - image_cropper_platform_interface 2.0.0 [flutter plugin_platform_interface http] - image_picker_android 0.8.5+1 [flutter flutter_plugin_android_lifecycle image_picker_platform_interface] - image_picker_for_web 2.1.8 [flutter flutter_web_plugins image_picker_platform_interface] - image_picker_ios 0.8.5+6 [flutter image_picker_platform_interface] - image_picker_platform_interface 2.5.0 [cross_file flutter http plugin_platform_interface] - in_app_purchase_android 0.2.3+1 [collection flutter in_app_purchase_platform_interface json_annotation] - in_app_purchase_platform_interface 1.3.1 [flutter plugin_platform_interface] - in_app_purchase_storekit 0.3.1 [collection flutter in_app_purchase_platform_interface json_annotation] - jovial_misc 0.8.4 [pointycastle intl async collection convert meta] - js 0.6.4 - json_annotation 4.6.0 [meta] - libphonenumber 2.0.2 [flutter meta] - libphonenumber_platform_interface 0.3.1 [flutter plugin_platform_interface] - libphonenumber_plugin 0.2.3 [flutter flutter_web_plugins libphonenumber_platform_interface libphonenumber_web libphonenumber] - libphonenumber_web 0.2.0+1 [flutter flutter_web_plugins js libphonenumber_platform_interface] - lints 2.0.0 - markdown 5.0.0 [args charcode meta] - matcher 0.12.12 [stack_trace] - material_color_utilities 0.1.5 - package_info_plus_linux 1.0.5 [package_info_plus_platform_interface flutter path] - package_info_plus_macos 1.3.0 [flutter] - package_info_plus_platform_interface 1.0.2 [flutter meta plugin_platform_interface] - package_info_plus_web 1.0.6 [flutter flutter_web_plugins http meta package_info_plus_platform_interface] - package_info_plus_windows 2.1.0 [package_info_plus_platform_interface ffi flutter win32] - path 1.8.2 - path_drawing 1.0.0 [vector_math meta path_parsing flutter] - path_parsing 1.0.0 [vector_math meta] - path_provider_android 2.0.16 [flutter path_provider_platform_interface] - path_provider_ios 2.0.10 [flutter path_provider_platform_interface] - path_provider_linux 2.1.7 [ffi flutter path path_provider_platform_interface xdg_directories] - path_provider_macos 2.0.6 [flutter path_provider_platform_interface] - path_provider_platform_interface 2.0.4 [flutter platform plugin_platform_interface] - path_provider_windows 2.1.0 [ffi flutter path path_provider_platform_interface win32] - petitparser 5.0.0 [meta] - platform 3.1.0 - plugin_platform_interface 2.1.2 [meta] - pointycastle 3.6.0 [collection convert js] - process 4.2.4 [file path platform] - quiver_hashcode 3.0.0+1 - shared_preferences_android 2.0.12 [flutter shared_preferences_platform_interface] - shared_preferences_ios 2.1.1 [flutter shared_preferences_platform_interface] - shared_preferences_linux 2.1.1 [file flutter path path_provider_linux path_provider_platform_interface shared_preferences_platform_interface] - shared_preferences_macos 2.0.4 [flutter shared_preferences_platform_interface] - shared_preferences_platform_interface 2.0.0 [flutter] - shared_preferences_web 2.0.4 [flutter flutter_web_plugins shared_preferences_platform_interface] - shared_preferences_windows 2.1.1 [file flutter path path_provider_platform_interface path_provider_windows shared_preferences_platform_interface] - sign_in_with_apple_platform_interface 1.0.0 [flutter plugin_platform_interface meta] - sign_in_with_apple_web 1.0.1 [flutter flutter_web_plugins sign_in_with_apple_platform_interface js] - sky_engine 0.0.99 - sliver_tools 0.2.8 [flutter] - smart_auth 1.0.5 [flutter flutter_web_plugins] - source_span 1.9.0 [collection path term_glyph] - sprintf 6.0.0 - stack_trace 1.10.0 [path] - stream_channel 2.1.0 [async] - stream_transform 2.1.0 - string_scanner 1.1.1 [source_span] - talker 1.3.0+1 [talker_logger] - talker_logger 1.2.1 [ansicolor] - term_glyph 1.2.1 - test_api 0.4.12 [async boolean_selector collection meta source_span stack_trace stream_channel string_scanner term_glyph matcher] - timezone 0.8.0 [path] - typed_data 1.3.1 [collection] - url_launcher_android 6.0.17 [flutter url_launcher_platform_interface] - url_launcher_ios 6.0.17 [flutter url_launcher_platform_interface] - url_launcher_linux 3.0.1 [flutter url_launcher_platform_interface] - url_launcher_macos 3.0.1 [flutter url_launcher_platform_interface] - url_launcher_platform_interface 2.1.0 [flutter plugin_platform_interface] - url_launcher_web 2.0.12 [flutter flutter_web_plugins url_launcher_platform_interface] - url_launcher_windows 3.0.1 [flutter url_launcher_platform_interface] - vector_math 2.1.2 - win32 2.7.0 [ffi] - xdg_directories 0.2.0+1 [meta path process] - xml 6.1.0 [collection meta petitparser] ```

darshankawar commented 1 year ago

Thanks for the report @jimmyff If you try to check explicitly if docSnapshot.data.data == null before .exists to confirm if indeed there's no data and also to see if this condition always returns true or not can probably help to see as why you might be getting occasional false negative.

What do you think ?

jimmyff commented 1 year ago

Hi @darshankawar I've added debug information to the Crashlytics log:

await FirebaseCrashlytics.instance.recordError(
                    Exception(
                        'Ignoring: Account ${uid} not found in snapshot listener AuthUID: ${user?.uid}. Data is null: ${docSnapshot.data() == null}.'),
                    null, fatal: false);

I will deploy this release now and report back tomorrow.

jimmyff commented 1 year ago
# Crashlytics - Stack trace
# Platform: android
# Version: 1.2.25 (85)
# Issue: 6ba104c7b332c7f59d3d22f74e189c3a
# Session: 63D77594017D00013AF9C120564A2784_DNE_1_v2
# Date: Mon Jan 30 2023 07:45:37 GMT+0000 (Greenwich Mean Time)

Non-fatal Exception: io.flutter.plugins.firebase.crashlytics.FlutterError: Exception: Ignoring: Account 24f90e23-ab8b-528d-88d7-b2b0b8bee4cb not found in snapshot listener AuthUID: dHbxenejBzUj1Bq5zmng3hrC8uo1. Data is null: true.. Error thrown null.
       at FirebaseCrashlytics.recordError(firebase_crashlytics.dart:117)
       at FbAuth._listenForAccountUpdates.<fn>(fb_auth.dart:593)

@darshankawar So when it reports docSnapshot.exists == false then docSnapshot.data() == null also appears to be true.

darshankawar commented 1 year ago

Thanks for the update. I am unable to replicate this behavior using the plugin example, but based on the report, I'll keep this issue open and label for team's thoughts on behavior reported.

darshankawar commented 1 year ago

/cc @Lyokone

Lyokone commented 1 year ago

Without reproducing steps, it will be hard to debug (we just transmit the data from Firebase to Flutter, so it might be a native bug if it's one). Do you think you might have a race condition or maybe no disposing of a listener properly?

jimmyff commented 1 year ago

Hey @Lyokone, I had thought it was possibly a race condition with the permissions (via claims) however I check that the necessary claims exist in the token result before setting up these streams. Also this would have thrown a permission denied error rather than a not exists. Here are related rules:

    function isAuthenticated() {
      return request.auth != null;
    }

    // Users
    function isOwner(os_uid) {
      return isAuthenticated() && "os_uid" in request.auth.token  && request.auth.token.os_uid == os_uid;
    }

    function isStaffWithAccountPermission() {
      return isAuthenticated() && "osp_accounts" in request.auth.token && request.auth.token.osp_accounts == true;
    }

    match /account/{os_uid} {
      allow read: if isOwner(os_uid) || isStaffWithAccountPermission();
      allow write: if (isOwner(os_uid) || isStaffWithAccountPermission()) && isTimestamp(request.resource.data.joined);
    }

I don't think it's disposing of a listener. This always seems to happen at app start-up.

Here is another recent error log captured on Crashlytics:

Stack trace:

# Crashlytics - Stack trace
# Platform: android
# Version: 1.2.26 (86)
# Issue: 6ba104c7b332c7f59d3d22f74e189c3a
# Session: 63DAEC5901E400011F17C4EF675A97BB_DNE_1_v2
# Date: Wed Feb 01 2023 22:49:09 GMT+0000 (Greenwich Mean Time)

Non-fatal Exception: io.flutter.plugins.firebase.crashlytics.FlutterError: Exception: Ignoring: Account 2c99b9e1-c074-572d-9ac7-1b989f729669 not found in snapshot listener AuthUID: oCUnxb19I4W1WfW8YQ8lG96mqRj2. Data is null: true.. Error thrown null.
       at FirebaseCrashlytics.recordError(firebase_crashlytics.dart:117)
       at FbAuth._listenForAccountUpdates.<fn>(fb_auth.dart:616)

Logs:

# Crashlytics - Custom logs
# Platform: android
# Version: 1.2.26 (86)
# Issue: 6ba104c7b332c7f59d3d22f74e189c3a
# Session: 63DAEC5901E400011F17C4EF675A97BB_DNE_1_v2
# Date: Wed Feb 01 2023 22:49:09 GMT+0000 (Greenwich Mean Time)

 0 | Wed Feb 01 2023 22:48:57 GMT+0000 (Greenwich Mean Time) | session_start
 1 | Wed Feb 01 2023 22:48:57 GMT+0000 (Greenwich Mean Time) | screen_view
 2 | Wed Feb 01 2023 22:48:57 GMT+0000 (Greenwich Mean Time) | Firebase initializeApp done.
 3 | Wed Feb 01 2023 22:48:58 GMT+0000 (Greenwich Mean Time) | Firebase initializeApp done.
 4 | Wed Feb 01 2023 22:48:58 GMT+0000 (Greenwich Mean Time) | Remote Config initalised.
 5 | Wed Feb 01 2023 22:48:58 GMT+0000 (Greenwich Mean Time) | Firebase fully initalised.
 6 | Wed Feb 01 2023 22:48:58 GMT+0000 (Greenwich Mean Time) | Firebase user set: oCUnxb19I4W1WfW8YQ8lG96mqRj2
 7 | Wed Feb 01 2023 22:48:58 GMT+0000 (Greenwich Mean Time) | _refreshTokenAndGetClaims (attempt: 1) force: true publishAuthSession: false
 8 | Wed Feb 01 2023 22:48:59 GMT+0000 (Greenwich Mean Time) | Got Claims: {os_uid: 2c99b9e1-c074-572d-9ac7-1b989f729669}
 9 | Wed Feb 01 2023 22:48:59 GMT+0000 (Greenwich Mean Time) | Listening for updates: 2c99b9e1-c074-572d-9ac7-1b989f729669
10 | Wed Feb 01 2023 22:48:59 GMT+0000 (Greenwich Mean Time) | Setup auth listeners done
11 | Wed Feb 01 2023 22:49:09 GMT+0000 (Greenwich Mean Time) | Radar not found for 2c99b9e1-c074-572d-9ac7-1b989f729669, creating new radar...
12 | Wed Feb 01 2023 22:49:09 GMT+0000 (Greenwich Mean Time) | Account 2c99b9e1-c074-572d-9ac7-1b989f729669 not found. AuthUID: oCUnxb19I4W1WfW8YQ8lG96mqRj2. Data is null: true  Ignoring...
13 | Wed Feb 01 2023 22:49:09 GMT+0000 (Greenwich Mean Time) | Queue 2c99b9e1-c074-572d-9ac7-1b989f729669 not found. AuthUID: oCUnxb19I4W1WfW8YQ8lG96mqRj2. Data is null: true. Ignoring...

You can see the Got Claims log message confirms that the correct permission (claims) are set.

I have just noticed that the not found exception is logged almsot precisely 10 seconds after the Setup auth listeners done log message. I have verified this across multiple recent captured errors. Could it be a timeout situation? This would tie in with the fact this same situation happened during the 2022 November Firestore global outage.

Based on the false negative it seems there is an sdk bug here somewhere even in my app is the cause, there should be a specific error thrown?

Thanks

Lyokone commented 1 year ago

Thanks for your research; it helps a lot. Do you have App Check activated on your app? Do you see failed request in the Firebase console?

jimmyff commented 1 year ago

Hey @Lyokone yes I do, I am enforcing all the Firestore requests due to the sensetive account data that I'm storing. Here are the AppCheck Firestore stats:

image

It looks like 1.2k requests over the last week were unverified/invalid requests. I had assumed these were bots or something irrelevant but could these be my failing requests?

Do you want me to unenforce firestore and see if the error reports stop coming in?

Lyokone commented 1 year ago

It could be something like that. I'm wondering if maybe the AppCheck plugin has a race condition with the Firestore plugin maybe?

jimmyff commented 1 year ago

@Lyokone ahhh great suggestion, that is a possibility which I've just resolved in the latest build. I will report back.

It would have been nice to have AppCheck errors in this situation?

Lyokone commented 1 year ago

There is something wrong if it's the case. If the issue is resolved, I would be interested in reproduction steps including AppCheck to improve the error handling :)

jimmyff commented 1 year ago

Hey @Lyokone, sorry for the delay in responding, I got swept up in another project. I'm still recieving this issue after eliminating the possible race condition 😩

I setup a few snapshot listeners at time of authentication (on collections: claims, account, purchases, chat messages etc). They all of fail (!exists) simultaniously, and all precisley 10 seconds after I setup the snapshot listeners.

jimmyff commented 1 year ago

I've just noticed that my AppCheck unverified queries have not gone down (they've actually gone up a little but so has traffic slightly so that is probably nothing): image

So AppCheck could still be the root cause of this problem although I'm not sure how this could happen. Here is a snippet from my main.dart:


  // main.dart snippet:

  // Keep trying to connect to firebase until we get app object.
  FirebaseApp? app;
  while (app == null)  {
    app = await _initFirebase();
  }

  // Configure notifications
  try {
    await NotificationConfig.init(
      onNotificationSelected: (payload) =>
          store.dispatch(NotificationSelectedAction(payload)),
      ignoreChatNotification: (payload) =>
          store.state.appState.conversationVisible ==
          payload.os_conversation_ref,
    ).timeout(Duration(seconds: 5));
  } catch (e, s) {
    FirebaseCrashlytics.instance
        .recordError(e, s, reason: 'NotificationConfig.init');
  }

  // App check
  await FirebaseAppCheck.instance.activate(
    webRecaptchaSiteKey: null,
  );
  await FirebaseAppCheck.instance.setTokenAutoRefreshEnabled(true);

  // Get firebase initalising.
  PackageInfo packageInfo = await PackageInfo.fromPlatform();
  fb.init(int.parse(packageInfo.buildNumber));

Only when the user hits my first material app screen does the FirebaseAuthentication start initalising which is when those problematic snapshot listeners are created.

Can you spot anything I'm doing incorrectly that could be causing this issue?

Do you want me to disable app check for 24 hours and see if the issue goes away? I wouldn't be comfortable disabling AppCheck permenantly as I am storing & processing sesentive customer information and want all the security measures I can get!

Thanks

jimmyff commented 1 year ago

I've just plugged an old test phone in that I've not used for a couple of months and on on the first authentication attempt I got Firestore permission denied errors.

Although this is not initially look like the same issue that I've been tracking above (timing out after 10 seconds of app start) I think it actually is the same issue however this is from an unauthenticated startup context whereas above logs are those that are currently authenticated.

As this was my own device I managed to capture the full client side flutter logs:

Flutter debug logs ``` Launching lib/main.dart on Pixel 3 in debug mode... Warning: Mapping new ns http://schemas.android.com/repository/android/common/02 to old ns http://schemas.android.com/repository/android/common/01 Warning: Mapping new ns http://schemas.android.com/repository/android/generic/02 to old ns http://schemas.android.com/repository/android/generic/01 Warning: Mapping new ns http://schemas.android.com/sdk/android/repo/addon2/02 to old ns http://schemas.android.com/sdk/android/repo/addon2/01 Warning: Mapping new ns http://schemas.android.com/sdk/android/repo/addon2/03 to old ns http://schemas.android.com/sdk/android/repo/addon2/01 Warning: Mapping new ns http://schemas.android.com/sdk/android/repo/repository2/02 to old ns http://schemas.android.com/sdk/android/repo/repository2/01 Warning: Mapping new ns http://schemas.android.com/sdk/android/repo/repository2/03 to old ns http://schemas.android.com/sdk/android/repo/repository2/01 Warning: Mapping new ns http://schemas.android.com/sdk/android/repo/sys-img2/03 to old ns http://schemas.android.com/sdk/android/repo/sys-img2/01 Warning: Mapping new ns http://schemas.android.com/sdk/android/repo/sys-img2/02 to old ns http://schemas.android.com/sdk/android/repo/sys-img2/01 Warning: unexpected element (uri:"", local:"base-extension"). Expected elements are <{}codename>,<{}layoutlib>,<{}api-level> Warning: Mapping new ns http://schemas.android.com/repository/android/common/02 to old ns http://schemas.android.com/repository/android/common/01 Warning: Mapping new ns http://schemas.android.com/repository/android/generic/02 to old ns http://schemas.android.com/repository/android/generic/01 Warning: Mapping new ns http://schemas.android.com/sdk/android/repo/addon2/02 to old ns http://schemas.android.com/sdk/android/repo/addon2/01 Warning: Mapping new ns http://schemas.android.com/sdk/android/repo/addon2/03 to old ns http://schemas.android.com/sdk/android/repo/addon2/01 Warning: Mapping new ns http://schemas.android.com/sdk/android/repo/repository2/02 to old ns http://schemas.android.com/sdk/android/repo/repository2/01 Warning: Mapping new ns http://schemas.android.com/sdk/android/repo/repository2/03 to old ns http://schemas.android.com/sdk/android/repo/repository2/01 Warning: Mapping new ns http://schemas.android.com/sdk/android/repo/sys-img2/03 to old ns http://schemas.android.com/sdk/android/repo/sys-img2/01 Warning: Mapping new ns http://schemas.android.com/sdk/android/repo/sys-img2/02 to old ns http://schemas.android.com/sdk/android/repo/sys-img2/01 Warning: unexpected element (uri:"", local:"base-extension"). Expected elements are <{}codename>,<{}layoutlib>,<{}api-level> βœ“ Built build/app/outputs/flutter-apk/app-debug.apk. D/FlutterGeolocator( 9690): Attaching Geolocator to activity D/FlutterGeolocator( 9690): Creating service. D/FlutterGeolocator( 9690): Binding to location service. D/FlutterGeolocator( 9690): Geolocator foreground service connected D/FlutterGeolocator( 9690): Initializing Geolocator services Connecting to VM Service at ws://127.0.0.1:58618/cSxI_w2SVG4=/ws I/flutter ( 9690): 1: NavigatorHolder.navigatorKey:[LabeledGlobalKey#d651f] I/flutter ( 9690): Firebase apps I/flutter ( 9690): Initalising firebase app... [log] Analytics Dart-only initializer doesn't work on Android, please make sure to add the config file. D/FRCPlugin( 9690): Sending fetchTimeout: 60 I/flutter ( 9690): 2: NavigatorHolder.navigatorKey:[LabeledGlobalKey#d651f] I/flutter ( 9690): 19:63 NOTIFICATIONS/FINE: Notification config initalised W/FlutterJNI( 9690): FlutterJNI.loadLibrary called more than once I/ResourceExtractor( 9690): Found extracted resources res_timestamp-93-1677749415565 W/FlutterJNI( 9690): FlutterJNI.init called more than once W/FlutterJNI( 9690): FlutterJNI.prefetchDefaultFontManager called more than once [log] Analytics Dart-only initializer doesn't work on Android, please make sure to add the config file. I/FLTFireBGExecutor( 9690): Creating background FlutterEngine instance, with args: [--start-paused, --enable-dart-profiling] D/DeviceInfoPlugin( 9690): Use TaskQueues. I/flutter ( 9690): NOTIFICATIONS: Token FCM: f1aIFXl9RBSJ150rBISj0q:APA91bE5GZaVqtWDiw7XzO0MoLYflxpxOLx9MiZpQBzfh7X1-j-JJZVK-HeAq8PP9rX5QBm5FNHHZiLAiiY3XuJLlDgiIT-7wNYAzj_Ckb03St9_nCXua4iSgFClk6CSqFDN I/flutter ( 9690): 19:67 NOTIFICATIONS/SHOUT: NOTIFICATIONS: Do FCM stuff... D/FlutterGeolocator( 9690): Geolocator foreground service connected D/FlutterGeolocator( 9690): Initializing Geolocator services I/flutter ( 9690): 19:69 Firebase/FINE: Init firebase... I/flutter ( 9690): Firebase apps I/flutter ( 9690): Firebase app already initalised... I/flutter ( 9690): 19:70 Firebase/FINE: Initalising remote config... I/flutter ( 9690): 19:70 RC/INFO: Initalising remote config... I/flutter ( 9690): 19:70 RC/INFO: We need to do a full refresh of settings... I/flutter ( 9690): 19:70 RC/INFO: Fetching... I/flutter ( 9690): 19:70 RC/INFO: Fetch RemoteConfig (attempt: 1 / 5) I/flutter ( 9690): Loading locale: en I/flutter ( 9690): UiWrapper, child: Navigator-[LabeledGlobalKey#d651f] I/flutter ( 9690): AppRouting: / I/flutter ( 9690): 20:70 Redux/INFO: 9:30:20.702 [DISPATCH] AppRoutingAction I/flutter ( 9690): AppRouting: /landing I/flutter ( 9690): 20:70 Redux/INFO: 9:30:20.708 [DISPATCH] AppRoutingAction I/flutter ( 9690): 20:76 DeviceMiddleware/INFO: InitAction I/flutter ( 9690): 20:76 Redux/INFO: 9:30:20.765 [DISPATCH] InitAction I/flutter ( 9690): 20:76 Redux/INFO: 9:30:20.769 [DISPATCH] InitStateAction I/FLTFireMsgService( 9690): FlutterFirebaseMessagingBackgroundService started! D/FRCPlugin( 9690): Sending fetchTimeout: 6 I/flutter ( 9690): (ignoring units "%") I/flutter ( 9690): Ignoring serif attribute(s) in svg I/flutter ( 9690): Ignoring space attribute(s) in svg I/flutter ( 9690): 21:45 DeviceMiddleware/INFO: Persisted notifications settings: true I/flutter ( 9690): 21:46 Redux/INFO: 9:30:21.466 [DISPATCH] DeviceSettingUpdatedAction I/flutter ( 9690): deviceid : bd33498ada6ae8cd I/flutter ( 9690): 21:48 Redux/INFO: 9:30:21.480 [DISPATCH] SetDeviceIdAction W/System ( 9690): Ignoring header If-None-Match because its value was null. I/Gralloc4( 9690): mapper 4.x is not supported W/Gralloc3( 9690): mapper 3.x is not supported W/Gralloc4( 9690): allocator 4.x is not supported W/Gralloc3( 9690): allocator 3.x is not supported D/FRCPlugin( 9690): Sending fetchTimeout: 6 I/flutter ( 9690): 21:91 RC/INFO: Activating I/flutter ( 9690): loading device id... I/flutter ( 9690): 21:94 Firebase/FINE: Initalising firestore... I/flutter ( 9690): 21:94 Fs/FINE: Initalised I/flutter ( 9690): 21:94 Firebase/FINE: Initalising stotage... I/flutter ( 9690): 21:94 Storage/FINE: Initalised I/flutter ( 9690): 21:94 Firebase/FINE: Creating auth... I/flutter ( 9690): promo end date: 2023-05-01 I/flutter ( 9690): 21:97 Redux/INFO: 9:30:21.972 [DISPATCH] SetPromoAction I/flutter ( 9690): 21:97 AuthMiddleware/INFO: InitAction I/flutter ( 9690): 21:97 Auth/FINE: Initalising... I/flutter ( 9690): 21:99 AuthMiddleware/FINE: Initalised Auth... I/flutter ( 9690): 21:99 RemoteConfigMiddleware/INFO: InitAction I/flutter ( 9690): 21:99 RemoteConfigMiddleware/FINE: Remote Config is initalised! I/flutter ( 9690): 21:99 BillingMiddleware/FINE: Day timer setup, tomorrow: 52178 seconds... I/flutter ( 9690): 22:10 Auth/INFO: _onAuthStateChanged : null I/flutter ( 9690): 22:30 Auth/INFO: Setting Auth Profile: Current phone: null vs null I/flutter ( 9690): 22:30 Auth/INFO: Setting Auth Profile, status=AuthState.notAuthenticated phone=null I/flutter ( 9690): 22:50 userReducer/FINE: State updated with AuthProfile object token: null I/flutter ( 9690): 22:60 Redux/INFO: 9:30:22.6 [DISPATCH] AuthSessionChangeAction I/flutter ( 9690): 22:70 AuthMiddleware/INFO: Handling auth change. State: AuthState.notAuthenticated I/flutter ( 9690): AppRouting: / I/flutter ( 9690): 22:10 Redux/INFO: 9:30:22.10 [DISPATCH] AppRoutingAction I/flutter ( 9690): 22:22 Redux/INFO: 9:30:22.22 [DISPATCH] NavigateToAction I/flutter ( 9690): Auth profile changed: AuthState.notAuthenticated W/BillingClient( 9690): Billing service disconnected. W/InstallReferrerClient( 9690): Install Referrer service disconnected. D/CompatibilityChangeReporter( 9690): Compat change id reported: 150939131; UID 10020; state: ENABLED I/flutter ( 9690): authenticateWithProviderThunk called! provider: AuthenticationProvider.google I/flutter ( 9690): 57:41 Redux/INFO: 9:30:57.413 [DISPATCH] UserIsSubmitting I/flutter ( 9690): 3:49 Redux/INFO: 9:31:3.495 [DISPATCH] UserIsSubmitting I/flutter ( 9690): newFirebaseAuthCredentialThunk called! cred: AuthCredential(providerId: google.com, signInMethod: google.com, token: null) I/flutter ( 9690): 3:58 Redux/INFO: 9:31:3.589 [DISPATCH] UserIsSubmitting I/flutter ( 9690): newFirebaseAuthCredentialThunk User: null I/flutter ( 9690): THUNK: User signed in! W/System ( 9690): Ignoring header X-Firebase-Locale because its value was null. W/System ( 9690): Ignoring header X-Firebase-Locale because its value was null. D/FirebaseAuth( 9690): Notifying id token listeners about user ( MsPQhRKykfM3WkehTpPBu0gw6Oj1 ). D/FirebaseAuth( 9690): Notifying auth state listeners about user ( MsPQhRKykfM3WkehTpPBu0gw6Oj1 ). I/flutter ( 9690): 4:99 Auth/INFO: _onAuthStateChanged : User(displayName: null, email: foobar@gmail.com, emailVerified: true, isAnonymous: false, metadata: UserMetadata(creationTime: 2023-01-27 10:51:26.786, lastSignInTime: 2023-03-02 09:31:03.854), phoneNumber: +447999999999, photoURL: null, providerData, [UserInfo(displayName: Foo Bar, email: foobar@gmail.com, phoneNumber: null, photoURL: https://lh3.googleusercontent.com/a/AGNmyxa-O-3eOMFcVZ1cPdo4Owqlu_ca1nIUNRR1Pqw-=s96-c, providerId: google.com, uid: 113958032945815660831), UserInfo(displayName: null, email: null, phoneNumber: +447999999999, photoURL: null, providerId: phone, uid: null)], refreshToken: , tenantId: null, uid: MsPQhRKykfM3WkehTpPBu0gw6Oj1) I/flutter ( 9690): Setting User, Sending to stream: User(displayName: null, email: foobar@gmail.com, emailVerified: true, isAnonymous: false, metadata: UserMetadata(creationTime: 2023-01-27 10:51:26.786, lastSignInTime: 2023-03-02 09:31:03.854), phoneNumber: +447999999999, photoURL: null, providerData, [UserInfo(displayName: Foo Bar, email: foobar@gmail.com, phoneNumber: null, photoURL: https://lh3.googleusercontent.com/a/AGNmyxa-O-3eOMFcVZ1cPdo4Owqlu_ca1nIUNRR1Pqw-=s96-c, providerId: google.com, uid: 113958032945815660831), UserInfo(displayName: null, email: null, phoneNumber: +447999999999, photoURL: null, providerId: phone, uid: null)], refreshToken: , tenantId: null, uid: MsPQhRKykfM3WkehTpPBu0gw6Oj1) I/flutter ( 9690): 4:10 userReducer/FINE: SetFirebaseUserAction: User(displayName: null, email: foobar@gmail.com, emailVerified: true, isAnonymous: false, metadata: UserMetadata(creationTime: 2023-01-27 10:51:26.786, lastSignInTime: 2023-03-02 09:31:03.854), phoneNumber: +447999999999, photoURL: null, providerData, [UserInfo(displayName: Foo Bar, email: foobar@gmail.com, phoneNumber: null, photoURL: https://lh3.googleusercontent.com/a/AGNmyxa-O-3eOMFcVZ1cPdo4Owqlu_ca1nIUNRR1Pqw-=s96-c, providerId: google.com, uid: 113958032945815660831), UserInfo(displayName: null, email: null, phoneNumber: +447999999999, photoURL: null, providerId: phone, uid: null)], refreshToken: , tenantId: null, uid: MsPQhRKykfM3WkehTpPBu0gw6Oj1) I/flutter ( 9690): 4:10 Redux/INFO: 9:31:4.103 [DISPATCH] SetFirebaseUserAction I/flutter ( 9690): 4:10 Auth/INFO: _refreshTokenAndGetClaims (attempt: 1) force: true publishAuthSession: false W/System ( 9690): Ignoring header X-Firebase-Locale because its value was null. I/flutter ( 9690): Set IdToken: Token<"eyJhbGci...rxyOzRtA">[1101] I/flutter ( 9690): 4:12 Auth/INFO: Setting Auth Profile: Current phone: null vs null I/flutter ( 9690): 4:13 Auth/INFO: Setting Auth Profile, status=AuthState.notAuthenticated phone=null I/flutter ( 9690): 4:13 Auth/SEVERE: Got token but no auth profile I/flutter ( 9690): 4:13 userReducer/FINE: State updated with AuthProfile object token I/flutter ( 9690): 4:13 Redux/INFO: 9:31:4.131 [DISPATCH] AuthSessionChangeAction I/flutter ( 9690): 4:13 Redux/INFO: 9:31:4.132 [DISPATCH] NewFirebaseUserAction I/flutter ( 9690): authenticateWithProviderThunk: AuthenticationProvider.google complete: User(displayName: null, email: foobar@gmail.com, emailVerified: true, isAnonymous: false, metadata: UserMetadata(creationTime: 2023-01-27 10:51:26.786, lastSignInTime: 2023-03-02 09:31:03.854), phoneNumber: +447999999999, photoURL: null, providerData, [UserInfo(displayName: Foo Bar, email: foobar@gmail.com, phoneNumber: null, photoURL: https://lh3.googleusercontent.com/a/AGNmyxa-O-3eOMFcVZ1cPdo4Owqlu_ca1nIUNRR1Pqw-=s96-c, providerId: google.com, uid: 113958032945815660831), UserInfo(displayName: null, email: null, phoneNumber: +447999999999, photoURL: null, providerId: phone, uid: null)], refreshToken: , tenantId: null, uid: MsPQhRKykfM3WkehTpPBu0gw6Oj1) I/flutter ( 9690): 4:13 Redux/INFO: 9:31:4.134 [DISPATCH] UserIsSubmitting I/flutter ( 9690): 4:13 Redux/INFO: 9:31:4.134 [DISPATCH] UserIsSubmitting I/flutter ( 9690): 4:13 AuthMiddleware/INFO: Handling auth change. State: AuthState.notAuthenticated I/flutter ( 9690): Auth profile changed: AuthState.notAuthenticated I/flutter ( 9690): 4:13 Auth/INFO: _onAuthStateChanged : User(displayName: null, email: foobar@gmail.com, emailVerified: true, isAnonymous: false, metadata: UserMetadata(creationTime: 2023-01-27 10:51:26.786, lastSignInTime: 2023-03-02 09:31:03.854), phoneNumber: +447999999999, photoURL: null, providerData, [UserInfo(displayName: Foo Bar, email: foobar@gmail.com, phoneNumber: null, photoURL: https://lh3.googleusercontent.com/a/AGNmyxa-O-3eOMFcVZ1cPdo4Owqlu_ca1nIUNRR1Pqw-=s96-c, providerId: google.com, uid: 113958032945815660831), UserInfo(displayName: null, email: null, phoneNumber: +447999999999, photoURL: null, providerId: phone, uid: null)], refreshToken: , tenantId: null, uid: MsPQhRKykfM3WkehTpPBu0gw6Oj1) I/flutter ( 9690): Setting User, Sending to stream: User(displayName: null, email: foobar@gmail.com, emailVerified: true, isAnonymous: false, metadata: UserMetadata(creationTime: 2023-01-27 10:51:26.786, lastSignInTime: 2023-03-02 09:31:03.854), phoneNumber: +447999999999, photoURL: null, providerData, [UserInfo(displayName: Foo Bar, email: foobar@gmail.com, phoneNumber: null, photoURL: https://lh3.googleusercontent.com/a/AGNmyxa-O-3eOMFcVZ1cPdo4Owqlu_ca1nIUNRR1Pqw-=s96-c, providerId: google.com, uid: 113958032945815660831), UserInfo(displayName: null, email: null, phoneNumber: +447999999999, photoURL: null, providerId: phone, uid: null)], refreshToken: , tenantId: null, uid: MsPQhRKykfM3WkehTpPBu0gw6Oj1) I/flutter ( 9690): 4:13 userReducer/FINE: SetFirebaseUserAction: User(displayName: null, email: foobar@gmail.com, emailVerified: true, isAnonymous: false, metadata: UserMetadata(creationTime: 2023-01-27 10:51:26.786, lastSignInTime: 2023-03-02 09:31:03.854), phoneNumber: +447999999999, photoURL: null, providerData, [UserInfo(displayName: Foo Bar, email: foobar@gmail.com, phoneNumber: null, photoURL: https://lh3.googleusercontent.com/a/AGNmyxa-O-3eOMFcVZ1cPdo4Owqlu_ca1nIUNRR1Pqw-=s96-c, providerId: google.com, uid: 113958032945815660831), UserInfo(displayName: null, email: null, phoneNumber: +447999999999, photoURL: null, providerId: phone, uid: null)], refreshToken: , tenantId: null, uid: MsPQhRKykfM3WkehTpPBu0gw6Oj1) I/flutter ( 9690): 4:13 Redux/INFO: 9:31:4.137 [DISPATCH] SetFirebaseUserAction I/flutter ( 9690): 4:13 Auth/INFO: _refreshTokenAndGetClaims (attempt: 1) force: true publishAuthSession: false W/System ( 9690): Ignoring header X-Firebase-Locale because its value was null. D/FirebaseAuth( 9690): Notifying id token listeners about user ( MsPQhRKykfM3WkehTpPBu0gw6Oj1 ). D/FirebaseAuth( 9690): Notifying id token listeners about user ( MsPQhRKykfM3WkehTpPBu0gw6Oj1 ). I/flutter ( 9690): 4:46 Auth/FINE: _refreshTokenAndGetClaims (attempt: 1) got token: Token<"eyJhbGci...owi03eiQ">[1101] I/flutter ( 9690): Set IdToken: Token<"eyJhbGci...owi03eiQ">[1101] I/flutter ( 9690): 4:46 Auth/INFO: Setting Auth Profile: Current phone: null vs null I/flutter ( 9690): 4:46 Auth/INFO: Setting Auth Profile, status=AuthState.notAuthenticated phone=null I/flutter ( 9690): 4:46 Auth/INFO: Got claims from token I/flutter ( 9690): 4:46 Auth/INFO: {os_uid: b80a3950-9e30-11ed-9595-550fbe4215c2, phone_number: +447999999999, firebase: {identities: {google.com: [113958032945815660831], email: [foobar@gmail.com], phone: [+447999999999]}, sign_in_provider: google.com}, user_id: MsPQhRKykfM3WkehTpPBu0gw6Oj1, aud: onesceneapp, exp: 1677753064, iat: 1677749464, iss: https://securetoken.google.com/onesceneapp, sub: MsPQhRKykfM3WkehTpPBu0gw6Oj1, email: foobar@gmail.com, email_verified: true, auth_time: 1677749463} I/flutter ( 9690): 4:46 Auth/INFO: Authenticated platforms: [google.com, phone] I/flutter ( 9690): 4:47 Auth/FINE: Signed in... uid: MsPQhRKykfM3WkehTpPBu0gw6Oj1, provider: google.com I/flutter ( 9690): 4:47 Auth/INFO: Setting up listeners... I/flutter ( 9690): 4:47 Auth/FINE: Listening to account updates for UID: b80a3950-9e30-11ed-9595-550fbe4215c2 I/flutter ( 9690): 4:49 Auth/FINE: Listening for account updates b80a3950-9e30-11ed-9595-550fbe4215c2 I/flutter ( 9690): 4:49 Auth/FINE: Listening to queue updates for UID: b80a3950-9e30-11ed-9595-550fbe4215c2 I/flutter ( 9690): 4:49 Auth/FINE: Listening for profile queue updates b80a3950-9e30-11ed-9595-550fbe4215c2 I/flutter ( 9690): 4:49 Auth/FINE: Listening to radar updates for UID: b80a3950-9e30-11ed-9595-550fbe4215c2 I/flutter ( 9690): 4:49 Auth/FINE: Listening for profile radar updates b80a3950-9e30-11ed-9595-550fbe4215c2 I/flutter ( 9690): 4:49 Auth/FINE: PURCHASE_RECEIPT: Listening: b80a3950-9e30-11ed-9595-550fbe4215c2 from 1677749464497210 I/flutter ( 9690): PURCHASE_RECEIPT: Listening for updates... on: b80a3950-9e30-11ed-9595-550fbe4215c2 I/flutter ( 9690): 4:51 Auth/INFO: Setting up done! I/flutter ( 9690): 4:51 Auth/FINE: Listening to claims updates for AuthUID: MsPQhRKykfM3WkehTpPBu0gw6Oj1 I/flutter ( 9690): CLAIMS: Listening for updates... on: MsPQhRKykfM3WkehTpPBu0gw6Oj1 I/flutter ( 9690): 4:51 Auth/INFO: Cannot update auth profile due to lack of account I/flutter ( 9690): 4:51 Auth/FINE: _refreshTokenAndGetClaims (attempt: 1) got token: Token<"eyJhbGci...owi03eiQ">[1101] I/flutter ( 9690): Set IdToken: Token<"eyJhbGci...owi03eiQ">[1101] I/flutter ( 9690): 4:51 Auth/INFO: Got claims from token I/flutter ( 9690): 4:51 Auth/INFO: {os_uid: b80a3950-9e30-11ed-9595-550fbe4215c2, phone_number: +447999999999, firebase: {identities: {google.com: [113958032945815660831], email: [foobar@gmail.com], phone: [+447999999999]}, sign_in_provider: google.com}, user_id: MsPQhRKykfM3WkehTpPBu0gw6Oj1, aud: onesceneapp, exp: 1677753064, iat: 1677749464, iss: https://securetoken.google.com/onesceneapp, sub: MsPQhRKykfM3WkehTpPBu0gw6Oj1, email: foobar@gmail.com, email_verified: true, auth_time: 1677749463} I/flutter ( 9690): 4:51 Auth/INFO: Authenticated platforms: [google.com, phone] I/flutter ( 9690): 4:51 Auth/FINE: Signed in... uid: MsPQhRKykfM3WkehTpPBu0gw6Oj1, provider: google.com I/flutter ( 9690): 4:51 Auth/INFO: Setting up listeners... I/flutter ( 9690): 4:51 Auth/INFO: Setting up done! I/flutter ( 9690): 4:51 Auth/INFO: Cannot update auth profile due to lack of account W/DynamiteModule( 9690): Local module descriptor class for com.google.android.gms.providerinstaller.dynamite not found. I/DynamiteModule( 9690): Considering local module com.google.android.gms.providerinstaller.dynamite:0 and remote module com.google.android.gms.providerinstaller.dynamite:0 W/ProviderInstaller( 9690): Failed to load providerinstaller module: No acceptable module com.google.android.gms.providerinstaller.dynamite found. Local version is 0 and remote version is 0. D/nativeloader( 9690): Configuring classloader-namespace for other apk /system/framework/com.android.media.remotedisplay.jar. target_sdk_version=33, uses_libraries=ALL, library_path=/data/app/~~fMlmWVMnTXW1Bzw9yBC-UA==/com.google.android.gms-6ZqQRtTVzsr0qjchpROSKw==/lib/arm64:/data/app/~~fMlmWVMnTXW1Bzw9yBC-UA==/com.google.android.gms-6ZqQRtTVzsr0qjchpROSKw==/base.apk!/lib/arm64-v8a, permitted_path=/data:/mnt/expand:/data/user/0/com.google.android.gms W/om.onescene.ap( 9690): Loading /data/misc/apexdata/com.android.art/dalvik-cache/arm64/system@framework@com.android.location.provider.jar@classes.odex non-executable as it requires an image which we failed to load D/nativeloader( 9690): Configuring classloader-namespace for other apk /system/framework/com.android.location.provider.jar. target_sdk_version=33, uses_libraries=ALL, library_path=/data/app/~~fMlmWVMnTXW1Bzw9yBC-UA==/com.google.android.gms-6ZqQRtTVzsr0qjchpROSKw==/lib/arm64:/data/app/~~fMlmWVMnTXW1Bzw9yBC-UA==/com.google.android.gms-6ZqQRtTVzsr0qjchpROSKw==/base.apk!/lib/arm64-v8a, permitted_path=/data:/mnt/expand:/data/user/0/com.google.android.gms D/nativeloader( 9690): Configuring classloader-namespace for other apk /data/app/~~fMlmWVMnTXW1Bzw9yBC-UA==/com.google.android.gms-6ZqQRtTVzsr0qjchpROSKw==/base.apk. target_sdk_version=33, uses_libraries=, library_path=/data/app/~~fMlmWVMnTXW1Bzw9yBC-UA==/com.google.android.gms-6ZqQRtTVzsr0qjchpROSKw==/lib/arm64:/data/app/~~fMlmWVMnTXW1Bzw9yBC-UA==/com.google.android.gms-6ZqQRtTVzsr0qjchpROSKw==/base.apk!/lib/arm64-v8a, permitted_path=/data:/mnt/expand:/data/user/0/com.google.android.gms V/NativeCrypto( 9690): Registering com/google/android/gms/org/conscrypt/NativeCrypto's 295 native methods... W/om.onescene.ap( 9690): Accessing hidden method Ljava/security/spec/ECParameterSpec;->getCurveName()Ljava/lang/String; (unsupported, reflection, allowed) I/ProviderInstaller( 9690): Installed default security provider GmsCore_OpenSSL W/om.onescene.ap( 9690): Accessing hidden field Ljava/net/Socket;->impl:Ljava/net/SocketImpl; (unsupported, reflection, allowed) W/om.onescene.ap( 9690): Accessing hidden method Ljava/security/spec/ECParameterSpec;->setCurveName(Ljava/lang/String;)V (unsupported, reflection, allowed) W/Firestore( 9690): (24.1.2) [Firestore]: Listen for Query(target=Query(queue/b80a3950-9e30-11ed-9595-550fbe4215c2 order by __name__);limitType=LIMIT_TO_FIRST) failed: e1{code=PERMISSION_DENIED, description=Missing or insufficient permissions., cause=null} W/Firestore( 9690): (24.1.2) [Firestore]: Listen for Query(target=Query(account/b80a3950-9e30-11ed-9595-550fbe4215c2 order by __name__);limitType=LIMIT_TO_FIRST) failed: e1{code=PERMISSION_DENIED, description=Missing or insufficient permissions., cause=null} W/Firestore( 9690): (24.1.2) [Firestore]: Listen for Query(target=Query(radar/b80a3950-9e30-11ed-9595-550fbe4215c2 order by __name__);limitType=LIMIT_TO_FIRST) failed: e1{code=PERMISSION_DENIED, description=Missing or insufficient permissions., cause=null} W/Firestore( 9690): (24.1.2) [Firestore]: Listen for Query(target=Query(purchase where uid==b80a3950-9e30-11ed-9595-550fbe4215c2 and consumed>time(1677749464,497210000) order by -consumed, -__name__);limitType=LIMIT_TO_FIRST) failed: e1{code=PERMISSION_DENIED, description=Missing or insufficient permissions., cause=null} W/Firestore( 9690): (24.1.2) [Firestore]: Listen for Query(target=Query(claims/MsPQhRKykfM3WkehTpPBu0gw6Oj1 order by __name__);limitType=LIMIT_TO_FIRST) failed: e1{code=PERMISSION_DENIED, description=Missing or insufficient permissions., cause=null} I/flutter ( 9690): 8:28 Auth/SEVERE: listenForProfileQueueUpdates error: [cloud_firestore/permission-denied] The caller does not have permission to execute the specified operation. I/flutter ( 9690): ----------------FIREBASE CRASHLYTICS---------------- I/flutter ( 9690): The following exception was thrown listenForProfileQueueUpdates: I/flutter ( 9690): [cloud_firestore/permission-denied] The caller does not have permission to execute the specified operation. I/flutter ( 9690): ---------------------------------------------------- I/flutter ( 9690): 8:34 Auth/SEVERE: listenForAccountUpdates error: [cloud_firestore/permission-denied] The caller does not have permission to execute the specified operation. I/flutter ( 9690): ----------------FIREBASE CRASHLYTICS---------------- I/flutter ( 9690): The following exception was thrown listenForAccountUpdates: I/flutter ( 9690): [cloud_firestore/permission-denied] The caller does not have permission to execute the specified operation. I/flutter ( 9690): ---------------------------------------------------- I/flutter ( 9690): 8:35 Auth/SEVERE: listenForProfileRadarUpdates error: [cloud_firestore/permission-denied] The caller does not have permission to execute the specified operation. I/flutter ( 9690): ----------------FIREBASE CRASHLYTICS---------------- I/flutter ( 9690): The following exception was thrown listenForProfileRadarUpdates: I/flutter ( 9690): [cloud_firestore/permission-denied] The caller does not have permission to execute the specified operation. I/flutter ( 9690): ---------------------------------------------------- I/flutter ( 9690): 8:35 Auth/SEVERE: listenForPurchases error: [cloud_firestore/permission-denied] The caller does not have permission to execute the specified operation. I/flutter ( 9690): ----------------FIREBASE CRASHLYTICS---------------- I/flutter ( 9690): The following exception was thrown listenForPurchases: I/flutter ( 9690): [cloud_firestore/permission-denied] The caller does not have permission to execute the specified operation. I/flutter ( 9690): ---------------------------------------------------- I/flutter ( 9690): 8:36 Auth/SEVERE: listenForClaimsUpdates error: [cloud_firestore/permission-denied] The caller does not have permission to execute the specified operation. I/flutter ( 9690): ----------------FIREBASE CRASHLYTICS---------------- I/flutter ( 9690): The following exception was thrown listenForClaimsUpdates: I/flutter ( 9690): [cloud_firestore/permission-denied] The caller does not have permission to execute the specified operation. I/flutter ( 9690): ---------------------------------------------------- W/Firestore( 9690): (24.1.2) [WatchStream]: (8386697) Stream closed with status: e1{code=CANCELLED, description=Disconnecting idle stream. Timed out waiting for new targets., cause=null}. ```

I also captured the logcat output:

app-log.txt

At line 5020 there are messages referencing my app and also fs-verity that could be Firestore app check failing?

03-02 09:30:15.918  1920  2090 E VerityUtils: Failed to measure fs-verity, errno 1: /data/app/~~dtXA1TuOihv4dVxvcCTsHQ==/com.MYAPP.app-NerpVLeRQElnOMh02lqIWw==/base.apk
03-02 09:30:15.949  1920  2061 W ActivityManager: Slow operation: 67ms so far, now at startProcess: done updating battery stats
03-02 09:30:15.949  1920  2061 W ActivityManager: Slow operation: 67ms so far, now at startProcess: building log message
03-02 09:30:15.949  1920  2061 I ActivityManager: Start proc 9690:com.MYAPP.app/u0a20 for pre-top-activity {com.MYAPP.app/com.MYAPP.app.MainActivity}
03-02 09:30:15.949  1920  2061 W ActivityManager: Slow operation: 67ms so far, now at startProcess: starting to update pids map
03-02 09:30:15.950  1920  2061 W ActivityManager: Slow operation: 67ms so far, now at startProcess: done updating pids map
03-02 09:30:16.376  1920  2059 W PackageManager: Failed registering loading progress callback. Package is fully loaded.
03-02 09:30:17.180  1920  2090 E VerityUtils: Failed to measure fs-verity, errno 1: /data/app/~~dtXA1TuOihv4dVxvcCTsHQ==/com.MYAPP.app-NerpVLeRQElnOMh02lqIWw==/base.apk

You can see the google sign in triggered at line 5766 which is what led to the permission denied errors. Oddly the debug output of from the flutter app isn't shown in logcat. I'm not sure why that is.

Hot-restarting the app fixed the issue. I do have the suspicion this all App Check related. The fact it was getting permission denied error attempting to loading claims/MsPQhRKykfM3WkehTpPBu0gw6Oj1 makes no sense, here are the related rules:

    function isAuthenticated() {
      return request.auth != null;
    }
    function isAuthOwner(auid) {
      return isAuthenticated() && request.auth.uid == auid;
    }
    match /claims/{auth_uid} {
      allow read: if isAuthOwner(auth_uid) || isStaffWithClaimsPermission() || isAdmin();
    }

You can see the in logs that the Firebase Auth claims have the uid set correctly: uid: MsPQhRKykfM3WkehTpPBu0gw6Oj1

I've already shared my app check implementation here. https://github.com/firebase/flutterfire/issues/10331#issuecomment-1434831612

Is there anything more I can do to try resolve this? I'm getting tens of these crash reports daily and negative reviews because of it.

wu-hui commented 1 year ago

Hey there, I work on the underlying Firestore SDK.

This issue does look like Auth/Appcheck related. I'd still like to ask a couple more questions:

Thanks.

jimmyff commented 1 year ago

Hi @wu-hui, so sorry for the delay getting back to you, I've only just seen your message.

I actually attempted turning off appcheck Firestore enforcement over the weekend however I still received many of these permission denied errors which was surprising.

  • Is persistence enabled?

No, I'm not using persistence

  • Is it possible to turn on debug logging for all firebase SDKs used here?

This is a production app but I'm willing to try anything at this point. How do I go about enabling debug logging for the SDKs?

Thanks

waprin commented 1 year ago

I've encountered this same issue. It only happens to me on Safari on iOS so far (even though its the exact same code on web).

Pretty frustrating since it says existing users don't exist so gets redirected to user onboarding.

I can't reliably reproduce it unfortunately but I am willing to try to report more debug info if I get some guidance on how to do so.

diegog-sf commented 1 year ago

Hello we're also experiencing this issue, we tried to get around it but the converters use it internally.

image
diegog-sf commented 1 year ago

I have a theory on why this could be happening. I just tested with a fresh install while offline and I received exists==false, so when there's no data available its returning exists==false. and because you @jimmyff don't have persistence, you won't have the document available offline.

Could you try adding to your reporting if the user has a network connection?

wmurphyrd commented 9 months ago

I think I'm seeing this as well. It's difficult to reproduce issue but with only a couple possible explanations with exists false negatives being one of them. Not actually using flutterfire - just JS web client for firestore (specifically in a snapshot listener callback)

surrounding logs definitely suggest internet connection issues, e.g. "Could not reach Cloud Firestore backend. Backend didn't respond within 10 seconds."

Is there an alternative to check if a document exists in a way that will fail if the backend cannot be reached?

Looks like https://firebase.google.com/docs/reference/js/firestore_.md#getdocfromserver might be the answer there

stevethehu commented 4 months ago

I'm also getting exists==false for a document that definitely exists, which is unexpected and breaking. I do have App Check enabled and there seem to be some number of rejected/unverified requests, but those usually manifest as permission denied errors.

wu-hui commented 4 months ago

Hi all,

I think @diegog-sf might be right. This might happen when the SDK try to get the document from cache but the document simply is not there due to network condition or some other reasons.

To make sure you see valid exists value, you should subscribe to snapshot metadata as well, and when fromCache is false, the snapshot is raised with backend data, which is a verified way to make sure the document exists or not.

An alternative is to use runTransation, this will bypass SDK cache all together, and will get the backend data only, and fail when there is connectivity issue.

stevethehu commented 4 months ago

Thanks @wu-hui ! Do you know whether this is expected behavior? It seems confusing for the SDK/cache to have no concept of cache misses and return "false negatives" for snapshots() listeners, particularly when it seems to throw cloud_firestore/unavailable errors for get() requests. Is this documented somewhere, and could you link to it if so?

russellwheatley commented 4 months ago

Hi all,

I think @diegog-sf might be right. This might happen when the SDK try to get the document from cache but the document simply is not there due to network condition or some other reasons.

To make sure you see valid exists value, you should subscribe to snapshot metadata as well, and when fromCache is false, the snapshot is raised with backend data, which is a verified way to make sure the document exists or not.

An alternative is to use runTransation, this will bypass SDK cache all together, and will get the backend data only, and fail when there is connectivity issue.

@wu-hui - thanks for the update. This makes sense given the difficulty to reproduce.

@jimmyff - I would redesign the implementation with the above mentioned in mind. If you still see false negatives, could you report back with your findings. Thanks πŸ™

stevethehu commented 4 months ago

I'm using flutter + firestore SDK (not flutterfire), and this is consistently reproducible by doing a clean install (empty cache) and then turning off network connectivity before making a document snapshots request or a get request. The snapshots return the exists==false snapshot from cache, while the get request throws the unavailable error. If the network connectivity is switched back on, the snapshots stream seems to then emit a valid snapshot from the server.

@russellwheatley maybe this issue should be re-routed if there's a different core firestore repo?

google-oss-bot commented 4 months ago

Hey @jimmyff. We need more information to resolve this issue but there hasn't been an update in 7 weekdays. I'm marking the issue as stale and if there are no new updates in the next 7 days I will close it automatically.

If you have more information that will help us get to the bottom of this, just add a comment!

google-oss-bot commented 3 months ago

Since there haven't been any recent updates here, I am going to close this issue.

@jimmyff if you're still experiencing this problem and want to continue the discussion just leave a comment here and we are happy to re-open this.

mogol commented 3 months ago

We bumped into similar issue: if the persistence is enabled for web, some snapshots return not exist even if docs do exist.
It's very annoying as it blocks critical path in user journey.

It can be reproduced when 1) firebase auth is used 2) the persistence is enabled 3) a user deletes site data

An example project: https://github.com/mogol/firestore-web-flutter/blob/master/lib/main.dart

Steps:

If persistence is off, it works as expected: it shows the latest value after tab refresh.

FirebaseFirestore.instance.settings = const Settings(persistenceEnabled: false);
mogol commented 3 months ago

@TarekkMA @russellwheatley Could you re-open the issue or should I create new one?

TarekkMA commented 3 months ago

@mogol If you can open a new issues that would be great, and please add a reproduction information.