2020-12-10T21:58:56.081Z,1607637536.081 [Supervisor](DEBUG): Initializing supervisor.
2020-12-10T21:58:56.085Z,1607637536.085 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2020-12-10T21:58:56.086Z,1607637536.086 [SyncHandler](INFO): Protected caller Thread ID is 826
2020-12-10T21:58:56.086Z,1607637536.086 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2020-12-10T21:58:56.087Z,1607637536.087 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2020-12-10T21:58:56.088Z,1607637536.088 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 827
2020-12-10T21:58:56.092Z,1607637536.092 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2020-12-10T21:58:56.112Z,1607637536.112 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2020-12-10T21:58:56.113Z,1607637536.113 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2020-12-10T21:58:56.113Z,1607637536.113 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 828
2020-12-10T21:58:56.115Z,1607637536.115 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2020-12-10T21:58:56.116Z,1607637536.116 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2020-12-10T21:58:56.117Z,1607637536.117 [logger ThreadHandler](INFO): Protected caller Thread ID is 829
2020-12-10T21:58:56.121Z,1607637536.121 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2020-12-10T21:58:56.121Z,1607637536.121 [Supervisor](INFO): Looking for Config files in directory: Config/
2020-12-10T21:58:56.125Z,1607637536.125 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2020-12-10T21:58:56.524Z,1607637536.524 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2020-12-10T21:58:56.526Z,1607637536.526 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2020-12-10T21:58:56.606Z,1607637536.606 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2020-12-10T21:58:56.937Z,1607637536.937 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2020-12-10T21:58:56.939Z,1607637536.939 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2020-12-10T21:58:57.039Z,1607637537.039 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2020-12-10T21:58:57.041Z,1607637537.041 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2020-12-10T21:58:57.236Z,1607637537.236 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2020-12-10T21:58:57.238Z,1607637537.238 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2020-12-10T21:58:57.754Z,1607637537.754 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2020-12-10T21:58:57.755Z,1607637537.755 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2020-12-10T21:58:57.992Z,1607637537.992 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2020-12-10T21:58:57.994Z,1607637537.994 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2020-12-10T21:58:58.142Z,1607637538.142 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2020-12-10T21:58:58.143Z,1607637538.143 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2020-12-10T21:58:58.336Z,1607637538.336 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2020-12-10T21:58:58.338Z,1607637538.338 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2020-12-10T21:58:58.435Z,1607637538.435 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2020-12-10T21:58:58.436Z,1607637538.436 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2020-12-10T21:58:58.658Z,1607637538.658 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2020-12-10T21:58:58.658Z,1607637538.658 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2020-12-10T21:58:58.978Z,1607637538.978 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2020-12-10T21:58:58.980Z,1607637538.980 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2020-12-10T21:58:59.062Z,1607637539.062 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2020-12-10T21:58:59.189Z,1607637539.189 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2020-12-10T21:58:59.191Z,1607637539.191 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2020-12-10T21:58:59.860Z,1607637539.860 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2020-12-10T21:59:00.486Z,1607637540.486 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2020-12-10T21:59:00.937Z,1607637540.937 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2020-12-10T21:59:00.938Z,1607637540.938 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2020-12-10T21:59:00.941Z,1607637540.941 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2020-12-10T21:59:01.142Z,1607637541.142 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2020-12-10T21:59:01.243Z,1607637541.243 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2020-12-10T21:59:01.343Z,1607637541.343 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2020-12-10T21:59:01.602Z,1607637541.602 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2020-12-10T21:59:01.602Z,1607637541.602 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2020-12-10T21:59:01.689Z,1607637541.689 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2020-12-10T21:59:01.786Z,1607637541.786 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2020-12-10T21:59:01.900Z,1607637541.900 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2020-12-10T21:59:01.985Z,1607637541.985 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Dock.cfg
2020-12-10T21:59:02.072Z,1607637542.072 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2020-12-10T21:59:02.182Z,1607637542.182 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/workSite.cfg
2020-12-10T21:59:02.282Z,1607637542.282 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2020-12-10T21:59:02.473Z,1607637542.473 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2020-12-10T21:59:02.612Z,1607637542.612 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2020-12-10T21:59:02.629Z,1607637542.629 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2020-12-10T21:59:03.350Z,1607637543.350 [AHRS_M2] Loaded
2020-12-10T21:59:03.351Z,1607637543.351 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2020-12-10T21:59:04.089Z,1607637544.089 [BPC1] Loaded
2020-12-10T21:59:04.089Z,1607637544.089 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2020-12-10T21:59:04.228Z,1607637544.228 [DataOverHttps] Loaded
2020-12-10T21:59:04.229Z,1607637544.229 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2020-12-10T21:59:04.230Z,1607637544.230 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 407974E0
2020-12-10T21:59:04.230Z,1607637544.230 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 917
2020-12-10T21:59:04.252Z,1607637544.252 [DDM] Loaded
2020-12-10T21:59:04.252Z,1607637544.252 [ComponentRegistry](DEBUG): SyncComponent "DDM" handled in the control thread.
2020-12-10T21:59:04.270Z,1607637544.270 [Depth_Keller] Loaded
2020-12-10T21:59:04.271Z,1607637544.271 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2020-12-10T21:59:04.275Z,1607637544.275 [DropWeight] Loaded
2020-12-10T21:59:04.275Z,1607637544.275 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2020-12-10T21:59:04.318Z,1607637544.318 [DUSBL_Hydroid] Loaded
2020-12-10T21:59:04.318Z,1607637544.318 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2020-12-10T21:59:04.364Z,1607637544.364 [Micromodem] Loaded
2020-12-10T21:59:04.364Z,1607637544.364 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2020-12-10T21:59:04.421Z,1607637544.421 [NAL9602] Loaded
2020-12-10T21:59:04.421Z,1607637544.421 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2020-12-10T21:59:04.449Z,1607637544.449 [Onboard] Loaded
2020-12-10T21:59:04.449Z,1607637544.449 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2020-12-10T21:59:04.450Z,1607637544.450 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 407C74E0
2020-12-10T21:59:04.450Z,1607637544.450 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 918
2020-12-10T21:59:04.464Z,1607637544.464 [Radio_Surface] Loaded
2020-12-10T21:59:04.464Z,1607637544.464 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2020-12-10T21:59:04.465Z,1607637544.465 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 407F74E0
2020-12-10T21:59:04.466Z,1607637544.466 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 919
2020-12-10T21:59:04.495Z,1607637544.495 [RDI_Pathfinder] Loaded
2020-12-10T21:59:04.496Z,1607637544.496 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2020-12-10T21:59:04.521Z,1607637544.521 [RDI_PathfinderUp] Loaded
2020-12-10T21:59:04.521Z,1607637544.521 [ComponentRegistry](DEBUG): SyncComponent "RDI_PathfinderUp" handled in the control thread.
2020-12-10T21:59:04.522Z,1607637544.522 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2020-12-10T21:59:04.522Z,1607637544.522 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2020-12-10T21:59:04.539Z,1607637544.539 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2020-12-10T21:59:04.541Z,1607637544.541 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2020-12-10T21:59:04.668Z,1607637544.668 [DeadReckonUsingMultipleVelocitySources] Loaded
2020-12-10T21:59:04.669Z,1607637544.669 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2020-12-10T21:59:04.689Z,1607637544.689 [LBLNavigation] Loaded
2020-12-10T21:59:04.689Z,1607637544.689 [ComponentRegistry](DEBUG): SyncComponent "LBLNavigation" handled in the control thread.
2020-12-10T21:59:04.702Z,1607637544.702 [NavChart] Loaded
2020-12-10T21:59:04.703Z,1607637544.703 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2020-12-10T21:59:04.708Z,1607637544.708 [UniversalFixResidualReporter] Loaded
2020-12-10T21:59:04.709Z,1607637544.709 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2020-12-10T21:59:04.719Z,1607637544.719 [WorkSite] Loaded
2020-12-10T21:59:04.720Z,1607637544.720 [ComponentRegistry](DEBUG): SyncComponent "WorkSite" handled in the control thread.
2020-12-10T21:59:04.720Z,1607637544.720 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2020-12-10T21:59:04.721Z,1607637544.721 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2020-12-10T21:59:04.828Z,1607637544.828 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2020-12-10T21:59:04.828Z,1607637544.828 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2020-12-10T21:59:04.968Z,1607637544.968 [BuoyancyServo] Loaded
2020-12-10T21:59:04.968Z,1607637544.968 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2020-12-10T21:59:04.989Z,1607637544.989 [ElevatorServo] Loaded
2020-12-10T21:59:04.990Z,1607637544.990 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2020-12-10T21:59:05.010Z,1607637545.010 [MassServo] Loaded
2020-12-10T21:59:05.010Z,1607637545.010 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2020-12-10T21:59:05.030Z,1607637545.030 [RudderServo] Loaded
2020-12-10T21:59:05.030Z,1607637545.030 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2020-12-10T21:59:05.049Z,1607637545.049 [ThrusterServo] Loaded
2020-12-10T21:59:05.049Z,1607637545.049 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2020-12-10T21:59:05.049Z,1607637545.049 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2020-12-10T21:59:05.050Z,1607637545.050 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2020-12-10T21:59:05.770Z,1607637545.770 [CTD_Seabird] Loaded
2020-12-10T21:59:05.770Z,1607637545.770 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2020-12-10T21:59:05.771Z,1607637545.771 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 409274E0
2020-12-10T21:59:05.771Z,1607637545.771 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 920
2020-12-10T21:59:05.803Z,1607637545.803 [PAR_Licor] Loaded
2020-12-10T21:59:05.804Z,1607637545.804 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2020-12-10T21:59:05.872Z,1607637545.872 [WetLabsSeaOWL_UV_A] Loaded
2020-12-10T21:59:05.873Z,1607637545.873 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2020-12-10T21:59:05.890Z,1607637545.890 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409574E0
2020-12-10T21:59:05.890Z,1607637545.890 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 921
2020-12-10T21:59:05.891Z,1607637545.891 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2020-12-10T21:59:05.892Z,1607637545.892 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2020-12-10T21:59:06.295Z,1607637546.295 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2020-12-10T21:59:06.296Z,1607637546.296 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2020-12-10T21:59:06.354Z,1607637546.354 [DepthRateCalculator] Loaded
2020-12-10T21:59:06.355Z,1607637546.355 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2020-12-10T21:59:06.360Z,1607637546.360 [PitchRateCalculator] Loaded
2020-12-10T21:59:06.360Z,1607637546.360 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2020-12-10T21:59:06.369Z,1607637546.369 [SpeedCalculator] Loaded
2020-12-10T21:59:06.370Z,1607637546.370 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2020-12-10T21:59:06.383Z,1607637546.383 [TempGradientCalculator] Loaded
2020-12-10T21:59:06.384Z,1607637546.384 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2020-12-10T21:59:06.388Z,1607637546.388 [YawRateCalculator] Loaded
2020-12-10T21:59:06.389Z,1607637546.389 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2020-12-10T21:59:06.410Z,1607637546.410 [ElevatorOffsetCalculator] Loaded
2020-12-10T21:59:06.411Z,1607637546.411 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2020-12-10T21:59:06.411Z,1607637546.411 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2020-12-10T21:59:06.412Z,1607637546.412 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2020-12-10T21:59:06.576Z,1607637546.576 [SBIT](DEBUG): Construct Startup Built In Test.
2020-12-10T21:59:06.588Z,1607637546.588 [SBIT] Loaded
2020-12-10T21:59:06.588Z,1607637546.588 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2020-12-10T21:59:06.591Z,1607637546.591 [IBIT](DEBUG): Construct Initiated Built In Test.
2020-12-10T21:59:06.604Z,1607637546.604 [IBIT] Loaded
2020-12-10T21:59:06.604Z,1607637546.604 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2020-12-10T21:59:06.610Z,1607637546.610 [CBIT](DEBUG): Construct Continuous Built In Test.
2020-12-10T21:59:06.712Z,1607637546.712 [CBIT] Loaded
2020-12-10T21:59:06.712Z,1607637546.712 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2020-12-10T21:59:06.712Z,1607637546.712 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2020-12-10T21:59:06.713Z,1607637546.713 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2020-12-10T21:59:06.790Z,1607637546.790 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2020-12-10T21:59:06.791Z,1607637546.791 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2020-12-10T21:59:06.917Z,1607637546.917 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2020-12-10T21:59:06.918Z,1607637546.918 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2020-12-10T21:59:06.988Z,1607637546.988 [VerticalControl](DEBUG): Construct VerticalControl.
2020-12-10T21:59:07.042Z,1607637547.042 [VerticalControl] Loaded
2020-12-10T21:59:07.042Z,1607637547.042 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2020-12-10T21:59:07.045Z,1607637547.045 [HorizontalControl](DEBUG): Construct HorizontalControl.
2020-12-10T21:59:07.081Z,1607637547.081 [HorizontalControl] Loaded
2020-12-10T21:59:07.081Z,1607637547.081 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2020-12-10T21:59:07.084Z,1607637547.084 [SpeedControl](DEBUG): Construct SpeedControl.
2020-12-10T21:59:07.085Z,1607637547.085 [SpeedControl] Loaded
2020-12-10T21:59:07.086Z,1607637547.086 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2020-12-10T21:59:07.089Z,1607637547.089 [LoopControl](DEBUG): Construct LoopControl.
2020-12-10T21:59:07.089Z,1607637547.089 [LoopControl] Loaded
2020-12-10T21:59:07.089Z,1607637547.089 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2020-12-10T21:59:07.090Z,1607637547.090 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2020-12-10T21:59:07.090Z,1607637547.090 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2020-12-10T21:59:07.132Z,1607637547.132 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2020-12-10T21:59:07.138Z,1607637547.138 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2020-12-10T21:59:07.141Z,1607637547.141 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2020-12-10T21:59:07.152Z,1607637547.152 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2020-12-10T21:59:07.153Z,1607637547.153 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AFF4E0
2020-12-10T21:59:07.153Z,1607637547.153 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 922
2020-12-10T21:59:07.158Z,1607637547.158 [Supervisor](INFO): Main Thread ID is 822
2020-12-10T21:59:07.158Z,1607637547.158 [Supervisor](DEBUG): Running supervisor.
2020-12-10T21:59:07.159Z,1607637547.159 [CommandLine ThreadHandler](INFO): Handler Thread ID is 923
2020-12-10T21:59:07.161Z,1607637547.161 [controlThread ThreadHandler](INFO): Handler Thread ID is 924
2020-12-10T21:59:07.161Z,1607637547.161 [controlThread](DEBUG): Initializing ControlThread
2020-12-10T21:59:07.167Z,1607637547.167 [NavChart](DEBUG): Initialize NavChart Navigation.
2020-12-10T21:59:07.167Z,1607637547.167 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2020-12-10T21:59:07.167Z,1607637547.167 [WorkSite](DEBUG): Initializing WorkSite component.
2020-12-10T21:59:07.172Z,1607637547.172 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2020-12-10T21:59:07.173Z,1607637547.173 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2020-12-10T21:59:07.173Z,1607637547.173 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2020-12-10T21:59:07.173Z,1607637547.173 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2020-12-10T21:59:07.174Z,1607637547.174 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2020-12-10T21:59:07.174Z,1607637547.174 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2020-12-10T21:59:07.175Z,1607637547.175 [SBIT](INFO): Initialize SBIT Component.
2020-12-10T21:59:07.175Z,1607637547.175 [SBIT](IMPORTANT): git: 2020-12-09_polaris
2020-12-10T21:59:07.175Z,1607637547.175 [SBIT](INFO): git hash: af9a0cd533cadbfdab8ca7c32aa0f39f5c9a4f8c
2020-12-10T21:59:07.176Z,1607637547.176 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2020-12-10T21:59:07.177Z,1607637547.177 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Thu Aug 6 12:04:53 PDT 2020
2020-12-10T21:59:07.178Z,1607637547.178 [SBIT](INFO): Beginning SBIT in 21.000000 seconds.
2020-12-10T21:59:07.179Z,1607637547.179 [IBIT](INFO): Initialize IBIT Component.
2020-12-10T21:59:07.180Z,1607637547.180 [CBIT](DEBUG): Initialize CBIT Component.
2020-12-10T21:59:07.181Z,1607637547.181 [logger ThreadHandler](INFO): Handler Thread ID is 925
2020-12-10T21:59:07.192Z,1607637547.192 [CBIT](DEBUG): Initialized mux pins.
2020-12-10T21:59:07.192Z,1607637547.192 [CBIT](DEBUG): Initializing the watchdog timer.
2020-12-10T21:59:07.200Z,1607637547.200 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 926
2020-12-10T21:59:07.201Z,1607637547.201 [DataOverHttps](DEBUG): dashIP=128.128.181.155 starts with a digit so assuming it is a numeric IP
2020-12-10T21:59:07.212Z,1607637547.212 [Onboard ThreadHandler](INFO): Handler Thread ID is 927
2020-12-10T21:59:07.216Z,1607637547.216 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2020-12-10T21:59:07.217Z,1607637547.217 [CBIT](DEBUG): Initializing heartbeat.
2020-12-10T21:59:07.230Z,1607637547.230 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 928
2020-12-10T21:59:07.252Z,1607637547.252 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 929
2020-12-10T21:59:07.253Z,1607637547.253 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2020-12-10T21:59:07.257Z,1607637547.257 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 931
2020-12-10T21:59:07.258Z,1607637547.258 [WetLabsSeaOWL_UV_A](INFO): Powering down
2020-12-10T21:59:07.269Z,1607637547.269 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 932
2020-12-10T21:59:07.277Z,1607637547.277 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2020-12-10T21:59:07.277Z,1607637547.277 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2020-12-10T21:59:07.277Z,1607637547.277 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2020-12-10T21:59:07.277Z,1607637547.277 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2020-12-10T21:59:07.278Z,1607637547.278 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2020-12-10T21:59:07.278Z,1607637547.278 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2020-12-10T21:59:07.278Z,1607637547.278 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2020-12-10T21:59:07.278Z,1607637547.278 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2020-12-10T21:59:07.278Z,1607637547.278 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2020-12-10T21:59:07.278Z,1607637547.278 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2020-12-10T21:59:07.279Z,1607637547.279 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2020-12-10T21:59:07.279Z,1607637547.279 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2020-12-10T21:59:07.279Z,1607637547.279 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2020-12-10T21:59:07.279Z,1607637547.279 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2020-12-10T21:59:07.279Z,1607637547.279 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2020-12-10T21:59:07.280Z,1607637547.280 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2020-12-10T21:59:07.288Z,1607637547.288 [CBIT](DEBUG): Deactivating GF circuits.
2020-12-10T21:59:07.288Z,1607637547.288 [CBIT](DEBUG): Deactivating emergency mode.
2020-12-10T21:59:07.324Z,1607637547.324 [CBIT](DEBUG): Backplane powered.
2020-12-10T21:59:07.324Z,1607637547.324 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2020-12-10T21:59:07.326Z,1607637547.326 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2020-12-10T21:59:07.327Z,1607637547.327 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2020-12-10T21:59:07.327Z,1607637547.327 [LoopControl](DEBUG): Initialize LoopControlComponent.
2020-12-10T21:59:07.328Z,1607637547.328 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2020-12-10T21:59:07.370Z,1607637547.370 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2020-12-10T21:59:07.390Z,1607637547.390 [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>


2020-12-10T21:59:07.391Z,1607637547.391 [MissionManager](INFO): Loading Mission: Missions/underIce/DefaultWithUndock.xml
2020-12-10T21:59:07.542Z,1607637547.542 [MissionManager](INFO): DefineArg DefaultWithUndock.ElapsedSinceDefaultStarted = 0.000000 min
2020-12-10T21:59:07.566Z,1607637547.566 [MissionManager](INFO): DefineArg DefaultWithUndock.DetachTimeout = 30.000000 min
2020-12-10T21:59:07.570Z,1607637547.570 [MissionManager](INFO): DefineArg DefaultWithUndock.TransponderCode = 2 count
2020-12-10T21:59:07.589Z,1607637547.589 [MissionManager](INFO): DefineArg DefaultWithUndock.TrackingUpdatePeriod = 2.500000 s
2020-12-10T21:59:07.593Z,1607637547.593 [MissionManager](INFO): DefineArg DefaultWithUndock.NumberOfPings = 1.000000 count
2020-12-10T21:59:07.612Z,1607637547.612 [MissionManager](INFO): DefineArg DefaultWithUndock.DetachModeDDM = 2.000000 count
2020-12-10T21:59:07.614Z,1607637547.614 [DefaultWithUndock:A.Wait](DEBUG): Construct Wait.
2020-12-10T21:59:07.636Z,1607637547.636 [Radio_Surface](INFO): Powering up
2020-12-10T21:59:07.742Z,1607637547.742 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Construct.
2020-12-10T21:59:07.742Z,1607637547.742 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initializing internal variables to default values.
2020-12-10T21:59:07.791Z,1607637547.791 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](DEBUG): Construct GoToSurface.
2020-12-10T21:59:07.838Z,1607637547.838 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2020-12-10T21:59:07.856Z,1607637547.856 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Construct Wait.
2020-12-10T21:59:07.878Z,1607637547.878 [DefaultWithUndock:E.Execute](DEBUG): Construct Execute.
2020-12-10T21:59:07.900Z,1607637547.900 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Dock="Tethys/Dock"
         xmlns:Estimation="Tethys/Estimation"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Sensor="Tethys/Sensor"
         xmlns:Units="Tethys/Units"
         xmlns:Universal="Tethys/Universal"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Dock http://okeanids.mbari.org/tethys/Xml/Dock.xsd
                             Tethys/Estimation http://okeanids.mbari.org/tethys/Xml/Estimation.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Sensor http://okeanids.mbari.org/tethys/Xml/Sensor.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
         Id="DefaultWithUndock">

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

    <DefineArg Name="DetachTimeout"><Description>
        Maximum time duration for the vehicle to detach form the dock.
    </Description><Units:minute/><Value>30</Value></DefineArg>

    <DefineArg Name="TransponderCode"><Description>
        Dock transponder address.
    </Description><Dock:Dock.transponderCode/></DefineArg>

    <DefineArg Name="TrackingUpdatePeriod"><Description>
        Time duration between acoustic range queries while the
        mission is detaching from the dock.
    </Description><Units:second/><Value>2.5</Value></DefineArg>

    <DefineArg Name="NumberOfPings"><Description>
        Number of pings requested each time.
    </Description><Units:count/><Value>1</Value></DefineArg>

    <DefineArg Name="DetachModeDDM"><Description>
        DDM DETACH mode enumeration (whiskers retracted, latch open).
    </Description><Units:count/><Value>2</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>30</Value></Setting>
    </Guidance:Wait>

    <Aggregate Id="LeaveDock">
        <Sequence/>

        <Timeout Duration="DetachTimeout">
            <Syslog Severity="Important">Timed out while trying to detach from dock at current depth of <Universal:depth/><Units:meter/>.</Syslog>
        </Timeout>

        <!-- Acoustic tracking directives -->
        <Estimation:TrackAcousticContact>
            <Parallel/>
            <Setting><Estimation:TrackAcousticContact.contactLabelSetting/><Arg Name="TransponderCode"/></Setting>
            <Setting><Estimation:TrackAcousticContact.numberOfSamplesSetting/><Arg Name="NumberOfPings"/></Setting>
            <Setting><Estimation:TrackAcousticContact.updatePeriodSetting/><Arg Name="TrackingUpdatePeriod"/></Setting>
        </Estimation:TrackAcousticContact>

        <!-- Leave the dock -->
        <Dock:Undock>
            <Sequence/>
        </Dock:Undock>

    </Aggregate>


    <Aggregate Id="SurfaceDefault">

        <Sequence/>

        <Aggregate Id="HoldLatchOpen">

            <While>
                <Universal:depth/>
                <Gt><Control:VerticalControl.surfaceThreshold/></Gt>
            </While>

            <!-- Power the DDM -->
            <ReadData>
                <Sensor:DDM.DDMMode/>
            </ReadData>

            <!-- Hold the DDM in DETACH mode (whiskers retracted, latch open) -->
            <Assign><Parallel/><Sensor:DDM.DDMModeCmd/><Arg Name="DetachModeDDM"/></Assign>

        </Aggregate>

        <!-- This mission assumes open water so from here on it's the same old default that's always used -->
        <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>

    </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>


2020-12-10T21:59:07.905Z,1607637547.905 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,DDM,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,RDI_Pathfinder,RDI_PathfinderUp,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,WorkSite,LBLNavigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2020-12-10T21:59:07.909Z,1607637547.909 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2020-12-10T21:59:08.061Z,1607637548.061 [DDM](INFO): Powering up
2020-12-10T21:59:08.061Z,1607637548.061 [DDM](DEBUG): Initializing DDM.
2020-12-10T21:59:08.112Z,1607637548.112 [DUSBL_Hydroid](INFO): Powering up
2020-12-10T21:59:08.113Z,1607637548.113 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2020-12-10T21:59:08.214Z,1607637548.214 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2020-12-10T21:59:08.220Z,1607637548.220 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2020-12-10T21:59:08.221Z,1607637548.221 [ElevatorServo](DEBUG): Initializing EZServoServo.
2020-12-10T21:59:08.228Z,1607637548.228 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2020-12-10T21:59:08.229Z,1607637548.229 [MassServo](DEBUG): Initializing EZServoServo.
2020-12-10T21:59:08.236Z,1607637548.236 [MassServo](DEBUG): Initializing MassServo.
2020-12-10T21:59:08.237Z,1607637548.237 [RudderServo](DEBUG): Initializing EZServoServo.
2020-12-10T21:59:08.244Z,1607637548.244 [RudderServo](DEBUG): Initializing RudderServo.
2020-12-10T21:59:08.245Z,1607637548.245 [ThrusterServo](DEBUG): Initializing EZServoServo.
2020-12-10T21:59:08.252Z,1607637548.252 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2020-12-10T21:59:08.335Z,1607637548.335 [Micromodem](INFO): Powering up
2020-12-10T21:59:08.335Z,1607637548.335 [Micromodem](DEBUG): Initializing Micromodem.
2020-12-10T21:59:09.060Z,1607637549.060 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2020-12-10T21:59:09.060Z,1607637549.060 [RudderServo](FAULT): Rudder failed to initialize
2020-12-10T21:59:09.060Z,1607637549.060 [RudderServo] Communications Fault, FailCount= 1
2020-12-10T21:59:09.060Z,1607637549.060 [RudderServo](ERROR): Communications Fault
2020-12-10T21:59:09.160Z,1607637549.160 [CBIT](ERROR): Communications Fault in component: RudderServo
2020-12-10T21:59:09.329Z,1607637549.329 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2020-12-10T21:59:09.329Z,1607637549.329 [RudderServo](INFO): Powering down
2020-12-10T21:59:10.009Z,1607637550.009 [RudderServo](DEBUG): Initializing EZServoServo.
2020-12-10T21:59:10.129Z,1607637550.129 [RudderServo](DEBUG): Initializing RudderServo.
2020-12-10T21:59:10.133Z,1607637550.133 [CBIT](INFO): Clearing failed state for component RudderServo
2020-12-10T21:59:10.133Z,1607637550.133 [RudderServo] No Fault, FailCount= 1
2020-12-10T21:59:13.655Z,1607637553.655 [Micromodem](ERROR): CFG response from modem unexpected: $CATMG,2020-12-10T21:59:12.951042Z,RTC,RTC*55

2020-12-10T21:59:23.712Z,1607637563.712 [DDM](INFO): Dynamic Docking Module:
2020-12-10T21:59:26.138Z,1607637566.138 [DUSBL_Hydroid](INFO): DUSBL Version:O
2020-12-10T21:59:28.624Z,1607637568.624 [SBIT](IMPORTANT): Beginning Startup BIT
2020-12-10T21:59:28.637Z,1607637568.637 [CBIT](IMPORTANT): Beginning ground fault scan
2020-12-10T21:59:33.428Z,1607637573.428 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T21:59:34.635Z,1607637574.635 [NAL9602](INFO): Powering up NAL9602
2020-12-10T21:59:39.592Z,1607637579.592 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): 0.065800
CHAN A1 (24V): 0.088993
CHAN A2 (12V): 0.041632
CHAN A3 (5V): 0.008626
CHAN B0 (3.3V): 0.003363
CHAN B1 (3.15aV): 0.003138
CHAN B2 (3.15bV): 0.002962
CHAN B3 (GND): -0.012131
OPEN: 0.007681
Full Scale Calc: 4.765 mA, -1.589 mA
2020-12-10T21:59:45.530Z,1607637585.530 [NAL9602](INFO): NAL9602 initialized
2020-12-10T22:00:01.692Z,1607637601.692 [NAL9602](INFO): SBD MO Status=0, MOMSN=12262, MT Status=0, MTMSN=0
2020-12-10T22:00:01.692Z,1607637601.692 [NAL9602](INFO): No messages in MT queue
2020-12-10T22:00:04.523Z,1607637604.523 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T22:00:06.563Z,1607637606.563 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T22:00:22.751Z,1607637622.751 [SBIT](IMPORTANT): SBIT PASSED
2020-12-10T22:00:22.751Z,1607637622.751 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2020-12-10T22:00:22.768Z,1607637622.768 [SBIT](IMPORTANT): Express none CTD_Seabird.bin_median_sea_water_salinity;

2020-12-10T22:00:22.768Z,1607637622.768 [SBIT](IMPORTANT): Express none CTD_Seabird.bin_median_sea_water_temperature;

2020-12-10T22:00:22.768Z,1607637622.768 [SBIT](IMPORTANT): Express none CurrentEstimator.current_direction_navigation_frame;

2020-12-10T22:00:22.768Z,1607637622.768 [SBIT](IMPORTANT): Express none CurrentEstimator.current_direction_vehicle_frame;

2020-12-10T22:00:22.768Z,1607637622.768 [SBIT](IMPORTANT): Express none CurrentEstimator.current_speed_navigation_frame;

2020-12-10T22:00:22.768Z,1607637622.768 [SBIT](IMPORTANT): Express none CurrentEstimator.current_speed_vehicle_frame;

2020-12-10T22:00:22.769Z,1607637622.769 [SBIT](IMPORTANT): LBLNavigation.loadAtStartup=1 bool;

2020-12-10T22:00:22.769Z,1607637622.769 [SBIT](IMPORTANT): Micromodem.destinationAddress=9 enum;

2020-12-10T22:00:22.769Z,1607637622.769 [SBIT](IMPORTANT): PowerOnly.loadAtStartup=0 bool;

2020-12-10T22:00:22.769Z,1607637622.769 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=114.655585 cubic_centimeter;

2020-12-10T22:00:22.769Z,1607637622.769 [SBIT](IMPORTANT): VerticalControl.massDefault=-0.364238 millimeter;

2020-12-10T22:00:23.135Z,1607637623.135 [WorkSite](IMPORTANT): Reading workSite position from Data/workSite.cfg
2020-12-10T22:00:23.139Z,1607637623.139 [WorkSite](IMPORTANT): WorkSite fix at 20201210T215741: (41.550864, -70.721185)
2020-12-10T22:00:23.141Z,1607637623.141 [MissionManager](IMPORTANT): Started mission Startup
2020-12-10T22:00:23.142Z,1607637623.142 [Startup] Running Loop=1
2020-12-10T22:00:23.143Z,1607637623.143 [Startup](DEBUG): Aggregate::initialize Startup
2020-12-10T22:00:23.143Z,1607637623.143 [Startup:A.GoToSurface] Running Loop=1
2020-12-10T22:00:23.144Z,1607637623.144 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2020-12-10T22:00:23.146Z,1607637623.146 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2020-12-10T22:00:23.147Z,1607637623.147 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2020-12-10T22:00:23.148Z,1607637623.148 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2020-12-10T22:00:23.148Z,1607637623.148 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2020-12-10T22:00:23.149Z,1607637623.149 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2020-12-10T22:00:23.150Z,1607637623.150 [Startup:StartupSatComms] Running Loop=1
2020-12-10T22:00:23.150Z,1607637623.150 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2020-12-10T22:00:23.150Z,1607637623.150 [Startup:StartupSatComms:A] Running Loop=1
2020-12-10T22:00:23.596Z,1607637623.596 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2020-12-10T22:00:57.046Z,1607637657.046 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,220056.00,A,4133.03780,N,07043.27680,W,0.194,0.00,101220,,,A*71
2020-12-10T22:00:57.049Z,1607637657.049 [NAL9602](INFO): GPS fix at 20201210T220056: (41.550630, -70.721280)
2020-12-10T22:00:57.060Z,1607637657.060 [Startup:StartupSatComms:A] Stopped
2020-12-10T22:00:57.060Z,1607637657.060 [Startup:StartupSatComms:B] Running Loop=1
2020-12-10T22:00:57.519Z,1607637657.519 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2020-12-10T22:01:42.427Z,1607637702.427 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T22:01:47.679Z,1607637707.679 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2020-12-10T22:01:47.685Z,1607637707.685 [RDI_PathfinderUp](ERROR): only read 3 of 4 data items
2020-12-10T22:01:51.313Z,1607637711.313 [NAL9602](INFO): SBD MO Status=2, MOMSN=12263, MT Status=2, MTMSN=0
2020-12-10T22:01:51.313Z,1607637711.313 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-12-10T22:01:52.565Z,1607637712.565 [RDI_PathfinderUp](ERROR): only read 2 of 4 data items
2020-12-10T22:01:58.653Z,1607637718.653 [Startup:StartupSatComms:B](INFO): Timed out from 2020-12-10T22:00:57.1Z
2020-12-10T22:01:58.653Z,1607637718.653 [Startup:StartupSatComms:B] Stopped
2020-12-10T22:01:58.653Z,1607637718.653 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2020-12-10T22:01:58.653Z,1607637718.653 [Startup:StartupSatComms] Stopped
2020-12-10T22:01:58.653Z,1607637718.653 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2020-12-10T22:01:58.654Z,1607637718.654 [Startup](INFO): Completed Startup
2020-12-10T22:01:58.654Z,1607637718.654 [MissionManager](INFO): Startup is completed.
2020-12-10T22:01:58.654Z,1607637718.654 [MissionManager](INFO): Uninitializing Mission Startup
2020-12-10T22:01:58.655Z,1607637718.655 [Startup] Stopped
2020-12-10T22:01:58.655Z,1607637718.655 [Startup](DEBUG): Aggregate::uninitialize Startup
2020-12-10T22:01:58.655Z,1607637718.655 [Startup:A.GoToSurface] Stopped
2020-12-10T22:01:58.655Z,1607637718.655 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2020-12-10T22:01:58.753Z,1607637718.753 [MissionManager](IMPORTANT): Started mission DefaultWithUndock
2020-12-10T22:01:58.754Z,1607637718.754 [DefaultWithUndock] Running Loop=1
2020-12-10T22:01:58.754Z,1607637718.754 [DefaultWithUndock](DEBUG): Aggregate::initialize DefaultWithUndock
2020-12-10T22:01:58.754Z,1607637718.754 [DefaultWithUndock:A.Wait] Running Loop=1
2020-12-10T22:01:58.754Z,1607637718.754 [DefaultWithUndock:A.Wait](DEBUG): Initialize Wait Component.
2020-12-10T22:02:10.415Z,1607637730.415 [NAL9602](INFO): SBD MO Status=2, MOMSN=12263, MT Status=2, MTMSN=0
2020-12-10T22:02:10.416Z,1607637730.416 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-12-10T22:02:12.441Z,1607637732.441 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T22:02:17.738Z,1607637737.738 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T22:02:22.523Z,1607637742.523 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T22:02:22.548Z,1607637742.548 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for altitude
2020-12-10T22:02:29.059Z,1607637749.059 [DefaultWithUndock:A.Wait](INFO): Done Waiting.
2020-12-10T22:02:29.059Z,1607637749.059 [DefaultWithUndock:A.Wait] Stopped
2020-12-10T22:02:29.059Z,1607637749.059 [DefaultWithUndock:A.Wait](DEBUG): Uninitialize Wait Component.
2020-12-10T22:02:29.060Z,1607637749.060 [DefaultWithUndock:LeaveDock] Running Loop=1
2020-12-10T22:02:29.060Z,1607637749.060 [DefaultWithUndock:LeaveDock](DEBUG): Aggregate::initialize DefaultWithUndock:LeaveDock
2020-12-10T22:02:29.060Z,1607637749.060 [DefaultWithUndock:LeaveDock:A.] Running Loop=1
2020-12-10T22:02:29.060Z,1607637749.060 [DefaultWithUndock:LeaveDock:A.](INFO): Initializing TrackAcousticContact.
2020-12-10T22:02:29.060Z,1607637749.060 [DefaultWithUndock:LeaveDock:B.Undock] Running Loop=1
2020-12-10T22:02:29.060Z,1607637749.060 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initialize.
2020-12-10T22:02:29.061Z,1607637749.061 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initializing internal variables to default values.
2020-12-10T22:02:29.463Z,1607637749.463 [DefaultWithUndock:LeaveDock:A.] Running Loop=1
2020-12-10T22:02:31.877Z,1607637751.877 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T22:02:33.066Z,1607637753.066 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004704
2020-12-10T22:02:33.136Z,1607637753.136 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detaching from dock.
2020-12-10T22:02:33.514Z,1607637753.514 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detected possible detachment. Starting timer.
2020-12-10T22:02:34.720Z,1607637754.720 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T22:02:37.917Z,1607637757.917 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T22:02:40.778Z,1607637760.778 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T22:02:41.136Z,1607637761.136 [NAL9602](INFO): Not Powering down - fast GPS
2020-12-10T22:02:43.989Z,1607637763.989 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T22:02:46.826Z,1607637766.826 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T22:02:47.624Z,1607637767.624 [RDI_Pathfinder](ERROR): DVL uart error: serial timeout
2020-12-10T22:02:47.624Z,1607637767.624 [RDI_Pathfinder] Communications Fault, FailCount= 1
2020-12-10T22:02:47.624Z,1607637767.624 [RDI_Pathfinder](ERROR): Communications Fault
2020-12-10T22:02:47.748Z,1607637767.748 [CBIT](ERROR): Communications Fault in component: RDI_Pathfinder
2020-12-10T22:02:48.092Z,1607637768.092 [RDI_Pathfinder](INFO): Powering down
2020-12-10T22:02:48.920Z,1607637768.920 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder
2020-12-10T22:02:48.921Z,1607637768.921 [RDI_Pathfinder] No Fault, FailCount= 1
2020-12-10T22:02:50.049Z,1607637770.049 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T22:02:52.875Z,1607637772.875 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T22:02:53.706Z,1607637773.706 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detached at range: 1104.18 m. Transitioning DDM to standby.
2020-12-10T22:02:55.794Z,1607637775.794 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T22:02:56.981Z,1607637776.981 [DefaultWithUndock:LeaveDock:B.Undock](INFO): DDM at standby.
2020-12-10T22:02:57.306Z,1607637777.306 [DefaultWithUndock:LeaveDock:B.Undock](IMPORTANT): Undocking sequence complete.
2020-12-10T22:02:57.306Z,1607637777.306 [DefaultWithUndock:LeaveDock:B.Undock] Stopped
2020-12-10T22:02:57.306Z,1607637777.306 [DefaultWithUndock:LeaveDock](INFO): Completed DefaultWithUndock:LeaveDock
2020-12-10T22:02:57.306Z,1607637777.306 [DefaultWithUndock:LeaveDock] Stopped
2020-12-10T22:02:57.306Z,1607637777.306 [DefaultWithUndock:LeaveDock](DEBUG): Aggregate::uninitialize DefaultWithUndock:LeaveDock
2020-12-10T22:02:57.306Z,1607637777.306 [DefaultWithUndock:LeaveDock:A.] Stopped
2020-12-10T22:02:57.307Z,1607637777.307 [DefaultWithUndock:SurfaceDefault] Running Loop=1
2020-12-10T22:02:57.307Z,1607637777.307 [DefaultWithUndock:SurfaceDefault](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault
2020-12-10T22:02:57.307Z,1607637777.307 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen] Running Loop=1
2020-12-10T22:02:57.307Z,1607637777.307 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:HoldLatchOpen
2020-12-10T22:02:57.307Z,1607637777.307 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen:A] Running Loop=1
2020-12-10T22:02:57.307Z,1607637777.307 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen:B] Running Loop=1
2020-12-10T22:02:57.307Z,1607637777.307 [DefaultWithUndock:SurfaceDefault:B.GoToSurface] Running Loop=1
2020-12-10T22:02:57.307Z,1607637777.307 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2020-12-10T22:02:57.307Z,1607637777.307 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2020-12-10T22:02:57.308Z,1607637777.308 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2020-12-10T22:02:57.308Z,1607637777.308 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2020-12-10T22:02:57.309Z,1607637777.309 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2020-12-10T22:02:57.309Z,1607637777.309 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2020-12-10T22:02:57.722Z,1607637777.722 [DefaultWithUndock:SurfaceDefault:CheckIn] Running Loop=1
2020-12-10T22:02:57.723Z,1607637777.723 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:CheckIn
2020-12-10T22:02:57.723Z,1607637777.723 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Running Loop=1
2020-12-10T22:02:57.723Z,1607637777.723 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen] Stopped
2020-12-10T22:02:57.723Z,1607637777.723 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:HoldLatchOpen
2020-12-10T22:02:57.723Z,1607637777.723 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen:A] Stopped
2020-12-10T22:02:57.723Z,1607637777.723 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen:B] Stopped
2020-12-10T22:02:58.185Z,1607637778.185 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2020-12-10T22:02:59.698Z,1607637779.698 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,220258.00,A,4133.03174,N,07043.27968,W,0.447,263.39,101220,,,A*7F
2020-12-10T22:02:59.700Z,1607637779.700 [NAL9602](INFO): GPS fix at 20201210T220258: (41.550529, -70.721328)
2020-12-10T22:02:59.711Z,1607637779.711 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Stopped
2020-12-10T22:02:59.711Z,1607637779.711 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Running Loop=1
2020-12-10T22:03:00.123Z,1607637780.123 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2020-12-10T22:03:03.183Z,1607637783.183 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20201210T214311/Courier0010.lzma
2020-12-10T22:03:04.186Z,1607637784.186 [DataOverHttps](INFO): Moved sent file to Logs/20201210T214311/Courier0010.lzma.bak
2020-12-10T22:03:04.186Z,1607637784.186 [DataOverHttps](INFO): SBD MOMSN=62050
2020-12-10T22:03:13.224Z,1607637793.224 [DataOverHttps](INFO): Sending 259 bytes from file Logs/20201210T215856/Courier0000.lzma
2020-12-10T22:03:14.226Z,1607637794.226 [DataOverHttps](INFO): Moved sent file to Logs/20201210T215856/Courier0000.lzma.bak
2020-12-10T22:03:14.226Z,1607637794.226 [DataOverHttps](INFO): SBD MOMSN=62052
2020-12-10T22:03:23.263Z,1607637803.263 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20201210T215856/Courier0004.lzma
2020-12-10T22:03:24.266Z,1607637804.266 [DataOverHttps](INFO): Moved sent file to Logs/20201210T215856/Courier0004.lzma.bak
2020-12-10T22:03:24.266Z,1607637804.266 [DataOverHttps](INFO): SBD MOMSN=62056
2020-12-10T22:03:33.303Z,1607637813.303 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20201210T214311/Express0011.lzma
2020-12-10T22:03:34.306Z,1607637814.306 [DataOverHttps](INFO): Moved sent file to Logs/20201210T214311/Express0011.lzma.bak
2020-12-10T22:03:34.306Z,1607637814.306 [DataOverHttps](INFO): SBD MOMSN=62059
2020-12-10T22:03:36.870Z,1607637816.870 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T22:03:40.174Z,1607637820.174 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2020-12-10T22:03:43.358Z,1607637823.358 [DataOverHttps](INFO): Sending 1016 bytes from file Logs/20201210T215856/Express0001.lzma
2020-12-10T22:03:45.362Z,1607637825.362 [DataOverHttps](INFO): Moved sent file to Logs/20201210T215856/Express0001.lzma.bak
2020-12-10T22:03:45.362Z,1607637825.362 [DataOverHttps](INFO): SBD MOMSN=62061
2020-12-10T22:03:54.400Z,1607637834.400 [DataOverHttps](INFO): Sending 285 bytes from file Logs/20201210T215856/Express0005.lzma
2020-12-10T22:03:55.402Z,1607637835.402 [DataOverHttps](INFO): Moved sent file to Logs/20201210T215856/Express0005.lzma.bak
2020-12-10T22:03:55.402Z,1607637835.402 [DataOverHttps](INFO): SBD MOMSN=62086
2020-12-10T22:03:56.726Z,1607637836.726 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Stopped
2020-12-10T22:03:56.726Z,1607637836.726 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Running Loop=1
2020-12-10T22:03:56.726Z,1607637836.726 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-12-10T22:05:25.134Z,1607637925.134 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2020-12-10T22:05:25.137Z,1607637925.137 [BPC1](INFO): Received data from all battery sticks.
2020-12-10T22:05:28.358Z,1607637928.358 [NAL9602](INFO): SBD MO Status=1, MOMSN=12263, MT Status=0, MTMSN=0
2020-12-10T22:05:28.358Z,1607637928.358 [NAL9602](INFO): No messages in MT queue
2020-12-10T22:05:59.066Z,1607637959.066 [NAL9602](INFO): Not Powering down - fast GPS
2020-12-10T22:06:56.146Z,1607638016.146 [DataOverHttps](IMPORTANT): SBD MTMSN=20201210T220656
2020-12-10T22:07:00.164Z,1607638020.164 [DataOverHttps](INFO): Received command:sched asap "load Engineering/LBLTest.xml;set LBLTest.trans1Location [41.57302,-70.69302] degree;set LBLTest.trans1Depth 6 meter;set LBLTest.trans2Location [41.557417,-70.714644] degree;set LBLTest.trans2Depth 6 meter" ctfh 1 3
2020-12-10T22:07:00.269Z,1607638020.269 [CommandLine](IMPORTANT): got command schedule asap "load Engineering/LBLTest.xml;set LBLTest.trans1Location [41.57302,-70.69302] degree;set LBLTest.trans1Depth 6 meter;set LBLTest.trans2Location [41.557417,-70.714644] degree;set LBLTest.trans2Depth 6 meter" ctfh 1 3.000000
2020-12-10T22:07:00.269Z,1607638020.269 [CommandLine](IMPORTANT): Scheduling command #1 of 3 with id=ctfh
2020-12-10T22:07:00.270Z,1607638020.270 [CommandLine](IMPORTANT): Scheduled #1 (#1 of 3 with id='ctfh'): "load Engineering/LBLTest.xml;set LBLTest.trans1Location [41.57302,-70.69302] degree;set LBLTest.trans1Depth 6 meter;set LBLTest.trans2Location [41.557417,-70.714644] degree;set LBLTest.trans2Depth 6 meter" ASAP
2020-12-10T22:07:01.166Z,1607638021.166 [DataOverHttps](IMPORTANT): SBD MTMSN=20201210T220701
2020-12-10T22:07:05.184Z,1607638025.184 [DataOverHttps](INFO): Received command:sched asap "set LBLTest.trans3Depth 6 meter;set LBLTest:transit.MissionTimeout 120 minute;set LBLTest:transit.NeedCommsTime 15 minute;set LBLTest:transit.Latitude 41.578595 degree;set LBLTest:transit.Longitude -70.675158 degree" ctfh 2 3
2020-12-10T22:07:05.210Z,1607638025.210 [CommandLine](IMPORTANT): got command schedule asap "set LBLTest.trans3Depth 6 meter;set LBLTest:transit.MissionTimeout 120 minute;set LBLTest:transit.NeedCommsTime 15 minute;set LBLTest:transit.Latitude 41.578595 degree;set LBLTest:transit.Longitude -70.675158 degree" ctfh 2 3.000000
2020-12-10T22:07:05.210Z,1607638025.210 [CommandLine](IMPORTANT): Scheduling command #2 of 3 with id=ctfh
2020-12-10T22:07:05.211Z,1607638025.211 [CommandLine](IMPORTANT): Scheduled #2 (#2 of 3 with id='ctfh'): "set LBLTest.trans3Depth 6 meter;set LBLTest:transit.MissionTimeout 120 minute;set LBLTest:transit.NeedCommsTime 15 minute;set LBLTest:transit.Latitude 41.578595 degree;set LBLTest:transit.Longitude -70.675158 degree" ASAP
2020-12-10T22:07:06.186Z,1607638026.186 [DataOverHttps](IMPORTANT): SBD MTMSN=20201210T220706
2020-12-10T22:07:10.204Z,1607638030.204 [DataOverHttps](INFO): Received command:sched asap "set LBLTest:transit.Depth 6 meter;set LBLTest:transit.MaxDepth 9 meter;set LBLTest:transit.MinOffshore 500 meter;set LBLTest:transit.MinAltitude 3 meter;run " ctfh 3 3
2020-12-10T22:07:10.257Z,1607638030.257 [CommandLine](IMPORTANT): got command schedule asap "set LBLTest:transit.Depth 6 meter;set LBLTest:transit.MaxDepth 9 meter;set LBLTest:transit.MinOffshore 500 meter;set LBLTest:transit.MinAltitude 3 meter;run " ctfh 3 3.000000
2020-12-10T22:07:10.257Z,1607638030.257 [CommandLine](IMPORTANT): Scheduling command #3 of 3 with id=ctfh
2020-12-10T22:07:10.258Z,1607638030.258 [CommandLine](IMPORTANT): Scheduled #3 (#3 of 3 with id='ctfh'): "set LBLTest:transit.Depth 6 meter;set LBLTest:transit.MaxDepth 9 meter;set LBLTest:transit.MinOffshore 500 meter;set LBLTest:transit.MinAltitude 3 meter;run " ASAP
2020-12-10T22:07:10.480Z,1607638030.480 [CommandLine](IMPORTANT): got command load ./Missions/Engineering/LBLTest.xml
2020-12-10T22:07:10.481Z,1607638030.481 [MissionManager](INFO): Loading Mission: ./Missions/Engineering/LBLTest.xml
2020-12-10T22:07:10.519Z,1607638030.519 [MissionManager](INFO): DefineArg LBLTest.trans1Location = [36.803398,-121.822304] deg
2020-12-10T22:07:10.523Z,1607638030.523 [MissionManager](INFO): DefineArg LBLTest.trans1Depth = 25.000000 m
2020-12-10T22:07:10.526Z,1607638030.526 [MissionManager](INFO): DefineArg LBLTest.trans2Location = [36.793400,-121.832199] deg
2020-12-10T22:07:10.530Z,1607638030.530 [MissionManager](INFO): DefineArg LBLTest.trans2Depth = 25.000000 m
2020-12-10T22:07:10.534Z,1607638030.534 [MissionManager](INFO): DefineArg LBLTest.trans3Location = [36.793400,-121.812202] deg
2020-12-10T22:07:10.537Z,1607638030.537 [MissionManager](INFO): DefineArg LBLTest.trans3Depth = 25.000000 m
2020-12-10T22:07:10.602Z,1607638030.602 [LBLTest:WhenAgg:D.LBL](DEBUG): Construct LBL.
2020-12-10T22:07:10.630Z,1607638030.630 [MissionManager](INFO): Inserting Stack: Missions/Transport/transit.xml
2020-12-10T22:07:10.739Z,1607638030.739 [MissionManager](INFO): DefineArg LBLTest:transit.MissionTimeout = 60.000000 min
2020-12-10T22:07:10.742Z,1607638030.742 [MissionManager](INFO): DefineArg LBLTest:transit.NeedCommsTime = 30.000000 min
2020-12-10T22:07:10.756Z,1607638030.756 [MissionManager](INFO): DefineArg LBLTest:transit.Latitude = nan deg
2020-12-10T22:07:10.759Z,1607638030.759 [MissionManager](INFO): DefineArg LBLTest:transit.Longitude = nan deg
2020-12-10T22:07:10.774Z,1607638030.774 [MissionManager](INFO): DefineArg LBLTest:transit.Northings = 0.000000 m
2020-12-10T22:07:10.778Z,1607638030.778 [MissionManager](INFO): DefineArg LBLTest:transit.Eastings = 0.000000 m
2020-12-10T22:07:10.781Z,1607638030.781 [MissionManager](INFO): DefineArg LBLTest:transit.Depth = 10.000000 m
2020-12-10T22:07:10.786Z,1607638030.786 [MissionManager](INFO): DefineArg LBLTest:transit.Speed = 1.000000 m/s
2020-12-10T22:07:10.789Z,1607638030.789 [MissionManager](INFO): DefineArg LBLTest:transit.MaxDepth = 20.000000 m
2020-12-10T22:07:10.793Z,1607638030.793 [MissionManager](INFO): DefineArg LBLTest:transit.MinOffshore = 1.000000 km
2020-12-10T22:07:10.820Z,1607638030.820 [MissionManager](INFO): DefineArg LBLTest:transit.MinAltitude = 7.000000 m
2020-12-10T22:07:10.823Z,1607638030.823 [MissionManager](INFO): DefineArg LBLTest:transit.MassHold = 1 bool
2020-12-10T22:07:10.826Z,1607638030.826 [MissionManager](INFO): DefineArg LBLTest:transit.BuoyancyHold = 1 bool
2020-12-10T22:07:10.827Z,1607638030.827 [MissionManager](INFO): Inserting Stack: Missions/Insert/NeedComms.xml
2020-12-10T22:07:10.899Z,1607638030.899 [MissionManager](INFO): DefineArg LBLTest:transit:NeedComms.DiveInterval = 3.000000 h
2020-12-10T22:07:10.911Z,1607638030.911 [MissionManager](INFO): DefineArg LBLTest:transit:NeedComms.WaitForPitchUp = 10.000000 min
2020-12-10T22:07:10.914Z,1607638030.914 [MissionManager](INFO): DefineArg LBLTest:transit:NeedComms.SurfacePitch = 20.000000 deg
2020-12-10T22:07:10.919Z,1607638030.919 [MissionManager](INFO): DefineArg LBLTest:transit:NeedComms.SurfaceDepthRate = nan m/s
2020-12-10T22:07:10.930Z,1607638030.930 [MissionManager](INFO): DefineArg LBLTest:transit:NeedComms.SurfaceSpeed = 1.000000 m/s
2020-12-10T22:07:10.933Z,1607638030.933 [MissionManager](INFO): DefineArg LBLTest:transit:NeedComms.GPSTimeout = 7.000000 min
2020-12-10T22:07:10.945Z,1607638030.945 [MissionManager](INFO): DefineArg LBLTest:transit:NeedComms.CommsTimeout = 30.000000 min
2020-12-10T22:07:10.955Z,1607638030.955 [LBLTest:transit:NeedComms:B.GoToSurface](DEBUG): Construct GoToSurface.
2020-12-10T22:07:11.046Z,1607638031.046 [MissionManager](INFO): Inserting Stack: Missions/Insert/StandardEnvelopes.xml
2020-12-10T22:07:11.109Z,1607638031.109 [MissionManager](INFO): DefineArg LBLTest:transit:StandardEnvelopes.MinAltitude = 5.000000 m
2020-12-10T22:07:11.124Z,1607638031.124 [MissionManager](INFO): DefineArg LBLTest:transit:StandardEnvelopes.MaxDepth = 200.000000 m
2020-12-10T22:07:11.127Z,1607638031.127 [MissionManager](INFO): DefineArg LBLTest:transit:StandardEnvelopes.MinOffshore = 2000.000000 m
2020-12-10T22:07:11.133Z,1607638031.133 [LBLTest:transit:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2020-12-10T22:07:11.150Z,1607638031.150 [LBLTest:transit:StandardEnvelopes:B.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2020-12-10T22:07:11.181Z,1607638031.181 [LBLTest:transit:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2020-12-10T22:07:11.232Z,1607638031.232 [LBLTest:transit:BuoyancyHold.Buoyancy](DEBUG): Construct Buoyancy.
2020-12-10T22:07:11.240Z,1607638031.240 [LBLTest:transit:MassHold.Pitch](DEBUG): Construct.
2020-12-10T22:07:11.258Z,1607638031.258 [LBLTest:transit:Transit:A.Pitch](DEBUG): Construct.
2020-12-10T22:07:11.281Z,1607638031.281 [LBLTest:transit:Transit:B.SetSpeed](DEBUG): Construct.
2020-12-10T22:07:11.289Z,1607638031.289 [LBLTest:transit:Transit:Wpt1.Waypoint](DEBUG): Construct Waypoint.
2020-12-10T22:07:11.334Z,1607638031.334 [MissionManager](INFO): RedefineArg LBLTest:transit.MissionTimeout = value:90.000000 min
2020-12-10T22:07:11.339Z,1607638031.339 [MissionManager](INFO): RedefineArg LBLTest:transit.Latitude = value:36.804901 deg
2020-12-10T22:07:11.349Z,1607638031.349 [MissionManager](INFO): RedefineArg LBLTest:transit.Longitude = value:-121.810799 deg
2020-12-10T22:07:11.356Z,1607638031.356 [MissionManager](INFO): RedefineArg LBLTest:transit.MinOffshore = value:750.000000 m
2020-12-10T22:07:11.414Z,1607638031.414 [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="LBLTest">
       
    <DefineArg Name="trans1Location"><Units:degree/><Value>[36.8034,-121.8223]</Value></DefineArg>

    <DefineArg Name="trans1Depth"><Units:meter/><Value>25</Value></DefineArg>

    <DefineArg Name="trans2Location"><Units:degree/><Value>[36.7934,-121.8322]</Value></DefineArg>

    <DefineArg Name="trans2Depth"><Units:meter/><Value>25</Value></DefineArg>

    <DefineArg Name="trans3Location"><Units:degree/><Value>[36.7934,-121.8122]</Value></DefineArg>

    <DefineArg Name="trans3Depth"><Units:meter/><Value>25</Value></DefineArg>

    <Timeout Duration="P70M"/>

    <Aggregate Id="WhenAgg">

        <When>
            <True/>
        </When>

        <Timeout Duration="P60M">
            <Syslog>WhenAgg timed out</Syslog>
        </Timeout>

<!-- The following asssigns have no effect if #. variables are not set -->

        <Assign><Parallel/><Arg Name="trans1Location"/><CustomUri Uri="#.t1"/></Assign>

        <Assign><Parallel/><Arg Name="trans2Location"/><CustomUri Uri="#.t2"/></Assign>

        <Assign><Parallel/><Arg Name="trans3Location"/><CustomUri Uri="#.t3"/></Assign>

        <Navigation:LBL>
            <Parallel/>
            <Setting><Navigation:LBL.trans1Location /><Arg Name="trans1Location"/></Setting>
            <Setting><Navigation:LBL.trans1Depth /><Arg Name="trans1Depth"/></Setting>
            <Setting><Navigation:LBL.trans2Location /><Arg Name="trans2Location"/></Setting>
            <Setting><Navigation:LBL.trans2Depth /><Arg Name="trans2Depth"/></Setting>
            <Setting><Navigation:LBL.trans3Location /><Arg Name="trans3Location"/></Setting>
            <Setting><Navigation:LBL.trans3Depth /><Arg Name="trans3Depth"/></Setting>
        </Navigation:LBL>

    </Aggregate>

    <Insert Filename="Transport/transit.xml">
        <RedefineArg Name="MissionTimeout"><Units:minute/><Value>90</Value></RedefineArg>
        <RedefineArg Name="Latitude"><Units:degree/><Value>36.8049</Value></RedefineArg>
        <RedefineArg Name="Longitude"><Units:degree/><Value>-121.8108</Value></RedefineArg>
        <RedefineArg Name="MinOffshore"><Units:meter/><Value>750</Value></RedefineArg>
    </Insert>

</Mission>


2020-12-10T22:07:11.414Z,1607638031.414 [CommandLine](IMPORTANT): Loaded ./Missions/Engineering/LBLTest.xml
2020-12-10T22:07:18.591Z,1607638038.591 [CommandLine](IMPORTANT): got command set LBLTest.trans1Location [41.57302,-70.69302] degree
2020-12-10T22:07:18.592Z,1607638038.592 [CommandLine](IMPORTANT): got command set LBLTest.trans1Depth 6 meter
2020-12-10T22:07:18.593Z,1607638038.593 [CommandLine](IMPORTANT): got command set LBLTest.trans2Location [41.557417,-70.714644] degree
2020-12-10T22:07:18.593Z,1607638038.593 [CommandLine](IMPORTANT): got command set LBLTest.trans2Depth 6 meter
2020-12-10T22:07:29.053Z,1607638049.053 [CommandLine](IMPORTANT): got command set LBLTest.trans3Depth 6 meter
2020-12-10T22:07:29.053Z,1607638049.053 [CommandLine](IMPORTANT): got command set LBLTest:transit.MissionTimeout 120 minute
2020-12-10T22:07:29.054Z,1607638049.054 [CommandLine](IMPORTANT): got command set LBLTest:transit.NeedCommsTime 15 minute
2020-12-10T22:07:29.055Z,1607638049.055 [CommandLine](IMPORTANT): got command set LBLTest:transit.Latitude 41.578595 degree
2020-12-10T22:07:29.055Z,1607638049.055 [CommandLine](IMPORTANT): got command set LBLTest:transit.Longitude -70.675158 degree
2020-12-10T22:07:43.186Z,1607638063.186 [CommandLine](IMPORTANT): got command set LBLTest:transit.Depth 6 meter
2020-12-10T22:07:43.187Z,1607638063.187 [CommandLine](IMPORTANT): got command set LBLTest:transit.MaxDepth 9 meter
2020-12-10T22:07:43.187Z,1607638063.187 [CommandLine](IMPORTANT): got command set LBLTest:transit.MinOffshore 500 meter
2020-12-10T22:07:43.192Z,1607638063.192 [CommandLine](IMPORTANT): got command set LBLTest:transit.MinAltitude 3 meter
2020-12-10T22:07:43.193Z,1607638063.193 [CommandLine](IMPORTANT): got command run 
2020-12-10T22:07:43.195Z,1607638063.195 [CommandLine](IMPORTANT): Running 
2020-12-10T22:07:43.494Z,1607638063.494 [DefaultWithUndock] Stopped
2020-12-10T22:07:43.494Z,1607638063.494 [DefaultWithUndock](DEBUG): Aggregate::uninitialize DefaultWithUndock
2020-12-10T22:07:43.494Z,1607638063.494 [DefaultWithUndock:SurfaceDefault] Stopped
2020-12-10T22:07:43.494Z,1607638063.494 [DefaultWithUndock:SurfaceDefault](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault
2020-12-10T22:07:43.494Z,1607638063.494 [DefaultWithUndock:SurfaceDefault:B.GoToSurface] Stopped
2020-12-10T22:07:43.494Z,1607638063.494 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2020-12-10T22:07:43.494Z,1607638063.494 [DefaultWithUndock:SurfaceDefault:CheckIn] Stopped
2020-12-10T22:07:43.495Z,1607638063.495 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:CheckIn
2020-12-10T22:07:43.495Z,1607638063.495 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Stopped
2020-12-10T22:07:43.495Z,1607638063.495 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-12-10T22:07:43.495Z,1607638063.495 [MissionManager](IMPORTANT): Started mission LBLTest
2020-12-10T22:07:43.495Z,1607638063.495 [LBLTest] Running Loop=1
2020-12-10T22:07:43.495Z,1607638063.495 [LBLTest](DEBUG): Aggregate::initialize LBLTest
2020-12-10T22:07:43.495Z,1607638063.495 [LBLTest:transit] Running Loop=1
2020-12-10T22:07:43.504Z,1607638063.504 [LBLTest:transit](DEBUG): Aggregate::initialize LBLTest:transit
2020-12-10T22:07:43.504Z,1607638063.504 [LBLTest:transit:StandardEnvelopes] Running Loop=1
2020-12-10T22:07:43.504Z,1607638063.504 [LBLTest:transit:StandardEnvelopes](DEBUG): Aggregate::initialize LBLTest:transit:StandardEnvelopes
2020-12-10T22:07:43.504Z,1607638063.504 [LBLTest:transit:StandardEnvelopes:A.AltitudeEnvelope] Running Loop=1
2020-12-10T22:07:43.504Z,1607638063.504 [LBLTest:transit:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2020-12-10T22:07:43.504Z,1607638063.504 [LBLTest:transit:StandardEnvelopes:B.DepthEnvelope] Running Loop=1
2020-12-10T22:07:43.505Z,1607638063.505 [LBLTest:transit:StandardEnvelopes:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2020-12-10T22:07:43.505Z,1607638063.505 [LBLTest:transit:StandardEnvelopes:C.OffshoreEnvelope] Running Loop=1
2020-12-10T22:07:43.505Z,1607638063.505 [LBLTest:transit:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2020-12-10T22:07:43.505Z,1607638063.505 [LBLTest:transit:BuoyancyHold.Buoyancy] Running Loop=1
2020-12-10T22:07:43.505Z,1607638063.505 [LBLTest:transit:BuoyancyHold.Buoyancy](DEBUG): Initialize Buoyancy Component.
2020-12-10T22:07:43.505Z,1607638063.505 [LBLTest:transit:MassHold.Pitch] Running Loop=1
2020-12-10T22:07:43.505Z,1607638063.505 [LBLTest:transit:MassHold.Pitch](DEBUG): Initialize.
2020-12-10T22:07:43.505Z,1607638063.505 [LBLTest:transit:B] Running Loop=1
2020-12-10T22:07:43.507Z,1607638063.507 [LBLTest:transit:MassHold.Pitch] Running Loop=1
2020-12-10T22:07:43.507Z,1607638063.507 [LBLTest:transit:BuoyancyHold.Buoyancy] Running Loop=1
2020-12-10T22:07:43.507Z,1607638063.507 [LBLTest:transit:StandardEnvelopes] Running Loop=1
2020-12-10T22:07:43.513Z,1607638063.513 [LBLTest:transit:StandardEnvelopes:C.OffshoreEnvelope] Running Loop=1
2020-12-10T22:07:43.513Z,1607638063.513 [LBLTest:transit:StandardEnvelopes:B.DepthEnvelope] Running Loop=1
2020-12-10T22:07:43.514Z,1607638063.514 [LBLTest:transit:StandardEnvelopes:A.AltitudeEnvelope] Running Loop=1
2020-12-10T22:07:43.515Z,1607638063.515 [LBLTest:transit:B] Stopped
2020-12-10T22:07:43.515Z,1607638063.515 [LBLTest:transit:C] Running Loop=1
2020-12-10T22:07:43.515Z,1607638063.515 [LBLTest:WhenAgg] Running Loop=1
2020-12-10T22:07:43.515Z,1607638063.515 [LBLTest:WhenAgg](DEBUG): Aggregate::initialize LBLTest:WhenAgg
2020-12-10T22:07:43.515Z,1607638063.515 [LBLTest:WhenAgg:A] Running Loop=1
2020-12-10T22:07:43.516Z,1607638063.516 [LBLTest:WhenAgg:B] Running Loop=1
2020-12-10T22:07:43.528Z,1607638063.528 [LBLTest:WhenAgg:C] Running Loop=1
2020-12-10T22:07:43.528Z,1607638063.528 [LBLTest:WhenAgg:D.LBL] Running Loop=1
2020-12-10T22:07:43.528Z,1607638063.528 [LBLTest:WhenAgg:D.LBL](DEBUG): Initialize LBLComponent.
2020-12-10T22:07:43.528Z,1607638063.528 [LBLTest:WhenAgg:D.LBL] Running Loop=1
2020-12-10T22:07:43.530Z,1607638063.530 [LBLTest:WhenAgg:C] Running Loop=1
2020-12-10T22:07:43.530Z,1607638063.530 [LBLTest:WhenAgg:B] Running Loop=1
2020-12-10T22:07:43.530Z,1607638063.530 [LBLTest:WhenAgg:A] Running Loop=1
2020-12-10T22:07:43.852Z,1607638063.852 [LBLNavigation](INFO): Read position 1: [0.725586,-1.233826,6.000000]
2020-12-10T22:07:43.853Z,1607638063.853 [LBLNavigation](INFO): Read position 2: [0.725314,-1.234203,6.000000]
2020-12-10T22:07:43.854Z,1607638063.854 [LBLNavigation](INFO): Read position 3: [0.642166,-2.126024,6.000000]
2020-12-10T22:07:43.865Z,1607638063.865 [LBLTest:transit:C] Stopped
2020-12-10T22:07:43.866Z,1607638063.866 [LBLTest:transit:E] Running Loop=1
2020-12-10T22:07:44.245Z,1607638064.245 [LBLTest:transit:E] Stopped
2020-12-10T22:07:44.245Z,1607638064.245 [LBLTest:transit:F] Running Loop=1
2020-12-10T22:07:44.673Z,1607638064.673 [LBLTest:transit:F] Stopped
2020-12-10T22:07:44.673Z,1607638064.673 [LBLTest:transit:G] Running Loop=1
2020-12-10T22:07:45.041Z,1607638065.041 [LBLTest:transit:G] Stopped
2020-12-10T22:07:45.041Z,1607638065.041 [LBLTest:transit:Transit] Running Loop=1
2020-12-10T22:07:45.041Z,1607638065.041 [LBLTest:transit:Transit](DEBUG): Aggregate::initialize LBLTest:transit:Transit
2020-12-10T22:07:45.041Z,1607638065.041 [LBLTest:transit:Transit:A.Pitch] Running Loop=1
2020-12-10T22:07:45.041Z,1607638065.041 [LBLTest:transit:Transit:A.Pitch](DEBUG): Initialize.
2020-12-10T22:07:45.041Z,1607638065.041 [LBLTest:transit:Transit:B.SetSpeed] Running Loop=1
2020-12-10T22:07:45.041Z,1607638065.041 [LBLTest:transit:Transit:B.SetSpeed](DEBUG): Initialize.
2020-12-10T22:07:45.042Z,1607638065.042 [LBLTest:transit:Transit:Wpt1.Waypoint] Running Loop=1
2020-12-10T22:07:45.042Z,1607638065.042 [LBLTest:transit:Transit:Wpt1.Waypoint](DEBUG): Initialize WaypointComponent.
2020-12-10T22:07:45.480Z,1607638065.480 [LBLTest:transit:Transit:B.SetSpeed] Running Loop=1
2020-12-10T22:07:45.481Z,1607638065.481 [LBLTest:transit:Transit:A.Pitch] Running Loop=1
2020-12-10T22:07:51.883Z,1607638071.883 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACST,6,0,20201210220751.203154,06,1512,31,0265,0150,59,02,02,00,04,1,009,001,0,4,1,0,150,13.5,8.00,12,-5.00,-01,0.26,33,14500,400*50
 expected 60
2020-12-10T22:08:04.003Z,1607638084.003 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACST,6,0,20201210220803.323022,06,3415,35,0325,0150,37,02,02,00,04,1,009,001,0,4,1,0,150,5.9,9.00,18,-6.00,-01,0.65,29,14500,4000*58
 expected 69
2020-12-10T22:08:16.134Z,1607638096.134 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACST,6,0,20201210220815.443916,06,1146,30,0214,0150,59,01,01,00,03,1,009,001,0,4,1,0,150,-28.9,700,15,-4.00-01,-0.66,45,14500,4000*5E
 expected 5C
2020-12-10T22:08:31.473Z,1607638111.473 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:08:34.303Z,1607638114.303 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T22:08:42.789Z,1607638122.789 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:08:50.867Z,1607638130.867 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACST,6,0,20201210220850.211382,06,191,16,0166,0150,90,02,01,04,1,009,001,0,4,1,0,150,10.5,2.00,07,1.00,-01,-1.71,38,14500,4000*62
 expected 44
2020-12-10T22:08:55.314Z,1607638135.314 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CAREV,220855,COPROC,0.10.0.46*8
 expected 48
2020-12-10T22:09:15.511Z,1607638155.511 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACST,,0,20210220914.877084,06,1066,24,0267,0150,59,02,02,01,02,1,009,001,0,4,1,0,150,10.7,4.00,08,-1.00,-01,-1.84,31,14500,4000*79
 expected 7C
2020-12-10T22:09:19.587Z,1607638159.587 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACST,6,0,20201210220919.260185,06,3107,34,0205,0150,37,02,02,00,04,1,012,001,0,4,1,0,150,20.2,6.00,16,-3.00,-01,-2.08,28,14500,400*7A
 expected 4A
2020-12-10T22:09:21.761Z,1607638161.761 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.240082
2020-12-10T22:09:52.682Z,1607638192.682 [Micromodem](INFO): Received CAACK with unexpected srcOfAck address: 148
2020-12-10T22:09:52.684Z,1607638192.684 [Micromodem](INFO): Received CAACK with unexpected srcOfAck address: 148
2020-12-10T22:09:53.097Z,1607638193.097 [Micromodem](INFO): Received CAACK with unexpected srcOfAck address: 148
2020-12-10T22:09:53.098Z,1607638193.098 [Micromodem](INFO): Received CAACK with unexpected srcOfAck address: 148
2020-12-10T22:09:55.004Z,1607638195.004 [Radio_Surface](INFO): Powering down
2020-12-10T22:09:55.909Z,1607638195.909 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:09:57.905Z,1607638197.905 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-12-10T22:09:58.909Z,1607638198.909 [DataOverHttps](INFO): Radio surface powered OFF, will not connect.
2020-12-10T22:10:11.666Z,1607638211.666 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:10:27.429Z,1607638227.429 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:10:44.794Z,1607638244.794 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CAREV,221045,AUV,2.0.32731*B
 expected 1B
2020-12-10T22:10:44.801Z,1607638244.801 [Micromodem](ERROR): Response from modem failed NMEA checksum: $ARE,221045,COPROC,0.10.0.46*40
 expected 55
2020-12-10T22:11:09.846Z,1607638269.846 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACST,6,0,20201210221109.145159,06,5186,37,0239,0150,07,01,01,00,04,1,012,001,0,4,1,0,150,25.2,11.00,21,-8.00,-01,-0.53,22,4500,4000*4D
 expected 7C
2020-12-10T22:11:22.374Z,1607638282.374 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACST,6,0,20201210221121.672684,06,2820,34,0186,0150,14,02,02,00,02,1,012,001,0,4,1,0,150,20.6,11.00,20,-8.00,-01,-085,29,14500,4000*41
 expected 6F
2020-12-10T22:11:34.891Z,1607638294.891 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACST,6,0,20201210221134.208521,06,5719,37,0271,0150,07,01,01,00,04,1,012,001,0,4,1,0,150,24.6,10.00,20,-7.0-01,-0.85,22,14500,4000*4F
 expected 53
2020-12-10T22:11:47.422Z,1607638307.422 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACST,6,0,20201210221146.733433,06,1665,32,0127,0150,14,02,02,00,02,1,012,001,0,4,1,0,150,21.1,9.00,19,-6.00,-01,-0.7,28,14500,4000*7C
 expected 4B
2020-12-10T22:12:12.470Z,1607638332.470 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACST,6,0,20201210221211.789048,06,1054,30,0157,0150,07,01,01,00,03,1,012,001,0,4,1,0,150,21.7,6.00,16,-3.00,-01,-1.26,22,14500,4000A
 expected 3C
2020-12-10T22:12:37.522Z,1607638357.522 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACST,6,0,20201210221236.853853,06,1649,32,0164,0150,07,01,01,00,03,1,12,001,0,4,1,0,150,22.7,8.00,17,-5.00,-01,-0.68,22,14500,4000*7C
 expected 4C
2020-12-10T22:14:15.299Z,1607638455.299 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,Bad Modulation Header,0*31

2020-12-10T22:14:18.917Z,1607638458.917 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:14:57.328Z,1607638497.328 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,Bad Modulation Header,0*31

2020-12-10T22:15:00.934Z,1607638500.934 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:15:52.261Z,1607638552.261 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,Bad Modulation Header,0*31

2020-12-10T22:15:55.877Z,1607638555.877 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:15:58.352Z,1607638558.352 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2020-12-10T22:16:08.411Z,1607638568.411 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T22:16:13.257Z,1607638573.257 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T22:16:18.126Z,1607638578.126 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2020-12-10T22:16:24.973Z,1607638584.973 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:16:33.115Z,1607638593.115 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2020-12-10T22:16:38.311Z,1607638598.311 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2020-12-10T22:16:41.134Z,1607638601.134 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:16:57.285Z,1607638617.285 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:17:13.453Z,1607638633.453 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:17:26.782Z,1607638646.782 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CAREV,221726,AUV,2.0.2731*19
 expected 2A
2020-12-10T22:17:39.711Z,1607638659.711 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CAREV,221739,COPROC,0.1.0.46*4C
 expected 7C
2020-12-10T22:17:55.465Z,1607638675.465 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:17:59.918Z,1607638679.918 [LBLTest:transit:NeedComms] Running Loop=1
2020-12-10T22:17:59.918Z,1607638679.918 [LBLTest:transit:NeedComms](DEBUG): Aggregate::initialize LBLTest:transit:NeedComms
2020-12-10T22:17:59.918Z,1607638679.918 [LBLTest:transit:NeedComms:B.GoToSurface] Running Loop=1
2020-12-10T22:17:59.918Z,1607638679.918 [LBLTest:transit:NeedComms:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2020-12-10T22:17:59.918Z,1607638679.918 [LBLTest:transit:NeedComms:B.GoToSurface](INFO): Received depth rate setting nan m/s.
2020-12-10T22:17:59.919Z,1607638679.919 [LBLTest:transit:NeedComms:B.GoToSurface](INFO): Received pitch setting 19.999999 degrees.
2020-12-10T22:17:59.919Z,1607638679.919 [LBLTest:transit:NeedComms:B.GoToSurface](INFO): Received speed setting 1.000000 m/s.
2020-12-10T22:17:59.919Z,1607638679.919 [LBLTest:transit:NeedComms:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2020-12-10T22:17:59.920Z,1607638679.920 [LBLTest:transit:NeedComms:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2020-12-10T22:17:59.921Z,1607638679.921 [LBLTest:transit:NeedComms:A] Running Loop=1
2020-12-10T22:17:59.922Z,1607638679.922 [LBLTest:transit:NeedComms:A](INFO): last time_fix was: 1607637778.000000 second since 1970/01/01T00:00:00Z 
2020-12-10T22:17:59.922Z,1607638679.922 [LBLTest:transit:NeedComms:A] Stopped
2020-12-10T22:18:11.622Z,1607638691.622 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:18:27.782Z,1607638707.782 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:18:33.857Z,1607638713.857 [LBLTest:transit:NeedComms:C] Running Loop=1
2020-12-10T22:18:34.276Z,1607638714.276 [LBLTest:transit:NeedComms:C](DEBUG): Initialize ReadDataComponent to sense time_fix
2020-12-10T22:18:34.548Z,1607638714.548 [Radio_Surface](INFO): Powering up
2020-12-10T22:18:40.048Z,1607638720.048 [DataOverHttps](INFO): Radio surface powered ON.
2020-12-10T22:18:43.939Z,1607638723.939 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:18:47.644Z,1607638727.644 [BuoyancyServo](FAULT): Overload Error
2020-12-10T22:18:47.644Z,1607638727.644 [BuoyancyServo] Hardware Fault, FailCount= 1
2020-12-10T22:18:47.644Z,1607638727.644 [BuoyancyServo](ERROR): Hardware Fault
2020-12-10T22:18:47.702Z,1607638727.702 [CBIT](ERROR): Hardware Fault in component: BuoyancyServo
2020-12-10T22:18:49.656Z,1607638729.656 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2020-12-10T22:18:49.656Z,1607638729.656 [BuoyancyServo](INFO): Powering down
2020-12-10T22:18:50.448Z,1607638730.448 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2020-12-10T22:18:50.448Z,1607638730.448 [BuoyancyServo] No Fault, FailCount= 1
2020-12-10T22:18:50.846Z,1607638730.846 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2020-12-10T22:18:50.847Z,1607638730.847 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2020-12-10T22:18:51.216Z,1607638731.216 [NAL9602](INFO): SBD MO Status=1, MOMSN=12264, MT Status=0, MTMSN=0
2020-12-10T22:18:51.217Z,1607638731.217 [NAL9602](INFO): No messages in MT queue
2020-12-10T22:18:52.426Z,1607638732.426 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,221852.00,A,4133.02452,N,07043.60573,W,0.778,0.00,101220,,,A*79
2020-12-10T22:18:52.428Z,1607638732.428 [NAL9602](INFO): GPS fix at 20201210T221852: (41.550409, -70.726762)
2020-12-10T22:18:52.469Z,1607638732.469 [UniversalFixResidualReporter](INFO): Fix residual: 2.8 %DT, over the last 521.5 m. Residual distance 14.5 m at bearing 81.9 degrees. Fix at (41.5504, -70.7268) with 452.4 m made good.
2020-12-10T22:18:52.473Z,1607638732.473 [LBLTest:transit:NeedComms:C] Stopped
2020-12-10T22:18:52.473Z,1607638732.473 [LBLTest:transit:NeedComms:D] Running Loop=1
2020-12-10T22:18:52.871Z,1607638732.871 [LBLTest:transit:NeedComms:D](DEBUG): Initialize ReadDataComponent to sense platform_communications
2020-12-10T22:18:59.922Z,1607638739.922 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:19:10.168Z,1607638750.168 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-12-10T22:19:10.432Z,1607638750.432 [NAL9602](INFO): SBD MO Status=1, MOMSN=12265, MT Status=0, MTMSN=0
2020-12-10T22:19:10.486Z,1607638750.486 [NAL9602](INFO): Sent 184 bytes from file Logs/20201210T215856/Courier0007.lzma
2020-12-10T22:19:10.487Z,1607638750.487 [NAL9602](INFO): Packets left to send: 1
2020-12-10T22:19:15.909Z,1607638755.909 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:19:23.987Z,1607638763.987 [NAL9602](INFO): SBD MO Status=1, MOMSN=12266, MT Status=0, MTMSN=0
2020-12-10T22:19:24.041Z,1607638764.041 [NAL9602](INFO): Sent 77 bytes from file Logs/20201210T215856/Courier0007.lzma
2020-12-10T22:19:24.042Z,1607638764.042 [NAL9602](INFO): Packets left to send: 0
2020-12-10T22:19:31.865Z,1607638771.865 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:19:36.346Z,1607638776.346 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,Bad Modulation Header,0*31

2020-12-10T22:19:43.175Z,1607638783.175 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:19:43.183Z,1607638783.183 [NAL9602](INFO): SBD MO Status=1, MOMSN=12267, MT Status=0, MTMSN=0
2020-12-10T22:19:43.237Z,1607638783.237 [NAL9602](INFO): Sent 184 bytes from file Logs/20201210T215856/Express0008.lzma
2020-12-10T22:19:43.238Z,1607638783.238 [NAL9602](INFO): Packets left to send: 4
2020-12-10T22:19:45.309Z,1607638785.309 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-12-10T22:19:53.096Z,1607638793.096 [NAL9602](INFO): SBD MO Status=1, MOMSN=12268, MT Status=0, MTMSN=0
2020-12-10T22:19:53.152Z,1607638793.152 [NAL9602](INFO): Sent 184 bytes from file Logs/20201210T215856/Express0008.lzma
2020-12-10T22:19:53.152Z,1607638793.152 [NAL9602](INFO): Packets left to send: 3
2020-12-10T22:19:54.341Z,1607638794.341 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:19:57.458Z,1607638797.458 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T22:20:04.743Z,1607638804.743 [NAL9602](INFO): SBD MO Status=1, MOMSN=12269, MT Status=0, MTMSN=0
2020-12-10T22:20:04.801Z,1607638804.801 [NAL9602](INFO): Sent 184 bytes from file Logs/20201210T215856/Express0008.lzma
2020-12-10T22:20:04.801Z,1607638804.801 [NAL9602](INFO): Packets left to send: 2
2020-12-10T22:20:10.209Z,1607638810.209 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:20:17.481Z,1607638817.481 [NAL9602](INFO): SBD MO Status=2, MOMSN=12270, MT Status=2, MTMSN=0
2020-12-10T22:20:17.481Z,1607638817.481 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-12-10T22:20:20.452Z,1607638820.452 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-12-10T22:20:21.518Z,1607638821.518 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:20:32.571Z,1607638832.571 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:20:39.849Z,1607638839.849 [NAL9602](INFO): SBD MO Status=1, MOMSN=12270, MT Status=0, MTMSN=0
2020-12-10T22:20:39.900Z,1607638839.900 [NAL9602](INFO): Sent 184 bytes from file Logs/20201210T215856/Express0008.lzma
2020-12-10T22:20:39.900Z,1607638839.900 [NAL9602](INFO): Packets left to send: 1
2020-12-10T22:20:46.584Z,1607638846.584 [NAL9602](INFO): SBD MO Status=1, MOMSN=12271, MT Status=0, MTMSN=0
2020-12-10T22:20:46.641Z,1607638846.641 [NAL9602](INFO): Sent 55 bytes from file Logs/20201210T215856/Express0008.lzma
2020-12-10T22:20:46.641Z,1607638846.641 [NAL9602](INFO): Packets left to send: 0
2020-12-10T22:20:48.605Z,1607638848.605 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:20:55.592Z,1607638855.592 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-12-10T22:21:01.935Z,1607638861.935 [NAL9602](INFO): SBD MO Status=0, MOMSN=12272, MT Status=0, MTMSN=0
2020-12-10T22:21:02.019Z,1607638862.019 [LBLTest:transit:NeedComms:D] Stopped
2020-12-10T22:21:02.020Z,1607638862.020 [LBLTest:transit:NeedComms:E] Running Loop=1
2020-12-10T22:21:02.418Z,1607638862.418 [LBLTest:transit:NeedComms:E](DEBUG): Initialize ReadDataComponent to sense time_fix
2020-12-10T22:21:04.360Z,1607638864.360 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,222104.00,A,4133.01884,N,07043.61140,W,0.467,210.70,101220,,,A*78
2020-12-10T22:21:04.362Z,1607638864.362 [NAL9602](INFO): GPS fix at 20201210T222104: (41.550314, -70.726857)
2020-12-10T22:21:04.407Z,1607638864.407 [LBLTest:transit:NeedComms:E] Stopped
2020-12-10T22:21:04.407Z,1607638864.407 [LBLTest:transit:NeedComms](INFO): Completed LBLTest:transit:NeedComms
2020-12-10T22:21:04.407Z,1607638864.407 [LBLTest:transit:NeedComms] Stopped
2020-12-10T22:21:04.407Z,1607638864.407 [LBLTest:transit:NeedComms](DEBUG): Aggregate::uninitialize LBLTest:transit:NeedComms
2020-12-10T22:21:04.412Z,1607638864.412 [LBLTest:transit:NeedComms:B.GoToSurface] Stopped
2020-12-10T22:21:04.412Z,1607638864.412 [LBLTest:transit:NeedComms:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2020-12-10T22:21:04.759Z,1607638864.759 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:21:18.585Z,1607638878.585 [RDI_PathfinderUp](ERROR): only read 3 of 4 data items
2020-12-10T22:21:20.919Z,1607638880.919 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:21:30.736Z,1607638890.736 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-12-10T22:21:36.700Z,1607638896.700 [NAL9602](INFO): Not Powering down - fast GPS
2020-12-10T22:21:37.098Z,1607638897.098 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:21:53.239Z,1607638913.239 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:21:59.863Z,1607638919.863 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005779
2020-12-10T22:22:04.551Z,1607638924.551 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:22:04.586Z,1607638924.586 [RDI_PathfinderUp](ERROR): only read 3 of 4 data items
2020-12-10T22:22:15.863Z,1607638935.863 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:22:23.548Z,1607638943.548 [RDI_PathfinderUp](ERROR): only read 3 of 4 data items
2020-12-10T22:22:32.023Z,1607638952.023 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:22:43.756Z,1607638963.756 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for altitude
2020-12-10T22:22:48.185Z,1607638968.185 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:22:53.463Z,1607638973.463 [RDI_PathfinderUp](ERROR): only read 2 of 4 data items
2020-12-10T22:22:59.501Z,1607638979.501 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:23:10.810Z,1607638990.810 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:23:15.714Z,1607638995.714 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T22:23:35.451Z,1607639015.451 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:23:46.771Z,1607639026.771 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:23:52.019Z,1607639032.019 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACST,6,0,20201210222351.308780,06,241,23,0132,0150,59,02,02,00,05,1,012,001,0,4,1,0,150,13.4,3.00,08,0.00,-01,-1.82,32,14500,400*60
 expected 50
2020-12-10T22:23:52.027Z,1607639032.027 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CAEV,222352,AUV,2.0.32731*1D
 expected 4F
2020-12-10T22:24:03.733Z,1607639043.733 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:24:15.048Z,1607639055.048 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:24:26.358Z,1607639066.358 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:24:31.611Z,1607639071.611 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACST,6,0,20201210222430.922979,06,106,20,0093,0150,59,02,02,00,04,1,012,001,0,4,1,0,150,11.0,3.00,07,0.00,-01,-0.82,3,14500,000*6B
 expected 6C
2020-12-10T22:24:42.919Z,1607639082.919 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:24:54.249Z,1607639094.249 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:25:05.551Z,1607639105.551 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:25:10.806Z,1607639110.806 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACST,6,0,20201210222510.138309,6,169,22,0109,0150,59,02,02,00,04,1,012,001,0,4,1,0,150,15.2,4.00,08,-1.00,-01,-1.70,32,14500,4000*40
 expected 70
2020-12-10T22:25:22.122Z,1607639122.122 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:25:33.421Z,1607639133.421 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:25:44.733Z,1607639144.733 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:25:56.043Z,1607639156.043 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:26:07.361Z,1607639167.361 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:26:18.677Z,1607639178.677 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:26:29.981Z,1607639189.981 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:26:35.288Z,1607639195.288 [ElevatorOffsetCalculator](INFO): New estimator for commanded vars: speed 1.00 m/s, pitch 20.00 deg, mass-position -0.36 mm (1 active estimators).
2020-12-10T22:27:14.018Z,1607639234.018 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:27:21.200Z,1607639241.200 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.247360
2020-12-10T22:27:30.579Z,1607639250.579 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:27:35.600Z,1607639255.600 [Radio_Surface](INFO): Powering down
2020-12-10T22:27:47.145Z,1607639267.145 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:27:57.357Z,1607639277.357 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-12-10T22:27:58.362Z,1607639278.362 [DataOverHttps](INFO): Radio surface powered OFF, will not connect.
2020-12-10T22:28:03.721Z,1607639283.721 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:28:34.010Z,1607639314.010 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:28:50.577Z,1607639330.577 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:29:04.331Z,1607639344.331 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC, Data Header,2*00

2020-12-10T22:29:07.141Z,1607639347.141 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:29:18.450Z,1607639358.450 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:29:29.765Z,1607639369.765 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:29:46.353Z,1607639386.353 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:30:02.890Z,1607639402.890 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:30:19.451Z,1607639419.451 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:30:36.022Z,1607639436.022 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:30:47.355Z,1607639447.355 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:30:58.641Z,1607639458.641 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:31:09.954Z,1607639469.954 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:31:21.269Z,1607639481.269 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:31:32.578Z,1607639492.578 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:31:43.890Z,1607639503.890 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:31:55.210Z,1607639515.210 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:32:06.517Z,1607639526.517 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:32:12.174Z,1607639532.174 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CARE,223212,AUV,2.0.32731*19
 expected 4F
2020-12-10T22:32:23.486Z,1607639543.486 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:32:40.074Z,1607639560.074 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:32:56.610Z,1607639576.610 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:33:07.922Z,1607639587.922 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:33:19.240Z,1607639599.240 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:33:30.552Z,1607639610.552 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:33:41.861Z,1607639621.861 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:34:07.714Z,1607639647.714 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:34:19.033Z,1607639659.033 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:34:30.358Z,1607639670.358 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:34:50.541Z,1607639690.541 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:35:01.850Z,1607639701.850 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:35:13.162Z,1607639713.162 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:35:24.471Z,1607639724.471 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:35:35.786Z,1607639735.786 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:35:39.091Z,1607639739.091 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2020-12-10T22:35:47.097Z,1607639747.097 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:35:49.123Z,1607639749.123 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T22:35:58.417Z,1607639758.417 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:36:04.892Z,1607639764.892 [LBLTest:transit:NeedComms] Running Loop=1
2020-12-10T22:36:04.892Z,1607639764.892 [LBLTest:transit:NeedComms](DEBUG): Aggregate::initialize LBLTest:transit:NeedComms
2020-12-10T22:36:04.892Z,1607639764.892 [LBLTest:transit:NeedComms:B.GoToSurface] Running Loop=1
2020-12-10T22:36:04.892Z,1607639764.892 [LBLTest:transit:NeedComms:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2020-12-10T22:36:04.893Z,1607639764.893 [LBLTest:transit:NeedComms:B.GoToSurface](INFO): Received depth rate setting nan m/s.
2020-12-10T22:36:04.893Z,1607639764.893 [LBLTest:transit:NeedComms:B.GoToSurface](INFO): Received pitch setting 19.999999 degrees.
2020-12-10T22:36:04.893Z,1607639764.893 [LBLTest:transit:NeedComms:B.GoToSurface](INFO): Received speed setting 1.000000 m/s.
2020-12-10T22:36:04.894Z,1607639764.894 [LBLTest:transit:NeedComms:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2020-12-10T22:36:04.894Z,1607639764.894 [LBLTest:transit:NeedComms:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2020-12-10T22:36:04.894Z,1607639764.894 [LBLTest:transit:NeedComms:A] Running Loop=1
2020-12-10T22:36:04.916Z,1607639764.916 [LBLTest:transit:NeedComms:A](INFO): last time_fix was: 1607638864.000000 second since 1970/01/01T00:00:00Z 
2020-12-10T22:36:04.916Z,1607639764.916 [LBLTest:transit:NeedComms:A] Stopped
2020-12-10T22:36:09.720Z,1607639769.720 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:36:19.424Z,1607639779.424 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T22:36:21.046Z,1607639781.046 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:36:24.275Z,1607639784.275 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2020-12-10T22:36:29.128Z,1607639789.128 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2020-12-10T22:36:32.350Z,1607639792.350 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:36:38.465Z,1607639798.465 [LBLTest:transit:NeedComms:C] Running Loop=1
2020-12-10T22:36:38.980Z,1607639798.980 [Radio_Surface](INFO): Powering up
2020-12-10T22:36:43.657Z,1607639803.657 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:36:44.517Z,1607639804.517 [DataOverHttps](INFO): Radio surface powered ON.
2020-12-10T22:36:52.212Z,1607639812.212 [BuoyancyServo](FAULT): Overload Error
2020-12-10T22:36:52.212Z,1607639812.212 [BuoyancyServo] Hardware Fault, FailCount= 1
2020-12-10T22:36:52.212Z,1607639812.212 [BuoyancyServo](ERROR): Hardware Fault
2020-12-10T22:36:52.253Z,1607639812.253 [CBIT](ERROR): Hardware Fault in component: BuoyancyServo
2020-12-10T22:36:54.207Z,1607639814.207 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2020-12-10T22:36:54.207Z,1607639814.207 [BuoyancyServo](INFO): Powering down
2020-12-10T22:36:54.973Z,1607639814.973 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:36:55.100Z,1607639815.100 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2020-12-10T22:36:55.100Z,1607639815.100 [BuoyancyServo] No Fault, FailCount= 1
2020-12-10T22:36:55.407Z,1607639815.407 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2020-12-10T22:36:55.408Z,1607639815.408 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2020-12-10T22:36:59.418Z,1607639819.418 [NAL9602](INFO): SBD MO Status=2, MOMSN=12273, MT Status=2, MTMSN=0
2020-12-10T22:36:59.418Z,1607639819.418 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-12-10T22:36:59.438Z,1607639819.438 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2020-12-10T22:37:06.295Z,1607639826.295 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:37:14.636Z,1607639834.636 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-12-10T22:37:15.577Z,1607639835.577 [NAL9602](INFO): SBD MO Status=2, MOMSN=12273, MT Status=2, MTMSN=0
2020-12-10T22:37:15.578Z,1607639835.578 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-12-10T22:37:17.594Z,1607639837.594 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:37:19.215Z,1607639839.215 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2020-12-10T22:37:28.909Z,1607639848.909 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:37:40.222Z,1607639860.222 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:37:49.792Z,1607639869.792 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-12-10T22:37:57.185Z,1607639877.185 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:38:08.112Z,1607639888.112 [NAL9602](INFO): SBD MO Status=0, MOMSN=12273, MT Status=0, MTMSN=0
2020-12-10T22:38:08.113Z,1607639888.113 [NAL9602](INFO): No messages in MT queue
2020-12-10T22:38:09.311Z,1607639889.311 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,223809.00,A,4133.05342,N,07044.10352,W,0.622,342.04,101220,,,A*7E
2020-12-10T22:38:09.313Z,1607639889.313 [NAL9602](INFO): GPS fix at 20201210T223809: (41.550890, -70.735059)
2020-12-10T22:38:09.397Z,1607639889.397 [UniversalFixResidualReporter](INFO): Fix residual: 5.8 %DT, over the last 662.2 m. Residual distance 38.2 m at bearing 74.9 degrees. Fix at (41.5509, -70.7351) with 685.5 m made good.
2020-12-10T22:38:09.405Z,1607639889.405 [LBLTest:transit:NeedComms:C] Stopped
2020-12-10T22:38:09.406Z,1607639889.406 [LBLTest:transit:NeedComms:D] Running Loop=1
2020-12-10T22:38:15.519Z,1607639895.519 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:38:24.945Z,1607639904.945 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-12-10T22:38:25.606Z,1607639905.606 [NAL9602](INFO): SBD MO Status=1, MOMSN=12274, MT Status=0, MTMSN=0
2020-12-10T22:38:25.656Z,1607639905.656 [NAL9602](INFO): Sent 88 bytes from file Logs/20201210T215856/Courier0010.lzma
2020-12-10T22:38:25.656Z,1607639905.656 [NAL9602](INFO): Packets left to send: 0
2020-12-10T22:38:32.221Z,1607639912.221 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:38:34.651Z,1607639914.651 [NAL9602](INFO): SBD MO Status=1, MOMSN=12275, MT Status=0, MTMSN=0
2020-12-10T22:38:34.712Z,1607639914.712 [NAL9602](INFO): Sent 184 bytes from file Logs/20201210T215856/Express0011.lzma
2020-12-10T22:38:34.712Z,1607639914.712 [NAL9602](INFO): Packets left to send: 0
2020-12-10T22:38:43.939Z,1607639923.939 [NAL9602](INFO): SBD MO Status=0, MOMSN=12276, MT Status=0, MTMSN=0
2020-12-10T22:38:44.030Z,1607639924.030 [LBLTest:transit:NeedComms:D] Stopped
2020-12-10T22:38:44.031Z,1607639924.031 [LBLTest:transit:NeedComms:E] Running Loop=1
2020-12-10T22:38:46.361Z,1607639926.361 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,223846.00,A,4133.05117,N,07044.10406,W,0.816,342.04,101220,,,A*78
2020-12-10T22:38:46.363Z,1607639926.363 [NAL9602](INFO): GPS fix at 20201210T223846: (41.550853, -70.735068)
2020-12-10T22:38:46.419Z,1607639926.419 [LBLTest:transit:NeedComms:E] Stopped
2020-12-10T22:38:46.419Z,1607639926.419 [LBLTest:transit:NeedComms](INFO): Completed LBLTest:transit:NeedComms
2020-12-10T22:38:46.419Z,1607639926.419 [LBLTest:transit:NeedComms] Stopped
2020-12-10T22:38:46.420Z,1607639926.420 [LBLTest:transit:NeedComms](DEBUG): Aggregate::uninitialize LBLTest:transit:NeedComms
2020-12-10T22:38:46.420Z,1607639926.420 [LBLTest:transit:NeedComms:B.GoToSurface] Stopped
2020-12-10T22:38:46.420Z,1607639926.420 [LBLTest:transit:NeedComms:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2020-12-10T22:39:00.085Z,1607639940.085 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-12-10T22:39:18.271Z,1607639958.271 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:39:18.678Z,1607639958.678 [NAL9602](INFO): Not Powering down - fast GPS
2020-12-10T22:39:29.583Z,1607639969.583 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:39:35.237Z,1607639975.237 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-12-10T22:39:40.895Z,1607639980.895 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:39:52.207Z,1607639992.207 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:40:03.569Z,1607640003.569 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:40:05.361Z,1607640005.361 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004197
2020-12-10T22:40:14.884Z,1607640014.884 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:40:26.201Z,1607640026.201 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:40:37.514Z,1607640037.514 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:40:48.815Z,1607640048.815 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:41:03.771Z,1607640063.771 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CAREV,224103,COPROC,0.10.046*46
 expected 68
2020-12-10T22:41:04.583Z,1607640064.583 [RDI_PathfinderUp](ERROR): only read 2 of 4 data items
2020-12-10T22:41:20.339Z,1607640080.339 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:41:29.625Z,1607640089.625 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T22:41:31.657Z,1607640091.657 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:41:34.479Z,1607640094.479 [RDI_PathfinderUp](ERROR): only read 3 of 4 data items
2020-12-10T22:41:39.390Z,1607640099.390 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T22:41:42.951Z,1607640102.951 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:41:49.028Z,1607640109.028 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CAREV,224149,COPROC,0.10.0.46*8
 expected 48
2020-12-10T22:41:49.457Z,1607640109.457 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for altitude
2020-12-10T22:41:54.674Z,1607640114.674 [RDI_PathfinderUp](ERROR): only read 2 of 4 data items
2020-12-10T22:41:54.797Z,1607640114.797 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.243492
2020-12-10T22:41:59.533Z,1607640119.533 [RDI_PathfinderUp](ERROR): only read 2 of 4 data items
2020-12-10T22:41:59.816Z,1607640119.816 [DataOverHttps](INFO): Radio surface powered OFF, will not connect.
2020-12-10T22:42:00.164Z,1607640120.164 [Radio_Surface](INFO): Powering down
2020-12-10T22:42:00.729Z,1607640120.729 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:42:06.789Z,1607640126.789 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CAREV,24206,OPROC,0.10.0.46*40
 expected 31
2020-12-10T22:42:14.474Z,1607640134.474 [RDI_PathfinderUp](ERROR): only read 2 of 4 data items
2020-12-10T22:42:18.506Z,1607640138.506 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:42:35.480Z,1607640155.480 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:42:46.787Z,1607640166.787 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:42:58.104Z,1607640178.104 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:43:09.438Z,1607640189.438 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:43:18.709Z,1607640198.709 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC, Data Header,2*00

2020-12-10T22:43:20.722Z,1607640200.722 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:43:31.231Z,1607640211.231 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T22:43:32.037Z,1607640212.037 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:43:52.638Z,1607640232.638 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:44:19.305Z,1607640259.305 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:44:36.689Z,1607640276.689 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:44:54.062Z,1607640294.062 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:45:11.418Z,1607640311.418 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:45:22.730Z,1607640322.730 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:45:34.054Z,1607640334.054 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:45:45.362Z,1607640345.362 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:45:56.663Z,1607640356.663 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:46:07.981Z,1607640367.981 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:46:28.585Z,1607640388.585 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:46:39.900Z,1607640399.900 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:46:57.269Z,1607640417.269 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:47:08.581Z,1607640428.581 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:47:19.890Z,1607640439.890 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:47:37.260Z,1607640457.260 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:47:48.574Z,1607640468.574 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:47:59.886Z,1607640479.886 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:48:17.261Z,1607640497.261 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:48:32.615Z,1607640512.615 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,Bad Modulation Header,0*31

2020-12-10T22:48:34.629Z,1607640514.629 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:48:52.005Z,1607640532.005 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:49:07.375Z,1607640547.375 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC, Data Header,2*00

2020-12-10T22:49:09.374Z,1607640549.374 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:49:26.745Z,1607640566.745 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:49:44.124Z,1607640584.124 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:49:55.427Z,1607640595.427 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:50:16.036Z,1607640616.036 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:50:25.734Z,1607640625.734 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACST,6,0,20201210225025.083000,06,106,14,0101,0150,119,02,02,05,1,009001,0,4,1,0,150,1.5,1.00,02,2.00,-01,-1.73,40,14500,4000*61
 expected 60
2020-12-10T22:50:33.003Z,1607640633.003 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC, Data Header,2*00

2020-12-10T22:50:37.070Z,1607640637.070 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:50:48.380Z,1607640648.380 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:50:57.243Z,1607640657.243 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC, Data Header,2*00

2020-12-10T22:50:59.669Z,1607640659.669 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:51:10.975Z,1607640670.975 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:51:28.754Z,1607640688.754 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:51:40.082Z,1607640700.082 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:51:51.381Z,1607640711.381 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:52:09.157Z,1607640729.157 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:52:20.472Z,1607640740.472 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:52:31.781Z,1607640751.781 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:52:49.557Z,1607640769.557 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:53:07.355Z,1607640787.355 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:53:18.642Z,1607640798.642 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:53:29.954Z,1607640809.954 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:53:36.423Z,1607640816.423 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC, Data Header,2*00

2020-12-10T22:53:41.269Z,1607640821.269 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:53:52.584Z,1607640832.584 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:53:58.281Z,1607640838.281 [LBLTest:transit:NeedComms] Running Loop=1
2020-12-10T22:53:58.281Z,1607640838.281 [LBLTest:transit:NeedComms](DEBUG): Aggregate::initialize LBLTest:transit:NeedComms
2020-12-10T22:53:58.281Z,1607640838.281 [LBLTest:transit:NeedComms:B.GoToSurface] Running Loop=1
2020-12-10T22:53:58.281Z,1607640838.281 [LBLTest:transit:NeedComms:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2020-12-10T22:53:58.281Z,1607640838.281 [LBLTest:transit:NeedComms:B.GoToSurface](INFO): Received depth rate setting nan m/s.
2020-12-10T22:53:58.282Z,1607640838.282 [LBLTest:transit:NeedComms:B.GoToSurface](INFO): Received pitch setting 19.999999 degrees.
2020-12-10T22:53:58.282Z,1607640838.282 [LBLTest:transit:NeedComms:B.GoToSurface](INFO): Received speed setting 1.000000 m/s.
2020-12-10T22:53:58.282Z,1607640838.282 [LBLTest:transit:NeedComms:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2020-12-10T22:53:58.283Z,1607640838.283 [LBLTest:transit:NeedComms:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2020-12-10T22:53:58.283Z,1607640838.283 [LBLTest:transit:NeedComms:A] Running Loop=1
2020-12-10T22:53:58.285Z,1607640838.285 [LBLTest:transit:NeedComms:A](INFO): last time_fix was: 1607639926.000000 second since 1970/01/01T00:00:00Z 
2020-12-10T22:53:58.285Z,1607640838.285 [LBLTest:transit:NeedComms:A] Stopped
2020-12-10T22:54:03.891Z,1607640843.891 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:54:15.202Z,1607640855.202 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:54:26.514Z,1607640866.514 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:54:32.993Z,1607640872.993 [LBLTest:transit:NeedComms:C] Running Loop=1
2020-12-10T22:54:33.628Z,1607640873.628 [Radio_Surface](INFO): Powering up
2020-12-10T22:54:37.823Z,1607640877.823 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:54:39.008Z,1607640879.008 [DataOverHttps](INFO): Radio surface powered ON.
2020-12-10T22:54:47.188Z,1607640887.188 [BuoyancyServo](FAULT): Overload Error
2020-12-10T22:54:47.188Z,1607640887.188 [BuoyancyServo] Hardware Fault, FailCount= 1
2020-12-10T22:54:47.188Z,1607640887.188 [BuoyancyServo](ERROR): Hardware Fault
2020-12-10T22:54:47.229Z,1607640887.229 [CBIT](ERROR): Hardware Fault in component: BuoyancyServo
2020-12-10T22:54:49.141Z,1607640889.141 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:54:49.197Z,1607640889.197 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2020-12-10T22:54:49.197Z,1607640889.197 [BuoyancyServo](INFO): Powering down
2020-12-10T22:54:50.107Z,1607640890.107 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2020-12-10T22:54:50.107Z,1607640890.107 [BuoyancyServo] No Fault, FailCount= 1
2020-12-10T22:54:50.393Z,1607640890.393 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2020-12-10T22:54:50.394Z,1607640890.394 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2020-12-10T22:54:53.188Z,1607640893.188 [NAL9602](IMPORTANT): SBD MO Status=0, MOMSN=12277, MT Status=1, MTMSN=520
2020-12-10T22:54:53.188Z,1607640893.188 [NAL9602](INFO): Data available in MT queue
2020-12-10T22:54:53.680Z,1607640893.680 [NAL9602](INFO): Received command:stop
2020-12-10T22:54:53.780Z,1607640893.780 [CommandLine](IMPORTANT): got command stop
2020-12-10T22:54:53.781Z,1607640893.781 [CommandLine](IMPORTANT): Scheduling is paused
2020-12-10T22:54:53.781Z,1607640893.781 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2020-12-10T22:54:54.023Z,1607640894.023 [MissionManager](INFO): MissionManager is completed.
2020-12-10T22:54:54.023Z,1607640894.023 [MissionManager](INFO): Uninitializing Mission LBLTest
2020-12-10T22:54:54.023Z,1607640894.023 [LBLTest] Stopped
2020-12-10T22:54:54.024Z,1607640894.024 [LBLTest](DEBUG): Aggregate::uninitialize LBLTest
2020-12-10T22:54:54.024Z,1607640894.024 [LBLTest:WhenAgg] Stopped
2020-12-10T22:54:54.024Z,1607640894.024 [LBLTest:WhenAgg](DEBUG): Aggregate::uninitialize LBLTest:WhenAgg
2020-12-10T22:54:54.024Z,1607640894.024 [LBLTest:WhenAgg:A] Stopped
2020-12-10T22:54:54.024Z,1607640894.024 [LBLTest:WhenAgg:B] Stopped
2020-12-10T22:54:54.024Z,1607640894.024 [LBLTest:WhenAgg:C] Stopped
2020-12-10T22:54:54.024Z,1607640894.024 [LBLTest:WhenAgg:D.LBL] Stopped
2020-12-10T22:54:54.024Z,1607640894.024 [LBLTest:WhenAgg:D.LBL](DEBUG): Uninitialize LBLComponent.
2020-12-10T22:54:54.024Z,1607640894.024 [LBLTest:transit] Stopped
2020-12-10T22:54:54.024Z,1607640894.024 [LBLTest:transit](DEBUG): Aggregate::uninitialize LBLTest:transit
2020-12-10T22:54:54.024Z,1607640894.024 [LBLTest:transit:NeedComms] Stopped
2020-12-10T22:54:54.025Z,1607640894.025 [LBLTest:transit:NeedComms](DEBUG): Aggregate::uninitialize LBLTest:transit:NeedComms
2020-12-10T22:54:54.025Z,1607640894.025 [LBLTest:transit:NeedComms:B.GoToSurface] Stopped
2020-12-10T22:54:54.025Z,1607640894.025 [LBLTest:transit:NeedComms:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2020-12-10T22:54:54.025Z,1607640894.025 [LBLTest:transit:NeedComms:C] Stopped
2020-12-10T22:54:54.025Z,1607640894.025 [LBLTest:transit:StandardEnvelopes] Stopped
2020-12-10T22:54:54.025Z,1607640894.025 [LBLTest:transit:StandardEnvelopes](DEBUG): Aggregate::uninitialize LBLTest:transit:StandardEnvelopes
2020-12-10T22:54:54.025Z,1607640894.025 [LBLTest:transit:StandardEnvelopes:A.AltitudeEnvelope] Stopped
2020-12-10T22:54:54.025Z,1607640894.025 [LBLTest:transit:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2020-12-10T22:54:54.025Z,1607640894.025 [LBLTest:transit:StandardEnvelopes:B.DepthEnvelope] Stopped
2020-12-10T22:54:54.025Z,1607640894.025 [LBLTest:transit:StandardEnvelopes:B.DepthEnvelope](DEBUG): Uninitialize.
2020-12-10T22:54:54.025Z,1607640894.025 [LBLTest:transit:StandardEnvelopes:C.OffshoreEnvelope] Stopped
2020-12-10T22:54:54.025Z,1607640894.025 [LBLTest:transit:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2020-12-10T22:54:54.025Z,1607640894.025 [LBLTest:transit:BuoyancyHold.Buoyancy] Stopped
2020-12-10T22:54:54.026Z,1607640894.026 [LBLTest:transit:BuoyancyHold.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2020-12-10T22:54:54.026Z,1607640894.026 [LBLTest:transit:MassHold.Pitch] Stopped
2020-12-10T22:54:54.026Z,1607640894.026 [LBLTest:transit:Transit] Stopped
2020-12-10T22:54:54.026Z,1607640894.026 [LBLTest:transit:Transit](DEBUG): Aggregate::uninitialize LBLTest:transit:Transit
2020-12-10T22:54:54.026Z,1607640894.026 [LBLTest:transit:Transit:A.Pitch] Stopped
2020-12-10T22:54:54.026Z,1607640894.026 [LBLTest:transit:Transit:B.SetSpeed] Stopped
2020-12-10T22:54:54.026Z,1607640894.026 [LBLTest:transit:Transit:B.SetSpeed](DEBUG): Uninitialize.
2020-12-10T22:54:54.026Z,1607640894.026 [LBLTest:transit:Transit:Wpt1.Waypoint] Stopped
2020-12-10T22:54:54.026Z,1607640894.026 [LBLTest:transit:Transit:Wpt1.Waypoint](DEBUG): Uninitialize WaypointComponent.
2020-12-10T22:54:54.447Z,1607640894.447 [MissionManager](IMPORTANT): Started mission DefaultWithUndock
2020-12-10T22:54:54.447Z,1607640894.447 [DefaultWithUndock] Running Loop=1
2020-12-10T22:54:54.447Z,1607640894.447 [DefaultWithUndock](DEBUG): Aggregate::initialize DefaultWithUndock
2020-12-10T22:54:54.448Z,1607640894.448 [DefaultWithUndock:A.Wait] Running Loop=1
2020-12-10T22:54:54.448Z,1607640894.448 [DefaultWithUndock:A.Wait](DEBUG): Initialize Wait Component.
2020-12-10T22:54:54.804Z,1607640894.804 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,225455.00,A,4133.07997,N,07044.61835,W,0.700,296.90,101220,,,A*75
2020-12-10T22:54:54.806Z,1607640894.806 [NAL9602](INFO): GPS fix at 20201210T225455: (41.551333, -70.743639)
2020-12-10T22:54:54.818Z,1607640894.818 [UniversalFixResidualReporter](INFO): Fix residual: 4.1 %DT, over the last 693.7 m. Residual distance 28.7 m at bearing 77.5 degrees. Fix at (41.5513, -70.7436) with 715.3 m made good.
2020-12-10T22:55:00.447Z,1607640900.447 [Micromodem](INFO): Ping timeout for: 
2020-12-10T22:55:00.450Z,1607640900.450 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T22:55:09.132Z,1607640909.132 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-12-10T22:55:24.705Z,1607640924.705 [DefaultWithUndock:A.Wait](INFO): Done Waiting.
2020-12-10T22:55:24.705Z,1607640924.705 [DefaultWithUndock:A.Wait] Stopped
2020-12-10T22:55:24.705Z,1607640924.705 [DefaultWithUndock:A.Wait](DEBUG): Uninitialize Wait Component.
2020-12-10T22:55:24.705Z,1607640924.705 [DefaultWithUndock:LeaveDock] Running Loop=1
2020-12-10T22:55:24.705Z,1607640924.705 [DefaultWithUndock:LeaveDock](DEBUG): Aggregate::initialize DefaultWithUndock:LeaveDock
2020-12-10T22:55:24.705Z,1607640924.705 [DefaultWithUndock:LeaveDock:A.] Running Loop=1
2020-12-10T22:55:24.705Z,1607640924.705 [DefaultWithUndock:LeaveDock:A.](INFO): Initializing TrackAcousticContact.
2020-12-10T22:55:24.706Z,1607640924.706 [DefaultWithUndock:LeaveDock:B.Undock] Running Loop=1
2020-12-10T22:55:24.706Z,1607640924.706 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initialize.
2020-12-10T22:55:24.706Z,1607640924.706 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initializing internal variables to default values.
2020-12-10T22:55:27.547Z,1607640927.547 [NAL9602](INFO): Not Powering down - fast GPS
2020-12-10T22:55:27.569Z,1607640927.569 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T22:55:28.825Z,1607640928.825 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detaching from dock.
2020-12-10T22:55:29.191Z,1607640929.191 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detected possible detachment. Starting timer.
2020-12-10T22:55:30.410Z,1607640930.410 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T22:55:31.993Z,1607640931.993 [DUSBL_Hydroid](ERROR): No response from remote modem.
2020-12-10T22:55:33.237Z,1607640933.237 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T22:55:36.053Z,1607640936.053 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T22:55:37.645Z,1607640937.645 [DUSBL_Hydroid](ERROR): No response from remote modem.
2020-12-10T22:55:38.873Z,1607640938.873 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T22:55:41.723Z,1607640941.723 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T22:55:43.309Z,1607640943.309 [DUSBL_Hydroid](ERROR): No response from remote modem.
2020-12-10T22:55:44.288Z,1607640944.288 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-12-10T22:55:44.545Z,1607640944.545 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T22:55:47.370Z,1607640947.370 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T22:55:48.961Z,1607640948.961 [DUSBL_Hydroid](ERROR): No response from remote modem.
2020-12-10T22:55:49.387Z,1607640949.387 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detached at range: 1104.18 m. Transitioning DDM to standby.
2020-12-10T22:55:50.211Z,1607640950.211 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T22:55:52.252Z,1607640952.252 [DefaultWithUndock:LeaveDock:B.Undock](INFO): DDM at standby.
2020-12-10T22:55:52.615Z,1607640952.615 [DefaultWithUndock:LeaveDock:B.Undock](IMPORTANT): Undocking sequence complete.
2020-12-10T22:55:52.615Z,1607640952.615 [DefaultWithUndock:LeaveDock:B.Undock] Stopped
2020-12-10T22:55:52.616Z,1607640952.616 [DefaultWithUndock:LeaveDock](INFO): Completed DefaultWithUndock:LeaveDock
2020-12-10T22:55:52.616Z,1607640952.616 [DefaultWithUndock:LeaveDock] Stopped
2020-12-10T22:55:52.616Z,1607640952.616 [DefaultWithUndock:LeaveDock](DEBUG): Aggregate::uninitialize DefaultWithUndock:LeaveDock
2020-12-10T22:55:52.616Z,1607640952.616 [DefaultWithUndock:LeaveDock:A.] Stopped
2020-12-10T22:55:52.616Z,1607640952.616 [DefaultWithUndock:SurfaceDefault] Running Loop=1
2020-12-10T22:55:52.616Z,1607640952.616 [DefaultWithUndock:SurfaceDefault](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault
2020-12-10T22:55:52.616Z,1607640952.616 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen] Running Loop=1
2020-12-10T22:55:52.616Z,1607640952.616 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:HoldLatchOpen
2020-12-10T22:55:52.616Z,1607640952.616 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen:A] Running Loop=1
2020-12-10T22:55:52.617Z,1607640952.617 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen:B] Running Loop=1
2020-12-10T22:55:52.617Z,1607640952.617 [DefaultWithUndock:SurfaceDefault:B.GoToSurface] Running Loop=1
2020-12-10T22:55:52.617Z,1607640952.617 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2020-12-10T22:55:52.617Z,1607640952.617 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2020-12-10T22:55:52.617Z,1607640952.617 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2020-12-10T22:55:52.618Z,1607640952.618 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2020-12-10T22:55:52.618Z,1607640952.618 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2020-12-10T22:55:52.618Z,1607640952.618 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2020-12-10T22:55:52.979Z,1607640952.979 [DefaultWithUndock:SurfaceDefault:CheckIn] Running Loop=1
2020-12-10T22:55:52.979Z,1607640952.979 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:CheckIn
2020-12-10T22:55:52.979Z,1607640952.979 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Running Loop=1
2020-12-10T22:55:52.979Z,1607640952.979 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen] Stopped
2020-12-10T22:55:52.979Z,1607640952.979 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:HoldLatchOpen
2020-12-10T22:55:52.979Z,1607640952.979 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen:A] Stopped
2020-12-10T22:55:52.979Z,1607640952.979 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen:B] Stopped
2020-12-10T22:55:54.991Z,1607640954.991 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,225555.00,A,4133.07799,N,07044.62255,W,0.311,296.90,101220,,,A*7F
2020-12-10T22:55:54.994Z,1607640954.994 [NAL9602](INFO): GPS fix at 20201210T225555: (41.551300, -70.743709)
2020-12-10T22:55:55.029Z,1607640955.029 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Stopped
2020-12-10T22:55:55.029Z,1607640955.029 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Running Loop=1
2020-12-10T22:56:12.123Z,1607640972.123 [NAL9602](INFO): SBD MO Status=1, MOMSN=12278, MT Status=0, MTMSN=0
2020-12-10T22:56:12.178Z,1607640972.178 [NAL9602](INFO): Sent 86 bytes from file Logs/20201210T215856/Courier0013.lzma
2020-12-10T22:56:12.178Z,1607640972.178 [NAL9602](INFO): Packets left to send: 0
2020-12-10T22:56:19.428Z,1607640979.428 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-12-10T22:56:23.599Z,1607640983.599 [NAL9602](INFO): SBD MO Status=1, MOMSN=12279, MT Status=0, MTMSN=0
2020-12-10T22:56:23.648Z,1607640983.648 [NAL9602](INFO): Sent 184 bytes from file Logs/20201210T215856/Express0014.lzma
2020-12-10T22:56:23.648Z,1607640983.648 [NAL9602](INFO): Packets left to send: 2
2020-12-10T22:56:35.025Z,1607640995.025 [NAL9602](INFO): SBD MO Status=1, MOMSN=12280, MT Status=0, MTMSN=0
2020-12-10T22:56:35.074Z,1607640995.074 [NAL9602](INFO): Sent 184 bytes from file Logs/20201210T215856/Express0014.lzma
2020-12-10T22:56:35.074Z,1607640995.074 [NAL9602](INFO): Packets left to send: 1
2020-12-10T22:56:47.308Z,1607641007.308 [NAL9602](INFO): SBD MO Status=1, MOMSN=12281, MT Status=0, MTMSN=0
2020-12-10T22:56:47.369Z,1607641007.369 [NAL9602](INFO): Sent 128 bytes from file Logs/20201210T215856/Express0014.lzma
2020-12-10T22:56:47.369Z,1607641007.369 [NAL9602](INFO): Packets left to send: 0
2020-12-10T22:56:50.140Z,1607641010.140 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2020-12-10T22:56:54.570Z,1607641014.570 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-12-10T22:56:57.816Z,1607641017.816 [NAL9602](INFO): SBD MO Status=0, MOMSN=12282, MT Status=0, MTMSN=0
2020-12-10T22:56:57.915Z,1607641017.915 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Stopped
2020-12-10T22:56:57.915Z,1607641017.915 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Running Loop=1
2020-12-10T22:56:57.915Z,1607641017.915 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-12-10T22:57:10.334Z,1607641030.334 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T22:57:15.197Z,1607641035.197 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T22:57:28.564Z,1607641048.564 [NAL9602](INFO): Not Powering down - fast GPS
2020-12-10T22:57:29.716Z,1607641049.716 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-12-10T22:57:59.869Z,1607641079.869 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003670
2020-12-10T22:58:17.103Z,1607641097.103 [CommandLine](IMPORTANT): got command schedule clear
2020-12-10T22:58:17.103Z,1607641097.103 [CommandLine](IMPORTANT): #Cleared scheduled commands:0
2020-12-10T22:58:21.988Z,1607641101.988 [CommandLine](IMPORTANT): got command schedule resume
2020-12-10T22:58:21.988Z,1607641101.988 [CommandLine](IMPORTANT): Scheduling is resumed
2020-12-10T23:01:58.404Z,1607641318.404 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](INFO): Done Waiting.
2020-12-10T23:01:58.404Z,1607641318.404 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Stopped
2020-12-10T23:01:58.405Z,1607641318.405 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-12-10T23:01:58.405Z,1607641318.405 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Running Loop=1
2020-12-10T23:01:58.812Z,1607641318.812 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Stopped
2020-12-10T23:01:58.812Z,1607641318.812 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Running Loop=1
2020-12-10T23:01:59.219Z,1607641319.219 [DefaultWithUndock:SurfaceDefault:CheckIn:E](IMPORTANT): Default mission has been running for 7.072744 min 
2020-12-10T23:01:59.220Z,1607641319.220 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Stopped
2020-12-10T23:01:59.220Z,1607641319.220 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Completed DefaultWithUndock:SurfaceDefault:CheckIn
2020-12-10T23:01:59.220Z,1607641319.220 [DefaultWithUndock:SurfaceDefault:CheckIn] Stopped
2020-12-10T23:01:59.220Z,1607641319.220 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:CheckIn
2020-12-10T23:01:59.220Z,1607641319.220 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Running loop #2
2020-12-10T23:01:59.220Z,1607641319.220 [DefaultWithUndock:SurfaceDefault:CheckIn] Running Loop=2
2020-12-10T23:01:59.220Z,1607641319.220 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:CheckIn
2020-12-10T23:01:59.221Z,1607641319.221 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Running Loop=1
2020-12-10T23:02:01.214Z,1607641321.214 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,230201.00,A,4133.05430,N,07044.63052,W,0.156,199.24,101220,,,A*79
2020-12-10T23:02:01.216Z,1607641321.216 [NAL9602](INFO): GPS fix at 20201210T230201: (41.550905, -70.743842)
2020-12-10T23:02:01.261Z,1607641321.261 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Stopped
2020-12-10T23:02:01.262Z,1607641321.262 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Running Loop=1
2020-12-10T23:02:04.851Z,1607641324.851 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20201210T215856/Courier0016.lzma
2020-12-10T23:02:05.854Z,1607641325.854 [DataOverHttps](INFO): Moved sent file to Logs/20201210T215856/Courier0016.lzma.bak
2020-12-10T23:02:05.854Z,1607641325.854 [DataOverHttps](INFO): SBD MOMSN=62174
2020-12-10T23:02:14.892Z,1607641334.892 [DataOverHttps](INFO): Sending 242 bytes from file Logs/20201210T215856/Express0017.lzma
2020-12-10T23:02:15.894Z,1607641335.894 [DataOverHttps](INFO): Moved sent file to Logs/20201210T215856/Express0017.lzma.bak
2020-12-10T23:02:15.894Z,1607641335.894 [DataOverHttps](INFO): SBD MOMSN=62177
2020-12-10T23:02:16.166Z,1607641336.166 [NAL9602](INFO): SBD MO Status=0, MOMSN=12283, MT Status=0, MTMSN=0
2020-12-10T23:02:16.166Z,1607641336.166 [NAL9602](INFO): No messages in MT queue
2020-12-10T23:02:17.447Z,1607641337.447 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Stopped
2020-12-10T23:02:17.447Z,1607641337.447 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Running Loop=1
2020-12-10T23:02:17.447Z,1607641337.447 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-12-10T23:02:38.806Z,1607641358.806 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for altitude
2020-12-10T23:02:46.873Z,1607641366.873 [NAL9602](INFO): Not Powering down - fast GPS
2020-12-10T23:03:32.210Z,1607641412.210 [DataOverHttps](IMPORTANT): SBD MTMSN=20201210T230332
2020-12-10T23:03:36.228Z,1607641416.228 [DataOverHttps](INFO): Received command:sched asap "load Science/sci2.xml;set sci2.Lat1 41.564004 degree;set sci2.Lon1 -70.698608 degree;set sci2.YoYoMinDepth 3 meter;set sci2.YoYoMaxDepth 7 meter;set sci2.YoYoMinAltitude 3 meter;set sci2.YoYoUpPitch 15 degree" cw1g 1 2
2020-12-10T23:03:36.242Z,1607641416.242 [CommandLine](IMPORTANT): got command schedule asap "load Science/sci2.xml;set sci2.Lat1 41.564004 degree;set sci2.Lon1 -70.698608 degree;set sci2.YoYoMinDepth 3 meter;set sci2.YoYoMaxDepth 7 meter;set sci2.YoYoMinAltitude 3 meter;set sci2.YoYoUpPitch 15 degree" cw1g 1 2.000000
2020-12-10T23:03:36.242Z,1607641416.242 [CommandLine](IMPORTANT): Scheduling command #1 of 2 with id=cw1g
2020-12-10T23:03:36.243Z,1607641416.243 [CommandLine](IMPORTANT): Scheduled #4 (#1 of 2 with id='cw1g'): "load Science/sci2.xml;set sci2.Lat1 41.564004 degree;set sci2.Lon1 -70.698608 degree;set sci2.YoYoMinDepth 3 meter;set sci2.YoYoMaxDepth 7 meter;set sci2.YoYoMinAltitude 3 meter;set sci2.YoYoUpPitch 15 degree" ASAP
2020-12-10T23:03:37.231Z,1607641417.231 [DataOverHttps](IMPORTANT): SBD MTMSN=20201210T230337
2020-12-10T23:03:41.248Z,1607641421.248 [DataOverHttps](INFO): Received command:sched asap "set sci2.YoYoDownPitch -15 degree;set sci2.MinAltitude 3 meter;set sci2.MaxDepth 9 meter;set sci2.MinOffshore 500 kilometer;run" cw1g 2 2
2020-12-10T23:03:41.293Z,1607641421.293 [CommandLine](IMPORTANT): got command schedule asap "set sci2.YoYoDownPitch -15 degree;set sci2.MinAltitude 3 meter;set sci2.MaxDepth 9 meter;set sci2.MinOffshore 500 kilometer;run" cw1g 2 2.000000
2020-12-10T23:03:41.294Z,1607641421.294 [CommandLine](IMPORTANT): Scheduling command #2 of 2 with id=cw1g
2020-12-10T23:03:41.294Z,1607641421.294 [CommandLine](IMPORTANT): Scheduled #5 (#2 of 2 with id='cw1g'): "set sci2.YoYoDownPitch -15 degree;set sci2.MinAltitude 3 meter;set sci2.MaxDepth 9 meter;set sci2.MinOffshore 500 kilometer;run" ASAP
2020-12-10T23:03:41.488Z,1607641421.488 [CommandLine](IMPORTANT): got command load ./Missions/Science/sci2.xml
2020-12-10T23:03:41.489Z,1607641421.489 [MissionManager](INFO): Loading Mission: ./Missions/Science/sci2.xml
2020-12-10T23:03:41.725Z,1607641421.725 [MissionManager](INFO): DefineArg sci2.MissionTimeout = 2.000000 h
2020-12-10T23:03:41.728Z,1607641421.728 [MissionManager](INFO): DefineArg sci2.NeedCommsTime = 60.000000 min
2020-12-10T23:03:41.731Z,1607641421.731 [MissionManager](INFO): DefineArg sci2.Repeat = 1.000000 count
2020-12-10T23:03:41.738Z,1607641421.738 [MissionManager](INFO): DefineArg sci2.Lat1 = nan deg
2020-12-10T23:03:41.741Z,1607641421.741 [MissionManager](INFO): DefineArg sci2.Lon1 = nan deg
2020-12-10T23:03:41.776Z,1607641421.776 [MissionManager](INFO): DefineArg sci2.Lat2 = nan deg
2020-12-10T23:03:41.779Z,1607641421.779 [MissionManager](INFO): DefineArg sci2.Lon2 = nan deg
2020-12-10T23:03:41.787Z,1607641421.787 [MissionManager](INFO): DefineArg sci2.Lat3 = nan deg
2020-12-10T23:03:41.835Z,1607641421.835 [MissionManager](INFO): DefineArg sci2.Lon3 = nan deg
2020-12-10T23:03:41.850Z,1607641421.850 [MissionManager](INFO): DefineArg sci2.Lat4 = nan deg
2020-12-10T23:03:41.873Z,1607641421.873 [MissionManager](INFO): DefineArg sci2.Lon4 = nan deg
2020-12-10T23:03:41.875Z,1607641421.875 [MissionManager](INFO): DefineArg sci2.Lat5 = nan deg
2020-12-10T23:03:41.895Z,1607641421.895 [MissionManager](INFO): DefineArg sci2.Lon5 = nan deg
2020-12-10T23:03:41.906Z,1607641421.906 [MissionManager](INFO): DefineArg sci2.Lat6 = nan deg
2020-12-10T23:03:41.930Z,1607641421.930 [MissionManager](INFO): DefineArg sci2.Lon6 = nan deg
2020-12-10T23:03:41.952Z,1607641421.952 [MissionManager](INFO): DefineArg sci2.Lat7 = nan deg
2020-12-10T23:03:41.955Z,1607641421.955 [MissionManager](INFO): DefineArg sci2.Lon7 = nan deg
2020-12-10T23:03:41.966Z,1607641421.966 [MissionManager](INFO): DefineArg sci2.Speed = 1.000000 m/s
2020-12-10T23:03:41.988Z,1607641421.988 [MissionManager](INFO): DefineArg sci2.CaptureRadius = nan m
2020-12-10T23:03:41.991Z,1607641421.991 [MissionManager](INFO): DefineArg sci2.YoYoMinDepth = 2.000000 m
2020-12-10T23:03:42.002Z,1607641422.002 [MissionManager](INFO): DefineArg sci2.YoYoMaxDepth = 200.000000 m
2020-12-10T23:03:42.006Z,1607641422.006 [MissionManager](INFO): DefineArg sci2.YoYoMinAltitude = 9.000000 m
2020-12-10T23:03:42.025Z,1607641422.025 [MissionManager](INFO): DefineArg sci2.YoYoUpPitch = 20.000000 deg
2020-12-10T23:03:42.036Z,1607641422.036 [MissionManager](INFO): DefineArg sci2.YoYoDownPitch = -20.000000 deg
2020-12-10T23:03:42.049Z,1607641422.049 [MissionManager](INFO): DefineArg sci2.BuoyancyNeutral = 114.655586 cc
2020-12-10T23:03:42.061Z,1607641422.061 [MissionManager](INFO): DefineArg sci2.MassDefault = -0.036424 cm
2020-12-10T23:03:42.097Z,1607641422.097 [MissionManager](INFO): DefineArg sci2.MinAltitude = 5.000000 m
2020-12-10T23:03:42.109Z,1607641422.109 [MissionManager](INFO): DefineArg sci2.MaxDepth = 205.000000 m
2020-12-10T23:03:42.120Z,1607641422.120 [MissionManager](INFO): DefineArg sci2.MinOffshore = 2.000000 km
2020-12-10T23:03:42.121Z,1607641422.121 [MissionManager](INFO): Inserting Stack: Missions/Insert/Science.xml
2020-12-10T23:03:42.751Z,1607641422.751 [MissionManager](INFO): DefineArg sci2:Science.PeakDetectChlActive = 0 bool
2020-12-10T23:03:42.762Z,1607641422.762 [MissionManager](INFO): DefineArg sci2:Science.TimeWindowPeakReport = nan min
2020-12-10T23:03:42.785Z,1607641422.785 [MissionManager](INFO): DefineArg sci2:Science.HighestChlPeakReportActive = 0 bool
2020-12-10T23:03:42.788Z,1607641422.788 [MissionManager](INFO): DefineArg sci2:Science.PatchTracking = 0 bool
2020-12-10T23:03:42.806Z,1607641422.806 [MissionManager](INFO): DefineArg sci2:Science.FilterWidthHorizontal = 3.000000 count
2020-12-10T23:03:42.809Z,1607641422.809 [MissionManager](INFO): DefineArg sci2:Science.NumProfilesSlidingwindow = 100.000000 count
2020-12-10T23:03:42.820Z,1607641422.820 [MissionManager](INFO): DefineArg sci2:Science.OffPeakFractionHorizontal = 80.000000 %
2020-12-10T23:03:42.823Z,1607641422.823 [MissionManager](INFO): DefineArg sci2:Science.PeakDetectNO3Active = 0 bool
2020-12-10T23:03:42.834Z,1607641422.834 [MissionManager](INFO): DefineArg sci2:Science.PeakDetectOilActive = 0 bool
2020-12-10T23:03:42.841Z,1607641422.841 [MissionManager](INFO): DefineArg sci2:Science.PeakDetectFDOMActive = 0 bool
2020-12-10T23:03:42.856Z,1607641422.856 [MissionManager](INFO): DefineArg sci2:Science.UpwardDerivativeOfTemperatureActive = 0 bool
2020-12-10T23:03:42.859Z,1607641422.859 [MissionManager](INFO): DefineArg sci2:Science.EnabledAanderaaO2 = 0 bool
2020-12-10T23:03:42.871Z,1607641422.871 [MissionManager](INFO): DefineArg sci2:Science.EnabledNeilBrown = 0 bool
2020-12-10T23:03:42.879Z,1607641422.879 [MissionManager](INFO): DefineArg sci2:Science.EnabledSeabird = 1 bool
2020-12-10T23:03:42.895Z,1607641422.895 [MissionManager](INFO): DefineArg sci2:Science.EnabledWetLabsBB2FL = 0 bool
2020-12-10T23:03:42.907Z,1607641422.907 [MissionManager](INFO): DefineArg sci2:Science.EnabledWetLabsSeaOWL_UV_A = 1 bool
2020-12-10T23:03:42.915Z,1607641422.915 [MissionManager](INFO): DefineArg sci2:Science.EnabledWetLabsUBAT = 0 bool
2020-12-10T23:03:42.931Z,1607641422.931 [MissionManager](INFO): DefineArg sci2:Science.LowPassWindowLength = 20.000000 count
2020-12-10T23:03:42.938Z,1607641422.938 [MissionManager](INFO): DefineArg sci2:Science.MedianFilterLen = 5.000000 count
2020-12-10T23:03:42.953Z,1607641422.953 [MissionManager](INFO): DefineArg sci2:Science.PeakShallowBound = nan m
2020-12-10T23:03:42.964Z,1607641422.964 [MissionManager](INFO): DefineArg sci2:Science.PeakDeepBound = nan m
2020-12-10T23:03:42.967Z,1607641422.967 [MissionManager](INFO): DefineOutput sci2:Science.PeakChl = 0.000000 ug/l
2020-12-10T23:03:42.986Z,1607641422.986 [MissionManager](INFO): DefineOutput sci2:Science.PeakChlDepth = 0.000000 m
2020-12-10T23:03:42.989Z,1607641422.989 [MissionManager](INFO): DefineOutput sci2:Science.PeakChlTemperature = 0.000000 degC
2020-12-10T23:03:42.997Z,1607641422.997 [MissionManager](INFO): DefineOutput sci2:Science.PeakChlLatitude = nan deg
2020-12-10T23:03:43.056Z,1607641423.056 [MissionManager](INFO): DefineOutput sci2:Science.PeakChlLongitude = nan deg
2020-12-10T23:03:43.093Z,1607641423.093 [MissionManager](INFO): DefineOutput sci2:Science.PeakNO3 = 0.000000 umol/l
2020-12-10T23:03:43.110Z,1607641423.110 [MissionManager](INFO): DefineOutput sci2:Science.PeakNO3Depth = 0.000000 m
2020-12-10T23:03:43.129Z,1607641423.129 [MissionManager](INFO): DefineOutput sci2:Science.PeakNO3Latitude = nan deg
2020-12-10T23:03:43.144Z,1607641423.144 [MissionManager](INFO): DefineOutput sci2:Science.PeakNO3Longitude = nan deg
2020-12-10T23:03:43.158Z,1607641423.158 [MissionManager](INFO): DefineOutput sci2:Science.PatchChl = 0.000000 m
2020-12-10T23:03:43.167Z,1607641423.167 [MissionManager](INFO): DefineOutput sci2:Science.PatchChlDepth = 0.000000 m
2020-12-10T23:03:43.178Z,1607641423.178 [MissionManager](INFO): DefineOutput sci2:Science.PatchChlLatitude = nan deg
2020-12-10T23:03:43.182Z,1607641423.182 [MissionManager](INFO): DefineOutput sci2:Science.PatchChlLongitude = nan deg
2020-12-10T23:03:43.201Z,1607641423.201 [MissionManager](INFO): DefineOutput sci2:Science.PatchChlDistance = nan m
2020-12-10T23:03:43.206Z,1607641423.206 [MissionManager](INFO): DefineOutput sci2:Science.PeakOil = 0.000000 kg/m3
2020-12-10T23:03:43.226Z,1607641423.226 [MissionManager](INFO): DefineOutput sci2:Science.PeakOilDepth = 0.000000 m
2020-12-10T23:03:43.237Z,1607641423.237 [MissionManager](INFO): DefineOutput sci2:Science.PeakOilLatitude = nan deg
2020-12-10T23:03:43.241Z,1607641423.241 [MissionManager](INFO): DefineOutput sci2:Science.PeakOilLongitude = nan deg
2020-12-10T23:03:43.261Z,1607641423.261 [MissionManager](INFO): DefineOutput sci2:Science.PeakFDOM = 0.000000 ppb
2020-12-10T23:03:43.272Z,1607641423.272 [MissionManager](INFO): DefineOutput sci2:Science.PeakFDOMDepth = 0.000000 m
2020-12-10T23:03:43.277Z,1607641423.277 [MissionManager](INFO): DefineOutput sci2:Science.PeakFDOMLatitude = nan deg
2020-12-10T23:03:43.286Z,1607641423.286 [MissionManager](INFO): DefineOutput sci2:Science.PeakFDOMLongitude = nan deg
2020-12-10T23:03:43.298Z,1607641423.298 [MissionManager](INFO): DefineOutput sci2:Science.PatchFDOMDistance = nan m
2020-12-10T23:03:43.458Z,1607641423.458 [sci2:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2020-12-10T23:03:43.515Z,1607641423.515 [sci2:Science:HighestChlPeakReport:A.PeakDetectHorizontal](DEBUG): Construct PeakDetectHorizontal.
2020-12-10T23:03:43.584Z,1607641423.584 [sci2:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2020-12-10T23:03:43.634Z,1607641423.634 [sci2:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2020-12-10T23:03:43.658Z,1607641423.658 [sci2:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2020-12-10T23:03:43.694Z,1607641423.694 [MissionManager](INFO): RedefineArg sci2:Science.PeakDetectChlActive = value:1 bool
2020-12-10T23:03:43.694Z,1607641423.694 [MissionManager](INFO): Inserting Stack: Missions/Insert/NeedComms.xml
2020-12-10T23:03:43.804Z,1607641423.804 [MissionManager](INFO): DefineArg sci2:NeedComms.DiveInterval = 3.000000 h
2020-12-10T23:03:43.807Z,1607641423.807 [MissionManager](INFO): DefineArg sci2:NeedComms.WaitForPitchUp = 10.000000 min
2020-12-10T23:03:43.818Z,1607641423.818 [MissionManager](INFO): DefineArg sci2:NeedComms.SurfacePitch = 20.000000 deg
2020-12-10T23:03:43.863Z,1607641423.863 [MissionManager](INFO): DefineArg sci2:NeedComms.SurfaceDepthRate = nan m/s
2020-12-10T23:03:43.886Z,1607641423.886 [MissionManager](INFO): DefineArg sci2:NeedComms.SurfaceSpeed = 1.000000 m/s
2020-12-10T23:03:43.899Z,1607641423.899 [MissionManager](INFO): DefineArg sci2:NeedComms.GPSTimeout = 7.000000 min
2020-12-10T23:03:43.926Z,1607641423.926 [MissionManager](INFO): DefineArg sci2:NeedComms.CommsTimeout = 30.000000 min
2020-12-10T23:03:43.959Z,1607641423.959 [sci2:NeedComms:B.GoToSurface](DEBUG): Construct GoToSurface.
2020-12-10T23:03:44.020Z,1607641424.020 [MissionManager](INFO): Inserting Stack: Missions/Insert/StandardEnvelopes.xml
2020-12-10T23:03:44.107Z,1607641424.107 [MissionManager](INFO): DefineArg sci2:StandardEnvelopes.MinAltitude = 5.000000 m
2020-12-10T23:03:44.115Z,1607641424.115 [MissionManager](INFO): DefineArg sci2:StandardEnvelopes.MaxDepth = 200.000000 m
2020-12-10T23:03:44.130Z,1607641424.130 [MissionManager](INFO): DefineArg sci2:StandardEnvelopes.MinOffshore = 2000.000000 m
2020-12-10T23:03:44.131Z,1607641424.131 [sci2:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2020-12-10T23:03:44.155Z,1607641424.155 [sci2:StandardEnvelopes:B.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2020-12-10T23:03:44.189Z,1607641424.189 [sci2:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2020-12-10T23:03:44.294Z,1607641424.294 [sci2:I.Pitch](DEBUG): Construct.
2020-12-10T23:03:44.346Z,1607641424.346 [sci2:J.Buoyancy](DEBUG): Construct Buoyancy.
2020-12-10T23:03:44.365Z,1607641424.365 [sci2:K.SetSpeed](DEBUG): Construct.
2020-12-10T23:03:44.380Z,1607641424.380 [sci2:L.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2020-12-10T23:03:44.440Z,1607641424.440 [sci2:M.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2020-12-10T23:03:44.472Z,1607641424.472 [sci2:N.YoYo](DEBUG): Construct YoYo.
2020-12-10T23:03:44.498Z,1607641424.498 [sci2:Lap:Wpt1:A.Waypoint](DEBUG): Construct Waypoint.
2020-12-10T23:03:44.510Z,1607641424.510 [sci2:Lap:Wpt2:A.Waypoint](DEBUG): Construct Waypoint.
2020-12-10T23:03:44.533Z,1607641424.533 [sci2:Lap:Wpt3:A.Waypoint](DEBUG): Construct Waypoint.
2020-12-10T23:03:44.559Z,1607641424.559 [sci2:Lap:Wpt4:A.Waypoint](DEBUG): Construct Waypoint.
2020-12-10T23:03:44.581Z,1607641424.581 [sci2:Lap:Wpt5:A.Waypoint](DEBUG): Construct Waypoint.
2020-12-10T23:03:44.606Z,1607641424.606 [sci2:Lap:Wpt6:A.Waypoint](DEBUG): Construct Waypoint.
2020-12-10T23:03:44.630Z,1607641424.630 [sci2:Lap:Wpt7:A.Waypoint](DEBUG): Construct Waypoint.
2020-12-10T23:03:44.778Z,1607641424.778 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Control="Tethys/Control"
         xmlns:Guidance="Tethys/Guidance"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd"
       Id="sci2">

    <Description>
        Vehicle yo-yo's to the specified waypoints, with science turned on.
    </Description>
    <DefineArg Name="MissionTimeout"><Description>
        Maximum duration of mission
    </Description><Units:hour/><Value>2</Value></DefineArg>

    <DefineArg Name="NeedCommsTime"><Description>
        How often to surface for commumications
    </Description><Units:minute/><Value>60</Value></DefineArg>

    <DefineArg Name="Repeat"><Description>
        Number of times the vehicle should try to cycle through waypoints..
    </Description><Units:count/><Value>1</Value></DefineArg>

    <DefineArg Name="Lat1"><Description>
        Latitude of waypoint 1. If nan, waypoint is skipped.
    </Description><Units:degree/><Value>NaN</Value></DefineArg>

    <DefineArg Name="Lon1"><Description>
        Longitude of waypoint 1. If nan, waypoint is skipped.
    </Description><Units:degree/><Value>NaN</Value></DefineArg>

    <DefineArg Name="Lat2"><Description>
        Latitude of waypoint 2. If nan, waypoint is skipped.
    </Description><Units:degree/><Value>NaN</Value></DefineArg>

    <DefineArg Name="Lon2"><Description>
        Longitude of waypoint 2. If nan, waypoint is skipped.
    </Description><Units:degree/><Value>NaN</Value></DefineArg>

    <DefineArg Name="Lat3"><Description>
        Latitude of waypoint 3. If nan, waypoint is skipped.
    </Description><Units:degree/><Value>NaN</Value></DefineArg>

    <DefineArg Name="Lon3"><Description>
        Longitude of waypoint 3. If nan, waypoint is skipped.
    </Description><Units:degree/><Value>NaN</Value></DefineArg>

    <DefineArg Name="Lat4"><Description>
        Latitude of waypoint 4. If nan, waypoint is skipped.
    </Description><Units:degree/><Value>NaN</Value></DefineArg>

    <DefineArg Name="Lon4"><Description>
        Longitude of waypoint 4. If nan, waypoint is skipped.
    </Description><Units:degree/><Value>NaN</Value></DefineArg>

    <DefineArg Name="Lat5"><Description>
        Latitude of waypoint 5. If nan, waypoint is skipped.
    </Description><Units:degree/><Value>NaN</Value></DefineArg>

    <DefineArg Name="Lon5"><Description>
        Longitude of waypoint 5. If nan, waypoint is skipped.
    </Description><Units:degree/><Value>NaN</Value></DefineArg>

    <DefineArg Name="Lat6"><Description>
        Latitude of waypoint 6. If nan, waypoint is skipped.
    </Description><Units:degree/><Value>NaN</Value></DefineArg>

    <DefineArg Name="Lon6"><Description>
        Longitude of waypoint 6. If nan, waypoint is skipped.
    </Description><Units:degree/><Value>NaN</Value></DefineArg>

    <DefineArg Name="Lat7"><Description>
        Latitude of waypoint 7. If nan, waypoint is skipped.
    </Description><Units:degree/><Value>NaN</Value></DefineArg>

    <DefineArg Name="Lon7"><Description>
        Longitude of waypoint 7. If nan, waypoint is skipped.
    </Description><Units:degree/><Value>NaN</Value></DefineArg>

    <DefineArg Name="Speed"><Description>
        Speed while performing the YoYo behavior.
    </Description><Units:meter_per_second/><Value>1</Value></DefineArg>

    <DefineArg Name="CaptureRadius"><Description>
        Speed while performing the YoYo behavior.
    </Description><Units:meter/><Value>NaN</Value></DefineArg>

    
    <DefineArg Name="YoYoMinDepth"><Description>
        Minimum depth while performing the YoYo behavior.
    </Description><Units:meter/><Value>2</Value></DefineArg>

    <DefineArg Name="YoYoMaxDepth"><Description>
        Maximum depth while performing the YoYo behavior.
    </Description><Units:meter/><Value>200</Value></DefineArg>

    <DefineArg Name="YoYoMinAltitude"><Description>
        Minimum altitude while performing the YoYo behavior (for
        bottom-terminated YoYos).
    </Description><Units:meter/><Value>9</Value></DefineArg>

    <DefineArg Name="YoYoUpPitch"><Description>
        Vehicle up pitch while performing the YoYo behavior.
    </Description><Units:degree/><Value>20</Value></DefineArg>

    <DefineArg Name="YoYoDownPitch"><Description>
        Vehicle down pitch while performing the YoYo behavior.
    </Description><Units:degree/><Value>-20</Value></DefineArg>

    <DefineArg Name="BuoyancyNeutral"><Description>
        Buoyancy bladder position while performing the YoYo behavior. Defaults
        to buoyancyNeutral setting in the Config/Control.cfg file. Set to NaN cc
        for active buoyancy
    </Description><Control:VerticalControl.buoyancyNeutral/></DefineArg>

    <DefineArg Name="MassDefault"><Description>
        Static setting for mass during the mission. Set to NaN mm for active
        mass position
    </Description><Control:VerticalControl.massDefault/></DefineArg>

    <DefineArg Name="MinAltitude"><Description>
        Minimum height above the sea floor for the entire mission.
    </Description><Units:meter/><Value>5</Value></DefineArg>

    <DefineArg Name="MaxDepth"><Description>
        Maximum depth for the entire mission.
    </Description><Units:meter/><Value>205</Value></DefineArg>

    <DefineArg Name="MinOffshore"><Description>
        Minimum offshore distance for the entire mission.
    </Description><Units:kilometer/><Value>2</Value></DefineArg>
    <Timeout Duration="MissionTimeout"/>

    <Insert Filename="Insert/Science.xml">
        <Description>
            Most missions will run the science sensors. If you don't place this
            aggregate above NeedComms, science instruments get turned off on the
            last upcast and while floating on the surface.
        </Description>
        <RedefineArg Name="PeakDetectChlActive"><True/></RedefineArg>
    </Insert>

    <Insert Filename="Insert/NeedComms.xml" Id="NeedComms"/>

    <Assign><Sequence/><Arg Name="NeedComms:DiveInterval"/><Arg Name="NeedCommsTime"/></Assign>

    <Insert Filename="Insert/StandardEnvelopes.xml"/>

    <Assign><Sequence/><Arg Name="StandardEnvelopes:MinAltitude"/><Arg Name="MinAltitude"/></Assign>

    <Assign><Sequence/><Arg Name="StandardEnvelopes:MaxDepth"/><Arg Name="MaxDepth"/></Assign>

    <Assign><Sequence/><Arg Name="StandardEnvelopes:MinOffshore"/><Arg Name="MinOffshore"/></Assign>

    <Call Id="StartingMission" RefId="NeedComms"/>

    <Guidance:Pitch>
        <Parallel/>
        <Setting><Guidance:Pitch.massPosition/><Arg Name="MassDefault"/></Setting>
    </Guidance:Pitch>

    <Guidance:Buoyancy>
        <Parallel/>
        <Setting><Guidance:Buoyancy.position/><Arg Name="BuoyancyNeutral"/></Setting>
    </Guidance:Buoyancy>

    <Guidance:SetSpeed>
        <Parallel/>
        <Setting><Guidance:SetSpeed.speed/><Arg Name="Speed"/></Setting>
    </Guidance:SetSpeed>

    <Guidance:DepthEnvelope>
        <Description>
            Another depth envelope for the YoYo behavior. This envelope should
            fall within the limits of the standard safety envelopes in
            Insert/StandardEnvelopes.xml in order to avoid commanding high pitch
            angles for depth-terminated YoYos.
        </Description>
        <Parallel/>
        <Setting><Guidance:DepthEnvelope.minDepth/><Arg Name="YoYoMinDepth"/></Setting>
        <Setting><Guidance:DepthEnvelope.maxDepth/><Arg Name="YoYoMaxDepth"/></Setting>
        <Setting><Guidance:DepthEnvelope.downPitch/><Arg Name="YoYoDownPitch"/></Setting>
        <Setting><Guidance:DepthEnvelope.upPitch/><Arg Name="YoYoUpPitch"/></Setting>
    </Guidance:DepthEnvelope>

    <Guidance:AltitudeEnvelope>
        <Description>
            Another altitude envelope for the YoYo behavior. This envelope
            should fall within the limits of the standard safety envelopes in
            Insert/StandardEnvelopes.xml in order to avoid commanding high pitch
            angles for bottom-terminated YoYos.
        </Description>
        <Parallel/>
        <Setting><Guidance:AltitudeEnvelope.minAltitude/><Arg Name="YoYoMinAltitude"/></Setting>
        <Setting><Guidance:AltitudeEnvelope.upPitch/><Arg Name="YoYoUpPitch"/></Setting>
    </Guidance:AltitudeEnvelope>

    <Guidance:YoYo>
        <Parallel/>
        <Setting><Guidance:YoYo.downPitch/><Arg Name="YoYoDownPitch"/></Setting>
        <Setting><Guidance:YoYo.upPitch/><Arg Name="YoYoUpPitch"/></Setting>
    </Guidance:YoYo>

    <Aggregate Id="Lap">
        <Sequence Repeat="Repeat"/>

        <Aggregate Id="Wpt1">
            <Sequence/>

            <Guidance:Waypoint>
                <Sequence/>
                <Setting><Guidance:Waypoint.latitude/><Arg Name="Lat1"/></Setting>
                <Setting><Guidance:Waypoint.longitude/><Arg Name="Lon1"/></Setting>
                <Setting><Guidance:Waypoint.captureRadius/><Arg Name="CaptureRadius"/></Setting>
            </Guidance:Waypoint>
        </Aggregate>

        <Aggregate Id="Wpt2">
            <Sequence/>

            <Guidance:Waypoint>
                <Sequence/>
                <Setting><Guidance:Waypoint.latitude/><Arg Name="Lat2"/></Setting>
                <Setting><Guidance:Waypoint.longitude/><Arg Name="Lon2"/></Setting>
            </Guidance:Waypoint>
        </Aggregate>

        <Aggregate Id="Wpt3">
            <Sequence/>

            <Guidance:Waypoint>
                <Sequence/>
                <Setting><Guidance:Waypoint.latitude/><Arg Name="Lat3"/></Setting>
                <Setting><Guidance:Waypoint.longitude/><Arg Name="Lon3"/></Setting>
            </Guidance:Waypoint>
        </Aggregate>

        <Aggregate Id="Wpt4">
            <Sequence/>

            <Guidance:Waypoint>
                <Sequence/>
                <Setting><Guidance:Waypoint.latitude/><Arg Name="Lat4"/></Setting>
                <Setting><Guidance:Waypoint.longitude/><Arg Name="Lon4"/></Setting>
            </Guidance:Waypoint>
        </Aggregate>

        <Aggregate Id="Wpt5">
            <Sequence/>

            <Guidance:Waypoint>
                <Sequence/>
                <Setting><Guidance:Waypoint.latitude/><Arg Name="Lat5"/></Setting>
                <Setting><Guidance:Waypoint.longitude/><Arg Name="Lon5"/></Setting>
            </Guidance:Waypoint>
        </Aggregate>

        <Aggregate Id="Wpt6">
            <Sequence/>

            <Guidance:Waypoint>
                <Sequence/>
                <Setting><Guidance:Waypoint.latitude/><Arg Name="Lat6"/></Setting>
                <Setting><Guidance:Waypoint.longitude/><Arg Name="Lon6"/></Setting>
            </Guidance:Waypoint>
        </Aggregate>

        <Aggregate Id="Wpt7">
            <Sequence/>

            <Guidance:Waypoint>
                <Sequence/>
                <Setting><Guidance:Waypoint.latitude/><Arg Name="Lat7"/></Setting>
                <Setting><Guidance:Waypoint.longitude/><Arg Name="Lon7"/></Setting>
            </Guidance:Waypoint>
        </Aggregate>
    </Aggregate>
</Mission>


2020-12-10T23:03:44.779Z,1607641424.779 [CommandLine](IMPORTANT): Loaded ./Missions/Science/sci2.xml
2020-12-10T23:04:00.882Z,1607641440.882 [CommandLine](IMPORTANT): got command set sci2.Lat1 41.564004 degree
2020-12-10T23:04:00.883Z,1607641440.883 [CommandLine](IMPORTANT): got command set sci2.Lon1 -70.698608 degree
2020-12-10T23:04:00.884Z,1607641440.884 [CommandLine](IMPORTANT): got command set sci2.YoYoMinDepth 3 meter
2020-12-10T23:04:00.884Z,1607641440.884 [CommandLine](IMPORTANT): got command set sci2.YoYoMaxDepth 7 meter
2020-12-10T23:04:00.885Z,1607641440.885 [CommandLine](IMPORTANT): got command set sci2.YoYoMinAltitude 3 meter
2020-12-10T23:04:00.886Z,1607641440.886 [CommandLine](IMPORTANT): got command set sci2.YoYoUpPitch 15 degree
2020-12-10T23:04:06.911Z,1607641446.911 [CommandLine](IMPORTANT): got command set sci2.YoYoDownPitch -15 degree
2020-12-10T23:04:06.912Z,1607641446.912 [CommandLine](IMPORTANT): got command set sci2.MinAltitude 3 meter
2020-12-10T23:04:06.913Z,1607641446.913 [CommandLine](IMPORTANT): got command set sci2.MaxDepth 9 meter
2020-12-10T23:04:06.913Z,1607641446.913 [CommandLine](IMPORTANT): got command set sci2.MinOffshore 500 kilometer
2020-12-10T23:04:06.914Z,1607641446.914 [CommandLine](IMPORTANT): got command run
2020-12-10T23:04:06.916Z,1607641446.916 [CommandLine](IMPORTANT): Running 
2020-12-10T23:04:07.033Z,1607641447.033 [DefaultWithUndock] Stopped
2020-12-10T23:04:07.033Z,1607641447.033 [DefaultWithUndock](DEBUG): Aggregate::uninitialize DefaultWithUndock
2020-12-10T23:04:07.033Z,1607641447.033 [DefaultWithUndock:SurfaceDefault] Stopped
2020-12-10T23:04:07.033Z,1607641447.033 [DefaultWithUndock:SurfaceDefault](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault
2020-12-10T23:04:07.033Z,1607641447.033 [DefaultWithUndock:SurfaceDefault:B.GoToSurface] Stopped
2020-12-10T23:04:07.033Z,1607641447.033 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2020-12-10T23:04:07.033Z,1607641447.033 [DefaultWithUndock:SurfaceDefault:CheckIn] Stopped
2020-12-10T23:04:07.033Z,1607641447.033 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:CheckIn
2020-12-10T23:04:07.033Z,1607641447.033 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Stopped
2020-12-10T23:04:07.034Z,1607641447.034 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-12-10T23:04:07.034Z,1607641447.034 [MissionManager](IMPORTANT): Started mission sci2
2020-12-10T23:04:07.034Z,1607641447.034 [sci2] Running Loop=1
2020-12-10T23:04:07.034Z,1607641447.034 [sci2](DEBUG): Aggregate::initialize sci2
2020-12-10T23:04:07.034Z,1607641447.034 [sci2:Science] Running Loop=1
2020-12-10T23:04:07.034Z,1607641447.034 [sci2:Science](DEBUG): Aggregate::initialize sci2:Science
2020-12-10T23:04:07.034Z,1607641447.034 [sci2:Science:A] Running Loop=1
2020-12-10T23:04:07.034Z,1607641447.034 [sci2:Science:B] Running Loop=1
2020-12-10T23:04:07.034Z,1607641447.034 [sci2:Science:C] Running Loop=1
2020-12-10T23:04:07.035Z,1607641447.035 [sci2:Science:D] Running Loop=1
2020-12-10T23:04:07.035Z,1607641447.035 [sci2:Science:E] Running Loop=1
2020-12-10T23:04:07.035Z,1607641447.035 [sci2:Science:F] Running Loop=1
2020-12-10T23:04:07.035Z,1607641447.035 [sci2:Science:Read_Oil] Running Loop=1
2020-12-10T23:04:07.035Z,1607641447.035 [sci2:Science:PeakDetectChl] Running Loop=1
2020-12-10T23:04:07.035Z,1607641447.035 [sci2:Science:PeakDetectChl](DEBUG): Aggregate::initialize sci2:Science:PeakDetectChl
2020-12-10T23:04:07.035Z,1607641447.035 [sci2:Science:PeakDetectChl:A.PeakDetectVsDepth] Running Loop=1
2020-12-10T23:04:07.035Z,1607641447.035 [sci2:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Initialize.
2020-12-10T23:04:07.037Z,1607641447.037 [sci2:Science:HighestChlPeakReport] Running Loop=1
2020-12-10T23:04:07.037Z,1607641447.037 [sci2:Science:HighestChlPeakReport](DEBUG): Aggregate::initialize sci2:Science:HighestChlPeakReport
2020-12-10T23:04:07.038Z,1607641447.038 [sci2:Science:HighestChlPeakReport:A.PeakDetectHorizontal] Running Loop=1
2020-12-10T23:04:07.038Z,1607641447.038 [sci2:Science:HighestChlPeakReport:A.PeakDetectHorizontal](INFO): Initialize.
2020-12-10T23:04:07.038Z,1607641447.038 [sci2:Science:PeakDetectNO3] Running Loop=1
2020-12-10T23:04:07.038Z,1607641447.038 [sci2:Science:PeakDetectNO3](DEBUG): Aggregate::initialize sci2:Science:PeakDetectNO3
2020-12-10T23:04:07.038Z,1607641447.038 [sci2:Science:PeakDetectNO3:A.PeakDetectVsDepth] Running Loop=1
2020-12-10T23:04:07.038Z,1607641447.038 [sci2:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Initialize.
2020-12-10T23:04:07.049Z,1607641447.049 [sci2:Science:PeakDetectOil] Running Loop=1
2020-12-10T23:04:07.049Z,1607641447.049 [sci2:Science:PeakDetectOil](DEBUG): Aggregate::initialize sci2:Science:PeakDetectOil
2020-12-10T23:04:07.050Z,1607641447.050 [sci2:Science:PeakDetectOil:A.PeakDetectVsDepth] Running Loop=1
2020-12-10T23:04:07.050Z,1607641447.050 [sci2:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Initialize.
2020-12-10T23:04:07.051Z,1607641447.051 [sci2:Science:PeakDetectFDOM] Running Loop=1
2020-12-10T23:04:07.051Z,1607641447.051 [sci2:Science:PeakDetectFDOM](DEBUG): Aggregate::initialize sci2:Science:PeakDetectFDOM
2020-12-10T23:04:07.051Z,1607641447.051 [sci2:Science:PeakDetectFDOM:A.PeakDetectVsDepth] Running Loop=1
2020-12-10T23:04:07.051Z,1607641447.051 [sci2:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Initialize.
2020-12-10T23:04:07.059Z,1607641447.059 [sci2:Science:OceanCurrent] Running Loop=1
2020-12-10T23:04:07.059Z,1607641447.059 [sci2:Science:OceanCurrent](DEBUG): Aggregate::initialize sci2:Science:OceanCurrent
2020-12-10T23:04:07.064Z,1607641447.064 [sci2:Science:OceanCurrent:A.] Running Loop=1
2020-12-10T23:04:07.064Z,1607641447.064 [sci2:Science:OceanCurrent:A.](INFO): Initializing CurrentEstimator.
2020-12-10T23:04:07.065Z,1607641447.065 [sci2:StandardEnvelopes] Running Loop=1
2020-12-10T23:04:07.065Z,1607641447.065 [sci2:StandardEnvelopes](DEBUG): Aggregate::initialize sci2:StandardEnvelopes
2020-12-10T23:04:07.065Z,1607641447.065 [sci2:StandardEnvelopes:A.AltitudeEnvelope] Running Loop=1
2020-12-10T23:04:07.066Z,1607641447.066 [sci2:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2020-12-10T23:04:07.066Z,1607641447.066 [sci2:StandardEnvelopes:B.DepthEnvelope] Running Loop=1
2020-12-10T23:04:07.066Z,1607641447.066 [sci2:StandardEnvelopes:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2020-12-10T23:04:07.067Z,1607641447.067 [sci2:StandardEnvelopes:C.OffshoreEnvelope] Running Loop=1
2020-12-10T23:04:07.067Z,1607641447.067 [sci2:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2020-12-10T23:04:07.067Z,1607641447.067 [sci2:I.Pitch] Running Loop=1
2020-12-10T23:04:07.067Z,1607641447.067 [sci2:I.Pitch](DEBUG): Initialize.
2020-12-10T23:04:07.072Z,1607641447.072 [sci2:J.Buoyancy] Running Loop=1
2020-12-10T23:04:07.072Z,1607641447.072 [sci2:J.Buoyancy](DEBUG): Initialize Buoyancy Component.
2020-12-10T23:04:07.073Z,1607641447.073 [sci2:K.SetSpeed] Running Loop=1
2020-12-10T23:04:07.073Z,1607641447.073 [sci2:K.SetSpeed](DEBUG): Initialize.
2020-12-10T23:04:07.073Z,1607641447.073 [sci2:L.DepthEnvelope] Running Loop=1
2020-12-10T23:04:07.073Z,1607641447.073 [sci2:L.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2020-12-10T23:04:07.074Z,1607641447.074 [sci2:M.AltitudeEnvelope] Running Loop=1
2020-12-10T23:04:07.074Z,1607641447.074 [sci2:M.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2020-12-10T23:04:07.075Z,1607641447.075 [sci2:N.YoYo] Running Loop=1
2020-12-10T23:04:07.075Z,1607641447.075 [sci2:N.YoYo](DEBUG): Initialize YoYoComponent.
2020-12-10T23:04:07.081Z,1607641447.081 [sci2:C] Running Loop=1
2020-12-10T23:04:07.082Z,1607641447.082 [sci2:N.YoYo] Running Loop=1
2020-12-10T23:04:07.088Z,1607641447.088 [sci2:M.AltitudeEnvelope] Running Loop=1
2020-12-10T23:04:07.089Z,1607641447.089 [sci2:L.DepthEnvelope] Running Loop=1
2020-12-10T23:04:07.091Z,1607641447.091 [sci2:K.SetSpeed] Running Loop=1
2020-12-10T23:04:07.096Z,1607641447.096 [sci2:J.Buoyancy] Running Loop=1
2020-12-10T23:04:07.097Z,1607641447.097 [sci2:I.Pitch] Running Loop=1
2020-12-10T23:04:07.098Z,1607641447.098 [sci2:StandardEnvelopes] Running Loop=1
2020-12-10T23:04:07.098Z,1607641447.098 [sci2:StandardEnvelopes:C.OffshoreEnvelope] Running Loop=1
2020-12-10T23:04:07.099Z,1607641447.099 [sci2:StandardEnvelopes:B.DepthEnvelope] Running Loop=1
2020-12-10T23:04:07.099Z,1607641447.099 [sci2:StandardEnvelopes:A.AltitudeEnvelope] Running Loop=1
2020-12-10T23:04:07.104Z,1607641447.104 [sci2:C] Stopped
2020-12-10T23:04:07.104Z,1607641447.104 [sci2:E] Running Loop=1
2020-12-10T23:04:07.104Z,1607641447.104 [sci2:Science] Running Loop=1
2020-12-10T23:04:07.105Z,1607641447.105 [sci2:Science:PeakDetectFDOM] Stopped
2020-12-10T23:04:07.105Z,1607641447.105 [sci2:Science:PeakDetectFDOM](DEBUG): Aggregate::uninitialize sci2:Science:PeakDetectFDOM
2020-12-10T23:04:07.105Z,1607641447.105 [sci2:Science:PeakDetectFDOM:A.PeakDetectVsDepth] Stopped
2020-12-10T23:04:07.105Z,1607641447.105 [sci2:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2020-12-10T23:04:07.105Z,1607641447.105 [sci2:Science:PeakDetectOil] Stopped
2020-12-10T23:04:07.105Z,1607641447.105 [sci2:Science:PeakDetectOil](DEBUG): Aggregate::uninitialize sci2:Science:PeakDetectOil
2020-12-10T23:04:07.106Z,1607641447.106 [sci2:Science:PeakDetectOil:A.PeakDetectVsDepth] Stopped
2020-12-10T23:04:07.106Z,1607641447.106 [sci2:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2020-12-10T23:04:07.106Z,1607641447.106 [sci2:Science:PeakDetectNO3] Stopped
2020-12-10T23:04:07.106Z,1607641447.106 [sci2:Science:PeakDetectNO3](DEBUG): Aggregate::uninitialize sci2:Science:PeakDetectNO3
2020-12-10T23:04:07.106Z,1607641447.106 [sci2:Science:PeakDetectNO3:A.PeakDetectVsDepth] Stopped
2020-12-10T23:04:07.106Z,1607641447.106 [sci2:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2020-12-10T23:04:07.106Z,1607641447.106 [sci2:Science:HighestChlPeakReport] Stopped
2020-12-10T23:04:07.106Z,1607641447.106 [sci2:Science:HighestChlPeakReport](DEBUG): Aggregate::uninitialize sci2:Science:HighestChlPeakReport
2020-12-10T23:04:07.106Z,1607641447.106 [sci2:Science:HighestChlPeakReport:A.PeakDetectHorizontal] Stopped
2020-12-10T23:04:07.106Z,1607641447.106 [sci2:Science:HighestChlPeakReport:A.PeakDetectHorizontal](DEBUG): Uninitialize.
2020-12-10T23:04:07.106Z,1607641447.106 [sci2:Science:PeakDetectChl] Running Loop=1
2020-12-10T23:04:07.107Z,1607641447.107 [sci2:Science:OceanCurrent:A.] Running Loop=1
2020-12-10T23:04:07.112Z,1607641447.112 [sci2:Science:Read_Oil] Running Loop=1
2020-12-10T23:04:07.113Z,1607641447.113 [sci2:Science:Read_Oil](DEBUG): Initialize ReadDataComponent to sense mass_concentration_of_chlorophyll_in_sea_water
2020-12-10T23:04:07.113Z,1607641447.113 [sci2:Science:F] Stopped
2020-12-10T23:04:07.113Z,1607641447.113 [sci2:Science:E] Running Loop=1
2020-12-10T23:04:07.114Z,1607641447.114 [sci2:Science:E](DEBUG): Initialize ReadDataComponent to sense mass_concentration_of_chlorophyll_in_sea_water
2020-12-10T23:04:07.114Z,1607641447.114 [sci2:Science:D] Stopped
2020-12-10T23:04:07.114Z,1607641447.114 [sci2:Science:C] Running Loop=1
2020-12-10T23:04:07.114Z,1607641447.114 [sci2:Science:C](DEBUG): Initialize ReadDataComponent to sense CTD_Seabird.sea_water_temperature
2020-12-10T23:04:07.115Z,1607641447.115 [sci2:Science:C](DEBUG): Initialize ReadDataComponent to sense CTD_Seabird.sea_water_salinity
2020-12-10T23:04:07.115Z,1607641447.115 [sci2:Science:B] Running Loop=1
2020-12-10T23:04:07.116Z,1607641447.116 [sci2:Science:B](DEBUG): Initialize ReadDataComponent to sense sea_water_temperature
2020-12-10T23:04:07.117Z,1607641447.117 [sci2:Science:B](DEBUG): Initialize ReadDataComponent to sense sea_water_salinity
2020-12-10T23:04:07.117Z,1607641447.117 [sci2:Science:A] Stopped
2020-12-10T23:04:07.168Z,1607641447.168 [WetLabsSeaOWL_UV_A](INFO): Powering up
2020-12-10T23:04:07.460Z,1607641447.460 [sci2:E] Stopped
2020-12-10T23:04:07.460Z,1607641447.460 [sci2:F] Running Loop=1
2020-12-10T23:04:07.815Z,1607641447.815 [sci2:F] Stopped
2020-12-10T23:04:07.815Z,1607641447.815 [sci2:G] Running Loop=1
2020-12-10T23:04:08.239Z,1607641448.239 [sci2:G] Stopped
2020-12-10T23:04:08.239Z,1607641448.239 [sci2:StartingMission] Running Loop=1
2020-12-10T23:04:08.240Z,1607641448.240 [sci2:StartingMission](DEBUG): Aggregate::initialize sci2:StartingMission
2020-12-10T23:04:08.642Z,1607641448.642 [sci2:NeedComms] Running Loop=1
2020-12-10T23:04:08.642Z,1607641448.642 [sci2:NeedComms](DEBUG): Aggregate::initialize sci2:NeedComms
2020-12-10T23:04:08.642Z,1607641448.642 [sci2:NeedComms:B.GoToSurface] Running Loop=1
2020-12-10T23:04:08.642Z,1607641448.642 [sci2:NeedComms:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2020-12-10T23:04:08.642Z,1607641448.642 [sci2:NeedComms:B.GoToSurface](INFO): Received depth rate setting nan m/s.
2020-12-10T23:04:08.643Z,1607641448.643 [sci2:NeedComms:B.GoToSurface](INFO): Received pitch setting 19.999999 degrees.
2020-12-10T23:04:08.643Z,1607641448.643 [sci2:NeedComms:B.GoToSurface](INFO): Received speed setting 1.000000 m/s.
2020-12-10T23:04:08.643Z,1607641448.643 [sci2:NeedComms:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2020-12-10T23:04:08.644Z,1607641448.644 [sci2:NeedComms:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2020-12-10T23:04:08.644Z,1607641448.644 [sci2:NeedComms:A] Running Loop=1
2020-12-10T23:04:08.645Z,1607641448.645 [sci2:NeedComms:A](INFO): last time_fix was: 1607641321.000000 second since 1970/01/01T00:00:00Z 
2020-12-10T23:04:08.645Z,1607641448.645 [sci2:NeedComms:A] Stopped
2020-12-10T23:04:09.018Z,1607641449.018 [sci2:NeedComms:C] Running Loop=1
2020-12-10T23:04:09.447Z,1607641449.447 [sci2:NeedComms:C](DEBUG): Initialize ReadDataComponent to sense time_fix
2020-12-10T23:04:10.437Z,1607641450.437 [CTD_Seabird](ERROR): Failed to parse device response: <!--startlogging-->
2020-12-10T23:04:11.028Z,1607641451.028 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,230411.00,A,4133.04649,N,07044.63170,W,0.058,198.56,101220,,,A*79
2020-12-10T23:04:11.030Z,1607641451.030 [NAL9602](INFO): GPS fix at 20201210T230411: (41.550775, -70.743862)
2020-12-10T23:04:11.062Z,1607641451.062 [sci2:NeedComms:C] Stopped
2020-12-10T23:04:11.062Z,1607641451.062 [sci2:NeedComms:D] Running Loop=1
2020-12-10T23:04:11.477Z,1607641451.477 [sci2:NeedComms:D](DEBUG): Initialize ReadDataComponent to sense platform_communications
2020-12-10T23:04:13.450Z,1607641453.450 [CTD_Seabird](ERROR): Salinity reading out of range: 26.661457 psu
2020-12-10T23:04:15.436Z,1607641455.436 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20201210T215856/Courier0021.lzma
2020-12-10T23:04:16.438Z,1607641456.438 [DataOverHttps](INFO): Moved sent file to Logs/20201210T215856/Courier0021.lzma.bak
2020-12-10T23:04:16.438Z,1607641456.438 [DataOverHttps](INFO): SBD MOMSN=62188
2020-12-10T23:04:25.476Z,1607641465.476 [DataOverHttps](INFO): Sending 544 bytes from file Logs/20201210T215856/Express0023.lzma
2020-12-10T23:04:26.478Z,1607641466.478 [DataOverHttps](INFO): Moved sent file to Logs/20201210T215856/Express0023.lzma.bak
2020-12-10T23:04:26.478Z,1607641466.478 [DataOverHttps](INFO): SBD MOMSN=62191
2020-12-10T23:04:35.515Z,1607641475.515 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20201210T215856/Express0026.lzma
2020-12-10T23:04:36.518Z,1607641476.518 [DataOverHttps](INFO): Moved sent file to Logs/20201210T215856/Express0026.lzma.bak
2020-12-10T23:04:36.518Z,1607641476.518 [DataOverHttps](INFO): SBD MOMSN=62216
2020-12-10T23:04:37.720Z,1607641477.720 [sci2:NeedComms:D] Stopped
2020-12-10T23:04:37.721Z,1607641477.721 [sci2:NeedComms:E] Running Loop=1
2020-12-10T23:04:38.139Z,1607641478.139 [sci2:NeedComms:E](DEBUG): Initialize ReadDataComponent to sense time_fix
2020-12-10T23:04:41.357Z,1607641481.357 [NAL9602](INFO): SBD MO Status=2, MOMSN=12284, MT Status=2, MTMSN=0
2020-12-10T23:04:41.358Z,1607641481.358 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-12-10T23:05:13.256Z,1607641513.256 [NAL9602](INFO): SBD MO Status=0, MOMSN=12284, MT Status=0, MTMSN=0
2020-12-10T23:05:13.256Z,1607641513.256 [NAL9602](INFO): No messages in MT queue
2020-12-10T23:05:14.462Z,1607641514.462 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,230514.00,A,4133.04219,N,07044.63450,W,0.369,198.56,101220,,,A*7A
2020-12-10T23:05:14.464Z,1607641514.464 [NAL9602](INFO): GPS fix at 20201210T230514: (41.550703, -70.743908)
2020-12-10T23:05:14.497Z,1607641514.497 [sci2:NeedComms:E] Stopped
2020-12-10T23:05:14.498Z,1607641514.498 [sci2:NeedComms](INFO): Completed sci2:NeedComms
2020-12-10T23:05:14.498Z,1607641514.498 [sci2:NeedComms] Stopped
2020-12-10T23:05:14.498Z,1607641514.498 [sci2:NeedComms](DEBUG): Aggregate::uninitialize sci2:NeedComms
2020-12-10T23:05:14.499Z,1607641514.499 [sci2:NeedComms:B.GoToSurface] Stopped
2020-12-10T23:05:14.499Z,1607641514.499 [sci2:NeedComms:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2020-12-10T23:05:14.899Z,1607641514.899 [sci2:StartingMission](INFO): Completed sci2:StartingMission
2020-12-10T23:05:14.899Z,1607641514.899 [sci2:StartingMission] Stopped
2020-12-10T23:05:14.899Z,1607641514.899 [sci2:StartingMission](DEBUG): Aggregate::uninitialize sci2:StartingMission
2020-12-10T23:05:14.899Z,1607641514.899 [sci2:Lap] Running Loop=1
2020-12-10T23:05:14.899Z,1607641514.899 [sci2:Lap](DEBUG): Aggregate::initialize sci2:Lap
2020-12-10T23:05:14.899Z,1607641514.899 [sci2:Lap:Wpt1] Running Loop=1
2020-12-10T23:05:14.899Z,1607641514.899 [sci2:Lap:Wpt1](DEBUG): Aggregate::initialize sci2:Lap:Wpt1
2020-12-10T23:05:14.899Z,1607641514.899 [sci2:Lap:Wpt1:A.Waypoint] Running Loop=1
2020-12-10T23:05:14.900Z,1607641514.900 [sci2:Lap:Wpt1:A.Waypoint](DEBUG): Initialize WaypointComponent.
2020-12-10T23:05:46.785Z,1607641546.785 [NAL9602](INFO): Not Powering down - fast GPS
2020-12-10T23:07:08.806Z,1607641628.806 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T23:07:31.029Z,1607641651.029 [ElevatorOffsetCalculator](INFO): New estimator for commanded vars: speed 1.00 m/s, pitch -15.00 deg, mass-position -0.36 mm (2 active estimators).
2020-12-10T23:07:43.141Z,1607641663.141 [ElevatorOffsetCalculator](INFO): New estimator for commanded vars: speed 1.00 m/s, pitch 15.00 deg, mass-position -0.36 mm (3 active estimators).
2020-12-10T23:08:02.373Z,1607641682.373 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.247086
2020-12-10T23:08:31.424Z,1607641711.424 [Radio_Surface](INFO): Powering down
2020-12-10T23:08:38.517Z,1607641718.517 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-12-10T23:08:39.520Z,1607641719.520 [DataOverHttps](INFO): Radio surface powered OFF, will not connect.
2020-12-10T23:10:20.437Z,1607641820.437 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T23:12:32.579Z,1607641952.579 [RDI_PathfinderUp](ERROR): only read 2 of 4 data items
2020-12-10T23:12:50.363Z,1607641970.363 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2020-12-10T23:12:50.365Z,1607641970.365 [BPC1](INFO): Received data from all battery sticks.
2020-12-10T23:16:08.724Z,1607642168.724 [RDI_PathfinderUp](ERROR): only read 2 of 4 data items
2020-12-10T23:16:21.241Z,1607642181.241 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T23:16:26.105Z,1607642186.105 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2020-12-10T23:16:31.344Z,1607642191.344 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2020-12-10T23:16:36.175Z,1607642196.175 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T23:16:46.280Z,1607642206.280 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2020-12-10T23:16:56.385Z,1607642216.385 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2020-12-10T23:17:06.119Z,1607642226.119 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2020-12-10T23:17:29.104Z,1607642249.104 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T23:17:51.429Z,1607642271.429 [ThrusterServo](FAULT): Invalid EZ Servo response:"/0@5242"
2020-12-10T23:17:51.429Z,1607642271.429 [ThrusterServo] Communications Fault, FailCount= 1
2020-12-10T23:17:51.429Z,1607642271.429 [ThrusterServo](ERROR): Communications Fault
2020-12-10T23:17:51.433Z,1607642271.433 [CBIT](ERROR): Communications Fault in component: ThrusterServo
2020-12-10T23:17:51.764Z,1607642271.764 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2020-12-10T23:17:51.764Z,1607642271.764 [ThrusterServo](INFO): Powering down
2020-12-10T23:17:52.562Z,1607642272.562 [ThrusterServo](DEBUG): Initializing EZServoServo.
2020-12-10T23:17:52.677Z,1607642272.677 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2020-12-10T23:17:52.681Z,1607642272.681 [CBIT](INFO): Clearing failed state for component ThrusterServo
2020-12-10T23:17:52.681Z,1607642272.681 [ThrusterServo] No Fault, FailCount= 1
2020-12-10T23:21:56.546Z,1607642516.546 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T23:22:01.414Z,1607642521.414 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T23:22:16.394Z,1607642536.394 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T23:22:51.507Z,1607642571.507 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for altitude
2020-12-10T23:23:50.130Z,1607642630.130 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2020-12-10T23:26:07.853Z,1607642767.853 [RDI_PathfinderUp](ERROR): only read 2 of 4 data items
2020-12-10T23:36:02.131Z,1607643362.131 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T23:36:27.172Z,1607643387.172 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T23:36:32.424Z,1607643392.424 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T23:36:42.126Z,1607643402.126 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T23:36:52.223Z,1607643412.223 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2020-12-10T23:36:57.115Z,1607643417.115 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2020-12-10T23:37:06.403Z,1607643426.403 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for altitude
2020-12-10T23:37:39.098Z,1607643459.098 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2020-12-10T23:37:41.101Z,1607643461.101 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2020-12-10T23:41:47.550Z,1607643707.550 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T23:41:57.646Z,1607643717.646 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T23:42:02.504Z,1607643722.504 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T23:42:07.419Z,1607643727.419 [RDI_PathfinderUp](ERROR): only read 2 of 4 data items
2020-12-10T23:43:04.363Z,1607643784.363 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T23:43:37.086Z,1607643817.086 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2020-12-10T23:44:12.587Z,1607643852.587 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for altitude
2020-12-10T23:45:22.891Z,1607643922.891 [RDI_PathfinderUp](ERROR): only read 3 of 4 data items
2020-12-10T23:47:23.279Z,1607644043.279 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2020-12-10T23:52:36.399Z,1607644356.399 [RDI_PathfinderUp](ERROR): only read 2 of 4 data items
2020-12-10T23:55:08.290Z,1607644508.290 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2020-12-10T23:55:23.274Z,1607644523.274 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2020-12-10T23:55:28.087Z,1607644528.087 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T23:55:43.085Z,1607644543.085 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2020-12-10T23:55:48.281Z,1607644548.281 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T23:56:03.232Z,1607644563.232 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2020-12-10T23:56:18.180Z,1607644578.180 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2020-12-10T23:57:37.447Z,1607644657.447 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for altitude
2020-12-10T23:59:34.536Z,1607644774.536 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for BIT error
2020-12-11T00:00:03.339Z,1607644803.339 [CTD_Seabird](ERROR): Failed to parse device response: 5.05,22
2020-12-11T00:01:08.684Z,1607644868.684 [RDI_PathfinderUp](ERROR): only read 2 of 4 data items
2020-12-11T00:01:14.387Z,1607644874.387 [RDI_PathfinderUp](ERROR): only read 3 of 4 data items
2020-12-11T00:01:23.621Z,1607644883.621 [RDI_PathfinderUp](ERROR): only read 2 of 4 data items
2020-12-11T00:01:38.562Z,1607644898.562 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for BIT error
2020-12-11T00:01:41.389Z,1607644901.389 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2020-12-11T00:01:43.445Z,1607644903.445 [RDI_PathfinderUp](ERROR): only read 3 of 4 data items
2020-12-11T00:01:48.683Z,1607644908.683 [RDI_PathfinderUp](ERROR): only read 2 of 4 data items
2020-12-11T00:01:53.510Z,1607644913.510 [RDI_PathfinderUp](ERROR): only read 3 of 4 data items
2020-12-11T00:01:56.417Z,1607644916.417 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for altitude
2020-12-11T00:02:13.721Z,1607644933.721 [RDI_PathfinderUp](ERROR): only read 2 of 4 data items
2020-12-11T00:02:33.520Z,1607644953.520 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for altitude
2020-12-11T00:04:18.558Z,1607645058.558 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for altitude
2020-12-11T00:05:14.722Z,1607645114.722 [sci2:NeedComms] Running Loop=1
2020-12-11T00:05:14.723Z,1607645114.723 [sci2:NeedComms](DEBUG): Aggregate::initialize sci2:NeedComms
2020-12-11T00:05:14.723Z,1607645114.723 [sci2:NeedComms:B.GoToSurface] Running Loop=1
2020-12-11T00:05:14.723Z,1607645114.723 [sci2:NeedComms:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2020-12-11T00:05:14.723Z,1607645114.723 [sci2:NeedComms:B.GoToSurface](INFO): Received depth rate setting nan m/s.
2020-12-11T00:05:14.723Z,1607645114.723 [sci2:NeedComms:B.GoToSurface](INFO): Received pitch setting 19.999999 degrees.
2020-12-11T00:05:14.744Z,1607645114.744 [sci2:NeedComms:B.GoToSurface](INFO): Received speed setting 1.000000 m/s.
2020-12-11T00:05:14.744Z,1607645114.744 [sci2:NeedComms:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2020-12-11T00:05:14.745Z,1607645114.745 [sci2:NeedComms:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2020-12-11T00:05:14.745Z,1607645114.745 [sci2:NeedComms:A] Running Loop=1
2020-12-11T00:05:14.747Z,1607645114.747 [sci2:NeedComms:A](INFO): last time_fix was: 1607641514.000000 second since 1970/01/01T00:00:00Z 
2020-12-11T00:05:14.747Z,1607645114.747 [sci2:NeedComms:A] Stopped
2020-12-11T00:05:41.371Z,1607645141.371 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2020-12-11T00:05:52.709Z,1607645152.709 [sci2:NeedComms:C] Running Loop=1
2020-12-11T00:05:53.436Z,1607645153.436 [Radio_Surface](INFO): Powering up
2020-12-11T00:05:55.798Z,1607645155.798 [CTD_Seabird](ERROR): Salinity reading out of range: 27.258883 psu
2020-12-11T00:05:58.700Z,1607645158.700 [DataOverHttps](INFO): Radio surface powered ON.
2020-12-11T00:06:06.896Z,1607645166.896 [BuoyancyServo](FAULT): Overload Error
2020-12-11T00:06:06.896Z,1607645166.896 [BuoyancyServo] Hardware Fault, FailCount= 1
2020-12-11T00:06:06.896Z,1607645166.896 [BuoyancyServo](ERROR): Hardware Fault
2020-12-11T00:06:06.937Z,1607645166.937 [CBIT](ERROR): Hardware Fault in component: BuoyancyServo
2020-12-11T00:06:08.909Z,1607645168.909 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2020-12-11T00:06:08.909Z,1607645168.909 [BuoyancyServo](INFO): Powering down
2020-12-11T00:06:09.688Z,1607645169.688 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2020-12-11T00:06:09.688Z,1607645169.688 [BuoyancyServo] No Fault, FailCount= 1
2020-12-11T00:06:10.114Z,1607645170.114 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2020-12-11T00:06:10.115Z,1607645170.115 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2020-12-11T00:06:28.828Z,1607645188.828 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-12-11T00:06:36.709Z,1607645196.709 [NAL9602](INFO): SBD MO Status=0, MOMSN=12285, MT Status=0, MTMSN=0
2020-12-11T00:06:36.709Z,1607645196.709 [NAL9602](INFO): No messages in MT queue
2020-12-11T00:06:37.931Z,1607645197.931 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,000638.00,A,4134.20259,N,07044.14897,W,0.447,17.61,111220,,,A*4C
2020-12-11T00:06:37.935Z,1607645197.935 [NAL9602](INFO): GPS fix at 20201211T000638: (41.570043, -70.735816)
2020-12-11T00:06:37.950Z,1607645197.950 [UniversalFixResidualReporter](INFO): Fix residual: 2.9 %DT, over the last 2205.0 m. Residual distance 63.1 m at bearing -149.9 degrees. Fix at (41.5700, -70.7358) with 2253.4 m made good.
2020-12-11T00:06:37.955Z,1607645197.955 [sci2:NeedComms:C] Stopped
2020-12-11T00:06:37.956Z,1607645197.956 [sci2:NeedComms:D] Running Loop=1
2020-12-11T00:06:54.355Z,1607645214.355 [NAL9602](INFO): SBD MO Status=1, MOMSN=12286, MT Status=0, MTMSN=0
2020-12-11T00:06:54.412Z,1607645214.412 [NAL9602](INFO): Sent 92 bytes from file Logs/20201210T215856/Courier0028.lzma
2020-12-11T00:06:54.412Z,1607645214.412 [NAL9602](INFO): Packets left to send: 0
2020-12-11T00:07:03.973Z,1607645223.973 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-12-11T00:07:04.168Z,1607645224.168 [NAL9602](INFO): SBD MO Status=1, MOMSN=12287, MT Status=0, MTMSN=0
2020-12-11T00:07:04.216Z,1607645224.216 [NAL9602](INFO): Sent 184 bytes from file Logs/20201210T215856/Express0029.lzma
2020-12-11T00:07:04.216Z,1607645224.216 [NAL9602](INFO): Packets left to send: 3
2020-12-11T00:07:24.142Z,1607645244.142 [NAL9602](INFO): SBD MO Status=2, MOMSN=12288, MT Status=2, MTMSN=0
2020-12-11T00:07:24.142Z,1607645244.142 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-12-11T00:07:39.124Z,1607645259.124 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-12-11T00:07:46.599Z,1607645266.599 [NAL9602](INFO): SBD MO Status=2, MOMSN=12288, MT Status=2, MTMSN=0
2020-12-11T00:07:46.603Z,1607645266.603 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-12-11T00:08:14.272Z,1607645294.272 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-12-11T00:08:23.103Z,1607645303.103 [NAL9602](INFO): SBD MO Status=2, MOMSN=12288, MT Status=2, MTMSN=0
2020-12-11T00:08:23.103Z,1607645303.103 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-12-11T00:08:49.412Z,1607645329.412 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-12-11T00:08:50.287Z,1607645330.287 [NAL9602](INFO): SBD MO Status=2, MOMSN=12288, MT Status=2, MTMSN=0
2020-12-11T00:08:50.288Z,1607645330.288 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-12-11T00:09:15.501Z,1607645355.501 [NAL9602](INFO): SBD MO Status=1, MOMSN=12288, MT Status=0, MTMSN=0
2020-12-11T00:09:15.548Z,1607645355.548 [NAL9602](INFO): Sent 184 bytes from file Logs/20201210T215856/Express0029.lzma
2020-12-11T00:09:15.548Z,1607645355.548 [NAL9602](INFO): Packets left to send: 2
2020-12-11T00:09:19.537Z,1607645359.537 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003717
2020-12-11T00:09:23.553Z,1607645363.553 [DataOverHttps](INFO): Sending 658 bytes from file Logs/20201210T215856/Express0029.lzma
2020-12-11T00:09:24.554Z,1607645364.554 [DataOverHttps](INFO): Moved sent file to Logs/20201210T215856/Express0029.lzma.bak
2020-12-11T00:09:24.555Z,1607645364.555 [DataOverHttps](INFO): SBD MOMSN=62224
2020-12-11T00:09:25.767Z,1607645365.767 [sci2:NeedComms:D] Stopped
2020-12-11T00:09:25.767Z,1607645365.767 [sci2:NeedComms:E] Running Loop=1
2020-12-11T00:09:32.638Z,1607645372.638 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for altitude
2020-12-11T00:09:34.204Z,1607645374.204 [NAL9602](INFO): SBD MO Status=2, MOMSN=12289, MT Status=2, MTMSN=0
2020-12-11T00:09:34.204Z,1607645374.204 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-12-11T00:09:35.416Z,1607645375.416 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,000935.00,A,4134.19168,N,07044.14924,W,0.311,116.57,111220,,,A*7D
2020-12-11T00:09:35.418Z,1607645375.418 [NAL9602](INFO): GPS fix at 20201211T000935: (41.569861, -70.735821)
2020-12-11T00:09:35.522Z,1607645375.522 [sci2:NeedComms:E] Stopped
2020-12-11T00:09:35.523Z,1607645375.523 [sci2:NeedComms](INFO): Completed sci2:NeedComms
2020-12-11T00:09:35.523Z,1607645375.523 [sci2:NeedComms] Stopped
2020-12-11T00:09:35.523Z,1607645375.523 [sci2:NeedComms](DEBUG): Aggregate::uninitialize sci2:NeedComms
2020-12-11T00:09:35.523Z,1607645375.523 [sci2:NeedComms:B.GoToSurface] Stopped
2020-12-11T00:09:35.523Z,1607645375.523 [sci2:NeedComms:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2020-12-11T00:10:04.721Z,1607645404.721 [DataOverHttps](IMPORTANT): SBD MTMSN=20201211T001004
2020-12-11T00:10:07.790Z,1607645407.790 [NAL9602](INFO): Not Powering down - fast GPS
2020-12-11T00:10:08.746Z,1607645408.746 [DataOverHttps](INFO): Received command:stop
2020-12-11T00:10:08.821Z,1607645408.821 [CommandLine](IMPORTANT): got command stop
2020-12-11T00:10:08.821Z,1607645408.821 [CommandLine](IMPORTANT): Scheduling is paused
2020-12-11T00:10:08.821Z,1607645408.821 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2020-12-11T00:10:09.026Z,1607645409.026 [MissionManager](INFO): MissionManager is completed.
2020-12-11T00:10:09.026Z,1607645409.026 [MissionManager](INFO): Uninitializing Mission sci2
2020-12-11T00:10:09.026Z,1607645409.026 [sci2] Stopped
2020-12-11T00:10:09.026Z,1607645409.026 [sci2](DEBUG): Aggregate::uninitialize sci2
2020-12-11T00:10:09.026Z,1607645409.026 [sci2:Science] Stopped
2020-12-11T00:10:09.027Z,1607645409.027 [sci2:Science](DEBUG): Aggregate::uninitialize sci2:Science
2020-12-11T00:10:09.027Z,1607645409.027 [sci2:Science:B] Stopped
2020-12-11T00:10:09.027Z,1607645409.027 [sci2:Science:C] Stopped
2020-12-11T00:10:09.027Z,1607645409.027 [sci2:Science:E] Stopped
2020-12-11T00:10:09.027Z,1607645409.027 [sci2:Science:Read_Oil] Stopped
2020-12-11T00:10:09.027Z,1607645409.027 [sci2:Science:OceanCurrent] Stopped
2020-12-11T00:10:09.027Z,1607645409.027 [sci2:Science:OceanCurrent](DEBUG): Aggregate::uninitialize sci2:Science:OceanCurrent
2020-12-11T00:10:09.027Z,1607645409.027 [sci2:Science:OceanCurrent:A.] Stopped
2020-12-11T00:10:09.027Z,1607645409.027 [sci2:Science:PeakDetectChl] Stopped
2020-12-11T00:10:09.027Z,1607645409.027 [sci2:Science:PeakDetectChl](DEBUG): Aggregate::uninitialize sci2:Science:PeakDetectChl
2020-12-11T00:10:09.027Z,1607645409.027 [sci2:Science:PeakDetectChl:A.PeakDetectVsDepth] Stopped
2020-12-11T00:10:09.027Z,1607645409.027 [sci2:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2020-12-11T00:10:09.027Z,1607645409.027 [sci2:StandardEnvelopes] Stopped
2020-12-11T00:10:09.027Z,1607645409.027 [sci2:StandardEnvelopes](DEBUG): Aggregate::uninitialize sci2:StandardEnvelopes
2020-12-11T00:10:09.032Z,1607645409.032 [sci2:StandardEnvelopes:A.AltitudeEnvelope] Stopped
2020-12-11T00:10:09.032Z,1607645409.032 [sci2:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2020-12-11T00:10:09.033Z,1607645409.033 [sci2:StandardEnvelopes:B.DepthEnvelope] Stopped
2020-12-11T00:10:09.033Z,1607645409.033 [sci2:StandardEnvelopes:B.DepthEnvelope](DEBUG): Uninitialize.
2020-12-11T00:10:09.033Z,1607645409.033 [sci2:StandardEnvelopes:C.OffshoreEnvelope] Stopped
2020-12-11T00:10:09.034Z,1607645409.034 [sci2:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2020-12-11T00:10:09.034Z,1607645409.034 [sci2:I.Pitch] Stopped
2020-12-11T00:10:09.034Z,1607645409.034 [sci2:J.Buoyancy] Stopped
2020-12-11T00:10:09.034Z,1607645409.034 [sci2:J.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2020-12-11T00:10:09.035Z,1607645409.035 [sci2:K.SetSpeed] Stopped
2020-12-11T00:10:09.035Z,1607645409.035 [sci2:K.SetSpeed](DEBUG): Uninitialize.
2020-12-11T00:10:09.035Z,1607645409.035 [sci2:L.DepthEnvelope] Stopped
2020-12-11T00:10:09.035Z,1607645409.035 [sci2:L.DepthEnvelope](DEBUG): Uninitialize.
2020-12-11T00:10:09.041Z,1607645409.041 [sci2:M.AltitudeEnvelope] Stopped
2020-12-11T00:10:09.041Z,1607645409.041 [sci2:M.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2020-12-11T00:10:09.041Z,1607645409.041 [sci2:N.YoYo] Stopped
2020-12-11T00:10:09.042Z,1607645409.042 [sci2:N.YoYo](DEBUG): Uninitialize YoYoComponent.
2020-12-11T00:10:09.042Z,1607645409.042 [sci2:Lap] Stopped
2020-12-11T00:10:09.042Z,1607645409.042 [sci2:Lap](DEBUG): Aggregate::uninitialize sci2:Lap
2020-12-11T00:10:09.042Z,1607645409.042 [sci2:Lap:Wpt1] Stopped
2020-12-11T00:10:09.043Z,1607645409.043 [sci2:Lap:Wpt1](DEBUG): Aggregate::uninitialize sci2:Lap:Wpt1
2020-12-11T00:10:09.043Z,1607645409.043 [sci2:Lap:Wpt1:A.Waypoint] Stopped
2020-12-11T00:10:09.043Z,1607645409.043 [sci2:Lap:Wpt1:A.Waypoint](DEBUG): Uninitialize WaypointComponent.
2020-12-11T00:10:09.264Z,1607645409.264 [WetLabsSeaOWL_UV_A](INFO): Powering down
2020-12-11T00:10:09.430Z,1607645409.430 [MissionManager](IMPORTANT): Started mission DefaultWithUndock
2020-12-11T00:10:09.430Z,1607645409.430 [DefaultWithUndock] Running Loop=1
2020-12-11T00:10:09.430Z,1607645409.430 [DefaultWithUndock](DEBUG): Aggregate::initialize DefaultWithUndock
2020-12-11T00:10:09.431Z,1607645409.431 [DefaultWithUndock:A.Wait] Running Loop=1
2020-12-11T00:10:09.431Z,1607645409.431 [DefaultWithUndock:A.Wait](DEBUG): Initialize Wait Component.
2020-12-11T00:10:39.710Z,1607645439.710 [DefaultWithUndock:A.Wait](INFO): Done Waiting.
2020-12-11T00:10:39.710Z,1607645439.710 [DefaultWithUndock:A.Wait] Stopped
2020-12-11T00:10:39.710Z,1607645439.710 [DefaultWithUndock:A.Wait](DEBUG): Uninitialize Wait Component.
2020-12-11T00:10:39.710Z,1607645439.710 [DefaultWithUndock:LeaveDock] Running Loop=1
2020-12-11T00:10:39.710Z,1607645439.710 [DefaultWithUndock:LeaveDock](DEBUG): Aggregate::initialize DefaultWithUndock:LeaveDock
2020-12-11T00:10:39.710Z,1607645439.710 [DefaultWithUndock:LeaveDock:A.] Running Loop=1
2020-12-11T00:10:39.710Z,1607645439.710 [DefaultWithUndock:LeaveDock:A.](INFO): Initializing TrackAcousticContact.
2020-12-11T00:10:39.710Z,1607645439.710 [DefaultWithUndock:LeaveDock:B.Undock] Running Loop=1
2020-12-11T00:10:39.710Z,1607645439.710 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initialize.
2020-12-11T00:10:39.711Z,1607645439.711 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initializing internal variables to default values.
2020-12-11T00:10:42.567Z,1607645442.567 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-11T00:10:43.516Z,1607645443.516 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detaching from dock.
2020-12-11T00:10:43.809Z,1607645443.809 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detected possible detachment. Starting timer.
2020-12-11T00:10:45.428Z,1607645445.428 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-11T00:10:46.989Z,1607645446.989 [DUSBL_Hydroid](ERROR): No response from remote modem.
2020-12-11T00:10:48.234Z,1607645448.234 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-11T00:10:51.096Z,1607645451.096 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-11T00:10:52.641Z,1607645452.641 [DUSBL_Hydroid](ERROR): No response from remote modem.
2020-12-11T00:10:53.869Z,1607645453.869 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-11T00:10:56.702Z,1607645456.702 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-11T00:10:58.293Z,1607645458.293 [DUSBL_Hydroid](ERROR): No response from remote modem.
2020-12-11T00:10:59.560Z,1607645459.560 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-11T00:11:02.395Z,1607645462.395 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-11T00:11:03.957Z,1607645463.957 [DUSBL_Hydroid](ERROR): No response from remote modem.
2020-12-11T00:11:03.970Z,1607645463.970 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detached at range: 1104.18 m. Transitioning DDM to standby.
2020-12-11T00:11:05.202Z,1607645465.202 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-11T00:11:06.821Z,1607645466.821 [DefaultWithUndock:LeaveDock:B.Undock](INFO): DDM at standby.
2020-12-11T00:11:07.236Z,1607645467.236 [DefaultWithUndock:LeaveDock:B.Undock](IMPORTANT): Undocking sequence complete.
2020-12-11T00:11:07.237Z,1607645467.237 [DefaultWithUndock:LeaveDock:B.Undock] Stopped
2020-12-11T00:11:07.237Z,1607645467.237 [DefaultWithUndock:LeaveDock](INFO): Completed DefaultWithUndock:LeaveDock
2020-12-11T00:11:07.237Z,1607645467.237 [DefaultWithUndock:LeaveDock] Stopped
2020-12-11T00:11:07.237Z,1607645467.237 [DefaultWithUndock:LeaveDock](DEBUG): Aggregate::uninitialize DefaultWithUndock:LeaveDock
2020-12-11T00:11:07.237Z,1607645467.237 [DefaultWithUndock:LeaveDock:A.] Stopped
2020-12-11T00:11:07.238Z,1607645467.238 [DefaultWithUndock:SurfaceDefault] Running Loop=1
2020-12-11T00:11:07.238Z,1607645467.238 [DefaultWithUndock:SurfaceDefault](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault
2020-12-11T00:11:07.238Z,1607645467.238 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen] Running Loop=1
2020-12-11T00:11:07.238Z,1607645467.238 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:HoldLatchOpen
2020-12-11T00:11:07.238Z,1607645467.238 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen:A] Running Loop=1
2020-12-11T00:11:07.238Z,1607645467.238 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen:B] Running Loop=1
2020-12-11T00:11:07.238Z,1607645467.238 [DefaultWithUndock:SurfaceDefault:B.GoToSurface] Running Loop=1
2020-12-11T00:11:07.238Z,1607645467.238 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2020-12-11T00:11:07.238Z,1607645467.238 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2020-12-11T00:11:07.239Z,1607645467.239 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2020-12-11T00:11:07.239Z,1607645467.239 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2020-12-11T00:11:07.239Z,1607645467.239 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2020-12-11T00:11:07.240Z,1607645467.240 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2020-12-11T00:11:07.583Z,1607645467.583 [DefaultWithUndock:SurfaceDefault:CheckIn] Running Loop=1
2020-12-11T00:11:07.583Z,1607645467.583 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:CheckIn
2020-12-11T00:11:07.583Z,1607645467.583 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Running Loop=1
2020-12-11T00:11:07.583Z,1607645467.583 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen] Stopped
2020-12-11T00:11:07.583Z,1607645467.583 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:HoldLatchOpen
2020-12-11T00:11:07.583Z,1607645467.583 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen:A] Stopped
2020-12-11T00:11:07.600Z,1607645467.600 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen:B] Stopped
2020-12-11T00:11:09.581Z,1607645469.581 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,001109.00,A,4134.19381,N,07044.14630,W,0.564,8.41,111220,,,A*79
2020-12-11T00:11:09.583Z,1607645469.583 [NAL9602](INFO): GPS fix at 20201211T001109: (41.569897, -70.735772)
2020-12-11T00:11:09.604Z,1607645469.604 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Stopped
2020-12-11T00:11:09.604Z,1607645469.604 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Running Loop=1
2020-12-11T00:11:14.007Z,1607645474.007 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20201210T215856/Courier0031.lzma
2020-12-11T00:11:15.010Z,1607645475.010 [DataOverHttps](INFO): Moved sent file to Logs/20201210T215856/Courier0031.lzma.bak
2020-12-11T00:11:15.010Z,1607645475.010 [DataOverHttps](INFO): SBD MOMSN=62231
2020-12-11T00:11:24.056Z,1607645484.056 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20201210T215856/Express0032.lzma
2020-12-11T00:11:25.057Z,1607645485.057 [DataOverHttps](INFO): Moved sent file to Logs/20201210T215856/Express0032.lzma.bak
2020-12-11T00:11:25.058Z,1607645485.058 [DataOverHttps](INFO): SBD MOMSN=62234
2020-12-11T00:11:27.379Z,1607645487.379 [NAL9602](INFO): SBD MO Status=1, MOMSN=12289, MT Status=0, MTMSN=0
2020-12-11T00:11:27.379Z,1607645487.379 [NAL9602](INFO): No messages in MT queue
2020-12-11T00:11:34.088Z,1607645494.088 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20201210T215856/Express0035.lzma
2020-12-11T00:11:35.090Z,1607645495.090 [DataOverHttps](INFO): Moved sent file to Logs/20201210T215856/Express0035.lzma.bak
2020-12-11T00:11:35.090Z,1607645495.090 [DataOverHttps](INFO): SBD MOMSN=62241
2020-12-11T00:11:36.279Z,1607645496.279 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Stopped
2020-12-11T00:11:36.284Z,1607645496.284 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Running Loop=1
2020-12-11T00:11:36.284Z,1607645496.284 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-12-11T00:11:58.092Z,1607645518.092 [NAL9602](INFO): Not Powering down - fast GPS
2020-12-11T00:12:40.356Z,1607645560.356 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.247185
2020-12-11T00:13:16.500Z,1607645596.500 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-12-11T00:13:25.541Z,1607645605.541 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003797
2020-12-11T00:14:00.684Z,1607645640.684 [DataOverHttps](IMPORTANT): SBD MTMSN=20201211T001400
2020-12-11T00:14:04.700Z,1607645644.700 [DataOverHttps](INFO): Received command:configSet LBLNavigation.loadAtStartup 0 bool persist;restart app
2020-12-11T00:14:04.859Z,1607645644.859 [CommandLine](IMPORTANT): got command configSet LBLNavigation.loadAtStartup 0.000000 bool persist
2020-12-11T00:14:04.859Z,1607645644.859 [CommandLine](IMPORTANT): configSet LBLNavigation.loadAtStartup requires a restart to take effect.
2020-12-11T00:14:04.862Z,1607645644.862 [CommandLine](IMPORTANT): got command restart application
2020-12-11T00:14:05.864Z,1607645645.864 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2020-12-11T00:14:05.864Z,1607645645.864 [CommandLine ThreadHandler](INFO): Thread cancelled.
2020-12-11T00:14:05.876Z,1607645645.876 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2020-12-11T00:14:05.876Z,1607645645.876 [CommandLine ThreadHandler](INFO): Thread cancelled.
2020-12-11T00:14:05.877Z,1607645645.877 [CommandLine](INFO): Join timeout helper Thread ID is 2621
2020-12-11T00:14:05.877Z,1607645645.877 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2020-12-11T00:14:05.877Z,1607645645.877 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2020-12-11T00:14:05.878Z,1607645645.878 [NavChartDb](INFO): Join timeout helper Thread ID is 2622
2020-12-11T00:14:05.888Z,1607645645.888 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2020-12-11T00:14:05.888Z,1607645645.888 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2020-12-11T00:14:05.896Z,1607645645.896 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2020-12-11T00:14:05.896Z,1607645645.896 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2020-12-11T00:14:05.896Z,1607645645.896 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 2623
2020-12-11T00:14:06.024Z,1607645646.024 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2020-12-11T00:14:06.024Z,1607645646.024 [WetLabsSeaOWL_UV_A](INFO): Powering down
2020-12-11T00:14:06.025Z,1607645646.025 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2020-12-11T00:14:06.040Z,1607645646.040 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2020-12-11T00:14:06.040Z,1607645646.040 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2020-12-11T00:14:06.041Z,1607645646.041 [CTD_Seabird](INFO): Join timeout helper Thread ID is 2624
2020-12-11T00:14:06.840Z,1607645646.840 [CTD_Seabird](INFO): Powering down
2020-12-11T00:14:06.852Z,1607645646.852 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2020-12-11T00:14:06.852Z,1607645646.852 [CTD_Seabird](INFO): Powering down
2020-12-11T00:14:06.864Z,1607645646.864 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2020-12-11T00:14:06.868Z,1607645646.868 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2020-12-11T00:14:06.868Z,1607645646.868 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2020-12-11T00:14:06.868Z,1607645646.868 [Radio_Surface](INFO): Join timeout helper Thread ID is 2625
2020-12-11T00:14:07.185Z,1607645647.185 [Radio_Surface](INFO): Powering down
2020-12-11T00:14:07.186Z,1607645647.186 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2020-12-11T00:14:07.187Z,1607645647.187 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2020-12-11T00:14:07.205Z,1607645647.205 [ComponentRegistry](INFO): Shutting down Onboard ThreadHandler
2020-12-11T00:14:07.205Z,1607645647.205 [Onboard ThreadHandler](INFO): Thread cancelled.
2020-12-11T00:14:07.205Z,1607645647.205 [Onboard](INFO): Join timeout helper Thread ID is 2626
2020-12-11T00:14:07.708Z,1607645647.708 [DataOverHttps](INFO): Radio surface powered OFF, will not connect.
2020-12-11T00:14:08.972Z,1607645648.972 [Onboard ThreadHandler](INFO): Uninitializing protected caller thread.
2020-12-11T00:14:08.972Z,1607645648.972 [Onboard ThreadHandler](INFO): Thread cancelled.
2020-12-11T00:14:08.989Z,1607645648.989 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2020-12-11T00:14:08.989Z,1607645648.989 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2020-12-11T00:14:08.990Z,1607645648.990 [DataOverHttps](INFO): Join timeout helper Thread ID is 2627
2020-12-11T00:14:09.716Z,1607645649.716 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2020-12-11T00:14:09.716Z,1607645649.716 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2020-12-11T00:14:09.733Z,1607645649.733 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2020-12-11T00:14:09.733Z,1607645649.733 [logger ThreadHandler](INFO): Thread cancelled.
2020-12-11T00:14:09.733Z,1607645649.733 [logger](INFO): Join timeout helper Thread ID is 2628
2020-12-11T00:14:09.736Z,1607645649.736 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2020-12-11T00:14:09.736Z,1607645649.736 [logger ThreadHandler](INFO): Thread cancelled.
2020-12-11T00:14:09.752Z,1607645649.752 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2020-12-11T00:14:09.753Z,1607645649.753 [CommandLine ThreadHandler](INFO): Thread cancelled.
2020-12-11T00:14:09.753Z,1607645649.753 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2020-12-11T00:14:09.753Z,1607645649.753 [controlThread ThreadHandler](INFO): Thread cancelled.
2020-12-11T00:14:09.753Z,1607645649.753 [controlThread](INFO): Join timeout helper Thread ID is 2629
2020-12-11T00:14:09.784Z,1607645649.784 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2020-12-11T00:14:09.784Z,1607645649.784 [controlThread](DEBUG): Uninitializing ControlThread
2020-12-11T00:14:09.785Z,1607645649.785 [AHRS_M2](INFO): Powering down
2020-12-11T00:14:09.857Z,1607645649.857 [DDM](INFO): Powering down
2020-12-11T00:14:09.928Z,1607645649.928 [DUSBL_Hydroid](INFO): Powering down
2020-12-11T00:14:10.000Z,1607645650.000 [Micromodem](INFO): Powering down
2020-12-11T00:14:10.096Z,1607645650.096 [NAL9602](INFO): Powering down
2020-12-11T00:14:10.168Z,1607645650.168 [RDI_Pathfinder](INFO): Powering down
2020-12-11T00:14:10.240Z,1607645650.240 [RDI_PathfinderUp](INFO): Powering down
2020-12-11T00:14:10.241Z,1607645650.241 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2020-12-11T00:14:10.242Z,1607645650.242 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2020-12-11T00:14:10.243Z,1607645650.243 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2020-12-11T00:14:10.243Z,1607645650.243 [MissionManager](INFO): Uninitializing Mission DefaultWithUndock
2020-12-11T00:14:10.243Z,1607645650.243 [DefaultWithUndock] Stopped
2020-12-11T00:14:10.244Z,1607645650.244 [DefaultWithUndock](DEBUG): Aggregate::uninitialize DefaultWithUndock
2020-12-11T00:14:10.244Z,1607645650.244 [DefaultWithUndock:SurfaceDefault] Stopped
2020-12-11T00:14:10.244Z,1607645650.244 [DefaultWithUndock:SurfaceDefault](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault
2020-12-11T00:14:10.244Z,1607645650.244 [DefaultWithUndock:SurfaceDefault:B.GoToSurface] Stopped
2020-12-11T00:14:10.244Z,1607645650.244 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2020-12-11T00:14:10.244Z,1607645650.244 [DefaultWithUndock:SurfaceDefault:CheckIn] Stopped
2020-12-11T00:14:10.244Z,1607645650.244 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:CheckIn
2020-12-11T00:14:10.244Z,1607645650.244 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Stopped
2020-12-11T00:14:10.244Z,1607645650.244 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-12-11T00:14:10.251Z,1607645650.251 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2020-12-11T00:14:10.252Z,1607645650.252 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2020-12-11T00:14:10.252Z,1607645650.252 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2020-12-11T00:14:10.253Z,1607645650.253 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2020-12-11T00:14:10.253Z,1607645650.253 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2020-12-11T00:14:10.253Z,1607645650.253 [BuoyancyServo](INFO): Powering down
2020-12-11T00:14:10.268Z,1607645650.268 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2020-12-11T00:14:10.268Z,1607645650.268 [ElevatorServo](INFO): Powering down
2020-12-11T00:14:10.269Z,1607645650.269 [MassServo](DEBUG): Uninitialize Mass Servo.
2020-12-11T00:14:10.269Z,1607645650.269 [MassServo](INFO): Powering down
2020-12-11T00:14:10.270Z,1607645650.270 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2020-12-11T00:14:10.270Z,1607645650.270 [RudderServo](INFO): Powering down
2020-12-11T00:14:10.271Z,1607645650.271 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2020-12-11T00:14:10.271Z,1607645650.271 [ThrusterServo](INFO): Powering down
2020-12-11T00:14:10.271Z,1607645650.271 [SBIT](DEBUG): Uninitialize SBIT Component.
2020-12-11T00:14:10.272Z,1607645650.272 [IBIT](DEBUG): Uninitialize IBIT Component.
2020-12-11T00:14:10.272Z,1607645650.272 [CBIT](DEBUG): Uninitialize CBIT Component.
2020-12-11T00:14:10.272Z,1607645650.272 [CBIT](DEBUG): Powering off loads.
2020-12-11T00:14:10.284Z,1607645650.284 [CBIT](DEBUG): Disabling WDT.
2020-12-11T00:14:10.296Z,1607645650.296 [CBIT](DEBUG): Opening all GF detection circuits.
2020-12-11T00:14:10.297Z,1607645650.297 [controlThread ThreadHandler](INFO): Thread cancelled.
2020-12-11T00:14:10.315Z,1607645650.315 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2020-12-11T00:14:10.318Z,1607645650.318 [Onboard ThreadHandler](INFO): Thread cancelled.
2020-12-11T00:14:10.328Z,1607645650.328 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2020-12-11T00:14:10.413Z,1607645650.413 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2020-12-11T00:14:10.417Z,1607645650.417 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2020-12-11T00:14:10.473Z,1607645650.473 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2020-12-11T00:14:10.540Z,1607645650.540 [logger ThreadHandler](INFO): Thread cancelled.