2019-02-08T01:20:55.772Z,1549588855.772 [Supervisor](DEBUG): Initializing supervisor.
2019-02-08T01:20:55.775Z,1549588855.775 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-02-08T01:20:55.776Z,1549588855.776 [SyncHandler](INFO): Protected caller Thread ID is 2246
2019-02-08T01:20:55.777Z,1549588855.777 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-02-08T01:20:55.778Z,1549588855.778 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-02-08T01:20:55.778Z,1549588855.778 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 2247
2019-02-08T01:20:55.782Z,1549588855.782 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-02-08T01:20:55.794Z,1549588855.794 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-02-08T01:20:55.795Z,1549588855.795 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-02-08T01:20:55.795Z,1549588855.795 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 2248
2019-02-08T01:20:55.796Z,1549588855.796 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-02-08T01:20:55.797Z,1549588855.797 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-02-08T01:20:55.798Z,1549588855.798 [logger ThreadHandler](INFO): Protected caller Thread ID is 2249
2019-02-08T01:20:55.800Z,1549588855.800 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-02-08T01:20:55.800Z,1549588855.800 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-02-08T01:20:55.802Z,1549588855.802 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-02-08T01:20:56.147Z,1549588856.147 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-02-08T01:20:56.148Z,1549588856.148 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-02-08T01:20:56.588Z,1549588856.588 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-02-08T01:20:56.589Z,1549588856.589 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-02-08T01:20:56.909Z,1549588856.909 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-02-08T01:20:56.910Z,1549588856.910 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-02-08T01:20:57.101Z,1549588857.101 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-02-08T01:20:57.101Z,1549588857.101 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-02-08T01:20:57.540Z,1549588857.540 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-02-08T01:20:57.540Z,1549588857.540 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-02-08T01:20:58.011Z,1549588858.011 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-02-08T01:20:58.011Z,1549588858.011 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-02-08T01:20:58.116Z,1549588858.116 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-02-08T01:20:58.117Z,1549588858.117 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-02-08T01:20:58.307Z,1549588858.307 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-02-08T01:20:58.308Z,1549588858.308 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-02-08T01:20:58.451Z,1549588858.451 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-02-08T01:20:58.452Z,1549588858.452 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-02-08T01:20:58.534Z,1549588858.534 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-02-08T01:20:58.740Z,1549588858.740 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-02-08T01:20:58.740Z,1549588858.740 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-02-08T01:20:58.841Z,1549588858.841 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-02-08T01:20:58.842Z,1549588858.842 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-02-08T01:20:58.938Z,1549588858.938 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-02-08T01:20:58.938Z,1549588858.938 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-02-08T01:20:59.087Z,1549588859.087 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-02-08T01:20:59.087Z,1549588859.087 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-02-08T01:20:59.402Z,1549588859.402 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-02-08T01:20:59.404Z,1549588859.404 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-02-08T01:20:59.405Z,1549588859.405 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-02-08T01:20:59.539Z,1549588859.539 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-02-08T01:20:59.768Z,1549588859.768 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-02-08T01:20:59.769Z,1549588859.769 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-02-08T01:20:59.934Z,1549588859.934 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-02-08T01:21:00.033Z,1549588860.033 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-02-08T01:21:00.131Z,1549588860.131 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-02-08T01:21:00.327Z,1549588860.327 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-02-08T01:21:00.501Z,1549588860.501 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-02-08T01:21:00.690Z,1549588860.690 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-02-08T01:21:00.874Z,1549588860.874 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-02-08T01:21:00.989Z,1549588860.989 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-02-08T01:21:01.162Z,1549588861.162 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/
2019-02-08T01:21:01.162Z,1549588861.162 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-02-08T01:21:01.167Z,1549588861.167 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-02-08T01:21:01.302Z,1549588861.302 [SBIT](DEBUG): Construct Startup Built In Test.
2019-02-08T01:21:01.333Z,1549588861.333 [SBIT] Loaded
2019-02-08T01:21:01.334Z,1549588861.334 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-02-08T01:21:01.334Z,1549588861.334 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-02-08T01:21:01.363Z,1549588861.363 [IBIT] Loaded
2019-02-08T01:21:01.363Z,1549588861.363 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-02-08T01:21:01.367Z,1549588861.367 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-02-08T01:21:01.758Z,1549588861.758 [CBIT] Loaded
2019-02-08T01:21:01.759Z,1549588861.759 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-02-08T01:21:01.759Z,1549588861.759 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-02-08T01:21:01.760Z,1549588861.760 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-02-08T01:21:01.887Z,1549588861.887 [BuoyancyServo] Loaded
2019-02-08T01:21:01.887Z,1549588861.887 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-02-08T01:21:01.902Z,1549588861.902 [ElevatorServo] Loaded
2019-02-08T01:21:01.902Z,1549588861.902 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-02-08T01:21:01.917Z,1549588861.917 [MassServo] Loaded
2019-02-08T01:21:01.917Z,1549588861.917 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-02-08T01:21:01.932Z,1549588861.932 [RudderServo] Loaded
2019-02-08T01:21:01.933Z,1549588861.933 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-02-08T01:21:01.947Z,1549588861.947 [ThrusterServo] Loaded
2019-02-08T01:21:01.947Z,1549588861.947 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-02-08T01:21:01.948Z,1549588861.948 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-02-08T01:21:01.948Z,1549588861.948 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-02-08T01:21:02.054Z,1549588862.054 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-02-08T01:21:02.054Z,1549588862.054 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-02-08T01:21:02.114Z,1549588862.114 [DeadReckonUsingSpeedCalculator] Loaded
2019-02-08T01:21:02.115Z,1549588862.115 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread.
2019-02-08T01:21:02.174Z,1549588862.174 [DeadReckonWithRespectToSeafloor] Loaded
2019-02-08T01:21:02.175Z,1549588862.175 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToSeafloor" handled in the control thread.
2019-02-08T01:21:02.191Z,1549588862.191 [NavChart] Loaded
2019-02-08T01:21:02.191Z,1549588862.191 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-02-08T01:21:02.195Z,1549588862.195 [UniversalFixResidualReporter] Loaded
2019-02-08T01:21:02.196Z,1549588862.196 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-02-08T01:21:02.196Z,1549588862.196 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-02-08T01:21:02.197Z,1549588862.197 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-02-08T01:21:02.211Z,1549588862.211 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-02-08T01:21:02.211Z,1549588862.211 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-02-08T01:21:02.446Z,1549588862.446 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-02-08T01:21:02.447Z,1549588862.447 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-02-08T01:21:02.784Z,1549588862.784 [AHRS_M2] Loaded
2019-02-08T01:21:02.784Z,1549588862.784 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-02-08T01:21:02.853Z,1549588862.853 [DataOverHttps] Loaded
2019-02-08T01:21:02.853Z,1549588862.853 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2019-02-08T01:21:02.866Z,1549588862.866 [Depth_Keller] Loaded
2019-02-08T01:21:02.867Z,1549588862.867 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-02-08T01:21:02.872Z,1549588862.872 [DropWeight] Loaded
2019-02-08T01:21:02.872Z,1549588862.872 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-02-08T01:21:02.924Z,1549588862.924 [DUSBL_Hydroid] Loaded
2019-02-08T01:21:02.924Z,1549588862.924 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-02-08T01:21:03.015Z,1549588863.015 [NAL9602] Loaded
2019-02-08T01:21:03.015Z,1549588863.015 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-02-08T01:21:03.021Z,1549588863.021 [Onboard] Loaded
2019-02-08T01:21:03.021Z,1549588863.021 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-02-08T01:21:03.028Z,1549588863.028 [Radio_Surface] Loaded
2019-02-08T01:21:03.028Z,1549588863.028 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-02-08T01:21:03.029Z,1549588863.029 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408494E0
2019-02-08T01:21:03.030Z,1549588863.030 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 2328
2019-02-08T01:21:03.058Z,1549588863.058 [RDI_Pathfinder] Loaded
2019-02-08T01:21:03.059Z,1549588863.059 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-02-08T01:21:03.081Z,1549588863.081 [RDI_PathfinderUp] Loaded
2019-02-08T01:21:03.081Z,1549588863.081 [ComponentRegistry](DEBUG): SyncComponent "RDI_PathfinderUp" handled in the control thread.
2019-02-08T01:21:04.634Z,1549588864.634 [BPC1] Loaded
2019-02-08T01:21:04.634Z,1549588864.634 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-02-08T01:21:04.635Z,1549588864.635 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-02-08T01:21:04.635Z,1549588864.635 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-02-08T01:21:04.705Z,1549588864.705 [VerticalControl](DEBUG): Construct VerticalControl.
2019-02-08T01:21:04.794Z,1549588864.794 [VerticalControl] Loaded
2019-02-08T01:21:04.794Z,1549588864.794 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-02-08T01:21:04.795Z,1549588864.795 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-02-08T01:21:04.854Z,1549588864.854 [HorizontalControl] Loaded
2019-02-08T01:21:04.855Z,1549588864.855 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-02-08T01:21:04.855Z,1549588864.855 [SpeedControl](DEBUG): Construct SpeedControl.
2019-02-08T01:21:04.857Z,1549588864.857 [SpeedControl] Loaded
2019-02-08T01:21:04.858Z,1549588864.858 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-02-08T01:21:04.858Z,1549588864.858 [LoopControl](DEBUG): Construct LoopControl.
2019-02-08T01:21:04.859Z,1549588864.859 [LoopControl] Loaded
2019-02-08T01:21:04.859Z,1549588864.859 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-02-08T01:21:04.860Z,1549588864.860 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-02-08T01:21:04.860Z,1549588864.860 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-02-08T01:21:04.960Z,1549588864.960 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-02-08T01:21:04.960Z,1549588864.960 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-02-08T01:21:05.145Z,1549588865.145 [Aanderaa_O2] Loaded
2019-02-08T01:21:05.146Z,1549588865.146 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread.
2019-02-08T01:21:05.231Z,1549588865.231 [CTD_NeilBrown] Loaded
2019-02-08T01:21:05.231Z,1549588865.231 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-02-08T01:21:05.232Z,1549588865.232 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 4095A4E0
2019-02-08T01:21:05.233Z,1549588865.233 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 2329
2019-02-08T01:21:05.279Z,1549588865.279 [WetLabsSeaOWL_UV_A] Loaded
2019-02-08T01:21:05.279Z,1549588865.279 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-02-08T01:21:05.281Z,1549588865.281 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 4098A4E0
2019-02-08T01:21:05.281Z,1549588865.281 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 2330
2019-02-08T01:21:05.282Z,1549588865.282 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-02-08T01:21:05.282Z,1549588865.282 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-02-08T01:21:05.346Z,1549588865.346 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-02-08T01:21:05.347Z,1549588865.347 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-02-08T01:21:05.545Z,1549588865.545 [DepthRateCalculator] Loaded
2019-02-08T01:21:05.545Z,1549588865.545 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-02-08T01:21:05.558Z,1549588865.558 [PitchRateCalculator] Loaded
2019-02-08T01:21:05.559Z,1549588865.559 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-02-08T01:21:05.573Z,1549588865.573 [SpeedCalculator] Loaded
2019-02-08T01:21:05.573Z,1549588865.573 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-02-08T01:21:05.595Z,1549588865.595 [TempGradientCalculator] Loaded
2019-02-08T01:21:05.595Z,1549588865.595 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-02-08T01:21:05.601Z,1549588865.601 [YawRateCalculator] Loaded
2019-02-08T01:21:05.601Z,1549588865.601 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-02-08T01:21:05.636Z,1549588865.636 [ElevatorOffsetCalculator] Loaded
2019-02-08T01:21:05.636Z,1549588865.636 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-02-08T01:21:05.637Z,1549588865.637 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-02-08T01:21:05.637Z,1549588865.637 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-02-08T01:21:05.665Z,1549588865.665 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-02-08T01:21:05.668Z,1549588865.668 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-02-08T01:21:05.669Z,1549588865.669 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-02-08T01:21:05.676Z,1549588865.676 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-02-08T01:21:05.677Z,1549588865.677 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A464E0
2019-02-08T01:21:05.677Z,1549588865.677 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 2331
2019-02-08T01:21:05.682Z,1549588865.682 [Supervisor](INFO): Main Thread ID is 1384
2019-02-08T01:21:05.682Z,1549588865.682 [Supervisor](DEBUG): Running supervisor.
2019-02-08T01:21:05.683Z,1549588865.683 [CommandLine ThreadHandler](INFO): Handler Thread ID is 2332
2019-02-08T01:21:05.685Z,1549588865.685 [controlThread ThreadHandler](INFO): Handler Thread ID is 2333
2019-02-08T01:21:05.686Z,1549588865.686 [controlThread](DEBUG): Initializing ControlThread
2019-02-08T01:21:05.687Z,1549588865.687 [SBIT](INFO): Initialize SBIT Component.
2019-02-08T01:21:05.687Z,1549588865.687 [SBIT](IMPORTANT): git: 2019-01-14A-54-g0d094c9
2019-02-08T01:21:05.687Z,1549588865.687 [SBIT](INFO): git hash: 0d094c9fe207dedbc4f0c5a93b42d412b4ef2ca6
2019-02-08T01:21:05.688Z,1549588865.688 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-02-08T01:21:05.688Z,1549588865.688 [SBIT](IMPORTANT): Kernel Version:#2 PREEMPT Thu Jan 11 20:13:48 PST 2018
2019-02-08T01:21:05.689Z,1549588865.689 [SBIT](INFO): Beginning SBIT in 28.000000 seconds.
2019-02-08T01:21:05.690Z,1549588865.690 [IBIT](INFO): Initialize IBIT Component.
2019-02-08T01:21:05.690Z,1549588865.690 [CBIT](DEBUG): Initialize CBIT Component.
2019-02-08T01:21:05.691Z,1549588865.691 [logger ThreadHandler](INFO): Handler Thread ID is 2334
2019-02-08T01:21:05.705Z,1549588865.705 [CBIT](DEBUG): Initialized mux pins.
2019-02-08T01:21:05.705Z,1549588865.705 [CBIT](DEBUG): Initializing the watchdog timer.
2019-02-08T01:21:05.718Z,1549588865.718 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 2335
2019-02-08T01:21:05.723Z,1549588865.723 [Radio_Surface](INFO): Powering up
2019-02-08T01:21:05.729Z,1549588865.729 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-02-08T01:21:05.729Z,1549588865.729 [CBIT](DEBUG): Initializing heartbeat.
2019-02-08T01:21:05.730Z,1549588865.730 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 2336
2019-02-08T01:21:05.730Z,1549588865.730 [CTD_NeilBrown](INFO): Powering down
2019-02-08T01:21:05.798Z,1549588865.798 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 2337
2019-02-08T01:21:05.801Z,1549588865.801 [CBIT](DEBUG): Deactivating GF circuits.
2019-02-08T01:21:05.801Z,1549588865.801 [CBIT](DEBUG): Deactivating emergency mode.
2019-02-08T01:21:05.803Z,1549588865.803 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-02-08T01:21:05.824Z,1549588865.824 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 2338
2019-02-08T01:21:05.830Z,1549588865.830 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-02-08T01:21:05.830Z,1549588865.830 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-02-08T01:21:05.830Z,1549588865.830 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-02-08T01:21:05.830Z,1549588865.830 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-02-08T01:21:05.831Z,1549588865.831 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-02-08T01:21:05.831Z,1549588865.831 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-02-08T01:21:05.831Z,1549588865.831 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-02-08T01:21:05.831Z,1549588865.831 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-02-08T01:21:05.832Z,1549588865.832 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-02-08T01:21:05.832Z,1549588865.832 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-02-08T01:21:05.832Z,1549588865.832 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-02-08T01:21:05.832Z,1549588865.832 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-02-08T01:21:05.833Z,1549588865.833 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-02-08T01:21:05.833Z,1549588865.833 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-02-08T01:21:05.833Z,1549588865.833 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-02-08T01:21:05.833Z,1549588865.833 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-02-08T01:21:05.839Z,1549588865.839 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2019-02-08T01:21:05.840Z,1549588865.840 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-02-08T01:21:05.840Z,1549588865.840 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-02-08T01:21:05.848Z,1549588865.848 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-02-08T01:21:05.850Z,1549588865.850 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-02-08T01:21:05.851Z,1549588865.851 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-02-08T01:21:05.852Z,1549588865.852 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-02-08T01:21:05.852Z,1549588865.852 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-02-08T01:21:05.853Z,1549588865.853 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-02-08T01:21:05.853Z,1549588865.853 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-02-08T01:21:05.853Z,1549588865.853 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-02-08T01:21:05.854Z,1549588865.854 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-02-08T01:21:05.854Z,1549588865.854 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-02-08T01:21:05.856Z,1549588865.856 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-02-08T01:21:05.903Z,1549588865.903 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-02-08T01:21:05.923Z,1549588865.923 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

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

    <Aggregate Id="StartupSatComms">

        <Sequence/>

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

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

    </Aggregate>

</Mission>


2019-02-08T01:21:05.924Z,1549588865.924 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-02-08T01:21:06.008Z,1549588866.008 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-02-08T01:21:06.025Z,1549588866.025 [Default:A.Wait](DEBUG): Construct Wait.
2019-02-08T01:21:06.027Z,1549588866.027 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-02-08T01:21:06.057Z,1549588866.057 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-02-08T01:21:06.060Z,1549588866.060 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-02-08T01:21:06.090Z,1549588866.090 [Default:E.Execute](DEBUG): Construct Execute.
2019-02-08T01:21:06.127Z,1549588866.127 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Universal="Tethys/Universal"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
         Id="Default">

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

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

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

    <Aggregate Id="CheckIn">

        <Sequence Repeat="288"/>

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

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

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

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

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

    </Aggregate>

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

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

</Mission>


2019-02-08T01:21:06.132Z,1549588866.132 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,DataOverHttps,Depth_Keller,DropWeight,DUSBL_Hydroid,NAL9602,Onboard,RDI_Pathfinder,RDI_PathfinderUp,BPC1,Aanderaa_O2,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,DeadReckonWithRespectToSeafloor,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-02-08T01:21:06.155Z,1549588866.155 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-02-08T01:21:06.205Z,1549588866.205 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-02-08T01:21:06.345Z,1549588866.345 [DUSBL_Hydroid](INFO): Powering up
2019-02-08T01:21:06.345Z,1549588866.345 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-02-08T01:21:06.753Z,1549588866.753 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-02-08T01:21:06.757Z,1549588866.757 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-02-08T01:21:06.779Z,1549588866.779 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-02-08T01:21:06.785Z,1549588866.785 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-02-08T01:21:06.818Z,1549588866.818 [MassServo](DEBUG): Initializing EZServoServo.
2019-02-08T01:21:06.821Z,1549588866.821 [MassServo](DEBUG): Initializing MassServo.
2019-02-08T01:21:06.827Z,1549588866.827 [RudderServo](DEBUG): Initializing EZServoServo.
2019-02-08T01:21:06.833Z,1549588866.833 [RudderServo](DEBUG): Initializing RudderServo.
2019-02-08T01:21:06.854Z,1549588866.854 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-02-08T01:21:06.861Z,1549588866.861 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-02-08T01:21:07.073Z,1549588867.073 [RDI_PathfinderUp](INFO): Powering down
2019-02-08T01:21:07.681Z,1549588867.681 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2019-02-08T01:21:07.681Z,1549588867.681 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2019-02-08T01:21:07.681Z,1549588867.681 [BuoyancyServo] Communications Fault, FailCount= 1
2019-02-08T01:21:07.681Z,1549588867.681 [BuoyancyServo](ERROR): Communications Fault
2019-02-08T01:21:07.885Z,1549588867.885 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2019-02-08T01:21:09.709Z,1549588869.709 [Aanderaa_O2](INFO): Powering down
2019-02-08T01:21:09.998Z,1549588869.998 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2019-02-08T01:21:09.998Z,1549588869.998 [BuoyancyServo] No Fault, FailCount= 1
2019-02-08T01:21:10.367Z,1549588870.367 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-02-08T01:21:10.486Z,1549588870.486 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-02-08T01:21:19.606Z,1549588879.606 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-02-08T01:21:24.381Z,1549588884.381 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-02-08T01:21:33.179Z,1549588893.179 [NAL9602](INFO): Powering up NAL9602
2019-02-08T01:21:34.411Z,1549588894.411 [SBIT](IMPORTANT): Beginning Startup BIT
2019-02-08T01:21:34.424Z,1549588894.424 [CBIT](IMPORTANT): Beginning ground fault scan
2019-02-08T01:21:44.099Z,1549588904.099 [NAL9602](INFO): NAL9602 initialized
2019-02-08T01:21:44.913Z,1549588904.913 [NAL9602](DEBUG): Fix Requested
2019-02-08T01:21:45.406Z,1549588905.406 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.010106
CHAN A1 (24V): -0.025123
CHAN A2 (12V): -0.006973
CHAN A3 (5V): -0.002908
CHAN B0 (3.3V): -0.000711
CHAN B1 (3.15aV): -0.000440
CHAN B2 (3.15bV): -0.000151
CHAN B3 (GND): 0.000823
OPEN: 0.009200
Full Scale Calc: 4.765 mA, -1.589 mA
2019-02-08T01:21:51.566Z,1549588911.566 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-02-08T01:21:51.566Z,1549588911.566 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19020718285099,35.0, -0.1,   0.0,10
2019-02-08T01:22:01.962Z,1549588921.962 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-02-08T01:22:01.962Z,1549588921.962 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19020718290099,35.0, -.0,1448.9,  0
2019-02-08T01:22:04.729Z,1549588924.729 [NAL9602](INFO): SBD MO Status=2, MOMSN=2138, MT Status=2, MTMSN=0
2019-02-08T01:22:04.729Z,1549588924.729 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-02-08T01:22:28.565Z,1549588948.565 [SBIT](IMPORTANT): SBIT PASSED
2019-02-08T01:22:28.594Z,1549588948.594 [CommandLine](IMPORTANT): got command configSet list
2019-02-08T01:22:28.595Z,1549588948.595 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-02-08T01:22:28.595Z,1549588948.595 [CommandLine](IMPORTANT): AHRS_M2.readMagnetics=1 bool;

2019-02-08T01:22:28.595Z,1549588948.595 [CommandLine](IMPORTANT): NAL9602.requestGGA=1 bool;

2019-02-08T01:22:28.906Z,1549588948.906 [MissionManager](IMPORTANT): Started mission Startup
2019-02-08T01:22:28.906Z,1549588948.906 [Startup] Running Loop=1
2019-02-08T01:22:28.907Z,1549588948.907 [Startup](DEBUG): Aggregate::initialize Startup
2019-02-08T01:22:28.907Z,1549588948.907 [Startup:A.GoToSurface] Running Loop=1
2019-02-08T01:22:28.907Z,1549588948.907 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-02-08T01:22:28.907Z,1549588948.907 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-02-08T01:22:28.908Z,1549588948.908 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-02-08T01:22:28.908Z,1549588948.908 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-02-08T01:22:28.925Z,1549588948.925 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-02-08T01:22:28.925Z,1549588948.925 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-02-08T01:22:28.931Z,1549588948.931 [Startup:StartupSatComms] Running Loop=1
2019-02-08T01:22:28.931Z,1549588948.931 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-02-08T01:22:28.931Z,1549588948.931 [Startup:StartupSatComms:A] Running Loop=1
2019-02-08T01:22:29.302Z,1549588949.302 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-02-08T01:23:30.657Z,1549589010.657 [Startup:StartupSatComms:A](INFO): Timed out from 2019-02-08T01:22:28.9Z
2019-02-08T01:23:30.657Z,1549589010.657 [Startup:StartupSatComms:A] Stopped
2019-02-08T01:23:30.657Z,1549589010.657 [Startup:StartupSatComms:B] Running Loop=1
2019-02-08T01:23:30.781Z,1549589010.781 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-02-08T01:23:31.486Z,1549589011.486 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004645
2019-02-08T01:23:35.856Z,1549589015.856 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190208T010215/Courier0007.lzma
2019-02-08T01:23:36.650Z,1549589016.650 [DataOverHttps](INFO): Moved sent file to Logs/20190208T010215/Courier0007.lzma.bak
2019-02-08T01:23:36.650Z,1549589016.650 [DataOverHttps](INFO): SBD MOMSN=9641953
2019-02-08T01:23:45.913Z,1549589025.913 [DataOverHttps](INFO): Sending 190 bytes from file Logs/20190208T010215/Express0008.lzma
2019-02-08T01:23:46.674Z,1549589026.674 [DataOverHttps](INFO): Moved sent file to Logs/20190208T010215/Express0008.lzma.bak
2019-02-08T01:23:46.674Z,1549589026.674 [DataOverHttps](INFO): SBD MOMSN=9641955
2019-02-08T01:23:56.018Z,1549589036.018 [DataOverHttps](INFO): Sending 709 bytes from file Logs/20190208T012055/Express0001.lzma
2019-02-08T01:23:56.814Z,1549589036.814 [DataOverHttps](INFO): Moved sent file to Logs/20190208T012055/Express0001.lzma.bak
2019-02-08T01:23:56.814Z,1549589036.814 [DataOverHttps](INFO): SBD MOMSN=9641962
2019-02-08T01:23:57.300Z,1549589037.300 [Startup:StartupSatComms:B] Stopped
2019-02-08T01:23:57.300Z,1549589037.300 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-02-08T01:23:57.300Z,1549589037.300 [Startup:StartupSatComms] Stopped
2019-02-08T01:23:57.300Z,1549589037.300 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-02-08T01:23:57.301Z,1549589037.301 [Startup](INFO): Completed Startup
2019-02-08T01:23:57.301Z,1549589037.301 [MissionManager](INFO): Startup is completed.
2019-02-08T01:23:57.302Z,1549589037.302 [MissionManager](INFO): Uninitializing Mission Startup
2019-02-08T01:23:57.302Z,1549589037.302 [Startup] Stopped
2019-02-08T01:23:57.302Z,1549589037.302 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-02-08T01:23:57.302Z,1549589037.302 [Startup:A.GoToSurface] Stopped
2019-02-08T01:23:57.302Z,1549589037.302 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-02-08T01:23:57.683Z,1549589037.683 [MissionManager](IMPORTANT): Started mission Default
2019-02-08T01:23:57.683Z,1549589037.683 [Default] Running Loop=1
2019-02-08T01:23:57.683Z,1549589037.683 [Default](DEBUG): Aggregate::initialize Default
2019-02-08T01:23:57.683Z,1549589037.683 [Default:B.GoToSurface] Running Loop=1
2019-02-08T01:23:57.683Z,1549589037.683 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-02-08T01:23:57.683Z,1549589037.683 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-02-08T01:23:57.684Z,1549589037.684 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-02-08T01:23:57.684Z,1549589037.684 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-02-08T01:23:57.684Z,1549589037.684 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-02-08T01:23:57.689Z,1549589037.689 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-02-08T01:23:57.689Z,1549589037.689 [Default:A.Wait] Running Loop=1
2019-02-08T01:23:57.689Z,1549589037.689 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-02-08T01:24:01.408Z,1549589041.408 [NAL9602](INFO): SBD MO Status=2, MOMSN=2138, MT Status=2, MTMSN=0
2019-02-08T01:24:01.408Z,1549589041.408 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-02-08T01:24:05.878Z,1549589045.878 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-02-08T01:24:05.878Z,1549589045.878 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-02-08T01:24:05.879Z,1549589045.879 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1
2019-02-08T01:24:05.879Z,1549589045.879 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2019-02-08T01:24:05.880Z,1549589045.880 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 1
2019-02-08T01:24:05.880Z,1549589045.880 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault
2019-02-08T01:24:05.909Z,1549589045.909 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-02-08T01:24:05.910Z,1549589045.910 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2019-02-08T01:24:05.910Z,1549589045.910 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor
2019-02-08T01:24:06.277Z,1549589046.277 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-02-08T01:24:06.278Z,1549589046.278 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-02-08T01:24:06.278Z,1549589046.278 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2019-02-08T01:24:06.278Z,1549589046.278 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1
2019-02-08T01:24:06.279Z,1549589046.279 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor
2019-02-08T01:24:06.279Z,1549589046.279 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 1
2019-02-08T01:24:06.641Z,1549589046.641 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2019-02-08T01:24:08.631Z,1549589048.631 [RDI_Pathfinder](ERROR): Failed to parse:
:BI,    +6,    -5,    +1,    -2,A
2019-02-08T01:24:11.041Z,1549589051.041 [Default:A.Wait](INFO): Done Waiting.
2019-02-08T01:24:11.041Z,1549589051.041 [Default:A.Wait] Stopped
2019-02-08T01:24:11.041Z,1549589051.041 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-02-08T01:24:11.442Z,1549589051.442 [Default:CheckIn] Running Loop=1
2019-02-08T01:24:11.442Z,1549589051.442 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-02-08T01:24:11.442Z,1549589051.442 [Default:CheckIn:Read_GPS] Running Loop=1
2019-02-08T01:24:11.847Z,1549589051.847 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-02-08T01:25:17.561Z,1549589117.561 [RDI_Pathfinder](ERROR): Failed to parse:
:BI,    -6,    +8,    +1,    -1,A
2019-02-08T01:25:57.704Z,1549589157.704 [NAL9602](INFO): SBD MO Status=2, MOMSN=2138, MT Status=2, MTMSN=0
2019-02-08T01:25:57.704Z,1549589157.704 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-02-08T01:26:04.617Z,1549589164.617 [BPC1](ERROR): BPC1B: No match for serial number 1717 in BPC1B's battery stick inventory (sticks 32-63 in onboard configuration file).
2019-02-08T01:26:58.232Z,1549589218.232 [NAL9602](INFO): SBD MO Status=2, MOMSN=2138, MT Status=2, MTMSN=0
2019-02-08T01:26:58.232Z,1549589218.232 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-02-08T01:26:58.631Z,1549589218.631 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-02-08T01:26:59.445Z,1549589219.445 [NAL9602](DEBUG): Fix Requested
2019-02-08T01:26:59.841Z,1549589219.841 [NAL9602](DEBUG): Parsing GGA sentence: $GPGGA,012610.00,3648.16541,N,12147.28499,W,1,5,2.43,9.5,M,-30.7,M,,*5E
2019-02-08T01:26:59.844Z,1549589219.844 [NAL9602](INFO): GPS fix at 20190208T012610: (36.802757, -121.788083)
2019-02-08T01:26:59.919Z,1549589219.919 [Default:CheckIn:Read_GPS] Stopped
2019-02-08T01:26:59.919Z,1549589219.919 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-02-08T01:27:00.306Z,1549589220.306 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-02-08T01:27:07.044Z,1549589227.044 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20190208T012055/Courier0004.lzma
2019-02-08T01:27:07.804Z,1549589227.804 [DataOverHttps](INFO): Moved sent file to Logs/20190208T012055/Courier0004.lzma.bak
2019-02-08T01:27:07.804Z,1549589227.804 [DataOverHttps](INFO): SBD MOMSN=9641979
2019-02-08T01:27:17.956Z,1549589237.956 [DataOverHttps](INFO): Sending 300 bytes from file Logs/20190208T012055/Express0005.lzma
2019-02-08T01:27:18.698Z,1549589238.698 [DataOverHttps](INFO): Moved sent file to Logs/20190208T012055/Express0005.lzma.bak
2019-02-08T01:27:18.698Z,1549589238.698 [DataOverHttps](INFO): SBD MOMSN=9641982
2019-02-08T01:27:19.470Z,1549589239.470 [Default:CheckIn:Read_Iridium] Stopped
2019-02-08T01:27:19.470Z,1549589239.470 [Default:CheckIn:C.Wait] Running Loop=1
2019-02-08T01:27:19.470Z,1549589239.470 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-02-08T01:27:36.962Z,1549589256.962 [NAL9602](INFO): Powering down
2019-02-08T01:28:29.658Z,1549589309.658 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-02-08T01:32:20.014Z,1549589540.014 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-02-08T01:32:20.014Z,1549589540.014 [Default:CheckIn:C.Wait] Stopped
2019-02-08T01:32:20.014Z,1549589540.014 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-02-08T01:32:20.014Z,1549589540.014 [Default:CheckIn:D] Running Loop=1
2019-02-08T01:32:20.410Z,1549589540.410 [Default:CheckIn:D] Stopped
2019-02-08T01:32:20.410Z,1549589540.410 [Default:CheckIn:E] Running Loop=1
2019-02-08T01:32:20.817Z,1549589540.817 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 8.378756 min 
2019-02-08T01:32:20.819Z,1549589540.819 [Default:CheckIn:E] Stopped
2019-02-08T01:32:20.819Z,1549589540.819 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-02-08T01:32:20.819Z,1549589540.819 [Default:CheckIn] Stopped
2019-02-08T01:32:20.819Z,1549589540.819 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-02-08T01:32:20.819Z,1549589540.819 [Default:CheckIn](INFO): Running loop #2
2019-02-08T01:32:20.819Z,1549589540.819 [Default:CheckIn] Running Loop=2
2019-02-08T01:32:20.819Z,1549589540.819 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-02-08T01:32:20.820Z,1549589540.820 [Default:CheckIn:Read_GPS] Running Loop=1
2019-02-08T01:32:21.571Z,1549589541.571 [NAL9602](INFO): Powering up
2019-02-08T01:32:32.759Z,1549589552.759 [NAL9602](INFO): NAL9602 initialized
2019-02-08T01:32:33.581Z,1549589553.581 [NAL9602](DEBUG): Fix Requested
2019-02-08T01:35:04.708Z,1549589704.708 [NAL9602](INFO): SBD MO Status=2, MOMSN=2138, MT Status=2, MTMSN=0
2019-02-08T01:35:04.708Z,1549589704.708 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-02-08T01:36:14.076Z,1549589774.076 [NAL9602](INFO): SBD MO Status=2, MOMSN=2138, MT Status=2, MTMSN=0
2019-02-08T01:36:14.076Z,1549589774.076 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-02-08T01:37:05.884Z,1549589825.884 [NAL9602](INFO): SBD MO Status=2, MOMSN=2138, MT Status=2, MTMSN=0
2019-02-08T01:37:05.884Z,1549589825.884 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-02-08T01:37:21.125Z,1549589841.125 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-02-08T01:32:20.8Z
2019-02-08T01:37:21.125Z,1549589841.125 [Default:CheckIn:Read_GPS] Stopped
2019-02-08T01:37:21.125Z,1549589841.125 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-02-08T01:37:25.691Z,1549589845.691 [DataOverHttps](INFO): Sending 190 bytes from file Logs/20190208T012055/Courier0007.lzma
2019-02-08T01:37:26.468Z,1549589846.468 [DataOverHttps](INFO): Moved sent file to Logs/20190208T012055/Courier0007.lzma.bak
2019-02-08T01:37:26.468Z,1549589846.468 [DataOverHttps](INFO): SBD MOMSN=9641999
2019-02-08T01:37:35.923Z,1549589855.923 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20190208T012055/Express0008.lzma
2019-02-08T01:37:36.691Z,1549589856.691 [DataOverHttps](INFO): Moved sent file to Logs/20190208T012055/Express0008.lzma.bak
2019-02-08T01:37:36.692Z,1549589856.692 [DataOverHttps](INFO): SBD MOMSN=9642001
2019-02-08T01:37:37.182Z,1549589857.182 [Default:CheckIn:Read_Iridium] Stopped
2019-02-08T01:37:37.182Z,1549589857.182 [Default:CheckIn:C.Wait] Running Loop=1
2019-02-08T01:37:37.182Z,1549589857.182 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-02-08T01:37:43.384Z,1549589863.384 [NAL9602](INFO): SBD MO Status=0, MOMSN=2138, MT Status=0, MTMSN=0
2019-02-08T01:37:43.384Z,1549589863.384 [NAL9602](INFO): No messages in MT queue
2019-02-08T01:38:15.876Z,1549589895.876 [NAL9602](INFO): Powering down
2019-02-08T01:39:09.166Z,1549589949.166 [CommandLine](IMPORTANT): got command quit
2019-02-08T01:39:10.173Z,1549589950.173 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2019-02-08T01:39:10.176Z,1549589950.176 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-02-08T01:39:10.176Z,1549589950.176 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-02-08T01:39:10.321Z,1549589950.321 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-02-08T01:39:10.321Z,1549589950.321 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-02-08T01:39:10.322Z,1549589950.322 [CommandLine](INFO): Join timeout helper Thread ID is 2373
2019-02-08T01:39:10.323Z,1549589950.323 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-02-08T01:39:10.323Z,1549589950.323 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-02-08T01:39:10.323Z,1549589950.323 [NavChartDb](INFO): Join timeout helper Thread ID is 2374
2019-02-08T01:39:10.577Z,1549589950.577 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-02-08T01:39:10.577Z,1549589950.577 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-02-08T01:39:10.589Z,1549589950.589 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-02-08T01:39:10.589Z,1549589950.589 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-02-08T01:39:10.589Z,1549589950.589 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 2375
2019-02-08T01:39:10.645Z,1549589950.645 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-02-08T01:39:10.645Z,1549589950.645 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-02-08T01:39:10.646Z,1549589950.646 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-02-08T01:39:10.648Z,1549589950.648 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-02-08T01:39:10.648Z,1549589950.648 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-02-08T01:39:10.651Z,1549589950.651 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 2376
2019-02-08T01:39:10.729Z,1549589950.729 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-02-08T01:39:10.729Z,1549589950.729 [CTD_NeilBrown](INFO): Powering down
2019-02-08T01:39:10.741Z,1549589950.741 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-02-08T01:39:10.761Z,1549589950.761 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-02-08T01:39:10.761Z,1549589950.761 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-02-08T01:39:10.761Z,1549589950.761 [Radio_Surface](INFO): Join timeout helper Thread ID is 2377
2019-02-08T01:39:10.773Z,1549589950.773 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-02-08T01:39:10.773Z,1549589950.773 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-02-08T01:39:10.775Z,1549589950.775 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-02-08T01:39:10.775Z,1549589950.775 [logger ThreadHandler](INFO): Thread cancelled.
2019-02-08T01:39:10.775Z,1549589950.775 [logger](INFO): Join timeout helper Thread ID is 2378
2019-02-08T01:39:10.778Z,1549589950.778 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-02-08T01:39:10.778Z,1549589950.778 [logger ThreadHandler](INFO): Thread cancelled.
2019-02-08T01:39:10.779Z,1549589950.779 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-02-08T01:39:10.780Z,1549589950.780 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-02-08T01:39:10.780Z,1549589950.780 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-02-08T01:39:10.780Z,1549589950.780 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-02-08T01:39:10.780Z,1549589950.780 [controlThread](INFO): Join timeout helper Thread ID is 2379
2019-02-08T01:39:11.021Z,1549589951.021 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-02-08T01:39:11.021Z,1549589951.021 [controlThread](DEBUG): Uninitializing ControlThread
2019-02-08T01:39:11.021Z,1549589951.021 [AHRS_M2](INFO): Powering down
2019-02-08T01:39:11.094Z,1549589951.094 [DUSBL_Hydroid](INFO): Powering down
2019-02-08T01:39:11.185Z,1549589951.185 [NAL9602](INFO): Powering down
2019-02-08T01:39:11.257Z,1549589951.257 [RDI_Pathfinder](INFO): Powering down
2019-02-08T01:39:11.258Z,1549589951.258 [RDI_PathfinderUp](INFO): Powering down
2019-02-08T01:39:11.259Z,1549589951.259 [Aanderaa_O2](INFO): Powering down
2019-02-08T01:39:11.260Z,1549589951.260 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-02-08T01:39:11.261Z,1549589951.261 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-02-08T01:39:11.262Z,1549589951.262 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-02-08T01:39:11.262Z,1549589951.262 [MissionManager](INFO): Uninitializing Mission Default
2019-02-08T01:39:11.262Z,1549589951.262 [Default] Stopped
2019-02-08T01:39:11.262Z,1549589951.262 [Default](DEBUG): Aggregate::uninitialize Default
2019-02-08T01:39:11.262Z,1549589951.262 [Default:B.GoToSurface] Stopped
2019-02-08T01:39:11.262Z,1549589951.262 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-02-08T01:39:11.263Z,1549589951.263 [Default:CheckIn] Stopped
2019-02-08T01:39:11.263Z,1549589951.263 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-02-08T01:39:11.263Z,1549589951.263 [Default:CheckIn:C.Wait] Stopped
2019-02-08T01:39:11.263Z,1549589951.263 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-02-08T01:39:11.266Z,1549589951.266 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-02-08T01:39:11.266Z,1549589951.266 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-02-08T01:39:11.266Z,1549589951.266 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-02-08T01:39:11.267Z,1549589951.267 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-02-08T01:39:11.267Z,1549589951.267 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-02-08T01:39:11.267Z,1549589951.267 [BuoyancyServo](INFO): Powering down
2019-02-08T01:39:11.281Z,1549589951.281 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-02-08T01:39:11.281Z,1549589951.281 [ElevatorServo](INFO): Powering down
2019-02-08T01:39:11.282Z,1549589951.282 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-02-08T01:39:11.282Z,1549589951.282 [MassServo](INFO): Powering down
2019-02-08T01:39:11.283Z,1549589951.283 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-02-08T01:39:11.283Z,1549589951.283 [RudderServo](INFO): Powering down
2019-02-08T01:39:11.284Z,1549589951.284 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-02-08T01:39:11.284Z,1549589951.284 [ThrusterServo](INFO): Powering down
2019-02-08T01:39:11.285Z,1549589951.285 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-02-08T01:39:11.285Z,1549589951.285 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-02-08T01:39:11.285Z,1549589951.285 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-02-08T01:39:11.285Z,1549589951.285 [CBIT](DEBUG): Powering off loads.
2019-02-08T01:39:11.297Z,1549589951.297 [CBIT](DEBUG): Disabling WDT.
2019-02-08T01:39:11.309Z,1549589951.309 [CBIT](DEBUG): Opening all GF detection circuits.
2019-02-08T01:39:11.310Z,1549589951.310 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-02-08T01:39:11.412Z,1549589951.412 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-02-08T01:39:11.454Z,1549589951.454 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-02-08T01:39:11.457Z,1549589951.457 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-02-08T01:39:11.479Z,1549589951.479 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-02-08T01:39:11.543Z,1549589951.543 [logger ThreadHandler](INFO): Thread cancelled.