2019-11-26T15:42:44.635Z,1574782964.635 [Supervisor](DEBUG): Initializing supervisor.
2019-11-26T15:42:44.638Z,1574782964.638 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-11-26T15:42:44.639Z,1574782964.639 [SyncHandler](INFO): Protected caller Thread ID is 806
2019-11-26T15:42:44.639Z,1574782964.639 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-11-26T15:42:44.640Z,1574782964.640 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-11-26T15:42:44.640Z,1574782964.640 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 807
2019-11-26T15:42:44.643Z,1574782964.643 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-11-26T15:42:44.654Z,1574782964.654 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-11-26T15:42:44.655Z,1574782964.655 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-11-26T15:42:44.656Z,1574782964.656 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 808
2019-11-26T15:42:44.656Z,1574782964.656 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-11-26T15:42:44.657Z,1574782964.657 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-11-26T15:42:44.658Z,1574782964.658 [logger ThreadHandler](INFO): Protected caller Thread ID is 809
2019-11-26T15:42:44.660Z,1574782964.660 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-11-26T15:42:44.660Z,1574782964.660 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-11-26T15:42:44.664Z,1574782964.664 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-11-26T15:42:45.077Z,1574782965.077 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-11-26T15:42:45.079Z,1574782965.079 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-11-26T15:42:45.175Z,1574782965.175 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-11-26T15:42:45.177Z,1574782965.177 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-11-26T15:42:45.482Z,1574782965.482 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-11-26T15:42:45.483Z,1574782965.483 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-11-26T15:42:45.622Z,1574782965.622 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-11-26T15:42:45.623Z,1574782965.623 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-11-26T15:42:45.808Z,1574782965.808 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-11-26T15:42:45.810Z,1574782965.810 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-11-26T15:42:46.247Z,1574782966.247 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-11-26T15:42:46.249Z,1574782966.249 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-11-26T15:42:46.450Z,1574782966.450 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-11-26T15:42:46.451Z,1574782966.451 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-11-26T15:42:46.592Z,1574782966.592 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-11-26T15:42:46.594Z,1574782966.594 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-11-26T15:42:46.777Z,1574782966.777 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-11-26T15:42:46.778Z,1574782966.778 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-11-26T15:42:46.872Z,1574782966.872 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-11-26T15:42:46.873Z,1574782966.873 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-11-26T15:42:47.165Z,1574782967.165 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-11-26T15:42:47.167Z,1574782967.167 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-11-26T15:42:47.247Z,1574782967.247 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-11-26T15:42:47.348Z,1574782967.348 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-11-26T15:42:47.349Z,1574782967.349 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-11-26T15:42:47.985Z,1574782967.985 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-11-26T15:42:47.986Z,1574782967.986 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-11-26T15:42:49.268Z,1574782969.268 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-11-26T15:42:49.270Z,1574782969.270 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-11-26T15:42:49.272Z,1574782969.272 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-11-26T15:42:49.472Z,1574782969.472 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-11-26T15:42:49.570Z,1574782969.570 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-11-26T15:42:49.666Z,1574782969.666 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-11-26T15:42:49.891Z,1574782969.891 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-11-26T15:42:49.893Z,1574782969.893 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-11-26T15:42:49.977Z,1574782969.977 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-11-26T15:42:50.070Z,1574782970.070 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-11-26T15:42:50.165Z,1574782970.165 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-11-26T15:42:50.247Z,1574782970.247 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-11-26T15:42:50.353Z,1574782970.353 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-11-26T15:42:50.530Z,1574782970.530 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-11-26T15:42:50.656Z,1574782970.656 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2019-11-26T15:42:50.661Z,1574782970.661 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-11-26T15:42:51.184Z,1574782971.184 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_orientation
2019-11-26T15:42:51.189Z,1574782971.189 [AHRS_M2](INFO): created writer for : platform_orientation
2019-11-26T15:42:51.191Z,1574782971.191 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_magnetic_orientation
2019-11-26T15:42:51.196Z,1574782971.196 [AHRS_M2](INFO): created writer for : platform_magnetic_orientation
2019-11-26T15:42:51.197Z,1574782971.197 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_pitch_angle
2019-11-26T15:42:51.202Z,1574782971.202 [AHRS_M2](INFO): created writer for : platform_pitch_angle
2019-11-26T15:42:51.202Z,1574782971.202 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_roll_angle
2019-11-26T15:42:51.208Z,1574782971.208 [AHRS_M2](INFO): created writer for : platform_roll_angle
2019-11-26T15:42:51.383Z,1574782971.383 [AHRS_M2] Loaded
2019-11-26T15:42:51.383Z,1574782971.383 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-11-26T15:42:51.529Z,1574782971.529 [DataOverHttps] Loaded
2019-11-26T15:42:51.529Z,1574782971.529 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-11-26T15:42:51.530Z,1574782971.530 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4076A4E0
2019-11-26T15:42:51.531Z,1574782971.531 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 888
2019-11-26T15:42:51.555Z,1574782971.555 [DDM] Loaded
2019-11-26T15:42:51.555Z,1574782971.555 [ComponentRegistry](DEBUG): SyncComponent "DDM" handled in the control thread.
2019-11-26T15:42:51.568Z,1574782971.568 [Depth_Keller] Loaded
2019-11-26T15:42:51.568Z,1574782971.568 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-11-26T15:42:51.573Z,1574782971.573 [DropWeight] Loaded
2019-11-26T15:42:51.573Z,1574782971.573 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-11-26T15:42:51.634Z,1574782971.634 [DUSBL_Hydroid] Loaded
2019-11-26T15:42:51.634Z,1574782971.634 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-11-26T15:42:51.680Z,1574782971.680 [Micromodem] Loaded
2019-11-26T15:42:51.681Z,1574782971.681 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-11-26T15:42:51.776Z,1574782971.776 [NAL9602] Loaded
2019-11-26T15:42:51.776Z,1574782971.776 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-11-26T15:42:51.792Z,1574782971.792 [Onboard] Loaded
2019-11-26T15:42:51.792Z,1574782971.792 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-11-26T15:42:51.798Z,1574782971.798 [PowerOnly] Loaded
2019-11-26T15:42:51.798Z,1574782971.798 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-11-26T15:42:51.804Z,1574782971.804 [Radio_Surface] Loaded
2019-11-26T15:42:51.805Z,1574782971.805 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-11-26T15:42:51.806Z,1574782971.806 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4079A4E0
2019-11-26T15:42:51.806Z,1574782971.806 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 889
2019-11-26T15:42:51.849Z,1574782971.849 [RDI_Pathfinder] Loaded
2019-11-26T15:42:51.849Z,1574782971.849 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-11-26T15:42:53.364Z,1574782973.364 [BPC1] Loaded
2019-11-26T15:42:53.365Z,1574782973.365 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-11-26T15:42:53.365Z,1574782973.365 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-11-26T15:42:53.366Z,1574782973.366 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-11-26T15:42:53.858Z,1574782973.858 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-11-26T15:42:53.860Z,1574782973.860 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-11-26T15:42:54.200Z,1574782974.200 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-11-26T15:42:54.201Z,1574782974.201 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-11-26T15:42:54.220Z,1574782974.220 [NavChart] Loaded
2019-11-26T15:42:54.221Z,1574782974.221 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-11-26T15:42:54.225Z,1574782974.225 [UniversalFixResidualReporter] Loaded
2019-11-26T15:42:54.225Z,1574782974.225 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-11-26T15:42:54.225Z,1574782974.225 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-11-26T15:42:54.226Z,1574782974.226 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-11-26T15:42:54.355Z,1574782974.355 [BuoyancyServo] Loaded
2019-11-26T15:42:54.356Z,1574782974.356 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-11-26T15:42:54.371Z,1574782974.371 [ElevatorServo] Loaded
2019-11-26T15:42:54.371Z,1574782974.371 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-11-26T15:42:54.386Z,1574782974.386 [MassServo] Loaded
2019-11-26T15:42:54.386Z,1574782974.386 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-11-26T15:42:54.401Z,1574782974.401 [RudderServo] Loaded
2019-11-26T15:42:54.401Z,1574782974.401 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-11-26T15:42:54.415Z,1574782974.415 [ThrusterServo] Loaded
2019-11-26T15:42:54.415Z,1574782974.415 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-11-26T15:42:54.416Z,1574782974.416 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-11-26T15:42:54.418Z,1574782974.418 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-11-26T15:42:54.750Z,1574782974.750 [CTD_NeilBrown] Loaded
2019-11-26T15:42:54.751Z,1574782974.751 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-11-26T15:42:54.752Z,1574782974.752 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408E54E0
2019-11-26T15:42:54.752Z,1574782974.752 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 891
2019-11-26T15:42:54.767Z,1574782974.767 [PAR_Licor] Loaded
2019-11-26T15:42:54.767Z,1574782974.767 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2019-11-26T15:42:54.810Z,1574782974.810 [WetLabsSeaOWL_UV_A] Loaded
2019-11-26T15:42:54.810Z,1574782974.810 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-11-26T15:42:54.811Z,1574782974.811 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409154E0
2019-11-26T15:42:54.812Z,1574782974.812 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 892
2019-11-26T15:42:54.812Z,1574782974.812 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-11-26T15:42:54.813Z,1574782974.813 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-11-26T15:42:55.170Z,1574782975.170 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-11-26T15:42:55.170Z,1574782975.170 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-11-26T15:42:55.225Z,1574782975.225 [DepthRateCalculator] Loaded
2019-11-26T15:42:55.225Z,1574782975.225 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-11-26T15:42:55.230Z,1574782975.230 [PitchRateCalculator] Loaded
2019-11-26T15:42:55.231Z,1574782975.231 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-11-26T15:42:55.243Z,1574782975.243 [SpeedCalculator] Loaded
2019-11-26T15:42:55.243Z,1574782975.243 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-11-26T15:42:55.263Z,1574782975.263 [TempGradientCalculator] Loaded
2019-11-26T15:42:55.263Z,1574782975.263 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-11-26T15:42:55.269Z,1574782975.269 [YawRateCalculator] Loaded
2019-11-26T15:42:55.269Z,1574782975.269 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-11-26T15:42:55.308Z,1574782975.308 [ElevatorOffsetCalculator] Loaded
2019-11-26T15:42:55.308Z,1574782975.308 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-11-26T15:42:55.309Z,1574782975.309 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-11-26T15:42:55.309Z,1574782975.309 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-11-26T15:42:55.469Z,1574782975.469 [SBIT](DEBUG): Construct Startup Built In Test.
2019-11-26T15:42:55.491Z,1574782975.491 [SBIT] Loaded
2019-11-26T15:42:55.491Z,1574782975.491 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-11-26T15:42:55.492Z,1574782975.492 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-11-26T15:42:55.504Z,1574782975.504 [IBIT] Loaded
2019-11-26T15:42:55.504Z,1574782975.504 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-11-26T15:42:55.507Z,1574782975.507 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-11-26T15:42:55.642Z,1574782975.642 [CBIT] Loaded
2019-11-26T15:42:55.642Z,1574782975.642 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-11-26T15:42:55.643Z,1574782975.643 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-11-26T15:42:55.645Z,1574782975.645 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-11-26T15:42:55.767Z,1574782975.767 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-11-26T15:42:55.768Z,1574782975.768 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-11-26T15:42:55.894Z,1574782975.894 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-11-26T15:42:55.895Z,1574782975.895 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-11-26T15:42:55.958Z,1574782975.958 [VerticalControl](DEBUG): Construct VerticalControl.
2019-11-26T15:42:56.039Z,1574782976.039 [VerticalControl] Loaded
2019-11-26T15:42:56.039Z,1574782976.039 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-11-26T15:42:56.040Z,1574782976.040 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-11-26T15:42:56.108Z,1574782976.108 [HorizontalControl] Loaded
2019-11-26T15:42:56.108Z,1574782976.108 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-11-26T15:42:56.109Z,1574782976.109 [SpeedControl](DEBUG): Construct SpeedControl.
2019-11-26T15:42:56.111Z,1574782976.111 [SpeedControl] Loaded
2019-11-26T15:42:56.111Z,1574782976.111 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-11-26T15:42:56.112Z,1574782976.112 [LoopControl](DEBUG): Construct LoopControl.
2019-11-26T15:42:56.112Z,1574782976.112 [LoopControl] Loaded
2019-11-26T15:42:56.112Z,1574782976.112 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-11-26T15:42:56.113Z,1574782976.113 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-11-26T15:42:56.114Z,1574782976.114 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-11-26T15:42:56.162Z,1574782976.162 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-11-26T15:42:56.166Z,1574782976.166 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-11-26T15:42:56.167Z,1574782976.167 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-11-26T15:42:56.173Z,1574782976.173 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-11-26T15:42:56.174Z,1574782976.174 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AF44E0
2019-11-26T15:42:56.175Z,1574782976.175 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 893
2019-11-26T15:42:56.179Z,1574782976.179 [Supervisor](INFO): Main Thread ID is 802
2019-11-26T15:42:56.179Z,1574782976.179 [Supervisor](DEBUG): Running supervisor.
2019-11-26T15:42:56.180Z,1574782976.180 [CommandLine ThreadHandler](INFO): Handler Thread ID is 894
2019-11-26T15:42:56.182Z,1574782976.182 [controlThread ThreadHandler](INFO): Handler Thread ID is 895
2019-11-26T15:42:56.182Z,1574782976.182 [controlThread](DEBUG): Initializing ControlThread
2019-11-26T15:42:56.188Z,1574782976.188 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-11-26T15:42:56.188Z,1574782976.188 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-11-26T15:42:56.193Z,1574782976.193 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-11-26T15:42:56.193Z,1574782976.193 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-11-26T15:42:56.194Z,1574782976.194 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-11-26T15:42:56.194Z,1574782976.194 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-11-26T15:42:56.195Z,1574782976.195 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-11-26T15:42:56.195Z,1574782976.195 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-11-26T15:42:56.196Z,1574782976.196 [SBIT](INFO): Initialize SBIT Component.
2019-11-26T15:42:56.196Z,1574782976.196 [SBIT](IMPORTANT): git: 2019-11-25
2019-11-26T15:42:56.196Z,1574782976.196 [SBIT](INFO): git hash: 613c3b988797d140e74aeade4f971920e69097b8
2019-11-26T15:42:56.197Z,1574782976.197 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-11-26T15:42:56.198Z,1574782976.198 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #2 PREEMPT Wed May 15 08:34:03 PDT 2019
2019-11-26T15:42:56.199Z,1574782976.199 [SBIT](INFO): Beginning SBIT in 28.000000 seconds.
2019-11-26T15:42:56.200Z,1574782976.200 [IBIT](INFO): Initialize IBIT Component.
2019-11-26T15:42:56.201Z,1574782976.201 [CBIT](DEBUG): Initialize CBIT Component.
2019-11-26T15:42:56.201Z,1574782976.201 [logger ThreadHandler](INFO): Handler Thread ID is 896
2019-11-26T15:42:56.213Z,1574782976.213 [CBIT](DEBUG): Initialized mux pins.
2019-11-26T15:42:56.213Z,1574782976.213 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2019-11-26T15:42:56.213Z,1574782976.213 [CBIT](DEBUG): Initializing the watchdog timer.
2019-11-26T15:42:56.221Z,1574782976.221 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 897
2019-11-26T15:42:56.222Z,1574782976.222 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-11-26T15:42:56.233Z,1574782976.233 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 898
2019-11-26T15:42:56.237Z,1574782976.237 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-11-26T15:42:56.237Z,1574782976.237 [CBIT](DEBUG): Initializing heartbeat.
2019-11-26T15:42:56.245Z,1574782976.245 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 899
2019-11-26T15:42:56.246Z,1574782976.246 [CTD_NeilBrown](INFO): Powering down
2019-11-26T15:42:56.274Z,1574782976.274 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 900
2019-11-26T15:42:56.274Z,1574782976.274 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-11-26T15:42:56.301Z,1574782976.301 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 901
2019-11-26T15:42:56.309Z,1574782976.309 [CBIT](DEBUG): Deactivating GF circuits.
2019-11-26T15:42:56.309Z,1574782976.309 [CBIT](DEBUG): Deactivating emergency mode.
2019-11-26T15:42:56.310Z,1574782976.310 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-11-26T15:42:56.311Z,1574782976.311 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-11-26T15:42:56.311Z,1574782976.311 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-11-26T15:42:56.311Z,1574782976.311 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-11-26T15:42:56.311Z,1574782976.311 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-11-26T15:42:56.311Z,1574782976.311 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-11-26T15:42:56.311Z,1574782976.311 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-11-26T15:42:56.312Z,1574782976.312 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-11-26T15:42:56.312Z,1574782976.312 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-11-26T15:42:56.312Z,1574782976.312 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-11-26T15:42:56.312Z,1574782976.312 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-11-26T15:42:56.312Z,1574782976.312 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-11-26T15:42:56.313Z,1574782976.313 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-11-26T15:42:56.313Z,1574782976.313 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-11-26T15:42:56.313Z,1574782976.313 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-11-26T15:42:56.313Z,1574782976.313 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-11-26T15:42:56.345Z,1574782976.345 [CBIT](DEBUG): Backplane powered.
2019-11-26T15:42:56.345Z,1574782976.345 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-11-26T15:42:56.347Z,1574782976.347 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-11-26T15:42:56.347Z,1574782976.347 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-11-26T15:42:56.348Z,1574782976.348 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-11-26T15:42:56.349Z,1574782976.349 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-11-26T15:42:56.373Z,1574782976.373 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-11-26T15:42:56.388Z,1574782976.388 [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-11-26T15:42:56.409Z,1574782976.409 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-11-26T15:42:56.456Z,1574782976.456 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-11-26T15:42:56.473Z,1574782976.473 [Default:A.Wait](DEBUG): Construct Wait.
2019-11-26T15:42:56.489Z,1574782976.489 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-11-26T15:42:56.507Z,1574782976.507 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-11-26T15:42:56.518Z,1574782976.518 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-11-26T15:42:56.524Z,1574782976.524 [Default:E.Execute](DEBUG): Construct Execute.
2019-11-26T15:42:56.544Z,1574782976.544 [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-11-26T15:42:56.549Z,1574782976.549 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,DDM,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,BPC1,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-11-26T15:42:56.561Z,1574782976.561 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-11-26T15:42:56.637Z,1574782976.637 [Radio_Surface](INFO): Powering up
2019-11-26T15:42:56.649Z,1574782976.649 [DDM](INFO): Powering up
2019-11-26T15:42:56.649Z,1574782976.649 [DDM](DEBUG): Initializing DDM.
2019-11-26T15:42:56.716Z,1574782976.716 [DUSBL_Hydroid](INFO): Powering up
2019-11-26T15:42:56.716Z,1574782976.716 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-11-26T15:42:56.909Z,1574782976.909 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-11-26T15:42:56.917Z,1574782976.917 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-11-26T15:42:56.918Z,1574782976.918 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-11-26T15:42:56.925Z,1574782976.925 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-11-26T15:42:56.926Z,1574782976.926 [MassServo](DEBUG): Initializing EZServoServo.
2019-11-26T15:42:56.933Z,1574782976.933 [MassServo](DEBUG): Initializing MassServo.
2019-11-26T15:42:56.934Z,1574782976.934 [RudderServo](DEBUG): Initializing EZServoServo.
2019-11-26T15:42:56.941Z,1574782976.941 [RudderServo](DEBUG): Initializing RudderServo.
2019-11-26T15:42:56.942Z,1574782976.942 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-11-26T15:42:56.950Z,1574782976.950 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-11-26T15:42:57.042Z,1574782977.042 [Micromodem](INFO): Powering up
2019-11-26T15:42:57.042Z,1574782977.042 [Micromodem](DEBUG): Initializing Micromodem.
2019-11-26T15:43:01.853Z,1574782981.853 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33

2019-11-26T15:43:02.256Z,1574782982.256 [Micromodem](INFO): Nmea in: $CATMG,2019-11-26T15:42:56.995023Z,RTC,RTC*5B

2019-11-26T15:43:02.256Z,1574782982.256 [Micromodem](ERROR): CFG response from modem unexpected: $CATMG,2019-11-26T15:42:56.995023Z,RTC,RTC*5B

2019-11-26T15:43:02.663Z,1574782982.663 [Micromodem](INFO): Nmea in: $CACFG,ALL,0*31

2019-11-26T15:43:02.663Z,1574782982.663 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31

2019-11-26T15:43:03.067Z,1574782983.067 [Micromodem](INFO): Nmea in: $CACFG,SRC,1*33

2019-11-26T15:43:03.067Z,1574782983.067 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-11-26T15:43:03.471Z,1574782983.471 [Micromodem](INFO): Nmea in: $CACFG,nav.dt.txtrig_gpio4,1*66

2019-11-26T15:43:03.471Z,1574782983.471 [Micromodem](INFO): Nmea out: $CCCFG,pwramp.txlevel,0*2F

2019-11-26T15:43:03.875Z,1574782983.875 [Micromodem](INFO): Nmea in: $CACFG,pwramp.txlevel,0*2D

2019-11-26T15:43:03.875Z,1574782983.875 [Micromodem](INFO): Nmea out: $CCCFG,DTO,30*1E

2019-11-26T15:43:04.283Z,1574782984.283 [Micromodem](INFO): Nmea in: $CACFG,DTO,30*1C

2019-11-26T15:43:04.283Z,1574782984.283 [Micromodem](INFO): Nmea out: $CCCFG,FC0,10000*46

2019-11-26T15:43:04.671Z,1574782984.671 [Micromodem](INFO): Nmea in: $CACFG,FC0,10000*44

2019-11-26T15:43:04.671Z,1574782984.671 [Micromodem](INFO): Nmea out: $CCCFG,BW0,4000*63

2019-11-26T15:43:05.499Z,1574782985.499 [Micromodem](INFO): Nmea in: $CACFG,BW0,4000*61

2019-11-26T15:43:05.500Z,1574782985.500 [Micromodem](INFO): Nmea out: $CCCFG,BND,0*3A

2019-11-26T15:43:05.680Z,1574782985.680 [Micromodem](INFO): Nmea in: $CACFG,BND,0*38

2019-11-26T15:43:05.687Z,1574782985.687 [Micromodem](INFO): Nmea out: $CCCLK,2019,11,26,15,43,06*4F

2019-11-26T15:43:06.031Z,1574782986.031 [Micromodem](INFO): Nmea in: $CACLK,2019,11,26,15,43,6*7D

2019-11-26T15:43:06.435Z,1574782986.435 [Micromodem](INFO): Nmea in: $CATMS,0,2019-11-26T15:43:07Z*7C

2019-11-26T15:43:06.436Z,1574782986.436 [Micromodem](INFO): Nmea in: $CATMG,2019-11-26T15:43:07.027354Z,USER_CMD,RTC*1C

2019-11-26T15:43:07.237Z,1574782987.237 [DDM](INFO): Dynamic Docking Module:
2019-11-26T15:43:10.096Z,1574782990.096 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-11-26T15:43:14.514Z,1574782994.514 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-11-26T15:43:21.795Z,1574783001.796 [NAL9602](INFO): Powering up NAL9602
2019-11-26T15:43:24.675Z,1574783004.675 [SBIT](IMPORTANT): Beginning Startup BIT
2019-11-26T15:43:24.683Z,1574783004.683 [CBIT](IMPORTANT): Beginning ground fault scan
2019-11-26T15:43:32.807Z,1574783012.807 [NAL9602](INFO): NAL9602 initialized
2019-11-26T15:43:35.755Z,1574783015.755 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.018538
CHAN A1 (24V): -0.024105
CHAN A2 (12V): -0.005405
CHAN A3 (5V): -0.001813
CHAN B0 (3.3V): 0.000149
CHAN B1 (3.15aV): 0.000263
CHAN B2 (3.15bV): -0.000048
CHAN B3 (GND): 0.002057
OPEN: 0.005910
Full Scale Calc: 4.765 mA, -1.589 mA
2019-11-26T15:43:54.797Z,1574783034.797 [NAL9602](INFO): SBD MO Status=0, MOMSN=10036, MT Status=0, MTMSN=0
2019-11-26T15:43:54.797Z,1574783034.797 [NAL9602](INFO): No messages in MT queue
2019-11-26T15:44:18.415Z,1574783058.415 [SBIT](IMPORTANT): SBIT PASSED
2019-11-26T15:44:18.505Z,1574783058.505 [CommandLine](IMPORTANT): got command configSet list
2019-11-26T15:44:18.505Z,1574783058.505 [CommandLine](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2019-11-26T15:44:18.746Z,1574783058.746 [MissionManager](IMPORTANT): Started mission Startup
2019-11-26T15:44:18.746Z,1574783058.746 [Startup] Running Loop=1
2019-11-26T15:44:18.746Z,1574783058.746 [Startup](DEBUG): Aggregate::initialize Startup
2019-11-26T15:44:18.746Z,1574783058.746 [Startup:A.GoToSurface] Running Loop=1
2019-11-26T15:44:18.746Z,1574783058.746 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-11-26T15:44:18.747Z,1574783058.747 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-11-26T15:44:18.747Z,1574783058.747 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-11-26T15:44:18.747Z,1574783058.747 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-11-26T15:44:18.748Z,1574783058.748 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-11-26T15:44:18.748Z,1574783058.748 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-11-26T15:44:18.750Z,1574783058.750 [Startup:StartupSatComms] Running Loop=1
2019-11-26T15:44:18.750Z,1574783058.750 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-11-26T15:44:18.750Z,1574783058.750 [Startup:StartupSatComms:A] Running Loop=1
2019-11-26T15:44:19.170Z,1574783059.170 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-11-26T15:45:10.833Z,1574783110.833 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,154502.00,A,3648.75379,N,12149.77202,W,1.089,339.56,261119,,,A*74
2019-11-26T15:45:10.836Z,1574783110.836 [NAL9602](INFO): GPS fix at 20191126T154502: (36.812563, -121.829534)
2019-11-26T15:45:10.918Z,1574783110.918 [Startup:StartupSatComms:A] Stopped
2019-11-26T15:45:10.918Z,1574783110.918 [Startup:StartupSatComms:B] Running Loop=1
2019-11-26T15:45:11.348Z,1574783111.348 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-11-26T15:45:43.160Z,1574783143.160 [NAL9602](INFO): Not Powering down - fast GPS
2019-11-26T15:46:11.081Z,1574783171.081 [Startup:StartupSatComms:B](INFO): Timed out from 2019-11-26T15:45:10.9Z
2019-11-26T15:46:11.081Z,1574783171.081 [Startup:StartupSatComms:B] Stopped
2019-11-26T15:46:11.081Z,1574783171.081 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-11-26T15:46:11.081Z,1574783171.081 [Startup:StartupSatComms] Stopped
2019-11-26T15:46:11.081Z,1574783171.081 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-11-26T15:46:11.082Z,1574783171.082 [Startup](INFO): Completed Startup
2019-11-26T15:46:11.082Z,1574783171.082 [MissionManager](INFO): Startup is completed.
2019-11-26T15:46:11.082Z,1574783171.082 [MissionManager](INFO): Uninitializing Mission Startup
2019-11-26T15:46:11.082Z,1574783171.082 [Startup] Stopped
2019-11-26T15:46:11.082Z,1574783171.082 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-11-26T15:46:11.083Z,1574783171.083 [Startup:A.GoToSurface] Stopped
2019-11-26T15:46:11.083Z,1574783171.083 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-11-26T15:46:11.473Z,1574783171.473 [MissionManager](IMPORTANT): Started mission Default
2019-11-26T15:46:11.473Z,1574783171.473 [Default] Running Loop=1
2019-11-26T15:46:11.473Z,1574783171.473 [Default](DEBUG): Aggregate::initialize Default
2019-11-26T15:46:11.473Z,1574783171.473 [Default:B.GoToSurface] Running Loop=1
2019-11-26T15:46:11.473Z,1574783171.473 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-11-26T15:46:11.474Z,1574783171.474 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-11-26T15:46:11.474Z,1574783171.474 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-11-26T15:46:11.474Z,1574783171.474 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-11-26T15:46:11.474Z,1574783171.474 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-11-26T15:46:11.475Z,1574783171.475 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-11-26T15:46:11.475Z,1574783171.475 [Default:A.Wait] Running Loop=1
2019-11-26T15:46:11.475Z,1574783171.475 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-11-26T15:46:24.795Z,1574783184.795 [Default:A.Wait](INFO): Done Waiting.
2019-11-26T15:46:24.795Z,1574783184.795 [Default:A.Wait] Stopped
2019-11-26T15:46:24.795Z,1574783184.795 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-11-26T15:46:25.232Z,1574783185.232 [Default:CheckIn] Running Loop=1
2019-11-26T15:46:25.232Z,1574783185.232 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-11-26T15:46:25.232Z,1574783185.232 [Default:CheckIn:Read_GPS] Running Loop=1
2019-11-26T15:46:25.622Z,1574783185.622 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-11-26T15:46:27.188Z,1574783187.188 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,154618.00,A,3648.76209,N,12149.77764,W,0.894,290.62,261119,,,A*7C
2019-11-26T15:46:27.191Z,1574783187.191 [NAL9602](INFO): GPS fix at 20191126T154618: (36.812702, -121.829627)
2019-11-26T15:46:27.364Z,1574783187.364 [Default:CheckIn:Read_GPS] Stopped
2019-11-26T15:46:27.364Z,1574783187.364 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-11-26T15:46:27.665Z,1574783187.665 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-11-26T15:46:32.499Z,1574783192.499 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004655
2019-11-26T15:46:40.162Z,1574783200.162 [DataOverHttps](INFO): Sending 91 bytes from file Logs/20191126T061554/Courier0066.lzma
2019-11-26T15:46:42.167Z,1574783202.167 [DataOverHttps](INFO): Moved sent file to Logs/20191126T061554/Courier0066.lzma.bak
2019-11-26T15:46:42.167Z,1574783202.167 [DataOverHttps](INFO): SBD MOMSN=12106959
2019-11-26T15:46:45.460Z,1574783205.460 [NAL9602](INFO): SBD MO Status=0, MOMSN=10037, MT Status=0, MTMSN=0
2019-11-26T15:46:45.460Z,1574783205.460 [NAL9602](INFO): No messages in MT queue
2019-11-26T15:47:02.868Z,1574783222.868 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20191126T154244/Courier0000.lzma
2019-11-26T15:47:04.874Z,1574783224.874 [DataOverHttps](INFO): Moved sent file to Logs/20191126T154244/Courier0000.lzma.bak
2019-11-26T15:47:04.874Z,1574783224.874 [DataOverHttps](INFO): SBD MOMSN=12107055
2019-11-26T15:47:14.995Z,1574783234.995 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-11-26T15:47:14.996Z,1574783234.996 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-3768,-32768,V
2019-11-26T15:47:16.159Z,1574783236.159 [NAL9602](INFO): Not Powering down - fast GPS
2019-11-26T15:47:24.720Z,1574783244.720 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20191126T154244/Courier0004.lzma
2019-11-26T15:47:28.734Z,1574783248.734 [DataOverHttps](INFO): Moved sent file to Logs/20191126T154244/Courier0004.lzma.bak
2019-11-26T15:47:28.734Z,1574783248.734 [DataOverHttps](INFO): SBD MOMSN=12107059
2019-11-26T15:47:46.336Z,1574783266.336 [DataOverHttps](INFO): Sending 5624 bytes from file Logs/20191126T061554/Express0067.lzma
2019-11-26T15:47:49.335Z,1574783269.335 [DataOverHttps](INFO): Moved sent file to Logs/20191126T061554/Express0067.lzma.bak
2019-11-26T15:47:49.335Z,1574783269.335 [DataOverHttps](INFO): SBD MOMSN=12107062
2019-11-26T15:48:09.992Z,1574783289.992 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20191126T150906/Express0001.lzma
2019-11-26T15:48:11.998Z,1574783291.998 [DataOverHttps](INFO): Moved sent file to Logs/20191126T150906/Express0001.lzma.bak
2019-11-26T15:48:11.999Z,1574783291.999 [DataOverHttps](INFO): SBD MOMSN=12107069
2019-11-26T15:48:12.323Z,1574783292.323 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00,   0.00
2019-11-26T15:48:29.327Z,1574783309.327 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,-32768,-32768,-32768,V
2019-11-26T15:48:31.738Z,1574783311.738 [DataOverHttps](INFO): Sending 679 bytes from file Logs/20191126T154244/Express0001.lzma
2019-11-26T15:48:33.339Z,1574783313.339 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-11-26T15:48:33.339Z,1574783313.339 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,191126095.0, -0.1,   0.0,1448.9,  0
2019-11-26T15:48:33.742Z,1574783313.742 [DataOverHttps](INFO): Moved sent file to Logs/20191126T154244/Express0001.lzma.bak
2019-11-26T15:48:33.742Z,1574783313.742 [DataOverHttps](INFO): SBD MOMSN=12107073
2019-11-26T15:48:58.216Z,1574783338.216 [DataOverHttps](INFO): Sending 94 bytes from file Logs/20191126T154244/Express0005.lzma
2019-11-26T15:49:00.222Z,1574783340.222 [DataOverHttps](INFO): Moved sent file to Logs/20191126T154244/Express0005.lzma.bak
2019-11-26T15:49:00.222Z,1574783340.222 [DataOverHttps](INFO): SBD MOMSN=12107087
2019-11-26T15:49:02.425Z,1574783342.425 [Default:CheckIn:Read_Iridium] Stopped
2019-11-26T15:49:02.425Z,1574783342.425 [Default:CheckIn:C.Wait] Running Loop=1
2019-11-26T15:49:02.425Z,1574783342.425 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-11-26T15:49:34.334Z,1574783374.334 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-11-26T15:49:34.334Z,1574783374.334 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-11-26T15:49:55.762Z,1574783395.762 [DataOverHttps](IMPORTANT): SBD MTMSN=20191126T154947
2019-11-26T15:50:03.549Z,1574783403.549 [DataOverHttps](INFO): Received command:Restart app
2019-11-26T15:50:03.557Z,1574783403.557 [CommandLine](IMPORTANT): got command restart application
2019-11-26T15:50:04.561Z,1574783404.561 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2019-11-26T15:50:04.561Z,1574783404.561 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-11-26T15:50:04.561Z,1574783404.561 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-11-26T15:50:04.721Z,1574783404.721 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-11-26T15:50:04.721Z,1574783404.721 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-11-26T15:50:04.722Z,1574783404.722 [CommandLine](INFO): Join timeout helper Thread ID is 941
2019-11-26T15:50:04.728Z,1574783404.728 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-11-26T15:50:04.728Z,1574783404.728 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-11-26T15:50:04.728Z,1574783404.728 [NavChartDb](INFO): Join timeout helper Thread ID is 942
2019-11-26T15:50:04.962Z,1574783404.962 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-11-26T15:50:04.963Z,1574783404.963 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-11-26T15:50:04.985Z,1574783404.985 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-11-26T15:50:04.985Z,1574783404.985 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-11-26T15:50:04.985Z,1574783404.985 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 943
2019-11-26T15:50:05.113Z,1574783405.113 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-11-26T15:50:05.113Z,1574783405.113 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-11-26T15:50:05.114Z,1574783405.114 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-11-26T15:50:05.125Z,1574783405.125 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-11-26T15:50:05.125Z,1574783405.125 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-11-26T15:50:05.125Z,1574783405.125 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 944
2019-11-26T15:50:05.306Z,1574783405.306 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-11-26T15:50:05.306Z,1574783405.306 [CTD_NeilBrown](INFO): Powering down
2019-11-26T15:50:05.321Z,1574783405.321 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-11-26T15:50:05.325Z,1574783405.325 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-11-26T15:50:05.325Z,1574783405.325 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-11-26T15:50:05.325Z,1574783405.325 [Radio_Surface](INFO): Join timeout helper Thread ID is 945
2019-11-26T15:50:05.341Z,1574783405.341 [Radio_Surface](INFO): Powering down
2019-11-26T15:50:05.342Z,1574783405.342 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-11-26T15:50:05.342Z,1574783405.342 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-11-26T15:50:05.346Z,1574783405.346 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-11-26T15:50:05.346Z,1574783405.346 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-11-26T15:50:05.346Z,1574783405.346 [DataOverHttps](INFO): Join timeout helper Thread ID is 946
2019-11-26T15:50:05.553Z,1574783405.553 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-11-26T15:50:05.556Z,1574783405.556 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-11-26T15:50:05.558Z,1574783405.558 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-11-26T15:50:05.558Z,1574783405.558 [logger ThreadHandler](INFO): Thread cancelled.
2019-11-26T15:50:05.558Z,1574783405.558 [logger](INFO): Join timeout helper Thread ID is 947
2019-11-26T15:50:05.569Z,1574783405.569 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-11-26T15:50:05.569Z,1574783405.569 [logger ThreadHandler](INFO): Thread cancelled.
2019-11-26T15:50:05.578Z,1574783405.578 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-11-26T15:50:05.578Z,1574783405.578 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-11-26T15:50:05.578Z,1574783405.578 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-11-26T15:50:05.578Z,1574783405.578 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-11-26T15:50:05.578Z,1574783405.578 [controlThread](INFO): Join timeout helper Thread ID is 948
2019-11-26T15:50:05.817Z,1574783405.817 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-11-26T15:50:05.817Z,1574783405.817 [controlThread](DEBUG): Uninitializing ControlThread
2019-11-26T15:50:05.818Z,1574783405.818 [AHRS_M2](INFO): Powering down
2019-11-26T15:50:05.889Z,1574783405.889 [DDM](INFO): Powering down
2019-11-26T15:50:05.995Z,1574783405.995 [DUSBL_Hydroid](INFO): Powering down
2019-11-26T15:50:06.113Z,1574783406.113 [Micromodem](INFO): Powering down
2019-11-26T15:50:06.209Z,1574783406.209 [NAL9602](INFO): Powering down
2019-11-26T15:50:06.289Z,1574783406.289 [RDI_Pathfinder](INFO): Powering down
2019-11-26T15:50:06.291Z,1574783406.291 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-11-26T15:50:06.292Z,1574783406.292 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-11-26T15:50:06.292Z,1574783406.292 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-11-26T15:50:06.293Z,1574783406.293 [MissionManager](INFO): Uninitializing Mission Default
2019-11-26T15:50:06.293Z,1574783406.293 [Default] Stopped
2019-11-26T15:50:06.293Z,1574783406.293 [Default](DEBUG): Aggregate::uninitialize Default
2019-11-26T15:50:06.293Z,1574783406.293 [Default:B.GoToSurface] Stopped
2019-11-26T15:50:06.293Z,1574783406.293 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-11-26T15:50:06.293Z,1574783406.293 [Default:CheckIn] Stopped
2019-11-26T15:50:06.293Z,1574783406.293 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-11-26T15:50:06.293Z,1574783406.293 [Default:CheckIn:C.Wait] Stopped
2019-11-26T15:50:06.293Z,1574783406.293 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-11-26T15:50:06.296Z,1574783406.296 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-11-26T15:50:06.296Z,1574783406.296 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-11-26T15:50:06.296Z,1574783406.296 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-11-26T15:50:06.296Z,1574783406.296 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-11-26T15:50:06.297Z,1574783406.297 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-11-26T15:50:06.297Z,1574783406.297 [BuoyancyServo](INFO): Powering down
2019-11-26T15:50:06.309Z,1574783406.309 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-11-26T15:50:06.309Z,1574783406.309 [ElevatorServo](INFO): Powering down
2019-11-26T15:50:06.310Z,1574783406.310 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-11-26T15:50:06.310Z,1574783406.310 [MassServo](INFO): Powering down
2019-11-26T15:50:06.311Z,1574783406.311 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-11-26T15:50:06.311Z,1574783406.311 [RudderServo](INFO): Powering down
2019-11-26T15:50:06.311Z,1574783406.311 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-11-26T15:50:06.312Z,1574783406.312 [ThrusterServo](INFO): Powering down
2019-11-26T15:50:06.312Z,1574783406.312 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-11-26T15:50:06.313Z,1574783406.313 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-11-26T15:50:06.313Z,1574783406.313 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-11-26T15:50:06.313Z,1574783406.313 [CBIT](DEBUG): Powering off loads.
2019-11-26T15:50:06.325Z,1574783406.325 [CBIT](DEBUG): Disabling WDT.
2019-11-26T15:50:06.337Z,1574783406.337 [CBIT](DEBUG): Opening all GF detection circuits.
2019-11-26T15:50:06.338Z,1574783406.338 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-11-26T15:50:06.380Z,1574783406.380 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-11-26T15:50:06.391Z,1574783406.391 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-11-26T15:50:06.433Z,1574783406.433 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-11-26T15:50:06.436Z,1574783406.436 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-11-26T15:50:06.495Z,1574783406.495 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-11-26T15:50:06.565Z,1574783406.565 [logger ThreadHandler](INFO): Thread cancelled.