2019-08-22T03:48:35.118Z,1566445715.118 [Supervisor](DEBUG): Initializing supervisor.
2019-08-22T03:48:35.121Z,1566445715.121 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-08-22T03:48:35.122Z,1566445715.122 [SyncHandler](INFO): Protected caller Thread ID is 3297
2019-08-22T03:48:35.123Z,1566445715.123 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-08-22T03:48:35.124Z,1566445715.124 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-08-22T03:48:35.124Z,1566445715.124 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 3298
2019-08-22T03:48:35.127Z,1566445715.127 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-08-22T03:48:35.139Z,1566445715.139 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-08-22T03:48:35.140Z,1566445715.140 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-08-22T03:48:35.140Z,1566445715.140 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 3299
2019-08-22T03:48:35.141Z,1566445715.141 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-08-22T03:48:35.142Z,1566445715.142 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-08-22T03:48:35.142Z,1566445715.142 [logger ThreadHandler](INFO): Protected caller Thread ID is 3300
2019-08-22T03:48:35.144Z,1566445715.144 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-08-22T03:48:35.145Z,1566445715.145 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-08-22T03:48:35.146Z,1566445715.146 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-08-22T03:48:35.273Z,1566445715.273 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-08-22T03:48:35.274Z,1566445715.274 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-08-22T03:48:35.817Z,1566445715.817 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-08-22T03:48:35.817Z,1566445715.817 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-08-22T03:48:35.917Z,1566445715.917 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-08-22T03:48:35.918Z,1566445715.918 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-08-22T03:48:36.021Z,1566445716.021 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-08-22T03:48:36.022Z,1566445716.022 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-08-22T03:48:36.103Z,1566445716.103 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-08-22T03:48:36.242Z,1566445716.242 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-08-22T03:48:36.243Z,1566445716.243 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-08-22T03:48:36.536Z,1566445716.536 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-08-22T03:48:36.536Z,1566445716.536 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-08-22T03:48:36.987Z,1566445716.987 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-08-22T03:48:36.988Z,1566445716.988 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-08-22T03:48:37.134Z,1566445717.134 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-08-22T03:48:37.135Z,1566445717.135 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-08-22T03:48:37.336Z,1566445717.336 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-08-22T03:48:37.337Z,1566445717.337 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-08-22T03:48:37.786Z,1566445717.786 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-08-22T03:48:37.786Z,1566445717.786 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-08-22T03:48:38.003Z,1566445718.003 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-08-22T03:48:38.004Z,1566445718.004 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-08-22T03:48:38.548Z,1566445718.548 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-08-22T03:48:38.549Z,1566445718.549 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-08-22T03:48:39.112Z,1566445719.112 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-08-22T03:48:39.113Z,1566445719.113 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-08-22T03:48:39.445Z,1566445719.445 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-08-22T03:48:39.447Z,1566445719.447 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-pontus/
2019-08-22T03:48:39.448Z,1566445719.448 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/secure.cfg
2019-08-22T03:48:39.533Z,1566445719.533 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Sensor.cfg
2019-08-22T03:48:39.690Z,1566445719.690 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Servo.cfg
2019-08-22T03:48:39.799Z,1566445719.799 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Simulator.cfg
2019-08-22T03:48:39.886Z,1566445719.886 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/logger.cfg
2019-08-22T03:48:39.983Z,1566445719.983 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/vehicle.cfg
2019-08-22T03:48:40.177Z,1566445720.177 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Battery.cfg
2019-08-22T03:48:40.402Z,1566445720.402 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-08-22T03:48:40.402Z,1566445720.402 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Navigation.cfg
2019-08-22T03:48:40.497Z,1566445720.497 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/BIT.cfg
2019-08-22T03:48:40.597Z,1566445720.597 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Science.cfg
2019-08-22T03:48:40.718Z,1566445720.718 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Control.cfg
2019-08-22T03:48:40.820Z,1566445720.820 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-pontus/root/
2019-08-22T03:48:40.820Z,1566445720.820 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-08-22T03:48:40.826Z,1566445720.826 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-08-22T03:48:40.890Z,1566445720.890 [VerticalControl](DEBUG): Construct VerticalControl.
2019-08-22T03:48:40.000Z,1566445721.000 [VerticalControl] Loaded
2019-08-22T03:48:41.000Z,1566445721.000 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-08-22T03:48:41.001Z,1566445721.001 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-08-22T03:48:41.067Z,1566445721.067 [HorizontalControl] Loaded
2019-08-22T03:48:41.068Z,1566445721.068 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-08-22T03:48:41.068Z,1566445721.068 [SpeedControl](DEBUG): Construct SpeedControl.
2019-08-22T03:48:41.074Z,1566445721.074 [SpeedControl] Loaded
2019-08-22T03:48:41.074Z,1566445721.074 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-08-22T03:48:41.075Z,1566445721.075 [LoopControl](DEBUG): Construct LoopControl.
2019-08-22T03:48:41.075Z,1566445721.075 [LoopControl] Loaded
2019-08-22T03:48:41.075Z,1566445721.075 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-08-22T03:48:41.076Z,1566445721.076 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-08-22T03:48:41.076Z,1566445721.076 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-08-22T03:48:41.115Z,1566445721.115 [DepthRateCalculator] Loaded
2019-08-22T03:48:41.116Z,1566445721.116 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-08-22T03:48:41.121Z,1566445721.121 [PitchRateCalculator] Loaded
2019-08-22T03:48:41.121Z,1566445721.121 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-08-22T03:48:41.136Z,1566445721.136 [SpeedCalculator] Loaded
2019-08-22T03:48:41.136Z,1566445721.136 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-08-22T03:48:41.156Z,1566445721.156 [TempGradientCalculator] Loaded
2019-08-22T03:48:41.157Z,1566445721.157 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-08-22T03:48:41.161Z,1566445721.161 [YawRateCalculator] Loaded
2019-08-22T03:48:41.162Z,1566445721.162 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-08-22T03:48:41.190Z,1566445721.190 [ElevatorOffsetCalculator] Loaded
2019-08-22T03:48:41.190Z,1566445721.190 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-08-22T03:48:41.190Z,1566445721.190 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-08-22T03:48:41.191Z,1566445721.191 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-08-22T03:48:41.221Z,1566445721.221 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-08-22T03:48:41.222Z,1566445721.222 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-08-22T03:48:41.288Z,1566445721.288 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-08-22T03:48:41.288Z,1566445721.288 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-08-22T03:48:41.561Z,1566445721.561 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-08-22T03:48:41.561Z,1566445721.561 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-08-22T03:48:41.654Z,1566445721.654 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-08-22T03:48:41.655Z,1566445721.655 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-08-22T03:48:42.009Z,1566445722.009 [AHRS_M2] Loaded
2019-08-22T03:48:42.010Z,1566445722.010 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-08-22T03:48:42.084Z,1566445722.084 [DataOverHttps] Loaded
2019-08-22T03:48:42.084Z,1566445722.084 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-08-22T03:48:42.085Z,1566445722.085 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 408CA4E0
2019-08-22T03:48:42.086Z,1566445722.086 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 3379
2019-08-22T03:48:42.099Z,1566445722.099 [Depth_Keller] Loaded
2019-08-22T03:48:42.099Z,1566445722.099 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-08-22T03:48:42.103Z,1566445722.103 [DropWeight] Loaded
2019-08-22T03:48:42.104Z,1566445722.104 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-08-22T03:48:42.197Z,1566445722.197 [NAL9602] Loaded
2019-08-22T03:48:42.197Z,1566445722.197 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-08-22T03:48:42.212Z,1566445722.212 [Onboard] Loaded
2019-08-22T03:48:42.213Z,1566445722.213 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-08-22T03:48:42.216Z,1566445722.216 [Radio_Surface] Loaded
2019-08-22T03:48:42.216Z,1566445722.216 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-08-22T03:48:42.217Z,1566445722.217 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408FA4E0
2019-08-22T03:48:42.218Z,1566445722.218 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 3380
2019-08-22T03:48:42.276Z,1566445722.276 [Rowe_600LCM] Loaded
2019-08-22T03:48:42.276Z,1566445722.276 [ComponentRegistry](DEBUG): Component "Rowe_600LCM" handled in its own thread.
2019-08-22T03:48:42.277Z,1566445722.277 [Rowe_600LCM ThreadHandler](DEBUG): Created PCaller Thread at 4092A4E0
2019-08-22T03:48:42.277Z,1566445722.277 [Rowe_600LCM ThreadHandler](INFO): Protected caller Thread ID is 3381
2019-08-22T03:48:43.717Z,1566445723.717 [BPC1] Loaded
2019-08-22T03:48:43.717Z,1566445723.717 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-08-22T03:48:43.717Z,1566445723.717 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-08-22T03:48:43.718Z,1566445723.718 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-08-22T03:48:44.149Z,1566445724.149 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-08-22T03:48:44.149Z,1566445724.149 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-08-22T03:48:44.169Z,1566445724.169 [NavChart] Loaded
2019-08-22T03:48:44.170Z,1566445724.170 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-08-22T03:48:44.174Z,1566445724.174 [UniversalFixResidualReporter] Loaded
2019-08-22T03:48:44.174Z,1566445724.174 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-08-22T03:48:44.174Z,1566445724.174 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-08-22T03:48:44.175Z,1566445724.175 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-08-22T03:48:44.412Z,1566445724.412 [SBIT](DEBUG): Construct Startup Built In Test.
2019-08-22T03:48:44.423Z,1566445724.423 [SBIT] Loaded
2019-08-22T03:48:44.423Z,1566445724.423 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-08-22T03:48:44.424Z,1566445724.424 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-08-22T03:48:44.463Z,1566445724.463 [IBIT] Loaded
2019-08-22T03:48:44.464Z,1566445724.464 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-08-22T03:48:44.467Z,1566445724.467 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-08-22T03:48:44.682Z,1566445724.682 [CBIT] Loaded
2019-08-22T03:48:44.682Z,1566445724.682 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-08-22T03:48:44.682Z,1566445724.682 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-08-22T03:48:44.683Z,1566445724.683 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-08-22T03:48:44.781Z,1566445724.781 [BuoyancyServo] Loaded
2019-08-22T03:48:44.781Z,1566445724.781 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-08-22T03:48:44.792Z,1566445724.792 [ElevatorServo] Loaded
2019-08-22T03:48:44.793Z,1566445724.793 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-08-22T03:48:44.803Z,1566445724.803 [MassServo] Loaded
2019-08-22T03:48:44.803Z,1566445724.803 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-08-22T03:48:44.814Z,1566445724.814 [RudderServo] Loaded
2019-08-22T03:48:44.814Z,1566445724.814 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-08-22T03:48:44.825Z,1566445724.825 [ThrusterServo] Loaded
2019-08-22T03:48:44.825Z,1566445724.825 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-08-22T03:48:44.825Z,1566445724.825 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-08-22T03:48:44.826Z,1566445724.826 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-08-22T03:48:44.839Z,1566445724.839 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-08-22T03:48:44.839Z,1566445724.839 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-08-22T03:48:45.003Z,1566445725.003 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_density
2019-08-22T03:48:45.008Z,1566445725.008 [CTD_Seabird](INFO): created writer for : sea_water_density
2019-08-22T03:48:45.010Z,1566445725.010 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): depth
2019-08-22T03:48:45.015Z,1566445725.015 [CTD_Seabird](INFO): created writer for : depth
2019-08-22T03:48:45.015Z,1566445725.015 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_pressure
2019-08-22T03:48:45.020Z,1566445725.020 [CTD_Seabird](INFO): created writer for : sea_water_pressure
2019-08-22T03:48:45.020Z,1566445725.020 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_salinity
2019-08-22T03:48:45.026Z,1566445725.026 [CTD_Seabird](INFO): created writer for : sea_water_salinity
2019-08-22T03:48:45.026Z,1566445725.026 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_temperature
2019-08-22T03:48:45.031Z,1566445725.031 [CTD_Seabird](INFO): created writer for : sea_water_temperature
2019-08-22T03:48:45.032Z,1566445725.032 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_electrical_conductivity
2019-08-22T03:48:45.037Z,1566445725.037 [CTD_Seabird](INFO): created writer for : sea_water_electrical_conductivity
2019-08-22T03:48:45.037Z,1566445725.037 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): speed_of_sound_in_sea_water
2019-08-22T03:48:45.042Z,1566445725.042 [CTD_Seabird](INFO): created writer for : speed_of_sound_in_sea_water
2019-08-22T03:48:45.068Z,1566445725.068 [CTD_Seabird] Loaded
2019-08-22T03:48:45.069Z,1566445725.069 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2019-08-22T03:48:45.070Z,1566445725.070 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40AAE4E0
2019-08-22T03:48:45.070Z,1566445725.070 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 3382
2019-08-22T03:48:45.117Z,1566445725.117 [WetLabsBB2FL] Loaded
2019-08-22T03:48:45.117Z,1566445725.117 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2019-08-22T03:48:45.118Z,1566445725.118 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40ADE4E0
2019-08-22T03:48:45.118Z,1566445725.118 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 3383
2019-08-22T03:48:45.119Z,1566445725.119 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-08-22T03:48:45.122Z,1566445725.122 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-08-22T03:48:45.123Z,1566445725.123 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-08-22T03:48:45.130Z,1566445725.130 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-08-22T03:48:45.131Z,1566445725.131 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40B0E4E0
2019-08-22T03:48:45.131Z,1566445725.131 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 3384
2019-08-22T03:48:45.136Z,1566445725.136 [Supervisor](INFO): Main Thread ID is 2500
2019-08-22T03:48:45.136Z,1566445725.136 [Supervisor](DEBUG): Running supervisor.
2019-08-22T03:48:45.137Z,1566445725.137 [CommandLine ThreadHandler](INFO): Handler Thread ID is 3385
2019-08-22T03:48:45.139Z,1566445725.139 [controlThread ThreadHandler](INFO): Handler Thread ID is 3386
2019-08-22T03:48:45.139Z,1566445725.139 [controlThread](DEBUG): Initializing ControlThread
2019-08-22T03:48:45.140Z,1566445725.140 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-08-22T03:48:45.142Z,1566445725.142 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-08-22T03:48:45.142Z,1566445725.142 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-08-22T03:48:45.143Z,1566445725.143 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-08-22T03:48:45.143Z,1566445725.143 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-08-22T03:48:45.144Z,1566445725.144 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-08-22T03:48:45.144Z,1566445725.144 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-08-22T03:48:45.144Z,1566445725.144 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-08-22T03:48:45.145Z,1566445725.145 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-08-22T03:48:45.145Z,1566445725.145 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-08-22T03:48:45.150Z,1566445725.150 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-08-22T03:48:45.151Z,1566445725.151 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-08-22T03:48:45.151Z,1566445725.151 [SBIT](INFO): Initialize SBIT Component.
2019-08-22T03:48:45.151Z,1566445725.151 [SBIT](IMPORTANT): git: 2019-08-21
2019-08-22T03:48:45.152Z,1566445725.152 [SBIT](INFO): git hash: 91726968a91bb65c09438a13bfa0101a916cbc64
2019-08-22T03:48:45.152Z,1566445725.152 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-08-22T03:48:45.152Z,1566445725.152 [SBIT](IMPORTANT): Kernel Version:#1 PREEMPT Thu Feb 21 11:17:40 PST 2019
2019-08-22T03:48:45.153Z,1566445725.153 [SBIT](INFO): Beginning SBIT in 59.000000 seconds.
2019-08-22T03:48:45.154Z,1566445725.154 [IBIT](INFO): Initialize IBIT Component.
2019-08-22T03:48:45.155Z,1566445725.155 [CBIT](DEBUG): Initialize CBIT Component.
2019-08-22T03:48:45.156Z,1566445725.156 [logger ThreadHandler](INFO): Handler Thread ID is 3387
2019-08-22T03:48:45.168Z,1566445725.168 [CBIT](DEBUG): Initialized mux pins.
2019-08-22T03:48:45.168Z,1566445725.168 [CBIT](DEBUG): Initializing the watchdog timer.
2019-08-22T03:48:45.176Z,1566445725.176 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 3388
2019-08-22T03:48:45.177Z,1566445725.177 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-08-22T03:48:45.188Z,1566445725.188 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 3389
2019-08-22T03:48:45.192Z,1566445725.192 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-08-22T03:48:45.192Z,1566445725.192 [CBIT](DEBUG): Initializing heartbeat.
2019-08-22T03:48:45.200Z,1566445725.200 [Rowe_600LCM ThreadHandler](INFO): Handler Thread ID is 3390
2019-08-22T03:48:45.201Z,1566445725.201 [Rowe_600LCM](INFO): Initializing
2019-08-22T03:48:45.264Z,1566445725.264 [CBIT](DEBUG): Deactivating GF circuits.
2019-08-22T03:48:45.264Z,1566445725.264 [CBIT](DEBUG): Deactivating emergency mode.
2019-08-22T03:48:45.292Z,1566445725.292 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 3391
2019-08-22T03:48:45.293Z,1566445725.293 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2019-08-22T03:48:45.296Z,1566445725.296 [CTD_Seabird](INFO): Opening uart, block timeout 10ths=20
2019-08-22T03:48:45.298Z,1566445725.298 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 3393
2019-08-22T03:48:45.299Z,1566445725.299 [WetLabsBB2FL](INFO): Powering down
2019-08-22T03:48:45.304Z,1566445725.304 [CBIT](DEBUG): Backplane powered.
2019-08-22T03:48:45.312Z,1566445725.312 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-08-22T03:48:45.326Z,1566445725.326 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-08-22T03:48:45.444Z,1566445725.444 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 3394
2019-08-22T03:48:45.447Z,1566445725.447 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-08-22T03:48:45.447Z,1566445725.447 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-08-22T03:48:45.448Z,1566445725.448 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-08-22T03:48:45.448Z,1566445725.448 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-08-22T03:48:45.448Z,1566445725.448 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-08-22T03:48:45.448Z,1566445725.448 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-08-22T03:48:45.448Z,1566445725.448 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-08-22T03:48:45.448Z,1566445725.448 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-08-22T03:48:45.449Z,1566445725.449 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-08-22T03:48:45.449Z,1566445725.449 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-08-22T03:48:45.449Z,1566445725.449 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-08-22T03:48:45.449Z,1566445725.449 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-08-22T03:48:45.449Z,1566445725.449 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-08-22T03:48:45.449Z,1566445725.449 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-08-22T03:48:45.450Z,1566445725.450 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-08-22T03:48:45.450Z,1566445725.450 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-08-22T03:48:45.471Z,1566445725.471 [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-08-22T03:48:45.471Z,1566445725.471 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-08-22T03:48:45.582Z,1566445725.582 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-08-22T03:48:45.583Z,1566445725.583 [Default:A.Wait](DEBUG): Construct Wait.
2019-08-22T03:48:45.585Z,1566445725.585 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-08-22T03:48:45.592Z,1566445725.592 [Radio_Surface](INFO): Powering up
2019-08-22T03:48:45.678Z,1566445725.678 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-08-22T03:48:45.681Z,1566445725.681 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-08-22T03:48:45.714Z,1566445725.714 [Default:E.Execute](DEBUG): Construct Execute.
2019-08-22T03:48:45.717Z,1566445725.717 [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-08-22T03:48:45.735Z,1566445725.735 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,NAL9602,Onboard,BPC1,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-08-22T03:48:45.741Z,1566445725.741 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-08-22T03:48:45.778Z,1566445725.778 [Depth_Keller](ERROR): Pressure reading out of range: 1650.297119 decibar
2019-08-22T03:48:45.836Z,1566445725.836 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-08-22T03:48:45.865Z,1566445725.865 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-08-22T03:48:45.872Z,1566445725.872 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-08-22T03:48:45.873Z,1566445725.873 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-08-22T03:48:45.880Z,1566445725.880 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-08-22T03:48:45.881Z,1566445725.881 [MassServo](DEBUG): Initializing EZServoServo.
2019-08-22T03:48:45.888Z,1566445725.888 [MassServo](DEBUG): Initializing MassServo.
2019-08-22T03:48:45.889Z,1566445725.889 [RudderServo](DEBUG): Initializing EZServoServo.
2019-08-22T03:48:45.896Z,1566445725.896 [RudderServo](DEBUG): Initializing RudderServo.
2019-08-22T03:48:45.897Z,1566445725.897 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-08-22T03:48:45.904Z,1566445725.904 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-08-22T03:48:46.372Z,1566445726.372 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface
2019-08-22T03:48:46.439Z,1566445726.439 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./auv-shared/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 38400 >& /dev/null &
2019-08-22T03:48:46.912Z,1566445726.912 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-08-22T03:48:46.912Z,1566445726.912 [RudderServo](FAULT): Rudder failed to initialize
2019-08-22T03:48:46.912Z,1566445726.912 [RudderServo] Communications Fault, FailCount= 1
2019-08-22T03:48:46.912Z,1566445726.912 [RudderServo](ERROR): Communications Fault
2019-08-22T03:48:47.023Z,1566445727.023 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-08-22T03:48:47.189Z,1566445727.189 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-08-22T03:48:47.189Z,1566445727.189 [RudderServo](INFO): Powering down
2019-08-22T03:48:47.863Z,1566445727.863 [RudderServo](DEBUG): Initializing EZServoServo.
2019-08-22T03:48:47.864Z,1566445727.864 [RudderServo](DEBUG): Initializing RudderServo.
2019-08-22T03:48:47.884Z,1566445727.884 [CBIT](INFO): Clearing failed state for component RudderServo
2019-08-22T03:48:47.884Z,1566445727.884 [RudderServo] No Fault, FailCount= 1
2019-08-22T03:48:52.360Z,1566445732.360 [CTD_Seabird](ERROR): Device message queue exceeded the allowed limit.
2019-08-22T03:49:12.490Z,1566445752.490 [NAL9602](INFO): Powering up NAL9602
2019-08-22T03:49:23.393Z,1566445763.393 [NAL9602](INFO): NAL9602 initialized
2019-08-22T03:49:24.216Z,1566445764.216 [NAL9602](DEBUG): Fix Requested
2019-08-22T03:49:44.862Z,1566445784.862 [SBIT](IMPORTANT): Beginning Startup BIT
2019-08-22T03:49:44.878Z,1566445784.878 [CBIT](IMPORTANT): Beginning ground fault scan
2019-08-22T03:49:55.957Z,1566445795.957 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): -0.012190
CHAN A1 (24V): 0.172749
CHAN A2 (12V): -0.007164
CHAN A3 (5V): -0.001969
CHAN B0 (3.3V): -0.000711
CHAN B1 (3.15aV): 0.000860
CHAN B2 (3.15bV): 0.000049
CHAN B3 (GND): 0.002000
OPEN: 0.007415
Full Scale Calc: 4.765 mA, -1.589 mA
2019-08-22T03:49:59.329Z,1566445799.329 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-08-22T03:50:11.533Z,1566445811.533 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-08-22T03:50:37.851Z,1566445837.851 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-08-22T03:50:38.590Z,1566445838.590 [SBIT](IMPORTANT): SBIT PASSED
2019-08-22T03:50:38.662Z,1566445838.662 [CommandLine](IMPORTANT): got command configSet list
2019-08-22T03:50:38.662Z,1566445838.662 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-08-22T03:50:38.663Z,1566445838.663 [CommandLine](IMPORTANT): Micromodem.loadAtStartup=0 bool;

2019-08-22T03:50:38.663Z,1566445838.663 [CommandLine](IMPORTANT): Rowe_600.loadAtStartup=0 bool;

2019-08-22T03:50:38.663Z,1566445838.663 [CommandLine](IMPORTANT): Rowe_600LCM.loadAtStartup=1 bool;

2019-08-22T03:50:38.663Z,1566445838.663 [CommandLine](IMPORTANT): VerticalControl.massDefault=10 millimeter;

2019-08-22T03:50:38.977Z,1566445838.977 [MissionManager](IMPORTANT): Started mission Startup
2019-08-22T03:50:38.977Z,1566445838.977 [Startup] Running Loop=1
2019-08-22T03:50:38.977Z,1566445838.977 [Startup](DEBUG): Aggregate::initialize Startup
2019-08-22T03:50:38.977Z,1566445838.977 [Startup:A.GoToSurface] Running Loop=1
2019-08-22T03:50:38.977Z,1566445838.977 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-08-22T03:50:38.978Z,1566445838.978 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-08-22T03:50:38.978Z,1566445838.978 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-08-22T03:50:38.979Z,1566445838.979 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-08-22T03:50:38.979Z,1566445838.979 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-08-22T03:50:38.979Z,1566445838.979 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-08-22T03:50:38.981Z,1566445838.981 [Startup:StartupSatComms] Running Loop=1
2019-08-22T03:50:38.981Z,1566445838.981 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-08-22T03:50:38.982Z,1566445838.982 [Startup:StartupSatComms:A] Running Loop=1
2019-08-22T03:50:39.377Z,1566445839.377 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-08-22T03:50:46.448Z,1566445846.448 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time.
2019-08-22T03:50:46.448Z,1566445846.448 [Rowe_600LCM] Communications Fault, FailCount= 1
2019-08-22T03:50:46.448Z,1566445846.448 [Rowe_600LCM](ERROR): Communications Fault
2019-08-22T03:50:46.677Z,1566445846.677 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM
2019-08-22T03:50:46.852Z,1566445846.852 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2019-08-22T03:50:48.677Z,1566445848.677 [CBIT](INFO): Clearing failed state for component Rowe_600LCM
2019-08-22T03:50:48.677Z,1566445848.677 [Rowe_600LCM] No Fault, FailCount= 1
2019-08-22T03:50:48.684Z,1566445848.684 [Rowe_600LCM](INFO): Initializing
2019-08-22T03:50:49.192Z,1566445849.192 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface
2019-08-22T03:50:49.262Z,1566445849.262 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./auv-shared/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 38400 >& /dev/null &
2019-08-22T03:51:11.102Z,1566445871.102 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004935
2019-08-22T03:51:39.197Z,1566445899.197 [Startup:StartupSatComms:A](INFO): Timed out from 2019-08-22T03:50:38.0Z
2019-08-22T03:51:39.197Z,1566445899.197 [Startup:StartupSatComms:A] Stopped
2019-08-22T03:51:39.197Z,1566445899.197 [Startup:StartupSatComms:B] Running Loop=1
2019-08-22T03:51:39.585Z,1566445899.585 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-08-22T03:51:45.261Z,1566445905.261 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-08-22T03:51:45.261Z,1566445905.261 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-08-22T03:51:45.287Z,1566445905.287 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-08-22T03:51:45.700Z,1566445905.700 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-08-22T03:51:45.700Z,1566445905.700 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-08-22T03:51:53.491Z,1566445913.491 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190821T205945/Courier0223.lzma
2019-08-22T03:51:54.298Z,1566445914.298 [DataOverHttps](INFO): Moved sent file to Logs/20190821T205945/Courier0223.lzma.bak
2019-08-22T03:51:54.298Z,1566445914.298 [DataOverHttps](INFO): SBD MOMSN=11665492
2019-08-22T03:51:55.486Z,1566445915.486 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-08-22T03:52:16.188Z,1566445936.188 [DataOverHttps](INFO): Sending 208 bytes from file Logs/20190821T205945/Express0224.lzma
2019-08-22T03:52:16.994Z,1566445936.994 [DataOverHttps](INFO): Moved sent file to Logs/20190821T205945/Express0224.lzma.bak
2019-08-22T03:52:16.994Z,1566445936.994 [DataOverHttps](INFO): SBD MOMSN=11665494
2019-08-22T03:52:38.417Z,1566445958.417 [DataOverHttps](INFO): Sending 803 bytes from file Logs/20190822T034835/Express0001.lzma
2019-08-22T03:52:39.221Z,1566445959.221 [DataOverHttps](INFO): Moved sent file to Logs/20190822T034835/Express0001.lzma.bak
2019-08-22T03:52:39.222Z,1566445959.222 [DataOverHttps](INFO): SBD MOMSN=11665505
2019-08-22T03:52:39.417Z,1566445959.417 [Startup:StartupSatComms:B](INFO): Timed out from 2019-08-22T03:51:39.2Z
2019-08-22T03:52:39.417Z,1566445959.417 [Startup:StartupSatComms:B] Stopped
2019-08-22T03:52:39.417Z,1566445959.417 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-08-22T03:52:39.417Z,1566445959.417 [Startup:StartupSatComms] Stopped
2019-08-22T03:52:39.418Z,1566445959.418 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-08-22T03:52:39.418Z,1566445959.418 [Startup](INFO): Completed Startup
2019-08-22T03:52:39.419Z,1566445959.419 [MissionManager](INFO): Startup is completed.
2019-08-22T03:52:39.419Z,1566445959.419 [MissionManager](INFO): Uninitializing Mission Startup
2019-08-22T03:52:39.419Z,1566445959.419 [Startup] Stopped
2019-08-22T03:52:39.419Z,1566445959.419 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-08-22T03:52:39.419Z,1566445959.419 [Startup:A.GoToSurface] Stopped
2019-08-22T03:52:39.419Z,1566445959.419 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-08-22T03:52:39.821Z,1566445959.821 [MissionManager](IMPORTANT): Started mission Default
2019-08-22T03:52:39.821Z,1566445959.821 [Default] Running Loop=1
2019-08-22T03:52:39.821Z,1566445959.821 [Default](DEBUG): Aggregate::initialize Default
2019-08-22T03:52:39.821Z,1566445959.821 [Default:B.GoToSurface] Running Loop=1
2019-08-22T03:52:39.821Z,1566445959.821 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-08-22T03:52:39.821Z,1566445959.821 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-08-22T03:52:39.822Z,1566445959.822 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-08-22T03:52:39.822Z,1566445959.822 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-08-22T03:52:39.822Z,1566445959.822 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-08-22T03:52:39.823Z,1566445959.823 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-08-22T03:52:39.823Z,1566445959.823 [Default:A.Wait] Running Loop=1
2019-08-22T03:52:39.823Z,1566445959.823 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-08-22T03:52:47.788Z,1566445967.788 [CommandLine](IMPORTANT): got command failComponent
2019-08-22T03:52:47.789Z,1566445967.789 [CommandLine](IMPORTANT): Failed components:
2019-08-22T03:52:47.789Z,1566445967.789 [CommandLine](IMPORTANT): No failed Components.
2019-08-22T03:52:49.140Z,1566445969.140 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time.
2019-08-22T03:52:49.140Z,1566445969.140 [Rowe_600LCM] Communications Fault, FailCount= 2
2019-08-22T03:52:49.140Z,1566445969.140 [Rowe_600LCM](ERROR): Communications Fault
2019-08-22T03:52:49.513Z,1566445969.513 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM
2019-08-22T03:52:49.544Z,1566445969.544 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2019-08-22T03:52:51.133Z,1566445971.133 [CBIT](INFO): Clearing failed state for component Rowe_600LCM
2019-08-22T03:52:51.133Z,1566445971.133 [Rowe_600LCM] No Fault, FailCount= 2
2019-08-22T03:52:51.372Z,1566445971.372 [Rowe_600LCM](INFO): Initializing
2019-08-22T03:52:51.856Z,1566445971.856 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface
2019-08-22T03:52:51.963Z,1566445971.963 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./auv-shared/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 38400 >& /dev/null &
2019-08-22T03:52:53.141Z,1566445973.141 [Default:A.Wait](INFO): Done Waiting.
2019-08-22T03:52:53.141Z,1566445973.141 [Default:A.Wait] Stopped
2019-08-22T03:52:53.141Z,1566445973.141 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-08-22T03:52:53.589Z,1566445973.589 [Default:CheckIn] Running Loop=1
2019-08-22T03:52:53.589Z,1566445973.589 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-22T03:52:53.589Z,1566445973.589 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-22T03:52:53.966Z,1566445973.966 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-08-22T03:54:26.845Z,1566446066.845 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-08-22T03:54:27.660Z,1566446067.660 [NAL9602](DEBUG): Fix Requested
2019-08-22T03:54:31.296Z,1566446071.296 [NAL9602](DEBUG): Fix Requested
2019-08-22T03:54:31.695Z,1566446071.695 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,035430.00,A,3648.16179,N,12147.28082,W,0.739,348.69,220819,,,A*70
2019-08-22T03:54:31.698Z,1566446071.698 [NAL9602](INFO): GPS fix at 20190822T035430: (36.802697, -121.788014)
2019-08-22T03:54:31.751Z,1566446071.751 [Default:CheckIn:Read_GPS] Stopped
2019-08-22T03:54:31.751Z,1566446071.751 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-22T03:54:32.146Z,1566446072.146 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-08-22T03:54:36.066Z,1566446076.066 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20190822T034835/Courier0004.lzma
2019-08-22T03:54:36.502Z,1566446076.502 [DataOverHttps](INFO): Moved sent file to Logs/20190822T034835/Courier0004.lzma.bak
2019-08-22T03:54:36.502Z,1566446076.502 [DataOverHttps](INFO): SBD MOMSN=11665535
2019-08-22T03:54:51.436Z,1566446091.436 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time.
2019-08-22T03:54:51.436Z,1566446091.436 [Rowe_600LCM] Communications Fault, FailCount= 3
2019-08-22T03:54:51.436Z,1566446091.436 [Rowe_600LCM](ERROR): Communications Fault
2019-08-22T03:54:51.559Z,1566446091.559 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM
2019-08-22T03:54:51.840Z,1566446091.840 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2019-08-22T03:54:53.504Z,1566446093.504 [CBIT](INFO): Clearing failed state for component Rowe_600LCM
2019-08-22T03:54:53.504Z,1566446093.504 [Rowe_600LCM] No Fault, FailCount= 3
2019-08-22T03:54:53.728Z,1566446093.728 [Rowe_600LCM](INFO): Initializing
2019-08-22T03:54:54.245Z,1566446094.245 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface
2019-08-22T03:54:54.358Z,1566446094.358 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./auv-shared/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 38400 >& /dev/null &
2019-08-22T03:54:59.876Z,1566446099.876 [DataOverHttps](INFO): Sending 404 bytes from file Logs/20190822T034835/Express0005.lzma
2019-08-22T03:55:00.681Z,1566446100.681 [DataOverHttps](INFO): Moved sent file to Logs/20190822T034835/Express0005.lzma.bak
2019-08-22T03:55:00.681Z,1566446100.681 [DataOverHttps](INFO): SBD MOMSN=11665538
2019-08-22T03:55:03.187Z,1566446103.187 [Default:CheckIn:Read_Iridium] Stopped
2019-08-22T03:55:03.187Z,1566446103.187 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-22T03:55:03.187Z,1566446103.187 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-22T03:55:03.975Z,1566446103.975 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-22T03:55:07.745Z,1566446107.745 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-08-22T03:55:22.364Z,1566446122.364 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-08-22T03:55:48.024Z,1566446148.024 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-08-22T03:56:14.511Z,1566446174.511 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-08-22T03:56:27.603Z,1566446187.603 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-08-22T03:56:41.084Z,1566446201.084 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-08-22T03:56:41.087Z,1566446201.087 [BPC1](INFO): Received data from all battery sticks.
2019-08-22T03:56:54.386Z,1566446214.386 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time.
2019-08-22T03:56:54.386Z,1566446214.386 [Rowe_600LCM] Communications Fault, FailCount= 4
2019-08-22T03:56:54.386Z,1566446214.386 [Rowe_600LCM](ERROR): Communications Fault
2019-08-22T03:56:54.455Z,1566446214.455 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM
2019-08-22T03:56:54.792Z,1566446214.792 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2019-08-22T03:56:56.444Z,1566446216.444 [CBIT](INFO): Clearing failed state for component Rowe_600LCM
2019-08-22T03:56:56.444Z,1566446216.444 [Rowe_600LCM] No Fault, FailCount= 4
2019-08-22T03:56:56.652Z,1566446216.652 [Rowe_600LCM](INFO): Initializing
2019-08-22T03:56:57.141Z,1566446217.141 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface
2019-08-22T03:56:57.275Z,1566446217.275 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./auv-shared/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 38400 >& /dev/null &
2019-08-22T03:58:56.796Z,1566446336.796 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time.
2019-08-22T03:58:56.796Z,1566446336.796 [Rowe_600LCM] Communications Fault, FailCount= 5
2019-08-22T03:58:56.796Z,1566446336.796 [Rowe_600LCM](ERROR): Communications Fault
2019-08-22T03:58:56.880Z,1566446336.880 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM
2019-08-22T03:58:56.881Z,1566446336.881 [CBIT](FAULT): Communications Fault in component: Rowe_600LCM
2019-08-22T03:58:57.200Z,1566446337.200 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2019-08-22T04:00:03.888Z,1566446403.888 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-08-22T04:00:03.888Z,1566446403.888 [Default:CheckIn:C.Wait] Stopped
2019-08-22T04:00:03.888Z,1566446403.888 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-22T04:00:03.888Z,1566446403.888 [Default:CheckIn:D] Running Loop=1
2019-08-22T04:00:04.302Z,1566446404.302 [Default:CheckIn:D] Stopped
2019-08-22T04:00:04.302Z,1566446404.302 [Default:CheckIn:E] Running Loop=1
2019-08-22T04:00:04.700Z,1566446404.700 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 7.408024 min 
2019-08-22T04:00:04.700Z,1566446404.700 [Default:CheckIn:E] Stopped
2019-08-22T04:00:04.700Z,1566446404.700 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-08-22T04:00:04.700Z,1566446404.700 [Default:CheckIn] Stopped
2019-08-22T04:00:04.700Z,1566446404.700 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-22T04:00:04.701Z,1566446404.701 [Default:CheckIn](INFO): Running loop #2
2019-08-22T04:00:04.701Z,1566446404.701 [Default:CheckIn] Running Loop=2
2019-08-22T04:00:04.701Z,1566446404.701 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-22T04:00:04.701Z,1566446404.701 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-22T04:00:06.304Z,1566446406.304 [NAL9602](DEBUG): Fix Requested
2019-08-22T04:00:06.702Z,1566446406.702 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,040006.00,A,3648.16247,N,12147.28230,W,0.117,188.40,220819,,,A*79
2019-08-22T04:00:06.705Z,1566446406.705 [NAL9602](INFO): GPS fix at 20190822T040006: (36.802708, -121.788038)
2019-08-22T04:00:06.735Z,1566446406.735 [Default:CheckIn:Read_GPS] Stopped
2019-08-22T04:00:06.735Z,1566446406.735 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-22T04:00:13.363Z,1566446413.363 [DataOverHttps](INFO): Sending 221 bytes from file Logs/20190822T034835/Courier0007.lzma
2019-08-22T04:00:14.169Z,1566446414.169 [DataOverHttps](INFO): Moved sent file to Logs/20190822T034835/Courier0007.lzma.bak
2019-08-22T04:00:14.169Z,1566446414.169 [DataOverHttps](INFO): SBD MOMSN=11665564
2019-08-22T04:00:27.420Z,1566446427.420 [DataOverHttps](INFO): Sending 275 bytes from file Logs/20190822T034835/Express0008.lzma
2019-08-22T04:00:28.225Z,1566446428.225 [DataOverHttps](INFO): Moved sent file to Logs/20190822T034835/Express0008.lzma.bak
2019-08-22T04:00:28.225Z,1566446428.225 [DataOverHttps](INFO): SBD MOMSN=11665567
2019-08-22T04:00:30.967Z,1566446430.967 [Default:CheckIn:Read_Iridium] Stopped
2019-08-22T04:00:30.967Z,1566446430.967 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-22T04:00:30.967Z,1566446430.967 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-22T04:00:37.401Z,1566446437.401 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-08-22T04:00:37.484Z,1566446437.484 [NAL9602](FAULT): received: 
+CSQ:0

OK
2019-08-22T04:00:37.484Z,1566446437.484 [NAL9602] Data Fault, FailCount= 1
2019-08-22T04:00:37.484Z,1566446437.484 [NAL9602](ERROR): Data Fault
2019-08-22T04:00:37.519Z,1566446437.519 [CBIT](ERROR): Data Fault in component: NAL9602
2019-08-22T04:00:37.802Z,1566446437.802 [NAL9602](INFO): Powering down
2019-08-22T04:00:38.650Z,1566446438.650 [CBIT](INFO): Clearing failed state for component NAL9602
2019-08-22T04:00:38.650Z,1566446438.650 [NAL9602] No Fault, FailCount= 1
2019-08-22T04:01:08.102Z,1566446468.102 [NAL9602](INFO): Powering up NAL9602
2019-08-22T04:01:19.010Z,1566446479.010 [NAL9602](INFO): NAL9602 initialized
2019-08-22T04:01:50.121Z,1566446510.121 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-22T04:05:31.563Z,1566446731.563 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-08-22T04:05:31.563Z,1566446731.563 [Default:CheckIn:C.Wait] Stopped
2019-08-22T04:05:31.563Z,1566446731.563 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-22T04:05:31.563Z,1566446731.563 [Default:CheckIn:D] Running Loop=1
2019-08-22T04:05:31.965Z,1566446731.965 [Default:CheckIn:D] Stopped
2019-08-22T04:05:31.966Z,1566446731.966 [Default:CheckIn:E] Running Loop=1
2019-08-22T04:05:32.371Z,1566446732.371 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 12.869077 min 
2019-08-22T04:05:32.371Z,1566446732.371 [Default:CheckIn:E] Stopped
2019-08-22T04:05:32.371Z,1566446732.371 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-08-22T04:05:32.371Z,1566446732.371 [Default:CheckIn] Stopped
2019-08-22T04:05:32.371Z,1566446732.371 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-22T04:05:32.371Z,1566446732.371 [Default:CheckIn](INFO): Running loop #3
2019-08-22T04:05:32.371Z,1566446732.371 [Default:CheckIn] Running Loop=3
2019-08-22T04:05:32.371Z,1566446732.371 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-22T04:05:32.372Z,1566446732.372 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-22T04:05:33.976Z,1566446733.976 [NAL9602](DEBUG): Fix Requested
2019-08-22T04:05:34.366Z,1566446734.366 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,040533.00,A,3648.16486,N,12147.28356,W,0.058,0.00,220819,,,A*7F
2019-08-22T04:05:34.369Z,1566446734.369 [NAL9602](INFO): GPS fix at 20190822T040533: (36.802748, -121.788059)
2019-08-22T04:05:34.409Z,1566446734.409 [Default:CheckIn:Read_GPS] Stopped
2019-08-22T04:05:34.409Z,1566446734.409 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-22T04:05:36.813Z,1566446736.813 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-08-22T04:05:43.167Z,1566446743.167 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190822T034835/Courier0010.lzma
2019-08-22T04:05:43.973Z,1566446743.973 [DataOverHttps](INFO): Moved sent file to Logs/20190822T034835/Courier0010.lzma.bak
2019-08-22T04:05:43.973Z,1566446743.973 [DataOverHttps](INFO): SBD MOMSN=11665599
2019-08-22T04:05:59.179Z,1566446759.179 [DataOverHttps](INFO): Sending 152 bytes from file Logs/20190822T034835/Express0011.lzma
2019-08-22T04:05:59.985Z,1566446759.985 [DataOverHttps](INFO): Moved sent file to Logs/20190822T034835/Express0011.lzma.bak
2019-08-22T04:05:59.985Z,1566446759.985 [DataOverHttps](INFO): SBD MOMSN=11665602
2019-08-22T04:06:02.703Z,1566446762.703 [Default:CheckIn:Read_Iridium] Stopped
2019-08-22T04:06:02.703Z,1566446762.703 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-22T04:06:02.703Z,1566446762.703 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-22T04:06:07.521Z,1566446767.521 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-22T04:06:32.678Z,1566446792.678 [CommandLine](IMPORTANT): got command configSet Rowe_600LCM.baud 9600.000000 bit_per_second persist
2019-08-22T04:06:32.678Z,1566446792.678 [CommandLine](IMPORTANT): configSet Rowe_600LCM.baud requires a restart to take effect.
2019-08-22T04:06:37.246Z,1566446797.246 [CommandLine](IMPORTANT): got command restart application
2019-08-22T04:06:38.252Z,1566446798.252 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2019-08-22T04:06:38.252Z,1566446798.252 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-22T04:06:38.253Z,1566446798.253 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-08-22T04:06:38.428Z,1566446798.428 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-08-22T04:06:38.428Z,1566446798.428 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-08-22T04:06:38.429Z,1566446798.429 [CommandLine](INFO): Join timeout helper Thread ID is 3457
2019-08-22T04:06:38.429Z,1566446798.429 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-08-22T04:06:38.429Z,1566446798.429 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-08-22T04:06:38.430Z,1566446798.430 [NavChartDb](INFO): Join timeout helper Thread ID is 3458
2019-08-22T04:06:38.776Z,1566446798.776 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-22T04:06:38.776Z,1566446798.776 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-08-22T04:06:38.792Z,1566446798.792 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2019-08-22T04:06:38.792Z,1566446798.792 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-08-22T04:06:38.792Z,1566446798.792 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 3459
2019-08-22T04:06:39.276Z,1566446799.276 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-22T04:06:39.277Z,1566446799.277 [WetLabsBB2FL](INFO): Powering down
2019-08-22T04:06:39.277Z,1566446799.277 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-08-22T04:06:39.296Z,1566446799.296 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2019-08-22T04:06:39.296Z,1566446799.296 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-08-22T04:06:39.296Z,1566446799.296 [CTD_Seabird](INFO): Join timeout helper Thread ID is 3460
2019-08-22T04:06:39.816Z,1566446799.816 [CTD_Seabird](INFO): Powering down
2019-08-22T04:06:39.833Z,1566446799.833 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-22T04:06:39.834Z,1566446799.834 [CTD_Seabird](INFO): Powering down
2019-08-22T04:06:39.848Z,1566446799.848 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-08-22T04:06:39.849Z,1566446799.849 [ComponentRegistry](INFO): Shutting down Rowe_600LCM ThreadHandler
2019-08-22T04:06:39.849Z,1566446799.849 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled.
2019-08-22T04:06:39.849Z,1566446799.849 [Rowe_600LCM](INFO): Join timeout helper Thread ID is 3461
2019-08-22T04:06:40.012Z,1566446800.012 [Rowe_600LCM ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-22T04:06:40.012Z,1566446800.012 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2019-08-22T04:06:40.101Z,1566446800.101 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled.
2019-08-22T04:06:40.113Z,1566446800.113 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-08-22T04:06:40.113Z,1566446800.113 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-08-22T04:06:40.113Z,1566446800.113 [Radio_Surface](INFO): Join timeout helper Thread ID is 3463
2019-08-22T04:06:40.408Z,1566446800.408 [Radio_Surface](INFO): Powering down
2019-08-22T04:06:40.409Z,1566446800.409 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-22T04:06:40.410Z,1566446800.410 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-08-22T04:06:40.428Z,1566446800.428 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-08-22T04:06:40.429Z,1566446800.429 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-08-22T04:06:40.429Z,1566446800.429 [DataOverHttps](INFO): Join timeout helper Thread ID is 3464
2019-08-22T04:06:40.524Z,1566446800.524 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-22T04:06:40.524Z,1566446800.524 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-08-22T04:06:40.529Z,1566446800.529 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-08-22T04:06:40.529Z,1566446800.529 [logger ThreadHandler](INFO): Thread cancelled.
2019-08-22T04:06:40.529Z,1566446800.529 [logger](INFO): Join timeout helper Thread ID is 3465
2019-08-22T04:06:40.584Z,1566446800.584 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-22T04:06:40.584Z,1566446800.584 [logger ThreadHandler](INFO): Thread cancelled.
2019-08-22T04:06:40.588Z,1566446800.588 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-08-22T04:06:40.589Z,1566446800.589 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-08-22T04:06:40.589Z,1566446800.589 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-08-22T04:06:40.589Z,1566446800.589 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-08-22T04:06:40.589Z,1566446800.589 [controlThread](INFO): Join timeout helper Thread ID is 3466
2019-08-22T04:06:40.628Z,1566446800.628 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-22T04:06:40.628Z,1566446800.628 [controlThread](DEBUG): Uninitializing ControlThread
2019-08-22T04:06:40.629Z,1566446800.629 [AHRS_M2](INFO): Powering down
2019-08-22T04:06:40.700Z,1566446800.700 [NAL9602](INFO): Powering down
2019-08-22T04:06:40.702Z,1566446800.702 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-08-22T04:06:40.703Z,1566446800.703 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-08-22T04:06:40.704Z,1566446800.704 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-08-22T04:06:40.704Z,1566446800.704 [MissionManager](INFO): Uninitializing Mission Default
2019-08-22T04:06:40.704Z,1566446800.704 [Default] Stopped
2019-08-22T04:06:40.705Z,1566446800.705 [Default](DEBUG): Aggregate::uninitialize Default
2019-08-22T04:06:40.705Z,1566446800.705 [Default:B.GoToSurface] Stopped
2019-08-22T04:06:40.705Z,1566446800.705 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-08-22T04:06:40.705Z,1566446800.705 [Default:CheckIn] Stopped
2019-08-22T04:06:40.705Z,1566446800.705 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-22T04:06:40.705Z,1566446800.705 [Default:CheckIn:C.Wait] Stopped
2019-08-22T04:06:40.705Z,1566446800.705 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-22T04:06:40.708Z,1566446800.708 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-08-22T04:06:40.708Z,1566446800.708 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-08-22T04:06:40.709Z,1566446800.709 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-08-22T04:06:40.709Z,1566446800.709 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-08-22T04:06:40.709Z,1566446800.709 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-08-22T04:06:40.709Z,1566446800.709 [BuoyancyServo](INFO): Powering down
2019-08-22T04:06:40.724Z,1566446800.724 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-08-22T04:06:40.724Z,1566446800.724 [ElevatorServo](INFO): Powering down
2019-08-22T04:06:40.725Z,1566446800.725 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-08-22T04:06:40.725Z,1566446800.725 [MassServo](INFO): Powering down
2019-08-22T04:06:40.726Z,1566446800.726 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-08-22T04:06:40.726Z,1566446800.726 [RudderServo](INFO): Powering down
2019-08-22T04:06:40.727Z,1566446800.727 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-08-22T04:06:40.727Z,1566446800.727 [ThrusterServo](INFO): Powering down
2019-08-22T04:06:40.728Z,1566446800.728 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-08-22T04:06:40.729Z,1566446800.729 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-08-22T04:06:40.729Z,1566446800.729 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-08-22T04:06:40.729Z,1566446800.729 [CBIT](DEBUG): Powering off loads.
2019-08-22T04:06:40.740Z,1566446800.740 [CBIT](DEBUG): Disabling WDT.
2019-08-22T04:06:40.752Z,1566446800.752 [CBIT](DEBUG): Opening all GF detection circuits.
2019-08-22T04:06:40.753Z,1566446800.753 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-08-22T04:06:40.861Z,1566446800.861 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled.
2019-08-22T04:06:40.864Z,1566446800.864 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-08-22T04:06:40.870Z,1566446800.870 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-08-22T04:06:40.926Z,1566446800.926 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-08-22T04:06:40.928Z,1566446800.928 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-08-22T04:06:40.938Z,1566446800.938 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-08-22T04:06:41.011Z,1566446801.011 [logger ThreadHandler](INFO): Thread cancelled.