2.0.3 not recording shows
  • Vote Up0Vote Down James DunnJames Dunn
    Posts: 226Member
    Hi guys,

    So I successfully installed 2.0.3 on a new machine and the archive has been upgraded. We went live with this today but Airtime 2.0.3 has not been recording all the shows. This is different to a previous error we had where the ecasound command wasn't even issued. Now the command is issued but returns an error code 1. Please see the attached logs. Luckily we are still running the other machine and recording from there.

    thanks
    James
  • 84 Comments sorted by
  • Vote Up1Vote Down James DunnJames Dunn
    Posts: 226Member
    After testing 2.0.3 for a week we decided to make the final step and swap over the 500Gb hard drive for the 2Tb because we were running out of space. Airtime can playback the files from this drive but when it copies the recorded shows to the drive, they do not show up in the playlist builder and are not uploaded to soundcloud. I've tried reinstalling 2.0.3 and restoring the schedule/database. This is now our production machine, which is not working! Could really use some help with this

    logs are attached

    thanks

    James

    airtime-log-all-2012-05-09-19-37-14.tgz
    2M
  • Vote Up1Vote Down James DunnJames Dunn
    Posts: 226Member
    Just so you all know, I just did a clean install manually of airtime-2.1.0-rc1 on another machine running Ubuntu 10.04.4 LTS i686 Desktop (not server) and encountered the same problem:

    show-recorder.log:

    2012-05-30 15:40:00,028 INFO - [recorder.py : record_show() : line 80] - command ecasound -f:16,2,44100 -i alsa -o /var/tmp/airtime/show-recorder/2012-05-30-15:40:00.ogg,256000 -t:1200.0
    2012-05-30 15:40:00,353 INFO - [recorder.py : record_show() : line 88] - finishing record, return code 1

    py-interpreter.log:

    TERM environment variable not set.
    Exception in thread Thread-6:
    Traceback (most recent call last):
      File "/usr/lib/python2.6/threading.py", line 532, in __bootstrap_inner
        self.run()
      File "/usr/lib/airtime/pypo/bin/recorder.py", line 166, in run
        os.remove(filepath)
    OSError: [Errno 2] No such file or directory: '/var/tmp/airtime/show-recorder/2012-05-30-15:40:00.ogg'

    So I added:

    export TERM=xterm

    to .bash_profile and /usr/lib/airtime/pypo/bin/airtime-playout and now it's working.
  • Vote Up0Vote Down James DunnJames Dunn
    Posts: 226Member
    Does anyone have any idea what this error could be? It hasn't happened again since 1st May but missing 5 shows is pretty crucial! Just wondering if we should go live with this version or maybe it will happen again?

    See this log:

    2012-05-01 19:59:55,058 DEBUG - [recorder.py : get_time_till_next_show() : line 221] - Shows {u'2012-05-01 19:00:00': [datetime.timedelta(0, 7200), u'4689', u'The New Jerusalem', u'Europe/London']}
    2012-05-01 19:59:55,111 DEBUG - [recorder.py : get_time_till_next_show() : line 222] - Next show 2012-05-01 19:00:00
    2012-05-01 19:59:55,121 DEBUG - [recorder.py : get_time_till_next_show() : line 223] - Now 2012-05-01 18:59:55.057877
    2012-05-01 19:59:55,122 DEBUG - [recorder.py : start_record() : line 231] - sleeping 4 seconds until show
    2012-05-01 19:59:59,270 INFO - [recorder.py : record_show() : line 85] - starting record
    2012-05-01 19:59:59,270 INFO - [recorder.py : record_show() : line 86] - command ecasound -f:16,2,44100 -i alsa -o /var/tmp/airtime/show-recorder/2012-05-01-20:00:00.mp3,192000 -t:7200.0
    2012-05-01 20:00:00,010 INFO - [recorder.py : record_show() : line 94] - finishing record, return code 1
    2012-05-01 20:00:00,010 INFO - [recorder.py : run() : line 165] - problem recording show
  • Vote Up0Vote Down Wade EilrichWade Eilrich
    Posts: 98Member
    Rather than swapping out the 500GB for the 2TB, it might be easier to use the Logical Volume Manager (LVM) to add the 2TB drive and keep the files where they are. Using LVM would give you an additional 2TB of space without the headaches of replacing a drive and having to deal with Linux file/drive/user permission issues.
  • Vote Up0Vote Down James DunnJames Dunn
    Posts: 226Member
    Point taken. I could probably look into that.

    However we now currently have the 2Tb hard drive installed and the permissions look fine. The shows are getting recorded but only sometimes copied across to the hard drive. When they are copied, they are not automatically uploaded to soundcloud.

    Also some shows seem to finish recording prematurely, with the message 'Show manually cancelled!'. I'm pretty sure these shows weren't manually cancelled from the web browser, mostly because when that happens, the show disappears from the calendar view and the display at the top of the browser says 'Nothing scheduled'. I still see 'Recording: some show' even though the show is not recording.

    In fact when I do manually cancel a show in the calendar I get a message like this:

    2012-05-09 17:11:50,901 INFO - [recorder.py : handle_message() : line 186] - Received msg from Pypo Message Handler: {u'server_timezone': u'Europe/London', u'event_type': u'cancel_recording', u'shows': [{u'time_filled': None, u'ends': u'2012-05-09 19:00:00', u'name': u'Sketchbook', u'color': u'000000', u'starts': u'2012-05-09 18:00:00', u'show_id': u'24', u'instance_id': u'4699', u'record': u'1', u'rebroadcast': u'0', u'file_id': None, u'background_color': u'5ae00d'}]}

    And the show is cancelled, both in the browser and with the ecasound command terminating. There is no 'Show manually cancelled' message in the log for this instance either. Seems some airtime gremlins want to cancel certain shows?

    Would be great to get these issues fixed

    thanks

    James
    Post edited by James Dunn at 2012-05-10 06:40:24
  • Vote Up0Vote Down James DunnJames Dunn
    Posts: 226Member
    Latest log:

    2012-05-11 09:59:55,756 DEBUG - [recorder.py : get_time_till_next_show() : line 221] - Shows {u'2012-05-11 09:00:00': [datetime.timedelta(0, 7200), u'4489', u'Imagination Land', u'Europe/London']}
    2012-05-11 09:59:55,756 DEBUG - [recorder.py : get_time_till_next_show() : line 222] - Next show 2012-05-11 09:00:00
    2012-05-11 09:59:55,756 DEBUG - [recorder.py : get_time_till_next_show() : line 223] - Now 2012-05-11 08:59:55.755993
    2012-05-11 09:59:55,757 DEBUG - [recorder.py : start_record() : line 231] - sleeping 4 seconds until show
    2012-05-11 09:59:59,843 INFO - [recorder.py : record_show() : line 85] - starting record
    2012-05-11 09:59:59,843 INFO - [recorder.py : record_show() : line 86] - command ecasound -f:16,2,44100 -i alsa -o /var/tmp/airtime/show-recorder/2012-05-11-10:00:00.mp3,192000 -t:7200.0
    2012-05-11 09:59:59,973 INFO - [recorder.py : record_show() : line 94] - finishing record, return code 1
    2012-05-11 09:59:59,974 INFO - [recorder.py : run() : line 165] - problem recording show

  • Vote Up0Vote Down NaomiNaomi
    Posts: 228Member
    Hey since it's a new install, maybe you are missing package "lame" for mp3 encoding? If you want to record in mp3 I think it's an extra dependency to install yourself these days.

    sudo apt-get install lame

    then try

    ecasound -f:16,2,44100 -i alsa -o ~/test.mp3,192000 -t:5

    to see if it can record. 

    you should get something that looks like this if it works

    **************************************************************************
    *        ecasound v2.8.1 (C) 1997-2011 Kai Vehmanen and others    
    **************************************************************************
    (eca-chainsetup-parser) Set processing time to 5.00.
    (eca-chainsetup) Chainsetup "untitled-chainsetup"
    (eca-chainsetup) NOTE: Real-time configuration, but insufficient privileges to utilize real-time scheduling (SCHED_FIFO). With small buffersizes, this may cause audible glitches during processing.
    (eca-chainsetup) "rt" buffering mode selected.
    (eca-chainsetup) Opened input "alsa", mode "read". Format: s16_le, channels 2, srate 44100, interleaved.
    (eca-chainsetup) NOTE: using existing audio parameters -f:s16_be,2,44100 for object '/home/naomiaro/test.mp3' (tried to open with -f:s16_le,2,44100).
    (eca-chainsetup) Opened output "/home/naomiaro/test.mp3", mode "write". Format: s16_be, channels 2, srate 44100, interleaved (locked params).
    - [ Connected chainsetup: "untitled-chainsetup" ] ------------------------
    - [ Controller/Starting batch processing ] -------------------------------
    - [ Engine - Driver start ] ----------------------------------------------
    (audioio-mp3) Starting to encode /home/naomiaro/test.mp3 with lame.

    - [ Engine - Processing finished ] ---------------------------------------
    - [ Controller/Batch processing finished (0) ] ---------------------------
    - [ Engine exiting ] -----------------------------------------------------
    (eca-control-objects) Disconnecting chainsetup:  "untitled-chainsetup".

  • Vote Up0Vote Down NaomiNaomi
    Posts: 228Member
    hmm reading above, I see that some of your shows have been recorded in the 2.0.3 install? Is that true?

    I'm checking the ecasound docs and they give this in their man pages for a return code of 1

    1
    Unable to create a valid chainsetup with the given parameters. Can be caused by invalid option syntax, etc.

    So if the above works for you and you already have lame installed can you send the output of one of the commands airtime is actually trying to issue itself such as

    ecasound -f:16,2,44100 -i alsa -o /var/tmp/airtime/show-recorder/2012-05-11-10:00:00.mp3,192000 -t:7200.0

    would have to either run that as root or pypo I guess.
  • Vote Up0Vote Down James DunnJames Dunn
    Posts: 226Member
    Hi Naomi,

    thanks for getting back to me. Lame is already installed. Here's the output of the ecasound command run manually as root:

    sudo ecasound -f:16,2,44100 -i alsa -o /var/tmp/airtime/show-recorder/2012-05-11-10:00:00.mp3,192000 -t:7200.0
    [sudo] password for nts-studio:
    **************************************************************************
    * ecasound v2.7.0 (C) 1997-2009 Kai Vehmanen and others
    **************************************************************************
    (eca-chainsetup-parser) Set processing time to 7200.00.
    (eca-chainsetup) Chainsetup "untitled-chainsetup"
    (eca-chainsetup) "rt" buffering mode selected.
    (audioio_alsa) Warning! Period-size differs from current client buffersize.
    (eca-chainsetup) Opened input "alsa", mode "read". Format: s16_le, channels 2, srate 44100, interleaved.
    (eca-chainsetup) NOTE: using existing audio parameters -f:s16_be,2,44100 for object
    ... '/var/tmp/airtime/show-recorder/2012-05-11-10:00:00.mp3 (tried to open with -f:s16_le,2,44100).
    (eca-chainsetup) Opened output "/var/tmp/airtime/show-recorder/2012-05-11-10:00:00.mp3", mode "write". Format: s16_be, channels 2,
    ... srate 44100, interleaved (locked params).
    - [ Connected chainsetup: "untitled-chainsetup" ] ------------------------
    - [ Controller/Starting batch processing ] -------------------------------
    - [ Engine - Driver start ] ----------------------------------------------
    (audioio-mp3) Starting to encode /var/tmp/airtime/show-recorder/2012-05-11-10:00:00.mp3 with lame.
    (eca-engine) Using realtime-scheduling (SCHED_FIFO:50).

    James
  • Vote Up0Vote Down NaomiNaomi
    Posts: 228Member
    hmm maybe try this

    sudo ecasound -f:16,2,44100 -i alsa -o /var/tmp/airtime/show-recorder/test.mp3,192000 -t:5

    just the same command but with a shorter time. Does the recording finish properly? There is a file in /var/tmp/airtime? What is the full output for this command?
    Post edited by Naomi at 2012-05-11 07:33:25
  • Vote Up0Vote Down James DunnJames Dunn
    Posts: 226Member
    Here's the output of the ecasound command:

    $ sudo ecasound -f:16,2,44100 -i alsa -o /var/tmp/airtime/show-recorder/test.mp3,192000 -t:5
    [sudo] password for nts-studio:
    **************************************************************************
    *        ecasound v2.7.0 (C) 1997-2009 Kai Vehmanen and others    
    **************************************************************************
    (eca-chainsetup-parser) Set processing time to 5.00.
    (eca-chainsetup) Chainsetup "untitled-chainsetup"
    (eca-chainsetup) "rt" buffering mode selected.
    (audioio_alsa) Warning! Period-size differs from current client buffersize.
    (eca-chainsetup) Opened input "alsa", mode "read". Format: s16_le, channels 2, srate 44100, interleaved.
    (eca-chainsetup) NOTE: using existing audio parameters -f:s16_be,2,44100 for object '/var/tmp/airtime/show-recorder/test.mp3 (tried to
    ... open with -f:s16_le,2,44100).
    (eca-chainsetup) Opened output "/var/tmp/airtime/show-recorder/test.mp3", mode "write". Format: s16_be, channels 2, srate 44100,
    ... interleaved (locked params).
    - [ Connected chainsetup: "untitled-chainsetup" ] ------------------------
    - [ Controller/Starting batch processing ] -------------------------------
    - [ Engine - Driver start ] ----------------------------------------------
    (audioio-mp3) Starting to encode /var/tmp/airtime/show-recorder/test.mp3 with lame.
    (eca-engine) Using realtime-scheduling (SCHED_FIFO:50).

    - [ Engine - Processing finished ] ---------------------------------------
    - [ Controller/Batch processing finished (0) ] ---------------------------
    - [ Engine exiting ] -----------------------------------------------------
    (eca-control-objects) Disconnecting chainsetup:  "untitled-chainsetup".

    and here's the contents of /var/tmp/airtime/show-recorder:

    $ ls -l /var/tmp/airtime/show-recorder/
    -rw-r--r-- 1 pypo pypo 115201670 2012-04-30 14:00 2012-04-30-12:00:00.mp3
    -rw-r--r-- 1 pypo pypo  86402193 2012-05-01 18:00 2012-05-01-17:00:00.mp3
    -rw-r--r-- 1 pypo pypo  86402193 2012-05-08 18:00 2012-05-08-17:00:00.mp3
    -rw-r--r-- 1 pypo pypo 259201566 2012-05-09 12:00 2012-05-09-09:00:00.mp3
    -rw-r--r-- 1 pypo pypo  86402193 2012-05-09 13:00 2012-05-09-12:00:00.mp3
    -rw-r--r-- 1 pypo pypo  86401566 2012-05-09 14:00 2012-05-09-13:00:00.mp3
    -rw-r--r-- 1 pypo pypo  10362880 2012-05-09 21:07 2012-05-09-21:00:00.mp3
    -rw-r--r-- 1 pypo pypo  86402193 2012-05-10 02:00 2012-05-10-01:00:00.mp3
    -rw-r--r-- 1 pypo pypo  13803520 2012-05-10 09:09 2012-05-10-09:00:00.mp3
    -rw-r--r-- 1 root root    122252 2012-05-11 12:45 test.mp3


    Strange that everything looks perfectly normal...
  • Vote Up0Vote Down NaomiNaomi
    Posts: 228Member
    hmm ok yes it does look fine

    so to match this line here

    2012-05-11 09:59:59,973 INFO - [recorder.py : record_show() : line 94] - finishing record, return code 1 

    can you send me the log section from /var/log/airtime/pypo/py-interpreter.log

    that matches this time? It should have the ecasound output.
  • Vote Up0Vote Down NaomiNaomi
    Posts: 228Member
    just realized there's no times in the py-interpreter.log file so just send everything that's in there...
  • Vote Up0Vote Down James DunnJames Dunn
    Posts: 226Member
    Unfortunately the py-intepreter.log doesn't go back that far... this is the entire log which relates to the show which is currently recording:

    $ sudo cat /var/log/airtime/pypo/py-interpreter.log
    **************************************************************************
    *        ecasound v2.7.0 (C) 1997-2009 Kai Vehmanen and others   
    **************************************************************************
    (eca-chainsetup-parser) Set processing time to 7200.00.
    (eca-chainsetup) Chainsetup "untitled-chainsetup"
    (eca-chainsetup) NOTE: Real-time configuration, but insufficient privileges
    ... to utilize real-time scheduling (SCHED_FIFO). With small buffersizes,
    ... this may cause audible glitches during processing.
    (eca-chainsetup) "rt" buffering mode selected.
    (audioio_alsa) Warning! Period-size differs from current client buffersize.
    (eca-chainsetup) Opened input "alsa", mode "read". Format: s16_le, channels
    ... 2, srate 44100, interleaved.
    (eca-chainsetup) NOTE: using existing audio parameters -f:s16_be,2,44100
    ... for object '/var/tmp/airtime/show-recorder/2012-05-11-14:00:00.mp3
    ... (tried to open with -f:s16_le,2,44100).
    (eca-chainsetup) Opened output
    ... "/var/tmp/airtime/show-recorder/2012-05-11-14:00:00.mp3", mode "write".
    ... Format: s16_be, channels 2, srate 44100, interleaved (locked params).
    - [ Connected chainsetup: "untitled-chainsetup" ] ------------------------
    - [ Controller/Starting batch processing ] -------------------------------
    - [ Engine - Driver start ] ----------------------------------------------
    (audioio-mp3) Starting to encode
    ... /var/tmp/airtime/show-recorder/2012-05-11-14:00:00.mp3 with lame.
  • Vote Up0Vote Down NaomiNaomi
    Posts: 228Member
    ok, this can only really tell us anything when it finishes recording and the output returns a 1 like above. I've tested both ogg/mp3 recordings using 2.0.3 on my machine and didn't have a problem.

    Another question which might affect something, do you have back to back records? or right after the recorded show a scheduled show?
  • Vote Up0Vote Down James DunnJames Dunn
    Posts: 226Member
    Ok so I'll check the py-interpreter.log immediately the next time this happens.

    We had a 2 hour show scheduled to be recorded at 10:00 which had the error. Then a 2 hour pre-recorded show and now the current 2 hour show which is recording (see attached screenshot)

    Screen shot 2012-05-11 at 14.50.15.png
    168 x 263 - 31K
    Post edited by James Dunn at 2012-05-11 10:11:28
  • Vote Up0Vote Down NaomiNaomi
    Posts: 228Member
    cool thanks for the screenshot

    Another question in /etc/airtime/liquidsoap.cfg

    what do you have for these values?

    output_sound_device
    output_sound_device_type
  • Vote Up0Vote Down NaomiNaomi
    Posts: 228Member
    and from your first post, can you send a snapshot of your schedule on May 1 around this log message

    2012-05-01 20:00:00,010 INFO - [recorder.py : record_show() : line 94] - finishing record, return code 1

    what timezone is your system in?
  • Vote Up0Vote Down James DunnJames Dunn
    Posts: 226Member
    /etc/airtime/liquidsoap.cfg:

    output_sound_device = true
    output_sound_device_type = "ALSA"
  • Vote Up0Vote Down NaomiNaomi
    Posts: 228Member
    cool, ok I was thinking you might have this set to true, I'll try more testing with this. 

    It might be best, could you send me a screen shot of the month views including the 5 failed shows and tell me which ones they were? If you still have the schedule in you calendar..

    thanks! :D
  • Vote Up0Vote Down James DunnJames Dunn
    Posts: 226Member
    Ok I've just got another weird error which I mentioned in an earlier post. I logged in to check ecasound was running and it wasn't! Then I checked show-recorder.log:

    2012-05-11 15:59:55,786 DEBUG - [recorder.py : get_time_till_next_show() : line 221] - Shows {u'2012-05-11 15:00:00': [datetime.timedelta(0, 3600), u'8260', u'Arcade w/ Federico', u'Europe/London']}
    2012-05-11 15:59:55,787 DEBUG - [recorder.py : get_time_till_next_show() : line 222] - Next show 2012-05-11 15:00:00
    2012-05-11 15:59:55,787 DEBUG - [recorder.py : get_time_till_next_show() : line 223] - Now 2012-05-11 14:59:55.786640
    2012-05-11 15:59:55,787 DEBUG - [recorder.py : start_record() : line 231] - sleeping 4 seconds until show
    2012-05-11 15:59:59,795 INFO - [recorder.py : record_show() : line 85] - starting record
    2012-05-11 15:59:59,796 INFO - [recorder.py : record_show() : line 86] - command ecasound -f:16,2,44100 -i alsa -o /var/tmp/airtime/show-recorder/2012-05-11-16:00:00.mp3,192000 -t:3600.0
    2012-05-11 16:00:06,151 INFO - [recorder.py : record_show() : line 94] - finishing record, return code 0
    2012-05-11 16:00:06,153 INFO - [recorder.py : run() : line 156] - Preparing to upload /var/tmp/airtime/show-recorder/2012-05-11-14:00:00.mp3
    2012-05-11 16:00:06,153 INFO - [recorder.py : set_metadata_and_save() : line 135] - time: 14-00-00
    2012-05-11 16:00:06,714 DEBUG - [api_client.py : upload_recorded_show() : line 375] - http://localhost:80/api/upload-file/format/json/api_key/%%api_key%%
    2012-05-11 16:00:06,714 DEBUG - [api_client.py : upload_recorded_show() : line 379] - Upload attempt: 1
    2012-05-11 16:00:20,896 INFO - [api_client.py : upload_recorded_show() : line 385] - uploaded show result []
    2012-05-11 16:13:20,654 DEBUG - [api_client.py : get_shows_to_record() : line 353] - http://localhost:80/api/recorded-shows/format/json/api_key/%%api_key%%
    2012-05-11 16:13:20,905 INFO - [api_client.py : get_shows_to_record() : line 358] - shows {u'is_recording': False, u'server_timezone': u'Europe/London', u'shows': [{u'time_filled': None, u'ends': u'2012-05-11 18:00:00', u'name': u'Devil Voodoo', u'color': u'', u'starts': u'2012-05-11 17:00:00', u'show_id': u'547', u'instance_id': u'4827', u'record': u'1', u'rebroadcast': u'0', u'file_id': None, u'background_color': u'43375c'}]}
    2012-05-11 16:13:20,905 INFO - [recorder.py : process_recorder_schedule() : line 198] - Parsing recording show schedules...
    2012-05-11 16:13:20,906 INFO - [recorder.py : run() : line 295] - updated recorder schedule received: {u'is_recording': False, u'server_timezone': u'Europe/London', u'shows': [{u'time_filled': None, u'ends': u'2012-05-11 18:00:00', u'name': u'Devil Voodoo', u'color': u'', u'starts': u'2012-05-11 17:00:00', u'show_id': u'547', u'instance_id': u'4827', u'record': u'1', u'rebroadcast': u'0', u'file_id': None, u'background_color': u'43375c'}]}
    2012-05-11 16:37:10,514 INFO - [recorder.py : handle_message() : line 186] - Received msg from Pypo Message Handler: {u'server_timezone': u'Europe/London', u'event_type': u'cancel_recording', u'shows': [{u'time_filled': None, u'ends': u'2012-05-11 18:00:00', u'name': u'Devil Voodoo', u'color': u'', u'starts': u'2012-05-11 17:00:00', u'show_id': u'547', u'instance_id': u'4827', u'record': u'1', u'rebroadcast': u'0', u'file_id': None, u'background_color': u'43375c'}]}
    2012-05-11 16:37:10,514 INFO - [recorder.py : cancel_recording() : line 109] - Show manually cancelled!
    2012-05-11 16:37:10,768 INFO - [recorder.py : record_show() : line 94] - finishing record, return code 0
    2012-05-11 16:37:10,769 INFO - [recorder.py : run() : line 156] - Preparing to upload /var/tmp/airtime/show-recorder/2012-05-11-16:00:00.mp3
    2012-05-11 16:37:10,769 INFO - [recorder.py : set_metadata_and_save() : line 135] - time: 16-00-00
    2012-05-11 16:37:10,940 DEBUG - [api_client.py : upload_recorded_show() : line 375] - http://localhost:80/api/upload-file/format/json/api_key/%%api_key%%
    2012-05-11 16:37:10,941 DEBUG - [api_client.py : upload_recorded_show() : line 379] - Upload attempt: 1

    Apparently the show was manually cancelled. If so, the calendar view should be empty. It's not (see the attached screenshot).

    Here's the entire contents of py-interpreter.log:

    **************************************************************************
    *        ecasound v2.7.0 (C) 1997-2009 Kai Vehmanen and others   
    **************************************************************************
    (eca-chainsetup-parser) Set processing time to 7200.00.
    (eca-chainsetup) Chainsetup "untitled-chainsetup"
    (eca-chainsetup) NOTE: Real-time configuration, but insufficient privileges
    ... to utilize real-time scheduling (SCHED_FIFO). With small buffersizes,
    ... this may cause audible glitches during processing.
    (eca-chainsetup) "rt" buffering mode selected.
    (audioio_alsa) Warning! Period-size differs from current client buffersize.
    (eca-chainsetup) Opened input "alsa", mode "read". Format: s16_le, channels
    ... 2, srate 44100, interleaved.
    (eca-chainsetup) NOTE: using existing audio parameters -f:s16_be,2,44100
    ... for object '/var/tmp/airtime/show-recorder/2012-05-11-14:00:00.mp3
    ... (tried to open with -f:s16_le,2,44100).
    (eca-chainsetup) Opened output
    ... "/var/tmp/airtime/show-recorder/2012-05-11-14:00:00.mp3", mode "write".
    ... Format: s16_be, channels 2, srate 44100, interleaved (locked params).
    - [ Connected chainsetup: "untitled-chainsetup" ] ------------------------
    - [ Controller/Starting batch processing ] -------------------------------
    - [ Engine - Driver start ] ----------------------------------------------
    (audioio-mp3) Starting to encode
    ... /var/tmp/airtime/show-recorder/2012-05-11-14:00:00.mp3 with lame.
    **************************************************************************
    *        ecasound v2.7.0 (C) 1997-2009 Kai Vehmanen and others   
    **************************************************************************
    (eca-chainsetup-parser) Set processing time to 3600.00.
    (eca-chainsetup) Chainsetup "untitled-chainsetup"
    (eca-chainsetup) NOTE: Real-time configuration, but insufficient privileges
    ... to utilize real-time scheduling (SCHED_FIFO). With small buffersizes,
    ... this may cause audible glitches during processing.
    (eca-chainsetup) "rt" buffering mode selected.
    (audioio_alsa) Warning! Period-size differs from current client buffersize.
    (eca-chainsetup) Opened input "alsa", mode "read". Format: s16_le, channels
    ... 2, srate 44100, interleaved.
    (eca-chainsetup) NOTE: using existing audio parameters -f:s16_be,2,44100
    ... for object '/var/tmp/airtime/show-recorder/2012-05-11-16:00:00.mp3
    ... (tried to open with -f:s16_le,2,44100).
    (eca-chainsetup) Opened output
    ... "/var/tmp/airtime/show-recorder/2012-05-11-16:00:00.mp3", mode "write".
    ... Format: s16_be, channels 2, srate 44100, interleaved (locked params).
    - [ Connected chainsetup: "untitled-chainsetup" ] ------------------------
    - [ Controller/Starting batch processing ] -------------------------------
    - [ Engine - Driver start ] ----------------------------------------------
    (audioio-mp3) Starting to encode
    ... /var/tmp/airtime/show-recorder/2012-05-11-16:00:00.mp3 with lame.

    - [ Engine - Processing finished ] ---------------------------------------
    - [ Controller/Batch processing finished (0) ] ---------------------------
    - [ Engine exiting ] -----------------------------------------------------
    (eca-control-objects) Disconnecting chainsetup:  "untitled-chainsetup".
    - [ Controller/Batch processing finished (0) ] ---------------------------
    - [ Engine exiting ] -----------------------------------------------------
    (eca-control-objects) Disconnecting chainsetup:  "untitled-chainsetup".

    Screen shot 2012-05-11 at 16.54.57.png
    1029 x 485 - 133K
  • Vote Up0Vote Down James DunnJames Dunn
    Posts: 226Member
    I don't have a screenshot of the 5 missing shows unfortunately.
  • Vote Up0Vote Down NaomiNaomi
    Posts: 228Member
    np about the 5 shows, this log is very useful, I think I know how I can recreate this now.
  • Vote Up0Vote Down James DunnJames Dunn
    Posts: 226Member
    Naomi said:

    what timezone is your system in?


    Europe/London (BST)

    I've noticed from the logs that the timestamps are diffferent, ie Open Deck Sessions runs from 14:00 to 16:00 not as follows:

    2012-05-11 13:12:54,790 INFO - [recorder.py : run() : line 295] - updated recorder schedule received: {u'is_recording': True, u'server_timezone': u'Europe/London', u'shows': [{u'time_filled': None, u'ends': u'2012-05-11 15:00:00', u'name': u'Open Deck Session', u'color': u'', u'starts': u'2012-05-11 13:00:00', u'show_id': u'251', u'instance_id': u'4861', u'record': u'1', u'rebroadcast': u'0', u'file_id': None, u'background_color': u''}]}

  • Vote Up0Vote Down NaomiNaomi
    Posts: 228Member
    yeah, the times are sent using UTC time, wanted to know your timezone so I can calculate the offsets.
  • Vote Up0Vote Down NaomiNaomi
    Posts: 228Member
    Hey I'm pretty sure I've fixed this in the latest devel branch for the 2.1 release, I'm just testing a bunch of back to back recorded shows now.

    Are you using this 2.0.3 version in production right now or just testing? It's just a small change to 1 python file that needs to be made to recorder.py

    You could make these changes in your 2.0.3 files and then do a reinstall keeping your database/config files intact and this problem shouldn't recur again. 
  • Vote Up0Vote Down NaomiNaomi
    Posts: 228Member
    This is what you need to change in recorder.py

    (airtime/python_apps/pypo/recorder.py)

    this line: (should be line #218)

    out = delta.seconds

    replace with:

    s = '%s.%s' % (delta.seconds, delta.microseconds)
    out = float(s)


  • Vote Up0Vote Down James DunnJames Dunn
    Posts: 226Member
    This is great news! 2.0.3 is our production machine as everything is configured to run from this machine. I have managed to get 1.8.2 up and running on another machine in the meantime as a backup so our shows are still getting recorded, but it doesn't have our audio archive. I'll try this out now.

    Is this a fix for both the manually cancelled show and the ecasound error or are they the same bug?

    thanks

    James
  • Vote Up0Vote Down NaomiNaomi
    Posts: 228Member
    the ecasound and manually cancelled show message are the same bug.

    cool. Let me know how everything goes! Hopefully you don't run into any other issues with 2.0.3
  • Vote Up0Vote Down James DunnJames Dunn
    Posts: 226Member
    yeah I hope so too, we've been trying to upgrade from 1.8.2 since August last year!



    thanks for all your help though, feels like we're nearly there  \:D/
  • Vote Up0Vote Down James DunnJames Dunn
    Posts: 226Member
    Or maybe not.. 2 shows have not recorded this morning:

    show-recorder.log:

    2012-05-13 09:59:56,222 DEBUG - [recorder.py : get_time_till_next_show() : line 224] - Next show 2012-05-13 09:00:00
    2012-05-13 09:59:56,222 DEBUG - [recorder.py : get_time_till_next_show() : line 225] - Now 2012-05-13 08:59:56.221917
    2012-05-13 09:59:56,223 DEBUG - [recorder.py : start_record() : line 233] - sleeping 3.778083 seconds until show
    2012-05-13 10:00:00,027 INFO - [recorder.py : record_show() : line 85] - starting record
    2012-05-13 10:00:00,028 INFO - [recorder.py : record_show() : line 86] - command ecasound -f:16,2,44100 -i alsa -o /var/tmp/airtime/show-recorder/2012-05-13-10:00:00.mp3,192000 -t:3600.0
    2012-05-13 10:00:00,142 INFO - [recorder.py : record_show() : line 94] - finishing record, return code 1
    2012-05-13 10:00:00,143 INFO - [recorder.py : run() : line 165] - problem recording show
    2012-05-13 10:00:26,054 DEBUG - [api_client.py : get_shows_to_record() : line 353] - http://localhost:80/api/recorded-shows/format/json/api_key/%%api_key%%
    2012-05-13 10:00:26,289 INFO - [api_client.py : get_shows_to_record() : line 358] - shows {u'is_recording': True, u'server_timezone': u'Europe/London', u'shows': [{u'time_filled': None, u'ends': u'2012-05-13 12:00:00', u'name': u"Mule Freedom's Sunday Pint", u'color': u'f0d8f0', u'starts': u'2012-05-13 10:00:00', u'show_id': u'64', u'instance_id': u'4608', u'record': u'1', u'rebroadcast': u'0', u'file_id': None, u'background_color': u'1f191f'}]}
    2012-05-13 10:00:26,289 INFO - [recorder.py : process_recorder_schedule() : line 198] - Parsing recording show schedules...
    2012-05-13 10:00:26,290 INFO - [recorder.py : run() : line 297] - updated recorder schedule received: {u'is_recording': True, u'server_timezone': u'Europe/London', u'shows': [{u'time_filled': None, u'ends': u'2012-05-13 12:00:00', u'name': u"Mule Freedom's Sunday Pint", u'color': u'f0d8f0', u'starts': u'2012-05-13 10:00:00', u'show_id': u'64', u'instance_id': u'4608', u'record': u'1', u'rebroadcast': u'0', u'file_id': None, u'background_color': u'1f191f'}]}
    2012-05-13 10:59:55,996 DEBUG - [recorder.py : get_time_till_next_show() : line 223] - Shows {u'2012-05-13 10:00:00': [datetime.timedelta(0, 7200), u'4608', u"Mule Freedom's Sunday Pint", u'Europe/London']}
    2012-05-13 10:59:55,996 DEBUG - [recorder.py : get_time_till_next_show() : line 224] - Next show 2012-05-13 10:00:00
    2012-05-13 10:59:55,997 DEBUG - [recorder.py : get_time_till_next_show() : line 225] - Now 2012-05-13 09:59:55.996337
    2012-05-13 10:59:55,997 DEBUG - [recorder.py : start_record() : line 233] - sleeping 4.3663 seconds until show
    2012-05-13 11:00:00,371 INFO - [recorder.py : record_show() : line 85] - starting record
    2012-05-13 11:00:00,371 INFO - [recorder.py : record_show() : line 86] - command ecasound -f:16,2,44100 -i alsa -o /var/tmp/airtime/show-recorder/2012-05-13-11:00:00.mp3,192000 -t:7200.0
    2012-05-13 11:00:00,382 INFO - [recorder.py : record_show() : line 94] - finishing record, return code 1
    2012-05-13 11:00:00,383 INFO - [recorder.py : run() : line 165] - problem recording show

    py-interpreter.log:

    'unknown': unknown terminal type.
    Exception in thread Thread-5:
    Traceback (most recent call last):
      File "/usr/lib/python2.6/threading.py", line 532, in __bootstrap_inner
        self.run()
      File "/usr/lib/airtime/pypo/bin/recorder.py", line 166, in run
        os.remove(filepath)
    OSError: [Errno 2] No such file or directory: '/var/tmp/airtime/show-recorder/2012-05-13-10:00:00.mp3'

    'unknown': unknown terminal type.
    Exception in thread Thread-6:
    Traceback (most recent call last):
      File "/usr/lib/python2.6/threading.py", line 532, in __bootstrap_inner
        self.run()
      File "/usr/lib/airtime/pypo/bin/recorder.py", line 166, in run
        os.remove(filepath)
    OSError: [Errno 2] No such file or directory: '/var/tmp/airtime/show-recorder/2012-05-13-11:00:00.mp3'
  • Vote Up0Vote Down James DunnJames Dunn
    Posts: 226Member
    here's a screenshot of the schedule
    Screen shot 2012-05-13 at 11.05.13.png
    166 x 272 - 31K
  • Vote Up0Vote Down NaomiNaomi
    Posts: 228Member
    That's annoying.... ok this looks like a different error, thanks for the logs I'll try and find out what is causing this new error...
  • Vote Up0Vote Down NaomiNaomi
    Posts: 228Member
    if you run this command in a terminal on your machine what is the result?

    echo $TERM
  • Vote Up0Vote Down James DunnJames Dunn
    Posts: 226Member
    xterm-color
  • Vote Up0Vote Down NaomiNaomi
    Posts: 228Member
    ok I think you will have to follow the bottom part of this the -color at the end is causing the problem


    you can run this command to have the generic xterm saved

    echo 'export TERM=xterm' >> ~/.bash_profile

    you should probably restart the playout etc to make sure it notices the new environment variable.
  • Vote Up0Vote Down James DunnJames Dunn
    Posts: 226Member
    Ok I've done that, then rebooted the system as the current show was not recording. Thanks again for your help, hopefully this is the last problem!
  • Vote Up0Vote Down NaomiNaomi
    Posts: 228Member
    Is Airtime working ok for you now? Things are recording?
  • Vote Up0Vote Down James DunnJames Dunn
    Posts: 226Member
    Well the last 2 shows have recorded so that's good, but between fixing the last bug in recorder.py on Friday and the x-term issue this morning Airtime recorded all shows up until Sunday morning when it missed suddenly missed 2. I think we'll know for sure in a week if it records all the shows! But things are looking good :)

    Thanks for you help again

    James
  • Vote Up0Vote Down James DunnJames Dunn
    Posts: 226Member
    Also, not sure if this is exactly the right place to post this but here's a couple of thoughts relating to shows being recorded / soundclouded:

    1) Would it not make sense to have the 'Recording: Some Show' display in the browser actually reflect whether ecasound is running or not? I don't know how, but maybe returning the PID of the process and if it exits prematurely then that could be reflected in the browser?

    2) When Airtime is set to automatically Soundcloud recorded shows, it would be great to also reflect this in the browser by having the 'running circle' displayed rather than silently uploading in the background. This might prevent users from aggressively attempting to upload a show which appears to not be already uploaded/uploading when it is in fact already in progress. Only when maximum attempts have been made would it then revert to a standard icon (or Soundcloud icon if successful). Or even prevent users from uploading the show if there's another attempt in process?

    Just some thoughts!
  • Vote Up0Vote Down Martin KonecnyMartin Konecny
    Posts: 1,860Member
    Hi James,

    Thanks for the suggestions. I believe that recording is one of Airtime's weaker features at the moment and definitely needs some work. We hope to find some time to fix these issues in 2.2 or 2.3, as we've already had several discussions about it internally.


    Airtime Pro Hosting: http://airtime.pro
  • Vote Up0Vote Down James DunnJames Dunn
    Posts: 226Member
    ah, the 'Show manually cancelled' error is back... :(

    show-recorder.log:

    2012-05-14 17:59:56,233 DEBUG - [recorder.py : get_time_till_next_show() : line 223] - Shows {u'2012-05-14 17:00:00': [datetime.timedelta(0, 7200), u'4624', u'Totem', u'Europe/London']}
    2012-05-14 17:59:56,233 DEBUG - [recorder.py : get_time_till_next_show() : line 224] - Next show 2012-05-14 17:00:00
    2012-05-14 17:59:56,234 DEBUG - [recorder.py : get_time_till_next_show() : line 225] - Now 2012-05-14 16:59:56.233199
    2012-05-14 17:59:56,234 DEBUG - [recorder.py : start_record() : line 233] - sleeping 3.766801 seconds until show
    2012-05-14 18:00:00,010 INFO - [recorder.py : record_show() : line 85] - starting record
    2012-05-14 18:00:00,010 INFO - [recorder.py : record_show() : line 86] - command ecasound -f:16,2,44100 -i alsa -o /var/tmp/airtime/show-recorder/2012-05-14-18:00:00.mp3,192000 -t:7200.0
    2012-05-14 18:00:04,437 INFO - [recorder.py : record_show() : line 94] - finishing record, return code 0
    2012-05-14 18:00:04,437 INFO - [recorder.py : run() : line 156] - Preparing to upload /var/tmp/airtime/show-recorder/2012-05-14-17:00:00.mp3
    2012-05-14 18:00:04,438 INFO - [recorder.py : set_metadata_and_save() : line 135] - time: 17-00-00
    2012-05-14 18:00:04,643 DEBUG - [api_client.py : upload_recorded_show() : line 375] - http://localhost:80/api/upload-file/format/json/api_key/%%api_key%%
    2012-05-14 18:00:04,644 DEBUG - [api_client.py : upload_recorded_show() : line 379] - Upload attempt: 1
    2012-05-14 18:00:11,619 INFO - [api_client.py : upload_recorded_show() : line 385] - uploaded show result []
    2012-05-14 18:30:39,823 INFO - [recorder.py : handle_message() : line 186] - Received msg from Pypo Message Handler: {u'server_timezone': u'Europe/London', u'event_type': u'cancel_recording', u'shows': []}
    2012-05-14 18:30:39,823 INFO - [recorder.py : cancel_recording() : line 109] - Show manually cancelled!
    2012-05-14 18:30:40,072 INFO - [recorder.py : record_show() : line 94] - finishing record, return code 0
    2012-05-14 18:30:40,072 INFO - [recorder.py : run() : line 156] - Preparing to upload /var/tmp/airtime/show-recorder/2012-05-14-18:00:00.mp3
    2012-05-14 18:30:40,073 INFO - [recorder.py : set_metadata_and_save() : line 135] - time: 18-00-00
    2012-05-14 18:30:40,237 DEBUG - [api_client.py : upload_recorded_show() : line 375] - http://localhost:80/api/upload-file/format/json/api_key/%%api_key%%
    2012-05-14 18:30:40,237 DEBUG - [api_client.py : upload_recorded_show() : line 379] - Upload attempt: 1
    2012-05-14 18:30:41,825 INFO - [recorder.py : handle_message() : line 186] - Received msg from Pypo Message Handler: {u'server_timezone': u'Europe/London', u'event_type': u'update_recorder_schedule', u'shows': []}

    py-interpreter.log; (just the section relating to the 1800 show)

    **************************************************************************
    *        ecasound v2.7.0 (C) 1997-2009 Kai Vehmanen and others   
    **************************************************************************
    (eca-chainsetup-parser) Set processing time to 7200.00.
    (eca-chainsetup) Chainsetup "untitled-chainsetup"
    (eca-chainsetup) NOTE: Real-time configuration, but insufficient privileges
    ... to utilize real-time scheduling (SCHED_FIFO). With small buffersizes,
    ... this may cause audible glitches during processing.
    (eca-chainsetup) "rt" buffering mode selected.
    (audioio_alsa) Warning! Period-size differs from current client buffersize.
    (eca-chainsetup) Opened input "alsa", mode "read". Format: s16_le, channels
    ... 2, srate 44100, interleaved.
    (eca-chainsetup) NOTE: using existing audio parameters -f:s16_be,2,44100
    ... for object '/var/tmp/airtime/show-recorder/2012-05-14-18:00:00.mp3
    ... (tried to open with -f:s16_le,2,44100).
    (eca-chainsetup) Opened output
    ... "/var/tmp/airtime/show-recorder/2012-05-14-18:00:00.mp3", mode "write".
    ... Format: s16_be, channels 2, srate 44100, interleaved (locked params).
    - [ Connected chainsetup: "untitled-chainsetup" ] ------------------------
    - [ Controller/Starting batch processing ] -------------------------------
    - [ Engine - Driver start ] ----------------------------------------------
    (audioio-mp3) Starting to encode
    ... /var/tmp/airtime/show-recorder/2012-05-14-18:00:00.mp3 with lame.

    - [ Engine - Processing finished ] ---------------------------------------
    - [ Controller/Batch processing finished (0) ] ---------------------------
    - [ Engine exiting ] -----------------------------------------------------
    (eca-control-objects) Disconnecting chainsetup:  "untitled-chainsetup".
    - [ Controller/Batch processing finished (0) ] ---------------------------
    - [ Engine exiting ] -----------------------------------------------------
    (eca-control-objects) Disconnecting chainsetup:  "untitled-chainsetup".
    Screen shot 2012-05-15 at 00.46.10.png
    169 x 272 - 28K
  • Vote Up0Vote Down NaomiNaomi
    Posts: 228Member
    Hey were you doing anything on the calendar during this time?

    Received msg from Pypo Message Handler: {u'server_timezone': u'Europe/London', u'event_type': u'cancel_recording', u'shows': []} 

    This message shows there was a cancel request sent to the program. Maybe somehow this is being incorrectly sent. I'll try and search for incorrect sending of this message in a bit.

    It doesn't even have to be sent just from the calendar, did you change any preferences?
    Post edited by Naomi at 2012-05-15 05:30:13
  • Vote Up0Vote Down James DunnJames Dunn
    Posts: 226Member
    Personally no, but this is our production machine so I will check with the other users now.
  • Vote Up0Vote Down NaomiNaomi
    Posts: 228Member
    OK.... wow I know what the problem is for this for bug. That's embarassing. Not really sure how this made it into a released version.  I will fix this in 2.1 (I'll see if it's still an issue there) and then either way I will post how you can fix this. But for now to avoid this if something is recording don't delete any recorded show... even if it's in the future.
    Post edited by Naomi at 2012-05-15 06:33:20
  • Vote Up0Vote Down NaomiNaomi
    Posts: 228Member
    This is an issue in 2.1

    I'll ask about maybe releasing 2.0.4 to address these recording problems
    Post edited by Naomi at 2012-05-15 06:54:29
  • Vote Up0Vote Down NaomiNaomi
    Posts: 228Member
    ok here is the fix for the show cancelled bug

    airtime/airtime_mvc/application/models/ShowInstance.php
    line #575

    replace this

    if($recording){
                Application_Model_RabbitMq::SendMessageToShowRecorder("cancel_recording");
            }


    WITH:


    if($recording){
                
                $starts = intval($this->getShowInstanceStart('U'));
                $ends = intval($this->getShowInstanceEnd('U'));
                $now = time();
                
                if ($starts <= $now && $ends >= $now) {
                    Application_Model_RabbitMq::SendMessageToShowRecorder("cancel_recording");
                }   
            }


    you can either do it in the downloaded files and then reinstall or you can so it directly in the file which apache is looking at right now (what's setup in /etc/apache2/sites-enabled for airtime)
  • Vote Up0Vote Down James DunnJames Dunn
    Posts: 226Member
    Thanks Naomi.

    I edited /usr/share/airtime/application/models/ShowInstance.php - is this correct?

    Do I need to restart any services like apache?

    James
  • Vote Up0Vote Down NaomiNaomi
    Posts: 228Member
    no you don't need to restart, the changes will be noticed.

    and yes it is correct :D
    Post edited by Naomi at 2012-05-15 11:38:35
  • Vote Up0Vote Down James DunnJames Dunn
    Posts: 226Member
    Checking in this morning I found I still have the 'problem recording show' ecasound bug:

    show-recorder.log:

    2012-05-16 08:59:55,565 DEBUG - [recorder.py : get_time_till_next_show() : line 223] - Shows {u'2012-05-16 08:00:00': [datetime.timedelta(0, 10800), u'4922', u'DO YOU BREAKFAST??!!', u'Europe/London']}
    2012-05-16 08:59:55,566 DEBUG - [recorder.py : get_time_till_next_show() : line 224] - Next show 2012-05-16 08:00:00
    2012-05-16 08:59:55,566 DEBUG - [recorder.py : get_time_till_next_show() : line 225] - Now 2012-05-16 07:59:55.565680
    2012-05-16 08:59:55,567 DEBUG - [recorder.py : start_record() : line 233] - sleeping 4.43432 seconds until show
    2012-05-16 09:00:00,028 INFO - [recorder.py : record_show() : line 85] - starting record
    2012-05-16 09:00:00,028 INFO - [recorder.py : record_show() : line 86] - command ecasound -f:16,2,44100 -i alsa -o /var/tmp/airtime/show-recorder/2012-05-16-09:00:00.mp3,192000 -t:10800.0
    2012-05-16 09:00:00,121 INFO - [recorder.py : record_show() : line 94] - finishing record, return code 1
    2012-05-16 09:00:00,122 INFO - [recorder.py : run() : line 165] - problem recording show

    $ sudo cat /var//log/airtime/pypo/py-interpreter.log

    'unknown': unknown terminal type.
    Exception in thread Thread-5:
    Traceback (most recent call last):
      File "/usr/lib/python2.6/threading.py", line 532, in __bootstrap_inner
        self.run()
      File "/usr/lib/airtime/pypo/bin/recorder.py", line 166, in run
        os.remove(filepath)
    OSError: [Errno 2] No such file or directory: '/var/tmp/airtime/show-recorder/2012-05-16-09:00:00.mp3'

    $ echo $TERM
    xterm
Add a Comment