Server Version#: 1.21.2.3918-e47113e83
Player Version#: 8.11.0.22186
Hello all, as the title mentions, the Android played cannot play a m4b audiobook when quality is set at “Original” but has no problem playing the file when quality is set at 320kbps. The error reported is “An error occurred while playing this item.” Here are the logs:
01-21 21:12:07.470 i: [OneApp] User can execute command without restrictions because they are entitled.
01-21 21:12:07.472 i: [PlayQueues] Creating delayed remote PQ.
01-21 21:12:07.486 i: [MediaBrowserAudioService] onCreate
01-21 21:12:07.486 i: [PlayerService] onCreate
01-21 21:12:07.488 i: [ConnectivityManager] Device is under Wifi
01-21 21:12:07.488 i: [Player] Changing to use Treble for playback.
01-21 21:12:07.491 i: [NetworkTypeMonitor] Starting to monitor
01-21 21:12:07.504 i: [Player][Treble] onAudioQueueSessionOptionsChanged
01-21 21:12:07.505 i: [Player][Treble] onAudioQueueSessionOptionsChanged
01-21 21:12:07.506 i: [Player][Treble] onRuntimeSessionOptionsChanged
01-21 21:12:07.506 i: [Player][Treble] onRuntimeSessionOptionsChanged
01-21 21:12:07.506 i: [MemoryOptimisationBehaviour] Reducing memory cache.
01-21 21:12:07.507 i: [Player][Treble] onRuntimeSessionOptionsChanged
01-21 21:12:07.513 i: [MediaSessionHelper] Starting media session with tag: music
01-21 21:12:07.513 i: [MediaSessionHelper] Creating media session with tag: music
01-21 21:12:07.522 i: [MediaSessionBehaviour] Updating metadata for music, thumb: false
01-21 21:12:07.523 i: [CurrentItemMetadataBehaviour] Fetching current item
01-21 21:12:07.523 i: Fetching [method:GET] https://.plex.direct:/library/metadata/553222?includeChapters=1&includeLoudnessRamps=1&includeMarkers=1&includeRelated=1&X-Plex-Token=…qrej
01-21 21:12:07.526 i: [Player][Treble] onRuntimeSessionOptionsChanged
01-21 21:12:07.527 i: [Treble]: BASS: Resume.
01-21 21:12:07.527 w: [Treble]: BASS: Can’t resume, no current stream.
01-21 21:12:07.527 i: [Player][Treble] Adding both current and next track, audio queue length: 0
01-21 21:12:07.527 i: [Treble]: BASS: Stop.
01-21 21:12:07.527 i: [Treble]: Play Queue: Clearing.
01-21 21:12:07.537 i: [MediaSessionBehaviour] Updating metadata for music, thumb: true
01-21 21:12:07.539 i: [MediaBrowserAudioService] Rebuilding…
01-21 21:12:07.548 i: Fetching [method:GET] https://.plex.direct:/library/metadata/553222?X-Plex-Token=…qrej
01-21 21:12:07.548 i: Creating PlayerActivity.
01-21 21:12:07.548 i: [Activity] Resuming the application, attempting to download item and children.
01-21 21:12:07.553 i: [Boot] PlayerActivity took 3ms to run create behaviours.
01-21 21:12:07.554 i: [PlayerActivity] Creating fragment
01-21 21:12:07.557 i: [Player][DimensionsLayout] Resizing: 100 x 100
01-21 21:12:07.561 i: [ConnectivityManager] Device is under Wifi
01-21 21:12:07.583 i: [MenuSheetHud] Item changed (and fetched), invalidating settings…
01-21 21:12:07.595 i: [CurrentItemMetadataBehaviour] Fetched current item, success: true
01-21 21:12:07.600 i: [MenuSheetHud] Item changed (and fetched), invalidating settings…
01-21 21:12:07.617 i: [Player][Treble] onRuntimeSessionOptionsChanged
01-21 21:12:07.618 i: [Treble]: BASS: Resume.
01-21 21:12:07.618 w: [Treble]: BASS: Can’t resume, no current stream.
01-21 21:12:07.631 i: Resuming PlayerActivity.
01-21 21:12:07.656 i: [Player][View] Layout has been measured with a size of 1080 x 2218 (1080 x 2218).
01-21 21:12:07.670 i: [SystemUIBehaviour] Showing the system user-interface.
01-21 21:12:07.680 i: [Player][View] Layout has been measured with a size of 1080 x 2340 (1080 x 2340).
01-21 21:12:07.727 i: [Player][Treble] Adding both current and next track, audio queue length: 0
01-21 21:12:07.730 i: [Treble]: BASS: Stop.
01-21 21:12:07.730 i: [Treble]: Play Queue: Clearing.
01-21 21:12:07.741 i: Fetching [method:GET] https://.plex.direct:/library/metadata/553222?X-Plex-Token=…qrej
01-21 21:12:07.774 i: [MediaBrowserAudioService] onCreate
01-21 21:12:07.778 i: [MediaBrowserAudioService] Rebuilding…
01-21 21:12:07.797 i: [Treble]: BASS: Resuming audio output (started: 1)
01-21 21:12:07.797 w: [Treble]: BASS: Mixer underflowed.
01-21 21:12:07.798 i: [Treble]: Play Queue: Set item Delay–1970837016 active to 1, 1 active remaining.
01-21 21:12:07.798 i: [Treble]: BASS: Queueing stream (1 total, 1 handles) with identifier Delay–1970837016, gain nan dB, overlap duration 0 ms, start offset 0 ms (paused: 0).
01-21 21:12:07.798 i: [Treble]: Play Queue: Setting current item to Delay–1970837016.
01-21 21:12:07.799 i: [Player][Treble] Finished queing item Delay–1970837016.
01-21 21:12:07.799 i: [Player][Treble] State (transcoding: false codec: bitrate: 0)
01-21 21:12:07.799 i: [Treble]: BASS: Opening stream Delay–1970837016.
01-21 21:12:07.799 i: [EngineEventManager] onBufferingStarted (isSeeking: false)
01-21 21:12:07.799 i: [Player][Timeline] Playback started (or buffering), scheduling updates
01-21 21:12:07.800 i: [Treble]: Cache: Opened cache file with 262144 bytes (of 2407240772 total) at ‘/data/user/0/com.plexapp.android/cache/Treble/Library/Caches/Media/1eb91b9f1d46c743c1f51d01ac19f25fb59575111c571637a536bd1f7b49de62’.
01-21 21:12:07.800 i: [Treble]: Media: Found an item to direct play with bitrate under 2147483647 (it was 352 kbps).
01-21 21:12:07.800 i: [Treble]: Cache: Opened cache file with 262144 bytes (of 2407240772 total) at ‘/data/user/0/com.plexapp.android/cache/Treble/Library/Caches/Media/1eb91b9f1d46c743c1f51d01ac19f25fb59575111c571637a536bd1f7b49de62’.
01-21 21:12:07.801 i: [Treble]: Cache: Using RAM buffer of 2048 KB for item with bitrate of 44 KB/sec.
01-21 21:12:07.801 i: [Treble]: Cache: Buffering until offset reaches 225280 (read buffer offset: 0, size: 225280).
01-21 21:12:07.802 i: [Treble]: Cache: Opened file: https://.plex.direct:/library/parts/27089896/1610757042/file.m4b?download=1&X-Plex-Client-Identifier=58d14193d652470e-com-plexapp-android&X-Plex-Device=ONEPLUS%20A6013&X-Plex-Device-Name=ONEPLUS%20A6013&X-Plex-Platform=Android&X-Plex-Platform-Version=11&X-Plex-Product=Plex%20for%20Android%20(Mobile)&X-Plex-Token=…qrej&X-Plex-Version=8%2E11%2E0%2E22186
01-21 21:12:07.802 i: [Treble]: Cache: Kicking off buffering thread at offset 0, disk cache has 262144 / 2407240772.
01-21 21:12:07.802 i: [Treble]: Cache: Adjusted offset to 262144 to compensate for disk cache, we’re still missing 2406978628 bytes.
01-21 21:12:07.809 i: [MediaSessionHelper] Releasing media session with tag: music
01-21 21:12:07.813 i: [MediaBrowserAudioService] onCreate
01-21 21:12:07.815 i: [MediaSessionHelper] Starting media session with tag: music
01-21 21:12:07.815 i: [MediaSessionHelper] Creating media session with tag: music
01-21 21:12:07.821 i: [MediaBrowserAudioService] Rebuilding…
01-21 21:12:07.851 i: [MediaBrowserAudioService] Obtaining root.
01-21 21:12:07.853 i: [MediaBrowserAudioService] onLoadChildren, parentId=ROOT
01-21 21:12:07.853 i: [MediaBrowserAudioServiceProvider] Retrieving: ROOT
01-21 21:12:07.853 i: [MediaBrowserAudioServiceProvider] Clearing image cache
01-21 21:12:07.853 i: [MediaBrowserAudioServiceProvider] Providers not ready, fetching them…
01-21 21:12:07.853 i: [MediaBrowserAudioServiceProvider] Providers are ready, adding them…
01-21 21:12:07.854 i: [MediaBrowserAudioServiceProvider] Filling providers and root entries
01-21 21:12:07.855 i: [MediaBrowserAudioServiceProvider] Adding music entry
01-21 21:12:07.855 i: [MediaBrowserAudioServiceProvider] Adding podcasts entry
01-21 21:12:07.855 i: [MediaBrowserAudioServiceProvider] Clearing image cache
01-21 21:12:07.855 i: [MediaBrowserAudioServiceProvider] Adding 1 root items from content provider
01-21 21:12:07.856 i: [MediaBrowserAudioServiceProvider] Adding 1 root items from content provider
01-21 21:12:07.856 i: [MediaBrowserAudioServiceProvider] Returning 2 root items
01-21 21:12:07.857 i: [MediaBrowserAudioService] Retrieved [MediaItem{mFlags=1, mDescription=Music, , null}, MediaItem{mFlags=1, mDescription=Podcasts, , null}] for parentId=ROOT
01-21 21:12:07.858 i: [MediaSessionHelper] Releasing media session with tag: music
01-21 21:12:08.080 i: [Treble]: Cache: HTTP response code was 206.
01-21 21:12:08.080 i: [Treble]: Cache: HTTP response total size was 2147483647.
01-21 21:12:08.134 i: [Treble]: Cache: Network buffer is now ahead of read buffer, which has 0 bytes. Godspeed.
01-21 21:12:08.135 i: [Treble]: Cache: Buffering complete as offset is now greater than 225280 (278528) and read completed: 0.
01-21 21:12:08.137 i: [Treble]: Cache: Asked to seek to offset 2396801565 with read buffer offset at 4096.
01-21 21:12:08.137 i: [Treble]: Cache: That sucks, total cache fail on seek. Such is life.
01-21 21:12:08.160 i: [Treble]: Cache: Ending network read thread.
01-21 21:12:08.165 i: [Treble]: Cache: Buffering until offset reaches 2397026845 (read buffer offset: 2396801565, size: 225280).
01-21 21:12:08.165 i: [Treble]: BASS: Stream Delay–1970837016 (channel 0x00000000) changed buffering state to 1.
01-21 21:12:08.165 i: [Treble]: Cache: Kicking off buffering thread at offset 2396801565, disk cache has 278528 / 2407240772.
01-21 21:12:08.167 i: [Treble]: Cache: We’ve been asked to buffer a disjoint region, we’ll just stream from network.
01-21 21:12:08.427 i: [Treble]: Cache: HTTP response code was 206.
01-21 21:12:08.428 i: [Treble]: Cache: HTTP response total size was 10439207.
01-21 21:12:08.472 i: [Treble]: Cache: Asked to seek to offset 2407192974 with read buffer offset at 2396805661.
01-21 21:12:08.473 i: [Treble]: Cache: That sucks, total cache fail on seek. Such is life.
01-21 21:12:08.473 i: [Treble]: Cache: Ending network read thread.
01-21 21:12:08.482 i: [Treble]: Cache: Buffering until offset reaches 2407240772 (read buffer offset: 2407192974, size: 47798).
01-21 21:12:08.484 i: [Treble]: Cache: Kicking off buffering thread at offset 2407192974, disk cache has 278528 / 2407240772.
01-21 21:12:08.484 i: [Treble]: Cache: We’ve been asked to buffer a disjoint region, we’ll just stream from network.
01-21 21:12:08.704 i: [Treble]: Cache: HTTP response code was 206.
01-21 21:12:08.705 i: [Treble]: Cache: HTTP response total size was 47798.
01-21 21:12:08.750 i: [Treble]: Cache: Asked to seek to offset 2407240629 with read buffer offset at 2407197070.
01-21 21:12:08.752 i: [Treble]: Cache: Failing a seek to the end.
01-21 21:12:08.753 i: [Treble]: Cache: Asked to seek to offset 2407240762 with read buffer offset at 2407197070.
01-21 21:12:08.753 i: [Treble]: Cache: Failing a seek to the end.
01-21 21:12:08.755 i: [Treble]: Cache: Asked to seek to offset 0 with read buffer offset at 2407197070.
01-21 21:12:08.755 i: [Treble]: Cache: Using the disk cache (278528 bytes / 2407240772 bytes) to fill in a seek, this is good.
01-21 21:12:08.757 i: [Treble]: Cache: Ending network read thread.
01-21 21:12:08.766 i: [Treble]: Cache: Buffering until offset reaches 225280 (read buffer offset: 0, size: 225280).
01-21 21:12:08.767 i: [Treble]: Cache: Kicking off buffering thread at offset 278528, disk cache has 278528 / 2407240772.
01-21 21:12:09.009 i: [Treble]: Cache: HTTP response code was 206.
01-21 21:12:09.010 i: [Treble]: Cache: HTTP response total size was 2147483647.
01-21 21:12:09.053 i: [Treble]: Cache: Network buffer is now ahead of read buffer, which has 0 bytes. Godspeed.
01-21 21:12:09.054 i: [Treble]: Cache: Buffering complete as offset is now greater than 225280 (294912) and read completed: 0.
01-21 21:12:09.055 i: [Treble]: BASS: Stream Delay–1970837016 (channel 0x00000000) changed buffering state to 0.
01-21 21:12:09.056 i: [Treble]: Cache: Asked to seek to offset 5100 with read buffer offset at 16000.
01-21 21:12:09.057 i: [Treble]: Cache: Yay, seek was inside read buffer.
01-21 21:12:09.058 i: [Treble]: Cache: Asked to seek to offset 15416 with read buffer offset at 48768.
01-21 21:12:09.059 i: [Treble]: Cache: Yay, seek was inside read buffer.
01-21 21:12:09.060 i: [Treble]: Cache: Asked to seek to offset 0 with read buffer offset at 19512.
01-21 21:12:09.060 i: [Treble]: Cache: Yay, seek was inside read buffer.
01-21 21:12:09.061 i: [Treble]: Cache: Asked to seek to offset 18446744071811385885 with read buffer offset at 4096.
01-21 21:12:09.062 i: [Treble]: Cache: That sucks, total cache fail on seek. Such is life.
01-21 21:12:09.075 i: [Treble]: Cache: Ending network read thread.
01-21 21:12:09.084 i: [Treble]: Cache: Buffering until offset reaches 18446744071811611165 (read buffer offset: 18446744071811385885, size: 225280).
01-21 21:12:09.085 i: [Treble]: Cache: Asked to seek to offset 0 with read buffer offset at 18446744071811385885.
01-21 21:12:09.086 i: [Treble]: BASS: Stream Delay–1970837016 (channel 0x00000000) changed buffering state to 1.
01-21 21:12:09.086 i: [Treble]: Cache: Kicking off buffering thread at offset 18446744071811385885, disk cache has 294912 / 2407240772.
01-21 21:12:09.086 i: [Treble]: Cache: Using the disk cache (294912 bytes / 2407240772 bytes) to fill in a seek, this is good.
01-21 21:12:09.086 i: [Treble]: Cache: We’ve been asked to buffer a disjoint region, we’ll just stream from network.
01-21 21:12:09.086 i: [Treble]: Cache: Buffering until offset reaches 225280 (read buffer offset: 0, size: 225280).
01-21 21:12:09.318 i: [Treble]: Cache: Network error (416) occurred, we might want to kick off recovery (still 0 bytes in network buffer).
01-21 21:12:09.442 e: [Treble]: BASS: Error [ret = BASS_StreamCreateFileUser((DWORD)STREAMFILE_NOBUFFER, flags, &proc, context)] - 41
01-21 21:12:09.444 e: [Treble]: BASS: Opening stream Delay–1970837016 failed. Sad.
01-21 21:12:09.444 i: [Treble]: Cache: Buffering complete as offset is now greater than 225280 (262144) and read completed: 0.
01-21 21:12:09.445 i: [Treble]: BASS: Stream Delay–1970837016 (channel 0x00000000) changed buffering state to 0.
01-21 21:12:09.448 i: [Player][Timeline] Handling player error
01-21 21:12:09.448 i: [Player][Timeline] Playback stopped (error: true)
01-21 21:12:09.448 i: [Player][Timeline] Player error not known by server, reporting original player error (or a playback interrupted one)
01-21 21:12:09.448 i: [Player] Error reported: TransientError (null)
01-21 21:12:09.449 i: [Player][Timeline] Playback stopped (error: false)
01-21 21:12:09.465 i: Showing toast: An error occurred while playing this item.
01-21 21:12:09.482 i: [EngineEventManager] onBufferingEnded
01-21 21:12:09.484 i: [EngineEventManager] onPlaybackStopped: Completed
01-21 21:12:09.485 i: [Player][Timeline] Playback stopped (error: false)
01-21 21:12:09.485 i: [PlaybackTimeBehaviour] Time: 0 IsStarted: false
01-21 21:12:09.486 i: [PlayQueueProgressBehaviour] Updating PlayQueueManager state, isPlaying: false
01-21 21:12:09.486 i: [PlayQueueProgressBehaviour] Last item in PlayQueue completed.
01-21 21:12:09.487 i: [Player][Treble] Destroying engine
01-21 21:12:09.487 i: [Treble]: BASS: Stop.
01-21 21:12:09.487 i: [Treble]: Play Queue: Clearing.
01-21 21:12:09.488 i: [Treble]: BASS: Asked to remove stream with identifier Delay–1970837016 with 1 existing streams (fade: 1, kickOffNext: 0).
01-21 21:12:09.488 i: [Treble]: Play Queue: Set item Delay–1970837016 active to 0, 0 active remaining.
01-21 21:12:09.489 i: [Treble]: BASS: Removed stream Delay–1970837016 from position 0, there are now 0 streams.
01-21 21:12:09.489 i: [Treble]: Cache: Asked to close file.
01-21 21:12:09.539 i: [Treble]: Connection Tester: success for http://:!
01-21 21:12:09.580 i: [Treble]: Cache: Ending network read thread.
01-21 21:12:09.582 i: [Treble]: Cache: Deleting file reader 0x72013572e8
01-21 21:12:09.582 i: [NetworkTypeMonitor] Stopping monitoring
01-21 21:12:09.589 i: [MemoryOptimisationBehaviour] Expanding memory cache.
01-21 21:12:09.590 i: [AudioFocusBehaviour] Behaviour being destroyed, giving up audio focus
01-21 21:12:09.635 i: [WiFiLockBehaviour] Releasing WiFi lock since playback was stopped.
01-21 21:12:09.643 i: [BatteryMonitorBehaviour] Playback session was 11146.6 minutes long.
01-21 21:12:09.644 i: [BatteryMonitorBehaviour] Average battery consumption was -160.95 µAh per minute.
01-21 21:12:09.703 i: [PlayerService] onDestroy
01-21 21:12:09.727 i: Resuming PreplayActivity.
I’ve removed some sensitive information. Have any of you received this error? Is this a bug with the Android player or is there something else going on?
