Filament: Update to Filament 1.5.2 with SceneForm 1.16.0 crashes in ArSceneView constructor

[zirman]

I'm getting the following crash when trying to use the latest version of Filament. Filament 1.4.5 does not get this crash on startup.

04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641] Runtime aborting...
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641] Dumping all threads without mutator lock held
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641] All threads:
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641] DALVIK THREADS (92):
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641] "main" prio=7 tid=1 Runnable
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   | group="" sCount=0 dsCount=0 flags=0 obj=0x715055c0 self=0x747c746000
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   | sysTid=24873 nice=-4 cgrp=default sched=0/0 handle=0x747dcb9ee8
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   | state=R schedstat=( 1926828335 218936642 2578 ) utm=162 stm=30 core=7 HZ=100
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   | stack=0x7fdda4c000-0x7fdda4e000 stackSize=8192KB
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   | held mutexes= "abort lock" "mutator lock"(shared held)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   native: #00 pc 0000000000411f0c  /apex/com.android.runtime/lib64/libart.so (art::DumpNativeStack(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, int, BacktraceMap*, char const*, art::ArtMethod*, void*, bool)+140)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   native: #01 pc 00000000004fa21c  /apex/com.android.runtime/lib64/libart.so (art::Thread::DumpStack(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, bool, BacktraceMap*, bool) const+512)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   native: #02 pc 000000000051487c  /apex/com.android.runtime/lib64/libart.so (art::DumpCheckpoint::Run(art::Thread*)+828)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   native: #03 pc 000000000050d9e4  /apex/com.android.runtime/lib64/libart.so (art::ThreadList::RunCheckpoint(art::Closure*, art::Closure*)+560)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   native: #04 pc 000000000050ce60  /apex/com.android.runtime/lib64/libart.so (art::ThreadList::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, bool)+1964)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   native: #05 pc 00000000004b9d54  /apex/com.android.runtime/lib64/libart.so (art::Runtime::Abort(char const*)+1452)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   native: #06 pc 000000000000b458  /system/lib64/libbase.so (android::base::LogMessage::~LogMessage()+580)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   native: #07 pc 00000000003786e8  /apex/com.android.runtime/lib64/libart.so (art::JavaVMExt::JniAbort(char const*, char const*)+1584)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   native: #08 pc 000000000037890c  /apex/com.android.runtime/lib64/libart.so (art::JavaVMExt::JniAbortV(char const*, char const*, std::__va_list)+108)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   native: #09 pc 000000000036ad34  /apex/com.android.runtime/lib64/libart.so (art::(anonymous namespace)::ScopedCheck::AbortF(char const*, ...)+136)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   native: #10 pc 000000000036a384  /apex/com.android.runtime/lib64/libart.so (art::(anonymous namespace)::ScopedCheck::CheckInstance(art::ScopedObjectAccess&, art::(anonymous namespace)::ScopedCheck::InstanceKind, _jobject*, bool)+420)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   native: #11 pc 00000000003695d4  /apex/com.android.runtime/lib64/libart.so (art::(anonymous namespace)::ScopedCheck::CheckPossibleHeapValue(art::ScopedObjectAccess&, char, art::(anonymous namespace)::JniValueType)+580)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   native: #12 pc 0000000000368bf0  /apex/com.android.runtime/lib64/libart.so (art::(anonymous namespace)::ScopedCheck::Check(art::ScopedObjectAccess&, bool, char const*, art::(anonymous namespace)::JniValueType*)+652)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   native: #13 pc 000000000036dc40  /apex/com.android.runtime/lib64/libart.so (art::(anonymous namespace)::CheckJNI::CheckCallArgs(art::ScopedObjectAccess&, art::(anonymous namespace)::ScopedCheck&, _JNIEnv*, _jobject*, _jclass*, _jmethodID*, art::InvokeType, art::(anonymous namespace)::VarArgs const*)+132)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   native: #14 pc 000000000036cb30  /apex/com.android.runtime/lib64/libart.so (art::(anonymous namespace)::CheckJNI::CallMethodV(char const*, _JNIEnv*, _jobject*, _jclass*, _jmethodID*, std::__va_list, art::Primitive::Type, art::InvokeType)+712)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   native: #15 pc 000000000035ce20  /apex/com.android.runtime/lib64/libart.so (art::(anonymous namespace)::CheckJNI::CallStaticIntMethodV(_JNIEnv*, _jclass*, _jmethodID*, std::__va_list)+76)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   native: #16 pc 000000000002fdfc  /data/app/com.ario.connect.debug-kJ2zyavn8QC-1Ba_nCjwwA==/lib/arm64/libfilament-jni.so (???)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   at com.google.android.filament.IndexBuffer.nSetBuffer(Native method)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   at com.google.android.filament.IndexBuffer.setBuffer(IndexBuffer.java:199)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   at com.google.android.filament.IndexBuffer.setBuffer(IndexBuffer.java:154)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   at com.google.ar.sceneform.rendering.CameraStream.<init>(CameraStream.java:84)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   at com.google.ar.sceneform.ArSceneView.initializeCameraStream(ArSceneView.java:716)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   at com.google.ar.sceneform.ArSceneView.initializeAr(ArSceneView.java:705)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   at com.google.ar.sceneform.ArSceneView.<init>(ArSceneView.java:99)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   at com.ario.connect.view.VideoCallActivity$onCreate$4.accept(VideoCallActivity.kt:227)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   at com.ario.connect.view.VideoCallActivity$onCreate$4.accept(VideoCallActivity.kt:59)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   at io.reactivex.internal.observers.LambdaObserver.onNext(LambdaObserver.java:63)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   at io.reactivex.internal.operators.observable.ObservableObserveOn$ObserveOnObserver.drainNormal(ObservableObserveOn.java:201)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   at io.reactivex.internal.operators.observable.ObservableObserveOn$ObserveOnObserver.run(ObservableObserveOn.java:255)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   at io.reactivex.android.schedulers.HandlerScheduler$ScheduledRunnable.run(HandlerScheduler.java:124)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   at android.os.Handler.handleCallback(Handler.java:883)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   at android.os.Handler.dispatchMessage(Handler.java:100)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   at android.os.Looper.loop(Looper.java:237)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   at android.app.ActivityThread.main(ActivityThread.java:7811)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   at java.lang.reflect.Method.invoke(Native method)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:493)
04-15 09:55:47.288 24873 24873 F o.connect.debu: runtime.cc:641]   at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1076)

Any help is appreciated.

[prideout]

Looks like this occurs when sceneform.rendering.CameraStream is calling filament.IndexBuffer.setBuffer. Hmm.

[prideout]

Given that you swapped out 1.4.5 with 1.5.2, did you have to make some updates to the sceneform source? We made a few non-backwards compatible API changes and material changes.

CC @tpsiaki

[mattmapadmi]

I'm running into the same issue. I didn't need to change any of the SceneForm source, it compiled fine. I've poked through the Filament source and can't see any changes in IndexBuffer between 1.4.5 and 1.5.2 that might cause this.

There's a more detailed error just above the stack trace in my app:

java_vm_ext.cc:570] JNI DETECTED ERROR IN APPLICATION: CallStaticIntMethodV received NULL jclass
java_vm_ext.cc:570]     in call to CallStaticIntMethodV
java_vm_ext.cc:570]     from int com.google.android.filament.IndexBuffer.nSetBuffer(long, long, java.nio.Buffer, int, int, int, java.lang.Object, java.lang.Runnable)

I thought maybe it was because there's no Handler or Callback supplied, but FilaMeshLoader doesn't pass those in either: https://github.com/google/filament/blob/b3d758f3b3fdf91b750a7561a1c729649cf4c1e8/tools/tungsten/core/src/com/google/android/filament/filamesh/FilameshLoader.java#L144

[zirman]

@prideout I didn't make any source changes to SceneForm 0.16 when updating Filament to 1.5.2.

[romainguy]

Checking with the ART team about what could cause this to happen. I don't understand what's causing this crash.

[romainguy]

BTW, @zirman @mattmapadmi did you compile Sceneform yourselves or are you using a prebuilt?

[zirman]

@romainguy I compile it myself. Oh wait. I did make some changes to get it working with androidx (@prideout). Here are my changes https://github.com/zirman/sceneform-android-sdk

[romainguy]

Those changes shouldn't matter, thanks for letting me know though.

[romainguy]

@prideout Could it be a JNI loading ordering issue maybe? Is Sceneform now supposed to call init from gltfio or from filament or both?

[romainguy]

I checked Sceneform's code and that's not it, they do the right thing:

if (!filamentInitialized) { try { gltfioInit(); } catch (UnsatisfiedLinkError err) { // Fallthrough and allow regular Filament to initialize. } } if (!filamentInitialized) { try { Filament.init(); filamentInitialized = true; } catch (UnsatisfiedLinkError err) { // For Scene Viewer Filament's jni is included in another lib, try that before failing. if (loadUnifiedJni()) { filamentInitialized = true; } else { throw err; } }

[romainguy]

@zirman Would mind adding logs in createEngine() in EngineInstance.java to see which code path is taken to initialize Filament's JNI?

[zirman]

@romainguy Sure. Here is what I did.

      if (!filamentInitialized) {
        try {
          Log.e("EngineInstance", "trying gltfioInit");
          gltfioInit();
        } catch (UnsatisfiedLinkError err) {
          Log.e("EngineInstance", "gltfioInit failed");
          err.printStackTrace();
          // Fallthrough and allow regular Filament to initialize.
        }
      }
      if (!filamentInitialized) {
        try {
          Log.e("EngineInstance", "trying Filament.init()");
          Filament.init();
          filamentInitialized = true;
        } catch (UnsatisfiedLinkError err) {
          Log.e("EngineInstance", "Filament.init() failed");
          err.printStackTrace();
          // For Scene Viewer Filament's jni is included in another lib, try that before failing.
          if (loadUnifiedJni()) {
            filamentInitialized = true;
          } else {
            throw err;
          }
        }
      }

With this result

2020-04-15 15:58:09.378 21092-21092/com.ario.connect.debug:video_call E/EngineInstance: trying gltfioInit

[romainguy]

Thank you. It's definitely doing the right thing then.

[zirman]

Are you able to repro? I could try posting the changes to the SceneForm sample app to help.

[romainguy]

I can't repro with any of our Android test apps that use IndexBuffer.

[zirman]

I opened the gltf project from here https://github.com/google-ar/sceneform-android-sdk/releases/download/v1.16.0%C2%A0/sceneform-android-sdk-1.16.0.zip
and just changed the filament dependencies to 1.5.2 and got the same error.

[romainguy]

I found the issue, it's in AutoBuffer. Apparently registerNioUtils() hasn't been invoked at the time we enter this code path.

[romainguy]

@prideout NioUtils uses a static struct to keep the JNI lookups. Could it be that we have multiple versions/we init the wrong one because we have multiple libraries?

[romainguy]

I submitted a fix. You can either use one of the continuous builds of Filament or wait for our next release to use it. Note that the next release breaks a couple of APIs which may impact Sceneform but we'll help you with the changes (they're fairly simple).