Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Soundbridge selective transcoding #1665

Open
frankusb opened this issue Oct 13, 2023 · 117 comments
Open

Soundbridge selective transcoding #1665

frankusb opened this issue Oct 13, 2023 · 117 comments

Comments

@frankusb
Copy link

  1. Could httpd_rsp.c transcode to CBR MP3 instead of WAV? This is mostly a question of if ffmpeg can do FLAC to MP3 like it does FLAC to WAV now.
  2. If so, could it do it on a per client basis?

Wireless Soundbridges can't handle WAV bitrates. Currently I have two instances of owntone running, one in conjunction with mp3fs to allow reliable playback on wireless Soundbridges. Besides the duplication of resources, the real annoyance is when I update a playlist, the mp3fs owntone then churns for 30-40 minutes re-reading all of the metadata since inotify is not supported with mp3fs.

@ejurgensen
Copy link
Member

Sounds like it should be possible, I'll look into it.

@ejurgensen
Copy link
Member

For testing this concept, I have made a branch with a very rudimentary implementation where the transcoding is switched to CBR MP3 at 256 kbit/s. Could you try if this works with a flac and the Soundbridge?

This is the branch: https://github.com/owntone/owntone-server/tree/rspmp3

@frankusb
Copy link
Author

frankusb commented Oct 21, 2023

I get httpd: Transcoding error, file id 37484 in the log.

Also, if it's not obvious, the Soundbridge does not play.

@ejurgensen
Copy link
Member

Which version of ffmpeg is it?

Also, can you confirm it doesn't play and you get the same error if you try from a browser? Try with http://[address]:3689/rsp/stream/37484

@frankusb
Copy link
Author

ffmpeg version 6.0 Copyright (c) 2000-2023 the FFmpeg developers
built with gcc 12 (Debian 12.2.0-14)
configuration: --disable-decoder=amrnb --disable-decoder=libopenjpeg --disable-gnutls --disable-liblensfun --disable-libopencv --disable-podpages --disable-sndio --disable-stripping --enable-avfilter --enable-chromaprint --enable-frei0r --enable-gcrypt --enable-gpl --enable-ladspa --enable-libaom --enable-libaribb24 --enable-libass --enable-libbluray --enable-libbs2b --enable-libcaca --enable-libcdio --enable-libcodec2 --enable-libdav1d --enable-libdavs2 --enable-libdc1394 --enable-libdrm --enable-libfdk-aac --enable-libflite --enable-libfontconfig --enable-libfreetype --enable-libfribidi --enable-libglslang --enable-libgme --enable-libgsm --enable-libiec61883 --enable-libjack --enable-libkvazaar --enable-libmp3lame --enable-libmysofa --enable-libopencore-amrnb --enable-libopencore-amrwb --enable-libopenh264 --enable-libopenjpeg --enable-libopenmpt --enable-libopus --enable-libpulse --enable-librabbitmq --enable-librist --enable-librsvg --enable-librubberband --enable-libshine --enable-libsmbclient --enable-libsnappy --enable-libsoxr --enable-libspeex --enable-libsrt --enable-libsvtav1 --enable-libtesseract --enable-libtheora --enable-libtwolame --enable-libvidstab --enable-libvo-amrwbenc --enable-libvorbis --enable-libvpx --enable-libwebp --enable-libwebp --enable-libx264 --enable-libx265 --enable-libxavs2 --enable-libxml2 --enable-libxvid --enable-libzimg --enable-libzmq --enable-libzvbi --enable-lv2 --enable-nonfree --enable-omx --enable-openal --enable-opencl --enable-opengl --enable-openssl --enable-postproc --enable-pthreads --enable-shared --enable-version3 --enable-vulkan --incdir=/usr/include/x86_64-linux-gnu --libdir=/usr/lib/x86_64-linux-gnu --prefix=/usr --toolchain=hardened --enable-vaapi --enable-libvpl --enable-libvmaf --enable-libilbc --enable-libjxl --disable-altivec --shlibdir=/usr/lib/x86_64-linux-gnu
libavutil 58. 2.100 / 58. 2.100
libavcodec 60. 3.100 / 60. 3.100
libavformat 60. 3.100 / 60. 3.100
libavdevice 60. 1.100 / 60. 1.100
libavfilter 9. 3.100 / 9. 3.100
libswscale 7. 1.100 / 7. 1.100
libswresample 4. 10.100 / 4. 10.100
libpostproc 57. 1.100 / 57. 1.100
Hyper fast Audio and Video encoder

It does not play and I get the same error if I try from a browser.

I also noticed that the Soundbridge shows the song info as "Kind:WAV audio file" and "Bit Rate: 1411 kbps" for FLAC files which is not what I would expect.

@ejurgensen
Copy link
Member

Ok, I found the reason it's not playing in the browser. I'll get back to you with a new attempt.

@ejurgensen
Copy link
Member

I've pushed a commit to the branch that I think should fix at least playback in browser. Please test and let me know.

@frankusb
Copy link
Author

frankusb commented Oct 28, 2023 via email

@frankusb
Copy link
Author

frankusb commented Nov 1, 2023

The Soundbridge is unable to stream. It still shows shows the song info as "Kind:WAV audio file" and "Bit Rate: 1411 kbps" for FLAC files. I can stream to my web browser.

[2023-11-01 09:27:09] [DEBUG] db: Starting query 'SELECT f.* FROM files f JOIN playlistitems pi ON f.path = pi.filepath WHERE f.disabled = 0 AND f.data_kind = 0 AND pi.playlistid = 12 ORDER BY pi.id ASC ;'
[2023-11-01 09:27:09] [DEBUG] db: End of query results
[2023-11-01 09:27:09] [DEBUG] httpd: Gzipping response
[2023-11-01 09:27:09] [DEBUG] rsp: RSP request '/rsp/db/0?query=id%3D12702&type=full' in worker thread 386760
[2023-11-01 09:27:09] [DEBUG] db: Running query 'SELECT COUNT() FROM files f WHERE f.disabled = 0 AND (f.id = 12702) AND f.data_kind = 0;'
[2023-11-01 09:27:09] [DEBUG] db: Starting query 'SELECT f.
FROM files f WHERE f.disabled = 0 AND (f.id = 12702) AND f.data_kind = 0 ORDER BY f.title_sort ;'
[2023-11-01 09:27:09] [DEBUG] db: End of query results
[2023-11-01 09:27:09] [DEBUG] httpd: Gzipping response
[2023-11-01 09:27:09] [DEBUG] rsp: RSP request '/rsp/stream/12702' in worker thread 386760
[2023-11-01 09:27:09] [DEBUG] db: Running query 'SELECT f.* FROM files f WHERE f.id = 12702;'
[2023-11-01 09:27:09] [ INFO] httpd: Preparing to transcode /var/autofs/removable/easystore10TB/Music/Travis Larson Band/Travis Larson Band-The New Exhibit/02-And Then.flac
[2023-11-01 09:27:09] [DEBUG] xcode: Selected encoder 'libmp3lame MP3 (MPEG audio layer 3)'
[2023-11-01 09:27:09] [DEBUG] ffmpeg: tb:1/44100 samplefmt:s16 samplerate:44100 chlayout:stereo
[2023-11-01 09:27:09] [DEBUG] xcode: Created 'abuffer' filter: 'time_base=1/44100:sample_rate=44100:sample_fmt=s16:channel_layout=stereo'
[2023-11-01 09:27:09] [DEBUG] xcode: Created 'aformat' filter: 'sample_fmts=s16p:sample_rates=44100:channel_layouts=stereo'
[2023-11-01 09:27:09] [DEBUG] xcode: Created 'abuffersink' filter: ''
[2023-11-01 09:27:09] [DEBUG] ffmpeg: auto-inserting filter 'auto_aresample_0' between the filter 'abuffer' and the filter 'aformat'
[2023-11-01 09:27:09] [DEBUG] ffmpeg: ch:2 chl:stereo fmt:s16 r:44100Hz -> ch:2 chl:stereo fmt:s16p r:44100Hz
[2023-11-01 09:27:09] [ INFO] httpd: Kicking off streaming for /var/autofs/removable/easystore10TB/Music/Travis Larson Band/Travis Larson Band-The New Exhibit/02-And Then.flac
[2023-11-01 09:27:09] [DEBUG] httpd: Got 66037 bytes from transcode; streaming file id 12702

@ejurgensen
Copy link
Member

Ok, that's progress then. It could sound like the Soundbridge gets some metadata that makes it expect wav, so I will check what is sent to it before streaming.

@ejurgensen
Copy link
Member

I see the RSP playlist response returns info about the media format, so now I made a change so that the response instead tells the Soundbridge that it is 256 kbit mp3. Please try again with the latest commit from the branch included.

@frankusb
Copy link
Author

frankusb commented Nov 1, 2023

It works perfect.

@ejurgensen
Copy link
Member

Excellent. Does seeking also work?

To change the implementation from experimental to actual, I have to decide which clients should get what formats. In the branch, all clients get 256 kbit mp3, even iTunes (haven't tested if it works, though). I would like to set some good defaults, so that configuration generally isn't needed. I am always weary about adding config options. What defaults do you suggest for RSP?

@frankusb
Copy link
Author

frankusb commented Nov 2, 2023

The Soundbridge does not support seeking, only next and previous tracks and that does work.

For bit rate default, I would suggest 320kbps. That's what I've been using with mp3fs for a while now. I used to frequent the Soundbridge forums and there were never complaints about mp3 bit rates needing to be reduced that I recall. May as well maximize sound quality.

Are there other default settings you are asking about?

To be clear, I am interested in this feature so that I can set wireless Soundbridges to receive 320kbps MP3 and wired Soundbridges to receive 1411kbps WAV. I have been thinking if the default should be 320kbps MP3 to insure that owntone will work with all Soundbridges regardless of type of network connection.

@Porco-Rosso
Copy link

Agreed 320kbps is a good default. Lots of literature to say that it's the level where its almost impossible to hear any difference from lossless files. It's also the most common mp3 format to download online.

@ejurgensen
Copy link
Member

While looking at how to do this, I came across this which seems to imply that the Soundbridge supports ALAC. Do you know if that is the case @frankusb? If so, would it be a better alternative? You would get lossless, but with less compression than the 320 kbps mp3, so requires more wifi bandwidth (I think the compression is about 50%, so half of 1411 kbps I guess).

@frankusb
Copy link
Author

frankusb commented Nov 6, 2023

You tried ALAC transcoding previously. I also found that the Soundbridge could not handle ALAC over wireless reliably by dropping some ALAC files in owntone.

@ejurgensen
Copy link
Member

I've been working some more on this, trying to make it more clean/less hardcoded, so that it can be merged. If you have the opportunity, please give the current rspmp3 branch a try again and let me know if it works.

@frankusb
Copy link
Author

It compiles and the Soundbridge plays fine. I'll leave it running and let you know if I notice anything.

@frankusb
Copy link
Author

I did notice that the file size shows the FLAC size rather than the MP3 effective size in the Soundbridge song info. If I recall correctly, it also did this with WAV trans-coding as well. It doesn't affect anything that I can tell.

@ejurgensen
Copy link
Member

I've now merged the change into master. It should also show the correct file size now.

@frankusb
Copy link
Author

frankusb commented Dec 4, 2023

Do I understand correctly that there is nothing selective about this? All RSP will be 320kbps?

@ejurgensen
Copy link
Member

ejurgensen commented Dec 4, 2023

Yes, indeed. Also DAAP, actually. I didn't add an option because in general I think mp3 is a better option than wav. Of course there is a slight quality loss, but wav could also be said to have that when the source was resampled to 44100. Another possible downside of mp3 is that the encoding requires cpu, but I figure that isn't much of problem these days.

One issue with mp3 that occurs to me now is that some installations might not have the encoder (I think it's only in "libavcodec-extras"?). I will look into adding something that checks for that.

@frankusb
Copy link
Author

frankusb commented Dec 4, 2023

Ripped CDs stored in FLAC format have zero quality loss transcoding to WAV at 44100 for the record unless there is something else I am unaware of in the transcoding from FLAC to WAV. The slight quality loss is only necessary for the wireless Soundbridges. Wired can have bit perfect playback.

And to be overly pedantic, only the M500, M1000 and M2000 have a codec that can play 44.1kHz. For M1001 and R1000, the audio codec can only do 48kHz. For best quality, one would transcode for those to 48kHz as the 400MHz Blackfin in the Soundbridges have audible artifacts upsampling from 44.1kHz to 48kHz.

If one wanted to be able to provide theoretical best quality, each individual device would need control over transcode output (WAV or MP3) and sample rate (44.1kHz vs 48kHz).

@ejurgensen
Copy link
Member

Yes, agree. What would you suggest as selection strategy? It should preferably be with no configuration, or at least as little as possible.

@frankusb
Copy link
Author

frankusb commented Dec 4, 2023

Well, you can't tell if a connection is bandwith limited (wireless), can you? It may be possible to determine the model and if so the optimal frequency could be selected. M500, M1000, M2000: 44.1kHz. M1001, R1000: 48kHz.

Actually for R1000, it's only wireless so it could be MP3 320kbps 48kHz and it's optimal. The M models can be either wired or wireless so I think would require user configuration to optimize.

@ejurgensen
Copy link
Member

By adding timers it might be possible to detect network and encoding bottlenecks, but it would be quite complicated and certainly nice to avoid. Reaction to an identified bottleneck would also be complex.

I'm not sure how much the Roku's reveal about themselves, but I've made a branch where the request headers are dumped to the log. If you have some of these devices then please try the branch debug_dump_headers and share the results.

I'm thinking I should make another attempt with ALAC. Seems like it could be a silver bullet.

@ejurgensen
Copy link
Member

I'm thinking I should make another attempt with ALAC. Seems like it could be a silver bullet.

Scratch that, now I see you said before that "I also found that the Soundbridge could not handle ALAC over wireless reliably by dropping some ALAC files in owntone."

@frankusb
Copy link
Author

frankusb commented Dec 5, 2023

I've tried ALAC at my house and my parent's house and it's better than WAV but still has dropouts. That and you said ffmpeg didn't support FLAC to ALAC transcoding.

Unfortunately, it appears the headers you captured are not unique between models (at least M2000 and M1001).

[2023-12-05 08:30:25] [DEBUG]    httpd: Request header 'User-Agent': 'Roku SoundBridge/3.0'
[2023-12-05 08:30:25] [DEBUG]    httpd: Request header 'Host': '192.168.1.119:3689'
[2023-12-05 08:30:25] [DEBUG]    httpd: Request header 'Accept': '*/*'
[2023-12-05 08:30:25] [DEBUG]    httpd: Request header 'Pragma': 'no-cache'
[2023-12-05 08:30:25] [DEBUG]    httpd: Request header 'accept-codecs': 'wma,mpeg,wav,mp4a,alac'
[2023-12-05 08:30:25] [DEBUG]    httpd: Request header 'rsp-version': '0.1'
[2023-12-05 08:30:25] [DEBUG]    httpd: Request header 'transcode-codecs': 'wav,mp3'
[2023-12-05 08:31:13] [DEBUG]    httpd: Request header 'User-Agent': 'Roku SoundBridge/3.0'
[2023-12-05 08:31:13] [DEBUG]    httpd: Request header 'Host': '192.168.1.119:3689'
[2023-12-05 08:31:13] [DEBUG]    httpd: Request header 'Accept': '*/*'
[2023-12-05 08:31:13] [DEBUG]    httpd: Request header 'Pragma': 'no-cache'
[2023-12-05 08:31:13] [DEBUG]    httpd: Request header 'accept-codecs': 'wma,mpeg,wav,mp4a,alac'
[2023-12-05 08:31:13] [DEBUG]    httpd: Request header 'rsp-version': '0.1'
[2023-12-05 08:31:13] [DEBUG]    httpd: Request header 'transcode-codecs': 'wav,mp3'

@frankusb
Copy link
Author

Yes, everything seems to be resolved except for the false start. Is this expected?

[2024-01-14 15:25:12] [DEBUG]      rsp: RSP request '/rsp/stream/32242' in worker thread 475008
[2024-01-14 15:25:12] [DEBUG]       db: Running query 'SELECT f.* FROM files f WHERE f.id = 32242;'
[2024-01-14 15:25:12] [ INFO]    httpd: Preparing to transcode /var/autofs/removable/easystore10TB/Music/George Lynch/George Lynch-Guitars at the End of the World/07-The Wolf.flac
[2024-01-14 15:25:12] [DEBUG]    httpd: Checking if client '192.168.1.40' is a speaker
[2024-01-14 15:25:12] [DEBUG]    cache: Cache header hit (11714 bytes)
[2024-01-14 15:25:12] [DEBUG]    xcode: Selected encoder 'ALAC (Apple Lossless Audio Codec)'
[2024-01-14 15:25:12] [DEBUG]   ffmpeg: tb:1/44100 samplefmt:s16 samplerate:44100 chlayout:stereo
[2024-01-14 15:25:12] [DEBUG]    xcode: Created 'abuffer' filter: 'time_base=1/44100:sample_rate=44100:sample_fmt=s16:channel_layout=stereo'
[2024-01-14 15:25:12] [DEBUG]    xcode: Created 'aformat' filter: 'sample_fmts=s16p:sample_rates=44100:channel_layouts=stereo'
[2024-01-14 15:25:12] [DEBUG]    xcode: Created 'abuffersink' filter: ''
[2024-01-14 15:25:12] [DEBUG]   ffmpeg: auto-inserting filter 'auto_aresample_0' between the filter 'abuffer' and the filter 'aformat'
[2024-01-14 15:25:12] [DEBUG]   ffmpeg: ch:2 chl:stereo fmt:s16 r:44100Hz -> ch:2 chl:stereo fmt:s16p r:44100Hz
[2024-01-14 15:25:12] [ INFO]    httpd: Kicking off streaming for /var/autofs/removable/easystore10TB/Music/George Lynch/George Lynch-Guitars at the End of the World/07-The Wolf.flac
[2024-01-14 15:25:12] [DEBUG]    httpd: Got 74993 bytes from transcode; streaming file id 32242
[2024-01-14 15:25:12] [ WARN]      rsp: Connection to '192.168.1.40' was closed
[2024-01-14 15:25:12] [DEBUG]   ffmpeg: Statistics: 242920 bytes read, 0 seeks
[2024-01-14 15:25:13] [DEBUG]      rsp: RSP request '/rsp/stream/32242' in worker thread 475007
[2024-01-14 15:25:13] [DEBUG]    httpd: Found Range header: bytes=144-
[2024-01-14 15:25:13] [DEBUG]       db: Running query 'SELECT f.* FROM files f WHERE f.id = 32242;'
[2024-01-14 15:25:13] [ INFO]    httpd: Preparing to transcode /var/autofs/removable/easystore10TB/Music/George Lynch/George Lynch-Guitars at the End of the World/07-The Wolf.flac
[2024-01-14 15:25:13] [DEBUG]    httpd: Checking if client '192.168.1.40' is a speaker
[2024-01-14 15:25:13] [DEBUG]    cache: Cache header hit (11714 bytes)
[2024-01-14 15:25:13] [DEBUG]    xcode: Selected encoder 'ALAC (Apple Lossless Audio Codec)'
[2024-01-14 15:25:13] [DEBUG]   ffmpeg: tb:1/44100 samplefmt:s16 samplerate:44100 chlayout:stereo
[2024-01-14 15:25:13] [DEBUG]    xcode: Created 'abuffer' filter: 'time_base=1/44100:sample_rate=44100:sample_fmt=s16:channel_layout=stereo'
[2024-01-14 15:25:13] [DEBUG]    xcode: Created 'aformat' filter: 'sample_fmts=s16p:sample_rates=44100:channel_layouts=stereo'
[2024-01-14 15:25:13] [DEBUG]    xcode: Created 'abuffersink' filter: ''
[2024-01-14 15:25:13] [DEBUG]   ffmpeg: auto-inserting filter 'auto_aresample_0' between the filter 'abuffer' and the filter 'aformat'
[2024-01-14 15:25:13] [DEBUG]   ffmpeg: ch:2 chl:stereo fmt:s16 r:44100Hz -> ch:2 chl:stereo fmt:s16p r:44100Hz
[2024-01-14 15:25:13] [DEBUG]    httpd: Stream request with range 144-0
[2024-01-14 15:25:13] [ INFO]    httpd: Kicking off streaming for /var/autofs/removable/easystore10TB/Music/George Lynch/George Lynch-Guitars at the End of the World/07-The Wolf.flac
[2024-01-14 15:25:13] [DEBUG]    httpd: Got 74993 bytes from transcode; streaming file id 32242
[2024-01-14 15:25:13] [DEBUG]    httpd: Got 74368 bytes from transcode; streaming file id 32242
[2024-01-14 15:25:13] [DEBUG]    httpd: Got 67968 bytes from transcode; streaming file id 32242
[2024-01-14 15:25:14] [DEBUG]    httpd: Got 68980 bytes from transcode; streaming file id 32242
[2024-01-14 15:25:14] [DEBUG]    httpd: Got 67951 bytes from transcode; streaming file id 32242
[2024-01-14 15:25:15] [DEBUG]    httpd: Got 70750 bytes from transcode; streaming file id 32242
[2024-01-14 15:25:15] [DEBUG]    httpd: Got 65915 bytes from transcode; streaming file id 32242
[2024-01-14 15:25:15] [DEBUG]    httpd: Got 73847 bytes from transcode; streaming file id 32242

@ejurgensen
Copy link
Member

I'm not sure what to make of that. As you can see, the Soundbridge seems to be streaming a bit, then hanging up and then reconnecting and asking for "Range header: bytes=144-". Can you try with an actual ALAC file for comparison? I wonder if it does the same.

@frankusb
Copy link
Author

Good test, it does similar.

[2024-01-14 16:47:06] [DEBUG]      rsp: RSP request '/rsp/stream/10085' in worker thread 478324
[2024-01-14 16:47:06] [DEBUG]       db: Running query 'SELECT f.* FROM files f WHERE f.id = 10085;'
[2024-01-14 16:47:06] [ INFO]    httpd: Preparing to stream /var/autofs/removable/easystore10TB/Music/2wo/01-I Am a Pig.m4a
[2024-01-14 16:47:06] [ INFO]    httpd: Kicking off streaming for /var/autofs/removable/easystore10TB/Music/2wo/01-I Am a Pig.m4a
[2024-01-14 16:47:06] [DEBUG]    httpd: Read 4096 bytes; streaming file id 10085
[2024-01-14 16:47:06] [DEBUG]    httpd: Read 4096 bytes; streaming file id 10085
[2024-01-14 16:47:06] [DEBUG]    httpd: Read 4096 bytes; streaming file id 10085
[2024-01-14 16:47:06] [DEBUG]    httpd: Read 4096 bytes; streaming file id 10085
[2024-01-14 16:47:06] [DEBUG]    httpd: Read 4096 bytes; streaming file id 10085
[2024-01-14 16:47:06] [DEBUG]    httpd: Read 4096 bytes; streaming file id 10085
[2024-01-14 16:47:06] [DEBUG]    httpd: Read 4096 bytes; streaming file id 10085
[2024-01-14 16:47:06] [DEBUG]    httpd: Read 4096 bytes; streaming file id 10085
[2024-01-14 16:47:06] [DEBUG]    httpd: Read 4096 bytes; streaming file id 10085
[2024-01-14 16:47:06] [DEBUG]    httpd: Read 4096 bytes; streaming file id 10085
[2024-01-14 16:47:06] [DEBUG]    httpd: (LOGGING SKIPPED - above log message is repeating)
[2024-01-14 16:47:06] [ WARN]      rsp: Connection to '192.168.1.40' was closed
[2024-01-14 16:47:06] [DEBUG]      rsp: RSP request '/rsp/stream/10085' in worker thread 478324
[2024-01-14 16:47:06] [DEBUG]    httpd: Found Range header: bytes=1235992-
[2024-01-14 16:47:06] [DEBUG]       db: Running query 'SELECT f.* FROM files f WHERE f.id = 10085;'
[2024-01-14 16:47:06] [ INFO]    httpd: Preparing to stream /var/autofs/removable/easystore10TB/Music/2wo/01-I Am a Pig.m4a
[2024-01-14 16:47:06] [DEBUG]    httpd: Stream request with range 1235992-0
[2024-01-14 16:47:06] [ INFO]    httpd: Kicking off streaming for /var/autofs/removable/easystore10TB/Music/2wo/01-I Am a Pig.m4a
[2024-01-14 16:47:06] [DEBUG]    httpd: Read 4096 bytes; streaming file id 10085
[2024-01-14 16:47:06] [DEBUG]    httpd: Read 4096 bytes; streaming file id 10085
[2024-01-14 16:47:06] [DEBUG]    httpd: Read 4096 bytes; streaming file id 10085
[2024-01-14 16:47:06] [DEBUG]    httpd: Read 4096 bytes; streaming file id 10085
[2024-01-14 16:47:06] [DEBUG]    httpd: Read 4096 bytes; streaming file id 10085
[2024-01-14 16:47:06] [DEBUG]    httpd: Read 4096 bytes; streaming file id 10085
[2024-01-14 16:47:06] [DEBUG]    httpd: Read 4096 bytes; streaming file id 10085
[2024-01-14 16:47:06] [DEBUG]    httpd: Read 4096 bytes; streaming file id 10085
[2024-01-14 16:47:06] [DEBUG]    httpd: Read 4096 bytes; streaming file id 10085
[2024-01-14 16:47:06] [DEBUG]    httpd: Read 4096 bytes; streaming file id 10085
[2024-01-14 16:47:06] [DEBUG]    httpd: (LOGGING SKIPPED - above log message is repeating)
[2024-01-14 16:47:10] [ WARN]      rsp: Connection to '192.168.1.40' was closed

Bad news is there appears to be another problem. When I removed a FLAC file to replace it with an ALAC, it seemed to drop all songs.

[2024-01-14 15:31:10] [  LOG]      lib: Library init scan completed in 17 sec (0 changes)
[2024-01-14 16:16:47] [  LOG]    cache: Deleting xcode file id 10085
[2024-01-14 16:16:48] [  LOG]    cache: Deleting xcode file id 10086
...
[2024-01-14 16:32:19] [  LOG]    cache: Deleting xcode file id 38130
[2024-01-14 16:32:19] [  LOG]    cache: Deleting xcode file id 38131
[2024-01-14 16:32:19] [  LOG]    cache: Deleting xcode file id 38132
[2024-01-14 16:32:19] [  LOG]    cache: Kicking off header generation
[2024-01-14 16:32:19] [  LOG]    cache: Header generation completed

After that the cache was no longer used.

A subsequent restart then added them all back and started preparing headers.

[2024-01-14 16:36:03] [DEBUG]    cache: Preparing mp4 header for '/var/autofs/removable/easystore10TB/Music/Roger Hodgson/Roger Hodgson-Classics Live/06-The Logical Song.flac' (file id 10088)
[2024-01-14 16:36:05] [DEBUG]    cache: Preparing mp4 header for '/var/autofs/removable/easystore10TB/Music/Roger Hodgson/Roger Hodgson-Classics Live/02-Give a Little Bit.flac' (file id 10089)

@ejurgensen
Copy link
Member

When I removed a FLAC file to replace it with an ALAC, it seemed to drop all songs.

Just so I reproduce in the right way: How exactly did you remove/replace? And the server was running, right?

@frankusb
Copy link
Author

frankusb commented Jan 15, 2024

Just so I reproduce in the right way: How exactly did you remove/replace? And the server was running, right?

I copied the FLAC to another directory not monitored by owntone, ran ffmpeg to create an ALAC, copied the ALAC to the directory monitored by owntone, then deleted the FLAC leaving only the ALAC. Owntone was running the entire time.

I was unable to reproduce myself but thought I better report it.

@ejurgensen
Copy link
Member

I could reproduce the problem with the headers being dropped, and I believe it should now be fixed.

@frankusb
Copy link
Author

I've got it compiled and will switch to ALAC for the wired Soundbridges.

@frankusb
Copy link
Author

frankusb commented Jan 20, 2024

ALAC headers finished this morning. I'm getting a lot of Soundbridge reboots. It is reproducible, the same song will always cause the Soundbridge to reboot if I try to play it. Some songs do play normally.

[2024-01-20 11:57:30] [DEBUG]       db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND (f.album_artist = 'Def Leppard' AND f.album = 'Drastic Symphonies') AND f.data_kind = 0  ORDER BY f.title_sort ;'
[2024-01-20 11:57:30] [DEBUG]       db: End of query results
[2024-01-20 11:57:30] [DEBUG]    httpd: Gzipping response
[2024-01-20 11:57:34] [DEBUG]      rsp: RSP request '/rsp/db/0?query=id%3D22457&type=full' in worker thread 757456
[2024-01-20 11:57:34] [DEBUG]    httpd: Checking if client '192.168.1.40' is a speaker
[2024-01-20 11:57:34] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND (f.id = 22457) AND f.data_kind = 0;'
[2024-01-20 11:57:34] [DEBUG]       db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND (f.id = 22457) AND f.data_kind = 0  ORDER BY f.title_sort ;'
[2024-01-20 11:57:34] [DEBUG]       db: End of query results
[2024-01-20 11:57:34] [DEBUG]    httpd: Gzipping response
[2024-01-20 11:57:34] [DEBUG]      rsp: RSP request '/rsp/stream/22457' in worker thread 757456
[2024-01-20 11:57:34] [DEBUG]       db: Running query 'SELECT f.* FROM files f WHERE f.id = 22457;'
[2024-01-20 11:57:34] [ INFO]    httpd: Preparing to transcode /var/autofs/removable/easystore10TB/Music/Def Leppard/Def Leppard-Drastic Symphonies/04-Pour Some Sugar On Me (Stripped version).flac
[2024-01-20 11:57:34] [DEBUG]    httpd: Checking if client '192.168.1.40' is a speaker
[2024-01-20 11:57:34] [DEBUG]    cache: Cache header hit (9002 bytes)
[2024-01-20 11:57:34] [DEBUG]    xcode: Selected encoder 'ALAC (Apple Lossless Audio Codec)'
[2024-01-20 11:57:34] [DEBUG]   ffmpeg: tb:1/44100 samplefmt:s16 samplerate:44100 chlayout:stereo
[2024-01-20 11:57:34] [DEBUG]    xcode: Created 'abuffer' filter: 'time_base=1/44100:sample_rate=44100:sample_fmt=s16:channel_layout=stereo'
[2024-01-20 11:57:34] [DEBUG]    xcode: Created 'aformat' filter: 'sample_fmts=s16p:sample_rates=44100:channel_layouts=stereo'
[2024-01-20 11:57:34] [DEBUG]    xcode: Created 'abuffersink' filter: ''
[2024-01-20 11:57:34] [DEBUG]   ffmpeg: auto-inserting filter 'auto_aresample_0' between the filter 'abuffer' and the filter 'aformat'
[2024-01-20 11:57:34] [DEBUG]   ffmpeg: ch:2 chl:stereo fmt:s16 r:44100Hz -> ch:2 chl:stereo fmt:s16p r:44100Hz
[2024-01-20 11:57:34] [ INFO]    httpd: Kicking off streaming for /var/autofs/removable/easystore10TB/Music/Def Leppard/Def Leppard-Drastic Symphonies/04-Pour Some Sugar On Me (Stripped version).flac
[2024-01-20 11:57:34] [DEBUG]    httpd: Got 69253 bytes from transcode; streaming file id 22457
[2024-01-20 11:57:34] [ WARN]      rsp: Connection to '192.168.1.40' was closed
[2024-01-20 11:57:34] [DEBUG]   ffmpeg: Statistics: 280704 bytes read, 0 seeks
[2024-01-20 11:57:34] [DEBUG]      rsp: RSP request '/rsp/stream/22457' in worker thread 757453
[2024-01-20 11:57:34] [DEBUG]    httpd: Found Range header: bytes=144-
[2024-01-20 11:57:34] [DEBUG]       db: Running query 'SELECT f.* FROM files f WHERE f.id = 22457;'
[2024-01-20 11:57:34] [ INFO]    httpd: Preparing to transcode /var/autofs/removable/easystore10TB/Music/Def Leppard/Def Leppard-Drastic Symphonies/04-Pour Some Sugar On Me (Stripped version).flac
[2024-01-20 11:57:34] [DEBUG]    httpd: Checking if client '192.168.1.40' is a speaker
[2024-01-20 11:57:34] [DEBUG]    cache: Cache header hit (9002 bytes)
[2024-01-20 11:57:34] [DEBUG]    xcode: Selected encoder 'ALAC (Apple Lossless Audio Codec)'
[2024-01-20 11:57:34] [DEBUG]   ffmpeg: tb:1/44100 samplefmt:s16 samplerate:44100 chlayout:stereo
[2024-01-20 11:57:34] [DEBUG]    xcode: Created 'abuffer' filter: 'time_base=1/44100:sample_rate=44100:sample_fmt=s16:channel_layout=stereo'
[2024-01-20 11:57:34] [DEBUG]    xcode: Created 'aformat' filter: 'sample_fmts=s16p:sample_rates=44100:channel_layouts=stereo'
[2024-01-20 11:57:34] [DEBUG]    xcode: Created 'abuffersink' filter: ''
[2024-01-20 11:57:34] [DEBUG]   ffmpeg: auto-inserting filter 'auto_aresample_0' between the filter 'abuffer' and the filter 'aformat'
[2024-01-20 11:57:34] [DEBUG]   ffmpeg: ch:2 chl:stereo fmt:s16 r:44100Hz -> ch:2 chl:stereo fmt:s16p r:44100Hz
[2024-01-20 11:57:34] [DEBUG]    httpd: Stream request with range 144-0
[2024-01-20 11:57:34] [ INFO]    httpd: Kicking off streaming for /var/autofs/removable/easystore10TB/Music/Def Leppard/Def Leppard-Drastic Symphonies/04-Pour Some Sugar On Me (Stripped version).flac
[2024-01-20 11:57:34] [DEBUG]    httpd: Got 69253 bytes from transcode; streaming file id 22457
[2024-01-20 11:57:35] [DEBUG]    httpd: Got 73998 bytes from transcode; streaming file id 22457
[2024-01-20 11:57:35] [DEBUG]    httpd: Got 69234 bytes from transcode; streaming file id 22457
[2024-01-20 11:57:49] [ WARN]      rsp: Connection to '192.168.1.40' was closed
[2024-01-20 11:57:49] [DEBUG]   ffmpeg: Statistics: 411776 bytes read, 0 seeks
[2024-01-20 11:57:50] [DEBUG]      rsp: RSP request '/rsp/info' in worker thread 757456
[2024-01-20 11:57:50] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND f.data_kind = 0;'

@frankusb
Copy link
Author

I did some more tests. I would assert my headers are corrupt for some files.

curl --header "Accept-Codecs: alac" http://localhost:3689/rsp/stream/22457 -o transcoded.m4a

resulted in an unplayable file in VLC. MediaInfo showed it was truncated.

touch ../easystore10TB/Music/Def\ Leppard/Def\ Leppard-Drastic\ Symphonies/04-Pour\ Some\ Sugar\ On\ Me\ \(Stripped\ version\).flac

[2024-01-21 10:51:47] [  LOG]    cache: Deleting xcode file id 22457
[2024-01-21 10:51:47] [  LOG]    cache: Adding xcode file id 22457, path '/var/autofs/removable/easystore10TB/Music/Def Leppard/Def Leppard-Drastic Symphonies/04-Pour Some Sugar On Me (Stripped version).flac'
[2024-01-21 10:51:47] [  LOG]    cache: Kicking off header generation
[2024-01-21 10:51:50] [  LOG]    cache: Header generation completed

curl --header "Accept-Codecs: alac" http://localhost:3689/rsp/stream/22457 -o transcoded22457.m4a

resulted in a playable file in VLC and no truncation in MediaInfo

@hacketiwack
Copy link
Collaborator

I did some more tests. I would assert my headers are corrupt for some files.

Not completely related to your situation, however, in my experience, I rarely had good result converting to ALAC with ffmpeg. For that, I use a script I created for afconvert. And of course it works only under macOS :-D. That's why I ended up converting all my lossless collection to ALAC in m4a containers.

This is the script I use:

#!/bin/zsh

# Format flags
flags=([16]=1 [20]=2 [24]=3 [32]=4)

# Retrieve the bit depth of the audio file
depth=$(afinfo "$1" | sed -n 's/.*depth: I\(.*\)/\1/p')

# Convert the audio file
echo "Converting $1"
afconvert -f m4af -d alac/${flags[depth]} "$1" "${1%.*}.m4a"

You'll have to retag your files afterwards.

@ejurgensen
Copy link
Member

@frankusb good idea using "touch" to recreate the header and then checking again. To me that indicates a bug in the cache storage/retrieval of headers. I will see if I can catch it.

@frankusb
Copy link
Author

frankusb commented Jan 26, 2024

@ejurgensen if you are not interested in any of my present xcode database information I was planning on removing it this weekend and rebuilding to see if the changes over time contributed to the current state or if there is something in the current codebase. I could always preserve it if you feel it might be interesting later.

@ejurgensen
Copy link
Member

I haven't gotten around to looking at the latest issue yet, so not sure how much more information I might need.

If you currently have a file which doesn't play due to invalid header, I think it would be great if you could save that invalid header. I think you can do that like this:

sqlite3 /var/cache/owntone/xcode.db
select id, file_id, format, length(header). hex(header) from data where file_id = [file_id];

Then just save the output. Then, when you have rebuilt, check if the new header matches. Also check if any other headers match:

select id, file_id, format, length(header). hex(header) from data where length(header) = [header_len];

@frankusb
Copy link
Author

I'm happy to leave the xcode database as is, weekends are just a good time to run the rebuild.

@ejurgensen
Copy link
Member

ejurgensen commented Jan 28, 2024

Hi @frankusb I found a possible issue, so I've made some modifications to the branch that I hope you can test. Before doing so, you would have to delete your current xcode.db and rebuild. The rebuilding should be 4x faster now, since one of the modifications is to run the encoding in parallel. I've tried to do it in a way that hopefully doesn't make the server inoperable during the encoding, but let me know what your experience is. You can adjust the number of parallel jobs with CACHE_XCODE_NTHREADS.

I tried testing the validity of the files with ffprobe, and they all pass, except for some special formats that can't be transcoded (e.g. due to DRM). If your Soundbridge still doesn't like some of the files, please check it with ffprobe, so I can see if that works as a test.

@frankusb
Copy link
Author

I gave it a go. All good as far as I can tell. I can't find any problem files for the Soundbridge but will keep it set to ALAC.

[2024-01-28 08:27:44] [  LOG]    cache: Kicking off header generation
[2024-01-28 09:17:42] [  LOG]    xcode: Error while feeding the filtergraph: Invalid argument
[2024-01-28 09:17:45] [  LOG]    xcode: Error while feeding the filtergraph: Invalid argument
[2024-01-28 10:02:34] [  LOG]   ffmpeg: No JPEG data found in image
...
[2024-01-28 13:25:05] [  LOG]   ffmpeg: (LOGGING SKIPPED - above log message is repeating)
[2024-01-28 15:05:24] [  LOG]    cache: Header generation completed

Some humble feedback. It might be useful to include the file for the above errors so one could correct/examine them. I happen to have 4 cores so your CACHE_XCODE_NTHREADS choice matches nicely. Querying the number of cores would probably be better. I could tell the system was sluggish but nothing stopped working. SCHED_IDLE vs SCHED_BATCH may help with this.

@ejurgensen
Copy link
Member

It might be useful to include the file for the above errors so one could correct/examine them

Yes, I've added a fix for that now

@frankusb
Copy link
Author

frankusb commented Jan 31, 2024

The fix did not trigger for me.

[2024-01-30 18:10:47] [  LOG]    xcode: Error while feeding the filtergraph: Invalid argument
[2024-01-30 18:10:49] [  LOG]    xcode: Error while feeding the filtergraph: Invalid argument
[2024-01-30 18:55:15] [  LOG]   ffmpeg: No JPEG data found in image

I've checked to make sure the update is in my codebase, make, install.

If I am reading the code correctly, make_mp4_header is not passing on the return value from read_decode_filter_encode_write back up to transcode_prepare_header.

@ejurgensen
Copy link
Member

Seems to work ok when I mock the error:

[2024-02-01 14:38:28] [  LOG]    xcode: Error while feeding the filtergraph: Invalid argument
[2024-02-01 14:38:28] [  LOG]    cache: Error preparing mp4 header for 'path/to/file.mp3' (file id 15)

@frankusb
Copy link
Author

frankusb commented Feb 1, 2024

filter_encode_write can be called from decode_filter_encode_write and transcode_encode. Is it possible that only one return path results in the additional log message? I can't see why it's not in my log.

On the bright side, I used a Soundbridge to play ALAC for 2-3 hours last night and it worked perfectly.

@ejurgensen
Copy link
Member

Yes, you are right, there are some code paths that could lead to no logging of the file name. It seems to be when the encoder is flushed, but I'm not sure if that is the only way. I'll add some extra logging so we can check what is leading to it.

@frankusb
Copy link
Author

frankusb commented May 1, 2024

I just noticed that WAV playtback is not working on the latest version of the rsp_daap_format3 branch. Sorry I took so long to notice, the problem only occurs at the very end of the first track played. When the Soundbridge buffers the next song during the end of the first track, it reboots.

Once ALAC was working, I switched all of my wired Soundbridges to ALAC and never retested WAV. I should have left half in WAV and half in ALAC. I found this because I added a Soundbridge to my network and it defaulted to WAV. Switching it to ALAC allows it to play multiple tracks without rebooting.

@ejurgensen
Copy link
Member

Thanks for the notice, it's great that you are testing. I haven't done much with the branch in some time, exactly because the changes are pretty extensive and thus need a lot of testing, otherwise merging into master will be too risky. I've also been busy with other things, but I haven't forgotten about this.

@frankusb
Copy link
Author

frankusb commented May 1, 2024

ALAC and MP3 have been flawless on the most recent version of the branch. I've been using it exclusively. I've done lots of library changes, playlist changes and general usage.

@ejurgensen
Copy link
Member

Good to hear. Also about the general usage, because it is also general regressions I'm concerned about.

@hacketiwack
Copy link
Collaborator

Not directly related to the problem here, I'm wondering what is the advantage of streaming PCM audio (aka Wav files) instead of ALAC audio, which is also lossless?

@frankusb
Copy link
Author

frankusb commented May 1, 2024

@hacketiwack ALAC saves network bandwidth over WAV is the only advantage from my perspective. This is mostly negligible though.

@ejurgensen my general usage includes Airplay speakers (receivers actually), Apple remote control, Web interface remote control, Soundbridge RSP, and a little Chromecast speakers (they tend to cut off but always have).

@ejurgensen
Copy link
Member

PCM/WAV has the advantage that it is decode only, so less cpu required, and also OwnTone can decode on the fly. With ALAC, OwnTone has to prebuild a cache of ALAC headers. This is cpu intensive and the cached headers do end up filling some disk space.

@frankusb
Copy link
Author

frankusb commented May 22, 2024

I just noticed that WAV playtback is not working on the latest version of the rsp_daap_format3 branch. Sorry I took so long to notice, the problem only occurs at the very end of the first track played. When the Soundbridge buffers the next song during the end of the first track, it reboots.

I need to amend this report as it manifests on only one M1001 that I have found so far, it does not reproduce on an M2000 in WAV mode. Even more insidious, it appears to be length of track related, the M1001 plays a 0:52 song while in WAV mode but fails on 3:xx and 4:xx songs. I will leave all of my Soundbridges in WAV mode for a while to see if I can narrow this down. It's possible this is device specific?

I tried on a second M1001 and it behaves the same. It appears to be model specific.

@ejurgensen
Copy link
Member

It's a hard to say. A possibility is that there is something in the WAV header that the M1001 doesn't like, but that the M2000 accepts. The header has the length of the track, so that could explain why that makes a difference. Here's how the header is made fyi: https://github.com/owntone/owntone-server/blob/master/src/transcode.c#L439

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants