Decode error at end of file stops playback in nup-headless #142

derat commented 2026年03月29日 05:39:44 +02:00

I heard playback stop and saw this in the logs:

21:07:26 Created decoder for /var/cache/nup/5815136073809920.mp3 (3m31.409s, 44.1kHz stereo, 18646272 samples)
21:07:45 Switching to /var/cache/nup/5815136073809920.mp3
...
21:09:31 Reporting play of 5815136073809920 at ...
21:09:32 Reported play successfully
...
21:10:59 Set next to /var/cache/nup/6292925507960832.mp3
21:10:59 Created decoder for /var/cache/nup/6292925507960832.mp3 (2m30.914s, 44.1kHz stereo, 13310594 samples)
21:11:17 Failed decoding /var/cache/nup/5815136073809920.mp3: mp3dec_ex_read returned E_DECODE
21:11:17 Failed decoding /var/cache/nup/5815136073809920.mp3: mp3dec_ex_read returned E_DECODE
21:11:17 Failed decoding /var/cache/nup/5815136073809920.mp3: mp3dec_ex_read returned E_DECODE
...
21:12:00 Failed decoding /var/cache/nup/5815136073809920.mp3: mp3dec_ex_read returned E_DECODE
21:12:00 Failed decoding /var/cache/nup/5815136073809920.mp3: mp3dec_ex_read returned E_DECODE

When I manually switched to the next track, 6292925507960832.mp3 played without any problems.

I wrote a tiny program that used minimp3.Decoder to decode the same file to a bytes.Buffer using io.Copy, and it was able to do so without any problems. I was able to repro it by reading from the decoder 4 bytes at a time, though:

2026年03月28日 21:32:17 Created decoder for ... (3m31.409s, 44.1kHz stereo, 18646272 samples)
2026年03月28日 21:32:19 Read failed at 9323136: mp3dec_ex_read returned E_DECODE

So it happened at the end of the decoded audio. I suspect that this wasn't anything to do with this particular audio file, and that I just got unlucky with where the reads happened to line up. I should figure out why mp3dec_ex_read set last_error to E_DECODE instead of leaving it at 0 and returning 0 (for the number of decoded samples), which is how I usually detect EOF.

I also need to fix audio.Feeder so it skips to the next track on decode failure instead of just logging the same error indefinitely.

I heard playback stop and saw this in the logs: ``` 21:07:26 Created decoder for /var/cache/nup/5815136073809920.mp3 (3m31.409s, 44.1kHz stereo, 18646272 samples) 21:07:45 Switching to /var/cache/nup/5815136073809920.mp3 ... 21:09:31 Reporting play of 5815136073809920 at ... 21:09:32 Reported play successfully ... 21:10:59 Set next to /var/cache/nup/6292925507960832.mp3 21:10:59 Created decoder for /var/cache/nup/6292925507960832.mp3 (2m30.914s, 44.1kHz stereo, 13310594 samples) 21:11:17 Failed decoding /var/cache/nup/5815136073809920.mp3: mp3dec_ex_read returned E_DECODE 21:11:17 Failed decoding /var/cache/nup/5815136073809920.mp3: mp3dec_ex_read returned E_DECODE 21:11:17 Failed decoding /var/cache/nup/5815136073809920.mp3: mp3dec_ex_read returned E_DECODE ... 21:12:00 Failed decoding /var/cache/nup/5815136073809920.mp3: mp3dec_ex_read returned E_DECODE 21:12:00 Failed decoding /var/cache/nup/5815136073809920.mp3: mp3dec_ex_read returned E_DECODE ``` When I manually switched to the next track, `6292925507960832.mp3` played without any problems. I wrote a tiny program that used `minimp3.Decoder` to decode the same file to a `bytes.Buffer` using `io.Copy`, and it was able to do so without any problems. I was able to repro it by reading from the decoder 4 bytes at a time, though: ``` 2026年03月28日 21:32:17 Created decoder for ... (3m31.409s, 44.1kHz stereo, 18646272 samples) 2026年03月28日 21:32:19 Read failed at 9323136: mp3dec_ex_read returned E_DECODE ``` So it happened at the end of the decoded audio. I suspect that this wasn't anything to do with this particular audio file, and that I just got unlucky with where the reads happened to line up. I should figure out why `mp3dec_ex_read` set `last_error` to `E_DECODE` instead of leaving it at 0 and returning 0 (for the number of decoded samples), which is how I usually detect EOF. I also need to fix `audio.Feeder` so it skips to the next track on decode failure instead of just logging the same error indefinitely.

derat commented 2026年03月29日 05:46:16 +02:00

I take it back; I think there's something weird about this file. I tried reading larger chunks, up to 32 KiB, and still saw E_DECODE. Then I tried using io.Copy(io.Discard, dec) and still got E_DECODE. Using io.Copy to copy to a bytes.Buffer succeeds, though. Huh?

I take it back; I think there's something weird about this file. I tried reading larger chunks, up to 32 KiB, and still saw `E_DECODE`. Then I tried using `io.Copy(io.Discard, dec)` and still got `E_DECODE`. Using `io.Copy` to copy to a `bytes.Buffer` succeeds, though. Huh?

derat commented 2026年03月29日 06:09:10 +02:00

Here's the pattern of Read calls that happens when copying to a bytes.Buffer:

Read(512) = 512, <nil> 
Read(512) = 512, <nil> 
Read(1024) = 1024, <nil> 
Read(2048) = 2048, <nil> 
Read(4096) = 4096, <nil> 
Read(8192) = 8192, <nil> 
Read(16384) = 16384, <nil> 
Read(32768) = 32768, <nil> 
Read(65536) = 65536, <nil> 
Read(131072) = 131072, <nil> 
Read(262144) = 262144, <nil> 
Read(524288) = 524288, <nil> 
Read(1048576) = 1048576, <nil> 
Read(2097152) = 2097152, <nil> 
Read(4194304) = 4194304, <nil> 
Read(8388608) = 8388608, <nil> 
Read(16777216) = 16777216, <nil> 
Read(33554432) = 3738112, <nil> 
Read(29816320) = 0, EOF

Here's the pattern of `Read` calls that happens when copying to a `bytes.Buffer`: ``` Read(512) = 512, <nil> Read(512) = 512, <nil> Read(1024) = 1024, <nil> Read(2048) = 2048, <nil> Read(4096) = 4096, <nil> Read(8192) = 8192, <nil> Read(16384) = 16384, <nil> Read(32768) = 32768, <nil> Read(65536) = 65536, <nil> Read(131072) = 131072, <nil> Read(262144) = 262144, <nil> Read(524288) = 524288, <nil> Read(1048576) = 1048576, <nil> Read(2097152) = 2097152, <nil> Read(4194304) = 4194304, <nil> Read(8388608) = 8388608, <nil> Read(16777216) = 16777216, <nil> Read(33554432) = 3738112, <nil> Read(29816320) = 0, EOF ```

derat commented 2026年03月29日 15:32:34 +02:00

Seems like the problem occurs when the final read occurs too close to the end of the audio data. There are 18646272 samples, so 37292544 bytes of audio data. If I read with a buffer that's 37287938 bytes (37292544-4606) or slightly larger, I get E_DECODE. At 37287937 (37292544-4607) or smaller, it succeeds. At exactly 37292544, it fails. At 37292546 (37292544+2) or larger, it succeeds. My guess would be that the problem occurs when the read starts within the final MPEG frame.

Seems like the problem occurs when the final read occurs too close to the end of the audio data. There are 18646272 samples, so 37292544 bytes of audio data. If I read with a buffer that's 37287938 bytes (37292544-4606) or slightly larger, I get `E_DECODE`. At 37287937 (37292544-4607) or smaller, it succeeds. At exactly 37292544, it fails. At 37292546 (37292544+2) or larger, it succeeds. My guess would be that the problem occurs when the read starts within the final MPEG frame.

derat commented 2026年03月29日 15:37:53 +02:00

I should still figure out what's weird about this file. Other songs from the same album also fail when I read with a 2048-byte buffer, but I haven't noticed the problem with any other random files yet. I noticed that the bad files don't have Xing headers, but some other files without Xing headers decode successfully.

I should still figure out what's weird about this file. Other songs from the same album also fail when I read with a 2048-byte buffer, but I haven't noticed the problem with any other random files yet. I noticed that the bad files don't have Xing headers, but some other files without Xing headers decode successfully.

derat commented 2026年03月29日 18:41:19 +02:00

minimp3_ex.h looks like it tries to return MP3D_E_DECODE for sampling rate changes, layer changes, or channel changes (if MINIMP3_ALLOW_MONO_STEREO_TRANSITION isn't defined). mp3dec_ex_read_frame sees the rate and layer change from 44100 and 3 to 0, probably because it couldn't decode a frame.

The beginning of mp3dec_ex_read_frame tries to bail out if all samples have already been decoded:

 if (dec->detected_samples && dec->cur_sample >= dec->detected_samples) 
 return 0; /* at end of stream */

It looks like detected_samples only gets set if there's a VBR tag, which isn't going to be happening with these files.

`minimp3_ex.h` looks like it tries to return `MP3D_E_DECODE` for sampling rate changes, layer changes, or channel changes (if `MINIMP3_ALLOW_MONO_STEREO_TRANSITION` isn't defined). `mp3dec_ex_read_frame` sees the rate and layer change from 44100 and 3 to 0, probably because it couldn't decode a frame. The beginning of `mp3dec_ex_read_frame` tries to bail out if all samples have already been decoded: ```c if (dec->detected_samples && dec->cur_sample >= dec->detected_samples) return 0; /* at end of stream */ ``` It looks like `detected_samples` only gets set if there's a VBR tag, which isn't going to be happening with these files.

derat commented 2026年03月30日 02:39:38 +02:00

I doubt I'll spend any more time looking into why minimp3 is returning an error here. As long as it only happens at the end of the file, it seems harmless now.

I doubt I'll spend any more time looking into why minimp3 is returning an error here. As long as it only happens at the end of the file, it seems harmless now.