Soundbridge M1001 reboots with wav-encoding
ejurgensen opened this issue · 38 comments
From issue #1665 reported by @frankusb:
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.
@frankusb one of the things I changed is that now OwnTone doesn't resample to a fixed sample rate of 44100 at 16 bits per sample when transcoding to wav. Instead the source file's quality is kept, which of course should mean better quality.
The transcoded wav from source files that are already 44100/16 will naturally be the same, and my tests confirm this. So could you try playing an album where the source files are as such to check if the M1001 reboots still happen? If they do it would indicate that it isn't the actual wav, but something else causing the problem.
If the reboots persists then also please make this test:
(starting from current master - replace [ID] with id of source file which is 44100/16)
curl --header "Accept-Codecs: wav" http://localhost:3689/rsp/stream/[ID] -o test_44100_new.wav
git checkout c30f44fd01ebc51544cdb32d4d5a77ea9d4ff42b
make
(reinstall/restart OwnTone with the new binary)
curl --header "Accept-Codecs: wav" http://localhost:3689/rsp/stream/[ID] -o test_44100_old.wav
diff test_44100_old.wav test_44100_new.wav
So transcode the same 44100/16 source file to wav with the old and new version of OwnTone to see if there is any difference in the output.
I will perform this test tonight. I can say that a vast majority of my FLAC files are 44.1kHz, 16 bit. I would have trouble finding a 48kHz, 16 bit. There are no higher bit depth files.
From what I have tried, the M1001 can play any FLAC file to start. It's when it buffers the next song in the playlist while playing the first song that causes the reboot. About 15 seconds before the end of the first song is when the reboot occurs and from prior experience, this is when it's buffering the next song.
Ok, then I guess it's unlikely that the sample rate is the problem. So instead of testing that I'd like to ask you for logs of the exact requests that the M1001 is making. Then I can try to make the same requests with the old and new versions and look for differences.
Testing with iTunes I found an issue which might be related. With some tracks, iTunes ends playback too early, switching to the next one. It happens with regular 44100 mp3's that OwnTone is sending without transcoding, so that indicates the issue is related to the track tags.
I turned on debug logging and captured the same two songs played on the M1001 and on the M2000. There does not appear to be anything useful in the log. The M1001 just stops due to the reboot I assume. I think it will require instrumenting the startup of the wav streaming to learn more. I filtered out dacp messages because they seem to be too frequent.
Actually, I wonder if it's something at the end of the stream? The M1001 can start with any track, it just doesn't end cleanly.
As you observed, the tags are incorrect. File id 10940 is 2.4MiB and the M1001 shows 5.4MB. This would explains why I can skip tracks but not play them all the way through.
git checkout c30f44f results in the M1001 showing a file size of 5.4MB and it reboots at the same time during playback of file id 10940. :(
As you observed, the tags are incorrect. File id 10940 is 2.4MiB and the M1001 shows 5.4MB. This would explains why I can skip tracks but not play them all the way through.
This is not necessarily an error. The size the M1001 will show is that of the transcoded wav, not the size of the flac source. So to check the size you need to download the transcoded wav with the command I shared above and then check if it is not 5.4MB.
git checkout c30f44f results in the M1001 showing a file size of 5.4MB and it reboots at the same time during playback of file id 10940. :(
This is surprising.... that means the reboot issue isn't a regression from the ALAC changes, so the rsp_daap_format3 branch? Are you sure you ran the correct binary when you tested?
You're right that the logs don't really show much, so I agree that indicates that there is something at the end of the file that is unexpected for the M1001. So one more thing I suggest testing:
curl --header "Accept-Codecs: wav" http://localhost:3689/rsp/stream/10940 -o transcoded10940.wav
curl --header "Accept-Codecs: wav" http://localhost:3689/rsp/stream/10941 -o transcoded10941.wav
Then put these two in your library and try to play them with the M1001. Does it now reboot?
This is not necessarily an error. The size the M1001 will show is that of the transcoded wav, not the size of the flac source. So to check the size you need to download the transcoded wav with the command I shared above and then check if it is not 5.4MB.
Sorry, you are correct and I forgot a blatantly obvious factor.
git checkout c30f44f results in the M1001 showing a file size of 5.4MB and it reboots at the same time during playback of file id 10940. :(
This is surprising.... that means the reboot issue isn't a regression from the ALAC changes, so the rsp_daap_format3 branch? Are you sure you ran the correct binary when you tested?
The file size changed.
-rwxr-xr-x 1 root root 3776896 Jun 18 20:09 /usr/sbin/owntone
-rwxr-xr-x 1 root root 3719240 Jun 19 07:50 /usr/sbin/owntone
I honestly use my M2000s way more than the M1001 so I may need to try some older branches to narrow this down.
curl --header "Accept-Codecs: wav" http://localhost:3689/rsp/stream/10940 -o transcoded10940.wav curl --header "Accept-Codecs: wav" http://localhost:3689/rsp/stream/10941 -o transcoded10941.wavThen put these two in your library and try to play them with the M1001. Does it now reboot?
It does reboot.
-rw-r--r-- 1 5727164 Jun 19 07:57 transcoded10940.wav
-rw-r--r-- 1 39196124 Jun 19 07:57 transcoded10941.wav
ffmpeg results in slightly different sizes, not sure if it matters.
ffmpeg -i 03-Thunderstruck\ \(Intro\).flac 03-Thunderstruck\ \(Intro\).wav
ffmpeg -i 04-Thunderstruck.flac 04-Thunderstruck.wav
-rw-r--r-- 1 5727300 Jun 19 08:05 '03-Thunderstruck (Intro).wav'
-rw-r--r-- 1 39196252 Jun 19 08:05 04-Thunderstruck.wav
ffmpeg results in slightly different sizes, not sure if it matters
Does the M1001 also reboot if you play the two wavs from ffmpeg via OwnTone?
When you convert with ffmpeg it will put metadata like track name in the wav header, so that's probably why the files aren't the same size. You can see this with xxd [file] | less. OwnTone has never included this metadata in the header.
Does the M1001 also reboot if you play the two wavs from ffmpeg via OwnTone?
The M1001 does not reboot if I play the two wavs from ffmpeg via OwnTone.
Here's a big hint. I tried tags/28.8 and it works fine (same two files). The Size reported by the M1001 reflects the FLAC size, 2.3MB.
Interesting findings, that should help narrow down the bug. I'll look into the commit and test before & after for comparison. Did you try downloading wav's with curl before and after to see if/how they were different?
I did not, I thought they had to be different since the Soundbridge showed a different size. As far as how they were different, I think a better comparison would be between curl from the latest version and ffmpeg of the same file since that plays.
I compared the wav's now, and I see a difference that could explain the crash. The wav header contains the total size of the wav, but that has always been an estimate, since before transcoding it is difficult to now precisely what it will end up being. The way this is estimated was changed in the commit you found, which results in slightly lower estimations. However, this means that there is greater risk that the estimate is lower than actual size. Perhaps that leads to a buffer ovewflow on the M1001.
I'll make a change to this estimation so you can test if this is it.
Here's a branch with the change to file size calculation: fix_wav_m1001. In my tests, the wavs are exactly the same as before the commit you found. Let me know if it fixes the reboots.
I tested both files with WAV playback on the M1001 and M2000 and they both worked. Interestingly, the file size is now 5.3MB for file id 10940 as shown by the Soundbridge.
Excellent. I have to think about how to include this fix, because despite the bug I think the new way of estimating size was more precise. So I will probably try to make an adapted version, which I hope you will test.
Interestingly, the file size is now 5.3MB for file id 10940 as shown by the Soundbridge.
Yes, this file size comes from the RSP metadata requests (so not the wav header). I think the Soundbridge only uses that size for display, so it doesn't really matter what it is.
Excellent. I have to think about how to include this fix, because despite the bug I think the new way of estimating size was more precise. So I will probably try to make an adapted version, which I hope you will test.
I will be happy to test.
Can I ask you to share the length of the track that wasn't working? I need it to check if my theory about the size calculation holds up. It has to be the length that OwnTone has in its db, which you can find from the length_ms field returned by http://localhost:3689/api/library/tracks/10940.
The track id changed. I removed my database files and rebuilt. Below is the first track I was playing.
{ "id": 10977, "title": "Thunderstruck (Intro)", "title_sort": "Thunderstruck (Intro)", "artist": "2Cellos", "artist_sort": "00002Cellos", "album": "Celloverse", "album_sort": "Celloverse", "album_id": "1630421823034735917", "album_artist": "2Cellos", "album_artist_sort": "00002Cellos", "album_artist_id": "7873393218485916779", "genre": "Pop", "year": 2015, "track_number": 3, "disc_number": 1, "length_ms": 32466, "rating": 0, "play_count": 1, "skip_count": 0, "time_played": "2024-06-22T22:31:34Z", "time_added": "2024-06-21T14:18:46Z", "date_released": "2015-01-01", "seek_ms": 0, "type": "flac", "samplerate": 44100, "bitrate": 617, "channels": 2, "usermark": 0, "media_kind": "music", "data_kind": "file", "path": "\/var\/autofs\/removable\/easystore10TB\/Music\/2Cellos\/2Cellos-Celloverse\/03-Thunderstruck (Intro).flac", "uri": "library:track:10977", "artwork_url": "\/artwork\/item\/10977" }
Ok, then this is a bit different than I expected:
Actual size (according to your post above): 5727164
Old estimation size (which is the one that is working): 5644844
New estimation size (which crashes the M1001): 5726870
Reference size calculation: 32466 * 44100 * 2 * 2 / 1000 + 44 = 5727046
(2 channels, 2 bytes per sample, 44 bytes WAV header size)
Clearly the old method is the most imprecise. It is also below the actual, so I don't understand why the M1001 is happy with that, but not with the new method which is just slightly below actual. Maybe there is something I'm not seeing.
Would it be worth comparing to the size that ffmpeg uses? Since that works as well on the M1001.
The only difference I am aware of in the software between M1001 and M2000 is the M1001 has to resample everything to 48kHz and the M2000/M1000/M500 do not. If I had to guess it is the resampling algorithm that is causing the reboot.
OK, it took me a bit because there appears to be some additional data in the header that most online sources don't mention, LIST vs data. The size of the WAV data according to ffmpeg is 5727120.
000000a0: 7666 3630 2e33 2e31 3030 0000 6461 7461 vf60.3.100..data
000000b0: 9063 5700 0000 0100 0100 0000 0000 0100 .cW.............
Given that I don't think the problem is over or under as the working is 5644844 and 5727120 and the non working is in between at 5726870. Might it be the file size field? I am making the assumption that owntone passes the wav file directly.
When ffmpeg creates a wav file it has the luxury of being able to write the header after the decoding, thus being able to write the precise file size. OwnTone can't do that since it is sending & decoding on the fly. The problem is a bit the same as with the ALAC headers. So looking at ffmpeg's version doesn't help that much.
I didn't quite understand your last message - what file are you looking at there? What do you mean "passes the wav file directly"?
I would like to know how your speakers react to the wav files having just 0 in the wav header size fields. I think that really would be more clean than putting an estimate. Can you check out the latest commit from the fix_wav_m1001 branch and test with that? If you want to check the file, you can download it with curl and use xxd to check that bytes 5-8 are 0.
So looking at ffmpeg's version doesn't help that much.
Sorry, it's another data point that might give some insight into the problem.
I didn't quite understand your last message - what file are you looking at there? What do you mean "passes the wav file directly"?
I took 03-Thunderstruck (Intro).flac, ffmpeg -i 03-Thunderstruck (Intro).flac 03-Thunderstruck (Intro).wav and ran xxd 03-Thunderstruck\ (Intro).wav | less
I would like to know how your speakers react to the wav files having just 0 in the wav header size fields. I think that really would be more clean than putting an estimate. Can you check out the latest commit from the fix_wav_m1001 branch and test with that? If you want to check the file, you can download it with curl and use xxd to check that bytes 5-8 are 0.
I will do that now.
I would like to know how your speakers react to the wav files having just 0 in the wav header size fields. I think that really would be more clean than putting an estimate. Can you check out the latest commit from the fix_wav_m1001 branch and test with that? If you want to check the file, you can download it with curl and use xxd to check that bytes 5-8 are 0.
Neither the M1001 or M2000 can play any FLAC converted to WAV files now.
Changing the data size back and leaving the file size at 0 works on both the M1001 and M2000.
diff --git a/src/transcode.c b/src/transcode.c
index 3af6e68b..41e5807b 100644
--- a/src/transcode.c
+++ b/src/transcode.c
@@ -1105,7 +1105,7 @@ make_wav_header(struct evbuffer **wav_header, int sample_rate, int bytes_per_sam
add_le16(header + 32, channels * bytes_per_sample); /* block align */
add_le16(header + 34, 8 * bytes_per_sample); /* bits per sample */
memcpy(header + 36, "data", 4);
- add_le32(header + 40, 0); // Size is unknown so set to zero
+ add_le32(header + 40, bytes_total - WAV_HEADER_LEN); // Size is unknown so set to zero
*wav_header = evbuffer_new();
evbuffer_add(*wav_header, header, sizeof(header));
Ok, interesting. So they are probably not using the file size. Just to try the opposite option, I have just now pushed a commit that basically sets these sizes to the maximum possible. Could you also give that try? They might not like it, but let's see :-)
Ok, interesting. So they are probably not using the file size. Just to try the opposite option, I have just now pushed a commit that basically sets these sizes to the maximum possible. Could you also give that try? They might not like it, but let's see :-)
They do not care that you are abusing them and play fine.
Does switching tracks also work? I'm thinking if these large header sizes cause them to expect more data and thus not detect EOF/switch track.
Does switching tracks also work?
Next and previous buttons work as expected on both.
I meant automatic switching tracks during playback: That the speaker proceeds to the next track when it is done playing a track. If the speaker believes there is more data to come it might not go to the next track.
Sorry, automatic next track works fine on both.
Great, that is promising. I actually have one more method I hope you can try, this one uses a calculation that is the most precise that I can think of. It also tries to make sure that the result is "frame aligned", i.e. the size is a multiple of channels x bytes_per_sample (so a multiple of 4). Maybe that was actually the root cause of the reboots.
Winner, winner, chicken dinner. Works on both.
Nice. I will clean it up and go with that then. Thanks for the quick testing!