Better error handling

spinn_front_end_common/interface/abstract_spinnaker_base.py

@@ -30,12 +30,10 @@
 from spinn_utilities.log import FormatAdapter
 
 from spinn_machine import __version__ as spinn_machine_version
-from spinn_machine import CoreSubsets, Machine
+from spinn_machine import Machine
 
 from spinnman import __version__ as spinnman_version
-from spinnman.exceptions import SpiNNManCoresNotInStateException
-from spinnman.model.cpu_infos import CPUInfos
-from spinnman.model.enums import CPUState, ExecutableType
+from spinnman.model.enums import ExecutableType
 
 from spalloc_client import __version__ as spalloc_version
 
@@ -74,7 +72,7 @@
 from spinn_front_end_common.interface.interface_functions import (
     application_finisher, application_runner,
     chip_io_buf_clearer, chip_io_buf_extractor,
-    chip_provenance_updater, chip_runtime_updater, compute_energy_used,
+    chip_runtime_updater, compute_energy_used,
     create_notification_protocol, database_interface,
     reload_dsg_regions, energy_provenance_reporter,
     load_application_data_specs, load_system_data_specs,
@@ -112,7 +110,8 @@
     routing_table_from_machine_report, tags_from_machine_report,
     write_json_machine, write_json_placements,
     write_json_routing_tables, drift_report)
-from spinn_front_end_common.utilities.iobuf_extractor import IOBufExtractor
+from spinn_front_end_common.utilities.emergency_recovery import (
+    emergency_recover_states_from_failure)
 from spinn_front_end_common.utility_models import (
     DataSpeedUpPacketGatherMachineVertex)
 from spinn_front_end_common.utilities.report_functions.reports import (
@@ -2193,76 +2192,7 @@ def __recover_from_error(self, exception):
         except Exception:
             logger.exception("Error reading router provenance")
 
-        # Find the cores that are not in an expected state
-        unsuccessful_cores = CPUInfos()
-        if isinstance(exception, SpiNNManCoresNotInStateException):
-            unsuccessful_cores = exception.failed_core_states()
-
-        # If there are no cores in a bad state, find those not yet in
-        # their finished state
-        transceiver = self._data_writer.get_transceiver()
-        if not unsuccessful_cores:
-            for executable_type, core_subsets in \
-                    self._data_writer.get_executable_types().items():
-                failed_cores = transceiver.get_cpu_infos(
-                    core_subsets, executable_type.end_state, False)
-                for (x, y, p) in failed_cores:
-                    unsuccessful_cores.add_processor(
-                        x, y, p, failed_cores.get_cpu_info(x, y, p))
-
-        # Print the details of error cores
-        logger.error(unsuccessful_cores.get_status_string())
-
-        # Find the cores that are not in RTE i.e. that can still be read
-        non_rte_cores = [
-            (x, y, p)
-            for (x, y, p), core_info in unsuccessful_cores.items()
-            if (core_info.state != CPUState.RUN_TIME_EXCEPTION and
-                core_info.state != CPUState.WATCHDOG)]
-
-        # If there are any cores that are not in RTE, extract data from them
-        if (non_rte_cores and
-                ExecutableType.USES_SIMULATION_INTERFACE in
-                self._data_writer.get_executable_types()):
-            non_rte_core_subsets = CoreSubsets()
-            for (x, y, p) in non_rte_cores:
-                non_rte_core_subsets.add_processor(x, y, p)
-
-            # Attempt to force the cores to write provenance and exit
-            try:
-                chip_provenance_updater(non_rte_core_subsets)
-            except Exception:
-                logger.exception("Could not update provenance on chip")
-
-            # Extract any written provenance data
-            try:
-                transceiver = self._data_writer.get_transceiver()
-                finished_cores = transceiver.get_cpu_infos(
-                    non_rte_core_subsets, CPUState.FINISHED, True)
-                finished_placements = Placements()
-                for (x, y, p) in finished_cores:
-                    try:
-                        placement = self._data_writer.\
-                            get_placement_on_processor(x, y, p)
-                        finished_placements.add_placement(placement)
-                    except Exception:   # pylint: disable=broad-except
-                        pass  # already recovering from error
-                placements_provenance_gatherer(
-                    finished_placements.n_placements,
-                    finished_placements.placements)
-            except Exception as pro_e:
-                logger.exception(f"Could not read provenance due to {pro_e}")
-
-        # Read IOBUF where possible (that should be everywhere)
-        iobuf = IOBufExtractor()
-        try:
-            errors, warnings = iobuf.extract_iobuf()
-        except Exception:
-            logger.exception("Could not get iobuf")
-            errors, warnings = [], []
-
-        # Print the IOBUFs
-        self._print_iobuf(errors, warnings)
+        emergency_recover_states_from_failure()
 
     @staticmethod
     def _print_iobuf(errors, warnings):

spinn_front_end_common/interface/interface_functions/__init__.py

@@ -16,7 +16,6 @@
 from .application_runner import application_runner
 from .chip_iobuf_clearer import chip_io_buf_clearer
 from .chip_iobuf_extractor import chip_io_buf_extractor
-from .chip_provenance_updater import chip_provenance_updater
 from .chip_runtime_updater import chip_runtime_updater
 from .compute_energy_used import compute_energy_used
 from .database_interface import database_interface
@@ -61,7 +60,7 @@
 
 __all__ = [
     "application_finisher", "application_runner", "chip_io_buf_clearer",
-    "chip_io_buf_extractor", "chip_provenance_updater",
+    "chip_io_buf_extractor",
     "chip_runtime_updater", "create_notification_protocol",
     "compute_energy_used", "database_interface",
     "reload_dsg_regions",

spinn_front_end_common/interface/interface_functions/application_runner.py

@@ -14,13 +14,17 @@
 
 import logging
 import time
+from math import ceil
 from spinn_utilities.log import FormatAdapter
+from spinn_utilities.progress_bar import ProgressBar
 from spinnman.messages.scp.enums import Signal
 from spinnman.model.enums import ExecutableType
 from spinn_front_end_common.data import FecDataView
-from spinn_front_end_common.utilities.exceptions import ConfigurationException
+from spinn_front_end_common.utilities.exceptions import (
+    ConfigurationException, ExecutableFailedToStopException)
 from spinn_front_end_common.utilities.constants import (
     MICRO_TO_MILLISECOND_CONVERSION)
+from spinnman.model.enums.cpu_state import CPUState
 
 SAFETY_FINISH_TIME = 0.1
 
@@ -117,10 +121,27 @@ def _run_wait(self, run_until_complete, runtime, time_threshold):
                       MICRO_TO_MILLISECOND_CONVERSION)
             scaled_runtime = runtime * factor
             time_to_wait = scaled_runtime + SAFETY_FINISH_TIME
-            logger.info(
-                "Application started; waiting {}s for it to stop",
-                time_to_wait)
-            time.sleep(time_to_wait)
+            steps = ceil(time_to_wait)
+            progress = ProgressBar(
+                steps,
+                f"Application started; waiting {time_to_wait}s for it to stop")
+            time_now = time.time()
+            start_time = time_now
+            last_progress = 0
+            end_time = time_now + time_to_wait
+            while time_now < end_time:
+                time.sleep(min(1.0, end_time - time_now))
+                for state in [CPUState.RUN_TIME_EXCEPTION, CPUState.WATCHDOG]:
+                    if self.__txrx.get_core_state_count(self.__app_id, state):
+                        raise ExecutableFailedToStopException(
+                            "Some cores have reached an error state during"
+                            " simulation; stopping early!")
+                time_now = time.time()
+                total_progress = min(ceil(time_now - start_time), steps)
+                progress_update = total_progress - last_progress
+                progress.update(progress_update)
+                last_progress = total_progress
+            progress.end()
             self._wait_for_end(timeout=time_threshold)
         else:
             logger.info("Application started; waiting until finished")
@@ -155,9 +176,16 @@ def _wait_for_end(self, timeout=None):
         :param timeout:
         :type timeout: float or None
         """
+        # Do progress here as if any cores overrun, it is nice to know
+        # that the wait has finished at least
+        exec_types = FecDataView.get_executable_types()
+        n_cores = sum(len(cores) for cores in exec_types.values())
+        progress = ProgressBar(n_cores, "Waiting for cores to finish")
         for ex_type, cores in FecDataView.get_executable_types().items():
             self.__txrx.wait_for_cores_to_be_in_state(
-                cores, self.__app_id, ex_type.end_state, timeout=timeout)
+                cores, self.__app_id, ex_type.end_state, timeout=timeout,
+                progress_bar=progress)
+        progress.end()
 
     def _determine_simulation_sync_signals(self):
         """

spinn_front_end_common/utilities/chip_provenance_updater.py

@@ -0,0 +1,82 @@
+# Copyright (c) 2016 The University of Manchester
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     https://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+import struct
+import logging
+from time import sleep
+from spinn_utilities.progress_bar import ProgressBar
+from spinn_utilities.log import FormatAdapter
+from spinnman.messages.sdp import SDPFlag, SDPHeader, SDPMessage
+from spinnman.model.enums import (
+    CPUState, SDP_PORTS, SDP_RUNNING_MESSAGE_CODES)
+from spinn_front_end_common.data import FecDataView
+
+
+logger = FormatAdapter(logging.getLogger(__name__))
+_ONE_WORD = struct.Struct("<I")
+
+
+def chip_provenance_updater(all_core_subsets, limit=10):
+    """ Update the provenance on all_core_subsets
+
+    :param ~spinn_machine.CoreSubsets all_core_subsets:
+    :param int limit: How many times to try to update provenance
+    """
+    app_id = FecDataView.get_app_id()
+    txrx = FecDataView.get_transceiver()
+    n_running_cores = txrx.get_core_state_count(app_id, CPUState.RUNNING)
+
+    progress = ProgressBar(
+        n_running_cores,
+        "Forcing error cores to generate provenance data")
+    attempts = 0
+    while n_running_cores and attempts < limit:
+        attempts += 1
+        running_cores = txrx.get_cpu_infos(
+            all_core_subsets, CPUState.RUNNING, include=True)
+
+        for (c_x, c_y, proc) in running_cores.keys():
+            send_chip_update_provenance_and_exit(txrx, c_x, c_y, proc)
+        sleep(0.5)
+
+        n_running_cores_now = txrx.get_core_state_count(
+            app_id, CPUState.RUNNING)
+
+        to_update = n_running_cores - n_running_cores_now
+        if to_update != 0:
+            progress.update(to_update)
+        n_running_cores = n_running_cores_now
+
+    progress.end()
+    if n_running_cores > 0:
+        logger.error("Unable to Finish getting provenance data. "
+                     "Abandoned after too many retries. "
+                     "Board may be left in an unstable state!")
+
+
+def send_chip_update_provenance_and_exit(txrx, c_x, c_y, proc):
+    """
+    :param int c_x:
+    :param int c_y:
+    :param int proc:
+    """
+    cmd = SDP_RUNNING_MESSAGE_CODES.SDP_UPDATE_PROVENCE_REGION_AND_EXIT
+    port = SDP_PORTS.RUNNING_COMMAND_SDP_PORT
+
+    txrx.send_sdp_message(SDPMessage(
+        SDPHeader(
+            flags=SDPFlag.REPLY_NOT_EXPECTED,
+            destination_port=port.value, destination_cpu=proc,
+            destination_chip_x=c_x, destination_chip_y=c_y),
+        data=_ONE_WORD.pack(cmd.value)))

spinn_front_end_common/utilities/emergency_recovery.py

@@ -14,9 +14,12 @@
 import logging
 
 from spinn_utilities.log import FormatAdapter
+from spinn_machine import CoreSubsets
 from spinnman.model import ExecutableTargets, CPUInfos
 from spinnman.model.enums import CPUState
 from spinn_front_end_common.data import FecDataView
+from .chip_provenance_updater import (
+    chip_provenance_updater, send_chip_update_provenance_and_exit)
 from .iobuf_extractor import IOBufExtractor
 
 logger = FormatAdapter(logging.getLogger(__name__))
@@ -79,6 +82,37 @@ def _emergency_iobuf_extract(executable_targets=None):
     extractor.extract_iobuf()
 
 
+def _emergency_exit():
+    """ Tries to get the cores to exit
+    """
+    # pylint: disable=broad-except
+    all_core_subsets = CoreSubsets()
+    for place in FecDataView.iterate_placemements():
+        all_core_subsets.add_processor(place.x, place.y, place.p)
+    try:
+        chip_provenance_updater(all_core_subsets)
+    except Exception:
+        logger.error("Could not exit - going to individual chips")
+        errors = list()
+        txrx = FecDataView.get_transceiver()
+        for chip_subset in all_core_subsets:
+            try:
+                chip_subsets = CoreSubsets([chip_subset])
+                running_cores = txrx.get_cpu_infos(
+                    chip_subsets, CPUState.RUNNING, include=True)
+                for (c_x, c_y, proc) in running_cores.keys():
+                    send_chip_update_provenance_and_exit(txrx, c_x, c_y, proc)
+                # Don't even bother to check; with luck this happens and all
+                # is well, but at this point we can't do much more than send
+                # the request and hope!
+            except Exception:
+                errors.append((chip_subset.x, chip_subset.y))
+        if len(errors) > 10:
+            logger.error(f"Could not stop cores on {len(errors)} chips")
+        elif errors:
+            logger.error(f"Could not stop cores on {errors}")
+
+
 def emergency_recover_state_from_failure(vertex, placement):
     """
     Used to get at least *some* information out of a core when something
@@ -109,4 +143,5 @@ def emergency_recover_states_from_failure():
         The what/where mapping
     """
     _emergency_state_check()
+    _emergency_exit()
     _emergency_iobuf_extract()