2018-09-05T16:46:19.631Z,1536165979.631 [Supervisor](DEBUG): Initializing supervisor.
2018-09-05T16:46:19.633Z,1536165979.633 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2018-09-05T16:46:19.634Z,1536165979.634 [SyncHandler](INFO): Protected caller Thread ID is 797
2018-09-05T16:46:19.634Z,1536165979.634 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2018-09-05T16:46:19.635Z,1536165979.635 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2018-09-05T16:46:19.636Z,1536165979.636 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 798
2018-09-05T16:46:19.638Z,1536165979.638 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2018-09-05T16:46:19.650Z,1536165979.650 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2018-09-05T16:46:19.651Z,1536165979.651 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2018-09-05T16:46:19.651Z,1536165979.651 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 799
2018-09-05T16:46:19.652Z,1536165979.652 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2018-09-05T16:46:19.653Z,1536165979.653 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2018-09-05T16:46:19.653Z,1536165979.653 [logger ThreadHandler](INFO): Protected caller Thread ID is 800
2018-09-05T16:46:19.655Z,1536165979.655 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2018-09-05T16:46:19.656Z,1536165979.656 [Supervisor](INFO): Looking for Config files in directory: Config/
2018-09-05T16:46:19.660Z,1536165979.660 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2018-09-05T16:46:20.008Z,1536165980.008 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2018-09-05T16:46:20.009Z,1536165980.009 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2018-09-05T16:46:20.220Z,1536165980.220 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2018-09-05T16:46:20.222Z,1536165980.222 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2018-09-05T16:46:20.526Z,1536165980.526 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2018-09-05T16:46:20.528Z,1536165980.528 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2018-09-05T16:46:20.672Z,1536165980.672 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2018-09-05T16:46:20.674Z,1536165980.674 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2018-09-05T16:46:20.773Z,1536165980.773 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2018-09-05T16:46:20.775Z,1536165980.775 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2018-09-05T16:46:21.262Z,1536165981.262 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2018-09-05T16:46:21.264Z,1536165981.264 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2018-09-05T16:46:21.709Z,1536165981.709 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2018-09-05T16:46:21.711Z,1536165981.711 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2018-09-05T16:46:22.199Z,1536165982.199 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2018-09-05T16:46:22.199Z,1536165982.199 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2018-09-05T16:46:22.306Z,1536165982.306 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2018-09-05T16:46:22.307Z,1536165982.307 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2018-09-05T16:46:22.406Z,1536165982.406 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2018-09-05T16:46:22.407Z,1536165982.407 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2018-09-05T16:46:22.620Z,1536165982.620 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2018-09-05T16:46:22.622Z,1536165982.622 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2018-09-05T16:46:22.839Z,1536165982.839 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2018-09-05T16:46:22.840Z,1536165982.840 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2018-09-05T16:46:23.203Z,1536165983.203 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2018-09-05T16:46:23.203Z,1536165983.203 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2018-09-05T16:46:23.352Z,1536165983.352 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2018-09-05T16:46:23.353Z,1536165983.353 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2018-09-05T16:46:23.951Z,1536165983.951 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2018-09-05T16:46:23.953Z,1536165983.953 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2018-09-05T16:46:24.060Z,1536165984.060 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2018-09-05T16:46:24.182Z,1536165984.182 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2018-09-05T16:46:24.278Z,1536165984.278 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2018-09-05T16:46:24.365Z,1536165984.365 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2018-09-05T16:46:24.528Z,1536165984.528 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2018-09-05T16:46:24.711Z,1536165984.711 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2018-09-05T16:46:24.788Z,1536165984.788 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg
2018-09-05T16:46:25.023Z,1536165985.023 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2018-09-05T16:46:25.024Z,1536165985.024 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2018-09-05T16:46:25.109Z,1536165985.109 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2018-09-05T16:46:25.201Z,1536165985.201 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2018-09-05T16:46:25.305Z,1536165985.305 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2018-09-05T16:46:25.436Z,1536165985.436 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2018-09-05T16:46:25.449Z,1536165985.449 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2018-09-05T16:46:25.729Z,1536165985.729 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2018-09-05T16:46:25.730Z,1536165985.730 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2018-09-05T16:46:25.786Z,1536165985.786 [DepthRateCalculator] Loaded
2018-09-05T16:46:25.786Z,1536165985.786 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2018-09-05T16:46:25.792Z,1536165985.792 [PitchRateCalculator] Loaded
2018-09-05T16:46:25.792Z,1536165985.792 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2018-09-05T16:46:25.808Z,1536165985.808 [SpeedCalculator] Loaded
2018-09-05T16:46:25.809Z,1536165985.809 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2018-09-05T16:46:25.830Z,1536165985.830 [TempGradientCalculator] Loaded
2018-09-05T16:46:25.831Z,1536165985.831 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2018-09-05T16:46:25.846Z,1536165985.846 [VerticalTemperatureHomogeneityIndexCalculator] Loaded
2018-09-05T16:46:25.846Z,1536165985.846 [ComponentRegistry](DEBUG): SyncComponent "VerticalTemperatureHomogeneityIndexCalculator" handled in the control thread.
2018-09-05T16:46:25.852Z,1536165985.852 [YawRateCalculator] Loaded
2018-09-05T16:46:25.852Z,1536165985.852 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2018-09-05T16:46:25.892Z,1536165985.892 [ElevatorOffsetCalculator] Loaded
2018-09-05T16:46:25.892Z,1536165985.892 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2018-09-05T16:46:25.893Z,1536165985.893 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2018-09-05T16:46:25.894Z,1536165985.894 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2018-09-05T16:46:25.996Z,1536165985.996 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2018-09-05T16:46:25.998Z,1536165985.998 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2018-09-05T16:46:26.130Z,1536165986.130 [BuoyancyServo] Loaded
2018-09-05T16:46:26.131Z,1536165986.131 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2018-09-05T16:46:26.145Z,1536165986.145 [ElevatorServo] Loaded
2018-09-05T16:46:26.146Z,1536165986.146 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2018-09-05T16:46:26.160Z,1536165986.160 [MassServo] Loaded
2018-09-05T16:46:26.161Z,1536165986.161 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2018-09-05T16:46:26.176Z,1536165986.176 [RudderServo] Loaded
2018-09-05T16:46:26.177Z,1536165986.177 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2018-09-05T16:46:26.191Z,1536165986.191 [ThrusterServo] Loaded
2018-09-05T16:46:26.191Z,1536165986.191 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2018-09-05T16:46:26.191Z,1536165986.191 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2018-09-05T16:46:26.193Z,1536165986.193 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2018-09-05T16:46:26.217Z,1536165986.217 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2018-09-05T16:46:26.219Z,1536165986.219 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2018-09-05T16:46:26.345Z,1536165986.345 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2018-09-05T16:46:26.347Z,1536165986.347 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2018-09-05T16:46:26.911Z,1536165986.911 [DataOverHttps] Loaded
2018-09-05T16:46:26.911Z,1536165986.911 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2018-09-05T16:46:26.925Z,1536165986.925 [Depth_Keller] Loaded
2018-09-05T16:46:26.925Z,1536165986.925 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2018-09-05T16:46:26.930Z,1536165986.930 [DropWeight] Loaded
2018-09-05T16:46:26.930Z,1536165986.930 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2018-09-05T16:46:27.029Z,1536165987.029 [NAL9602] Loaded
2018-09-05T16:46:27.030Z,1536165987.030 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2018-09-05T16:46:27.046Z,1536165987.046 [Onboard] Loaded
2018-09-05T16:46:27.046Z,1536165987.046 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2018-09-05T16:46:27.057Z,1536165987.057 [Radio_Surface] Loaded
2018-09-05T16:46:27.057Z,1536165987.057 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2018-09-05T16:46:27.058Z,1536165987.058 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408864E0
2018-09-05T16:46:27.059Z,1536165987.059 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 882
2018-09-05T16:46:27.211Z,1536165987.211 [PNI_TCM] Loaded
2018-09-05T16:46:27.211Z,1536165987.211 [ComponentRegistry](DEBUG): SyncComponent "PNI_TCM" handled in the control thread.
2018-09-05T16:46:27.272Z,1536165987.272 [Rowe_600LCM] Loaded
2018-09-05T16:46:27.273Z,1536165987.273 [ComponentRegistry](DEBUG): Component "Rowe_600LCM" handled in its own thread.
2018-09-05T16:46:27.274Z,1536165987.274 [Rowe_600LCM ThreadHandler](DEBUG): Created PCaller Thread at 408B64E0
2018-09-05T16:46:27.274Z,1536165987.274 [Rowe_600LCM ThreadHandler](INFO): Protected caller Thread ID is 883
2018-09-05T16:46:29.541Z,1536165989.541 [BPC1] Loaded
2018-09-05T16:46:29.542Z,1536165989.542 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2018-09-05T16:46:29.542Z,1536165989.542 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2018-09-05T16:46:29.544Z,1536165989.544 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2018-09-05T16:46:29.700Z,1536165989.700 [SBIT](DEBUG): Construct Startup Built In Test.
2018-09-05T16:46:29.722Z,1536165989.722 [SBIT] Loaded
2018-09-05T16:46:29.723Z,1536165989.723 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2018-09-05T16:46:29.723Z,1536165989.723 [IBIT](DEBUG): Construct Initiated Built In Test.
2018-09-05T16:46:29.735Z,1536165989.735 [IBIT] Loaded
2018-09-05T16:46:29.735Z,1536165989.735 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2018-09-05T16:46:29.738Z,1536165989.738 [CBIT](DEBUG): Construct Continuous Built In Test.
2018-09-05T16:46:29.890Z,1536165989.890 [CBIT] Loaded
2018-09-05T16:46:29.890Z,1536165989.890 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2018-09-05T16:46:29.891Z,1536165989.891 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2018-09-05T16:46:29.893Z,1536165989.893 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2018-09-05T16:46:30.084Z,1536165990.084 [Aanderaa_O2] Loaded
2018-09-05T16:46:30.085Z,1536165990.085 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread.
2018-09-05T16:46:30.165Z,1536165990.165 [CTD_NeilBrown] Loaded
2018-09-05T16:46:30.165Z,1536165990.165 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2018-09-05T16:46:30.166Z,1536165990.166 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 4097A4E0
2018-09-05T16:46:30.166Z,1536165990.166 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 884
2018-09-05T16:46:30.218Z,1536165990.218 [CTD_Seabird] Loaded
2018-09-05T16:46:30.218Z,1536165990.218 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2018-09-05T16:46:30.219Z,1536165990.219 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 409AA4E0
2018-09-05T16:46:30.220Z,1536165990.220 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 885
2018-09-05T16:46:30.234Z,1536165990.234 [PAR_Licor] Loaded
2018-09-05T16:46:30.234Z,1536165990.234 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2018-09-05T16:46:30.284Z,1536165990.284 [WetLabsBB2FL] Loaded
2018-09-05T16:46:30.284Z,1536165990.284 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2018-09-05T16:46:30.285Z,1536165990.285 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 409DA4E0
2018-09-05T16:46:30.286Z,1536165990.286 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 886
2018-09-05T16:46:30.286Z,1536165990.286 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2018-09-05T16:46:30.287Z,1536165990.287 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2018-09-05T16:46:30.375Z,1536165990.375 [VerticalControl](DEBUG): Construct VerticalControl.
2018-09-05T16:46:30.460Z,1536165990.460 [VerticalControl] Loaded
2018-09-05T16:46:30.460Z,1536165990.460 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2018-09-05T16:46:30.461Z,1536165990.461 [HorizontalControl](DEBUG): Construct HorizontalControl.
2018-09-05T16:46:30.518Z,1536165990.518 [HorizontalControl] Loaded
2018-09-05T16:46:30.518Z,1536165990.518 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2018-09-05T16:46:30.519Z,1536165990.519 [SpeedControl](DEBUG): Construct SpeedControl.
2018-09-05T16:46:30.521Z,1536165990.521 [SpeedControl] Loaded
2018-09-05T16:46:30.521Z,1536165990.521 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2018-09-05T16:46:30.522Z,1536165990.522 [LoopControl](DEBUG): Construct LoopControl.
2018-09-05T16:46:30.522Z,1536165990.522 [LoopControl] Loaded
2018-09-05T16:46:30.522Z,1536165990.522 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2018-09-05T16:46:30.523Z,1536165990.523 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2018-09-05T16:46:30.524Z,1536165990.524 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2018-09-05T16:46:30.561Z,1536165990.561 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2018-09-05T16:46:30.562Z,1536165990.562 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2018-09-05T16:46:30.669Z,1536165990.669 [DeadReckonUsingSpeedCalculator] Loaded
2018-09-05T16:46:30.670Z,1536165990.670 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread.
2018-09-05T16:46:30.686Z,1536165990.686 [NavChart] Loaded
2018-09-05T16:46:30.686Z,1536165990.686 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2018-09-05T16:46:30.690Z,1536165990.690 [UniversalFixResidualReporter] Loaded
2018-09-05T16:46:30.690Z,1536165990.690 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2018-09-05T16:46:30.691Z,1536165990.691 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2018-09-05T16:46:30.695Z,1536165990.695 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2018-09-05T16:46:30.695Z,1536165990.695 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2018-09-05T16:46:30.702Z,1536165990.702 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2018-09-05T16:46:30.703Z,1536165990.703 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A664E0
2018-09-05T16:46:30.704Z,1536165990.704 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 887
2018-09-05T16:46:30.708Z,1536165990.708 [Supervisor](INFO): Main Thread ID is 796
2018-09-05T16:46:30.708Z,1536165990.708 [Supervisor](DEBUG): Running supervisor.
2018-09-05T16:46:30.709Z,1536165990.709 [CommandLine ThreadHandler](INFO): Handler Thread ID is 888
2018-09-05T16:46:30.711Z,1536165990.711 [controlThread ThreadHandler](INFO): Handler Thread ID is 889
2018-09-05T16:46:30.712Z,1536165990.712 [controlThread](DEBUG): Initializing ControlThread
2018-09-05T16:46:30.713Z,1536165990.713 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2018-09-05T16:46:30.713Z,1536165990.713 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2018-09-05T16:46:30.713Z,1536165990.713 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2018-09-05T16:46:30.714Z,1536165990.714 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2018-09-05T16:46:30.714Z,1536165990.714 [VerticalTemperatureHomogeneityIndexCalculator](DEBUG): (re)initializing
2018-09-05T16:46:30.715Z,1536165990.715 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2018-09-05T16:46:30.715Z,1536165990.715 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2018-09-05T16:46:30.723Z,1536165990.723 [SBIT](INFO): Initialize SBIT Component.
2018-09-05T16:46:30.724Z,1536165990.724 [SBIT](IMPORTANT): git: 2018-09-04
2018-09-05T16:46:30.724Z,1536165990.724 [SBIT](INFO): git hash: ec53a78724503e2fb746f629f4029aa8924f623d
2018-09-05T16:46:30.724Z,1536165990.724 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2018-09-05T16:46:30.726Z,1536165990.726 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
Kernel Reported: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
2018-09-05T16:46:30.727Z,1536165990.727 [SBIT](INFO): Beginning SBIT in 23.000000 seconds.
2018-09-05T16:46:30.727Z,1536165990.727 [IBIT](INFO): Initialize IBIT Component.
2018-09-05T16:46:30.728Z,1536165990.728 [CBIT](DEBUG): Initialize CBIT Component.
2018-09-05T16:46:30.729Z,1536165990.729 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2018-09-05T16:46:30.730Z,1536165990.730 [logger ThreadHandler](INFO): Handler Thread ID is 890
2018-09-05T16:46:30.749Z,1536165990.749 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 891
2018-09-05T16:46:30.755Z,1536165990.755 [Radio_Surface](INFO): Powering up
2018-09-05T16:46:30.761Z,1536165990.761 [Rowe_600LCM ThreadHandler](INFO): Handler Thread ID is 892
2018-09-05T16:46:30.762Z,1536165990.762 [Rowe_600LCM](INFO): Initializing
2018-09-05T16:46:30.762Z,1536165990.762 [Rowe_600LCM](INFO): Checking LCM
2018-09-05T16:46:30.843Z,1536165990.843 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2018-09-05T16:46:30.849Z,1536165990.849 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2018-09-05T16:46:30.852Z,1536165990.852 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2018-09-05T16:46:30.853Z,1536165990.853 [LoopControl](DEBUG): Initialize LoopControlComponent.
2018-09-05T16:46:30.853Z,1536165990.853 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-09-05T16:46:30.854Z,1536165990.854 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-09-05T16:46:30.855Z,1536165990.855 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-09-05T16:46:30.855Z,1536165990.855 [NavChart](DEBUG): Initialize NavChart Navigation.
2018-09-05T16:46:30.855Z,1536165990.855 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2018-09-05T16:46:30.856Z,1536165990.856 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2018-09-05T16:46:30.891Z,1536165990.891 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 893
2018-09-05T16:46:30.892Z,1536165990.892 [CTD_NeilBrown](INFO): Powering down
2018-09-05T16:46:31.024Z,1536165991.024 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 894
2018-09-05T16:46:31.024Z,1536165991.024 [CTD_Seabird](INFO): Initializing
2018-09-05T16:46:31.025Z,1536165991.025 [CTD_Seabird](INFO): Checking LCM
2018-09-05T16:46:31.026Z,1536165991.026 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 895
2018-09-05T16:46:31.033Z,1536165991.033 [WetLabsBB2FL](INFO): Powering down
2018-09-05T16:46:31.124Z,1536165991.124 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 896
2018-09-05T16:46:31.128Z,1536165991.128 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2018-09-05T16:46:31.134Z,1536165991.134 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2018-09-05T16:46:31.134Z,1536165991.134 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2018-09-05T16:46:31.134Z,1536165991.134 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2018-09-05T16:46:31.134Z,1536165991.134 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2018-09-05T16:46:31.135Z,1536165991.135 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2018-09-05T16:46:31.135Z,1536165991.135 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2018-09-05T16:46:31.135Z,1536165991.135 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2018-09-05T16:46:31.135Z,1536165991.135 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2018-09-05T16:46:31.135Z,1536165991.135 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2018-09-05T16:46:31.136Z,1536165991.136 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2018-09-05T16:46:31.136Z,1536165991.136 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2018-09-05T16:46:31.136Z,1536165991.136 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2018-09-05T16:46:31.136Z,1536165991.136 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2018-09-05T16:46:31.136Z,1536165991.136 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2018-09-05T16:46:31.137Z,1536165991.137 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2018-09-05T16:46:31.137Z,1536165991.137 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2018-09-05T16:46:31.219Z,1536165991.219 [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-09-05T16:46:31.220Z,1536165991.220 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2018-09-05T16:46:31.244Z,1536165991.244 [CTD_Seabird](INFO): LCM OK
2018-09-05T16:46:31.244Z,1536165991.244 [CTD_Seabird](INFO): Powering up
2018-09-05T16:46:31.244Z,1536165991.244 [Rowe_600LCM](INFO): LCM OK
2018-09-05T16:46:31.257Z,1536165991.257 [Rowe_600LCM](INFO): Powering up
2018-09-05T16:46:31.298Z,1536165991.298 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2018-09-05T16:46:31.299Z,1536165991.299 [Default:A.Wait](DEBUG): Construct Wait.
2018-09-05T16:46:31.301Z,1536165991.301 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2018-09-05T16:46:31.340Z,1536165991.340 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2018-09-05T16:46:31.358Z,1536165991.358 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2018-09-05T16:46:31.364Z,1536165991.364 [Default:E.Execute](DEBUG): Construct Execute.
2018-09-05T16:46:31.384Z,1536165991.384 [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-09-05T16:46:31.389Z,1536165991.389 [controlThread](DEBUG): Component order: CycleStarter,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,PNI_TCM,BPC1,Aanderaa_O2,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,VerticalTemperatureHomogeneityIndexCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2018-09-05T16:46:31.430Z,1536165991.430 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2018-09-05T16:46:31.440Z,1536165991.440 [Depth_Keller](ERROR): Pressure reading out of range: 1831.023193 decibar
2018-09-05T16:46:31.814Z,1536165991.814 [DepthRateCalculator](ERROR): Depth measurement is not active
2018-09-05T16:46:31.913Z,1536165991.913 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-09-05T16:46:32.145Z,1536165992.145 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2018-09-05T16:46:32.153Z,1536165992.153 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2018-09-05T16:46:32.176Z,1536165992.176 [ElevatorServo](DEBUG): Initializing EZServoServo.
2018-09-05T16:46:32.181Z,1536165992.181 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2018-09-05T16:46:32.195Z,1536165992.195 [MassServo](DEBUG): Initializing EZServoServo.
2018-09-05T16:46:32.201Z,1536165992.201 [MassServo](DEBUG): Initializing MassServo.
2018-09-05T16:46:32.207Z,1536165992.207 [RudderServo](DEBUG): Initializing EZServoServo.
2018-09-05T16:46:32.213Z,1536165992.213 [RudderServo](DEBUG): Initializing RudderServo.
2018-09-05T16:46:32.227Z,1536165992.227 [ThrusterServo](DEBUG): Initializing EZServoServo.
2018-09-05T16:46:32.233Z,1536165992.233 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2018-09-05T16:46:32.522Z,1536165992.522 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-09-05T16:46:32.765Z,1536165992.765 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-09-05T16:46:33.097Z,1536165993.097 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2018-09-05T16:46:33.097Z,1536165993.097 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2018-09-05T16:46:33.097Z,1536165993.097 [BuoyancyServo] Communications Fault, FailCount= 1
2018-09-05T16:46:33.097Z,1536165993.097 [BuoyancyServo](ERROR): Communications Fault
2018-09-05T16:46:33.309Z,1536165993.309 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2018-09-05T16:46:33.358Z,1536165993.358 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-09-05T16:46:33.367Z,1536165993.367 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2018-09-05T16:46:33.368Z,1536165993.368 [BuoyancyServo](INFO): Powering down
2018-09-05T16:46:33.797Z,1536165993.797 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-09-05T16:46:34.189Z,1536165994.189 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-09-05T16:46:34.573Z,1536165994.573 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-09-05T16:46:35.000Z,1536165995.000 [Aanderaa_O2](INFO): Powering down
2018-09-05T16:46:35.100Z,1536165995.100 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-09-05T16:46:35.330Z,1536165995.330 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface
2018-09-05T16:46:35.464Z,1536165995.464 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null &
2018-09-05T16:46:35.635Z,1536165995.635 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2018-09-05T16:46:35.635Z,1536165995.635 [BuoyancyServo] No Fault, FailCount= 1
2018-09-05T16:46:35.676Z,1536165995.676 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track
2018-09-05T16:46:35.690Z,1536165995.690 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity
2018-09-05T16:46:35.691Z,1536165995.691 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe
2018-09-05T16:46:35.828Z,1536165995.828 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2018-09-05T16:46:35.828Z,1536165995.828 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2018-09-05T16:46:36.543Z,1536165996.543 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface
2018-09-05T16:46:36.712Z,1536165996.712 [CTD_Seabird](INFO): Started Seabird LCM interface with command:nohup ./lrauv-framework/onboard/bin/gpctd -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyC6 -b 9600 >& /dev/null &
2018-09-05T16:46:36.714Z,1536165996.714 [CTD_Seabird](INFO): LCM subscribed to channel:seabird_gpctd_t.seabird-gpctd
2018-09-05T16:46:36.737Z,1536165996.737 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2018-09-05T16:46:36.737Z,1536165996.737 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2018-09-05T16:46:36.737Z,1536165996.737 [BuoyancyServo] Communications Fault, FailCount= 2
2018-09-05T16:46:36.737Z,1536165996.737 [BuoyancyServo](ERROR): Communications Fault
2018-09-05T16:46:36.804Z,1536165996.804 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2018-09-05T16:46:37.329Z,1536165997.329 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2018-09-05T16:46:37.331Z,1536165997.331 [BuoyancyServo](INFO): Powering down
2018-09-05T16:46:37.513Z,1536165997.513 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface
2018-09-05T16:46:37.513Z,1536165997.513 [CTD_Seabird](INFO): Powering down
2018-09-05T16:46:39.574Z,1536165999.574 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2018-09-05T16:46:39.574Z,1536165999.574 [BuoyancyServo] No Fault, FailCount= 2
2018-09-05T16:46:39.967Z,1536165999.967 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2018-09-05T16:46:39.967Z,1536165999.967 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2018-09-05T16:46:54.381Z,1536166014.381 [SBIT](IMPORTANT): Beginning Startup BIT
2018-09-05T16:46:54.386Z,1536166014.386 [CBIT](IMPORTANT): Beginning ground fault scan
2018-09-05T16:46:57.211Z,1536166017.211 [NAL9602](INFO): Powering up NAL9602
2018-09-05T16:47:05.779Z,1536166025.779 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.010713
CHAN A1 (24V): -0.013873
CHAN A2 (12V): -0.001668
CHAN A3 (5V): -0.002013
CHAN B0 (3.3V): 0.000297
CHAN B1 (3.15aV): -0.000214
CHAN B2 (3.15bV): -0.000210
CHAN B3 (GND): 0.000555
OPEN: -0.000338
Full Scale Calc: 4.765 mA, -1.589 mA
2018-09-05T16:47:08.099Z,1536166028.099 [NAL9602](INFO): NAL9602 initialized
2018-09-05T16:47:24.744Z,1536166044.744 [NAL9602](INFO): SBD MO Status=0, MOMSN=8685, MT Status=0, MTMSN=0
2018-09-05T16:47:24.744Z,1536166044.744 [NAL9602](INFO): No messages in MT queue
2018-09-05T16:47:48.181Z,1536166068.181 [SBIT](IMPORTANT): SBIT PASSED
2018-09-05T16:47:48.230Z,1536166068.230 [CommandLine](IMPORTANT): got command configSet list
2018-09-05T16:47:48.230Z,1536166068.230 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2018-09-05T16:47:48.233Z,1536166068.233 [CommandLine](IMPORTANT): Express none CTD_NeilBrown.bin_mean_sea_water_salinity;

2018-09-05T16:47:48.234Z,1536166068.234 [CommandLine](IMPORTANT): Express none CTD_Seabird.bin_median_sea_water_salinity;

2018-09-05T16:47:48.234Z,1536166068.234 [CommandLine](IMPORTANT): Express none Rowe_600LCM.height_above_sea_floor;

2018-09-05T16:47:48.234Z,1536166068.234 [CommandLine](IMPORTANT): Express none VerticalTemperatureHomogeneityIndexCalculator.vertical_temperature_homogeneity_index;

2018-09-05T16:47:48.234Z,1536166068.234 [CommandLine](IMPORTANT): Express linearApproximation height_above_sea_floor 5.000000 meter;

2018-09-05T16:47:48.234Z,1536166068.234 [CommandLine](IMPORTANT): IBIT.batteryMissingStickThreshold=16 count;

2018-09-05T16:47:48.234Z,1536166068.234 [CommandLine](IMPORTANT): StratificationFrontDetector.loadAtStartup=0 bool;

2018-09-05T16:47:48.578Z,1536166068.578 [MissionManager](IMPORTANT): Started mission Startup
2018-09-05T16:47:48.578Z,1536166068.578 [Startup] Running Loop=1
2018-09-05T16:47:48.579Z,1536166068.579 [Startup](DEBUG): Aggregate::initialize Startup
2018-09-05T16:47:48.579Z,1536166068.579 [Startup:A.GoToSurface] Running Loop=1
2018-09-05T16:47:48.579Z,1536166068.579 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2018-09-05T16:47:48.579Z,1536166068.579 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2018-09-05T16:47:48.580Z,1536166068.580 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2018-09-05T16:47:48.580Z,1536166068.580 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2018-09-05T16:47:48.581Z,1536166068.581 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2018-09-05T16:47:48.581Z,1536166068.581 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2018-09-05T16:47:48.587Z,1536166068.587 [Startup:StartupSatComms] Running Loop=1
2018-09-05T16:47:48.587Z,1536166068.587 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2018-09-05T16:47:48.588Z,1536166068.588 [Startup:StartupSatComms:A] Running Loop=1
2018-09-05T16:47:49.020Z,1536166069.020 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2018-09-05T16:48:10.540Z,1536166090.540 [NAL9602](INFO): GPS fix at 20180905T164801: (36.988695, -122.522562)
2018-09-05T16:48:10.698Z,1536166090.698 [Startup:StartupSatComms:A] Stopped
2018-09-05T16:48:10.698Z,1536166090.698 [Startup:StartupSatComms:B] Running Loop=1
2018-09-05T16:48:11.002Z,1536166091.002 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2018-09-05T16:48:32.888Z,1536166112.888 [NAL9602](INFO): SBD MO Status=1, MOMSN=8686, MT Status=0, MTMSN=0
2018-09-05T16:48:32.937Z,1536166112.937 [NAL9602](INFO): Sent 25 bytes from file Logs/20180905T163032/Courier0010.lzma
2018-09-05T16:48:32.937Z,1536166112.937 [NAL9602](INFO): Packets left to send: 0
2018-09-05T16:48:32.939Z,1536166112.939 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180905T163032/Courier0010.lzma.parts/0000.sbd
2018-09-05T16:48:32.939Z,1536166112.939 [NAL9602](DEBUG): Completed sending Logs/20180905T163032/Courier0010.lzma
2018-09-05T16:48:46.992Z,1536166126.992 [NAL9602](INFO): SBD MO Status=1, MOMSN=8687, MT Status=0, MTMSN=0
2018-09-05T16:48:47.049Z,1536166127.049 [NAL9602](INFO): Sent 305 bytes from file Logs/20180905T164619/Courier0000.lzma
2018-09-05T16:48:47.049Z,1536166127.049 [NAL9602](INFO): Packets left to send: 0
2018-09-05T16:48:47.051Z,1536166127.051 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180905T164619/Courier0000.lzma.parts/0000.sbd
2018-09-05T16:48:47.051Z,1536166127.051 [NAL9602](DEBUG): Completed sending Logs/20180905T164619/Courier0000.lzma
2018-09-05T16:48:56.681Z,1536166136.681 [NAL9602](INFO): SBD MO Status=1, MOMSN=8688, MT Status=0, MTMSN=0
2018-09-05T16:48:56.733Z,1536166136.733 [NAL9602](INFO): Sent 162 bytes from file Logs/20180905T163032/Express0011.lzma
2018-09-05T16:48:56.733Z,1536166136.733 [NAL9602](INFO): Packets left to send: 0
2018-09-05T16:48:56.735Z,1536166136.735 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180905T163032/Express0011.lzma.parts/0000.sbd
2018-09-05T16:48:56.735Z,1536166136.735 [NAL9602](DEBUG): Completed sending Logs/20180905T163032/Express0011.lzma
2018-09-05T16:49:10.020Z,1536166150.020 [NAL9602](INFO): SBD MO Status=1, MOMSN=8689, MT Status=0, MTMSN=0
2018-09-05T16:49:10.073Z,1536166150.073 [NAL9602](INFO): Sent 332 bytes from file Logs/20180905T164619/Express0001.lzma
2018-09-05T16:49:10.073Z,1536166150.073 [NAL9602](INFO): Packets left to send: 2
2018-09-05T16:49:10.075Z,1536166150.075 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180905T164619/Express0001.lzma.parts/0002.sbd
2018-09-05T16:49:10.776Z,1536166150.776 [Startup:StartupSatComms:B](INFO): Timed out from 2018-09-05T16:48:10.7Z
2018-09-05T16:49:10.776Z,1536166150.776 [Startup:StartupSatComms:B] Stopped
2018-09-05T16:49:10.776Z,1536166150.776 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2018-09-05T16:49:10.776Z,1536166150.776 [Startup:StartupSatComms] Stopped
2018-09-05T16:49:10.776Z,1536166150.776 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2018-09-05T16:49:10.777Z,1536166150.777 [Startup](INFO): Completed Startup
2018-09-05T16:49:10.778Z,1536166150.778 [MissionManager](INFO): Startup is completed.
2018-09-05T16:49:10.778Z,1536166150.778 [MissionManager](INFO): Uninitializing Mission Startup
2018-09-05T16:49:10.778Z,1536166150.778 [Startup] Stopped
2018-09-05T16:49:10.778Z,1536166150.778 [Startup](DEBUG): Aggregate::uninitialize Startup
2018-09-05T16:49:10.778Z,1536166150.778 [Startup:A.GoToSurface] Stopped
2018-09-05T16:49:10.778Z,1536166150.778 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2018-09-05T16:49:10.936Z,1536166150.936 [MissionManager](IMPORTANT): Started mission Default
2018-09-05T16:49:10.936Z,1536166150.936 [Default] Running Loop=1
2018-09-05T16:49:10.941Z,1536166150.941 [Default](DEBUG): Aggregate::initialize Default
2018-09-05T16:49:10.941Z,1536166150.941 [Default:B.GoToSurface] Running Loop=1
2018-09-05T16:49:10.941Z,1536166150.941 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2018-09-05T16:49:10.941Z,1536166150.941 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2018-09-05T16:49:10.942Z,1536166150.942 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2018-09-05T16:49:10.942Z,1536166150.942 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2018-09-05T16:49:10.942Z,1536166150.942 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2018-09-05T16:49:10.943Z,1536166150.943 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2018-09-05T16:49:10.943Z,1536166150.943 [Default:A.Wait] Running Loop=1
2018-09-05T16:49:10.943Z,1536166150.943 [Default:A.Wait](DEBUG): Initialize Wait Component.
2018-09-05T16:49:20.524Z,1536166160.524 [NAL9602](INFO): SBD MO Status=1, MOMSN=8690, MT Status=0, MTMSN=0
2018-09-05T16:49:20.575Z,1536166160.575 [NAL9602](INFO): Sent 332 bytes from file Logs/20180905T164619/Express0001.lzma
2018-09-05T16:49:20.575Z,1536166160.575 [NAL9602](INFO): Packets left to send: 1
2018-09-05T16:49:20.576Z,1536166160.576 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180905T164619/Express0001.lzma.parts/0001.sbd
2018-09-05T16:49:24.161Z,1536166164.161 [Default:A.Wait](INFO): Done Waiting.
2018-09-05T16:49:24.162Z,1536166164.162 [Default:A.Wait] Stopped
2018-09-05T16:49:24.162Z,1536166164.162 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2018-09-05T16:49:24.571Z,1536166164.571 [Default:CheckIn] Running Loop=1
2018-09-05T16:49:24.572Z,1536166164.572 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-09-05T16:49:24.572Z,1536166164.572 [Default:CheckIn:Read_GPS] Running Loop=1
2018-09-05T16:49:24.982Z,1536166164.982 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2018-09-05T16:49:26.541Z,1536166166.541 [NAL9602](INFO): GPS fix at 20180905T164917: (36.988819, -122.522565)
2018-09-05T16:49:26.600Z,1536166166.600 [Default:CheckIn:Read_GPS] Stopped
2018-09-05T16:49:26.600Z,1536166166.600 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-09-05T16:49:26.980Z,1536166166.980 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2018-09-05T16:49:51.437Z,1536166191.437 [NAL9602](INFO): SBD MO Status=1, MOMSN=8691, MT Status=0, MTMSN=0
2018-09-05T16:49:51.489Z,1536166191.489 [NAL9602](INFO): Sent 62 bytes from file Logs/20180905T164619/Courier0004.lzma
2018-09-05T16:49:51.489Z,1536166191.489 [NAL9602](INFO): Packets left to send: 0
2018-09-05T16:49:51.491Z,1536166191.491 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180905T164619/Courier0004.lzma.parts/0000.sbd
2018-09-05T16:49:51.491Z,1536166191.491 [NAL9602](DEBUG): Completed sending Logs/20180905T164619/Courier0004.lzma
2018-09-05T16:50:02.688Z,1536166202.688 [NAL9602](INFO): SBD MO Status=1, MOMSN=8692, MT Status=0, MTMSN=0
2018-09-05T16:50:02.737Z,1536166202.737 [NAL9602](INFO): Sent 304 bytes from file Logs/20180905T164619/Express0001.lzma
2018-09-05T16:50:02.737Z,1536166202.737 [NAL9602](INFO): Packets left to send: 0
2018-09-05T16:50:02.738Z,1536166202.738 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180905T164619/Express0001.lzma.parts/0000.sbd
2018-09-05T16:50:02.739Z,1536166202.739 [NAL9602](DEBUG): Completed sending Logs/20180905T164619/Express0001.lzma
2018-09-05T16:50:03.083Z,1536166203.083 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004016
2018-09-05T16:50:09.818Z,1536166209.818 [DataOverHttps](INFO): Sending 114 bytes from file Logs/20180905T164619/Express0005.lzma
2018-09-05T16:50:10.618Z,1536166210.618 [DataOverHttps](INFO): Moved sent file to Logs/20180905T164619/Express0005.lzma.bak
2018-09-05T16:50:10.618Z,1536166210.618 [DataOverHttps](INFO): SBD MOMSN=8473878
2018-09-05T16:50:11.136Z,1536166211.136 [Default:CheckIn:Read_Iridium] Stopped
2018-09-05T16:50:11.136Z,1536166211.136 [Default:CheckIn:C.Wait] Running Loop=1
2018-09-05T16:50:11.136Z,1536166211.136 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-09-05T16:50:15.095Z,1536166215.095 [NAL9602](INFO): SBD MO Status=1, MOMSN=8693, MT Status=0, MTMSN=0
2018-09-05T16:50:15.145Z,1536166215.145 [NAL9602](INFO): Sent 114 bytes from file Logs/20180905T164619/Express0005.lzma
2018-09-05T16:50:15.145Z,1536166215.145 [NAL9602](INFO): Packets left to send: 0
2018-09-05T16:50:15.147Z,1536166215.147 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180905T164619/Express0005.lzma.parts/0000.sbd
2018-09-05T16:50:15.147Z,1536166215.147 [NAL9602](DEBUG): Completed sending Logs/20180905T164619/Express0005.lzma
2018-09-05T16:50:45.882Z,1536166245.882 [NAL9602](INFO): Powering down
2018-09-05T16:53:20.871Z,1536166400.871 [DataOverHttps](IMPORTANT): SBD MTMSN=20180905T165312
2018-09-05T16:53:26.162Z,1536166406.162 [DataOverHttps](INFO): Received command:stop
2018-09-05T16:53:26.254Z,1536166406.254 [CommandLine](IMPORTANT): got command stop
2018-09-05T16:53:26.255Z,1536166406.255 [CommandLine](IMPORTANT): Scheduling is paused
2018-09-05T16:53:26.256Z,1536166406.256 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2018-09-05T16:55:11.834Z,1536166511.834 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-09-05T16:55:11.834Z,1536166511.834 [Default:CheckIn:C.Wait] Stopped
2018-09-05T16:55:11.834Z,1536166511.834 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-09-05T16:55:11.834Z,1536166511.834 [Default:CheckIn:D] Running Loop=1
2018-09-05T16:55:12.263Z,1536166512.263 [Default:CheckIn:D] Stopped
2018-09-05T16:55:12.263Z,1536166512.263 [Default:CheckIn:E] Running Loop=1
2018-09-05T16:55:12.648Z,1536166512.648 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 6.022075 min 
2018-09-05T16:55:12.657Z,1536166512.657 [Default:CheckIn:E] Stopped
2018-09-05T16:55:12.657Z,1536166512.657 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-09-05T16:55:12.657Z,1536166512.657 [Default:CheckIn] Stopped
2018-09-05T16:55:12.657Z,1536166512.657 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-09-05T16:55:12.657Z,1536166512.657 [Default:CheckIn](INFO): Running loop #2
2018-09-05T16:55:12.658Z,1536166512.658 [Default:CheckIn] Running Loop=2
2018-09-05T16:55:12.658Z,1536166512.658 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-09-05T16:55:12.658Z,1536166512.658 [Default:CheckIn:Read_GPS] Running Loop=1
2018-09-05T16:55:13.386Z,1536166513.386 [NAL9602](INFO): Powering up
2018-09-05T16:55:25.820Z,1536166525.820 [NAL9602](INFO): NAL9602 initialized
2018-09-05T16:56:04.646Z,1536166564.646 [NAL9602](INFO): SBD MO Status=0, MOMSN=8694, MT Status=0, MTMSN=0
2018-09-05T16:56:04.646Z,1536166564.646 [NAL9602](INFO): No messages in MT queue
2018-09-05T16:56:28.459Z,1536166588.459 [DataOverHttps](IMPORTANT): SBD MTMSN=20180905T165619
2018-09-05T16:56:34.627Z,1536166594.627 [DataOverHttps](INFO): Received command:configSet ESPComponent.loadAtStartup 1 bool persist
2018-09-05T16:56:34.966Z,1536166594.966 [CommandLine](IMPORTANT): got command configSet ESPComponent.loadAtStartup 1.000000 bool persist
2018-09-05T16:56:34.966Z,1536166594.966 [CommandLine](IMPORTANT): configSet ESPComponent.loadAtStartup requires a restart to take effect.
2018-09-05T16:56:35.891Z,1536166595.891 [DataOverHttps](IMPORTANT): SBD MTMSN=20180905T165627
2018-09-05T16:56:45.134Z,1536166605.134 [DataOverHttps](INFO): Received command:configSet ESPComponent.simulateHardware 1 bool persist
2018-09-05T16:56:45.384Z,1536166605.384 [CommandLine](IMPORTANT): got command configSet ESPComponent.simulateHardware 1.000000 bool persist
2018-09-05T16:57:35.538Z,1536166655.538 [NAL9602](INFO): GPS fix at 20180905T165726: (36.989644, -122.523042)
2018-09-05T16:57:35.619Z,1536166655.619 [Default:CheckIn:Read_GPS] Stopped
2018-09-05T16:57:35.619Z,1536166655.619 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-09-05T16:57:41.398Z,1536166661.398 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20180905T164619/Courier0007.lzma
2018-09-05T16:57:42.193Z,1536166662.193 [DataOverHttps](INFO): Moved sent file to Logs/20180905T164619/Courier0007.lzma.bak
2018-09-05T16:57:42.194Z,1536166662.194 [DataOverHttps](IMPORTANT): SBD MOMSN=8473974, MTMSN=20180905T165733
2018-09-05T16:57:48.277Z,1536166668.277 [DataOverHttps](INFO): Received command:configSet ESPComponent.sampleTimeout 10 minute persist
2018-09-05T16:57:48.616Z,1536166668.616 [CommandLine](IMPORTANT): got command configSet ESPComponent.sampleTimeout 10.000000 minute persist
2018-09-05T16:57:54.313Z,1536166674.313 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180905T164619/Courier0010.lzma
2018-09-05T16:57:55.511Z,1536166675.511 [DataOverHttps](INFO): Moved sent file to Logs/20180905T164619/Courier0010.lzma.bak
2018-09-05T16:57:55.511Z,1536166675.511 [DataOverHttps](INFO): SBD MOMSN=8473978
2018-09-05T16:58:08.002Z,1536166688.002 [NAL9602](INFO): Powering down
2018-09-05T16:58:08.888Z,1536166688.888 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180905T164619/Courier0013.lzma
2018-09-05T16:58:10.487Z,1536166690.487 [DataOverHttps](INFO): Moved sent file to Logs/20180905T164619/Courier0013.lzma.bak
2018-09-05T16:58:10.487Z,1536166690.487 [DataOverHttps](INFO): SBD MOMSN=8473980
2018-09-05T16:58:24.566Z,1536166704.566 [DataOverHttps](INFO): Sending 444 bytes from file Logs/20180905T164619/Express0008.lzma
2018-09-05T16:58:25.759Z,1536166705.759 [DataOverHttps](INFO): Moved sent file to Logs/20180905T164619/Express0008.lzma.bak
2018-09-05T16:58:25.759Z,1536166705.759 [DataOverHttps](INFO): SBD MOMSN=8473982
2018-09-05T16:58:37.251Z,1536166717.251 [DataOverHttps](IMPORTANT): SBD MTMSN=20180905T165828
2018-09-05T16:58:48.907Z,1536166728.907 [DataOverHttps](INFO): Sending 52 bytes from file Logs/20180905T164619/Express0011.lzma
2018-09-05T16:58:48.909Z,1536166728.909 [DataOverHttps](INFO): Received command:restart sys
2018-09-05T16:58:48.934Z,1536166728.934 [CommandLine](IMPORTANT): got command restart system
2018-09-05T16:58:49.707Z,1536166729.707 [DataOverHttps](INFO): Moved sent file to Logs/20180905T164619/Express0011.lzma.bak
2018-09-05T16:58:49.707Z,1536166729.707 [DataOverHttps](INFO): SBD MOMSN=8473994
2018-09-05T16:58:51.872Z,1536166731.872 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2018-09-05T16:58:51.873Z,1536166731.873 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-09-05T16:58:51.937Z,1536166731.937 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2018-09-05T16:58:51.937Z,1536166731.937 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-09-05T16:58:51.938Z,1536166731.938 [CommandLine](INFO): Join timeout helper Thread ID is 934
2018-09-05T16:58:51.949Z,1536166731.949 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2018-09-05T16:58:51.949Z,1536166731.949 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-09-05T16:58:51.949Z,1536166731.949 [NavChartDb](INFO): Join timeout helper Thread ID is 935
2018-09-05T16:58:51.961Z,1536166731.961 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2018-09-05T16:58:51.961Z,1536166731.961 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-09-05T16:58:51.962Z,1536166731.962 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2018-09-05T16:58:51.962Z,1536166731.962 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-09-05T16:58:51.962Z,1536166731.962 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 936
2018-09-05T16:58:52.338Z,1536166732.338 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2018-09-05T16:58:52.338Z,1536166732.338 [WetLabsBB2FL](INFO): Powering down
2018-09-05T16:58:52.339Z,1536166732.339 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-09-05T16:58:52.353Z,1536166732.353 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2018-09-05T16:58:52.353Z,1536166732.353 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2018-09-05T16:58:52.354Z,1536166732.354 [CTD_Seabird](INFO): Join timeout helper Thread ID is 937
2018-09-05T16:58:52.545Z,1536166732.545 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2018-09-05T16:58:52.753Z,1536166732.753 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface
2018-09-05T16:58:52.753Z,1536166732.753 [CTD_Seabird](INFO): Powering down
2018-09-05T16:58:52.754Z,1536166732.754 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2018-09-05T16:58:52.773Z,1536166732.773 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2018-09-05T16:58:52.773Z,1536166732.773 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2018-09-05T16:58:52.773Z,1536166732.773 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 939
2018-09-05T16:58:52.993Z,1536166732.993 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2018-09-05T16:58:52.993Z,1536166732.993 [CTD_NeilBrown](INFO): Powering down
2018-09-05T16:58:52.994Z,1536166732.994 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2018-09-05T16:58:52.998Z,1536166732.998 [ComponentRegistry](INFO): Shutting down Rowe_600LCM ThreadHandler
2018-09-05T16:58:52.998Z,1536166732.998 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled.
2018-09-05T16:58:52.998Z,1536166732.998 [Rowe_600LCM](INFO): Join timeout helper Thread ID is 940
2018-09-05T16:58:53.733Z,1536166733.733 [Rowe_600LCM ThreadHandler](INFO): Uninitializing protected caller thread.
2018-09-05T16:58:53.733Z,1536166733.733 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2018-09-05T16:58:53.917Z,1536166733.917 [Rowe_600LCM](INFO): Powering down
2018-09-05T16:58:53.918Z,1536166733.918 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled.
2018-09-05T16:58:53.930Z,1536166733.930 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2018-09-05T16:58:53.930Z,1536166733.930 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-09-05T16:58:53.930Z,1536166733.930 [Radio_Surface](INFO): Join timeout helper Thread ID is 942
2018-09-05T16:58:54.173Z,1536166734.173 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2018-09-05T16:58:54.173Z,1536166734.173 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-09-05T16:58:54.182Z,1536166734.182 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2018-09-05T16:58:54.182Z,1536166734.182 [logger ThreadHandler](INFO): Thread cancelled.
2018-09-05T16:58:54.182Z,1536166734.182 [logger](INFO): Join timeout helper Thread ID is 943
2018-09-05T16:58:54.188Z,1536166734.188 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2018-09-05T16:58:54.188Z,1536166734.188 [logger ThreadHandler](INFO): Thread cancelled.
2018-09-05T16:58:54.190Z,1536166734.190 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2018-09-05T16:58:54.190Z,1536166734.190 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-09-05T16:58:54.190Z,1536166734.190 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2018-09-05T16:58:54.190Z,1536166734.190 [controlThread ThreadHandler](INFO): Thread cancelled.
2018-09-05T16:58:54.191Z,1536166734.191 [controlThread](INFO): Join timeout helper Thread ID is 944
2018-09-05T16:58:54.580Z,1536166734.580 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2018-09-05T16:58:54.580Z,1536166734.580 [controlThread](DEBUG): Uninitializing ControlThread
2018-09-05T16:58:54.583Z,1536166734.583 [NAL9602](INFO): Powering down
2018-09-05T16:58:54.585Z,1536166734.585 [PNI_TCM](INFO): Powering down
2018-09-05T16:58:54.673Z,1536166734.673 [Aanderaa_O2](INFO): Powering down
2018-09-05T16:58:54.675Z,1536166734.675 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2018-09-05T16:58:54.676Z,1536166734.676 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2018-09-05T16:58:54.677Z,1536166734.677 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2018-09-05T16:58:54.677Z,1536166734.677 [MissionManager](INFO): Uninitializing Mission Default
2018-09-05T16:58:54.677Z,1536166734.677 [Default] Stopped
2018-09-05T16:58:54.678Z,1536166734.678 [Default](DEBUG): Aggregate::uninitialize Default
2018-09-05T16:58:54.678Z,1536166734.678 [Default:B.GoToSurface] Stopped
2018-09-05T16:58:54.678Z,1536166734.678 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2018-09-05T16:58:54.678Z,1536166734.678 [Default:CheckIn] Stopped
2018-09-05T16:58:54.678Z,1536166734.678 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-09-05T16:58:54.678Z,1536166734.678 [Default:CheckIn:Read_Iridium] Stopped
2018-09-05T16:58:54.682Z,1536166734.682 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2018-09-05T16:58:54.683Z,1536166734.683 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2018-09-05T16:58:54.683Z,1536166734.683 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2018-09-05T16:58:54.683Z,1536166734.683 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2018-09-05T16:58:54.684Z,1536166734.684 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2018-09-05T16:58:54.684Z,1536166734.684 [BuoyancyServo](INFO): Powering down
2018-09-05T16:58:54.697Z,1536166734.697 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2018-09-05T16:58:54.697Z,1536166734.697 [ElevatorServo](INFO): Powering down
2018-09-05T16:58:54.698Z,1536166734.698 [MassServo](DEBUG): Uninitialize Mass Servo.
2018-09-05T16:58:54.698Z,1536166734.698 [MassServo](INFO): Powering down
2018-09-05T16:58:54.699Z,1536166734.699 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2018-09-05T16:58:54.699Z,1536166734.699 [RudderServo](INFO): Powering down
2018-09-05T16:58:54.700Z,1536166734.700 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2018-09-05T16:58:54.701Z,1536166734.701 [ThrusterServo](INFO): Powering down
2018-09-05T16:58:54.702Z,1536166734.702 [SBIT](DEBUG): Uninitialize SBIT Component.
2018-09-05T16:58:54.702Z,1536166734.702 [IBIT](DEBUG): Uninitialize IBIT Component.
2018-09-05T16:58:54.702Z,1536166734.702 [CBIT](DEBUG): Uninitialize CBIT Component.
2018-09-05T16:58:54.703Z,1536166734.703 [controlThread ThreadHandler](INFO): Thread cancelled.
2018-09-05T16:58:54.828Z,1536166734.828 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled.
2018-09-05T16:58:54.835Z,1536166734.835 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-09-05T16:58:54.873Z,1536166734.873 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-09-05T16:58:54.877Z,1536166734.877 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2018-09-05T16:58:54.879Z,1536166734.879 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2018-09-05T16:58:54.906Z,1536166734.906 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-09-05T16:58:54.970Z,1536166734.970 [logger ThreadHandler](INFO): Thread cancelled.