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.
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
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.
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
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.
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:
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?
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.
(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.
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
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?
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?
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)
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..
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.
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.
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?
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'
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 :)
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?
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.
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?
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.
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)
'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'