Media 3 on wear issue infinite buferring.

[Tolriq]

Version

Media3 1.5.0

More version details

No response

Devices that reproduce the issue

Some Pixel watch 2 and Pixel watch 3.

Devices that do not reproduce the issue

No response

Reproducible in the demo app?

No

Reproduction steps

I don't have a proper repro yet as I can't reproduce on my watch, only users reports.

But playback on watch some media with offloading will trigger infinite buffering and kill the battery very fast.
Restarting the same media and they will play correctly.
Seems there's some issues with handling discontinuity on Wear due to offloading or something.

One user did not give the logs but says it reproduce at 1:00 exactly every 2 songs.

So the first song play, the 2nd stall at 1:00 if he skip back if will play the song without issue too.

This 1 minute mark with offload and gapless will probably give some clue if you know how offload works (I don't :) )

Expected result

The media play correctly, or if it's a failure that ExoPlayer is not able to recover from, it should error so we can stop playback or skip next and not kill the battery.

Actual result

Media stays in buffering state and kills the battery.

Relevant logCat:

11-26 23:00:28.845 W MonotonicFrameCounter 730 updateAndGetMonotonicFrameCount: retrograde newFrameCount:2647749 < mLastReceivedFrameCount:7911650, ignoring, returning 7911650 as frameCount
11-26 23:00:28.853 W MonotonicFrameCounter 730 updateAndGetMonotonicFrameCount: retrograde newFrameCount:2647749 < mLastReceivedFrameCount:7911650, ignoring, returning 7911650 as frameCount
11-26 23:00:28.875 W DefaultAudioSink 5595 Spurious audio timestamp (frame position mismatch): 10490108, 426521657, 426512856, 179711746, 12001536, 11964672
11-26 23:00:28.883 V Playback 5595 rendererReady [eventTime=289.01, mediaPos=26.10, window=3, period=3, rendererIndex=0, audio, false]
11-26 23:00:28.886 W MonotonicFrameCounter 730 updateAndGetMonotonicFrameCount: retrograde newFrameCount:2647749 < mLastReceivedFrameCount:7911650, ignoring, returning 7911650 as frameCount
11-26 23:00:28.887 D AHAL: AudioStrea 657): astream_pause: 564: pause
11-26 23:00:28.887 I AHAL: AudioStrea 657): Pause: 2239: Enter: usecase(4: compress-offload-playback)
11-26 23:00:28.889 D AGM: grap 1324): graph_set_config: 1104 entry graph_handle 0x47534c
11-26 23:00:28.892 D AGM: grap 1324): graph_set_config: 1112 exit, graph handle 0x47534c, ret 0
11-26 23:00:28.893 I PAL: SessionAlsaCompres 657): setParameters: 2168: mixer set vol ctrl ramp status=0
11-26 23:00:28.895 D AGM: grap 1324): graph_set_config: 1104 entry graph_handle 0x47534c
11-26 23:00:28.898 D AGM: grap 1324): graph_set_config: 1112 exit, graph handle 0x47534c, ret 0
11-26 23:00:28.899 I PAL: SessionAlsaCompres 657): setParameters: 2130: mixer set volume config status=0
11-26 23:00:28.943 I PAL: ResourceManage 657): mixerEventWaitThreadLoop: 4698: Event Received COMPRESS105 event
11-26 23:00:28.943 E PLUGIN: compres 657): agm_compress_event_cb: 217 agm_compress_event_cb: error: Invalid event params id: 134221887
11-26 23:00:28.944 D AHAL: AudioStrea 657): Pause: 2286: Exit ret: 0
11-26 23:00:28.950 D audioserver 730 logFgsApiEnd: FGS Logger Transaction failed, -129
11-26 23:00:28.953 V Playback 5595 onPlaybackStateChanged 2
11-26 23:00:28.954 D MediaSessionService 1304 onSessionPlaybackStateChanged: record=app.symfonik.music.player/androidx.media3.session.id./5 (userId=0)playbackState=PlaybackState {state=BUFFERING(6), position=26097, buffered position=95712, speed=0.0, updated=426611, actions=7340031, custom actions=[], active item id=3, error=null}allowRunningInForeground=true
11-26 23:00:28.954 D AHAL: AudioStrea 657): out_update_source_metadata_v7: 1174: track count is 0 for usecase(4: compress-offload-playback)
11-26 23:00:28.960 W audioserver 730 Binder 0xf7227208 destroyed after setMinSchedulerPolicy before being parceled.
11-26 23:00:28.962 V Playback 5595 isPlaying [eventTime=289.09, mediaPos=26.10, window=3, period=3, false]
11-26 23:00:28.962 D MediaSessionService 1304 onSessionPlaybackStateChanged: record=app.symfonik.music.player/androidx.media3.session.id./5 (userId=0)playbackState=PlaybackState {state=BUFFERING(6), position=26097, buffered position=95712, speed=0.0, updated=426614, actions=7340031, custom actions=[], active item id=3, error=null}allowRunningInForeground=true
11-26 23:00:28.964 V Unknown  5595): sleeping for offload false
11-26 23:00:28.967 W AudioFlinger 730 moveEffectChain_ll: effect chain for session 0 not on source thread 0xf6a819e8
11-26 23:00:28.967 I WMS-WearMediaStatsLogge 2728 Logging mediaSessionStateChanged: sessionId=1750582075, mediaPlayerPackageName=app.symfonik.music.player, isRemoteSession=false, sessionState=SESSION_BUFFERING, isPlayWhenReady=true, playbackSuppressionReason=PLAYBACK_SUPPRESSION_REASON_NONE, has_playback_suppression_due_to_unsuitable_output_resolved=false
11-26 23:00:28.973 I WMS-OngoingActivityMana 2728 Canceling previous ongoing activity
11-26 23:00:28.974 D OomAdjuster 1304 Not killing cached processes
11-26 23:00:28.980 I sysui_multi_action 1304 [757,128,758,5,759,8,793,60000,794,0,795,60000,796,0,797,ongoing_media_notification_tag,806,com.google.android.wearable.media.sessions,857,MEDIA_APK_CHANNEL_ID,858,3,946,ranker_group,947,0,1500,59992,1641,transport,1688,1]
11-26 23:00:28.980 I notification_canceled 1304 [0|com.google.android.wearable.media.sessions|0|ongoing_media_notification_tag|10038,8,60000,60000,0,-1,-1,NULL]
11-26 23:00:28.987 I notification_enqueue 1304 [10135,5595,app.symfonik.music.player,1001,NULL,0,Notification(channel=default_channel_id shortcut=null contentView=null vibrate=null sound=null defaults=0x0 flags=0x48 color=0x00000000 category=transport groupKey=media3_group_key actions=3 vis=PUBLIC),1]
11-26 23:00:28.988 I notification_enqueue 1304 [10038,2728,com.google.android.wearable.media.sessions,2147483647,ranker_group,0,Notification(channel=MEDIA_APK_CHANNEL_ID shortcut=null contentView=null vibrate=null sound=null defaults=0x0 flags=0x700 color=0x00000000 groupKey=ranker_group vis=PRIVATE),1]
11-26 23:00:28.992 I NearbyFastPair 1733 (REDACTED) TriangleSessionTracker: flush media count=%s, media duration=%ss, call count=%s
11-26 23:00:29.008 I DisplayOffloadManager 1692 sendStatusBar
11-26 23:00:29.013 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.014 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.015 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.016 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.016 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.017 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.017 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.017 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.017 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.018 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.018 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.018 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.018 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.019 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.019 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.020 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.020 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.020 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.020 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.021 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.021 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.021 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.021 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.022 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.022 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.022 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.022 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.023 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.023 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.023 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.023 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 
11-26 23:00:29.024 I AF::TrackHandle 730 opChanged OP_PLAY_AUDIO callback received for 

After that nothing ExoPlayer or audio related in the logcat from the user.

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.

[Tolriq]

And just confirmed with 2 users.

Removing

                    trackSelectionParameters = trackSelectionParameters.buildUpon()
                        .setAudioOffloadPreferences(
                            AudioOffloadPreferences.Builder()
                                .setAudioOffloadMode(AudioOffloadPreferences.AUDIO_OFFLOAD_MODE_ENABLED)
                                .setIsSpeedChangeSupportRequired(false)
                                .setIsGaplessSupportRequired(false)
                                .build(),
                        )
                        .build()

Fully fix the issue for them. Since battery usage in Wear is important this is a little problematic to disable by default and users would not always found the option or think to contact me.
It would at least be useful that we had a way to detect that so we could disable offload.

[Tolriq]

Bump on this one as it's quite problematic and I can't find a good way to only workaround the issue without impacting all the wear users battery life.

[microkatz]

@Tolriq

As you were able to confirm with users and the description says its easily reproducible(every two songs), would you be able to provide the content or a bug report? If you're unable to share bug reports or test content publicly, please send them to android-media-github@google.com with the subject Issue #1920. Please also update this issue to indicate you've done this.

[Tolriq]

A bug report was sent,

[Tolriq]

Bump as the number of users grow and the number of complains too.

[Tolriq]

Monthly bump. Is wear an officially supported platform for Media3? Or should I disable offload by default and not care about battery.

[RPJoshL]

I'm having the exact same problem with my Pixel Watch 2 LTE when enabling AudioOffloading. The playback stops after exactly 01:00 Minute for the second song in the playlist.

Because using Audio Offloading is even recommended in the Android docs for playing media, I've expected it works without any problems on WearOS.

That's my foreground service I'm used for testing.

[Tolriq]

Yep at this point I guess it's best not to offload as no reaction here, and in my case complains increase and ratings goes down. Even if Wear is a small part of the users, in my case it's still 4300 users and counting.

[microkatz]

@Tolriq

Apologies for the delay and truly thank you for keeping this issue on our radar!

According to the log traces that you provided, the underlying audio track is receiving a pause event.

  702: {audio.track.42, (12-20 08:39:44.238), (app.symfonik.music.player, 0, 10136), (bufferSizeFrames=131072, event#=stop, executionTimeNs=334062, state=STATE_STOPPING, underrun=0)}
  703: {audio.thread.85, (12-20 08:40:19.476), (audioserver, 0, 1041), (event#=createAudioPatch, inputDevices=, outputDevices=(AUDIO_DEVICE_OUT_BLUETOOTH_A2DP, 14:22:3B:DE:60:4F))}
  704: {audio.track.42, (12-20 08:40:19.489), (app.symfonik.music.player, 0, 10136), (callerName=java, event#=start, executionTimeNs=85404740, state=STATE_ACTIVE, status#=0)}
  705: {audio.track.42, (12-20 08:41:18.601), (app.symfonik.music.player, 0, 10136), (event#=pause, executionTimeNs=173226562, state=STATE_PAUSED)}

Does your application have any custom pause or stop procedure that may be causing this? This is also from what I can tell in your log traces as it did not contain any ExoPlayer debug logging.

In addition, would you be able to provide the content that is causing the issue so as to see if we can reproduce with the demo application?