2019-07-27T06:15:04.852Z,1564208104.852 [Supervisor](DEBUG): Initializing supervisor.
2019-07-27T06:15:04.855Z,1564208104.855 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-07-27T06:15:04.855Z,1564208104.855 [SyncHandler](INFO): Protected caller Thread ID is 6415
2019-07-27T06:15:04.856Z,1564208104.856 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-07-27T06:15:04.857Z,1564208104.857 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-07-27T06:15:04.857Z,1564208104.857 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 6416
2019-07-27T06:15:04.860Z,1564208104.860 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-07-27T06:15:04.872Z,1564208104.872 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-07-27T06:15:04.873Z,1564208104.873 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-07-27T06:15:04.873Z,1564208104.873 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 6417
2019-07-27T06:15:04.874Z,1564208104.874 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-07-27T06:15:04.875Z,1564208104.875 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-07-27T06:15:04.875Z,1564208104.875 [logger ThreadHandler](INFO): Protected caller Thread ID is 6418
2019-07-27T06:15:04.877Z,1564208104.877 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-07-27T06:15:04.878Z,1564208104.878 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-07-27T06:15:04.879Z,1564208104.879 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-07-27T06:15:05.079Z,1564208105.079 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-07-27T06:15:05.080Z,1564208105.080 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-07-27T06:15:05.161Z,1564208105.161 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-07-27T06:15:05.591Z,1564208105.591 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-07-27T06:15:05.592Z,1564208105.592 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-07-27T06:15:05.924Z,1564208105.924 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-07-27T06:15:05.925Z,1564208105.925 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-07-27T06:15:06.023Z,1564208106.023 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-07-27T06:15:06.024Z,1564208106.024 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-07-27T06:15:06.319Z,1564208106.319 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-07-27T06:15:06.320Z,1564208106.320 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-07-27T06:15:06.514Z,1564208106.514 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-07-27T06:15:06.514Z,1564208106.514 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-07-27T06:15:06.963Z,1564208106.963 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-07-27T06:15:06.964Z,1564208106.964 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-07-27T06:15:07.133Z,1564208107.133 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-07-27T06:15:07.134Z,1564208107.134 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-07-27T06:15:07.337Z,1564208107.337 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-07-27T06:15:07.338Z,1564208107.338 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-07-27T06:15:08.046Z,1564208108.046 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-07-27T06:15:08.047Z,1564208108.047 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-07-27T06:15:08.438Z,1564208108.438 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-07-27T06:15:08.439Z,1564208108.439 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-07-27T06:15:08.633Z,1564208108.633 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-07-27T06:15:08.633Z,1564208108.633 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-07-27T06:15:08.779Z,1564208108.779 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-07-27T06:15:08.780Z,1564208108.780 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-07-27T06:15:08.929Z,1564208108.929 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-07-27T06:15:08.931Z,1564208108.931 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2019-07-27T06:15:08.931Z,1564208108.931 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2019-07-27T06:15:09.024Z,1564208109.024 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2019-07-27T06:15:09.111Z,1564208109.111 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2019-07-27T06:15:09.215Z,1564208109.215 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2019-07-27T06:15:09.300Z,1564208109.300 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2019-07-27T06:15:09.397Z,1564208109.397 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2019-07-27T06:15:09.499Z,1564208109.499 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2019-07-27T06:15:09.709Z,1564208109.709 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2019-07-27T06:15:09.787Z,1564208109.787 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2019-07-27T06:15:09.957Z,1564208109.957 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2019-07-27T06:15:10.093Z,1564208110.093 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2019-07-27T06:15:10.214Z,1564208110.214 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg
2019-07-27T06:15:10.442Z,1564208110.442 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-07-27T06:15:10.443Z,1564208110.443 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/root/
2019-07-27T06:15:10.444Z,1564208110.444 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-07-27T06:15:10.464Z,1564208110.464 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-07-27T06:15:10.530Z,1564208110.530 [VerticalControl](DEBUG): Construct VerticalControl.
2019-07-27T06:15:10.639Z,1564208110.639 [VerticalControl] Loaded
2019-07-27T06:15:10.640Z,1564208110.640 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-07-27T06:15:10.640Z,1564208110.640 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-07-27T06:15:10.708Z,1564208110.708 [HorizontalControl] Loaded
2019-07-27T06:15:10.708Z,1564208110.708 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-07-27T06:15:10.708Z,1564208110.708 [SpeedControl](DEBUG): Construct SpeedControl.
2019-07-27T06:15:10.714Z,1564208110.714 [SpeedControl] Loaded
2019-07-27T06:15:10.714Z,1564208110.714 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-07-27T06:15:10.715Z,1564208110.715 [LoopControl](DEBUG): Construct LoopControl.
2019-07-27T06:15:10.715Z,1564208110.715 [LoopControl] Loaded
2019-07-27T06:15:10.716Z,1564208110.716 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-07-27T06:15:10.716Z,1564208110.716 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-07-27T06:15:10.717Z,1564208110.717 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-07-27T06:15:10.730Z,1564208110.730 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-07-27T06:15:10.730Z,1564208110.730 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-07-27T06:15:10.827Z,1564208110.827 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-07-27T06:15:10.828Z,1564208110.828 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-07-27T06:15:10.952Z,1564208110.952 [BuoyancyServo] Loaded
2019-07-27T06:15:10.953Z,1564208110.953 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-07-27T06:15:10.964Z,1564208110.964 [ElevatorServo] Loaded
2019-07-27T06:15:10.964Z,1564208110.964 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-07-27T06:15:10.974Z,1564208110.974 [MassServo] Loaded
2019-07-27T06:15:10.975Z,1564208110.975 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-07-27T06:15:10.986Z,1564208110.986 [RudderServo] Loaded
2019-07-27T06:15:10.986Z,1564208110.986 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-07-27T06:15:10.997Z,1564208110.997 [ThrusterServo] Loaded
2019-07-27T06:15:10.997Z,1564208110.997 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-07-27T06:15:10.997Z,1564208110.997 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-07-27T06:15:10.998Z,1564208110.998 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-07-27T06:15:11.103Z,1564208111.103 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-07-27T06:15:11.103Z,1564208111.103 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-07-27T06:15:11.124Z,1564208111.124 [NavChart] Loaded
2019-07-27T06:15:11.124Z,1564208111.124 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-07-27T06:15:11.128Z,1564208111.128 [UniversalFixResidualReporter] Loaded
2019-07-27T06:15:11.128Z,1564208111.128 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-07-27T06:15:11.129Z,1564208111.129 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-07-27T06:15:11.129Z,1564208111.129 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-07-27T06:15:11.198Z,1564208111.198 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-07-27T06:15:11.199Z,1564208111.199 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-07-27T06:15:11.525Z,1564208111.525 [DataOverHttps] Loaded
2019-07-27T06:15:11.525Z,1564208111.525 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-07-27T06:15:11.526Z,1564208111.526 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4087D4E0
2019-07-27T06:15:11.527Z,1564208111.527 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 6500
2019-07-27T06:15:11.540Z,1564208111.540 [Depth_Keller] Loaded
2019-07-27T06:15:11.540Z,1564208111.540 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-07-27T06:15:11.635Z,1564208111.635 [NAL9602] Loaded
2019-07-27T06:15:11.636Z,1564208111.636 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-07-27T06:15:11.651Z,1564208111.651 [Onboard] Loaded
2019-07-27T06:15:11.652Z,1564208111.652 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-07-27T06:15:11.655Z,1564208111.655 [Radio_Surface] Loaded
2019-07-27T06:15:11.655Z,1564208111.655 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-07-27T06:15:11.656Z,1564208111.656 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408AD4E0
2019-07-27T06:15:11.657Z,1564208111.657 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 6501
2019-07-27T06:15:13.667Z,1564208113.667 [BPC1] Loaded
2019-07-27T06:15:13.667Z,1564208113.667 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-07-27T06:15:13.668Z,1564208113.668 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-07-27T06:15:13.668Z,1564208113.668 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-07-27T06:15:13.709Z,1564208113.709 [DepthRateCalculator] Loaded
2019-07-27T06:15:13.709Z,1564208113.709 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-07-27T06:15:13.714Z,1564208113.714 [PitchRateCalculator] Loaded
2019-07-27T06:15:13.714Z,1564208113.714 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-07-27T06:15:13.726Z,1564208113.726 [SpeedCalculator] Loaded
2019-07-27T06:15:13.726Z,1564208113.726 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-07-27T06:15:13.747Z,1564208113.747 [TempGradientCalculator] Loaded
2019-07-27T06:15:13.747Z,1564208113.747 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-07-27T06:15:13.753Z,1564208113.753 [YawRateCalculator] Loaded
2019-07-27T06:15:13.753Z,1564208113.753 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-07-27T06:15:13.782Z,1564208113.782 [ElevatorOffsetCalculator] Loaded
2019-07-27T06:15:13.782Z,1564208113.782 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-07-27T06:15:13.783Z,1564208113.783 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-07-27T06:15:13.783Z,1564208113.783 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-07-27T06:15:13.981Z,1564208113.981 [ESPComponent] Loaded
2019-07-27T06:15:13.982Z,1564208113.982 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2019-07-27T06:15:13.996Z,1564208113.996 [PAR_Licor] Loaded
2019-07-27T06:15:13.996Z,1564208113.996 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2019-07-27T06:15:13.997Z,1564208113.997 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-07-27T06:15:13.997Z,1564208113.997 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-07-27T06:15:14.029Z,1564208114.029 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-07-27T06:15:14.030Z,1564208114.030 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-07-27T06:15:14.314Z,1564208114.314 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-07-27T06:15:14.314Z,1564208114.314 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-07-27T06:15:14.442Z,1564208114.442 [SBIT](DEBUG): Construct Startup Built In Test.
2019-07-27T06:15:14.453Z,1564208114.453 [SBIT] Loaded
2019-07-27T06:15:14.453Z,1564208114.453 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-07-27T06:15:14.454Z,1564208114.454 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-07-27T06:15:14.465Z,1564208114.465 [IBIT] Loaded
2019-07-27T06:15:14.465Z,1564208114.465 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-07-27T06:15:14.469Z,1564208114.469 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-07-27T06:15:14.602Z,1564208114.602 [CBIT] Loaded
2019-07-27T06:15:14.602Z,1564208114.602 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-07-27T06:15:14.603Z,1564208114.603 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-07-27T06:15:14.606Z,1564208114.606 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-07-27T06:15:14.607Z,1564208114.607 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-07-27T06:15:14.614Z,1564208114.614 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-07-27T06:15:14.615Z,1564208114.615 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A7F4E0
2019-07-27T06:15:14.615Z,1564208114.615 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 6502
2019-07-27T06:15:14.620Z,1564208114.620 [Supervisor](INFO): Main Thread ID is 6056
2019-07-27T06:15:14.620Z,1564208114.620 [Supervisor](DEBUG): Running supervisor.
2019-07-27T06:15:14.621Z,1564208114.621 [CommandLine ThreadHandler](INFO): Handler Thread ID is 6503
2019-07-27T06:15:14.623Z,1564208114.623 [controlThread ThreadHandler](INFO): Handler Thread ID is 6504
2019-07-27T06:15:14.623Z,1564208114.623 [controlThread](DEBUG): Initializing ControlThread
2019-07-27T06:15:14.624Z,1564208114.624 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-07-27T06:15:14.626Z,1564208114.626 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-07-27T06:15:14.627Z,1564208114.627 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-07-27T06:15:14.627Z,1564208114.627 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-07-27T06:15:14.629Z,1564208114.629 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-07-27T06:15:14.629Z,1564208114.629 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-07-27T06:15:14.632Z,1564208114.632 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-07-27T06:15:14.632Z,1564208114.632 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-07-27T06:15:14.632Z,1564208114.632 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-07-27T06:15:14.633Z,1564208114.633 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-07-27T06:15:14.633Z,1564208114.633 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-07-27T06:15:14.633Z,1564208114.633 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-07-27T06:15:14.635Z,1564208114.635 [SBIT](INFO): Initialize SBIT Component.
2019-07-27T06:15:14.636Z,1564208114.636 [SBIT](IMPORTANT): git: 2019-07-25-3-gc1f6a7a
2019-07-27T06:15:14.636Z,1564208114.636 [SBIT](INFO): git hash: c1f6a7a8eed835918ee5d3e81e798bcc189f4b20
2019-07-27T06:15:14.636Z,1564208114.636 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-07-27T06:15:14.637Z,1564208114.637 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Tue Dec 18 21:19:28 PST 2018
2019-07-27T06:15:14.638Z,1564208114.638 [SBIT](INFO): Beginning SBIT in 29.000000 seconds.
2019-07-27T06:15:14.639Z,1564208114.639 [IBIT](INFO): Initialize IBIT Component.
2019-07-27T06:15:14.640Z,1564208114.640 [CBIT](DEBUG): Initialize CBIT Component.
2019-07-27T06:15:14.641Z,1564208114.641 [logger ThreadHandler](INFO): Handler Thread ID is 6505
2019-07-27T06:15:14.651Z,1564208114.651 [CBIT](DEBUG): Initialized mux pins.
2019-07-27T06:15:14.651Z,1564208114.651 [CBIT](DEBUG): Initializing the watchdog timer.
2019-07-27T06:15:14.659Z,1564208114.659 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 6506
2019-07-27T06:15:14.660Z,1564208114.660 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-07-27T06:15:14.671Z,1564208114.671 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 6507
2019-07-27T06:15:14.675Z,1564208114.675 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-07-27T06:15:14.675Z,1564208114.675 [CBIT](DEBUG): Initializing heartbeat.
2019-07-27T06:15:14.683Z,1564208114.683 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 6508
2019-07-27T06:15:14.686Z,1564208114.686 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-07-27T06:15:14.686Z,1564208114.686 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-07-27T06:15:14.687Z,1564208114.687 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-07-27T06:15:14.687Z,1564208114.687 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-07-27T06:15:14.687Z,1564208114.687 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-07-27T06:15:14.687Z,1564208114.687 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-07-27T06:15:14.688Z,1564208114.688 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-07-27T06:15:14.688Z,1564208114.688 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-07-27T06:15:14.688Z,1564208114.688 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-07-27T06:15:14.688Z,1564208114.688 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-07-27T06:15:14.688Z,1564208114.688 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-07-27T06:15:14.688Z,1564208114.688 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-07-27T06:15:14.689Z,1564208114.689 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-07-27T06:15:14.689Z,1564208114.689 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-07-27T06:15:14.689Z,1564208114.689 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-07-27T06:15:14.689Z,1564208114.689 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-07-27T06:15:14.747Z,1564208114.747 [CBIT](DEBUG): Deactivating GF circuits.
2019-07-27T06:15:14.747Z,1564208114.747 [CBIT](DEBUG): Deactivating emergency mode.
2019-07-27T06:15:14.783Z,1564208114.783 [CBIT](DEBUG): Backplane powered.
2019-07-27T06:15:14.784Z,1564208114.784 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-07-27T06:15:14.794Z,1564208114.794 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-07-27T06:15:14.805Z,1564208114.805 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

    <Guidance:GoToSurface>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="StartupSatComms">

        <Sequence/>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:latitude_fix/>
        </ReadDatum>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:platform_communications/>
        </ReadDatum>

    </Aggregate>

</Mission>


2019-07-27T06:15:14.805Z,1564208114.805 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-07-27T06:15:14.885Z,1564208114.885 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-07-27T06:15:14.886Z,1564208114.886 [Default:A.Wait](DEBUG): Construct Wait.
2019-07-27T06:15:14.888Z,1564208114.888 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-07-27T06:15:14.927Z,1564208114.927 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-07-27T06:15:14.929Z,1564208114.929 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-07-27T06:15:14.951Z,1564208114.951 [Default:E.Execute](DEBUG): Construct Execute.
2019-07-27T06:15:14.954Z,1564208114.954 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Universal="Tethys/Universal"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
         Id="Default">

    <DefineArg Name="ElapsedSinceDefaultStarted"><Units:minute/><Value>0</Value></DefineArg>

    <Guidance:Wait>
        <Description>
            Wait a moment to see if the scheduler starts a new mission before
            starting to actually run Default.
        </Description>
        <Sequence/>
        <Setting><Guidance:Wait.duration/><Units:second/><Value>13</Value></Setting>
    </Guidance:Wait>

    <Guidance:GoToSurface>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="CheckIn">

        <Sequence Repeat="288"/>

        <ReadDatum Id="Read_GPS">
            <Timeout Duration="P5M"/>
            <Universal:time_fix/>
        </ReadDatum>

        <ReadDatum Id="Read_Iridium">
            <Timeout Duration="P2H">
                <Guidance:Execute>
                    <Sequence/>
                    <Setting><Guidance:Execute.command/><String>Burn on</String></Setting>
                </Guidance:Execute>
                <Syslog Severity="Critical">Dropped weight due to communications timeout.</Syslog>
            </Timeout>
            <Universal:platform_communications/>
        </ReadDatum>

        <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Units:minute/><Value>5</Value></Setting>
        </Guidance:Wait>

        <Assign><Sequence/><Arg Name="ElapsedSinceDefaultStarted"/><Elapsed><Universal:mission_started/></Elapsed></Assign>

        <Syslog Severity="Important">Default mission has been running for <Arg Name="ElapsedSinceDefaultStarted"/><Units:minute/></Syslog>

    </Aggregate>

    <Syslog Severity="Important">Restarting logs and Default mission.</Syslog>

    <Guidance:Execute>
        <Sequence/>
        <Setting><Guidance:Execute.command/><String>restart logs</String></Setting>
    </Guidance:Execute>

</Mission>


2019-07-27T06:15:14.966Z,1564208114.966 [controlThread](DEBUG): Component order: CycleStarter,Depth_Keller,NAL9602,Onboard,BPC1,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-07-27T06:15:14.981Z,1564208114.981 [Depth_Keller](ERROR): Pressure reading out of range: 1831.023193 decibar
2019-07-27T06:15:15.075Z,1564208115.075 [Radio_Surface](INFO): Powering up
2019-07-27T06:15:15.130Z,1564208115.130 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-07-27T06:15:15.179Z,1564208115.179 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-07-27T06:15:15.187Z,1564208115.187 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-07-27T06:15:15.188Z,1564208115.188 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-07-27T06:15:15.195Z,1564208115.195 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-07-27T06:15:15.196Z,1564208115.196 [MassServo](DEBUG): Initializing EZServoServo.
2019-07-27T06:15:15.203Z,1564208115.203 [MassServo](DEBUG): Initializing MassServo.
2019-07-27T06:15:15.204Z,1564208115.204 [RudderServo](DEBUG): Initializing EZServoServo.
2019-07-27T06:15:15.211Z,1564208115.211 [RudderServo](DEBUG): Initializing RudderServo.
2019-07-27T06:15:15.212Z,1564208115.212 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-07-27T06:15:15.219Z,1564208115.219 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-07-27T06:15:16.119Z,1564208116.119 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-07-27T06:15:16.119Z,1564208116.119 [RudderServo](FAULT): Rudder failed to initialize
2019-07-27T06:15:16.119Z,1564208116.119 [RudderServo] Communications Fault, FailCount= 1
2019-07-27T06:15:16.119Z,1564208116.119 [RudderServo](ERROR): Communications Fault
2019-07-27T06:15:16.230Z,1564208116.230 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-07-27T06:15:16.432Z,1564208116.432 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-07-27T06:15:16.432Z,1564208116.432 [RudderServo](INFO): Powering down
2019-07-27T06:15:17.117Z,1564208117.117 [RudderServo](DEBUG): Initializing EZServoServo.
2019-07-27T06:15:17.236Z,1564208117.236 [RudderServo](DEBUG): Initializing RudderServo.
2019-07-27T06:15:17.240Z,1564208117.240 [CBIT](INFO): Clearing failed state for component RudderServo
2019-07-27T06:15:17.240Z,1564208117.240 [RudderServo] No Fault, FailCount= 1
2019-07-27T06:15:24.815Z,1564208124.815 [CBIT](CRITICAL): Environmental Failure. Press:14.729767 PSI. Humidity:30%. Temp:30 C. ABORTING MISSION
2019-07-27T06:15:24.816Z,1564208124.816 [Supervisor](INFO): Stop Mission called by CBIT::monitorEnvironmentals
2019-07-27T06:15:25.233Z,1564208125.233 [CommandLine](FAULT): Scheduling is paused
2019-07-27T06:15:25.233Z,1564208125.233 [CBIT](INFO): Critical error at 20190727T061524
2019-07-27T06:15:41.700Z,1564208141.700 [NAL9602](INFO): Powering up NAL9602
2019-07-27T06:15:44.176Z,1564208144.176 [SBIT](IMPORTANT): Beginning Startup BIT
2019-07-27T06:15:44.180Z,1564208144.180 [CBIT](IMPORTANT): Beginning ground fault scan
2019-07-27T06:15:52.700Z,1564208152.700 [NAL9602](INFO): NAL9602 initialized
2019-07-27T06:15:53.519Z,1564208153.519 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:15:55.574Z,1564208155.574 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): 0.010579
CHAN A1 (24V): -0.199047
CHAN A2 (12V): -0.002200
CHAN A3 (5V): -0.000932
CHAN B0 (3.3V): 0.000237
CHAN B1 (3.15aV): -0.000137
CHAN B2 (3.15bV): -0.000305
CHAN B3 (GND): 0.000376
OPEN: -0.000532
Full Scale Calc: 4.765 mA, -1.589 mA
2019-07-27T06:16:37.762Z,1564208197.762 [SBIT](IMPORTANT): SBIT PASSED
2019-07-27T06:16:37.820Z,1564208197.820 [CommandLine](IMPORTANT): got command configSet list
2019-07-27T06:16:37.820Z,1564208197.820 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-07-27T06:16:37.821Z,1564208197.821 [CommandLine](IMPORTANT): AHRS_M2.loadAtStartup=0 bool;

2019-07-27T06:16:37.821Z,1564208197.821 [CommandLine](IMPORTANT): Aanderaa_O2.loadAtStartup=0 bool;

2019-07-27T06:16:37.821Z,1564208197.821 [CommandLine](IMPORTANT): BPC1.batteryMissingStickThreshold=0 count;

2019-07-27T06:16:37.822Z,1564208197.822 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=6 hour;

2019-07-27T06:16:37.822Z,1564208197.822 [CommandLine](IMPORTANT): CBIT.abortDepth=296 meter;

2019-07-27T06:16:37.822Z,1564208197.822 [CommandLine](IMPORTANT): CBIT.gf24Offset=172 microampere;

2019-07-27T06:16:37.822Z,1564208197.822 [CommandLine](IMPORTANT): CBIT.stopDepth=288 meter;

2019-07-27T06:16:37.822Z,1564208197.822 [CommandLine](IMPORTANT): CTD_NeilBrown.loadAtStartup=0 bool;

2019-07-27T06:16:37.822Z,1564208197.822 [CommandLine](IMPORTANT): CTD_Seabird.loadAtStartup=0 bool;

2019-07-27T06:16:37.822Z,1564208197.822 [CommandLine](IMPORTANT): DAT.ignoreElevationAngle=1 bool;

2019-07-27T06:16:37.822Z,1564208197.822 [CommandLine](IMPORTANT): DAT.loadAtStartup=0 bool;

2019-07-27T06:16:37.822Z,1564208197.822 [CommandLine](IMPORTANT): DVL_micro.loadAtStartup=0 bool;

2019-07-27T06:16:37.823Z,1564208197.823 [CommandLine](IMPORTANT): DropWeight.loadAtStartup=0 bool;

2019-07-27T06:16:37.823Z,1564208197.823 [CommandLine](IMPORTANT): ESPComponent.loadAtStartup=1 bool;

2019-07-27T06:16:37.823Z,1564208197.823 [CommandLine](IMPORTANT): Express linearApproximation DAT.range 5.000000 meter;

2019-07-27T06:16:37.823Z,1564208197.823 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 10.000000 meter;

2019-07-27T06:16:37.823Z,1564208197.823 [CommandLine](IMPORTANT): Express linearApproximation depth 5.000000 meter;

2019-07-27T06:16:37.823Z,1564208197.823 [CommandLine](IMPORTANT): Express linearApproximation latitude 0.005000 degree;

2019-07-27T06:16:37.823Z,1564208197.823 [CommandLine](IMPORTANT): Express linearApproximation longitude 0.005000 degree;

2019-07-27T06:16:37.823Z,1564208197.823 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-07-27T06:16:37.824Z,1564208197.824 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=274 cubic_centimeter;

2019-07-27T06:16:37.824Z,1564208197.824 [CommandLine](IMPORTANT): VerticalControl.massDefault=-2.3 millimeter;

2019-07-27T06:16:37.824Z,1564208197.824 [CommandLine](IMPORTANT): VerticalControl.massPositionLimitAft=-31 millimeter;

2019-07-27T06:16:37.824Z,1564208197.824 [CommandLine](IMPORTANT): VerticalControl.massPositionLimitFwd=30 millimeter;

2019-07-27T06:16:37.824Z,1564208197.824 [CommandLine](IMPORTANT): WetLabsBB2FL.loadAtStartup=0 bool;

2019-07-27T06:16:38.148Z,1564208198.148 [MissionManager](IMPORTANT): Started mission Startup
2019-07-27T06:16:38.149Z,1564208198.149 [Startup] Running Loop=1
2019-07-27T06:16:38.149Z,1564208198.149 [Startup](DEBUG): Aggregate::initialize Startup
2019-07-27T06:16:38.149Z,1564208198.149 [Startup:A.GoToSurface] Running Loop=1
2019-07-27T06:16:38.149Z,1564208198.149 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-27T06:16:38.150Z,1564208198.150 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-27T06:16:38.150Z,1564208198.150 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-27T06:16:38.150Z,1564208198.150 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-27T06:16:38.151Z,1564208198.151 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-27T06:16:38.151Z,1564208198.151 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-27T06:16:38.153Z,1564208198.153 [Startup:StartupSatComms] Running Loop=1
2019-07-27T06:16:38.153Z,1564208198.153 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-07-27T06:16:38.153Z,1564208198.153 [Startup:StartupSatComms:A] Running Loop=1
2019-07-27T06:16:38.553Z,1564208198.553 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-07-27T06:17:14.919Z,1564208234.919 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-07-27T06:17:14.919Z,1564208234.919 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-07-27T06:17:14.919Z,1564208234.919 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-27T06:17:14.930Z,1564208234.930 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-27T06:17:15.332Z,1564208235.332 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-27T06:17:15.332Z,1564208235.332 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-07-27T06:17:38.336Z,1564208258.336 [Startup:StartupSatComms:A](INFO): Timed out from 2019-07-27T06:16:38.2Z
2019-07-27T06:17:38.336Z,1564208258.336 [Startup:StartupSatComms:A] Stopped
2019-07-27T06:17:38.336Z,1564208258.336 [Startup:StartupSatComms:B] Running Loop=1
2019-07-27T06:17:38.740Z,1564208258.740 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-07-27T06:17:53.809Z,1564208273.809 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004911
2019-07-27T06:17:56.764Z,1564208276.764 [CommandLine](IMPORTANT): got command maintain sensor NAL9602.latitude_fix 36.797001 degree
2019-07-27T06:17:56.765Z,1564208276.765 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.latitude_fix" handled in the control thread.
2019-07-27T06:17:56.766Z,1564208276.766 [CommandLine](IMPORTANT): got command maintain sensor NAL9602.longitude_fix -121.847000 degree
2019-07-27T06:17:56.768Z,1564208276.768 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.longitude_fix" handled in the control thread.
2019-07-27T06:17:56.985Z,1564208276.985 [controlThread](DEBUG): Component order: CycleStarter,Depth_Keller,NAL9602,Onboard,BPC1,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,Maintain_NAL9602.latitude_fix,Maintain_NAL9602.longitude_fix,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-07-27T06:17:57.380Z,1564208277.380 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-07-27T06:17:57.380Z,1564208277.380 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2019-07-27T06:17:57.380Z,1564208277.380 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-27T06:17:57.394Z,1564208277.394 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-27T06:17:57.777Z,1564208277.777 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-27T06:17:57.777Z,1564208277.777 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2019-07-27T06:17:58.547Z,1564208278.547 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-07-27T06:17:58.547Z,1564208278.547 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2019-07-27T06:17:58.547Z,1564208278.547 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-27T06:17:58.565Z,1564208278.565 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-27T06:17:58.975Z,1564208278.975 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-27T06:17:58.975Z,1564208278.975 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2019-07-27T06:17:59.402Z,1564208279.402 [DataOverHttps](INFO): Sending 43 bytes from file Logs/20190727T054822/Courier0013.lzma
2019-07-27T06:17:59.750Z,1564208279.750 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-07-27T06:17:59.750Z,1564208279.750 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2019-07-27T06:17:59.750Z,1564208279.750 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-27T06:17:59.759Z,1564208279.759 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-27T06:18:00.170Z,1564208280.170 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-27T06:18:00.170Z,1564208280.170 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2019-07-27T06:18:00.208Z,1564208280.208 [DataOverHttps](INFO): Moved sent file to Logs/20190727T054822/Courier0013.lzma.bak
2019-07-27T06:18:00.208Z,1564208280.208 [DataOverHttps](INFO): SBD MOMSN=11479533
2019-07-27T06:18:00.967Z,1564208280.967 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-07-27T06:18:00.967Z,1564208280.967 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5
2019-07-27T06:18:00.967Z,1564208280.967 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-27T06:18:01.014Z,1564208281.014 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-27T06:18:01.380Z,1564208281.380 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-27T06:18:01.380Z,1564208281.380 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5
2019-07-27T06:18:02.207Z,1564208282.207 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-07-27T06:18:02.207Z,1564208282.207 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6
2019-07-27T06:18:02.207Z,1564208282.207 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-27T06:18:02.233Z,1564208282.233 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-27T06:18:02.607Z,1564208282.607 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-27T06:18:02.607Z,1564208282.607 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6
2019-07-27T06:18:03.396Z,1564208283.396 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-07-27T06:18:03.396Z,1564208283.396 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 7
2019-07-27T06:18:03.397Z,1564208283.397 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-27T06:18:03.431Z,1564208283.431 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-27T06:18:03.851Z,1564208283.851 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-27T06:18:03.851Z,1564208283.851 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 7
2019-07-27T06:18:04.596Z,1564208284.596 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-07-27T06:18:04.596Z,1564208284.596 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 8
2019-07-27T06:18:04.596Z,1564208284.596 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-27T06:18:04.610Z,1564208284.610 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-27T06:18:05.035Z,1564208285.035 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-27T06:18:05.035Z,1564208285.035 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 8
2019-07-27T06:18:05.811Z,1564208285.811 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-07-27T06:18:05.811Z,1564208285.811 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 9
2019-07-27T06:18:05.811Z,1564208285.811 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-27T06:18:05.829Z,1564208285.829 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-27T06:18:06.235Z,1564208286.235 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-27T06:18:06.236Z,1564208286.236 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 9
2019-07-27T06:18:07.037Z,1564208287.037 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-07-27T06:18:07.037Z,1564208287.037 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 10
2019-07-27T06:18:07.037Z,1564208287.037 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-27T06:18:07.047Z,1564208287.047 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-27T06:18:07.440Z,1564208287.440 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-27T06:18:07.440Z,1564208287.440 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 10
2019-07-27T06:18:08.232Z,1564208288.232 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-07-27T06:18:08.232Z,1564208288.232 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 11
2019-07-27T06:18:08.232Z,1564208288.232 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-27T06:18:08.242Z,1564208288.242 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-27T06:18:08.644Z,1564208288.644 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-27T06:18:08.644Z,1564208288.644 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 11
2019-07-27T06:18:08.792Z,1564208288.792 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1564208256.000000
2019-07-27T06:18:08.792Z,1564208288.792 [CommandLine](FAULT): Incomplete syntax. Try: help set
2019-07-27T06:18:09.460Z,1564208289.460 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-07-27T06:18:09.460Z,1564208289.460 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 12
2019-07-27T06:18:09.460Z,1564208289.460 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-27T06:18:09.478Z,1564208289.478 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-27T06:18:09.903Z,1564208289.903 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-27T06:18:09.903Z,1564208289.903 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 12
2019-07-27T06:18:10.692Z,1564208290.692 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-07-27T06:18:10.692Z,1564208290.692 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 13
2019-07-27T06:18:10.692Z,1564208290.692 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-27T06:18:10.739Z,1564208290.739 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-27T06:18:11.125Z,1564208291.125 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-27T06:18:11.125Z,1564208291.125 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 13
2019-07-27T06:18:11.903Z,1564208291.903 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-07-27T06:18:11.903Z,1564208291.903 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 14
2019-07-27T06:18:11.903Z,1564208291.903 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-27T06:18:11.956Z,1564208291.956 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-27T06:18:12.319Z,1564208292.319 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-27T06:18:12.319Z,1564208292.319 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 14
2019-07-27T06:18:13.100Z,1564208293.100 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1564208256.000000 second
2019-07-27T06:18:13.954Z,1564208293.954 [DataOverHttps](INFO): Sending 142 bytes from file Logs/20190727T061504/Courier0000.lzma
2019-07-27T06:18:14.760Z,1564208294.760 [DataOverHttps](INFO): Moved sent file to Logs/20190727T061504/Courier0000.lzma.bak
2019-07-27T06:18:14.760Z,1564208294.760 [DataOverHttps](INFO): SBD MOMSN=11479535
2019-07-27T06:18:27.667Z,1564208307.667 [DataOverHttps](INFO): Sending 1567 bytes from file Logs/20190727T054822/Express0014.lzma
2019-07-27T06:18:28.452Z,1564208308.452 [DataOverHttps](INFO): Moved sent file to Logs/20190727T054822/Express0014.lzma.bak
2019-07-27T06:18:28.452Z,1564208308.452 [DataOverHttps](INFO): SBD MOMSN=11479539
2019-07-27T06:18:31.623Z,1564208311.623 [CommandLine](IMPORTANT): got command show stack
2019-07-27T06:18:31.624Z,1564208311.624 [CommandLine](IMPORTANT): Behavior Stack:

2019-07-27T06:18:31.624Z,1564208311.624 [Startup](IMPORTANT): Priority 0: Startup:A.GoToSurface
2019-07-27T06:18:31.624Z,1564208311.624 [Startup:StartupSatComms](IMPORTANT): Priority 1: Startup:StartupSatComms:B
2019-07-27T06:18:38.577Z,1564208318.577 [Startup:StartupSatComms:B](INFO): Timed out from 2019-07-27T06:17:38.3Z
2019-07-27T06:18:38.577Z,1564208318.577 [Startup:StartupSatComms:B] Stopped
2019-07-27T06:18:38.577Z,1564208318.577 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-07-27T06:18:38.577Z,1564208318.577 [Startup:StartupSatComms] Stopped
2019-07-27T06:18:38.577Z,1564208318.577 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-07-27T06:18:38.578Z,1564208318.578 [Startup](INFO): Completed Startup
2019-07-27T06:18:38.578Z,1564208318.578 [MissionManager](INFO): Startup is completed.
2019-07-27T06:18:38.578Z,1564208318.578 [MissionManager](INFO): Uninitializing Mission Startup
2019-07-27T06:18:38.578Z,1564208318.578 [Startup] Stopped
2019-07-27T06:18:38.578Z,1564208318.578 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-07-27T06:18:38.583Z,1564208318.583 [Startup:A.GoToSurface] Stopped
2019-07-27T06:18:38.583Z,1564208318.583 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-27T06:18:38.971Z,1564208318.971 [MissionManager](IMPORTANT): Started mission Default
2019-07-27T06:18:38.972Z,1564208318.972 [Default] Running Loop=1
2019-07-27T06:18:38.972Z,1564208318.972 [Default](DEBUG): Aggregate::initialize Default
2019-07-27T06:18:38.972Z,1564208318.972 [Default:B.GoToSurface] Running Loop=1
2019-07-27T06:18:38.972Z,1564208318.972 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-27T06:18:38.972Z,1564208318.972 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-27T06:18:38.972Z,1564208318.972 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-27T06:18:38.973Z,1564208318.973 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-27T06:18:38.973Z,1564208318.973 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-27T06:18:38.973Z,1564208318.973 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-27T06:18:38.974Z,1564208318.974 [Default:A.Wait] Running Loop=1
2019-07-27T06:18:38.974Z,1564208318.974 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-07-27T06:18:40.633Z,1564208320.633 [DataOverHttps](INFO): Sending 1174 bytes from file Logs/20190727T061504/Express0001.lzma
2019-07-27T06:18:41.436Z,1564208321.436 [DataOverHttps](INFO): Moved sent file to Logs/20190727T061504/Express0001.lzma.bak
2019-07-27T06:18:41.436Z,1564208321.436 [DataOverHttps](INFO): SBD MOMSN=11479587
2019-07-27T06:18:52.266Z,1564208332.266 [Default:A.Wait](INFO): Done Waiting.
2019-07-27T06:18:52.266Z,1564208332.266 [Default:A.Wait] Stopped
2019-07-27T06:18:52.266Z,1564208332.266 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-27T06:18:52.673Z,1564208332.673 [Default:CheckIn] Running Loop=1
2019-07-27T06:18:52.674Z,1564208332.674 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-07-27T06:18:52.674Z,1564208332.674 [Default:CheckIn:Read_GPS] Running Loop=1
2019-07-27T06:18:53.075Z,1564208333.075 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-07-27T06:19:47.820Z,1564208387.820 [DataOverHttps](IMPORTANT): SBD MTMSN=20190727T061825
2019-07-27T06:19:52.655Z,1564208392.655 [DataOverHttps](INFO): Received command:load Science/esp_kiss.xml;set esp_kiss.SettleTime 0.1 minute;set esp_kiss.ApproachSettleTimePreDive 1 second;run 
2019-07-27T06:19:52.691Z,1564208392.691 [CommandLine](IMPORTANT): got command load ./Missions/Science/esp_kiss.xml
2019-07-27T06:19:52.691Z,1564208392.691 [MissionManager](INFO): Loading Mission: ./Missions/Science/esp_kiss.xml
2019-07-27T06:19:52.812Z,1564208392.812 [MissionManager](INFO): DefineArg esp_kiss.MissionTimeout = 4.000000 h
2019-07-27T06:19:52.815Z,1564208392.815 [MissionManager](INFO): DefineArg esp_kiss.TargetDepth = 3.000000 m
2019-07-27T06:19:52.818Z,1564208392.818 [MissionManager](INFO): DefineArg esp_kiss.ESPCartridgeType_1 = -4.000000 count
2019-07-27T06:19:52.820Z,1564208392.820 [MissionManager](INFO): DefineArg esp_kiss.ESPCartridgeType_2 = -9.000000 count
2019-07-27T06:19:52.823Z,1564208392.823 [MissionManager](INFO): DefineArg esp_kiss.ESPCartridgeType_3 = nan count
2019-07-27T06:19:52.826Z,1564208392.826 [MissionManager](INFO): DefineArg esp_kiss.ESPCartridgeType_4 = nan count
2019-07-27T06:19:52.829Z,1564208392.829 [MissionManager](INFO): DefineArg esp_kiss.SettleTime = 3.000000 min
2019-07-27T06:19:52.841Z,1564208392.841 [MissionManager](INFO): DefineArg esp_kiss.Speed = 0.000000 m/s
2019-07-27T06:19:52.843Z,1564208392.843 [MissionManager](INFO): DefineArg esp_kiss.ApproachDepth = 3.000000 m
2019-07-27T06:19:52.846Z,1564208392.846 [MissionManager](INFO): DefineArg esp_kiss.ApproachSpeed = 0.700000 m/s
2019-07-27T06:19:52.849Z,1564208392.849 [MissionManager](INFO): DefineArg esp_kiss.ApproachDepthRate = 0.050000 m/s
2019-07-27T06:19:52.862Z,1564208392.862 [MissionManager](INFO): DefineArg esp_kiss.ApproachPitchLimit = 10.000000 arcdeg
2019-07-27T06:19:52.877Z,1564208392.877 [MissionManager](INFO): DefineArg esp_kiss.ApproachSettleTimePreDive = 90.000000 s
2019-07-27T06:19:52.880Z,1564208392.880 [MissionManager](INFO): DefineArg esp_kiss.ApproachSettleTimePostDive = 0.000000 s
2019-07-27T06:19:52.920Z,1564208392.920 [MissionManager](INFO): DefineArg esp_kiss.ApproachDepthTimeout = 15.000000 min
2019-07-27T06:19:52.923Z,1564208392.923 [MissionManager](INFO): DefineArg esp_kiss.kpDepth = 0.070000 rad/m
2019-07-27T06:19:52.925Z,1564208392.925 [MissionManager](INFO): DefineArg esp_kiss.DepthDeadband = 0.010000 m
2019-07-27T06:19:52.944Z,1564208392.944 [MissionManager](INFO): DefineArg esp_kiss.MinAltitude = 2.000000 m
2019-07-27T06:19:52.948Z,1564208392.948 [MissionManager](INFO): DefineArg esp_kiss.MaxDepth = 5.000000 m
2019-07-27T06:19:52.950Z,1564208392.950 [MissionManager](INFO): DefineArg esp_kiss.MinOffshore = 1.000000 km
2019-07-27T06:19:52.953Z,1564208392.953 [MissionManager](INFO): DefineOutput esp_kiss.ESPCartridgeType = nan count
2019-07-27T06:19:52.955Z,1564208392.955 [esp_kiss:A.AbortSample](DEBUG): Construct.
2019-07-27T06:19:52.955Z,1564208392.955 [MissionManager](INFO): Inserting Stack: Missions/Insert/StandardEnvelopes.xml
2019-07-27T06:19:53.019Z,1564208393.019 [MissionManager](INFO): DefineArg esp_kiss:StandardEnvelopes.MinAltitude = 5.000000 m
2019-07-27T06:19:53.022Z,1564208393.022 [MissionManager](INFO): DefineArg esp_kiss:StandardEnvelopes.MaxDepth = 200.000000 m
2019-07-27T06:19:53.025Z,1564208393.025 [MissionManager](INFO): DefineArg esp_kiss:StandardEnvelopes.MinOffshore = 2000.000000 m
2019-07-27T06:19:53.026Z,1564208393.026 [esp_kiss:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2019-07-27T06:19:53.054Z,1564208393.054 [esp_kiss:StandardEnvelopes:B.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2019-07-27T06:19:53.079Z,1564208393.079 [esp_kiss:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2019-07-27T06:19:53.098Z,1564208393.098 [MissionManager](INFO): Inserting Stack: Missions/Insert/NeedComms.xml
2019-07-27T06:19:53.196Z,1564208393.196 [MissionManager](INFO): DefineArg esp_kiss:NeedComms.DiveInterval = 3.000000 h
2019-07-27T06:19:53.200Z,1564208393.200 [MissionManager](INFO): DefineArg esp_kiss:NeedComms.WaitForPitchUp = 10.000000 min
2019-07-27T06:19:53.206Z,1564208393.206 [MissionManager](INFO): DefineArg esp_kiss:NeedComms.SurfacePitch = 20.000000 arcdeg
2019-07-27T06:19:53.217Z,1564208393.217 [MissionManager](INFO): DefineArg esp_kiss:NeedComms.SurfaceDepthRate = nan m/s
2019-07-27T06:19:53.221Z,1564208393.221 [MissionManager](INFO): DefineArg esp_kiss:NeedComms.SurfaceSpeed = 1.000000 m/s
2019-07-27T06:19:53.225Z,1564208393.225 [MissionManager](INFO): DefineArg esp_kiss:NeedComms.GPSTimeout = 7.000000 min
2019-07-27T06:19:53.251Z,1564208393.251 [MissionManager](INFO): DefineArg esp_kiss:NeedComms.CommsTimeout = 30.000000 min
2019-07-27T06:19:53.280Z,1564208393.280 [esp_kiss:NeedComms:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-07-27T06:19:53.343Z,1564208393.343 [esp_kiss:SampleESP:sample:B.Wait](DEBUG): Construct Wait.
2019-07-27T06:19:53.375Z,1564208393.375 [MissionManager](ERROR): Slate does not contain CTD_NeilBrown.bin_mean_sea_water_temperature
2019-07-27T06:19:53.376Z,1564208393.376 [MissionManager](ERROR): Slate does not contain celsius
2019-07-27T06:19:53.376Z,1564208393.376 [MissionManager](ERROR): Slate does not contain WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water
2019-07-27T06:19:53.376Z,1564208393.376 [MissionManager](ERROR): Slate does not contain microgram_per_liter
2019-07-27T06:19:53.379Z,1564208393.379 [MissionManager](INFO): Inserting Stack: Missions/Insert/Science.xml
2019-07-27T06:19:53.737Z,1564208393.737 [MissionManager](INFO): DefineArg esp_kiss:Science.SampleISUS = 0 bool
2019-07-27T06:19:53.741Z,1564208393.741 [MissionManager](INFO): DefineArg esp_kiss:Science.SampleISUSmaxPitch = 60.000000 arcdeg
2019-07-27T06:19:53.752Z,1564208393.752 [MissionManager](INFO): DefineArg esp_kiss:Science.SampleISUSminPitch = -60.000000 arcdeg
2019-07-27T06:19:53.759Z,1564208393.759 [MissionManager](INFO): DefineArg esp_kiss:Science.PeakDetectChlActive = 0 bool
2019-07-27T06:19:53.762Z,1564208393.762 [MissionManager](INFO): DefineArg esp_kiss:Science.TimeWindowPeakReport = nan min
2019-07-27T06:19:53.765Z,1564208393.765 [MissionManager](INFO): DefineArg esp_kiss:Science.HighestChlPeakReportActive = 0 bool
2019-07-27T06:19:53.780Z,1564208393.780 [MissionManager](INFO): DefineArg esp_kiss:Science.PatchTracking = 0 bool
2019-07-27T06:19:53.783Z,1564208393.783 [MissionManager](INFO): DefineArg esp_kiss:Science.FilterWidthHorizontal = 3.000000 count
2019-07-27T06:19:53.786Z,1564208393.786 [MissionManager](INFO): DefineArg esp_kiss:Science.NumProfilesSlidingwindow = 100.000000 count
2019-07-27T06:19:53.793Z,1564208393.793 [MissionManager](INFO): DefineArg esp_kiss:Science.OffPeakFractionHorizontal = 80.000000 %
2019-07-27T06:19:53.796Z,1564208393.796 [MissionManager](INFO): DefineArg esp_kiss:Science.PeakDetectNO3Active = 0 bool
2019-07-27T06:19:53.814Z,1564208393.814 [MissionManager](INFO): DefineArg esp_kiss:Science.PeakDetectOilActive = 0 bool
2019-07-27T06:19:53.821Z,1564208393.821 [MissionManager](INFO): DefineArg esp_kiss:Science.PeakDetectFDOMActive = 0 bool
2019-07-27T06:19:53.824Z,1564208393.824 [MissionManager](INFO): DefineArg esp_kiss:Science.UpwardDerivativeOfTemperatureActive = 0 bool
2019-07-27T06:19:53.835Z,1564208393.835 [MissionManager](INFO): DefineArg esp_kiss:Science.EnabledAanderaaO2 = 0.000000 bool
2019-07-27T06:19:53.843Z,1564208393.843 [MissionManager](INFO): DefineArg esp_kiss:Science.EnabledNeilBrown = 0.000000 bool
2019-07-27T06:19:53.846Z,1564208393.846 [MissionManager](INFO): DefineArg esp_kiss:Science.EnabledSeabird = 0.000000 bool
2019-07-27T06:19:53.854Z,1564208393.854 [MissionManager](INFO): DefineArg esp_kiss:Science.EnabledTurbulence_NPS = 0.000000 bool
2019-07-27T06:19:53.857Z,1564208393.857 [MissionManager](INFO): DefineArg esp_kiss:Science.EnabledWetLabsBB2FL = 0.000000 bool
2019-07-27T06:19:53.869Z,1564208393.869 [MissionManager](INFO): DefineArg esp_kiss:Science.EnabledWetLabsSeaOWL_UV_A = 0.000000 bool
2019-07-27T06:19:53.873Z,1564208393.873 [MissionManager](INFO): DefineArg esp_kiss:Science.EnabledWetLabsUBAT = 0.000000 bool
2019-07-27T06:19:53.899Z,1564208393.899 [MissionManager](INFO): DefineArg esp_kiss:Science.EnabledISUS = 0.000000 bool
2019-07-27T06:19:53.902Z,1564208393.902 [MissionManager](INFO): DefineArg esp_kiss:Science.LowPassWindowLength = 20.000000 count
2019-07-27T06:19:53.913Z,1564208393.913 [MissionManager](INFO): DefineArg esp_kiss:Science.MedianFilterLen = 5.000000 count
2019-07-27T06:19:53.916Z,1564208393.916 [MissionManager](INFO): DefineArg esp_kiss:Science.PeakChlShallowBound = nan m
2019-07-27T06:19:53.919Z,1564208393.919 [MissionManager](INFO): DefineArg esp_kiss:Science.PeakChlDeepBound = nan m
2019-07-27T06:19:53.922Z,1564208393.922 [MissionManager](INFO): DefineArg esp_kiss:Science.PeakShallowBound = nan m
2019-07-27T06:19:53.937Z,1564208393.937 [MissionManager](INFO): DefineArg esp_kiss:Science.PeakDeepBound = nan m
2019-07-27T06:19:53.940Z,1564208393.940 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakChl = 0.000000 ug/l
2019-07-27T06:19:53.963Z,1564208393.963 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakChlDepth = 0.000000 m
2019-07-27T06:19:53.966Z,1564208393.966 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakChlTemperature = 0.000000 degC
2019-07-27T06:19:53.969Z,1564208393.969 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakChlLatitude = nan arcdeg
2019-07-27T06:19:53.973Z,1564208393.973 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakChlLongitude = nan arcdeg
2019-07-27T06:19:53.976Z,1564208393.976 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakNO3 = 0.000000 umol/l
2019-07-27T06:19:53.979Z,1564208393.979 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakNO3Depth = 0.000000 m
2019-07-27T06:19:53.996Z,1564208393.996 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakNO3Latitude = nan arcdeg
2019-07-27T06:19:53.999Z,1564208393.999 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakNO3Longitude = nan arcdeg
2019-07-27T06:19:54.002Z,1564208394.002 [MissionManager](INFO): DefineOutput esp_kiss:Science.PatchChl = 0.000000 m
2019-07-27T06:19:54.017Z,1564208394.017 [MissionManager](INFO): DefineOutput esp_kiss:Science.PatchChlDepth = 0.000000 m
2019-07-27T06:19:54.020Z,1564208394.020 [MissionManager](INFO): DefineOutput esp_kiss:Science.PatchChlLatitude = nan arcdeg
2019-07-27T06:19:54.024Z,1564208394.024 [MissionManager](INFO): DefineOutput esp_kiss:Science.PatchChlLongitude = nan arcdeg
2019-07-27T06:19:54.029Z,1564208394.029 [MissionManager](INFO): DefineOutput esp_kiss:Science.PatchChlDistance = nan m
2019-07-27T06:19:54.032Z,1564208394.032 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakOil = 0.000000 kg/m3
2019-07-27T06:19:54.040Z,1564208394.040 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakOilDepth = 0.000000 m
2019-07-27T06:19:54.087Z,1564208394.087 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakOilLatitude = nan arcdeg
2019-07-27T06:19:54.090Z,1564208394.090 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakOilLongitude = nan arcdeg
2019-07-27T06:19:54.093Z,1564208394.093 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakFDOM = 0.000000 ppb
2019-07-27T06:19:54.112Z,1564208394.112 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakFDOMDepth = 0.000000 m
2019-07-27T06:19:54.115Z,1564208394.115 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakFDOMLatitude = nan arcdeg
2019-07-27T06:19:54.118Z,1564208394.118 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakFDOMLongitude = nan arcdeg
2019-07-27T06:19:54.141Z,1564208394.141 [MissionManager](INFO): DefineOutput esp_kiss:Science.PatchFDOMDistance = nan m
2019-07-27T06:19:54.169Z,1564208394.169 [esp_kiss:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2019-07-27T06:19:54.195Z,1564208394.195 [esp_kiss:Science:HighestChlPeakReport:A.PeakDetectHorizontal](DEBUG): Construct PeakDetectHorizontal.
2019-07-27T06:19:54.224Z,1564208394.224 [esp_kiss:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2019-07-27T06:19:54.246Z,1564208394.246 [esp_kiss:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2019-07-27T06:19:54.268Z,1564208394.268 [esp_kiss:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2019-07-27T06:19:54.290Z,1564208394.290 [esp_kiss:InitialDive:C.Pitch](DEBUG): Construct.
2019-07-27T06:19:54.312Z,1564208394.312 [esp_kiss:InitialDive:D.Point](DEBUG): Construct.
2019-07-27T06:19:54.318Z,1564208394.318 [esp_kiss:InitialDive:E.Buoyancy](DEBUG): Construct Buoyancy.
2019-07-27T06:19:54.336Z,1564208394.336 [esp_kiss:InitialDive:G.Wait](DEBUG): Construct Wait.
2019-07-27T06:19:54.348Z,1564208394.348 [esp_kiss:InitialDive:ApproachDepth:A.SetSpeed](DEBUG): Construct.
2019-07-27T06:19:54.359Z,1564208394.359 [esp_kiss:InitialDive:ApproachDepth:B.Pitch](DEBUG): Construct.
2019-07-27T06:19:54.367Z,1564208394.367 [esp_kiss:InitialDive:ApproachDepth:B.Pitch:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-07-27T06:19:54.397Z,1564208394.397 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:B.Pitch](DEBUG): Construct.
2019-07-27T06:19:54.419Z,1564208394.419 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:C.Wait](DEBUG): Construct Wait.
2019-07-27T06:19:54.421Z,1564208394.421 [esp_kiss:SampleAtTargetDepth:A.SetSpeed](DEBUG): Construct.
2019-07-27T06:19:54.424Z,1564208394.424 [esp_kiss:SampleAtTargetDepth:B.Pitch](DEBUG): Construct.
2019-07-27T06:19:54.439Z,1564208394.439 [esp_kiss:SampleAtTargetDepth:Spinout:HoldMassPosition.Pitch](DEBUG): Construct.
2019-07-27T06:19:54.446Z,1564208394.446 [esp_kiss:SampleAtTargetDepth:Spinout:HoldBuoyancyPosition.Buoyancy](DEBUG): Construct Buoyancy.
2019-07-27T06:19:54.493Z,1564208394.493 [esp_kiss:SampleAtTargetDepth:Spinout:HoldRudderAngle.Point](DEBUG): Construct.
2019-07-27T06:19:54.637Z,1564208394.637 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>

<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd
                             Tethys/Science http://okeanids.mbari.org/tethys/Xml/Science.xsd"
       Id="esp_kiss">

    <Description>
        This mission takes ESP samples at the designated depth.
    </Description>

    <DefineArg Name="MissionTimeout"><Description>
        Maximum duration of mission.
    </Description><Units:hour/><Value>4</Value></DefineArg>

    <DefineArg Name="TargetDepth"><Description>
        Depth to sample at. Initialized to 3 m.
    </Description><Units:meter/><Value>3</Value></DefineArg>

    <DefineArg Name="ESPCartridgeType_1"><Description>
        Specifies ESP cartridge type code for sample# 1. Set to NaN to skip this sample.
    </Description><Units:count/><Value>-4</Value></DefineArg>

    <DefineArg Name="ESPCartridgeType_2"><Description>
        Specifies ESP cartridge type code for sample# 2. Set to NaN to skip this sample.
    </Description><Units:count/><Value>-9</Value></DefineArg>

    <DefineArg Name="ESPCartridgeType_3"><Description>
        Specifies ESP cartridge type code for sample# 3. Set to NaN to skip this sample.
    </Description><Units:count/><Value>NaN</Value></DefineArg>

    <DefineArg Name="ESPCartridgeType_4"><Description>
        Specifies ESP cartridge type code for sample# 4. Set to NaN to skip this sample.
    </Description><Units:count/><Value>NaN</Value></DefineArg>

    <DefineArg Name="SettleTime"><Description>
        How long to wait between samples. This starts *before* the first sample.
    </Description><Units:minute/><Value>3</Value></DefineArg>

    <DefineArg Name="Speed"><Description>
        Vehicle speed while sampling. Set to zero to maintain depth using VBS (drift).
    </Description><Units:meter_per_second/><Value>0</Value></DefineArg>

    <DefineArg Name="ApproachDepth"><Description>
        Depth for initial descent form the surface. Initialized to 3 m.
    </Description><Units:meter/><Value>3</Value></DefineArg>

    <DefineArg Name="ApproachSpeed"><Description>
        Vehicle speed for initial descent form the surface to target depth. Set to zero
        to disable the thruster and descend using VBS (drift).
    </Description><Units:meter_per_second/><Value>0.7</Value></DefineArg>

    <DefineArg Name="ApproachDepthRate"><Description>
        Descent depth rate (Positive depth rate means going down).
    </Description><Units:meter_per_second/><Value>0.05</Value></DefineArg>

    <DefineArg Name="ApproachPitchLimit"><Description>
        Max vehicle pitch (+/-) when decending from the surface.
    </Description><Units:degree/><Value>10</Value></DefineArg>

    <DefineArg Name="ApproachSettleTimePreDive"><Description>
        Time duration for the vehicle to pump down the VBS *BEFORE* leaving the surface.
    </Description><Units:second/><Value>90</Value></DefineArg>

    <DefineArg Name="ApproachSettleTimePostDive"><Description>
        Time duration for the vehicle to settele *AFTER* reaching the target depth.
    </Description><Units:second/><Value>0</Value></DefineArg>

    <DefineArg Name="ApproachDepthTimeout"><Description>
        Maximum time duration for the vehicle to reach the target depth.
    </Description><Units:minute/><Value>15</Value></DefineArg>

    <DefineArg Name="kpDepth"><Description>
        Dive loop proportional gain (applied only while the vehicle is descending to target depth).
    </Description><Units:radian_per_meter/><Value>0.07</Value></DefineArg>

    <DefineArg Name="DepthDeadband"><Description>
        How much vertical drift from the specified depth is allowed while sampling.
    </Description><Units:meter/><Value>0.01</Value></DefineArg>

    <DefineArg Name="MinAltitude"><Description>
        Minimum height above the sea floor for the entire mission.
    </Description><Units:meter/><Value>2</Value></DefineArg>

    <DefineArg Name="MaxDepth"><Description>
        Maximum allowable depth during the mission.
    </Description><Units:meter/><Value>5</Value></DefineArg>

    <DefineArg Name="MinOffshore"><Description>
        Minimum distance from the shoreline to maintain.
    </Description><Units:kilometer/><Value>1</Value></DefineArg>

    <DefineOutput Name="ESPCartridgeType"><Description>
        Mission parameter (don't change). Specifies ESP cartridge type code.
    </Description><Units:count/><Value>NaN</Value></DefineOutput>
    
    <!-- Mission timeout -->

    <Timeout Duration="MissionTimeout"/>

    <!-- Safety nets and surfacing behaviors -->

    <Trigger:AbortSample>
        <Parallel/>
    </Trigger:AbortSample>

    <Insert Filename="Insert/StandardEnvelopes.xml"/>

    <Assign><Sequence/><Arg Name="StandardEnvelopes:MaxDepth"/><Arg Name="MaxDepth"/></Assign>

    <Assign><Sequence/><Arg Name="StandardEnvelopes:MinAltitude"/><Arg Name="MinAltitude"/></Assign>

    <Assign><Sequence/><Arg Name="StandardEnvelopes:MinOffshore"/><Arg Name="MinOffshore"/></Assign>


    <Insert Filename="Insert/NeedComms.xml" Id="NeedComms"/>

    <Assign><Sequence/><Arg Name="NeedComms:DiveInterval"/><Arg Name="MissionTimeout"/></Assign>

    <Assign><Sequence/><Arg Name="NeedComms:WaitForPitchUp"/><Units:minute/><Value>0</Value></Assign>


    <Assign><Parallel/><Control:VerticalControl.depthDeadband/><Arg Name="DepthDeadband"/></Assign>

        
    <!-- Callable aggregate -->

    <Aggregate Id="SampleESP">
        
        <When>
            <Called/>
        </When>

        <Aggregate Id="sample">
            <Sequence/>

            <Syslog Severity="Important">At <Universal:depth/><Units:meter/>, settling for <Arg Name="SettleTime"/><Units:minute/></Syslog>

            <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="SettleTime"/></Setting>
            </Guidance:Wait>

            <Syslog Severity="Important">Requesting ESP cartridge type:<Arg Name="ESPCartridgeType"/><Units:count/></Syslog>

            <Assign><Sequence/><Science:ESPComponent.cartridge/><Arg Name="ESPCartridgeType"/></Assign>

            <ReadDatum Id="TriggerESP">
                <Science:ESPComponent.sampling/>
            </ReadDatum>

            <Syslog Severity="Important">ESP sampling at <Universal:depth/><Units:meter/> in <Science:CTD_NeilBrown.bin_mean_sea_water_temperature/><Units:celsius/> water with <Science:WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water/><Units:microgram_per_liter/>chlorophyll fluorescence.</Syslog>

            <ReadDatum Id="WaitForESP">
                <Science:ESPComponent.sample_number/>
            </ReadDatum>
        </Aggregate>

    </Aggregate>


    <!-- Start mission sequence -->

    <Call Id="StartingMission" RefId="NeedComms"/>
    
    <Insert Filename="Insert/Science.xml"></Insert>

    <Aggregate Id="InitialDive">
        <Description>
            Descend from the surface to approach depth at ApproachSpeed, limit pitch,
            depth-rate, and hold the rudder.
        </Description>

        <Sequence/>

        <Assign><Parallel/><Control:VerticalControl.pitchLimit/><Arg Name="ApproachPitchLimit"/></Assign>

        <Assign><Parallel/><Control:VerticalControl.kpDepth/><Arg Name="kpDepth"/></Assign>

        <Guidance:Pitch>
            <Parallel/>
            <Setting><Guidance:Pitch.massPosition/><Control:VerticalControl.massDefault/></Setting>
        </Guidance:Pitch>

        <Guidance:Point>
            <Parallel/>
            <Setting><Guidance:Point.rudderAngle/><Units:degree/><Value>13</Value></Setting>
        </Guidance:Point>
        
        <Guidance:Buoyancy>
            <Parallel/>
            <Setting><Guidance:Buoyancy.position/><Control:VerticalControl.buoyancyNeutral/></Setting>
        </Guidance:Buoyancy>

        <Syslog Severity="Info">Waiting for <Arg Name="ApproachSettleTimePreDive"/><Units:second/>while pumping down to neutral.</Syslog>

        <Guidance:Wait>
            <Description>Take a few moments to ensure the VBS reaches neutral.</Description>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Arg Name="ApproachSettleTimePreDive"/></Setting>
        </Guidance:Wait>

        <Syslog>Moving to <Arg Name="ApproachDepth"/><Units:meter/></Syslog>

        <Aggregate Id="ApproachDepth">

            <Sequence/>

            <Guidance:SetSpeed>
                <Parallel/>
                <Setting><Guidance:SetSpeed.speed/><Arg Name="ApproachSpeed"/></Setting>
            </Guidance:SetSpeed>

            <Guidance:Pitch>
                <Sequence/>

                <Timeout Duration="ApproachDepthTimeout">
                    <Syslog Severity="Important">Timed out while trying to reach target depth at current depth of <Universal:depth/><Units:meter/>.</Syslog>
                    <Guidance:Execute>
                        <Sequence/>
                        <Setting><Guidance:Execute.command/><String>stop</String></Setting>
                    </Guidance:Execute>
                </Timeout>

                <Setting><Guidance:Pitch.depth/><Arg Name="ApproachDepth"/></Setting>
                <Setting><Guidance:Pitch.depthRate/><Arg Name="ApproachDepthRate"/></Setting>
            </Guidance:Pitch>

            <Aggregate Id="SettleAtDepth">
                <Description>
                    Take a few more moments here to make sure the VBS reached neutral position and
                    the vechile is settled at the target depth.
                </Description>

                <Sequence/>

                <Syslog Severity="Info">Reached <Universal:depth/><Units:meter/>, settling for <Arg Name="ApproachSettleTimePostDive"/><Units:second/></Syslog>

                <Guidance:Pitch>
                    <Parallel/>
                    <Setting><Guidance:Pitch.depth/><Arg Name="ApproachDepth"/></Setting>
                    <Setting><Guidance:Pitch.depthRate/><Arg Name="ApproachDepthRate"/></Setting>
                </Guidance:Pitch>

                <Guidance:Wait>
                    <Sequence/>
                    <Setting><Guidance:Wait.duration/><Arg Name="ApproachSettleTimePostDive"/></Setting>
                </Guidance:Wait>

            </Aggregate>

        </Aggregate>

    </Aggregate>


    <Aggregate Id="SampleAtTargetDepth">
        <Description>
            Maintain target depth and acquire ESP samples.
        </Description>

        <Sequence/>

        <Guidance:SetSpeed>
            <Parallel/>
            <Setting><Guidance:SetSpeed.speed/><Arg Name="Speed"/></Setting>
        </Guidance:SetSpeed>

        <Guidance:Pitch>
            <Parallel/>
            <Setting><Guidance:Pitch.depth/><Arg Name="TargetDepth"/></Setting>
        </Guidance:Pitch>
        
        <Aggregate Id="Spinout">
            <Description>
                A speed has been specified, spin in circels while sampling.
            </Description>
            
            <While>
                <Arg Name="Speed"/><Gt><Units:meter_per_second/><Value>0.0</Value></Gt>
            </While>
            
            <Guidance:Pitch Id="HoldMassPosition">
                <Parallel/>
                <Setting><Guidance:Pitch.massPosition/><Control:VerticalControl.massDefault/></Setting>
            </Guidance:Pitch>
            
            <Guidance:Buoyancy Id="HoldBuoyancyPosition">
                <Parallel/>
                <Setting><Guidance:Buoyancy.position/><Control:VerticalControl.buoyancyNeutral/></Setting>
            </Guidance:Buoyancy>

            <Guidance:Point Id="HoldRudderAngle">
                <Setting><Guidance:Point.rudderAngle/><Units:degree/><Value>13</Value></Setting>
            </Guidance:Point>

        </Aggregate>

        <Aggregate Id="GrabSamples">

            <Sequence/>

            <Aggregate Id="Sample1">
                <Break>
                    <IsNaN><Arg Name="ESPCartridgeType_1"/></IsNaN>
                </Break>

                <Assign><Sequence/><Arg Name="ESPCartridgeType"/><Arg Name="ESPCartridgeType_1"/></Assign>

                <Call RefId="SampleESP"/>
            </Aggregate>


            <Aggregate Id="Sample2">
                <Break>
                    <IsNaN><Arg Name="ESPCartridgeType_2"/></IsNaN>
                </Break>

                <Assign><Sequence/><Arg Name="ESPCartridgeType"/><Arg Name="ESPCartridgeType_2"/></Assign>

                <Call RefId="SampleESP"/>
            </Aggregate>


            <Aggregate Id="Sample3">
                <Break>
                    <IsNaN><Arg Name="ESPCartridgeType_3"/></IsNaN>
                </Break>
                
                <Assign><Sequence/><Arg Name="ESPCartridgeType"/><Arg Name="ESPCartridgeType_3"/></Assign>
                
                <Call RefId="SampleESP"/>
            </Aggregate>


            <Aggregate Id="Sample4">
                <Break>
                    <IsNaN><Arg Name="ESPCartridgeType_4"/></IsNaN>
                </Break>

                <Assign><Sequence/><Arg Name="ESPCartridgeType"/><Arg Name="ESPCartridgeType_4"/></Assign>

                <Call RefId="SampleESP"/>
            </Aggregate>

        </Aggregate>

    </Aggregate>

</Mission>


2019-07-27T06:19:54.637Z,1564208394.637 [CommandLine](IMPORTANT): Loaded ./Missions/Science/esp_kiss.xml
2019-07-27T06:20:00.388Z,1564208400.388 [CommandLine](IMPORTANT): got command set esp_kiss.SettleTime 0.100000 minute
2019-07-27T06:20:00.388Z,1564208400.388 [CommandLine](IMPORTANT): got command set esp_kiss.ApproachSettleTimePreDive 1.000000 second
2019-07-27T06:20:00.389Z,1564208400.389 [CommandLine](IMPORTANT): got command run 
2019-07-27T06:20:00.392Z,1564208400.392 [CommandLine](IMPORTANT): Running 
2019-07-27T06:20:00.538Z,1564208400.538 [Default] Stopped
2019-07-27T06:20:00.538Z,1564208400.538 [Default](DEBUG): Aggregate::uninitialize Default
2019-07-27T06:20:00.538Z,1564208400.538 [Default:B.GoToSurface] Stopped
2019-07-27T06:20:00.538Z,1564208400.538 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-27T06:20:00.538Z,1564208400.538 [Default:CheckIn] Stopped
2019-07-27T06:20:00.538Z,1564208400.538 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-07-27T06:20:00.538Z,1564208400.538 [Default:CheckIn:Read_GPS] Stopped
2019-07-27T06:20:00.539Z,1564208400.539 [MissionManager](IMPORTANT): Started mission esp_kiss
2019-07-27T06:20:00.539Z,1564208400.539 [esp_kiss] Running Loop=1
2019-07-27T06:20:00.539Z,1564208400.539 [esp_kiss](DEBUG): Aggregate::initialize esp_kiss
2019-07-27T06:20:00.539Z,1564208400.539 [esp_kiss:A.AbortSample] Running Loop=1
2019-07-27T06:20:00.539Z,1564208400.539 [esp_kiss:A.AbortSample](INFO): Initializing AbortSample.
2019-07-27T06:20:00.539Z,1564208400.539 [esp_kiss:StandardEnvelopes] Running Loop=1
2019-07-27T06:20:00.539Z,1564208400.539 [esp_kiss:StandardEnvelopes](DEBUG): Aggregate::initialize esp_kiss:StandardEnvelopes
2019-07-27T06:20:00.539Z,1564208400.539 [esp_kiss:StandardEnvelopes:A.AltitudeEnvelope] Running Loop=1
2019-07-27T06:20:00.540Z,1564208400.540 [esp_kiss:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2019-07-27T06:20:00.540Z,1564208400.540 [esp_kiss:StandardEnvelopes:B.DepthEnvelope] Running Loop=1
2019-07-27T06:20:00.540Z,1564208400.540 [esp_kiss:StandardEnvelopes:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2019-07-27T06:20:00.540Z,1564208400.540 [esp_kiss:StandardEnvelopes:C.OffshoreEnvelope] Running Loop=1
2019-07-27T06:20:00.540Z,1564208400.540 [esp_kiss:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2019-07-27T06:20:00.540Z,1564208400.540 [esp_kiss:I] Running Loop=1
2019-07-27T06:20:00.540Z,1564208400.540 [esp_kiss:Science] Running Loop=1
2019-07-27T06:20:00.540Z,1564208400.540 [esp_kiss:Science](DEBUG): Aggregate::initialize esp_kiss:Science
2019-07-27T06:20:00.541Z,1564208400.541 [esp_kiss:Science:A] Running Loop=1
2019-07-27T06:20:00.541Z,1564208400.541 [esp_kiss:Science:B] Running Loop=1
2019-07-27T06:20:00.541Z,1564208400.541 [esp_kiss:Science:C] Running Loop=1
2019-07-27T06:20:00.541Z,1564208400.541 [esp_kiss:Science:D] Running Loop=1
2019-07-27T06:20:00.541Z,1564208400.541 [esp_kiss:Science:E] Running Loop=1
2019-07-27T06:20:00.541Z,1564208400.541 [esp_kiss:Science:F] Running Loop=1
2019-07-27T06:20:00.541Z,1564208400.541 [esp_kiss:Science:G] Running Loop=1
2019-07-27T06:20:00.541Z,1564208400.541 [esp_kiss:Science:H] Running Loop=1
2019-07-27T06:20:00.541Z,1564208400.541 [esp_kiss:Science:Read_Oil] Running Loop=1
2019-07-27T06:20:00.541Z,1564208400.541 [esp_kiss:Science:PeakDetectChl] Running Loop=1
2019-07-27T06:20:00.541Z,1564208400.541 [esp_kiss:Science:PeakDetectChl](DEBUG): Aggregate::initialize esp_kiss:Science:PeakDetectChl
2019-07-27T06:20:00.542Z,1564208400.542 [esp_kiss:Science:PeakDetectChl:A.PeakDetectVsDepth] Running Loop=1
2019-07-27T06:20:00.542Z,1564208400.542 [esp_kiss:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Initialize.
2019-07-27T06:20:00.544Z,1564208400.544 [esp_kiss:Science:HighestChlPeakReport] Running Loop=1
2019-07-27T06:20:00.544Z,1564208400.544 [esp_kiss:Science:HighestChlPeakReport](DEBUG): Aggregate::initialize esp_kiss:Science:HighestChlPeakReport
2019-07-27T06:20:00.544Z,1564208400.544 [esp_kiss:Science:HighestChlPeakReport:A.PeakDetectHorizontal] Running Loop=1
2019-07-27T06:20:00.544Z,1564208400.544 [esp_kiss:Science:HighestChlPeakReport:A.PeakDetectHorizontal](INFO): Initialize.
2019-07-27T06:20:00.545Z,1564208400.545 [esp_kiss:Science:PeakDetectNO3] Running Loop=1
2019-07-27T06:20:00.545Z,1564208400.545 [esp_kiss:Science:PeakDetectNO3](DEBUG): Aggregate::initialize esp_kiss:Science:PeakDetectNO3
2019-07-27T06:20:00.545Z,1564208400.545 [esp_kiss:Science:PeakDetectNO3:A.PeakDetectVsDepth] Running Loop=1
2019-07-27T06:20:00.545Z,1564208400.545 [esp_kiss:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Initialize.
2019-07-27T06:20:00.547Z,1564208400.547 [esp_kiss:Science:PeakDetectOil] Running Loop=1
2019-07-27T06:20:00.547Z,1564208400.547 [esp_kiss:Science:PeakDetectOil](DEBUG): Aggregate::initialize esp_kiss:Science:PeakDetectOil
2019-07-27T06:20:00.547Z,1564208400.547 [esp_kiss:Science:PeakDetectOil:A.PeakDetectVsDepth] Running Loop=1
2019-07-27T06:20:00.547Z,1564208400.547 [esp_kiss:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Initialize.
2019-07-27T06:20:00.549Z,1564208400.549 [esp_kiss:Science:PeakDetectFDOM] Running Loop=1
2019-07-27T06:20:00.549Z,1564208400.549 [esp_kiss:Science:PeakDetectFDOM](DEBUG): Aggregate::initialize esp_kiss:Science:PeakDetectFDOM
2019-07-27T06:20:00.549Z,1564208400.549 [esp_kiss:Science:PeakDetectFDOM:A.PeakDetectVsDepth] Running Loop=1
2019-07-27T06:20:00.549Z,1564208400.549 [esp_kiss:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Initialize.
2019-07-27T06:20:00.564Z,1564208400.564 [esp_kiss:C] Running Loop=1
2019-07-27T06:20:00.565Z,1564208400.565 [esp_kiss:Science] Running Loop=1
2019-07-27T06:20:00.569Z,1564208400.569 [esp_kiss:Science:PeakDetectFDOM] Stopped
2019-07-27T06:20:00.569Z,1564208400.569 [esp_kiss:Science:PeakDetectFDOM](DEBUG): Aggregate::uninitialize esp_kiss:Science:PeakDetectFDOM
2019-07-27T06:20:00.569Z,1564208400.569 [esp_kiss:Science:PeakDetectFDOM:A.PeakDetectVsDepth] Stopped
2019-07-27T06:20:00.569Z,1564208400.569 [esp_kiss:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2019-07-27T06:20:00.569Z,1564208400.569 [esp_kiss:Science:PeakDetectOil] Stopped
2019-07-27T06:20:00.570Z,1564208400.570 [esp_kiss:Science:PeakDetectOil](DEBUG): Aggregate::uninitialize esp_kiss:Science:PeakDetectOil
2019-07-27T06:20:00.570Z,1564208400.570 [esp_kiss:Science:PeakDetectOil:A.PeakDetectVsDepth] Stopped
2019-07-27T06:20:00.570Z,1564208400.570 [esp_kiss:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2019-07-27T06:20:00.570Z,1564208400.570 [esp_kiss:Science:PeakDetectNO3] Stopped
2019-07-27T06:20:00.570Z,1564208400.570 [esp_kiss:Science:PeakDetectNO3](DEBUG): Aggregate::uninitialize esp_kiss:Science:PeakDetectNO3
2019-07-27T06:20:00.570Z,1564208400.570 [esp_kiss:Science:PeakDetectNO3:A.PeakDetectVsDepth] Stopped
2019-07-27T06:20:00.570Z,1564208400.570 [esp_kiss:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2019-07-27T06:20:00.570Z,1564208400.570 [esp_kiss:Science:HighestChlPeakReport] Stopped
2019-07-27T06:20:00.570Z,1564208400.570 [esp_kiss:Science:HighestChlPeakReport](DEBUG): Aggregate::uninitialize esp_kiss:Science:HighestChlPeakReport
2019-07-27T06:20:00.570Z,1564208400.570 [esp_kiss:Science:HighestChlPeakReport:A.PeakDetectHorizontal] Stopped
2019-07-27T06:20:00.570Z,1564208400.570 [esp_kiss:Science:HighestChlPeakReport:A.PeakDetectHorizontal](DEBUG): Uninitialize.
2019-07-27T06:20:00.570Z,1564208400.570 [esp_kiss:Science:PeakDetectChl] Stopped
2019-07-27T06:20:00.571Z,1564208400.571 [esp_kiss:Science:PeakDetectChl](DEBUG): Aggregate::uninitialize esp_kiss:Science:PeakDetectChl
2019-07-27T06:20:00.571Z,1564208400.571 [esp_kiss:Science:PeakDetectChl:A.PeakDetectVsDepth] Stopped
2019-07-27T06:20:00.571Z,1564208400.571 [esp_kiss:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2019-07-27T06:20:00.571Z,1564208400.571 [esp_kiss:Science:Read_Oil] Stopped
2019-07-27T06:20:00.571Z,1564208400.571 [esp_kiss:Science:H] Stopped
2019-07-27T06:20:00.571Z,1564208400.571 [esp_kiss:Science:G] Stopped
2019-07-27T06:20:00.571Z,1564208400.571 [esp_kiss:Science:F] Stopped
2019-07-27T06:20:00.571Z,1564208400.571 [esp_kiss:Science:E] Stopped
2019-07-27T06:20:00.571Z,1564208400.571 [esp_kiss:Science:D] Stopped
2019-07-27T06:20:00.571Z,1564208400.571 [esp_kiss:Science:C] Stopped
2019-07-27T06:20:00.571Z,1564208400.571 [esp_kiss:Science:B] Stopped
2019-07-27T06:20:00.571Z,1564208400.571 [esp_kiss:Science:A] Stopped
2019-07-27T06:20:00.571Z,1564208400.571 [esp_kiss:I] Running Loop=1
2019-07-27T06:20:00.583Z,1564208400.583 [esp_kiss:C] Stopped
2019-07-27T06:20:00.583Z,1564208400.583 [esp_kiss:D] Running Loop=1
2019-07-27T06:20:00.583Z,1564208400.583 [esp_kiss:StandardEnvelopes] Running Loop=1
2019-07-27T06:20:00.583Z,1564208400.583 [esp_kiss:StandardEnvelopes:C.OffshoreEnvelope] Running Loop=1
2019-07-27T06:20:00.584Z,1564208400.584 [esp_kiss:StandardEnvelopes:B.DepthEnvelope] Running Loop=1
2019-07-27T06:20:00.585Z,1564208400.585 [esp_kiss:StandardEnvelopes:A.AltitudeEnvelope] Running Loop=1
2019-07-27T06:20:00.585Z,1564208400.585 [esp_kiss:A.AbortSample] Running Loop=1
2019-07-27T06:20:00.951Z,1564208400.951 [esp_kiss:D] Stopped
2019-07-27T06:20:00.951Z,1564208400.951 [esp_kiss:E] Running Loop=1
2019-07-27T06:20:01.350Z,1564208401.350 [esp_kiss:E] Stopped
2019-07-27T06:20:01.351Z,1564208401.351 [esp_kiss:G] Running Loop=1
2019-07-27T06:20:01.748Z,1564208401.748 [esp_kiss:G] Stopped
2019-07-27T06:20:01.748Z,1564208401.748 [esp_kiss:H] Running Loop=1
2019-07-27T06:20:02.171Z,1564208402.171 [esp_kiss:H] Stopped
2019-07-27T06:20:02.171Z,1564208402.171 [esp_kiss:StartingMission] Running Loop=1
2019-07-27T06:20:02.171Z,1564208402.171 [esp_kiss:StartingMission](DEBUG): Aggregate::initialize esp_kiss:StartingMission
2019-07-27T06:20:02.172Z,1564208402.172 [esp_kiss:StandardEnvelopes:A.AltitudeEnvelope](ERROR): Altitude Measurement is not Active.
2019-07-27T06:20:02.574Z,1564208402.574 [esp_kiss:NeedComms] Running Loop=1
2019-07-27T06:20:02.574Z,1564208402.574 [esp_kiss:NeedComms](DEBUG): Aggregate::initialize esp_kiss:NeedComms
2019-07-27T06:20:02.574Z,1564208402.574 [esp_kiss:NeedComms:B.GoToSurface] Running Loop=1
2019-07-27T06:20:02.574Z,1564208402.574 [esp_kiss:NeedComms:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-27T06:20:02.575Z,1564208402.575 [esp_kiss:NeedComms:B.GoToSurface](INFO): Received depth rate setting nan m/s.
2019-07-27T06:20:02.575Z,1564208402.575 [esp_kiss:NeedComms:B.GoToSurface](INFO): Received pitch setting 19.999999 degrees.
2019-07-27T06:20:02.575Z,1564208402.575 [esp_kiss:NeedComms:B.GoToSurface](INFO): Received speed setting 1.000000 m/s.
2019-07-27T06:20:02.576Z,1564208402.576 [esp_kiss:NeedComms:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-27T06:20:02.576Z,1564208402.576 [esp_kiss:NeedComms:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-27T06:20:02.576Z,1564208402.576 [esp_kiss:NeedComms:A] Running Loop=1
2019-07-27T06:20:02.577Z,1564208402.577 [esp_kiss:NeedComms:A](INFO): last time_fix was: 1564208256.000000 second since 1970/01/01T00:00:00Z 
2019-07-27T06:20:02.577Z,1564208402.577 [esp_kiss:NeedComms:A] Stopped
2019-07-27T06:20:02.979Z,1564208402.979 [esp_kiss:NeedComms:C] Running Loop=1
2019-07-27T06:20:03.387Z,1564208403.387 [esp_kiss:NeedComms:C](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-07-27T06:20:13.084Z,1564208413.084 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-07-27T06:20:13.084Z,1564208413.084 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-07-27T06:20:13.084Z,1564208413.084 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-27T06:20:13.097Z,1564208413.097 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-27T06:20:13.498Z,1564208413.498 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-27T06:20:13.498Z,1564208413.498 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-07-27T06:20:56.279Z,1564208456.279 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-07-27T06:20:57.087Z,1564208457.087 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:21:01.535Z,1564208461.535 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:21:03.555Z,1564208463.555 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:21:06.787Z,1564208466.787 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:21:09.615Z,1564208469.615 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:21:12.843Z,1564208472.843 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:21:15.675Z,1564208475.675 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:21:18.903Z,1564208478.903 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:21:21.731Z,1564208481.731 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:21:24.563Z,1564208484.563 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:21:26.579Z,1564208486.579 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:21:29.815Z,1564208489.815 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:21:32.643Z,1564208492.643 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:21:35.871Z,1564208495.871 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:21:38.703Z,1564208498.703 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:21:41.935Z,1564208501.935 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:21:44.763Z,1564208504.763 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:21:47.595Z,1564208507.595 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:21:49.607Z,1564208509.607 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:21:51.627Z,1564208511.627 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:21:54.863Z,1564208514.863 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:21:57.691Z,1564208517.691 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:21:58.305Z,1564208518.305 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1564208512.000000 second
2019-07-27T06:21:58.532Z,1564208518.532 [esp_kiss:NeedComms:C] Stopped
2019-07-27T06:21:58.532Z,1564208518.532 [esp_kiss:NeedComms:D] Running Loop=1
2019-07-27T06:21:58.919Z,1564208518.919 [esp_kiss:NeedComms:D](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-07-27T06:22:04.294Z,1564208524.294 [DataOverHttps](INFO): Sending 146 bytes from file Logs/20190727T061504/Courier0004.lzma
2019-07-27T06:22:05.100Z,1564208525.100 [DataOverHttps](INFO): Moved sent file to Logs/20190727T061504/Courier0004.lzma.bak
2019-07-27T06:22:05.100Z,1564208525.100 [DataOverHttps](INFO): SBD MOMSN=11479629
2019-07-27T06:22:14.287Z,1564208534.287 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-07-27T06:22:14.287Z,1564208534.287 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-07-27T06:22:14.287Z,1564208534.287 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-27T06:22:14.300Z,1564208534.300 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-27T06:22:14.690Z,1564208534.690 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-27T06:22:14.691Z,1564208534.691 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-07-27T06:22:16.096Z,1564208536.096 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1564208512.000000 second
2019-07-27T06:22:16.562Z,1564208536.562 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20190727T061504/Courier0007.lzma
2019-07-27T06:22:17.368Z,1564208537.368 [DataOverHttps](INFO): Moved sent file to Logs/20190727T061504/Courier0007.lzma.bak
2019-07-27T06:22:17.368Z,1564208537.368 [DataOverHttps](INFO): SBD MOMSN=11479631
2019-07-27T06:22:29.079Z,1564208549.079 [DataOverHttps](INFO): Sending 793 bytes from file Logs/20190727T061504/Express0005.lzma
2019-07-27T06:22:29.884Z,1564208549.884 [DataOverHttps](INFO): Moved sent file to Logs/20190727T061504/Express0005.lzma.bak
2019-07-27T06:22:29.884Z,1564208549.884 [DataOverHttps](INFO): SBD MOMSN=11479633
2019-07-27T06:22:30.803Z,1564208550.803 [NAL9602](INFO): Not Powering down - fast GPS
2019-07-27T06:22:40.196Z,1564208560.196 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1564208512.000000 second
2019-07-27T06:22:41.674Z,1564208561.674 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20190727T061504/Express0009.lzma
2019-07-27T06:22:42.480Z,1564208562.480 [DataOverHttps](INFO): Moved sent file to Logs/20190727T061504/Express0009.lzma.bak
2019-07-27T06:22:42.480Z,1564208562.480 [DataOverHttps](INFO): SBD MOMSN=11479656
2019-07-27T06:22:42.556Z,1564208562.556 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-07-27T06:22:42.559Z,1564208562.559 [BPC1](INFO): Received data from all battery sticks.
2019-07-27T06:22:44.202Z,1564208564.202 [esp_kiss:NeedComms:D] Stopped
2019-07-27T06:22:44.202Z,1564208564.202 [esp_kiss:NeedComms:E] Running Loop=1
2019-07-27T06:22:44.581Z,1564208564.581 [esp_kiss:NeedComms:E](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-07-27T06:22:45.763Z,1564208565.763 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:23:06.141Z,1564208586.141 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1564208512.000000 second
2019-07-27T06:23:06.380Z,1564208586.380 [esp_kiss:NeedComms:E] Stopped
2019-07-27T06:23:06.381Z,1564208586.381 [esp_kiss:NeedComms](INFO): Completed esp_kiss:NeedComms
2019-07-27T06:23:06.381Z,1564208586.381 [esp_kiss:NeedComms] Stopped
2019-07-27T06:23:06.381Z,1564208586.381 [esp_kiss:NeedComms](DEBUG): Aggregate::uninitialize esp_kiss:NeedComms
2019-07-27T06:23:06.381Z,1564208586.381 [esp_kiss:NeedComms:B.GoToSurface] Stopped
2019-07-27T06:23:06.381Z,1564208586.381 [esp_kiss:NeedComms:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-27T06:23:06.786Z,1564208586.786 [esp_kiss:StartingMission](INFO): Completed esp_kiss:StartingMission
2019-07-27T06:23:06.786Z,1564208586.786 [esp_kiss:StartingMission] Stopped
2019-07-27T06:23:06.786Z,1564208586.786 [esp_kiss:StartingMission](DEBUG): Aggregate::uninitialize esp_kiss:StartingMission
2019-07-27T06:23:06.786Z,1564208586.786 [esp_kiss:InitialDive] Running Loop=1
2019-07-27T06:23:06.787Z,1564208586.787 [esp_kiss:InitialDive](DEBUG): Aggregate::initialize esp_kiss:InitialDive
2019-07-27T06:23:06.787Z,1564208586.787 [esp_kiss:InitialDive:A] Running Loop=1
2019-07-27T06:23:06.787Z,1564208586.787 [esp_kiss:InitialDive:B] Running Loop=1
2019-07-27T06:23:06.787Z,1564208586.787 [esp_kiss:InitialDive:C.Pitch] Running Loop=1
2019-07-27T06:23:06.787Z,1564208586.787 [esp_kiss:InitialDive:C.Pitch](DEBUG): Initialize.
2019-07-27T06:23:06.787Z,1564208586.787 [esp_kiss:InitialDive:D.Point] Running Loop=1
2019-07-27T06:23:06.787Z,1564208586.787 [esp_kiss:InitialDive:D.Point](DEBUG): Initialize.
2019-07-27T06:23:06.787Z,1564208586.787 [esp_kiss:InitialDive:E.Buoyancy] Running Loop=1
2019-07-27T06:23:06.787Z,1564208586.787 [esp_kiss:InitialDive:E.Buoyancy](DEBUG): Initialize Buoyancy Component.
2019-07-27T06:23:06.788Z,1564208586.788 [esp_kiss:InitialDive:F] Running Loop=1
2019-07-27T06:23:07.190Z,1564208587.190 [esp_kiss:InitialDive:F](INFO): Waiting for 1.000000 s while pumping down to neutral.
2019-07-27T06:23:07.190Z,1564208587.190 [esp_kiss:InitialDive:F] Stopped
2019-07-27T06:23:07.190Z,1564208587.190 [esp_kiss:InitialDive:G.Wait] Running Loop=1
2019-07-27T06:23:07.190Z,1564208587.190 [esp_kiss:InitialDive:G.Wait](DEBUG): Initialize Wait Component.
2019-07-27T06:23:07.190Z,1564208587.190 [esp_kiss:InitialDive:E.Buoyancy] Running Loop=1
2019-07-27T06:23:07.190Z,1564208587.190 [esp_kiss:InitialDive:D.Point] Running Loop=1
2019-07-27T06:23:07.191Z,1564208587.191 [esp_kiss:InitialDive:C.Pitch] Running Loop=1
2019-07-27T06:23:07.191Z,1564208587.191 [esp_kiss:InitialDive:B] Running Loop=1
2019-07-27T06:23:07.192Z,1564208587.192 [esp_kiss:InitialDive:A] Running Loop=1
2019-07-27T06:23:08.810Z,1564208588.810 [esp_kiss:InitialDive:G.Wait](INFO): Done Waiting.
2019-07-27T06:23:08.810Z,1564208588.810 [esp_kiss:InitialDive:G.Wait] Stopped
2019-07-27T06:23:08.810Z,1564208588.810 [esp_kiss:InitialDive:G.Wait](DEBUG): Uninitialize Wait Component.
2019-07-27T06:23:08.810Z,1564208588.810 [esp_kiss:InitialDive:H] Running Loop=1
2019-07-27T06:23:09.221Z,1564208589.221 [esp_kiss:InitialDive:H](INFO): Moving to 3.000000 m 
2019-07-27T06:23:09.221Z,1564208589.221 [esp_kiss:InitialDive:H] Stopped
2019-07-27T06:23:09.221Z,1564208589.221 [esp_kiss:InitialDive:ApproachDepth] Running Loop=1
2019-07-27T06:23:09.221Z,1564208589.221 [esp_kiss:InitialDive:ApproachDepth](DEBUG): Aggregate::initialize esp_kiss:InitialDive:ApproachDepth
2019-07-27T06:23:09.221Z,1564208589.221 [esp_kiss:InitialDive:ApproachDepth:A.SetSpeed] Running Loop=1
2019-07-27T06:23:09.221Z,1564208589.221 [esp_kiss:InitialDive:ApproachDepth:A.SetSpeed](DEBUG): Initialize.
2019-07-27T06:23:09.222Z,1564208589.222 [esp_kiss:InitialDive:ApproachDepth:B.Pitch] Running Loop=1
2019-07-27T06:23:09.222Z,1564208589.222 [esp_kiss:InitialDive:ApproachDepth:B.Pitch](DEBUG): Initialize.
2019-07-27T06:23:09.606Z,1564208589.606 [esp_kiss:InitialDive:ApproachDepth:A.SetSpeed] Running Loop=1
2019-07-27T06:23:16.293Z,1564208596.293 [CommandLine](IMPORTANT): got command maintain sensor DepthRateCalculator.depth_rate 0.001000 meter_per_second
2019-07-27T06:23:16.294Z,1564208596.294 [ComponentRegistry](DEBUG): SyncComponent "Maintain_DepthRateCalculator.depth_rate" handled in the control thread.
2019-07-27T06:23:16.295Z,1564208596.295 [CommandLine](IMPORTANT): got command maintain sensor Depth_Keller.depth 3.000000 meter
2019-07-27T06:23:16.296Z,1564208596.296 [ComponentRegistry](DEBUG): SyncComponent "Maintain_Depth_Keller.depth" handled in the control thread.
2019-07-27T06:23:16.565Z,1564208596.565 [controlThread](DEBUG): Component order: CycleStarter,Depth_Keller,NAL9602,Onboard,BPC1,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,Maintain_NAL9602.latitude_fix,Maintain_NAL9602.longitude_fix,Maintain_DepthRateCalculator.depth_rate,Maintain_Depth_Keller.depth,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-07-27T06:23:16.860Z,1564208596.860 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-07-27T06:23:16.943Z,1564208596.943 [NAL9602](FAULT): received: 
+CSQ:0

OK
2019-07-27T06:23:16.943Z,1564208596.943 [NAL9602] Data Fault, FailCount= 1
2019-07-27T06:23:16.943Z,1564208596.943 [NAL9602](ERROR): Data Fault
2019-07-27T06:23:16.971Z,1564208596.971 [esp_kiss:InitialDive:ApproachDepth:B.Pitch] Stopped
2019-07-27T06:23:16.972Z,1564208596.972 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth] Running Loop=1
2019-07-27T06:23:16.972Z,1564208596.972 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth](DEBUG): Aggregate::initialize esp_kiss:InitialDive:ApproachDepth:SettleAtDepth
2019-07-27T06:23:16.972Z,1564208596.972 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:B.Pitch] Running Loop=1
2019-07-27T06:23:16.972Z,1564208596.972 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:B.Pitch](DEBUG): Initialize.
2019-07-27T06:23:16.973Z,1564208596.973 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:A] Running Loop=1
2019-07-27T06:23:16.975Z,1564208596.975 [esp_kiss:NeedComms] Running Loop=1
2019-07-27T06:23:16.975Z,1564208596.975 [esp_kiss:NeedComms](DEBUG): Aggregate::initialize esp_kiss:NeedComms
2019-07-27T06:23:16.975Z,1564208596.975 [esp_kiss:NeedComms:B.GoToSurface] Running Loop=1
2019-07-27T06:23:16.975Z,1564208596.975 [esp_kiss:NeedComms:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-27T06:23:16.976Z,1564208596.976 [esp_kiss:NeedComms:B.GoToSurface](INFO): Received depth rate setting nan m/s.
2019-07-27T06:23:16.976Z,1564208596.976 [esp_kiss:NeedComms:B.GoToSurface](INFO): Received pitch setting 19.999999 degrees.
2019-07-27T06:23:16.976Z,1564208596.976 [esp_kiss:NeedComms:B.GoToSurface](INFO): Received speed setting 1.000000 m/s.
2019-07-27T06:23:16.977Z,1564208596.977 [esp_kiss:NeedComms:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-27T06:23:16.977Z,1564208596.977 [esp_kiss:NeedComms:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-27T06:23:16.977Z,1564208596.977 [esp_kiss:NeedComms:A] Running Loop=1
2019-07-27T06:23:16.980Z,1564208596.980 [esp_kiss:NeedComms:A](ERROR): caught uninitialized data element exception.
2019-07-27T06:23:16.980Z,1564208596.980 [esp_kiss:NeedComms:A](INFO): last time_fix was: nan second since 1970/01/01T00:00:00Z 
2019-07-27T06:23:16.980Z,1564208596.980 [esp_kiss:NeedComms:A] Stopped
2019-07-27T06:23:17.067Z,1564208597.067 [CBIT](ERROR): Data Fault in component: NAL9602
2019-07-27T06:23:17.264Z,1564208597.264 [NAL9602](INFO): Powering down
2019-07-27T06:23:17.294Z,1564208597.294 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:B.Pitch] Running Loop=1
2019-07-27T06:23:17.295Z,1564208597.295 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:A](INFO): Reached 3.000000 m , settling for 0.000000 s 
2019-07-27T06:23:17.296Z,1564208597.296 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:A] Stopped
2019-07-27T06:23:17.296Z,1564208597.296 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:C.Wait] Running Loop=1
2019-07-27T06:23:17.296Z,1564208597.296 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:C.Wait](DEBUG): Initialize Wait Component.
2019-07-27T06:23:17.693Z,1564208597.693 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:C.Wait](INFO): Done Waiting.
2019-07-27T06:23:17.693Z,1564208597.693 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:C.Wait] Stopped
2019-07-27T06:23:17.693Z,1564208597.693 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:C.Wait](DEBUG): Uninitialize Wait Component.
2019-07-27T06:23:17.693Z,1564208597.693 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth](INFO): Completed esp_kiss:InitialDive:ApproachDepth:SettleAtDepth
2019-07-27T06:23:17.694Z,1564208597.694 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth] Stopped
2019-07-27T06:23:17.694Z,1564208597.694 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth](DEBUG): Aggregate::uninitialize esp_kiss:InitialDive:ApproachDepth:SettleAtDepth
2019-07-27T06:23:17.694Z,1564208597.694 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:B.Pitch] Stopped
2019-07-27T06:23:17.694Z,1564208597.694 [esp_kiss:InitialDive:ApproachDepth](INFO): Completed esp_kiss:InitialDive:ApproachDepth
2019-07-27T06:23:17.694Z,1564208597.694 [esp_kiss:InitialDive:ApproachDepth] Stopped
2019-07-27T06:23:17.694Z,1564208597.694 [esp_kiss:InitialDive:ApproachDepth](DEBUG): Aggregate::uninitialize esp_kiss:InitialDive:ApproachDepth
2019-07-27T06:23:17.694Z,1564208597.694 [esp_kiss:InitialDive:ApproachDepth:A.SetSpeed] Stopped
2019-07-27T06:23:17.694Z,1564208597.694 [esp_kiss:InitialDive:ApproachDepth:A.SetSpeed](DEBUG): Uninitialize.
2019-07-27T06:23:17.696Z,1564208597.696 [esp_kiss:InitialDive](INFO): Completed esp_kiss:InitialDive
2019-07-27T06:23:17.696Z,1564208597.696 [esp_kiss:InitialDive] Stopped
2019-07-27T06:23:17.696Z,1564208597.696 [esp_kiss:InitialDive](DEBUG): Aggregate::uninitialize esp_kiss:InitialDive
2019-07-27T06:23:17.696Z,1564208597.696 [esp_kiss:InitialDive:A] Stopped
2019-07-27T06:23:17.696Z,1564208597.696 [esp_kiss:InitialDive:B] Stopped
2019-07-27T06:23:17.696Z,1564208597.696 [esp_kiss:InitialDive:C.Pitch] Stopped
2019-07-27T06:23:17.696Z,1564208597.696 [esp_kiss:InitialDive:D.Point] Stopped
2019-07-27T06:23:17.696Z,1564208597.696 [esp_kiss:InitialDive:E.Buoyancy] Stopped
2019-07-27T06:23:17.696Z,1564208597.696 [esp_kiss:InitialDive:E.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2019-07-27T06:23:17.696Z,1564208597.696 [esp_kiss:SampleAtTargetDepth] Running Loop=1
2019-07-27T06:23:17.696Z,1564208597.696 [esp_kiss:SampleAtTargetDepth](DEBUG): Aggregate::initialize esp_kiss:SampleAtTargetDepth
2019-07-27T06:23:17.696Z,1564208597.696 [esp_kiss:SampleAtTargetDepth:A.SetSpeed] Running Loop=1
2019-07-27T06:23:17.697Z,1564208597.697 [esp_kiss:SampleAtTargetDepth:A.SetSpeed](DEBUG): Initialize.
2019-07-27T06:23:17.697Z,1564208597.697 [esp_kiss:SampleAtTargetDepth:B.Pitch] Running Loop=1
2019-07-27T06:23:17.697Z,1564208597.697 [esp_kiss:SampleAtTargetDepth:B.Pitch](DEBUG): Initialize.
2019-07-27T06:23:17.697Z,1564208597.697 [esp_kiss:SampleAtTargetDepth:Spinout] Running Loop=1
2019-07-27T06:23:17.697Z,1564208597.697 [esp_kiss:SampleAtTargetDepth:Spinout](DEBUG): Aggregate::initialize esp_kiss:SampleAtTargetDepth:Spinout
2019-07-27T06:23:17.697Z,1564208597.697 [esp_kiss:SampleAtTargetDepth:Spinout:HoldMassPosition.Pitch] Running Loop=1
2019-07-27T06:23:17.697Z,1564208597.697 [esp_kiss:SampleAtTargetDepth:Spinout:HoldMassPosition.Pitch](DEBUG): Initialize.
2019-07-27T06:23:17.697Z,1564208597.697 [esp_kiss:SampleAtTargetDepth:Spinout:HoldBuoyancyPosition.Buoyancy] Running Loop=1
2019-07-27T06:23:17.697Z,1564208597.697 [esp_kiss:SampleAtTargetDepth:Spinout:HoldBuoyancyPosition.Buoyancy](DEBUG): Initialize Buoyancy Component.
2019-07-27T06:23:17.697Z,1564208597.697 [esp_kiss:SampleAtTargetDepth:Spinout:HoldRudderAngle.Point] Running Loop=1
2019-07-27T06:23:17.698Z,1564208597.698 [esp_kiss:SampleAtTargetDepth:Spinout:HoldRudderAngle.Point](DEBUG): Initialize.
2019-07-27T06:23:17.698Z,1564208597.698 [esp_kiss:SampleAtTargetDepth:GrabSamples] Running Loop=1
2019-07-27T06:23:17.698Z,1564208597.698 [esp_kiss:SampleAtTargetDepth:GrabSamples](DEBUG): Aggregate::initialize esp_kiss:SampleAtTargetDepth:GrabSamples
2019-07-27T06:23:17.698Z,1564208597.698 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1] Running Loop=1
2019-07-27T06:23:17.698Z,1564208597.698 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1](DEBUG): Aggregate::initialize esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1
2019-07-27T06:23:17.698Z,1564208597.698 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1:A] Running Loop=1
2019-07-27T06:23:18.098Z,1564208598.098 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1:A] Stopped
2019-07-27T06:23:18.098Z,1564208598.098 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1:B] Running Loop=1
2019-07-27T06:23:18.098Z,1564208598.098 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1:B](DEBUG): Aggregate::initialize esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1:B
2019-07-27T06:23:18.098Z,1564208598.098 [esp_kiss:SampleAtTargetDepth:Spinout] Stopped
2019-07-27T06:23:18.098Z,1564208598.098 [esp_kiss:SampleAtTargetDepth:Spinout](DEBUG): Aggregate::uninitialize esp_kiss:SampleAtTargetDepth:Spinout
2019-07-27T06:23:18.098Z,1564208598.098 [esp_kiss:SampleAtTargetDepth:Spinout:HoldMassPosition.Pitch] Stopped
2019-07-27T06:23:18.098Z,1564208598.098 [esp_kiss:SampleAtTargetDepth:Spinout:HoldBuoyancyPosition.Buoyancy] Stopped
2019-07-27T06:23:18.098Z,1564208598.098 [esp_kiss:SampleAtTargetDepth:Spinout:HoldBuoyancyPosition.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2019-07-27T06:23:18.098Z,1564208598.098 [esp_kiss:SampleAtTargetDepth:Spinout:HoldRudderAngle.Point] Stopped
2019-07-27T06:23:18.098Z,1564208598.098 [esp_kiss:SampleAtTargetDepth:B.Pitch] Running Loop=1
2019-07-27T06:23:18.099Z,1564208598.099 [esp_kiss:SampleAtTargetDepth:A.SetSpeed] Running Loop=1
2019-07-27T06:23:18.151Z,1564208598.151 [CBIT](INFO): Clearing failed state for component NAL9602
2019-07-27T06:23:18.151Z,1564208598.151 [NAL9602] No Fault, FailCount= 1
2019-07-27T06:23:18.503Z,1564208598.503 [esp_kiss:SampleESP] Running Loop=1
2019-07-27T06:23:18.503Z,1564208598.503 [esp_kiss:SampleESP](DEBUG): Aggregate::initialize esp_kiss:SampleESP
2019-07-27T06:23:18.504Z,1564208598.504 [esp_kiss:SampleESP:sample] Running Loop=1
2019-07-27T06:23:18.504Z,1564208598.504 [esp_kiss:SampleESP:sample](DEBUG): Aggregate::initialize esp_kiss:SampleESP:sample
2019-07-27T06:23:18.504Z,1564208598.504 [esp_kiss:SampleESP:sample:A] Running Loop=1
2019-07-27T06:23:18.505Z,1564208598.505 [esp_kiss:SampleESP:sample:A](IMPORTANT): At 3.000000 m , settling for 0.100000 min 
2019-07-27T06:23:18.505Z,1564208598.505 [esp_kiss:SampleESP:sample:A] Stopped
2019-07-27T06:23:18.505Z,1564208598.505 [esp_kiss:SampleESP:sample:B.Wait] Running Loop=1
2019-07-27T06:23:18.505Z,1564208598.505 [esp_kiss:SampleESP:sample:B.Wait](DEBUG): Initialize Wait Component.
2019-07-27T06:23:24.967Z,1564208604.967 [esp_kiss:SampleESP:sample:B.Wait](INFO): Done Waiting.
2019-07-27T06:23:24.967Z,1564208604.967 [esp_kiss:SampleESP:sample:B.Wait] Stopped
2019-07-27T06:23:24.967Z,1564208604.967 [esp_kiss:SampleESP:sample:B.Wait](DEBUG): Uninitialize Wait Component.
2019-07-27T06:23:24.967Z,1564208604.967 [esp_kiss:SampleESP:sample:C] Running Loop=1
2019-07-27T06:23:25.371Z,1564208605.371 [esp_kiss:SampleESP:sample:C](IMPORTANT): Requesting ESP cartridge type: -4.000000 count 
2019-07-27T06:23:25.371Z,1564208605.371 [esp_kiss:SampleESP:sample:C] Stopped
2019-07-27T06:23:25.371Z,1564208605.371 [esp_kiss:SampleESP:sample:D] Running Loop=1
2019-07-27T06:23:25.779Z,1564208605.779 [esp_kiss:SampleESP:sample:D] Stopped
2019-07-27T06:23:25.780Z,1564208605.780 [esp_kiss:SampleESP:sample:TriggerESP] Running Loop=1
2019-07-27T06:23:26.184Z,1564208606.184 [esp_kiss:SampleESP:sample:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling
2019-07-27T06:23:26.979Z,1564208606.979 [ESPComponent](IMPORTANT): Setting regex for ESP Log summary: 'Selecting Cartridge|Sampled|Error|Underpressure|Overpressure|Fail|Retry|Cmd::|Sampler::'
2019-07-27T06:23:26.982Z,1564208606.982 [ESPComponent](INFO): compiled regex: "Selecting Cartridge|Sampled|Error|Underpressure|Overpressure|Fail|Retry|Cmd::|Sampler::"
2019-07-27T06:23:27.379Z,1564208607.379 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:28.191Z,1564208608.191 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:28.993Z,1564208608.993 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:29.805Z,1564208609.805 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:30.614Z,1564208610.614 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:31.417Z,1564208611.417 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:32.230Z,1564208612.230 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:33.038Z,1564208613.038 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:33.839Z,1564208613.839 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:34.649Z,1564208614.649 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:35.463Z,1564208615.463 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:36.263Z,1564208616.263 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:37.078Z,1564208617.078 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:37.886Z,1564208617.886 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:38.689Z,1564208618.689 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:39.501Z,1564208619.501 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:40.310Z,1564208620.310 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:41.114Z,1564208621.114 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:41.922Z,1564208621.922 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:42.733Z,1564208622.733 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:43.542Z,1564208623.542 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:44.346Z,1564208624.346 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:45.158Z,1564208625.158 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:45.962Z,1564208625.962 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:46.767Z,1564208626.767 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:47.568Z,1564208627.568 [NAL9602](INFO): Powering up NAL9602
2019-07-27T06:23:47.583Z,1564208627.583 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:48.383Z,1564208628.383 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:49.194Z,1564208629.194 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:50.006Z,1564208630.006 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:50.814Z,1564208630.814 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:51.618Z,1564208631.618 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:52.426Z,1564208632.426 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:53.238Z,1564208633.238 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:54.042Z,1564208634.042 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:54.851Z,1564208634.851 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:55.655Z,1564208635.655 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:56.469Z,1564208636.469 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:57.279Z,1564208637.279 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:58.094Z,1564208638.094 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:58.476Z,1564208638.476 [NAL9602](INFO): NAL9602 initialized
2019-07-27T06:23:58.891Z,1564208638.891 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:23:59.701Z,1564208639.701 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:24:00.503Z,1564208640.503 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:24:00.764Z,1564208640.764 [CommandLine](IMPORTANT): got command stop
2019-07-27T06:24:00.764Z,1564208640.764 [CommandLine](IMPORTANT): Scheduling is paused
2019-07-27T06:24:00.765Z,1564208640.765 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-07-27T06:24:00.929Z,1564208640.929 [MissionManager](INFO): MissionManager is completed.
2019-07-27T06:24:00.930Z,1564208640.930 [MissionManager](INFO): Uninitializing Mission esp_kiss
2019-07-27T06:24:00.930Z,1564208640.930 [esp_kiss] Stopped
2019-07-27T06:24:00.930Z,1564208640.930 [esp_kiss](DEBUG): Aggregate::uninitialize esp_kiss
2019-07-27T06:24:00.930Z,1564208640.930 [esp_kiss:A.AbortSample] Stopped
2019-07-27T06:24:00.930Z,1564208640.930 [esp_kiss:A.AbortSample](INFO): Uninitializing AbortSample.
2019-07-27T06:24:00.930Z,1564208640.930 [esp_kiss:StandardEnvelopes] Stopped
2019-07-27T06:24:00.930Z,1564208640.930 [esp_kiss:StandardEnvelopes](DEBUG): Aggregate::uninitialize esp_kiss:StandardEnvelopes
2019-07-27T06:24:00.930Z,1564208640.930 [esp_kiss:StandardEnvelopes:A.AltitudeEnvelope] Stopped
2019-07-27T06:24:00.930Z,1564208640.930 [esp_kiss:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2019-07-27T06:24:00.943Z,1564208640.943 [esp_kiss:StandardEnvelopes:B.DepthEnvelope] Stopped
2019-07-27T06:24:00.943Z,1564208640.943 [esp_kiss:StandardEnvelopes:B.DepthEnvelope](DEBUG): Uninitialize.
2019-07-27T06:24:00.943Z,1564208640.943 [esp_kiss:StandardEnvelopes:C.OffshoreEnvelope] Stopped
2019-07-27T06:24:00.943Z,1564208640.943 [esp_kiss:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2019-07-27T06:24:00.943Z,1564208640.943 [esp_kiss:NeedComms] Stopped
2019-07-27T06:24:00.943Z,1564208640.943 [esp_kiss:NeedComms](DEBUG): Aggregate::uninitialize esp_kiss:NeedComms
2019-07-27T06:24:00.943Z,1564208640.943 [esp_kiss:NeedComms:B.GoToSurface] Stopped
2019-07-27T06:24:00.943Z,1564208640.943 [esp_kiss:NeedComms:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-27T06:24:00.943Z,1564208640.943 [esp_kiss:I] Stopped
2019-07-27T06:24:00.943Z,1564208640.943 [esp_kiss:SampleESP] Stopped
2019-07-27T06:24:00.943Z,1564208640.943 [esp_kiss:SampleESP](DEBUG): Aggregate::uninitialize esp_kiss:SampleESP
2019-07-27T06:24:00.944Z,1564208640.944 [esp_kiss:SampleESP:sample] Stopped
2019-07-27T06:24:00.944Z,1564208640.944 [esp_kiss:SampleESP:sample](DEBUG): Aggregate::uninitialize esp_kiss:SampleESP:sample
2019-07-27T06:24:00.944Z,1564208640.944 [esp_kiss:SampleESP:sample:TriggerESP] Stopped
2019-07-27T06:24:00.944Z,1564208640.944 [esp_kiss:Science] Stopped
2019-07-27T06:24:00.944Z,1564208640.944 [esp_kiss:Science](DEBUG): Aggregate::uninitialize esp_kiss:Science
2019-07-27T06:24:00.944Z,1564208640.944 [esp_kiss:SampleAtTargetDepth] Stopped
2019-07-27T06:24:00.944Z,1564208640.944 [esp_kiss:SampleAtTargetDepth](DEBUG): Aggregate::uninitialize esp_kiss:SampleAtTargetDepth
2019-07-27T06:24:00.944Z,1564208640.944 [esp_kiss:SampleAtTargetDepth:A.SetSpeed] Stopped
2019-07-27T06:24:00.944Z,1564208640.944 [esp_kiss:SampleAtTargetDepth:A.SetSpeed](DEBUG): Uninitialize.
2019-07-27T06:24:00.944Z,1564208640.944 [esp_kiss:SampleAtTargetDepth:B.Pitch] Stopped
2019-07-27T06:24:00.944Z,1564208640.944 [esp_kiss:SampleAtTargetDepth:GrabSamples] Stopped
2019-07-27T06:24:00.944Z,1564208640.944 [esp_kiss:SampleAtTargetDepth:GrabSamples](DEBUG): Aggregate::uninitialize esp_kiss:SampleAtTargetDepth:GrabSamples
2019-07-27T06:24:00.945Z,1564208640.945 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1] Stopped
2019-07-27T06:24:00.945Z,1564208640.945 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1](DEBUG): Aggregate::uninitialize esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1
2019-07-27T06:24:00.945Z,1564208640.945 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1:B] Stopped
2019-07-27T06:24:00.945Z,1564208640.945 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1:B](DEBUG): Aggregate::uninitialize esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1:B
2019-07-27T06:24:01.320Z,1564208641.320 [MissionManager](IMPORTANT): Started mission Default
2019-07-27T06:24:01.321Z,1564208641.321 [Default] Running Loop=1
2019-07-27T06:24:01.321Z,1564208641.321 [Default](DEBUG): Aggregate::initialize Default
2019-07-27T06:24:01.321Z,1564208641.321 [Default:B.GoToSurface] Running Loop=1
2019-07-27T06:24:01.321Z,1564208641.321 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-27T06:24:01.321Z,1564208641.321 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-27T06:24:01.321Z,1564208641.321 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-27T06:24:01.322Z,1564208641.322 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-27T06:24:01.322Z,1564208641.322 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-27T06:24:01.322Z,1564208641.322 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-27T06:24:01.323Z,1564208641.323 [Default:A.Wait] Running Loop=1
2019-07-27T06:24:01.323Z,1564208641.323 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-07-27T06:24:01.718Z,1564208641.718 [ESPComponent](DEBUG): Resetting stopSampling to false
2019-07-27T06:24:01.719Z,1564208641.719 [ESPComponent](IMPORTANT): [sample #0] No ESP summary messages.
2019-07-27T06:24:01.719Z,1564208641.719 [ESPComponent](INFO): powering down ESP
2019-07-27T06:24:01.738Z,1564208641.738 [ESPComponent](INFO): powering down ESP secondary power supply
2019-07-27T06:24:10.921Z,1564208650.921 [CommandLine](IMPORTANT): got command maintain clear
2019-07-27T06:24:11.104Z,1564208651.104 [controlThread](DEBUG): Component order: CycleStarter,Depth_Keller,NAL9602,Onboard,BPC1,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-07-27T06:24:14.686Z,1564208654.686 [Default:A.Wait](INFO): Done Waiting.
2019-07-27T06:24:14.687Z,1564208654.687 [Default:A.Wait] Stopped
2019-07-27T06:24:14.687Z,1564208654.687 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-27T06:24:15.081Z,1564208655.081 [Default:CheckIn] Running Loop=1
2019-07-27T06:24:15.081Z,1564208655.081 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-07-27T06:24:15.081Z,1564208655.081 [Default:CheckIn:Read_GPS] Running Loop=1
2019-07-27T06:24:15.487Z,1564208655.487 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-07-27T06:24:15.487Z,1564208655.487 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-07-27T06:24:15.487Z,1564208655.487 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-27T06:24:15.547Z,1564208655.547 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-27T06:24:15.931Z,1564208655.931 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-27T06:24:15.931Z,1564208655.931 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-07-27T06:24:16.687Z,1564208656.687 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:25:21.741Z,1564208721.741 [CommandLine](IMPORTANT): got command run ./Missions/Science/esp_kiss.xml
2019-07-27T06:25:21.741Z,1564208721.741 [MissionManager](INFO): Loading Mission: ./Missions/Science/esp_kiss.xml
2019-07-27T06:25:21.932Z,1564208721.932 [MissionManager](INFO): DefineArg esp_kiss.MissionTimeout = 4.000000 h
2019-07-27T06:25:21.935Z,1564208721.935 [MissionManager](INFO): DefineArg esp_kiss.TargetDepth = 3.000000 m
2019-07-27T06:25:21.937Z,1564208721.937 [MissionManager](INFO): DefineArg esp_kiss.ESPCartridgeType_1 = -4.000000 count
2019-07-27T06:25:21.939Z,1564208721.939 [MissionManager](INFO): DefineArg esp_kiss.ESPCartridgeType_2 = -9.000000 count
2019-07-27T06:25:21.941Z,1564208721.941 [MissionManager](INFO): DefineArg esp_kiss.ESPCartridgeType_3 = nan count
2019-07-27T06:25:21.944Z,1564208721.944 [MissionManager](INFO): DefineArg esp_kiss.ESPCartridgeType_4 = nan count
2019-07-27T06:25:21.946Z,1564208721.946 [MissionManager](INFO): DefineArg esp_kiss.SettleTime = 3.000000 min
2019-07-27T06:25:21.948Z,1564208721.948 [MissionManager](INFO): DefineArg esp_kiss.Speed = 0.000000 m/s
2019-07-27T06:25:21.950Z,1564208721.950 [MissionManager](INFO): DefineArg esp_kiss.ApproachDepth = 3.000000 m
2019-07-27T06:25:21.953Z,1564208721.953 [MissionManager](INFO): DefineArg esp_kiss.ApproachSpeed = 0.700000 m/s
2019-07-27T06:25:21.955Z,1564208721.955 [MissionManager](INFO): DefineArg esp_kiss.ApproachDepthRate = 0.050000 m/s
2019-07-27T06:25:21.957Z,1564208721.957 [MissionManager](INFO): DefineArg esp_kiss.ApproachPitchLimit = 10.000000 arcdeg
2019-07-27T06:25:21.960Z,1564208721.960 [MissionManager](INFO): DefineArg esp_kiss.ApproachSettleTimePreDive = 90.000000 s
2019-07-27T06:25:21.962Z,1564208721.962 [MissionManager](INFO): DefineArg esp_kiss.ApproachSettleTimePostDive = 0.000000 s
2019-07-27T06:25:21.964Z,1564208721.964 [MissionManager](INFO): DefineArg esp_kiss.ApproachDepthTimeout = 15.000000 min
2019-07-27T06:25:21.966Z,1564208721.966 [MissionManager](INFO): DefineArg esp_kiss.kpDepth = 0.070000 rad/m
2019-07-27T06:25:21.968Z,1564208721.968 [MissionManager](INFO): DefineArg esp_kiss.DepthDeadband = 0.010000 m
2019-07-27T06:25:21.971Z,1564208721.971 [MissionManager](INFO): DefineArg esp_kiss.MinAltitude = 2.000000 m
2019-07-27T06:25:21.973Z,1564208721.973 [MissionManager](INFO): DefineArg esp_kiss.MaxDepth = 5.000000 m
2019-07-27T06:25:21.975Z,1564208721.975 [MissionManager](INFO): DefineArg esp_kiss.MinOffshore = 1.000000 km
2019-07-27T06:25:21.977Z,1564208721.977 [MissionManager](INFO): DefineOutput esp_kiss.ESPCartridgeType = nan count
2019-07-27T06:25:21.979Z,1564208721.979 [esp_kiss:A.AbortSample](DEBUG): Construct.
2019-07-27T06:25:21.979Z,1564208721.979 [MissionManager](INFO): Inserting Stack: Missions/Insert/StandardEnvelopes.xml
2019-07-27T06:25:21.996Z,1564208721.996 [MissionManager](INFO): DefineArg esp_kiss:StandardEnvelopes.MinAltitude = 5.000000 m
2019-07-27T06:25:21.998Z,1564208721.998 [MissionManager](INFO): DefineArg esp_kiss:StandardEnvelopes.MaxDepth = 200.000000 m
2019-07-27T06:25:22.001Z,1564208722.001 [MissionManager](INFO): DefineArg esp_kiss:StandardEnvelopes.MinOffshore = 2000.000000 m
2019-07-27T06:25:22.001Z,1564208722.001 [esp_kiss:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2019-07-27T06:25:22.007Z,1564208722.007 [esp_kiss:StandardEnvelopes:B.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2019-07-27T06:25:22.040Z,1564208722.040 [esp_kiss:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2019-07-27T06:25:22.088Z,1564208722.088 [MissionManager](INFO): Inserting Stack: Missions/Insert/NeedComms.xml
2019-07-27T06:25:22.304Z,1564208722.304 [MissionManager](INFO): DefineArg esp_kiss:NeedComms.DiveInterval = 3.000000 h
2019-07-27T06:25:22.306Z,1564208722.306 [MissionManager](INFO): DefineArg esp_kiss:NeedComms.WaitForPitchUp = 10.000000 min
2019-07-27T06:25:22.312Z,1564208722.312 [MissionManager](INFO): DefineArg esp_kiss:NeedComms.SurfacePitch = 20.000000 arcdeg
2019-07-27T06:25:22.314Z,1564208722.314 [MissionManager](INFO): DefineArg esp_kiss:NeedComms.SurfaceDepthRate = nan m/s
2019-07-27T06:25:22.328Z,1564208722.328 [MissionManager](INFO): DefineArg esp_kiss:NeedComms.SurfaceSpeed = 1.000000 m/s
2019-07-27T06:25:22.339Z,1564208722.339 [MissionManager](INFO): DefineArg esp_kiss:NeedComms.GPSTimeout = 7.000000 min
2019-07-27T06:25:22.341Z,1564208722.341 [MissionManager](INFO): DefineArg esp_kiss:NeedComms.CommsTimeout = 30.000000 min
2019-07-27T06:25:22.346Z,1564208722.346 [esp_kiss:NeedComms:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-07-27T06:25:22.412Z,1564208722.412 [esp_kiss:SampleESP:sample:B.Wait](DEBUG): Construct Wait.
2019-07-27T06:25:22.417Z,1564208722.417 [MissionManager](ERROR): Slate does not contain CTD_NeilBrown.bin_mean_sea_water_temperature
2019-07-27T06:25:22.417Z,1564208722.417 [MissionManager](ERROR): Slate does not contain celsius
2019-07-27T06:25:22.418Z,1564208722.418 [MissionManager](ERROR): Slate does not contain WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water
2019-07-27T06:25:22.418Z,1564208722.418 [MissionManager](ERROR): Slate does not contain microgram_per_liter
2019-07-27T06:25:22.464Z,1564208722.464 [MissionManager](INFO): Inserting Stack: Missions/Insert/Science.xml
2019-07-27T06:25:22.957Z,1564208722.957 [MissionManager](INFO): DefineArg esp_kiss:Science.SampleISUS = 0 bool
2019-07-27T06:25:22.980Z,1564208722.980 [MissionManager](INFO): DefineArg esp_kiss:Science.SampleISUSmaxPitch = 60.000000 arcdeg
2019-07-27T06:25:22.982Z,1564208722.982 [MissionManager](INFO): DefineArg esp_kiss:Science.SampleISUSminPitch = -60.000000 arcdeg
2019-07-27T06:25:23.004Z,1564208723.004 [MissionManager](INFO): DefineArg esp_kiss:Science.PeakDetectChlActive = 0 bool
2019-07-27T06:25:23.006Z,1564208723.006 [MissionManager](INFO): DefineArg esp_kiss:Science.TimeWindowPeakReport = nan min
2019-07-27T06:25:23.061Z,1564208723.061 [MissionManager](INFO): DefineArg esp_kiss:Science.HighestChlPeakReportActive = 0 bool
2019-07-27T06:25:23.071Z,1564208723.071 [MissionManager](INFO): DefineArg esp_kiss:Science.PatchTracking = 0 bool
2019-07-27T06:25:23.073Z,1564208723.073 [MissionManager](INFO): DefineArg esp_kiss:Science.FilterWidthHorizontal = 3.000000 count
2019-07-27T06:25:23.076Z,1564208723.076 [MissionManager](INFO): DefineArg esp_kiss:Science.NumProfilesSlidingwindow = 100.000000 count
2019-07-27T06:25:23.078Z,1564208723.078 [MissionManager](INFO): DefineArg esp_kiss:Science.OffPeakFractionHorizontal = 80.000000 %
2019-07-27T06:25:23.104Z,1564208723.104 [MissionManager](INFO): DefineArg esp_kiss:Science.PeakDetectNO3Active = 0 bool
2019-07-27T06:25:23.106Z,1564208723.106 [MissionManager](INFO): DefineArg esp_kiss:Science.PeakDetectOilActive = 0 bool
2019-07-27T06:25:23.108Z,1564208723.108 [MissionManager](INFO): DefineArg esp_kiss:Science.PeakDetectFDOMActive = 0 bool
2019-07-27T06:25:23.110Z,1564208723.110 [MissionManager](INFO): DefineArg esp_kiss:Science.UpwardDerivativeOfTemperatureActive = 0 bool
2019-07-27T06:25:23.126Z,1564208723.126 [MissionManager](INFO): DefineArg esp_kiss:Science.EnabledAanderaaO2 = 0.000000 bool
2019-07-27T06:25:23.129Z,1564208723.129 [MissionManager](INFO): DefineArg esp_kiss:Science.EnabledNeilBrown = 0.000000 bool
2019-07-27T06:25:23.143Z,1564208723.143 [MissionManager](INFO): DefineArg esp_kiss:Science.EnabledSeabird = 0.000000 bool
2019-07-27T06:25:23.161Z,1564208723.161 [MissionManager](INFO): DefineArg esp_kiss:Science.EnabledTurbulence_NPS = 0.000000 bool
2019-07-27T06:25:23.182Z,1564208723.182 [MissionManager](INFO): DefineArg esp_kiss:Science.EnabledWetLabsBB2FL = 0.000000 bool
2019-07-27T06:25:23.188Z,1564208723.188 [MissionManager](INFO): DefineArg esp_kiss:Science.EnabledWetLabsSeaOWL_UV_A = 0.000000 bool
2019-07-27T06:25:23.203Z,1564208723.203 [MissionManager](INFO): DefineArg esp_kiss:Science.EnabledWetLabsUBAT = 0.000000 bool
2019-07-27T06:25:23.205Z,1564208723.205 [MissionManager](INFO): DefineArg esp_kiss:Science.EnabledISUS = 0.000000 bool
2019-07-27T06:25:23.220Z,1564208723.220 [MissionManager](INFO): DefineArg esp_kiss:Science.LowPassWindowLength = 20.000000 count
2019-07-27T06:25:23.235Z,1564208723.235 [MissionManager](INFO): DefineArg esp_kiss:Science.MedianFilterLen = 5.000000 count
2019-07-27T06:25:23.237Z,1564208723.237 [MissionManager](INFO): DefineArg esp_kiss:Science.PeakChlShallowBound = nan m
2019-07-27T06:25:23.245Z,1564208723.245 [MissionManager](INFO): DefineArg esp_kiss:Science.PeakChlDeepBound = nan m
2019-07-27T06:25:23.259Z,1564208723.259 [MissionManager](INFO): DefineArg esp_kiss:Science.PeakShallowBound = nan m
2019-07-27T06:25:23.262Z,1564208723.262 [MissionManager](INFO): DefineArg esp_kiss:Science.PeakDeepBound = nan m
2019-07-27T06:25:23.295Z,1564208723.295 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakChl = 0.000000 ug/l
2019-07-27T06:25:23.297Z,1564208723.297 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakChlDepth = 0.000000 m
2019-07-27T06:25:23.308Z,1564208723.308 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakChlTemperature = 0.000000 degC
2019-07-27T06:25:23.310Z,1564208723.310 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakChlLatitude = nan arcdeg
2019-07-27T06:25:23.325Z,1564208723.325 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakChlLongitude = nan arcdeg
2019-07-27T06:25:23.331Z,1564208723.331 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakNO3 = 0.000000 umol/l
2019-07-27T06:25:23.334Z,1564208723.334 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakNO3Depth = 0.000000 m
2019-07-27T06:25:23.395Z,1564208723.395 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakNO3Latitude = nan arcdeg
2019-07-27T06:25:23.398Z,1564208723.398 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakNO3Longitude = nan arcdeg
2019-07-27T06:25:23.417Z,1564208723.417 [MissionManager](INFO): DefineOutput esp_kiss:Science.PatchChl = 0.000000 m
2019-07-27T06:25:23.440Z,1564208723.440 [MissionManager](INFO): DefineOutput esp_kiss:Science.PatchChlDepth = 0.000000 m
2019-07-27T06:25:23.455Z,1564208723.455 [MissionManager](INFO): DefineOutput esp_kiss:Science.PatchChlLatitude = nan arcdeg
2019-07-27T06:25:23.457Z,1564208723.457 [MissionManager](INFO): DefineOutput esp_kiss:Science.PatchChlLongitude = nan arcdeg
2019-07-27T06:25:23.476Z,1564208723.476 [MissionManager](INFO): DefineOutput esp_kiss:Science.PatchChlDistance = nan m
2019-07-27T06:25:23.478Z,1564208723.478 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakOil = 0.000000 kg/m3
2019-07-27T06:25:23.484Z,1564208723.484 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakOilDepth = 0.000000 m
2019-07-27T06:25:23.491Z,1564208723.491 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakOilLatitude = nan arcdeg
2019-07-27T06:25:23.493Z,1564208723.493 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakOilLongitude = nan arcdeg
2019-07-27T06:25:23.507Z,1564208723.507 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakFDOM = 0.000000 ppb
2019-07-27T06:25:23.510Z,1564208723.510 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakFDOMDepth = 0.000000 m
2019-07-27T06:25:23.524Z,1564208723.524 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakFDOMLatitude = nan arcdeg
2019-07-27T06:25:23.535Z,1564208723.535 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakFDOMLongitude = nan arcdeg
2019-07-27T06:25:23.537Z,1564208723.537 [MissionManager](INFO): DefineOutput esp_kiss:Science.PatchFDOMDistance = nan m
2019-07-27T06:25:23.585Z,1564208723.585 [esp_kiss:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2019-07-27T06:25:23.611Z,1564208723.611 [esp_kiss:Science:HighestChlPeakReport:A.PeakDetectHorizontal](DEBUG): Construct PeakDetectHorizontal.
2019-07-27T06:25:23.638Z,1564208723.638 [esp_kiss:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2019-07-27T06:25:23.708Z,1564208723.708 [esp_kiss:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2019-07-27T06:25:23.733Z,1564208723.733 [esp_kiss:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2019-07-27T06:25:23.805Z,1564208723.805 [esp_kiss:InitialDive:C.Pitch](DEBUG): Construct.
2019-07-27T06:25:23.809Z,1564208723.809 [esp_kiss:InitialDive:D.Point](DEBUG): Construct.
2019-07-27T06:25:23.834Z,1564208723.834 [esp_kiss:InitialDive:E.Buoyancy](DEBUG): Construct Buoyancy.
2019-07-27T06:25:23.838Z,1564208723.838 [esp_kiss:InitialDive:G.Wait](DEBUG): Construct Wait.
2019-07-27T06:25:23.861Z,1564208723.861 [esp_kiss:InitialDive:ApproachDepth:A.SetSpeed](DEBUG): Construct.
2019-07-27T06:25:23.863Z,1564208723.863 [esp_kiss:InitialDive:ApproachDepth:B.Pitch](DEBUG): Construct.
2019-07-27T06:25:23.875Z,1564208723.875 [esp_kiss:InitialDive:ApproachDepth:B.Pitch:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-07-27T06:25:23.895Z,1564208723.895 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:B.Pitch](DEBUG): Construct.
2019-07-27T06:25:23.899Z,1564208723.899 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:C.Wait](DEBUG): Construct Wait.
2019-07-27T06:25:23.902Z,1564208723.902 [esp_kiss:SampleAtTargetDepth:A.SetSpeed](DEBUG): Construct.
2019-07-27T06:25:23.928Z,1564208723.928 [esp_kiss:SampleAtTargetDepth:B.Pitch](DEBUG): Construct.
2019-07-27T06:25:23.941Z,1564208723.941 [esp_kiss:SampleAtTargetDepth:Spinout:HoldMassPosition.Pitch](DEBUG): Construct.
2019-07-27T06:25:23.971Z,1564208723.971 [esp_kiss:SampleAtTargetDepth:Spinout:HoldBuoyancyPosition.Buoyancy](DEBUG): Construct Buoyancy.
2019-07-27T06:25:23.974Z,1564208723.974 [esp_kiss:SampleAtTargetDepth:Spinout:HoldRudderAngle.Point](DEBUG): Construct.
2019-07-27T06:25:24.114Z,1564208724.114 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>

<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd
                             Tethys/Science http://okeanids.mbari.org/tethys/Xml/Science.xsd"
       Id="esp_kiss">

    <Description>
        This mission takes ESP samples at the designated depth.
    </Description>

    <DefineArg Name="MissionTimeout"><Description>
        Maximum duration of mission.
    </Description><Units:hour/><Value>4</Value></DefineArg>

    <DefineArg Name="TargetDepth"><Description>
        Depth to sample at. Initialized to 3 m.
    </Description><Units:meter/><Value>3</Value></DefineArg>

    <DefineArg Name="ESPCartridgeType_1"><Description>
        Specifies ESP cartridge type code for sample# 1. Set to NaN to skip this sample.
    </Description><Units:count/><Value>-4</Value></DefineArg>

    <DefineArg Name="ESPCartridgeType_2"><Description>
        Specifies ESP cartridge type code for sample# 2. Set to NaN to skip this sample.
    </Description><Units:count/><Value>-9</Value></DefineArg>

    <DefineArg Name="ESPCartridgeType_3"><Description>
        Specifies ESP cartridge type code for sample# 3. Set to NaN to skip this sample.
    </Description><Units:count/><Value>NaN</Value></DefineArg>

    <DefineArg Name="ESPCartridgeType_4"><Description>
        Specifies ESP cartridge type code for sample# 4. Set to NaN to skip this sample.
    </Description><Units:count/><Value>NaN</Value></DefineArg>

    <DefineArg Name="SettleTime"><Description>
        How long to wait between samples. This starts *before* the first sample.
    </Description><Units:minute/><Value>3</Value></DefineArg>

    <DefineArg Name="Speed"><Description>
        Vehicle speed while sampling. Set to zero to maintain depth using VBS (drift).
    </Description><Units:meter_per_second/><Value>0</Value></DefineArg>

    <DefineArg Name="ApproachDepth"><Description>
        Depth for initial descent form the surface. Initialized to 3 m.
    </Description><Units:meter/><Value>3</Value></DefineArg>

    <DefineArg Name="ApproachSpeed"><Description>
        Vehicle speed for initial descent form the surface to target depth. Set to zero
        to disable the thruster and descend using VBS (drift).
    </Description><Units:meter_per_second/><Value>0.7</Value></DefineArg>

    <DefineArg Name="ApproachDepthRate"><Description>
        Descent depth rate (Positive depth rate means going down).
    </Description><Units:meter_per_second/><Value>0.05</Value></DefineArg>

    <DefineArg Name="ApproachPitchLimit"><Description>
        Max vehicle pitch (+/-) when decending from the surface.
    </Description><Units:degree/><Value>10</Value></DefineArg>

    <DefineArg Name="ApproachSettleTimePreDive"><Description>
        Time duration for the vehicle to pump down the VBS *BEFORE* leaving the surface.
    </Description><Units:second/><Value>90</Value></DefineArg>

    <DefineArg Name="ApproachSettleTimePostDive"><Description>
        Time duration for the vehicle to settele *AFTER* reaching the target depth.
    </Description><Units:second/><Value>0</Value></DefineArg>

    <DefineArg Name="ApproachDepthTimeout"><Description>
        Maximum time duration for the vehicle to reach the target depth.
    </Description><Units:minute/><Value>15</Value></DefineArg>

    <DefineArg Name="kpDepth"><Description>
        Dive loop proportional gain (applied only while the vehicle is descending to target depth).
    </Description><Units:radian_per_meter/><Value>0.07</Value></DefineArg>

    <DefineArg Name="DepthDeadband"><Description>
        How much vertical drift from the specified depth is allowed while sampling.
    </Description><Units:meter/><Value>0.01</Value></DefineArg>

    <DefineArg Name="MinAltitude"><Description>
        Minimum height above the sea floor for the entire mission.
    </Description><Units:meter/><Value>2</Value></DefineArg>

    <DefineArg Name="MaxDepth"><Description>
        Maximum allowable depth during the mission.
    </Description><Units:meter/><Value>5</Value></DefineArg>

    <DefineArg Name="MinOffshore"><Description>
        Minimum distance from the shoreline to maintain.
    </Description><Units:kilometer/><Value>1</Value></DefineArg>

    <DefineOutput Name="ESPCartridgeType"><Description>
        Mission parameter (don't change). Specifies ESP cartridge type code.
    </Description><Units:count/><Value>NaN</Value></DefineOutput>
    
    <!-- Mission timeout -->

    <Timeout Duration="MissionTimeout"/>

    <!-- Safety nets and surfacing behaviors -->

    <Trigger:AbortSample>
        <Parallel/>
    </Trigger:AbortSample>

    <Insert Filename="Insert/StandardEnvelopes.xml"/>

    <Assign><Sequence/><Arg Name="StandardEnvelopes:MaxDepth"/><Arg Name="MaxDepth"/></Assign>

    <Assign><Sequence/><Arg Name="StandardEnvelopes:MinAltitude"/><Arg Name="MinAltitude"/></Assign>

    <Assign><Sequence/><Arg Name="StandardEnvelopes:MinOffshore"/><Arg Name="MinOffshore"/></Assign>


    <Insert Filename="Insert/NeedComms.xml" Id="NeedComms"/>

    <Assign><Sequence/><Arg Name="NeedComms:DiveInterval"/><Arg Name="MissionTimeout"/></Assign>

    <Assign><Sequence/><Arg Name="NeedComms:WaitForPitchUp"/><Units:minute/><Value>0</Value></Assign>


    <Assign><Parallel/><Control:VerticalControl.depthDeadband/><Arg Name="DepthDeadband"/></Assign>

        
    <!-- Callable aggregate -->

    <Aggregate Id="SampleESP">
        
        <When>
            <Called/>
        </When>

        <Aggregate Id="sample">
            <Sequence/>

            <Syslog Severity="Important">At <Universal:depth/><Units:meter/>, settling for <Arg Name="SettleTime"/><Units:minute/></Syslog>

            <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="SettleTime"/></Setting>
            </Guidance:Wait>

            <Syslog Severity="Important">Requesting ESP cartridge type:<Arg Name="ESPCartridgeType"/><Units:count/></Syslog>

            <Assign><Sequence/><Science:ESPComponent.cartridge/><Arg Name="ESPCartridgeType"/></Assign>

            <ReadDatum Id="TriggerESP">
                <Science:ESPComponent.sampling/>
            </ReadDatum>

            <Syslog Severity="Important">ESP sampling at <Universal:depth/><Units:meter/> in <Science:CTD_NeilBrown.bin_mean_sea_water_temperature/><Units:celsius/> water with <Science:WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water/><Units:microgram_per_liter/>chlorophyll fluorescence.</Syslog>

            <ReadDatum Id="WaitForESP">
                <Science:ESPComponent.sample_number/>
            </ReadDatum>
        </Aggregate>

    </Aggregate>


    <!-- Start mission sequence -->

    <Call Id="StartingMission" RefId="NeedComms"/>
    
    <Insert Filename="Insert/Science.xml"></Insert>

    <Aggregate Id="InitialDive">
        <Description>
            Descend from the surface to approach depth at ApproachSpeed, limit pitch,
            depth-rate, and hold the rudder.
        </Description>

        <Sequence/>

        <Assign><Parallel/><Control:VerticalControl.pitchLimit/><Arg Name="ApproachPitchLimit"/></Assign>

        <Assign><Parallel/><Control:VerticalControl.kpDepth/><Arg Name="kpDepth"/></Assign>

        <Guidance:Pitch>
            <Parallel/>
            <Setting><Guidance:Pitch.massPosition/><Control:VerticalControl.massDefault/></Setting>
        </Guidance:Pitch>

        <Guidance:Point>
            <Parallel/>
            <Setting><Guidance:Point.rudderAngle/><Units:degree/><Value>13</Value></Setting>
        </Guidance:Point>
        
        <Guidance:Buoyancy>
            <Parallel/>
            <Setting><Guidance:Buoyancy.position/><Control:VerticalControl.buoyancyNeutral/></Setting>
        </Guidance:Buoyancy>

        <Syslog Severity="Info">Waiting for <Arg Name="ApproachSettleTimePreDive"/><Units:second/>while pumping down to neutral.</Syslog>

        <Guidance:Wait>
            <Description>Take a few moments to ensure the VBS reaches neutral.</Description>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Arg Name="ApproachSettleTimePreDive"/></Setting>
        </Guidance:Wait>

        <Syslog>Moving to <Arg Name="ApproachDepth"/><Units:meter/></Syslog>

        <Aggregate Id="ApproachDepth">

            <Sequence/>

            <Guidance:SetSpeed>
                <Parallel/>
                <Setting><Guidance:SetSpeed.speed/><Arg Name="ApproachSpeed"/></Setting>
            </Guidance:SetSpeed>

            <Guidance:Pitch>
                <Sequence/>

                <Timeout Duration="ApproachDepthTimeout">
                    <Syslog Severity="Important">Timed out while trying to reach target depth at current depth of <Universal:depth/><Units:meter/>.</Syslog>
                    <Guidance:Execute>
                        <Sequence/>
                        <Setting><Guidance:Execute.command/><String>stop</String></Setting>
                    </Guidance:Execute>
                </Timeout>

                <Setting><Guidance:Pitch.depth/><Arg Name="ApproachDepth"/></Setting>
                <Setting><Guidance:Pitch.depthRate/><Arg Name="ApproachDepthRate"/></Setting>
            </Guidance:Pitch>

            <Aggregate Id="SettleAtDepth">
                <Description>
                    Take a few more moments here to make sure the VBS reached neutral position and
                    the vechile is settled at the target depth.
                </Description>

                <Sequence/>

                <Syslog Severity="Info">Reached <Universal:depth/><Units:meter/>, settling for <Arg Name="ApproachSettleTimePostDive"/><Units:second/></Syslog>

                <Guidance:Pitch>
                    <Parallel/>
                    <Setting><Guidance:Pitch.depth/><Arg Name="ApproachDepth"/></Setting>
                    <Setting><Guidance:Pitch.depthRate/><Arg Name="ApproachDepthRate"/></Setting>
                </Guidance:Pitch>

                <Guidance:Wait>
                    <Sequence/>
                    <Setting><Guidance:Wait.duration/><Arg Name="ApproachSettleTimePostDive"/></Setting>
                </Guidance:Wait>

            </Aggregate>

        </Aggregate>

    </Aggregate>


    <Aggregate Id="SampleAtTargetDepth">
        <Description>
            Maintain target depth and acquire ESP samples.
        </Description>

        <Sequence/>

        <Guidance:SetSpeed>
            <Parallel/>
            <Setting><Guidance:SetSpeed.speed/><Arg Name="Speed"/></Setting>
        </Guidance:SetSpeed>

        <Guidance:Pitch>
            <Parallel/>
            <Setting><Guidance:Pitch.depth/><Arg Name="TargetDepth"/></Setting>
        </Guidance:Pitch>
        
        <Aggregate Id="Spinout">
            <Description>
                A speed has been specified, spin in circels while sampling.
            </Description>
            
            <While>
                <Arg Name="Speed"/><Gt><Units:meter_per_second/><Value>0.0</Value></Gt>
            </While>
            
            <Guidance:Pitch Id="HoldMassPosition">
                <Parallel/>
                <Setting><Guidance:Pitch.massPosition/><Control:VerticalControl.massDefault/></Setting>
            </Guidance:Pitch>
            
            <Guidance:Buoyancy Id="HoldBuoyancyPosition">
                <Parallel/>
                <Setting><Guidance:Buoyancy.position/><Control:VerticalControl.buoyancyNeutral/></Setting>
            </Guidance:Buoyancy>

            <Guidance:Point Id="HoldRudderAngle">
                <Setting><Guidance:Point.rudderAngle/><Units:degree/><Value>13</Value></Setting>
            </Guidance:Point>

        </Aggregate>

        <Aggregate Id="GrabSamples">

            <Sequence/>

            <Aggregate Id="Sample1">
                <Break>
                    <IsNaN><Arg Name="ESPCartridgeType_1"/></IsNaN>
                </Break>

                <Assign><Sequence/><Arg Name="ESPCartridgeType"/><Arg Name="ESPCartridgeType_1"/></Assign>

                <Call RefId="SampleESP"/>
            </Aggregate>


            <Aggregate Id="Sample2">
                <Break>
                    <IsNaN><Arg Name="ESPCartridgeType_2"/></IsNaN>
                </Break>

                <Assign><Sequence/><Arg Name="ESPCartridgeType"/><Arg Name="ESPCartridgeType_2"/></Assign>

                <Call RefId="SampleESP"/>
            </Aggregate>


            <Aggregate Id="Sample3">
                <Break>
                    <IsNaN><Arg Name="ESPCartridgeType_3"/></IsNaN>
                </Break>
                
                <Assign><Sequence/><Arg Name="ESPCartridgeType"/><Arg Name="ESPCartridgeType_3"/></Assign>
                
                <Call RefId="SampleESP"/>
            </Aggregate>


            <Aggregate Id="Sample4">
                <Break>
                    <IsNaN><Arg Name="ESPCartridgeType_4"/></IsNaN>
                </Break>

                <Assign><Sequence/><Arg Name="ESPCartridgeType"/><Arg Name="ESPCartridgeType_4"/></Assign>

                <Call RefId="SampleESP"/>
            </Aggregate>

        </Aggregate>

    </Aggregate>

</Mission>


2019-07-27T06:25:24.140Z,1564208724.140 [CommandLine](IMPORTANT): Running ./Missions/Science/esp_kiss.xml
2019-07-27T06:25:24.227Z,1564208724.227 [Default] Stopped
2019-07-27T06:25:24.227Z,1564208724.227 [Default](DEBUG): Aggregate::uninitialize Default
2019-07-27T06:25:24.227Z,1564208724.227 [Default:B.GoToSurface] Stopped
2019-07-27T06:25:24.227Z,1564208724.227 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-27T06:25:24.227Z,1564208724.227 [Default:CheckIn] Stopped
2019-07-27T06:25:24.228Z,1564208724.228 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-07-27T06:25:24.228Z,1564208724.228 [Default:CheckIn:Read_GPS] Stopped
2019-07-27T06:25:24.228Z,1564208724.228 [MissionManager](IMPORTANT): Started mission esp_kiss
2019-07-27T06:25:24.228Z,1564208724.228 [esp_kiss] Running Loop=1
2019-07-27T06:25:24.228Z,1564208724.228 [esp_kiss](DEBUG): Aggregate::initialize esp_kiss
2019-07-27T06:25:24.228Z,1564208724.228 [esp_kiss:A.AbortSample] Running Loop=1
2019-07-27T06:25:24.228Z,1564208724.228 [esp_kiss:A.AbortSample](INFO): Initializing AbortSample.
2019-07-27T06:25:24.228Z,1564208724.228 [esp_kiss:StandardEnvelopes] Running Loop=1
2019-07-27T06:25:24.229Z,1564208724.229 [esp_kiss:StandardEnvelopes](DEBUG): Aggregate::initialize esp_kiss:StandardEnvelopes
2019-07-27T06:25:24.229Z,1564208724.229 [esp_kiss:StandardEnvelopes:A.AltitudeEnvelope] Running Loop=1
2019-07-27T06:25:24.229Z,1564208724.229 [esp_kiss:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2019-07-27T06:25:24.229Z,1564208724.229 [esp_kiss:StandardEnvelopes:B.DepthEnvelope] Running Loop=1
2019-07-27T06:25:24.229Z,1564208724.229 [esp_kiss:StandardEnvelopes:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2019-07-27T06:25:24.229Z,1564208724.229 [esp_kiss:StandardEnvelopes:C.OffshoreEnvelope] Running Loop=1
2019-07-27T06:25:24.229Z,1564208724.229 [esp_kiss:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2019-07-27T06:25:24.229Z,1564208724.229 [esp_kiss:I] Running Loop=1
2019-07-27T06:25:24.229Z,1564208724.229 [esp_kiss:Science] Running Loop=1
2019-07-27T06:25:24.229Z,1564208724.229 [esp_kiss:Science](DEBUG): Aggregate::initialize esp_kiss:Science
2019-07-27T06:25:24.230Z,1564208724.230 [esp_kiss:Science:A] Running Loop=1
2019-07-27T06:25:24.230Z,1564208724.230 [esp_kiss:Science:B] Running Loop=1
2019-07-27T06:25:24.230Z,1564208724.230 [esp_kiss:Science:C] Running Loop=1
2019-07-27T06:25:24.230Z,1564208724.230 [esp_kiss:Science:D] Running Loop=1
2019-07-27T06:25:24.230Z,1564208724.230 [esp_kiss:Science:E] Running Loop=1
2019-07-27T06:25:24.230Z,1564208724.230 [esp_kiss:Science:F] Running Loop=1
2019-07-27T06:25:24.230Z,1564208724.230 [esp_kiss:Science:G] Running Loop=1
2019-07-27T06:25:24.230Z,1564208724.230 [esp_kiss:Science:H] Running Loop=1
2019-07-27T06:25:24.230Z,1564208724.230 [esp_kiss:Science:Read_Oil] Running Loop=1
2019-07-27T06:25:24.230Z,1564208724.230 [esp_kiss:Science:PeakDetectChl] Running Loop=1
2019-07-27T06:25:24.230Z,1564208724.230 [esp_kiss:Science:PeakDetectChl](DEBUG): Aggregate::initialize esp_kiss:Science:PeakDetectChl
2019-07-27T06:25:24.230Z,1564208724.230 [esp_kiss:Science:PeakDetectChl:A.PeakDetectVsDepth] Running Loop=1
2019-07-27T06:25:24.231Z,1564208724.231 [esp_kiss:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Initialize.
2019-07-27T06:25:24.232Z,1564208724.232 [esp_kiss:Science:HighestChlPeakReport] Running Loop=1
2019-07-27T06:25:24.232Z,1564208724.232 [esp_kiss:Science:HighestChlPeakReport](DEBUG): Aggregate::initialize esp_kiss:Science:HighestChlPeakReport
2019-07-27T06:25:24.232Z,1564208724.232 [esp_kiss:Science:HighestChlPeakReport:A.PeakDetectHorizontal] Running Loop=1
2019-07-27T06:25:24.232Z,1564208724.232 [esp_kiss:Science:HighestChlPeakReport:A.PeakDetectHorizontal](INFO): Initialize.
2019-07-27T06:25:24.232Z,1564208724.232 [esp_kiss:Science:PeakDetectNO3] Running Loop=1
2019-07-27T06:25:24.233Z,1564208724.233 [esp_kiss:Science:PeakDetectNO3](DEBUG): Aggregate::initialize esp_kiss:Science:PeakDetectNO3
2019-07-27T06:25:24.233Z,1564208724.233 [esp_kiss:Science:PeakDetectNO3:A.PeakDetectVsDepth] Running Loop=1
2019-07-27T06:25:24.233Z,1564208724.233 [esp_kiss:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Initialize.
2019-07-27T06:25:24.234Z,1564208724.234 [esp_kiss:Science:PeakDetectOil] Running Loop=1
2019-07-27T06:25:24.234Z,1564208724.234 [esp_kiss:Science:PeakDetectOil](DEBUG): Aggregate::initialize esp_kiss:Science:PeakDetectOil
2019-07-27T06:25:24.234Z,1564208724.234 [esp_kiss:Science:PeakDetectOil:A.PeakDetectVsDepth] Running Loop=1
2019-07-27T06:25:24.234Z,1564208724.234 [esp_kiss:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Initialize.
2019-07-27T06:25:24.247Z,1564208724.247 [esp_kiss:Science:PeakDetectFDOM] Running Loop=1
2019-07-27T06:25:24.247Z,1564208724.247 [esp_kiss:Science:PeakDetectFDOM](DEBUG): Aggregate::initialize esp_kiss:Science:PeakDetectFDOM
2019-07-27T06:25:24.248Z,1564208724.248 [esp_kiss:Science:PeakDetectFDOM:A.PeakDetectVsDepth] Running Loop=1
2019-07-27T06:25:24.248Z,1564208724.248 [esp_kiss:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Initialize.
2019-07-27T06:25:24.249Z,1564208724.249 [esp_kiss:C] Running Loop=1
2019-07-27T06:25:24.249Z,1564208724.249 [esp_kiss:Science] Running Loop=1
2019-07-27T06:25:24.250Z,1564208724.250 [esp_kiss:Science:PeakDetectFDOM] Stopped
2019-07-27T06:25:24.250Z,1564208724.250 [esp_kiss:Science:PeakDetectFDOM](DEBUG): Aggregate::uninitialize esp_kiss:Science:PeakDetectFDOM
2019-07-27T06:25:24.267Z,1564208724.267 [esp_kiss:Science:PeakDetectFDOM:A.PeakDetectVsDepth] Stopped
2019-07-27T06:25:24.267Z,1564208724.267 [esp_kiss:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2019-07-27T06:25:24.267Z,1564208724.267 [esp_kiss:Science:PeakDetectOil] Stopped
2019-07-27T06:25:24.267Z,1564208724.267 [esp_kiss:Science:PeakDetectOil](DEBUG): Aggregate::uninitialize esp_kiss:Science:PeakDetectOil
2019-07-27T06:25:24.267Z,1564208724.267 [esp_kiss:Science:PeakDetectOil:A.PeakDetectVsDepth] Stopped
2019-07-27T06:25:24.267Z,1564208724.267 [esp_kiss:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2019-07-27T06:25:24.267Z,1564208724.267 [esp_kiss:Science:PeakDetectNO3] Stopped
2019-07-27T06:25:24.267Z,1564208724.267 [esp_kiss:Science:PeakDetectNO3](DEBUG): Aggregate::uninitialize esp_kiss:Science:PeakDetectNO3
2019-07-27T06:25:24.267Z,1564208724.267 [esp_kiss:Science:PeakDetectNO3:A.PeakDetectVsDepth] Stopped
2019-07-27T06:25:24.267Z,1564208724.267 [esp_kiss:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2019-07-27T06:25:24.267Z,1564208724.267 [esp_kiss:Science:HighestChlPeakReport] Stopped
2019-07-27T06:25:24.268Z,1564208724.268 [esp_kiss:Science:HighestChlPeakReport](DEBUG): Aggregate::uninitialize esp_kiss:Science:HighestChlPeakReport
2019-07-27T06:25:24.268Z,1564208724.268 [esp_kiss:Science:HighestChlPeakReport:A.PeakDetectHorizontal] Stopped
2019-07-27T06:25:24.268Z,1564208724.268 [esp_kiss:Science:HighestChlPeakReport:A.PeakDetectHorizontal](DEBUG): Uninitialize.
2019-07-27T06:25:24.268Z,1564208724.268 [esp_kiss:Science:PeakDetectChl] Stopped
2019-07-27T06:25:24.268Z,1564208724.268 [esp_kiss:Science:PeakDetectChl](DEBUG): Aggregate::uninitialize esp_kiss:Science:PeakDetectChl
2019-07-27T06:25:24.268Z,1564208724.268 [esp_kiss:Science:PeakDetectChl:A.PeakDetectVsDepth] Stopped
2019-07-27T06:25:24.268Z,1564208724.268 [esp_kiss:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2019-07-27T06:25:24.268Z,1564208724.268 [esp_kiss:Science:Read_Oil] Stopped
2019-07-27T06:25:24.268Z,1564208724.268 [esp_kiss:Science:H] Stopped
2019-07-27T06:25:24.268Z,1564208724.268 [esp_kiss:Science:G] Stopped
2019-07-27T06:25:24.268Z,1564208724.268 [esp_kiss:Science:F] Stopped
2019-07-27T06:25:24.268Z,1564208724.268 [esp_kiss:Science:E] Stopped
2019-07-27T06:25:24.268Z,1564208724.268 [esp_kiss:Science:D] Stopped
2019-07-27T06:25:24.268Z,1564208724.268 [esp_kiss:Science:C] Stopped
2019-07-27T06:25:24.268Z,1564208724.268 [esp_kiss:Science:B] Stopped
2019-07-27T06:25:24.268Z,1564208724.268 [esp_kiss:Science:A] Stopped
2019-07-27T06:25:24.268Z,1564208724.268 [esp_kiss:I] Running Loop=1
2019-07-27T06:25:24.269Z,1564208724.269 [esp_kiss:C] Stopped
2019-07-27T06:25:24.269Z,1564208724.269 [esp_kiss:D] Running Loop=1
2019-07-27T06:25:24.269Z,1564208724.269 [esp_kiss:StandardEnvelopes] Running Loop=1
2019-07-27T06:25:24.269Z,1564208724.269 [esp_kiss:StandardEnvelopes:C.OffshoreEnvelope] Running Loop=1
2019-07-27T06:25:24.270Z,1564208724.270 [esp_kiss:StandardEnvelopes:B.DepthEnvelope] Running Loop=1
2019-07-27T06:25:24.270Z,1564208724.270 [esp_kiss:StandardEnvelopes:A.AltitudeEnvelope] Running Loop=1
2019-07-27T06:25:24.270Z,1564208724.270 [esp_kiss:A.AbortSample] Running Loop=1
2019-07-27T06:25:24.610Z,1564208724.610 [esp_kiss:D] Stopped
2019-07-27T06:25:24.610Z,1564208724.610 [esp_kiss:E] Running Loop=1
2019-07-27T06:25:25.025Z,1564208725.025 [esp_kiss:E] Stopped
2019-07-27T06:25:25.026Z,1564208725.026 [esp_kiss:G] Running Loop=1
2019-07-27T06:25:25.430Z,1564208725.430 [esp_kiss:G] Stopped
2019-07-27T06:25:25.430Z,1564208725.430 [esp_kiss:H] Running Loop=1
2019-07-27T06:25:25.834Z,1564208725.834 [esp_kiss:H] Stopped
2019-07-27T06:25:25.839Z,1564208725.839 [esp_kiss:StartingMission] Running Loop=1
2019-07-27T06:25:25.839Z,1564208725.839 [esp_kiss:StartingMission](DEBUG): Aggregate::initialize esp_kiss:StartingMission
2019-07-27T06:25:25.840Z,1564208725.840 [esp_kiss:StandardEnvelopes:A.AltitudeEnvelope](ERROR): Altitude Measurement is not Active.
2019-07-27T06:25:26.223Z,1564208726.223 [esp_kiss:NeedComms] Running Loop=1
2019-07-27T06:25:26.223Z,1564208726.223 [esp_kiss:NeedComms](DEBUG): Aggregate::initialize esp_kiss:NeedComms
2019-07-27T06:25:26.223Z,1564208726.223 [esp_kiss:NeedComms:B.GoToSurface] Running Loop=1
2019-07-27T06:25:26.223Z,1564208726.223 [esp_kiss:NeedComms:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-27T06:25:26.224Z,1564208726.224 [esp_kiss:NeedComms:B.GoToSurface](INFO): Received depth rate setting nan m/s.
2019-07-27T06:25:26.224Z,1564208726.224 [esp_kiss:NeedComms:B.GoToSurface](INFO): Received pitch setting 19.999999 degrees.
2019-07-27T06:25:26.224Z,1564208726.224 [esp_kiss:NeedComms:B.GoToSurface](INFO): Received speed setting 1.000000 m/s.
2019-07-27T06:25:26.225Z,1564208726.225 [esp_kiss:NeedComms:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-27T06:25:26.225Z,1564208726.225 [esp_kiss:NeedComms:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-27T06:25:26.225Z,1564208726.225 [esp_kiss:NeedComms:A] Running Loop=1
2019-07-27T06:25:26.226Z,1564208726.226 [esp_kiss:NeedComms:A](INFO): last time_fix was: 1564208512.000000 second since 1970/01/01T00:00:00Z 
2019-07-27T06:25:26.255Z,1564208726.255 [esp_kiss:NeedComms:A] Stopped
2019-07-27T06:25:26.640Z,1564208726.640 [esp_kiss:NeedComms:C] Running Loop=1
2019-07-27T06:25:27.040Z,1564208727.040 [esp_kiss:NeedComms:C](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-07-27T06:25:33.617Z,1564208733.617 [CommandLine](IMPORTANT): got command maintain sensor NAL9602.latitude_fix 36.797001 degree
2019-07-27T06:25:33.618Z,1564208733.618 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.latitude_fix" handled in the control thread.
2019-07-27T06:25:33.619Z,1564208733.619 [CommandLine](IMPORTANT): got command maintain sensor NAL9602.longitude_fix -121.847000 degree
2019-07-27T06:25:33.620Z,1564208733.620 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.longitude_fix" handled in the control thread.
2019-07-27T06:25:33.895Z,1564208733.895 [controlThread](DEBUG): Component order: CycleStarter,Depth_Keller,NAL9602,Onboard,BPC1,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,Maintain_NAL9602.latitude_fix,Maintain_NAL9602.longitude_fix,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-07-27T06:25:46.553Z,1564208746.553 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1564208768.000000 second
2019-07-27T06:25:46.811Z,1564208746.811 [esp_kiss:NeedComms:C] Stopped
2019-07-27T06:25:46.812Z,1564208746.812 [esp_kiss:NeedComms:D] Running Loop=1
2019-07-27T06:25:47.215Z,1564208747.215 [esp_kiss:NeedComms:D](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-07-27T06:25:53.966Z,1564208753.966 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190727T061504/Courier0008.lzma
2019-07-27T06:25:54.772Z,1564208754.772 [DataOverHttps](INFO): Moved sent file to Logs/20190727T061504/Courier0008.lzma.bak
2019-07-27T06:25:54.772Z,1564208754.772 [DataOverHttps](INFO): SBD MOMSN=11479658
2019-07-27T06:26:06.502Z,1564208766.502 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190727T061504/Express0010.lzma
2019-07-27T06:26:07.308Z,1564208767.308 [DataOverHttps](INFO): Moved sent file to Logs/20190727T061504/Express0010.lzma.bak
2019-07-27T06:26:07.308Z,1564208767.308 [DataOverHttps](INFO): SBD MOMSN=11479660
2019-07-27T06:26:09.070Z,1564208769.070 [esp_kiss:NeedComms:D] Stopped
2019-07-27T06:26:09.070Z,1564208769.070 [esp_kiss:NeedComms:E] Running Loop=1
2019-07-27T06:26:09.466Z,1564208769.466 [esp_kiss:NeedComms:E](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-07-27T06:26:16.330Z,1564208776.330 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-07-27T06:26:16.330Z,1564208776.330 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-07-27T06:26:16.331Z,1564208776.331 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-27T06:26:16.406Z,1564208776.406 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-27T06:26:16.742Z,1564208776.742 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-27T06:26:16.742Z,1564208776.742 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-07-27T06:26:17.752Z,1564208777.752 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1564208768.000000 second
2019-07-27T06:26:17.933Z,1564208777.933 [esp_kiss:NeedComms:E] Stopped
2019-07-27T06:26:17.934Z,1564208777.934 [esp_kiss:NeedComms](INFO): Completed esp_kiss:NeedComms
2019-07-27T06:26:17.934Z,1564208777.934 [esp_kiss:NeedComms] Stopped
2019-07-27T06:26:17.934Z,1564208777.934 [esp_kiss:NeedComms](DEBUG): Aggregate::uninitialize esp_kiss:NeedComms
2019-07-27T06:26:17.934Z,1564208777.934 [esp_kiss:NeedComms:B.GoToSurface] Stopped
2019-07-27T06:26:17.934Z,1564208777.934 [esp_kiss:NeedComms:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-27T06:26:18.358Z,1564208778.358 [esp_kiss:StartingMission](INFO): Completed esp_kiss:StartingMission
2019-07-27T06:26:18.358Z,1564208778.358 [esp_kiss:StartingMission] Stopped
2019-07-27T06:26:18.358Z,1564208778.358 [esp_kiss:StartingMission](DEBUG): Aggregate::uninitialize esp_kiss:StartingMission
2019-07-27T06:26:18.358Z,1564208778.358 [esp_kiss:InitialDive] Running Loop=1
2019-07-27T06:26:18.359Z,1564208778.359 [esp_kiss:InitialDive](DEBUG): Aggregate::initialize esp_kiss:InitialDive
2019-07-27T06:26:18.359Z,1564208778.359 [esp_kiss:InitialDive:A] Running Loop=1
2019-07-27T06:26:18.359Z,1564208778.359 [esp_kiss:InitialDive:B] Running Loop=1
2019-07-27T06:26:18.359Z,1564208778.359 [esp_kiss:InitialDive:C.Pitch] Running Loop=1
2019-07-27T06:26:18.359Z,1564208778.359 [esp_kiss:InitialDive:C.Pitch](DEBUG): Initialize.
2019-07-27T06:26:18.359Z,1564208778.359 [esp_kiss:InitialDive:D.Point] Running Loop=1
2019-07-27T06:26:18.359Z,1564208778.359 [esp_kiss:InitialDive:D.Point](DEBUG): Initialize.
2019-07-27T06:26:18.359Z,1564208778.359 [esp_kiss:InitialDive:E.Buoyancy] Running Loop=1
2019-07-27T06:26:18.359Z,1564208778.359 [esp_kiss:InitialDive:E.Buoyancy](DEBUG): Initialize Buoyancy Component.
2019-07-27T06:26:18.359Z,1564208778.359 [esp_kiss:InitialDive:F] Running Loop=1
2019-07-27T06:26:18.758Z,1564208778.758 [esp_kiss:InitialDive:F](INFO): Waiting for 90.000000 s while pumping down to neutral.
2019-07-27T06:26:18.758Z,1564208778.758 [esp_kiss:InitialDive:F] Stopped
2019-07-27T06:26:18.758Z,1564208778.758 [esp_kiss:InitialDive:G.Wait] Running Loop=1
2019-07-27T06:26:18.758Z,1564208778.758 [esp_kiss:InitialDive:G.Wait](DEBUG): Initialize Wait Component.
2019-07-27T06:26:18.758Z,1564208778.758 [esp_kiss:InitialDive:E.Buoyancy] Running Loop=1
2019-07-27T06:26:18.758Z,1564208778.758 [esp_kiss:InitialDive:D.Point] Running Loop=1
2019-07-27T06:26:18.759Z,1564208778.759 [esp_kiss:InitialDive:C.Pitch] Running Loop=1
2019-07-27T06:26:18.759Z,1564208778.759 [esp_kiss:InitialDive:B] Running Loop=1
2019-07-27T06:26:18.759Z,1564208778.759 [esp_kiss:InitialDive:A] Running Loop=1
2019-07-27T06:27:48.812Z,1564208868.812 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-07-27T06:27:49.261Z,1564208869.261 [esp_kiss:InitialDive:G.Wait](INFO): Done Waiting.
2019-07-27T06:27:49.261Z,1564208869.261 [esp_kiss:InitialDive:G.Wait] Stopped
2019-07-27T06:27:49.261Z,1564208869.261 [esp_kiss:InitialDive:G.Wait](DEBUG): Uninitialize Wait Component.
2019-07-27T06:27:49.262Z,1564208869.262 [esp_kiss:InitialDive:H] Running Loop=1
2019-07-27T06:27:49.677Z,1564208869.677 [esp_kiss:InitialDive:H](INFO): Moving to 3.000000 m 
2019-07-27T06:27:49.677Z,1564208869.677 [esp_kiss:InitialDive:H] Stopped
2019-07-27T06:27:49.677Z,1564208869.677 [esp_kiss:InitialDive:ApproachDepth] Running Loop=1
2019-07-27T06:27:49.677Z,1564208869.677 [esp_kiss:InitialDive:ApproachDepth](DEBUG): Aggregate::initialize esp_kiss:InitialDive:ApproachDepth
2019-07-27T06:27:49.678Z,1564208869.678 [esp_kiss:InitialDive:ApproachDepth:A.SetSpeed] Running Loop=1
2019-07-27T06:27:49.678Z,1564208869.678 [esp_kiss:InitialDive:ApproachDepth:A.SetSpeed](DEBUG): Initialize.
2019-07-27T06:27:49.678Z,1564208869.678 [esp_kiss:InitialDive:ApproachDepth:B.Pitch] Running Loop=1
2019-07-27T06:27:49.678Z,1564208869.678 [esp_kiss:InitialDive:ApproachDepth:B.Pitch](DEBUG): Initialize.
2019-07-27T06:27:50.046Z,1564208870.046 [esp_kiss:InitialDive:ApproachDepth:A.SetSpeed] Running Loop=1
2019-07-27T06:27:51.161Z,1564208871.161 [CommandLine](IMPORTANT): got command maintain sensor DepthRateCalculator.depth_rate 0.001000 meter_per_second
2019-07-27T06:27:51.162Z,1564208871.162 [ComponentRegistry](DEBUG): SyncComponent "Maintain_DepthRateCalculator.depth_rate" handled in the control thread.
2019-07-27T06:27:51.162Z,1564208871.162 [CommandLine](IMPORTANT): got command maintain sensor Depth_Keller.depth 3.000000 meter
2019-07-27T06:27:51.163Z,1564208871.163 [ComponentRegistry](DEBUG): SyncComponent "Maintain_Depth_Keller.depth" handled in the control thread.
2019-07-27T06:27:51.396Z,1564208871.396 [controlThread](DEBUG): Component order: CycleStarter,Depth_Keller,NAL9602,Onboard,BPC1,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,Maintain_NAL9602.latitude_fix,Maintain_NAL9602.longitude_fix,Maintain_DepthRateCalculator.depth_rate,Maintain_Depth_Keller.depth,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-07-27T06:27:51.666Z,1564208871.666 [esp_kiss:InitialDive:ApproachDepth:B.Pitch] Stopped
2019-07-27T06:27:51.667Z,1564208871.667 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth] Running Loop=1
2019-07-27T06:27:51.667Z,1564208871.667 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth](DEBUG): Aggregate::initialize esp_kiss:InitialDive:ApproachDepth:SettleAtDepth
2019-07-27T06:27:51.667Z,1564208871.667 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:B.Pitch] Running Loop=1
2019-07-27T06:27:51.667Z,1564208871.667 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:B.Pitch](DEBUG): Initialize.
2019-07-27T06:27:51.667Z,1564208871.667 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:A] Running Loop=1
2019-07-27T06:27:52.070Z,1564208872.070 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:B.Pitch] Running Loop=1
2019-07-27T06:27:52.072Z,1564208872.072 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:A](INFO): Reached 3.000000 m , settling for 0.000000 s 
2019-07-27T06:27:52.072Z,1564208872.072 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:A] Stopped
2019-07-27T06:27:52.072Z,1564208872.072 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:C.Wait] Running Loop=1
2019-07-27T06:27:52.072Z,1564208872.072 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:C.Wait](DEBUG): Initialize Wait Component.
2019-07-27T06:27:52.475Z,1564208872.475 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:C.Wait](INFO): Done Waiting.
2019-07-27T06:27:52.475Z,1564208872.475 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:C.Wait] Stopped
2019-07-27T06:27:52.475Z,1564208872.475 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:C.Wait](DEBUG): Uninitialize Wait Component.
2019-07-27T06:27:52.476Z,1564208872.476 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth](INFO): Completed esp_kiss:InitialDive:ApproachDepth:SettleAtDepth
2019-07-27T06:27:52.476Z,1564208872.476 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth] Stopped
2019-07-27T06:27:52.476Z,1564208872.476 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth](DEBUG): Aggregate::uninitialize esp_kiss:InitialDive:ApproachDepth:SettleAtDepth
2019-07-27T06:27:52.476Z,1564208872.476 [esp_kiss:InitialDive:ApproachDepth:SettleAtDepth:B.Pitch] Stopped
2019-07-27T06:27:52.476Z,1564208872.476 [esp_kiss:InitialDive:ApproachDepth](INFO): Completed esp_kiss:InitialDive:ApproachDepth
2019-07-27T06:27:52.476Z,1564208872.476 [esp_kiss:InitialDive:ApproachDepth] Stopped
2019-07-27T06:27:52.476Z,1564208872.476 [esp_kiss:InitialDive:ApproachDepth](DEBUG): Aggregate::uninitialize esp_kiss:InitialDive:ApproachDepth
2019-07-27T06:27:52.476Z,1564208872.476 [esp_kiss:InitialDive:ApproachDepth:A.SetSpeed] Stopped
2019-07-27T06:27:52.476Z,1564208872.476 [esp_kiss:InitialDive:ApproachDepth:A.SetSpeed](DEBUG): Uninitialize.
2019-07-27T06:27:52.478Z,1564208872.478 [esp_kiss:InitialDive](INFO): Completed esp_kiss:InitialDive
2019-07-27T06:27:52.478Z,1564208872.478 [esp_kiss:InitialDive] Stopped
2019-07-27T06:27:52.478Z,1564208872.478 [esp_kiss:InitialDive](DEBUG): Aggregate::uninitialize esp_kiss:InitialDive
2019-07-27T06:27:52.478Z,1564208872.478 [esp_kiss:InitialDive:A] Stopped
2019-07-27T06:27:52.478Z,1564208872.478 [esp_kiss:InitialDive:B] Stopped
2019-07-27T06:27:52.478Z,1564208872.478 [esp_kiss:InitialDive:C.Pitch] Stopped
2019-07-27T06:27:52.478Z,1564208872.478 [esp_kiss:InitialDive:D.Point] Stopped
2019-07-27T06:27:52.478Z,1564208872.478 [esp_kiss:InitialDive:E.Buoyancy] Stopped
2019-07-27T06:27:52.478Z,1564208872.478 [esp_kiss:InitialDive:E.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2019-07-27T06:27:52.478Z,1564208872.478 [esp_kiss:SampleAtTargetDepth] Running Loop=1
2019-07-27T06:27:52.478Z,1564208872.478 [esp_kiss:SampleAtTargetDepth](DEBUG): Aggregate::initialize esp_kiss:SampleAtTargetDepth
2019-07-27T06:27:52.479Z,1564208872.479 [esp_kiss:SampleAtTargetDepth:A.SetSpeed] Running Loop=1
2019-07-27T06:27:52.479Z,1564208872.479 [esp_kiss:SampleAtTargetDepth:A.SetSpeed](DEBUG): Initialize.
2019-07-27T06:27:52.479Z,1564208872.479 [esp_kiss:SampleAtTargetDepth:B.Pitch] Running Loop=1
2019-07-27T06:27:52.479Z,1564208872.479 [esp_kiss:SampleAtTargetDepth:B.Pitch](DEBUG): Initialize.
2019-07-27T06:27:52.479Z,1564208872.479 [esp_kiss:SampleAtTargetDepth:Spinout] Running Loop=1
2019-07-27T06:27:52.479Z,1564208872.479 [esp_kiss:SampleAtTargetDepth:Spinout](DEBUG): Aggregate::initialize esp_kiss:SampleAtTargetDepth:Spinout
2019-07-27T06:27:52.479Z,1564208872.479 [esp_kiss:SampleAtTargetDepth:Spinout:HoldMassPosition.Pitch] Running Loop=1
2019-07-27T06:27:52.479Z,1564208872.479 [esp_kiss:SampleAtTargetDepth:Spinout:HoldMassPosition.Pitch](DEBUG): Initialize.
2019-07-27T06:27:52.479Z,1564208872.479 [esp_kiss:SampleAtTargetDepth:Spinout:HoldBuoyancyPosition.Buoyancy] Running Loop=1
2019-07-27T06:27:52.479Z,1564208872.479 [esp_kiss:SampleAtTargetDepth:Spinout:HoldBuoyancyPosition.Buoyancy](DEBUG): Initialize Buoyancy Component.
2019-07-27T06:27:52.480Z,1564208872.480 [esp_kiss:SampleAtTargetDepth:Spinout:HoldRudderAngle.Point] Running Loop=1
2019-07-27T06:27:52.480Z,1564208872.480 [esp_kiss:SampleAtTargetDepth:Spinout:HoldRudderAngle.Point](DEBUG): Initialize.
2019-07-27T06:27:52.480Z,1564208872.480 [esp_kiss:SampleAtTargetDepth:GrabSamples] Running Loop=1
2019-07-27T06:27:52.480Z,1564208872.480 [esp_kiss:SampleAtTargetDepth:GrabSamples](DEBUG): Aggregate::initialize esp_kiss:SampleAtTargetDepth:GrabSamples
2019-07-27T06:27:52.480Z,1564208872.480 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1] Running Loop=1
2019-07-27T06:27:52.480Z,1564208872.480 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1](DEBUG): Aggregate::initialize esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1
2019-07-27T06:27:52.480Z,1564208872.480 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1:A] Running Loop=1
2019-07-27T06:27:52.879Z,1564208872.879 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1:A] Stopped
2019-07-27T06:27:52.879Z,1564208872.879 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1:B] Running Loop=1
2019-07-27T06:27:52.879Z,1564208872.879 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1:B](DEBUG): Aggregate::initialize esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1:B
2019-07-27T06:27:52.879Z,1564208872.879 [esp_kiss:SampleAtTargetDepth:Spinout] Stopped
2019-07-27T06:27:52.879Z,1564208872.879 [esp_kiss:SampleAtTargetDepth:Spinout](DEBUG): Aggregate::uninitialize esp_kiss:SampleAtTargetDepth:Spinout
2019-07-27T06:27:52.880Z,1564208872.880 [esp_kiss:SampleAtTargetDepth:Spinout:HoldMassPosition.Pitch] Stopped
2019-07-27T06:27:52.880Z,1564208872.880 [esp_kiss:SampleAtTargetDepth:Spinout:HoldBuoyancyPosition.Buoyancy] Stopped
2019-07-27T06:27:52.880Z,1564208872.880 [esp_kiss:SampleAtTargetDepth:Spinout:HoldBuoyancyPosition.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2019-07-27T06:27:52.880Z,1564208872.880 [esp_kiss:SampleAtTargetDepth:Spinout:HoldRudderAngle.Point] Stopped
2019-07-27T06:27:52.880Z,1564208872.880 [esp_kiss:SampleAtTargetDepth:B.Pitch] Running Loop=1
2019-07-27T06:27:52.880Z,1564208872.880 [esp_kiss:SampleAtTargetDepth:A.SetSpeed] Running Loop=1
2019-07-27T06:27:53.284Z,1564208873.284 [esp_kiss:SampleESP] Running Loop=1
2019-07-27T06:27:53.284Z,1564208873.284 [esp_kiss:SampleESP](DEBUG): Aggregate::initialize esp_kiss:SampleESP
2019-07-27T06:27:53.284Z,1564208873.284 [esp_kiss:SampleESP:sample] Running Loop=1
2019-07-27T06:27:53.285Z,1564208873.285 [esp_kiss:SampleESP:sample](DEBUG): Aggregate::initialize esp_kiss:SampleESP:sample
2019-07-27T06:27:53.285Z,1564208873.285 [esp_kiss:SampleESP:sample:A] Running Loop=1
2019-07-27T06:27:53.285Z,1564208873.285 [esp_kiss:SampleESP:sample:A](IMPORTANT): At 3.000000 m , settling for 3.000000 min 
2019-07-27T06:27:53.286Z,1564208873.286 [esp_kiss:SampleESP:sample:A] Stopped
2019-07-27T06:27:53.286Z,1564208873.286 [esp_kiss:SampleESP:sample:B.Wait] Running Loop=1
2019-07-27T06:27:53.286Z,1564208873.286 [esp_kiss:SampleESP:sample:B.Wait](DEBUG): Initialize Wait Component.
2019-07-27T06:28:17.147Z,1564208897.147 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-07-27T06:28:17.147Z,1564208897.147 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-07-27T06:28:17.147Z,1564208897.147 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-27T06:28:17.231Z,1564208897.231 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-27T06:28:17.602Z,1564208897.602 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-27T06:28:17.602Z,1564208897.602 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-07-27T06:28:19.515Z,1564208899.515 [NAL9602](INFO): Not Powering down - fast GPS
2019-07-27T06:28:52.023Z,1564208932.023 [Radio_Surface](INFO): Powering down
2019-07-27T06:28:52.071Z,1564208932.071 [DataOverHttps](INFO): Radio surface powered OFF, will not connect.
2019-07-27T06:30:18.320Z,1564209018.320 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-07-27T06:30:18.320Z,1564209018.320 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2019-07-27T06:30:18.320Z,1564209018.320 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-27T06:30:18.359Z,1564209018.359 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-27T06:30:18.791Z,1564209018.791 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-27T06:30:18.791Z,1564209018.791 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2019-07-27T06:30:53.865Z,1564209053.865 [esp_kiss:SampleESP:sample:B.Wait](INFO): Done Waiting.
2019-07-27T06:30:53.865Z,1564209053.865 [esp_kiss:SampleESP:sample:B.Wait] Stopped
2019-07-27T06:30:53.865Z,1564209053.865 [esp_kiss:SampleESP:sample:B.Wait](DEBUG): Uninitialize Wait Component.
2019-07-27T06:30:53.865Z,1564209053.865 [esp_kiss:SampleESP:sample:C] Running Loop=1
2019-07-27T06:30:54.276Z,1564209054.276 [esp_kiss:SampleESP:sample:C](IMPORTANT): Requesting ESP cartridge type: -4.000000 count 
2019-07-27T06:30:54.276Z,1564209054.276 [esp_kiss:SampleESP:sample:C] Stopped
2019-07-27T06:30:54.277Z,1564209054.277 [esp_kiss:SampleESP:sample:D] Running Loop=1
2019-07-27T06:30:54.676Z,1564209054.676 [esp_kiss:SampleESP:sample:D] Stopped
2019-07-27T06:30:54.676Z,1564209054.676 [esp_kiss:SampleESP:sample:TriggerESP] Running Loop=1
2019-07-27T06:30:55.080Z,1564209055.080 [esp_kiss:SampleESP:sample:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling
2019-07-27T06:30:56.291Z,1564209056.291 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:30:57.095Z,1564209057.095 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:30:57.895Z,1564209057.895 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:30:58.703Z,1564209058.703 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:30:59.523Z,1564209059.523 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:00.327Z,1564209060.327 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:01.135Z,1564209061.135 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:01.939Z,1564209061.939 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:02.749Z,1564209062.749 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:03.559Z,1564209063.559 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:04.367Z,1564209064.367 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:05.175Z,1564209065.175 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:05.980Z,1564209065.980 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:06.783Z,1564209066.783 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:07.595Z,1564209067.595 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:08.403Z,1564209068.403 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:09.212Z,1564209069.212 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:10.015Z,1564209070.015 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:10.823Z,1564209070.823 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:11.635Z,1564209071.635 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:12.443Z,1564209072.443 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:13.260Z,1564209073.260 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:14.055Z,1564209074.055 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:14.863Z,1564209074.863 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:15.671Z,1564209075.671 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:16.484Z,1564209076.484 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:17.291Z,1564209077.291 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:18.103Z,1564209078.103 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:18.907Z,1564209078.907 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:19.716Z,1564209079.716 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:20.519Z,1564209080.519 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:21.335Z,1564209081.335 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:22.139Z,1564209082.139 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:22.946Z,1564209082.946 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:23.751Z,1564209083.751 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:24.559Z,1564209084.559 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:25.371Z,1564209085.371 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:26.183Z,1564209086.183 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:26.991Z,1564209086.991 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:27.791Z,1564209087.791 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:28.599Z,1564209088.599 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:29.407Z,1564209089.407 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:30.223Z,1564209090.223 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:31.023Z,1564209091.023 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:31.831Z,1564209091.831 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:32.639Z,1564209092.639 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:33.459Z,1564209093.459 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:34.263Z,1564209094.263 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:35.063Z,1564209095.063 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:35.871Z,1564209095.871 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:36.684Z,1564209096.684 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:37.487Z,1564209097.487 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:38.299Z,1564209098.299 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:39.107Z,1564209099.107 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:39.919Z,1564209099.919 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:40.719Z,1564209100.719 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:41.527Z,1564209101.527 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:42.343Z,1564209102.343 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:43.152Z,1564209103.152 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:43.951Z,1564209103.951 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:44.767Z,1564209104.767 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:45.575Z,1564209105.575 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:46.381Z,1564209106.381 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:47.187Z,1564209107.187 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:47.999Z,1564209107.999 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:48.799Z,1564209108.799 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:49.615Z,1564209109.615 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:50.428Z,1564209110.428 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:51.231Z,1564209111.231 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:51.851Z,1564209111.851 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=180.183472
2019-07-27T06:31:52.031Z,1564209112.031 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:52.839Z,1564209112.839 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:53.647Z,1564209113.647 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:54.459Z,1564209114.459 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:55.271Z,1564209115.271 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:56.079Z,1564209116.079 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:56.885Z,1564209116.885 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:57.687Z,1564209117.687 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:58.495Z,1564209118.495 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:31:59.307Z,1564209119.307 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:32:00.123Z,1564209120.123 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:32:00.919Z,1564209120.919 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:32:01.727Z,1564209121.727 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:32:02.539Z,1564209122.539 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:32:03.352Z,1564209123.352 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:32:04.159Z,1564209124.159 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:32:04.959Z,1564209124.959 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:32:05.540Z,1564209125.540 [CommandLine](IMPORTANT): got command stop
2019-07-27T06:32:05.541Z,1564209125.541 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-07-27T06:32:05.768Z,1564209125.768 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-27T06:32:05.780Z,1564209125.780 [MissionManager](INFO): MissionManager is completed.
2019-07-27T06:32:05.780Z,1564209125.780 [MissionManager](INFO): Uninitializing Mission esp_kiss
2019-07-27T06:32:05.780Z,1564209125.780 [esp_kiss] Stopped
2019-07-27T06:32:05.780Z,1564209125.780 [esp_kiss](DEBUG): Aggregate::uninitialize esp_kiss
2019-07-27T06:32:05.780Z,1564209125.780 [esp_kiss:A.AbortSample] Stopped
2019-07-27T06:32:05.780Z,1564209125.780 [esp_kiss:A.AbortSample](INFO): Uninitializing AbortSample.
2019-07-27T06:32:05.781Z,1564209125.781 [esp_kiss:StandardEnvelopes] Stopped
2019-07-27T06:32:05.781Z,1564209125.781 [esp_kiss:StandardEnvelopes](DEBUG): Aggregate::uninitialize esp_kiss:StandardEnvelopes
2019-07-27T06:32:05.781Z,1564209125.781 [esp_kiss:StandardEnvelopes:A.AltitudeEnvelope] Stopped
2019-07-27T06:32:05.781Z,1564209125.781 [esp_kiss:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2019-07-27T06:32:05.781Z,1564209125.781 [esp_kiss:StandardEnvelopes:B.DepthEnvelope] Stopped
2019-07-27T06:32:05.781Z,1564209125.781 [esp_kiss:StandardEnvelopes:B.DepthEnvelope](DEBUG): Uninitialize.
2019-07-27T06:32:05.781Z,1564209125.781 [esp_kiss:StandardEnvelopes:C.OffshoreEnvelope] Stopped
2019-07-27T06:32:05.781Z,1564209125.781 [esp_kiss:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2019-07-27T06:32:05.781Z,1564209125.781 [esp_kiss:I] Stopped
2019-07-27T06:32:05.781Z,1564209125.781 [esp_kiss:SampleESP] Stopped
2019-07-27T06:32:05.781Z,1564209125.781 [esp_kiss:SampleESP](DEBUG): Aggregate::uninitialize esp_kiss:SampleESP
2019-07-27T06:32:05.781Z,1564209125.781 [esp_kiss:SampleESP:sample] Stopped
2019-07-27T06:32:05.781Z,1564209125.781 [esp_kiss:SampleESP:sample](DEBUG): Aggregate::uninitialize esp_kiss:SampleESP:sample
2019-07-27T06:32:05.782Z,1564209125.782 [esp_kiss:SampleESP:sample:TriggerESP] Stopped
2019-07-27T06:32:05.782Z,1564209125.782 [esp_kiss:Science] Stopped
2019-07-27T06:32:05.782Z,1564209125.782 [esp_kiss:Science](DEBUG): Aggregate::uninitialize esp_kiss:Science
2019-07-27T06:32:05.782Z,1564209125.782 [esp_kiss:SampleAtTargetDepth] Stopped
2019-07-27T06:32:05.782Z,1564209125.782 [esp_kiss:SampleAtTargetDepth](DEBUG): Aggregate::uninitialize esp_kiss:SampleAtTargetDepth
2019-07-27T06:32:05.782Z,1564209125.782 [esp_kiss:SampleAtTargetDepth:A.SetSpeed] Stopped
2019-07-27T06:32:05.782Z,1564209125.782 [esp_kiss:SampleAtTargetDepth:A.SetSpeed](DEBUG): Uninitialize.
2019-07-27T06:32:05.782Z,1564209125.782 [esp_kiss:SampleAtTargetDepth:B.Pitch] Stopped
2019-07-27T06:32:05.782Z,1564209125.782 [esp_kiss:SampleAtTargetDepth:GrabSamples] Stopped
2019-07-27T06:32:05.782Z,1564209125.782 [esp_kiss:SampleAtTargetDepth:GrabSamples](DEBUG): Aggregate::uninitialize esp_kiss:SampleAtTargetDepth:GrabSamples
2019-07-27T06:32:05.782Z,1564209125.782 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1] Stopped
2019-07-27T06:32:05.783Z,1564209125.783 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1](DEBUG): Aggregate::uninitialize esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1
2019-07-27T06:32:05.783Z,1564209125.783 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1:B] Stopped
2019-07-27T06:32:05.783Z,1564209125.783 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1:B](DEBUG): Aggregate::uninitialize esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1:B
2019-07-27T06:32:06.212Z,1564209126.212 [MissionManager](IMPORTANT): Started mission Default
2019-07-27T06:32:06.212Z,1564209126.212 [Default] Running Loop=1
2019-07-27T06:32:06.213Z,1564209126.213 [Default](DEBUG): Aggregate::initialize Default
2019-07-27T06:32:06.213Z,1564209126.213 [Default:B.GoToSurface] Running Loop=1
2019-07-27T06:32:06.213Z,1564209126.213 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-27T06:32:06.213Z,1564209126.213 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-27T06:32:06.213Z,1564209126.213 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-27T06:32:06.214Z,1564209126.214 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-27T06:32:06.214Z,1564209126.214 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-27T06:32:06.214Z,1564209126.214 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-27T06:32:06.215Z,1564209126.215 [Default:A.Wait] Running Loop=1
2019-07-27T06:32:06.215Z,1564209126.215 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-07-27T06:32:06.578Z,1564209126.578 [ESPComponent](DEBUG): Resetting stopSampling to false
2019-07-27T06:32:06.578Z,1564209126.578 [ESPComponent](IMPORTANT): [sample #0] No ESP summary messages.
2019-07-27T06:32:06.578Z,1564209126.578 [ESPComponent](INFO): powering down ESP
2019-07-27T06:32:06.579Z,1564209126.579 [ESPComponent](INFO): powering down ESP secondary power supply
2019-07-27T06:32:06.755Z,1564209126.755 [Radio_Surface](INFO): Powering up
2019-07-27T06:32:12.051Z,1564209132.051 [DataOverHttps](INFO): Radio surface powered ON.
2019-07-27T06:32:13.872Z,1564209133.872 [CommandLine](IMPORTANT): got command maintain clear
2019-07-27T06:32:13.997Z,1564209133.997 [controlThread](DEBUG): Component order: CycleStarter,Depth_Keller,NAL9602,Onboard,BPC1,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-07-27T06:32:19.145Z,1564209139.145 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-07-27T06:32:19.145Z,1564209139.145 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2019-07-27T06:32:19.145Z,1564209139.145 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-27T06:32:19.231Z,1564209139.231 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-27T06:32:19.556Z,1564209139.556 [Default:A.Wait](INFO): Done Waiting.
2019-07-27T06:32:19.556Z,1564209139.556 [Default:A.Wait] Stopped
2019-07-27T06:32:19.556Z,1564209139.556 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-27T06:32:19.647Z,1564209139.647 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-27T06:32:19.647Z,1564209139.647 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2019-07-27T06:32:19.949Z,1564209139.949 [Default:CheckIn] Running Loop=1
2019-07-27T06:32:19.949Z,1564209139.949 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-07-27T06:32:19.949Z,1564209139.949 [Default:CheckIn:Read_GPS] Running Loop=1
2019-07-27T06:32:21.552Z,1564209141.552 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-07-27T06:32:21.552Z,1564209141.552 [NAL9602] Data Fault, FailCount= 1
2019-07-27T06:32:21.552Z,1564209141.552 [NAL9602](ERROR): Data Fault
2019-07-27T06:32:21.636Z,1564209141.636 [CBIT](ERROR): Data Fault in component: NAL9602
2019-07-27T06:32:21.952Z,1564209141.952 [NAL9602](INFO): Powering down
2019-07-27T06:32:22.835Z,1564209142.835 [CBIT](INFO): Clearing failed state for component NAL9602
2019-07-27T06:32:22.835Z,1564209142.835 [NAL9602] No Fault, FailCount= 1
2019-07-27T06:32:42.351Z,1564209162.351 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-07-27T06:32:52.256Z,1564209172.256 [NAL9602](INFO): Powering up NAL9602
2019-07-27T06:33:03.164Z,1564209183.164 [NAL9602](INFO): NAL9602 initialized
2019-07-27T06:33:03.979Z,1564209183.979 [NAL9602](DEBUG): Fix Requested
2019-07-27T06:33:13.055Z,1564209193.055 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-07-27T06:33:43.759Z,1564209223.759 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-07-27T06:34:14.463Z,1564209254.463 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-07-27T06:34:19.965Z,1564209259.965 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-07-27T06:34:19.965Z,1564209259.965 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2019-07-27T06:34:19.965Z,1564209259.965 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-27T06:34:20.003Z,1564209260.003 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-27T06:34:20.403Z,1564209260.403 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-27T06:34:20.403Z,1564209260.403 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2019-07-27T06:34:29.192Z,1564209269.192 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003766
2019-07-27T06:34:40.092Z,1564209280.092 [CommandLine](IMPORTANT): got command maintain clear
2019-07-27T06:36:21.155Z,1564209381.155 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-07-27T06:36:21.155Z,1564209381.155 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5
2019-07-27T06:36:21.155Z,1564209381.155 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-27T06:36:21.195Z,1564209381.195 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-27T06:36:21.566Z,1564209381.566 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-27T06:36:21.566Z,1564209381.566 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5
2019-07-27T06:37:03.868Z,1564209423.868 [CommandLine](IMPORTANT): got command restart application
2019-07-27T06:37:04.875Z,1564209424.875 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-27T06:37:04.875Z,1564209424.875 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-27T06:37:04.915Z,1564209424.915 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-07-27T06:37:04.915Z,1564209424.915 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-27T06:37:04.916Z,1564209424.916 [CommandLine](INFO): Join timeout helper Thread ID is 6584
2019-07-27T06:37:04.916Z,1564209424.916 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-07-27T06:37:04.916Z,1564209424.916 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-27T06:37:04.916Z,1564209424.916 [NavChartDb](INFO): Join timeout helper Thread ID is 6585
2019-07-27T06:37:05.311Z,1564209425.311 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-27T06:37:05.311Z,1564209425.311 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-27T06:37:05.319Z,1564209425.319 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-07-27T06:37:05.319Z,1564209425.319 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-27T06:37:05.319Z,1564209425.319 [Radio_Surface](INFO): Join timeout helper Thread ID is 6586
2019-07-27T06:37:05.343Z,1564209425.343 [Radio_Surface](INFO): Powering down
2019-07-27T06:37:05.344Z,1564209425.344 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-27T06:37:05.344Z,1564209425.344 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-27T06:37:05.359Z,1564209425.359 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-07-27T06:37:05.359Z,1564209425.359 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-27T06:37:05.359Z,1564209425.359 [DataOverHttps](INFO): Join timeout helper Thread ID is 6587
2019-07-27T06:37:05.564Z,1564209425.564 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-27T06:37:05.564Z,1564209425.564 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-27T06:37:05.572Z,1564209425.572 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-07-27T06:37:05.572Z,1564209425.572 [logger ThreadHandler](INFO): Thread cancelled.
2019-07-27T06:37:05.573Z,1564209425.573 [logger](INFO): Join timeout helper Thread ID is 6588
2019-07-27T06:37:05.603Z,1564209425.603 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-27T06:37:05.603Z,1564209425.603 [logger ThreadHandler](INFO): Thread cancelled.
2019-07-27T06:37:05.612Z,1564209425.612 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-07-27T06:37:05.612Z,1564209425.612 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-27T06:37:05.612Z,1564209425.612 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-07-27T06:37:05.612Z,1564209425.612 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-07-27T06:37:05.612Z,1564209425.612 [controlThread](INFO): Join timeout helper Thread ID is 6589
2019-07-27T06:37:05.955Z,1564209425.955 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-27T06:37:05.955Z,1564209425.955 [controlThread](DEBUG): Uninitializing ControlThread
2019-07-27T06:37:05.956Z,1564209425.956 [NAL9602](INFO): Powering down
2019-07-27T06:37:05.959Z,1564209425.959 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-07-27T06:37:05.960Z,1564209425.960 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-07-27T06:37:05.960Z,1564209425.960 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-07-27T06:37:05.960Z,1564209425.960 [MissionManager](INFO): Uninitializing Mission Default
2019-07-27T06:37:05.960Z,1564209425.960 [Default] Stopped
2019-07-27T06:37:05.960Z,1564209425.960 [Default](DEBUG): Aggregate::uninitialize Default
2019-07-27T06:37:05.961Z,1564209425.961 [Default:B.GoToSurface] Stopped
2019-07-27T06:37:05.961Z,1564209425.961 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-27T06:37:05.961Z,1564209425.961 [Default:CheckIn] Stopped
2019-07-27T06:37:05.961Z,1564209425.961 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-07-27T06:37:05.961Z,1564209425.961 [Default:CheckIn:Read_GPS] Stopped
2019-07-27T06:37:05.963Z,1564209425.963 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-07-27T06:37:05.963Z,1564209425.963 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-07-27T06:37:05.964Z,1564209425.964 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-07-27T06:37:05.964Z,1564209425.964 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-07-27T06:37:05.964Z,1564209425.964 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-07-27T06:37:05.964Z,1564209425.964 [BuoyancyServo](INFO): Powering down
2019-07-27T06:37:05.979Z,1564209425.979 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-07-27T06:37:05.979Z,1564209425.979 [ElevatorServo](INFO): Powering down
2019-07-27T06:37:05.980Z,1564209425.980 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-07-27T06:37:05.980Z,1564209425.980 [MassServo](INFO): Powering down
2019-07-27T06:37:05.981Z,1564209425.981 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-07-27T06:37:05.981Z,1564209425.981 [RudderServo](INFO): Powering down
2019-07-27T06:37:05.981Z,1564209425.981 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-07-27T06:37:05.982Z,1564209425.982 [ThrusterServo](INFO): Powering down
2019-07-27T06:37:05.982Z,1564209425.982 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-07-27T06:37:05.983Z,1564209425.983 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-07-27T06:37:05.983Z,1564209425.983 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-07-27T06:37:05.983Z,1564209425.983 [CBIT](DEBUG): Powering off loads.
2019-07-27T06:37:05.995Z,1564209425.995 [CBIT](DEBUG): Disabling WDT.
2019-07-27T06:37:06.007Z,1564209426.007 [CBIT](DEBUG): Opening all GF detection circuits.
2019-07-27T06:37:06.007Z,1564209426.007 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-07-27T06:37:06.099Z,1564209426.099 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-27T06:37:06.104Z,1564209426.104 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-27T06:37:06.181Z,1564209426.181 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-27T06:37:06.250Z,1564209426.250 [logger ThreadHandler](INFO): Thread cancelled.