ryanheise / audio_service

Flutter plugin to play audio in the background while the screen is off.
806 stars 480 forks source link

App cannot be terminated after reboot on Android 11 #923

Open mehayhe opened 2 years ago

mehayhe commented 2 years ago

Documented behaviour

n/a

Actual behaviour

Should be able to remove active app completely by using Task Manager after reboot when audio is not playing.

Minimal reproduction project

https://github.com/mehayhe/audio_service/tree/android11-app-removal-issue

Reproduction steps

  1. build and run example app on Android 11 emulator
  2. close emulator
  3. cold boot (reboot) emulator
  4. wait until emulator has started
  5. open logcat and filter log with text "audioservice"
  6. observe the messages "com.ryanheise.audioserviceexample I/flutter: app started # sec ago" indicating the app has already been started in background
  7. find the example app from home screen and launch it
  8. check the started duration in the app (should be a few secs if it was just started)
  9. open task manager and remove the app
  10. launch the app again and observe the started duration (repeat step 7-10 a few times if desired)

    Output of flutter doctor

    [✓] Flutter (Channel stable, 2.10.4, on macOS 11.6.5 20G527 darwin-x64, locale en-US)
    [✓] Android toolchain - develop for Android devices (Android SDK version 31.0.0-rc4)
    [✓] Xcode - develop for iOS and macOS (Xcode 13.1)
    [✓] Chrome - develop for the web
    [✓] Android Studio (version 2021.1)

    Devices exhibiting the bug

    only Android 11

The cause might be because of this line in AudioService.jave:

flutterEngine = AudioServicePlugin.getFlutterEngine(this);

The cached flutter engine could possibly hold a strong reference to the audio service object. In that case the service cannot be destroyed automatically when not in use and same with the app. The only way to do so is to dispose the cached engine using AudioServicePlugin.disposeFlutterEngine(). Calling the dispose method in the onDestroy() activity event seems to fix the issue:

public class MainActivity extends AudioServiceActivity {
    @Override
    public void onDestroy() {
        super.onDestroy();
        AudioServicePlugin.disposeFlutterEngine();
    }
}
ryanheise commented 2 years ago

This is the normal documented behaviour for Android 11+ in relation to how media sessions are now made persistent across boot.

mehayhe commented 2 years ago

I'm aware of the resumption feature that load audio services on boot. The main problem is that the app cannot be terminated using task manager because of the active service. On Android 12, the app can be terminated using task manager fine. Try out the modified example app on Android 12 and see. There is no point of keeping the app running indefinitely in the background if the user doesn't want it to be taking up resources. The app state will never be reseted. If there are multiple apps using audio service plugin then they all will stay persistent until those are being uninstalled. Keep rebooting again will not help.

My app is getting some ANRs Input dispatching timed out (ActivityRecord{...} does not have a focused window. I think it might have something to do with the app running in the background for too long and trying to response to some media session actions. The ANRs only happened on android 11 but no other android versions.

mehayhe commented 2 years ago

The audio service doesn't persistent for long after boot on Android 12. The system automatically kills the service & app after a short while. See the log below.

Android 12 boot log ``` 2022-03-30 07:03:13.000 727-727/com.android.bluetooth I/AvrcpBrowsedPlayerWrapper: Wrapping Media Browser com.ryanheise.audioserviceexample 2022-03-30 07:03:13.110 555-590/system_process I/ActivityManager: Start proc 1623:com.ryanheise.audioserviceexample/u0a146 for service {com.ryanheise.audioserviceexample/com.ryanheise.audioservice.AudioService} 2022-03-30 07:03:13.660 1623-1623/com.ryanheise.audioserviceexample V/GraphicsEnvironment: ANGLE Developer option for 'com.ryanheise.audioserviceexample' set to: 'default' 2022-03-30 07:03:13.660 1623-1623/com.ryanheise.audioserviceexample V/GraphicsEnvironment: Neither updatable production driver nor prerelease driver is supported. 2022-03-30 07:03:13.661 1623-1623/com.ryanheise.audioserviceexample D/NetworkSecurityConfig: No Network Security Config specified, using platform default 2022-03-30 07:03:13.662 1623-1623/com.ryanheise.audioserviceexample D/NetworkSecurityConfig: No Network Security Config specified, using platform default 2022-03-30 07:03:13.667 1623-1623/com.ryanheise.audioserviceexample D/CompatibilityChangeReporter: Compat change id reported: 160794467; UID 10146; state: ENABLED 2022-03-30 07:03:14.323 1623-1623/com.ryanheise.audioserviceexample W/oserviceexample: type=1400 audit(0.0:6): avc: denied { read } for name="max_map_count" dev="proc" ino=42520 scontext=u:r:untrusted_app:s0:c146,c256,c512,c768 tcontext=u:object_r:proc_max_map_count:s0 tclass=file permissive=0 app=com.ryanheise.audioserviceexample 2022-03-30 07:03:14.402 1623-1623/com.ryanheise.audioserviceexample D/libEGL: loaded /vendor/lib64/egl/libEGL_emulation.so 2022-03-30 07:03:14.406 1623-1623/com.ryanheise.audioserviceexample D/libEGL: loaded /vendor/lib64/egl/libGLESv1_CM_emulation.so 2022-03-30 07:03:14.459 1623-1623/com.ryanheise.audioserviceexample D/libEGL: loaded /vendor/lib64/egl/libGLESv2_emulation.so 2022-03-30 07:03:14.927 1623-1623/com.ryanheise.audioserviceexample D/HostConnection: createUnique: call 2022-03-30 07:03:14.928 1623-1623/com.ryanheise.audioserviceexample D/HostConnection: HostConnection::get() New Host Connection established 0x7c9ba96429d0, tid 1623 2022-03-30 07:03:14.967 1623-1623/com.ryanheise.audioserviceexample D/HostConnection: HostComposition ext ANDROID_EMU_CHECKSUM_HELPER_v1 ANDROID_EMU_native_sync_v2 ANDROID_EMU_native_sync_v3 ANDROID_EMU_native_sync_v4 ANDROID_EMU_dma_v1 ANDROID_EMU_direct_mem ANDROID_EMU_host_composition_v1 ANDROID_EMU_host_composition_v2 ANDROID_EMU_YUV_Cache ANDROID_EMU_has_shared_slots_host_memory_allocator ANDROID_EMU_sync_buffer_data ANDROID_EMU_read_color_buffer_dma GL_OES_EGL_image_external_essl3 GL_OES_vertex_array_object GL_KHR_texture_compression_astc_ldr ANDROID_EMU_host_side_tracing ANDROID_EMU_gles_max_version_3_0 2022-03-30 07:03:14.972 1623-1623/com.ryanheise.audioserviceexample D/EGL_emulation: eglCreateContext: 0x7c9ba96438d0: maj 3 min 0 rcv 3 2022-03-30 07:03:14.973 1623-1623/com.ryanheise.audioserviceexample D/EGL_emulation: eglCreateContext: 0x7c9ba96432d0: maj 3 min 0 rcv 3 2022-03-30 07:03:14.980 1623-1769/com.ryanheise.audioserviceexample D/HostConnection: createUnique: call 2022-03-30 07:03:14.980 1623-1769/com.ryanheise.audioserviceexample D/HostConnection: HostConnection::get() New Host Connection established 0x7c9ba9642e50, tid 1769 2022-03-30 07:03:15.034 1623-1769/com.ryanheise.audioserviceexample D/HostConnection: HostComposition ext ANDROID_EMU_CHECKSUM_HELPER_v1 ANDROID_EMU_native_sync_v2 ANDROID_EMU_native_sync_v3 ANDROID_EMU_native_sync_v4 ANDROID_EMU_dma_v1 ANDROID_EMU_direct_mem ANDROID_EMU_host_composition_v1 ANDROID_EMU_host_composition_v2 ANDROID_EMU_YUV_Cache ANDROID_EMU_has_shared_slots_host_memory_allocator ANDROID_EMU_sync_buffer_data ANDROID_EMU_read_color_buffer_dma GL_OES_EGL_image_external_essl3 GL_OES_vertex_array_object GL_KHR_texture_compression_astc_ldr ANDROID_EMU_host_side_tracing ANDROID_EMU_gles_max_version_3_0 2022-03-30 07:03:15.044 1623-1769/com.ryanheise.audioserviceexample D/EGL_emulation: eglMakeCurrent: 0x7c9ba96432d0: ver 3 0 (tinfo 0x7c9dcf780100) (first time) 2022-03-30 07:03:15.160 1623-1623/com.ryanheise.audioserviceexample D/MediaBrowserCompat: Connecting to a MediaBrowserService. 2022-03-30 07:03:15.644 1623-1657/com.ryanheise.audioserviceexample I/oserviceexampl: Background young concurrent copying GC freed 3179(321KB) AllocSpace objects, 2(40KB) LOS objects, 92% free, 1990KB/25MB, paused 108us,8us total 503.233ms 2022-03-30 07:03:15.675 1623-1623/com.ryanheise.audioserviceexample I/TextToSpeech: Sucessfully bound to com.google.android.tts 2022-03-30 07:03:15.676 1623-1623/com.ryanheise.audioserviceexample D/PathProviderPlugin: Don't use TaskQueues. 2022-03-30 07:03:15.710 1623-1623/com.ryanheise.audioserviceexample I/System.out: flutterEngine warmed up 2022-03-30 07:03:15.712 1623-1623/com.ryanheise.audioserviceexample I/System.out: AUDIOSERVICE service onBind Intent { act=android.media.browse.MediaBrowserService cmp=com.ryanheise.audioserviceexample/com.ryanheise.audioservice.AudioService } 2022-03-30 07:03:15.863 727-727/com.android.bluetooth I/AvrcpBrowsedPlayerWrapper: onConnected: com.ryanheise.audioserviceexample is connected 2022-03-30 07:03:15.864 727-727/com.android.bluetooth D/AvrcpBrowsablePlayerConnector: Browse player callback called: package=com.ryanheise.audioserviceexample : status=0 2022-03-30 07:03:15.865 727-727/com.android.bluetooth I/AvrcpBrowsablePlayerConnector: Checking root contents for com.ryanheise.audioserviceexample 2022-03-30 07:03:15.891 727-727/com.android.bluetooth I/AvrcpBrowsedPlayerWrapper: onConnected: com.ryanheise.audioserviceexample is connected 2022-03-30 07:03:15.891 727-727/com.android.bluetooth I/AvrcpBrowsedPlayerWrapper: getFolderItems: Connected to browsable player: com.ryanheise.audioserviceexample 2022-03-30 07:03:16.317 1623-1623/com.ryanheise.audioserviceexample I/ExoPlayerImpl: Init 550fd97 [ExoPlayerLib/2.15.0] [emulator64_x86_64_arm64, sdk_gphone64_x86_64, Google, 31] 2022-03-30 07:03:17.233 1623-1756/com.ryanheise.audioserviceexample I/flutter: app started 1 sec ago 2022-03-30 07:03:18.231 1623-1756/com.ryanheise.audioserviceexample I/flutter: app started 2 sec ago 2022-03-30 07:03:18.280 1623-1670/com.ryanheise.audioserviceexample I/TextToSpeech: Connected to TTS engine 2022-03-30 07:03:18.527 1623-2275/com.ryanheise.audioserviceexample D/CCodec: allocate(c2.android.mp3.decoder) 2022-03-30 07:03:18.530 1623-2275/com.ryanheise.audioserviceexample I/Codec2Client: Available Codec2 services: "default" "software" 2022-03-30 07:03:18.568 1623-2275/com.ryanheise.audioserviceexample I/CCodec: setting up 'default' as default (vendor) store 2022-03-30 07:03:18.603 1623-2275/com.ryanheise.audioserviceexample I/CCodec: Created component [c2.android.mp3.decoder] 2022-03-30 07:03:18.604 1623-2275/com.ryanheise.audioserviceexample D/CCodecConfig: read media type: audio/mpeg 2022-03-30 07:03:18.611 1623-2275/com.ryanheise.audioserviceexample D/ReflectedParamUpdater: extent() != 1 for single value type: algo.buffers.max-count.values 2022-03-30 07:03:18.612 1623-2275/com.ryanheise.audioserviceexample D/ReflectedParamUpdater: extent() != 1 for single value type: output.subscribed-indices.values 2022-03-30 07:03:18.613 1623-2275/com.ryanheise.audioserviceexample D/ReflectedParamUpdater: extent() != 1 for single value type: input.buffers.allocator-ids.values 2022-03-30 07:03:18.613 1623-2275/com.ryanheise.audioserviceexample D/ReflectedParamUpdater: extent() != 1 for single value type: output.buffers.allocator-ids.values 2022-03-30 07:03:18.613 1623-2275/com.ryanheise.audioserviceexample D/ReflectedParamUpdater: extent() != 1 for single value type: algo.buffers.allocator-ids.values 2022-03-30 07:03:18.613 1623-2275/com.ryanheise.audioserviceexample D/ReflectedParamUpdater: extent() != 1 for single value type: output.buffers.pool-ids.values 2022-03-30 07:03:18.613 1623-2275/com.ryanheise.audioserviceexample D/ReflectedParamUpdater: extent() != 1 for single value type: algo.buffers.pool-ids.values 2022-03-30 07:03:18.615 1623-2275/com.ryanheise.audioserviceexample I/CCodecConfig: query failed after returning 7 values (BAD_INDEX) 2022-03-30 07:03:18.615 1623-2275/com.ryanheise.audioserviceexample D/CCodecConfig: c2 config diff is Dict { c2::u32 coded.bitrate.value = 64000 c2::u32 input.buffers.max-size.value = 8192 c2::u32 input.delay.value = 0 string input.media-type.value = "audio/mpeg" string output.media-type.value = "audio/raw" c2::u32 raw.channel-count.value = 2 c2::u32 raw.sample-rate.value = 44100 } 2022-03-30 07:03:18.616 1623-2275/com.ryanheise.audioserviceexample D/CCodec: [c2.android.mp3.decoder] buffers are bound to CCodec for this session 2022-03-30 07:03:18.616 1623-2275/com.ryanheise.audioserviceexample D/CCodecConfig: no c2 equivalents for flags 2022-03-30 07:03:18.617 1623-2275/com.ryanheise.audioserviceexample D/CCodecConfig: config failed => CORRUPTED 2022-03-30 07:03:18.617 1623-2275/com.ryanheise.audioserviceexample W/Codec2Client: query -- param skipped: index = 1107298332. 2022-03-30 07:03:18.617 1623-2275/com.ryanheise.audioserviceexample D/CCodec: client requested max input size 4096, which is smaller than what component recommended (8192); overriding with component recommendation. 2022-03-30 07:03:18.617 1623-2275/com.ryanheise.audioserviceexample W/CCodec: This behavior is subject to change. It is recommended that app developers double check whether the requested max input size is in reasonable range. 2022-03-30 07:03:18.617 1623-2275/com.ryanheise.audioserviceexample D/CCodec: setup formats input: AMessage(what = 0x00000000) = { int32_t bitrate = 64000 int32_t channel-count = 2 int32_t max-input-size = 8192 string mime = "audio/mpeg" int32_t sample-rate = 44100 } 2022-03-30 07:03:18.617 1623-2275/com.ryanheise.audioserviceexample D/CCodec: setup formats output: AMessage(what = 0x00000000) = { int32_t channel-count = 2 string mime = "audio/raw" int32_t sample-rate = 44100 } 2022-03-30 07:03:18.617 1623-2275/com.ryanheise.audioserviceexample I/CCodecConfig: query failed after returning 7 values (BAD_INDEX) 2022-03-30 07:03:18.619 1623-2275/com.ryanheise.audioserviceexample W/Codec2Client: query -- param skipped: index = 1342179345. 2022-03-30 07:03:18.619 1623-2275/com.ryanheise.audioserviceexample W/Codec2Client: query -- param skipped: index = 2415921170. 2022-03-30 07:03:18.619 1623-2275/com.ryanheise.audioserviceexample D/C2Store: Using DMABUF Heaps 2022-03-30 07:03:18.622 1623-2275/com.ryanheise.audioserviceexample D/CCodecBufferChannel: [c2.android.mp3.decoder#268] Created input block pool with allocatorID 16 => poolID 17 - OK (0) 2022-03-30 07:03:18.656 1623-2275/com.ryanheise.audioserviceexample I/CCodecBufferChannel: [c2.android.mp3.decoder#268] Created output block pool with allocatorID 16 => poolID 26 - OK 2022-03-30 07:03:18.657 1623-2275/com.ryanheise.audioserviceexample D/CCodecBufferChannel: [c2.android.mp3.decoder#268] Configured output block pool ids 26 => OK 2022-03-30 07:03:18.666 1623-2275/com.ryanheise.audioserviceexample I/DMABUFHEAPS: Using DMA-BUF heap named: system 2022-03-30 07:03:18.804 1623-2246/com.ryanheise.audioserviceexample I/TextToSpeech: Setting up the connection to TTS engine... 2022-03-30 07:03:19.231 1623-1756/com.ryanheise.audioserviceexample I/flutter: app started 3 sec ago 2022-03-30 07:03:20.234 1623-1756/com.ryanheise.audioserviceexample I/flutter: app started 4 sec ago 2022-03-30 07:03:21.233 1623-1756/com.ryanheise.audioserviceexample I/flutter: app started 5 sec ago 2022-03-30 07:03:22.231 1623-1756/com.ryanheise.audioserviceexample I/flutter: app started 6 sec ago 2022-03-30 07:03:23.231 1623-1756/com.ryanheise.audioserviceexample I/flutter: app started 7 sec ago 2022-03-30 07:03:23.838 1623-2278/com.ryanheise.audioserviceexample D/BufferPoolAccessor2.0: bufferpool2 0x7c9bf9668608 : 5(40960 size) total buffers - 4(32768 size) used buffers - 0/5 (recycle/alloc) - 7/34 (fetch/transfer) 2022-03-30 07:03:23.838 1623-2278/com.ryanheise.audioserviceexample D/BufferPoolAccessor2.0: evictor expired: 1, evicted: 1 2022-03-30 07:03:24.231 1623-1756/com.ryanheise.audioserviceexample I/flutter: app started 8 sec ago 2022-03-30 07:03:25.234 1623-1756/com.ryanheise.audioserviceexample I/flutter: app started 9 sec ago 2022-03-30 07:03:25.520 555-633/system_process I/ActivityManager: Killing 1623:com.ryanheise.audioserviceexample/u0a146 (adj 975): empty #17 2022-03-30 07:03:25.625 555-706/system_process V/MediaSessionRecord: Removing dead callback in pushSessionDestroyed, this=com.ryanheise.audioserviceexample/media-session (userId=0), callback package=com.ryanheise.audioserviceexample, exception=android.os.DeadObjectException ```
ryanheise commented 2 years ago

Android apps don't typically kill their own processes, it is up to the operating system to decide when to keep an app in memory, and it is typical to keep apps in memory for as long as possible, until that memory is needed to start another app.

ryanheise commented 2 years ago

Just to add to that, the operating system will typically wait until all activities are destroyed AND all services are in a reclaimable state (e.g. not in foreground mode). After boot, the OS doesn't launch your activity but it does bind to your service and if it stays bound, then the OS is deciding to keep your app in memory. If it unbinds, your app's memory can be reclaimed. You aren't completely in control of how the OS binds to your service (e.g. it happens not only after boot, but whenever the media session is resumed via the media notification). You can override onTaskRemoved to call stop but even that will not make your process reclaimable if the OS is still trying to hold onto a connection to your service.

If you are observing that the media session is not persisted for long after reboot, that may be worth reporting as a separate bug.

mehayhe commented 2 years ago

I tried to use onTaskRemoved to trigger the AudioService.stop() so that it can release & destroy itself. That didn't work because the stopSelf can't stop the service because the cached flutter engine had a hold on it. So the AudioService.onDestroy() was never being called and in turn not the disposeFlutterEngine() either. As the result, using the task manager to kill the app didn't work so the app stayed in memory indefinitely. It seems like a retain cycle problem to me.

I ran the example app on Android 13 preview and it worked the same way as on Android 12. The audio service didn't persist for long during the boot process. The persistent issue is only unique to android 11 so it's something that should be concern about because it might cause other unexpected issues.

mehayhe commented 2 years ago

I tried the example app with the following modification:

  @override
  Future<void> onTaskRemoved() async {
    print('onTaskRemoved');
    await stop();
  }

The audio stopped and AudioService.stop() did get call but still not AudioService.onDestroy() so nothing has been being released.

According to the media browser service documentation:

A service that is only bound (and not started) is destroyed when all of its clients unbind. If your UI activity disconnects at this point, the service is destroyed. This isn't a problem if you haven't played any music yet.

This is not happening on Android 11 when running the example app after cold boot. If I open the app and kill it without playing the audio, the audio service is not being destroyed and same with the app. Maybe there are multiple clients connected to the service for some reason.

ryanheise commented 2 years ago

That is what I was describing earlier. The client that is bound to it is Android 11 itself, in order to manage the media notification.

mehayhe commented 2 years ago

But then why calling AudioServicePlugin.disposeFlutterEngine() from the activity.onDestroy able to release the service?

public class MainActivity extends AudioServiceActivity {
    @Override
    public void onDestroy() {
        super.onDestroy();
        AudioServicePlugin.disposeFlutterEngine();
    }
}
ryanheise commented 2 years ago

I don't see how disposeFlutterEngine could trigger AudioService.onDestroy when it is programmed to work the other way around.

The way it should work is:

  1. The activity is destroyed via a user-initiated action.
  2. On destroy, the activity unbinds from the service.
  3. If nothing else is bound to it and it's not in the foreground, the service is destroyed by Android.
  4. This then triggers a call to disposeFlutterEngine.
  5. If there are no more activities using the engine, the engine is destroyed.

Can you tell me at which step your observations diverge?

mehayhe commented 2 years ago

disposeFlutterEngine() -> engine.destroy() -> pluginRegistry.destroy() -> FlutterEngineConnectionRegistry detaches service -> OS releases & destroys service -> AudioService.onDestroy

Here is the snippet of the FlutterEngineConnectionRegistry.destroy():

  public void destroy() {
    Log.v(TAG, "Destroying.");
    // Detach from any Android component that we may currently be attached to, e.g., Activity,
    // Service, BroadcastReceiver, ContentProvider. This must happen before removing all plugins so
    // that the plugins have an opportunity to clean up references as a result of component
    // detachment.
    detachFromAppComponent();

    // Remove all registered plugins.
    removeAll();
  }

This scenario only happens if audio service started first before the activity. On boot up this is what is happening. The flutter engine uses audio service as the context to instantiate itself. When FlutterEngineConnectionRegistry attaches to a service or activity, destroy must be called to detach it. The system won't destroy the service if it has been attached to some other object.

For Android 12 & 13 preview, audio service is being started on boot as well but it will be killed by the system shortly after for some reason according to the log above. That's why they don't have the same persistent issue as Android 11.

ryanheise commented 2 years ago

But can you tell me at which of the 5 steps your observations diverge?

mehayhe commented 2 years ago

Step 3. Unbind the service might not destroy it if it is still being attached to a listener by plugin registry so AudioService.onDestroy won't be called. FlutterEngineConnectionRegistry adds a ServiceAware listener to the service to detect its lifecycle similarly like an activity.

@Override
  public void attachToService(
      @NonNull Service service, @Nullable Lifecycle lifecycle, boolean isForeground) {
    Trace.beginSection("FlutterEngineConnectionRegistry#attachToService");
    Log.v(TAG, "Attaching to a Service: " + service);

    try {
      // If we were already attached to an Android component, detach from it.
      detachFromAppComponent();

      this.service = service;
      this.servicePluginBinding = new FlutterEngineServicePluginBinding(service, lifecycle);

      // Notify all ServiceAware plugins that they are now attached to a new Service.
      for (ServiceAware serviceAware : serviceAwarePlugins.values()) {
        serviceAware.onAttachedToService(servicePluginBinding);
      }
    } finally {
      Trace.endSection();
    }
  }

 @Override
  public void detachFromService() {
    if (isAttachedToService()) {
      Trace.beginSection("FlutterEngineConnectionRegistry#detachFromService");
      Log.v(TAG, "Detaching from a Service: " + service);

      try {
        // Notify all ServiceAware plugins that they are no longer attached to a Service.
        for (ServiceAware serviceAware : serviceAwarePlugins.values()) {
          serviceAware.onDetachedFromService();
        }

        service = null;
        servicePluginBinding = null;
      } finally {
        Trace.endSection();
      }
    } else {
      Log.e(TAG, "Attempted to detach plugins from a Service when no Service was attached.");
    }
  }
ryanheise commented 2 years ago

Thanks, that does shed some light on it. Although this plugin doesn't explicitly implement ServiceAware, I do vaguely seem to recall that Flutter may automatically register for lifecycle events on a service but not on an activity. However I don't remember the precise details.

You say:

The flutter engine uses audio service as the context to instantiate itself.

But the FlutterEngine is created using the application context, not the service. So I'm not sure if that is the mechanism.

ryanheise commented 2 years ago

Looking through the Flutter engine code, nowhere does it "bind" to the service, so merely holding a reference to the service object should not in itself be a reason why a service would be prevented from being destroyed. Android will still go ahead and destroy a service once all clients unbind from it and it's no longer started in the foreground. All that these dangling references will do is cause a leaked context.

So in my mind, it appears that the behaviour you're observing is just the behaviour of Android 11. It will sometimes bind to your service and never let go of it, and maybe what destroying the engine in Activity.onDestroy does is simply disable the service so that when Android 11 does try to communicate with it, it can't and gives up.

If you have an alternative theory, let me know.

mehayhe commented 2 years ago

Maybe my assumption about the root cause might be incorrect due to my lack of experience with the flutter engine and android. The fact still remains that calling disposeFlutterEngine() does help release the service and trigger AudioService.onDestroy(). I used to code in ObjC and had memory leak & retain problems similar to this issue. I think this persistent issue is serious enough that needs to be addressed or at least mention it in the documentation so people is aware of it. It can be reproduced consistently by debugging the example app.

I discovered this issue when trying to find the cause for the “Input dispatching timed out” ANRs and after seeing these: https://github.com/ryanheise/audio_service/issues/880 & https://github.com/ryanheise/audio_service/issues/916. The ANR cannot be reproduced locally though. After I added a workaround to kill the audio service if it has been started on boot or if the app is in a detached state for long, the ANR problem seems to go away. The update was just recent so it’s still early to know for sure but so far it looks promising. The workaround is not an ideal solution for apps that need to play audio in the background independently from the main activity though. For my app, that is not a requirement.

ryanheise commented 2 years ago

Can you please clarify whether the ANR issue is part of the Android 11 issue you are reporting or whether it is a separate issue? The Android 12 issue that you mentioned is at least a different issue. For separate issues, it will help to submit them as separate issues.

As for the original issue, my take was that this was not a bug and just the app maintaining a connection to Android 11's media controller as required by Android 11. I did not think that was an ANR, but just the service being kept alive.

mehayhe commented 2 years ago

The ANR is a separate problem which I don't know the exact cause so I didn't open an issue for it. It could be caused by some other plugins the app is using. But it seems that if the app doesn't persistent indefinitely then it'll go away.

I was wrong about a few things. I jump into conclusion too quickly sometimes. Plugin registry is not attaching to the service on boot. More like flutter engine is attaching to the app context by some means. Also, disposeFlutterEngine() doesn't trigger the release of the service. It only disposes the engine. The service would still be bound to the media browser. The app would be in a weird state when running again so not really a good solution.

ryanheise commented 2 years ago

More like flutter engine is attaching to the app context by some means.

Destroying the service isn't affected by such things as strong or weak references, or any other means, except for binding. I think Android is the one who is binding here and hence in control of the situation. I am not sure if there is a proper way to get Android to unbind, but if there were, I'd like to implement it properly.

ryanheise commented 2 years ago

Did you have any further thoughts on this matter, and in particular do you still believe it to be a leak within the plugin (as opposed to Android holding onto the binding)?

Vitalie-Andries commented 2 years ago

Hello, I have the same problem as @mehayhe , the application created in Flutter and which is in production now gives me multiple ANR errors in GPConsole only on Android 11. I would like to ask you how I could solve this problem. Maybe @mehayhe could give me some advice how to solve this problem. Thank you in advance.

ANR Error: Input dispatching timed out (ActivityRecord{d00c486 u0 com.myapp/com.ryanheise.audioservice.AudioServiceActivity t195} does not have a focused window)

ryanheise commented 2 years ago

@Vitalie-Andries is there anything else you can share about the crash? For an ANR a crash report should also have been recorded.

Vitalie-Andries commented 2 years ago

Hello, sure... here is full ANR report:

Input dispatching timed out (ActivityRecord{d00c486 u0 com.myapp/com.ryanheise.audioservice.AudioServiceActivity t195} does not have a focused window) com.ryanheise.audioservice.AudioServiceActivity

Thanks in advance.


Type "main" prio=5 tid=1 Native
  #00  pc 0000000000089c8c  /apex/com.android.runtime/lib64/bionic/libc.so (syscall+28)
  #00  pc 000000000019fd34  /apex/com.android.art/lib64/libart.so (art::ConditionVariable::WaitHoldingLocks(art::Thread*)+148)
  #00  pc 000000000038c9bc  /apex/com.android.art/lib64/libart.so (art::JNI<false>::CallObjectMethodV(_JNIEnv*, _jobject*, _jmethodID*, std::__va_list)+504)
  #00  pc 0000000000004040  /apex/com.android.art/lib64/libnativehelper.so (_JNIEnv::CallObjectMethod(_jobject*, _jmethodID*, ...)+124)
  #00  pc 00000000000ed4ec  /system/lib64/libandroid_runtime.so (android::NativeDisplayEventReceiver::dispatchVsync(long, unsigned long, unsigned int)+48)
  #00  pc 0000000000094170  /system/lib64/libgui.so (android::DisplayEventDispatcher::handleEvent(int, int, void*)+160)
  #00  pc 000000000001a4c0  /system/lib64/libutils.so (android::Looper::pollInner(int)+896)
  #00  pc 000000000001a0d8  /system/lib64/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+112)
  #00  pc 000000000011aedc  /system/lib64/libandroid_runtime.so (android::android_os_MessageQueue_nativePollOnce(_JNIEnv*, _jobject*, long, int)+44)
  at android.os.MessageQueue.nativePollOnce (Native method)
  at android.os.MessageQueue.next (MessageQueue.java:335)
  at android.os.Looper.loop (Looper.java:206)
  at android.app.ActivityThread.main (ActivityThread.java:8587)
  at java.lang.reflect.Method.invoke (Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run (RuntimeInit.java:602)
  at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:1130)```

```Type "Jit thread pool worker thread 0" daemon prio=5 tid=8 Native
  #00  pc 0000000000089c8c  /apex/com.android.runtime/lib64/bionic/libc.so (syscall+28)
  #00  pc 000000000019fd34  /apex/com.android.art/lib64/libart.so (art::ConditionVariable::WaitHoldingLocks(art::Thread*)+148)
  #00  pc 00000000005a7350  /apex/com.android.art/lib64/libart.so (art::ThreadPool::GetTask(art::Thread*)+120)
  #00  pc 00000000005a66e4  /apex/com.android.art/lib64/libart.so (art::ThreadPoolWorker::Run()+144)
  #00  pc 00000000005a6190  /apex/com.android.art/lib64/libart.so (art::ThreadPoolWorker::Callback(void*)+192)
  #00  pc 00000000000f41b4  /apex/com.android.runtime/lib64/bionic/libc.so (__pthread_start(void*)+64)
  #00  pc 000000000008ede4  /apex/com.android.runtime/lib64/bionic/libc.so (__start_thread+64)```

```Type "ReferenceQueueDaemon" daemon prio=5 tid=9 Waiting
  at java.lang.Object.wait (Native method)
  at java.lang.Object.wait (Object.java:442)
  at java.lang.Object.wait (Object.java:568)
  at java.lang.Daemons$ReferenceQueueDaemon.runInternal (Daemons.java:217)
  at java.lang.Daemons$Daemon.run (Daemons.java:139)
  at java.lang.Thread.run (Thread.java:923)```

```Type "FinalizerWatchdogDaemon" daemon prio=5 tid=10 Sleeping
  at java.lang.Thread.sleep (Native method)
  at java.lang.Thread.sleep (Thread.java:442)
  at java.lang.Thread.sleep (Thread.java:358)
  at java.lang.Daemons$FinalizerWatchdogDaemon.sleepForNanos (Daemons.java:390)
  at java.lang.Daemons$FinalizerWatchdogDaemon.waitForFinalization (Daemons.java:419)
  at java.lang.Daemons$FinalizerWatchdogDaemon.runInternal (Daemons.java:325)
  at java.lang.Daemons$Daemon.run (Daemons.java:139)
  at java.lang.Thread.run (Thread.java:923)```

```Type "FinalizerDaemon" daemon prio=5 tid=11 Waiting
  at java.lang.Object.wait (Native method)
  at java.lang.Object.wait (Object.java:442)
  at java.lang.ref.ReferenceQueue.remove (ReferenceQueue.java:190)
  at java.lang.ref.ReferenceQueue.remove (ReferenceQueue.java:211)
  at java.lang.Daemons$FinalizerDaemon.runInternal (Daemons.java:273)
  at java.lang.Daemons$Daemon.run (Daemons.java:139)
  at java.lang.Thread.run (Thread.java:923)```

```Type "Binder:11517_1" prio=5 tid=12 Native
  #00  pc 00000000000ddb44  /apex/com.android.runtime/lib64/bionic/libc.so (__ioctl+4)
  #00  pc 0000000000097108  /apex/com.android.runtime/lib64/bionic/libc.so (ioctl+156)
  #00  pc 0000000000053420  /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+248)
  #00  pc 00000000000536f8  /system/lib64/libbinder.so (android::IPCThreadState::getAndExecuteCommand()+24)
  #00  pc 000000000005431c  /system/lib64/libbinder.so (android::IPCThreadState::joinThreadPool(bool)+72)
  #00  pc 000000000007ce40  /system/lib64/libbinder.so (android::PoolThread::threadLoop()+400)
  #00  pc 000000000001553c  /system/lib64/libutils.so (android::Thread::_threadLoop(void*)+320)
  #00  pc 00000000000a4974  /system/lib64/libandroid_runtime.so (android::AndroidRuntime::javaThreadShell(void*)+144)
  #00  pc 0000000000014db0  /system/lib64/libutils.so (thread_data_t::trampoline(thread_data_t const*)+408)
  #00  pc 00000000000f41b4  /apex/com.android.runtime/lib64/bionic/libc.so (__pthread_start(void*)+64)
  #00  pc 000000000008ede4  /apex/com.android.runtime/lib64/bionic/libc.so (__start_thread+64)```

```Type "Binder:11517_2" prio=5 tid=13 Native
  #00  pc 00000000000ddb44  /apex/com.android.runtime/lib64/bionic/libc.so (__ioctl+4)
  #00  pc 0000000000097108  /apex/com.android.runtime/lib64/bionic/libc.so (ioctl+156)
  #00  pc 0000000000053420  /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+248)
  #00  pc 00000000000536f8  /system/lib64/libbinder.so (android::IPCThreadState::getAndExecuteCommand()+24)
  #00  pc 0000000000054348  /system/lib64/libbinder.so (android::IPCThreadState::joinThreadPool(bool)+116)
  #00  pc 000000000007ce40  /system/lib64/libbinder.so (android::PoolThread::threadLoop()+400)
  #00  pc 000000000001553c  /system/lib64/libutils.so (android::Thread::_threadLoop(void*)+320)
  #00  pc 00000000000a4974  /system/lib64/libandroid_runtime.so (android::AndroidRuntime::javaThreadShell(void*)+144)
  #00  pc 0000000000014db0  /system/lib64/libutils.so (thread_data_t::trampoline(thread_data_t const*)+408)
  #00  pc 00000000000f41b4  /apex/com.android.runtime/lib64/bionic/libc.so (__pthread_start(void*)+64)
  #00  pc 000000000008ede4  /apex/com.android.runtime/lib64/bionic/libc.so (__start_thread+64)```

```Type "Profile Saver" daemon prio=5 tid=14 Native
  #00  pc 0000000000089c8c  /apex/com.android.runtime/lib64/bionic/libc.so (syscall+28)
  #00  pc 000000000019fd34  /apex/com.android.art/lib64/libart.so (art::ConditionVariable::WaitHoldingLocks(art::Thread*)+148)
  #00  pc 0000000000341d9c  /apex/com.android.art/lib64/libart.so (art::ProfileSaver::Run()+484)
  #00  pc 000000000034644c  /apex/com.android.art/lib64/libart.so (art::ProfileSaver::RunProfileSaverThread(void*)+180)
  #00  pc 00000000000f41b4  /apex/com.android.runtime/lib64/bionic/libc.so (__pthread_start(void*)+64)
  #00  pc 000000000008ede4  /apex/com.android.runtime/lib64/bionic/libc.so (__start_thread+64)```

```Type "ScionFrontendApi" prio=5 tid=15 TimedWaiting
  at sun.misc.Unsafe.park (Native method)
  at java.util.concurrent.locks.LockSupport.parkNanos (LockSupport.java:230)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos (AbstractQueuedSynchronizer.java:2109)
  at java.util.concurrent.LinkedBlockingQueue.poll (LinkedBlockingQueue.java:467)
  at java.util.concurrent.ThreadPoolExecutor.getTask (ThreadPoolExecutor.java:1091)
  at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1152)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:641)
  at java.lang.Thread.run (Thread.java:923)```

```Type "GmsDynamite" prio=5 tid=16 Waiting
  at java.lang.Object.wait (Native method)
  at java.lang.Object.wait (Object.java:442)
  at java.lang.Object.wait (Object.java:568)
  at n6.a.run```

```Type "TokenRefresher" prio=5 tid=17 Native
  #00  pc 00000000000deb08  /apex/com.android.runtime/lib64/bionic/libc.so (__epoll_pwait+8)
  #00  pc 000000000001a1f4  /system/lib64/libutils.so (android::Looper::pollInner(int)+180)
  #00  pc 000000000001a0d8  /system/lib64/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+112)
  #00  pc 000000000011aedc  /system/lib64/libandroid_runtime.so (android::android_os_MessageQueue_nativePollOnce(_JNIEnv*, _jobject*, long, int)+44)
  at android.os.MessageQueue.nativePollOnce (Native method)
  at android.os.MessageQueue.next (MessageQueue.java:335)
  at android.os.Looper.loop (Looper.java:206)
  at android.os.HandlerThread.run (HandlerThread.java:67)```

```Type "pool-7-thread-1" prio=5 tid=19 Waiting
  at sun.misc.Unsafe.park (Native method)
  at java.util.concurrent.locks.LockSupport.park (LockSupport.java:190)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await (AbstractQueuedSynchronizer.java:2067)
  at java.util.concurrent.LinkedBlockingQueue.take (LinkedBlockingQueue.java:442)
  at java.util.concurrent.ThreadPoolExecutor.getTask (ThreadPoolExecutor.java:1092)
  at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1152)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:641)
  at java.lang.Thread.run (Thread.java:923)```

```Type "Firebase-Messaging-Init" prio=5 tid=20 Waiting
  at sun.misc.Unsafe.park (Native method)
  at java.util.concurrent.locks.LockSupport.park (LockSupport.java:190)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await (AbstractQueuedSynchronizer.java:2067)
  at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take (ScheduledThreadPoolExecutor.java:1120)
  at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take (ScheduledThreadPoolExecutor.java:849)
  at java.util.concurrent.ThreadPoolExecutor.getTask (ThreadPoolExecutor.java:1092)
  at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1152)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:641)
  at k6.b.run
  at java.lang.Thread.run (Thread.java:923)```

```Type "Firebase-Messaging-Topics-Io" prio=5 tid=21 Waiting
  at sun.misc.Unsafe.park (Native method)
  at java.util.concurrent.locks.LockSupport.park (LockSupport.java:190)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await (AbstractQueuedSynchronizer.java:2067)
  at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take (ScheduledThreadPoolExecutor.java:1120)
  at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take (ScheduledThreadPoolExecutor.java:849)
  at java.util.concurrent.ThreadPoolExecutor.getTask (ThreadPoolExecutor.java:1092)
  at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1152)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:641)
  at k6.b.run
  at java.lang.Thread.run (Thread.java:923)```

```Type "WM.task-1" prio=5 tid=22 Waiting
  at sun.misc.Unsafe.park (Native method)
  at java.util.concurrent.locks.LockSupport.park (LockSupport.java:190)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await (AbstractQueuedSynchronizer.java:2067)
  at java.util.concurrent.LinkedBlockingQueue.take (LinkedBlockingQueue.java:442)
  at java.util.concurrent.ThreadPoolExecutor.getTask (ThreadPoolExecutor.java:1092)
  at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1152)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:641)
  at java.lang.Thread.run (Thread.java:923)```

```Type "Measurement Worker" prio=5 tid=24 TimedWaiting
  at java.lang.Object.wait (Native method)
  at java.lang.Object.wait (Object.java:442)
  at jc.run (com.google.android.gms.dynamite_measurementdynamite@221514081@22.15.14 (150400-0):7)```

```Type "WM.task-2" prio=5 tid=25 Waiting
  at sun.misc.Unsafe.park (Native method)
  at java.util.concurrent.locks.LockSupport.park (LockSupport.java:190)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await (AbstractQueuedSynchronizer.java:2067)
  at java.util.concurrent.LinkedBlockingQueue.take (LinkedBlockingQueue.java:442)
  at java.util.concurrent.ThreadPoolExecutor.getTask (ThreadPoolExecutor.java:1092)
  at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1152)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:641)
  at java.lang.Thread.run (Thread.java:923)```

```Type "AsyncTask #2" prio=5 tid=26 Waiting
  at sun.misc.Unsafe.park (Native method)
  at java.util.concurrent.locks.LockSupport.park (LockSupport.java:190)
  at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill (SynchronousQueue.java:459)
  at java.util.concurrent.SynchronousQueue$TransferStack.transfer (SynchronousQueue.java:362)
  at java.util.concurrent.SynchronousQueue.take (SynchronousQueue.java:920)
  at java.util.concurrent.ThreadPoolExecutor.getTask (ThreadPoolExecutor.java:1092)
  at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1152)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:641)
  at java.lang.Thread.run (Thread.java:923)```

```Type "pool-13-thread-1" prio=5 tid=31 TimedWaiting
  at sun.misc.Unsafe.park (Native method)
  at java.util.concurrent.locks.LockSupport.parkNanos (LockSupport.java:230)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos (AbstractQueuedSynchronizer.java:2109)
  at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take (ScheduledThreadPoolExecutor.java:1132)
  at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take (ScheduledThreadPoolExecutor.java:849)
  at java.util.concurrent.ThreadPoolExecutor.getTask (ThreadPoolExecutor.java:1092)
  at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1152)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:641)
  at java.lang.Thread.run (Thread.java:923)```

```Type "pool-14-thread-1" prio=5 tid=32 Waiting
  at sun.misc.Unsafe.park (Native method)
  at java.util.concurrent.locks.LockSupport.park (LockSupport.java:190)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await (AbstractQueuedSynchronizer.java:2067)
  at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take (ScheduledThreadPoolExecutor.java:1120)
  at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take (ScheduledThreadPoolExecutor.java:849)
  at java.util.concurrent.ThreadPoolExecutor.getTask (ThreadPoolExecutor.java:1092)
  at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1152)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:641)
  at java.lang.Thread.run (Thread.java:923)```

```Type "Binder:11517_3" prio=5 tid=33 Native
  #00  pc 00000000000ddb44  /apex/com.android.runtime/lib64/bionic/libc.so (__ioctl+4)
  #00  pc 0000000000097108  /apex/com.android.runtime/lib64/bionic/libc.so (ioctl+156)
  #00  pc 0000000000053420  /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+248)
  #00  pc 00000000000536f8  /system/lib64/libbinder.so (android::IPCThreadState::getAndExecuteCommand()+24)
  #00  pc 0000000000054348  /system/lib64/libbinder.so (android::IPCThreadState::joinThreadPool(bool)+116)
  #00  pc 000000000007ce40  /system/lib64/libbinder.so (android::PoolThread::threadLoop()+400)
  #00  pc 000000000001553c  /system/lib64/libutils.so (android::Thread::_threadLoop(void*)+320)
  #00  pc 00000000000a4974  /system/lib64/libandroid_runtime.so (android::AndroidRuntime::javaThreadShell(void*)+144)
  #00  pc 0000000000014db0  /system/lib64/libutils.so (thread_data_t::trampoline(thread_data_t const*)+408)
  #00  pc 00000000000f41b4  /apex/com.android.runtime/lib64/bionic/libc.so (__pthread_start(void*)+64)
  #00  pc 000000000008ede4  /apex/com.android.runtime/lib64/bionic/libc.so (__start_thread+64)```

```Type "OkHttp ConnectionPool" daemon prio=5 tid=34 TimedWaiting
  at java.lang.Object.wait (Native method)
  at com.android.okhttp.ConnectionPool$1.run (ConnectionPool.java:106)
  at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1167)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:641)
  at java.lang.Thread.run (Thread.java:923)```

```Type "flutter-worker-0" prio=5 tid=35 TimedWaiting
  at sun.misc.Unsafe.park (Native method)
  at java.util.concurrent.locks.LockSupport.parkNanos (LockSupport.java:230)
  at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill (SynchronousQueue.java:461)
  at java.util.concurrent.SynchronousQueue$TransferStack.transfer (SynchronousQueue.java:362)
  at java.util.concurrent.SynchronousQueue.poll (SynchronousQueue.java:937)
  at java.util.concurrent.ThreadPoolExecutor.getTask (ThreadPoolExecutor.java:1091)
  at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1152)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:641)
  at java.lang.Thread.run (Thread.java:923)```

```Type "flutter-worker-1" prio=5 tid=36 TimedWaiting
  at sun.misc.Unsafe.park (Native method)
  at java.util.concurrent.locks.LockSupport.parkNanos (LockSupport.java:230)
  at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill (SynchronousQueue.java:461)
  at java.util.concurrent.SynchronousQueue$TransferStack.transfer (SynchronousQueue.java:362)
  at java.util.concurrent.SynchronousQueue.poll (SynchronousQueue.java:937)
  at java.util.concurrent.ThreadPoolExecutor.getTask (ThreadPoolExecutor.java:1091)
  at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1152)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:641)
  at java.lang.Thread.run (Thread.java:923)```

```Type "queued-work-looper" prio=5 tid=37 Native
  #00  pc 00000000000deb08  /apex/com.android.runtime/lib64/bionic/libc.so (__epoll_pwait+8)
  #00  pc 000000000001a1f4  /system/lib64/libutils.so (android::Looper::pollInner(int)+180)
  #00  pc 000000000001a0d8  /system/lib64/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+112)
  #00  pc 000000000011aedc  /system/lib64/libandroid_runtime.so (android::android_os_MessageQueue_nativePollOnce(_JNIEnv*, _jobject*, long, int)+44)
  at android.os.MessageQueue.nativePollOnce (Native method)
  at android.os.MessageQueue.next (MessageQueue.java:335)
  at android.os.Looper.loop (Looper.java:206)
  at android.os.HandlerThread.run (HandlerThread.java:67)```

```Type "AudioPortEventHandler" prio=5 tid=40 Native
  #00  pc 00000000000deb08  /apex/com.android.runtime/lib64/bionic/libc.so (__epoll_pwait+8)
  #00  pc 000000000001a1f4  /system/lib64/libutils.so (android::Looper::pollInner(int)+180)
  #00  pc 000000000001a0d8  /system/lib64/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+112)
  #00  pc 000000000011aedc  /system/lib64/libandroi```

```Type "Signal Catcher" daemon prio=10 tid=5 Runnable
  #00  pc 0000000000483028  /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)
  #00  pc 0000000000588888  /apex/com.android.art/lib64/libart.so (art::Thread::DumpStack(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, bool, BacktraceMap*, bool) const+380)
  #00  pc 00000000005a56d4  /apex/com.android.art/lib64/libart.so (art::DumpCheckpoint::Run(art::Thread*)+924)
  #00  pc 000000000059f078  /apex/com.android.art/lib64/libart.so (art::ThreadList::RunCheckpoint(art::Closure*, art::Closure*)+536)
  #00  pc 000000000059e134  /apex/com.android.art/lib64/libart.so (art::ThreadList::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, bool)+1928)
  #00  pc 000000000059d5cc  /apex/com.android.art/lib64/libart.so (art::ThreadList::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+776)
  #00  pc 000000000054ae40  /apex/com.android.art/lib64/libart.so (art::Runtime::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+196)
  #00  pc 000000000056099c  /apex/com.android.art/lib64/libart.so (art::SignalCatcher::HandleSigQuit()+1400)
  #00  pc 000000000055f950  /apex/com.android.art/lib64/libart.so (art::SignalCatcher::Run(void*)+384)
  #00  pc 00000000000f41b4  /apex/com.android.runtime/lib64/bionic/libc.so (__pthread_start(void*)+64)
  #00  pc 000000000008ede4  /apex/com.android.runtime/lib64/bionic/libc.so (__start_thread+64)```

```Type "HeapTaskDaemon" daemon prio=5 tid=7 WaitingForTaskProcessor
  #00  pc 0000000000089c8c  /apex/com.android.runtime/lib64/bionic/libc.so (syscall+28)
  #00  pc 000000000019fd34  /apex/com.android.art/lib64/libart.so (art::ConditionVariable::WaitHoldingLocks(art::Thread*)+148)
  #00  pc 00000000002d85b4  /apex/com.android.art/lib64/libart.so (art::gc::TaskProcessor::GetTask(art::Thread*)+540)
  #00  pc 00000000002d8ed8  /apex/com.android.art/lib64/libart.so (art::gc::TaskProcessor::RunAllTasks(art::Thread*)+92)
  at dalvik.system.VMRuntime.runHeapTasks (Native method)
  at java.lang.Daemons$HeapTaskDaemon.runInternal (Daemons.java:531)
  at java.lang.Daemons$Daemon.run (Daemons.java:139)
  at java.lang.Thread.run (Thread.java:923)```
ryanheise commented 2 years ago

Thanks, but can you please format this with correct markdown? Multiline code blocks should be enclosed in 3-backtick quotes.

Edit: And please "edit" your existing comment rather than post a new comment.

ryanheise commented 2 years ago

All I can find on this particular ANR so far is this:

https://stackoverflow.com/questions/69955232/anr-input-dispatching-timed-out-activityrecord-does-not-have-a-focused-window

Which isn't helpful.

I know you are observing this in production but are you able to collect the user steps leading up to this ANR so that there may be a chance of reproducing it?

Vitalie-Andries commented 2 years ago

Thank you very much for your quick response. I will try to find a physical device with Android 11 and I will try to catch the ANR error, so that I can reproduce it, the emulator will not help in this case. Thank you @ryanheise for your support and work.

ryanheise commented 2 years ago

Hi @Vitalie-Andries , have you had any update in being able to reproduce this?

Vitalie-Andries commented 2 years ago

Hello @ryanheise, unfortunately not, in emulator i cant catch this ANR, but a physical device with SDK30 I dont have. And this ANRs still persist in play console and just for Android 11.

Screenshot 2022-06-29 at 11 14 56 Screenshot 2022-06-29 at 11 14 44

`

keshavs01 commented 2 years ago

Hey @ryanheise , I don't know if this is helpful or not but I am also facing similar type of ANRs for Android 11 devices. Although my ANR details heading is little different than the one mentioned above.

Input dispatching timed out (b01ae51 com.my.package/com.ryanheise.audioservice.AudioServiceActivity (server) is not responding. Waited 10001ms for MotionEvent)

I have been trying to find the root cause but so far no luck. Edit: audio_service verion : ^0.18.2. I have updated my app to latest version (v0.18.7) recently and will update if there is drop in ANRs.

ryanheise commented 2 years ago

I think the next step would be to reproduce it. I am curious to know whether this is caused by another plugin because "if" another plugin were to cause an ANR, Android would still report AudioServiceActivity as the activity name since that's just the activity that contains everything in your app.