End of night shutdown improvements. (#407)

* End of night shutdown

A number of fixes and changes to account for situation when on valid
observations are found but we don't want to shut down the state machine.

* If scheduler has a list of `observations` then it `has_valid_observations`.
	which is True when starting.

Process:
* `scheduling` state calls `observatory.get_observation()`
* `get_observation` first checks if `has_valid_observations is False`
	if so it will reread the field list.
* `get_observation` either returns an observation or, if none found,
	calls `clear_available_observations`, making `has_valid_observations = False`.
* If no observation is returned to `scheduling` state, send to `parking` (then to `sleeping`).
* In `sleeping`, if `has_valid_observations is False` then sleep for an hour
	then try again (or shut down if `run_once` is specified).
  If `has_valid_observations is True` and it is safe and dark, shut down because
  	of unknown error.

Other changes:
* Remove `reread_fields_file` from dispatch scheduler as it is handled at
the `observatory` level by `observatory.get_observation`.
* Misc small fixes

* If no messaging then show `say` commands in log

* More shutdown cleanup

Note: This changes some of the state behavior for how parking and retrying
is handled. Housekeeping state will now only be called at the very end
of an observing run (either in the morning when unsafe or when too many
retry attempts). This moves some behavior from `sleeping` into `parked`.

* Fix the `should_retry` so it does not modify values
* Create a `reset_observing_run` method. Currenlty only resets number
of retries
* Other PR fixes

* Better name for private variable

* More updates

* Adding back the ability to reread fields file from the `get_observation`
call so that a user can do it manually rather than relying on an empty
observations list. But do it cleaner.
* Test the rereading of a fields with same entires only with a new higher
priority target
* Skip duplicate observation entries rather than stopping with assertion error.

* Removing a whole test as it seems to be a duplication of the one below
it for no reason and is also not testing what it says it should be testing.

* Clear fields_file when clearing observations
Explicitly clear observations for test of no targets

* Feedback from PR

* cleaning up code so parking logic is clearer

pocs/core.py

@@ -81,7 +81,8 @@ def __init__(
         self._interrupted = False
         self.force_reschedule = False
 
-        self._retry_attempts = 3
+        self._retry_attempts = kwargs.get('retry_attempts', 3)
+        self._obs_run_retries = self._retry_attempts
 
         self.status()
 
@@ -118,8 +119,7 @@ def has_messaging(self, value):
 
     @property
     def should_retry(self):
-        self._retry_attempts -= 1
-        return self._retry_attempts >= 0
+        return self._obs_run_retries >= 0
 
 
 ##################################################################################################
@@ -136,6 +136,7 @@ def initialize(self):
         """
 
         if not self._initialized:
+            self.logger.info('*' * 80)
             self.say("Initializing the system! Woohoo!")
 
             try:
@@ -176,6 +177,8 @@ def say(self, msg):
         Args:
             msg(str): Message to be sent
         """
+        if self.has_messaging is False:
+            self.logger.info('Unit says: {}', msg)
         self.send_message(msg, channel='PANCHAT')
 
     def send_message(self, msg, channel='POCS'):
@@ -260,6 +263,10 @@ def power_down(self):
             self._connected = False
             self.logger.info("Power down complete")
 
+    def reset_observing_run(self):
+        """Reset an observing run loop. """
+        self.logger.debug("Resetting observing run attempts")
+        self._obs_run_retries = self._retry_attempts
 
 ##################################################################################################
 # Safety Methods
@@ -422,7 +429,7 @@ def sleep(self, delay=2.5, with_status=True):
             time.sleep(delay)
 
     def wait_until_safe(self):
-        """ Waits until weather is safe
+        """ Waits until weather is safe.
 
         This will wait until a True value is returned from the safety check,
         blocking until then.

pocs/observatory.py

@@ -184,9 +184,17 @@ def get_observation(self, *args, **kwargs):
         """
 
         self.logger.debug("Getting observation for observatory")
+
+        # If observation list is empty or a reread is requested
+        if (self.scheduler.has_valid_observations is False or
+                kwargs.get('reread_fields_file', False)):
+            self.scheduler.read_field_list()
+
+        # This will set the `current_observation`
         self.scheduler.get_observation(*args, **kwargs)
 
-        if self.scheduler.current_observation is None:
+        if self.current_observation is None:
+            self.scheduler.clear_available_observations()
             raise error.NoObservation("No valid observations found")
 
         return self.current_observation

pocs/scheduler/dispatch.py

@@ -30,16 +30,13 @@ def get_observation(self, time=None, show_all=False, reread_fields_file=False):
                 defaults to time called
             show_all (bool, optional): Return all valid observations along with
                 merit value, defaults to False to only get top value
-            reread_fields_file (bool, optional): If targets file should be reread
-                before getting observation, default False.
 
         Returns:
             tuple or list: A tuple (or list of tuples) with name and score of ranked observations
         """
         if reread_fields_file:
             self.logger.debug("Rereading fields file")
-            # The setter method on `fields_file` will force a reread
-            self.fields_file = self.fields_file
+            self.read_field_list()
 
         if time is None:
             time = current_time()

pocs/scheduler/scheduler.py

@@ -66,11 +66,15 @@ def observations(self):
         Note:
             `read_field_list` is called if list is None
         """
-        if len(self._observations.keys()) == 0:
+        if self.has_valid_observations is False:
             self.read_field_list()
 
         return self._observations
 
+    @property
+    def has_valid_observations(self):
+        return len(self._observations.keys()) > 0
+
     @property
     def current_observation(self):
         """The observation that is currently selected by the scheduler
@@ -131,10 +135,7 @@ def fields_file(self):
 
     @fields_file.setter
     def fields_file(self, new_file):
-        # Clear out existing list and observations
-        self.current_observation = None
-        self._fields_list = None
-        self._observations = dict()
+        self.clear_available_observations()
 
         self._fields_file = new_file
         if new_file is not None:
@@ -161,9 +162,7 @@ def fields_list(self):
 
     @fields_list.setter
     def fields_list(self, new_list):
-        # Clear out existing list and observations
-        self._fields_file = None
-        self._observations = dict()
+        self.clear_available_observations()
 
         self._fields_list = new_list
         self.read_field_list()
@@ -172,6 +171,14 @@ def fields_list(self, new_list):
 # Methods
 ##########################################################################
 
+    def clear_available_observations(self):
+        """Reset the list of available observations"""
+        # Clear out existing list and observations
+        self.current_observation = None
+        self._fields_file = None
+        self._fields_list = None
+        self._observations = dict()
+
     def get_observation(self, time=None, show_all=False):
         """Get a valid observation
 
@@ -219,6 +226,7 @@ def add_observation(self, field_config):
         if 'exp_time' in field_config:
             field_config['exp_time'] = float(field_config['exp_time']) * u.second
 
+        self.logger.debug("Adding {} to scheduler", field_config['name'])
         field = Field(field_config['name'], field_config['position'])
 
         try:
@@ -256,7 +264,10 @@ def read_field_list(self):
 
         if self._fields_list is not None:
             for field_config in self._fields_list:
-                self.add_observation(field_config)
+                try:
+                    self.add_observation(field_config)
+                except AssertionError:
+                    self.logger.debug("Skipping duplicate field.")
 
 ##########################################################################
 # Utility Methods

pocs/state/machine.py

@@ -121,6 +121,7 @@ def run(self, exit_when_done=False, run_once=False):
 
             # If we are processing the states
             if self.do_states:
+
                 # If sleeping, wait until safe (or interrupt)
                 if self.state == 'sleeping':
                     if self.is_safe() is not True:
@@ -129,7 +130,8 @@ def run(self, exit_when_done=False, run_once=False):
                 try:
                     state_changed = self.goto_next_state()
                 except Exception as e:
-                    self.logger.warning("Problem going to next state, exiting loop [{}]".format(e))
+                    self.logger.warning("Problem going from {} to {}, exiting loop [{!r}]".format(
+                        self.state, self.next_state, e))
                     self.stop_states()
                     break
 
@@ -144,6 +146,14 @@ def run(self, exit_when_done=False, run_once=False):
                 else:
                     _loop_iteration = 0
 
+                ########################################################
+                # Note that `self.state` below has changed from above
+                ########################################################
+
+                # If we are in ready state then we are making one attempt
+                if self.state == 'ready':
+                    self._obs_run_retries -= 1
+
                 if self.state == 'sleeping' and self.run_once:
                     self.stop_states()
             elif exit_when_done:
@@ -170,7 +180,6 @@ def stop_states(self):
         """ Stops the machine loop on the next iteration """
         self.logger.info("Stopping POCS states")
         self._do_states = False
-        self._retry_attemps = 0
 
     def status(self):
         """Computes status, a dict, of whole observatory."""

pocs/state/states/default/parked.py

@@ -4,5 +4,26 @@ def on_enter(event_data):
     pocs = event_data.model
     pocs.say("I'm parked now. Phew.")
 
-    pocs.say("Cleaning up for the night!")
-    pocs.next_state = 'housekeeping'
+    has_valid_observations = pocs.observatory.scheduler.has_valid_observations
+
+    if has_valid_observations:
+        if pocs.is_safe():
+            if pocs.should_retry is False or pocs.run_once is True:
+                pocs.say("Done retrying for this run, going to clean up and shut down!")
+                pocs.next_state = 'housekeeping'
+            else:
+                pocs.say("Things look okay for now. I'm going to try again.")
+                pocs.next_state = 'ready'
+        else:
+            pocs.say("Cleaning up for the night!")
+            pocs.next_state = 'housekeeping'
+    else:
+        if pocs.run_once is False:
+            pocs.say("No observations found. Going to stay parked for an hour then try again.")
+            pocs.sleep(delay=3600)  # 1 hour = 3600 seconds
+
+            pocs.reset_observing_run()
+            pocs.next_state = 'ready'
+        else:
+            pocs.say("Only wanted to run once so cleaning up!")
+            pocs.next_state = 'housekeeping'

pocs/state/states/default/sleeping.py

@@ -1,14 +1,15 @@
 def on_enter(event_data):
     """ """
     pocs = event_data.model
-    pocs.next_state = 'ready'
 
-    # If it is dark and safe we shouldn't be in sleeping state
-    if pocs.is_dark() and pocs.is_safe():
-        if pocs.should_retry is False:
-            pocs.say("Weather is good and it is dark. Something must have gone wrong. Stopping loop")
-            pocs.stop_states()
-        else:
-            pocs.say("Things look okay for now. I'm going to try again.")
+    if pocs.should_retry is False:
+        pocs.say("Weather is good and it is dark. Something must have gone wrong. " +
+                 "Stopping loop.")
+        pocs.stop_states()
     else:
-        pocs.say("Another successful night!")
+        # Note: Unit will "sleep" before transition until it is safe
+        # to observe again.
+        pocs.next_state = 'ready'
+        pocs.reset_observing_run()
+
+    pocs.say("Another successful night!")

pocs/tests/test_dispatch_scheduler.py

@@ -115,14 +115,14 @@ def test_get_observation_reread(field_list, observer, temp_file, constraints):
     assert isinstance(best[1], float)
 
     # Alter the field file - note same target but new name
-    with open(temp_file, 'w') as f:
+    with open(temp_file, 'a') as f:
         f.write(yaml.dump([{
             'name': 'New Name',
             'position': '20h00m43.7135s +22d42m39.0645s',
-            'priority': 50
+            'priority': 5000
         }]))
 
-    # Get observation but reread file
+    # Get observation but reread file first
     best = scheduler.get_observation(time=time, reread_fields_file=True)
     assert best[0] != 'HD 189733'
     assert isinstance(best[1], float)

pocs/tests/test_pocs.py

@@ -286,8 +286,9 @@ def test_run_no_targets_and_exit(pocs):
     pocs.state = 'sleeping'
 
     pocs.initialize()
+    pocs.observatory.scheduler.clear_available_observations()
     assert pocs.is_initialized is True
-    pocs.run(exit_when_done=True)
+    pocs.run(exit_when_done=True, run_once=True)
     assert pocs.state == 'sleeping'
 
 
@@ -312,41 +313,6 @@ def test_run_complete(pocs):
     assert pocs.state == 'sleeping'
 
 
-def test_run_interrupt_with_reschedule_of_target(observatory):
-    def start_pocs():
-        pocs = POCS(observatory, messaging=True)
-        pocs.logger.info('Before initialize')
-        pocs.initialize()
-        pocs.logger.info('POCS initialized, back in test')
-        pocs.observatory.scheduler.fields_list = [{'name': 'KIC 8462852',
-                                                   'position': '20h06m15.4536s +44d27m24.75s',
-                                                   'priority': '100',
-                                                   'exp_time': 2,
-                                                   'min_nexp': 1,
-                                                   'exp_set_size': 1,
-                                                   }]
-        pocs.run(exit_when_done=True, run_once=True)
-        pocs.logger.info('run finished, powering down')
-        pocs.power_down()
-
-    pub = PanMessaging.create_publisher(6500)
-    sub = PanMessaging.create_subscriber(6511)
-
-    pocs_process = Process(target=start_pocs)
-    pocs_process.start()
-
-    while True:
-        msg_type, msg_obj = sub.receive_message()
-        if msg_type == 'STATUS':
-            current_state = msg_obj.get('state', {})
-            if current_state == 'pointing':
-                pub.send_message('POCS-CMD', 'shutdown')
-                break
-
-    pocs_process.join()
-    assert pocs_process.is_alive() is False
-
-
 def test_run_power_down_interrupt(observatory):
     def start_pocs():
         pocs = POCS(observatory, messaging=True)