androidx
Media 3 on wear issue infinite buferring.
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 bugreportto [email protected] after filing this issue.
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.
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.
@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 [email protected] with the subject Issue #1920. Please also update this issue to indicate you've done this.
Monthly bump. Is wear an officially supported platform for Media3? Or should I disable offload by default and not care about battery.
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.
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.
@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?
There's nothing special and removing offload and only removing that fixes this. Furthermore ExoPlayer state report buffering not paused.
I currently no more have users willing to provide dumps and logs after so long.
Maybe @RPJoshL can repro and provide more needed logs as he can repro the exact same behavior or 1min every 2 songs.
@Tolriq
There is a fix that we are working on that for an offload issue that may be linked to this one. The issue is such that for very short content or players with high minimum buffer duration in their load control settings, there can be a position hang and mismatch as you described. However, one difference though is that the audio would continue to play, the position would eventually fix itself.
I will update this bug when the fix has been submitted.
Thank you for your patience.
@Tolriq
A fix has been submitted that may address this, https://github.com/androidx/media/commit/8327a2a52dd72a98d4abc123f33cfe1250898318 as mentioned in the previous comment. Thanks again for your patience!
Since updating from WearOS 5.0 to 5.1, playback stability has slightly improved: instead of consistently failing after every two tracks, the issue now occurs randomly between 10 and 20 minutes.
I tested with a playlist of 20 MP3 files, each approximately 3 minutes long. Unfortunately, I haven’t noticed any difference with your commit (8327a2a) applied to the 1.6.0 release.
Below is the relevant portion of the logcat:
Sample 1
# Track played for like 5 seconds
2025-04-04 20:11:22.809 653-1453 PAL: ResourceManager android.hardware.audio.service I mixerEventWaitThreadLoop: 4700: Event Received COMPRESS105 event
2025-04-04 20:11:22.809 653-3539 PLUGIN: compress android.hardware.audio.service D agm_compress_event_cb: 207 agm_compress_event_cb: Early EOS event received
2025-04-04 20:11:22.809 653-6431 PLUGIN: compress android.hardware.audio.service D agm_compress_partial_drain: 744 agm_compress_partial_drain: out of early eos wait
2025-04-04 20:11:22.809 653-6431 PAL: Sessi...saCompress android.hardware.audio.service I offloadThreadLoop: 656: out of partial compress_drain, ret 0
2025-04-04 20:11:22.809 653-6431 AHAL: AudioStream android.hardware.audio.service D pal_callback: 346: received PARTIAL DRAIN_READY event
2025-04-04 20:11:22.812 653-1453 AHAL: AudioStream android.hardware.audio.service E pal_callback: 356: Invalid event id:134222118
2025-04-04 20:11:22.822 725-6428 audioserver audioserver D logFgsApiEnd: FGS Logger Transaction failed, -129
2025-04-04 20:11:22.825 653-681 AHAL: AudioStream android.hardware.audio.service D out_update_source_metadata_v7: 1174: track count is 0 for usecase(4: compress-offload-playback)
2025-04-04 20:11:22.834 725-981 audioserver audioserver W Binder 0xf3a22398 destroyed after setInheritRt before being parceled.
2025-04-04 20:11:22.834 725-981 audioserver audioserver W Binder 0xf3a22398 destroyed after setMinSchedulerPolicy before being parceled.
2025-04-04 20:11:22.835 725-2783 Permission audioserver W The package name(android) provided does not correspond to the uid 1041
2025-04-04 20:11:22.843 653-681 EffectsFactory android.hardware.audio.service I EffectCreate() create_effect
2025-04-04 20:11:22.845 1923-1923 HWUI com.google.wear.watchface.runtime W Image decoding logging dropped!
2025-04-04 20:11:22.848 1923-1923 HWUI com.google.wear.watchface.runtime W Image decoding logging dropped!
2025-04-04 20:11:22.848 725-981 AudioFlinger audioserver W moveEffectChain_ll: effect chain for session 0 not on source thread 0xf2fd6da0
2025-04-04 20:11:22.851 725-2783 AudioFlinger audioserver W moveEffectChain_ll: effect chain for session 0 not on source thread 0xf311b2a4
2025-04-04 20:11:22.923 1923-1923 HWUI com.google.wear.watchface.runtime W Image decoding logging dropped!
2025-04-04 20:11:22.973 653-3539 AHAL: AudioDevice android.hardware.audio.service D CreateAudioPatch: 439: source: 2, sink: 1, source type: 165, sink type 128
2025-04-04 20:11:22.973 653-3539 AHAL: AudioDevice android.hardware.audio.service D CreateAudioPatch: 441: enter: num sources 1, num_sinks 1
2025-04-04 20:11:22.973 653-3539 AHAL: AudioDevice android.hardware.audio.service D CreateAudioPatch: 456: source role 1, source type 2
2025-04-04 20:11:22.973 653-3539 AHAL: AudioDevice android.hardware.audio.service D CreateAudioPatch: 496: Playback patch from mix handle 165 to device 80
2025-04-04 20:11:22.973 653-3539 AHAL: AudioDevice android.hardware.audio.service I OutGetStream: 1319: Found existing stream associated with iohandle 165
2025-04-04 20:11:22.973 653-3539 AHAL: AudioVoice android.hardware.audio.service D RouteStream: 494: Enter
2025-04-04 20:11:22.973 653-3539 AHAL: AudioVoice android.hardware.audio.service E GetMatchingTxDevices: 471: unsupported Device Id of 128
2025-04-04 20:11:22.973 653-3539 AHAL: AudioVoice android.hardware.audio.service E RouteStream: 509: Invalid Tx/Rx device
2025-04-04 20:11:22.973 653-3539 AHAL: AudioVoice android.hardware.audio.service D RouteStream: 604: Exit ret: 0
2025-04-04 20:11:22.973 653-3539 AHAL: AudioStream android.hardware.audio.service I RouteStream: 2494: enter: usecase(4: compress-offload-playback) devices 0x80, num devices 1
2025-04-04 20:11:22.973 653-3539 AHAL: AudioStream android.hardware.audio.service D RouteStream: 2497: mAndroidOutDevices 128, mNoOfOutDevices 1
2025-04-04 20:11:22.973 653-3539 AHAL: AudioDevice android.hardware.audio.service D GetPalDeviceIds: 2436: haldeviceIds: 1
2025-04-04 20:11:22.973 653-3539 AHAL: AudioDevice android.hardware.audio.service D GetPalDeviceIds: 2443: Found haldeviceId: 80 and PAL Device ID 8
2025-04-04 20:11:22.973 653-3539 AHAL: AudioDevice android.hardware.audio.service D GetPalDeviceIds: 2462: devices allocated 1, pal device ids before returning 1
2025-04-04 20:11:22.973 653-3539 AHAL: AudioStream android.hardware.audio.service D RouteStream: 2526: noPalDevices: 1 , new_devices: 1
2025-04-04 20:11:22.973 653-3539 PAL: API android.hardware.audio.service I pal_stream_set_device: 1057: Enter. Stream handle :0xef636280K
2025-04-04 20:11:22.973 653-3539 btaudio_offload_aidl android.hardware.audio.service I audio_check_a2dp_ready_api: state = AUDIO_STATE_STARTED
2025-04-04 20:11:22.973 653-3539 btaudio_offload_aidl android.hardware.audio.service I audio_check_a2dp_ready_api: session ready = 1
2025-04-04 20:11:22.974 653-3539 PAL: Stream android.hardware.audio.service I switchDevice: 1504: number of active devices 1, new devices 1
2025-04-04 20:11:22.974 653-3539 PAL: ResourceManager android.hardware.audio.service I getActiveStream_l: 5601: no active streams found for device 7 ret -2
2025-04-04 20:11:22.974 653-3539 PAL: ResourceManager android.hardware.audio.service I doDevAttrDiffer: 11898: A2DP force device switch is 0
2025-04-04 20:11:22.974 653-3539 PAL: ResourceManager android.hardware.audio.service I compareSharedBEStreamDevAttr: 7023: switchStreams is 0
2025-04-04 20:11:22.974 653-3539 PAL: ResourceManager android.hardware.audio.service I streamDevSwitch: 7205: Enter
2025-04-04 20:11:22.974 653-3539 btaudio_offload_aidl android.hardware.audio.service I audio_check_a2dp_ready_api: state = AUDIO_STATE_STARTED
2025-04-04 20:11:22.974 653-3539 btaudio_offload_aidl android.hardware.audio.service I audio_check_a2dp_ready_api: session ready = 1
2025-04-04 20:11:22.974 653-3539 PAL: Device android.hardware.audio.service I setDeviceAttributes: 373: DeviceAttributes for Device Id 8 updated
2025-04-04 20:11:22.974 653-3539 PAL: Stream android.hardware.audio.service I connectStreamDevice_l: 1160: stream is already connected to device 8 name PAL_DEVICE_OUT_BLUETOOTH_A2DP - return
2025-04-04 20:11:22.974 653-3539 PAL: ResourceManager android.hardware.audio.service I streamDevSwitch: 7297: Exit status: 0
2025-04-04 20:11:22.974 653-3539 PAL: API android.hardware.audio.service I pal_stream_set_device: 1172: Exit. status 0
2025-04-04 20:11:22.974 653-3539 AHAL: AudioStream android.hardware.audio.service D RouteStream: 2651: exit 0
2025-04-04 20:11:22.974 653-3539 AHAL: AudioDevice android.hardware.audio.service D CreateAudioPatch: 552: Exit ret: 0
2025-04-04 20:11:22.978 653-3539 AHAL: AudioStream android.hardware.audio.service D out_update_source_metadata_v7: 1174: track count is 0 for usecase(4: compress-offload-playback)
2025-04-04 20:11:22.987 725-2783 audioserver audioserver D logFgsApiBegin: FGS Logger Transaction failed, -129
2025-04-04 20:11:22.987 1923-1923 HWUI com.google.wear.watchface.runtime W Image decoding logging dropped!
2025-04-04 20:11:22.994 1923-1923 HWUI com.google.wear.watchface.runtime W Image decoding logging dropped!
2025-04-04 20:11:22.994 653-3539 AHAL: AudioStream android.hardware.audio.service D out_update_source_metadata_v7: 1174: track count is 1 for usecase(4: compress-offload-playback)
2025-04-04 20:11:22.994 653-3539 AHAL: AudioStream android.hardware.audio.service D out_update_source_metadata_v7: 1215: Source metadata usage:1 content_type:0
2025-04-04 20:11:22.994 653-3539 AHAL: AudioStream android.hardware.audio.service D SetAggregateSourceMetadata: 3946: Aggregated Source metadata usage:1 content_type:0
2025-04-04 20:11:23.008 653-3539 AHAL: AudioStream android.hardware.audio.service D SetVolume: 2718: Enter: left 1.000000, right 1.000000 for usecase(4: compress-offload-playback)
2025-04-04 20:11:23.008 1395-1411 AGM: graph [email protected] D graph_set_config: 1104 entry graph_handle 0x47534c
2025-04-04 20:11:23.010 1395-1411 AGM: graph [email protected] D graph_set_config: 1112 exit, graph handle 0x47534c, ret 0
2025-04-04 20:11:23.010 653-3539 PAL: Sessi...saCompress android.hardware.audio.service I setParameters: 2130: mixer set volume config status=0
2025-04-04 20:11:23.010 653-3539 AHAL: AudioStream android.hardware.audio.service D SetVolume: 2769: Exit ret: 0
2025-04-04 20:11:23.011 653-6430 AHAL: AudioStream android.hardware.audio.service D write: 3762: sending gapless metadata
2025-04-04 20:11:23.012 1395-1411 AGM: graph [email protected] D graph_set_gapless_metadata: 2094 Decoder module IID 4082
2025-04-04 20:11:23.013 1395-1409 AGM: graph [email protected] D graph_set_gapless_metadata: 2094 Decoder module IID 4082
2025-04-04 20:11:23.312 725-2783 StreamHalHidl audioserver W Retrograde motion of 8241626 frames
2025-04-04 20:11:23.429 1395-1404 gsl [email protected] E gsl_handle_eos:236 Got invalid eos status 0 from Spf
2025-04-04 20:11:23.430 653-3539 PLUGIN: compress android.hardware.audio.service D agm_compress_event_cb: 195 agm_compress_event_cb: EOS event received
2025-04-04 20:11:23.430 653-3539 PLUGIN: compress android.hardware.audio.service D agm_compress_event_cb: 202 agm_compress_event_cb: EOS received before drain called
2025-04-04 20:11:23.441 725-6428 MonotonicFrameCounter audioserver W updateAndGetMonotonicFrameCount: retrograde newFrameCount:0 < mLastReceivedFrameCount:8232608, ignoring, returning 8232608 as frameCount
Sample 2
# Track played longer than a minute
2025-04-04 21:39:04.751 5590-9468 AudioTrack de.rpjosh.rpdb.testandroid W getTimestamp_l(113): startup glitch detected deltaTimeUs(270946) deltaPositionUs(197233990) tsmPosition(8698019)
2025-04-04 21:40:27.056 725-9474 MonotonicFrameCounter audioserver W updateAndGetMonotonicFrameCount: retrograde newFrameCount:3604064 < mLastReceivedFrameCount:12143421, ignoring, returning 12143421 as frameCount
2025-04-04 21:40:27.065 725-9474 MonotonicFrameCounter audioserver W updateAndGetMonotonicFrameCount: retrograde newFrameCount:3604064 < mLastReceivedFrameCount:12143421, ignoring, returning 12143421 as frameCount
2025-04-04 21:40:27.089 5590-9468 DefaultAudioSink de.rpjosh.rpdb.testandroid W Spurious audio timestamp (frame position mismatch): 77584917, 20855921433, 20855908532, 1772039523, 80137728, 80100864
2025-04-04 21:40:27.113 725-9474 MonotonicFrameCounter audioserver W updateAndGetMonotonicFrameCount: retrograde newFrameCount:3604064 < mLastReceivedFrameCount:12143421, ignoring, returning 12143421 as frameCount
2025-04-04 21:40:27.113 653-679 AHAL: AudioStream android.hardware.audio.service D astream_pause: 564: pause
2025-04-04 21:40:27.114 653-679 AHAL: AudioStream android.hardware.audio.service I Pause: 2239: Enter: usecase(4: compress-offload-playback)
2025-04-04 21:40:27.116 1395-20228 AGM: graph [email protected] D graph_set_config: 1104 entry graph_handle 0x47534c
2025-04-04 21:40:27.119 1395-20228 AGM: graph [email protected] D graph_set_config: 1112 exit, graph handle 0x47534c, ret 0
2025-04-04 21:40:27.120 653-679 PAL: Sessi...saCompress android.hardware.audio.service I setParameters: 2168: mixer set vol ctrl ramp status=0
2025-04-04 21:40:27.123 1395-20228 AGM: graph [email protected] D graph_set_config: 1104 entry graph_handle 0x47534c
2025-04-04 21:40:27.127 1395-20228 AGM: graph [email protected] D graph_set_config: 1112 exit, graph handle 0x47534c, ret 0
2025-04-04 21:40:27.128 653-679 PAL: Sessi...saCompress android.hardware.audio.service I setParameters: 2130: mixer set volume config status=0
2025-04-04 21:40:27.138 653-1453 PAL: ResourceManager android.hardware.audio.service I mixerEventWaitThreadLoop: 4700: Event Received COMPRESS105 event
2025-04-04 21:40:27.138 653-3540 PLUGIN: compress android.hardware.audio.service E agm_compress_event_cb: 217 agm_compress_event_cb: error: Invalid event params id: 134221887
2025-04-04 21:40:27.140 653-679 AHAL: AudioStream android.hardware.audio.service D Pause: 2286: Exit ret: 0
2025-04-04 21:40:27.154 725-9474 audioserver audioserver D logFgsApiEnd: FGS Logger Transaction failed, -129
2025-04-04 21:40:27.156 653-679 AHAL: AudioStream android.hardware.audio.service D out_update_source_metadata_v7: 1174: track count is 0 for usecase(4: compress-offload-playback)
2025-04-04 21:40:27.159 7865-9034 NearbyFastPair com.google.android.gms.persistent I (REDACTED) TriangleSessionTracker: flush media count=%s, media duration=%ss, call count=%s
2025-04-04 21:40:27.167 725-981 audioserver audioserver W Binder 0xf3a225c8 destroyed after setInheritRt before being parceled.
2025-04-04 21:40:27.167 725-981 audioserver audioserver W Binder 0xf3a225c8 destroyed after setMinSchedulerPolicy before being parceled.
2025-04-04 21:40:27.176 725-981 AudioFlinger audioserver W moveEffectChain_ll: effect chain for session 0 not on source thread 0xf2fde2a0
Sample 3 (with Event logger)
2025-04-04 22:35:35.990 10362-10362 EventLogger de.rpjosh.rpdb.testandroid D positionDiscontinuity [eventTime=2323.56, mediaPos=0.01, window=12, period=12, reason=AUTO_TRANSITION, PositionInfo:old [mediaItem=11, period=11, pos=220003], PositionInfo:new [mediaItem=12, period=12, pos=0]]
2025-04-04 22:35:36.001 10362-10362 EventLogger de.rpjosh.rpdb.testandroid D mediaItem [eventTime=2323.56, mediaPos=0.01, window=12, period=12, reason=AUTO]
2025-04-04 22:35:36.006 10362-10362 EventLogger de.rpjosh.rpdb.testandroid D tracks [eventTime=2323.57, mediaPos=0.02, window=12, period=12
2025-04-04 22:35:36.006 10362-10362 EventLogger de.rpjosh.rpdb.testandroid D group [
2025-04-04 22:35:36.007 10362-10362 EventLogger de.rpjosh.rpdb.testandroid D [X] Track:0, id=null, mimeType=audio/mpeg, container=audio/mpeg, bitrate=128000, channels=2, sample_rate=44100, supported=YES
2025-04-04 22:35:36.008 10362-10362 EventLogger de.rpjosh.rpdb.testandroid D ]
2025-04-04 22:35:36.008 10362-10362 EventLogger de.rpjosh.rpdb.testandroid D Metadata [
2025-04-04 22:35:36.009 10362-10362 EventLogger de.rpjosh.rpdb.testandroid D TXXX: description=major_brand: values=[isom]
2025-04-04 22:35:36.010 10362-10362 EventLogger de.rpjosh.rpdb.testandroid D TXXX: description=minor_version: values=[512]
2025-04-04 22:35:36.010 10362-10362 EventLogger de.rpjosh.rpdb.testandroid D TXXX: description=compatible_brands: values=[isomiso2mp41]
2025-04-04 22:35:36.011 10362-10362 EventLogger de.rpjosh.rpdb.testandroid D TSSE: description=null: values=[Lavf60.16.100]
2025-04-04 22:35:36.012 10362-10362 EventLogger de.rpjosh.rpdb.testandroid D ]
2025-04-04 22:35:36.012 10362-10362 EventLogger de.rpjosh.rpdb.testandroid D ]
2025-04-04 22:35:51.923 10362-10362 EventLogger de.rpjosh.rpdb.testandroid D isPlaying [eventTime=2339.49, mediaPos=15.65, window=12, period=12, true]
2025-04-04 22:35:51.961 10362-10552 DefaultAudioSink de.rpjosh.rpdb.testandroid W Spurious audio timestamp (frame position mismatch): 102234840, 23609042692, 23608967204, 2333166893, 105143040, 105116544
2025-04-04 22:35:52.158 10362-10362 EventLogger de.rpjosh.rpdb.testandroid D loading [eventTime=2339.73, mediaPos=16.20, window=12, period=12, false]
# Freeze happened here
2025-04-04 22:36:54.966 10362-10552 DefaultAudioSink de.rpjosh.rpdb.testandroid W Spurious audio timestamp (frame position mismatch): 105012631, 23672043008, 23672030637, 2396155351, 107686656, 107649792
2025-04-04 22:36:54.977 10362-10362 EventLogger de.rpjosh.rpdb.testandroid D rendererReady [eventTime=2402.55, mediaPos=78.93, window=12, period=12, rendererIndex=1, audio, false]
2025-04-04 22:36:54.981 725-10558 MonotonicFrameCounter audioserver W updateAndGetMonotonicFrameCount: retrograde newFrameCount:3635474 < mLastReceivedFrameCount:11066490, ignoring, returning 11066490 as frameCount
2025-04-04 22:36:54.982 653-679 AHAL: AudioStream android.hardware.audio.service D astream_pause: 564: pause
2025-04-04 22:36:54.982 653-679 AHAL: AudioStream android.hardware.audio.service I Pause: 2239: Enter: usecase(4: compress-offload-playback)
2025-04-04 22:36:54.984 1395-1409 AGM: graph [email protected] D graph_set_config: 1104 entry graph_handle 0x47534c
2025-04-04 22:36:54.987 1395-1409 AGM: graph [email protected] D graph_set_config: 1112 exit, graph handle 0x47534c, ret 0
2025-04-04 22:36:54.988 653-679 PAL: Sessi...saCompress android.hardware.audio.service I setParameters: 2168: mixer set vol ctrl ramp status=0
2025-04-04 22:36:54.990 1395-1409 AGM: graph [email protected] D graph_set_config: 1104 entry graph_handle 0x47534c
2025-04-04 22:36:54.993 1395-1409 AGM: graph [email protected] D graph_set_config: 1112 exit, graph handle 0x47534c, ret 0
2025-04-04 22:36:54.994 653-679 PAL: Sessi...saCompress android.hardware.audio.service I setParameters: 2130: mixer set volume config status=0
2025-04-04 22:36:55.011 653-1453 PAL: ResourceManager android.hardware.audio.service I mixerEventWaitThreadLoop: 4700: Event Received COMPRESS105 event
2025-04-04 22:36:55.011 653-3539 PLUGIN: compress android.hardware.audio.service E agm_compress_event_cb: 217 agm_compress_event_cb: error: Invalid event params id: 134221887
2025-04-04 22:36:55.012 653-679 AHAL: AudioStream android.hardware.audio.service D Pause: 2286: Exit ret: 0
2025-04-04 22:36:55.017 725-10558 audioserver audioserver D logFgsApiEnd: FGS Logger Transaction failed, -129
2025-04-04 22:36:55.023 653-679 AHAL: AudioStream android.hardware.audio.service D out_update_source_metadata_v7: 1174: track count is 0 for usecase(4: compress-offload-playback)
2025-04-04 22:36:55.030 7865-9034 NearbyFastPair com.google.android.gms.persistent I (REDACTED) TriangleSessionTracker: flush media count=%s, media duration=%ss, call count=%s
2025-04-04 22:36:55.030 725-981 audioserver audioserver W Binder 0xf3a222f8 destroyed after setInheritRt before being parceled.
2025-04-04 22:36:55.030 725-981 audioserver audioserver W Binder 0xf3a222f8 destroyed after setMinSchedulerPolicy before being parceled.
2025-04-04 22:36:55.044 725-981 AudioFlinger audioserver W moveEffectChain_ll: effect chain for session 0 not on source thread 0xf2fde760
2025-04-04 22:36:55.050 10362-10362 EventLogger de.rpjosh.rpdb.testandroid D state [eventTime=2402.62, mediaPos=78.93, window=12, period=12, BUFFERING]
2025-04-04 22:36:55.064 10362-10362 EventLogger de.rpjosh.rpdb.testandroid D isPlaying [eventTime=2402.64, mediaPos=78.93, window=12, period=12, false]
For additional context, I’ve attached the full unfiltered logcat with a 10-minute offset for sample 1. logcat.log
@microkatz I now get tons of report that Pixel watches 2 / 3 at least updated to the last Wear 6 reboots during playback with offload. Is this is known issue internally is there anything or places to report that for fix ? I have a bug report from one user.
@Tolriq
Could you please share that bugreport? If you cant share the bug report publicly, please send them to [email protected] with the subject Issue #1920
Sent.
See https://support.symfonium.app/t/wear-os-restarts-when-using-symfonium-for-some-time/11190 for some user details and just confirmed that disabling offload fixes the issue.
@microkatz does this one log the reboot ? All previous users did not answer the requests to provide bug reports, so if not it's best to ask this new user while he's still motivated :)
Thanks for asking!
The logs that ExoPlayer would care about like logcat would be wiped post reboot. Based on the device "rebooting" as you say and post OS update, I suspect this is an issue in the platform. Not sure what logs would be beneficial for them.
I'll submit a bug internally and see from there if they will still request the bug report if possible.
@Tolriq
I created the internal issue but it would greatly assist if you were able to provide a bug report. Thanks in advance!
@microkatz I did send the one the user gave me. see https://github.com/androidx/media/issues/1920#issuecomment-3496370361
@Tolriq
Thank you! After discussing with the relevant teams, apparently this issue has already been addressed and is in the next release, 6.1, which I believe is 25Q4. After the users' devices take in that next update then it should no longer be a problem. Thanks for your patience!
Thanks, I've pushed a build with offload disabled anyway due to the initial issue still more or less present.
@microkatz 6.1 is up, the watch no more restart, but the initial issue is still present.