Erroneous onPlaybackStatsReady calls when changing playlist

[vfsfitvnm]

Media3 Version

1.0.0-beta02

Devices that reproduce the issue

Devices that do not reproduce the issue

No response

Reproducible in the demo app?

Yes

Reproduction steps

Let's consider the following playlist:

0. A
[...]
497. B
498. C
499. D

And the following onPlaybackStatsReady:

override fun onPlaybackStatsReady(eventTime: AnalyticsListener.EventTime, playbackStats: PlaybackStats) {
    val mediaItem = eventTime.timeline.getWindow(eventTime.windowIndex, Timeline.Window()).mediaItem
    val totalPlayTimeMs = playbackStats.totalPlayTimeMs

    println("${mediaItem.mediaId} played for ${totalPlayTimeMs}ms")
}

Case 1

1. Play B
2. Change playlist

Case 2

1. Play B
2. Play C
3. Play D
4. Change playlist

Expected result

Case 1

B played for 1000ms

Case 2

B played for 1000ms
C played for 1000ms
D played for 1000ms

Actual result

Case 1

B played for 1000ms
A played for 1000ms

Case 2

B played for 1000ms
C played for 1000ms
D played for 1000ms
A played for 2996ms

Media

Not applicable

Bug Report

• You will email the zip file produced by adb bugreport to dev.exoplayer@gmail.com after filing this issue.

[vfsfitvnm]

device-2022-10-05-190902.mp4

[tonihei]

Could you clarify what you mean by "Change playlist" in your instructions? It seems "A" is never played in the reproduction steps, so it's not entirely clear why you expect a callback for this media item.

Note that the onPlaybackStatsReady is only called once an item definitely finished playing, so maybe it just happens later than you expect it happen?

[vfsfitvnm]

After submitting the issue I realized I put the "expected result" as "actual result" as vice versa - and I quickly edited the message. However I think you still read the original message (via e-mail maybe) - however yes, "A" is never played and so I do not expect a callback to be called for such media item.

But as you can see from the screen recording, the callback for "A" occurs.

For "changing playlist" I meant calling player.setMediaItems(...) (this is what happens in demo-session).

[vfsfitvnm]

To add more, playing around with playlist changes, I can see suspicious calls for the first media item of the just-replaced playlist with playbackStats.totalPlayTimeMs equals to zero.

[tonihei]

I can reproduce what you are seeing, but it looks as if everything is working as intended.

PlayableFolderActivity in the session demo app calls:

browser.setMediaItems(subItemMediaList)
browser.seekToDefaultPosition(/* mediaItemIndex= */ position)

The first method will start playback with the first item in the list, the second call will update the position to the item you tapped. So the PlaybackStatsListener correctly tracks 0 play time for the first item in the list as it was briefly the active item.

To actually avoid the issue, the PlayableFolderActivity should set the item list and the start position in one command. I'm going to update the code accordingly.

browser.setMediaItems(subItemMediaList, /* startIndex= */ position, /* startPositionMs= */ C.TIME_UNSET)

[vfsfitvnm]

That's what I thought too, but I swear I couldn't find such setMediaItems overload. This solves the original issue!

However, I still find odd that onPlaybackStatsReady (having the first mediaItem of the playlist) is called with totalPlayTimeMs not equal to zero. It looks like the playback time counter keeps running with these calls:

browser.setMediaItems(subItemMediaList)
browser.seekToDefaultPosition(/* mediaItemIndex= */ position)

[tonihei]

It was always zero in my tests. Can you describe a specific sequence of item selections that cause the additional problem of keeping the counter running? And also, where exactly did you add/remove/replace the PlaybackStatsListener?

[vfsfitvnm]

Here's the fork which reproduces the issue: https://github.com/vfsfitvnm/media

Steps to reproduce:

1. Album folder > Jazz & Blues > (scroll all the way down) The Messenger
2. Let the music play for few seconds
3. Play any other playlist - i.e. Album folder > Irsen's Tale > Leaving

[tonihei]

Thanks for the helpful reproduction steps. This is indeed a bug in our session tracking that happens only for the case where we seek very quickly to a new item before the current one got the chance to update its internal state. We'll provide a fix for this as well.

[tonihei]

Issue was fixed by the commits above.