2018-11-02T20:36:58.156Z,1541191018.156 [Supervisor](DEBUG): Initializing supervisor.
2018-11-02T20:36:58.160Z,1541191018.160 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2018-11-02T20:36:58.161Z,1541191018.161 [SyncHandler](INFO): Protected caller Thread ID is 2074
2018-11-02T20:36:58.161Z,1541191018.161 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2018-11-02T20:36:58.162Z,1541191018.162 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2018-11-02T20:36:58.163Z,1541191018.163 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 2075
2018-11-02T20:36:58.166Z,1541191018.166 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2018-11-02T20:36:58.179Z,1541191018.179 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2018-11-02T20:36:58.180Z,1541191018.180 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2018-11-02T20:36:58.180Z,1541191018.180 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 2076
2018-11-02T20:36:58.181Z,1541191018.181 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2018-11-02T20:36:58.182Z,1541191018.182 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2018-11-02T20:36:58.183Z,1541191018.183 [logger ThreadHandler](INFO): Protected caller Thread ID is 2077
2018-11-02T20:36:58.185Z,1541191018.185 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2018-11-02T20:36:58.185Z,1541191018.185 [Supervisor](INFO): Looking for Config files in directory: Config/
2018-11-02T20:36:58.187Z,1541191018.187 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2018-11-02T20:36:58.638Z,1541191018.638 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2018-11-02T20:36:58.639Z,1541191018.639 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2018-11-02T20:36:59.103Z,1541191019.103 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2018-11-02T20:36:59.104Z,1541191019.104 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2018-11-02T20:36:59.304Z,1541191019.304 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2018-11-02T20:36:59.304Z,1541191019.304 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2018-11-02T20:36:59.453Z,1541191019.453 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2018-11-02T20:36:59.454Z,1541191019.454 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2018-11-02T20:36:59.910Z,1541191019.910 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2018-11-02T20:36:59.910Z,1541191019.910 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2018-11-02T20:37:00.007Z,1541191020.007 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2018-11-02T20:37:00.007Z,1541191020.007 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2018-11-02T20:37:00.151Z,1541191020.151 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2018-11-02T20:37:00.152Z,1541191020.152 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2018-11-02T20:37:00.254Z,1541191020.254 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2018-11-02T20:37:00.255Z,1541191020.255 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2018-11-02T20:37:00.359Z,1541191020.359 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2018-11-02T20:37:00.359Z,1541191020.359 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2018-11-02T20:37:00.715Z,1541191020.715 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2018-11-02T20:37:00.716Z,1541191020.716 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2018-11-02T20:37:00.925Z,1541191020.925 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2018-11-02T20:37:00.926Z,1541191020.926 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2018-11-02T20:37:01.146Z,1541191021.146 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2018-11-02T20:37:01.146Z,1541191021.146 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2018-11-02T20:37:01.228Z,1541191021.228 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2018-11-02T20:37:01.596Z,1541191021.596 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2018-11-02T20:37:01.597Z,1541191021.597 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2018-11-02T20:37:01.938Z,1541191021.938 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2018-11-02T20:37:01.941Z,1541191021.941 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-galene/
2018-11-02T20:37:01.942Z,1541191021.942 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Simulator.cfg
2018-11-02T20:37:02.085Z,1541191022.085 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Sensor.cfg
2018-11-02T20:37:02.363Z,1541191022.363 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/BIT.cfg
2018-11-02T20:37:02.540Z,1541191022.540 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/vehicle.cfg
2018-11-02T20:37:02.844Z,1541191022.844 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/secure.cfg
2018-11-02T20:37:02.931Z,1541191022.931 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Battery.cfg
2018-11-02T20:37:03.160Z,1541191023.160 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2018-11-02T20:37:03.161Z,1541191023.161 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Science.cfg
2018-11-02T20:37:03.278Z,1541191023.278 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/logger.cfg
2018-11-02T20:37:03.379Z,1541191023.379 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Navigation.cfg
2018-11-02T20:37:03.475Z,1541191023.475 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Control.cfg
2018-11-02T20:37:03.580Z,1541191023.580 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Servo.cfg
2018-11-02T20:37:03.694Z,1541191023.694 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-galene/root/
2018-11-02T20:37:03.695Z,1541191023.695 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2018-11-02T20:37:03.701Z,1541191023.701 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2018-11-02T20:37:03.745Z,1541191023.745 [DepthRateCalculator] Loaded
2018-11-02T20:37:03.746Z,1541191023.746 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2018-11-02T20:37:03.752Z,1541191023.752 [PitchRateCalculator] Loaded
2018-11-02T20:37:03.752Z,1541191023.752 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2018-11-02T20:37:03.768Z,1541191023.768 [SpeedCalculator] Loaded
2018-11-02T20:37:03.768Z,1541191023.768 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2018-11-02T20:37:03.790Z,1541191023.790 [TempGradientCalculator] Loaded
2018-11-02T20:37:03.791Z,1541191023.791 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2018-11-02T20:37:03.796Z,1541191023.796 [YawRateCalculator] Loaded
2018-11-02T20:37:03.797Z,1541191023.797 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2018-11-02T20:37:03.837Z,1541191023.837 [ElevatorOffsetCalculator] Loaded
2018-11-02T20:37:03.838Z,1541191023.838 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2018-11-02T20:37:03.838Z,1541191023.838 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2018-11-02T20:37:03.839Z,1541191023.839 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2018-11-02T20:37:04.083Z,1541191024.083 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2018-11-02T20:37:04.084Z,1541191024.084 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2018-11-02T20:37:04.399Z,1541191024.399 [DataOverHttps] Loaded
2018-11-02T20:37:04.399Z,1541191024.399 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2018-11-02T20:37:04.424Z,1541191024.424 [Depth_Keller] Loaded
2018-11-02T20:37:04.424Z,1541191024.424 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2018-11-02T20:37:04.429Z,1541191024.429 [DropWeight] Loaded
2018-11-02T20:37:04.429Z,1541191024.429 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2018-11-02T20:37:04.529Z,1541191024.529 [NAL9602] Loaded
2018-11-02T20:37:04.530Z,1541191024.530 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2018-11-02T20:37:04.546Z,1541191024.546 [Onboard] Loaded
2018-11-02T20:37:04.547Z,1541191024.547 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2018-11-02T20:37:04.557Z,1541191024.557 [Radio_Surface] Loaded
2018-11-02T20:37:04.557Z,1541191024.557 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2018-11-02T20:37:04.558Z,1541191024.558 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 407C34E0
2018-11-02T20:37:04.559Z,1541191024.559 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 2156
2018-11-02T20:37:04.565Z,1541191024.565 [SCPI] Loaded
2018-11-02T20:37:04.566Z,1541191024.566 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread.
2018-11-02T20:37:06.339Z,1541191026.339 [BPC1] Loaded
2018-11-02T20:37:06.339Z,1541191026.339 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2018-11-02T20:37:06.340Z,1541191026.340 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2018-11-02T20:37:06.340Z,1541191026.340 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2018-11-02T20:37:06.406Z,1541191026.406 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2018-11-02T20:37:06.407Z,1541191026.407 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2018-11-02T20:37:06.503Z,1541191026.503 [DeadReckonUsingMultipleVelocitySources] Loaded
2018-11-02T20:37:06.504Z,1541191026.504 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2018-11-02T20:37:06.558Z,1541191026.558 [DeadReckonUsingSpeedCalculator] Loaded
2018-11-02T20:37:06.559Z,1541191026.559 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread.
2018-11-02T20:37:06.575Z,1541191026.575 [NavChart] Loaded
2018-11-02T20:37:06.575Z,1541191026.575 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2018-11-02T20:37:06.580Z,1541191026.579 [UniversalFixResidualReporter] Loaded
2018-11-02T20:37:06.580Z,1541191026.580 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2018-11-02T20:37:06.580Z,1541191026.580 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2018-11-02T20:37:06.581Z,1541191026.581 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2018-11-02T20:37:06.813Z,1541191026.813 [CTD_NeilBrown] Loaded
2018-11-02T20:37:06.813Z,1541191026.813 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2018-11-02T20:37:06.814Z,1541191026.814 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408CE4E0
2018-11-02T20:37:06.815Z,1541191026.815 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 2157
2018-11-02T20:37:06.865Z,1541191026.865 [WetLabsBB2FL] Loaded
2018-11-02T20:37:06.865Z,1541191026.865 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2018-11-02T20:37:06.866Z,1541191026.866 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 408FE4E0
2018-11-02T20:37:06.867Z,1541191026.867 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 2158
2018-11-02T20:37:06.868Z,1541191026.868 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2018-11-02T20:37:06.868Z,1541191026.868 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2018-11-02T20:37:06.938Z,1541191026.938 [VerticalControl](DEBUG): Construct VerticalControl.
2018-11-02T20:37:07.039Z,1541191027.039 [VerticalControl] Loaded
2018-11-02T20:37:07.040Z,1541191027.040 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2018-11-02T20:37:07.040Z,1541191027.040 [HorizontalControl](DEBUG): Construct HorizontalControl.
2018-11-02T20:37:07.111Z,1541191027.111 [HorizontalControl] Loaded
2018-11-02T20:37:07.111Z,1541191027.111 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2018-11-02T20:37:07.112Z,1541191027.112 [SpeedControl](DEBUG): Construct SpeedControl.
2018-11-02T20:37:07.117Z,1541191027.117 [SpeedControl] Loaded
2018-11-02T20:37:07.118Z,1541191027.118 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2018-11-02T20:37:07.118Z,1541191027.118 [LoopControl](DEBUG): Construct LoopControl.
2018-11-02T20:37:07.119Z,1541191027.119 [LoopControl] Loaded
2018-11-02T20:37:07.119Z,1541191027.119 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2018-11-02T20:37:07.119Z,1541191027.119 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2018-11-02T20:37:07.120Z,1541191027.120 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2018-11-02T20:37:07.213Z,1541191027.213 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2018-11-02T20:37:07.214Z,1541191027.214 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2018-11-02T20:37:07.507Z,1541191027.507 [SBIT](DEBUG): Construct Startup Built In Test.
2018-11-02T20:37:07.518Z,1541191027.518 [SBIT] Loaded
2018-11-02T20:37:07.519Z,1541191027.519 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2018-11-02T20:37:07.519Z,1541191027.519 [IBIT](DEBUG): Construct Initiated Built In Test.
2018-11-02T20:37:07.531Z,1541191027.531 [IBIT] Loaded
2018-11-02T20:37:07.531Z,1541191027.531 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2018-11-02T20:37:07.534Z,1541191027.534 [CBIT](DEBUG): Construct Continuous Built In Test.
2018-11-02T20:37:07.742Z,1541191027.742 [CBIT] Loaded
2018-11-02T20:37:07.742Z,1541191027.742 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2018-11-02T20:37:07.742Z,1541191027.742 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2018-11-02T20:37:07.743Z,1541191027.743 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2018-11-02T20:37:07.846Z,1541191027.846 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2018-11-02T20:37:07.847Z,1541191027.847 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2018-11-02T20:37:07.872Z,1541191027.872 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2018-11-02T20:37:07.873Z,1541191027.873 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2018-11-02T20:37:07.973Z,1541191027.973 [BuoyancyServo] Loaded
2018-11-02T20:37:07.973Z,1541191027.973 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2018-11-02T20:37:07.985Z,1541191027.985 [ElevatorServo] Loaded
2018-11-02T20:37:07.985Z,1541191027.985 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2018-11-02T20:37:07.996Z,1541191027.996 [MassServo] Loaded
2018-11-02T20:37:07.997Z,1541191027.997 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2018-11-02T20:37:08.008Z,1541191028.008 [RudderServo] Loaded
2018-11-02T20:37:08.008Z,1541191028.008 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2018-11-02T20:37:08.019Z,1541191028.019 [ThrusterServo] Loaded
2018-11-02T20:37:08.020Z,1541191028.020 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2018-11-02T20:37:08.020Z,1541191028.020 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2018-11-02T20:37:08.024Z,1541191028.024 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2018-11-02T20:37:08.025Z,1541191028.025 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2018-11-02T20:37:08.032Z,1541191028.032 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2018-11-02T20:37:08.033Z,1541191028.033 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A164E0
2018-11-02T20:37:08.033Z,1541191028.033 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 2159
2018-11-02T20:37:08.038Z,1541191028.038 [Supervisor](INFO): Main Thread ID is 1952
2018-11-02T20:37:08.039Z,1541191028.039 [Supervisor](DEBUG): Running supervisor.
2018-11-02T20:37:08.039Z,1541191028.039 [CommandLine ThreadHandler](INFO): Handler Thread ID is 2160
2018-11-02T20:37:08.042Z,1541191028.042 [controlThread ThreadHandler](INFO): Handler Thread ID is 2161
2018-11-02T20:37:08.042Z,1541191028.042 [controlThread](DEBUG): Initializing ControlThread
2018-11-02T20:37:08.043Z,1541191028.043 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2018-11-02T20:37:08.043Z,1541191028.043 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2018-11-02T20:37:08.044Z,1541191028.044 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2018-11-02T20:37:08.044Z,1541191028.044 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2018-11-02T20:37:08.045Z,1541191028.045 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2018-11-02T20:37:08.045Z,1541191028.045 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2018-11-02T20:37:08.052Z,1541191028.052 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2018-11-02T20:37:08.053Z,1541191028.053 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s.
2018-11-02T20:37:08.053Z,1541191028.053 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s.
2018-11-02T20:37:08.054Z,1541191028.054 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-11-02T20:37:08.054Z,1541191028.054 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-11-02T20:37:08.054Z,1541191028.054 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-11-02T20:37:08.055Z,1541191028.055 [NavChart](DEBUG): Initialize NavChart Navigation.
2018-11-02T20:37:08.055Z,1541191028.055 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2018-11-02T20:37:08.055Z,1541191028.055 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2018-11-02T20:37:08.057Z,1541191028.057 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2018-11-02T20:37:08.058Z,1541191028.058 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2018-11-02T20:37:08.058Z,1541191028.058 [LoopControl](DEBUG): Initialize LoopControlComponent.
2018-11-02T20:37:08.059Z,1541191028.059 [SBIT](INFO): Initialize SBIT Component.
2018-11-02T20:37:08.059Z,1541191028.059 [SBIT](IMPORTANT): git: 2018-11-02
2018-11-02T20:37:08.059Z,1541191028.059 [SBIT](INFO): git hash: 766718804c5d96cf896f07eddb44b232c8585615
2018-11-02T20:37:08.060Z,1541191028.060 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2018-11-02T20:37:08.060Z,1541191028.060 [SBIT](IMPORTANT): Kernel Version:#2 PREEMPT Thu Jan 11 20:13:48 PST 2018
2018-11-02T20:37:08.061Z,1541191028.061 [SBIT](INFO): Beginning SBIT in 28.000000 seconds.
2018-11-02T20:37:08.061Z,1541191028.061 [IBIT](INFO): Initialize IBIT Component.
2018-11-02T20:37:08.062Z,1541191028.062 [CBIT](DEBUG): Initialize CBIT Component.
2018-11-02T20:37:08.063Z,1541191028.063 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2018-11-02T20:37:08.063Z,1541191028.063 [logger ThreadHandler](INFO): Handler Thread ID is 2162
2018-11-02T20:37:08.081Z,1541191028.081 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 2163
2018-11-02T20:37:08.087Z,1541191028.087 [Radio_Surface](INFO): Powering up
2018-11-02T20:37:08.093Z,1541191028.093 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 2164
2018-11-02T20:37:08.105Z,1541191028.105 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 2165
2018-11-02T20:37:08.106Z,1541191028.106 [WetLabsBB2FL](INFO): Powering down
2018-11-02T20:37:08.133Z,1541191028.133 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 2166
2018-11-02T20:37:08.137Z,1541191028.137 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2018-11-02T20:37:08.137Z,1541191028.137 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2018-11-02T20:37:08.137Z,1541191028.137 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2018-11-02T20:37:08.138Z,1541191028.138 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2018-11-02T20:37:08.138Z,1541191028.138 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2018-11-02T20:37:08.138Z,1541191028.138 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2018-11-02T20:37:08.138Z,1541191028.138 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2018-11-02T20:37:08.138Z,1541191028.138 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2018-11-02T20:37:08.139Z,1541191028.139 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2018-11-02T20:37:08.139Z,1541191028.139 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2018-11-02T20:37:08.139Z,1541191028.139 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2018-11-02T20:37:08.139Z,1541191028.139 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2018-11-02T20:37:08.139Z,1541191028.139 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2018-11-02T20:37:08.139Z,1541191028.139 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2018-11-02T20:37:08.140Z,1541191028.140 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2018-11-02T20:37:08.140Z,1541191028.140 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2018-11-02T20:37:08.170Z,1541191028.170 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2018-11-02T20:37:08.182Z,1541191028.182 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2018-11-02T20:37:08.210Z,1541191028.210 [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>


2018-11-02T20:37:08.210Z,1541191028.210 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2018-11-02T20:37:08.281Z,1541191028.281 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2018-11-02T20:37:08.282Z,1541191028.282 [Default:A.Wait](DEBUG): Construct Wait.
2018-11-02T20:37:08.284Z,1541191028.284 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2018-11-02T20:37:08.328Z,1541191028.328 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2018-11-02T20:37:08.331Z,1541191028.331 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2018-11-02T20:37:08.364Z,1541191028.364 [Default:E.Execute](DEBUG): Construct Execute.
2018-11-02T20:37:08.368Z,1541191028.368 [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>


2018-11-02T20:37:08.374Z,1541191028.374 [controlThread](DEBUG): Component order: CycleStarter,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,SCPI,BPC1,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2018-11-02T20:37:08.407Z,1541191028.407 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2018-11-02T20:37:08.457Z,1541191028.457 [Depth_Keller](ERROR): Pressure reading out of range: 1628.471313 decibar
2018-11-02T20:37:08.600Z,1541191028.600 [DepthRateCalculator](ERROR): Depth measurement is not active
2018-11-02T20:37:08.866Z,1541191028.866 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2018-11-02T20:37:08.873Z,1541191028.873 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2018-11-02T20:37:08.887Z,1541191028.887 [ElevatorServo](DEBUG): Initializing EZServoServo.
2018-11-02T20:37:08.894Z,1541191028.894 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2018-11-02T20:37:08.899Z,1541191028.899 [MassServo](DEBUG): Initializing EZServoServo.
2018-11-02T20:37:08.905Z,1541191028.905 [MassServo](DEBUG): Initializing MassServo.
2018-11-02T20:37:08.914Z,1541191028.914 [RudderServo](DEBUG): Initializing EZServoServo.
2018-11-02T20:37:08.921Z,1541191028.921 [RudderServo](DEBUG): Initializing RudderServo.
2018-11-02T20:37:08.942Z,1541191028.942 [ThrusterServo](DEBUG): Initializing EZServoServo.
2018-11-02T20:37:08.949Z,1541191028.949 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2018-11-02T20:37:09.101Z,1541191029.101 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2018-11-02T20:37:09.101Z,1541191029.101 [DropWeight] Hardware Fault, FailCount= 1
2018-11-02T20:37:09.101Z,1541191029.101 [DropWeight](ERROR): Hardware Fault
2018-11-02T20:37:09.121Z,1541191029.121 [DepthRateCalculator](ERROR): Depth measurement is not active
2018-11-02T20:37:09.150Z,1541191029.150 [CommandLine](FAULT): Scheduling is paused
2018-11-02T20:37:09.150Z,1541191029.150 [CBIT](INFO): Critical error at 20181102T203709
2018-11-02T20:37:09.151Z,1541191029.151 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2018-11-02T20:37:09.153Z,1541191029.153 [CBIT](ERROR): Hardware Fault in component: DropWeight
2018-11-02T20:37:09.154Z,1541191029.154 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2018-11-02T20:37:09.793Z,1541191029.793 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2018-11-02T20:37:09.793Z,1541191029.793 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2018-11-02T20:37:09.793Z,1541191029.793 [BuoyancyServo] Communications Fault, FailCount= 1
2018-11-02T20:37:09.793Z,1541191029.793 [BuoyancyServo](ERROR): Communications Fault
2018-11-02T20:37:09.999Z,1541191029.999 [CBIT](INFO): Critical error at 20181102T203709
2018-11-02T20:37:10.002Z,1541191030.002 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2018-11-02T20:37:10.046Z,1541191030.046 [BuoyancyServo](INFO): Commanding VB valve closed.
2018-11-02T20:37:10.443Z,1541191030.443 [BuoyancyServo](INFO): Waiting for VB valve to close.
2018-11-02T20:37:10.842Z,1541191030.842 [BuoyancyServo](INFO): Waiting for VB valve to close.
2018-11-02T20:37:11.255Z,1541191031.255 [BuoyancyServo](INFO): Waiting for VB valve to close.
2018-11-02T20:37:12.086Z,1541191032.086 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2018-11-02T20:37:12.086Z,1541191032.086 [BuoyancyServo] No Fault, FailCount= 1
2018-11-02T20:37:12.442Z,1541191032.442 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2018-11-02T20:37:12.562Z,1541191032.562 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2018-11-02T20:37:34.814Z,1541191054.814 [NAL9602](INFO): Powering up NAL9602
2018-11-02T20:37:36.492Z,1541191056.492 [SBIT](IMPORTANT): Beginning Startup BIT
2018-11-02T20:37:36.496Z,1541191056.496 [CBIT](IMPORTANT): Beginning ground fault scan
2018-11-02T20:37:47.470Z,1541191067.470 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): 0.005387
CHAN A1 (24V): 0.001401
CHAN A2 (12V): -0.005741
CHAN A3 (5V): -0.002643
CHAN B0 (3.3V): -0.000958
CHAN B1 (3.15aV): -0.001190
CHAN B2 (3.15bV): -0.001352
CHAN B3 (GND): -0.000304
OPEN: -0.001412
Full Scale Calc: 4.765 mA, -1.589 mA
2018-11-02T20:37:55.514Z,1541191075.514 [NAL9602](ERROR): NAL9602 initialization error.
2018-11-02T20:37:55.514Z,1541191075.514 [NAL9602] Communications Fault, FailCount= 1
2018-11-02T20:37:55.514Z,1541191075.514 [NAL9602](ERROR): Communications Fault
2018-11-02T20:37:55.666Z,1541191075.666 [CBIT](ERROR): Communications Fault in component: NAL9602
2018-11-02T20:37:55.922Z,1541191075.922 [NAL9602](INFO): Powering down
2018-11-02T20:37:56.994Z,1541191076.994 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T20:37:56.994Z,1541191076.994 [NAL9602] No Fault, FailCount= 1
2018-11-02T20:38:02.510Z,1541191082.510 [CommandLine](IMPORTANT): got command failComponent
2018-11-02T20:38:02.511Z,1541191082.511 [CommandLine](IMPORTANT): Failed components:
2018-11-02T20:38:02.511Z,1541191082.511 [CommandLine](IMPORTANT): DropWeight: Hardware Fault
2018-11-02T20:38:26.049Z,1541191106.049 [NAL9602](INFO): Powering up NAL9602
2018-11-02T20:38:29.687Z,1541191109.687 [SBIT](IMPORTANT): SBIT PASSED
2018-11-02T20:38:29.744Z,1541191109.744 [CommandLine](IMPORTANT): got command configSet list
2018-11-02T20:38:29.744Z,1541191109.744 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2018-11-02T20:38:29.745Z,1541191109.745 [CommandLine](IMPORTANT): AHRS_M2.loadAtStartup=0 bool;

2018-11-02T20:38:29.745Z,1541191109.745 [CommandLine](IMPORTANT): CTD_Seabird.loadAtStartup=0 bool;

2018-11-02T20:38:29.745Z,1541191109.745 [CommandLine](IMPORTANT): Depth_Keller.offset=2.34 decibar;

2018-11-02T20:38:29.746Z,1541191109.746 [CommandLine](IMPORTANT): Depth_Keller.scale=38.77 micropascal;

2018-11-02T20:38:29.746Z,1541191109.746 [CommandLine](IMPORTANT): PAR_Licor.loadAtStartup=0 bool;

2018-11-02T20:38:30.089Z,1541191110.089 [MissionManager](IMPORTANT): Started mission Startup
2018-11-02T20:38:30.090Z,1541191110.090 [Startup] Running Loop=1
2018-11-02T20:38:30.090Z,1541191110.090 [Startup](DEBUG): Aggregate::initialize Startup
2018-11-02T20:38:30.090Z,1541191110.090 [Startup:A.GoToSurface] Running Loop=1
2018-11-02T20:38:30.090Z,1541191110.090 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2018-11-02T20:38:30.091Z,1541191110.091 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2018-11-02T20:38:30.091Z,1541191110.091 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2018-11-02T20:38:30.092Z,1541191110.092 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2018-11-02T20:38:30.092Z,1541191110.092 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2018-11-02T20:38:30.092Z,1541191110.092 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2018-11-02T20:38:30.098Z,1541191110.098 [Startup:StartupSatComms] Running Loop=1
2018-11-02T20:38:30.099Z,1541191110.099 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2018-11-02T20:38:30.099Z,1541191110.099 [Startup:StartupSatComms:A] Running Loop=1
2018-11-02T20:38:30.499Z,1541191110.499 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2018-11-02T20:38:47.242Z,1541191127.242 [NAL9602](ERROR): NAL9602 initialization error.
2018-11-02T20:38:47.242Z,1541191127.242 [NAL9602] Communications Fault, FailCount= 2
2018-11-02T20:38:47.242Z,1541191127.242 [NAL9602](ERROR): Communications Fault
2018-11-02T20:38:47.319Z,1541191127.319 [CBIT](ERROR): Communications Fault in component: NAL9602
2018-11-02T20:38:47.642Z,1541191127.642 [NAL9602](INFO): Powering down
2018-11-02T20:38:48.495Z,1541191128.495 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T20:38:48.495Z,1541191128.495 [NAL9602] No Fault, FailCount= 2
2018-11-02T20:39:08.069Z,1541191148.069 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2018-11-02T20:39:08.069Z,1541191148.069 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2018-11-02T20:39:08.069Z,1541191148.069 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2018-11-02T20:39:08.071Z,1541191148.071 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2018-11-02T20:39:08.071Z,1541191148.071 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1
2018-11-02T20:39:08.071Z,1541191148.071 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2018-11-02T20:39:08.116Z,1541191148.116 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2018-11-02T20:39:08.116Z,1541191148.116 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2018-11-02T20:39:08.481Z,1541191148.481 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2018-11-02T20:39:08.481Z,1541191148.481 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2018-11-02T20:39:08.481Z,1541191148.481 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2018-11-02T20:39:08.481Z,1541191148.481 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1
2018-11-02T20:39:08.872Z,1541191148.872 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2018-11-02T20:39:08.873Z,1541191148.873 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s.
2018-11-02T20:39:08.874Z,1541191148.874 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s.
2018-11-02T20:39:08.874Z,1541191148.874 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-11-02T20:39:08.875Z,1541191148.875 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-11-02T20:39:08.875Z,1541191148.875 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-11-02T20:39:17.645Z,1541191157.645 [NAL9602](INFO): Powering up NAL9602
2018-11-02T20:39:32.768Z,1541191172.768 [Startup:StartupSatComms:A](INFO): Timed out from 2018-11-02T20:38:30.1Z
2018-11-02T20:39:32.768Z,1541191172.768 [Startup:StartupSatComms:A] Stopped
2018-11-02T20:39:32.769Z,1541191172.769 [Startup:StartupSatComms:B] Running Loop=1
2018-11-02T20:39:32.872Z,1541191172.872 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2018-11-02T20:39:33.595Z,1541191173.595 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004439
2018-11-02T20:39:37.680Z,1541191177.680 [DataOverHttps](INFO): Sending 78 bytes from file Logs/20181102T195605/Courier0016.lzma
2018-11-02T20:39:38.065Z,1541191178.065 [NAL9602](ERROR): NAL9602 initialization error.
2018-11-02T20:39:38.065Z,1541191178.065 [NAL9602] Communications Fault, FailCount= 3
2018-11-02T20:39:38.065Z,1541191178.065 [NAL9602](ERROR): Communications Fault
2018-11-02T20:39:38.149Z,1541191178.149 [CBIT](ERROR): Communications Fault in component: NAL9602
2018-11-02T20:39:38.455Z,1541191178.455 [DataOverHttps](INFO): Moved sent file to Logs/20181102T195605/Courier0016.lzma.bak
2018-11-02T20:39:38.455Z,1541191178.455 [DataOverHttps](INFO): SBD MOMSN=8783606
2018-11-02T20:39:38.489Z,1541191178.489 [NAL9602](INFO): Powering down
2018-11-02T20:39:39.295Z,1541191179.295 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T20:39:39.295Z,1541191179.295 [NAL9602] No Fault, FailCount= 3
2018-11-02T20:39:47.142Z,1541191187.142 [DataOverHttps](INFO): Sending 134 bytes from file Logs/20181102T203658/Courier0000.lzma
2018-11-02T20:39:47.939Z,1541191187.939 [DataOverHttps](INFO): Moved sent file to Logs/20181102T203658/Courier0000.lzma.bak
2018-11-02T20:39:47.939Z,1541191187.939 [DataOverHttps](INFO): SBD MOMSN=8783609
2018-11-02T20:39:56.753Z,1541191196.753 [DataOverHttps](INFO): Sending 160 bytes from file Logs/20181102T195605/Express0017.lzma
2018-11-02T20:39:57.551Z,1541191197.551 [DataOverHttps](INFO): Moved sent file to Logs/20181102T195605/Express0017.lzma.bak
2018-11-02T20:39:57.551Z,1541191197.551 [DataOverHttps](INFO): SBD MOMSN=8783614
2018-11-02T20:40:06.390Z,1541191206.390 [DataOverHttps](INFO): Sending 940 bytes from file Logs/20181102T203658/Express0001.lzma
2018-11-02T20:40:07.159Z,1541191207.159 [DataOverHttps](INFO): Moved sent file to Logs/20181102T203658/Express0001.lzma.bak
2018-11-02T20:40:07.159Z,1541191207.159 [DataOverHttps](INFO): SBD MOMSN=8783619
2018-11-02T20:40:07.651Z,1541191207.651 [Startup:StartupSatComms:B] Stopped
2018-11-02T20:40:07.651Z,1541191207.651 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2018-11-02T20:40:07.651Z,1541191207.651 [Startup:StartupSatComms] Stopped
2018-11-02T20:40:07.651Z,1541191207.651 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2018-11-02T20:40:07.652Z,1541191207.652 [Startup](INFO): Completed Startup
2018-11-02T20:40:07.652Z,1541191207.652 [MissionManager](INFO): Startup is completed.
2018-11-02T20:40:07.652Z,1541191207.652 [MissionManager](INFO): Uninitializing Mission Startup
2018-11-02T20:40:07.653Z,1541191207.653 [Startup] Stopped
2018-11-02T20:40:07.653Z,1541191207.653 [Startup](DEBUG): Aggregate::uninitialize Startup
2018-11-02T20:40:07.653Z,1541191207.653 [Startup:A.GoToSurface] Stopped
2018-11-02T20:40:07.653Z,1541191207.653 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2018-11-02T20:40:07.992Z,1541191207.992 [MissionManager](IMPORTANT): Started mission Default
2018-11-02T20:40:07.992Z,1541191207.992 [Default] Running Loop=1
2018-11-02T20:40:07.992Z,1541191207.992 [Default](DEBUG): Aggregate::initialize Default
2018-11-02T20:40:07.992Z,1541191207.992 [Default:B.GoToSurface] Running Loop=1
2018-11-02T20:40:07.992Z,1541191207.992 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2018-11-02T20:40:07.993Z,1541191207.993 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2018-11-02T20:40:07.993Z,1541191207.993 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2018-11-02T20:40:07.993Z,1541191207.993 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2018-11-02T20:40:07.994Z,1541191207.994 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2018-11-02T20:40:07.994Z,1541191207.994 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2018-11-02T20:40:07.994Z,1541191207.994 [Default:A.Wait] Running Loop=1
2018-11-02T20:40:07.994Z,1541191207.994 [Default:A.Wait](DEBUG): Initialize Wait Component.
2018-11-02T20:40:11.051Z,1541191211.051 [NAL9602](INFO): Powering up NAL9602
2018-11-02T20:40:21.141Z,1541191221.141 [Default:A.Wait](INFO): Done Waiting.
2018-11-02T20:40:21.142Z,1541191221.142 [Default:A.Wait] Stopped
2018-11-02T20:40:21.142Z,1541191221.142 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T20:40:21.555Z,1541191221.555 [Default:CheckIn] Running Loop=1
2018-11-02T20:40:21.556Z,1541191221.556 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T20:40:21.556Z,1541191221.556 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T20:40:21.943Z,1541191221.943 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2018-11-02T20:40:31.914Z,1541191231.914 [NAL9602](ERROR): NAL9602 initialization error.
2018-11-02T20:40:31.914Z,1541191231.914 [NAL9602] Communications Fault, FailCount= 4
2018-11-02T20:40:31.914Z,1541191231.914 [NAL9602](ERROR): Communications Fault
2018-11-02T20:40:31.969Z,1541191231.969 [CBIT](ERROR): Communications Fault in component: NAL9602
2018-11-02T20:40:32.310Z,1541191232.310 [NAL9602](INFO): Powering down
2018-11-02T20:40:33.265Z,1541191233.265 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T20:40:33.265Z,1541191233.265 [NAL9602] No Fault, FailCount= 4
2018-11-02T20:40:42.821Z,1541191242.821 [CommandLine](IMPORTANT): got command failComponent
2018-11-02T20:40:42.822Z,1541191242.822 [CommandLine](IMPORTANT): Failed components:
2018-11-02T20:40:42.822Z,1541191242.822 [CommandLine](IMPORTANT): DropWeight: Hardware Fault
2018-11-02T20:41:02.547Z,1541191262.547 [NAL9602](INFO): Powering up NAL9602
2018-11-02T20:41:08.278Z,1541191268.278 [CommandLine](IMPORTANT): got command restart application
2018-11-02T20:41:08.976Z,1541191268.976 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2018-11-02T20:41:08.976Z,1541191268.976 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2018-11-02T20:41:08.976Z,1541191268.976 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2018-11-02T20:41:08.977Z,1541191268.977 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2018-11-02T20:41:08.978Z,1541191268.978 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 2
2018-11-02T20:41:08.978Z,1541191268.978 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2018-11-02T20:41:08.990Z,1541191268.990 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2018-11-02T20:41:08.991Z,1541191268.991 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2018-11-02T20:41:09.287Z,1541191269.287 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-02T20:41:09.288Z,1541191269.288 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-11-02T20:41:09.377Z,1541191269.377 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2018-11-02T20:41:09.377Z,1541191269.377 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-11-02T20:41:09.378Z,1541191269.378 [CommandLine](INFO): Join timeout helper Thread ID is 2187
2018-11-02T20:41:09.390Z,1541191269.390 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2018-11-02T20:41:09.390Z,1541191269.390 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2018-11-02T20:41:09.391Z,1541191269.391 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2018-11-02T20:41:09.391Z,1541191269.391 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 2
2018-11-02T20:41:09.393Z,1541191269.393 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2018-11-02T20:41:09.393Z,1541191269.393 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-11-02T20:41:09.394Z,1541191269.394 [NavChartDb](INFO): Join timeout helper Thread ID is 2188
2018-11-02T20:41:09.425Z,1541191269.425 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-02T20:41:09.425Z,1541191269.425 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-11-02T20:41:09.441Z,1541191269.441 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2018-11-02T20:41:09.441Z,1541191269.441 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-11-02T20:41:09.441Z,1541191269.441 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 2189
2018-11-02T20:41:09.705Z,1541191269.705 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-02T20:41:09.705Z,1541191269.705 [WetLabsBB2FL](INFO): Powering down
2018-11-02T20:41:09.706Z,1541191269.706 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-11-02T20:41:09.724Z,1541191269.724 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2018-11-02T20:41:09.724Z,1541191269.724 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2018-11-02T20:41:09.725Z,1541191269.725 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 2190
2018-11-02T20:41:09.761Z,1541191269.761 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2018-11-02T20:41:09.762Z,1541191269.762 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s.
2018-11-02T20:41:09.762Z,1541191269.762 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s.
2018-11-02T20:41:09.763Z,1541191269.763 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-11-02T20:41:09.763Z,1541191269.763 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-11-02T20:41:09.763Z,1541191269.763 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-11-02T20:41:09.813Z,1541191269.813 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-02T20:41:09.813Z,1541191269.813 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2018-11-02T20:41:09.833Z,1541191269.833 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2018-11-02T20:41:09.833Z,1541191269.833 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-11-02T20:41:09.833Z,1541191269.833 [Radio_Surface](INFO): Join timeout helper Thread ID is 2191
2018-11-02T20:41:09.837Z,1541191269.837 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-02T20:41:09.837Z,1541191269.837 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-11-02T20:41:09.854Z,1541191269.854 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2018-11-02T20:41:09.854Z,1541191269.854 [logger ThreadHandler](INFO): Thread cancelled.
2018-11-02T20:41:09.854Z,1541191269.854 [logger](INFO): Join timeout helper Thread ID is 2192
2018-11-02T20:41:09.869Z,1541191269.869 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-02T20:41:09.869Z,1541191269.869 [logger ThreadHandler](INFO): Thread cancelled.
2018-11-02T20:41:09.873Z,1541191269.873 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2018-11-02T20:41:09.874Z,1541191269.874 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-11-02T20:41:09.874Z,1541191269.874 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2018-11-02T20:41:09.874Z,1541191269.874 [controlThread ThreadHandler](INFO): Thread cancelled.
2018-11-02T20:41:09.874Z,1541191269.874 [controlThread](INFO): Join timeout helper Thread ID is 2193
2018-11-02T20:41:10.133Z,1541191270.133 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-02T20:41:10.133Z,1541191270.133 [controlThread](DEBUG): Uninitializing ControlThread
2018-11-02T20:41:10.134Z,1541191270.134 [NAL9602](INFO): Powering down
2018-11-02T20:41:10.136Z,1541191270.136 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2018-11-02T20:41:10.137Z,1541191270.137 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2018-11-02T20:41:10.138Z,1541191270.138 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2018-11-02T20:41:10.138Z,1541191270.138 [MissionManager](INFO): Uninitializing Mission Default
2018-11-02T20:41:10.138Z,1541191270.138 [Default] Stopped
2018-11-02T20:41:10.138Z,1541191270.138 [Default](DEBUG): Aggregate::uninitialize Default
2018-11-02T20:41:10.138Z,1541191270.138 [Default:B.GoToSurface] Stopped
2018-11-02T20:41:10.138Z,1541191270.138 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2018-11-02T20:41:10.138Z,1541191270.138 [Default:CheckIn] Stopped
2018-11-02T20:41:10.139Z,1541191270.139 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T20:41:10.139Z,1541191270.139 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T20:41:10.142Z,1541191270.142 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2018-11-02T20:41:10.142Z,1541191270.142 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2018-11-02T20:41:10.142Z,1541191270.142 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2018-11-02T20:41:10.142Z,1541191270.142 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2018-11-02T20:41:10.142Z,1541191270.142 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2018-11-02T20:41:10.143Z,1541191270.143 [BuoyancyServo](INFO): Powering down
2018-11-02T20:41:10.157Z,1541191270.157 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2018-11-02T20:41:10.157Z,1541191270.157 [ElevatorServo](INFO): Powering down
2018-11-02T20:41:10.158Z,1541191270.158 [MassServo](DEBUG): Uninitialize Mass Servo.
2018-11-02T20:41:10.158Z,1541191270.158 [MassServo](INFO): Powering down
2018-11-02T20:41:10.159Z,1541191270.159 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2018-11-02T20:41:10.159Z,1541191270.159 [RudderServo](INFO): Powering down
2018-11-02T20:41:10.160Z,1541191270.160 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2018-11-02T20:41:10.160Z,1541191270.160 [ThrusterServo](INFO): Powering down
2018-11-02T20:41:10.161Z,1541191270.161 [SBIT](DEBUG): Uninitialize SBIT Component.
2018-11-02T20:41:10.161Z,1541191270.161 [IBIT](DEBUG): Uninitialize IBIT Component.
2018-11-02T20:41:10.161Z,1541191270.161 [CBIT](DEBUG): Uninitialize CBIT Component.
2018-11-02T20:41:10.162Z,1541191270.162 [controlThread ThreadHandler](INFO): Thread cancelled.
2018-11-02T20:41:10.235Z,1541191270.235 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-11-02T20:41:10.276Z,1541191270.276 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-11-02T20:41:10.279Z,1541191270.279 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2018-11-02T20:41:10.329Z,1541191270.329 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-11-02T20:41:10.382Z,1541191270.382 [logger ThreadHandler](INFO): Thread cancelled.