ANR with new Emergency Wifi lock

Version

Media3 main branch

More version details

1.9.0

Devices that reproduce the issue

Probably all

Devices that do not reproduce the issue

No response

Reproducible in the demo app?

Not tested

Reproduction steps

N/A

Expected result

No ANR, the usual don't do binding stuff on main thread.

Actual result

#00 pc 0xddd4c libc.so (__ioctl + 12) (BuildId: 6279f80eeba93a6e8a410cf52e4285b6)
#01 pc 0x82140 libc.so (ioctl + 144) (BuildId: 6279f80eeba93a6e8a410cf52e4285b6)
#02 pc 0x62ed8 libbinder.so (android::IPCThreadState::transact + 1528) (BuildId: c948af07b9d02b14fbb8fffae0734189)
#03 pc 0x71600 libbinder.so (android::BpBinder::transact + 288) (BuildId: c948af07b9d02b14fbb8fffae0734189)
#04 pc 0x1e7ecc libandroid_runtime.so (android_os_BinderProxy_transact + 156) (BuildId: 2c41cbf37dbf26de0ad69008fa837015)
       at android.os.BinderProxy.transactNative(Native method)
       at android.os.BinderProxy.transact(BinderProxy.java:592)
       at android.net.wifi.IWifiManager$Stub$Proxy.releaseWifiLock(IWifiManager.java:4929)
       at android.net.wifi.WifiManager$WifiLock.release(WifiManager.java:8468)
       at androidx.media3.common.util.WifiLockManager$WifiLockManagerInternal.forceReleaseWifiLock(WifiLockManager.java:162)
       at androidx.media3.common.util.WifiLockManager$WifiLockManagerInternal.access$100(WifiLockManager.java:121)
       at androidx.media3.common.util.WifiLockManager.lambda$postUpdateWifiLock$1(WifiLockManager.java:106)
       at android.os.Handler.handleCallback(Handler.java:1041)
       at android.os.Handler.dispatchMessage(Handler.java:103)
       at android.os.Looper.dispatchMessage(Looper.java:315)
       at android.os.Looper.loopOnce(Looper.java:251)
       at android.os.Looper.loop(Looper.java:349)
       at android.app.ActivityThread.main(ActivityThread.java:9041)
       at java.lang.reflect.Method.invoke(Native method)
       at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:593)
       at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:929)

Media

N/A

Bug Report

You will email the zip file produced by adb bugreport to android-media-github@google.com after filing this issue.

Thanks for your report!

the usual don't do binding stuff on main thread.

I don't think this is a usual put-binder-things-off-the-main thread case. ExoPlayer is generally already free of such calls for normal behaviour I think.

Looks like this emergency release is sent to the main thread on purpose because the separate thread that is specifically intended to do WIFILock related binder calls fails to process the release early enough (1 second after posting the runnable).

It seems there is some kind of issue already before that, because if it would work as intended, then the lock is released on a specific thread off the main thread [1].

Do you see any other irregularities in the logs of a device that shows that behaviour?

[1] https://github.com/androidx/media/blob/release/libraries/common/src/main/java/androidx/media3/common/util/WifiLockManager.java#L107-L112

@tonihei

I do not have logs it's all from Crashlytics.

My understanding from the @tonihei PR is that, that message is sent to main thread when the lock handler thread does not respond on time.

That does not mean the actual release should occurs on main thread.

IMO the ANR is mostly expected here. If the lock handler thread is blocked due to binding and IPC lock blocking the release call, restarting the same call on main thread will be locked too, but with higher consequences.

So unless I'm missing something the fix from the PR is probably worse then the initial problem since there's no way to ensure any lock blocking the other thread will be fixed when the same thing occurs on main thread.

That does not mean the actual release should occurs on main thread.

This is a good point, especially because there is some likelihood this call will also block, as you already pointed out. I wouldn't say this is always the case because the playback thread may be blocked for other reasons (e.g. stuck codec call), but generally it could easily be blocked again if the initial blockage is caused by some binder overload in the system. The best solution is probably to start a completely new thread to at least attempt to release the wake lock. Starting a thread is not particularly cheap either, but that situation is release only used as a last resort fallback, so seems acceptable.

Move emergency WakeLock/WifiLock release to new thread

@tonihei

@tonihei your last changes have a small race risk, due to the time to start of a new thread.

The synchronized does not protect from the wake lock being re acquired during the thread start since there no lock during that time.

Small risk but I prefer tell.

The synchronized does not protect from the wake lock being re acquired during the thread start since there no lock during that time.

That's true, but that was never the point of the synchronization itself. It's only meant to protect the access to the wakeLock instance.

We lose some ordering guarantees though because the call to mainHandler.removeCallbacks(emergencyRelease); no longer reliably prevents the emergency release from happening if the main thread message has already been triggered. This would only be a problem is the playback thread is blocked for exactly one second and unblocks itself exactly during this short amount of time while the new thread is started... Seems extremely unlikely, but easily fixable, so I'll send a follow up change to make it fully safe again. Thanks again for the detailed analysis!