def log_message(msg, level='info', boldtype=False, colourtext='black'):
bold = boldtype
colour = colourtext
if level == 'debug':
user_logger.debug(str(msg))
elif level == 'info':
user_logger.info(str(msg))
elif level == 'warn':
user_logger.warn(str(msg))
colour = 'orange'
bold = True
elif level == 'error':
user_logger.error(str(msg))
colour = 'red'
bold = True
if not bold and colour == 'black':
email_msg.append(timestamp() + level.upper() + ' ' + str(msg))
elif colour != 'black' and not(bold):
email_msg.append('<font color="{colour}">{timestamp} {level} {msg}</font>'.format(
colour=colour, timestamp=timestamp(), level=level.upper(), msg=str(msg)))
else:
email_msg.append('<font color="{colour}"><b>{timestamp} {level} {msg}</b></font>'.format(
colour=colour, timestamp=timestamp(), level=level.upper(), msg=str(msg)))
def start_ants(ants, dry_run=False):
if not dry_run:
user_logger.info("Setting Antennae Mode to 'STOP', Powering on Antenna Drives.")
ants.set_sampling_strategy('mode', 'event')
ants.req.mode('STOP')
try:
ants.wait('mode', 'STOP', timeout=12)
except Exception as err:
#user_logger.warn(err)
user_logger.warn("not all antennas were in 'STOP' mode.")
def _katcp_reply_(dig_katcp_replies):
""" KATCP timestamp return logs"""
ant_ts_list = []
for ant in sorted(dig_katcp_replies):
reply, informs = dig_katcp_replies[ant]
if reply.reply_ok():
ant_ts_list.append(_nd_log_msg_(ant, reply, informs))
else:
msg = ('Noise diode request failed on ant {}: {} ({})'.format(
ant, reply.arguments, informs))
user_logger.warn(msg)
# assume all ND timestamps similar and return average
return np.mean(ant_ts_list) if ant_ts_list else np.nan
def _katcp_reply_(dig_katcp_replies):
""" KATCP timestamp return logs"""
ant_ts_list = []
for ant in sorted(dig_katcp_replies):
reply, informs = dig_katcp_replies[ant]
if reply.reply_ok():
ant_ts_list.append(_nd_log_msg_(ant, reply, informs))
else:
msg = 'Unexpected noise diode reply from ant {}'.format(ant)
user_logger.warn(msg)
user_logger.debug('DEBUG: {}'.format(reply.arguments))
continue
# assume all ND timestamps similar and return average
return np.mean(ant_ts_list)
def point_ants(ants, dry_run=False):
ants.set_sampling_strategy('lock', 'event')
ant_diff = ['m057', 'm058', 'm059']
for ant in ants:
if ant.name in ant_diff:
user_logger.info('slewing %s to azim: 30, elev: 18' % ant.name)
ant.req.target_azel(30, 18)
else:
user_logger.info('slewing %s to azim: 217, elev: 18' % (ant.name))
ant.req.target_azel(217, 18)
ant.req.mode('POINT')
if not dry_run:
try:
ants.wait('lock', True, timeout=300)
user_logger.info('target reached')
except Exception:
not_locked = []
not_locked = [ant.name for ant in ants if ant.sensor.lock.get_value() == False]
user_logger.warn('{} did not reach target'.format(', '.join(not_locked)))
time.sleep(3)
ants.req.mode('STOP')
def run_observation(opts, kat):
"""Extract control and observation information provided in observation file."""
obs_plan_params = opts.obs_plan_params
# remove observation specific instructions housed in YAML file
del opts.obs_plan_params
# set up duration periods for observation control
obs_duration = -1
if "durations" in obs_plan_params:
if "obs_duration" in obs_plan_params["durations"]:
obs_duration = obs_plan_params["durations"]["obs_duration"]
# check for nonsensical observation duration setting
if abs(obs_duration) < 1e-5:
user_logger.error(
"Unexpected value: obs_duration: {}".format(obs_duration))
return
# TODO: the description requirement in sessions should be re-evaluated
# since the schedule block has the description
# Description argument in instruction_set should be retired, but is
# needed by sessions
# Assign proposal_description if available, else create a dummy
if "description" not in vars(opts):
session_opts = vars(opts)
description = "Observation run"
if "proposal_description" in vars(opts):
description = opts.proposal_description
session_opts["description"] = description
nr_obs_loops = len(obs_plan_params["observation_loop"])
with start_session(kat.array, **vars(opts)) as session:
session.standard_setup(**vars(opts))
# Each observation loop contains a number of observation cycles over LST ranges
# For a single observation loop, only a start LST and duration is required
# Target observation loop
observation_timer = time.time()
for obs_cntr, observation_cycle in enumerate(
obs_plan_params["observation_loop"]):
if nr_obs_loops > 1:
user_logger.info("Observation loop {} of {}.".format(
obs_cntr + 1, nr_obs_loops))
user_logger.info("Loop LST range {}.".format(
observation_cycle["LST"]))
# Unpack all target information
if not ("target_list" in observation_cycle.keys()):
user_logger.error(
"No targets provided - stopping script instead of hanging around"
)
continue
obs_targets = observation_cycle["target_list"]
target_list = obs_targets["target"].tolist()
# build katpoint catalogues for tidy handling of targets
catalogue = collect_targets(kat.array, target_list)
obs_tags = []
for tgt in obs_targets:
# catalogue names are no longer unique
name = tgt["name"]
# add tag evaluation to identify catalogue targets
tags = tgt["target"].split(",")[1].strip()
for cat_tgt in catalogue:
if name == cat_tgt.name:
if ("special" in cat_tgt.tags
or "xephem" in cat_tgt.tags
or tags == " ".join(cat_tgt.tags)):
tgt["target"] = cat_tgt
obs_tags.extend(cat_tgt.tags)
break
obs_tags = list(set(obs_tags))
cal_tags = [tag for tag in obs_tags if tag[-3:] == "cal"]
# observer object handle to track the observation timing in a more user
# friendly way
# observer = catalogue._antenna.observer
ref_antenna = catalogue.antenna
observer = ref_antenna.observer
start_datetime = timestamp2datetime(time.time())
observer.date = ephem.Date(start_datetime)
user_logger.trace("TRACE: requested start time "
"({}) {}".format(
datetime2timestamp(start_datetime),
start_datetime))
user_logger.trace("TRACE: observer at start\n {}".format(observer))
# Only observe targets in valid LST range
if nr_obs_loops > 1 and obs_cntr < nr_obs_loops - 1:
[start_lst, end_lst] = get_lst(observation_cycle["LST"],
multi_loop=True)
if end_lst is None:
# for multi loop the end lst is required
raise RuntimeError(
'Multi-loop observations require end LST times')
next_obs_plan = obs_plan_params["observation_loop"][obs_cntr +
1]
[next_start_lst, next_end_lst] = get_lst(next_obs_plan["LST"])
user_logger.trace("TRACE: current LST range {}-{}".format(
ephem.hours(str(start_lst)), ephem.hours(str(end_lst))))
user_logger.trace("TRACE: next LST range {}-{}".format(
ephem.hours(str(next_start_lst)),
ephem.hours(str(next_end_lst))))
else:
next_start_lst = None
next_end_lst = None
[start_lst, end_lst] = get_lst(observation_cycle["LST"])
# Verify the observation is in a valid LST range
# and that it is worth while continuing with the observation
# Do not use float() values, ephem.hours does not convert as
# expected
local_lst = observer.sidereal_time()
user_logger.trace("TRACE: Local LST {}".format(
ephem.hours(local_lst)))
# Only observe targets in current LST range
log_msg = "Local LST outside LST range {}-{}".format(
ephem.hours(str(start_lst)), ephem.hours(str(end_lst)))
if float(start_lst) < end_lst:
# lst ends before midnight
if not _same_day(start_lst, end_lst, local_lst):
if obs_cntr < nr_obs_loops - 1:
user_logger.info(log_msg)
else:
user_logger.error(log_msg)
continue
else:
# lst ends after midnight
if _next_day(start_lst, end_lst, local_lst):
if obs_cntr < nr_obs_loops - 1:
user_logger.info(log_msg)
else:
user_logger.error(log_msg)
continue
# Verify that it is worth while continuing with the observation
# The filter functions uses the current time as timestamps
# and thus incorrectly set the simulation timestamp
if not kat.array.dry_run:
# Quit early if there are no sources to observe
if len(catalogue.filter(el_limit_deg=opts.horizon)) == 0:
raise NoTargetsUpError(
"No targets are currently visible - "
"please re-run the script later")
# Quit early if the observation requires all targets to be visible
if opts.all_up and (len(
catalogue.filter(el_limit_deg=opts.horizon)) !=
len(catalogue)):
raise NotAllTargetsUpError(
"Not all targets are currently visible - please re-run the script"
"with --visibility for information")
# List sources and their associated functions from observation tags
not_cals_filter_list = []
for cal_type in cal_tags:
not_cals_filter_list.append("~{}".format(cal_type))
cal_array = [cal.name for cal in catalogue.filter(cal_type)]
if len(cal_array) < 1:
continue # do not display empty tags
user_logger.info("{} calibrators are {}".format(
str.upper(cal_type[:-3]), cal_array))
user_logger.info("Observation targets are [{}]".format(", ".join([
repr(target.name)
for target in catalogue.filter(not_cals_filter_list)
])))
# TODO: setup of noise diode pattern should be moved to sessions
# so it happens in the line above
if "noise_diode" in obs_plan_params:
nd_setup = obs_plan_params["noise_diode"]
nd_lead = nd_setup.get('lead_time')
# Set noise diode period to multiple of correlator integration time.
if not kat.array.dry_run:
cbf_corr = session.cbf.correlator
dump_period = cbf_corr.sensor.int_time.get_value()
else:
dump_period = 0.5 # sec
user_logger.debug(
'DEBUG: Correlator integration time {} [sec]'.format(
dump_period))
if "cycle_len" in nd_setup:
if (nd_setup['cycle_len'] >= dump_period):
cycle_len_frac = nd_setup['cycle_len'] // dump_period
nd_setup['cycle_len'] = cycle_len_frac * dump_period
msg = ('Set noise diode period '
'to multiple of correlator dump period: '
'cycle length = {} [sec]'.format(
nd_setup['cycle_len']))
else:
msg = ('Requested cycle length {}s '
'< correlator dump period {}s, '
'ND not synchronised with dump edge'.format(
nd_setup['cycle_len'], dump_period))
user_logger.warning(msg)
noisediode.pattern(
kat.array,
nd_setup,
lead_time=nd_lead,
)
# Adding explicit init after "Capture-init failed" exception was
# encountered
session.capture_init()
user_logger.debug("DEBUG: Initialise capture start with timestamp "
"{} ({})".format(int(time.time()),
timestamp2datetime(
time.time())))
# Go to first target before starting capture
user_logger.info("Slewing to first target")
observe(session, ref_antenna, obs_targets[0], slewonly=True)
# Only start capturing once we are on target
session.capture_start()
user_logger.trace("TRACE: capture start time after slew "
"({}) {}".format(time.time(),
timestamp2datetime(
time.time())))
user_logger.trace(
"TRACE: observer after slew\n {}".format(observer))
done = False
sanity_cntr = 0
while not done:
# small errors can cause an infinite loop here
# preventing infinite loops
sanity_cntr += 1
if sanity_cntr > 100000:
user_logger.error("While limit counter has reached {}, "
"exiting".format(sanity_cntr))
break
# Cycle through target list in order listed
targets_visible = False
time_remaining = obs_duration
observation_timer = time.time()
for tgt_cntr, target in enumerate(obs_targets):
katpt_target = target["target"]
user_logger.debug("DEBUG: {} {}".format(tgt_cntr, target))
user_logger.trace(
"TRACE: initial observer for target\n {}".format(
observer))
# check target visible before doing anything
# make sure the target would be visible for the entire duration
target_duration = target['duration']
visible = True
if type(katpt_target.body) is ephem.FixedBody:
visible = above_horizon(
target=katpt_target.body.copy(),
observer=observer.copy(),
horizon=opts.horizon,
duration=target_duration)
if not visible:
show_horizon_status = True
# warning for cadence targets only when they are due
if (target["cadence"] > 0
and target["last_observed"] is not None):
delta_time = time.time() - target["last_observed"]
show_horizon_status = delta_time >= target[
"cadence"]
if show_horizon_status:
user_logger.warn("Target {} below {} deg horizon, "
"continuing".format(
target["name"], opts.horizon))
continue
user_logger.trace(
"TRACE: observer after horizon check\n {}".format(
observer))
# check and observe all targets with cadences
while_cntr = 0
cadence_targets = list(obs_targets)
while True:
tgt = cadence_target(cadence_targets)
if not tgt:
break
# check enough time remaining to continue
if obs_duration > 0 and time_remaining < tgt[
"duration"]:
done = True
break
# check target visible before doing anything
user_logger.trace("TRACE: cadence"
"target\n{}\n {}".format(
tgt, catalogue[tgt["name"]]))
user_logger.trace("TRACE: initial observer for cadence"
"target\n {}".format(observer))
user_logger.trace(
"TRACE: observer before track\n {}".format(
observer))
user_logger.trace(
"TRACE: target observation # {} last observed "
"{}".format(tgt["obs_cntr"], tgt["last_observed"]))
cat_target = catalogue[tgt["name"]]
if above_horizon(
target=cat_target.body,
observer=cat_target.antenna.observer.copy(),
horizon=opts.horizon,
duration=tgt["duration"]):
if observe(session, ref_antenna, tgt,
**obs_plan_params):
targets_visible += True
tgt["obs_cntr"] += 1
tgt["last_observed"] = time.time()
else:
# target not visibile to sessions anymore
cadence_targets.remove(tgt)
user_logger.trace(
"TRACE: observer after track\n {}".format(
observer))
user_logger.trace(
"TRACE: target observation # {} last observed "
"{}".format(tgt["obs_cntr"],
tgt["last_observed"]))
else:
cadence_targets.remove(tgt)
while_cntr += 1
if while_cntr > len(obs_targets):
break
if done:
break
user_logger.trace(
"TRACE: observer after cadence\n {}".format(observer))
# observe non cadence target
if target["cadence"] < 0:
user_logger.trace(
"TRACE: normal target\n {}".format(target))
user_logger.trace(
"TRACE: observer before track\n {}".format(
observer))
user_logger.trace("TRACE: ts before observe {}".format(
time.time()))
user_logger.trace("TRACE: target last "
"observed {}".format(
target["last_observed"]))
targets_visible += observe(session, ref_antenna,
target, **obs_plan_params)
user_logger.trace(
"TRACE: observer after track\n {}".format(
observer))
user_logger.trace("TRACE: ts after observe {}".format(
time.time()))
if targets_visible:
target["obs_cntr"] += 1
target["last_observed"] = time.time()
user_logger.trace(
"TRACE: target observation # {} last observed "
"{}".format(target["obs_cntr"],
target["last_observed"]))
user_logger.trace(
"TRACE: observer after track\n {}".format(
observer))
# loop continuation checks
delta_time = time.time() - session.start_time
user_logger.trace(
"TRACE: time elapsed {} sec".format(delta_time))
user_logger.trace(
"TRACE: total obs duration {} sec".format(
obs_duration))
if obs_duration > 0:
time_remaining = obs_duration - delta_time
user_logger.trace(
"TRACE: time remaining {} sec".format(
time_remaining))
next_target = obs_targets[(tgt_cntr + 1) %
len(obs_targets)]
user_logger.trace("TRACE: next target before cadence "
"check:\n{}".format(next_target))
# check if there is a cadence target that must be run
# instead of next target
for next_cadence_tgt_idx in range(
tgt_cntr + 1, len(obs_targets)):
next_cadence_target = obs_targets[
next_cadence_tgt_idx % len(obs_targets)]
if next_cadence_target["cadence"] > 0:
user_logger.trace(
"TRACE: time needed for next obs "
"{} sec".format(
next_cadence_target["cadence"]))
next_target = obs_targets[next_cadence_tgt_idx
% len(obs_targets)]
continue
user_logger.trace("TRACE: next target after cadence "
"check:\n{}".format(next_target))
user_logger.trace("TRACE: time needed for next obs "
"{} sec".format(
next_target["duration"]))
if (time_remaining < 1.0
or time_remaining < next_target["duration"]):
user_logger.info(
"Scheduled observation time lapsed - ending observation"
)
done = True
break
# during dry-run when sessions exit time is reset so will be incorrect
# outside the loop
observation_timer = time.time()
if obs_duration < 0:
user_logger.info(
"Observation list completed - ending observation")
done = True
# for multiple loop, check start lst of next loop
if next_start_lst is not None:
check_local_lst = observer.sidereal_time()
if (check_local_lst > next_start_lst) or (not _next_day(
next_start_lst, next_end_lst, check_local_lst)):
user_logger.info("Moving to next LST loop")
done = True
# End if there is nothing to do
if not targets_visible:
user_logger.warning(
"No more targets to observe - stopping script "
"instead of hanging around")
done = True
user_logger.trace("TRACE: observer at end\n {}".format(observer))
# display observation cycle statistics
# currently only available for single LST range observations
if nr_obs_loops < 2:
print
user_logger.info("Observation loop statistics")
total_obs_time = observation_timer - session.start_time
if obs_duration < 0:
user_logger.info("Single run through observation target list")
else:
user_logger.info("Desired observation time {:.2f} sec "
"({:.2f} min)".format(obs_duration,
obs_duration / 60.0))
user_logger.info("Total observation time {:.2f} sec "
"({:.2f} min)".format(total_obs_time,
total_obs_time / 60.0))
if len(obs_targets) > 0:
user_logger.info("Targets observed :")
for unique_target in np.unique(obs_targets["name"]):
cntrs = obs_targets[obs_targets["name"] ==
unique_target]["obs_cntr"]
durations = obs_targets[obs_targets["name"] ==
unique_target]["duration"]
if np.isnan(durations).any():
user_logger.info("{} observed {} times".format(
unique_target, np.sum(cntrs)))
else:
user_logger.info("{} observed for {} sec".format(
unique_target, np.sum(cntrs * durations)))
print