2019-07-25T20:12:39.413Z,1564085559.413 [Supervisor](DEBUG): Initializing supervisor.
2019-07-25T20:12:39.416Z,1564085559.416 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-07-25T20:12:39.416Z,1564085559.416 [SyncHandler](INFO): Protected caller Thread ID is 3524
2019-07-25T20:12:39.417Z,1564085559.417 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-07-25T20:12:39.418Z,1564085559.418 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-07-25T20:12:39.418Z,1564085559.418 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 3525
2019-07-25T20:12:39.421Z,1564085559.421 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-07-25T20:12:39.433Z,1564085559.433 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-07-25T20:12:39.434Z,1564085559.434 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-07-25T20:12:39.434Z,1564085559.434 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 3526
2019-07-25T20:12:39.435Z,1564085559.435 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-07-25T20:12:39.436Z,1564085559.436 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-07-25T20:12:39.436Z,1564085559.436 [logger ThreadHandler](INFO): Protected caller Thread ID is 3527
2019-07-25T20:12:39.438Z,1564085559.438 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-07-25T20:12:39.439Z,1564085559.439 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-07-25T20:12:39.440Z,1564085559.440 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-07-25T20:12:39.709Z,1564085559.709 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-07-25T20:12:39.710Z,1564085559.710 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-07-25T20:12:39.792Z,1564085559.792 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-07-25T20:12:40.250Z,1564085560.250 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-07-25T20:12:40.251Z,1564085560.251 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-07-25T20:12:40.584Z,1564085560.584 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-07-25T20:12:40.585Z,1564085560.585 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-07-25T20:12:40.683Z,1564085560.683 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-07-25T20:12:40.684Z,1564085560.684 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-07-25T20:12:40.981Z,1564085560.981 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-07-25T20:12:40.982Z,1564085560.982 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-07-25T20:12:41.307Z,1564085561.307 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-07-25T20:12:41.308Z,1564085561.308 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-07-25T20:12:41.758Z,1564085561.758 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-07-25T20:12:41.758Z,1564085561.758 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-07-25T20:12:41.866Z,1564085561.866 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-07-25T20:12:41.866Z,1564085561.866 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-07-25T20:12:41.969Z,1564085561.969 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-07-25T20:12:41.969Z,1564085561.969 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-07-25T20:12:42.563Z,1564085562.563 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-07-25T20:12:42.563Z,1564085562.563 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-07-25T20:12:42.953Z,1564085562.953 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-07-25T20:12:42.953Z,1564085562.953 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-07-25T20:12:43.150Z,1564085563.150 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-07-25T20:12:43.151Z,1564085563.151 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-07-25T20:12:43.298Z,1564085563.298 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-07-25T20:12:43.298Z,1564085563.298 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-07-25T20:12:43.448Z,1564085563.448 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-07-25T20:12:43.451Z,1564085563.451 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2019-07-25T20:12:43.451Z,1564085563.451 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2019-07-25T20:12:43.545Z,1564085563.545 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2019-07-25T20:12:43.634Z,1564085563.634 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2019-07-25T20:12:43.739Z,1564085563.739 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2019-07-25T20:12:43.825Z,1564085563.825 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2019-07-25T20:12:43.924Z,1564085563.924 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2019-07-25T20:12:44.027Z,1564085564.027 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2019-07-25T20:12:44.239Z,1564085564.239 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2019-07-25T20:12:44.318Z,1564085564.318 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2019-07-25T20:12:44.489Z,1564085564.489 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2019-07-25T20:12:44.625Z,1564085564.625 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2019-07-25T20:12:44.746Z,1564085564.746 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg
2019-07-25T20:12:44.974Z,1564085564.974 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-07-25T20:12:44.976Z,1564085564.976 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/root/
2019-07-25T20:12:44.976Z,1564085564.976 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-07-25T20:12:44.998Z,1564085564.998 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-07-25T20:12:45.065Z,1564085565.065 [VerticalControl](DEBUG): Construct VerticalControl.
2019-07-25T20:12:45.173Z,1564085565.173 [VerticalControl] Loaded
2019-07-25T20:12:45.174Z,1564085565.174 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-07-25T20:12:45.174Z,1564085565.174 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-07-25T20:12:45.241Z,1564085565.241 [HorizontalControl] Loaded
2019-07-25T20:12:45.241Z,1564085565.241 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-07-25T20:12:45.242Z,1564085565.242 [SpeedControl](DEBUG): Construct SpeedControl.
2019-07-25T20:12:45.247Z,1564085565.247 [SpeedControl] Loaded
2019-07-25T20:12:45.247Z,1564085565.247 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-07-25T20:12:45.248Z,1564085565.248 [LoopControl](DEBUG): Construct LoopControl.
2019-07-25T20:12:45.249Z,1564085565.249 [LoopControl] Loaded
2019-07-25T20:12:45.249Z,1564085565.249 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-07-25T20:12:45.249Z,1564085565.249 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-07-25T20:12:45.250Z,1564085565.250 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-07-25T20:12:45.263Z,1564085565.263 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-07-25T20:12:45.264Z,1564085565.264 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-07-25T20:12:45.360Z,1564085565.360 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-07-25T20:12:45.360Z,1564085565.360 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-07-25T20:12:45.486Z,1564085565.486 [BuoyancyServo] Loaded
2019-07-25T20:12:45.487Z,1564085565.487 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-07-25T20:12:45.498Z,1564085565.498 [ElevatorServo] Loaded
2019-07-25T20:12:45.498Z,1564085565.498 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-07-25T20:12:45.508Z,1564085565.508 [MassServo] Loaded
2019-07-25T20:12:45.509Z,1564085565.509 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-07-25T20:12:45.519Z,1564085565.519 [RudderServo] Loaded
2019-07-25T20:12:45.520Z,1564085565.520 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-07-25T20:12:45.530Z,1564085565.530 [ThrusterServo] Loaded
2019-07-25T20:12:45.531Z,1564085565.531 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-07-25T20:12:45.531Z,1564085565.531 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-07-25T20:12:45.532Z,1564085565.532 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-07-25T20:12:45.637Z,1564085565.637 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-07-25T20:12:45.637Z,1564085565.637 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-07-25T20:12:45.658Z,1564085565.658 [NavChart] Loaded
2019-07-25T20:12:45.658Z,1564085565.658 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-07-25T20:12:45.662Z,1564085565.662 [UniversalFixResidualReporter] Loaded
2019-07-25T20:12:45.662Z,1564085565.662 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-07-25T20:12:45.662Z,1564085565.662 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-07-25T20:12:45.663Z,1564085565.663 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-07-25T20:12:45.735Z,1564085565.735 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-07-25T20:12:45.736Z,1564085565.736 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-07-25T20:12:46.065Z,1564085566.065 [DataOverHttps] Loaded
2019-07-25T20:12:46.065Z,1564085566.065 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-07-25T20:12:46.066Z,1564085566.066 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4087D4E0
2019-07-25T20:12:46.067Z,1564085566.067 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 3609
2019-07-25T20:12:46.080Z,1564085566.080 [Depth_Keller] Loaded
2019-07-25T20:12:46.080Z,1564085566.080 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-07-25T20:12:46.174Z,1564085566.174 [NAL9602] Loaded
2019-07-25T20:12:46.174Z,1564085566.174 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-07-25T20:12:46.190Z,1564085566.190 [Onboard] Loaded
2019-07-25T20:12:46.190Z,1564085566.190 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-07-25T20:12:46.193Z,1564085566.193 [Radio_Surface] Loaded
2019-07-25T20:12:46.194Z,1564085566.194 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-07-25T20:12:46.195Z,1564085566.195 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408AD4E0
2019-07-25T20:12:46.195Z,1564085566.195 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 3610
2019-07-25T20:12:47.948Z,1564085567.948 [BPC1] Loaded
2019-07-25T20:12:47.949Z,1564085567.949 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-07-25T20:12:47.949Z,1564085567.949 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-07-25T20:12:47.949Z,1564085567.949 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-07-25T20:12:47.990Z,1564085567.990 [DepthRateCalculator] Loaded
2019-07-25T20:12:47.990Z,1564085567.990 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-07-25T20:12:47.995Z,1564085567.995 [PitchRateCalculator] Loaded
2019-07-25T20:12:47.995Z,1564085567.995 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-07-25T20:12:48.007Z,1564085568.007 [SpeedCalculator] Loaded
2019-07-25T20:12:48.007Z,1564085568.007 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-07-25T20:12:48.028Z,1564085568.028 [TempGradientCalculator] Loaded
2019-07-25T20:12:48.028Z,1564085568.028 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-07-25T20:12:48.033Z,1564085568.033 [YawRateCalculator] Loaded
2019-07-25T20:12:48.034Z,1564085568.034 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-07-25T20:12:48.063Z,1564085568.063 [ElevatorOffsetCalculator] Loaded
2019-07-25T20:12:48.063Z,1564085568.063 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-07-25T20:12:48.063Z,1564085568.063 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-07-25T20:12:48.064Z,1564085568.064 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-07-25T20:12:48.258Z,1564085568.258 [ESPComponent] Loaded
2019-07-25T20:12:48.258Z,1564085568.258 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2019-07-25T20:12:48.272Z,1564085568.272 [PAR_Licor] Loaded
2019-07-25T20:12:48.272Z,1564085568.272 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2019-07-25T20:12:48.273Z,1564085568.273 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-07-25T20:12:48.274Z,1564085568.274 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-07-25T20:12:48.306Z,1564085568.306 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-07-25T20:12:48.307Z,1564085568.307 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-07-25T20:12:49.125Z,1564085569.125 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-07-25T20:12:49.125Z,1564085569.125 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-07-25T20:12:49.474Z,1564085569.474 [SBIT](DEBUG): Construct Startup Built In Test.
2019-07-25T20:12:49.485Z,1564085569.485 [SBIT] Loaded
2019-07-25T20:12:49.485Z,1564085569.485 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-07-25T20:12:49.486Z,1564085569.486 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-07-25T20:12:49.497Z,1564085569.497 [IBIT] Loaded
2019-07-25T20:12:49.497Z,1564085569.497 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-07-25T20:12:49.501Z,1564085569.501 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-07-25T20:12:49.867Z,1564085569.867 [CBIT] Loaded
2019-07-25T20:12:49.867Z,1564085569.867 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-07-25T20:12:49.867Z,1564085569.867 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-07-25T20:12:49.871Z,1564085569.871 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-07-25T20:12:49.872Z,1564085569.872 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-07-25T20:12:49.879Z,1564085569.879 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-07-25T20:12:49.880Z,1564085569.880 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A7F4E0
2019-07-25T20:12:49.880Z,1564085569.880 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 3611
2019-07-25T20:12:49.885Z,1564085569.885 [Supervisor](INFO): Main Thread ID is 1790
2019-07-25T20:12:49.885Z,1564085569.885 [Supervisor](DEBUG): Running supervisor.
2019-07-25T20:12:49.886Z,1564085569.886 [CommandLine ThreadHandler](INFO): Handler Thread ID is 3612
2019-07-25T20:12:49.897Z,1564085569.897 [controlThread ThreadHandler](INFO): Handler Thread ID is 3613
2019-07-25T20:12:49.898Z,1564085569.898 [controlThread](DEBUG): Initializing ControlThread
2019-07-25T20:12:49.898Z,1564085569.898 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-07-25T20:12:49.900Z,1564085569.900 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-07-25T20:12:49.900Z,1564085569.900 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-07-25T20:12:49.901Z,1564085569.901 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-07-25T20:12:49.902Z,1564085569.902 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-07-25T20:12:49.903Z,1564085569.903 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-07-25T20:12:49.906Z,1564085569.906 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-07-25T20:12:49.906Z,1564085569.906 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-07-25T20:12:49.907Z,1564085569.907 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-07-25T20:12:49.907Z,1564085569.907 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-07-25T20:12:49.908Z,1564085569.908 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-07-25T20:12:49.908Z,1564085569.908 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-07-25T20:12:49.913Z,1564085569.913 [SBIT](INFO): Initialize SBIT Component.
2019-07-25T20:12:49.914Z,1564085569.914 [SBIT](IMPORTANT): git: 2019-07-23
2019-07-25T20:12:49.914Z,1564085569.914 [SBIT](INFO): git hash: 66f82fd8c0ed4c5b011038c11738fd4b7b507f51
2019-07-25T20:12:49.914Z,1564085569.914 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-07-25T20:12:49.915Z,1564085569.915 [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-25T20:12:49.916Z,1564085569.916 [SBIT](INFO): Beginning SBIT in 29.000000 seconds.
2019-07-25T20:12:49.917Z,1564085569.917 [IBIT](INFO): Initialize IBIT Component.
2019-07-25T20:12:49.918Z,1564085569.918 [CBIT](DEBUG): Initialize CBIT Component.
2019-07-25T20:12:49.919Z,1564085569.919 [logger ThreadHandler](INFO): Handler Thread ID is 3614
2019-07-25T20:12:49.920Z,1564085569.920 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 3615
2019-07-25T20:12:49.921Z,1564085569.921 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 3616
2019-07-25T20:12:49.937Z,1564085569.937 [CBIT](DEBUG): Initialized mux pins.
2019-07-25T20:12:49.937Z,1564085569.937 [CBIT](DEBUG): Initializing the watchdog timer.
2019-07-25T20:12:49.941Z,1564085569.941 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-07-25T20:12:49.944Z,1564085569.944 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 3617
2019-07-25T20:12:49.961Z,1564085569.961 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-07-25T20:12:49.961Z,1564085569.961 [CBIT](DEBUG): Initializing heartbeat.
2019-07-25T20:12:50.033Z,1564085570.033 [CBIT](DEBUG): Deactivating GF circuits.
2019-07-25T20:12:50.033Z,1564085570.033 [CBIT](DEBUG): Deactivating emergency mode.
2019-07-25T20:12:50.069Z,1564085570.069 [CBIT](DEBUG): Backplane powered.
2019-07-25T20:12:50.070Z,1564085570.070 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-07-25T20:12:50.251Z,1564085570.251 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-07-25T20:12:50.251Z,1564085570.251 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-07-25T20:12:50.251Z,1564085570.251 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-07-25T20:12:50.251Z,1564085570.251 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-07-25T20:12:50.251Z,1564085570.251 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-07-25T20:12:50.251Z,1564085570.251 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-07-25T20:12:50.252Z,1564085570.252 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-07-25T20:12:50.252Z,1564085570.252 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-07-25T20:12:50.252Z,1564085570.252 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-07-25T20:12:50.252Z,1564085570.252 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-07-25T20:12:50.252Z,1564085570.252 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-07-25T20:12:50.252Z,1564085570.252 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-07-25T20:12:50.253Z,1564085570.253 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-07-25T20:12:50.253Z,1564085570.253 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-07-25T20:12:50.253Z,1564085570.253 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-07-25T20:12:50.253Z,1564085570.253 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-07-25T20:12:50.266Z,1564085570.266 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-07-25T20:12:50.297Z,1564085570.297 [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-25T20:12:50.298Z,1564085570.298 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-07-25T20:12:50.325Z,1564085570.325 [Radio_Surface](INFO): Powering up
2019-07-25T20:12:50.524Z,1564085570.524 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-07-25T20:12:50.525Z,1564085570.525 [Default:A.Wait](DEBUG): Construct Wait.
2019-07-25T20:12:50.527Z,1564085570.527 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-07-25T20:12:50.587Z,1564085570.587 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-07-25T20:12:50.589Z,1564085570.589 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-07-25T20:12:50.617Z,1564085570.617 [Default:E.Execute](DEBUG): Construct Execute.
2019-07-25T20:12:50.637Z,1564085570.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: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-25T20:12:50.641Z,1564085570.641 [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-25T20:12:50.682Z,1564085570.682 [Depth_Keller](ERROR): Pressure reading out of range: 1831.023193 decibar
2019-07-25T20:12:50.865Z,1564085570.865 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-07-25T20:12:50.887Z,1564085570.887 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-07-25T20:12:50.893Z,1564085570.893 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-07-25T20:12:50.894Z,1564085570.894 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-07-25T20:12:50.901Z,1564085570.901 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-07-25T20:12:50.902Z,1564085570.902 [MassServo](DEBUG): Initializing EZServoServo.
2019-07-25T20:12:50.909Z,1564085570.909 [MassServo](DEBUG): Initializing MassServo.
2019-07-25T20:12:50.910Z,1564085570.910 [RudderServo](DEBUG): Initializing EZServoServo.
2019-07-25T20:12:50.917Z,1564085570.917 [RudderServo](DEBUG): Initializing RudderServo.
2019-07-25T20:12:50.918Z,1564085570.918 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-07-25T20:12:50.925Z,1564085570.925 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-07-25T20:12:51.809Z,1564085571.809 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-07-25T20:12:51.809Z,1564085571.809 [RudderServo](FAULT): Rudder failed to initialize
2019-07-25T20:12:51.809Z,1564085571.809 [RudderServo] Communications Fault, FailCount= 1
2019-07-25T20:12:51.809Z,1564085571.809 [RudderServo](ERROR): Communications Fault
2019-07-25T20:12:51.920Z,1564085571.920 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-07-25T20:12:52.118Z,1564085572.118 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-07-25T20:12:52.118Z,1564085572.118 [RudderServo](INFO): Powering down
2019-07-25T20:12:52.805Z,1564085572.805 [RudderServo](DEBUG): Initializing EZServoServo.
2019-07-25T20:12:52.926Z,1564085572.926 [RudderServo](DEBUG): Initializing RudderServo.
2019-07-25T20:12:52.930Z,1564085572.930 [CBIT](INFO): Clearing failed state for component RudderServo
2019-07-25T20:12:52.930Z,1564085572.930 [RudderServo] No Fault, FailCount= 1
2019-07-25T20:13:00.118Z,1564085580.118 [CBIT](CRITICAL): Environmental Failure. Press:14.764948 PSI. Humidity:28%. Temp:30 C. ABORTING MISSION
2019-07-25T20:13:00.119Z,1564085580.119 [Supervisor](INFO): Stop Mission called by CBIT::monitorEnvironmentals
2019-07-25T20:13:00.503Z,1564085580.503 [CommandLine](FAULT): Scheduling is paused
2019-07-25T20:13:00.504Z,1564085580.504 [CBIT](INFO): Critical error at 20190725T201300
2019-07-25T20:13:16.574Z,1564085596.574 [NAL9602](INFO): Powering up NAL9602
2019-07-25T20:13:19.468Z,1564085599.468 [SBIT](IMPORTANT): Beginning Startup BIT
2019-07-25T20:13:19.472Z,1564085599.472 [CBIT](IMPORTANT): Beginning ground fault scan
2019-07-25T20:13:27.566Z,1564085607.566 [NAL9602](INFO): NAL9602 initialized
2019-07-25T20:13:28.385Z,1564085608.385 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:13:30.445Z,1564085610.445 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): -0.016033
CHAN A1 (24V): 4.592929
CHAN A2 (12V): -0.002263
CHAN A3 (5V): -0.001751
CHAN B0 (3.3V): -0.000311
CHAN B1 (3.15aV): -0.000020
CHAN B2 (3.15bV): -0.000346
CHAN B3 (GND): 0.000120
OPEN: -0.000286
Full Scale Calc: 4.765 mA, -1.589 mA
2019-07-25T20:14:12.769Z,1564085652.769 [SBIT](IMPORTANT): SBIT PASSED
2019-07-25T20:14:12.789Z,1564085652.789 [CommandLine](IMPORTANT): got command configSet list
2019-07-25T20:14:12.790Z,1564085652.790 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-07-25T20:14:12.790Z,1564085652.790 [CommandLine](IMPORTANT): AHRS_M2.loadAtStartup=0 bool;

2019-07-25T20:14:12.791Z,1564085652.791 [CommandLine](IMPORTANT): Aanderaa_O2.loadAtStartup=0 bool;

2019-07-25T20:14:12.791Z,1564085652.791 [CommandLine](IMPORTANT): BPC1.batteryMissingStickThreshold=0 count;

2019-07-25T20:14:12.791Z,1564085652.791 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=6 hour;

2019-07-25T20:14:12.791Z,1564085652.791 [CommandLine](IMPORTANT): CBIT.abortDepth=296 meter;

2019-07-25T20:14:12.791Z,1564085652.791 [CommandLine](IMPORTANT): CBIT.gf24Offset=172 microampere;

2019-07-25T20:14:12.791Z,1564085652.791 [CommandLine](IMPORTANT): CBIT.stopDepth=288 meter;

2019-07-25T20:14:12.791Z,1564085652.791 [CommandLine](IMPORTANT): CTD_NeilBrown.loadAtStartup=0 bool;

2019-07-25T20:14:12.791Z,1564085652.791 [CommandLine](IMPORTANT): CTD_Seabird.loadAtStartup=0 bool;

2019-07-25T20:14:12.791Z,1564085652.791 [CommandLine](IMPORTANT): DAT.ignoreElevationAngle=1 bool;

2019-07-25T20:14:12.792Z,1564085652.792 [CommandLine](IMPORTANT): DAT.loadAtStartup=0 bool;

2019-07-25T20:14:12.792Z,1564085652.792 [CommandLine](IMPORTANT): DVL_micro.loadAtStartup=0 bool;

2019-07-25T20:14:12.792Z,1564085652.792 [CommandLine](IMPORTANT): DropWeight.loadAtStartup=0 bool;

2019-07-25T20:14:12.792Z,1564085652.792 [CommandLine](IMPORTANT): ESPComponent.loadAtStartup=1 bool;

2019-07-25T20:14:12.792Z,1564085652.792 [CommandLine](IMPORTANT): Express linearApproximation DAT.range 5.000000 meter;

2019-07-25T20:14:12.792Z,1564085652.792 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 10.000000 meter;

2019-07-25T20:14:12.792Z,1564085652.792 [CommandLine](IMPORTANT): Express linearApproximation depth 5.000000 meter;

2019-07-25T20:14:12.792Z,1564085652.792 [CommandLine](IMPORTANT): Express linearApproximation latitude 0.005000 degree;

2019-07-25T20:14:12.792Z,1564085652.792 [CommandLine](IMPORTANT): Express linearApproximation longitude 0.005000 degree;

2019-07-25T20:14:12.793Z,1564085652.793 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-07-25T20:14:12.793Z,1564085652.793 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=274 cubic_centimeter;

2019-07-25T20:14:12.793Z,1564085652.793 [CommandLine](IMPORTANT): VerticalControl.massDefault=-2.3 millimeter;

2019-07-25T20:14:12.793Z,1564085652.793 [CommandLine](IMPORTANT): VerticalControl.massPositionLimitAft=-31 millimeter;

2019-07-25T20:14:12.793Z,1564085652.793 [CommandLine](IMPORTANT): VerticalControl.massPositionLimitFwd=30 millimeter;

2019-07-25T20:14:12.793Z,1564085652.793 [CommandLine](IMPORTANT): WetLabsBB2FL.loadAtStartup=0 bool;

2019-07-25T20:14:13.097Z,1564085653.097 [MissionManager](IMPORTANT): Started mission Startup
2019-07-25T20:14:13.098Z,1564085653.098 [Startup] Running Loop=1
2019-07-25T20:14:13.098Z,1564085653.098 [Startup](DEBUG): Aggregate::initialize Startup
2019-07-25T20:14:13.098Z,1564085653.098 [Startup:A.GoToSurface] Running Loop=1
2019-07-25T20:14:13.098Z,1564085653.098 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-25T20:14:13.099Z,1564085653.099 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-25T20:14:13.099Z,1564085653.099 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-25T20:14:13.099Z,1564085653.099 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-25T20:14:13.100Z,1564085653.100 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-25T20:14:13.100Z,1564085653.100 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-25T20:14:13.102Z,1564085653.102 [Startup:StartupSatComms] Running Loop=1
2019-07-25T20:14:13.102Z,1564085653.102 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-07-25T20:14:13.102Z,1564085653.102 [Startup:StartupSatComms:A] Running Loop=1
2019-07-25T20:14:13.503Z,1564085653.503 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-07-25T20:14:50.268Z,1564085690.268 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-07-25T20:14:50.268Z,1564085690.268 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-07-25T20:14:50.268Z,1564085690.268 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-25T20:14:50.309Z,1564085690.309 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-25T20:14:50.656Z,1564085690.656 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-25T20:14:50.656Z,1564085690.656 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-07-25T20:15:13.278Z,1564085713.278 [Startup:StartupSatComms:A](INFO): Timed out from 2019-07-25T20:14:13.1Z
2019-07-25T20:15:13.279Z,1564085713.279 [Startup:StartupSatComms:A] Stopped
2019-07-25T20:15:13.279Z,1564085713.279 [Startup:StartupSatComms:B] Running Loop=1
2019-07-25T20:15:13.688Z,1564085713.688 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-07-25T20:15:28.599Z,1564085728.599 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.009276
2019-07-25T20:15:33.589Z,1564085733.589 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190724T051104/Courier0517.lzma
2019-07-25T20:15:34.397Z,1564085734.397 [DataOverHttps](INFO): Moved sent file to Logs/20190724T051104/Courier0517.lzma.bak
2019-07-25T20:15:34.397Z,1564085734.397 [DataOverHttps](INFO): SBD MOMSN=11475534
2019-07-25T20:15:45.096Z,1564085745.096 [DataOverHttps](INFO): Sending 143 bytes from file Logs/20190725T201239/Courier0000.lzma
2019-07-25T20:15:45.902Z,1564085745.902 [DataOverHttps](INFO): Moved sent file to Logs/20190725T201239/Courier0000.lzma.bak
2019-07-25T20:15:45.902Z,1564085745.902 [DataOverHttps](INFO): SBD MOMSN=11475536
2019-07-25T20:15:57.212Z,1564085757.212 [DataOverHttps](INFO): Sending 78 bytes from file Logs/20190724T051104/Express0518.lzma
2019-07-25T20:15:58.019Z,1564085758.019 [DataOverHttps](INFO): Moved sent file to Logs/20190724T051104/Express0518.lzma.bak
2019-07-25T20:15:58.019Z,1564085758.019 [DataOverHttps](INFO): SBD MOMSN=11475540
2019-07-25T20:11:55.477Z,1564085515.477 [CommandLine](IMPORTANT): got command failComponent
2019-07-25T20:11:55.478Z,1564085515.478 [CommandLine](IMPORTANT): Failed components:
2019-07-25T20:11:55.478Z,1564085515.478 [CommandLine](IMPORTANT): No failed Components.
2019-07-25T20:13:38.015Z,1564085618.015 [CommandLine](IMPORTANT): got command failComponent
2019-07-25T20:13:38.015Z,1564085618.015 [CommandLine](IMPORTANT): Failed components:
2019-07-25T20:13:38.015Z,1564085618.015 [CommandLine](IMPORTANT): No failed Components.
2019-07-25T20:15:28.772Z,1564085728.772 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-07-25T20:15:35.183Z,1564085735.183 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-07-25T20:15:35.186Z,1564085735.186 [BPC1](INFO): Received data from all battery sticks.
2019-07-25T20:16:06.392Z,1564085766.392 [DataOverHttps](INFO): Sending 1171 bytes from file Logs/20190725T201239/Express0001.lzma
2019-07-25T20:16:11.511Z,1564085771.511 [DataOverHttps](INFO): Sending 1171 bytes from file Logs/20190725T201239/Express0001.lzma
2019-07-25T20:16:12.315Z,1564085772.315 [DataOverHttps](INFO): Moved sent file to Logs/20190725T201239/Express0001.lzma.bak
2019-07-25T20:16:12.315Z,1564085772.315 [DataOverHttps](IMPORTANT): SBD MOMSN=11475544, MTMSN=20190725T201611
2019-07-25T20:16:13.590Z,1564085773.590 [Startup:StartupSatComms:B](INFO): Timed out from 2019-07-25T20:15:13.3Z
2019-07-25T20:16:13.590Z,1564085773.590 [Startup:StartupSatComms:B] Stopped
2019-07-25T20:16:13.591Z,1564085773.591 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-07-25T20:16:13.591Z,1564085773.591 [Startup:StartupSatComms] Stopped
2019-07-25T20:16:13.591Z,1564085773.591 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-07-25T20:16:13.591Z,1564085773.591 [Startup](INFO): Completed Startup
2019-07-25T20:16:13.592Z,1564085773.592 [MissionManager](INFO): Startup is completed.
2019-07-25T20:16:13.592Z,1564085773.592 [MissionManager](INFO): Uninitializing Mission Startup
2019-07-25T20:16:13.592Z,1564085773.592 [Startup] Stopped
2019-07-25T20:16:13.592Z,1564085773.592 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-07-25T20:16:13.592Z,1564085773.592 [Startup:A.GoToSurface] Stopped
2019-07-25T20:16:13.592Z,1564085773.592 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-25T20:16:13.974Z,1564085773.974 [MissionManager](IMPORTANT): Started mission Default
2019-07-25T20:16:13.974Z,1564085773.974 [Default] Running Loop=1
2019-07-25T20:16:13.975Z,1564085773.975 [Default](DEBUG): Aggregate::initialize Default
2019-07-25T20:16:13.975Z,1564085773.975 [Default:B.GoToSurface] Running Loop=1
2019-07-25T20:16:13.975Z,1564085773.975 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-25T20:16:13.975Z,1564085773.975 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-25T20:16:13.975Z,1564085773.975 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-25T20:16:13.976Z,1564085773.976 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-25T20:16:13.976Z,1564085773.976 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-25T20:16:13.976Z,1564085773.976 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-25T20:16:13.976Z,1564085773.976 [Default:A.Wait] Running Loop=1
2019-07-25T20:16:13.977Z,1564085773.977 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-07-25T20:16:18.062Z,1564085778.062 [DataOverHttps](INFO): Received command:load Maintenance/sample.xml;set sample.CartridgeType -4 count;set sample.WaitBeforeSample 0.1 minute;run 
2019-07-25T20:16:18.074Z,1564085778.074 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/sample.xml
2019-07-25T20:16:18.075Z,1564085778.075 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/sample.xml
2019-07-25T20:16:18.100Z,1564085778.100 [MissionManager](INFO): DefineArg sample.MissionTimeout = 90.000000 min
2019-07-25T20:16:18.103Z,1564085778.103 [MissionManager](INFO): DefineArg sample.Depth = 7.000000 m
2019-07-25T20:16:18.106Z,1564085778.106 [MissionManager](INFO): DefineArg sample.CartridgeType = -1.000000 count
2019-07-25T20:16:18.108Z,1564085778.108 [MissionManager](INFO): DefineArg sample.NumberOfSamples = 1.000000 count
2019-07-25T20:16:18.111Z,1564085778.111 [MissionManager](INFO): DefineArg sample.WaitBeforeSample = 3.000000 min
2019-07-25T20:16:18.112Z,1564085778.112 [sample:A.AbortSample](DEBUG): Construct.
2019-07-25T20:16:18.114Z,1564085778.114 [sample:B.Pitch](DEBUG): Construct.
2019-07-25T20:16:18.120Z,1564085778.120 [sample:C.SetSpeed](DEBUG): Construct.
2019-07-25T20:16:18.122Z,1564085778.122 [MissionManager](INFO): Inserting Stack: Missions/Insert/SampleAtDepth.xml
2019-07-25T20:16:18.307Z,1564085778.307 [MissionManager](INFO): DefineArg sample:SampleAtDepth.TargetDepth = 5.000000 m
2019-07-25T20:16:18.318Z,1564085778.318 [MissionManager](INFO): DefineArg sample:SampleAtDepth.SettleTime = 10.000000 s
2019-07-25T20:16:18.326Z,1564085778.326 [MissionManager](INFO): DefineArg sample:SampleAtDepth.MaxWaitNotReachingDepth = 3.000000 h
2019-07-25T20:16:18.328Z,1564085778.328 [MissionManager](INFO): DefineArg sample:SampleAtDepth.RotateOnly = 0.000000 bool
2019-07-25T20:16:18.342Z,1564085778.342 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseCANONSampler = 0.000000 bool
2019-07-25T20:16:18.348Z,1564085778.348 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseESP = 1.000000 bool
2019-07-25T20:16:18.351Z,1564085778.351 [MissionManager](INFO): DefineArg sample:SampleAtDepth.ESPCartridgeType = nan count
2019-07-25T20:16:18.358Z,1564085778.358 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTriggerTimeout = 1.000000 min
2019-07-25T20:16:18.361Z,1564085778.361 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTimeout = 6.000000 min
2019-07-25T20:16:18.364Z,1564085778.364 [MissionManager](INFO): DefineArg sample:SampleAtDepth.BuoyancyNeutral = 273.999991 cc
2019-07-25T20:16:18.367Z,1564085778.367 [sample:SampleAtDepth:ApproachDepth:B.Pitch](DEBUG): Construct.
2019-07-25T20:16:18.427Z,1564085778.427 [sample:SampleAtDepth:ApproachDepth:B.Pitch:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-07-25T20:16:18.435Z,1564085778.435 [sample:SampleAtDepth:SampleWrapper:A.Pitch](DEBUG): Construct.
2019-07-25T20:16:18.462Z,1564085778.462 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Construct Wait.
2019-07-25T20:16:18.477Z,1564085778.477 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-07-25T20:16:18.492Z,1564085778.492 [MissionManager](ERROR): Slate does not contain CTD_NeilBrown.bin_mean_sea_water_temperature
2019-07-25T20:16:18.492Z,1564085778.492 [MissionManager](ERROR): Slate does not contain celsius
2019-07-25T20:16:18.492Z,1564085778.492 [MissionManager](ERROR): Slate does not contain WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water
2019-07-25T20:16:18.493Z,1564085778.493 [MissionManager](ERROR): Slate does not contain microgram_per_liter
2019-07-25T20:16:18.500Z,1564085778.500 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:E:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-07-25T20:16:18.528Z,1564085778.528 [MissionManager](ERROR): Slate does not contain CTD_NeilBrown.bin_mean_sea_water_temperature
2019-07-25T20:16:18.528Z,1564085778.528 [MissionManager](ERROR): Slate does not contain celsius
2019-07-25T20:16:18.529Z,1564085778.529 [MissionManager](ERROR): Slate does not contain WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water
2019-07-25T20:16:18.533Z,1564085778.533 [MissionManager](ERROR): Slate does not contain microgram_per_liter
2019-07-25T20:16:18.582Z,1564085778.582 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<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"
       Id="sample">

    <Description>
        This mission is designed to be run in the test tank only and samples
        whichever sampler is installed once the vehicle reaches the target
        depth.
    </Description>

    <DefineArg Name="MissionTimeout"><Description>
        How long to let the mission run.
    </Description><Units:minute/><Value>90</Value></DefineArg>

    <DefineArg Name="Depth"><Description>
        Depth to sample at.
    </Description><Units:meter/><Value>7</Value></DefineArg>

    <DefineArg Name="CartridgeType"><Description>
        Specifies ESP cartridge type code.
    </Description><Units:count/><Value>-1</Value></DefineArg>
    
    <DefineArg Name="NumberOfSamples"><Description>
        Number of samples to take.
    </Description><Units:count/><Value>1</Value></DefineArg>

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

    <Timeout Duration="MissionTimeout"/>

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

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

    <Guidance:SetSpeed>
        <Parallel/>
        <Setting><Guidance:SetSpeed.speed/><Units:meter_per_second/><Value>0</Value></Setting>
    </Guidance:SetSpeed>

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

    <Assign><Sequence/><Arg Name="SampleAtDepth:TargetDepth"/><Arg Name="Depth"/></Assign>

    <Assign><Sequence/><Arg Name="SampleAtDepth:SettleTime"/><Arg Name="WaitBeforeSample"/></Assign>

    <Assign><Sequence/><Arg Name="SampleAtDepth:ESPCartridgeType"/><Arg Name="CartridgeType"/></Assign>

    <Aggregate Id="SampleRepeater">

        <Sequence Repeat="NumberOfSamples"/>

        <Call Id="Sample" RefId="SampleAtDepth"/>

    </Aggregate>

</Mission>


2019-07-25T20:16:18.582Z,1564085778.582 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/sample.xml
2019-07-25T20:16:22.001Z,1564085782.001 [CommandLine](IMPORTANT): got command set sample.CartridgeType -4.000000 count
2019-07-25T20:16:22.010Z,1564085782.010 [CommandLine](IMPORTANT): got command set sample.WaitBeforeSample 0.100000 minute
2019-07-25T20:16:22.011Z,1564085782.011 [CommandLine](IMPORTANT): got command run 
2019-07-25T20:16:22.013Z,1564085782.013 [CommandLine](IMPORTANT): Running 
2019-07-25T20:16:22.047Z,1564085782.047 [Default] Stopped
2019-07-25T20:16:22.047Z,1564085782.047 [Default](DEBUG): Aggregate::uninitialize Default
2019-07-25T20:16:22.047Z,1564085782.047 [Default:A.Wait] Stopped
2019-07-25T20:16:22.047Z,1564085782.047 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-25T20:16:22.047Z,1564085782.047 [Default:B.GoToSurface] Stopped
2019-07-25T20:16:22.047Z,1564085782.047 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-25T20:16:22.048Z,1564085782.048 [MissionManager](IMPORTANT): Started mission sample
2019-07-25T20:16:22.048Z,1564085782.048 [sample] Running Loop=1
2019-07-25T20:16:22.048Z,1564085782.048 [sample](DEBUG): Aggregate::initialize sample
2019-07-25T20:16:22.048Z,1564085782.048 [sample:A.AbortSample] Running Loop=1
2019-07-25T20:16:22.048Z,1564085782.048 [sample:A.AbortSample](INFO): Initializing AbortSample.
2019-07-25T20:16:22.048Z,1564085782.048 [sample:B.Pitch] Running Loop=1
2019-07-25T20:16:22.048Z,1564085782.048 [sample:B.Pitch](DEBUG): Initialize.
2019-07-25T20:16:22.049Z,1564085782.049 [sample:C.SetSpeed] Running Loop=1
2019-07-25T20:16:22.049Z,1564085782.049 [sample:C.SetSpeed](DEBUG): Initialize.
2019-07-25T20:16:22.049Z,1564085782.049 [sample:E] Running Loop=1
2019-07-25T20:16:22.050Z,1564085782.050 [sample:E] Stopped
2019-07-25T20:16:22.050Z,1564085782.050 [sample:F] Running Loop=1
2019-07-25T20:16:22.050Z,1564085782.050 [sample:C.SetSpeed] Running Loop=1
2019-07-25T20:16:22.050Z,1564085782.050 [sample:B.Pitch] Running Loop=1
2019-07-25T20:16:22.050Z,1564085782.050 [sample:A.AbortSample] Running Loop=1
2019-07-25T20:16:22.470Z,1564085782.470 [sample:F] Stopped
2019-07-25T20:16:22.471Z,1564085782.471 [sample:G] Running Loop=1
2019-07-25T20:16:22.865Z,1564085782.865 [sample:G] Stopped
2019-07-25T20:16:22.865Z,1564085782.865 [sample:SampleRepeater] Running Loop=1
2019-07-25T20:16:22.865Z,1564085782.865 [sample:SampleRepeater](DEBUG): Aggregate::initialize sample:SampleRepeater
2019-07-25T20:16:22.865Z,1564085782.865 [sample:SampleRepeater:Sample] Running Loop=1
2019-07-25T20:16:22.866Z,1564085782.866 [sample:SampleRepeater:Sample](DEBUG): Aggregate::initialize sample:SampleRepeater:Sample
2019-07-25T20:16:23.279Z,1564085783.279 [sample:SampleAtDepth] Running Loop=1
2019-07-25T20:16:23.279Z,1564085783.279 [sample:SampleAtDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth
2019-07-25T20:16:23.279Z,1564085783.279 [sample:SampleAtDepth:ApproachDepth] Running Loop=1
2019-07-25T20:16:23.279Z,1564085783.279 [sample:SampleAtDepth:ApproachDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth:ApproachDepth
2019-07-25T20:16:23.279Z,1564085783.279 [sample:SampleAtDepth:ApproachDepth:A] Running Loop=1
2019-07-25T20:16:23.280Z,1564085783.280 [sample:SampleAtDepth:ApproachDepth:A](INFO): Moving to 7.000000 m 
2019-07-25T20:16:23.280Z,1564085783.280 [sample:SampleAtDepth:ApproachDepth:A] Stopped
2019-07-25T20:16:23.280Z,1564085783.280 [sample:SampleAtDepth:ApproachDepth:B.Pitch] Running Loop=1
2019-07-25T20:16:23.280Z,1564085783.280 [sample:SampleAtDepth:ApproachDepth:B.Pitch](DEBUG): Initialize.
2019-07-25T20:16:47.072Z,1564085807.072 [CommandLine](IMPORTANT): got command maintain sensor Depth_Keller.depth 7.000000 meter
2019-07-25T20:16:47.074Z,1564085807.074 [ComponentRegistry](DEBUG): SyncComponent "Maintain_Depth_Keller.depth" handled in the control thread.
2019-07-25T20:16:47.174Z,1564085807.174 [controlThread](DEBUG): Component order: CycleStarter,Depth_Keller,NAL9602,Onboard,BPC1,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,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-25T20:16:47.516Z,1564085807.516 [sample:SampleAtDepth:ApproachDepth:B.Pitch] Stopped
2019-07-25T20:16:47.516Z,1564085807.516 [sample:SampleAtDepth:ApproachDepth](INFO): Completed sample:SampleAtDepth:ApproachDepth
2019-07-25T20:16:47.516Z,1564085807.516 [sample:SampleAtDepth:ApproachDepth] Stopped
2019-07-25T20:16:47.516Z,1564085807.516 [sample:SampleAtDepth:ApproachDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:ApproachDepth
2019-07-25T20:16:47.516Z,1564085807.516 [sample:SampleAtDepth:SampleWrapper] Running Loop=1
2019-07-25T20:16:47.516Z,1564085807.516 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper
2019-07-25T20:16:47.517Z,1564085807.517 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Running Loop=1
2019-07-25T20:16:47.517Z,1564085807.517 [sample:SampleAtDepth:SampleWrapper:A.Pitch](DEBUG): Initialize.
2019-07-25T20:16:47.517Z,1564085807.517 [sample:SampleAtDepth:SampleWrapper:B] Running Loop=1
2019-07-25T20:16:47.934Z,1564085807.934 [sample:SampleAtDepth:SampleWrapper:B](IMPORTANT): At 7.000000 m , settling for 0.100000 min 
2019-07-25T20:16:47.934Z,1564085807.934 [sample:SampleAtDepth:SampleWrapper:B] Stopped
2019-07-25T20:16:47.934Z,1564085807.934 [sample:SampleAtDepth:SampleWrapper:C.Wait] Running Loop=1
2019-07-25T20:16:47.935Z,1564085807.935 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Initialize Wait Component.
2019-07-25T20:16:47.935Z,1564085807.935 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Running Loop=1
2019-07-25T20:16:51.146Z,1564085811.146 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-07-25T20:16:51.146Z,1564085811.146 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2019-07-25T20:16:51.146Z,1564085811.146 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-25T20:16:51.158Z,1564085811.158 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-25T20:16:51.614Z,1564085811.614 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-25T20:16:51.614Z,1564085811.614 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2019-07-25T20:16:54.382Z,1564085814.382 [sample:SampleAtDepth:SampleWrapper:C.Wait](INFO): Done Waiting.
2019-07-25T20:16:54.382Z,1564085814.382 [sample:SampleAtDepth:SampleWrapper:C.Wait] Stopped
2019-07-25T20:16:54.382Z,1564085814.382 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Uninitialize Wait Component.
2019-07-25T20:16:54.383Z,1564085814.383 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Running Loop=1
2019-07-25T20:16:54.383Z,1564085814.383 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler
2019-07-25T20:16:54.383Z,1564085814.383 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Running Loop=1
2019-07-25T20:16:54.383Z,1564085814.383 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Running Loop=1
2019-07-25T20:16:54.383Z,1564085814.383 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Running Loop=1
2019-07-25T20:16:54.794Z,1564085814.794 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Stopped
2019-07-25T20:16:54.794Z,1564085814.794 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler
2019-07-25T20:16:54.794Z,1564085814.794 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Stopped
2019-07-25T20:16:54.794Z,1564085814.794 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Stopped
2019-07-25T20:16:54.794Z,1564085814.794 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Stopped
2019-07-25T20:16:54.795Z,1564085814.795 [sample:SampleAtDepth:SampleWrapper:SampleESP] Running Loop=1
2019-07-25T20:16:54.795Z,1564085814.795 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleESP
2019-07-25T20:16:54.795Z,1564085814.795 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge] Running Loop=1
2019-07-25T20:16:54.795Z,1564085814.795 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge
2019-07-25T20:16:54.795Z,1564085814.795 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge:A] Running Loop=1
2019-07-25T20:16:55.191Z,1564085815.191 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge:A] Stopped
2019-07-25T20:16:55.191Z,1564085815.191 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge](INFO): Completed sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge
2019-07-25T20:16:55.191Z,1564085815.191 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge] Stopped
2019-07-25T20:16:55.191Z,1564085815.191 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge
2019-07-25T20:16:55.191Z,1564085815.191 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Running Loop=1
2019-07-25T20:16:55.594Z,1564085815.594 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling
2019-07-25T20:16:56.382Z,1564085816.382 [ESPComponent](IMPORTANT): Setting regex for ESP Log summary: 'Selecting Cartridge|Sampled|Error|Fail|Retry|Cmd::|Sampler::'
2019-07-25T20:16:56.428Z,1564085816.428 [ESPComponent](INFO): compiled regex: "Selecting Cartridge|Sampled|Error|Fail|Retry|Cmd::|Sampler::"
2019-07-25T20:16:56.787Z,1564085816.787 [ESPComponent](INFO): powering up ESP
2019-07-25T20:16:56.805Z,1564085816.805 [ESPComponent](INFO): powering up ESP secondary power supply
2019-07-25T20:16:56.822Z,1564085816.822 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 /dev/ttyTX1 linkname esp noauth local lock 115200 10.89.8.2:10.89.8.3 persist maxfail 0 holdoff 10 lcp-echo-interval 60 lcp-echo-failure 3 proxyarp ktune deflate 12 ms-dns 8.8.8.8
2019-07-25T20:16:56.947Z,1564085816.947 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=150.0000)
2019-07-25T20:16:57.265Z,1564085817.265 [ESPComponent](INFO): console:
2019-07-25T20:16:58.008Z,1564085818.008 [ESPComponent](INFO): console:

2019-07-25T20:16:58.406Z,1564085818.406 [ESPComponent](INFO): console:NAND:  256 MiB
2019-07-25T20:16:58.824Z,1564085818.824 [ESPComponent](INFO): console:
BOOTMODE: SDMMC
2019-07-25T20:16:59.209Z,1564085819.209 [ESPComponent](INFO): console:

2019-07-25T20:16:59.632Z,1564085819.632 [ESPComponent](INFO): console:

2019-07-25T20:17:00.042Z,1564085820.042 [ESPComponent](INFO): console:
U-Boot 2009.11-mbariC (Apr 02 2019 - 18:00:17)
2019-07-25T20:17:00.436Z,1564085820.436 [ESPComponent](INFO): console:

2019-07-25T20:17:00.844Z,1564085820.844 [ESPComponent](INFO): console:
MBARI LPC31xx ESP 3G
2019-07-25T20:17:01.239Z,1564085821.239 [ESPComponent](INFO): console:
flash params are already written into flash
2019-07-25T20:17:01.634Z,1564085821.634 [ESPComponent](INFO): console:
DRAM:  64 MB
2019-07-25T20:17:02.038Z,1564085822.038 [ESPComponent](INFO): console:
In:    serial
2019-07-25T20:17:02.442Z,1564085822.442 [ESPComponent](INFO): console:
Out:   serial
2019-07-25T20:17:02.843Z,1564085822.843 [ESPComponent](INFO): console:
Err:   serial
2019-07-25T20:17:03.255Z,1564085823.255 [ESPComponent](INFO): console:
Net:   ks8851_mll
2019-07-25T20:17:03.659Z,1564085823.659 [ESPComponent](INFO): console:
Hit <ctrl-C> to stop autoboot:  1  0 
2019-07-25T20:17:04.059Z,1564085824.059 [ESPComponent](INFO): console:
mmc1 is available
2019-07-25T20:17:04.471Z,1564085824.471 [ESPComponent](INFO): console:
reading uImage
2019-07-25T20:17:04.888Z,1564085824.888 [ESPComponent](INFO): console:

2019-07-25T20:17:05.281Z,1564085825.281 [ESPComponent](INFO): console:
1681452 bytes read
2019-07-25T20:17:05.688Z,1564085825.688 [ESPComponent](INFO): console:
## Booting kernel from Legacy Image at 31000000 ...
2019-07-25T20:17:06.093Z,1564085826.093 [ESPComponent](INFO): console:
   Image Name:   Linux-2.6.33-ea3131-mbari6
2019-07-25T20:17:06.483Z,1564085826.483 [ESPComponent](INFO): console:
   Image Type:   ARM Linux Kernel Image (uncompressed)
2019-07-25T20:17:06.890Z,1564085826.890 [ESPComponent](INFO): console:
   Data Size:    1681388 Bytes =  1.6 MB
2019-07-25T20:17:07.294Z,1564085827.294 [ESPComponent](INFO): console:
   Load Address: 30008000
2019-07-25T20:17:07.698Z,1564085827.698 [ESPComponent](INFO): console:
   Entry Point:  30008000
2019-07-25T20:17:08.105Z,1564085828.105 [ESPComponent](INFO): console:
   Verifying Checksum ... OK
2019-07-25T20:17:08.507Z,1564085828.507 [ESPComponent](INFO): console:
   Loading Kernel Image ... OK
2019-07-25T20:17:08.909Z,1564085828.909 [ESPComponent](INFO): console:
OK
2019-07-25T20:17:09.310Z,1564085829.310 [ESPComponent](INFO): console:

2019-07-25T20:17:09.714Z,1564085829.714 [ESPComponent](INFO): console:
Starting kernel ...
2019-07-25T20:17:10.132Z,1564085830.132 [ESPComponent](INFO): console:

2019-07-25T20:17:10.532Z,1564085830.532 [ESPComponent](INFO): console:
Uncompressing Linux... done, booting the kernel.
2019-07-25T20:17:10.942Z,1564085830.942 [ESPComponent](INFO): console:
[    0.00] CPU: ARM926EJ-S [41069265] revision 5 (ARMv5TEJ), cr=00053177
2019-07-25T20:17:11.345Z,1564085831.345 [ESPComponent](INFO): console:
[    0.00] CPU: VIVT data cache, VIVT instruction cache
2019-07-25T20:17:11.738Z,1564085831.738 [ESPComponent](INFO): console:
[    0.00] Machine: NXP EA313X
2019-07-25T20:17:12.139Z,1564085832.139 [ESPComponent](INFO): console:
[    0.00] Memory policy: ECC disabled, Data cache writeback
2019-07-25T20:17:12.540Z,1564085832.540 [ESPComponent](INFO): console:
[    0.00] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 16256
2019-07-25T20:17:12.950Z,1564085832.950 [ESPComponent](INFO): console:
[    0.24] Mount-cache hash table entries: 512
2019-07-25T20:17:13.355Z,1564085833.355 [ESPComponent](INFO): console:
[    0.29] MBARI ESP 3G
2019-07-25T20:17:13.754Z,1564085833.754 [ESPComponent](INFO): console:
[    0.39] bio: create slab <bio-0> at 0
2019-07-25T20:17:14.163Z,1564085834.163 [ESPComponent](INFO): console:
[    0.46] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-07-25T20:17:14.569Z,1564085834.569 [ESPComponent](INFO): console:
[    0.48] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-07-25T20:17:14.973Z,1564085834.973 [ESPComponent](INFO): console:
[    0.50] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-07-25T20:17:15.386Z,1564085835.386 [ESPComponent](INFO): console:
[    0.52] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-07-25T20:17:15.786Z,1564085835.786 [ESPComponent](INFO): console:
[    0.54] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-07-25T20:17:16.189Z,1564085836.189 [ESPComponent](INFO): console:
[    0.56] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-07-25T20:17:16.593Z,1564085836.593 [ESPComponent](INFO): console:
[    0.56] NetWinder Floating Point Emulator V0.97 (double precision)
2019-07-25T20:17:16.987Z,1564085836.987 [ESPComponent](INFO): console:
[    0.58] yaffs Dec 14 2018 09:19:05 Installing. 
2019-07-25T20:17:17.391Z,1564085837.391 [ESPComponent](INFO): console:
[    0.72] m25p80 spi0.3: m25p80 found s25sl032a flash
2019-07-25T20:17:17.794Z,1564085837.794 [ESPComponent](INFO): console:
[    1.03]  p1 p2 p3
2019-07-25T20:17:18.204Z,1564085838.204 [ESPComponent](INFO): console:
[    2.43] VFS: Mounted root (ext2 filesystem) readonly on device 179:2.
2019-07-25T20:17:18.601Z,1564085838.601 [ESPComponent](INFO): console:

2019-07-25T20:17:19.010Z,1564085839.010 [ESPComponent](INFO): console:INIT: version 2.85 booting
2019-07-25T20:17:19.414Z,1564085839.414 [ESPComponent](INFO): console:

2019-07-25T20:17:19.819Z,1564085839.819 [ESPComponent](INFO): console:MBARI ESP Embedded Linux    http://www.mbari.org   mailto:brent@mbari.org
2019-07-25T20:17:20.222Z,1564085840.222 [ESPComponent](INFO): console:
ESPlrauvSIM
2019-07-25T20:17:20.637Z,1564085840.637 [ESPComponent](INFO): console:

2019-07-25T20:17:21.036Z,1564085841.036 [ESPComponent](INFO): console:INIT: Entering runlevel: 3
2019-07-25T20:17:21.447Z,1564085841.447 [ESPComponent](INFO): console:

2019-07-25T20:17:21.852Z,1564085841.852 [ESPComponent](INFO): console:Loading kernel modules
2019-07-25T20:17:22.239Z,1564085842.239 [ESPComponent](INFO): console:
Mounting filesystems and adding swapfiles listed in /etc/fstab
2019-07-25T20:17:22.646Z,1564085842.646 [ESPComponent](INFO): console:
mount: /dev/mmcblk0p2 already mounted or /card busy
2019-07-25T20:17:23.047Z,1564085843.047 [ESPComponent](INFO): console:
Starting hotplug events dispatcher udevd
2019-07-25T20:17:23.450Z,1564085843.450 [ESPComponent](INFO): console:
Set system clock to:  Thu Jul 25 13:17:12 PDT 2019
2019-07-25T20:17:23.857Z,1564085843.857 [ESPComponent](INFO): console:
Starting syslogd klogd...
2019-07-25T20:17:24.262Z,1564085844.262 [ESPComponent](INFO): console:
Bringing up interface lo ...
2019-07-25T20:17:24.664Z,1564085844.664 [ESPComponent](INFO): console:
lo IP=127.0.0.1
2019-07-25T20:17:25.073Z,1564085845.073 [ESPComponent](INFO): console:
Packet forwarding enabled
2019-07-25T20:17:25.475Z,1564085845.475 [ESPComponent](INFO): console:
Bringing up interface ppp2 ...
2019-07-25T20:17:25.892Z,1564085845.892 [ESPComponent](INFO): console:
Starting portmap...
2019-07-25T20:17:26.292Z,1564085846.292 [ESPComponent](INFO): console:
Bringing up interface eth0 ...
2019-07-25T20:17:26.697Z,1564085846.697 [ESPComponent](INFO): console:
Network unavailable:  Local time is Thu Jul 25 13:17:14 PDT 2019
2019-07-25T20:17:27.096Z,1564085847.096 [ESPComponent](INFO): console:
Starting thttpd...
2019-07-25T20:17:27.491Z,1564085847.491 [ESPComponent](INFO): console:
Determining IP configuration for eth0....udhcpc (v1.11.2) started
2019-07-25T20:17:27.898Z,1564085847.898 [ESPComponent](INFO): console:
Sending discover...
2019-07-25T20:17:28.302Z,1564085848.302 [ESPComponent](INFO): console:

2019-07-25T20:17:28.710Z,1564085848.710 [ESPComponent](INFO): console:

2019-07-25T20:17:29.110Z,1564085849.110 [ESPComponent](IMPORTANT): ESP has connected as client
2019-07-25T20:17:30.028Z,1564085850.028 [ESPComponent](IMPORTANT): [sample #1] Setting cartridge argument to -4
2019-07-25T20:17:30.029Z,1564085850.029 [ESPComponent](IMPORTANT): [sample #1] ESP sampling sequence starting. Sampling state: S_WAITING_INITIAL_PROMPT
2019-07-25T20:17:30.030Z,1564085850.030 [ESPComponent](DEBUG): Writing samplingActive=1, sampleNumber=1
2019-07-25T20:17:30.036Z,1564085850.036 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Stopped
2019-07-25T20:17:30.037Z,1564085850.037 [sample:SampleAtDepth:SampleWrapper:SampleESP:C] Running Loop=1
2019-07-25T20:17:30.335Z,1564085850.335 [sample:SampleAtDepth:SampleWrapper:SampleESP:C](IMPORTANT): ESP sampling at 7.000000 m inwater withchlorophyll fluorescence.
2019-07-25T20:17:30.335Z,1564085850.335 [sample:SampleAtDepth:SampleWrapper:SampleESP:C] Stopped
2019-07-25T20:17:30.335Z,1564085850.335 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP] Running Loop=1
2019-07-25T20:17:30.735Z,1564085850.735 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sample_number
2019-07-25T20:17:31.140Z,1564085851.140 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_LOG
2019-07-25T20:17:31.544Z,1564085851.544 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_STATUS
2019-07-25T20:17:33.152Z,1564085853.152 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_LOADING_CARTRIDGE
2019-07-25T20:17:57.530Z,1564085877.530 [DataOverHttps](INFO): Radio surface powered OFF, will not connect.
2019-07-25T20:17:57.545Z,1564085877.545 [Radio_Surface](INFO): Powering down
2019-07-25T20:18:09.113Z,1564085889.113 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PRIMING (@21,archiveHiBiomass_bac)
2019-07-25T20:18:10.714Z,1564085890.714 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PRIMING (@5.0)
2019-07-25T20:18:11.528Z,1564085891.528 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_FILTERING (@5.0)
2019-07-25T20:18:30.906Z,1564085910.906 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-07-25T20:18:31.721Z,1564085911.721 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:18:36.569Z,1564085916.569 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:18:39.801Z,1564085919.801 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:18:42.629Z,1564085922.629 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:18:44.650Z,1564085924.650 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_FILTERING (@0.0)
2019-07-25T20:18:45.058Z,1564085925.058 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PAUSED (@0.0)
2019-07-25T20:18:45.865Z,1564085925.865 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:18:48.693Z,1564085928.693 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:18:51.517Z,1564085931.517 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:18:52.350Z,1564085932.350 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-07-25T20:18:52.350Z,1564085932.350 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2019-07-25T20:18:52.350Z,1564085932.350 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-25T20:18:52.397Z,1564085932.397 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-25T20:18:52.755Z,1564085932.755 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-25T20:18:52.755Z,1564085932.755 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2019-07-25T20:18:53.541Z,1564085933.541 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:18:55.561Z,1564085935.561 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:18:58.789Z,1564085938.789 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:19:01.621Z,1564085941.621 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:19:01.637Z,1564085941.637 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PAUSED (@10.0)
2019-07-25T20:19:01.666Z,1564085941.666 [ESPComponent](DEBUG): Writing sampleVolume=10.000000
2019-07-25T20:19:02.047Z,1564085942.047 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PROCESSING (@10.0)
2019-07-25T20:19:04.450Z,1564085944.450 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PROCESSED (@21,archiveHiBiomass_bac)
2019-07-25T20:19:04.849Z,1564085944.849 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:19:07.681Z,1564085947.681 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:19:10.909Z,1564085950.909 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:19:13.737Z,1564085953.737 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:19:16.569Z,1564085956.569 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:19:18.593Z,1564085958.593 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:19:21.821Z,1564085961.821 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:19:24.649Z,1564085964.649 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:19:27.881Z,1564085967.881 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:19:30.709Z,1564085970.709 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:19:33.941Z,1564085973.941 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:19:36.769Z,1564085976.769 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:19:39.593Z,1564085979.593 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:19:41.617Z,1564085981.617 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:19:43.637Z,1564085983.637 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:19:46.865Z,1564085986.865 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:19:49.693Z,1564085989.693 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:19:52.929Z,1564085992.929 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:19:55.757Z,1564085995.757 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:19:58.985Z,1564085998.985 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:20:01.813Z,1564086001.813 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:20:04.641Z,1564086004.641 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:20:06.665Z,1564086006.665 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:20:08.681Z,1564086008.681 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:20:11.913Z,1564086011.913 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:20:14.741Z,1564086014.741 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:20:17.973Z,1564086017.973 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:20:20.801Z,1564086020.801 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:20:24.037Z,1564086024.037 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:20:26.861Z,1564086026.861 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:20:29.689Z,1564086029.689 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:20:31.713Z,1564086031.713 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:20:34.945Z,1564086034.945 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:20:37.769Z,1564086037.769 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:20:41.001Z,1564086041.001 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:20:43.829Z,1564086043.829 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:20:47.069Z,1564086047.069 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:20:49.634Z,1564086049.634 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=180.183563
2019-07-25T20:20:49.889Z,1564086049.889 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:20:52.721Z,1564086052.721 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:20:53.150Z,1564086053.150 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-07-25T20:20:53.150Z,1564086053.150 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2019-07-25T20:20:53.150Z,1564086053.150 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-25T20:20:53.221Z,1564086053.221 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-25T20:20:53.590Z,1564086053.590 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-25T20:20:53.590Z,1564086053.590 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2019-07-25T20:20:54.737Z,1564086054.737 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:20:57.969Z,1564086057.969 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:21:00.800Z,1564086060.800 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:21:04.033Z,1564086064.033 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:21:06.857Z,1564086066.857 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:21:10.089Z,1564086070.089 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:21:12.917Z,1564086072.917 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:21:15.749Z,1564086075.749 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:21:17.769Z,1564086077.769 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:21:19.785Z,1564086079.785 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:21:23.017Z,1564086083.017 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:21:25.849Z,1564086085.849 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:21:29.077Z,1564086089.077 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:21:31.905Z,1564086091.905 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:21:35.137Z,1564086095.137 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:21:37.965Z,1564086097.965 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:21:40.796Z,1564086100.796 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:21:42.813Z,1564086102.813 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:21:46.045Z,1564086106.045 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:21:48.873Z,1564086108.873 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:21:52.109Z,1564086112.109 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:21:54.933Z,1564086114.933 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:21:58.168Z,1564086118.168 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:22:00.997Z,1564086120.997 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:22:03.825Z,1564086123.825 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:22:05.845Z,1564086125.845 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:22:07.869Z,1564086127.869 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:22:11.093Z,1564086131.093 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:22:13.921Z,1564086133.921 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:22:17.153Z,1564086137.153 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:22:19.981Z,1564086139.981 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:22:23.213Z,1564086143.213 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:22:26.045Z,1564086146.045 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:22:28.874Z,1564086148.874 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:22:30.889Z,1564086150.889 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:22:34.121Z,1564086154.121 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:22:36.949Z,1564086156.949 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:22:37.772Z,1564086157.772 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_STOPPING (@21,archiveHiBiomass_bac)
2019-07-25T20:22:40.181Z,1564086160.181 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:22:43.009Z,1564086163.009 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:22:46.244Z,1564086166.244 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:22:49.073Z,1564086169.073 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:22:51.901Z,1564086171.901 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:22:53.921Z,1564086173.921 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:22:54.341Z,1564086174.341 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-07-25T20:22:54.341Z,1564086174.341 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5
2019-07-25T20:22:54.341Z,1564086174.341 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-25T20:22:54.352Z,1564086174.352 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-25T20:22:54.764Z,1564086174.764 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-25T20:22:54.764Z,1564086174.764 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5
2019-07-25T20:22:57.153Z,1564086177.153 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:22:59.981Z,1564086179.981 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:23:03.212Z,1564086183.212 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:23:04.831Z,1564086184.831 [ESPComponent](IMPORTANT): [sample #1] ESP sampling sequence completed normally.
2019-07-25T20:23:04.831Z,1564086184.831 [ESPComponent](DEBUG): Writing samplingActive=0, sampleNumber=1
2019-07-25T20:23:04.843Z,1564086184.843 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP] Stopped
2019-07-25T20:23:04.843Z,1564086184.843 [sample:SampleAtDepth:SampleWrapper:SampleESP](INFO): Completed sample:SampleAtDepth:SampleWrapper:SampleESP
2019-07-25T20:23:04.843Z,1564086184.843 [sample:SampleAtDepth:SampleWrapper:SampleESP] Stopped
2019-07-25T20:23:04.843Z,1564086184.843 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleESP
2019-07-25T20:23:04.844Z,1564086184.844 [sample:SampleAtDepth:SampleWrapper](INFO): Completed sample:SampleAtDepth:SampleWrapper
2019-07-25T20:23:04.844Z,1564086184.844 [sample:SampleAtDepth:SampleWrapper] Stopped
2019-07-25T20:23:04.844Z,1564086184.844 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper
2019-07-25T20:23:04.844Z,1564086184.844 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Stopped
2019-07-25T20:23:04.844Z,1564086184.844 [sample:SampleAtDepth](INFO): Completed sample:SampleAtDepth
2019-07-25T20:23:04.844Z,1564086184.844 [sample:SampleAtDepth] Stopped
2019-07-25T20:23:04.844Z,1564086184.844 [sample:SampleAtDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth
2019-07-25T20:23:05.235Z,1564086185.235 [ESPComponent](IMPORTANT): [sample #1] ESP log summary report (2 messages):
@13:17:39.95 Selecting Cartridge 21
@13:18:59.41 Sampled  10.0ml

2019-07-25T20:23:05.235Z,1564086185.235 [ESPComponent](INFO): powering down ESP
2019-07-25T20:23:05.236Z,1564086185.236 [ESPComponent](INFO): powering down ESP secondary power supply
2019-07-25T20:23:05.403Z,1564086185.403 [sample:SampleRepeater:Sample](INFO): Completed sample:SampleRepeater:Sample
2019-07-25T20:23:05.403Z,1564086185.403 [sample:SampleRepeater:Sample] Stopped
2019-07-25T20:23:05.403Z,1564086185.403 [sample:SampleRepeater:Sample](DEBUG): Aggregate::uninitialize sample:SampleRepeater:Sample
2019-07-25T20:23:05.404Z,1564086185.404 [sample:SampleRepeater](INFO): Completed sample:SampleRepeater
2019-07-25T20:23:05.404Z,1564086185.404 [sample:SampleRepeater] Stopped
2019-07-25T20:23:05.404Z,1564086185.404 [sample:SampleRepeater](DEBUG): Aggregate::uninitialize sample:SampleRepeater
2019-07-25T20:23:05.405Z,1564086185.405 [sample](INFO): Completed sample
2019-07-25T20:23:05.405Z,1564086185.405 [MissionManager](INFO): sample is completed.
2019-07-25T20:23:05.405Z,1564086185.405 [MissionManager](INFO): Uninitializing Mission sample
2019-07-25T20:23:05.405Z,1564086185.405 [sample] Stopped
2019-07-25T20:23:05.405Z,1564086185.405 [sample](DEBUG): Aggregate::uninitialize sample
2019-07-25T20:23:05.405Z,1564086185.405 [sample:A.AbortSample] Stopped
2019-07-25T20:23:05.405Z,1564086185.405 [sample:A.AbortSample](INFO): Uninitializing AbortSample.
2019-07-25T20:23:05.406Z,1564086185.406 [sample:B.Pitch] Stopped
2019-07-25T20:23:05.406Z,1564086185.406 [sample:C.SetSpeed] Stopped
2019-07-25T20:23:05.406Z,1564086185.406 [sample:C.SetSpeed](DEBUG): Uninitialize.
2019-07-25T20:23:05.644Z,1564086185.644 [MissionManager](IMPORTANT): Started mission Default
2019-07-25T20:23:05.644Z,1564086185.644 [Default] Running Loop=1
2019-07-25T20:23:05.644Z,1564086185.644 [Default](DEBUG): Aggregate::initialize Default
2019-07-25T20:23:05.644Z,1564086185.644 [Default:B.GoToSurface] Running Loop=1
2019-07-25T20:23:05.644Z,1564086185.644 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-25T20:23:05.645Z,1564086185.645 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-25T20:23:05.645Z,1564086185.645 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-25T20:23:05.645Z,1564086185.645 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-25T20:23:05.646Z,1564086185.646 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-25T20:23:05.646Z,1564086185.646 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-25T20:23:05.646Z,1564086185.646 [Default:A.Wait] Running Loop=1
2019-07-25T20:23:05.647Z,1564086185.647 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-07-25T20:23:06.037Z,1564086186.037 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:23:06.134Z,1564086186.134 [BuoyancyServo](FAULT): Reading outside of valid range:0.000000

2019-07-25T20:23:06.134Z,1564086186.134 [BuoyancyServo](FAULT): Buoyancy engine reporting null position
2019-07-25T20:23:06.134Z,1564086186.134 [BuoyancyServo] Hardware Fault, FailCount= 1
2019-07-25T20:23:06.134Z,1564086186.134 [BuoyancyServo](ERROR): Hardware Fault
2019-07-25T20:23:06.145Z,1564086186.145 [CBIT](ERROR): Hardware Fault in component: BuoyancyServo
2019-07-25T20:23:06.205Z,1564086186.205 [Radio_Surface](INFO): Powering up
2019-07-25T20:23:08.115Z,1564086188.115 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-07-25T20:23:08.116Z,1564086188.116 [BuoyancyServo](INFO): Powering down
2019-07-25T20:23:08.942Z,1564086188.942 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2019-07-25T20:23:08.942Z,1564086188.942 [BuoyancyServo] No Fault, FailCount= 1
2019-07-25T20:23:09.293Z,1564086189.293 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:23:09.324Z,1564086189.324 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-07-25T20:23:09.325Z,1564086189.325 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-07-25T20:23:11.846Z,1564086191.846 [DataOverHttps](INFO): Radio surface powered ON.
2019-07-25T20:23:12.121Z,1564086192.121 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:23:14.949Z,1564086194.949 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:23:16.969Z,1564086196.969 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:23:19.004Z,1564086199.004 [Default:A.Wait](INFO): Done Waiting.
2019-07-25T20:23:19.004Z,1564086199.004 [Default:A.Wait] Stopped
2019-07-25T20:23:19.004Z,1564086199.004 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-25T20:23:20.201Z,1564086200.201 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:23:23.033Z,1564086203.033 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:23:26.265Z,1564086206.265 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:23:29.082Z,1564086209.082 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-07-25T20:23:29.082Z,1564086209.082 [NAL9602] Data Fault, FailCount= 1
2019-07-25T20:23:29.083Z,1564086209.083 [NAL9602](ERROR): Data Fault
2019-07-25T20:23:29.186Z,1564086209.186 [CBIT](ERROR): Data Fault in component: NAL9602
2019-07-25T20:23:29.482Z,1564086209.482 [NAL9602](INFO): Powering down
2019-07-25T20:23:30.397Z,1564086210.397 [CBIT](INFO): Clearing failed state for component NAL9602
2019-07-25T20:23:30.397Z,1564086210.397 [NAL9602] No Fault, FailCount= 1
2019-07-25T20:23:42.145Z,1564086222.145 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-07-25T20:23:59.783Z,1564086239.783 [NAL9602](INFO): Powering up NAL9602
2019-07-25T20:24:10.695Z,1564086250.695 [NAL9602](INFO): NAL9602 initialized
2019-07-25T20:24:11.513Z,1564086251.513 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:24:12.849Z,1564086252.849 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-07-25T20:24:14.341Z,1564086254.341 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:24:17.165Z,1564086257.165 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:24:20.401Z,1564086260.401 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:24:23.225Z,1564086263.225 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:24:26.457Z,1564086266.457 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:24:29.289Z,1564086269.289 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:24:32.521Z,1564086272.521 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:24:35.345Z,1564086275.345 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:24:38.173Z,1564086278.173 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:24:40.193Z,1564086280.193 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:24:43.425Z,1564086283.425 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:24:43.554Z,1564086283.554 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-07-25T20:24:46.257Z,1564086286.257 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:24:49.489Z,1564086289.489 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:24:52.313Z,1564086292.313 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:24:55.155Z,1564086295.155 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-07-25T20:24:55.155Z,1564086295.155 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6
2019-07-25T20:24:55.155Z,1564086295.155 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-25T20:24:55.194Z,1564086295.194 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-25T20:24:55.545Z,1564086295.545 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:24:55.614Z,1564086295.614 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-25T20:24:55.614Z,1564086295.614 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6
2019-07-25T20:24:58.373Z,1564086298.373 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:25:01.201Z,1564086301.201 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:25:03.221Z,1564086303.221 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:25:06.457Z,1564086306.457 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:25:09.281Z,1564086309.281 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:25:12.517Z,1564086312.517 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:25:14.270Z,1564086314.270 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-07-25T20:25:15.341Z,1564086315.341 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:25:18.573Z,1564086318.573 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:25:21.401Z,1564086321.401 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:25:24.229Z,1564086324.229 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:25:26.249Z,1564086326.249 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:25:28.273Z,1564086328.273 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:25:31.501Z,1564086331.501 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:25:34.329Z,1564086334.329 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:25:37.577Z,1564086337.577 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:25:40.417Z,1564086340.417 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:25:43.245Z,1564086343.245 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:25:44.998Z,1564086344.998 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-07-25T20:25:45.265Z,1564086345.265 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:25:47.285Z,1564086347.285 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:25:49.308Z,1564086349.308 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:25:50.610Z,1564086350.610 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003782
2019-07-25T20:25:52.537Z,1564086352.537 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:25:55.361Z,1564086355.361 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:25:58.597Z,1564086358.597 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:26:01.425Z,1564086361.425 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:26:01.974Z,1564086361.974 [CommandLine](IMPORTANT): got command show stack
2019-07-25T20:26:01.974Z,1564086361.974 [CommandLine](IMPORTANT): Behavior Stack:

2019-07-25T20:26:01.975Z,1564086361.975 [Default](IMPORTANT): Priority 0: Default:B.GoToSurface
2019-07-25T20:26:04.657Z,1564086364.657 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:26:07.485Z,1564086367.485 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:26:10.317Z,1564086370.317 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:26:12.333Z,1564086372.333 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:26:15.569Z,1564086375.569 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:26:18.393Z,1564086378.393 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:26:21.629Z,1564086381.629 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:26:24.457Z,1564086384.457 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:26:27.689Z,1564086387.689 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:26:30.513Z,1564086390.513 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:26:33.345Z,1564086393.345 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:26:35.361Z,1564086395.361 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:26:38.593Z,1564086398.593 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:26:41.425Z,1564086401.425 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:26:44.653Z,1564086404.653 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:26:47.484Z,1564086407.484 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:26:50.713Z,1564086410.713 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:26:53.545Z,1564086413.545 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:26:55.981Z,1564086415.981 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-07-25T20:26:55.981Z,1564086415.981 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 7
2019-07-25T20:26:55.982Z,1564086415.982 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-25T20:26:55.992Z,1564086415.992 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-25T20:26:56.373Z,1564086416.373 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:26:56.407Z,1564086416.407 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-25T20:26:56.407Z,1564086416.407 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 7
2019-07-25T20:26:58.393Z,1564086418.393 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:27:00.413Z,1564086420.413 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:27:03.645Z,1564086423.645 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:27:06.469Z,1564086426.469 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:27:09.705Z,1564086429.705 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:27:12.529Z,1564086432.529 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:27:15.765Z,1564086435.765 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:27:18.589Z,1564086438.589 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:27:21.417Z,1564086441.417 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:27:23.437Z,1564086443.437 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:27:26.673Z,1564086446.673 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:27:29.497Z,1564086449.497 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:27:32.733Z,1564086452.733 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:27:35.561Z,1564086455.561 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:27:38.794Z,1564086458.794 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:27:41.621Z,1564086461.621 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:27:44.445Z,1564086464.445 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:27:46.465Z,1564086466.465 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:27:48.493Z,1564086468.493 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:27:51.717Z,1564086471.717 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:27:54.549Z,1564086474.549 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:27:57.777Z,1564086477.777 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:28:00.609Z,1564086480.609 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:28:03.841Z,1564086483.841 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:28:06.669Z,1564086486.669 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:28:09.493Z,1564086489.493 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:28:11.517Z,1564086491.517 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:28:14.749Z,1564086494.749 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:28:17.573Z,1564086497.573 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:28:20.805Z,1564086500.805 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:28:23.641Z,1564086503.641 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:28:26.869Z,1564086506.869 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:28:29.697Z,1564086509.697 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:28:32.521Z,1564086512.521 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:28:34.545Z,1564086514.545 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:28:36.561Z,1564086516.561 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:28:39.797Z,1564086519.797 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:28:42.621Z,1564086522.621 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:28:45.857Z,1564086525.857 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:28:48.681Z,1564086528.681 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:28:51.913Z,1564086531.913 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:28:54.741Z,1564086534.741 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:28:57.181Z,1564086537.181 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-07-25T20:28:57.181Z,1564086537.181 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 8
2019-07-25T20:28:57.182Z,1564086537.182 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-25T20:28:57.192Z,1564086537.192 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-25T20:28:57.573Z,1564086537.573 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:28:57.607Z,1564086537.607 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-25T20:28:57.607Z,1564086537.607 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 8
2019-07-25T20:28:59.589Z,1564086539.589 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:29:02.821Z,1564086542.821 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:29:05.649Z,1564086545.649 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:29:08.881Z,1564086548.881 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:29:11.709Z,1564086551.709 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:29:13.239Z,1564086553.239 [CommandLine](IMPORTANT): got command restart application
2019-07-25T20:29:14.241Z,1564086554.241 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2019-07-25T20:29:14.242Z,1564086554.242 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-25T20:29:14.242Z,1564086554.242 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-25T20:29:14.377Z,1564086554.377 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-07-25T20:29:14.377Z,1564086554.377 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-25T20:29:14.378Z,1564086554.378 [CommandLine](INFO): Join timeout helper Thread ID is 3691
2019-07-25T20:29:14.379Z,1564086554.379 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-07-25T20:29:14.379Z,1564086554.379 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-25T20:29:14.379Z,1564086554.379 [NavChartDb](INFO): Join timeout helper Thread ID is 3692
2019-07-25T20:29:14.713Z,1564086554.713 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-25T20:29:14.714Z,1564086554.714 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-25T20:29:14.717Z,1564086554.717 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-07-25T20:29:14.717Z,1564086554.717 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-25T20:29:14.718Z,1564086554.718 [Radio_Surface](INFO): Join timeout helper Thread ID is 3693
2019-07-25T20:29:14.941Z,1564086554.941 [NAL9602](DEBUG): Fix Requested
2019-07-25T20:29:15.117Z,1564086555.117 [Radio_Surface](INFO): Powering down
2019-07-25T20:29:15.118Z,1564086555.118 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-25T20:29:15.119Z,1564086555.119 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-25T20:29:15.137Z,1564086555.137 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-07-25T20:29:15.137Z,1564086555.137 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-25T20:29:15.138Z,1564086555.138 [DataOverHttps](INFO): Join timeout helper Thread ID is 3694
2019-07-25T20:29:15.501Z,1564086555.501 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-25T20:29:15.502Z,1564086555.502 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-25T20:29:15.509Z,1564086555.509 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-07-25T20:29:15.509Z,1564086555.509 [logger ThreadHandler](INFO): Thread cancelled.
2019-07-25T20:29:15.510Z,1564086555.510 [logger](INFO): Join timeout helper Thread ID is 3695
2019-07-25T20:29:15.577Z,1564086555.577 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-25T20:29:15.578Z,1564086555.578 [logger ThreadHandler](INFO): Thread cancelled.
2019-07-25T20:29:15.590Z,1564086555.590 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-07-25T20:29:15.590Z,1564086555.590 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-25T20:29:15.590Z,1564086555.590 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-07-25T20:29:15.590Z,1564086555.590 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-07-25T20:29:15.591Z,1564086555.591 [controlThread](INFO): Join timeout helper Thread ID is 3696
2019-07-25T20:29:15.729Z,1564086555.729 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-25T20:29:15.730Z,1564086555.730 [controlThread](DEBUG): Uninitializing ControlThread
2019-07-25T20:29:15.730Z,1564086555.730 [NAL9602](INFO): Powering down
2019-07-25T20:29:15.733Z,1564086555.733 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-07-25T20:29:15.734Z,1564086555.734 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-07-25T20:29:15.734Z,1564086555.734 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-07-25T20:29:15.734Z,1564086555.734 [MissionManager](INFO): Uninitializing Mission Default
2019-07-25T20:29:15.735Z,1564086555.735 [Default] Stopped
2019-07-25T20:29:15.735Z,1564086555.735 [Default](DEBUG): Aggregate::uninitialize Default
2019-07-25T20:29:15.735Z,1564086555.735 [Default:B.GoToSurface] Stopped
2019-07-25T20:29:15.735Z,1564086555.735 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-25T20:29:15.737Z,1564086555.737 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-07-25T20:29:15.737Z,1564086555.737 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-07-25T20:29:15.737Z,1564086555.737 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-07-25T20:29:15.738Z,1564086555.738 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-07-25T20:29:15.738Z,1564086555.738 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-07-25T20:29:15.738Z,1564086555.738 [BuoyancyServo](INFO): Powering down
2019-07-25T20:29:15.749Z,1564086555.749 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-07-25T20:29:15.750Z,1564086555.750 [ElevatorServo](INFO): Powering down
2019-07-25T20:29:15.750Z,1564086555.750 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-07-25T20:29:15.750Z,1564086555.750 [MassServo](INFO): Powering down
2019-07-25T20:29:15.751Z,1564086555.751 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-07-25T20:29:15.751Z,1564086555.751 [RudderServo](INFO): Powering down
2019-07-25T20:29:15.752Z,1564086555.752 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-07-25T20:29:15.752Z,1564086555.752 [ThrusterServo](INFO): Powering down
2019-07-25T20:29:15.753Z,1564086555.753 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-07-25T20:29:15.753Z,1564086555.753 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-07-25T20:29:15.754Z,1564086555.754 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-07-25T20:29:15.754Z,1564086555.754 [CBIT](DEBUG): Powering off loads.
2019-07-25T20:29:15.765Z,1564086555.765 [CBIT](DEBUG): Disabling WDT.
2019-07-25T20:29:15.777Z,1564086555.777 [CBIT](DEBUG): Opening all GF detection circuits.
2019-07-25T20:29:15.778Z,1564086555.778 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-07-25T20:29:15.858Z,1564086555.858 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-25T20:29:15.864Z,1564086555.864 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-25T20:29:16.033Z,1564086556.033 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-25T20:29:16.087Z,1564086556.087 [logger ThreadHandler](INFO): Thread cancelled.