Songs randomly stop playing right before the end

[acroyear]

Ok, so here's the technical details, based on my experience in SubFire noticed from a 'bug' in the Android audio player that Chromium didn't fix until release 52 (Amazon Silk is at 52, but Amazon's WebView for the app tester and any apps is still at 49).

The fixed-bitrate MP3 format does not actually give its real duration. It doesn't. There is NOTHING in the file format to do that.

VARIABLE bitrate files DO have a tag that gives the duration, but Constant does not.

When an ac3 or flac is transcoded, it is transcoded at a constant bit rate. This means that the audio tag has not received a REAL "range" that tells it exactly when the file has or will end. So it guesses, based on the numbers it has. And it gets it wrong. inevitably, because compression is inconsistent.

But if you had VBR mp3s (like what Amazon and Google Play sell), everything is fine, because the html5 audio tag can find the particular value in VBR that tells it the real duration.

As for SubFire on several platforms (Android Chrome < 52, IE <= 11, FFX < 36 or so, I forget it was so long ago), that's where the bug comes into play. If the audio tag can't get the duration, for CBR files, it often doesn't get the 'current time' value either. I literally do not get updates as the audio tag plays on those platforms. My only way to guess when to end the track and move on to the next one is just that, a guess. I start a second-counter right away, and update to that. When the second-counter has passed the duration that SubSonic reported in the song from the API, I stop and move on (ok, I pad it 2 seconds just in case). That literally is all I can do. And it took me months to get it as good as it is under those circumstances.

So yeah, what you're really dealing with are bugs in the audio tag, combined with the fact that transcoding, or 'streaming' effectively, can't give an accurate Range: header in response to the audio tag's Range: request, because it hasn't finished transcoding the whole file in order to know exactly how many bytes are going to be in it. in the case of the broken browsers dealing with normal CBR mp3s (like Amazon Fire), the audio tag isn't sending the Range: request appropriately. In other cases, it is the fact that it is transcoding on the fly that means the Range: response is inconsistent. Those broken audio tags often don't send a "audio ended" event either, which is another reason i've needed to write all this 'guessing' code for those platforms...but what it means is that if because of buffering or network issues, if a file doesn't start playing right away, my timer is off by the real thing by a number of seconds...so yeah, i can end earlier than I should.

So yeah, it all comes down to the fact that an mp3 file actually has no idea how long it is. it really has no clue. the mp3 format wasn't designed for that - it was designed for streaming and for compression of the audio to go along with video, where the container of the video file would have the duration details so the audio layer didn't need to care...thus it became an oversight when the mp3 file was actually created.

[Deviant0ne]

Regardless of the FLAC -> MP3 bit-rate issues, transcoding worked in previous versions of Subsonic and now it's broken.

Does anyone know how to submit a bug request to the developers? I can't find anything online and this issue is really starting to drive me crazy.

Also, I'm assuming since this is a transcoding issue, this won't help but since Google Chrome is able to natively play OGG files, shouldn't Subsonic be able to transcode FLAC to OGG using

Code: Select all

oggenc -Q -q 7 -o /dev/stdout %s

? I can't get this to play for the life of me.

EDIT: found an official bug request here: https://sourceforge.net/p/subsonic/bugs/175/

[mortiiscof]

I'm having similar issues since upgrading to the latest (this didn't happen previously). I don't think it is encoding (although maybe my issue is different). What I notice is that FireFox is dynamically loading the song chunk by chunk (instead of pulling the whole stream it is pulling, say, 1:30 at a time). I'm guessing this is a feature added to ensure a song can start playing before the whole song is downloaded. What is happening is the player is getting to the "end" of the song (I quote this as in some songs it isn't pulling the full song but will stop at 2:24/2:30 but in actuality the song is 3:34 in length) and instead of loading more chunks it freezes. This doesn't trigger the "next" track either (or the rest of the current song!).

I think there must be a logic flaw in this new lazy loading feature where it is not being triggered to download the rest of the song.

I'll try to pull some logs from my server when I get a chance.

[mortiiscof]

Playing Snow by RHCP... song loads 2:06 of a 5:38 length song. When it got to 2:06 it loaded to 2:09 then 2:28 then 2:41. When it got to 2:41 it STOPS.

At the other time marks it triggered an update and loaded more... I'm not sure why it failed to do so at 2:41.

Now if I start the song over, and CLICK at 2:05 it loads a big chunk, then CLICK ahead to the new endpoint and it loads more (the full 5:32 in length). Then I can start the song from the beginning and it'll

Full log of this interaction:

First run failure at 2:41:
[brace01@crunchygrooves /var/subsonic]$ less subsonic.log
[2018-02-23 13:16:15,829] INFO HsqlDaoHelper - Checking database schema.
[2018-02-23 13:16:17,278] INFO HsqlDaoHelper - Done checking database schema.
[2018-02-23 13:16:17,346] INFO SettingsService - Java: 1.8.0_131, OS: FreeBSD
[2018-02-23 13:16:17,351] INFO VersionService - Resolved local Subsonic version to: 6.1.3
[2018-02-23 13:16:17,593] INFO MediaScannerService - Automatic media library scanning scheduled to run every 1 day(s), starting at Sat Feb 24 03:00:00 EST 2018
[2018-02-23 13:16:17,654] INFO UPnPService - Starting UPnP service...
[2018-02-23 13:16:17,676] INFO PodcastService - Automatic Podcast update scheduled to run every 24 hour(s), starting at Fri Feb 23 13:21:17 EST 2018
[2018-02-23 13:16:17,696] INFO UPnPService - Disabling UPnP/DLNA media server
[2018-02-23 13:16:17,697] INFO UPnPService - Starting UPnP service - Done!
[2018-02-23 13:16:25,717] INFO SonosService - No Sonos controller found
[2018-02-23 13:16:26,949] INFO BootstrapVerificationFilter - Servlet container: jetty-6.1.x
[2018-02-23 13:16:27,876] WARN NetworkService - No UPnP router found.
[2018-02-23 13:16:46,233] INFO VersionService - Resolved latest Subsonic final version to: 6.1.3
[2018-02-23 13:16:46,233] INFO VersionService - Resolved latest Subsonic beta version to: 6.1.beta2
[2018-02-23 13:17:10,114] INFO TranscodeInputStream - Starting transcoder: /var/subsonic/transcode/ffmpeg -loglevel debug -i /var/music/Red Hot Chili Peppers/2006 - Stadium Arcadium - Disc 1/2 - Red Hot Chili Peppers - Snow (Hey Oh).m4a -map 0:0 -b:a 320k -v 0 -f mp3 -
[2018-02-23 13:17:10,143] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) ffmpeg version 3.3 Copyright (c) 2000-2017 the FFmpeg developers
[2018-02-23 13:17:10,143] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) built with FreeBSD clang version 3.4.1 (tags/RELEASE_34/dot1-final 208032) 20140512
[2018-02-23 13:17:10,143] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) configuration: --prefix=/usr/local --mandir=/usr/local/man --datadir=/usr/local/share/ffmpeg --pkgconfigdir=/usr/local/libdata/pkgconfig --enable-shared --enable-pic --enable-gpl --enable-postproc --enable-avfilter --enable-avresample --enable-pthreads --cc=cc --disable-indev=alsa --disable-outdev=alsa --disable-libopencore-amrnb --disable-libopencore-amrwb --disable-libass --disable-libbs2b --disable-libcaca --enable-libcdio --enable-libcelt --disable-chromaprint --disable-libdc1394 --disable-stripping --enable-htmlpages --enable-libfdk-aac --disable-ffserver --disable-libflite --disable-fontconfig --disable-libfreetype --enable-frei0r --disable-libfribidi --disable-libgme --enable-libgsm --enable-iconv --enable-libilbc --disable-indev=jack --enable-libkvazaar --enable-ladspa --enable-libmp3lame --disable-libbluray --enable-mmx --disable-libmodplug --disable-netcdf --enable-openal --disable-opencl --enable-libopencv --enable-opengl --enable-libopenh264 --enable-libopenjpeg --enable-optimizations --enable-libopus --disable-libpulse --disable-indev=pulse --disable-outdev=pulse --enable-runtime-cpudetect --disable-librubberband --enable-libschroedinger --enable-ffplay --disable-libsmbclient --enable-libsnappy --disable-libsoxr --disable-libspeex --enable-sse --disable-libssh --disable-libtesseract --enable-libtheora --enable-libtwolame --enable-libv4l2 --enable-vaapi --enable-vdpau --disable-libvidstab --enable-libvorbis --disable-libvo-amrwbenc --enable-libvpx --enable-libwavpack --disable-libwebp --enable-libx264 --enable-libx265 --enable-libxcb --enable-libxvid --enable-libzimg --disable-libzmq --disable-libzvbi --disable-gcrypt --enable-gmp --disable-librtmp --enable-gnutls --disable-openssl --enable-version3 --enable-nonfree
[2018-02-23 13:17:10,143] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) libavutil 55. 58.100 / 55. 58.100
[2018-02-23 13:17:10,143] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) libavcodec 57. 89.100 / 57. 89.100
[2018-02-23 13:17:10,144] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) libavformat 57. 71.100 / 57. 71.100
[2018-02-23 13:17:10,144] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) libavdevice 57. 6.100 / 57. 6.100
[2018-02-23 13:17:10,144] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) libavfilter 6. 82.100 / 6. 82.100
[2018-02-23 13:17:10,144] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) libavresample 3. 5. 0 / 3. 5. 0
[2018-02-23 13:17:10,144] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) libswscale 4. 6.100 / 4. 6.100
[2018-02-23 13:17:10,144] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) libswresample 2. 7.100 / 2. 7.100
[2018-02-23 13:17:10,144] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) libpostproc 54. 5.100 / 54. 5.100
[2018-02-23 13:17:10,144] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) Splitting the commandline.
[2018-02-23 13:17:10,144] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) Reading option '-loglevel' ... matched as option 'loglevel' (set logging level) with argument 'debug'.
[2018-02-23 13:17:10,144] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) Reading option '-i' ... matched as input url with argument '/var/music/Red Hot Chili Peppers/2006 - Stadium Arcadium - Disc 1/2 - Red Hot Chili Peppers - Snow (Hey Oh).m4a'.
[2018-02-23 13:17:10,144] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) Reading option '-map' ... matched as option 'map' (set input stream mapping) with argument '0:0'.
[2018-02-23 13:17:10,144] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) Reading option '-b:a' ... matched as option 'b' (video bitrate (please use -b:v)) with argument '320k'.
[2018-02-23 13:17:10,144] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) Reading option '-v' ... matched as option 'v' (set logging level) with argument '0'.
[2018-02-23 13:17:10,144] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) Reading option '-f' ... matched as option 'f' (force format) with argument 'mp3'.
[2018-02-23 13:17:10,144] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) Reading option '-' ... matched as output url.
[2018-02-23 13:17:10,144] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) Finished splitting the commandline.
[2018-02-23 13:17:10,144] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) Parsing a group of options: global .
[2018-02-23 13:17:10,144] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) Applying option loglevel (set logging level) with argument debug.
[2018-02-23 13:17:10,144] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) Applying option v (set logging level) with argument 0.
[2018-02-23 13:21:17,843] INFO PodcastService - Starting scheduled Podcast refresh.
[2018-02-23 13:21:17,843] INFO PodcastService - Completed scheduled Podcast refresh.


With CLICKS to load the whole song:
[2018-02-23 13:25:09,815] INFO HsqlDaoHelper - Checking database schema.
[2018-02-23 13:25:11,504] INFO HsqlDaoHelper - Done checking database schema.
[2018-02-23 13:25:11,554] INFO SettingsService - Java: 1.8.0_131, OS: FreeBSD
[2018-02-23 13:25:11,558] INFO VersionService - Resolved local Subsonic version to: 6.1.3
[2018-02-23 13:25:11,770] INFO MediaScannerService - Automatic media library scanning scheduled to run every 1 day(s), starting at Sat Feb 24 03:00:00 EST 2018
[2018-02-23 13:25:11,801] INFO UPnPService - Starting UPnP service...
[2018-02-23 13:25:11,826] INFO PodcastService - Automatic Podcast update scheduled to run every 24 hour(s), starting at Fri Feb 23 13:30:11 EST 2018
[2018-02-23 13:25:11,842] INFO UPnPService - Disabling UPnP/DLNA media server
[2018-02-23 13:25:11,842] INFO UPnPService - Starting UPnP service - Done!
[2018-02-23 13:25:17,116] INFO BootstrapVerificationFilter - Servlet container: jetty-6.1.x
[2018-02-23 13:25:19,888] INFO SonosService - No Sonos controller found
[2018-02-23 13:25:21,840] WARN NetworkService - No UPnP router found.
[2018-02-23 13:28:05,671] INFO TranscodeInputStream - Starting transcoder: /var/subsonic/transcode/ffmpeg -loglevel debug -i /var/music/Red Hot Chili Peppers/2006 - Stadium Arcadium - Disc 1/2 - Red Hot Chili Peppers - Snow (Hey Oh).m4a -map 0:0 -b:a 320k -v 0 -f mp3 -
[2018-02-23 13:28:05,698] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) ffmpeg version 3.3 Copyright (c) 2000-2017 the FFmpeg developers
[2018-02-23 13:28:05,698] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) built with FreeBSD clang version 3.4.1 (tags/RELEASE_34/dot1-final 208032) 20140512
[2018-02-23 13:28:05,698] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) configuration: --prefix=/usr/local --mandir=/usr/local/man --datadir=/usr/local/share/ffmpeg --pkgconfigdir=/usr/local/libdata/pkgconfig --enable-shared --enable-pic --enable-gpl --enable-postproc --enable-avfilter --enable-avresample --enable-pthreads --cc=cc --disable-indev=alsa --disable-outdev=alsa --disable-libopencore-amrnb --disable-libopencore-amrwb --disable-libass --disable-libbs2b --disable-libcaca --enable-libcdio --enable-libcelt --disable-chromaprint --disable-libdc1394 --disable-stripping --enable-htmlpages --enable-libfdk-aac --disable-ffserver --disable-libflite --disable-fontconfig --disable-libfreetype --enable-frei0r --disable-libfribidi --disable-libgme --enable-libgsm --enable-iconv --enable-libilbc --disable-indev=jack --enable-libkvazaar --enable-ladspa --enable-libmp3lame --disable-libbluray --enable-mmx --disable-libmodplug --disable-netcdf --enable-openal --disable-opencl --enable-libopencv --enable-opengl --enable-libopenh264 --enable-libopenjpeg --enable-optimizations --enable-libopus --disable-libpulse --disable-indev=pulse --disable-outdev=pulse --enable-runtime-cpudetect --disable-librubberband --enable-libschroedinger --enable-ffplay --disable-libsmbclient --enable-libsnappy --disable-libsoxr --disable-libspeex --enable-sse --disable-libssh --disable-libtesseract --enable-libtheora --enable-libtwolame --enable-libv4l2 --enable-vaapi --enable-vdpau --disable-libvidstab --enable-libvorbis --disable-libvo-amrwbenc --enable-libvpx --enable-libwavpack --disable-libwebp --enable-libx264 --enable-libx265 --enable-libxcb --enable-libxvid --enable-libzimg --disable-libzmq --disable-libzvbi --disable-gcrypt --enable-gmp --disable-librtmp --enable-gnutls --disable-openssl --enable-version3 --enable-nonfree
[2018-02-23 13:28:05,698] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) libavutil 55. 58.100 / 55. 58.100
[2018-02-23 13:28:05,698] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) libavcodec 57. 89.100 / 57. 89.100
[2018-02-23 13:28:05,698] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) libavformat 57. 71.100 / 57. 71.100
[2018-02-23 13:28:05,698] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) libavdevice 57. 6.100 / 57. 6.100
[2018-02-23 13:28:05,698] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) libavfilter 6. 82.100 / 6. 82.100
[2018-02-23 13:28:05,698] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) libavresample 3. 5. 0 / 3. 5. 0
[2018-02-23 13:28:05,698] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) libswscale 4. 6.100 / 4. 6.100
[2018-02-23 13:28:05,698] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) libswresample 2. 7.100 / 2. 7.100
[2018-02-23 13:28:05,698] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) libpostproc 54. 5.100 / 54. 5.100
[2018-02-23 13:28:05,698] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) Splitting the commandline.
[2018-02-23 13:28:05,698] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) Reading option '-loglevel' ... matched as option 'loglevel' (set logging level) with argument 'debug'.
[2018-02-23 13:28:05,698] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) Reading option '-i' ... matched as input url with argument '/var/music/Red Hot Chili Peppers/2006 - Stadium Arcadium - Disc 1/2 - Red Hot Chili Peppers - Snow (Hey Oh).m4a'.
[2018-02-23 13:28:05,698] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) Reading option '-map' ... matched as option 'map' (set input stream mapping) with argument '0:0'.
[2018-02-23 13:28:05,698] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) Reading option '-b:a' ... matched as option 'b' (video bitrate (please use -b:v)) with argument '320k'.
[2018-02-23 13:28:05,698] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) Reading option '-v' ... matched as option 'v' (set logging level) with argument '0'.
[2018-02-23 13:28:05,698] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) Reading option '-f' ... matched as option 'f' (force format) with argument 'mp3'.
[2018-02-23 13:28:05,698] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) Reading option '-' ... matched as output url.
[2018-02-23 13:28:05,698] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) Finished splitting the commandline.
[2018-02-23 13:28:05,698] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) Parsing a group of options: global .
[2018-02-23 13:28:05,698] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) Applying option loglevel (set logging level) with argument debug.
[2018-02-23 13:28:05,699] INFO InputStreamReaderThread - (/var/subsonic/transcode/ffmpeg) Applying option v (set logging level) with argument 0.

[mortiiscof]

Hmm... there really isn't much within that to point to anything. Does anyone know how I can make the logging more granular?