2021-04-02T18:00:16.796Z,1617386416.796 [Supervisor](DEBUG): Initializing supervisor.
2021-04-02T18:00:16.800Z,1617386416.800 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2021-04-02T18:00:16.801Z,1617386416.801 [SyncHandler](INFO): Protected caller Thread ID is 4187
2021-04-02T18:00:16.801Z,1617386416.801 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2021-04-02T18:00:16.802Z,1617386416.802 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2021-04-02T18:00:16.802Z,1617386416.802 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 4188
2021-04-02T18:00:16.806Z,1617386416.806 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2021-04-02T18:00:16.825Z,1617386416.825 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2021-04-02T18:00:16.826Z,1617386416.826 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2021-04-02T18:00:16.826Z,1617386416.826 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 4189
2021-04-02T18:00:16.828Z,1617386416.828 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2021-04-02T18:00:16.829Z,1617386416.829 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2021-04-02T18:00:16.830Z,1617386416.830 [logger ThreadHandler](INFO): Protected caller Thread ID is 4190
2021-04-02T18:00:16.833Z,1617386416.833 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2021-04-02T18:00:16.834Z,1617386416.834 [Supervisor](INFO): Looking for Config files in directory: Config/
2021-04-02T18:00:16.835Z,1617386416.835 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2021-04-02T18:00:17.167Z,1617386417.167 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2021-04-02T18:00:17.167Z,1617386417.167 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2021-04-02T18:00:17.773Z,1617386417.773 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2021-04-02T18:00:17.773Z,1617386417.773 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2021-04-02T18:00:17.874Z,1617386417.874 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2021-04-02T18:00:17.875Z,1617386417.875 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2021-04-02T18:00:18.394Z,1617386418.394 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2021-04-02T18:00:18.395Z,1617386418.395 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2021-04-02T18:00:18.492Z,1617386418.492 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2021-04-02T18:00:18.493Z,1617386418.493 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2021-04-02T18:00:18.575Z,1617386418.575 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2021-04-02T18:00:18.930Z,1617386418.930 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2021-04-02T18:00:18.931Z,1617386418.931 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2021-04-02T18:00:19.080Z,1617386419.080 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2021-04-02T18:00:19.081Z,1617386419.081 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2021-04-02T18:00:19.207Z,1617386419.207 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2021-04-02T18:00:19.208Z,1617386419.208 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2021-04-02T18:00:19.435Z,1617386419.435 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2021-04-02T18:00:19.435Z,1617386419.435 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2021-04-02T18:00:19.873Z,1617386419.873 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2021-04-02T18:00:19.873Z,1617386419.873 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2021-04-02T18:00:20.239Z,1617386420.239 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2021-04-02T18:00:20.239Z,1617386420.239 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2021-04-02T18:00:20.320Z,1617386420.320 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2021-04-02T18:00:20.512Z,1617386420.512 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2021-04-02T18:00:20.513Z,1617386420.513 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2021-04-02T18:00:20.722Z,1617386420.722 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2021-04-02T18:00:20.723Z,1617386420.723 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2021-04-02T18:00:20.969Z,1617386420.969 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2021-04-02T18:00:20.971Z,1617386420.971 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-brizo/
2021-04-02T18:00:20.972Z,1617386420.972 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Control.cfg
2021-04-02T18:00:21.070Z,1617386421.070 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Sensor.cfg
2021-04-02T18:00:21.214Z,1617386421.214 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Simulator.cfg
2021-04-02T18:00:21.301Z,1617386421.301 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/secure.cfg
2021-04-02T18:00:21.399Z,1617386421.399 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Servo.cfg
2021-04-02T18:00:21.758Z,1617386421.758 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/vehicle.cfg
2021-04-02T18:00:22.166Z,1617386422.166 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Battery.cfg
2021-04-02T18:00:22.539Z,1617386422.539 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2021-04-02T18:00:22.539Z,1617386422.539 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Science.cfg
2021-04-02T18:00:22.660Z,1617386422.660 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/logger.cfg
2021-04-02T18:00:22.757Z,1617386422.757 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/BIT.cfg
2021-04-02T18:00:22.864Z,1617386422.864 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Navigation.cfg
2021-04-02T18:00:22.960Z,1617386422.960 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2021-04-02T18:00:22.965Z,1617386422.965 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2021-04-02T18:00:23.048Z,1617386423.048 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2021-04-02T18:00:23.049Z,1617386423.049 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2021-04-02T18:00:23.059Z,1617386423.059 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2021-04-02T18:00:23.059Z,1617386423.059 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2021-04-02T18:00:23.100Z,1617386423.100 [DepthRateCalculator] Loaded
2021-04-02T18:00:23.100Z,1617386423.100 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2021-04-02T18:00:23.105Z,1617386423.105 [PitchRateCalculator] Loaded
2021-04-02T18:00:23.105Z,1617386423.105 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2021-04-02T18:00:23.115Z,1617386423.115 [SpeedCalculator] Loaded
2021-04-02T18:00:23.116Z,1617386423.116 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2021-04-02T18:00:23.128Z,1617386423.128 [TempGradientCalculator] Loaded
2021-04-02T18:00:23.128Z,1617386423.128 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2021-04-02T18:00:23.133Z,1617386423.133 [YawRateCalculator] Loaded
2021-04-02T18:00:23.133Z,1617386423.133 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2021-04-02T18:00:23.152Z,1617386423.152 [ElevatorOffsetCalculator] Loaded
2021-04-02T18:00:23.153Z,1617386423.153 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2021-04-02T18:00:23.153Z,1617386423.153 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2021-04-02T18:00:23.154Z,1617386423.154 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2021-04-02T18:00:23.204Z,1617386423.204 [VerticalControl](DEBUG): Construct VerticalControl.
2021-04-02T18:00:23.259Z,1617386423.259 [VerticalControl] Loaded
2021-04-02T18:00:23.259Z,1617386423.259 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2021-04-02T18:00:23.262Z,1617386423.262 [HorizontalControl](DEBUG): Construct HorizontalControl.
2021-04-02T18:00:23.298Z,1617386423.298 [HorizontalControl] Loaded
2021-04-02T18:00:23.298Z,1617386423.298 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2021-04-02T18:00:23.300Z,1617386423.300 [SpeedControl](DEBUG): Construct SpeedControl.
2021-04-02T18:00:23.303Z,1617386423.303 [SpeedControl] Loaded
2021-04-02T18:00:23.303Z,1617386423.303 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2021-04-02T18:00:23.306Z,1617386423.306 [LoopControl](DEBUG): Construct LoopControl.
2021-04-02T18:00:23.306Z,1617386423.306 [LoopControl] Loaded
2021-04-02T18:00:23.306Z,1617386423.306 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2021-04-02T18:00:23.307Z,1617386423.307 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2021-04-02T18:00:23.307Z,1617386423.307 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2021-04-02T18:00:23.384Z,1617386423.384 [DeadReckonUsingMultipleVelocitySources] Loaded
2021-04-02T18:00:23.385Z,1617386423.385 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2021-04-02T18:00:23.397Z,1617386423.397 [NavChart] Loaded
2021-04-02T18:00:23.397Z,1617386423.397 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2021-04-02T18:00:23.403Z,1617386423.403 [UniversalFixResidualReporter] Loaded
2021-04-02T18:00:23.403Z,1617386423.403 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2021-04-02T18:00:23.403Z,1617386423.403 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2021-04-02T18:00:23.404Z,1617386423.404 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2021-04-02T18:00:23.500Z,1617386423.500 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2021-04-02T18:00:23.501Z,1617386423.501 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2021-04-02T18:00:23.847Z,1617386423.847 [AHRS_M2] Loaded
2021-04-02T18:00:23.848Z,1617386423.848 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2021-04-02T18:00:24.955Z,1617386424.955 [BPC1] Loaded
2021-04-02T18:00:24.955Z,1617386424.955 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2021-04-02T18:00:25.031Z,1617386425.031 [DataOverHttps] Loaded
2021-04-02T18:00:25.031Z,1617386425.031 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2021-04-02T18:00:25.032Z,1617386425.032 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 408674E0
2021-04-02T18:00:25.033Z,1617386425.033 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 4272
2021-04-02T18:00:25.052Z,1617386425.052 [Depth_Keller] Loaded
2021-04-02T18:00:25.052Z,1617386425.052 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2021-04-02T18:00:25.056Z,1617386425.056 [DropWeight] Loaded
2021-04-02T18:00:25.056Z,1617386425.056 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2021-04-02T18:00:25.090Z,1617386425.090 [DVL_micro] Loaded
2021-04-02T18:00:25.090Z,1617386425.090 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2021-04-02T18:00:25.146Z,1617386425.146 [NAL9602] Loaded
2021-04-02T18:00:25.147Z,1617386425.147 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2021-04-02T18:00:25.174Z,1617386425.174 [Onboard] Loaded
2021-04-02T18:00:25.175Z,1617386425.175 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2021-04-02T18:00:25.176Z,1617386425.176 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 408974E0
2021-04-02T18:00:25.176Z,1617386425.176 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 4273
2021-04-02T18:00:25.189Z,1617386425.189 [Radio_Surface] Loaded
2021-04-02T18:00:25.189Z,1617386425.189 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2021-04-02T18:00:25.190Z,1617386425.190 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408C74E0
2021-04-02T18:00:25.190Z,1617386425.190 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 4274
2021-04-02T18:00:25.268Z,1617386425.268 [DAT] Loaded
2021-04-02T18:00:25.268Z,1617386425.268 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2021-04-02T18:00:25.268Z,1617386425.268 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2021-04-02T18:00:25.269Z,1617386425.269 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2021-04-02T18:00:25.374Z,1617386425.374 [BuoyancyServo] Loaded
2021-04-02T18:00:25.374Z,1617386425.374 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2021-04-02T18:00:25.393Z,1617386425.393 [ElevatorServo] Loaded
2021-04-02T18:00:25.394Z,1617386425.394 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2021-04-02T18:00:25.411Z,1617386425.411 [MassServo] Loaded
2021-04-02T18:00:25.412Z,1617386425.412 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2021-04-02T18:00:25.429Z,1617386425.429 [RudderServo] Loaded
2021-04-02T18:00:25.429Z,1617386425.429 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2021-04-02T18:00:25.446Z,1617386425.446 [ThrusterServo] Loaded
2021-04-02T18:00:25.446Z,1617386425.446 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2021-04-02T18:00:25.446Z,1617386425.446 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2021-04-02T18:00:25.447Z,1617386425.447 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2021-04-02T18:00:25.499Z,1617386425.499 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2021-04-02T18:00:25.499Z,1617386425.499 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2021-04-02T18:00:25.526Z,1617386425.526 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2021-04-02T18:00:25.527Z,1617386425.527 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2021-04-02T18:00:25.829Z,1617386425.829 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2021-04-02T18:00:25.829Z,1617386425.829 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2021-04-02T18:00:25.994Z,1617386425.994 [CTD_Seabird] Loaded
2021-04-02T18:00:25.995Z,1617386425.995 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2021-04-02T18:00:25.996Z,1617386425.996 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40A4F4E0
2021-04-02T18:00:25.996Z,1617386425.996 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 4275
2021-04-02T18:00:26.028Z,1617386426.028 [ESPComponent] Loaded
2021-04-02T18:00:26.028Z,1617386426.028 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2021-04-02T18:00:26.046Z,1617386426.046 [PAR_Licor] Loaded
2021-04-02T18:00:26.047Z,1617386426.047 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2021-04-02T18:00:26.077Z,1617386426.077 [WetLabsBB2FL] Loaded
2021-04-02T18:00:26.077Z,1617386426.077 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2021-04-02T18:00:26.078Z,1617386426.078 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40A7F4E0
2021-04-02T18:00:26.079Z,1617386426.079 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 4276
2021-04-02T18:00:26.079Z,1617386426.079 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2021-04-02T18:00:26.080Z,1617386426.080 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2021-04-02T18:00:26.215Z,1617386426.215 [SBIT](DEBUG): Construct Startup Built In Test.
2021-04-02T18:00:26.224Z,1617386426.224 [SBIT] Loaded
2021-04-02T18:00:26.224Z,1617386426.224 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2021-04-02T18:00:26.227Z,1617386426.227 [IBIT](DEBUG): Construct Initiated Built In Test.
2021-04-02T18:00:26.239Z,1617386426.239 [IBIT] Loaded
2021-04-02T18:00:26.240Z,1617386426.240 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2021-04-02T18:00:26.245Z,1617386426.245 [CBIT](DEBUG): Construct Continuous Built In Test.
2021-04-02T18:00:26.343Z,1617386426.343 [CBIT] Loaded
2021-04-02T18:00:26.343Z,1617386426.343 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2021-04-02T18:00:26.344Z,1617386426.344 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2021-04-02T18:00:26.350Z,1617386426.350 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2021-04-02T18:00:26.352Z,1617386426.352 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2021-04-02T18:00:26.362Z,1617386426.362 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2021-04-02T18:00:26.363Z,1617386426.363 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AEB4E0
2021-04-02T18:00:26.364Z,1617386426.364 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 4277
2021-04-02T18:00:26.368Z,1617386426.368 [Supervisor](INFO): Main Thread ID is 4018
2021-04-02T18:00:26.368Z,1617386426.368 [Supervisor](DEBUG): Running supervisor.
2021-04-02T18:00:26.369Z,1617386426.369 [CommandLine ThreadHandler](INFO): Handler Thread ID is 4278
2021-04-02T18:00:26.371Z,1617386426.371 [controlThread ThreadHandler](INFO): Handler Thread ID is 4279
2021-04-02T18:00:26.372Z,1617386426.372 [controlThread](DEBUG): Initializing ControlThread
2021-04-02T18:00:26.372Z,1617386426.372 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2021-04-02T18:00:26.373Z,1617386426.373 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2021-04-02T18:00:26.373Z,1617386426.373 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2021-04-02T18:00:26.373Z,1617386426.373 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2021-04-02T18:00:26.374Z,1617386426.374 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2021-04-02T18:00:26.374Z,1617386426.374 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2021-04-02T18:00:26.375Z,1617386426.375 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2021-04-02T18:00:26.377Z,1617386426.377 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2021-04-02T18:00:26.377Z,1617386426.377 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2021-04-02T18:00:26.378Z,1617386426.378 [LoopControl](DEBUG): Initialize LoopControlComponent.
2021-04-02T18:00:26.379Z,1617386426.379 [NavChart](DEBUG): Initialize NavChart Navigation.
2021-04-02T18:00:26.379Z,1617386426.379 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2021-04-02T18:00:26.385Z,1617386426.385 [SBIT](INFO): Initialize SBIT Component.
2021-04-02T18:00:26.385Z,1617386426.385 [SBIT](IMPORTANT): git: 2021-03-26
2021-04-02T18:00:26.386Z,1617386426.386 [SBIT](INFO): git hash: 3e39556f75aeeaed90da67e82e5e852ed9f537e3
2021-04-02T18:00:26.386Z,1617386426.386 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2021-04-02T18:00:26.386Z,1617386426.386 [SBIT](IMPORTANT): Kernel Version:#1 PREEMPT Tue Sep 24 11:12:27 PDT 2019
2021-04-02T18:00:26.387Z,1617386426.387 [SBIT](INFO): Beginning SBIT in 39.000000 seconds.
2021-04-02T18:00:26.388Z,1617386426.388 [IBIT](INFO): Initialize IBIT Component.
2021-04-02T18:00:26.389Z,1617386426.389 [CBIT](DEBUG): Initialize CBIT Component.
2021-04-02T18:00:26.390Z,1617386426.390 [logger ThreadHandler](INFO): Handler Thread ID is 4280
2021-04-02T18:00:26.401Z,1617386426.401 [CBIT](DEBUG): Initialized mux pins.
2021-04-02T18:00:26.401Z,1617386426.401 [CBIT](DEBUG): Initializing the watchdog timer.
2021-04-02T18:00:26.409Z,1617386426.409 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 4281
2021-04-02T18:00:26.410Z,1617386426.410 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2021-04-02T18:00:26.421Z,1617386426.421 [Onboard ThreadHandler](INFO): Handler Thread ID is 4282
2021-04-02T18:00:26.434Z,1617386426.434 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2021-04-02T18:00:26.434Z,1617386426.434 [CBIT](DEBUG): Initializing heartbeat.
2021-04-02T18:00:26.440Z,1617386426.440 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 4283
2021-04-02T18:00:26.451Z,1617386426.451 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 4284
2021-04-02T18:00:26.453Z,1617386426.453 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 4285
2021-04-02T18:00:26.456Z,1617386426.456 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 4287
2021-04-02T18:00:26.459Z,1617386426.459 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2021-04-02T18:00:26.459Z,1617386426.459 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2021-04-02T18:00:26.460Z,1617386426.460 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2021-04-02T18:00:26.460Z,1617386426.460 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2021-04-02T18:00:26.460Z,1617386426.460 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2021-04-02T18:00:26.460Z,1617386426.460 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2021-04-02T18:00:26.460Z,1617386426.460 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2021-04-02T18:00:26.460Z,1617386426.460 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2021-04-02T18:00:26.461Z,1617386426.461 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2021-04-02T18:00:26.461Z,1617386426.461 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2021-04-02T18:00:26.461Z,1617386426.461 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2021-04-02T18:00:26.461Z,1617386426.461 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2021-04-02T18:00:26.462Z,1617386426.462 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2021-04-02T18:00:26.462Z,1617386426.462 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2021-04-02T18:00:26.462Z,1617386426.462 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2021-04-02T18:00:26.462Z,1617386426.462 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2021-04-02T18:00:26.466Z,1617386426.466 [WetLabsBB2FL](INFO): Powering up
2021-04-02T18:00:26.473Z,1617386426.473 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2021-04-02T18:00:26.505Z,1617386426.505 [CBIT](DEBUG): Deactivating GF circuits.
2021-04-02T18:00:26.505Z,1617386426.505 [CBIT](DEBUG): Deactivating emergency mode.
2021-04-02T18:00:26.541Z,1617386426.541 [CBIT](DEBUG): Backplane powered.
2021-04-02T18:00:26.542Z,1617386426.542 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2021-04-02T18:00:26.554Z,1617386426.554 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2021-04-02T18:00:26.566Z,1617386426.566 [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>


2021-04-02T18:00:26.567Z,1617386426.567 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2021-04-02T18:00:26.694Z,1617386426.694 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2021-04-02T18:00:26.695Z,1617386426.695 [Default:A.Wait](DEBUG): Construct Wait.
2021-04-02T18:00:26.714Z,1617386426.714 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2021-04-02T18:00:26.751Z,1617386426.751 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2021-04-02T18:00:26.754Z,1617386426.754 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2021-04-02T18:00:26.779Z,1617386426.779 [Default:E.Execute](DEBUG): Construct Execute.
2021-04-02T18:00:26.783Z,1617386426.783 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Universal="Tethys/Universal"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
         Id="Default">

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

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

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

    <Aggregate Id="CheckIn">

        <Sequence Repeat="288"/>

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

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

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

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

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

    </Aggregate>

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

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

</Mission>


2021-04-02T18:00:26.793Z,1617386426.793 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,DropWeight,DVL_micro,NAL9602,DAT,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2021-04-02T18:00:26.805Z,1617386426.805 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2021-04-02T18:00:26.845Z,1617386426.845 [Radio_Surface](INFO): Powering up
2021-04-02T18:00:26.980Z,1617386426.980 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2
2021-04-02T18:00:26.980Z,1617386426.980 [DAT](INFO): Powering up
2021-04-02T18:00:26.985Z,1617386426.985 [DAT](DEBUG): Initializing DAT.
2021-04-02T18:00:27.059Z,1617386427.059 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2021-04-02T18:00:27.065Z,1617386427.065 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2021-04-02T18:00:27.066Z,1617386427.066 [ElevatorServo](DEBUG): Initializing EZServoServo.
2021-04-02T18:00:27.069Z,1617386427.069 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2
2021-04-02T18:00:27.101Z,1617386427.101 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2021-04-02T18:00:27.102Z,1617386427.102 [MassServo](DEBUG): Initializing EZServoServo.
2021-04-02T18:00:27.105Z,1617386427.105 [MassServo](DEBUG): Initializing MassServo.
2021-04-02T18:00:27.106Z,1617386427.106 [RudderServo](DEBUG): Initializing EZServoServo.
2021-04-02T18:00:27.121Z,1617386427.121 [RudderServo](DEBUG): Initializing RudderServo.
2021-04-02T18:00:27.122Z,1617386427.122 [ThrusterServo](DEBUG): Initializing EZServoServo.
2021-04-02T18:00:27.133Z,1617386427.133 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2021-04-02T18:00:27.226Z,1617386427.226 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2021-04-02T18:00:27.226Z,1617386427.226 [DropWeight] Hardware Fault, FailCount= 1
2021-04-02T18:00:27.226Z,1617386427.226 [DropWeight](ERROR): Hardware Fault
2021-04-02T18:00:27.299Z,1617386427.299 [CommandLine](FAULT): Scheduling is paused
2021-04-02T18:00:27.300Z,1617386427.300 [CBIT](INFO): Critical error at 20210402T180027
2021-04-02T18:00:27.300Z,1617386427.300 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2021-04-02T18:00:27.302Z,1617386427.302 [CBIT](ERROR): Hardware Fault in component: DropWeight
2021-04-02T18:00:27.303Z,1617386427.303 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2021-04-02T18:00:27.937Z,1617386427.937 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2021-04-02T18:00:27.937Z,1617386427.937 [RudderServo](FAULT): Rudder failed to initialize
2021-04-02T18:00:27.937Z,1617386427.937 [RudderServo] Communications Fault, FailCount= 1
2021-04-02T18:00:27.937Z,1617386427.937 [RudderServo](ERROR): Communications Fault
2021-04-02T18:00:28.035Z,1617386428.035 [CBIT](INFO): Critical error at 20210402T180027
2021-04-02T18:00:28.037Z,1617386428.037 [CBIT](ERROR): Communications Fault in component: RudderServo
2021-04-02T18:00:28.202Z,1617386428.202 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2021-04-02T18:00:28.202Z,1617386428.202 [RudderServo](INFO): Powering down
2021-04-02T18:00:28.869Z,1617386428.869 [RudderServo](DEBUG): Initializing EZServoServo.
2021-04-02T18:00:28.990Z,1617386428.990 [RudderServo](DEBUG): Initializing RudderServo.
2021-04-02T18:00:28.994Z,1617386428.994 [CBIT](INFO): Clearing failed state for component RudderServo
2021-04-02T18:00:28.994Z,1617386428.994 [RudderServo] No Fault, FailCount= 1
2021-04-02T18:00:29.069Z,1617386429.069 [WetLabsBB2FL](INFO): Powering down
2021-04-02T18:00:33.537Z,1617386433.537 [CTD_Seabird](ERROR): Device message queue exceeded the allowed limit.
2021-04-02T18:00:55.518Z,1617386455.518 [NAL9602](INFO): Powering up NAL9602
2021-04-02T18:01:06.072Z,1617386466.072 [SBIT](IMPORTANT): Beginning Startup BIT
2021-04-02T18:01:06.080Z,1617386466.080 [CBIT](IMPORTANT): Beginning ground fault scan
2021-04-02T18:01:06.427Z,1617386466.427 [NAL9602](INFO): NAL9602 initialized
2021-04-02T18:01:17.003Z,1617386477.003 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.005135
CHAN A1 (24V): -0.002580
CHAN A2 (12V): -0.000434
CHAN A3 (5V): 0.000057
CHAN B0 (3.3V): 0.001378
CHAN B1 (3.15aV): 0.000606
CHAN B2 (3.15bV): 0.000103
CHAN B3 (GND): 0.000682
OPEN: 0.004269
Full Scale Calc: 4.765 mA, -1.589 mA
2021-04-02T18:01:27.039Z,1617386487.039 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2021-04-02T18:01:27.039Z,1617386487.039 [DAT] Communications Fault, FailCount= 1
2021-04-02T18:01:27.039Z,1617386487.039 [DAT](ERROR): Communications Fault
2021-04-02T18:01:27.321Z,1617386487.321 [CBIT](ERROR): Communications Fault in component: DAT
2021-04-02T18:01:27.467Z,1617386487.467 [DAT](INFO): Powering down
2021-04-02T18:01:28.318Z,1617386488.318 [CBIT](INFO): Clearing failed state for component DAT
2021-04-02T18:01:28.318Z,1617386488.318 [DAT] No Fault, FailCount= 1
2021-04-02T18:01:30.699Z,1617386490.699 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2
2021-04-02T18:01:30.699Z,1617386490.699 [DAT](INFO): Powering up
2021-04-02T18:01:30.699Z,1617386490.699 [DAT](DEBUG): Initializing DAT.
2021-04-02T18:01:30.745Z,1617386490.745 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2
2021-04-02T18:02:00.181Z,1617386520.181 [SBIT](IMPORTANT): SBIT PASSED
2021-04-02T18:02:00.181Z,1617386520.181 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2021-04-02T18:02:00.182Z,1617386520.182 [SBIT](IMPORTANT): BPC1.batteryMissingStickThreshold=2 count;

2021-04-02T18:02:00.182Z,1617386520.182 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=194.331976 cubic_centimeter;

2021-04-02T18:02:00.182Z,1617386520.182 [SBIT](IMPORTANT): VerticalControl.massDefault=4.752829 millimeter;

2021-04-02T18:02:00.590Z,1617386520.590 [MissionManager](IMPORTANT): Started mission Startup
2021-04-02T18:02:00.590Z,1617386520.590 [Startup] Running Loop=1
2021-04-02T18:02:00.590Z,1617386520.590 [Startup](DEBUG): Aggregate::initialize Startup
2021-04-02T18:02:00.590Z,1617386520.590 [Startup:A.GoToSurface] Running Loop=1
2021-04-02T18:02:00.590Z,1617386520.590 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2021-04-02T18:02:00.591Z,1617386520.591 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2021-04-02T18:02:00.592Z,1617386520.592 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2021-04-02T18:02:00.592Z,1617386520.592 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2021-04-02T18:02:00.592Z,1617386520.592 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2021-04-02T18:02:00.593Z,1617386520.593 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2021-04-02T18:02:00.594Z,1617386520.594 [Startup:StartupSatComms] Running Loop=1
2021-04-02T18:02:00.594Z,1617386520.594 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2021-04-02T18:02:00.595Z,1617386520.595 [Startup:StartupSatComms:A] Running Loop=1
2021-04-02T18:02:01.020Z,1617386521.020 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2021-04-02T18:02:30.887Z,1617386550.887 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2021-04-02T18:02:30.887Z,1617386550.887 [DAT] Communications Fault, FailCount= 2
2021-04-02T18:02:30.887Z,1617386550.887 [DAT](ERROR): Communications Fault
2021-04-02T18:02:30.925Z,1617386550.925 [CBIT](ERROR): Communications Fault in component: DAT
2021-04-02T18:02:31.299Z,1617386551.299 [DAT](INFO): Powering down
2021-04-02T18:02:32.096Z,1617386552.096 [CBIT](INFO): Clearing failed state for component DAT
2021-04-02T18:02:32.096Z,1617386552.096 [DAT] No Fault, FailCount= 2
2021-04-02T18:02:34.515Z,1617386554.515 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2
2021-04-02T18:02:34.515Z,1617386554.515 [DAT](INFO): Powering up
2021-04-02T18:02:34.515Z,1617386554.515 [DAT](DEBUG): Initializing DAT.
2021-04-02T18:02:34.534Z,1617386554.534 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2
2021-04-02T18:03:00.774Z,1617386580.774 [Startup:StartupSatComms:A](INFO): Timed out from 2021-04-02T18:02:00.6Z
2021-04-02T18:03:00.774Z,1617386580.774 [Startup:StartupSatComms:A] Stopped
2021-04-02T18:03:00.774Z,1617386580.774 [Startup:StartupSatComms:B] Running Loop=1
2021-04-02T18:03:01.187Z,1617386581.187 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2021-04-02T18:03:05.218Z,1617386585.218 [DAT](INFO): unknown deviceResponse_: Acoustic Wakeup

2021-04-02T18:03:05.220Z,1617386585.220 [DAT](INFO): commRate: 800
2021-04-02T18:03:06.012Z,1617386586.012 [DAT](INFO): unknown deviceResponse_: Lowpower

2021-04-02T18:03:07.229Z,1617386587.229 [DAT](INFO): entering command mode
2021-04-02T18:03:07.649Z,1617386587.649 [DAT](INFO): commRate: 800
2021-04-02T18:03:09.665Z,1617386589.665 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:10.081Z,1617386590.081 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:10.473Z,1617386590.473 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:10.867Z,1617386590.867 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:11.271Z,1617386591.271 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:11.675Z,1617386591.675 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:12.080Z,1617386592.080 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:12.500Z,1617386592.500 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:12.887Z,1617386592.887 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:13.404Z,1617386593.404 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:13.718Z,1617386593.718 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:14.123Z,1617386594.123 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:14.545Z,1617386594.545 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:14.921Z,1617386594.921 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:15.333Z,1617386595.333 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:15.728Z,1617386595.728 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:16.115Z,1617386596.115 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:16.515Z,1617386596.515 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:16.928Z,1617386596.928 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:17.323Z,1617386597.323 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:17.737Z,1617386597.737 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:18.132Z,1617386598.132 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:18.540Z,1617386598.540 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:18.939Z,1617386598.939 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:19.347Z,1617386599.347 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:19.765Z,1617386599.765 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:20.181Z,1617386600.181 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:20.573Z,1617386600.573 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:20.977Z,1617386600.977 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:21.367Z,1617386601.367 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:21.772Z,1617386601.772 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:22.179Z,1617386602.179 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:22.583Z,1617386602.583 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-02T18:03:22.583Z,1617386602.583 [DAT](FAULT): failed to enter command mode
2021-04-02T18:03:22.989Z,1617386602.989 [DAT](INFO): entering command mode
2021-04-02T18:03:23.396Z,1617386603.396 [DAT](INFO): setting verbose to 3
2021-04-02T18:03:23.788Z,1617386603.788 [DAT](INFO): set verbose to 3
2021-04-02T18:03:23.789Z,1617386603.789 [DAT](INFO): setting DatVerbose to 27440
2021-04-02T18:03:24.193Z,1617386604.193 [DAT](INFO): set DatVerbose to 27440
2021-04-02T18:03:24.193Z,1617386604.193 [DAT](INFO): setting transmit power to 8
2021-04-02T18:03:24.600Z,1617386604.600 [DAT](INFO): set transmit power to 8
2021-04-02T18:03:24.600Z,1617386604.600 [DAT](INFO): setting local address to 8
2021-04-02T18:03:25.022Z,1617386605.022 [DAT](INFO): set local address to 8
2021-04-02T18:03:26.637Z,1617386606.637 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2021-04-02T18:03:26.637Z,1617386606.637 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-04-02T18:03:26.656Z,1617386606.656 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-04-02T18:03:27.070Z,1617386607.070 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-04-02T18:03:27.070Z,1617386607.070 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2021-04-02T18:03:29.487Z,1617386609.487 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.012662
2021-04-02T18:03:36.712Z,1617386616.712 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20210402T174919/Courier0007.lzma
2021-04-02T18:03:37.715Z,1617386617.715 [DataOverHttps](INFO): Moved sent file to Logs/20210402T174919/Courier0007.lzma.bak
2021-04-02T18:03:37.715Z,1617386617.715 [DataOverHttps](INFO): SBD MOMSN=15539758
2021-04-02T18:03:57.077Z,1617386637.077 [DataOverHttps](INFO): Sending 246 bytes from file Logs/20210402T180016/Courier0000.lzma
2021-04-02T18:03:58.079Z,1617386638.079 [DataOverHttps](INFO): Moved sent file to Logs/20210402T180016/Courier0000.lzma.bak
2021-04-02T18:03:58.079Z,1617386638.079 [DataOverHttps](INFO): SBD MOMSN=15539760
2021-04-02T18:04:01.078Z,1617386641.078 [Startup:StartupSatComms:B](INFO): Timed out from 2021-04-02T18:03:00.8Z
2021-04-02T18:04:01.078Z,1617386641.078 [Startup:StartupSatComms:B] Stopped
2021-04-02T18:04:01.078Z,1617386641.078 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2021-04-02T18:04:01.078Z,1617386641.078 [Startup:StartupSatComms] Stopped
2021-04-02T18:04:01.078Z,1617386641.078 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2021-04-02T18:04:01.079Z,1617386641.079 [Startup](INFO): Completed Startup
2021-04-02T18:04:01.079Z,1617386641.079 [MissionManager](INFO): Startup is completed.
2021-04-02T18:04:01.079Z,1617386641.079 [MissionManager](INFO): Uninitializing Mission Startup
2021-04-02T18:04:01.079Z,1617386641.079 [Startup] Stopped
2021-04-02T18:04:01.079Z,1617386641.079 [Startup](DEBUG): Aggregate::uninitialize Startup
2021-04-02T18:04:01.079Z,1617386641.079 [Startup:A.GoToSurface] Stopped
2021-04-02T18:04:01.080Z,1617386641.080 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2021-04-02T18:04:01.509Z,1617386641.509 [MissionManager](IMPORTANT): Started mission Default
2021-04-02T18:04:01.509Z,1617386641.509 [Default] Running Loop=1
2021-04-02T18:04:01.509Z,1617386641.509 [Default](DEBUG): Aggregate::initialize Default
2021-04-02T18:04:01.509Z,1617386641.509 [Default:B.GoToSurface] Running Loop=1
2021-04-02T18:04:01.509Z,1617386641.509 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2021-04-02T18:04:01.510Z,1617386641.510 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2021-04-02T18:04:01.510Z,1617386641.510 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2021-04-02T18:04:01.510Z,1617386641.510 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2021-04-02T18:04:01.511Z,1617386641.511 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2021-04-02T18:04:01.511Z,1617386641.511 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2021-04-02T18:04:01.511Z,1617386641.511 [Default:A.Wait] Running Loop=1
2021-04-02T18:04:01.511Z,1617386641.511 [Default:A.Wait](DEBUG): Initialize Wait Component.
2021-04-02T18:04:14.819Z,1617386654.819 [Default:A.Wait](INFO): Done Waiting.
2021-04-02T18:04:14.819Z,1617386654.819 [Default:A.Wait] Stopped
2021-04-02T18:04:14.819Z,1617386654.819 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2021-04-02T18:04:15.231Z,1617386655.231 [Default:CheckIn] Running Loop=1
2021-04-02T18:04:15.231Z,1617386655.231 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-04-02T18:04:15.231Z,1617386655.231 [Default:CheckIn:Read_GPS] Running Loop=1
2021-04-02T18:04:15.619Z,1617386655.619 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2021-04-02T18:04:16.069Z,1617386656.069 [DataOverHttps](INFO): Sending 236 bytes from file Logs/20210402T174919/Express0008.lzma
2021-04-02T18:04:17.070Z,1617386657.070 [DataOverHttps](INFO): Moved sent file to Logs/20210402T174919/Express0008.lzma.bak
2021-04-02T18:04:17.071Z,1617386657.071 [DataOverHttps](INFO): SBD MOMSN=15539765
2021-04-02T18:04:39.308Z,1617386679.308 [DVL_micro](ERROR): only read 3 of 4 data items
2021-04-02T18:04:39.308Z,1617386679.308 [DVL_micro](ERROR): Failed to parse:
:BI,-00206,+00468,+0000,I
2021-04-02T18:06:09.554Z,1617386769.554 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-04-02T18:06:27.770Z,1617386787.770 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2021-04-02T18:06:27.770Z,1617386787.770 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-04-02T18:06:27.781Z,1617386787.781 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-04-02T18:06:28.195Z,1617386788.195 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-04-02T18:06:28.195Z,1617386788.195 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2021-04-02T18:08:05.231Z,1617386885.231 [BPC1](ERROR): Battery stick #6 (s/n: 00CA) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0.
2021-04-02T18:08:05.232Z,1617386885.232 [BPC1](INFO): Calculating totals. Valid battery stick count: 55. Valid reserve battery stick count: 6.
2021-04-02T18:08:05.235Z,1617386885.235 [BPC1](INFO): Received data from all battery sticks.
2021-04-02T18:09:15.535Z,1617386955.535 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-04-02T18:04:15.2Z
2021-04-02T18:09:15.535Z,1617386955.535 [Default:CheckIn:Read_GPS] Stopped
2021-04-02T18:09:15.536Z,1617386955.536 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-04-02T18:09:15.944Z,1617386955.944 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2021-04-02T18:09:22.371Z,1617386962.371 [DataOverHttps](INFO): Sending 168 bytes from file Logs/20210402T180016/Courier0004.lzma
2021-04-02T18:09:23.371Z,1617386963.371 [DataOverHttps](INFO): Moved sent file to Logs/20210402T180016/Courier0004.lzma.bak
2021-04-02T18:09:23.371Z,1617386963.371 [DataOverHttps](INFO): SBD MOMSN=15539809
2021-04-02T18:09:28.890Z,1617386968.890 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2021-04-02T18:09:28.890Z,1617386968.890 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-04-02T18:09:28.904Z,1617386968.904 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-04-02T18:09:29.318Z,1617386969.318 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-04-02T18:09:29.318Z,1617386969.318 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2021-04-02T18:09:38.738Z,1617386978.738 [DataOverHttps](INFO): Sending 901 bytes from file Logs/20210402T180016/Express0001.lzma
2021-04-02T18:09:39.739Z,1617386979.739 [DataOverHttps](INFO): Moved sent file to Logs/20210402T180016/Express0001.lzma.bak
2021-04-02T18:09:39.739Z,1617386979.739 [DataOverHttps](INFO): SBD MOMSN=15539811
2021-04-02T18:10:00.845Z,1617387000.845 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20210402T180016/Express0005.lzma
2021-04-02T18:10:01.848Z,1617387001.848 [DataOverHttps](INFO): Moved sent file to Logs/20210402T180016/Express0005.lzma.bak
2021-04-02T18:10:01.848Z,1617387001.848 [DataOverHttps](INFO): SBD MOMSN=15539833
2021-04-02T18:10:03.753Z,1617387003.753 [Default:CheckIn:Read_Iridium] Stopped
2021-04-02T18:10:03.754Z,1617387003.754 [Default:CheckIn:C.Wait] Running Loop=1
2021-04-02T18:10:03.754Z,1617387003.754 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-04-02T18:10:27.112Z,1617387027.112 [CommandLine](IMPORTANT): got command failComponent
2021-04-02T18:10:27.112Z,1617387027.112 [CommandLine](IMPORTANT): Failed components:
2021-04-02T18:10:27.113Z,1617387027.113 [CommandLine](IMPORTANT): DropWeight: Hardware Fault
2021-04-02T18:11:08.407Z,1617387068.407 [NAL9602](FAULT): GPS failed to acquire within timeout.
2021-04-02T18:11:08.407Z,1617387068.407 [NAL9602] Data Fault, FailCount= 1
2021-04-02T18:11:08.407Z,1617387068.407 [NAL9602](ERROR): Data Fault
2021-04-02T18:11:08.424Z,1617387068.424 [CBIT](ERROR): Data Fault in component: NAL9602
2021-04-02T18:11:08.807Z,1617387068.807 [NAL9602](INFO): Powering down
2021-04-02T18:11:09.646Z,1617387069.646 [CBIT](INFO): Clearing failed state for component NAL9602
2021-04-02T18:11:09.646Z,1617387069.646 [NAL9602] No Fault, FailCount= 1
2021-04-02T18:11:39.110Z,1617387099.110 [NAL9602](INFO): Powering up NAL9602
2021-04-02T18:11:50.015Z,1617387110.015 [NAL9602](INFO): NAL9602 initialized
2021-04-02T18:12:14.323Z,1617387134.323 [CommandLine](IMPORTANT): got command failComponent none DropWeight
2021-04-02T18:12:14.323Z,1617387134.323 [DropWeight] No Fault, FailCount= 1
2021-04-02T18:12:14.323Z,1617387134.323 [CommandLine](IMPORTANT): DropWeight failureMode is No Fault
2021-04-02T18:12:29.684Z,1617387149.684 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2021-04-02T18:12:29.684Z,1617387149.684 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-04-02T18:12:29.706Z,1617387149.706 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-04-02T18:12:30.113Z,1617387150.113 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-04-02T18:12:30.113Z,1617387150.113 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2021-04-02T18:13:33.593Z,1617387213.593 [CommandLine](IMPORTANT): got command strobe off
2021-04-02T18:13:33.593Z,1617387213.593 [CommandLine](IMPORTANT): Deactivating strobe
2021-04-02T18:15:04.423Z,1617387304.423 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-04-02T18:15:04.423Z,1617387304.423 [Default:CheckIn:C.Wait] Stopped
2021-04-02T18:15:04.423Z,1617387304.423 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-04-02T18:15:04.423Z,1617387304.423 [Default:CheckIn:D] Running Loop=1
2021-04-02T18:15:04.833Z,1617387304.833 [Default:CheckIn:D] Stopped
2021-04-02T18:15:04.833Z,1617387304.833 [Default:CheckIn:E] Running Loop=1
2021-04-02T18:15:05.234Z,1617387305.234 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 11.055389 min 
2021-04-02T18:15:05.234Z,1617387305.234 [Default:CheckIn:E] Stopped
2021-04-02T18:15:05.234Z,1617387305.234 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-04-02T18:15:05.234Z,1617387305.234 [Default:CheckIn] Stopped
2021-04-02T18:15:05.235Z,1617387305.235 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-04-02T18:15:05.235Z,1617387305.235 [Default:CheckIn](INFO): Running loop #2
2021-04-02T18:15:05.235Z,1617387305.235 [Default:CheckIn] Running Loop=2
2021-04-02T18:15:05.235Z,1617387305.235 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-04-02T18:15:05.235Z,1617387305.235 [Default:CheckIn:Read_GPS] Running Loop=1
2021-04-02T18:15:07.222Z,1617387307.222 [DVL_micro](ERROR): only read 3 of 4 data items
2021-04-02T18:15:07.223Z,1617387307.223 [DVL_micro](ERROR): Failed to parse:
:BI,-00196,+01169,+00416,+

2021-04-02T18:15:30.670Z,1617387330.670 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5
2021-04-02T18:15:30.670Z,1617387330.670 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-04-02T18:15:30.681Z,1617387330.681 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-04-02T18:15:31.094Z,1617387331.094 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-04-02T18:15:31.094Z,1617387331.094 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5
2021-04-02T18:18:31.718Z,1617387511.718 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6
2021-04-02T18:18:31.718Z,1617387511.718 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-04-02T18:18:31.729Z,1617387511.729 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-04-02T18:18:32.125Z,1617387512.125 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-04-02T18:18:32.125Z,1617387512.125 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6
2021-04-02T18:18:57.802Z,1617387537.802 [CommandLine](IMPORTANT): got command failComponent
2021-04-02T18:18:57.803Z,1617387537.803 [CommandLine](IMPORTANT): Failed components:
2021-04-02T18:18:57.803Z,1617387537.803 [CommandLine](IMPORTANT): No failed Components.
2021-04-02T18:20:05.439Z,1617387605.439 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-04-02T18:15:05.2Z
2021-04-02T18:20:05.439Z,1617387605.439 [Default:CheckIn:Read_GPS] Stopped
2021-04-02T18:20:05.440Z,1617387605.440 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-04-02T18:20:11.416Z,1617387611.416 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20210402T180016/Courier0007.lzma
2021-04-02T18:20:12.430Z,1617387612.430 [DataOverHttps](INFO): Moved sent file to Logs/20210402T180016/Courier0007.lzma.bak
2021-04-02T18:20:12.432Z,1617387612.432 [DataOverHttps](INFO): SBD MOMSN=15539879
2021-04-02T18:20:27.801Z,1617387627.801 [DataOverHttps](INFO): Sending 338 bytes from file Logs/20210402T180016/Express0008.lzma
2021-04-02T18:20:28.802Z,1617387628.802 [DataOverHttps](INFO): Moved sent file to Logs/20210402T180016/Express0008.lzma.bak
2021-04-02T18:20:28.803Z,1617387628.803 [DataOverHttps](INFO): SBD MOMSN=15539881
2021-04-02T18:20:30.103Z,1617387630.103 [Default:CheckIn:Read_Iridium] Stopped
2021-04-02T18:20:30.103Z,1617387630.103 [Default:CheckIn:C.Wait] Running Loop=1
2021-04-02T18:20:30.103Z,1617387630.103 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-04-02T18:21:32.748Z,1617387692.748 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 7
2021-04-02T18:21:32.748Z,1617387692.748 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-04-02T18:21:32.759Z,1617387692.759 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-04-02T18:21:33.123Z,1617387693.123 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-04-02T18:21:33.123Z,1617387693.123 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 7
2021-04-02T18:21:35.289Z,1617387695.289 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-02T18:21:37.297Z,1617387697.297 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.247238
2021-04-02T18:21:52.083Z,1617387712.083 [NAL9602](FAULT): GPS failed to acquire within timeout.
2021-04-02T18:21:52.083Z,1617387712.083 [NAL9602] Data Fault, FailCount= 2
2021-04-02T18:21:52.083Z,1617387712.083 [NAL9602](ERROR): Data Fault
2021-04-02T18:21:52.108Z,1617387712.108 [CBIT](ERROR): Data Fault in component: NAL9602
2021-04-02T18:21:52.495Z,1617387712.495 [NAL9602](INFO): Powering down
2021-04-02T18:21:53.316Z,1617387713.316 [CBIT](INFO): Clearing failed state for component NAL9602
2021-04-02T18:21:53.316Z,1617387713.316 [NAL9602] No Fault, FailCount= 2
2021-04-02T18:22:10.429Z,1617387730.429 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-02T18:22:22.791Z,1617387742.791 [NAL9602](INFO): Powering up NAL9602
2021-04-02T18:22:33.708Z,1617387753.708 [NAL9602](INFO): NAL9602 initialized
2021-04-02T18:22:45.569Z,1617387765.569 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-02T18:23:20.709Z,1617387800.709 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-02T18:23:55.849Z,1617387835.849 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-02T18:24:30.989Z,1617387870.989 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-02T18:24:33.740Z,1617387873.740 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 8
2021-04-02T18:24:33.740Z,1617387873.740 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-04-02T18:24:33.751Z,1617387873.751 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-04-02T18:24:34.132Z,1617387874.132 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-04-02T18:24:34.132Z,1617387874.132 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 8
2021-04-02T18:25:06.133Z,1617387906.133 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-02T18:25:30.675Z,1617387930.675 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-04-02T18:25:30.675Z,1617387930.675 [Default:CheckIn:C.Wait] Stopped
2021-04-02T18:25:30.676Z,1617387930.676 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-04-02T18:25:30.676Z,1617387930.676 [Default:CheckIn:D] Running Loop=1
2021-04-02T18:25:31.064Z,1617387931.064 [Default:CheckIn:D] Stopped
2021-04-02T18:25:31.064Z,1617387931.064 [Default:CheckIn:E] Running Loop=1
2021-04-02T18:25:31.479Z,1617387931.479 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 21.492578 min 
2021-04-02T18:25:31.479Z,1617387931.479 [Default:CheckIn:E] Stopped
2021-04-02T18:25:31.479Z,1617387931.479 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-04-02T18:25:31.479Z,1617387931.479 [Default:CheckIn] Stopped
2021-04-02T18:25:31.479Z,1617387931.479 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-04-02T18:25:31.479Z,1617387931.479 [Default:CheckIn](INFO): Running loop #3
2021-04-02T18:25:31.479Z,1617387931.479 [Default:CheckIn] Running Loop=3
2021-04-02T18:25:31.479Z,1617387931.479 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-04-02T18:25:31.479Z,1617387931.479 [Default:CheckIn:Read_GPS] Running Loop=1
2021-04-02T18:25:41.273Z,1617387941.273 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-02T18:26:16.421Z,1617387976.421 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-02T18:26:51.561Z,1617388011.561 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-02T18:27:26.701Z,1617388046.701 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-02T18:27:34.710Z,1617388054.710 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 9
2021-04-02T18:27:34.710Z,1617388054.710 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-04-02T18:27:34.721Z,1617388054.721 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-04-02T18:27:35.133Z,1617388055.133 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-04-02T18:27:35.133Z,1617388055.133 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 9
2021-04-02T18:28:01.841Z,1617388081.841 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-02T18:28:36.989Z,1617388116.989 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-02T18:29:12.137Z,1617388152.137 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-02T18:29:47.281Z,1617388187.281 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-02T18:30:22.421Z,1617388222.421 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-02T18:30:31.663Z,1617388231.663 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-04-02T18:25:31.5Z
2021-04-02T18:30:31.663Z,1617388231.663 [Default:CheckIn:Read_GPS] Stopped
2021-04-02T18:30:31.664Z,1617388231.664 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-04-02T18:30:35.714Z,1617388235.714 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 10
2021-04-02T18:30:35.714Z,1617388235.714 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-04-02T18:30:35.725Z,1617388235.725 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-04-02T18:30:36.114Z,1617388236.114 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-04-02T18:30:36.114Z,1617388236.114 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 10
2021-04-02T18:30:57.577Z,1617388257.577 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-02T18:31:32.717Z,1617388292.717 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-02T18:32:07.865Z,1617388327.865 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-02T18:32:36.467Z,1617388356.467 [NAL9602](FAULT): GPS failed to acquire within timeout.
2021-04-02T18:32:36.467Z,1617388356.467 [NAL9602] Data Fault, FailCount= 3
2021-04-02T18:32:36.467Z,1617388356.467 [NAL9602](ERROR): Data Fault
2021-04-02T18:32:36.484Z,1617388356.484 [CBIT](ERROR): Data Fault in component: NAL9602
2021-04-02T18:32:36.867Z,1617388356.867 [NAL9602](INFO): Powering down
2021-04-02T18:32:37.709Z,1617388357.709 [CBIT](INFO): Clearing failed state for component NAL9602
2021-04-02T18:32:37.709Z,1617388357.709 [NAL9602] No Fault, FailCount= 3
2021-04-02T18:32:43.006Z,1617388363.006 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-02T18:33:07.171Z,1617388387.171 [NAL9602](INFO): Powering up NAL9602
2021-04-02T18:33:18.103Z,1617388398.103 [NAL9602](INFO): NAL9602 initialized
2021-04-02T18:33:18.145Z,1617388398.145 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-02T18:33:36.862Z,1617388416.862 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 11
2021-04-02T18:33:36.862Z,1617388416.862 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-04-02T18:33:36.872Z,1617388416.872 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-04-02T18:33:37.079Z,1617388417.079 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-04-02T18:33:37.079Z,1617388417.079 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 11
2021-04-02T18:33:53.293Z,1617388433.293 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-02T18:34:23.741Z,1617388463.741 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002967
2021-04-02T18:34:31.228Z,1617388471.228 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20210402T180016/Courier0010.lzma
2021-04-02T18:34:32.230Z,1617388472.230 [DataOverHttps](INFO): Moved sent file to Logs/20210402T180016/Courier0010.lzma.bak
2021-04-02T18:34:32.231Z,1617388472.231 [DataOverHttps](INFO): SBD MOMSN=15539993
2021-04-02T18:34:47.632Z,1617388487.632 [DataOverHttps](INFO): Sending 150 bytes from file Logs/20210402T180016/Express0011.lzma
2021-04-02T18:34:48.635Z,1617388488.635 [DataOverHttps](INFO): Moved sent file to Logs/20210402T180016/Express0011.lzma.bak
2021-04-02T18:34:48.635Z,1617388488.635 [DataOverHttps](INFO): SBD MOMSN=15539995
2021-04-02T18:34:50.208Z,1617388490.208 [Default:CheckIn:Read_Iridium] Stopped
2021-04-02T18:34:50.208Z,1617388490.208 [Default:CheckIn:C.Wait] Running Loop=1
2021-04-02T18:34:50.208Z,1617388490.208 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-04-02T18:36:37.721Z,1617388597.721 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 12
2021-04-02T18:36:37.721Z,1617388597.721 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-04-02T18:36:37.731Z,1617388597.731 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-04-02T18:36:38.119Z,1617388598.119 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-04-02T18:36:38.119Z,1617388598.119 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 12
2021-04-02T18:37:13.622Z,1617388633.622 [DVL_micro](ERROR): only read 3 of 4 data items
2021-04-02T18:37:13.622Z,1617388633.622 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.999,+9999.99,+9999.99
2021-04-02T18:39:38.723Z,1617388778.723 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 13
2021-04-02T18:39:38.723Z,1617388778.723 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-04-02T18:39:38.733Z,1617388778.733 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-04-02T18:39:39.141Z,1617388779.141 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-04-02T18:39:39.141Z,1617388779.141 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 13
2021-04-02T18:39:50.823Z,1617388790.823 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-04-02T18:39:50.823Z,1617388790.823 [Default:CheckIn:C.Wait] Stopped
2021-04-02T18:39:50.823Z,1617388790.823 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-04-02T18:39:50.823Z,1617388790.823 [Default:CheckIn:D] Running Loop=1
2021-04-02T18:39:51.240Z,1617388791.240 [Default:CheckIn:D] Stopped
2021-04-02T18:39:51.240Z,1617388791.240 [Default:CheckIn:E] Running Loop=1
2021-04-02T18:39:51.674Z,1617388791.674 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 35.828841 min 
2021-04-02T18:39:51.674Z,1617388791.674 [Default:CheckIn:E] Stopped
2021-04-02T18:39:51.674Z,1617388791.674 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-04-02T18:39:51.674Z,1617388791.674 [Default:CheckIn] Stopped
2021-04-02T18:39:51.675Z,1617388791.675 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-04-02T18:39:51.675Z,1617388791.675 [Default:CheckIn](INFO): Running loop #4
2021-04-02T18:39:51.675Z,1617388791.675 [Default:CheckIn] Running Loop=4
2021-04-02T18:39:51.675Z,1617388791.675 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-04-02T18:39:51.675Z,1617388791.675 [Default:CheckIn:Read_GPS] Running Loop=1
2021-04-02T18:40:31.621Z,1617388831.621 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184048.00,A,3648.15824,N,12147.29592,W,0.855,53.35,020421,,,A*47
2021-04-02T18:40:31.624Z,1617388831.624 [NAL9602](INFO): GPS fix at 20210402T184048: (36.802637, -121.788265)
2021-04-02T18:40:31.651Z,1617388831.651 [Default:CheckIn:Read_GPS] Stopped
2021-04-02T18:40:31.651Z,1617388831.651 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-04-02T18:40:40.937Z,1617388840.937 [DataOverHttps](INFO): Sending 222 bytes from file Logs/20210402T180016/Courier0013.lzma
2021-04-02T18:40:41.939Z,1617388841.939 [DataOverHttps](INFO): Moved sent file to Logs/20210402T180016/Courier0013.lzma.bak
2021-04-02T18:40:41.939Z,1617388841.939 [DataOverHttps](INFO): SBD MOMSN=15540009
2021-04-02T18:40:57.912Z,1617388857.912 [DataOverHttps](INFO): Sending 285 bytes from file Logs/20210402T180016/Express0014.lzma
2021-04-02T18:40:58.910Z,1617388858.910 [DataOverHttps](INFO): Moved sent file to Logs/20210402T180016/Express0014.lzma.bak
2021-04-02T18:40:58.911Z,1617388858.911 [DataOverHttps](INFO): SBD MOMSN=15540045
2021-04-02T18:41:00.386Z,1617388860.386 [Default:CheckIn:Read_Iridium] Stopped
2021-04-02T18:41:00.386Z,1617388860.386 [Default:CheckIn:C.Wait] Running Loop=1
2021-04-02T18:41:00.386Z,1617388860.386 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-04-02T18:41:03.986Z,1617388863.986 [NAL9602](INFO): Not Powering down - fast GPS
2021-04-02T18:46:01.064Z,1617389161.064 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-04-02T18:46:01.064Z,1617389161.064 [Default:CheckIn:C.Wait] Stopped
2021-04-02T18:46:01.064Z,1617389161.064 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-04-02T18:46:01.064Z,1617389161.064 [Default:CheckIn:D] Running Loop=1
2021-04-02T18:46:01.435Z,1617389161.435 [Default:CheckIn:D] Stopped
2021-04-02T18:46:01.435Z,1617389161.435 [Default:CheckIn:E] Running Loop=1
2021-04-02T18:46:01.857Z,1617389161.857 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 41.998759 min 
2021-04-02T18:46:01.857Z,1617389161.857 [Default:CheckIn:E] Stopped
2021-04-02T18:46:01.857Z,1617389161.857 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-04-02T18:46:01.858Z,1617389161.858 [Default:CheckIn] Stopped
2021-04-02T18:46:01.858Z,1617389161.858 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-04-02T18:46:01.858Z,1617389161.858 [Default:CheckIn](INFO): Running loop #5
2021-04-02T18:46:01.858Z,1617389161.858 [Default:CheckIn] Running Loop=5
2021-04-02T18:46:01.858Z,1617389161.858 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-04-02T18:46:01.858Z,1617389161.858 [Default:CheckIn:Read_GPS] Running Loop=1
2021-04-02T18:46:03.850Z,1617389163.850 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184621.00,A,3648.16292,N,12147.28740,W,0.369,274.82,020421,,,A*79
2021-04-02T18:46:03.852Z,1617389163.852 [NAL9602](INFO): GPS fix at 20210402T184621: (36.802715, -121.788123)
2021-04-02T18:46:03.879Z,1617389163.879 [Default:CheckIn:Read_GPS] Stopped
2021-04-02T18:46:03.879Z,1617389163.879 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-04-02T18:46:10.788Z,1617389170.788 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210402T180016/Courier0016.lzma
2021-04-02T18:46:11.795Z,1617389171.795 [DataOverHttps](INFO): Moved sent file to Logs/20210402T180016/Courier0016.lzma.bak
2021-04-02T18:46:11.796Z,1617389171.796 [DataOverHttps](INFO): SBD MOMSN=15540057
2021-04-02T18:46:37.508Z,1617389197.508 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20210402T180016/Express0017.lzma
2021-04-02T18:46:38.510Z,1617389198.510 [DataOverHttps](INFO): Moved sent file to Logs/20210402T180016/Express0017.lzma.bak
2021-04-02T18:46:38.511Z,1617389198.511 [DataOverHttps](INFO): SBD MOMSN=15540060
2021-04-02T18:46:40.204Z,1617389200.204 [Default:CheckIn:Read_Iridium] Stopped
2021-04-02T18:46:40.221Z,1617389200.221 [Default:CheckIn:C.Wait] Running Loop=1
2021-04-02T18:46:40.221Z,1617389200.221 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-04-02T18:48:51.154Z,1617389331.154 [NAL9602](INFO): SBD MO Status=2, MOMSN=1648, MT Status=2, MTMSN=0
2021-04-02T18:48:51.154Z,1617389331.154 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-04-02T18:49:19.038Z,1617389359.038 [NAL9602](INFO): SBD MO Status=2, MOMSN=1648, MT Status=2, MTMSN=0
2021-04-02T18:49:19.038Z,1617389359.038 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-04-02T18:50:14.388Z,1617389414.388 [NAL9602](INFO): SBD MO Status=2, MOMSN=1648, MT Status=2, MTMSN=0
2021-04-02T18:50:14.388Z,1617389414.388 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-04-02T18:50:45.908Z,1617389445.908 [NAL9602](INFO): SBD MO Status=2, MOMSN=1648, MT Status=2, MTMSN=0
2021-04-02T18:50:45.908Z,1617389445.908 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-04-02T18:51:09.329Z,1617389469.329 [NAL9602](INFO): SBD MO Status=2, MOMSN=1648, MT Status=2, MTMSN=0
2021-04-02T18:51:09.330Z,1617389469.330 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-04-02T18:51:09.739Z,1617389469.739 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-04-02T18:51:40.435Z,1617389500.435 [NAL9602](INFO): Not Powering down - fast GPS
2021-04-02T18:51:40.865Z,1617389500.865 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-04-02T18:51:40.865Z,1617389500.865 [Default:CheckIn:C.Wait] Stopped
2021-04-02T18:51:40.865Z,1617389500.865 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-04-02T18:51:40.865Z,1617389500.865 [Default:CheckIn:D] Running Loop=1
2021-04-02T18:51:41.262Z,1617389501.262 [Default:CheckIn:D] Stopped
2021-04-02T18:51:41.262Z,1617389501.262 [Default:CheckIn:E] Running Loop=1
2021-04-02T18:51:41.671Z,1617389501.671 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 47.662549 min 
2021-04-02T18:51:41.671Z,1617389501.671 [Default:CheckIn:E] Stopped
2021-04-02T18:51:41.672Z,1617389501.672 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-04-02T18:51:41.672Z,1617389501.672 [Default:CheckIn] Stopped
2021-04-02T18:51:41.672Z,1617389501.672 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-04-02T18:51:41.672Z,1617389501.672 [Default:CheckIn](INFO): Running loop #6
2021-04-02T18:51:41.672Z,1617389501.672 [Default:CheckIn] Running Loop=6
2021-04-02T18:51:41.672Z,1617389501.672 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-04-02T18:51:41.672Z,1617389501.672 [Default:CheckIn:Read_GPS] Running Loop=1
2021-04-02T18:51:43.677Z,1617389503.677 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185201.00,A,3648.16583,N,12147.28106,W,0.408,274.82,020421,,,A*7D
2021-04-02T18:51:43.679Z,1617389503.679 [NAL9602](INFO): GPS fix at 20210402T185201: (36.802764, -121.788018)
2021-04-02T18:51:43.738Z,1617389503.738 [Default:CheckIn:Read_GPS] Stopped
2021-04-02T18:51:43.738Z,1617389503.738 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-04-02T18:51:53.416Z,1617389513.416 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210402T180016/Courier0019.lzma
2021-04-02T18:51:54.419Z,1617389514.419 [DataOverHttps](INFO): Moved sent file to Logs/20210402T180016/Courier0019.lzma.bak
2021-04-02T18:51:54.419Z,1617389514.419 [DataOverHttps](INFO): SBD MOMSN=15540106
2021-04-02T18:52:13.208Z,1617389533.208 [DataOverHttps](INFO): Sending 204 bytes from file Logs/20210402T180016/Express0020.lzma
2021-04-02T18:52:14.211Z,1617389534.211 [DataOverHttps](INFO): Moved sent file to Logs/20210402T180016/Express0020.lzma.bak
2021-04-02T18:52:14.211Z,1617389534.211 [DataOverHttps](INFO): SBD MOMSN=15540109
2021-04-02T18:52:15.761Z,1617389535.761 [Default:CheckIn:Read_Iridium] Stopped
2021-04-02T18:52:15.762Z,1617389535.762 [Default:CheckIn:C.Wait] Running Loop=1
2021-04-02T18:52:15.762Z,1617389535.762 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-04-02T18:52:31.486Z,1617389551.486 [NAL9602](INFO): SBD MO Status=2, MOMSN=1648, MT Status=2, MTMSN=0
2021-04-02T18:52:31.486Z,1617389551.486 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-04-02T18:54:36.737Z,1617389676.737 [DVL_micro](ERROR): Failed to parse:
9.99,+9999.99,+9999.99,+9999.99
2021-04-02T18:56:39.276Z,1617389799.276 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2021-04-02T18:56:39.276Z,1617389799.276 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.4,0000.0,14
2021-04-02T18:56:46.106Z,1617389806.106 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-04-02T18:57:16.411Z,1617389836.411 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-04-02T18:57:16.411Z,1617389836.411 [Default:CheckIn:C.Wait] Stopped
2021-04-02T18:57:16.411Z,1617389836.411 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-04-02T18:57:16.411Z,1617389836.411 [Default:CheckIn:D] Running Loop=1
2021-04-02T18:57:16.806Z,1617389836.806 [NAL9602](INFO): Not Powering down - fast GPS
2021-04-02T18:57:16.818Z,1617389836.818 [Default:CheckIn:D] Stopped
2021-04-02T18:57:16.818Z,1617389836.818 [Default:CheckIn:E] Running Loop=1
2021-04-02T18:57:17.228Z,1617389837.228 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 53.255151 min 
2021-04-02T18:57:17.229Z,1617389837.229 [Default:CheckIn:E] Stopped
2021-04-02T18:57:17.229Z,1617389837.229 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-04-02T18:57:17.229Z,1617389837.229 [Default:CheckIn] Stopped
2021-04-02T18:57:17.229Z,1617389837.229 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-04-02T18:57:17.229Z,1617389837.229 [Default:CheckIn](INFO): Running loop #7
2021-04-02T18:57:17.229Z,1617389837.229 [Default:CheckIn] Running Loop=7
2021-04-02T18:57:17.229Z,1617389837.229 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-04-02T18:57:17.229Z,1617389837.229 [Default:CheckIn:Read_GPS] Running Loop=1
2021-04-02T18:57:19.236Z,1617389839.236 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185736.00,A,3648.16051,N,12147.28607,W,0.292,0.00,020421,,,A*7E
2021-04-02T18:57:19.238Z,1617389839.238 [NAL9602](INFO): GPS fix at 20210402T185736: (36.802675, -121.788101)
2021-04-02T18:57:19.249Z,1617389839.249 [Default:CheckIn:Read_GPS] Stopped
2021-04-02T18:57:19.249Z,1617389839.249 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-04-02T18:57:26.968Z,1617389846.968 [DataOverHttps](INFO): Sending 71 bytes from file Logs/20210402T180016/Courier0022.lzma
2021-04-02T18:57:27.971Z,1617389847.971 [DataOverHttps](INFO): Moved sent file to Logs/20210402T180016/Courier0022.lzma.bak
2021-04-02T18:57:27.971Z,1617389847.971 [DataOverHttps](INFO): SBD MOMSN=15540154
2021-04-02T18:57:43.821Z,1617389863.821 [DataOverHttps](INFO): Sending 204 bytes from file Logs/20210402T180016/Express0023.lzma
2021-04-02T18:57:44.823Z,1617389864.823 [DataOverHttps](INFO): Moved sent file to Logs/20210402T180016/Express0023.lzma.bak
2021-04-02T18:57:44.823Z,1617389864.823 [DataOverHttps](INFO): SBD MOMSN=15540157
2021-04-02T18:57:46.731Z,1617389866.731 [Default:CheckIn:Read_Iridium] Stopped
2021-04-02T18:57:46.731Z,1617389866.731 [Default:CheckIn:C.Wait] Running Loop=1
2021-04-02T18:57:46.731Z,1617389866.731 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-04-02T18:57:49.971Z,1617389869.971 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2021-04-02T18:57:50.049Z,1617389870.049 [NAL9602](FAULT): received: 
+CSQ:0

OK48, 2, 0, 0, 0

OK
2021-04-02T18:57:50.049Z,1617389870.049 [NAL9602] Data Fault, FailCount= 4
2021-04-02T18:57:50.049Z,1617389870.049 [NAL9602](ERROR): Data Fault
2021-04-02T18:57:50.195Z,1617389870.195 [CBIT](ERROR): Data Fault in component: NAL9602
2021-04-02T18:57:50.379Z,1617389870.379 [NAL9602](INFO): Powering down
2021-04-02T18:57:51.276Z,1617389871.276 [CBIT](INFO): Clearing failed state for component NAL9602
2021-04-02T18:57:51.276Z,1617389871.276 [NAL9602] No Fault, FailCount= 4
2021-04-02T18:58:20.712Z,1617389900.712 [NAL9602](INFO): Powering up NAL9602
2021-04-02T18:58:31.638Z,1617389911.638 [NAL9602](INFO): NAL9602 initialized
2021-04-02T18:58:44.548Z,1617389924.548 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2021-04-02T18:58:44.549Z,1617389924.549 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.4,000.0,000
2021-04-02T18:59:02.726Z,1617389942.726 [NAL9602](INFO): Not Powering down - fast GPS
2021-04-02T19:02:47.402Z,1617390167.402 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-04-02T19:02:47.402Z,1617390167.402 [Default:CheckIn:C.Wait] Stopped
2021-04-02T19:02:47.402Z,1617390167.402 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-04-02T19:02:47.402Z,1617390167.402 [Default:CheckIn:D] Running Loop=1
2021-04-02T19:02:47.821Z,1617390167.821 [Default:CheckIn:D] Stopped
2021-04-02T19:02:47.821Z,1617390167.821 [Default:CheckIn:E] Running Loop=1
2021-04-02T19:02:48.229Z,1617390168.229 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 58.771855 min 
2021-04-02T19:02:48.229Z,1617390168.229 [Default:CheckIn:E] Stopped
2021-04-02T19:02:48.229Z,1617390168.229 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-04-02T19:02:48.229Z,1617390168.229 [Default:CheckIn] Stopped
2021-04-02T19:02:48.229Z,1617390168.229 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-04-02T19:02:48.230Z,1617390168.230 [Default:CheckIn](INFO): Running loop #8
2021-04-02T19:02:48.230Z,1617390168.230 [Default:CheckIn] Running Loop=8
2021-04-02T19:02:48.230Z,1617390168.230 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-04-02T19:02:48.230Z,1617390168.230 [Default:CheckIn:Read_GPS] Running Loop=1
2021-04-02T19:02:52.645Z,1617390172.645 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-04-02T19:03:14.468Z,1617390194.468 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190331.00,A,3648.15959,N,12147.27827,W,0.369,229.01,020421,,,A*75
2021-04-02T19:03:14.470Z,1617390194.470 [NAL9602](INFO): GPS fix at 20210402T190331: (36.802660, -121.787971)
2021-04-02T19:03:14.502Z,1617390194.502 [Default:CheckIn:Read_GPS] Stopped
2021-04-02T19:03:14.502Z,1617390194.502 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-04-02T19:03:21.824Z,1617390201.824 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210402T180016/Courier0025.lzma
2021-04-02T19:03:22.827Z,1617390202.827 [DataOverHttps](INFO): Moved sent file to Logs/20210402T180016/Courier0025.lzma.bak
2021-04-02T19:03:22.827Z,1617390202.827 [DataOverHttps](INFO): SBD MOMSN=15540209
2021-04-02T19:03:38.581Z,1617390218.581 [DataOverHttps](INFO): Sending 246 bytes from file Logs/20210402T180016/Express0026.lzma
2021-04-02T19:03:39.605Z,1617390219.605 [DataOverHttps](INFO): Moved sent file to Logs/20210402T180016/Express0026.lzma.bak
2021-04-02T19:03:39.605Z,1617390219.605 [DataOverHttps](INFO): SBD MOMSN=15540212
2021-04-02T19:03:41.144Z,1617390221.144 [Default:CheckIn:Read_Iridium] Stopped
2021-04-02T19:03:41.144Z,1617390221.144 [Default:CheckIn:C.Wait] Running Loop=1
2021-04-02T19:03:41.144Z,1617390221.144 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-04-02T19:03:47.222Z,1617390227.222 [NAL9602](INFO): Not Powering down - fast GPS
2021-04-02T19:06:09.768Z,1617390369.768 [CommandLine](IMPORTANT): got command report mod platform_buoyancy_position
2021-04-02T19:06:09.864Z,1617390369.864 [Reporter](INFO): platform_buoyancy_position 945.176147 cc
2021-04-02T19:06:11.462Z,1617390371.462 [CommandLine](IMPORTANT): got command maintain
2021-04-02T19:06:11.622Z,1617390371.622 [DataOverHttps](IMPORTANT): SBD MTMSN=20210402T190629