2.0.3 not recording shows - Airtime Support Discussions on Sourcefabric Forum

Naomi

hmmmmmmmm

ok I'm not really sure what to look into first for this. What kind of system do you have airtime installed on?

can you run this and post the results?

sudo airtime-check-system

James Dunn

It's Ubuntu 10.04 LTS 64-bit

$ sudo airtime-check-system
AIRTIME_STATUS_URL             = http://localhost/api/status/format/json/api_key/%%api_key%%
AIRTIME_SERVER_RESPONDING      = OK
KERNEL_VERSION                 = 2.6.32-41-server
MACHINE_ARCHITECTURE           = x86_64
TOTAL_MEMORY_MBYTES            = 2048896
TOTAL_SWAP_MBYTES              = UNKNOWN
AIRTIME_VERSION                = 2.0.3
OS                             = Ubuntu 10.04.4 LTS x86_64
CPU                            = Intel(R) Pentium(R) 4 CPU 3.20GHz
WEB_SERVER                     = Apache/2.2.14 (Ubuntu)
PLAYOUT_ENGINE_PROCESS_ID      = 30578
PLAYOUT_ENGINE_RUNNING_SECONDS = 14002
PLAYOUT_ENGINE_MEM_PERC        = 0.6%
PLAYOUT_ENGINE_CPU_PERC        = 0.0%
LIQUIDSOAP_PROCESS_ID          = 30583
LIQUIDSOAP_RUNNING_SECONDS     = 14002
LIQUIDSOAP_MEM_PERC            = 1.7%
LIQUIDSOAP_CPU_PERC            = 21.4%
MEDIA_MONITOR_PROCESS_ID       = 908
MEDIA_MONITOR_RUNNING_SECONDS = 88995
MEDIA_MONITOR_MEM_PERC         = 0.7%
MEDIA_MONITOR_CPU_PERC         = 0.4%
RABBITMQ_PROCESS_ID            = 1067
RABBITMQ_RUNNING_SECONDS       = 88992
RABBITMQ_MEM_PERC              = 0.9%
RABBITMQ_CPU_PERC              = 0.0%

James Dunn

So we're still getting these errors. I searched around and a couple of places recommend installing ncurses-term. So I did,

sudo apt-get install ncurses-term

now I get a different error:

$ sudo cat /var/log/airtime/pypo/py-interpreter.log
'unknown': I need something more specific.
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-19-10:00:00.mp3'

Marcin Tym

Hi.
We've got a similar problem (but recording oggs). Firstly our shows were recorded randomly. Now it's worsened and none of the shows are being recorded. As it occurs, it's not just a single case of James.

ecasound runs smooth:
root@ra01:/var/tmp/airtime/show-recorder# ecasound -f:16,2,44100 -i alsa -o /var/tmp/airtime/show-recorder/2012-05-19-19:00:00.ogg,256000 -t:5.0
**************************************************************************
* 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.
(eca-chainsetup) Opened input "alsa", mode "read". Format: s16_le, channels 2, srate 44100, interleaved.
(eca-chainsetup) Opened output "/var/tmp/airtime/show-recorder/2012-05-19-19:00:00.ogg", mode "write". Format: s16_le, channels 2, srate 44100, interleaved (locked params).
- [ Connected chainsetup: "untitled-chainsetup" ] ------------------------
- [ Controller/Starting batch processing ] -------------------------------
- [ Engine - Driver start ] ----------------------------------------------
(audioio-ogg) Starting to encode /var/tmp/airtime/show-recorder/2012-05-19-19:00:00.ogg with vorbize.
(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".

But in a log something's wrong:
2012-05-19 18:59:33,295 INFO - [recorder.py : run() : line 285] - heartbeat
2012-05-19 18:59:55,319 DEBUG - [recorder.py : get_time_till_next_show() : line 221] - Shows {u'2012-05-19 17:00:00': [datetime.timedelta(0, 3600), u'800', u'More Fyah!', u'Europe/Warsaw']}
2012-05-19 18:59:55,319 DEBUG - [recorder.py : get_time_till_next_show() : line 222] - Next show 2012-05-19 17:00:00
2012-05-19 18:59:55,320 DEBUG - [recorder.py : get_time_till_next_show() : line 223] - Now 2012-05-19 16:59:55.319021
2012-05-19 18:59:55,320 DEBUG - [recorder.py : start_record() : line 231] - sleeping 4 seconds until show
2012-05-19 18:59:59,331 INFO - [recorder.py : record_show() : line 85] - starting record
2012-05-19 18:59:59,335 INFO - [recorder.py : record_show() : line 86] - command ecasound -f:16,2,44100 -i alsa -o /var/tmp/airtime/show-recorder/2012-05-19-19:00:00.ogg,256000 -t:3600.0
2012-05-19 18:59:59,379 INFO - [recorder.py : record_show() : line 94] - finishing record, return code 1
2012-05-19 18:59:59,380 INFO - [recorder.py : run() : line 165] - problem recording show
2012-05-19 19:00:07,338 INFO - [recorder.py : run() : line 285] - heartbeat

Naomi

hey when you post your logs for the show recorder I'll also need what's currently in py-interpreter.log in /var/log/airtime/pypo

i've put code on here to fix 2 of James Dunn's problems, you might be having them as well, but I'd need to see this other file to make sure. Unfortunately py-interpreter.log overwrites itself so it might not have what happened when this error was caused. I'd also need more line from this other recorder log, were you recording shows back to back? If so you'll need to do the python fix I posted earlier in this thread.

James Dunn

Unfortunately the 'problem recording show' bug is still not fixed here. It usually fails to get the first show every morning such as the current show:

/var/log/airtime/pypo/show-recorder.log:

2012-05-22 08:59:56,254 DEBUG - [recorder.py : get_time_till_next_show() : line 223] - Shows {u'2012-05-22 08:00:00': [datetime.timedelta(0, 10800), u'4589', u'NTS Mornings with MarshmeLLo', u'Europe/London']}
2012-05-22 08:59:56,254 DEBUG - [recorder.py : get_time_till_next_show() : line 224] - Next show 2012-05-22 08:00:00
2012-05-22 08:59:56,255 DEBUG - [recorder.py : get_time_till_next_show() : line 225] - Now 2012-05-22 07:59:56.254153
2012-05-22 08:59:56,255 DEBUG - [recorder.py : start_record() : line 233] - sleeping 3.745847 seconds until show
2012-05-22 09:00:00,027 INFO - [recorder.py : record_show() : line 85] - starting record
2012-05-22 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-22-09:00:00.mp3,192000 -t:10800.0
2012-05-22 09:00:00,132 INFO - [recorder.py : record_show() : line 94] - finishing record, return code 1
2012-05-22 09:00:00,132 INFO - [recorder.py : run() : line 165] - problem recording show

/var/log/airtime/pypo/py-interpreter.log:

'unknown': I need something more specific.
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-22-09:00:00.mp3'

I then reboot the PC and it picks up all the shows for the rest of the day. I installed ncurses-term which changed the error in py-interpreter.log from:

'unknown': unknown terminal type.

to:

'unknown': I need something more specific.

I've also tried changing the .bash_profile to 'export TERM=linux' but it's the same error.

James

James Dunn · Screen shot 2012-05-24 at 09.09.19.png

Ok I think I've found a workaround to at least make sure all shows get recorded. It seemed that it was always the first show of the day that didn't get recorded so a couple of days ago I scheduled a reboot with cron at 7am, and all shows since then have been recorded. Of course this is hardly a fix, but at least it's working. Here's a screenshot of our weekly schedule - would still be great to know what the problem is with this

James

Naomi

Sorry I haven't had time to look into this lately since I really don't have any idea right now of what the problem is. This screenshot of the schedule is kind of small here, but I just want to make sure that the shows scheduled at 0:00 and 1:00 recorded fine the next day? Then you'd have problems always with the 9:00 show "Do you breakfast????" so you're rebooting at 7am?

hmm I wonder if it was something to do with the show name even ending with !!!???? maybe that's doing something weird nobody checked for.

James Dunn

I've uploaded a screenshot of the current weekly schedule to here too:

http://www.4thharmonic.com/images/Screen shot 2012-05-24 at 12.07.32.png

The 00:00 and 01:00 shows recorded ok.

Typically what has been happening is all shows would record until the end of the 'day' (ie the last show would finish at 00:00 or 02:00 or whenever). Then there is no scheduled content/recording until 08:00, 09:00 or 10:00, at which point Airtime would fail to record these shows with the error 'problem recording show' / 'unknown terminal'.

I realised this pattern as I was making some changes, like installing ncurses-term, or changing the terminal to 'export TERM=linux' and rebooting every morning. After the reboot, Airtime starts recording as normal but then I noticed it would always fail to pick up the first show (and subsequent shows unless I rebooted) regardless of the changes I had made. So I concluded that I just need to reboot the PC before the first scheduled show of the 'day' (ie around 07:00). Airtime has now recorded every show since May 22nd at 12:21 when I manually rebooted the PC. This is because the cron job rebooted the PC at 07:00 on the 23rd and 24th.

Regarding the show name "DO YOU BREAKFAST??!!" it's also worth noting that Airtime failed to record "NTS Mornings with MarshmeLLo" (see my post from May 22nd above) as well as some other shows without unusual characters.

It seems as though Airtime goes to sleep when there is a gap in the schedule of around 6-9 hours and needs to be kicked out of bed in the morning!

James

Martin Konecny

Hi James,

Regarding the TERM environment variable problem, what is the output of the following:

env | grep TERM

I believe you should see something like

"TERM=xterm"

in the results. If so please update the file at /usr/lib/airtime/pypo/bin/airtime-playout and insert the following line

export TERM=xterm

near the other export statements. Let me know how it goes.

James Dunn

Hi Martin,

$ env | grep TERM
TERM=xterm

So I added export TERM=xterm after the other export commands in /usr/lib/airtime/pypo/bin/airtime-playout and disabled the system reboot via cron. We'll see how this goes then...

thanks for you help

James

James Dunn

Hi Martin,

this is working fine now thanks! All shows have been recorded since Friday.

James

Martin Konecny

Great. We are missing this export statement in 2.1.0 RC (Not sure why only you seem to need it). I won't be putting it into the final 2.1.0 since I'm unsure if any side effects will occur and we don't have time to test it.

But I'll make sure we include and test this statement for 2.1.1.

Marcin Tym · Post edited by Marcin Tym at 2012-05-28 15:55:43

Hi, Me again :)

I have both logs to show now:

Recorder LOG:

2012-05-28 17:59:34,025 INFO - [recorder.py : run() : line 285] - heartbeat
2012-05-28 17:59:56,046 DEBUG - [recorder.py : get_time_till_next_show() : line 221] - Shows {u'2012-05-28 16:00:00': [datetime.timedelta(0, 7200), u'794', u'Aktywacja Poniedzia\u0142kowa', u'Europe/Warsaw']}
2012-05-28 17:59:56,047 DEBUG - [recorder.py : get_time_till_next_show() : line 222] - Next show 2012-05-28 16:00:00
2012-05-28 17:59:56,047 DEBUG - [recorder.py : get_time_till_next_show() : line 223] - Now 2012-05-28 15:59:56.046653
2012-05-28 17:59:56,048 DEBUG - [recorder.py : start_record() : line 231] - sleeping 3 seconds until show
2012-05-28 17:59:59,054 INFO - [recorder.py : record_show() : line 85] - starting record
2012-05-28 17:59:59,054 INFO - [recorder.py : record_show() : line 86] - command ecasound -f:16,2,44100 -i alsa -o /var/tmp/airtime/show-recorder/2012-05-28-18:00:00.ogg,256000 -t:7200.0
2012-05-28 17:59:59,089 INFO - [recorder.py : record_show() : line 94] - finishing record, return code 1
2012-05-28 17:59:59,090 INFO - [recorder.py : run() : line 165] - problem recording show
2012-05-28 18:00:07,062 INFO - [recorder.py : run() : line 285] - heartbeat
...
2012-05-28 19:59:48,574 INFO - [recorder.py : run() : line 285] - heartbeat
2012-05-28 19:59:56,582 DEBUG - [recorder.py : get_time_till_next_show() : line 221] - Shows {u'2012-05-28 18:00:00': [datetime.timedelta(0, 3600), u'754', u'Zwierzenia Rockmana', u'Europe/Warsaw'], u'2012-05-28 19:00:00': [datetime.time
delta(0, 3600), u'814', u'Biuro Podr\xf3\u017cy', u'Europe/Warsaw']}
2012-05-28 19:59:56,583 DEBUG - [recorder.py : get_time_till_next_show() : line 222] - Next show 2012-05-28 18:00:00
2012-05-28 19:59:56,583 DEBUG - [recorder.py : get_time_till_next_show() : line 223] - Now 2012-05-28 17:59:56.582629
2012-05-28 19:59:56,584 DEBUG - [recorder.py : start_record() : line 231] - sleeping 3 seconds until show
2012-05-28 19:59:59,590 INFO - [recorder.py : record_show() : line 85] - starting record
2012-05-28 19:59:59,590 INFO - [recorder.py : record_show() : line 86] - command ecasound -f:16,2,44100 -i alsa -o /var/tmp/airtime/show-recorder/2012-05-28-20:00:00.ogg,256000 -t:3600.0
2012-05-28 19:59:59,602 INFO - [recorder.py : record_show() : line 94] - finishing record, return code 1
2012-05-28 19:59:59,602 INFO - [recorder.py : run() : line 165] - problem recording show
2012-05-28 20:00:21,612 INFO - [recorder.py : run() : line 285] - heartbeat

py interpreter LOG:

TERM environment variable not set.
Exception in thread Thread-35:
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-28-18:00:00.ogg'

TERM environment variable not set.
Exception in thread Thread-36:
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-28-20:00:00.ogg'
And our schedule:

As far as I see this is the problem mentioned earlier. Right? I'll try to solve it and will post if works.

One addition: I've noticed a strange time difference in a log above. Marked in red. Issue with timezone?

Marcin

Marcin Tym

James,

Why did you disabl reboot? How is it harmful for the TERM export?

Thanks,
Marcin

James Dunn · Post edited by James Dunn at 2012-05-28 15:46:43

Marcin,

I added a system reboot command via cron as a workaround until Martin suggested the fix above which works for me. This is why I then disabled the cron reboot as I no longer need it!

James

Marcin Tym

Reply to @James+Dunn:
Oh, yup. Sorry. I don't know why but I've read "enabled" instead of "disabled". My bad , sorry :)

Marcin Tym

Ok. Unfortunetly, that didn't fix my whole problem. I think there is some problem with shows being recorder back to back.

Logs from recorder:
2012-05-30 20:15:14,000 INFO - [recorder.py : run() : line 285] - heartbeat
2012-05-30 20:15:16,003 DEBUG - [api_client.py : get_shows_to_record() : line 353] - http://localhost:80/api/recorded-shows/format/json/api_key/%%api_key%%
2012-05-30 20:15:16,347 INFO - [api_client.py : get_shows_to_record() : line 358] - shows {u'is_recording': True, u'server_timezone': u'Europe/Warsaw', u'shows': [{u'time_filled': None, u'ends': u'2012-05-30 21:00:00', u'name': u'Sunday
At Devil Dirt', u'color': u'000000', u'starts': u'2012-05-30 19:30:00', u'show_id': u'57', u'instance_id': u'790', u'record': u'1', u'rebroadcast': u'0', u'file_id': None, u'background_color': u'25a4de'}]}
2012-05-30 20:15:16,357 INFO - [recorder.py : process_recorder_schedule() : line 198] - Parsing recording show schedules...
2012-05-30 20:15:16,358 INFO - [recorder.py : run() : line 295] - updated recorder schedule received: {u'is_recording': True, u'server_timezone': u'Europe/Warsaw', u'shows': [{u'time_filled': None, u'ends': u'2012-05-30 21:00:00', u'name
': u'Sunday At Devil Dirt', u'color': u'000000', u'starts': u'2012-05-30 19:30:00', u'show_id': u'57', u'instance_id': u'790', u'record': u'1', u'rebroadcast': u'0', u'file_id': None, u'background_color': u'25a4de'}]}
2012-05-30 20:15:46,388 INFO - [recorder.py : run() : line 285] - heartbeat

Logs form py-interpreter:

**************************************************************************
*        ecasound v2.7.0 (C) 1997-2009 Kai Vehmanen and others
**************************************************************************
(eca-chainsetup-parser) Set processing time to 5400.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.

- [ Engine - Processing finished ] ---------------------------------------
ERROR: Connecting chainsetup failed: "Enabling chainsetup: AUDIOIO-ALSA:
... Unable to open ALSA--device for capture; error: Device or resource busy"
Exception in thread Thread-10:
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-20:00:00.ogg'

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

Is there any way to quickly fix it?

Many thanks,
Marcin

Marcin Tym · Post edited by Marcin Tym at 2012-05-30 16:56:04

OK. And there is a second unrecorded show this day but this time it was interrupted:

2012-05-30 21:55:28,647 INFO - [recorder.py : run() : line 285] - heartbeat
2012-05-30 21:55:52,670 INFO - [recorder.py : handle_message() : line 186] - Received msg from Pypo Message Handler: {u'server_timezone': u'Europe/Warsaw', u'event_type': u'cancel_recording', u'shows': [{u'time_filled': None, u'ends': u'
2012-05-30 22:00:00', u'name': u'Nocny Autobus', u'color': u'000000', u'starts': u'2012-05-30 21:00:00', u'show_id': u'127', u'instance_id': u'925', u'record': u'1', u'rebroadcast': u'0', u'file_id': None, u'background_color': u'25a4de'}
]}
2012-05-30 21:55:52,671 INFO - [recorder.py : cancel_recording() : line 109] - Show manually cancelled!
2012-05-30 21:55:53,031 INFO - [recorder.py : record_show() : line 94] - finishing record, return code 0
2012-05-30 21:55:53,031 INFO - [recorder.py : run() : line 156] - Preparing to upload /var/tmp/airtime/show-recorder/2012-05-30-21:30:00.ogg
2012-05-30 21:55:53,032 INFO - [recorder.py : set_metadata_and_save() : line 135] - time: 21-30-00
2012-05-30 21:55:53,495 DEBUG - [api_client.py : upload_recorded_show() : line 375] - http://localhost:80/api/upload-file/format/json/api_key/%%api_key%%
2012-05-30 21:55:53,500 DEBUG - [api_client.py : upload_recorded_show() : line 379] - Upload attempt: 1
2012-05-30 21:55:54,673 INFO - [recorder.py : handle_message() : line 186] - Received msg from Pypo Message Handler: {u'server_timezone': u'Europe/Warsaw', u'event_type': u'update_recorder_schedule', u'shows': [{u'time_filled': None, u'e
nds': u'2012-05-30 22:00:00', u'name': u'Nocny Autobus', u'color': u'000000', u'starts': u'2012-05-30 21:00:00', u'show_id': u'127', u'instance_id': u'925', u'record': u'1', u'rebroadcast': u'0', u'file_id': None, u'background_color': u'
25a4de'}]}
2012-05-30 21:55:54,674 INFO - [recorder.py : process_recorder_schedule() : line 198] - Parsing recording show schedules...
2012-05-30 21:56:00,135 INFO - [api_client.py : upload_recorded_show() : line 385] - uploaded show result []
2012-05-30 21:56:24,702 INFO - [recorder.py : run() : line 285] - heartbeat
2012-05-30 21:56:26,720 INFO - [recorder.py : handle_message() : line 186] - Received msg from Pypo Message Handler: {u'server_timezone': u'Europe/Warsaw', u'event_type': u'update_recorder_schedule', u'shows': [{u'time_filled': None, u'e
nds': u'2012-05-30 22:00:00', u'name': u'Nocny Autobus', u'color': u'000000', u'starts': u'2012-05-30 21:00:00', u'show_id': u'127', u'instance_id': u'925', u'record': u'1', u'rebroadcast': u'0', u'file_id': None, u'background_color': u'
25a4de'}]}
2012-05-30 21:56:26,721 INFO - [recorder.py : process_recorder_schedule() : line 198] - Parsing recording show schedules...
2012-05-30 21:56:46,741 INFO - [recorder.py : handle_message() : line 186] - Received msg from Pypo Message Handler: {u'server_timezone': u'Europe/Warsaw', u'event_type': u'update_recorder_schedule', u'shows': [{u'time_filled': None, u'e
nds': u'2012-05-30 22:00:00', u'name': u'Nocny Autobus', u'color': u'000000', u'starts': u'2012-05-30 21:00:00', u'show_id': u'127', u'instance_id': u'925', u'record': u'1', u'rebroadcast': u'0', u'file_id': None, u'background_color': u'
25a4de'}]}
2012-05-30 21:56:46,741 INFO - [recorder.py : process_recorder_schedule() : line 198] - Parsing recording show schedules...
2012-05-30 21:56:50,748 INFO - [recorder.py : handle_message() : line 186] - Received msg from Pypo Message Handler: {u'server_timezone': u'Europe/Warsaw', u'event_type': u'update_recorder_schedule', u'shows': [{u'time_filled': None, u'ends': u'2012-05-30 22:00:00', u'name': u'Nocny Autobus', u'color': u'000000', u'starts': u'2012-05-30 21:00:00', u'show_id': u'127', u'instance_id': u'925', u'record': u'1', u'rebroadcast': u'0', u'file_id': None, u'background_color': u'25a4de'}]}
2012-05-30 21:56:50,748 INFO - [recorder.py : process_recorder_schedule() : line 198] - Parsing recording show schedules...
2012-05-30 21:57:20,780 INFO - [recorder.py : run() : line 285] - heartbeat
2012-05-30 21:57:50,809 INFO - [recorder.py : run() : line 285] - heartbeat
2012-05-30 21:58:20,838 INFO - [recorder.py : run() : line 285] - heartbeat
2012-05-30 21:58:50,867 INFO - [recorder.py : run() : line 285] - heartbeat
2012-05-30 21:59:20,898 INFO - [recorder.py : run() : line 285] - heartbeat
2012-05-30 21:59:50,925 INFO - [recorder.py : run() : line 285] - heartbeat
2012-05-30 21:59:56,932 INFO - [recorder.py : handle_message() : line 186] - Received msg from Pypo Message Handler: {u'server_timezone': u'Europe/Warsaw', u'event_type': u'cancel_recording', u'shows': [{u'time_filled': None, u'ends': u'2012-05-30 22:00:00', u'name': u'Nocny Autobus', u'color': u'000000', u'starts': u'2012-05-30 21:00:00', u'show_id': u'127', u'instance_id': u'925', u'record': u'1', u'rebroadcast': u'0', u'file_id': None, u'background_color': u'25a4de'}]}
2012-05-30 21:59:58,936 INFO - [recorder.py : handle_message() : line 186] - Received msg from Pypo Message Handler: {u'server_timezone': u'Europe/Warsaw', u'event_type': u'update_recorder_schedule', u'shows': [{u'time_filled': None, u'ends': u'2012-05-30 22:00:00', u'name': u'Nocny Autobus', u'color': u'000000', u'starts': u'2012-05-30 21:00:00', u'show_id': u'127', u'instance_id': u'925', u'record': u'1', u'rebroadcast': u'0', u'file_id': None, u'background_color': u'25a4de'}]}
2012-05-30 21:59:58,937 INFO - [recorder.py : process_recorder_schedule() : line 198] - Parsing recording show schedules...
2012-05-30 22:00:28,964 INFO - [recorder.py : run() : line 285] - heartbeat
2012-05-30 22:00:34,971 INFO - [recorder.py : handle_message() : line 186] - Received msg from Pypo Message Handler: {u'server_timezone': u'Europe/Warsaw', u'event_type': u'update_recorder_schedule', u'shows': [{u'time_filled': None, u'ends': u'2012-05-30 22:00:00', u'name': u'Nocny Autobus', u'color': u'000000', u'starts': u'2012-05-30 21:00:00', u'show_id': u'127', u'instance_id': u'925', u'record': u'1', u'rebroadcast': u'0', u'file_id': None, u'background_color': u'25a4de'}]}
2012-05-30 22:00:34,972 INFO - [recorder.py : process_recorder_schedule() : line 198] - Parsing recording show schedules...
2012-05-30 22:01:05,002 INFO - [recorder.py : run() : line 285] - heartbeat

Any ideas what happened? May I be of any service and supply You with further logs? :)

Marcin

Martin Konecny

@James+Dunn

We didn't include the xterm change in 2.1.0 because I was unsure of side effects so close to 2.1 release. For now, please make that change manually and we'll include it in a future release :)

@marcin

Please file a bug for 2.1 on dev.sourcefabric.org detailing this problem, and we'll look into it.

Naomi

Hey Marcin, the back to back problem has already been addressed earlier in this thread including code how to fix it for 2.0.3 it is already fixed in 2.1

there is one other php problem already addressed in this thread as well. If you're going to be using 2.0.3 you should take care of both of these issues first. 2.1 does not have either of the problems.

Marcin Tym

Oh, indeed it was already adressed. I've missed it somehow, Sorry for bringing it again.

I won't file a bug for the interuption problem. I checked it thoroughly and it appears had been caused by system failure. Not Airtime's fault so case closed.

Thank You for your help :)

Naomi

Great, thanks for posting problems you are having :) helps the community.

Airtime 2.1 should be released soon so you might want to give the RCs a try to see how you like it. James Dunn has found 1 problem with recording shows in RC2 currently so that will be fixed soon.

Marcin Tym · Post edited by Marcin Tym at 2012-06-09 06:56:01

Hi,

I upgraded to 2.1 and there still seems to be the problem for back to back shows.

recorder log:
2012-06-07 20:59:14,010 INFO - [recorder.py : run() : line 284] - heartbeat
2012-06-07 20:59:44,041 INFO - [recorder.py : run() : line 284] - heartbeat
2012-06-07 20:59:56,054 DEBUG - [recorder.py : get_time_till_next_show() : line 222] - Shows {u'2012-06-07 19:00:00': [datetime.timedelta(0, 3600), 703, u'1996', u'Europe/Warsaw'], u'2012-06-07 20:00:00': [datetime.timedelta(0, 7200), 1189, u'Czwartkowa Radioza', u'Europe/Warsaw']}
2012-06-07 20:59:56,054 DEBUG - [recorder.py : get_time_till_next_show() : line 223] - Next show 2012-06-07 19:00:00
2012-06-07 20:59:56,055 DEBUG - [recorder.py : get_time_till_next_show() : line 224] - Now 2012-06-07 18:59:56.054160
2012-06-07 20:59:56,055 DEBUG - [recorder.py : start_record() : line 232] - sleeping 3.94584 seconds until show
2012-06-07 21:00:00,031 INFO - [recorder.py : record_show() : line 79] - starting record
2012-06-07 21:00:00,033 INFO - [recorder.py : record_show() : line 80] - command ecasound -f:16,2,44100 -i alsa -o /var/tmp/airtime/show-recorder/2012-06-07-21:00:00.ogg,256000 -t:3600.0
2012-06-07 21:00:00,138 INFO - [recorder.py : record_show() : line 88] - finishing record, return code 2
2012-06-07 21:00:00,139 INFO - [recorder.py : run() : line 165] - problem recording show
2012-06-07 21:00:00,207 INFO - [recorder.py : record_show() : line 88] - finishing record, return code 0
2012-06-07 21:00:00,207 INFO - [recorder.py : run() : line 156] - Preparing to upload /var/tmp/airtime/show-recorder/2012-06-07-20:00:00.ogg
2012-06-07 21:00:00,207 INFO - [recorder.py : set_metadata_and_save() : line 129] - time: 20-00-00
2012-06-07 21:00:01,948 DEBUG - [api_client.py : upload_recorded_show() : line 341] - http://localhost:80/api/upload-file/format/json/api_key/%%api_key%%
2012-06-07 21:00:01,948 DEBUG - [api_client.py : upload_recorded_show() : line 345] - Upload attempt: 1
2012-06-07 21:00:16,731 INFO - [api_client.py : upload_recorded_show() : line 351] - uploaded show result []
2012-06-07 21:00:18,045 INFO - [recorder.py : run() : line 284] - heartbeat
2012-06-07 21:00:48,078 INFO - [recorder.py : run() : line 284] - heartbeat

Unfortunetly I missed to get py-interpreter log on time. It's alread overwritten. :( I'll try to hunt it down next time.

Schedule attached. All shows but one have been recorded. The one that failed was 1996 (21:00 - 22:00).

I checked recorder.py. The line (#218) is corrected due to upgrade but there is still something wrong.

Please, let me know if you need more logs, info ,etc.

Martin Konecny

Did you apply the "export TERM=xterm" fix? This will be included by us in the 2.1.1 release.

Marcin Tym · Post edited by Marcin Tym at 2012-06-10 16:59:50

Yes, It's already applied. And there is now problem with it. It normally ended recording just after ecasound start with exit code 1. Now it's 2. And it's quite visible that ecasound is trying to start new recording before ending the former (which's baaad, m'kay). The former is recorded fine and ends with 0 status.

One more back to back shows were recorded since then. Suprisingly, there was nothing wrong with them. So for now it's 1 out of 2. I'll continue to monitor the recordings and will inform You if anything unexpected happens.

Martin Konecny

Reply to @Marcin+Tym:

Yup that's an embarassing race condition we have. I was actually going to patch that this weekend until I realized that you can in fact have multiple ecasound processes reading from the microphone input (at least during my brief experimenting).

I'm curious if you can run multiple instances of ecasound simultaneously on your system.

Marcin Tym

I'm not a specialist on ecasound, but I think it's not the problem here. Presumably ecasound is using sound card port to record input. If You use two instances of a process to read from a port, one of them connects and and the second one crashes because the port is already taken.

But as I said I'm not an expert on ecasound. Maybe it has data stream duplication (or whatever) running on sound card input. No idea...

Martin Konecny

We'll look into this more. At the moment it seems you can run multiple instances of ecasound at the same time (which would be ideal as one ecasound is starting as the other is finishing up writing to a file).

It doesn't seem to be an impossibility that two processes could record simultaneously from microphone input. It's similar to reading a single file, as long as the file is being read from, and not written to then no problem.

Marcin Tym

Ok, just FYI. Two of yesterday shows haven't been recorded. Shows missed at 18:00 and 22:00.

Please take a look at logs from around 21:00. Back to back shows recorded normally.

Logs and schedule attached.

Marcin Tym · Post edited by Marcin Tym at 2012-06-19 05:35:49

NVM

Marcin Tym · Post edited by Marcin Tym at 2013-06-05 11:53:02

BUMPING the topic. The problem still exists (v 2.3.1). Back to back shows may not be recorded cause there is a great possibility that two ecasound processes will try to read from the same card port using ALSA. This is the standard behaviour - one process, one sound card port.

If I may suggest the one of the two solutions I have in mind:
- Ensure that only one ecasound is running. Wait with starting the second ecasound until the first finished.
- use some kind of audio routing server e.g. JACK

I'll gladly help with developing and testing the solution for that problem.

Marcin Tym

Good news. The issue has been solved as in http://dev.sourcefabric.org/browse/CC-5299.

Need to use dsnoop to allow concurent read on audio interface.

Daniel James

Hi Marcin, could you post the details of your dsnoop configuration for the benefit of other users please? Did you put this in the file /etc/asound.conf ?

Thanks!

Daniel

Howdy, Stranger!

Categories

Poll

Top Posters