Using Airtime 1.8.2 installed from sourcefabric's deb repository on Debian AMD64 architecture.

At random times Airtime skips playing random items from the scheduled playlist. They simply don't start and normally, another audio item after the not-played one is streamed fine.

Icecast running, no errors, simply shows: Current Song: Airtime - offline

Airtime itself shows item as being played, however "ON AIR" is not red-hilighted.

Problem appers with random audio tracks, sometimes they are played, sometimes not. This time it was the 3rd item in the playlist that has not been played but it may perfectly be first or last item on the list.

Issue started at 13:00:

/var/log/airtime/pypo-liquidsoap # less ls_script.log


2011/06/29 09:59:43 [server:3] New client: localhost
2011/06/29 09:59:43 [decoder:3] Method "MP3" accepted " /var/tmp/airtime/pypo/cache/scheduler/2011-06-29-09-59-43/23 f35ff508b60879e425dfb4956a7f78.mp3 ".
2011/06/29 09:59:43 [queue:3] Prepared " /var/tmp/airtime/pypo/cache/scheduler/2011-06-29-09-59-43/23 f35ff508b60879e425dfb4956a7f78.mp3 " (RID 0).
2011/06/29 09:59:43 [fallback_4312:3] Switch to src_4277 with transition.
2011/06/29 10:22:38 [server:3] New client: localhost
2011/06/29 10:59:42 [server:3] New client: localhost
2011/06/29 10:59:42 [queue:3] Finished with " /var/tmp/airtime/pypo/cache/scheduler/2011-06-29-09-59-43/23 f35ff508b60879e425dfb4956a7f78.mp3 ".
2011/06/29 10:59:42 [decoder:3] Method "MP3" accepted " /var/tmp/airtime/pypo/cache/scheduler/2011-06-29-10-59-42/12 5786a67388b4ac3491cc8df9b6ab3a.mp3 ".
2011/06/29 10:59:42 [queue:3] Prepared " /var/tmp/airtime/pypo/cache/scheduler/2011-06-29-10-59-42/12 5786a67388b4ac3491cc8df9b6ab3a.mp3 " (RID 1).
2011/06/29 11:22:38 [server:3] New client: localhost
2011/06/29 11:29:39 [queue:3] Finished with " /var/tmp/airtime/pypo/cache/scheduler/2011-06-29-10-59-42/12 5786a67388b4ac3491cc8df9b6ab3a.mp3 ".
2011/06/29 11:29:39 [fallback_4312:3] Switch to src_4310 with forgetful transition.
2011/06/29 11:29:40 [server:3] New client: localhost
2011/06/29 11:29:40 [decoder:3] Method "MP3" accepted " /var/tmp/airtime/pypo/cache/scheduler/2011-06-29-11-29-40/79 afe3975d9424430d55358bb6a2bc0c.mp3 ".
2011/06/29 11:29:40 [queue:3] Prepared " /var/tmp/airtime/pypo/cache/scheduler/2011-06-29-11-29-40/79 afe3975d9424430d55358bb6a2bc0c.mp3 " (RID 0).
2011/06/29 11:29:40 [fallback_4312:3] Switch to src_4277 with transition.
2011/06/29 11:59:39 [queue:3] Finished with " /var/tmp/airtime/pypo/cache/scheduler/2011-06-29-11-29-40/79 afe3975d9424430d55358bb6a2bc0c.mp3 ".
2011/06/29 11:59:39 [fallback_4312:3] Switch to src_4310 with forgetful transition.
2011/06/29 12:00:00 [server:3] New client: localhost
2011/06/29 12:00:00 [decoder:3] Method "MP3" accepted " /var/tmp/airtime/pypo/cache/scheduler/2011-06-29-12-00-00/c3 0bec685245c26b6703bcef1deb5124.mp3 ".
2011/06/29 12:00:00 [queue:3] Prepared " /var/tmp/airtime/pypo/cache/scheduler/2011-06-29-12-00-00/c3 0bec685245c26b6703bcef1deb5124.mp3 " (RID 1).
2011/06/29 12:00:00 [fallback_4312:3] Switch to src_4277 with transition.
2011/06/29 12:22:38 [server:3] New client: localhost
2011/06/29 12:59:42 [server:3] New client: localhost
2011/06/29 12:59:42 [queue:3] Finished with " /var/tmp/airtime/pypo/cache/scheduler/2011-06-29-12-00-00/c3 0bec685245c26b6703bcef1deb5124.mp3 ".
2011/06/29 12:59:42 [decoder:3] Method "MP3" accepted " /var/tmp/airtime/pypo/cache/scheduler/2011-06-29-12-59-42/37 0ab602c36d33f7dc803499238ea0ff.mp3 ".
2011/06/29 12:59:42 [queue:3] Prepared " /var/tmp/airtime/pypo/cache/scheduler/2011-06-29-12-59-42/37 0ab602c36d33f7dc803499238ea0ff.mp3 " (RID 0).
2011/06/29 12:59:47 [queue:3] Finished with " /var/tmp/airtime/pypo/cache/scheduler/2011-06-29-12-59-42/37 0ab602c36d33f7dc803499238ea0ff.mp3 ".
2011/06/29 12:59:47 [fallback_4312:3] Switch to src_4310 with forgetful transition.
2011/06/29 13:22:39 [server:3] New client: localhost



/var/log/airtime/pypo-liquidsoap/main # less current


xxx 2011-06-29 12:00:00,223 INFO - [api_client.py : notify_media_item_start_playing() : line 290] - API-Status 1
xxx 2011-06-29 12:00:00,223 INFO - [api_client.py : notify_media_item_start_playing() : line 291] - API-Message
xxx 2011-06-29 12:00:00,223 DEBUG - [pypo-notify.py : notify_media_start_playing() : line 80] - Response: {"status": 1, "message": ""}
xxx 2011/06/29 12:22:38 [server:3] New client: localhost
xxx 2011/06/29 12:59:42 [server:3] New client: localhost
xxx 2011/06/29 12:59:42 [queue:3] Finished with " /var/tmp/airtime/pypo/cache/scheduler/2011-06-29-12-00-00/c3 0bec685245c26b6703bcef1deb5124.mp3 ".
xxx 2011/06/29 12:59:42 [decoder:3] Method "MP3" accepted " /var/tmp/airtime/pypo/cache/scheduler/2011-06-29-12-59-42/37 0ab602c36d33f7dc803499238ea0ff.mp3 ".
xxx 2011/06/29 12:59:42 [queue:3] Prepared " /var/tmp/airtime/pypo/cache/scheduler/2011-06-29-12-59-42/37 0ab602c36d33f7dc803499238ea0ff.mp3 " (RID 0).
xxx /usr/lib/airtime/pypo/bin/scripts/notify.sh --data='301' --media-id=373
xxx
xxx #########################################
xxx # *** pypo *** #
xxx # pypo notification gateway #
xxx#########################################
xxx 2011-06-29 12:59:42,103 DEBUG - [pypo-notify.py : notify_media_start_playing() : line 75] - #################################################
xxx 2011-06-29 12:59:42,103 DEBUG - [pypo-notify.py : notify_media_start_playing() : line 76] - # Calling server to update about what's playing #
xxx 2011-06-29 12:59:42,103 DEBUG - [pypo-notify.py : notify_media_start_playing() : line 77] - #################################################
xxx 2011-06-29 12:59:42,103 DEBUG - [pypo-notify.py : notify_media_start_playing() : line 78] - data = 301
xxx 2011-06-29 12:59:42,103 DEBUG - [api_client.py : notify_media_item_start_playing() : line 286] - http://radiobioslone.pl:80/api/notify-media-item-start-play/ api_key/%%api_key%%/media_id/373/schedule_id/301
xxx 2011-06-29 12:59:42,201 INFO - [api_client.py : notify_media_item_start_playing() : line 290] - API-Status 1
xxx 2011-06-29 12:59:42,201 INFO - [api_client.py : notify_media_item_start_playing() : line 291] - API-Message
xxx 2011-06-29 12:59:42,201 DEBUG - [pypo-notify.py : notify_media_start_playing() : line 80] - Response: {"status": 1, "message": ""}
xxx 2011/06/29 12:59:47 [queue:3] Finished with " /var/tmp/airtime/pypo/cache/scheduler/2011-06-29-12-59-42/37 0ab602c36d33f7dc803499238ea0ff.mp3 ".
xxx 2011/06/29 12:59:47 [fallback_4312:3] Switch to src_4310 with forgetful transition.



/var/log/airtime/pypo/main # less current


xxx 2011-06-29 12:58:01,493 INFO - [pypopush.py : run() : line 234] - heartbeat
xxx 2011-06-29 12:58:31,986 INFO - [pypopush.py : run() : line 234] - heartbeat
xxx 2011-06-29 12:59:02,490 INFO - [pypopush.py : run() : line 234] - heartbeat
xxx 2011-06-29 12:59:32,992 INFO - [pypopush.py : run() : line 234] - heartbeat
xxx 2011-06-29 12:59:33,022 DEBUG - [pypopush.py : push() : line 102] - Preparing to push playlist scheduled at: 2011-06-29-12-59-42
xxx 2011-06-29 12:59:33,023 DEBUG - [pypopush.py : push_liquidsoap() : line 160] - Epoch start: 1309345182
xxx 2011-06-29 12:59:33,023 DEBUG - [pypopush.py : push_liquidsoap() : line 161] - Epoch now: 1309345173.02
xxx 2011-06-29 12:59:33,023 DEBUG - [pypopush.py : push_liquidsoap() : line 168] - sleeping for 8.97700309753 s
xxx 2011-06-29 12:59:42,009 DEBUG - [pypopush.py : push_liquidsoap() : line 174] - source.skip
xxx
xxx 2011-06-29 12:59:42,009 DEBUG - [pypopush.py : push_liquidsoap() : line 181] - vars.pypo_data 301
xxx
xxx 2011-06-29 12:59:42,009 DEBUG - [pypopush.py : push_liquidsoap() : line 184] - Preparing to push playlist 2011-06-29-12-59-42
xxx 2011-06-29 12:59:42,023 DEBUG - [pypopush.py : push_liquidsoap() : line 192] - Skipped
xxx END
xxx Done
xxx END
xxx 0
xxx END
xxx Audycje
xxx END
xxx Bye!
xxx
xxx 2011-06-29 12:59:42,023 DEBUG - [pypopush.py : push() : line 110] - Pushed to liquidsoap, updating 'played' status.
xxx 2011-06-29 12:59:42,079 DEBUG - [pypopush.py : push() : line 122] - Doing callback to server to update 'played' status.
xxx 2011-06-29 12:59:42,079 DEBUG - [api_client.py : notify_scheduled_item_start_playing() : line 258] - http://radiobioslone.pl:80/api/notify-schedule-group-play/ap i_key/%%api_key%%/schedule_id/301
xxx 2011-06-29 12:59:42,171 INFO - [api_client.py : notify_scheduled_item_start_playing() : line 264] - API-Status 1
xxx 2011-06-29 12:59:42,172 INFO - [api_client.py : notify_scheduled_item_start_playing() : line 265] - API-Message
xxx 2011-06-29 13:00:12,654 INFO - [pypopush.py : run() : line 234] - heartbeat
xxx 2011-06-29 13:00:43,161 INFO - [pypopush.py : run() : line 234] - heartbeat


# airtime-check-system
CPU = Intel(R) Core(TM) i7 CPU 950 @ 3.07GHz
Total RAM = 8190812 kB
Free RAM = 1087908 kB
OS = 6.0.2 x86-64
AIRTIME_CONFIG_FILES = OK
POSTGRESQL_DATABASE = OK
PYTHON_KOMBU_VERSION = 1.1.6
PYTHON_POSTER_VERSION = 0.8.1
RABBITMQ_SERVER = OK
AIRTIME_VERSION_URL = http://radiobioslone.pl:80/api/version/api_key/%%api_key%%
APACHE_CONFIGURED = YES
AIRTIME_VERSION = 1.8.2
PLAYOUT_ENGINE_PROCESS_ID = 2943
PLAYOUT_ENGINE_RUNNING_SECONDS = 748857
LIQUIDSOAP_PROCESS_ID = 2944
LIQUIDSOAP_RUNNING_SECONDS = 748857
ICECAST_PROCESS_ID = 1409

-- There appears to be problems with your setup. Please visit
-- http://wiki.sourcefabric.org/x/HABQ for troubleshooting info.


If you need more logs, please let me know.

Regards,
Jacek