Hi everyone

This is part <stopped counting> of <many> on this problem of liquidsoap refusing to record live shows (coming from input.harbor) in individual mp3 files.

I tried to modify my script so that my two input.harbor sources would be recorded independantly, from two different hooks in the script, using two different output.file commands that would record two different files (instead of having a fallback(harbor1,harbor2) as a source, which was the original design).

Although it seemed to improve things a bit at first, it looks like the problem still remains. After a while, liquidsoap will launch lame encoder to start recording the live show, but then immediately stops, leaving only a 4KB mp3 file instead of the recording of what came from the harbor.

I also have a feeling that, although it doesn't always trigger the bug nor is it the only thing that triggers it, sending metadatas to a harbor while nobody's streaming to it (by sending an HTTP request in the like of http://<server>/admin.cgi?pass=<pass>&mode=updinfo&song=<metadata>) seems to increase the probability of the bug being triggered next time someone connects.


Yet, I still have no idea what exactly triggers the bug and particularly how NOT to trigger it. This is starting to be a problem.


Azrael.

On Mon, Mar 10, 2014 at 7:02 PM, Kerozen <kerozen@gmail.com> wrote:
Hi everyone,

Here are the news regarding this problem.

Short reminder for those who forgot/didn't follow the problem : I have liquidsoap configured to record a new mp3 file each time a DJ connects to a liquidsoap input.harbor (but not when liquidsoap is broadcasting a playlist by itself), and after a random amount of connections/disconnections, every new recording file created remains empty until liquidsoap is restarted.

So as to troubleshoot the problem and verify it wasn't something like liquidsoap outputting silence, I decided to create a new output.icecast that closely replicates the output.file part of my script. Liquidsoap starts and stops broadcasting on that input the exact same way it starts and stops recording live shows in a new file.

My hypothesis was that when the bug was triggered, Liquidsoap would indeed start broadcasting on output.icecast, but would output silence (due to the use of mksafe).
It turned out I was wrong.

Once the bug is triggered, Liquidsoap does NOT broadcast to the output.icecast designated server. Apparently, from what I gather from the logs, it starts broadcasting and immediately stops.

FYI : "archive2" is the name of the output.icecast that emulates the output.file.

2014/03/10 18:08:48 [lang:3] Live démarré
2014/03/10 18:08:48 [threads:3] Created thread "harbor source feeding" (2 total).
2014/03/10 18:08:48 [live2:3] Decoding...
2014/03/10 18:08:48 [mksafe:3] Switch to fallback_4814 with transition.
2014/03/10 18:08:48 [safe_blank:4] Activations changed: static=[], dynamic=[mksafe:archive:archive].
2014/03/10 18:08:48 [fallback_4814:4] Activations changed: static=[mksafe:archive:archive], dynamic=[mksafe:archive2:archive2, mksafe:archive:archive].
2014/03/10 18:08:48 [fallback_4814:4] Enabling caching mode: possible dynamic activation.
2014/03/10 18:08:48 [archive2:3] Connecting mount rifftest1 for source@localhost...
2014/03/10 18:08:48 [archive2:3] Connection setup was successful.
2014/03/10 18:08:48 [mksafe:3] Switch to fallback_4814 with transition.
2014/03/10 18:08:48 [safe_blank:4] Activations changed: static=[], dynamic=[mksafe:archive2:archive2].
2014/03/10 18:08:48 [fallback_4814:4] Activations changed: static=[mksafe:archive2:archive2, mksafe:archive:archive], dynamic=[mksafe:archive2:archive2, mksafe:arch$
2014/03/10 18:08:48 [archive2:3] Closing connection...
2014/03/10 18:08:49 [live2:4] End of track.
2014/03/10 18:09:05 [live2:2] Feeding stopped: Mad.End_of_stream.
2014/03/10 18:09:05 [lang:3] Live terminé
2014/03/10 18:09:05 [threads:3] Thread "harbor source feeding" terminated (1 remaining).

Notice the "closing connection / end of track" only one second after the live starts, and 16 seconds before the live is actually terminated from the DJ side.

This doesn't happen when the bug is not triggered. Here is a log from when the bug was not triggered (after rebooting liquidsoap), for reference :

2014/03/10 18:34:15 [lang:3] Live démarré
2014/03/10 18:34:15 [threads:3] Created thread "harbor source feeding" (2 total).
2014/03/10 18:34:15 [live2:3] Decoding...
2014/03/10 18:34:15 [archive2:3] Connecting mount rifftest1 for source@localhost...
2014/03/10 18:34:15 [archive2:3] Connection setup was successful.
2014/03/10 18:34:15 [mksafe:3] Switch to safe_blank.
2014/03/10 18:34:15 [safe_blank:4] Activations changed: static=[mksafe:archive2:archive2], dynamic=[mksafe:archive2:archive2].
2014/03/10 18:34:15 [mksafe:3] Switch to safe_blank.
2014/03/10 18:34:15 [safe_blank:4] Activations changed: static=[mksafe:archive:archive], dynamic=[mksafe:archive:archive].
2014/03/10 18:34:18 [fallback_4866:3] Switch to strip_blank_4810 with transition.
2014/03/10 18:34:18 [add_4864:4] Activations changed: static=[], dynamic=[fallback_4866:fallback_4868:on_metadata_4874:Riff:Riff].
2014/03/10 18:34:18 [strip_blank_4810:4] Activations changed: static=[fallback_4866:fallback_4868:on_metadata_4874:Riff:Riff, dummy(dot)1:dummy(dot)1, strip_blank_4$
2014/03/10 18:34:18 [mksafe:3] Switch to fallback_4814 with transition.
2014/03/10 18:34:18 [safe_blank:4] Activations changed: static=[], dynamic=[mksafe:archive2:archive2].
2014/03/10 18:34:18 [fallback_4814:4] Activations changed: static=[mksafe:archive2:archive2], dynamic=[mksafe:archive2:archive2, mksafe:archive:archive].
2014/03/10 18:34:18 [fallback_4814:4] Enabling caching mode: possible dynamic activation.
2014/03/10 18:34:18 [mksafe:3] Switch to fallback_4814 with transition.
2014/03/10 18:34:18 [safe_blank:4] Activations changed: static=[], dynamic=[mksafe:archive:archive].
2014/03/10 18:34:18 [fallback_4814:4] Activations changed: static=[mksafe:archive:archive, mksafe:archive2:archive2], dynamic=[mksafe:archive2:archive2, mksafe:arch$
2014/03/10 18:34:18 [fallback_4814:3] Switch to strip_blank_4810.
2014/03/10 18:34:18 [strip_blank_4810:4] Activations changed: static=[fallback_4814:mksafe:archive:archive, fallback_4866:fallback_4868:on_metadata_4874:Riff:Riff, $
2014/03/10 18:34:50 [live2:2] Feeding stopped: Mad.End_of_stream.
2014/03/10 18:34:50 [lang:3] Live terminé
2014/03/10 18:34:50 [fullplaylist(dot)m3u:3] Finished with "/var/music/playlist/BaseRock/06 - Blink 182 - I Miss You.mp3".
2014/03/10 18:34:50 [threads:3] Thread "harbor source feeding" terminated (1 remaining).
2014/03/10 18:34:50 [archive2:3] Closing connection...
2014/03/10 18:34:52 [live2:4] End of track.
2014/03/10 18:34:52 [live2:4] Buffer emptied, buffering needed.
2014/03/10 18:34:52 [fallback_4866:3] Switch to add_4864 with forgetful transition.


Notice how the end of track / closing connection only happens when the DJ disconnects from the harbor ("Feeding stopped")


My new hypothesis on this bug is now the following : once the bug is triggered, liquidsoap starts outputting (to icecast and/or to a file) AND immediately stops, barely a second later, even though it hasn't received the signal to do so (the "Live terminé" message is in the script sending the signal to stop recording).

I also found an apparently 100% sure way to trigger the bug : inputting from TWO harbor at the same time WILL trigger the bug, always. Probably has to do with this :

def live_start(blah) =
    log("Live démarré")
    ignore(server.execute("archive.start"))
end # live_start is triggered by input.harbor's "on_connect" argument
liverec = fallback(track_sensitive=false,[live,live2]) # live and live2 corresponds to harbor 1 and harbor 2.
output.file(id="archive",start=false,... mksafe(liverec))

So it looks like triggering the archive.start when it's already started WILL trigger the bug with 100% certainty.
But it's NOT the only way to trigger the bug, as the bug is sometimes triggered even though the previous recording has been correctly stopped (a proof of this is the last correctly recorded file not growing enormous, which proves liquidsoap HAS stopped recording in it).



As of today, I can say I understand WHAT the bug does exactly, but I still don't understand what exactly triggers this bug and why it happens.

Any idea will be welcome !


Azrael.


On Wed, Feb 12, 2014 at 4:21 PM, Kerozen <kerozen@gmail.com> wrote:
Hi,

I was wondering if anyone had any news or any idea regarding this problem. As of now, we haven't found a solution.

I decided to have a look into one of those 4KB, failed-recording files. An interesting thing is that the file isn't actually empty.

Here is one of those file if anyone wants to analyse it : http://api.riff-radio.org/0/test.mp3

It seems to contain some LAME header, but that's about all. This could indicate that liquidsoap had no trouble creating the file and lame didn't have any problem accessing it and writing into it, but that it just doesn't write **sound** in it.


Any new idea or walkaround is welcome.


Azrael.


On Fri, Jan 31, 2014 at 9:42 AM, Ken Restivo <ken@restivo.org> wrote:
FWIW, we're having this same problem with a very similar kind of script (saving an incoming DJ stream). In our case, we're usign an http stream as the input, and outputing to vorbis not mp3, but still it'll randomly close the file, and reopen it, with about 10 seconds of lost audio (in the saved files) while it falls back with transition to the jukebox and then back to the live stream again. Listeners to the icecast output likewise hear no glitches: only the archives show glitches.

I thought for sure it was because I was doing something dumb that could be solved by grounding streams with output.dummy or doing something with the clocks or something similar. I'm reading up on it more now. I haven't yet really started isolating it and trying to get it to fail in a sandbox environment.

-ken
--
-------
On Thu, Jan 30, 2014 at 06:19:16PM +0100, Kerozen wrote:
> Hi,
>
> We're on a 64-bit machine, using Debian 4.6.3-14 with a 3.2.0-4-amd64
> kernel.
>
> Prior to 1.1.1, we were using svn8237. And prior to that I don't remember
> (it was on another server) but I'm pretty sure the problem was already
> there.
>
> Also worth noting is that besides of this output.file, we're also
> broadcasting our stream to shoutcast servers using
> output.icecast(protocol="icy"...), and those are always working as expected
> : we never have any problem with those. Only output.file is affected by
> this problem. However, this could be because output.icecast is only called
> when the script starts (then it never stops as it's broadcasting 24/7,
> either live or playlist) whereas output.file is started and stopped "on
> demand" when a live show occurs.
>
>
> Azrael.
>
>
> On Thu, Jan 30, 2014 at 5:19 PM, Romain Beauxis <toots@rastageeks.org>wrote:
>
> > Hi,
> >
> > 2014-01-29 Kerozen <kerozen@gmail.com>:
> > > I have a pretty weird problem on a pretty complex script. I'm afraid this
> > > one is gonna be tough so brace yourselves, here it comes :
> > >
> > > This problem happens with Liquidsoap 1.1.1 as well as every previous
> > version
> > > I've tested so far. The problem is related with output.file creating new
> > > files (as expected) but, after a while, stopping recording in it what
> > should
> > > be recorded (once the bug occurs, any newly created file remains empty).
> > >
> > > I have set up a system where liquidsoap automatically creates a new mp3
> > > files each time a DJ connects to one harbor and records the live show in
> > it
> > > (when nobody is streaming to any harbor, the script falls back to a
> > > playlist). It's working as follow (only showing here what I thought
> > might be
> > > of any interest for our problem, switching all the playlist generation
> > part
> > > of the script) :
> > >
> > > # En début de live (called by harbor)
> > > def live_start(blah) =
> > >     log("Live démarré")
> > >     ignore(server.execute("archive.start"))
> > >     system("/etc/liquidsoap/scripts/write_status.sh LIVE")
> > > end
> > >
> > > # En fin de live (same)
> > > def live_stop() =
> > >     log("Live terminé")
> > >     ignore(server.execute("archive.stop"))
> > >     system("/etc/liquidsoap/scripts/write_status.sh PLAYLIST")
> > >     ignore(server.execute("xradio.skip"))
> > > end
> > >
> > > live = input.harbor(id="prelive", port=8018, on_connect=live_start,
> > > on_disconnect=live_stop, icy=true...)
> > > live2 = input.harbor(id="live2", port=8020, on_connect=live_start,
> > > on_disconnect=live_stop, icy=true...)
> > >
> > > live = strip_blank(live)
> > > live2 = strip_blank(live2)
> > > output.dummy(fallible=true,live2) # Permet d'éviter des buffers overrun
> > > output.dummy(fallible=true,live) # Permet d'éviter des buffers overrun
> > >
> > > # Fallback pour la sauvegarde : live1 avant traitement et live2 (jamais
> > > traité)
> > > liverec = fallback(track_sensitive=false,[live,live2])
> > >
> > > xradio = { a complex playlist generation system written much earlier in
> > the
> > > script, but no live yet }
> > >
> > > # Manual skipping, for when track limit is lost in the playlist system
> > due
> > > to the use of add() later
> > > def skip_radio(s) =
> > > source.skip(s)
> > > end
> > >
> > > server.register(namespace="xradio",
> > > description = "Skip current song",
> > > usage = "xradio.skip",
> > > "skip",
> > > fun (s) -> begin skip_radio(xradio) "Skipped." end)
> > > # End manual skipping
> > >
> > > ###### Here lies the creation of a new mp3 recording what was
> > broadcasted to
> > > any harbor
> > > liverectitle = '$(if $(title),"%m-%d-%Y-%H:%M:%S -
> > > $(title)","%m-%d-%Y-%H:%M:%S - Emission Inconnue")'
> > > output.file(%mp3(bitrate=192, samplerate=44100, stereo=true),
> > id="archive",
> > > start=false, "/var/music/archives/d-day/" ^ liverectitle ^ ".mp3",
> > > mksafe(liverec))
> > >
> > > # Adding live and playlist together
> > > output = fallback(track_sensitive=false,[live, xradio])
> > > output = sky(output) # this is when we lose our track limits
> > > # Adding the other harbor, unprocessed
> > > output = fallback(track_sensitive=false,[live2,output])
> > >
> > >
> > > The problem is as follow : for a random amount of different connections
> > to
> > > one or the other harbor, things will work as expected : a new mp3 file is
> > > created and what's broadcasted to the harbor is recorded in it.
> > >
> > > After a random amount of different connections (can happen as fast as the
> > > third time, but can also not happen even after several dozen
> > connections), a
> > > new behavior occurs : the mp3 file is indeed created by output.file, but
> > the
> > > mp3 file remains empty, weighing only 4KB. Once this behavior has started
> > > occuring, it will happen EACH and EVERY time someone connects to a harbor
> > > (there will be NO MORE recording, ever), until liquidsoap is restarted.
> > >
> > > I couldn't find any error or interesting bit of information in the logs.
> > >
> > > If this can help in any way finding where the problem lies exactly, I
> > > noticed that the problematic behavior is much more likely to be triggered
> > > when several connections are done in a very short amount of time.
> > Typically,
> > > if a DJ undergoes several buffer underruns in a row, the problematic
> > > behavior is likely to be triggered. Same thing if a DJ connects RIGHT
> > after
> > > the previous one disconnects (like, so fast that liquidsoap is not even
> > > given the time to fall back to playlist).
> > >
> > > However, while these situations tend to trigger the problem more often,
> > they
> > > do NOT trigger it all the time, and they are NOT the only cases where the
> > > problem happens.
> > >
> > > Sometimes, even 20 buffer underruns in less than 3 minutes won't trigger
> > the
> > > behavior. By contrast, tonight, the new behaviour was triggered even
> > though
> > > I was connecting more than 20 hours after the last DJ stopped
> > broadcasting,
> > > and this was only the third file created since last liquidsoap reboot.
> > >
> > > Yesterday was 158M    /var/music/archives/day2/01-28-2014-21:11:46 -
> > > Emission Inconnue.mp3
> > > But today is 4.0K    /var/music/archives/d-day/01-29-2014-21:08:17 -
> > > Emission Inconnue.mp3
> > > And as explained, once triggered, this is for good. One DJ broadcasted
> > today
> > > after I ended my show, he was not recorded either : 4.0K
> > > /var/music/archives/d-day/01-29-2014-23:05:26 - Emission Inconnue.mp3
> > >
> > >
> > >
> > > Any idea as to what might be the problem ?
> >
> > This sounds a lot like the dreaded "Liquidsoap sometimes stream
> > silence" issue.. Although, the issue has never been present in
> > liquidsoap version prior to 1.1.1 and also doesn't seem to appear on
> > 64 bit machines..
> >
> > Which version of liquidsoap have you tried for this bug? Can/do you
> > run on a 64 bit machine?
> >
> > Thanks,
> > Romain
> >

> ------------------------------------------------------------------------------
> WatchGuard Dimension instantly turns raw network data into actionable
> security intelligence. It gives you real-time visual feedback on key
> security issues and trends.  Skip the complicated setup - simply import
> a virtual appliance and go from zero to informed in seconds.
> http://pubads.g.doubleclick.net/gampad/clk?id=123612991&iu=/4140/ostg.clktrk

> _______________________________________________
> Savonet-users mailing list
> Savonet-users@lists.sourceforge.net
> https://lists.sourceforge.net/lists/listinfo/savonet-users