import asyncio
import datetime
import json
+import logging
import random
import signal
import sys
+import time
import requests
from django.core.management.base import BaseCommand
from emissions.models import Nonstop
-from nonstop.models import Track, SomaLogLine, ScheduledDiffusion, RecurringStreamOccurence, RecurringRandomDirectoryOccurence
+from nonstop.models import (NonstopZoneSettings, Track, Jingle, SomaLogLine,
+ ScheduledDiffusion, RecurringStreamOccurence, RecurringRandomDirectoryOccurence)
from nonstop.app_settings import app_settings
+from nonstop.utils import Tracklist
+
+
+logger = logging.getLogger('stamina')
class Command(BaseCommand):
quit = False
def handle(self, verbosity, **kwargs):
- try:
- asyncio.run(self.main(), debug=settings.DEBUG)
- except KeyboardInterrupt:
- pass
+ alert_index = 0
+ latest_alert_timestamp = 0
+ latest_exception_timestamp = 0
+
+ def exception_alert_thresholds():
+ yield 0
+ duration = 3
+ while duration < 3600:
+ yield duration
+ duration *= 5
+ duration = 3600
+ while True:
+ yield duration
+ duration += 3600
+
+ while True:
+ try:
+ asyncio.run(self.main(), debug=settings.DEBUG)
+ except KeyboardInterrupt:
+ break
+ except Exception:
+ timestamp = time.time()
+ if (timestamp - latest_exception_timestamp) > 300:
+ # if latest exception was a "long" time ago, assume
+ # things went smooth for a while and reset things
+ alert_index = 0
+ latest_alert_timestamp = 0
+ latest_exception_timestamp = 0
+
+ alert_threshold = 0
+ for i, threshold in enumerate(exception_alert_thresholds()):
+ if i == alert_index:
+ alert_threshold = threshold
+ break
+
+ if (timestamp - latest_alert_timestamp) > alert_threshold:
+ logger.exception('General exception (alert index: %s)', alert_index)
+ latest_alert_timestamp = timestamp
+ alert_index += 1
+
+ time.sleep(2) # retry after a bit
+ latest_exception_timestamp = timestamp
+ continue
+ break
def get_playlist(self, zone, start_datetime, end_datetime):
current_datetime = start_datetime
playlist = []
adjustment_counter = 0
try:
- jingles = list(zone.nonstopzonesettings_set.first().jingles.all())
+ zone_settings = zone.nonstopzonesettings_set.first()
+ jingles = list(zone_settings.jingles.all())
except AttributeError:
+ zone_settings = NonstopZoneSettings()
jingles = []
+ zone_ids = [zone.id]
+ extra_zones = app_settings.EXTRA_ZONES.get(zone.slug)
+ if extra_zones:
+ zone_ids.extend([x.id for x in Nonstop.objects.filter(slug__in=extra_zones)])
+
recent_tracks_id = [x.track_id for x in
SomaLogLine.objects.exclude(on_air=False).filter(
track__isnull=False,
play_timestamp__gt=datetime.datetime.now() - datetime.timedelta(days=app_settings.NO_REPEAT_DELAY))]
+
+ tracklist = Tracklist(zone_settings, zone_ids, recent_tracks_id)
+ random_tracks_iterator = tracklist.get_random_tracks()
t0 = datetime.datetime.now()
allow_overflow = False
while current_datetime < end_datetime:
if jingles and current_datetime - self.last_jingle_datetime > datetime.timedelta(minutes=20):
# jingle time, every ~20 minutes
- playlist.append(random.choice(jingles))
+ tracklist.playlist.append(random.choice(jingles))
self.last_jingle_datetime = current_datetime
- current_datetime = start_datetime + sum(
- [x.duration for x in playlist], datetime.timedelta(seconds=0))
-
+ current_datetime = start_datetime + tracklist.get_duration()
remaining_time = (end_datetime - current_datetime)
- track = Track.objects.filter(
- nonstop_zones=zone,
- duration__isnull=False).exclude(
- id__in=recent_tracks_id + [x.id for x in playlist if isinstance(x, Track)]
- ).order_by('?').first()
- if track is None:
- # no track, reduce recent tracks exclusion
- recent_tracks_id = recent_tracks_id[:len(recent_tracks_id)//2]
- continue
- playlist.append(track)
- current_datetime = start_datetime + sum(
- [x.duration for x in playlist], datetime.timedelta(seconds=0))
+
+ track = next(random_tracks_iterator)
+ tracklist.append(track)
+ current_datetime = start_datetime + tracklist.get_duration()
if current_datetime > end_datetime and not allow_overflow:
# last track overshot
# 1st strategy: remove last track and try to get a track with
# exact remaining time
- print('overshoot', current_datetime, file=sys.stderr)
- playlist = playlist[:-1]
+ logger.debug('Overshoot %s, %s', adjustment_counter, current_datetime)
+ tracklist.pop()
track = Track.objects.filter(
- nonstop_zones=zone,
+ nonstop_zones__in=zone_ids,
duration__gte=remaining_time,
duration__lt=remaining_time + datetime.timedelta(seconds=1)
- ).exclude(
- id__in=recent_tracks_id + [x.id for x in playlist if isinstance(x, Track)]
- ).order_by('?').first()
+ ).exclude(id__in=tracklist.get_recent_track_ids()).order_by('?').first()
if track:
# found a track
- playlist.append(track)
+ tracklist.append(track)
else:
# fallback strategy: didn't find track of expected duration,
# reduce playlist further
adjustment_counter += 1
- playlist = playlist[:-1]
- if len(playlist) == 0 or adjustment_counter > 5:
+ if tracklist.pop() is None or adjustment_counter > 5:
# a dedicated sound that ended a bit too early,
# or too many failures to get an appropriate file,
# allow whatever comes.
allow_overflow = True
- print('allow overflow', file=sys.stderr)
+ logger.debug('Allowing overflows')
- current_datetime = start_datetime + sum(
- [x.duration for x in playlist], datetime.timedelta(seconds=0))
+ current_datetime = start_datetime + tracklist.get_duration()
- print('computed playlist: (computation time: %ss)' % (datetime.datetime.now() - t0), file=sys.stderr)
+ logger.info('Computed playlist for "%s" (computation time: %ss)',
+ zone, (datetime.datetime.now() - t0))
current_datetime = start_datetime
- for track in playlist:
- print(' ', current_datetime, track.duration, track.title, file=sys.stderr)
+ for track in tracklist.playlist:
+ logger.debug('- track: %s %s %s', current_datetime, track.duration, track.title)
current_datetime += track.duration
- print(' ', current_datetime, '---', file=sys.stderr)
- print(' adjustment_counter:', adjustment_counter, file=sys.stderr)
-
- return playlist
+ logger.debug('- end: %s', current_datetime)
+ return tracklist.playlist
def is_nonstop_on_air(self):
# check if nonstop system is currently on air
log_line.save()
async def player_process(self, item, timeout=None):
+ cmd = [app_settings.PLAYER_COMMAND] + app_settings.PLAYER_ARGS
+ if hasattr(item, 'is_stream') and item.is_stream():
+ cmd.append(item.stream.url)
+ logger.info('Play stream: %s', item.stream.url)
+ else:
+ cmd.append(item.file_path())
+ logger.info('Play file: %s', item.file_path())
if app_settings.DEBUG_WITH_SLEEPS:
+ # replace command by a sleep call, for silent debugging
if hasattr(item, 'is_stream') and item.is_stream():
cmd = 'sleep 86400 # %s' % item.stream.url
elif isinstance(item.duration, datetime.timedelta):
cmd = 'sleep %s # %s' % (item.duration.total_seconds(), item.file_path())
elif isinstance(item.duration, int):
cmd = 'sleep %s # %s' % (item.duration, item.file_path())
- else:
- cmd = [app_settings.PLAYER_COMMAND] + app_settings.PLAYER_ARGS
- if hasattr(item, 'is_stream') and item.is_stream():
- cmd.append(item.stream.url)
- else:
- cmd.append(item.file_path())
- print('cmd:', cmd, file=sys.stderr)
+ logger.debug('cmd %r', cmd)
if isinstance(cmd, str):
self.player = await asyncio.create_subprocess_shell(
cmd,
except IndexError:
break
self.current_track_start_datetime = now
- print(now, track.title, track.duration, file=sys.stderr)
+ if isinstance(track, Jingle):
+ logger.info('Jingle: %s (id: %s) (%s)', track.title, track.id, track.duration)
+ else:
+ logger.info('Track: %s (id: %s) (%s)', track.title, track.id, track.duration)
record_task = None
if isinstance(track, Track): # not jingles
record_task = asyncio.create_task(self.record_nonstop_line(track, datetime.datetime.now()))
break
self.playhead += 1
elif slot.is_stream():
- print(now, 'playing stream', slot.stream, file=sys.stderr)
+ logger.info('Stream: %s', slot.stream)
if slot.jingle_id:
await self.player_process(slot.jingle, timeout=60)
- print('timeout at', (slot.end_datetime - now).total_seconds(), file=sys.stderr)
- await self.player_process(slot, timeout=(slot.end_datetime - now).total_seconds())
+ logger.debug('Stream timeout: %s', (slot.end_datetime - now).total_seconds())
+ short_interruption_counter = 0
+ has_played = False
+ while True:
+ player_start_time = datetime.datetime.now()
+ await self.player_process(slot, timeout=(slot.end_datetime - player_start_time).total_seconds())
+ now = datetime.datetime.now()
+ if (slot.end_datetime - now).total_seconds() < 2:
+ # it went well, stop
+ break
+ # stream got interrupted
+ if (datetime.datetime.now() - player_start_time).total_seconds() < 15:
+ # and was up for less than 15 seconds.
+ if not has_played:
+ # never up before, probably not even started
+ if isinstance(slot, RecurringStreamOccurence):
+ # no mercy for recurring stream, remove occurence
+ logger.info('Missing stream for %s, removing', slot)
+ slot.delete()
+ elif slot.auto_delayed is True:
+ # was already delayed and is still not up, remove.
+ logger.info('Still missing stream for %s, removing', slot)
+ slot.delete()
+ else:
+ # push back start datetime for 5 minutes, and get
+ # back to nonstop music in the meantime
+ logger.info('Pushing starting time of %s', slot.diffusion.episode)
+ slot.diffusion.datetime = slot.diffusion.datetime + datetime.timedelta(seconds=300)
+ slot.diffusion.episode.duration = slot.diffusion.episode.get_duration() - 5
+ if slot.diffusion.episode.duration <= 5:
+ slot.diffusion.episode.duration = 0
+ slot.auto_delayed = True
+ slot.diffusion.save()
+ slot.diffusion.episode.save()
+ slot.save()
+ break
+ short_interruption_counter += 1
+ # wait a bit
+ await asyncio.sleep(short_interruption_counter)
+ else:
+ # mark stream as ok at least one, and reset short
+ # interruption counter
+ has_played = True
+ short_interruption_counter = 0
+ logger.debug('Stream error for %s', slot)
+
+ if short_interruption_counter > 5:
+ # many short interruptions
+ logger.info('Too many stream errors for %s, removing', slot)
+ slot.delete()
+ break
else:
if hasattr(slot, 'episode'):
- print(now, 'playing sound', slot.episode, file=sys.stderr)
+ logger.info('Episode: %s (id: %s)', slot.episode, slot.episode.id)
else:
- print(now, 'playing random', file=sys.stderr)
+ logger.info('Random: %s', slot)
if slot.jingle_id:
await self.player_process(slot.jingle, timeout=60)
await self.player_process(slot)
def recompute_playlist(self):
current_track = self.playlist[self.playhead]
- print('recompute_playlist, from', current_track.title, self.current_track_start_datetime + current_track.duration, 'to', self.slot.end_datetime, file=sys.stderr)
+ logger.debug('Recomputing playlist at %s, from %s to %s',
+ current_track.title,
+ self.current_track_start_datetime + current_track.duration,
+ self.slot.end_datetime)
playlist = self.get_playlist(self.slot,
self.current_track_start_datetime + current_track.duration, self.slot.end_datetime)
if playlist:
datetime__lt=before_datetime,
).order_by('datetime').first()
if diffusion and occurence:
- return diffusion if diffusion.diffusion__datetime < occurence.datetime else occurence
+ return diffusion if diffusion.diffusion.datetime < occurence.datetime else occurence
if diffusion:
return diffusion
if occurence:
def recompute_slots(self):
now = datetime.datetime.now()
- # print(now, 'recompute_slots', file=sys.stderr)
diffusion = self.get_current_diffusion()
if diffusion:
self.slot = diffusion
async def recompute_slots_loop(self):
now = datetime.datetime.now()
- print(now, 'recompute_slots_loop', file=sys.stderr)
sleep = (60 - now.second) % 10 # adjust to awake at :00
while not self.quit:
await asyncio.sleep(sleep)
expected_slot = self.slot
if current_slot != expected_slot:
now = datetime.datetime.now()
- print(now, 'unexpected change', current_slot, 'vs', expected_slot, file=sys.stderr)
+ logger.info('Unexpected change, %s vs %s', current_slot, expected_slot)
if isinstance(current_slot, Nonstop) and isinstance(expected_slot, Nonstop):
# ask for a softstop, i.e. finish the track then switch.
self.softstop = True
- else:
+ elif isinstance(current_slot, Nonstop):
# interrupt nonstop
- print('interrupting nonstop', file=sys.stderr)
+ logger.info('Interrupting nonstop')
self.play_task.cancel()
elif current_slot.end_datetime > expected_slot.end_datetime:
now = datetime.datetime.now()
- print(now, 'change in end time, from %s to %s' %
- (current_slot.end_datetime, expected_slot.end_datetime), file=sys.stderr)
+ logger.debug('Change in end time, from %s to %s',
+ current_slot.end_datetime,
+ expected_slot.end_datetime)
if expected_slot.end_datetime - datetime.datetime.now() > datetime.timedelta(minutes=5):
# more than 5 minutes left, recompute playlist
self.recompute_playlist()
try:
message = data.decode().strip()
except UnicodeDecodeError:
- print('got invalid message %r' % message, file=sys.stderr)
+ logger.debug('Server, invalid message %r', message)
if not data:
end = True
continue
- print('got message: %r' % message, file=sys.stderr)
+ logger.debug('Server, message %r', message)
if message == 'status':
response = {'slot': str(self.slot)}
if isinstance(self.slot, Nonstop):
writer.close()
def sigterm_handler(self):
- print('got signal', file=sys.stderr)
+ logger.info('Got SIGTERM')
self.quit = True
self.play_task.cancel()
loop.add_signal_handler(
signal.SIGTERM,
self.sigterm_handler)
- now = datetime.datetime.now()
self.recompute_slots()
server = await asyncio.start_server(
self.handle_connection,
self.recompute_slots_task = asyncio.create_task(self.recompute_slots_loop())
while not self.quit:
+ now = datetime.datetime.now()
duration = (self.slot.end_datetime - now).seconds
- print('next sure slot', duration, self.slot.end_datetime, file=sys.stderr)
+ logger.debug('Next sure shot %s (in %s)', self.slot.end_datetime, duration)
if duration < 2:
# next slot is very close, wait for it
await asyncio.sleep(duration)
try:
await self.play_task
self.recompute_slots()
- except asyncio.CancelledError as exc:
- print('exc:', exc, file=sys.stderr)
+ except asyncio.CancelledError:
+ logger.debug('Player cancelled exception')
if self.player and self.player.returncode is None: # not finished
self.player.kill()
except KeyboardInterrupt:
projects / django-panik-nonstop.git / blobdiff