Playing track in single mode results in incomplete play

[owl770]

Bug report

Describe the bug

Setup: repeat=0, single=1, consume=1
If the playlist contains one track, it is played correctly (to the end).
If the playlist contains more than one track, the single track is not played to the end. With my sample track, it plays around 1.8 seconds of a 2.76 second track.
This behaviour starts with version 0.21. It did not exist in 0.20.
It is reproducible 100% of the time (in my environment at least).

The sample track is:
https://www.dropbox.com/s/wnyavo8blzal8oz/e98603d0ab460dd17a6cfdae2b3e61a2.mp3?dl=0

The script I use to reproduce the problem is:
export MPD_PORT=6601
LOG=/var/log/mpd/mpd1.log
TRACK=_not_music/e98603d0ab460dd17a6cfdae2b3e61a2.mp3

set -x
mpc -p $MPD_PORT clear
sudo killall mpd
sudo rm $LOG
sudo mpd_init
sleep 5
cp $LOG /tmp/mpd1.log.straight_after_startup
mpc add $TRACK
mpc add $TRACK
mpc repeat on
mpc single off
mpc consume on
sleep 5
cp $LOG /tmp/mpd1.log.before_first_play
mpc play
echo "Press when playing stopped"
read A
cp $LOG /tmp/mpd1.log.after_first_play
mpc add $TRACK
mpc add $TRACK
mpc repeat off
mpc single on
sleep 5
cp $LOG /tmp/mpd1.log.before_second_play
mpc play
echo "Press when playing stopped"
read A
cp $LOG /tmp/mpd1.log.after_second_play
mpc play
echo "Press when playing stopped"
read A
cp $LOG /tmp/mpd1.log.after_third_play

Background (in case you are interested)

I use MPD to pipe music through the house (various instances of MPD driving different sets of speakers). I have Raspberry Pi's in my house that monitor various functions (eg. internet access, power usage, number plate recognition for announcing arrivals etc). When an 'announcement' needs to be made, it uses voicerss.org to convert the text to an MP3 file. This is added to MPD, inserted into the playlist, the new track is played in single mode (repeat off and consume on so that the inserted track gets removed from the playlist) and then resumes playback from where it left off. It works perfectly in terms of alerting us (audibly) to events that occur.

Expected Behavior

If the playlist contains more than one track and is in single mode, the playing track should play to the end.

Actual Behavior

If the playlist contains more than one track and is in single mode, the playing track is cut short.

Version

Music Player Daemon 0.21.22 (0.21.22)
Copyright 2003-2007 Warren Dukes warren.dukes@gmail.com
Copyright 2008-2018 Max Kellermann max.kellermann@gmail.com
This is free software; see the source for copying conditions. There is NO
warranty; not even MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.

Database plugins:
simple proxy upnp

Storage plugins:
local smbclient udisks nfs curl

Neighbor plugins:
smbclient upnp udisks

Decoders plugins:
[mad] mp3 mp2
[mpg123] mp3
[vorbis] ogg oga
[oggflac] ogg oga
[flac] flac
[opus] opus ogg oga
[sndfile] wav aiff aif au snd paf iff svx sf voc w64 pvf xi htk caf sd2
[audiofile] wav au aiff aif
[dsdiff] dff
[dsf] dsf
[hybrid_dsd] m4a
[faad] aac
[mpcdec] mpc
[wavpack] wv
[modplug] 669 amf ams dbm dfm dsm far it med mdl mod mtm mt2 okt s3m stm ult umx xm
[mikmod] amf dsm far gdm imf it med mod mtm s3m stm stx ult uni xm
[sidplay] sid mus str prg P00
[wildmidi] mid
[fluidsynth] mid
[adplug] amd d00 hsc laa rad raw sa2
[ffmpeg] 16sv 3g2 3gp 4xm 8svx aa3 aac ac3 adx afc aif aifc aiff al alaw amr anim apc ape asf atrac au aud avi avm2 avs bap bfi c93 cak cin cmv cpk daud dct divx dts dv dvd dxa eac3 film flac flc fli fll flx flv g726 gsm gxf iss m1v m2v m2t m2ts m4a m4b m4v mad mj2 mjpeg mjpg mka mkv mlp mm mmf mov mp+ mp1 mp2 mp3 mp4 mpc mpeg mpg mpga mpp mpu mve mvi mxf nc nsv nut nuv oga ogm ogv ogx oma ogg omg opus psp pva qcp qt r3d ra ram rl2 rm rmvb roq rpl rvc shn smk snd sol son spx str swf tak tgi tgq tgv thp ts tsp tta xa xvid uv uv2 vb vid vob voc vp6 vmd wav webm wma wmv wsaud wsvga wv wve
[gme] ay gbs gym hes kss nsf nsfe sap spc vgm vgz
[pcm]

Filters:
libsamplerate soxr

Tag plugins:
id3tag

Output plugins:
shout null fifo sndio pipe alsa ao openal pulse jack httpd recorder

Encoder plugins:
null vorbis opus lame twolame wave flac shine

Archive plugins:
[bz2] bz2
[zzip] zip
[iso] iso

Input plugins:
file archive alsa tidal qobuz curl ffmpeg smbclient nfs mms cdio_paranoia

Playlist plugins:
extm3u m3u pls xspf asx rss soundcloud flac cue embcue

Protocols:
file:// alsa:// tidal:// qobuz:// http:// https:// gopher:// rtp:// rtsp:// rtmp:// rtmpt:// rtmps:// smb:// nfs:// mms:// mmsh:// mmst:// mmsu:// cdda://

Other features:
avahi dbus udisks epoll icu inotify ipv6 systemd tcp un

Config

music_directory "/media/nas001/music/songs"
playlist_directory "/media/nas001/music/playlists"
db_file "/var/lib/mpd/tag_cache"
log_file "/var/log/mpd/mpd1.log"
pid_file "/var/run/mpd/pid1"
state_file "/var/lib/mpd/state1"
sticker_file "/var/lib/mpd/sticker.sql"
user "mpd"
bind_to_address "any"
port "6601"
log_level "verbose"
zeroconf_enabled "yes"
zeroconf_name "Music Player 1.1"
input {
plugin "curl"
}
audio_output {
type "alsa"
name "Deck"
auto_resample "no"
device "hw:12,0" # optional
}
audio_output {
type "alsa"
name "Kitchen/Dining"
auto_resample "no"
device "hw:14,0" # optional
}
audio_output {
type "alsa"
name "Lounge"
auto_resample "no"
device "hw:15,0" # optional
}
audio_output {
type "httpd"
name "Whole House"
port "8888"
bitrate "128" # do not define if quality is defined
}
audio_output_format "96000:24:2"
mixer_type "software"
volume_normalization "yes"
audio_buffer_size "10240"
max_connections "20"
filesystem_charset "UTF-8"

Log

Apr 13 10:48 : avahi: Initializing interface
Apr 13 10:48 : avahi: Client changed to state 2
Apr 13 10:48 : avahi: Client is RUNNING
Apr 13 10:48 : avahi: Registering service _mpd._tcp/Music Player 1.1
Apr 13 10:48 : avahi: Service group changed to state 0
Apr 13 10:48 : avahi: Service group is UNCOMMITED
Apr 13 10:48 : state_file: Loading state file /var/lib/mpd/state1
Apr 13 10:48 : avahi: Service group changed to state 1
Apr 13 10:48 : avahi: Service group is REGISTERING
Apr 13 10:48 : avahi: Service group changed to state 2
Apr 13 10:48 : avahi: Service 'Music Player 1.1' successfully established.
Apr 13 10:48 : client: [0] opened from 127.0.0.1:47322
Apr 13 10:48 : client: [0] process command "idle database"
Apr 13 10:48 : client: [0] command returned 1
Apr 13 10:48 : client: [1] opened from 127.0.0.1:43816
Apr 13 10:48 : client: [1] process command list
Apr 13 10:48 : client: process command "add "_not_music/e98603d0ab460dd17a6cfdae2b3e61a2.mp3""
Apr 13 10:48 : client: command returned 0
Apr 13 10:48 : client: [1] process command list returned 0
Apr 13 10:48 : client: [1] closed
Apr 13 10:48 : client: [2] opened from 127.0.0.1:43818
Apr 13 10:48 : client: [2] process command list
Apr 13 10:48 : client: process command "add "_not_music/e98603d0ab460dd17a6cfdae2b3e61a2.mp3""
Apr 13 10:48 : client: command returned 0
Apr 13 10:48 : client: [2] process command list returned 0
Apr 13 10:48 : client: [2] closed
Apr 13 10:48 : client: [3] opened from 127.0.0.1:43820
Apr 13 10:48 : client: [3] process command "repeat "1""
Apr 13 10:48 : client: [3] command returned 0
Apr 13 10:48 : client: [3] process command list
Apr 13 10:48 : client: process command "status"
Apr 13 10:48 : client: command returned 0
Apr 13 10:48 : client: process command "currentsong"
Apr 13 10:48 : client: command returned 0
Apr 13 10:48 : client: [3] process command list returned 0
Apr 13 10:48 : client: [3] closed
Apr 13 10:48 : client: [4] opened from 127.0.0.1:43822
Apr 13 10:48 : client: [4] process command "single "0""
Apr 13 10:48 : client: [4] command returned 0
Apr 13 10:48 : client: [4] process command list
Apr 13 10:48 : client: process command "status"
Apr 13 10:48 : client: command returned 0
Apr 13 10:48 : client: process command "currentsong"
Apr 13 10:48 : client: command returned 0
Apr 13 10:48 : client: [4] process command list returned 0
Apr 13 10:48 : client: [4] closed
Apr 13 10:48 : client: [5] opened from 127.0.0.1:43824
Apr 13 10:48 : client: [5] process command "consume "1""
Apr 13 10:48 : client: [5] command returned 0
Apr 13 10:48 : client: [5] process command list
Apr 13 10:48 : client: process command "status"
Apr 13 10:48 : client: command returned 0
Apr 13 10:48 : client: process command "currentsong"
Apr 13 10:48 : client: command returned 0
Apr 13 10:48 : client: [5] process command list returned 0
Apr 13 10:48 : client: [5] closed
Apr 13 10:48 : state_file: Saving state file /var/lib/mpd/state1
Apr 13 10:48 : client: [6] opened from 127.0.0.1:43826
Apr 13 10:48 : client: [6] process command "play"
Apr 13 10:48 : playlist: play 0:"_not_music/e98603d0ab460dd17a6cfdae2b3e61a2.mp3"
Apr 13 10:48 : client: [6] command returned 0
Apr 13 10:48 : playlist: queue song 1:"_not_music/e98603d0ab460dd17a6cfdae2b3e61a2.mp3"
Apr 13 10:48 : client: [6] process command list
Apr 13 10:48 : client: process command "status"
Apr 13 10:48 : client: command returned 0
Apr 13 10:48 : client: process command "currentsong"
Apr 13 10:48 : client: command returned 0
Apr 13 10:48 : client: [6] process command list returned 0
Apr 13 10:48 : decoder_thread: probing plugin mad
Apr 13 10:48 : client: [6] closed
Apr 13 10:48 : decoder: audio_format=48000:24:2, seekable=true
Apr 13 10:48 : decoder: converting to 96000:24:2
Apr 13 10:48 : libsamplerate: setting samplerate conversion ratio to 2.00
Apr 13 10:48 : alsa_output: opened hw:14,0 type=HW
Apr 13 10:48 : alsa_output: buffer: size=192..174762 time=2000..1820438
Apr 13 10:48 : alsa_output: period: size=96..87381 time=1000..910219
Apr 13 10:48 : alsa_output: default period_time = buffer_time/4 = 500000/4 = 125000
Apr 13 10:48 : alsa_output: format=S24_3LE (Signed 24 bit Little Endian in 3bytes)
Apr 13 10:48 : alsa_output: buffer_size=48000 period_size=12000
Apr 13 10:48 : output: opened "Kitchen/Dining" (alsa) audio_format=96000:24:2
Apr 13 10:48 : output: converting in=96000:24:2 -> f=96000:16:2 -> out=96000:24:2
Apr 13 10:48 : alsa_output: opened hw:15,0 type=HW
Apr 13 10:48 : alsa_output: buffer: size=192..174762 time=2000..1820438
Apr 13 10:48 : alsa_output: period: size=96..87381 time=1000..910219
Apr 13 10:48 : alsa_output: default period_time = buffer_time/4 = 500000/4 = 125000
Apr 13 10:48 : alsa_output: format=S24_3LE (Signed 24 bit Little Endian in 3bytes)
Apr 13 10:48 : alsa_output: buffer_size=48000 period_size=12000
Apr 13 10:48 : output: opened "Lounge" (alsa) audio_format=96000:24:2
Apr 13 10:48 : output: converting in=96000:24:2 -> f=96000:16:2 -> out=96000:24:2
Apr 13 10:48 : decoder_thread: probing plugin mad
Apr 13 10:48 : decoder: audio_format=48000:24:2, seekable=true
Apr 13 10:48 : decoder: converting to 96000:24:2
Apr 13 10:48 : libsamplerate: setting samplerate conversion ratio to 2.00
Apr 13 10:48 : player: played "_not_music/e98603d0ab460dd17a6cfdae2b3e61a2.mp3"
Apr 13 10:48 : state_file: Saving state file /var/lib/mpd/state1
Apr 13 10:48 : player: played "_not_music/e98603d0ab460dd17a6cfdae2b3e61a2.mp3"
Apr 13 10:48 : playlist: stop
Apr 13 10:48 : output: closed "Kitchen/Dining" (alsa)
Apr 13 10:48 : output: closed "Lounge" (alsa)
Apr 13 10:48 : client: [7] opened from 127.0.0.1:43828
Apr 13 10:48 : client: [7] process command list
Apr 13 10:48 : client: process command "add "_not_music/e98603d0ab460dd17a6cfdae2b3e61a2.mp3""
Apr 13 10:48 : client: command returned 0
Apr 13 10:48 : client: [7] process command list returned 0
Apr 13 10:48 : client: [7] closed
Apr 13 10:48 : client: [8] opened from 127.0.0.1:43830
Apr 13 10:48 : client: [8] process command list
Apr 13 10:48 : client: process command "add "_not_music/e98603d0ab460dd17a6cfdae2b3e61a2.mp3""
Apr 13 10:48 : client: command returned 0
Apr 13 10:48 : client: [8] process command list returned 0
Apr 13 10:48 : client: [8] closed
Apr 13 10:48 : client: [9] opened from 127.0.0.1:43832
Apr 13 10:48 : client: [9] process command "repeat "0""
Apr 13 10:48 : client: [9] command returned 0
Apr 13 10:48 : client: [9] process command list
Apr 13 10:48 : client: process command "status"
Apr 13 10:48 : client: command returned 0
Apr 13 10:48 : client: process command "currentsong"
Apr 13 10:48 : client: command returned 0
Apr 13 10:48 : client: [9] process command list returned 0
Apr 13 10:48 : client: [9] closed
Apr 13 10:48 : client: [10] opened from 127.0.0.1:43834
Apr 13 10:48 : client: [10] process command "single "1""
Apr 13 10:48 : client: [10] command returned 0
Apr 13 10:48 : client: [10] process command list
Apr 13 10:48 : client: process command "status"
Apr 13 10:48 : client: command returned 0
Apr 13 10:48 : client: process command "currentsong"
Apr 13 10:48 : client: command returned 0
Apr 13 10:48 : client: [10] process command list returned 0
Apr 13 10:48 : client: [10] closed
Apr 13 10:48 : state_file: Saving state file /var/lib/mpd/state1
Apr 13 10:48 : client: [11] opened from 127.0.0.1:43836
Apr 13 10:48 : client: [11] process command "play"
Apr 13 10:48 : playlist: play 0:"_not_music/e98603d0ab460dd17a6cfdae2b3e61a2.mp3"
Apr 13 10:48 : client: [11] command returned 0
Apr 13 10:48 : playlist: queue song 1:"_not_music/e98603d0ab460dd17a6cfdae2b3e61a2.mp3"
Apr 13 10:48 : client: [11] process command list
Apr 13 10:48 : client: process command "status"
Apr 13 10:48 : client: command returned 0
Apr 13 10:48 : client: process command "currentsong"
Apr 13 10:48 : decoder_thread: probing plugin mad
Apr 13 10:48 : client: command returned 0
Apr 13 10:48 : client: [11] process command list returned 0
Apr 13 10:48 : decoder: audio_format=48000:24:2, seekable=true
Apr 13 10:48 : decoder: converting to 96000:24:2
Apr 13 10:48 : libsamplerate: setting samplerate conversion ratio to 2.00
Apr 13 10:48 : alsa_output: opened hw:14,0 type=HW
Apr 13 10:48 : alsa_output: buffer: size=192..174762 time=2000..1820438
Apr 13 10:48 : alsa_output: period: size=96..87381 time=1000..910219
Apr 13 10:48 : alsa_output: default period_time = buffer_time/4 = 500000/4 = 125000
Apr 13 10:48 : alsa_output: format=S24_3LE (Signed 24 bit Little Endian in 3bytes)
Apr 13 10:48 : alsa_output: buffer_size=48000 period_size=12000
Apr 13 10:48 : output: opened "Kitchen/Dining" (alsa) audio_format=96000:24:2
Apr 13 10:48 : output: converting in=96000:24:2 -> f=96000:16:2 -> out=96000:24:2
Apr 13 10:48 : alsa_output: opened hw:15,0 type=HW
Apr 13 10:48 : alsa_output: buffer: size=192..174762 time=2000..1820438
Apr 13 10:48 : alsa_output: period: size=96..87381 time=1000..910219
Apr 13 10:48 : alsa_output: default period_time = buffer_time/4 = 500000/4 = 125000
Apr 13 10:48 : alsa_output: format=S24_3LE (Signed 24 bit Little Endian in 3bytes)
Apr 13 10:48 : alsa_output: buffer_size=48000 period_size=12000
Apr 13 10:48 : output: opened "Lounge" (alsa) audio_format=96000:24:2
Apr 13 10:48 : output: converting in=96000:24:2 -> f=96000:16:2 -> out=96000:24:2
Apr 13 10:48 : client: [11] closed
Apr 13 10:48 : decoder_thread: probing plugin mad
Apr 13 10:48 : decoder: audio_format=48000:24:2, seekable=true
Apr 13 10:48 : decoder: converting to 96000:24:2
Apr 13 10:48 : libsamplerate: setting samplerate conversion ratio to 2.00
Apr 13 10:48 : player: played "_not_music/e98603d0ab460dd17a6cfdae2b3e61a2.mp3"
Apr 13 10:48 : output: closed "Kitchen/Dining" (alsa)
Apr 13 10:48 : output: closed "Lounge" (alsa)
Apr 13 10:48 : client: [12] opened from 127.0.0.1:43838
Apr 13 10:48 : client: [12] process command "play"
Apr 13 10:48 : alsa_output: opened hw:14,0 type=HW
Apr 13 10:48 : alsa_output: buffer: size=192..174762 time=2000..1820438
Apr 13 10:48 : alsa_output: period: size=96..87381 time=1000..910219
Apr 13 10:48 : alsa_output: default period_time = buffer_time/4 = 500000/4 = 125000
Apr 13 10:48 : alsa_output: format=S24_3LE (Signed 24 bit Little Endian in 3bytes)
Apr 13 10:48 : alsa_output: buffer_size=48000 period_size=12000
Apr 13 10:48 : output: opened "Kitchen/Dining" (alsa) audio_format=96000:24:2
Apr 13 10:48 : output: converting in=96000:24:2 -> f=96000:16:2 -> out=96000:24:2
Apr 13 10:48 : alsa_output: opened hw:15,0 type=HW
Apr 13 10:48 : alsa_output: buffer: size=192..174762 time=2000..1820438
Apr 13 10:48 : alsa_output: period: size=96..87381 time=1000..910219
Apr 13 10:48 : alsa_output: default period_time = buffer_time/4 = 500000/4 = 125000
Apr 13 10:48 : alsa_output: format=S24_3LE (Signed 24 bit Little Endian in 3bytes)
Apr 13 10:48 : alsa_output: buffer_size=48000 period_size=12000
Apr 13 10:48 : output: opened "Lounge" (alsa) audio_format=96000:24:2
Apr 13 10:48 : output: converting in=96000:24:2 -> f=96000:16:2 -> out=96000:24:2
Apr 13 10:48 : client: [12] command returned 0
Apr 13 10:48 : client: [12] process command list
Apr 13 10:48 : client: process command "status"
Apr 13 10:48 : client: command returned 0
Apr 13 10:48 : client: process command "currentsong"
Apr 13 10:48 : client: command returned 0
Apr 13 10:48 : client: [12] process command list returned 0
Apr 13 10:48 : client: [12] closed
Apr 13 10:48 : state_file: Saving state file /var/lib/mpd/state1
Apr 13 10:48 : player: played "_not_music/e98603d0ab460dd17a6cfdae2b3e61a2.mp3"
Apr 13 10:48 : playlist: stop
Apr 13 10:48 : output: closed "Kitchen/Dining" (alsa)
Apr 13 10:48 : output: closed "Lounge" (alsa)