firebase / quickstart-unity

Firebase Quickstart Samples for Unity
https://firebase.google.com/games
Apache License 2.0
832 stars 428 forks source link

Firestore Listener Callback Crashes On Android, but works fine in the Unity editor. #959

Closed RobinopdeBeek closed 3 years ago

RobinopdeBeek commented 3 years ago

[REQUIRED] Please fill in the following fields:

[REQUIRED] Please describe the issue here:

I am not sure how to reproduce this issue. I am mostly looking for insights into what could cause this issue. Sorry if this is the wrong place to ask this. Patrick Martin suggested I ask my question here again.

My Unity app uses Firebase Firestore listeners to receive data. In the Unity editor everything works very well and I never get an error. I built to my Android device (Pixel 2), but there it crashes about a second after startup.

I looked at Android Logcat and noticed that the last thing it did was receive a callback from Firestore:

2021/02/11 10:04:35.698 26660 26697 Info Unity Received Public Projects Query Callback. No pending writes, so we can update the Projects. Documents: 2
2021/02/11 10:04:35.698 26660 26697 Info Unity ArchViewer.<>c:<ListenToPublicProjects>b__71_0(QuerySnapshot)
2021/02/11 10:04:35.698 26660 26697 Info Unity System.Action`1:Invoke(T)
2021/02/11 10:04:35.698 26660 26697 Info Unity Firebase.Firestore.<Listen>c__AnonStorey1:<>m__0()
2021/02/11 10:04:35.698 26660 26697 Info Unity System.Func`1:Invoke()
2021/02/11 10:04:35.698 26660 26697 Info Unity System.Action`3:Invoke(T1, T2, T3)
2021/02/11 10:04:35.698 26660 26697 Info Unity Firebase.Firestore.Query:QuerySnapshotsHandler(Int32, IntPtr, FirestoreError, String)
2021/02/11 10:04:35.698 26660 26697 Info Unity Firebase.AppUtilPINVOKE:PollCallbacks()
2021/02/11 10:04:35.698 26660 26697 Info Unity Firebase.AppUtil:PollCallbacks()
2021/02/11 10:04:35.698 26660 26697 Info Unity Firebase.Platform.FirebaseHandler:Update()
2021/02/11 10:04:35.698 26660 26697 Info Unity 
2021/02/11 10:04:35.708 26660 26697 Info Unity Finished creating Project ScriptableObject with title: Public 1
2021/02/11 10:04:35.708 26660 26697 Info Unity ArchViewer.<>c:<ListenToPublicProjects>b__71_0(QuerySnapshot)
2021/02/11 10:04:35.708 26660 26697 Info Unity System.Action`1:Invoke(T)
2021/02/11 10:04:35.708 26660 26697 Info Unity Firebase.Firestore.<Listen>c__AnonStorey1:<>m__0()
2021/02/11 10:04:35.708 26660 26697 Info Unity System.Func`1:Invoke()
2021/02/11 10:04:35.708 26660 26697 Info Unity System.Action`3:Invoke(T1, T2, T3)
2021/02/11 10:04:35.708 26660 26697 Info Unity Firebase.Firestore.Query:QuerySnapshotsHandler(Int32, IntPtr, FirestoreError, String)
2021/02/11 10:04:35.708 26660 26697 Info Unity Firebase.AppUtilPINVOKE:PollCallbacks()
2021/02/11 10:04:35.708 26660 26697 Info Unity Firebase.AppUtil:PollCallbacks()
2021/02/11 10:04:35.708 26660 26697 Info Unity Firebase.Platform.FirebaseHandler:Update()

After that the fatal error(s) happens:

2021/02/11 10:04:35.710 26660 26697 Fatal igns.ArchViewe java_vm_ext.cc:577] JNI DETECTED ERROR IN APPLICATION: mid == null
2021/02/11 10:04:35.710 26660 26697 Fatal igns.ArchViewe java_vm_ext.cc:577]     in call to CallObjectMethodV
2021/02/11 10:04:35.710 26660 26697 Fatal igns.ArchViewe java_vm_ext.cc:577]     from boolean com.unity3d.player.UnityPlayer.nativeRender()
2021/02/11 10:04:35.918 26660 26697 Fatal igns.ArchViewe runtime.cc:655] Runtime aborting...
2021/02/11 10:04:35.918 26660 26697 Fatal igns.ArchViewe runtime.cc:655] Dumping all threads without mutator lock held
2021/02/11 10:04:35.918 26660 26697 Fatal igns.ArchViewe runtime.cc:655] All threads:
2021/02/11 10:04:35.918 26660 26697 Fatal igns.ArchViewe runtime.cc:655] DALVIK THREADS (47):
2021/02/11 10:04:35.918 26660 26697 Fatal igns.ArchViewe runtime.cc:655] "UnityMain" prio=5 tid=23 Runnable
2021/02/11 10:04:35.918 26660 26697 Fatal igns.ArchViewe runtime.cc:655]   | group="" sCount=0 dsCount=0 flags=0 obj=0x13380d50 self=0x7937c7c330
2021/02/11 10:04:35.918 26660 26697 Fatal igns.ArchViewe runtime.cc:655]   | sysTid=26697 nice=0 cgrp=default sched=0/0 handle=0x775df12cc0
2021/02/11 10:04:35.918 26660 26697 Fatal igns.ArchViewe runtime.cc:655]   | state=R schedstat=( 1655690067 79266843 2054 ) utm=124 stm=40 core=6 HZ=100
2021/02/11 10:04:35.918 26660 26697 Fatal igns.ArchViewe runtime.cc:655]   | stack=0x775de0f000-0x775de11000 stackSize=1043KB
2021/02/11 10:04:35.918 26660 26697 Fatal igns.ArchViewe runtime.cc:655]   | held mutexes= "abort lock" "mutator lock"(shared held)
2021/02/11 10:04:35.918 26660 26697 Fatal igns.ArchViewe runtime.cc:655]   native: #00 pc 00000000004a53f4  /apex/com.android.art/lib64/libart.so (art::DumpNativeStack(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, int, BacktraceMap*, char const*, art::ArtMethod*, void*, bool)+140)
2021/02/11 10:04:35.918 26660 26697 Fatal igns.ArchViewe runtime.cc:655]   native: #01 pc 00000000005b42b4  /apex/com.android.art/lib64/libart.so (art::Thread::DumpStack(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, bool, BacktraceMap*, bool) const+372)
2021/02/11 10:04:35.918 26660 26697 Fatal igns.ArchViewe runtime.cc:655]   native: #02 pc 00000000005d1854  /apex/com.android.art/lib64/libart.so (art::DumpCheckpoint::Run(art::Thread*)+924)
2021/02/11 10:04:35.918 26660 26697 Fatal igns.ArchViewe runtime.cc:655]   native: #03 pc 00000000005cb6c4  /apex/com.android.art/lib64/libart.so (art::ThreadList::RunCheckpoint(art::Closure*, art::Closure*)+532)
2021/02/11 10:04:35.918 26660 26697 Fatal igns.ArchViewe runtime.cc:655]   native: #04 pc 00000000005ca844  /apex/com.android.art/lib64/libart.so (art::ThreadList::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, bool)+1876)
2021/02/11 10:04:35.918 26660 26697 Fatal igns.ArchViewe runtime.cc:655]   native: #05 pc 000000000056462c  /apex/com.android.art/lib64/libart.so (art::Runtime::Abort(char const*)+1876)
2021/02/11 10:04:35.918 26660 26697 Fatal igns.ArchViewe runtime.cc:655]   native: #06 pc 0000000000013ab0  /system/lib64/libbase.so (android::base::SetAborter(std::__1::function<void (char const*)>&&)::$_3::__invoke(char const*)+80)
2021/02/11 10:04:35.918 26660 26697 Fatal igns.ArchViewe runtime.cc:655]   native: #07 pc 0000000000013090  /system/lib64/libbase.so (android::base::LogMessage::~LogMessage()+320)
2021/02/11 10:04:35.918 26660 26697 Fatal igns.ArchViewe runtime.cc:655]   native: #08 pc 0000000000389da8  /apex/com.android.art/lib64/libart.so (art::JavaVMExt::JniAbort(char const*, char const*)+2608)
2021/02/11 10:04:35.918 26660 26697 Fatal igns.ArchViewe runtime.cc:655]   native: #09 pc 00000000003a4734  /apex/com.android.art/lib64/libart.so (art::JNI<false>::CallObjectMethodV(_JNIEnv*, _jobject*, _jmethodID*, std::__va_list)+1700)
2021/02/11 10:04:35.918 26660 26697 Fatal igns.ArchViewe runtime.cc:655]   native: #10 pc 00000000001e7554  /data/app/~~WK9Rq0LV_A-EsduTZIxKVw==/com.AugmentedDesigns.ArchViewer-1j8xGXViQlOWNbsspWzlgQ==/lib/arm64/libFirebaseCppApp-7_0_2.so (_JNIEnv::CallObjectMethod(_jobject*, _jmethodID*, ...)+92)
2021/02/11 10:04:35.918 26660 26697 Fatal igns.ArchViewe runtime.cc:655]   native: #11 pc 0000000000224b7c  /data/app/~~WK9Rq0LV_A-EsduTZIxKVw==/com.AugmentedDesigns.ArchViewer-1j8xGXViQlOWNbsspWzlgQ==/lib/arm64/libFirebaseCppApp-7_0_2.so (std::__ndk1::enable_if<!(is_same<firebase::firestore::DocumentChangeTypeInternal, void>::value), firebase::firestore::jni::ResultTypeMap<firebase::firestore::DocumentChangeTypeInternal, IsPrimitive<firebase::firestore::jni::JniTypeMap<std::__ndk1::decay<firebase::firestore::DocumentChangeTypeInternal>::type>::type>::value>::type>::type firebase::firestore::jni::Env::CallHelper<firebase::firestore::DocumentChangeTypeInternal, _jobject* (_JNIEnv::*&)(_jobject*, _jmethodID*, ...), _jobject*, _jmethodID*>(_jobject* (_JNIEnv::*&)(_jobject*, _jmethodID*, ...), _jobject*&&, _jmethodID*&&)+112)
2021/02/11 10:04:35.918 26660 26697 Fatal igns.ArchViewe runtime.cc:655]   native: #12 pc 0000000000224988  /data/app/~~WK9Rq0LV_A-EsduTZIxKVw==/com.AugmentedDesigns.ArchViewer-1j8xGXViQlOWNbsspWzlgQ==/lib/arm64/libFirebaseCppApp-7_0_2.so (firebase::firestore::jni::ResultTypeMap<firebase::firestore::DocumentChangeTypeInternal, IsPrimitive<firebase::firestore::jni::JniTypeMap<std::__ndk1::decay<firebase::firestore::DocumentChangeTypeInternal>::type>::type>::value>::type firebase::firestore::jni::Env::Call<firebase::firestore::DocumentChangeTypeInternal>(firebase::firestore::jni::Object const&, firebase::firestore::jni::Method<firebase::firestore::DocumentChangeTypeInternal> const&)+88)
2021/02/11 10:04:35.918 26660 26697 Fatal igns.ArchViewe runtime.cc:655]   native: #13 pc 00000000002248fc  /data/app/~~WK9Rq0LV_A-EsduTZIxKVw==/com.AugmentedDesigns.ArchViewer-1j8xGXViQlOWNbsspWzlgQ==/lib/arm64/libFirebaseCppApp-7_0_2.so (firebase::firestore::DocumentChangeInternal::type() const+36)
2021/02/11 10:04:35.918 26660 26697 Fatal igns.ArchViewe runtime.cc:655]   native: #14 pc 00000000007b0300  /data/app/~~WK9Rq0LV_A-EsduTZIxKVw==/com.AugmentedDesigns.ArchViewer-1j8xGXViQlOWNbsspWzlgQ==/lib/arm64/libil2cpp.so (???)

And that goes on for another 2700 lines... If you need a different section just let me know

Steps to reproduce:

Have you been able to reproduce this issue with just the Firebase Unity quickstarts (this GitHub project)? No, this is from my project that I've been working on for quite some time. Hopefully someone can give some insights into what could cause this issue first, but if you guys really need a sample project I'll spend some time on making it :)

Relevant Code:

The code that handles initialization:

private static FirebaseApp app;

        private async void Start()
        {
            await Initialize();
        }

        private async Task Initialize()
        {
            var dependencyResult = await FirebaseApp.CheckAndFixDependenciesAsync();
            if (dependencyResult == DependencyStatus.Available)
            {
                Debug.Log("Initializing Firebase");
                app = FirebaseApp.DefaultInstance;

                FirestoreManager.InitializeDatabase();
                DatabaseManager.InitializeDatabase();
                StorageManager.InitializeStorage();
                CloudFunctionManager.InitializeCloud();
                AuthenticationManager.InitializeAuth();
            }
            else
            {
                Debug.LogError(String.Format(
                      "Could not resolve all Firebase dependencies: " + dependencyStatus));
            }
        }

// In FirestoreManager:
private static FirebaseFirestore database;

        public static void InitializeDatabase()
        {
            if (database == null)
            {
                database = FirebaseFirestore.DefaultInstance;
            }
        }

The code that registers the Firestore listener and callback:

        public static ListenerRegistration ListenToPublicProjects(Timestamp LastModified)
        {
            Query queryRef = database.Collection(ProjectsCollection).WhereEqualTo(ProjectTypeField, 1)
                .WhereGreaterThan(LastModifiedField, LastModified);

            ListenerRegistration listener = queryRef.Listen(snapshot =>
            {
                if (snapshot.Metadata.HasPendingWrites)
                {   Debug.Log("Received Public Projects Query Callback. Still waiting for pending writes before we can update the Projects..."); return; }
                else
                    Debug.Log("Received Public Projects Query Callback. No pending writes, so we can update the Projects. Documents: " + snapshot.Count);

                if (snapshot.Count == 0)
                {   Debug.Log("Public Projects Query is empty"); return; }

                foreach (DocumentChange change in snapshot.GetChanges())
                {
                    DocumentSnapshot document = change.Document;
                    ArchProjectData projectData = ArchProjectData.FromDictionary(document.ToDictionary()); // Creates a new ArchProjectData class with all info received from the document.
                    ArchProject project = AssemblyManager.CreateProject(projectData); // Creates a ScriptableObject 

                    Debug.Log("Finished creating Project ScriptableObject with title: " + project.data.Title);  // --- This line is found in Logcat ---

                    if (change.ChangeType == DocumentChange.Type.Added)
                    {
                        Debug.Log(String.Format("New public project: {0}", change.Document.Id)); // --- This line is NOT found in Logcat ---
                        ReferenceManager.AddProject(project, ProjectList.PublicProjects);
                    }
                    else if (change.ChangeType == DocumentChange.Type.Modified)
                    {
                        Debug.Log(String.Format("Modified public project: {0}", change.Document.Id));
                        ReferenceManager.UpdateProject(project, ProjectList.PublicProjects);
                    }
                    else if (change.ChangeType == DocumentChange.Type.Removed)
                    {
                        Debug.Log(String.Format("Removed public project: {0}", change.Document.Id));
                        ReferenceManager.RemoveProject(project, ProjectList.PublicProjects);
                    }
                }

                OnPublicProjectsReceived?.Invoke();
            });
            return listener;
        }

My thoughts so far

The code reaches Debug.Log("Finished creating Project ScriptableObject with title: " + project.data.Title);. So the documents are well received. After that I handle the DocumentChanges, where the error JNI DETECTED ERROR IN APPLICATION: mid == null is raised. Does that mean the QuerySnapshot or DocumentChange no longer exist? I tried storing both the QuerySnapshot and DocumentChange as static variables, but that didn't help.

Thanks for any assistance!

RobinopdeBeek commented 3 years ago

I've pinpointed where the issue occurs and it happens when callling change.ChangeType. I ran this code in the listener callback code:

foreach (DocumentChange change in snapshot.GetChanges())
{
    Debug.Log("change.ToString()" + change.ToString());
    Debug.Log("change.Document.Id" + change.Document.Id);
    Debug.Log("change.NewIndex" + change.NewIndex);
    Debug.Log("DocumentChange.Type.Added: " + DocumentChange.Type.Added);
    Debug.Log("change.ChangeType" + change.ChangeType);
}

Reading .Document.ID or .NewIndex work fine, but when trying to read .ChangeType the crash happens.

Any ideas for a solution or work around maybe?

RobinopdeBeek commented 3 years ago

Found the work around on the forums! https://github.com/firebase/quickstart-unity/issues/889#issuecomment-745695182

public DocumentChange.Type GetChangeType(DocumentChange change) {
  if (change.OldIndex < 0) {
    return DocumentChange.Type.Added;
  } else if (change.NewIndex < 0) {
    return DocumentChange.Type.Removed;
  } else {
    return DocumentChange.Type.Modified;
  }
}

Thanks @wilhuff !