search

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

Sometimes Liquidsoap streams silence #66

Closed mkonecny closed 6 years ago

mkonecny commented 11 years ago

We have two users that have mentioned their stream goes silent during the night.

http://forum.sourcefabric.org/discussion/15111/airtime-audio-fails-daily/p1 http://forum.sourcefabric.org/discussion/15412/unidentified-problem/p1

I've done some extensive analysis into what could be causing this problem - It appears it may be Liquidsoap related because I can see in the logs that Liquidsoap's queue did have tracks in it. It's only after Liquidsoap is restarted that audible output is heard.

Another user has mentioned that connecting to Liquidsoap via input.harbor "awakens" it.

s = queue(...)

s = if slave_enabled then
    slave_live = mksafe(
        audio_to_stereo(
            input.harbor(...)))

    ignore(output.dummy(slave_live, fallible=true))

    switch(id="show_schedule_noise_switch",
            track_sensitive=false,
            transitions=[transition, transition],
            [({!live_slave_enabled}, slave_live), ({true}, s)]
        )
else
    s
end

s = if master_enabled then
    master_live = mksafe(
        audio_to_stereo(
            input.harbor(...)))

    ignore(output.dummy(master_live, fallible=true))

    switch(id="show_schedule_noise_switch",
            track_sensitive=false,
            transitions=[transition, transition],
            [({!live_master_enabled}, master_live), ({true}, s)]
        )
else
    s
end

out(s)

One user gave me ssh access, and I could not get the output started unless restarting liquidsoap. I was able to see that tracks were in the queue, and I tried changing live_slave_enabled and live_master_enabled on/off via telnet to no effect.

The one lead I have right now is the user connecting to input.harbor and disconnecting again - any ideas how I should approach narrowing this down further?

virtualfunction commented 11 years ago

What codec are you using? I also had this issue, but this was largely with Ogg Vorbis and Icecast, not to mention due to the buffering / lack of sync mechanisms I used to get a lot of latency introduced on the listener side with Icecast (To the point we switched to Flash some years back).

mkonecny commented 11 years ago

@virtualfunction I don't believe this is related. It happens with various codecs. I've looked further into the issue, and believe I have found the root cause for which I'll be filing another ticket.

mkonecny commented 11 years ago

Upon cross-referencing a few log files, it appears that input.harbor may be part of the problem. All users with this problem have been using the harbor functionality.

This theory is a bit of a paradox, because I'm basing my theory on the fact that the "switch()" statement is somehow reading the state of the input.harbor incorrectly, and therefore not falling back to playing the files in request.queue.

However forcefully telling the switch ignore the input.harbor via live_master_enabled := false` stream does not appear to do anything.

Perhaps there is somehow a case where input.harbor can cause a switch to become dysfunctional? Keep in mind that the users report getting the switch working again by simply connecting to input.harbor temporarily and disconnecting after a few seconds.

toots commented 11 years ago

Hi @mkonecny,

There could be a bug in the switch source selection code. I'll have a look at it but, basically, with tracks_sensitive=false and the guarding method returning false, the switch should switch to the other source, regardless of the hardbor's status.

Any chance you'd have some logs to share around the time that you unblock liq by connecting/disconnecting from the harbor? Thanks!

mkonecny commented 11 years ago

Incoming log.

The user's description:

This happened again today. I checked at around 0300 & it was fine but when I looked again at 1130 it was down. I have restarted the AIrtime-Liquidsoap service to restore the audio & then ran sudo tar czf airtime.tar.gz /var/log/airtime.

From what I can see in the logs, the user connected to input.harbor at 1am, and disconnected at 3am at which point 2013/02/19 03:00:00 [decoder:3] Method "MAD" accepted "/var/tmp/airtime/pypo/cache/scheduler/8.mp3" kicks in. From that point on at 03:00:02 a user tries to connect to input.harbor (but fails to pass the authentication).

At 10:38:29 track 25.mp3 is scheduled (not sure if problem started with this track). The annotation (from our scheduler log) is

queue.push annotate:media_id="25",liq_start_next="0",liq_fade_in="0.5",liq_fade_out="0.5",liq_cue_in="0.0",liq_cue_out="6226.0",schedule_table_id="2185",replay_gain="-4.54 dB":/var/tmp/airtime/pypo/cache/scheduler/25.mp3

As you can see the track as a length of almost 2 hours

At 11:31:19 the user restarts Liquidsoap since he noticed it is silent.

2013/02/19 00:00:00 [cue_cut_5385:3] Cueing out...
2013/02/19 00:00:00 [queue:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/42.mp3".
2013/02/19 00:00:00 [amplify_5390:3] End of the current overriding.
2013/02/19 00:00:00 [cross_5394:3] No next track ready yet.
2013/02/19 00:00:00 [dummy(dot)3:3] Source failed (no more tracks) stopping output...
2013/02/19 00:00:00 [dummy(dot)4:3] Source failed (no more tracks) stopping output...
2013/02/19 00:00:00 [default_switch:3] Switch to map_metadata_5421 with forgetful transition.
2013/02/19 00:00:00 [lang:3] transition called...
2013/02/19 00:01:30 [lang:3] live dj connected
2013/02/19 00:01:30 [decoder:3] Method "MAD" accepted "audio/mpeg".
2013/02/19 00:01:30 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --source-name=live_dj --source-status=true &
2013/02/19 00:01:30 [threads:3] Created thread "harbor source feeding" (3 total).
2013/02/19 00:01:30 [live_dj_harbor:3] Decoding...
2013/02/19 00:01:31 [server:3] New client: localhost.localdomain.
2013/02/19 00:01:31 [lang:3] streams.live_dj_start
2013/02/19 00:01:31 [server:3] Client localhost.localdomain disconnected.
2013/02/19 00:01:31 [master_dj_switch:3] Switch to mksafe with transition.
2013/02/19 00:01:31 [lang:3] transition called...
2013/02/19 00:01:32 [mksafe:3] Switch to audio_to_stereo_5487 with transition.
2013/02/19 00:01:40 [live_dj_harbor:2] Feeding stopped: End_of_file.
2013/02/19 00:01:40 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --source-name=live_dj --source-status=false &
2013/02/19 00:01:40 [threads:3] Thread "harbor source feeding" terminated (2 remaining).
2013/02/19 00:01:41 [server:3] New client: localhost.localdomain.
2013/02/19 00:01:41 [lang:3] streams.live_dj_stop
2013/02/19 00:01:41 [server:3] Client localhost.localdomain disconnected.
2013/02/19 00:01:41 [master_dj_switch:3] Switch to default_switch with transition.
2013/02/19 00:01:41 [lang:3] transition called...
2013/02/19 00:01:42 [mksafe:3] Switch to safe_blank with forgetful transition.
2013/02/19 00:01:47 [lang:3] live dj connected
2013/02/19 00:01:47 [decoder:3] Method "MAD" accepted "audio/mpeg".
2013/02/19 00:01:47 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --source-name=live_dj --source-status=true &
2013/02/19 00:01:47 [threads:3] Created thread "harbor source feeding" (3 total).
2013/02/19 00:01:47 [live_dj_harbor:3] Decoding...
2013/02/19 00:01:48 [server:3] New client: localhost.localdomain.
2013/02/19 00:01:48 [lang:3] streams.live_dj_start
2013/02/19 00:01:48 [server:3] Client localhost.localdomain disconnected.
2013/02/19 00:01:48 [master_dj_switch:3] Switch to mksafe with transition.
2013/02/19 00:01:48 [lang:3] transition called...
2013/02/19 00:01:49 [mksafe:3] Switch to audio_to_stereo_5487 with transition.
2013/02/19 00:01:52 [server:3] New client: localhost.localdomain.
2013/02/19 00:01:52 [server:3] Client localhost.localdomain disconnected.
2013/02/19 00:01:52 [server:3] New client: localhost.localdomain.
2013/02/19 00:01:52 [lang:3] dynamic_source.get_id
2013/02/19 00:01:52 [server:3] Client localhost.localdomain disconnected.
2013/02/19 00:02:37 [live_dj_harbor:2] Feeding stopped: End_of_file.
2013/02/19 00:02:37 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --source-name=live_dj --source-status=false &
2013/02/19 00:02:37 [threads:3] Thread "harbor source feeding" terminated (2 remaining).
2013/02/19 00:02:37 [server:3] New client: localhost.localdomain.
2013/02/19 00:02:37 [lang:3] streams.live_dj_stop
2013/02/19 00:02:37 [server:3] Client localhost.localdomain disconnected.
2013/02/19 00:02:37 [master_dj_switch:3] Switch to default_switch with transition.
2013/02/19 00:02:37 [lang:3] transition called...
2013/02/19 00:02:39 [mksafe:3] Switch to safe_blank with forgetful transition.
2013/02/19 00:02:53 [lang:3] live dj connected
2013/02/19 00:02:53 [decoder:3] Method "MAD" accepted "audio/mpeg".
2013/02/19 00:02:53 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --source-name=live_dj --source-status=true &
2013/02/19 00:02:53 [threads:3] Created thread "harbor source feeding" (3 total).
2013/02/19 00:02:53 [live_dj_harbor:3] Decoding...
2013/02/19 00:02:53 [server:3] New client: localhost.localdomain.
2013/02/19 00:02:53 [lang:3] streams.live_dj_start
2013/02/19 00:02:53 [server:3] Client localhost.localdomain disconnected.
2013/02/19 00:02:53 [master_dj_switch:3] Switch to mksafe with transition.
2013/02/19 00:02:53 [lang:3] transition called...
2013/02/19 00:02:54 [live_dj_harbor:2] Feeding stopped: End_of_file.
2013/02/19 00:02:54 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --source-name=live_dj --source-status=false &
2013/02/19 00:02:54 [threads:3] Thread "harbor source feeding" terminated (2 remaining).
2013/02/19 00:02:54 [server:3] New client: localhost.localdomain.
2013/02/19 00:02:54 [lang:3] streams.live_dj_stop
2013/02/19 00:02:54 [server:3] Client localhost.localdomain disconnected.
2013/02/19 00:02:54 [master_dj_switch:3] Switch to default_switch with transition.
2013/02/19 00:02:54 [lang:3] transition called...
2013/02/19 00:02:58 [lang:3] live dj connected
2013/02/19 00:02:58 [decoder:3] Method "MAD" accepted "audio/mpeg".
2013/02/19 00:02:58 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --source-name=live_dj --source-status=true &
2013/02/19 00:02:58 [threads:3] Created thread "harbor source feeding" (3 total).
2013/02/19 00:02:58 [live_dj_harbor:3] Decoding...
2013/02/19 00:02:59 [server:3] New client: localhost.localdomain.
2013/02/19 00:02:59 [lang:3] streams.live_dj_start
2013/02/19 00:02:59 [server:3] Client localhost.localdomain disconnected.
2013/02/19 00:02:59 [master_dj_switch:3] Switch to mksafe with transition.
2013/02/19 00:02:59 [lang:3] transition called...
2013/02/19 00:03:00 [mksafe:3] Switch to audio_to_stereo_5487 with transition.
2013/02/19 00:03:01 [live_dj_harbor:2] Feeding stopped: End_of_file.
2013/02/19 00:03:01 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --source-name=live_dj --source-status=false &
2013/02/19 00:03:01 [threads:3] Thread "harbor source feeding" terminated (2 remaining).
2013/02/19 00:03:01 [server:3] New client: localhost.localdomain.
2013/02/19 00:03:01 [lang:3] streams.live_dj_stop
2013/02/19 00:03:01 [server:3] Client localhost.localdomain disconnected.
2013/02/19 00:03:01 [master_dj_switch:3] Switch to default_switch with transition.
2013/02/19 00:03:01 [lang:3] transition called...
2013/02/19 00:03:03 [mksafe:3] Switch to safe_blank with forgetful transition.
2013/02/19 00:03:19 [lang:3] live dj connected
2013/02/19 00:03:20 [decoder:3] Method "MAD" accepted "audio/mpeg".
2013/02/19 00:03:20 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --source-name=live_dj --source-status=true &
2013/02/19 00:03:20 [threads:3] Created thread "harbor source feeding" (3 total).
2013/02/19 00:03:20 [live_dj_harbor:3] Decoding...
2013/02/19 00:03:20 [server:3] New client: localhost.localdomain.
2013/02/19 00:03:20 [lang:3] streams.live_dj_start
2013/02/19 00:03:20 [server:3] Client localhost.localdomain disconnected.
2013/02/19 00:03:20 [master_dj_switch:3] Switch to mksafe with transition.
2013/02/19 00:03:20 [lang:3] transition called...
2013/02/19 00:03:22 [mksafe:3] Switch to audio_to_stereo_5487 with transition.
2013/02/19 00:05:01 [live_dj_harbor:2] Feeding stopped: End_of_file.
2013/02/19 00:05:01 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --source-name=live_dj --source-status=false &
2013/02/19 00:05:01 [threads:3] Thread "harbor source feeding" terminated (2 remaining).
2013/02/19 00:05:02 [server:3] New client: localhost.localdomain.
2013/02/19 00:05:02 [lang:3] streams.live_dj_stop
2013/02/19 00:05:02 [server:3] Client localhost.localdomain disconnected.
2013/02/19 00:05:02 [master_dj_switch:3] Switch to default_switch with transition.
2013/02/19 00:05:02 [lang:3] transition called...
2013/02/19 00:05:03 [mksafe:3] Switch to safe_blank with forgetful transition.
2013/02/19 00:05:07 [lang:3] live dj connected
2013/02/19 00:05:07 [decoder:3] Method "MAD" accepted "audio/mpeg".
2013/02/19 00:05:07 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --source-name=live_dj --source-status=true &
2013/02/19 00:05:07 [threads:3] Created thread "harbor source feeding" (3 total).
2013/02/19 00:05:07 [live_dj_harbor:3] Decoding...
2013/02/19 00:05:07 [server:3] New client: localhost.localdomain.
2013/02/19 00:05:07 [lang:3] streams.live_dj_start
2013/02/19 00:05:07 [server:3] Client localhost.localdomain disconnected.
2013/02/19 00:05:07 [master_dj_switch:3] Switch to mksafe with transition.
2013/02/19 00:05:07 [lang:3] transition called...
2013/02/19 00:05:09 [mksafe:3] Switch to audio_to_stereo_5487 with transition.
2013/02/19 00:05:49 [live_dj_harbor:2] Feeding stopped: End_of_file.
2013/02/19 00:05:49 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --source-name=live_dj --source-status=false &
2013/02/19 00:05:49 [threads:3] Thread "harbor source feeding" terminated (2 remaining).
2013/02/19 00:05:49 [server:3] New client: localhost.localdomain.
2013/02/19 00:05:49 [lang:3] streams.live_dj_stop
2013/02/19 00:05:49 [server:3] Client localhost.localdomain disconnected.
2013/02/19 00:05:49 [master_dj_switch:3] Switch to default_switch with transition.
2013/02/19 00:05:49 [lang:3] transition called...
2013/02/19 00:05:51 [mksafe:3] Switch to safe_blank with forgetful transition.
2013/02/19 00:05:52 [lang:3] live dj connected
2013/02/19 00:05:53 [decoder:3] Method "MAD" accepted "audio/mpeg".
2013/02/19 00:05:53 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --source-name=live_dj --source-status=true &
2013/02/19 00:05:53 [threads:3] Created thread "harbor source feeding" (3 total).
2013/02/19 00:05:53 [live_dj_harbor:3] Decoding...
2013/02/19 00:05:53 [server:3] New client: localhost.localdomain.
2013/02/19 00:05:53 [lang:3] streams.live_dj_start
2013/02/19 00:05:53 [server:3] Client localhost.localdomain disconnected.
2013/02/19 00:05:53 [master_dj_switch:3] Switch to mksafe with transition.
2013/02/19 00:05:53 [lang:3] transition called...
2013/02/19 00:05:54 [live_dj_harbor:2] Feeding stopped: End_of_file.
2013/02/19 00:05:54 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --source-name=live_dj --source-status=false &
2013/02/19 00:05:54 [threads:3] Thread "harbor source feeding" terminated (2 remaining).
2013/02/19 00:05:54 [server:3] New client: localhost.localdomain.
2013/02/19 00:05:54 [lang:3] streams.live_dj_stop
2013/02/19 00:05:54 [server:3] Client localhost.localdomain disconnected.
2013/02/19 00:05:54 [master_dj_switch:3] Switch to default_switch with transition.
2013/02/19 00:05:54 [lang:3] transition called...
2013/02/19 00:06:04 [lang:3] live dj connected
2013/02/19 00:06:04 [decoder:3] Method "MAD" accepted "audio/mpeg".
2013/02/19 00:06:04 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --source-name=live_dj --source-status=true &
2013/02/19 00:06:04 [threads:3] Created thread "harbor source feeding" (3 total).
2013/02/19 00:06:04 [live_dj_harbor:3] Decoding...
2013/02/19 00:06:04 [server:3] New client: localhost.localdomain.
2013/02/19 00:06:04 [lang:3] streams.live_dj_start
2013/02/19 00:06:04 [server:3] Client localhost.localdomain disconnected.
2013/02/19 00:06:04 [master_dj_switch:3] Switch to mksafe with transition.
2013/02/19 00:06:04 [lang:3] transition called...
2013/02/19 00:06:05 [mksafe:3] Switch to audio_to_stereo_5487 with transition.
2013/02/19 00:07:47 [lang:3] live dj connected
2013/02/19 00:07:49 [lang:3] live dj connected
2013/02/19 00:07:52 [lang:3] live dj connected
2013/02/19 00:07:55 [lang:3] live dj connected
2013/02/19 00:16:45 [mksafe:3] Switch to safe_blank with forgetful transition.
2013/02/19 00:17:02 [live_dj_harbor:2] Feeding stopped: Connection reset by peer in read().
2013/02/19 00:17:02 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --source-name=live_dj --source-status=false &
2013/02/19 00:17:02 [threads:3] Thread "harbor source feeding" terminated (2 remaining).
2013/02/19 00:17:03 [server:3] New client: localhost.localdomain.
2013/02/19 00:17:03 [lang:3] streams.live_dj_stop
2013/02/19 00:17:03 [server:3] Client localhost.localdomain disconnected.
2013/02/19 00:17:03 [master_dj_switch:3] Switch to default_switch with transition.
2013/02/19 00:17:03 [lang:3] transition called...
2013/02/19 00:17:03 [lang:3] live dj connected
2013/02/19 00:17:03 [decoder:3] Method "MAD" accepted "audio/mpeg".
2013/02/19 00:17:03 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --source-name=live_dj --source-status=true &
2013/02/19 00:17:03 [threads:3] Created thread "harbor source feeding" (3 total).
2013/02/19 00:17:03 [live_dj_harbor:3] Decoding...
2013/02/19 00:17:04 [server:3] New client: localhost.localdomain.
2013/02/19 00:17:04 [lang:3] streams.live_dj_start
2013/02/19 00:17:04 [server:3] Client localhost.localdomain disconnected.
2013/02/19 00:17:04 [master_dj_switch:3] Switch to mksafe with transition.
2013/02/19 00:17:04 [lang:3] transition called...
2013/02/19 00:17:06 [mksafe:3] Switch to audio_to_stereo_5487 with transition.
2013/02/19 00:18:28 [lang:3] live dj connected
2013/02/19 00:18:31 [lang:3] live dj connected
2013/02/19 00:19:31 [lang:3] live dj connected
2013/02/19 00:19:46 [lang:3] live dj connected
2013/02/19 00:19:48 [lang:3] live dj connected
2013/02/19 00:28:48 [lang:3] live dj connected
2013/02/19 00:28:50 [lang:3] live dj connected
2013/02/19 00:31:47 [mksafe:3] Switch to safe_blank with forgetful transition.
2013/02/19 00:31:52 [server:3] New client: localhost.localdomain.
2013/02/19 00:31:52 [server:3] Client localhost.localdomain disconnected.
2013/02/19 00:31:52 [server:3] New client: localhost.localdomain.
2013/02/19 00:31:52 [lang:3] dynamic_source.get_id
2013/02/19 00:31:52 [server:3] Client localhost.localdomain disconnected.
2013/02/19 00:32:05 [live_dj_harbor:2] Feeding stopped: Connection reset by peer in read().
2013/02/19 00:32:05 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --source-name=live_dj --source-status=false &
2013/02/19 00:32:05 [threads:3] Thread "harbor source feeding" terminated (2 remaining).
2013/02/19 00:32:05 [server:3] New client: localhost.localdomain.
2013/02/19 00:32:05 [lang:3] streams.live_dj_stop
2013/02/19 00:32:05 [server:3] Client localhost.localdomain disconnected.
2013/02/19 00:32:05 [master_dj_switch:3] Switch to default_switch with transition.
2013/02/19 00:32:05 [lang:3] transition called...
2013/02/19 00:32:06 [lang:3] live dj connected
2013/02/19 00:32:06 [decoder:3] Method "MAD" accepted "audio/mpeg".
2013/02/19 00:32:06 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --source-name=live_dj --source-status=true &
2013/02/19 00:32:06 [threads:3] Created thread "harbor source feeding" (3 total).
2013/02/19 00:32:06 [live_dj_harbor:3] Decoding...
2013/02/19 00:32:07 [server:3] New client: localhost.localdomain.
2013/02/19 00:32:07 [lang:3] streams.live_dj_start
2013/02/19 00:32:07 [server:3] Client localhost.localdomain disconnected.
2013/02/19 00:32:07 [master_dj_switch:3] Switch to mksafe with transition.
2013/02/19 00:32:07 [lang:3] transition called...
2013/02/19 00:32:08 [mksafe:3] Switch to audio_to_stereo_5487 with transition.
2013/02/19 00:42:40 [mksafe:3] Switch to safe_blank with forgetful transition.
2013/02/19 00:42:45 [mksafe:3] Switch to audio_to_stereo_5487 with transition.
2013/02/19 00:56:26 [lang:3] live dj connected
2013/02/19 00:56:27 [lang:3] live dj connected
2013/02/19 00:56:58 [server:3] New client: localhost.localdomain.
2013/02/19 00:56:58 [server:3] Client localhost.localdomain disconnected.
2013/02/19 00:56:58 [server:3] New client: localhost.localdomain.
2013/02/19 00:56:58 [lang:3] dynamic_source.get_id
2013/02/19 00:56:58 [server:3] Client localhost.localdomain disconnected.
2013/02/19 00:59:15 [lang:3] live dj connected
2013/02/19 00:59:19 [lang:3] live dj connected
2013/02/19 00:59:21 [lang:3] live dj connected
2013/02/19 00:59:23 [lang:3] live dj connected
2013/02/19 00:59:26 [lang:3] live dj connected
2013/02/19 00:59:29 [lang:3] live dj connected
2013/02/19 00:59:33 [lang:3] live dj connected
2013/02/19 00:59:45 [lang:3] live dj connected
2013/02/19 00:59:56 [lang:3] live dj connected
2013/02/19 01:00:00 [server:3] New client: localhost.localdomain.
2013/02/19 01:00:00 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --source-name=live_dj --source-status=false &
2013/02/19 01:00:00 [server:3] Client localhost.localdomain disconnected.
2013/02/19 01:00:00 [server:3] New client: localhost.localdomain.
2013/02/19 01:00:00 [lang:3] streams.live_dj_stop
2013/02/19 01:00:00 [server:3] Client localhost.localdomain disconnected.
2013/02/19 01:00:00 [master_dj_switch:3] Switch to default_switch with transition.
2013/02/19 01:00:00 [lang:3] transition called...
2013/02/19 01:00:00 [live_dj_harbor:2] Feeding stopped: Source stopped.
2013/02/19 01:00:00 [threads:3] Thread "harbor source feeding" terminated (2 remaining).
2013/02/19 01:00:01 [mksafe:3] Switch to safe_blank with forgetful transition.
2013/02/19 01:00:02 [lang:3] live dj connected
2013/02/19 01:00:06 [lang:3] live dj connected
2013/02/19 01:00:07 [decoder:3] Method "MAD" accepted "audio/mpeg".
2013/02/19 01:00:07 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --source-name=live_dj --source-status=true &
2013/02/19 01:00:07 [threads:3] Created thread "harbor source feeding" (3 total).
2013/02/19 01:00:07 [live_dj_harbor:3] Decoding...
2013/02/19 01:00:07 [server:3] New client: localhost.localdomain.
2013/02/19 01:00:07 [lang:3] streams.live_dj_start
2013/02/19 01:00:07 [server:3] Client localhost.localdomain disconnected.
2013/02/19 01:00:07 [master_dj_switch:3] Switch to mksafe with transition.
2013/02/19 01:00:07 [lang:3] transition called...
2013/02/19 01:00:09 [mksafe:3] Switch to audio_to_stereo_5487 with transition.
2013/02/19 01:00:14 [lang:3] live dj connected
2013/02/19 01:00:26 [lang:3] live dj connected
2013/02/19 01:00:48 [lang:3] live dj connected
2013/02/19 01:01:10 [lang:3] live dj connected
2013/02/19 01:02:12 [lang:3] live dj connected
2013/02/19 01:03:14 [lang:3] live dj connected
2013/02/19 01:26:59 [server:3] New client: localhost.localdomain.
2013/02/19 01:26:59 [server:3] Client localhost.localdomain disconnected.
2013/02/19 01:26:59 [server:3] New client: localhost.localdomain.
2013/02/19 01:26:59 [lang:3] dynamic_source.get_id
2013/02/19 01:26:59 [server:3] Client localhost.localdomain disconnected.
2013/02/19 01:53:50 [server:3] New client: localhost.localdomain.
2013/02/19 01:53:50 [server:3] Client localhost.localdomain disconnected.
2013/02/19 01:53:50 [server:3] New client: localhost.localdomain.
2013/02/19 01:53:50 [lang:3] dynamic_source.get_id
2013/02/19 01:53:50 [server:3] Client localhost.localdomain disconnected.
2013/02/19 02:20:42 [server:3] New client: localhost.localdomain.
2013/02/19 02:20:42 [server:3] Client localhost.localdomain disconnected.
2013/02/19 02:20:42 [server:3] New client: localhost.localdomain.
2013/02/19 02:20:42 [lang:3] dynamic_source.get_id
2013/02/19 02:20:42 [server:3] Client localhost.localdomain disconnected.
2013/02/19 02:47:33 [server:3] New client: localhost.localdomain.
2013/02/19 02:47:33 [server:3] Client localhost.localdomain disconnected.
2013/02/19 02:47:33 [server:3] New client: localhost.localdomain.
2013/02/19 02:47:33 [lang:3] dynamic_source.get_id
2013/02/19 02:47:33 [server:3] Client localhost.localdomain disconnected.
2013/02/19 02:59:41 [server:3] New client: localhost.localdomain.
2013/02/19 02:59:41 [server:3] Client localhost.localdomain disconnected.
2013/02/19 02:59:41 [server:3] New client: localhost.localdomain.
2013/02/19 02:59:41 [lang:3] dynamic_source.get_id
2013/02/19 02:59:41 [server:3] Client localhost.localdomain disconnected.
2013/02/19 03:00:00 [server:3] New client: localhost.localdomain.
2013/02/19 03:00:00 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --source-name=live_dj --source-status=false &
2013/02/19 03:00:00 [server:3] Client localhost.localdomain disconnected.
2013/02/19 03:00:00 [server:3] New client: localhost.localdomain.
2013/02/19 03:00:00 [lang:3] streams.live_dj_stop
2013/02/19 03:00:00 [server:3] Client localhost.localdomain disconnected.
2013/02/19 03:00:00 [server:3] New client: localhost.localdomain.
2013/02/19 03:00:00 [decoder:3] Method "MAD" accepted "/var/tmp/airtime/pypo/cache/scheduler/8.mp3".
2013/02/19 03:00:00 [lang:3] vars.show_name
2013/02/19 03:00:00 [server:3] Client localhost.localdomain disconnected.
2013/02/19 03:00:00 [queue:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/8.mp3" (RID 0).
2013/02/19 03:00:00 [amplify_5390:3] Overriding amplification: 0.944061.
2013/02/19 03:00:00 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --data='0' --media-id=2178 &
2013/02/19 03:00:00 [lang:3] Using stream_format 0
2013/02/19 03:00:00 [switch_5414:3] Switch to map_metadata_5401.
2013/02/19 03:00:00 [master_dj_switch:3] Switch to default_switch with transition.
2013/02/19 03:00:00 [lang:3] transition called...
2013/02/19 03:00:00 [default_switch:3] Switch to switch_5414 with transition.
2013/02/19 03:00:00 [lang:3] transition called...
2013/02/19 03:00:00 [live_dj_harbor:2] Feeding stopped: Source client disconnected.
2013/02/19 03:00:00 [threads:3] Thread "harbor source feeding" terminated (2 remaining).
2013/02/19 03:00:02 [mksafe:3] Switch to safe_blank with forgetful transition.
2013/02/19 03:00:02 [lang:3] live dj connected
2013/02/19 03:00:05 [lang:3] live dj connected
2013/02/19 03:00:08 [lang:3] live dj connected
2013/02/19 03:29:41 [server:3] New client: localhost.localdomain.
2013/02/19 03:29:41 [server:3] Client localhost.localdomain disconnected.
2013/02/19 03:29:41 [server:3] New client: localhost.localdomain.
2013/02/19 03:29:41 [lang:3] dynamic_source.get_id
2013/02/19 03:29:41 [server:3] Client localhost.localdomain disconnected.
2013/02/19 03:59:22 [server:3] New client: localhost.localdomain.
2013/02/19 03:59:22 [server:3] Client localhost.localdomain disconnected.
2013/02/19 03:59:22 [server:3] New client: localhost.localdomain.
2013/02/19 03:59:22 [lang:3] dynamic_source.get_id
2013/02/19 03:59:22 [server:3] Client localhost.localdomain disconnected.
2013/02/19 03:59:59 [queue:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/8.mp3".
2013/02/19 03:59:59 [cue_cut_5385:3] End of track before cue-out point.
2013/02/19 03:59:59 [amplify_5390:3] End of the current overriding.
2013/02/19 03:59:59 [default_switch:3] Switch to map_metadata_5421 with forgetful transition.
2013/02/19 03:59:59 [lang:3] transition called...
2013/02/19 03:59:59 [dummy(dot)4:3] Source failed (no more tracks) stopping output...
2013/02/19 03:59:59 [dummy(dot)3:3] Source failed (no more tracks) stopping output...
2013/02/19 04:00:00 [server:3] New client: localhost.localdomain.
2013/02/19 04:00:00 [decoder:3] Method "MAD" accepted "/var/tmp/airtime/pypo/cache/scheduler/15.mp3".
2013/02/19 04:00:00 [queue:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/15.mp3" (RID 1).
2013/02/19 04:00:00 [lang:3] vars.show_name
2013/02/19 04:00:00 [server:3] Client localhost.localdomain disconnected.
2013/02/19 04:00:00 [amplify_5390:3] Overriding amplification: 0.411623.
2013/02/19 04:00:00 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --data='0' --media-id=2179 &
2013/02/19 04:00:00 [lang:3] Using stream_format 0
2013/02/19 04:00:00 [switch_5414:3] Switch to map_metadata_5401.
2013/02/19 04:00:00 [default_switch:3] Switch to switch_5414 with transition.
2013/02/19 04:00:00 [lang:3] transition called...
2013/02/19 04:29:03 [server:3] New client: localhost.localdomain.
2013/02/19 04:29:03 [server:3] Client localhost.localdomain disconnected.
2013/02/19 04:29:03 [server:3] New client: localhost.localdomain.
2013/02/19 04:29:03 [lang:3] dynamic_source.get_id
2013/02/19 04:29:03 [server:3] Client localhost.localdomain disconnected.
2013/02/19 04:57:49 [server:3] New client: localhost.localdomain.
2013/02/19 04:57:49 [server:3] Client localhost.localdomain disconnected.
2013/02/19 04:57:49 [server:3] New client: localhost.localdomain.
2013/02/19 04:57:49 [lang:3] dynamic_source.get_id
2013/02/19 04:57:49 [server:3] Client localhost.localdomain disconnected.
2013/02/19 04:58:09 [server:3] New client: localhost.localdomain.
2013/02/19 04:58:09 [server:3] Client localhost.localdomain disconnected.
2013/02/19 04:58:09 [server:3] New client: localhost.localdomain.
2013/02/19 04:58:09 [lang:3] dynamic_source.get_id
2013/02/19 04:58:09 [server:3] Client localhost.localdomain disconnected.
2013/02/19 04:58:28 [server:3] New client: localhost.localdomain.
2013/02/19 04:58:28 [server:3] Client localhost.localdomain disconnected.
2013/02/19 04:58:28 [server:3] New client: localhost.localdomain.
2013/02/19 04:58:28 [lang:3] dynamic_source.get_id
2013/02/19 04:58:28 [server:3] Client localhost.localdomain disconnected.
2013/02/19 05:06:02 [cue_cut_5385:3] Cueing out...
2013/02/19 05:06:02 [queue:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/15.mp3".
2013/02/19 05:06:02 [amplify_5390:3] End of the current overriding.
2013/02/19 05:06:02 [cross_5394:3] No next track ready yet.
2013/02/19 05:06:02 [dummy(dot)3:3] Source failed (no more tracks) stopping output...
2013/02/19 05:06:02 [dummy(dot)4:3] Source failed (no more tracks) stopping output...
2013/02/19 05:06:02 [default_switch:3] Switch to map_metadata_5421 with forgetful transition.
2013/02/19 05:06:02 [lang:3] transition called...
2013/02/19 05:06:03 [server:3] New client: localhost.localdomain.
2013/02/19 05:06:03 [decoder:3] Method "MAD" accepted "/var/tmp/airtime/pypo/cache/scheduler/9.mp3".
2013/02/19 05:06:03 [lang:3] vars.show_name
2013/02/19 05:06:03 [server:3] Client localhost.localdomain disconnected.
2013/02/19 05:06:03 [queue:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/9.mp3" (RID 0).
2013/02/19 05:06:03 [default_switch:3] Switch to switch_5414 with transition.
2013/02/19 05:06:03 [lang:3] transition called...
2013/02/19 05:06:03 [switch_5414:3] Switch to map_metadata_5401.
2013/02/19 05:06:03 [amplify_5390:3] Overriding amplification: 1.076465.
2013/02/19 05:06:03 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --data='0' --media-id=2180 &
2013/02/19 05:06:03 [lang:3] Using stream_format 0
2013/02/19 05:28:28 [server:3] New client: localhost.localdomain.
2013/02/19 05:28:28 [server:3] Client localhost.localdomain disconnected.
2013/02/19 05:28:28 [server:3] New client: localhost.localdomain.
2013/02/19 05:28:28 [lang:3] dynamic_source.get_id
2013/02/19 05:28:28 [server:3] Client localhost.localdomain disconnected.
2013/02/19 05:58:29 [server:3] New client: localhost.localdomain.
2013/02/19 05:58:29 [server:3] Client localhost.localdomain disconnected.
2013/02/19 05:58:29 [server:3] New client: localhost.localdomain.
2013/02/19 05:58:29 [lang:3] dynamic_source.get_id
2013/02/19 05:58:29 [server:3] Client localhost.localdomain disconnected.
2013/02/19 06:05:58 [server:3] New client: localhost.localdomain.
2013/02/19 06:05:58 [decoder:3] Method "MAD" accepted "/var/tmp/airtime/pypo/cache/scheduler/29.mp3".
2013/02/19 06:05:58 [lang:3] vars.show_name
2013/02/19 06:05:58 [server:3] Client localhost.localdomain disconnected.
2013/02/19 06:05:58 [cue_cut_5385:3] Cueing out...
2013/02/19 06:05:58 [queue:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/9.mp3".
2013/02/19 06:05:58 [amplify_5390:3] End of the current overriding.
2013/02/19 06:05:58 [queue:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/29.mp3" (RID 1).
2013/02/19 06:05:58 [amplify_5390:3] Overriding amplification: 0.782528.
2013/02/19 06:05:58 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --data='0' --media-id=2181 &
2013/02/19 06:05:58 [lang:3] Using stream_format 0
2013/02/19 06:28:29 [server:3] New client: localhost.localdomain.
2013/02/19 06:28:29 [server:3] Client localhost.localdomain disconnected.
2013/02/19 06:28:29 [server:3] New client: localhost.localdomain.
2013/02/19 06:28:29 [lang:3] dynamic_source.get_id
2013/02/19 06:28:29 [server:3] Client localhost.localdomain disconnected.
2013/02/19 06:58:29 [server:3] New client: localhost.localdomain.
2013/02/19 06:58:29 [server:3] Client localhost.localdomain disconnected.
2013/02/19 06:58:29 [server:3] New client: localhost.localdomain.
2013/02/19 06:58:29 [lang:3] dynamic_source.get_id
2013/02/19 06:58:29 [server:3] Client localhost.localdomain disconnected.
2013/02/19 07:05:58 [cue_cut_5385:3] Cueing out...
2013/02/19 07:05:58 [queue:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/29.mp3".
2013/02/19 07:05:58 [amplify_5390:3] End of the current overriding.
2013/02/19 07:05:58 [cross_5394:3] No next track ready yet.
2013/02/19 07:05:58 [dummy(dot)3:3] Source failed (no more tracks) stopping output...
2013/02/19 07:05:58 [dummy(dot)4:3] Source failed (no more tracks) stopping output...
2013/02/19 07:05:58 [default_switch:3] Switch to map_metadata_5421 with forgetful transition.
2013/02/19 07:05:58 [lang:3] transition called...
2013/02/19 07:05:59 [server:3] New client: localhost.localdomain.
2013/02/19 07:05:59 [decoder:3] Method "MAD" accepted "/var/tmp/airtime/pypo/cache/scheduler/41.mp3".
2013/02/19 07:05:59 [queue:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/41.mp3" (RID 0).
2013/02/19 07:05:59 [default_switch:3] Switch to switch_5414 with transition.
2013/02/19 07:05:59 [lang:3] transition called...
2013/02/19 07:05:59 [lang:3] vars.show_name
2013/02/19 07:05:59 [server:3] Client localhost.localdomain disconnected.
2013/02/19 07:05:59 [switch_5414:3] Switch to map_metadata_5401.
2013/02/19 07:05:59 [amplify_5390:3] Overriding amplification: 1.452112.
2013/02/19 07:05:59 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --data='0' --media-id=2182 &
2013/02/19 07:05:59 [lang:3] Using stream_format 0
2013/02/19 07:28:29 [server:3] New client: localhost.localdomain.
2013/02/19 07:28:29 [server:3] Client localhost.localdomain disconnected.
2013/02/19 07:28:29 [server:3] New client: localhost.localdomain.
2013/02/19 07:28:29 [lang:3] dynamic_source.get_id
2013/02/19 07:28:29 [server:3] Client localhost.localdomain disconnected.
2013/02/19 07:58:30 [server:3] New client: localhost.localdomain.
2013/02/19 07:58:30 [server:3] Client localhost.localdomain disconnected.
2013/02/19 07:58:30 [server:3] New client: localhost.localdomain.
2013/02/19 07:58:30 [lang:3] dynamic_source.get_id
2013/02/19 07:58:30 [server:3] Client localhost.localdomain disconnected.
2013/02/19 08:05:04 [cue_cut_5385:3] Cueing out...
2013/02/19 08:05:04 [queue:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/41.mp3".
2013/02/19 08:05:04 [amplify_5390:3] End of the current overriding.
2013/02/19 08:05:04 [cross_5394:3] No next track ready yet.
2013/02/19 08:05:04 [dummy(dot)3:3] Source failed (no more tracks) stopping output...
2013/02/19 08:05:04 [dummy(dot)4:3] Source failed (no more tracks) stopping output...
2013/02/19 08:05:04 [default_switch:3] Switch to map_metadata_5421 with forgetful transition.
2013/02/19 08:05:04 [lang:3] transition called...
2013/02/19 08:05:05 [server:3] New client: localhost.localdomain.
2013/02/19 08:05:05 [decoder:3] Method "MAD" accepted "/var/tmp/airtime/pypo/cache/scheduler/35.mp3".
2013/02/19 08:05:05 [lang:3] vars.show_name
2013/02/19 08:05:05 [server:3] Client localhost.localdomain disconnected.
2013/02/19 08:05:05 [queue:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/35.mp3" (RID 1).
2013/02/19 08:05:05 [default_switch:3] Switch to switch_5414 with transition.
2013/02/19 08:05:05 [lang:3] transition called...
2013/02/19 08:05:05 [switch_5414:3] Switch to map_metadata_5401.
2013/02/19 08:05:05 [amplify_5390:3] Overriding amplification: 1.051962.
2013/02/19 08:05:05 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --data='0' --media-id=2183 &
2013/02/19 08:05:05 [lang:3] Using stream_format 0
2013/02/19 08:28:30 [server:3] New client: localhost.localdomain.
2013/02/19 08:28:30 [server:3] Client localhost.localdomain disconnected.
2013/02/19 08:28:30 [server:3] New client: localhost.localdomain.
2013/02/19 08:28:30 [lang:3] dynamic_source.get_id
2013/02/19 08:28:30 [server:3] Client localhost.localdomain disconnected.
2013/02/19 08:58:30 [server:3] New client: localhost.localdomain.
2013/02/19 08:58:30 [server:3] Client localhost.localdomain disconnected.
2013/02/19 08:58:30 [server:3] New client: localhost.localdomain.
2013/02/19 08:58:30 [lang:3] dynamic_source.get_id
2013/02/19 08:58:30 [server:3] Client localhost.localdomain disconnected.
2013/02/19 09:05:36 [server:3] New client: localhost.localdomain.
2013/02/19 09:05:36 [decoder:3] Method "MAD" accepted "/var/tmp/airtime/pypo/cache/scheduler/40.mp3".
2013/02/19 09:05:36 [cue_cut_5385:3] Cueing out...
2013/02/19 09:05:36 [lang:3] vars.show_name
2013/02/19 09:05:36 [queue:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/35.mp3".
2013/02/19 09:05:36 [amplify_5390:3] End of the current overriding.
2013/02/19 09:05:36 [queue:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/40.mp3" (RID 0).
2013/02/19 09:05:36 [server:3] Client localhost.localdomain disconnected.
2013/02/19 09:05:36 [amplify_5390:3] Overriding amplification: 1.000000.
2013/02/19 09:05:36 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --data='0' --media-id=2184 &
2013/02/19 09:05:36 [lang:3] Using stream_format 0
2013/02/19 09:28:31 [server:3] New client: localhost.localdomain.
2013/02/19 09:28:31 [server:3] Client localhost.localdomain disconnected.
2013/02/19 09:28:31 [server:3] New client: localhost.localdomain.
2013/02/19 09:28:31 [lang:3] dynamic_source.get_id
2013/02/19 09:28:31 [server:3] Client localhost.localdomain disconnected.
2013/02/19 09:58:31 [server:3] New client: localhost.localdomain.
2013/02/19 09:58:31 [server:3] Client localhost.localdomain disconnected.
2013/02/19 09:58:31 [server:3] New client: localhost.localdomain.
2013/02/19 09:58:31 [lang:3] dynamic_source.get_id
2013/02/19 09:58:31 [server:3] Client localhost.localdomain disconnected.
2013/02/19 10:28:31 [server:3] New client: localhost.localdomain.
2013/02/19 10:28:31 [server:3] Client localhost.localdomain disconnected.
2013/02/19 10:28:31 [server:3] New client: localhost.localdomain.
2013/02/19 10:28:31 [lang:3] dynamic_source.get_id
2013/02/19 10:28:31 [server:3] Client localhost.localdomain disconnected.
2013/02/19 10:38:29 [server:3] New client: localhost.localdomain.
2013/02/19 10:38:29 [lang:3] vars.show_name
2013/02/19 10:38:29 [server:3] Client localhost.localdomain disconnected.
2013/02/19 10:38:29 [cue_cut_5385:3] Cueing out...
2013/02/19 10:38:29 [queue:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/40.mp3".
2013/02/19 10:38:29 [amplify_5390:3] End of the current overriding.
2013/02/19 10:38:29 [cross_5394:3] No next track ready yet.
2013/02/19 10:38:29 [default_switch:3] Switch to map_metadata_5421 with forgetful transition.
2013/02/19 10:38:29 [lang:3] transition called...
2013/02/19 10:38:29 [decoder:3] Method "MAD" accepted "/var/tmp/airtime/pypo/cache/scheduler/25.mp3".
2013/02/19 10:38:29 [dummy(dot)4:3] Source failed (no more tracks) stopping output...
2013/02/19 10:38:29 [queue:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/25.mp3" (RID 1).
2013/02/19 10:38:29 [amplify_5390:3] Overriding amplification: 0.592925.
2013/02/19 10:38:29 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --data='0' --media-id=2185 &
2013/02/19 10:38:29 [lang:3] Using stream_format 0
2013/02/19 10:38:29 [switch_5414:3] Switch to map_metadata_5401.
2013/02/19 10:38:29 [default_switch:3] Switch to switch_5414 with transition.
2013/02/19 10:38:29 [lang:3] transition called...
2013/02/19 10:58:31 [server:3] New client: localhost.localdomain.
2013/02/19 10:58:31 [server:3] Client localhost.localdomain disconnected.
2013/02/19 10:58:31 [server:3] New client: localhost.localdomain.
2013/02/19 10:58:31 [lang:3] dynamic_source.get_id
2013/02/19 10:58:31 [server:3] Client localhost.localdomain disconnected.
2013/02/19 11:28:32 [server:3] New client: localhost.localdomain.
2013/02/19 11:28:32 [server:3] Client localhost.localdomain disconnected.
2013/02/19 11:28:32 [server:3] New client: localhost.localdomain.
2013/02/19 11:28:32 [lang:3] dynamic_source.get_id
2013/02/19 11:28:32 [server:3] Client localhost.localdomain disconnected.
2013/02/19 11:31:18 [server:3] New client: localhost.localdomain.
2013/02/19 11:31:18 [server:3] Client localhost.localdomain disconnected.
2013/02/19 11:31:18 [main:3] Shutdown started!
2013/02/19 11:31:18 [main:3] Waiting for threads to terminate...
2013/02/19 11:31:18 [live:3] Closing connection...
2013/02/19 11:31:18 [queue:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/25.mp3".
2013/02/19 11:31:18 [harbor:3] Removing mountpoint '/live' on port 8051
2013/02/19 11:31:18 [harbor:3] Nothing more on port 8051: closing sockets.
2013/02/19 11:31:18 [harbor:3] Removing mountpoint '/master' on port 8050
2013/02/19 11:31:18 [harbor:3] Nothing more on port 8050: closing sockets.
2013/02/19 11:31:18 [clock.wallclock_main:3] Streaming loop stopped.
2013/02/19 11:31:18 [threads:3] Thread "wallclock_main" terminated (1 remaining).
2013/02/19 11:31:19 [threads:3] Thread "http polling" terminated (0 remaining).
2013/02/19 11:31:19 [main:3] Cleaning downloaded files...
2013/02/19 11:31:19 [main:3] Freeing memory...
2013/02/19 11:31:19 >>> LOG END
2013/02/19 11:31:21 >>> LOG START
2013/02/19 11:31:21 [protocols.external:3] Didn't find "ufetch".
2013/02/19 11:31:21 [protocols.external:3] Found "/usr/bin/wget".
2013/02/19 11:31:21 [main:3] Liquidsoap 1.0.1+scm
2013/02/19 11:31:21 [main:3] Using: graphics=[distributed with Ocaml] pcre=6.2.3 dtools=0.3.0 duppy=0.4.2 duppy.syntax=0.4.2 cry=0.2.2 mm=0.2.0 xmlplaylist=0.1.3 ogg=0.4.3 vorbis=0.6.1 mad=0.4.4 flac=0.1.1 flac.ogg=0.1.1 dynlink=[distributed with Ocaml] lame=0.3.1 alsa=0.2.1 ao=0.2.0 taglib=0.2.0 camomile=0.8.3 faad=0.3.1 portaudio=0.2.0 pulseaudio=0.1.2 ladspa=0.1.4 camlimages=4.0.0
2013/02/19 11:31:21 [main:2] 
2013/02/19 11:31:21 [main:2] DISCLAIMER: This version of Liquidsoap has been
2013/02/19 11:31:21 [main:2] compiled from a snapshot of the development code.
2013/02/19 11:31:21 [main:2] As such, it should not be used in production
2013/02/19 11:31:21 [main:2] unless you know what you are doing!
2013/02/19 11:31:21 [main:2] 
2013/02/19 11:31:21 [main:2] We are, however, very interested in any feedback
2013/02/19 11:31:21 [main:2] about our development code and committed to fix
2013/02/19 11:31:21 [main:2] issues as soon as possible.
2013/02/19 11:31:21 [main:2] 
2013/02/19 11:31:21 [main:2] If you are interested in collaborating to
2013/02/19 11:31:21 [main:2] the development of Liquidsoap, feel free to
2013/02/19 11:31:21 [main:2] drop us a mail at <savonet-devl@lists.sf.net>
2013/02/19 11:31:21 [main:2] or to join the #savonet IRC channel on Freenode.
2013/02/19 11:31:21 [main:2] 
2013/02/19 11:31:21 [main:2] Please send any bug report or feature request
2013/02/19 11:31:21 [main:2] at <http://dev.sourcefabric.org/browse/LS>.
2013/02/19 11:31:21 [main:2] 
2013/02/19 11:31:21 [main:2] We hope you enjoy this snapshot build of Liquidsoap!
2013/02/19 11:31:21 [main:2] 
2013/02/19 11:31:21 [dynamic.loader:3] Could not find dynamic module for aacplus encoder.
2013/02/19 11:31:21 [dynamic.loader:2] Could not load plugins in directory /usr/local/lib/liquidsoap/scm/plugins.
2013/02/19 11:31:21 [frame:3] Using 44100Hz audio, 25Hz video, 44100Hz master.
2013/02/19 11:31:21 [frame:3] Frame size must be a multiple of 1764 ticks = 1764 audio samples = 1 video samples.
2013/02/19 11:31:21 [frame:3] Targetting 'frame.duration': 0.04s = 1764 audio samples = 1764 ticks.
2013/02/19 11:31:21 [frame:3] Frames last 0.04s = 1764 audio samples = 1 video samples = 1764 ticks.
2013/02/19 11:31:21 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --liquidsoap-started &
2013/02/19 11:31:21 [threads:3] Created thread "generic queue #1".
2013/02/19 11:31:21 [threads:3] Created thread "generic queue #2".
2013/02/19 11:31:21 [threads:3] Created thread "non-blocking queue #1".
2013/02/19 11:31:21 [harbor:3] Adding mountpoint '/master' on port 8050
2013/02/19 11:31:21 [harbor:3] Adding mountpoint '/live' on port 8051
2013/02/19 11:31:21 [threads:3] Created thread "http polling" (1 total).
2013/02/19 11:31:21 [live:3] Connecting mount live for source@176.31.239.83...
2013/02/19 11:31:21 [live:3] Connection setup was successful.
2013/02/19 11:31:21 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --connect --stream-id=1 --time=1361259081.56 &
2013/02/19 11:31:21 [threads:3] Created thread "wallclock_main" (2 total).
2013/02/19 11:31:21 [clock.wallclock_main:3] Streaming loop starts, synchronized with wallclock.
2013/02/19 11:31:21 [mksafe:3] Switch to safe_blank.
2013/02/19 11:31:21 [mksafe:3] Switch to safe_blank.
2013/02/19 11:31:21 [dummy(dot)2:3] Source failed (no more tracks) stopping output...
2013/02/19 11:31:21 [dummy(dot)3:3] Source failed (no more tracks) stopping output...
2013/02/19 11:31:21 [dummy(dot)4:3] Source failed (no more tracks) stopping output...
2013/02/19 11:31:21 [map_metadata_5421:3] Inserting missing metadata.
2013/02/19 11:31:21 [master_dj_switch:3] Switch to default_switch.
2013/02/19 11:31:21 [default_switch:3] Switch to map_metadata_5421.
2013/02/19 11:31:22 [server:3] New client: localhost.localdomain.
2013/02/19 11:31:22 [lang:3] streams.scheduled_play_start
2013/02/19 11:31:22 [lang:3] streams.live_dj_stop
2013/02/19 11:31:22 [lang:3] streams.master_dj_stop
2013/02/19 11:31:22 [lang:3] vars.stream_metadata_type
2013/02/19 11:31:22 [lang:3] vars.station_name
2013/02/19 11:31:22 [lang:3] vars.default_dj_fade
2013/02/19 11:31:22 [server:3] Client localhost.localdomain disconnected.
2013/02/19 11:31:22 [server:3] New client: localhost.localdomain.
2013/02/19 11:31:22 [server:3] Client localhost.localdomain disconnected.
2013/02/19 11:31:22 [server:3] New client: localhost.localdomain.
2013/02/19 11:31:22 [lang:3] dynamic_source.get_id
2013/02/19 11:31:22 [server:3] Client localhost.localdomain disconnected.
2013/02/19 11:31:22 [server:3] New client: localhost.localdomain.
2013/02/19 11:31:22 [lang:3] source.skip
2013/02/19 11:31:22 [server:3] Client localhost.localdomain disconnected.
2013/02/19 11:31:22 [server:3] New client: localhost.localdomain.
2013/02/19 11:31:22 [lang:3] dynamic_source.output_stop
2013/02/19 11:31:22 [lang:3] dynamic_source.id
2013/02/19 11:31:22 [server:3] Client localhost.localdomain disconnected.
2013/02/19 11:31:22 [server:3] New client: localhost.localdomain.
2013/02/19 11:31:22 [decoder:3] Method "MAD" accepted "/var/tmp/airtime/pypo/cache/scheduler/25.mp3".
2013/02/19 11:31:22 [lang:3] vars.show_name
2013/02/19 11:31:22 [queue:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/25.mp3" (RID 0).
2013/02/19 11:31:22 [default_switch:3] Switch to switch_5414 with transition.
2013/02/19 11:31:22 [lang:3] transition called...
2013/02/19 11:31:22 [server:3] Client localhost.localdomain disconnected.
2013/02/19 11:31:22 [server:3] New client: localhost.localdomain.
2013/02/19 11:31:22 [switch_5414:3] Switch to map_metadata_5401.
2013/02/19 11:31:22 [server:3] Client localhost.localdomain disconnected.
2013/02/19 11:31:22 [cue_cut_5385:3] Cueing in...
2013/02/19 11:31:32 [amplify_5390:3] Overriding amplification: 0.592925.
2013/02/19 11:31:32 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --data='0' --media-id=2185 &
2013/02/19 11:31:32 [lang:3] Using stream_format 0
2013/02/19 11:31:32 [clock.wallclock_main:2] We must catchup 9.70 seconds!
2013/02/19 11:31:33 [clock.wallclock_main:2] We must catchup 0.82 seconds (we've been late for 100 rounds)!
toots commented 11 years ago

Hi @mkonecny and thanks for the very detailed report. I will look at it today. One immediate issue here is that it's hard to pinpoint which source is streaming blank data. It'd be cool if you could increase verbosity and add ids (I bet that's why you pushed this PR now..). Also, one way to detect which source is streaming silence would be to use a fallback with a static single so we can hear which single is being played.. Also, that could be a way to mitigate the issue with your users while we work on fixing it..

toots commented 11 years ago

Hi @mkonecny! I've realized something wrong with your script:

[({!live_slave_enabled}, slave_live), ({true}, s)]

This is not correct, as !live_slave_enabled will be evaluated once at startup and you'll only get a constant function.. What you need is:

f = fun () -> !live_slave_enabled
[(f, slave_live), ({true}, s)]

Let me know if that fixes your problem..

smimram commented 11 years ago

Don't think so, {!live_slave_enabled} is just syntactic sugar for fun () -> !live_slave_enabled...

mkonecny commented 11 years ago

One user went back to Liquidsoap 1.1.0 and mentioned his daily silence issue has disappeared. Romain, I will use your debug method with the static single and report back.

mkonecny commented 11 years ago

Another piece to the puzzle...

So what we did is started using a silence detector on one of ours user's streams. We had ssh access to their box, so as soon as it happened, I got in, and started playing around.

I found I could do the following in telnet

streams.master_dj_start # !live_master_enabled => true
streams.master_dj_stop # !live_master_enabled => false

Doing the first command I heard a slight click. The second command fixed the playback.

I know from past attempts that using the second command alone does not fix the problem.

toots commented 11 years ago

Thanks @mkonecny I'm putting this on top of my TODO list. Sorry for the inconveniences..

mkonecny commented 11 years ago

It happened again, and I have more useful information:

  1. Metadata is still streamed!!! It's only the audio that dies.
  2. I mentioned I heard a click when doing streams.master_dj_start. Today I noticed it again and it's actually a small fraction of a song that is played. Almost as if some buffer's contents is released. As before, doing `streams.master_dj_stop is what finally gets the audio flowing.
mkonecny commented 11 years ago

Also one of the users this is happening to just reported something else:

In the previous message I said metadata was still being streamed during silence. It appears that metadata corresponded to what was last sent to input.harbor. However the user said when he disconnected from input.harbor, the metadata + audio switched successfully to his scheduled content in request.equeue. Only sometime later (more than 30min) he found that the stream had turned silent, and the metadata had switched back to what he had streamed last in input.harbor.

So if I'm interpreting this situation correctly, the input.harbor buffer has some residual data left in it. This buffer is not receiving data anymore, but is not being completely flushed out either. I guess the switch operator detects that there is some data at a later time, and switches to this "dead" source, is able to capture metadata from this buffer and output it, resulting in what we've seen?

toots commented 11 years ago

Ok, been looking at the logs above. I've noticed several occurrences of:

2013/02/19 08:05:04 [dummy(dot)3:3] Source failed (no more tracks) stopping output...
2013/02/19 08:05:04 [dummy(dot)4:3] Source failed (no more tracks) stopping output...

These look like the input.harbor finishing their current stream. However, there are several points that I do not fully understand:

2013/02/19 00:59:15 [lang:3] live dj connected
2013/02/19 00:59:19 [lang:3] live dj connected
2013/02/19 00:59:21 [lang:3] live dj connected
2013/02/19 00:59:23 [lang:3] live dj connected
2013/02/19 00:59:26 [lang:3] live dj connected
2013/02/19 00:59:29 [lang:3] live dj connected
2013/02/19 00:59:33 [lang:3] live dj connected
2013/02/19 00:59:45 [lang:3] live dj connected
2013/02/19 00:59:56 [lang:3] live dj connected

Finally, at 10:38, we have:

2013/02/19 10:38:29 [decoder:3] Method "MAD" accepted "/var/tmp/airtime/pypo/cache/scheduler/25.mp3".
2013/02/19 10:38:29 [dummy(dot)4:3] Source failed (no more tracks) stopping output...
2013/02/19 10:38:29 [queue:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/25.mp3" (RID 1).

Compared to the previous pattern, only one output stops. I'd suspect the second one got stuck playing silence..

mkonecny commented 11 years ago

For reference, here is our stream tree.

20130605_123923

Regarding this output:

2013/02/19 08:05:04 [dummy(dot)3:3] Source failed (no more tracks) stopping output...
2013/02/19 08:05:04 [dummy(dot)4:3] Source failed (no more tracks) stopping output...

There are two output.dummy sinks. One after queue in the diagram, and one after the first switch. When They both fire that log when the track finishes, and they are not related to input.harbor.

live dj connected log happens whenever there is a connection attempt - but in this case the user is not passing authenication, since their show hasn't started yet at the top of the hour (this user's broadcast client is hammering liquidsoap so it can start asap at 01:00:00)

Compared to the previous pattern, only one output stops. I'd suspect the second one got stuck playing silence..

Maybe only of the dummy sinks fired this log because a new track was immediately pushed? Not sure why it only happened once.

mkonecny commented 11 years ago

Happened again last night, so perhaps this abbreviated log will help (we now know the exact time it goes silent)

2013/06/05 01:10:22 [server:3] New client: localhost.localdomain.
2013/06/05 01:10:22 [decoder:3] Method "MAD" accepted "/var/tmp/airtime/pypo/cache/scheduler/73.mp3".
2013/06/05 01:10:22 [lang:3] vars.show_name
2013/06/05 01:10:22 [server:3] Client localhost.localdomain disconnected.
2013/06/05 01:10:22 [queue:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/10.wav".
2013/06/05 01:10:22 [cue_cut_5446:3] End of track before cue-out point.
2013/06/05 01:10:22 [amplify_5451:3] End of the current overriding.
2013/06/05 01:10:22 [queue:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/73.mp3" (RID 2).
2013/06/05 01:10:22 [cue_cut_5446:3] Cueing in...
2013/06/05 01:10:22 [amplify_5451:3] Overriding amplification: 1.000000.
2013/06/05 01:10:22 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --media-id=11740 &
2013/06/05 01:10:22 [lang:3] Using stream_format 0
2013/06/05 01:10:22 [stdout:3] 
2013/06/05 01:10:22 [stdout:3] #########################################
2013/06/05 01:10:22 [stdout:3] #           *** pypo  ***               #
2013/06/05 01:10:22 [stdout:3] #     pypo notification gateway         #
2013/06/05 01:10:22 [stdout:3] #########################################
2013/06/05 01:25:32 [server:3] New client: localhost.localdomain.
2013/06/05 01:25:32 [server:3] Client localhost.localdomain disconnected.
2013/06/05 01:25:32 [server:3] New client: localhost.localdomain.
2013/06/05 01:25:32 [lang:3] dynamic_source.get_id
2013/06/05 01:25:32 [server:3] Client localhost.localdomain disconnected.
2013/06/05 01:52:29 [server:3] New client: localhost.localdomain.
2013/06/05 01:52:29 [server:3] Client localhost.localdomain disconnected.
2013/06/05 01:52:29 [server:3] New client: localhost.localdomain.
2013/06/05 01:52:29 [lang:3] dynamic_source.get_id
2013/06/05 01:52:29 [server:3] Client localhost.localdomain disconnected.
>>>1:54 - SILENCE DETECTED
2013/06/05 02:07:29 [server:3] New client: localhost.localdomain.
2013/06/05 02:07:29 [decoder:3] Method "MAD" accepted "/var/tmp/airtime/pypo/cache/scheduler/68.mp3".
2013/06/05 02:07:29 [lang:3] vars.show_name
2013/06/05 02:07:29 [server:3] Client localhost.localdomain disconnected.
2013/06/05 02:07:29 [cue_cut_5446:3] Cueing out...
2013/06/05 02:07:29 [queue:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/73.mp3".
2013/06/05 02:07:29 [amplify_5451:3] End of the current overriding.
2013/06/05 02:07:29 [queue:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/68.mp3" (RID 0).
2013/06/05 02:07:29 [amplify_5451:3] Overriding amplification: 1.000000.
2013/06/05 02:07:29 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --media-id=11741 &

You can see we telnetted into Liquidsoap twice 2 min before the silence. The first was to get execute queue.queue. The second was to execute dynamic_source.get_id which is defined as follows:

def get_dynamic_source_id() =
    string_of(!current_dyn_id)
end

server.register(namespace="dynamic_source",
                description="Get the streams cc_schedule row id",
                usage="get_id",
                "get_id",
                fun (s) -> begin log("dynamic_source.get_id") get_dynamic_source_id() end)

It simply tells us the id of the current webstream playing through input.http (or negative number if it isn't playing, which is the case here)

mkonecny commented 11 years ago

@toots,

Happened again twice for two different users. I took a look, and now I think my previous post isn't too helpful...there is no consistent sequence of logged events right before stream goes silence :(.

I know that I'm bombarding you with info here...two more pieces of info

toots commented 11 years ago

Ok, it seems like this was fixed. Closing now, please reopen/submit again if needed.

awgneo commented 11 years ago

I have seen this daily in 1.1.0 and I am using no mksafe operators. The audio is silent but the metadata still flows through fine :/ It seems to occur 6 to 12 hours after someone connects via input.harbor, even after disconnecting.

toots commented 11 years ago

Hi @awgneo and thanks for your feedback. Would be kind enough to share your script and details, if you have more than what you said above? Thks!

awgneo commented 11 years ago

Absolutely. Unfortunately I lost the original logs that were being produced during the error. However, my station is running 24/7, so when my listeners complain about dead air, I shall post it ASAP, haha ;)

Until then, my liquidsoap script can be found in full here: https://github.com/TeamPalmTree/cloudcast-liquidsoap. The bulk of the hookups can be found in includes\radio.liq file.

This is part of a larger open source radio automation project I've been working on called CloudCast: https://github.com/TeamPalmTree/cloudcast-full. Thanks for your help! It would be greatly appreciated. I've really enjoyed the dedication you guys have shown to liquidsoap and I've loved making donations to it in the name of open source radio.

toots commented 11 years ago

Thanks @awgneo! This bug is the last one preventing a new release. Hoping we can fix it soon!

awgneo commented 10 years ago

Sorry for the delay! It takes quite some time to replicate this issue.

Last night, I ran a test instance of my script (https://github.com/TeamPalmTree/cloudcast-liquidsoap) and did some live talkover broadcasting via input.harbor. I then disconnected and let the queue run the rest of the night. When I woke up this morning, this issue was replicated. Metadata was being pushed out, Liquidsoap was not crashed, the log continued to get filled, but the application was completely silent.

This has happened via output.icecast and output.ao; however, in this case, I was using output.ao in my test environment. I am not sure when exactly the silence began, as my previous attempts to deduce where it occurred in the log have failed. This log was generated at level 5.

https://www.dropbox.com/s/evvawjvfel8qm9j/cloudcast.log

Thanks! I will be available the next several days pretty much 24/7 for questions.

awgneo commented 10 years ago

Also, many people on the Airtime forums have suggested that this is an architecture issue (http://forum.sourcefabric.org/discussion/comment/26052#Comment_26052) with 32-bit linux distributions. I am also using a 32-bit OS (CentOS 6.4 x86).

dbaelde commented 10 years ago

I'd like to help with this issue. Obviously, it would be best if we could reproduce easily, or at least reproduce after some time on a minimal script. But I tried to dig in your log anyway, for lack of anything better. I have a bunch of remarks, sorry if some are dumb, I haven't followed all the story.

Liquidsoap starts at 18:39. The second file to be added to the queue is the Nerd Tuesdays Midshow. It is pushed at 18:39:56 but is only fully prepared and ready to play at 18:45:03. It seems that the MP3 decoder is taking a long time to open and check this file, I wonder why. Can you try liquidsoap -r ? It shouldn't take long, even to compute the duration, because the file lasts only one second: in your logs, it ends at 18:45:04.

(We have a similar situation with the third file, Mat Zo something, pushed at 18:45:15 and ready at 18:49:28.)

While the file is being prepared we see lots of noise in the logs. What is supposed to be playing while this file is being prepared? (A pointer to one of your files on github could be useful.) I want to make sure that you're not using a source that liquidsoap treats as failsafe but in reality requires super long resolutions to produce its data. If you see metadata passing through, this kind of contradicts this hypothesis, though.

Apart from that, I didn't notice anything interesting in your log :(

Regarding the bug in itself, do you know if silence is being streamed inside liquidsoap? I see that you have an on_blank operator, does it tell you anything? We should try to know if this is a problem local to the encoder, or if it's deeper in liquidsoap.

awgneo commented 10 years ago

Hello. Yes, this is a rather complex script :/.

The queue is just a dynamic list of key and value pairs for each file (defined in variables.liq, managed in queue.liq). It is separate from the actual liquidsoap request.queue (defined in variables.liq, pushed to in queue.liq via server.execute("schedule.push #{queue['file_name']}")). My queue contains each file's information and is kept in sync with the request.queue.

The MP3 decoder is instantaneous and there is no lag. Looking at the log, the first file (Above & Beyond - On My Way To Heaven (Seven Lions Remix) [feat. Richard Bedford].mp3) is pushed to my queue at 18:39:47. It then plays at 18:39:47 (2013/11/12 18:39:47 [schedule:3] Prepared "E:\CloudCast\backup\prepared\Above & Beyond - On My Way To Heaven (Seven Lions Remix) [feat. Richard Bedford].mp3" (RID 22).).

My queue then receives the Nerd Tuesdays Midshow file (as the queue was emptied), and it is pushed to the request.queue at 18:39:56. This file isn't prepared or played, however, until the previous Above & Beyond file is complete. I have always assumed that the server.execute("schedule.push #{queue['file_name']}") call I use to get the file into the schedule request.queue doesn't force the file to immediately prepare itself in Liquidsoap until it is really needed. Therefore, there are no gaps or lags in sound. I am just queuing up files in advance.

The meat of the liquidsoap code is in the radio.liq file, which hooks everything together. The on_blank operator I currently use is for microphone input blank detection and not the final output stream. I can add a on_blank to the final output and see if that picks up anything. That might be a good test :).

Thanks!

toots commented 10 years ago

Now that we know that the bug might be arch specific and, considering the fact that it seems to occur after a fairly large amount of time, I am wondering if we could be dealing with some kind of overflow.. For instance, in 32 bit archs, integers are 4 bytes long. In liquidsoap, we store some value in ticks using integers. I think that OCaml uses one bit for its GC management, so that leaves us with 31 bits. At 44100Hz, that means that the maximum length that can be stored in ticks in a integer is 13h... It is possible that, for some reason, input.harbor keeps a integer counter in ticks that overflows.. @dbaelde, what do you think?

toots commented 10 years ago

Actually, this is even worst since integers are signed.. We only have about 6-7h available in ticks on 32bit platforms..

awgneo commented 10 years ago

This occurs several hours after we disconnect from input.harbor. Is this integer counter still running after disconnection? The station runs fine 24/7/365 as long as we don't touch the input.harbors.

dbaelde commented 10 years ago

@awgneo thanks for the explanation. My comments was misleaded, indeed the final preparation can happen quite a big of time after the initial checking that happens when you push a local file.

@toots I don't think ticks are the cause, but I cannot say for sure. In principle, our ticks could be stored in just a boolean, we only ever need to distinguish one tick from the next. I have left a comment saying this in source.ml or clock.ml, but have never really tested that assumption: it would be interesting (and fun) to do so! (Make time be a bool, or even an abstract data type, and make sure nobody looks into them in incompatible ways.)

dbaelde commented 10 years ago

Ok, I tested the assumption, at first sight it seems correct. See https://github.com/savonet/liquidsoap/commit/737f25d2793e08d5666f3f0cfba69325f602b21a.

@toots you might have had in mind another kind of ticks. For instance in clock.ml, the class wallclock has a streaming loop that keeps track of time more precisely that just the tic/tac of clock#get_tick. But there ticks are implemented as Int64 integers, which is safe.

okayawright commented 10 years ago

Just to report that I get the exact same symptoms described above, but it only appeared quite recently, I blame this on an upgrade to liquidsoad v1.1.1 (sourceforge public release) on 32bit Debian from lower versions (didn't keep track of the exact revision numbers) on 64bit NetBSD, on a test machine. But it might also be pure coincidence. The liquidsoap scripts used before and after the migration are basically the same (the core is identical, only a few more decorations in the newer scripts.)

I never connect to input.harbor() but it's yet active in a fallback() branch. eat_blank() and strip_blank() thresholds are set to -30db.

toots commented 10 years ago

Hi!

We've confirmed that the issue only appears on 32bit architectures. Beside that, though, we're in dead waters regarding what causes it.. Will look at the reports again soon..

okayawright commented 10 years ago

Hello, are there any workarounds available yet, please, except using a 64bit OS? Can I be of any help? I don't know anything about OCaml but is there some kind of a platform-specific GDB I can use for auditing the binary when the problem occurs and provide you with some logs? Do we know yet whether it's linked to the core or to one of its dependencies (codec, icecast library, etc)? Thanks

dbaelde commented 10 years ago

Sorry, no known workaround. We don't even know at which level exactly the bug is (sources, encoder, network, etc); if we knew it'd probably be fixed already...

On Wed, Dec 25, 2013 at 11:46 PM, okayawright notifications@github.comwrote:

Hello, are there any workarounds available yet, please, except using a 64bit OS? Thanks

— Reply to this email directly or view it on GitHubhttps://github.com/savonet/liquidsoap/issues/66#issuecomment-31206515 .

David

okayawright commented 10 years ago

If it might be of any help, and it might just be a fluke, but apparently downgrading Liquidsoap and dependencies from 1.1.1-6 to 1.0.1+repack1-1.1 (official debian packages) is stable and streams no silent for 5 full days now - a record yet to break. The only difference with the prior installation (except the version numbers) is that I forgot to install the last.fm plugin this time.

ii liquidsoap 1.0.1+repack1-1.1 i386 audio streaming language ii liquidsoap-plugin-flac 1.0.1+repack1-1.1 i386 audio streaming language -- FLAC plugin ii liquidsoap-plugin-icecast 1.0.1+repack1-1.1 i386 audio streaming language -- Icecast plugin ii liquidsoap-plugin-lame 1.0.1+repack1-1.1 i386 audio streaming language -- Lame plugin ii liquidsoap-plugin-mad 1.0.1+repack1-1.1 i386 audio streaming language -- Mad plugin ii liquidsoap-plugin-ogg 1.0.1+repack1-1.1 i386 audio streaming language -- Ogg plugin ii liquidsoap-plugin-samplerate 1.0.1+repack1-1.1 i386 audio streaming language -- Samplerate plugin ii liquidsoap-plugin-taglib 1.0.1+repack1-1.1 i386 audio streaming language -- Taglib plugin ii liquidsoap-plugin-xmlplaylist 1.0.1+repack1-1.1 i386 audio streaming language -- Xmlplaylist plugin

toots commented 10 years ago

Thanks for the input. Sorry that we have no clue about this bug. I don't know of any changes between 1.0.1 and 1.1.1 that would suggest this kind of issue. At this point, I am even considering a possible bug in the OCaml compiler itself..

Romain

2014/1/2 okayawright notifications@github.com

If it might be of any help, and it might just be a fluke, but apparently downgrading Liquidsoap and dependencies from 1.1.1-6 to 1.0.1+repack1-1.1 (official debian packages) is stable and streams no silent for 5 full days now - a record yet to break. The only difference with the prior installation (except the version numbers) is that I forgot to install the last.fm plugin this time.

ii liquidsoap 1.0.1+repack1-1.1 i386 audio streaming language ii liquidsoap-plugin-flac 1.0.1+repack1-1.1 i386 audio streaming language -- FLAC plugin ii liquidsoap-plugin-icecast 1.0.1+repack1-1.1 i386 audio streaming language -- Icecast plugin ii liquidsoap-plugin-lame 1.0.1+repack1-1.1 i386 audio streaming language -- Lame plugin ii liquidsoap-plugin-mad 1.0.1+repack1-1.1 i386 audio streaming language -- Mad plugin ii liquidsoap-plugin-ogg 1.0.1+repack1-1.1 i386 audio streaming language -- Ogg plugin ii liquidsoap-plugin-samplerate 1.0.1+repack1-1.1 i386 audio streaming language -- Samplerate plugin ii liquidsoap-plugin-taglib 1.0.1+repack1-1.1 i386 audio streaming language -- Taglib plugin ii liquidsoap-plugin-xmlplaylist 1.0.1+repack1-1.1 i386 audio streaming language -- Xmlplaylist plugin

— Reply to this email directly or view it on GitHubhttps://github.com/savonet/liquidsoap/issues/66#issuecomment-31432808 .

smimram commented 10 years ago

A side note. If this gets reproductible, it might be a good idea to try the native version of ocaml-duppy (https://github.com/savonet/ocaml-duppy/pull/2) and see if the problem persists (I think this could be a deadlock in duppy).

okayawright commented 10 years ago

FYI, that specific build of Liquidsoap 1.0.1 is still running perfectly here. I'm on vacation now but I'll test this branch and report ASAP, thank you for your dedicated and relentless work, very much appreciated! Which versions of the OCaml and C toolchains can I use? Are the one provided with the current Debian Testing fine?

toots commented 10 years ago

Hi,

It looks like 1.0.1 was compiled with ocaml 3.12. Since you can reproduce, here's something that would be interesting to try, although probably painful as hell:

C toolchain probably doesn't matter I think..

Romain

2014/1/3 okayawright notifications@github.com

FYI, that specific build of Liquidsoap 1.0.1 is still running perfectly here. I'm on vacation now but I'll test this branch and report ASAP, thank you for your dedicated and relentless work, very appreciated! Which versions of the OCaml and C toolchains can I use? Are the one provided with the current Debian Testing fine?

? Reply to this email directly or view it on GitHubhttps://github.com/savonet/liquidsoap/issues/66#issuecomment-31553755 .

mkonecny commented 10 years ago

I can confirm that when this bug was happening for Sourcefabric, it was with a 3.1x OCaml compiler.

okayawright commented 10 years ago

(Finally) I have been able to recompile the whole stuff with Ocaml 3.12, and Liquidsoap still displays that bug. Didn't try Ocaml 4. @mkonecny How did you get rid of that in the end? Do you provide DEB packages?

toots commented 10 years ago

This bug is a nightmare.. Still can't reproduce... Would love to fix for the next release but may have to leave it aside unless more info surfaces.. :-(

okayawright commented 10 years ago

Exact same environment, a 32bit Debian box with Ocaml 4.01.0. when compiling from scratch and running: -The 1.1.1 full tarball from Sourceforge: bug reproduced -The de8d49c1a605950adad95853c03af0d0b99666e2:20140513:205754 Git commit object: bug NOT reproducible

toots commented 10 years ago

Thanks for the update.. We might go ahead and release later, hoping the bug is fixed..

toots commented 6 years ago

Hi,

Unfortunately, this issue is so old that I don't think we'll ever be able to fix it in the current codebase. Closing now.. :-/