savonet / liquidsoap

Liquidsoap is a statically typed scripting general-purpose language with dedicated operators and backend for all thing media, streaming, file generation, automation, HTTP backend and more.
http://liquidsoap.info
GNU General Public License v2.0
1.4k stars 130 forks source link

Playlist reload + preload lead to tracks played twice #195

Closed giflw closed 9 years ago

giflw commented 9 years ago

liquidsoap version: 1.1.1

Using the script below, i copy 2 songs in a folder (/tmp/music).

pls = playlist(mode="normal", reload=1, reload_mode="rounds",  "/tmp/music")
out(pls)

After deleting one file and and copying it again to the music folder, playlist reloads 2 files, but play the deleted file twice. If I delete the file and copy it again, that file is played tree times.

Same occurs if I use randomize mode.

liquidsoap log:

2014/11/06 22:35:30 >>> LOG START
2014/11/06 22:35:30 [protocols.external:3] Found "/usr/bin/wget".
2014/11/06 22:35:30 [main:3] Liquidsoap 1.1.1
2014/11/06 22:35:30 [main:3] Using: graphics=[distributed with Ocaml] pcre=7.0.2 dtools=0.3.1 duppy=0.5.1 duppy.syntax=0.5.1 cry=0.2.2 mm=0.2.1 xmlplaylist=0.1.3 lastfm=0.3.0 ogg=0.4.5 vorbis=0.6.1 opus=0.1.0 speex=0.2.0 mad=0.4.4 flac=0.1.1 flac.ogg=0.1.1 dynlink=[distributed with Ocaml] lame=0.3.2 shine=0.1.1 gstreamer=0.2.0 frei0r=0.1.0 voaacenc=0.1.0 theora=0.3.0 schroedinger=0.1.0 gavl=0.1.5 bjack=0.1.4 alsa=0.2.1 ao=0.2.0 samplerate=0.1.2 taglib=0.3.1 magic=0.7.3 camomile=0.8.4 inotify=1.0 faad=0.3.2 soundtouch=0.1.7 portaudio=0.2.0 pulseaudio=0.1.2 ladspa=0.1.4 dssi=0.1.1 sdl=0.9.1 camlimages=4.0.0 lo=0.1.0 yojson=1.1.7 gd=1.0a5
2014/11/06 22:35:30 [dynamic.loader:3] Could not find dynamic module for fdkaac encoder.
2014/11/06 22:35:30 [dynamic.loader:3] Could not find dynamic module for aacplus encoder.
2014/11/06 22:35:30 [dynamic.loader:2] Loaded plugin file /usr/lib/liquidsoap/1.1.1/plugins/voaacenc.cmxs.
2014/11/06 22:35:30 [dynamic.loader:2] Loaded plugin file /usr/lib/liquidsoap/1.1.1/plugins/cry.cmxs.
2014/11/06 22:35:30 [dynamic.loader:2] Loaded plugin file /usr/lib/liquidsoap/1.1.1/plugins/flac.cmxs.
2014/11/06 22:35:30 [dynamic.loader:2] Loaded plugin file /usr/lib/liquidsoap/1.1.1/plugins/lame.cmxs.
2014/11/06 22:35:30 [dynamic.loader:2] Loaded plugin file /usr/lib/liquidsoap/1.1.1/plugins/ogg.cmxs.
2014/11/06 22:35:30 [dynamic.loader:2] Loaded plugin file /usr/lib/liquidsoap/1.1.1/plugins/mad.cmxs.
2014/11/06 22:35:30 [dynamic.loader:2] Loaded plugin file /usr/lib/liquidsoap/1.1.1/plugins/faad.cmxs.
2014/11/06 22:35:30 [dynamic.loader:2] Loaded plugin file /usr/lib/liquidsoap/1.1.1/plugins/flac_ogg.cmxs.
2014/11/06 22:35:30 [dynamic.loader:2] Loaded plugin file /usr/lib/liquidsoap/1.1.1/plugins/pulseaudio.cmxs.
2014/11/06 22:35:30 [dynamic.loader:2] Loaded plugin file /usr/lib/liquidsoap/1.1.1/plugins/taglib.cmxs.
2014/11/06 22:35:30 [dynamic.loader:2] Loaded plugin file /usr/lib/liquidsoap/1.1.1/plugins/vorbis.cmxs.
2014/11/06 22:35:30 [frame:3] Using 44100Hz audio, 25Hz video, 44100Hz master.
2014/11/06 22:35:30 [frame:3] Frame size must be a multiple of 1764 ticks = 1764 audio samples = 1 video samples.
2014/11/06 22:35:30 [frame:3] Targetting 'frame.duration': 0.04s = 1764 audio samples = 1764 ticks.
2014/11/06 22:35:30 [frame:3] Frames last 0.04s = 1764 audio samples = 1 video samples = 1764 ticks.
2014/11/06 22:35:30 [threads:3] Created thread "generic queue #1".
2014/11/06 22:35:30 [threads:3] Created thread "generic queue #2".
2014/11/06 22:35:30 [music:3] Loading playlist...
2014/11/06 22:35:30 [music:3] Playlist is a directory.
2014/11/06 22:35:30 [music:3] Successfully loaded a playlist of 2 tracks.
2014/11/06 22:35:30 [threads:3] Created thread "wallclock_pulse" (1 total).
2014/11/06 22:35:30 [clock.wallclock_pulse:3] Streaming loop starts, synchronized by active sources.
2014/11/06 22:35:30 [decoder:3] Method "MAD" accepted "/tmp/music/Clint_Eastwood.mp3".
2014/11/06 22:35:30 [mksafe:3] Switch to safe_blank.
2014/11/06 22:35:30 [decoder:3] Method "MAD" accepted "/tmp/music/I_dont_wanna_miss_a_thing-Armageddon_soundtrack.mp3".
2014/11/06 22:35:30 [music:3] Prepared "/tmp/music/Clint_Eastwood.mp3" (RID 1).
2014/11/06 22:35:30 [mksafe:3] Switch to music with transition.
2014/11/06 22:39:58 [music:3] Finished with "/tmp/music/Clint_Eastwood.mp3".
2014/11/06 22:39:58 [music:3] Prepared "/tmp/music/I_dont_wanna_miss_a_thing-Armageddon_soundtrack.mp3" (RID 2).
2014/11/06 22:44:49 [music:3] Loading playlist...
2014/11/06 22:44:49 [music:3] Playlist is a directory.
2014/11/06 22:44:49 [music:3] Successfully loaded a playlist of 2 tracks.
2014/11/06 22:44:49 [decoder:3] Method "MAD" accepted "/tmp/music/Clint_Eastwood.mp3".
2014/11/06 22:44:59 [music:3] Finished with "/tmp/music/I_dont_wanna_miss_a_thing-Armageddon_soundtrack.mp3".
2014/11/06 22:44:59 [music:3] Prepared "/tmp/music/Clint_Eastwood.mp3" (RID 3).
2014/11/06 22:49:18 [decoder:3] Method "MAD" accepted "/tmp/music/Clint_Eastwood.mp3".
2014/11/06 22:49:28 [music:3] Finished with "/tmp/music/Clint_Eastwood.mp3".
2014/11/06 22:49:28 [music:3] Prepared "/tmp/music/Clint_Eastwood.mp3" (RID 0).
2014/11/06 22:53:46 [decoder:3] Method "MAD" accepted "/tmp/music/I_dont_wanna_miss_a_thing-Armageddon_soundtrack.mp3".
2014/11/06 22:53:56 [music:3] Finished with "/tmp/music/Clint_Eastwood.mp3".
2014/11/06 22:53:56 [music:3] Prepared "/tmp/music/I_dont_wanna_miss_a_thing-Armageddon_soundtrack.mp3" (RID 1).
2014/11/06 22:58:47 [music:3] Loading playlist...
2014/11/06 22:58:47 [music:3] Playlist is a directory.
2014/11/06 22:58:47 [music:3] Successfully loaded a playlist of 2 tracks.
2014/11/06 22:58:47 [decoder:3] Method "MAD" accepted "/tmp/music/Clint_Eastwood.mp3".
2014/11/06 22:58:57 [music:3] Finished with "/tmp/music/I_dont_wanna_miss_a_thing-Armageddon_soundtrack.mp3".
2014/11/06 22:58:57 [music:3] Prepared "/tmp/music/Clint_Eastwood.mp3" (RID 2).
2014/11/06 23:03:16 [decoder:3] Method "MAD" accepted "/tmp/music/Clint_Eastwood.mp3".
2014/11/06 23:03:26 [music:3] Finished with "/tmp/music/Clint_Eastwood.mp3".
2014/11/06 23:03:26 [music:3] Prepared "/tmp/music/Clint_Eastwood.mp3" (RID 3).
2014/11/06 23:07:44 [decoder:3] Method "MAD" accepted "/tmp/music/I_dont_wanna_miss_a_thing-Armageddon_soundtrack.mp3".
2014/11/06 23:07:54 [music:3] Finished with "/tmp/music/Clint_Eastwood.mp3".
2014/11/06 23:07:54 [music:3] Prepared "/tmp/music/I_dont_wanna_miss_a_thing-Armageddon_soundtrack.mp3" (RID 0).
2014/11/06 23:12:45 [music:3] Loading playlist...
2014/11/06 23:12:45 [music:3] Playlist is a directory.
2014/11/06 23:12:45 [music:3] Successfully loaded a playlist of 2 tracks.
2014/11/06 23:12:45 [decoder:3] Method "MAD" accepted "/tmp/music/Clint_Eastwood.mp3".
2014/11/06 23:12:55 [music:3] Finished with "/tmp/music/I_dont_wanna_miss_a_thing-Armageddon_soundtrack.mp3".
2014/11/06 23:12:55 [music:3] Prepared "/tmp/music/Clint_Eastwood.mp3" (RID 1).
2014/11/06 23:17:13 [decoder:3] Method "MAD" accepted "/tmp/music/Clint_Eastwood.mp3".
2014/11/06 23:17:23 [music:3] Finished with "/tmp/music/Clint_Eastwood.mp3".
2014/11/06 23:17:23 [music:3] Prepared "/tmp/music/Clint_Eastwood.mp3" (RID 2).
2014/11/06 23:21:42 [decoder:3] Method "MAD" accepted "/tmp/music/I_dont_wanna_miss_a_thing-Armageddon_soundtrack.mp3".
2014/11/06 23:21:52 [music:3] Finished with "/tmp/music/Clint_Eastwood.mp3".
2014/11/06 23:21:52 [music:3] Prepared "/tmp/music/I_dont_wanna_miss_a_thing-Armageddon_soundtrack.mp3" (RID 3).
2014/11/06 23:26:43 [music:3] Loading playlist...
2014/11/06 23:26:43 [decoder:3] Method "MAD" accepted "/tmp/music/Clint_Eastwood.mp3".
2014/11/06 23:26:43 [music:3] Playlist is a directory.
2014/11/06 23:26:43 [music:3] Successfully loaded a playlist of 2 tracks.
2014/11/06 23:26:53 [music:3] Finished with "/tmp/music/I_dont_wanna_miss_a_thing-Armageddon_soundtrack.mp3".
2014/11/06 23:26:53 [music:3] Prepared "/tmp/music/Clint_Eastwood.mp3" (RID 0).
2014/11/06 23:31:11 [decoder:3] Method "MAD" accepted "/tmp/music/Clint_Eastwood.mp3".
2014/11/06 23:31:21 [music:3] Finished with "/tmp/music/Clint_Eastwood.mp3".
2014/11/06 23:31:21 [music:3] Prepared "/tmp/music/Clint_Eastwood.mp3" (RID 1).
2014/11/06 23:35:39 [decoder:3] Method "MAD" accepted "/tmp/music/I_dont_wanna_miss_a_thing-Armageddon_soundtrack.mp3".
2014/11/06 23:35:49 [music:3] Finished with "/tmp/music/Clint_Eastwood.mp3".
2014/11/06 23:35:49 [music:3] Prepared "/tmp/music/I_dont_wanna_miss_a_thing-Armageddon_soundtrack.mp3" (RID 2).
2014/11/06 23:40:40 [music:3] Loading playlist...
2014/11/06 23:40:40 [music:3] Playlist is a directory.
2014/11/06 23:40:40 [music:3] Successfully loaded a playlist of 2 tracks.
2014/11/06 23:40:40 [decoder:3] Method "MAD" accepted "/tmp/music/Clint_Eastwood.mp3".
2014/11/06 23:40:51 [music:3] Finished with "/tmp/music/I_dont_wanna_miss_a_thing-Armageddon_soundtrack.mp3".
2014/11/06 23:40:51 [music:3] Prepared "/tmp/music/Clint_Eastwood.mp3" (RID 3).
2014/11/06 23:45:09 [decoder:3] Method "MAD" accepted "/tmp/music/Clint_Eastwood.mp3".
2014/11/06 23:45:19 [music:3] Finished with "/tmp/music/Clint_Eastwood.mp3".
2014/11/06 23:45:19 [music:3] Prepared "/tmp/music/Clint_Eastwood.mp3" (RID 0).
2014/11/06 23:49:37 [decoder:3] Method "MAD" accepted "/tmp/music/I_dont_wanna_miss_a_thing-Armageddon_soundtrack.mp3".
2014/11/06 23:49:47 [music:3] Finished with "/tmp/music/Clint_Eastwood.mp3".
2014/11/06 23:49:47 [music:3] Prepared "/tmp/music/I_dont_wanna_miss_a_thing-Armageddon_soundtrack.mp3" (RID 1).
2014/11/06 23:54:38 [request:3] Nonexistent file or ill-formed URI "/tmp/music/Clint_Eastwood.mp3"!
2014/11/06 23:54:38 [request:3] Nonexistent file or ill-formed URI "/tmp/music/I_dont_wanna_miss_a_thing-Armageddon_soundtrack.mp3"!
2014/11/06 23:54:38 [music:3] Loading playlist...
2014/11/06 23:54:38 [music:3] Playlist is a directory.
2014/11/06 23:54:38 [music:3] Got an empty list: keeping the old one.
2014/11/06 23:54:38 [request:3] Nonexistent file or ill-formed URI "/tmp/music/Clint_Eastwood.mp3"!
2014/11/06 23:54:42 [music:3] Loading playlist...
2014/11/06 23:54:42 [music:3] Playlist is a directory.
2014/11/06 23:54:42 [music:3] Got an empty list: keeping the old one.
2014/11/06 23:54:42 [request:3] Nonexistent file or ill-formed URI "/tmp/music/I_dont_wanna_miss_a_thing-Armageddon_soundtrack.mp3"!
2014/11/06 23:54:42 [music:3] Loading playlist...
2014/11/06 23:54:42 [music:3] Playlist is a directory.
2014/11/06 23:54:42 [music:3] Successfully loaded a playlist of 1 tracks.
2014/11/06 23:54:42 [decoder:3] Method "MAD" accepted "/tmp/music/Clint_Eastwood.mp3".
2014/11/06 23:54:48 [music:1] Finished with a non-existent file?! Something may have been moved or destroyed during decoding. It is VERY dangerous, avoid it!
2014/11/06 23:54:48 [music:3] Prepared "/tmp/music/Clint_Eastwood.mp3" (RID 249).
2014/11/06 23:59:07 [decoder:3] Method "MAD" accepted "/tmp/music/Clint_Eastwood.mp3".
2014/11/06 23:59:17 [music:3] Finished with "/tmp/music/Clint_Eastwood.mp3".
2014/11/06 23:59:17 [music:3] Prepared "/tmp/music/Clint_Eastwood.mp3" (RID 3).
2014/11/07 00:03:35 [music:3] Loading playlist...
2014/11/07 00:03:35 [music:3] Playlist is a directory.
2014/11/07 00:03:35 [music:3] Successfully loaded a playlist of 2 tracks.
2014/11/07 00:03:35 [decoder:3] Method "MAD" accepted "/tmp/music/Clint_Eastwood.mp3".
2014/11/07 00:03:45 [music:3] Finished with "/tmp/music/Clint_Eastwood.mp3".
2014/11/07 00:03:45 [music:3] Prepared "/tmp/music/Clint_Eastwood.mp3" (RID 0).
2014/11/07 00:08:03 [decoder:3] Method "MAD" accepted "/tmp/music/Clint_Eastwood.mp3".
2014/11/07 00:08:13 [music:3] Finished with "/tmp/music/Clint_Eastwood.mp3".
2014/11/07 00:08:13 [music:3] Prepared "/tmp/music/Clint_Eastwood.mp3" (RID 1).
2014/11/07 00:12:32 [decoder:3] Method "MAD" accepted "/tmp/music/Like_A_Stone.mp3".
2014/11/07 00:12:42 [music:3] Finished with "/tmp/music/Clint_Eastwood.mp3".
2014/11/07 00:12:42 [music:3] Prepared "/tmp/music/Like_A_Stone.mp3" (RID 2).
2014/11/07 00:17:31 [decoder:3] Method "MAD" accepted "/tmp/music/Clint_Eastwood.mp3".
2014/11/07 00:17:31 [music:3] Loading playlist...
2014/11/07 00:17:31 [music:3] Playlist is a directory.
2014/11/07 00:17:31 [music:3] Successfully loaded a playlist of 2 tracks.
2014/11/07 00:17:41 [music:3] Finished with "/tmp/music/Like_A_Stone.mp3".
2014/11/07 00:17:41 [music:3] Prepared "/tmp/music/Clint_Eastwood.mp3" (RID 3).
2014/11/07 00:22:00 [decoder:3] Method "MAD" accepted "/tmp/music/Clint_Eastwood.mp3".
2014/11/07 00:22:10 [music:3] Finished with "/tmp/music/Clint_Eastwood.mp3".
2014/11/07 00:22:10 [music:3] Prepared "/tmp/music/Clint_Eastwood.mp3" (RID 0).
dbaelde commented 9 years ago

I'm not sure to understand the issue here. Liquidsoap cannot play a deleted file... unless it has been opened (playing started) before you delete it.

giflw commented 9 years ago

I have deleted and recreated it again, with same name and content. After that, reloading playlist made it play twice in a row every round. Em 11/11/2014 07:05, "David Baelde" notifications@github.com escreveu:

I'm not sure to understand the issue here. Liquidsoap cannot play a deleted file... unless it has been opened (playing started) before you delete it.

— Reply to this email directly or view it on GitHub https://github.com/savonet/liquidsoap/issues/195#issuecomment-62519776.

dbaelde commented 9 years ago

Please realize that getting into a log is time consuming, especially with very little context as is the case here. It would have helped to know at what timestamp in the log I should look for an anomaly. There are see plenty of places where Clint_Eastwood is played twice in a row.

The time where you delete some file seems to be 23:54:38. There, liquidsoap complains about two playlist entries that do not exist. It reaches the end of the list, reloads, gets an empty playlist and thus keeps the old one (twice). It keeps struggling with files that do not exist. That all seems normal.

At 23:54:42 it loads a new non-empty playlist of 1 entry, then manages to load Clint_Eastwood which you have restored. It plays it and reaches the end of the playlist. At this point it reloads the file at 23:59:17 and the playlist at 00:03:35. I wonder here why it does not reload the playlist immediately. I can investigate this more closely later.

After the reload at 00:03:35 it says it has two tracks but it plays Clint_Eastwood three times before reloading. Did you cut the log or kill liquidsoap afterwards? I would be interested to know whether it keeps going like that.

One question: is /tmp/music a normal directory? (no NFS, fuse)

giflw commented 9 years ago

Sorry for the trouble reading the log. This is the full log (as I remember), and I have tested sometimes before opening this issue, and the strange behavior persists until I reload the playlist, supposing the deleted file is not put back on the folder. For each time I delete/put back the file on the directory, it got played one more time in a raw.

Regarding to /tmp/music, I'm using Ubuntu 14.04 with default setup. I checked and /tmp seems to be a common directory on the filesystem. Inside it I created the music directory.

I tested this behavior with files and symbolic links. I also tested with playlist as file instead of directory, and in that case it worked as expected, as I remember.

dbaelde commented 9 years ago

In my previous comment I identified two oddities, and I believe they come from the same issue: in the first case, there is a single file in the playlist but it is played twice before reload; in the second case there are two files (twice the same) in the playlist but it is played three times before reload.

This is due to the fact that reloading is triggered after that the end of the playlist is played, i.e., at the time when the first item of the playlist is picked again. I have changed this locally, so that the playlist reload is programmed after that the last item is picked. However, this interacts badly with another feature: when reload is performed, it cancels the files previously loaded. (This is nice because it allows the reload to take effect immediately even though we prepare files in advance.) As a result, on the example of a single item playlist, I get the following behavior: load playlist, prepare item, reload, cancel item, prepare (same) item, ... (this can happen a number of times until) play the item.

To conclude, I agree that there is a bug in our current reload strategy for the randomize mode but I don't have a patch yet. I could try to be clever with request expirations and create a special case for this kind of scenario, but I would like to find a simpler/cleaner approach instead.

dbaelde commented 9 years ago

I've been thinking about this a bit more, and it seems to me that the right approach is simply to not use expirations when reloading after a round. Expirations make sense for manual, time- and watch-based reloading but not for round-based ones. Unless somebody contradicts me, I'll just have to figure a way to disable expirations in round-based reloaded playlists, but re-enable them selectively for manual reloads.

giflw commented 9 years ago

Can you make something to enforce reload just after the prepared item start playing? You pointed that in your atempt, this behaviour occurs: load playlist, prepare item, reload, cancel item, prepare (same) item. Is there a way to make a reload only after start playing item? Something like this: load playlist, prepare item, start playing item, reload, cancel item, prepare (same) item. Maybe using a listenner or an observer pattern?

dbaelde commented 9 years ago

The issue should be fixed now. I'll consider merging soon but would welcome feedback. Tests confirm the fix but nothing tells us that backward compatibility is preserved: we should make sure that we did not remove expirations where they were needed.