def run(self):
schedule = self._schedule
stop_event = self._stop_event
terminated_event = self._terminated_event
notify = self._notifier.notify_listeners
now = time_utils.get_utc_now()
state = schedule.get_state(now)
notify('schedule_run_started', now, state)
transitions = tuple(schedule.get_transitions(start=now))
for i, t in enumerate(transitions):
self._wait_for_transition_or_stop(t)
if stop_event.is_set():
# stop requested
# Because there are multiple threads at play, it is
# possible (though unlikely) that `now` follows or
# equals the times of one or more transitions in
# `transitions[i:]`, i.e. that the transitions have
# occurred but the schedule's listeners have not been
# notified of them. We perform the notifications here.
while i < len(transitions) and transitions[i].time <= now:
t = transitions[i]
notify('schedule_state_changed', t.time, t.state)
i += 1
now = time_utils.get_utc_now()
state = schedule.get_state(now)
notify('schedule_run_stopped', now, state)
terminated_event.set()
return
else:
notify('schedule_state_changed', t.time, t.state)
# If we get here, the schedule run completed. The schedule is off
# since we are at or past the end of every interval of the schedule.
now = time_utils.get_utc_now()
notify('schedule_run_completed', now, False)
terminated_event.set()
def _add_annotation_constraints(self, job_info):
constraints_data = self.metadata.get('annotation_constraints')
if constraints_data is not None:
for data in constraints_data:
name = _get_required(data, 'name', 'annotation constraint')
self._logger.info(
'Adding annotation constraint "{}"...'.format(name))
description = data.get('description', '')
text = yaml_utils.dump(data)
creation_time = time_utils.get_utc_now()
creating_user = None
creating_job = Job.objects.get(id=job_info.job_id)
AnnotationConstraint.objects.create(
name=name,
description=description,
text=text,
creation_time=creation_time,
creating_user=creating_user,
creating_job=creating_job)
def delete_clip_annotation(
clip, annotation_info, creation_time=None, creating_user=None,
creating_job=None, creating_processor=None):
try:
annotation = StringAnnotation.objects.get(
clip=clip,
info=annotation_info)
except StringAnnotation.DoesNotExist:
return
else:
annotation.delete()
if creation_time is None:
creation_time = time_utils.get_utc_now()
StringAnnotationEdit.objects.create(
clip=clip,
info=annotation_info,
action=StringAnnotationEdit.ACTION_DELETE,
creation_time=creation_time,
creating_user=creating_user,
creating_job=creating_job,
creating_processor=creating_processor)
def classify_clips(clips, user, annotation_info, classification):
count = 0
for clip in clips:
creation_time = time_utils.get_utc_now()
kwargs = {
'value': classification,
'creation_time': creation_time,
'creating_user': user,
'creating_job': None,
'creating_processor': None
}
StringAnnotation.objects.create(
clip=clip,
info=annotation_info,
**kwargs)
StringAnnotationEdit.objects.create(
clip=clip,
info=annotation_info,
action=StringAnnotationEdit.ACTION_SET,
**kwargs)
count += 1
if count % 10000 == 0:
print(' {}...'.format(count))
def _add_annotation_constraints(self, job_info):
constraints_data = self.archive_data.get('annotation_constraints')
if constraints_data is not None:
for data in constraints_data:
name = _get_required(data, 'name', 'annotation constraint')
self._logger.info(
'Adding annotation constraint "{}"...'.format(name))
description = data.get('description', '')
text = yaml_utils.dump(data)
creation_time = time_utils.get_utc_now()
creating_user = None
creating_job = Job.objects.get(id=job_info.job_id)
AnnotationConstraint.objects.create(
name=name,
description=description,
text=text,
creation_time=creation_time,
creating_user=creating_user,
creating_job=creating_job)
def _add_annotations(self, job_info):
annotations_data = self.archive_data.get('annotations')
if annotations_data is not None:
for data in annotations_data:
name = _get_required(data, 'name', 'annotation')
self._logger.info('Adding annotation "{}"...'.format(name))
description = data.get('description', '')
type_ = data.get('type', 'String')
constraint = self._get_annotation_constraint(data)
creation_time = time_utils.get_utc_now()
creating_user = None
creating_job = Job.objects.get(id=job_info.job_id)
AnnotationInfo.objects.create(
name=name,
description=description,
type=type_,
constraint=constraint,
creation_time=creation_time,
creating_user=creating_user,
creating_job=creating_job)
def _wait_for_transition_or_stop(self, t):
while True:
now = time_utils.get_utc_now()
seconds = (t.time - now).total_seconds()
if seconds <= 0:
# transition time reached
return
else:
# transition time not reached
# We limit the wait duration to avoid `OverflowError`
# exceptions that we have seen (admittedly for very
# large numbers of seconds) if we don't. We keep the
# maximum wait duration fairly small on the hunch that
# doing so might improve the accuracy of schedule
# transition notification times, at least on some
# platforms.
seconds = min(seconds, 5)
self._stop_event.wait(seconds)
if self._stop_event.is_set():
return
def setUpClass(cls):
preference_manager.instance._push_test_module_preferences(__file__)
create = Processor.objects.create
create(name='Tseep Detector', type='Detector')
create(name='Thrush Detector', type='Detector')
create(name='Coarse Classifier', type='Classifier')
create(name='Species Classifier', type='Classifier')
creation_time = time_utils.get_utc_now()
constraint = AnnotationConstraint.objects.create(
name='Classification',
text=_CLASSIFICATION_CONSTRAINT_TEXT,
creation_time=creation_time)
AnnotationInfo.objects.create(
name='Classification',
type='String',
constraint=constraint,
creation_time=creation_time)
constraint = AnnotationConstraint.objects.create(
name='Confidence',
text=_CONFIDENCE_CONSTRAINT_TEXT,
creation_time=creation_time)
AnnotationInfo.objects.create(
name='Confidence',
type='String',
constraint=constraint,
creation_time=creation_time)
def delete_clip_annotation(
clip, annotation_info, creation_time=None, creating_user=None,
creating_job=None, creating_processor=None):
try:
annotation = StringAnnotation.objects.get(
clip=clip,
info=annotation_info)
except StringAnnotation.DoesNotExist:
return
else:
annotation.delete()
if creation_time is None:
creation_time = time_utils.get_utc_now()
StringAnnotationEdit.objects.create(
clip=clip,
info=annotation_info,
action=StringAnnotationEdit.ACTION_DELETE,
creation_time=creation_time,
creating_user=creating_user,
creating_job=creating_job,
creating_processor=creating_processor)
def classify_clips(clips, user, annotation_info, classification):
count = 0
for clip in clips:
creation_time = time_utils.get_utc_now()
kwargs = {
'value': classification,
'creation_time': creation_time,
'creating_user': user,
'creating_job': None,
'creating_processor': None
}
StringAnnotation.objects.create(clip=clip,
info=annotation_info,
**kwargs)
StringAnnotationEdit.objects.create(
clip=clip,
info=annotation_info,
action=StringAnnotationEdit.ACTION_SET,
**kwargs)
count += 1
if count % 10000 == 0:
print(' {}...'.format(count))
def _add_annotations(self, job_info):
annotations_data = self.metadata.get('annotations')
if annotations_data is not None:
for data in annotations_data:
name = _get_required(data, 'name', 'annotation')
self._logger.info('Adding annotation "{}"...'.format(name))
description = data.get('description', '')
type_ = data.get('type', 'String')
constraint = self._get_annotation_constraint(data)
creation_time = time_utils.get_utc_now()
creating_user = None
creating_job = Job.objects.get(id=job_info.job_id)
AnnotationInfo.objects.create(name=name,
description=description,
type=type_,
constraint=constraint,
creation_time=creation_time,
creating_user=creating_user,
creating_job=creating_job)
def _archive_clip(self, file_path, samples, start_index):
station = self._recording.station
# Get clip start time as a `datetime`.
start_seconds = start_index / self._sample_rate
start_delta = datetime.timedelta(seconds=start_seconds)
start_time = self._recording.start_time + start_delta
# Get clip length in sample frames.
length = len(samples)
end_time = signal_utils.get_end_time(
start_time, length, self._sample_rate)
creation_time = time_utils.get_utc_now()
try:
with archive_lock.atomic():
with transaction.atomic():
clip = Clip.objects.create(
station=station,
mic_output=self._mic_output,
recording_channel=self._recording_channel,
start_index=start_index,
length=length,
sample_rate=self._sample_rate,
start_time=start_time,
end_time=end_time,
date=station.get_night(start_time),
creation_time=creation_time,
creating_user=None,
creating_job=self._job,
creating_processor=self._detector
)
# We must create the clip audio file after creating
# the clip row in the database. The file's path
# depends on the clip ID, which is set as part of
# creating the clip row.
#
# We create the audio file within the database
# transaction to ensure that the clip row and
# audio file are created atomically.
if self._create_clip_files:
self._clip_manager.create_audio_file(clip, samples)
except Exception as e:
self._logger.error((
'Attempt to create clip from file "{}" failed with message: '
'{}. File will be ignored.').format(
file_path, str(e)))
else:
self._logger.info('Archived {} clip {}.'.format(self.name, clip))
def _import_recordings(self, recordings):
for r in recordings:
end_time = signal_utils.get_end_time(
r.start_time, r.length, r.sample_rate)
creation_time = time_utils.get_utc_now()
recording = Recording(
station=r.station,
recorder=r.recorder,
num_channels=r.num_channels,
length=r.length,
sample_rate=r.sample_rate,
start_time=r.start_time,
end_time=end_time,
creation_time=creation_time,
creating_job=self._job)
recording.save()
r.model = recording
for channel_num in range(r.num_channels):
recorder_channel_num = r.recorder_channel_nums[channel_num]
mic_output = r.mic_outputs[channel_num]
channel = RecordingChannel(
recording=recording,
channel_num=channel_num,
recorder_channel_num=recorder_channel_num,
mic_output=mic_output)
channel.save()
start_index = 0
for file_num, f in enumerate(r.files):
# We store all paths in the archive database as POSIX
# paths, even on Windows, for portability, since Python's
# `pathlib` module recognizes the slash as a path separator
# on all platforms, but not the backslash.
path = f.path.as_posix()
file = RecordingFile(
recording=recording,
file_num=file_num,
start_index=start_index,
length=f.length,
path=path)
file.save()
start_index += f.length
def _import_recordings(self, recordings):
for r in recordings:
end_time = signal_utils.get_end_time(
r.start_time, r.length, r.sample_rate)
creation_time = time_utils.get_utc_now()
recording = Recording(
station=r.station,
recorder=r.recorder,
num_channels=r.num_channels,
length=r.length,
sample_rate=r.sample_rate,
start_time=r.start_time,
end_time=end_time,
creation_time=creation_time,
creating_job=self._job)
recording.save()
r.model = recording
for channel_num in range(r.num_channels):
recorder_channel_num = r.recorder_channel_nums[channel_num]
mic_output = r.mic_outputs[channel_num]
channel = RecordingChannel(
recording=recording,
channel_num=channel_num,
recorder_channel_num=recorder_channel_num,
mic_output=mic_output)
channel.save()
start_index = 0
for file_num, f in enumerate(r.files):
# We store all paths in the archive database as POSIX
# paths, even on Windows, for portability, since Python's
# `pathlib` module recognizes the slash as a path separator
# on all platforms, but not the backslash.
path = f.path.as_posix()
file = RecordingFile(
recording=recording,
file_num=file_num,
start_index=start_index,
length=f.length,
path=path)
file.save()
start_index += f.length
def _import_clip(self, file_path, info):
length, sample_rate = _get_audio_file_info(file_path)
start_time = info.start_time
end_time = signal_utils.get_end_time(start_time, length, sample_rate)
mic_output = self._get_mic_output(info.station.name)
recording_channel = self._get_recording_channel(
info.station, info.date, sample_rate)
recording = recording_channel.recording
_assert_recording_contains_clip(recording, start_time, end_time)
creation_time = time_utils.get_utc_now()
clip = Clip.objects.create(station=info.station,
mic_output=mic_output,
recording_channel=recording_channel,
start_index=None,
length=length,
sample_rate=sample_rate,
start_time=start_time,
end_time=end_time,
date=info.date,
creation_time=creation_time,
creating_job=self._job,
creating_processor=info.detector)
_copy_clip_audio_file(file_path, clip)
if info.classification is not None:
creation_time = time_utils.get_utc_now()
# We assume that any classification performed before the
# import was by the user who started the import.
creating_user = self._job.creating_user
model_utils.annotate_clip(clip,
self._annotation_info,
info.classification,
creation_time=creation_time,
creating_user=creating_user)
def _archive_clip(self, file_path, samples, start_index):
station = self._recording.station
# Get clip start time as a `datetime`.
start_seconds = start_index / self._sample_rate
start_delta = datetime.timedelta(seconds=start_seconds)
start_time = self._recording.start_time + start_delta
# Get clip length in sample frames.
length = len(samples)
end_time = signal_utils.get_end_time(start_time, length,
self._sample_rate)
creation_time = time_utils.get_utc_now()
try:
with archive_lock.atomic():
with transaction.atomic():
clip = Clip.objects.create(
station=station,
mic_output=self._mic_output,
recording_channel=self._recording_channel,
start_index=start_index,
length=length,
sample_rate=self._sample_rate,
start_time=start_time,
end_time=end_time,
date=station.get_night(start_time),
creation_time=creation_time,
creating_user=None,
creating_job=self._job,
creating_processor=self._detector)
# We must create the clip audio file after creating
# the clip row in the database. The file's path
# depends on the clip ID, which is set as part of
# creating the clip row.
#
# We create the audio file within the database
# transaction to ensure that the clip row and
# audio file are created atomically.
if self._create_clip_files:
self._clip_manager.create_audio_file(clip, samples)
except Exception as e:
self._logger.error(
('Attempt to create clip from file "{}" failed with message: '
'{}. File will be ignored.').format(file_path, str(e)))
else:
self._logger.info('Archived {} clip {}.'.format(self.name, clip))
def _import_clip(self, file_path, info):
length, sample_rate = _get_audio_file_info(file_path)
start_time = info.start_time
end_time = signal_utils.get_end_time(start_time, length, sample_rate)
mic_output = self._get_mic_output(info.station.name)
recording_channel = self._get_recording_channel(
info.station, info.date, sample_rate)
recording = recording_channel.recording
_assert_recording_contains_clip(recording, start_time, end_time)
creation_time = time_utils.get_utc_now()
clip = Clip.objects.create(
station=info.station,
mic_output=mic_output,
recording_channel=recording_channel,
start_index=None,
length=length,
sample_rate=sample_rate,
start_time=start_time,
end_time=end_time,
date=info.date,
creation_time=creation_time,
creating_job=self._job,
creating_processor=info.detector)
_copy_clip_audio_file(file_path, clip)
if info.classification is not None:
creation_time = time_utils.get_utc_now()
# We assume that any classification performed before the
# import was by the user who started the import.
creating_user = self._job.creating_user
model_utils.annotate_clip(
clip, self._annotation_info, info.classification,
creation_time=creation_time, creating_user=creating_user)
def _create_job(command_spec, user):
with archive_lock.atomic():
job = Job.objects.create(command=json.dumps(
command_spec, default=_json_date_serializer),
creation_time=time_utils.get_utc_now(),
creating_user=user,
status='Unstarted')
return job.id
def _create_job(command_spec, user):
with archive_lock.atomic():
job = Job.objects.create(
command=json.dumps(command_spec, default=_json_date_serializer),
creation_time=time_utils.get_utc_now(),
creating_user=user,
status='Not Started')
return job.id
def annotate_clip(clip, annotation_value):
annotation_info = AnnotationInfo.objects.get(name='Classification')
creation_time = time_utils.get_utc_now()
try:
StringAnnotation.objects.create(clip=clip,
info=annotation_info,
value=annotation_value,
creation_time=creation_time)
except Exception:
# This can happen if a clip from one detector overlaps two or
# more clips from another detector.
pass
def annotate_clip(
clip, annotation_info, value, creation_time=None, creating_user=None,
creating_job=None, creating_processor=None):
try:
annotation = StringAnnotation.objects.get(
clip=clip,
info=annotation_info)
except StringAnnotation.DoesNotExist:
annotation = None
if annotation is None or annotation.value != value:
# annotation does not exist or value differs from specified value
if creation_time is None:
creation_time = time_utils.get_utc_now()
kwargs = {
'value': value,
'creation_time': creation_time,
'creating_user': creating_user,
'creating_job': creating_job,
'creating_processor': creating_processor
}
if annotation is None:
# annotation does not exist
StringAnnotation.objects.create(
clip=clip,
info=annotation_info,
**kwargs)
else:
# annotation exists but value differs from specified value
StringAnnotation.objects.filter(
clip=clip,
info=annotation_info
).update(**kwargs)
StringAnnotationEdit.objects.create(
clip=clip,
info=annotation_info,
action=StringAnnotationEdit.ACTION_SET,
**kwargs)
def annotate_clip(
clip, annotation_info, value, creation_time=None, creating_user=None,
creating_job=None, creating_processor=None):
try:
annotation = StringAnnotation.objects.get(
clip=clip,
info=annotation_info)
except StringAnnotation.DoesNotExist:
annotation = None
if annotation is None or annotation.value != value:
# annotation does not exist or value differs from specified value
if creation_time is None:
creation_time = time_utils.get_utc_now()
kwargs = {
'value': value,
'creation_time': creation_time,
'creating_user': creating_user,
'creating_job': creating_job,
'creating_processor': creating_processor
}
if annotation is None:
# annotation does not exist
StringAnnotation.objects.create(
clip=clip,
info=annotation_info,
**kwargs)
else:
# annotation exists but value differs from specified value
StringAnnotation.objects.filter(
clip=clip,
info=annotation_info
).update(**kwargs)
StringAnnotationEdit.objects.create(
clip=clip,
info=annotation_info,
action=StringAnnotationEdit.ACTION_SET,
**kwargs)
def annotate_clip(clip, annotation_value):
annotation_info = AnnotationInfo.objects.get(name='Classification')
creation_time = time_utils.get_utc_now()
try:
StringAnnotation.objects.create(
clip=clip,
info=annotation_info,
value=annotation_value,
creation_time=creation_time)
except Exception:
# This can happen if a clip from one detector overlaps two or
# more clips from another detector.
pass
def _create_recording_channel(self, station, date, sample_rate):
station_name = station.name
recorder = self._get_recorder(station_name)
mic_output = self._get_mic_output(station_name)
start_time, end_time = \
_get_recording_start_and_end_times(station, date)
duration = (end_time - start_time).total_seconds()
length = int(round(duration * sample_rate))
# Recompute end time from recording start time, length, and
# sample rate so it is consistent with our definition (i.e. so
# that it is the time of the last sample of the recording rather
# than the time of the sample after that).
end_time = signal_utils.get_end_time(start_time, length, sample_rate)
creation_time = time_utils.get_utc_now()
recording = Recording.objects.create(
station=station,
recorder=recorder,
num_channels=_NUM_RECORDING_CHANNELS,
length=length,
sample_rate=sample_rate,
start_time=start_time,
end_time=end_time,
creation_time=creation_time,
creating_job=self._job)
recording_channel = RecordingChannel.objects.create(
recording=recording,
channel_num=_RECORDING_CHANNEL_NUM,
recorder_channel_num=_RECORDER_CHANNEL_NUM,
mic_output=mic_output)
return recording_channel
def _create_recording_channel(self, station, date, sample_rate):
station_name = station.name
recorder = self._get_recorder(station_name)
mic_output = self._get_mic_output(station_name)
start_time, end_time = \
_get_recording_start_and_end_times(station, date)
duration = (end_time - start_time).total_seconds()
length = int(round(duration * sample_rate))
# Recompute end time from recording start time, length, and
# sample rate so it is consistent with our definition (i.e. so
# that it is the time of the last sample of the recording rather
# than the time of the sample after that).
end_time = signal_utils.get_end_time(start_time, length, sample_rate)
creation_time = time_utils.get_utc_now()
recording = Recording.objects.create(
station=station,
recorder=recorder,
num_channels=_NUM_RECORDING_CHANNELS,
length=length,
sample_rate=sample_rate,
start_time=start_time,
end_time=end_time,
creation_time=creation_time,
creating_job=self._job)
recording_channel = RecordingChannel.objects.create(
recording=recording,
channel_num=_RECORDING_CHANNEL_NUM,
recorder_channel_num=_RECORDER_CHANNEL_NUM,
mic_output=mic_output)
return recording_channel
def _add_recordings(source_archive_dir_path):
processing_start_time = time.time()
channel_recordings = _get_channel_recordings(source_archive_dir_path)
# Partition recording channels into sets that belong to the same
# recording. The result is a mapping from (station, start_time)
# pairs (with each pair representing a recording) to sets of
# (recording_channel, mic_output) pairs.
channel_info_sets = defaultdict(set)
for r in channel_recordings:
station, mic_output, recorder_input = \
_get_recording_channel_info(r.station.name)
channel_info_sets[(station, r.start_time)].add(
(r, mic_output, recorder_input))
keys = sorted(channel_info_sets.keys(), key=lambda p: (p[0].name, p[1]))
num_recordings = len(keys)
print('Adding recordings to destination archive...')
for i, (station, start_time) in enumerate(keys):
if i % _RECORDING_PROGRESS_PERIOD == 0 and i != 0:
print('Added {} of {} recordings...'.format(i, num_recordings))
channel_infos = list(channel_info_sets[(station, start_time)])
channel_infos.sort(key=lambda i: i[2].channel_num)
r, _, recorder_input = channel_infos[0]
# Extend the length of the recording artificially by two seconds.
# We do this because we have encountered cases where clips that
# were extracted from recordings are stamped with times that are
# up to a second past the end of the recording. This script
# rejects clips that don't seem to belong to any known recording,
# but we want to retain these. In cases where we have the recordings
# from which the clips were extracted, we can later find the precise
# start indices of the clips in the recordings, and correct both
# the clip start times and the recording durations in the archive.
length = r.length + 2 * r.sample_rate
r = OldRecording(r.station, r.start_time, length, r.sample_rate)
recorder = recorder_input.device
num_channels = len(channel_infos)
span = (r.length - 1) / r.sample_rate
end_time = r.start_time + datetime.timedelta(seconds=span)
creation_time = time_utils.get_utc_now()
recording = Recording(
station=station,
recorder=recorder,
num_channels=num_channels,
length=r.length,
sample_rate=r.sample_rate,
start_time=r.start_time,
end_time=end_time,
creation_time=creation_time,
creating_job=None)
recording.save()
if _SHOW_RECORDINGS:
# print('Recording {} {}'.format(i, str(recording)))
print('Recording {} {} / {} / {} / {} / {} / {}'.format(
i, station.name, r.start_time, r.length, r.sample_rate,
r.length / r.sample_rate, end_time))
for _, mic_output, recorder_input in channel_infos:
# We assume here that the recording channel number is the
# same as the recorder channel number.
channel_num = recorder_input.channel_num
channel = RecordingChannel(
recording=recording,
channel_num=channel_num,
recorder_channel_num=channel_num,
mic_output=mic_output)
channel.save()
if _SHOW_RECORDINGS:
print(' Channel {} {}'.format(channel_num, mic_output.name))
elapsed_time = time.time() - processing_start_time
rate = num_recordings / elapsed_time
print((
'Added a total of {} recordings in {:.1f} seconds, an average of '
'{:.1f} recordings per second.').format(len(keys), elapsed_time, rate))
def _create_clips(self, threshold):
if not _CREATE_CLIPS:
return
# TODO: Find out exactly what database queries are
# executed during detection (ideally, record the sequence
# of queries) to see if database interaction could be
# made more efficient, for example with a cache.
recording_channel = self._recording_channel
detector_model = self._detector_model
start_offset = self._file_start_index + self._interval_start_index
creation_time = time_utils.get_utc_now()
create_clip_files = self._create_clip_files
if self._defer_clip_creation:
for start_index, length, annotations in self._clips:
start_index += start_offset
clip = [
recording_channel.id, start_index, length, creation_time,
self._job.id, detector_model.id, annotations]
self._deferred_clips.append(clip)
else:
# database writes not deferred
station = self._recording.station
sample_rate = self._recording.sample_rate
mic_output = recording_channel.mic_output
if create_clip_files:
clips = []
# Create database records for current batch of clips in one
# database transaction.
# trans_start_time = time.time()
try:
with archive_lock.atomic(), transaction.atomic():
for start_index, length, annotations in self._clips:
try:
# Get clip start time as a `datetime`.
start_index += start_offset
start_delta = datetime.timedelta(
seconds=start_index / sample_rate)
start_time = \
self._recording.start_time + start_delta
end_time = signal_utils.get_end_time(
start_time, length, sample_rate)
# It would be nice to use Django's
# `bulk_create` here, but unfortunately that
# won't automatically set clip IDs for us
# except (as of this writing) if we're using
# PostgreSQL.
clip = Clip.objects.create(
station=station,
mic_output=mic_output,
recording_channel=recording_channel,
start_index=start_index,
length=length,
sample_rate=sample_rate,
start_time=start_time,
end_time=end_time,
date=station.get_night(start_time),
creation_time=creation_time,
creating_user=None,
creating_job=self._job,
creating_processor=detector_model
)
if create_clip_files:
# Save clip so we can create clip file
# outside of transaction.
clips.append(clip)
if annotations is not None:
for name, value in annotations.items():
annotation_info = \
self._get_annotation_info(name)
model_utils.annotate_clip(
clip, annotation_info, str(value),
creation_time=creation_time,
creating_user=None,
creating_job=self._job,
creating_processor=detector_model)
except Exception as e:
duration = signal_utils.get_duration(
length, sample_rate)
clip_string = Clip.get_string(
station.name, mic_output.name,
detector_model.name, start_time, duration)
raise _ClipCreationError(clip_string, e)
# trans_end_time = time.time()
# self._num_transactions += 1
# self._total_transactions_duration += \
# trans_end_time - trans_start_time
except _ClipCreationError as e:
batch_size = len(self._clips)
self._num_database_failures += batch_size
if batch_size == 1:
prefix = 'Clip'
else:
prefix = 'All {} clips in this batch'.format(
batch_size)
self._logger.error((
' Attempt to create clip {} failed with '
'message: {} {} will be ignored.').format(
clip_string, str(e.wrapped_exception), prefix))
else:
# clip creation succeeded
if create_clip_files:
for clip in clips:
try:
self._clip_manager.create_audio_file(clip)
except Exception as e:
self._num_file_failures += 1
self._logger.error((
' Attempt to create audio file '
'for clip {} failed with message: {} Clip '
'database record was still created.').format(
str(clip), str(e)))
self._clips = []
def run_job(job_info):
"""
Runs a job in a new process.
This function is executed by the Vesper job manager each time it
starts a new job. The function is executed in a new process, called
the *main job process* of the job.
The function sets up Django and configures the root logger for the
main job process, constructs the command to be executed, and invokes
the command's `execute` method. Logging is shut down after that method
returns.
Parameters:
job_info : `Bunch`
information pertaining to the new job.
The information includes the command specification for the
new job, the ID of the Django Job model instance for the job,
and the stop event for the job.
The information includes the ID of the Django job model
instance rather than the instance itself so that the job
info can be unpickled in the new process without first
setting up Django.
This object is *not* of type `vesper.command.job_info.JobInfo`,
which contains somewhat different (though overlapping)
information. This function invokes the `execute` method of the
command of the new job with an argument of type
`vesper.command.job_info.JobInfo`.
"""
# Set up Django for the main job process. We must do this before we try
# to use anything Django (e.g. the ORM) in the new process. We perform
# the setup inside of this function rather than at the top of this module
# so that it happens only in a new job process, and not in a parent
# process that is importing this module merely to be able to execute
# this function. In the latter case Django will already have been set up
# in the importing process if it is needed, and it would be redundant
# and potentially problematic to perform the setup again.
django_utils.set_up_django()
# These imports are here rather than at the top of this module so
# they will be executed after Django is set up in the main job process.
# from django.conf import settings as django_settings
from vesper.django.app.models import Job
import vesper.util.archive_lock as archive_lock
# Set the archive lock for this process. The lock is provided to
# this process by its creator.
archive_lock.set_lock(job_info.archive_lock)
# Get the Django model instance for this job.
job = Job.objects.get(id=job_info.job_id)
# Start up logging.
# level = logging.DEBUG if django_settings.DEBUG else logging.INFO
level = logging.INFO
logging_manager = JobLoggingManager(job, level)
logging_manager.start_up_logging()
# Configure root logger for the main job process.
logger = logging.getLogger()
logging_config = logging_manager.logging_config
JobLoggingManager.configure_logger(logger, logging_config)
try:
# Mark job as running.
job.start_time = time_utils.get_utc_now()
job.status = 'Running'
with archive_lock.atomic():
job.save()
# Create command from command spec.
command = _create_command(job_info.command_spec)
prefix = 'Job started for command "{}"'.format(command.name)
if len(command.arguments) == 0:
logger.info('{} with no arguments.'.format(prefix))
else:
logger.info('{} with arguments:'.format(prefix))
# Log command arguments JSON.
args = json.dumps(command.arguments,
sort_keys=False,
indent=4,
cls=_CommandArgsEncoder)
lines = args.splitlines()
for line in lines:
logger.info(' {}'.format(line))
# Execute command.
info = JobInfo(job_info.job_id, logging_config, job_info.stop_event)
complete = command.execute(info)
except Exception:
# Update job status and log error message
job.end_time = time_utils.get_utc_now()
job.status = 'Failed'
with archive_lock.atomic():
job.save()
logger.error('Job failed with an exception. See traceback below.\n' +
traceback.format_exc())
else:
# Update job status and log final message.
status = 'Completed' if complete else 'Interrupted'
job.end_time = time_utils.get_utc_now()
job.status = status
with archive_lock.atomic():
job.save()
logger.info('Job {}.'.format(status.lower()))
finally:
# At one point this `finally` clause attempted to log a final
# message that included counts of the critical, error, and
# warning log messages that had been logged for this job.
# This didn't work, however, due to a race condition. In
# particular, there seemed to be no way for this thread to
# ensure that all log records other than the one that it was
# preparing had been processed by the logging thread before
# this thread read the record counts. If all of the log
# records had not been processed, the counts were inaccurate.
#
# In the future we may add record count fields to the Django
# `Job` class so that accurate log record counts can be
# reported in log displays. See record counts handler
# TODO in `job_logging_manager` module for more detail.
logging_manager.shut_down_logging()
def run_job(job_info):
"""
Runs a job in a new process.
This function is executed by the Vesper job manager each time it
starts a new job. The function is executed in a new process, called
the *main job process* of the job.
The function sets up Django and configures the root logger for the
main job process, constructs the command to be executed, and invokes
the command's `execute` method. Logging is shut down after that method
returns.
Parameters:
job_info : `Bunch`
information pertaining to the new job.
The information includes the command specification for the
new job, the ID of the Django Job model instance for the job,
and the stop event for the job.
The information includes the ID of the Django job model
instance rather than the instance itself so that the job
info can be unpickled in the new process without first
setting up Django.
This object is *not* of type `vesper.command.job_info.JobInfo`,
which contains somewhat different (though overlapping)
information. This function invokes the `execute` method of the
command of the new job with an argument of type
`vesper.command.job_info.JobInfo`.
"""
# Set up Django for the main job process. We must do this before we try
# to use anything Django (e.g. the ORM) in the new process. We perform
# the setup inside of this function rather than at the top of this module
# so that it happens only in a new job process, and not in a parent
# process that is importing this module merely to be able to execute
# this function. In the latter case Django will already have been set up
# in the importing process if it is needed, and it would be redundant
# and potentially problematic to perform the setup again.
django_utils.set_up_django()
# These imports are here rather than at the top of this module so
# they will be executed after Django is set up in the main job process.
# from django.conf import settings as django_settings
from vesper.django.app.models import Job
import vesper.util.archive_lock as archive_lock
# Set the archive lock for this process. The lock is provided to
# this process by its creator.
archive_lock.set_lock(job_info.archive_lock)
# Get the Django model instance for this job.
job = Job.objects.get(id=job_info.job_id)
# Start up logging.
# level = logging.DEBUG if django_settings.DEBUG else logging.INFO
level = logging.INFO
logging_manager = JobLoggingManager(job, level)
logging_manager.start_up_logging()
# Configure root logger for the main job process.
logger = logging.getLogger()
logging_config = logging_manager.logging_config
JobLoggingManager.configure_logger(logger, logging_config)
try:
# Mark job as running.
job.start_time = time_utils.get_utc_now()
job.status = 'Running'
with archive_lock.atomic():
job.save()
# Create command from command spec.
command = _create_command(job_info.command_spec)
prefix = 'Job started for command "{}"'.format(command.name)
if len(command.arguments) == 0:
logger.info('{} with no arguments.'.format(prefix))
else:
logger.info('{} with arguments:'.format(prefix))
# Log command arguments JSON.
args = json.dumps(
command.arguments, sort_keys=False, indent=4,
cls=_CommandArgsEncoder)
lines = args.splitlines()
for line in lines:
logger.info(' {}'.format(line))
# Execute command.
info = JobInfo(job_info.job_id, logging_config, job_info.stop_event)
complete = command.execute(info)
except Exception:
# Update job status and log error message
job.end_time = time_utils.get_utc_now()
job.status = 'Raised Exception'
with archive_lock.atomic():
job.save()
logger.error(
'Job raised exception. See traceback below.\n' +
traceback.format_exc())
else:
# Update job status and log final message.
status = 'Complete' if complete else 'Interrupted'
job.end_time = time_utils.get_utc_now()
job.status = status
with archive_lock.atomic():
job.save()
logger.info('Job {}.'.format(status.lower()))
finally:
# At one point this `finally` clause attempted to log a final
# message that included counts of the critical, error, and
# warning log messages that had been logged for this job.
# This didn't work, however, due to a race condition. In
# particular, there seemed to be no way for this thread to
# ensure that all log records other than the one that it was
# preparing had been processed by the logging thread before
# this thread read the record counts. If all of the log
# records had not been processed, the counts were inaccurate.
#
# In the future we may add record count fields to the Django
# `Job` class so that accurate log record counts can be
# reported in log displays. See record counts handler
# TODO in `job_logging_manager` module for more detail.
logging_manager.shut_down_logging()
def _add_clips_aux(clips, night, detectors, annotation_infos):
global _clip_count
annotation_info = \
_get_annotation_info('Classification', annotation_infos)
num_added = 0
num_rejected = 0
num_excluded = 0
for c in clips:
_clip_count += 1
if _clip_count % _PAUSE_CHECK_PERIOD == 0:
_pause_if_indicated()
if not _include_clip(c):
num_excluded += 1
continue
file_path = c.file_path
if _CLIP_FILES_AVAILABLE and not (os.path.exists(file_path)):
print(
'Could not find clip file "{}". Clip will be ignored.'.format(
file_path))
num_rejected += 1
continue
try:
channel = _get_clip_recording_channel(c)
except Exception:
print((
'Could not get recording channel for clip "{}". '
'Clip will be ignored').format(file_path))
num_rejected += 1
continue
try:
detector = _get_detector(c, detectors)
except ValueError:
print((
'Could not get detector "{}" for clip "{}". '
'Clip will be ignored.').format(c.detector_name, file_path))
num_rejected += 1
continue
# The code between here and the return statement used to be a
# single database transaction.
# with transaction.atomic():
recording = channel.recording
station = recording.station
mic_output = channel.mic_output
sample_rate = recording.sample_rate
if _CLIP_FILES_AVAILABLE:
try:
length = audio_file_utils.get_wave_file_info(file_path).length
except Exception as e:
print((
'Could not read audio file info for clip "{}". '
'Error message was: {}. '
'Clip will be ignored.').format(file_path, str(e)))
num_rejected += 1
continue
else:
length = c.duration * sample_rate
start_time = c.start_time
span = (length - 1) / sample_rate
end_time = start_time + datetime.timedelta(seconds=span)
creation_time = time_utils.get_utc_now()
clip = Clip(
station=station,
mic_output=mic_output,
recording_channel=channel,
start_index=None,
length=length,
sample_rate=sample_rate,
start_time=start_time,
end_time=end_time,
date=night,
creation_time=creation_time,
creating_processor=detector)
if _SHOW_CLIPS:
print('Clip', _clip_count, clip)
clip.save()
if _CLIP_FILES_AVAILABLE and _COPY_CLIP_FILES:
try:
_copy_clip_audio_file(file_path, clip)
except Exception as e:
print((
'Copy failed for clip file "{}". '
'Error message was: {}. '
'Clip will be ignored.').format(file_path, str(e)))
num_rejected += 1
continue
if c.clip_class_name is not None:
# TODO: When this script becomes an importer, add the
# creating job to the following.
model_utils.annotate_clip(
clip, annotation_info, c.clip_class_name)
num_added += 1
return (num_added, num_rejected, num_excluded)
def main():
center_index_info = AnnotationInfo.objects.get(name='Call Center Index')
center_freq_info = AnnotationInfo.objects.get(name='Call Center Freq')
classification_info = AnnotationInfo.objects.get(name='Classification')
annotation_user = User.objects.get(username='******')
for recording in Recording.objects.all():
print('processing recording {}...'.format(str(recording)))
# Get field values that are the same for all clips of this recording.
station = recording.station
recording_channel = recording.channels.get()
mic_output = recording_channel.mic_output
sample_rate = recording.sample_rate
length = int(round(CLIP_DURATION * sample_rate))
night = station.get_night(recording.start_time)
detector = Processor.objects.get(name='BirdVox-70k')
clip_data = get_recording_clip_data(recording)
center_indices = set()
for center_index, center_freq in clip_data:
# Some call center indices in the input data are
# duplicates, so that clip start indices computed
# from them violate a Vesper archive database
# uniqueness constraint. We bump duplicate indices
# by one until they are unique to resolve the issue.
while center_index in center_indices:
center_index += 1
center_indices.add(center_index)
start_index = center_index - length // 2
start_offset = start_index / sample_rate
start_time_delta = datetime.timedelta(seconds=start_offset)
start_time = recording.start_time + start_time_delta
end_time = signal_utils.get_end_time(start_time, length,
sample_rate)
creation_time = time_utils.get_utc_now()
try:
clip = Clip.objects.create(station=station,
mic_output=mic_output,
recording_channel=recording_channel,
start_index=start_index,
length=length,
sample_rate=sample_rate,
start_time=start_time,
end_time=end_time,
date=night,
creation_time=creation_time,
creating_processor=detector)
except IntegrityError:
print(('Duplicate clip with center index {}. '
'Clip will be ignored.').format(center_index),
file=sys.stderr)
else:
# Add classification annotation.
classification = get_classification(center_freq)
StringAnnotation.objects.create(clip=clip,
info=classification_info,
value=classification,
creation_time=creation_time,
creating_user=annotation_user)
if classification.startswith('Call.'):
# Add center time annotation.
StringAnnotation.objects.create(
clip=clip,
info=center_index_info,
value=str(center_index),
creation_time=creation_time,
creating_user=annotation_user)
# Add center frequency annotation.
StringAnnotation.objects.create(
clip=clip,
info=center_freq_info,
value=str(center_freq),
creation_time=creation_time,
creating_user=annotation_user)
def _create_clips(self, threshold):
if not _CREATE_CLIPS:
return
# TODO: Find out exactly what database queries are
# executed during detection (ideally, record the sequence
# of queries) to see if database interaction could be
# made more efficient, for example with a cache.
recording_channel = self._recording_channel
detector_model = self._detector_model
start_offset = self._file_start_index + self._interval_start_index
creation_time = time_utils.get_utc_now()
create_clip_files = self._create_clip_files
if self._defer_clip_creation:
for start_index, length, annotations in self._clips:
start_index += start_offset
clip = [
recording_channel.id, start_index, length, creation_time,
self._job.id, detector_model.id, annotations
]
self._deferred_clips.append(clip)
else:
# database writes not deferred
station = self._recording.station
sample_rate = self._recording.sample_rate
mic_output = recording_channel.mic_output
if create_clip_files:
clips = []
# Create database records for current batch of clips in one
# database transaction.
# trans_start_time = time.time()
try:
with archive_lock.atomic(), transaction.atomic():
for start_index, length, annotations in self._clips:
# Get clip start time as a `datetime`.
start_index += start_offset
start_delta = datetime.timedelta(seconds=start_index /
sample_rate)
start_time = \
self._recording.start_time + start_delta
end_time = signal_utils.get_end_time(
start_time, length, sample_rate)
try:
# It would be nice to use Django's
# `bulk_create` here, but unfortunately that
# won't automatically set clip IDs for us
# except (as of this writing) if we're using
# PostgreSQL.
clip = Clip.objects.create(
station=station,
mic_output=mic_output,
recording_channel=recording_channel,
start_index=start_index,
length=length,
sample_rate=sample_rate,
start_time=start_time,
end_time=end_time,
date=station.get_night(start_time),
creation_time=creation_time,
creating_user=None,
creating_job=self._job,
creating_processor=detector_model)
if create_clip_files:
# Save clip so we can create clip file
# outside of transaction.
clips.append(clip)
if annotations is not None:
for name, value in annotations.items():
annotation_info = \
self._get_annotation_info(name)
model_utils.annotate_clip(
clip,
annotation_info,
str(value),
creation_time=creation_time,
creating_user=None,
creating_job=self._job,
creating_processor=detector_model)
except Exception as e:
# Note that it's important not to perform any
# database queries here. If the database raised
# the exception, we have to wait until we're
# outside of the transaction to query the
# database again.
raise _ClipCreationError(e)
# trans_end_time = time.time()
# self._num_transactions += 1
# self._total_transactions_duration += \
# trans_end_time - trans_start_time
except _ClipCreationError as e:
duration = signal_utils.get_duration(length, sample_rate)
clip_string = Clip.get_string(station.name, mic_output.name,
detector_model.name, start_time,
duration)
batch_size = len(self._clips)
self._num_database_failures += batch_size
if batch_size == 1:
prefix = 'Clip'
else:
prefix = f'All {batch_size} clips in this batch'
self._logger.error(
f' Attempt to create clip {clip_string} '
f'failed with message: {str(e.wrapped_exception)}. '
f'{prefix} will be ignored.')
else:
# clip creation succeeded
if create_clip_files:
for clip in clips:
try:
self._clip_manager.create_audio_file(clip)
except Exception as e:
self._num_file_failures += 1
self._logger.error(
(' Attempt to create audio file '
'for clip {} failed with message: {} Clip '
'database record was still created.').format(
str(clip), str(e)))
self._clips = []