search

airsdk / Adobe-Runtime-Support

Report, track and discuss issues in Adobe AIR. Monitored by Adobe - and HARMAN - and maintained by the AIR community.
197 stars 11 forks source link

[urgent] ANE-PlayAssetDelivery - got error in transfering stage #1817

Open jimmymjing opened 2 years ago

jimmymjing commented 2 years ago

@ajwfrost @marchbold Hello, we just uploaded a new version. It work in internal sharing stage, but failed in release. Here's the log. As it is online. Please help. play store_2022_4_3_23_19_49.log

ajwfrost commented 2 years ago

There's something about a missing class in the log: 

04-03 15:18:38.813 E/LoadedApk( 3773): java.lang.ClassNotFoundException: Didn't find class "com.google.android.gms.chimera.GmsAppComponentFactory" on path: DexPathList[[zip file "/data/app/com.google.android.gms-LlJHSyIlEq33DaSbt2bMAg==/base.apk"],nativeLibraryDirectories=[/data/app/com.google.android.gms-LlJHSyIlEq33DaSbt2bMAg==/lib/arm64, /data/app/com.google.android.gms-LlJHSyIlEq33DaSbt2bMAg==/base.apk!/lib/arm64-v8a, /system/lib64, /product/lib64]]
04-03 15:18:38.813 E/LoadedApk( 3773):  at dalvik.system.BaseDexClassLoader.findClass(BaseDexClassLoader.java:196)
04-03 15:18:38.813 E/LoadedApk( 3773):  at java.lang.ClassLoader.loadClass(ClassLoader.java:379)
04-03 15:18:38.813 E/LoadedApk( 3773):  at java.lang.ClassLoader.loadClass(ClassLoader.java:312)
04-03 15:18:38.813 E/LoadedApk( 3773):  at android.app.LoadedApk.createAppFactory(LoadedApk.java:273)
04-03 15:18:38.813 E/LoadedApk( 3773):  at android.app.LoadedApk.createOrUpdateClassLoaderLocked(LoadedApk.java:896)
04-03 15:18:38.813 E/LoadedApk( 3773):  at android.app.LoadedApk.getClassLoader(LoadedApk.java:991)
04-03 15:18:38.813 E/LoadedApk( 3773):  at android.app.ContextImpl.getClassLoader(ContextImpl.java:390)
04-03 15:18:38.813 E/LoadedApk( 3773):  at com.google.android.gms.security.ProviderInstaller.zzb(com.google.android.gms:play-services-basement@@18.0.0:1)
04-03 15:18:38.813 E/LoadedApk( 3773):  at com.google.android.gms.security.ProviderInstaller.installIfNeeded(com.google.android.gms:play-services-basement@@18.0.0:9)
04-03 15:18:38.813 E/LoadedApk( 3773):  at com.google.firebase.inappmessaging.internal.ProviderInstaller.install(ProviderInstaller.java:34)
04-03 15:18:38.813 E/LoadedApk( 3773):  at com.google.firebase.inappmessaging.internal.ApiClient.getFiams(ApiClient.java:68)
04-03 15:18:38.813 E/LoadedApk( 3773):  at com.google.firebase.inappmessaging.internal.InAppMessageStreamManager.lambda$createFirebaseInAppMessageStream$16$InAppMessageStreamManager(InAppMessageStreamManager.java:261)
04-03 15:18:38.813 E/LoadedApk( 3773):  at com.google.firebase.inappmessaging.internal.InAppMessageStreamManager$$ExternalSyntheticLambda13.apply(Unknown Source:6)
04-03 15:18:38.813 E/LoadedApk( 3773):  at io.reactivex.internal.operators.maybe.MaybeMap$MapMaybeObserver.onSuccess(MaybeMap.java:82)
04-03 15:18:38.813 E/LoadedApk( 3773):  at io.reactivex.internal.operators.maybe.MaybeFilter$FilterMaybeObserver.onSuccess(MaybeFilter.java:89)
04-03 15:18:38.813 E/LoadedApk( 3773):  at io.reactivex.internal.operators.maybe.MaybeObserveOn$ObserveOnMaybeObserver.run(MaybeObserveOn.java:104)
04-03 15:18:38.813 E/LoadedApk( 3773):  at io.reactivex.Scheduler$DisposeTask.run(Scheduler.java:579)
04-03 15:18:38.813 E/LoadedApk( 3773):  at io.reactivex.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:66)
04-03 15:18:38.813 E/LoadedApk( 3773):  at io.reactivex.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:57)
04-03 15:18:38.813 E/LoadedApk( 3773):  at java.util.concurrent.FutureTask.run(FutureTask.java:266)
04-03 15:18:38.813 E/LoadedApk( 3773):  at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:301)
04-03 15:18:38.813 E/LoadedApk( 3773):  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
04-03 15:18:38.813 E/LoadedApk( 3773):  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
04-03 15:18:38.813 E/LoadedApk( 3773):  at java.lang.Thread.run(Thread.java:919)
04-03 15:18:38.815 W/System  ( 3773): ClassLoader referenced unknown path: /data/app/com.google.android.gms-LlJHSyIlEq33DaSbt2bMAg==/base.apk!/lib/arm64-v8a
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773): Could not install GmsCore nativeLibraryDirectories.
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773): java.lang.IllegalArgumentException: field dalvik.system.DexPathList.nativeLibraryPathElements has type dalvik.system.DexPathList$NativeLibraryElement[], got dalvik.system.DexPathList$Element[]
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at java.lang.reflect.Field.set(Native Method)
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at uvx.d(:com.google.android.gms@212417010@21.24.17 (020400-382381763):21)
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at uvx.g(:com.google.android.gms@212417010@21.24.17 (020400-382381763):4)
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at uvx.f(:com.google.android.gms@212417010@21.24.17 (020400-382381763):2)
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at com.google.android.gms.providerinstaller.ProviderInstallerImpl.b(:com.google.android.gms@212417010@21.24.17 (020400-382381763):6)
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at com.google.android.gms.providerinstaller.ProviderInstallerImpl.insertProvider(:com.google.android.gms@212417010@21.24.17 (020400-382381763):5)
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at java.lang.reflect.Method.invoke(Native Method)
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at com.google.android.gms.common.security.ProviderInstallerImpl.insertProvider(:com.google.android.gms@212417010@21.24.17 (020400-382381763):2)
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at java.lang.reflect.Method.invoke(Native Method)
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at com.google.android.gms.security.ProviderInstaller.zzc(com.google.android.gms:play-services-basement@@18.0.0:2)
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at com.google.android.gms.security.ProviderInstaller.installIfNeeded(com.google.android.gms:play-services-basement@@18.0.0:12)
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at com.google.firebase.inappmessaging.internal.ProviderInstaller.install(ProviderInstaller.java:34)
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at com.google.firebase.inappmessaging.internal.ApiClient.getFiams(ApiClient.java:68)
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at com.google.firebase.inappmessaging.internal.InAppMessageStreamManager.lambda$createFirebaseInAppMessageStream$16$InAppMessageStreamManager(InAppMessageStreamManager.java:261)
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at com.google.firebase.inappmessaging.internal.InAppMessageStreamManager$$ExternalSyntheticLambda13.apply(Unknown Source:6)
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at io.reactivex.internal.operators.maybe.MaybeMap$MapMaybeObserver.onSuccess(MaybeMap.java:82)
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at io.reactivex.internal.operators.maybe.MaybeFilter$FilterMaybeObserver.onSuccess(MaybeFilter.java:89)
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at io.reactivex.internal.operators.maybe.MaybeObserveOn$ObserveOnMaybeObserver.run(MaybeObserveOn.java:104)
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at io.reactivex.Scheduler$DisposeTask.run(Scheduler.java:579)
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at io.reactivex.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:66)
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at io.reactivex.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:57)
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at java.util.concurrent.FutureTask.run(FutureTask.java:266)
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:301)
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
04-03 15:18:38.815 E/GmsNativeLibraryLoader( 3773):     at java.lang.Thread.run(Thread.java:919)

and also this bugsnag extension appears to be throwing an exception:

04-03 15:18:40.147 W/System.err( 3773): com.adobe.fre.FRENoSuchNameException
04-03 15:18:40.147 W/System.err( 3773):     at com.adobe.fre.FREObject.getProperty(Native Method)
04-03 15:18:40.147 W/System.err( 3773):     at com.bugsnag.utils.FREUtils.getStringProperty(Unknown Source:0)
04-03 15:18:40.147 W/System.err( 3773):     at com.bugsnag.functions.Initialize.call(Unknown Source:12)
04-03 15:18:40.147 W/System.err( 3773):     at com.adobe.air.customHandler.callTimeoutFunction(Native Method)
04-03 15:18:40.147 W/System.err( 3773):     at com.adobe.air.customHandler.handleMessage(customHandler.java:28)
04-03 15:18:40.147 W/System.err( 3773):     at android.os.Handler.dispatchMessage(Handler.java:107)
04-03 15:18:40.147 W/System.err( 3773):     at android.os.Looper.loop(Looper.java:237)
04-03 15:18:40.147 W/System.err( 3773):     at android.app.ActivityThread.main(ActivityThread.java:8129)
04-03 15:18:40.147 W/System.err( 3773):     at java.lang.reflect.Method.invoke(Native Method)
04-03 15:18:40.147 W/System.err( 3773):     at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:496)
04-03 15:18:40.147 W/System.err( 3773):     at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1100)
04-03 15:18:40.147 W/System.err( 3773): com.adobe.fre.FRENoSuchNameException
04-03 15:18:40.147 W/System.err( 3773):     at com.adobe.fre.FREObject.getProperty(Native Method)
04-03 15:18:40.147 W/System.err( 3773):     at com.bugsnag.utils.FREUtils.getStringProperty(Unknown Source:0)
04-03 15:18:40.148 W/System.err( 3773):     at com.bugsnag.functions.Initialize.call(Unknown Source:19)
04-03 15:18:40.148 W/System.err( 3773):     at com.adobe.air.customHandler.callTimeoutFunction(Native Method)
04-03 15:18:40.148 W/System.err( 3773):     at com.adobe.air.customHandler.handleMessage(customHandler.java:28)
04-03 15:18:40.148 W/System.err( 3773):     at android.os.Handler.dispatchMessage(Handler.java:107)
04-03 15:18:40.148 W/System.err( 3773):     at android.os.Looper.loop(Looper.java:237)
04-03 15:18:40.148 W/System.err( 3773):     at android.app.ActivityThread.main(ActivityThread.java:8129)
04-03 15:18:40.148 W/System.err( 3773):     at java.lang.reflect.Method.invoke(Native Method)
04-03 15:18:40.148 W/System.err( 3773):     at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:496)
04-03 15:18:40.148 W/System.err( 3773):     at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1100)
04-03 15:18:40.148 W/System.err( 3773): com.adobe.fre.FRENoSuchNameException
04-03 15:18:40.148 W/System.err( 3773):     at com.bugsnag.utils.FREUtils.getStringProperty(Unknown Source:0)
04-03 15:18:40.148 W/System.err( 3773):     at com.bugsnag.functions.Initialize.call(Unknown Source:26)
04-03 15:18:40.148 W/System.err( 3773):     at com.adobe.air.customHandler.callTimeoutFunction(Native Method)
04-03 15:18:40.148 W/System.err( 3773):     at com.adobe.air.customHandler.handleMessage(customHandler.java:28)
04-03 15:18:40.148 W/System.err( 3773):     at android.os.Handler.dispatchMessage(Handler.java:107)
04-03 15:18:40.148 W/System.err( 3773):     at android.os.Looper.loop(Looper.java:237)
04-03 15:18:40.148 W/System.err( 3773):     at android.app.ActivityThread.main(ActivityThread.java:8129)
04-03 15:18:40.148 W/System.err( 3773):     at java.lang.reflect.Method.invoke(Native Method)
04-03 15:18:40.148 W/System.err( 3773):     at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:496)
04-03 15:18:40.148 W/System.err( 3773):     at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1100)

The final thing I can see going wrong is the asset pack loading:

04-03 15:19:46.590 D/        ( 3773): [LoadingAssetPack]: status: DOWNLOADING
04-03 15:19:46.597 D/        ( 3773): [LoadingAssetPack]: getTotalBytesToDownLoad: 218277297
04-03 15:19:46.602 D/        ( 3773): [LoadingAssetPack]: getByteDownloaded: 218238902

(and earlier getTotalBytesToDownLoad: 218277297) but then:

04-03 15:19:47.389 D/        ( 3773): [LoadingAssetPack]: status: TRANSFERRING
04-03 15:19:47.402 I/PlayCore( 3773): UID: [10394]  PID: [3773] ExtractionForegroundService : Starting foreground installation service.
04-03 15:19:47.403 E/PlayCore( 3773): UID: [10394]  PID: [3773] ExtractionForegroundService : Unknown action type received: 1
04-03 15:19:49.565 E/PlayCore( 3773): UID: [10394]  PID: [3773] ExtractorLooper : Error during extraction task: Verification failed for slice ap_assets_one.
04-03 15:19:49.565 I/PlayCore( 3773): UID: [10394]  PID: [3773] AssetPackServiceImpl : notifySessionFailed
04-03 15:19:49.565 I/PlayCore( 3773): UID: [10394]  PID: [3773] AssetPackServiceImpl : Initiate binding to the service.
04-03 15:19:49.574 I/PlayCore( 3773): UID: [10394]  PID: [3773] AssetPackServiceImpl : ServiceConnectionImpl.onServiceConnected(ComponentInfo{com.android.vending/com.google.android.finsky.assetmoduleservice.AssetModuleService})
04-03 15:19:49.575 I/PlayCore( 3773): UID: [10394]  PID: [3773] AssetPackServiceImpl : linkToDeath
04-03 15:19:49.579 E/Finsky  (16399): [33179] fjg.call(3): Received PlayCore failure signal, failing asset module session[id=1] with error '-100'
04-03 15:19:49.585 I/Finsky  (16399): [33179] uhv.ap(1): Processing update for PlayCore extraction service state.
04-03 15:19:49.589 I/PlayCore( 3773): UID: [10394]  PID: [3773] AssetPackServiceImpl : onNotifySessionFailed(1)
04-03 15:19:50.068 D/        ( 3773): [LoadingAssetPack]: status: FAILED

Not quite sure what would cause this, "Verification failed"... is there some signing of the asset pack happening somewhere?

jimmymjing commented 2 years ago

Hello, I have no idea about "signing of the asset pack". I keep using the same id for the asset pack. Do I need to modify it?

<assetPacks>
      <assetPack id="ap_assets_one" delivery="fast-follow" folder="assets"/>
    </assetPacks>

Do I need to change the id to something else? Did google play try to download previous asset pack? Speaking of the missing class, what shall I do with it? Is it used by ANEs?

jimmymjing commented 2 years ago

@ajwfrost Please help and let me know how to proceed... now many players can't login after updating to the new version... Did I include not-allowed content inside the asset pack directory?

jimmymjing commented 2 years ago

I have uploaded the same aab to internal sharing. And it works. Here's the log: (I tested twice on 2 devices) play store_2022_4_4_1_54_29.log play store_2022_4_4_2_4_43.log

ajwfrost commented 2 years ago

The success logs have a different asset pack...?

Failed = ap_assets_one

04-03 15:19:49.565 E/PlayCore( 3773): UID: [10394]  PID: [3773] ExtractorLooper : Error during extraction task: Verification failed for slice ap_assets_one.

Succeeded = ap_assets_two

04-03 17:54:20.999 I/PlayCore( 7805): UID: [10364]  PID: [7805] AssetPackServiceImpl : onNotifyModuleCompleted(ap_assets_two, sessionId=1)

Are you able to try with the same asset pack in both cases?

Can you find out from Google what those error messages mean? 

04-03 15:19:49.565 E/PlayCore( 3773): UID: [10394]  PID: [3773] ExtractorLooper : Error during extraction task: Verification failed for slice ap_assets_one.
04-03 15:19:49.565 I/PlayCore( 3773): UID: [10394]  PID: [3773] AssetPackServiceImpl : notifySessionFailed
04-03 15:19:49.565 I/PlayCore( 3773): UID: [10394]  PID: [3773] AssetPackServiceImpl : Initiate binding to the service.
04-03 15:19:49.574 I/PlayCore( 3773): UID: [10394]  PID: [3773] AssetPackServiceImpl : ServiceConnectionImpl.onServiceConnected(ComponentInfo{com.android.vending/com.google.android.finsky.assetmoduleservice.AssetModuleService})
04-03 15:19:49.575 I/PlayCore( 3773): UID: [10394]  PID: [3773] AssetPackServiceImpl : linkToDeath
04-03 15:19:49.575 I/Finsky  (16399): [33159] fjw.g(2): notifySessionFailed for package: com.voxverbi.bf
04-03 15:19:49.579 E/Finsky  (16399): [33179] fjg.call(3): Received PlayCore failure signal, failing asset module session[id=1] with error '-100'

It almost sounds like something has gone wrong with the packaging or uploading of these in the zip format...

thanks

jimmymjing commented 2 years ago

I did nothing but renamed it. But even though I renamed it, it still fails for production.

jimmymjing commented 2 years ago

Another really strange thing is that whenever I create a new version of Internal testing, it always works for the first time. But then I will get that error from all devices. (I have tested over 30 times...) It almost sounds like something has gone wrong with the packaging or uploading of these in the zip format... Do you mean it is a problem of the files inside the asset folder?

First time success log: play store_2022_4_4_5_2_18(first time success).log.zip

Rest times fail: (I will receive PlayAssetStatus.FAILED event during loading) play store_2022_4_4_5_6_10.log.zip

jimmymjing commented 2 years ago

I googled around by couldn't find anything related to these errors...

ajwfrost commented 2 years ago

Hmm. so the success log has:

04-03 20:56:14.619 I/PlayCore( 9081): UID: [10490]  PID: [9081] AssetPackServiceImpl : startDownload([ap_assets_two])
04-03 20:56:14.717 D/        ( 9081): [LoadingAssetPack]: status: DOWNLOADING
04-03 21:01:53.223 I/Finsky  (12893): [274] fiz.apply(5): Completed download of module ap_assets_two
04-03 21:01:53.278 I/PlayCore( 9081): UID: [10490]  PID: [9081] AssetPackServiceImpl : getChunkFileDescriptor(ap_assets_two, ap_assets_two, 0, session=1)
04-03 21:01:53.280 D/        ( 9081): [LoadingAssetPack]: status: TRANSFERRING
04-03 21:01:53.291 I/Finsky  (12893): [93] fjw.b(2): getChunkFileDescriptor for package: com.voxverbi.bf, chunkId: AssetModuleChunkId{sessionId=1, moduleName=ap_assets_two, sliceId=ap_assets_two, chunkIndex=0}
04-03 21:01:56.692 I/PlayCore( 9081): UID: [10490]  PID: [9081] ExtractChunkTaskHandler : Extraction finished for chunk 0 of slice ap_assets_two of pack ap_assets_two of session 1.

but the failure log has:

04-03 21:05:56.550 I/PlayCore(23661): UID: [10479]  PID: [23661] AssetPackServiceImpl : startDownload([ap_assets_two])
04-03 21:05:56.644 I/PlayCore(23661): UID: [10479]  PID: [23661] AssetPackServiceImpl : getChunkFileDescriptor(ap_assets_two, ap_assets_two, 0, session=1)
04-03 21:05:56.685 D/        (23661): [LoadingAssetPack]: status: DOWNLOADING

In other words, the second time starts the download but then has a call to getChunkFileDescriptor, which should only happen once the download has finished.

When you say it works for the first time but then fails, do you mean on the same device? It maybe sounds like the first time, the download works, but the second time the download is unnecessary: are you checking for the status to start with, e.g. using getAssetPackStatus() to see what the current status is?

thanks

jimmymjing commented 2 years ago

@ajwfrost I have checked the status. I didn't mean on the same device. It just got succeeded once, and then no matter which devices that I use, it fails... I use a real devices farm to test this function, so these devices should not have the asset packs and I couldn't figure out why there's a call to getChunkFileDescriptor.

p.s. I just randomly removed 2 files, and then it works. But I really need to figure out the cause otherwise I couldn't update our game on Google Play... The first release of our game works fine with the Asset Pack Delivery and has no issues at all I haven't changed any logic for this part in our code base. (Has Google updated this Asset Pack Delivery SDK??)

dakahler commented 5 months ago

@jimmymjing did you ever figure this out?

ajwfrost commented 5 months ago

Just one comment from our side, as we've been doing a fair bit of work on the Play Asset Delivery ANE recently; we do find that "local testing" isn't particularly reliable, and there are a lot of use cases that don't necessarily work the way you'd expect. So it is much better to set up a test app on the Google Play console and use the Internal Testing feature so that you can upload the .aab file and download the app and assets from the Play Store..