Scheduled files for playout are delayed by up to a minute
  • Hi, we are having a few problems with Airtime 2.5.1 at the moment, one of which is content that has been scheduled for playout is delayed by up to 1 minute. Airtime normally corrects itself after the first live show of the day. Attached is a log file generated by the following command:

    sudo grep '2014/06/20' /var/log/airtime/pypo-liquidsoap/ls_script.log

    Any idea why this could be happening?

    thanks

    James

  • 25 Comments sorted by
  • Hello! Did ya figure it out? Which OS are you using? And which method did you use to install Airtime? Is this on a dedicated box?
  • Hi Roger, thanks for the reply.

    No we are still having this issue unfortunately. Our system is Ubuntu 12.04.4 LTS (GNU/Linux 3.5.0-51-generic x86_64). I didn't carry out this installation of Airtime so I don't know exactly how it was installed. It is running on a dedicated PC in our studio.

    Strangely the timing issue gets corrected whenever a new recorded show finishes. Check the log below - you can see that the 10am pre-recorded show started 18 secs late, the 11am live show started 22 seconds late, but the 11.30am pre-recorded show started right on time. Screenshot of calendar is attached too.

    James

    james@airtime:~$ sudo grep '2014/07/08 1'
    /var/log/airtime/pypo-liquidsoap/ls_script.log | egrep -v 'New
    client|Client localhost|dynamic_source' | tail -n 50


    2014/07/08 10:00:00 [lang:3] vars.show_name

    2014/07/08 10:00:18 [decoder:3] Method "MAD" accepted "/var/tmp/airtime/pypo/cache/scheduler/7747.mp3".

    2014/07/08 10:00:18 [s0:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/7805.mp3".

    2014/07/08 10:00:18 [cue_cut_5466:3] End of track before cue-out point.

    2014/07/08 10:00:18 [amplify_5470:3] End of the current overriding.

    2014/07/08 10:00:18 [s0:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/7747.mp3" (RID 1).

    2014/07/08 10:00:18 [amplify_5470:3] Overriding amplification: 0.946237.

    2014/07/08 10:00:18 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --media-id=8133 &

    2014/07/08 10:00:18 [lang:3] Using stream_format 0

    2014/07/08 10:00:18 [lang:3] Using stream_format 0

    2014/07/08 10:00:18 [lang:3] Using stream_format 0

    2014/07/08 10:00:19 [stdout:3]

    2014/07/08 10:00:19 [stdout:3] #########################################

    2014/07/08 10:00:19 [stdout:3] #           *** pypo  ***               #

    2014/07/08 10:00:19 [stdout:3] #     pypo notification gateway         #

    2014/07/08 10:00:19 [stdout:3] #########################################

    2014/07/08 11:00:22 [s0:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/7747.mp3".

    2014/07/08 11:00:22 [cue_cut_5466:3] End of track before cue-out point.

    2014/07/08 11:00:22 [amplify_5470:3] End of the current overriding.

    2014/07/08 11:00:22 [dummy(dot)2:3] Source failed (no more tracks) stopping output...

    2014/07/08 11:00:22 [dummy(dot)3:3] Source failed (no more tracks) stopping output...

    2014/07/08 11:00:22 [schedule_noise_switch:3] Switch to map_metadata_5601 with forgetful transition.

    2014/07/08 11:00:22 [lang:3] transition called...

    2014/07/08 11:30:00 [decoder:3] Method "MAD" accepted "/var/tmp/airtime/pypo/cache/scheduler/7745.mp3".

    2014/07/08 11:30:00 [lang:3] vars.show_name

    2014/07/08 11:30:00 [s0:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/7745.mp3" (RID 0).

    2014/07/08 11:30:00 [amplify_5470:3] Overriding amplification: 0.931108.

    2014/07/08 11:30:00 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --media-id=8131 &

    2014/07/08 11:30:00 [switch_5592:3] Switch to insert_metadata_5578.

    2014/07/08 11:30:00 [lang:3] Using stream_format 0

    2014/07/08 11:30:00 [schedule_noise_switch:3] Switch to map_metadata_5594 with transition.

    2014/07/08 11:30:00 [lang:3] transition called...

    2014/07/08 11:30:00 [stdout:3]

    2014/07/08 11:30:00 [stdout:3] #########################################

    2014/07/08 11:30:00 [stdout:3] #           *** pypo  ***               #

    2014/07/08 11:30:00 [stdout:3] #     pypo notification gateway         #

    2014/07/08 11:30:00 [stdout:3] #########################################


  • Are you connected to an external Icecast server? (other than your local machine)
  • No. Actually there are no streams output from this server. Hardware only.
    Post edited by James Dunn at 2014-07-23 08:36:32
  • Ok, what is selected on the output type? ALSA ?
  • Yes it's ALSA
  • I got some problems with alsa, maybe you could try OSS ?
  • I tried OSS but unfortunately our production machine isn't configured for OSS.

    This is becoming more of a problem as we haven't had a live show for a couple of weeks and the playout is now off by nearly 6 minutes!!! See the attached screenshot.

    A live show always seems to reset the lag for some reason.

    I've scheduled a restart of the airtime-playout service via cron for 4am each day to see if this helps, but it would be great to have a proper solution to this.

    James
  • Have you syncronised all your clocks to a timeserver on a cron? Maybe its as simple as that? The caching should have happened a while before the indicated show time.
    No longer using Airtime or Libretime.
  • What you describe could be related to this https://dev.sourcefabric.org/browse/CC-5554 but the difference is you don't use icecast...

    Actually I'm using ALSA output and it works perfect, I don't have any delay. What is your soundcard?
  • I saw a few like this before - it was always clock drift. Timezones maybe should be checked while you are doing it. 2.5.1 and 2.5.1a fixed a lot of time issues and the Git 2.5.2 fixes even more of it - as they brought the clock/timezone stuff together.

    Please try this for a test.. set every clock timezone you can find to UTC timezone (GMT).

    Drift will and does occur, so we need to synchronse the hardware clock with a ntp server on a cron - say hourly. We then need to sync the Unix Time from that from your control panel (hidden cron) or from your own written cron. Be aware Airtime keeps its own clock too :/

    Now all of the system should be marching to the beat of the same drummer.

    There were (and maybe still are) timezone bugs in 2.5.x. So I made every clock to UTC (GMT) and display it, to the masses, in local time and that sorted that. The nice side effect is - everybody sees the schedule in their local time.
    Post edited by John Chewter at 2014-08-18 20:21:55
    No longer using Airtime or Libretime.
  • I installed NTP on Debian and added the servers in /etc/ntp.conf. Is it automatically updated or I have to run ntpdate on cron?
  • Normally you have to add it to chron
    No longer using Airtime or Libretime.
  • Thanks for the replies. I've never seen a problem with the system clock, but I have just run the following commands:

    $ sudo dpkg-reconfigure tzdata

    Current default time zone: 'Europe/London'
    Local time is now:      Tue Aug 19 15:46:08 BST 2014.
    Universal Time is now:  Tue Aug 19 14:46:08 UTC 2014.

    $ sudo invoke-rc.d ntp restart
     * Stopping NTP server ntpd
       ...done.
     * Starting NTP server ntpd
       ...done.

    $ ntpq -p
         remote           refid      st t when poll reach   delay   offset  jitter
    ==============================================================================
     golem.canonical 192.93.2.20      2 u   10   64    1   14.121    0.089   0.000
     87.117.251.3    129.215.42.240   3 u    9   64    1   14.735   -0.273   0.000
     ntp2.websters-c 81.187.219.213   2 u    8   64    1   14.025   -0.741   0.000
     dns2-ha.uk.syra 193.47.164.28    3 u    7   64    1   13.899    0.538   0.000
     rigel.retrosnub 158.43.128.33    2 u    6   64    1   22.366   -4.165   0.000

    However there is something else very strange going on as yesterday we had a 2 hour show play out, only to be followed by the same 2 hour show, when it should have been a completely different 30 minutes show!! I've attached some logs, but the relevant section is pasted below:

    /var/log/airtime/pypo-liquidsoap/ls_script.log:

    2014/08/18 15:38:06 [stdout:3] #########################################
    2014/08/18 15:38:06 [stdout:3] #           *** pypo  ***               #
    2014/08/18 15:38:06 [stdout:3] #     pypo notification gateway         #
    2014/08/18 15:38:06 [stdout:3] #########################################
    2014/08/18 16:00:00 [lang:3] vars.show_name
    2014/08/18 16:00:00 [lang:3] vars.show_name
    2014/08/18 16:00:00 [decoder:3] Method "OGG" accepted "/var/tmp/airtime/pypo/cache/scheduler/105.ogg".
    2014/08/18 16:00:01 [s0:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/6067.mp3".
    2014/08/18 16:00:01 [cue_cut_5466:3] End of track before cue-out point.
    2014/08/18 16:00:01 [amplify_5470:3] End of the current overriding.
    2014/08/18 16:00:01 [s0:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/105.ogg" (RID 0).
    2014/08/18 16:00:01 [amplify_5470:3] Overriding amplification: 0.944061.
    2014/08/18 16:00:01 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --media-id=10200 &
    2014/08/18 16:00:01 [lang:3] Using stream_format 0
    2014/08/18 16:00:01 [lang:3] Using stream_format 0
    2014/08/18 16:00:01 [lang:3] Using stream_format 0
    2014/08/18 16:00:01 [stdout:3]
    2014/08/18 16:00:01 [stdout:3] #########################################
    2014/08/18 16:00:01 [stdout:3] #           *** pypo  ***               #
    2014/08/18 16:00:01 [stdout:3] #     pypo notification gateway         #
    2014/08/18 16:00:01 [stdout:3] #########################################
    2014/08/18 16:02:05 [lang:3] dynamic_source.get_id
    2014/08/18 16:08:02 [lang:3] dynamic_source.get_id
    2014/08/18 16:32:05 [lang:3] dynamic_source.get_id
    2014/08/18 16:38:02 [lang:3] dynamic_source.get_id
    2014/08/18 17:02:05 [lang:3] dynamic_source.get_id
    2014/08/18 17:08:02 [lang:3] dynamic_source.get_id
    2014/08/18 17:11:58 [lang:3] dynamic_source.get_id
    2014/08/18 17:18:51 [lang:3] dynamic_source.get_id
    2014/08/18 17:19:09 [lang:3] dynamic_source.get_id
    2014/08/18 17:19:16 [lang:3] dynamic_source.get_id
    2014/08/18 17:49:09 [lang:3] dynamic_source.get_id
    2014/08/18 17:49:16 [lang:3] dynamic_source.get_id
    2014/08/18 18:00:00 [lang:3] vars.show_name
    2014/08/18 18:00:00 [lang:3] vars.show_name
    2014/08/18 18:00:06 [decoder:3] Method "OGG" accepted "/var/tmp/airtime/pypo/cache/scheduler/105.ogg".
    2014/08/18 18:00:07 [s0:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/105.ogg".
    2014/08/18 18:00:07 [cue_cut_5466:3] Cueing out...
    2014/08/18 18:00:07 [amplify_5470:3] End of the current overriding.
    2014/08/18 18:00:07 [s0:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/105.ogg" (RID 1).
    2014/08/18 18:00:07 [amplify_5470:3] Overriding amplification: 0.944061.
    2014/08/18 18:00:07 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --media-id=10200 &
    2014/08/18 18:00:07 [lang:3] Using stream_format 0
    2014/08/18 18:00:07 [lang:3] Using stream_format 0
    2014/08/18 18:00:07 [lang:3] Using stream_format 0
    2014/08/18 18:00:07 [stdout:3]
    2014/08/18 18:00:07 [stdout:3] #########################################
    2014/08/18 18:00:07 [stdout:3] #           *** pypo  ***               #
    2014/08/18 18:00:07 [stdout:3] #     pypo notification gateway         #
    2014/08/18 18:00:07 [stdout:3] #########################################

    /var/log/airtime/pypo/pypo.log:

    2014-08-18 17:58:14,709 DEBUG - [api_client.py : get_stream_parameters() : line 504] - {u'stream_params': {u's3': {u'admin_pass': u'', u'enable': u'false', u'description': u'', u'url': u'', u'bitrate': u'48', u'mount': u'', u'liquidsoap_error': u'waiting', u'channels': u'stereo', u'host': u'', u'admin_user': u'', u'user': u'', u'pass': u'', u'genre': u'', u'output': u'icecast', u'type': u'ogg', u'port': u'', u'name': u''}, u's2': {u'admin_pass': u'', u'enable': u'false', u'description': u'', u'url': u'', u'bitrate': u'48', u'mount': u'', u'liquidsoap_error': u'waiting', u'channels': u'stereo', u'host': u'', u'admin_user': u'', u'user': u'', u'pass': u'', u'genre': u'', u'output': u'icecast', u'type': u'ogg', u'port': u'', u'name': u''}, u's1': {u'admin_pass': u'hackme', u'admin_user': u'admin', u'description': u'Airtime Radio! Stream #1', u'url': u'http://airtime.sourcefabric.org', u'bitrate': u'128', u'mount': u'airtime_128', u'liquidsoap_error': u'waiting', u'channels': u'stereo', u'host': u'localhost', u'enable': u'false', u'user': u'', u'pass': u'hackme', u'genre': u'genre', u'output': u'icecast', u'type': u'ogg', u'port': u'8000', u'name': u'Airtime!'}}}
    2014-08-18 18:00:00,001 DEBUG - [telnetliquidsoap.py : queue_push() : line 89] - s0.push annotate:media_id="7366",liq_start_next="0",liq_fade_in="0.5",liq_fade_out="0.5",liq_cue_in="0.038",liq_cue_out="1800.118",schedule_table_id="10126",replay_gain="2.06 dB":/var/tmp/airtime/pypo/cache/scheduler/7366.mp3

    2014-08-18 18:00:00,001 DEBUG - [telnetliquidsoap.py : queue_push() : line 95] - vars.show_name Daniel Ruiz Tizon

    2014-08-18 18:00:00,005 DEBUG - [telnetliquidsoap.py : queue_push() : line 98] - 3
    END
    Daniel Ruiz Tizon
    END
    Bye!

    2014-08-18 18:00:00,008 INFO - [pypoliqqueue.py : main() : line 38] - waiting 1799.991734s until next scheduled item
    2014-08-18 18:00:14,786 DEBUG - [api_client.py : __call__() : line 134] - http://localhost:80/api/get-stream-parameters/api_key/Q2WKM6URXO5U5J1LLUMG/format/json

    As you can see, '105.ogg' was played twice, when the 18:00 show should have been '7366.mp3'!
  • Also, after this the 18:30 show was played at 8pm, then repeated immediately afterwards at 10pm! Needless to say this was not in the calendar!
  • Calendar screenshot attached
    Post edited by James Dunn at 2014-08-19 11:23:07
  • Are all of the ingested media files of the same exact codec, bitrate, et cetera? I'm pretty sure there's a known bug where the calculated durations are off.
  • I change all incoming files to 128k constant rate in my ingest code ingest.
    No longer using Airtime or Libretime.
  • "as they brought the clock/timezone stuff together" - J. Chewter

    What's different? :-SS
  • In places they had some software clocks in UTC Time Zone and others in Station Time Zone, some code referencing the wrong clock and they did not match, giving seemingly unpredictable results and 2 tracks playing and other wierdness. In 2.5.0 I found this and set all the software and hardware clocks to the same timezone and much 'weirdness' stopped. There are some changes in the 2.5.2 GIT (post 2.5.1a) with further fixes.
    No longer using Airtime or Libretime.
  • @Roger:

    No, our media files are all sorts! Here's a selection of them:

    128 kbps, 44.1 kHz, JntStereo
    320 kbps, 44.1 kHz, Stereo
    128 kbps, 48 kHz, JntStereo
    128 kbps, 44.1 kHz, JntStereo
    160 kbps, 48 kHz, JntStereo
    128 kbps, 44.1 kHz, JntStereo
    128 kbps, 44.1 kHz, JntStereo
    160 kbps, 48 kHz, JntStereo
    160 kbps, 48 kHz, JntStereo
    128 kbps, 44.1 kHz, JntStereo
    160 kbps, 48 kHz, JntStereo
    128 kbps, 44.1 kHz, JntStereo
    128 kbps, 44.1 kHz, JntStereo
    128 kbps, 44.1 kHz, Stereo
    192 kbps, 44.1 kHz, Stereo
    160 kbps, 44.1 kHz, JntStereo
    128 kbps, 44.1 kHz, JntStereo
    48 kbps, 44.1 kHz, JntStereo
    48 kbps, 44.1 kHz, JntStereo
    192 kbps, 44.1 kHz, JntStereo
    192 kbps, 44.1 kHz, JntStereo
    160 kbps, 44.1 kHz, JntStereo
    128 kbps, 44.1 kHz, JntStereo
    128 kbps, 44.1 kHz, Stereo
    128 kbps, 44.1 kHz, Stereo
    320 kbps, 44.1 kHz, Stereo
    320 kbps, 44.1 kHz, JntStereo
    128 kbps, 44.1 kHz, Stereo
    144 kbps, 22.05 kHz, Stereo
    320 kbps, 44.1 kHz, JntStereo
    256 kbps, 44.1 kHz, Stereo

    These are all mp3, but we have some ogg vorbis files too. It could be the bitrate or sample rate that is throwing it off I suppose. Or the ogg vs mp3? Surely airtime/liquidsoap can handle these different files though?

    @John:

    Both the Station Time displayed in the web ui and the system time on the command line are the same. Are there any other clocks to adjust?

    James
  • Hardware clock is not necessarily periodlically updated from NTP and Unix Sytem time may not be updated from it. It often is, in a standard deployment, but may not be. ESPECIALLY in dedicated servers! Sometimes its only updated at boot time. Check the cron jobs. This shows up as time creep. I set the hardware TZ to UTC 0. (I am having fun with this on an ARM server - which has no hardware clock at all!)

    I have seen systems where the hardware clock is getting updated from NTP, but not the Unix clock. So, they check they time in the control panel (hardware clock) and scream that the clock is right. But when I compared it with the Unix clock, it was seconds different (creep) or even 5 hours (timezone issues).

    Note: internally, for the schedule, shows etc., AT uses UTC 0  for its internal calculations, or rather it should do. In places, this was not the case, alas. I switched everything to, specifically, UTC 0 so most errors would seem to disappear if the AT bugs had got it wrong. There are some more changes in GIT v2.5.2, after 2.5.1a, where further TZ bugs were fixed.

    Liquidsoap also maintains its own clock BTW.
    Post edited by John Chewter at 2014-08-21 09:30:12
    No longer using Airtime or Libretime.
  • I've just checked our hardware clock and the system clock and they are still the same. I've just changed the timezone to UTC and set the clocks again in case this helps.

    However we are currently 7 minutes behind in our broadcast!


    ~$ sudo tail -n 300 /var/log/airtime/pypo-liquidsoap/ls_script.log | egrep -v 'New client: localhost|Client localhost disconnected'
    2014/09/01 10:56:44 [lang:3] dynamic_source.get_id
    2014/09/01 11:00:00 [lang:3] vars.show_name
    2014/09/01 11:07:01 [decoder:3] Method "MAD" accepted "/var/tmp/airtime/pypo/cache/scheduler/7103.mp3".
    2014/09/01 11:07:01 [s0:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/5406.ogg".
    2014/09/01 11:07:01 [cue_cut_5466:3] End of track before cue-out point.
    2014/09/01 11:07:01 [amplify_5470:3] End of the current overriding.
    2014/09/01 11:07:01 [s0:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/7103.mp3" (RID 0).
    2014/09/01 11:07:01 [cue_cut_5466:3] Cueing in...
    2014/09/01 11:07:01 [cue_cut_5466:2] Could not seek to cue point!
    2014/09/01 11:07:01 [amplify_5470:3] Overriding amplification: 0.829851.
    2014/09/01 11:07:01 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --media-id=10847 &
    2014/09/01 11:07:01 [lang:3] Using stream_format 0
    2014/09/01 11:07:01 [lang:3] Using stream_format 0
    2014/09/01 11:07:01 [lang:3] Using stream_format 0
    2014/09/01 11:07:02 [stdout:3]
    2014/09/01 11:07:02 [stdout:3] #########################################
    2014/09/01 11:07:02 [stdout:3] #           *** pypo  ***               #
    2014/09/01 11:07:02 [stdout:3] #     pypo notification gateway         #
    2014/09/01 11:07:02 [stdout:3] #########################################
  • For anyone else having the same problem, Albert said it is a soundcard issue which is currently unresolvable:

    https://dev.sourcefabric.org/browse/CC-5909
  • Almost unlikely a soundcard issue.I have 5 cards in one machine  without issues
    1. USB Mixer Board  (connect the mixer to MainPlayout)
    2. MAudio Fast-Track pro (for Editing)
    3. Turtle Beach USB for Monitoring Playout
    4. USB Generic for Satellite in
    5. UCA222 for Guest Connection

    Top  shows 45-60% on a dual core machine

    If it was the sound card you should see a message like this "we have to catch up xxx sec"

    but just to be on the safe side you can tweak the sound settings to like this in you ls_script

    #for Alsa Inputs
    set("frame.size",1881)
    set("alsa.buffer_length",25)



    # for Alsa Outputs
    set("decoding.buffer_length",20.,)
    set("frame.channels", 2)
    set("frame.samplerate", 48000)


    and there is a settings to have your soundcard  runs on it own alsa clock.I am searching to find it,but it has a disadvantage of underruns which cause drifts if you try using the inputs and outputs simultaneously

    If you are using the Hardware Output on the stream settings try using AO. or Pulse

    Also my advise to anyone is that if you are using this output in the stream settings you will get unpredictable results,You may even have to disable the first stream.

    I cannot tell you what is wrong with it but if you reall want to monitor your output,get

    • an AM/FM radio for Terrestrial radio  or
    • An internet Stream radio/your phone to listen


    Gosh its 6 cards I have the 2496 which is the default and for Airtime Input/Output

    Try a NON-OBIVIOUS thing Change the CMOS Battery.Doubt it though

    VOISSES


    Post edited by Voisses Tech at 2014-09-08 13:50:07
    Anyone reading this a find it funny about my grammar , I make no apology ,Go get a translator.
    "The Problem with education today is that it takes a university degree to switch on a light bulb"
    "You learn from your mistakes but wise people learn from others mistakes avoid Making mistakes there is not sufficient rooms to make them"
    "Innuendo","If's","Assumptions" and "Fear" are for politician.Who,What,where,When and How are for those seeking knowledge and care about Humanity.
    "I might be in Mud but that does not Make me a Wild Hog(pig)"
    “Any intelligent fool can make things bigger, more complex, and more violent. It takes a touch of genius — and a lot of courage to move in the opposite direction.”
    "The only thing that remains constant is change itself"
    May the force be with you,until our path or destiny bring us in tandem.