2023-04-05T20:23:17.249Z,1680726197.249 [Supervisor](DEBUG): Initializing supervisor.
2023-04-05T20:23:17.254Z,1680726197.254 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2023-04-05T20:23:17.254Z,1680726197.254 [SyncHandler](INFO): Protected caller Thread ID is 1271
2023-04-05T20:23:17.255Z,1680726197.255 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2023-04-05T20:23:17.256Z,1680726197.256 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2023-04-05T20:23:17.256Z,1680726197.256 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1272
2023-04-05T20:23:17.261Z,1680726197.261 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2023-04-05T20:23:17.279Z,1680726197.279 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread.
2023-04-05T20:23:17.280Z,1680726197.280 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2023-04-05T20:23:17.280Z,1680726197.280 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 1273
2023-04-05T20:23:17.284Z,1680726197.284 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2023-04-05T20:23:17.285Z,1680726197.285 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2023-04-05T20:23:17.286Z,1680726197.286 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1274
2023-04-05T20:23:17.288Z,1680726197.288 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2023-04-05T20:23:17.289Z,1680726197.289 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0
2023-04-05T20:23:17.289Z,1680726197.289 [logger ThreadHandler](INFO): Protected caller Thread ID is 1275
2023-04-05T20:23:17.293Z,1680726197.293 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2023-04-05T20:23:17.293Z,1680726197.293 [Supervisor](INFO): Looking for Config files in directory: Config/
2023-04-05T20:23:17.295Z,1680726197.295 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2023-04-05T20:23:17.615Z,1680726197.615 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2023-04-05T20:23:17.615Z,1680726197.615 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2023-04-05T20:23:18.241Z,1680726198.241 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2023-04-05T20:23:18.242Z,1680726198.242 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2023-04-05T20:23:18.349Z,1680726198.349 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2023-04-05T20:23:18.350Z,1680726198.350 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2023-04-05T20:23:18.817Z,1680726198.817 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2023-04-05T20:23:18.817Z,1680726198.817 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2023-04-05T20:23:18.913Z,1680726198.913 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2023-04-05T20:23:18.913Z,1680726198.913 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2023-04-05T20:23:18.993Z,1680726198.993 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2023-04-05T20:23:19.375Z,1680726199.375 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2023-04-05T20:23:19.376Z,1680726199.376 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2023-04-05T20:23:19.587Z,1680726199.587 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2023-04-05T20:23:19.588Z,1680726199.588 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2023-04-05T20:23:19.722Z,1680726199.722 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2023-04-05T20:23:19.723Z,1680726199.723 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2023-04-05T20:23:19.945Z,1680726199.945 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2023-04-05T20:23:19.946Z,1680726199.946 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2023-04-05T20:23:20.454Z,1680726200.454 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2023-04-05T20:23:20.455Z,1680726200.455 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2023-04-05T20:23:20.808Z,1680726200.808 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2023-04-05T20:23:20.809Z,1680726200.809 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2023-04-05T20:23:20.887Z,1680726200.887 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2023-04-05T20:23:21.065Z,1680726201.065 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2023-04-05T20:23:21.065Z,1680726201.065 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2023-04-05T20:23:21.276Z,1680726201.276 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2023-04-05T20:23:21.277Z,1680726201.277 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2023-04-05T20:23:21.621Z,1680726201.621 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2023-04-05T20:23:21.623Z,1680726201.623 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-brizo/
2023-04-05T20:23:21.624Z,1680726201.624 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Control.cfg
2023-04-05T20:23:21.876Z,1680726201.876 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Sensor.cfg
2023-04-05T20:23:22.073Z,1680726202.073 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Simulator.cfg
2023-04-05T20:23:22.182Z,1680726202.182 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/secure.cfg
2023-04-05T20:23:22.268Z,1680726202.268 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Servo.cfg
2023-04-05T20:23:22.619Z,1680726202.619 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/vehicle.cfg
2023-04-05T20:23:22.787Z,1680726202.787 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Battery.cfg
2023-04-05T20:23:23.048Z,1680726203.048 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2023-04-05T20:23:23.048Z,1680726203.048 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Science.cfg
2023-04-05T20:23:23.175Z,1680726203.175 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/logger.cfg
2023-04-05T20:23:23.266Z,1680726203.266 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/BIT.cfg
2023-04-05T20:23:23.367Z,1680726203.367 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Navigation.cfg
2023-04-05T20:23:23.466Z,1680726203.466 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-brizo/root/
2023-04-05T20:23:23.466Z,1680726203.466 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2023-04-05T20:23:23.481Z,1680726203.481 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2023-04-05T20:23:23.579Z,1680726203.579 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2023-04-05T20:23:23.580Z,1680726203.580 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2023-04-05T20:23:23.589Z,1680726203.589 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2023-04-05T20:23:23.590Z,1680726203.590 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2023-04-05T20:23:23.642Z,1680726203.642 [DepthRateCalculator] Loaded
2023-04-05T20:23:23.642Z,1680726203.642 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2023-04-05T20:23:23.647Z,1680726203.647 [PitchRateCalculator] Loaded
2023-04-05T20:23:23.648Z,1680726203.648 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2023-04-05T20:23:23.658Z,1680726203.658 [SpeedCalculator] Loaded
2023-04-05T20:23:23.658Z,1680726203.658 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2023-04-05T20:23:23.674Z,1680726203.674 [VerticalHomogeneityIndexCalculator] Loaded
2023-04-05T20:23:23.674Z,1680726203.674 [ComponentRegistry](DEBUG): SyncComponent "VerticalHomogeneityIndexCalculator" handled in the control thread.
2023-04-05T20:23:23.679Z,1680726203.679 [YawRateCalculator] Loaded
2023-04-05T20:23:23.679Z,1680726203.679 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2023-04-05T20:23:23.701Z,1680726203.701 [ElevatorOffsetCalculator] Loaded
2023-04-05T20:23:23.701Z,1680726203.701 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2023-04-05T20:23:23.701Z,1680726203.701 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2023-04-05T20:23:23.702Z,1680726203.702 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2023-04-05T20:23:23.751Z,1680726203.751 [VerticalControl](DEBUG): Construct VerticalControl.
2023-04-05T20:23:23.807Z,1680726203.807 [VerticalControl] Loaded
2023-04-05T20:23:23.808Z,1680726203.808 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2023-04-05T20:23:23.810Z,1680726203.810 [HorizontalControl](DEBUG): Construct HorizontalControl.
2023-04-05T20:23:23.851Z,1680726203.851 [HorizontalControl] Loaded
2023-04-05T20:23:23.852Z,1680726203.852 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2023-04-05T20:23:23.854Z,1680726203.854 [SpeedControl](DEBUG): Construct SpeedControl.
2023-04-05T20:23:23.857Z,1680726203.857 [SpeedControl] Loaded
2023-04-05T20:23:23.857Z,1680726203.857 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2023-04-05T20:23:23.860Z,1680726203.860 [LoopControl](DEBUG): Construct LoopControl.
2023-04-05T20:23:23.860Z,1680726203.860 [LoopControl] Loaded
2023-04-05T20:23:23.861Z,1680726203.861 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2023-04-05T20:23:23.861Z,1680726203.861 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2023-04-05T20:23:23.862Z,1680726203.862 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2023-04-05T20:23:23.972Z,1680726203.972 [DeadReckonUsingMultipleVelocitySources] Loaded
2023-04-05T20:23:23.972Z,1680726203.972 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2023-04-05T20:23:23.986Z,1680726203.986 [NavChart] Loaded
2023-04-05T20:23:23.986Z,1680726203.986 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2023-04-05T20:23:23.992Z,1680726203.992 [UniversalFixResidualReporter] Loaded
2023-04-05T20:23:23.992Z,1680726203.992 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2023-04-05T20:23:23.993Z,1680726203.993 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2023-04-05T20:23:23.993Z,1680726203.993 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2023-04-05T20:23:24.139Z,1680726204.139 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2023-04-05T20:23:24.140Z,1680726204.140 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2023-04-05T20:23:24.585Z,1680726204.585 [AHRS_M2] Loaded
2023-04-05T20:23:24.586Z,1680726204.586 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2023-04-05T20:23:24.622Z,1680726204.622 [BackseatComponent] Loaded
2023-04-05T20:23:24.622Z,1680726204.622 [ComponentRegistry](DEBUG): Component "BackseatComponent" handled in its own thread.
2023-04-05T20:23:24.623Z,1680726204.623 [BackseatComponent ThreadHandler](DEBUG): Created PCaller Thread at 408F64E0
2023-04-05T20:23:24.623Z,1680726204.623 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 1357
2023-04-05T20:23:24.626Z,1680726204.626 [LcmUniversalReporter] Loaded
2023-04-05T20:23:24.627Z,1680726204.627 [ComponentRegistry](DEBUG): SyncComponent "LcmUniversalReporter" handled in the control thread.
2023-04-05T20:23:25.439Z,1680726205.439 [BPC1] Loaded
2023-04-05T20:23:25.439Z,1680726205.439 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2023-04-05T20:23:25.511Z,1680726205.511 [DataOverHttps] Loaded
2023-04-05T20:23:25.512Z,1680726205.512 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2023-04-05T20:23:25.513Z,1680726205.513 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 409264E0
2023-04-05T20:23:25.513Z,1680726205.513 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 1358
2023-04-05T20:23:25.533Z,1680726205.533 [Depth_Keller] Loaded
2023-04-05T20:23:25.534Z,1680726205.534 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2023-04-05T20:23:25.539Z,1680726205.539 [DropWeight] Loaded
2023-04-05T20:23:25.539Z,1680726205.539 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2023-04-05T20:23:25.577Z,1680726205.577 [DVL_micro] Loaded
2023-04-05T20:23:25.577Z,1680726205.577 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2023-04-05T20:23:25.639Z,1680726205.639 [NAL9602] Loaded
2023-04-05T20:23:25.639Z,1680726205.639 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2023-04-05T20:23:25.669Z,1680726205.669 [Onboard] Loaded
2023-04-05T20:23:25.669Z,1680726205.669 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2023-04-05T20:23:25.670Z,1680726205.670 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 409564E0
2023-04-05T20:23:25.671Z,1680726205.671 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 1359
2023-04-05T20:23:25.683Z,1680726205.683 [Power24vConverter] Loaded
2023-04-05T20:23:25.683Z,1680726205.683 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread.
2023-04-05T20:23:25.696Z,1680726205.696 [Radio_Surface] Loaded
2023-04-05T20:23:25.696Z,1680726205.696 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2023-04-05T20:23:25.697Z,1680726205.697 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 409864E0
2023-04-05T20:23:25.698Z,1680726205.698 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1360
2023-04-05T20:23:25.789Z,1680726205.789 [DAT] Loaded
2023-04-05T20:23:25.790Z,1680726205.790 [ComponentRegistry](DEBUG): Component "DAT" handled in its own thread.
2023-04-05T20:23:25.791Z,1680726205.791 [DAT ThreadHandler](DEBUG): Created PCaller Thread at 409B64E0
2023-04-05T20:23:25.791Z,1680726205.791 [DAT ThreadHandler](INFO): Protected caller Thread ID is 1361
2023-04-05T20:23:25.792Z,1680726205.792 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2023-04-05T20:23:25.792Z,1680726205.792 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2023-04-05T20:23:25.921Z,1680726205.921 [BuoyancyServo] Loaded
2023-04-05T20:23:25.921Z,1680726205.921 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2023-04-05T20:23:25.942Z,1680726205.942 [ElevatorServo] Loaded
2023-04-05T20:23:25.942Z,1680726205.942 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2023-04-05T20:23:25.962Z,1680726205.962 [MassServo] Loaded
2023-04-05T20:23:25.962Z,1680726205.962 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2023-04-05T20:23:25.981Z,1680726205.981 [RudderServo] Loaded
2023-04-05T20:23:25.981Z,1680726205.981 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2023-04-05T20:23:25.996Z,1680726205.996 [ThrusterHE] Loaded
2023-04-05T20:23:25.996Z,1680726205.996 [ComponentRegistry](DEBUG): SyncComponent "ThrusterHE" handled in the control thread.
2023-04-05T20:23:25.996Z,1680726205.996 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2023-04-05T20:23:25.997Z,1680726205.997 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2023-04-05T20:23:26.066Z,1680726206.066 [StratificationFrontDetector](IMPORTANT): thresholdVTHI set to: 0.050012 degC
2023-04-05T20:23:26.066Z,1680726206.066 [StratificationFrontDetector](INFO): (re)initializing
2023-04-05T20:23:26.067Z,1680726206.067 [StratificationFrontDetector] Loaded
2023-04-05T20:23:26.067Z,1680726206.067 [ComponentRegistry](DEBUG): SyncComponent "StratificationFrontDetector" handled in the control thread.
2023-04-05T20:23:26.068Z,1680726206.068 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2023-04-05T20:23:26.068Z,1680726206.068 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2023-04-05T20:23:26.095Z,1680726206.095 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2023-04-05T20:23:26.095Z,1680726206.095 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2023-04-05T20:23:26.400Z,1680726206.400 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2023-04-05T20:23:26.400Z,1680726206.400 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2023-04-05T20:23:26.569Z,1680726206.569 [CTD_Seabird] Loaded
2023-04-05T20:23:26.569Z,1680726206.569 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2023-04-05T20:23:26.570Z,1680726206.570 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40B404E0
2023-04-05T20:23:26.571Z,1680726206.571 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 1362
2023-04-05T20:23:26.604Z,1680726206.604 [ESPComponent] Loaded
2023-04-05T20:23:26.604Z,1680726206.604 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2023-04-05T20:23:26.626Z,1680726206.626 [PAR_Licor] Loaded
2023-04-05T20:23:26.626Z,1680726206.626 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2023-04-05T20:23:26.658Z,1680726206.658 [WetLabsBB2FL] Loaded
2023-04-05T20:23:26.658Z,1680726206.658 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2023-04-05T20:23:26.659Z,1680726206.659 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40B704E0
2023-04-05T20:23:26.659Z,1680726206.659 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 1363
2023-04-05T20:23:26.660Z,1680726206.660 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2023-04-05T20:23:26.661Z,1680726206.661 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2023-04-05T20:23:27.010Z,1680726207.010 [SBIT](DEBUG): Construct Startup Built In Test.
2023-04-05T20:23:27.019Z,1680726207.019 [SBIT] Loaded
2023-04-05T20:23:27.020Z,1680726207.020 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2023-04-05T20:23:27.022Z,1680726207.022 [IBIT](DEBUG): Construct Initiated Built In Test.
2023-04-05T20:23:27.036Z,1680726207.036 [IBIT] Loaded
2023-04-05T20:23:27.036Z,1680726207.036 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2023-04-05T20:23:27.042Z,1680726207.042 [CBIT](DEBUG): Construct Continuous Built In Test.
2023-04-05T20:23:27.148Z,1680726207.148 [CBIT] Loaded
2023-04-05T20:23:27.148Z,1680726207.148 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2023-04-05T20:23:27.149Z,1680726207.149 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2023-04-05T20:23:27.155Z,1680726207.155 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2023-04-05T20:23:27.158Z,1680726207.158 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2023-04-05T20:23:27.169Z,1680726207.169 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2023-04-05T20:23:27.170Z,1680726207.170 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40BDE4E0
2023-04-05T20:23:27.170Z,1680726207.170 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1364
2023-04-05T20:23:27.175Z,1680726207.175 [Supervisor](INFO): Main Thread ID is 827
2023-04-05T20:23:27.175Z,1680726207.175 [Supervisor](DEBUG): Running supervisor.
2023-04-05T20:23:27.176Z,1680726207.176 [CommandExec ThreadHandler](INFO): Handler Thread ID is 1365
2023-04-05T20:23:27.176Z,1680726207.176 [CommandExec](INFO): Initializing the command executive.
2023-04-05T20:23:27.177Z,1680726207.177 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1366
2023-04-05T20:23:27.180Z,1680726207.180 [controlThread ThreadHandler](INFO): Handler Thread ID is 1367
2023-04-05T20:23:27.180Z,1680726207.180 [controlThread](DEBUG): Initializing ControlThread
2023-04-05T20:23:27.181Z,1680726207.181 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2023-04-05T20:23:27.181Z,1680726207.181 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2023-04-05T20:23:27.182Z,1680726207.182 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2023-04-05T20:23:27.182Z,1680726207.182 [VerticalHomogeneityIndexCalculator](DEBUG): (re)initializing
2023-04-05T20:23:27.183Z,1680726207.183 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2023-04-05T20:23:27.183Z,1680726207.183 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2023-04-05T20:23:27.184Z,1680726207.184 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2023-04-05T20:23:27.185Z,1680726207.185 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2023-04-05T20:23:27.186Z,1680726207.186 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2023-04-05T20:23:27.187Z,1680726207.187 [LoopControl](DEBUG): Initialize LoopControlComponent.
2023-04-05T20:23:27.188Z,1680726207.188 [NavChart](DEBUG): Initialize NavChart Navigation.
2023-04-05T20:23:27.188Z,1680726207.188 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2023-04-05T20:23:27.196Z,1680726207.196 [SBIT](INFO): Initialize SBIT Component.
2023-04-05T20:23:27.197Z,1680726207.197 [SBIT](IMPORTANT): git: 2023-04-04
2023-04-05T20:23:27.197Z,1680726207.197 [SBIT](INFO): git hash: b8e3dc7784c205eaa6d34dbcc6cfad52b0792170
2023-04-05T20:23:27.197Z,1680726207.197 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2023-04-05T20:23:27.198Z,1680726207.198 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #1 PREEMPT Tue Sep 24 11:12:27 PDT 2019
Kernel Reported: #1 PREEMPT Wed Mar 17 08:23:48 PDT 2021
2023-04-05T20:23:27.199Z,1680726207.199 [SBIT](INFO): Beginning SBIT in 149.000000 seconds.
2023-04-05T20:23:27.200Z,1680726207.200 [IBIT](INFO): Initialize IBIT Component.
2023-04-05T20:23:27.201Z,1680726207.201 [CBIT](DEBUG): Initialize CBIT Component.
2023-04-05T20:23:27.201Z,1680726207.201 [logger ThreadHandler](INFO): Handler Thread ID is 1368
2023-04-05T20:23:27.212Z,1680726207.212 [CBIT](DEBUG): Initialized mux pins.
2023-04-05T20:23:27.212Z,1680726207.212 [CBIT](DEBUG): Initializing the watchdog timer.
2023-04-05T20:23:27.220Z,1680726207.220 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 1369
2023-04-05T20:23:27.232Z,1680726207.232 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 1370
2023-04-05T20:23:27.233Z,1680726207.233 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2023-04-05T20:23:27.236Z,1680726207.236 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2023-04-05T20:23:27.236Z,1680726207.236 [CBIT](DEBUG): Initializing heartbeat.
2023-04-05T20:23:27.244Z,1680726207.244 [Onboard ThreadHandler](INFO): Handler Thread ID is 1371
2023-04-05T20:23:27.262Z,1680726207.262 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1372
2023-04-05T20:23:27.281Z,1680726207.281 [DAT ThreadHandler](INFO): Handler Thread ID is 1373
2023-04-05T20:23:27.281Z,1680726207.281 [DAT](INFO): Powering up
2023-04-05T20:23:27.282Z,1680726207.282 [DAT](DEBUG): Initializing DAT.
2023-04-05T20:23:27.285Z,1680726207.285 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 1375
2023-04-05T20:23:27.286Z,1680726207.286 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2023-04-05T20:23:27.289Z,1680726207.289 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 1377
2023-04-05T20:23:27.292Z,1680726207.292 [WetLabsBB2FL](INFO): Powering up
2023-04-05T20:23:27.293Z,1680726207.293 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1379
2023-04-05T20:23:27.296Z,1680726207.296 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2023-04-05T20:23:27.296Z,1680726207.296 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2023-04-05T20:23:27.297Z,1680726207.297 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2023-04-05T20:23:27.297Z,1680726207.297 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2023-04-05T20:23:27.297Z,1680726207.297 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2023-04-05T20:23:27.297Z,1680726207.297 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2023-04-05T20:23:27.297Z,1680726207.297 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2023-04-05T20:23:27.297Z,1680726207.297 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2023-04-05T20:23:27.308Z,1680726207.308 [CBIT](DEBUG): Deactivating GF circuits.
2023-04-05T20:23:27.308Z,1680726207.308 [CBIT](DEBUG): Deactivating emergency mode.
2023-04-05T20:23:27.348Z,1680726207.348 [CBIT](DEBUG): Backplane powered.
2023-04-05T20:23:27.349Z,1680726207.349 [MissionManager](INFO): Loading Mission from file: Missions/Startup.xml
2023-04-05T20:23:27.361Z,1680726207.361 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2023-04-05T20:23:27.385Z,1680726207.385 [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>


2023-04-05T20:23:27.385Z,1680726207.385 [MissionManager](INFO): Loading Mission from file: Missions/Default.xml
2023-04-05T20:23:27.468Z,1680726207.468 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2023-04-05T20:23:27.469Z,1680726207.469 [Default:A.Wait](DEBUG): Construct Wait.
2023-04-05T20:23:27.496Z,1680726207.496 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2023-04-05T20:23:27.523Z,1680726207.523 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2023-04-05T20:23:27.526Z,1680726207.526 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2023-04-05T20:23:27.552Z,1680726207.552 [Default:E.Execute](DEBUG): Construct Execute.
2023-04-05T20:23:27.555Z,1680726207.555 [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="P4H">
                <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>


2023-04-05T20:23:27.564Z,1680726207.564 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,DropWeight,DVL_micro,NAL9602,Power24vConverter,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,VerticalHomogeneityIndexCalculator,YawRateCalculator,ElevatorOffsetCalculator,StratificationFrontDetector,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter,
2023-04-05T20:23:27.576Z,1680726207.576 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2023-04-05T20:23:27.661Z,1680726207.661 [Power24vConverter](INFO): Powering up.
2023-04-05T20:23:27.668Z,1680726207.668 [Radio_Surface](INFO): Powering up
2023-04-05T20:23:27.730Z,1680726207.730 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2023-04-05T20:23:27.736Z,1680726207.736 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2023-04-05T20:23:27.737Z,1680726207.737 [ElevatorServo](DEBUG): Initializing EZServoServo.
2023-04-05T20:23:27.744Z,1680726207.744 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2023-04-05T20:23:27.745Z,1680726207.745 [MassServo](DEBUG): Initializing EZServoServo.
2023-04-05T20:23:27.752Z,1680726207.752 [MassServo](DEBUG): Initializing MassServo.
2023-04-05T20:23:27.753Z,1680726207.753 [RudderServo](DEBUG): Initializing EZServoServo.
2023-04-05T20:23:27.760Z,1680726207.760 [RudderServo](DEBUG): Initializing RudderServo.
2023-04-05T20:23:27.761Z,1680726207.761 [ThrusterHE](DEBUG): Initializing EZServoServo.
2023-04-05T20:23:27.768Z,1680726207.768 [ThrusterHE](DEBUG): Initializing ThrusterHE.
2023-04-05T20:23:29.904Z,1680726209.904 [WetLabsBB2FL](INFO): Powering down
2023-04-05T20:23:33.345Z,1680726213.345 [ThrusterHE](ERROR): Zero Speed Commanded.
2023-04-05T20:23:34.316Z,1680726214.316 [CTD_Seabird](ERROR): Device message queue exceeded the allowed limit.
2023-04-05T20:23:55.858Z,1680726235.858 [NAL9602](INFO): Powering up NAL9602
2023-04-05T20:24:06.770Z,1680726246.770 [NAL9602](INFO): NAL9602 initialized
2023-04-05T20:24:27.284Z,1680726267.284 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2023-04-05T20:24:27.284Z,1680726267.284 [DAT] Communications Fault, FailCount= 1
2023-04-05T20:24:27.284Z,1680726267.284 [DAT](ERROR): Communications Fault
2023-04-05T20:24:27.428Z,1680726267.428 [CBIT](ERROR): Communications Fault in component: DAT
2023-04-05T20:24:27.688Z,1680726267.688 [DAT](INFO): Powering down
2023-04-05T20:24:28.668Z,1680726268.668 [CBIT](INFO): Clearing failed state for component DAT
2023-04-05T20:24:28.669Z,1680726268.669 [DAT] No Fault, FailCount= 1
2023-04-05T20:24:30.740Z,1680726270.740 [DAT](INFO): Powering up
2023-04-05T20:24:30.740Z,1680726270.740 [DAT](DEBUG): Initializing DAT.
2023-04-05T20:25:25.191Z,1680726325.191 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:25:30.988Z,1680726330.988 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2023-04-05T20:25:30.988Z,1680726330.988 [DAT] Communications Fault, FailCount= 2
2023-04-05T20:25:30.988Z,1680726330.988 [DAT](ERROR): Communications Fault
2023-04-05T20:25:31.227Z,1680726331.227 [CBIT](ERROR): Communications Fault in component: DAT
2023-04-05T20:25:31.392Z,1680726331.392 [DAT](INFO): Powering down
2023-04-05T20:25:32.444Z,1680726332.444 [CBIT](INFO): Clearing failed state for component DAT
2023-04-05T20:25:32.444Z,1680726332.444 [DAT] No Fault, FailCount= 2
2023-04-05T20:25:34.440Z,1680726334.440 [DAT](INFO): Powering up
2023-04-05T20:25:34.440Z,1680726334.440 [DAT](DEBUG): Initializing DAT.
2023-04-05T20:25:39.685Z,1680726339.685 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:25:54.224Z,1680726354.224 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:25:56.674Z,1680726356.674 [SBIT](IMPORTANT): Beginning Startup BIT
2023-04-05T20:25:56.679Z,1680726356.679 [CBIT](IMPORTANT): Beginning ground fault scan
2023-04-05T20:26:07.602Z,1680726367.602 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.005220
CHAN A1 (24V): -0.002067
CHAN A2 (12V): -0.000408
CHAN A3 (5V): 0.000587
CHAN B0 (3.3V): 0.000664
CHAN B1 (3.15aV): 0.000301
CHAN B2 (3.15bV): 0.000548
CHAN B3 (GND): 0.000019
OPEN: 0.005088
Full Scale: +/- 1 mA
2023-04-05T20:26:09.172Z,1680726369.172 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:26:24.121Z,1680726384.121 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:26:27.386Z,1680726387.386 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2023-04-05T20:26:27.386Z,1680726387.386 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-04-05T20:26:27.405Z,1680726387.405 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-04-05T20:26:27.813Z,1680726387.813 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-04-05T20:26:27.814Z,1680726387.814 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2023-04-05T20:26:30.281Z,1680726390.281 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004213
2023-04-05T20:26:34.468Z,1680726394.468 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2023-04-05T20:26:34.468Z,1680726394.468 [DAT] Communications Fault, FailCount= 3
2023-04-05T20:26:34.468Z,1680726394.468 [DAT](ERROR): Communications Fault
2023-04-05T20:26:34.656Z,1680726394.656 [CBIT](ERROR): Communications Fault in component: DAT
2023-04-05T20:26:34.872Z,1680726394.872 [DAT](INFO): Powering down
2023-04-05T20:26:35.884Z,1680726395.884 [CBIT](INFO): Clearing failed state for component DAT
2023-04-05T20:26:35.884Z,1680726395.884 [DAT] No Fault, FailCount= 3
2023-04-05T20:26:37.920Z,1680726397.920 [DAT](INFO): Powering up
2023-04-05T20:26:37.920Z,1680726397.920 [DAT](DEBUG): Initializing DAT.
2023-04-05T20:26:39.473Z,1680726399.473 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:26:50.404Z,1680726410.404 [SBIT](FAULT): Mass: EXPECTED:0.032500 ACTUAL:0.032000
2023-04-05T20:26:50.405Z,1680726410.405 [SBIT](FAULT): Control surface position failure.
2023-04-05T20:26:50.807Z,1680726410.807 [SBIT](CRITICAL): SBIT FAILED
2023-04-05T20:26:50.807Z,1680726410.807 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2023-04-05T20:26:50.809Z,1680726410.809 [SBIT](IMPORTANT): BPC1.batteryMissingStickThreshold=5 count;

2023-04-05T20:26:50.809Z,1680726410.809 [SBIT](IMPORTANT): DAT.sbdAddress=-1 enum;

2023-04-05T20:26:50.809Z,1680726410.809 [SBIT](IMPORTANT): Depth_Keller.offset=3.5 decibar;

2023-04-05T20:26:50.809Z,1680726410.809 [SBIT](IMPORTANT): Express none CBIT.ampHoursUsed;

2023-04-05T20:26:50.809Z,1680726410.809 [SBIT](IMPORTANT): Express linearApproximation VerticalHomogeneityIndexCalculator.vertical_temperature_homogeneity_index 0.050000 celsius;

2023-04-05T20:26:50.811Z,1680726410.811 [SBIT](IMPORTANT): Express none WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water;

2023-04-05T20:26:50.811Z,1680726410.811 [SBIT](IMPORTANT): StratificationFrontDetector.loadAtStartup=1 bool;

2023-04-05T20:26:50.812Z,1680726410.812 [SBIT](IMPORTANT): StratificationFrontDetector.threshold_VTHI=0.05 celsius;

2023-04-05T20:26:50.812Z,1680726410.812 [SBIT](IMPORTANT): StratificationFrontDetector.verbosity=1 count;

2023-04-05T20:26:50.812Z,1680726410.812 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=341.374110 cubic_centimeter;

2023-04-05T20:26:50.812Z,1680726410.812 [SBIT](IMPORTANT): VerticalControl.massDefault=3.25 centimeter;

2023-04-05T20:26:50.812Z,1680726410.812 [SBIT](IMPORTANT): VerticalControl.massPositionLimitAft=-28 millimeter;

2023-04-05T20:26:50.812Z,1680726410.812 [SBIT](IMPORTANT): VerticalControl.massPositionLimitFwd=32 millimeter;

2023-04-05T20:26:50.812Z,1680726410.812 [SBIT](IMPORTANT): VerticalControl.surfaceThreshold=1.5 meter;

2023-04-05T20:26:50.812Z,1680726410.812 [SBIT](IMPORTANT): VerticalHomogeneityIndexCalculator.depth3=15 meter;

2023-04-05T20:26:50.813Z,1680726410.813 [SBIT](IMPORTANT): VerticalHomogeneityIndexCalculator.depth4=20 meter;

2023-04-05T20:26:50.813Z,1680726410.813 [SBIT](IMPORTANT): VerticalHomogeneityIndexCalculator.loadAtStartup=1 bool;

2023-04-05T20:26:50.817Z,1680726410.817 [CommandExec](FAULT): Scheduling is paused
2023-04-05T20:26:50.817Z,1680726410.817 [CBIT](INFO): Critical error at 20230405T202650
2023-04-05T20:26:50.818Z,1680726410.818 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2023-04-05T20:26:51.220Z,1680726411.220 [MissionManager](IMPORTANT): Started mission Startup
2023-04-05T20:26:51.221Z,1680726411.221 [Startup] Running Loop=1
2023-04-05T20:26:51.221Z,1680726411.221 [Startup](DEBUG): Aggregate::initialize Startup
2023-04-05T20:26:51.221Z,1680726411.221 [Startup:A.GoToSurface] Running Loop=1
2023-04-05T20:26:51.221Z,1680726411.221 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2023-04-05T20:26:51.222Z,1680726411.222 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2023-04-05T20:26:51.222Z,1680726411.222 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2023-04-05T20:26:51.222Z,1680726411.222 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2023-04-05T20:26:51.223Z,1680726411.223 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2023-04-05T20:26:51.223Z,1680726411.223 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2023-04-05T20:26:51.225Z,1680726411.225 [Startup:StartupSatComms] Running Loop=1
2023-04-05T20:26:51.225Z,1680726411.225 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2023-04-05T20:26:51.226Z,1680726411.226 [Startup:StartupSatComms:A] Running Loop=1
2023-04-05T20:26:51.624Z,1680726411.624 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2023-04-05T20:26:54.420Z,1680726414.420 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:27:09.368Z,1680726429.368 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:27:23.913Z,1680726443.913 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:27:38.164Z,1680726458.164 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2023-04-05T20:27:38.164Z,1680726458.164 [DAT] Communications Fault, FailCount= 4
2023-04-05T20:27:38.164Z,1680726458.164 [DAT](ERROR): Communications Fault
2023-04-05T20:27:38.568Z,1680726458.568 [DAT](INFO): Powering down
2023-04-05T20:27:38.605Z,1680726458.605 [CBIT](ERROR): Communications Fault in component: DAT
2023-04-05T20:27:38.860Z,1680726458.860 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:27:39.709Z,1680726459.709 [CBIT](INFO): Clearing failed state for component DAT
2023-04-05T20:27:39.709Z,1680726459.709 [DAT] No Fault, FailCount= 4
2023-04-05T20:27:41.616Z,1680726461.616 [DAT](INFO): Powering up
2023-04-05T20:27:41.616Z,1680726461.616 [DAT](DEBUG): Initializing DAT.
2023-04-05T20:27:51.431Z,1680726471.431 [Startup:StartupSatComms:A](INFO): Timed out from 2023-04-05T20:26:51.2Z
2023-04-05T20:27:51.431Z,1680726471.431 [Startup:StartupSatComms:A] Stopped
2023-04-05T20:27:51.431Z,1680726471.431 [Startup:StartupSatComms:B] Running Loop=1
2023-04-05T20:27:51.850Z,1680726471.850 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2023-04-05T20:28:01.004Z,1680726481.004 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20230405T195657/Courier0013.lzma
2023-04-05T20:28:02.006Z,1680726482.006 [DataOverHttps](INFO): Moved sent file to Logs/20230405T195657/Courier0013.lzma.bak
2023-04-05T20:28:02.006Z,1680726482.006 [DataOverHttps](INFO): SBD MOMSN=18035283
2023-04-05T20:28:02.848Z,1680726482.848 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-04-05T20:28:02.848Z,1680726482.848 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+21.4,089.0,000
2023-04-05T20:28:17.535Z,1680726497.535 [DataOverHttps](INFO): Sending 185 bytes from file Logs/20230405T202317/Courier0000.lzma
2023-04-05T20:28:18.537Z,1680726498.537 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Courier0000.lzma.bak
2023-04-05T20:28:18.538Z,1680726498.538 [DataOverHttps](INFO): SBD MOMSN=18035285
2023-04-05T20:28:34.128Z,1680726514.128 [DataOverHttps](INFO): Sending 482 bytes from file Logs/20230405T195657/Express0014.lzma
2023-04-05T20:28:35.129Z,1680726515.129 [DataOverHttps](INFO): Moved sent file to Logs/20230405T195657/Express0014.lzma.bak
2023-04-05T20:28:35.130Z,1680726515.130 [DataOverHttps](INFO): SBD MOMSN=18035289
2023-04-05T20:28:41.864Z,1680726521.864 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2023-04-05T20:28:41.864Z,1680726521.864 [DAT] Communications Fault, FailCount= 5
2023-04-05T20:28:41.864Z,1680726521.864 [DAT](ERROR): Communications Fault
2023-04-05T20:28:42.062Z,1680726522.062 [CBIT](ERROR): Communications Fault in component: DAT
2023-04-05T20:28:42.268Z,1680726522.268 [DAT](INFO): Powering down
2023-04-05T20:28:43.301Z,1680726523.301 [CBIT](INFO): Clearing failed state for component DAT
2023-04-05T20:28:43.302Z,1680726523.302 [DAT] No Fault, FailCount= 5
2023-04-05T20:28:45.320Z,1680726525.320 [DAT](INFO): Powering up
2023-04-05T20:28:45.320Z,1680726525.320 [DAT](DEBUG): Initializing DAT.
2023-04-05T20:28:50.646Z,1680726530.646 [DataOverHttps](INFO): Sending 1217 bytes from file Logs/20230405T202317/Express0001.lzma
2023-04-05T20:28:51.646Z,1680726531.646 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Express0001.lzma.bak
2023-04-05T20:28:51.646Z,1680726531.646 [DataOverHttps](INFO): SBD MOMSN=18035338
2023-04-05T20:28:51.747Z,1680726531.747 [Startup:StartupSatComms:B](INFO): Timed out from 2023-04-05T20:27:51.4Z
2023-04-05T20:28:51.747Z,1680726531.747 [Startup:StartupSatComms:B] Stopped
2023-04-05T20:28:51.747Z,1680726531.747 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2023-04-05T20:28:51.747Z,1680726531.747 [Startup:StartupSatComms] Stopped
2023-04-05T20:28:51.747Z,1680726531.747 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2023-04-05T20:28:51.748Z,1680726531.748 [Startup](INFO): Completed Startup
2023-04-05T20:28:51.748Z,1680726531.748 [MissionManager](INFO): Startup is completed.
2023-04-05T20:28:51.748Z,1680726531.748 [MissionManager](INFO): Uninitializing Mission Startup
2023-04-05T20:28:51.748Z,1680726531.748 [Startup] Stopped
2023-04-05T20:28:51.749Z,1680726531.749 [Startup](DEBUG): Aggregate::uninitialize Startup
2023-04-05T20:28:51.749Z,1680726531.749 [Startup:A.GoToSurface] Stopped
2023-04-05T20:28:51.749Z,1680726531.749 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2023-04-05T20:28:52.158Z,1680726532.158 [MissionManager](IMPORTANT): Started mission Default
2023-04-05T20:28:52.159Z,1680726532.159 [Default] Running Loop=1
2023-04-05T20:28:52.159Z,1680726532.159 [Default](DEBUG): Aggregate::initialize Default
2023-04-05T20:28:52.159Z,1680726532.159 [Default:B.GoToSurface] Running Loop=1
2023-04-05T20:28:52.159Z,1680726532.159 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2023-04-05T20:28:52.159Z,1680726532.159 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2023-04-05T20:28:52.159Z,1680726532.159 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2023-04-05T20:28:52.160Z,1680726532.160 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2023-04-05T20:28:52.160Z,1680726532.160 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2023-04-05T20:28:52.161Z,1680726532.161 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2023-04-05T20:28:52.161Z,1680726532.161 [Default:A.Wait] Running Loop=1
2023-04-05T20:28:52.161Z,1680726532.161 [Default:A.Wait](DEBUG): Initialize Wait Component.
2023-04-05T20:29:05.561Z,1680726545.561 [Default:A.Wait](INFO): Done Waiting.
2023-04-05T20:29:05.561Z,1680726545.561 [Default:A.Wait] Stopped
2023-04-05T20:29:05.561Z,1680726545.561 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2023-04-05T20:29:05.891Z,1680726545.891 [Default:CheckIn] Running Loop=1
2023-04-05T20:29:05.891Z,1680726545.891 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-04-05T20:29:05.891Z,1680726545.891 [Default:CheckIn:Read_GPS] Running Loop=1
2023-04-05T20:29:06.317Z,1680726546.317 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2023-04-05T20:29:10.318Z,1680726550.318 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-04-05T20:29:28.533Z,1680726568.533 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2023-04-05T20:29:28.533Z,1680726568.533 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-04-05T20:29:28.544Z,1680726568.544 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-04-05T20:29:28.920Z,1680726568.920 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-04-05T20:29:28.921Z,1680726568.921 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2023-04-05T20:29:45.380Z,1680726585.380 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2023-04-05T20:29:45.380Z,1680726585.380 [DAT] Communications Fault, FailCount= 6
2023-04-05T20:29:45.380Z,1680726585.380 [DAT](ERROR): Communications Fault
2023-04-05T20:29:45.507Z,1680726585.507 [CBIT](ERROR): Communications Fault in component: DAT
2023-04-05T20:29:45.784Z,1680726585.784 [DAT](INFO): Powering down
2023-04-05T20:29:46.700Z,1680726586.700 [CBIT](INFO): Clearing failed state for component DAT
2023-04-05T20:29:46.701Z,1680726586.701 [DAT] No Fault, FailCount= 6
2023-04-05T20:29:48.832Z,1680726588.832 [DAT](INFO): Powering up
2023-04-05T20:29:48.832Z,1680726588.832 [DAT](DEBUG): Initializing DAT.
2023-04-05T20:30:48.860Z,1680726648.860 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2023-04-05T20:30:48.860Z,1680726648.860 [DAT] Communications Fault, FailCount= 7
2023-04-05T20:30:48.860Z,1680726648.860 [DAT](ERROR): Communications Fault
2023-04-05T20:30:48.940Z,1680726648.940 [CBIT](ERROR): Communications Fault in component: DAT
2023-04-05T20:30:49.264Z,1680726649.264 [DAT](INFO): Powering down
2023-04-05T20:30:50.162Z,1680726650.162 [CBIT](INFO): Clearing failed state for component DAT
2023-04-05T20:30:50.162Z,1680726650.162 [DAT] No Fault, FailCount= 7
2023-04-05T20:30:52.324Z,1680726652.324 [DAT](INFO): Powering up
2023-04-05T20:30:52.324Z,1680726652.324 [DAT](DEBUG): Initializing DAT.
2023-04-05T20:31:08.860Z,1680726668.860 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T20:31:10.868Z,1680726670.868 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.247253
2023-04-05T20:31:44.000Z,1680726704.000 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T20:31:52.328Z,1680726712.328 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2023-04-05T20:31:52.328Z,1680726712.328 [DAT] Communications Fault, FailCount= 8
2023-04-05T20:31:52.328Z,1680726712.328 [DAT](ERROR): Communications Fault
2023-04-05T20:31:52.403Z,1680726712.403 [CBIT](ERROR): Communications Fault in component: DAT
2023-04-05T20:31:52.404Z,1680726712.404 [CBIT](FAULT): Communications Fault in component: DAT
2023-04-05T20:31:52.732Z,1680726712.732 [DAT](INFO): Powering down
2023-04-05T20:32:05.164Z,1680726725.164 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002858
2023-04-05T20:32:29.568Z,1680726749.568 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2023-04-05T20:32:29.568Z,1680726749.568 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-04-05T20:32:29.587Z,1680726749.587 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-04-05T20:32:29.990Z,1680726749.990 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-04-05T20:32:29.990Z,1680726749.990 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2023-04-05T20:34:06.131Z,1680726846.131 [Default:CheckIn:Read_GPS](INFO): Timed out from 2023-04-05T20:29:05.9Z
2023-04-05T20:34:06.131Z,1680726846.131 [Default:CheckIn:Read_GPS] Stopped
2023-04-05T20:34:06.131Z,1680726846.131 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-04-05T20:34:06.619Z,1680726846.619 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2023-04-05T20:34:07.758Z,1680726847.758 [NAL9602](FAULT): GPS failed to acquire within timeout.
2023-04-05T20:34:07.758Z,1680726847.758 [NAL9602] Data Fault, FailCount= 1
2023-04-05T20:34:07.758Z,1680726847.758 [NAL9602](ERROR): Data Fault
2023-04-05T20:34:07.823Z,1680726847.823 [CBIT](ERROR): Data Fault in component: NAL9602
2023-04-05T20:34:08.154Z,1680726848.154 [NAL9602](INFO): Powering down
2023-04-05T20:34:09.248Z,1680726849.248 [CBIT](INFO): Clearing failed state for component NAL9602
2023-04-05T20:34:09.248Z,1680726849.248 [NAL9602] No Fault, FailCount= 1
2023-04-05T20:34:14.727Z,1680726854.727 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20230405T202317/Courier0004.lzma
2023-04-05T20:34:15.729Z,1680726855.729 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Courier0004.lzma.bak
2023-04-05T20:34:15.730Z,1680726855.730 [DataOverHttps](INFO): SBD MOMSN=18035376
2023-04-05T20:34:31.287Z,1680726871.287 [DataOverHttps](INFO): Sending 291 bytes from file Logs/20230405T202317/Express0005.lzma
2023-04-05T20:34:32.289Z,1680726872.289 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Express0005.lzma.bak
2023-04-05T20:34:32.290Z,1680726872.290 [DataOverHttps](INFO): SBD MOMSN=18035378
2023-04-05T20:34:33.615Z,1680726873.615 [Default:CheckIn:Read_Iridium] Stopped
2023-04-05T20:34:33.615Z,1680726873.615 [Default:CheckIn:C.Wait] Running Loop=1
2023-04-05T20:34:33.615Z,1680726873.615 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-04-05T20:34:38.450Z,1680726878.450 [NAL9602](INFO): Powering up NAL9602
2023-04-05T20:34:49.418Z,1680726889.418 [NAL9602](INFO): NAL9602 initialized
2023-04-05T20:35:19.652Z,1680726919.652 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:35:30.577Z,1680726930.577 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2023-04-05T20:35:30.577Z,1680726930.577 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-04-05T20:35:30.615Z,1680726930.615 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-04-05T20:35:30.995Z,1680726930.995 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-04-05T20:35:30.995Z,1680726930.995 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2023-04-05T20:35:38.238Z,1680726938.238 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:35:56.877Z,1680726956.877 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:36:15.464Z,1680726975.464 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:36:34.045Z,1680726994.045 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:36:52.628Z,1680727012.628 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:36:52.663Z,1680727012.663 [CBIT](INFO): Clearing failed state for component DAT
2023-04-05T20:36:52.663Z,1680727012.663 [DAT] No Fault, FailCount= 8
2023-04-05T20:36:52.744Z,1680727012.744 [DAT](INFO): Powering up
2023-04-05T20:36:52.745Z,1680727012.745 [DAT](DEBUG): Initializing DAT.
2023-04-05T20:37:04.600Z,1680727024.600 [DAT](INFO): DAT read: 

2023-04-05T20:37:04.602Z,1680727024.602 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series

2023-04-05T20:37:06.113Z,1680727026.113 [DAT](INFO): DAT read: MF Frequency Band

2023-04-05T20:37:06.114Z,1680727026.114 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.15.0

2023-04-05T20:37:06.114Z,1680727026.114 [DAT](INFO): DAT read: Apr  5 2023 20:37:00 

2023-04-05T20:37:07.121Z,1680727027.121 [DAT](INFO): DAT read: Features enabled [Bearing]

2023-04-05T20:37:07.122Z,1680727027.122 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP

2023-04-05T20:37:07.122Z,1680727027.122 [DAT](INFO): commRate: 800
2023-04-05T20:37:09.196Z,1680727029.196 [DAT](INFO): entering command mode
2023-04-05T20:37:09.396Z,1680727029.396 [DAT](INFO): DAT read: 

2023-04-05T20:37:09.397Z,1680727029.397 [DAT](INFO): DAT read: user:1>

2023-04-05T20:37:09.397Z,1680727029.397 [DAT](INFO): setting verbose to 3
2023-04-05T20:37:09.648Z,1680727029.648 [DAT](INFO): DAT read: user:1>

2023-04-05T20:37:09.649Z,1680727029.649 [DAT](INFO): DAT read: Verbose         | 3           

2023-04-05T20:37:09.650Z,1680727029.650 [DAT](INFO): set verbose to 3
2023-04-05T20:37:09.650Z,1680727029.650 [DAT](INFO): setting DatVerbose to 27440
2023-04-05T20:37:09.900Z,1680727029.900 [DAT](INFO): DAT read: user:2>

2023-04-05T20:37:09.901Z,1680727029.901 [DAT](INFO): DAT read: DatVerbose      | 27440       

2023-04-05T20:37:09.902Z,1680727029.902 [DAT](INFO): set DatVerbose to 27440
2023-04-05T20:37:09.902Z,1680727029.902 [DAT](INFO): setting transmit power to 8
2023-04-05T20:37:10.152Z,1680727030.152 [DAT](INFO): DAT read: user:3>

2023-04-05T20:37:10.153Z,1680727030.153 [DAT](INFO): DAT read: TxPower         | 8 (Max)     

2023-04-05T20:37:10.154Z,1680727030.154 [DAT](INFO): set transmit power to 8
2023-04-05T20:37:10.154Z,1680727030.154 [DAT](INFO): setting local address to 8
2023-04-05T20:37:10.404Z,1680727030.404 [DAT](INFO): DAT read: user:4>

2023-04-05T20:37:10.406Z,1680727030.406 [DAT](INFO): DAT read: LocalAddr       | 8           

2023-04-05T20:37:10.406Z,1680727030.406 [DAT](INFO): set local address to 8
2023-04-05T20:37:10.407Z,1680727030.407 [DAT](INFO): Setting time to: 20:37:10 And date to:4/5/2023
2023-04-05T20:37:10.657Z,1680727030.657 [DAT](INFO): DAT read: user:5>

2023-04-05T20:37:10.657Z,1680727030.657 [DAT](INFO): DAT read: Wed Apr 5, 2023  20:37:10  

2023-04-05T20:37:10.658Z,1680727030.658 [DAT](INFO): Local DAT time set to Wed Apr 5, 2023  20:37:10  

2023-04-05T20:37:11.212Z,1680727031.212 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:37:29.797Z,1680727049.797 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:38:31.655Z,1680727111.655 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5
2023-04-05T20:38:31.655Z,1680727111.655 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-04-05T20:38:31.666Z,1680727111.666 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-04-05T20:38:32.071Z,1680727112.071 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-04-05T20:38:32.071Z,1680727112.071 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5
2023-04-05T20:39:34.262Z,1680727174.262 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-04-05T20:39:34.262Z,1680727174.262 [Default:CheckIn:C.Wait] Stopped
2023-04-05T20:39:34.262Z,1680727174.262 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-04-05T20:39:34.262Z,1680727174.262 [Default:CheckIn:D] Running Loop=1
2023-04-05T20:39:34.669Z,1680727174.669 [Default:CheckIn:D] Stopped
2023-04-05T20:39:34.670Z,1680727174.670 [Default:CheckIn:E] Running Loop=1
2023-04-05T20:39:35.070Z,1680727175.070 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 10.708514 min 
2023-04-05T20:39:35.070Z,1680727175.070 [Default:CheckIn:E] Stopped
2023-04-05T20:39:35.071Z,1680727175.071 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-04-05T20:39:35.071Z,1680727175.071 [Default:CheckIn] Stopped
2023-04-05T20:39:35.071Z,1680727175.071 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-04-05T20:39:35.071Z,1680727175.071 [Default:CheckIn](INFO): Running loop #2
2023-04-05T20:39:35.071Z,1680727175.071 [Default:CheckIn] Running Loop=2
2023-04-05T20:39:35.071Z,1680727175.071 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-04-05T20:39:35.071Z,1680727175.071 [Default:CheckIn:Read_GPS] Running Loop=1
2023-04-05T20:40:10.525Z,1680727210.525 [DAT](INFO): DAT read: user:6>Lowpower

2023-04-05T20:40:10.525Z,1680727210.525 [DAT](DEBUG): Re-entering command mode due to deviceResponse_: user:6>Lowpower

2023-04-05T20:40:32.888Z,1680727232.888 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204032.00,A,3648.17462,N,12147.28805,W,0.058,60.26,050423,,,A*4D
2023-04-05T20:40:32.891Z,1680727232.891 [NAL9602](INFO): GPS fix at 20230405T204032: (36.802910, -121.788134)
2023-04-05T20:40:32.957Z,1680727232.957 [Default:CheckIn:Read_GPS] Stopped
2023-04-05T20:40:32.957Z,1680727232.957 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-04-05T20:40:35.128Z,1680727235.128 [DataOverHttps](INFO): Sending 224 bytes from file Logs/20230405T202317/Courier0007.lzma
2023-04-05T20:40:36.130Z,1680727236.130 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Courier0007.lzma.bak
2023-04-05T20:40:36.130Z,1680727236.130 [DataOverHttps](IMPORTANT): SBD MOMSN=18035427, MTMSN=20230405T204035
2023-04-05T20:40:43.884Z,1680727243.884 [DataOverHttps](INFO): Received command: ibit
2023-04-05T20:40:43.948Z,1680727243.948 [CommandExec](IMPORTANT): got command ibit
2023-04-05T20:40:44.296Z,1680727244.296 [IBIT](IMPORTANT): Beginning Initiated BIT
2023-04-05T20:40:44.296Z,1680727244.296 [IBIT](IMPORTANT): Beginning control surface checks.
2023-04-05T20:40:44.299Z,1680727244.299 [CBIT](IMPORTANT): Beginning ground fault scan
2023-04-05T20:40:45.897Z,1680727245.897 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204045.00,A,3648.17369,N,12147.28638,W,0.175,60.26,050423,,,A*4F
2023-04-05T20:40:45.899Z,1680727245.899 [NAL9602](INFO): GPS fix at 20230405T204045: (36.802895, -121.788106)
2023-04-05T20:40:48.840Z,1680727248.840 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204048.00,A,3648.17370,N,12147.28620,W,0.097,60.26,050423,,,A*4E
2023-04-05T20:40:48.842Z,1680727248.842 [NAL9602](INFO): GPS fix at 20230405T204048: (36.802895, -121.788103)
2023-04-05T20:40:51.991Z,1680727251.991 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204051.00,A,3648.17368,N,12147.28587,W,0.428,60.26,050423,,,A*41
2023-04-05T20:40:51.993Z,1680727251.993 [NAL9602](INFO): GPS fix at 20230405T204051: (36.802895, -121.788098)
2023-04-05T20:40:52.812Z,1680727252.812 [DataOverHttps](INFO): Sending 316 bytes from file Logs/20230405T202317/Express0008.lzma
2023-04-05T20:40:53.813Z,1680727253.813 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Express0008.lzma.bak
2023-04-05T20:40:53.814Z,1680727253.814 [DataOverHttps](INFO): SBD MOMSN=18035431
2023-04-05T20:40:54.889Z,1680727254.889 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204054.00,A,3648.17371,N,12147.28551,W,0.058,60.26,050423,,,A*44
2023-04-05T20:40:54.891Z,1680727254.891 [NAL9602](INFO): GPS fix at 20230405T204054: (36.802895, -121.788092)
2023-04-05T20:40:55.686Z,1680727255.686 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.004474
CHAN A1 (24V): -0.002386
CHAN A2 (12V): 0.000176
CHAN A3 (5V): 0.000598
CHAN B0 (3.3V): 0.000861
CHAN B1 (3.15aV): -0.000147
CHAN B2 (3.15bV): 0.000740
CHAN B3 (GND): 0.000819
OPEN: 0.004947
Full Scale: +/- 1 mA
2023-04-05T20:40:58.055Z,1680727258.055 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204057.00,A,3648.17385,N,12147.28560,W,0.078,60.26,050423,,,A*4C
2023-04-05T20:40:58.058Z,1680727258.058 [NAL9602](INFO): GPS fix at 20230405T204057: (36.802898, -121.788093)
2023-04-05T20:41:00.879Z,1680727260.879 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204100.00,A,3648.17398,N,12147.28584,W,0.039,60.26,050423,,,A*4C
2023-04-05T20:41:00.882Z,1680727260.882 [NAL9602](INFO): GPS fix at 20230405T204100: (36.802900, -121.788097)
2023-04-05T20:41:03.723Z,1680727263.723 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204103.00,A,3648.17414,N,12147.28616,W,0.214,60.26,050423,,,A*49
2023-04-05T20:41:03.726Z,1680727263.726 [NAL9602](INFO): GPS fix at 20230405T204103: (36.802902, -121.788103)
2023-04-05T20:41:06.944Z,1680727266.944 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204106.00,A,3648.17420,N,12147.28650,W,0.136,60.26,050423,,,A*4A
2023-04-05T20:41:06.946Z,1680727266.946 [NAL9602](INFO): GPS fix at 20230405T204106: (36.802903, -121.788108)
2023-04-05T20:41:09.776Z,1680727269.776 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204109.00,A,3648.17422,N,12147.28675,W,0.078,60.26,050423,,,A*4B
2023-04-05T20:41:09.778Z,1680727269.778 [NAL9602](INFO): GPS fix at 20230405T204109: (36.802904, -121.788112)
2023-04-05T20:41:10.095Z,1680727270.095 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20230405T202317/Courier0010.lzma
2023-04-05T20:41:11.098Z,1680727271.098 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Courier0010.lzma.bak
2023-04-05T20:41:11.098Z,1680727271.098 [DataOverHttps](INFO): SBD MOMSN=18035436
2023-04-05T20:41:13.014Z,1680727273.014 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204112.00,A,3648.17423,N,12147.28664,W,0.156,60.26,050423,,,A*4D
2023-04-05T20:41:13.016Z,1680727273.016 [NAL9602](INFO): GPS fix at 20230405T204112: (36.802904, -121.788111)
2023-04-05T20:41:15.859Z,1680727275.859 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204115.00,A,3648.17428,N,12147.28665,W,0.097,60.26,050423,,,A*4C
2023-04-05T20:41:15.866Z,1680727275.866 [NAL9602](INFO): GPS fix at 20230405T204115: (36.802905, -121.788111)
2023-04-05T20:41:19.063Z,1680727279.063 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204118.00,A,3648.17434,N,12147.28667,W,0.078,60.26,050423,,,A*4F
2023-04-05T20:41:19.066Z,1680727279.066 [NAL9602](INFO): GPS fix at 20230405T204118: (36.802906, -121.788111)
2023-04-05T20:41:21.893Z,1680727281.893 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204121.00,A,3648.17440,N,12147.28679,W,0.117,60.26,050423,,,A*41
2023-04-05T20:41:21.895Z,1680727281.895 [NAL9602](INFO): GPS fix at 20230405T204121: (36.802907, -121.788113)
2023-04-05T20:41:24.731Z,1680727284.731 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204124.00,A,3648.17439,N,12147.28697,W,0.117,60.26,050423,,,A*4A
2023-04-05T20:41:24.733Z,1680727284.733 [NAL9602](INFO): GPS fix at 20230405T204124: (36.802906, -121.788116)
2023-04-05T20:41:27.500Z,1680727287.500 [DataOverHttps](INFO): Sending 246 bytes from file Logs/20230405T202317/Express0011.lzma
2023-04-05T20:41:27.949Z,1680727287.949 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204127.00,A,3648.17450,N,12147.28685,W,0.078,60.26,050423,,,A*4D
2023-04-05T20:41:27.951Z,1680727287.951 [NAL9602](INFO): GPS fix at 20230405T204127: (36.802908, -121.788114)
2023-04-05T20:41:28.502Z,1680727288.502 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Express0011.lzma.bak
2023-04-05T20:41:28.502Z,1680727288.502 [DataOverHttps](INFO): SBD MOMSN=18035438
2023-04-05T20:41:30.780Z,1680727290.780 [DVL_micro](ERROR): only read 3 of 4 data items
2023-04-05T20:41:30.780Z,1680727290.780 [DVL_micro](ERROR): Failed to parse:
:BI,-0160,+01135,+00000,I
2023-04-05T20:41:30.782Z,1680727290.782 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204130.00,A,3648.17456,N,12147.28651,W,0.117,60.26,050423,,,A*4C
2023-04-05T20:41:30.785Z,1680727290.785 [NAL9602](INFO): GPS fix at 20230405T204130: (36.802909, -121.788109)
2023-04-05T20:41:34.007Z,1680727294.007 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204133.00,A,3648.17452,N,12147.28614,W,0.078,60.26,050423,,,A*42
2023-04-05T20:41:34.010Z,1680727294.010 [NAL9602](INFO): GPS fix at 20230405T204133: (36.802909, -121.788102)
2023-04-05T20:41:36.834Z,1680727296.834 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204136.00,A,3648.17457,N,12147.28550,W,0.039,60.26,050423,,,A*44
2023-04-05T20:41:36.837Z,1680727296.837 [NAL9602](INFO): GPS fix at 20230405T204136: (36.802909, -121.788092)
2023-04-05T20:41:39.680Z,1680727299.680 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204139.00,A,3648.17446,N,12147.28491,W,0.019,60.26,050423,,,A*45
2023-04-05T20:41:39.682Z,1680727299.682 [NAL9602](INFO): GPS fix at 20230405T204139: (36.802908, -121.788082)
2023-04-05T20:41:42.935Z,1680727302.935 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204142.00,A,3648.17440,N,12147.28433,W,0.039,60.26,050423,,,A*45
2023-04-05T20:41:42.938Z,1680727302.938 [NAL9602](INFO): GPS fix at 20230405T204142: (36.802907, -121.788072)
2023-04-05T20:41:45.795Z,1680727305.795 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204145.00,A,3648.17443,N,12147.28371,W,0.136,60.26,050423,,,A*4E
2023-04-05T20:41:45.798Z,1680727305.798 [NAL9602](INFO): GPS fix at 20230405T204145: (36.802907, -121.788062)
2023-04-05T20:41:49.015Z,1680727309.015 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204148.00,A,3648.17445,N,12147.28332,W,0.156,60.26,050423,,,A*44
2023-04-05T20:41:49.018Z,1680727309.018 [NAL9602](INFO): GPS fix at 20230405T204148: (36.802908, -121.788055)
2023-04-05T20:41:51.852Z,1680727311.852 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204151.00,A,3648.17455,N,12147.28313,W,0.117,60.26,050423,,,A*4B
2023-04-05T20:41:51.854Z,1680727311.854 [NAL9602](INFO): GPS fix at 20230405T204151: (36.802909, -121.788052)
2023-04-05T20:41:54.703Z,1680727314.703 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204154.00,A,3648.17457,N,12147.28292,W,0.078,60.26,050423,,,A*4C
2023-04-05T20:41:54.705Z,1680727314.705 [NAL9602](INFO): GPS fix at 20230405T204154: (36.802909, -121.788049)
2023-04-05T20:41:57.967Z,1680727317.967 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204157.00,A,3648.17465,N,12147.28292,W,0.078,60.26,050423,,,A*4E
2023-04-05T20:41:57.970Z,1680727317.970 [NAL9602](INFO): GPS fix at 20230405T204157: (36.802911, -121.788049)
2023-04-05T20:42:00.806Z,1680727320.806 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204200.00,A,3648.17471,N,12147.28285,W,0.136,60.26,050423,,,A*47
2023-04-05T20:42:00.808Z,1680727320.808 [NAL9602](INFO): GPS fix at 20230405T204200: (36.802912, -121.788048)
2023-04-05T20:42:04.061Z,1680727324.061 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204203.00,A,3648.17476,N,12147.28272,W,0.078,60.26,050423,,,A*40
2023-04-05T20:42:04.072Z,1680727324.072 [NAL9602](INFO): GPS fix at 20230405T204203: (36.802913, -121.788045)
2023-04-05T20:42:06.844Z,1680727326.844 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204206.00,A,3648.17470,N,12147.28272,W,0.039,60.26,050423,,,A*46
2023-04-05T20:42:06.846Z,1680727326.846 [NAL9602](INFO): GPS fix at 20230405T204206: (36.802912, -121.788045)
2023-04-05T20:42:09.675Z,1680727329.675 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204209.00,A,3648.17449,N,12147.28298,W,0.039,60.26,050423,,,A*47
2023-04-05T20:42:09.677Z,1680727329.677 [NAL9602](INFO): GPS fix at 20230405T204209: (36.802908, -121.788050)
2023-04-05T20:42:12.903Z,1680727332.903 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204212.00,A,3648.17449,N,12147.28294,W,0.039,60.26,050423,,,A*41
2023-04-05T20:42:12.905Z,1680727332.905 [NAL9602](INFO): GPS fix at 20230405T204212: (36.802908, -121.788049)
2023-04-05T20:42:15.747Z,1680727335.747 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204215.00,A,3648.17448,N,12147.28320,W,0.058,60.26,050423,,,A*4E
2023-04-05T20:42:15.750Z,1680727335.750 [NAL9602](INFO): GPS fix at 20230405T204215: (36.802908, -121.788053)
2023-04-05T20:42:18.963Z,1680727338.963 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204218.00,A,3648.17443,N,12147.28358,W,0.078,60.26,050423,,,A*45
2023-04-05T20:42:18.965Z,1680727338.965 [NAL9602](INFO): GPS fix at 20230405T204218: (36.802907, -121.788060)
2023-04-05T20:42:21.865Z,1680727341.865 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204221.00,A,3648.17435,N,12147.28389,W,0.019,60.26,050423,,,A*45
2023-04-05T20:42:21.867Z,1680727341.867 [NAL9602](INFO): GPS fix at 20230405T204221: (36.802906, -121.788065)
2023-04-05T20:42:25.023Z,1680727345.023 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204224.00,A,3648.17428,N,12147.28421,W,0.136,60.26,050423,,,A*45
2023-04-05T20:42:25.026Z,1680727345.026 [NAL9602](INFO): GPS fix at 20230405T204224: (36.802905, -121.788070)
2023-04-05T20:42:27.851Z,1680727347.851 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204227.00,A,3648.17427,N,12147.28433,W,0.039,60.26,050423,,,A*44
2023-04-05T20:42:27.853Z,1680727347.853 [NAL9602](INFO): GPS fix at 20230405T204227: (36.802904, -121.788072)
2023-04-05T20:42:30.699Z,1680727350.699 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204230.00,A,3648.17419,N,12147.28420,W,0.136,60.26,050423,,,A*43
2023-04-05T20:42:30.702Z,1680727350.702 [NAL9602](INFO): GPS fix at 20230405T204230: (36.802903, -121.788070)
2023-04-05T20:42:33.912Z,1680727353.912 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204233.00,A,3648.17414,N,12147.28406,W,0.156,60.26,050423,,,A*4F
2023-04-05T20:42:33.914Z,1680727353.914 [NAL9602](INFO): GPS fix at 20230405T204233: (36.802902, -121.788068)
2023-04-05T20:42:35.558Z,1680727355.558 [IBIT](FAULT): Error acquiring IBIT communications status. Timeout expired.
2023-04-05T20:42:36.020Z,1680727356.020 [IBIT](FAULT): Warning: Battery Data not active. Expected only when running primaries. Threshold checking not active.
2023-04-05T20:42:36.406Z,1680727356.406 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2023-04-05T20:42:36.407Z,1680727356.407 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2023-04-05T20:42:36.407Z,1680727356.407 [IBIT](IMPORTANT): Pressure:9.873557 PSI
2023-04-05T20:42:36.408Z,1680727356.408 [IBIT](IMPORTANT): Humidity:15.321694 %
2023-04-05T20:42:36.763Z,1680727356.763 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204236.00,A,3648.17407,N,12147.28392,W,0.058,60.26,050423,,,A*4D
2023-04-05T20:42:36.766Z,1680727356.766 [NAL9602](INFO): GPS fix at 20230405T204236: (36.802901, -121.788065)
2023-04-05T20:42:36.783Z,1680727356.783 [IBIT](IMPORTANT): Vehicle Pitch:-0.500576 degrees
2023-04-05T20:42:36.783Z,1680727356.783 [IBIT](IMPORTANT): Vehicle  Roll:-3.347627 degrees
2023-04-05T20:42:36.783Z,1680727356.783 [IBIT](IMPORTANT): Vehicle  Heading:85.512794 degrees
2023-04-05T20:42:37.233Z,1680727357.233 [IBIT](IMPORTANT): surfaceThreshold: 1.500000 m
2023-04-05T20:42:37.234Z,1680727357.234 [IBIT](IMPORTANT): buoyancyNeutral: 341.374115 cc
2023-04-05T20:42:37.234Z,1680727357.234 [IBIT](IMPORTANT): massDefault: 3.250000 cm
2023-04-05T20:42:37.234Z,1680727357.234 [IBIT](IMPORTANT): stopDepth: 265.000000 m
2023-04-05T20:42:37.235Z,1680727357.235 [IBIT](IMPORTANT): abortDepth: 300.000000 m
2023-04-05T20:42:37.235Z,1680727357.235 [IBIT](IMPORTANT): IBIT FAILED
2023-04-05T20:42:37.564Z,1680727357.564 [Default:CheckIn:Read_Iridium] Stopped
2023-04-05T20:42:37.564Z,1680727357.564 [Default:CheckIn:C.Wait] Running Loop=1
2023-04-05T20:42:37.564Z,1680727357.564 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-04-05T20:43:09.461Z,1680727389.461 [NAL9602](INFO): Not Powering down - fast GPS
2023-04-05T20:45:13.929Z,1680727513.929 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:45:19.582Z,1680727519.582 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:45:34.530Z,1680727534.530 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:45:49.478Z,1680727549.478 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:46:04.426Z,1680727564.426 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:46:18.970Z,1680727578.970 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:46:33.523Z,1680727593.523 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:46:48.488Z,1680727608.488 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:47:03.007Z,1680727623.007 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:47:17.954Z,1680727637.954 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:47:32.902Z,1680727652.902 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T20:47:38.193Z,1680727658.193 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-04-05T20:47:38.193Z,1680727658.193 [Default:CheckIn:C.Wait] Stopped
2023-04-05T20:47:38.193Z,1680727658.193 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-04-05T20:47:38.193Z,1680727658.193 [Default:CheckIn:D] Running Loop=1
2023-04-05T20:47:38.573Z,1680727658.573 [Default:CheckIn:D] Stopped
2023-04-05T20:47:38.574Z,1680727658.574 [Default:CheckIn:E] Running Loop=1
2023-04-05T20:47:38.981Z,1680727658.981 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 18.773580 min 
2023-04-05T20:47:38.981Z,1680727658.981 [Default:CheckIn:E] Stopped
2023-04-05T20:47:38.981Z,1680727658.981 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-04-05T20:47:38.981Z,1680727658.981 [Default:CheckIn] Stopped
2023-04-05T20:47:38.981Z,1680727658.981 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-04-05T20:47:38.981Z,1680727658.981 [Default:CheckIn](INFO): Running loop #3
2023-04-05T20:47:38.981Z,1680727658.981 [Default:CheckIn] Running Loop=3
2023-04-05T20:47:38.981Z,1680727658.981 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-04-05T20:47:38.981Z,1680727658.981 [Default:CheckIn:Read_GPS] Running Loop=1
2023-04-05T20:47:40.986Z,1680727660.986 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204740.00,A,3648.17705,N,12147.27443,W,0.058,60.26,050423,,,A*4C
2023-04-05T20:47:40.998Z,1680727660.998 [NAL9602](INFO): GPS fix at 20230405T204740: (36.802951, -121.787907)
2023-04-05T20:47:41.010Z,1680727661.010 [Default:CheckIn:Read_GPS] Stopped
2023-04-05T20:47:41.010Z,1680727661.010 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-04-05T20:47:47.991Z,1680727667.991 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20230405T202317/Courier0013.lzma
2023-04-05T20:47:48.993Z,1680727668.993 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Courier0013.lzma.bak
2023-04-05T20:47:48.994Z,1680727668.994 [DataOverHttps](INFO): SBD MOMSN=18035454
2023-04-05T20:47:53.576Z,1680727673.576 [NAL9602](INFO): SBD MO Status=0, MOMSN=14713, MT Status=0, MTMSN=0
2023-04-05T20:47:53.576Z,1680727673.576 [NAL9602](INFO): No messages in MT queue
2023-04-05T20:48:07.700Z,1680727687.700 [DataOverHttps](INFO): Sending 645 bytes from file Logs/20230405T202317/Express0014.lzma
2023-04-05T20:48:08.702Z,1680727688.702 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Express0014.lzma.bak
2023-04-05T20:48:08.702Z,1680727688.702 [DataOverHttps](INFO): SBD MOMSN=18035462
2023-04-05T20:48:09.738Z,1680727689.738 [Default:CheckIn:Read_Iridium] Stopped
2023-04-05T20:48:09.738Z,1680727689.738 [Default:CheckIn:C.Wait] Running Loop=1
2023-04-05T20:48:09.738Z,1680727689.738 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-04-05T20:48:24.278Z,1680727704.278 [NAL9602](INFO): Not Powering down - fast GPS
2023-04-05T20:52:36.495Z,1680727956.495 [DVL_micro](ERROR): Failed to parse:
:WI,+02006,-00080,+00309,+00000,A
2023-04-05T20:53:10.431Z,1680727990.431 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-04-05T20:53:10.431Z,1680727990.431 [Default:CheckIn:C.Wait] Stopped
2023-04-05T20:53:10.432Z,1680727990.432 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-04-05T20:53:10.432Z,1680727990.432 [Default:CheckIn:D] Running Loop=1
2023-04-05T20:53:10.840Z,1680727990.840 [Default:CheckIn:D] Stopped
2023-04-05T20:53:10.840Z,1680727990.840 [Default:CheckIn:E] Running Loop=1
2023-04-05T20:53:11.241Z,1680727991.241 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 24.311361 min 
2023-04-05T20:53:11.241Z,1680727991.241 [Default:CheckIn:E] Stopped
2023-04-05T20:53:11.241Z,1680727991.241 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-04-05T20:53:11.241Z,1680727991.241 [Default:CheckIn] Stopped
2023-04-05T20:53:11.241Z,1680727991.241 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-04-05T20:53:11.241Z,1680727991.241 [Default:CheckIn](INFO): Running loop #4
2023-04-05T20:53:11.241Z,1680727991.241 [Default:CheckIn] Running Loop=4
2023-04-05T20:53:11.241Z,1680727991.241 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-04-05T20:53:11.242Z,1680727991.242 [Default:CheckIn:Read_GPS] Running Loop=1
2023-04-05T20:53:13.252Z,1680727993.252 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,205312.00,A,3648.14800,N,12147.25539,W,2.197,189.43,050423,,,A*7C
2023-04-05T20:53:13.254Z,1680727993.254 [NAL9602](INFO): GPS fix at 20230405T205312: (36.802467, -121.787590)
2023-04-05T20:53:13.284Z,1680727993.284 [Default:CheckIn:Read_GPS] Stopped
2023-04-05T20:53:13.284Z,1680727993.284 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-04-05T20:53:21.283Z,1680728001.283 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20230405T202317/Courier0016.lzma
2023-04-05T20:53:22.286Z,1680728002.286 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Courier0016.lzma.bak
2023-04-05T20:53:22.286Z,1680728002.286 [DataOverHttps](INFO): SBD MOMSN=18035486
2023-04-05T20:53:37.905Z,1680728017.905 [NAL9602](INFO): SBD MO Status=0, MOMSN=14714, MT Status=0, MTMSN=0
2023-04-05T20:53:37.905Z,1680728017.905 [NAL9602](INFO): No messages in MT queue
2023-04-05T20:53:38.223Z,1680728018.223 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20230405T202317/Express0017.lzma
2023-04-05T20:53:39.226Z,1680728019.226 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Express0017.lzma.bak
2023-04-05T20:53:39.226Z,1680728019.226 [DataOverHttps](INFO): SBD MOMSN=18035489
2023-04-05T20:53:40.352Z,1680728020.352 [Default:CheckIn:Read_Iridium] Stopped
2023-04-05T20:53:40.352Z,1680728020.352 [Default:CheckIn:C.Wait] Running Loop=1
2023-04-05T20:53:40.352Z,1680728020.352 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-04-05T20:54:08.601Z,1680728048.601 [NAL9602](INFO): Not Powering down - fast GPS
2023-04-05T20:54:28.041Z,1680728068.041 [BPC1](INFO): Calculating totals. Valid battery stick count: 48. Valid reserve battery stick count: 5.
2023-04-05T20:54:28.044Z,1680728068.044 [BPC1](ERROR): Failed to receive data from all sticks prior to timeout. Will not retry this scan cycle.
2023-04-05T20:55:32.305Z,1680728132.305 [DVL_micro](ERROR): Failed to parse:
:.99,+9999.99,+9999.99,+9999.99
2023-04-05T20:57:04.046Z,1680728224.046 [DVL_micro](ERROR): Failed to parse:
:WI,+01462,-00295,+00527,+00000,A
2023-04-05T20:58:40.980Z,1680728320.980 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-04-05T20:58:40.980Z,1680728320.980 [Default:CheckIn:C.Wait] Stopped
2023-04-05T20:58:40.980Z,1680728320.980 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-04-05T20:58:40.980Z,1680728320.980 [Default:CheckIn:D] Running Loop=1
2023-04-05T20:58:41.381Z,1680728321.381 [Default:CheckIn:D] Stopped
2023-04-05T20:58:41.381Z,1680728321.381 [Default:CheckIn:E] Running Loop=1
2023-04-05T20:58:41.789Z,1680728321.789 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 29.820369 min 
2023-04-05T20:58:41.789Z,1680728321.789 [Default:CheckIn:E] Stopped
2023-04-05T20:58:41.789Z,1680728321.789 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-04-05T20:58:41.789Z,1680728321.789 [Default:CheckIn] Stopped
2023-04-05T20:58:41.789Z,1680728321.789 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-04-05T20:58:41.789Z,1680728321.789 [Default:CheckIn](INFO): Running loop #5
2023-04-05T20:58:41.789Z,1680728321.789 [Default:CheckIn] Running Loop=5
2023-04-05T20:58:41.789Z,1680728321.789 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-04-05T20:58:41.790Z,1680728321.790 [Default:CheckIn:Read_GPS] Running Loop=1
2023-04-05T20:58:43.805Z,1680728323.805 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,205843.00,A,3648.14038,N,12147.22475,W,0.097,56.90,050423,,,D*45
2023-04-05T20:58:43.807Z,1680728323.807 [NAL9602](INFO): GPS fix at 20230405T205843: (36.802340, -121.787079)
2023-04-05T20:58:43.846Z,1680728323.846 [Default:CheckIn:Read_GPS] Stopped
2023-04-05T20:58:43.847Z,1680728323.847 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-04-05T20:58:51.403Z,1680728331.403 [DataOverHttps](INFO): Sending 203 bytes from file Logs/20230405T202317/Courier0019.lzma
2023-04-05T20:58:52.406Z,1680728332.406 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Courier0019.lzma.bak
2023-04-05T20:58:52.406Z,1680728332.406 [DataOverHttps](INFO): SBD MOMSN=18035500
2023-04-05T20:58:57.931Z,1680728337.931 [NAL9602](INFO): SBD MO Status=0, MOMSN=14715, MT Status=0, MTMSN=0
2023-04-05T20:58:57.931Z,1680728337.931 [NAL9602](INFO): No messages in MT queue
2023-04-05T20:59:08.327Z,1680728348.327 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20230405T202317/Express0020.lzma
2023-04-05T20:59:09.330Z,1680728349.330 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Express0020.lzma.bak
2023-04-05T20:59:09.330Z,1680728349.330 [DataOverHttps](INFO): SBD MOMSN=18035503
2023-04-05T20:59:10.471Z,1680728350.471 [Default:CheckIn:Read_Iridium] Stopped
2023-04-05T20:59:10.471Z,1680728350.471 [Default:CheckIn:C.Wait] Running Loop=1
2023-04-05T20:59:10.471Z,1680728350.471 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-04-05T20:59:28.642Z,1680728368.642 [NAL9602](INFO): Not Powering down - fast GPS
2023-04-05T21:04:11.139Z,1680728651.139 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-04-05T21:04:11.139Z,1680728651.139 [Default:CheckIn:C.Wait] Stopped
2023-04-05T21:04:11.139Z,1680728651.139 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-04-05T21:04:11.139Z,1680728651.139 [Default:CheckIn:D] Running Loop=1
2023-04-05T21:04:11.548Z,1680728651.548 [Default:CheckIn:D] Stopped
2023-04-05T21:04:11.548Z,1680728651.548 [Default:CheckIn:E] Running Loop=1
2023-04-05T21:04:11.949Z,1680728651.949 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 35.323149 min 
2023-04-05T21:04:11.950Z,1680728651.950 [Default:CheckIn:E] Stopped
2023-04-05T21:04:11.950Z,1680728651.950 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-04-05T21:04:11.950Z,1680728651.950 [Default:CheckIn] Stopped
2023-04-05T21:04:11.950Z,1680728651.950 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-04-05T21:04:11.950Z,1680728651.950 [Default:CheckIn](INFO): Running loop #6
2023-04-05T21:04:11.950Z,1680728651.950 [Default:CheckIn] Running Loop=6
2023-04-05T21:04:11.950Z,1680728651.950 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-04-05T21:04:11.950Z,1680728651.950 [Default:CheckIn:Read_GPS] Running Loop=1
2023-04-05T21:04:13.960Z,1680728653.960 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,210413.00,A,3648.15065,N,12147.22167,W,0.058,56.58,050423,,,D*40
2023-04-05T21:04:13.962Z,1680728653.962 [NAL9602](INFO): GPS fix at 20230405T210413: (36.802511, -121.787028)
2023-04-05T21:04:13.999Z,1680728653.999 [Default:CheckIn:Read_GPS] Stopped
2023-04-05T21:04:13.999Z,1680728653.999 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-04-05T21:04:24.823Z,1680728664.823 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20230405T202317/Courier0022.lzma
2023-04-05T21:04:25.826Z,1680728665.826 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Courier0022.lzma.bak
2023-04-05T21:04:25.826Z,1680728665.826 [DataOverHttps](INFO): SBD MOMSN=18035507
2023-04-05T21:04:42.017Z,1680728682.017 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20230405T202317/Express0023.lzma
2023-04-05T21:04:43.018Z,1680728683.018 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Express0023.lzma.bak
2023-04-05T21:04:43.018Z,1680728683.018 [DataOverHttps](INFO): SBD MOMSN=18035510
2023-04-05T21:04:44.349Z,1680728684.349 [Default:CheckIn:Read_Iridium] Stopped
2023-04-05T21:04:44.349Z,1680728684.349 [Default:CheckIn:C.Wait] Running Loop=1
2023-04-05T21:04:44.349Z,1680728684.349 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-04-05T21:05:32.411Z,1680728732.411 [NAL9602](INFO): SBD MO Status=2, MOMSN=14716, MT Status=2, MTMSN=0
2023-04-05T21:05:32.411Z,1680728732.411 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-04-05T21:06:07.187Z,1680728767.187 [NAL9602](INFO): SBD MO Status=2, MOMSN=14716, MT Status=2, MTMSN=0
2023-04-05T21:06:07.187Z,1680728767.187 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-04-05T21:06:29.395Z,1680728789.395 [NAL9602](INFO): SBD MO Status=0, MOMSN=14716, MT Status=0, MTMSN=0
2023-04-05T21:06:29.395Z,1680728789.395 [NAL9602](INFO): No messages in MT queue
2023-04-05T21:07:00.093Z,1680728820.093 [NAL9602](INFO): Not Powering down - fast GPS
2023-04-05T21:09:44.991Z,1680728984.991 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-04-05T21:09:44.991Z,1680728984.991 [Default:CheckIn:C.Wait] Stopped
2023-04-05T21:09:44.991Z,1680728984.991 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-04-05T21:09:44.992Z,1680728984.992 [Default:CheckIn:D] Running Loop=1
2023-04-05T21:09:45.400Z,1680728985.400 [Default:CheckIn:D] Stopped
2023-04-05T21:09:45.400Z,1680728985.400 [Default:CheckIn:E] Running Loop=1
2023-04-05T21:09:45.815Z,1680728985.815 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 40.887358 min 
2023-04-05T21:09:45.815Z,1680728985.815 [Default:CheckIn:E] Stopped
2023-04-05T21:09:45.816Z,1680728985.816 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-04-05T21:09:45.816Z,1680728985.816 [Default:CheckIn] Stopped
2023-04-05T21:09:45.816Z,1680728985.816 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-04-05T21:09:45.816Z,1680728985.816 [Default:CheckIn](INFO): Running loop #7
2023-04-05T21:09:45.816Z,1680728985.816 [Default:CheckIn] Running Loop=7
2023-04-05T21:09:45.816Z,1680728985.816 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-04-05T21:09:45.816Z,1680728985.816 [Default:CheckIn:Read_GPS] Running Loop=1
2023-04-05T21:09:46.606Z,1680728986.606 [DVL_micro](ERROR): Failed to parse:
:SA,+01.01,-05.63,188.2
2023-04-05T21:09:47.810Z,1680728987.810 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,210947.00,A,3648.14959,N,12147.22243,W,0.097,56.58,050423,,,D*4D
2023-04-05T21:09:47.812Z,1680728987.812 [NAL9602](INFO): GPS fix at 20230405T210947: (36.802493, -121.787041)
2023-04-05T21:09:47.823Z,1680728987.823 [Default:CheckIn:Read_GPS] Stopped
2023-04-05T21:09:47.823Z,1680728987.823 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-04-05T21:09:55.059Z,1680728995.059 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20230405T202317/Courier0025.lzma
2023-04-05T21:09:56.062Z,1680728996.062 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Courier0025.lzma.bak
2023-04-05T21:09:56.062Z,1680728996.062 [DataOverHttps](INFO): SBD MOMSN=18035520
2023-04-05T21:10:07.255Z,1680729007.255 [NAL9602](INFO): SBD MO Status=2, MOMSN=14717, MT Status=2, MTMSN=0
2023-04-05T21:10:07.273Z,1680729007.273 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-04-05T21:10:15.075Z,1680729015.075 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20230405T202317/Express0026.lzma
2023-04-05T21:10:16.078Z,1680729016.078 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Express0026.lzma.bak
2023-04-05T21:10:16.078Z,1680729016.078 [DataOverHttps](INFO): SBD MOMSN=18035523
2023-04-05T21:10:17.398Z,1680729017.398 [Default:CheckIn:Read_Iridium] Stopped
2023-04-05T21:10:17.398Z,1680729017.398 [Default:CheckIn:C.Wait] Running Loop=1
2023-04-05T21:10:17.398Z,1680729017.398 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-04-05T21:10:36.407Z,1680729036.407 [NAL9602](INFO): SBD MO Status=2, MOMSN=14717, MT Status=2, MTMSN=0
2023-04-05T21:10:36.407Z,1680729036.407 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-04-05T21:10:53.774Z,1680729053.774 [NAL9602](INFO): SBD MO Status=2, MOMSN=14717, MT Status=2, MTMSN=0
2023-04-05T21:10:53.775Z,1680729053.775 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-04-05T21:11:10.752Z,1680729070.752 [NAL9602](INFO): SBD MO Status=0, MOMSN=14717, MT Status=0, MTMSN=0
2023-04-05T21:11:10.752Z,1680729070.752 [NAL9602](INFO): No messages in MT queue
2023-04-05T21:11:41.455Z,1680729101.455 [NAL9602](INFO): Not Powering down - fast GPS
2023-04-05T21:15:07.903Z,1680729307.903 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-04-05T21:15:07.904Z,1680729307.904 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+21.6,0000.0,14
2023-04-05T21:15:18.025Z,1680729318.025 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-04-05T21:15:18.025Z,1680729318.025 [Default:CheckIn:C.Wait] Stopped
2023-04-05T21:15:18.025Z,1680729318.025 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-04-05T21:15:18.025Z,1680729318.025 [Default:CheckIn:D] Running Loop=1
2023-04-05T21:15:18.412Z,1680729318.412 [Default:CheckIn:D] Stopped
2023-04-05T21:15:18.412Z,1680729318.412 [Default:CheckIn:E] Running Loop=1
2023-04-05T21:15:18.816Z,1680729318.816 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 46.437549 min 
2023-04-05T21:15:18.816Z,1680729318.816 [Default:CheckIn:E] Stopped
2023-04-05T21:15:18.816Z,1680729318.816 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-04-05T21:15:18.816Z,1680729318.816 [Default:CheckIn] Stopped
2023-04-05T21:15:18.816Z,1680729318.816 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-04-05T21:15:18.816Z,1680729318.816 [Default:CheckIn](INFO): Running loop #8
2023-04-05T21:15:18.817Z,1680729318.817 [Default:CheckIn] Running Loop=8
2023-04-05T21:15:18.817Z,1680729318.817 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-04-05T21:15:18.817Z,1680729318.817 [Default:CheckIn:Read_GPS] Running Loop=1
2023-04-05T21:15:20.824Z,1680729320.824 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,211520.00,A,3648.14935,N,12147.21992,W,0.058,56.58,050423,,,D*4C
2023-04-05T21:15:20.826Z,1680729320.826 [NAL9602](INFO): GPS fix at 20230405T211520: (36.802489, -121.786999)
2023-04-05T21:15:20.842Z,1680729320.842 [Default:CheckIn:Read_GPS] Stopped
2023-04-05T21:15:20.842Z,1680729320.842 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-04-05T21:15:28.619Z,1680729328.619 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20230405T202317/Courier0028.lzma
2023-04-05T21:15:29.622Z,1680729329.622 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Courier0028.lzma.bak
2023-04-05T21:15:29.622Z,1680729329.622 [DataOverHttps](INFO): SBD MOMSN=18035527
2023-04-05T21:15:31.331Z,1680729331.331 [NAL9602](INFO): SBD MO Status=0, MOMSN=14718, MT Status=0, MTMSN=0
2023-04-05T21:15:31.331Z,1680729331.331 [NAL9602](INFO): No messages in MT queue
2023-04-05T21:15:45.407Z,1680729345.407 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20230405T202317/Express0029.lzma
2023-04-05T21:15:46.410Z,1680729346.410 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Express0029.lzma.bak
2023-04-05T21:15:46.410Z,1680729346.410 [DataOverHttps](INFO): SBD MOMSN=18035530
2023-04-05T21:15:47.523Z,1680729347.523 [Default:CheckIn:Read_Iridium] Stopped
2023-04-05T21:15:47.524Z,1680729347.524 [Default:CheckIn:C.Wait] Running Loop=1
2023-04-05T21:15:47.524Z,1680729347.524 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-04-05T21:16:02.052Z,1680729362.052 [NAL9602](INFO): Not Powering down - fast GPS
2023-04-05T21:19:25.284Z,1680729565.284 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-04-05T21:19:25.284Z,1680729565.284 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+21.5,0000.,000
2023-04-05T21:20:48.169Z,1680729648.169 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-04-05T21:20:48.169Z,1680729648.169 [Default:CheckIn:C.Wait] Stopped
2023-04-05T21:20:48.169Z,1680729648.169 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-04-05T21:20:48.169Z,1680729648.169 [Default:CheckIn:D] Running Loop=1
2023-04-05T21:20:48.584Z,1680729648.584 [Default:CheckIn:D] Stopped
2023-04-05T21:20:48.584Z,1680729648.584 [Default:CheckIn:E] Running Loop=1
2023-04-05T21:20:48.967Z,1680729648.967 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 51.940149 min 
2023-04-05T21:20:48.967Z,1680729648.967 [Default:CheckIn:E] Stopped
2023-04-05T21:20:48.967Z,1680729648.967 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-04-05T21:20:48.967Z,1680729648.967 [Default:CheckIn] Stopped
2023-04-05T21:20:48.967Z,1680729648.967 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-04-05T21:20:48.968Z,1680729648.968 [Default:CheckIn](INFO): Running loop #9
2023-04-05T21:20:48.968Z,1680729648.968 [Default:CheckIn] Running Loop=9
2023-04-05T21:20:48.968Z,1680729648.968 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-04-05T21:20:48.968Z,1680729648.968 [Default:CheckIn:Read_GPS] Running Loop=1
2023-04-05T21:20:50.979Z,1680729650.979 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,212050.00,A,3648.14950,N,12147.22175,W,0.039,56.58,050423,,,D*4B
2023-04-05T21:20:50.982Z,1680729650.982 [NAL9602](INFO): GPS fix at 20230405T212050: (36.802492, -121.787029)
2023-04-05T21:20:50.993Z,1680729650.993 [Default:CheckIn:Read_GPS] Stopped
2023-04-05T21:20:50.993Z,1680729650.993 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-04-05T21:20:58.731Z,1680729658.731 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20230405T202317/Courier0031.lzma
2023-04-05T21:20:59.734Z,1680729659.734 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Courier0031.lzma.bak
2023-04-05T21:20:59.734Z,1680729659.734 [DataOverHttps](INFO): SBD MOMSN=18035574
2023-04-05T21:21:10.776Z,1680729670.776 [NAL9602](INFO): SBD MO Status=0, MOMSN=14719, MT Status=0, MTMSN=0
2023-04-05T21:21:10.776Z,1680729670.776 [NAL9602](INFO): No messages in MT queue
2023-04-05T21:21:15.531Z,1680729675.531 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20230405T202317/Express0032.lzma
2023-04-05T21:21:16.534Z,1680729676.534 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Express0032.lzma.bak
2023-04-05T21:21:16.534Z,1680729676.534 [DataOverHttps](INFO): SBD MOMSN=18035577
2023-04-05T21:21:17.670Z,1680729677.670 [Default:CheckIn:Read_Iridium] Stopped
2023-04-05T21:21:17.670Z,1680729677.670 [Default:CheckIn:C.Wait] Running Loop=1
2023-04-05T21:21:17.670Z,1680729677.670 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-04-05T21:21:41.476Z,1680729701.476 [NAL9602](INFO): Not Powering down - fast GPS
2023-04-05T21:21:45.530Z,1680729705.530 [DVL_micro](ERROR): Failed to parse:
:B,+00013,+00427,+00000,I
2023-04-05T21:24:00.862Z,1680729840.862 [DVL_micro](ERROR): Failed to parse:
:1,-00064,+00924,+00000,I
2023-04-05T21:26:18.327Z,1680729978.327 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-04-05T21:26:18.327Z,1680729978.327 [Default:CheckIn:C.Wait] Stopped
2023-04-05T21:26:18.327Z,1680729978.327 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-04-05T21:26:18.327Z,1680729978.327 [Default:CheckIn:D] Running Loop=1
2023-04-05T21:26:18.709Z,1680729978.709 [Default:CheckIn:D] Stopped
2023-04-05T21:26:18.709Z,1680729978.709 [Default:CheckIn:E] Running Loop=1
2023-04-05T21:26:19.104Z,1680729979.104 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 57.442505 min 
2023-04-05T21:26:19.104Z,1680729979.104 [Default:CheckIn:E] Stopped
2023-04-05T21:26:19.104Z,1680729979.104 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-04-05T21:26:19.104Z,1680729979.104 [Default:CheckIn] Stopped
2023-04-05T21:26:19.104Z,1680729979.104 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-04-05T21:26:19.104Z,1680729979.104 [Default:CheckIn](INFO): Running loop #10
2023-04-05T21:26:19.105Z,1680729979.105 [Default:CheckIn] Running Loop=10
2023-04-05T21:26:19.105Z,1680729979.105 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-04-05T21:26:19.105Z,1680729979.105 [Default:CheckIn:Read_GPS] Running Loop=1
2023-04-05T21:26:21.133Z,1680729981.133 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,212620.00,A,3648.15022,N,12147.22224,W,0.019,56.58,050423,,,D*42
2023-04-05T21:26:21.135Z,1680729981.135 [NAL9602](INFO): GPS fix at 20230405T212620: (36.802504, -121.787037)
2023-04-05T21:26:21.183Z,1680729981.183 [Default:CheckIn:Read_GPS] Stopped
2023-04-05T21:26:21.183Z,1680729981.183 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-04-05T21:26:29.193Z,1680729989.193 [NAL9602](INFO): SBD MO Status=0, MOMSN=14720, MT Status=0, MTMSN=0
2023-04-05T21:26:29.193Z,1680729989.193 [NAL9602](INFO): No messages in MT queue
2023-04-05T21:26:29.635Z,1680729989.635 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20230405T202317/Courier0034.lzma
2023-04-05T21:26:30.638Z,1680729990.638 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Courier0034.lzma.bak
2023-04-05T21:26:30.638Z,1680729990.638 [DataOverHttps](INFO): SBD MOMSN=18035584
2023-04-05T21:26:43.747Z,1680730003.747 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-04-05T21:26:43.747Z,1680730003.747 [DVL_micro](ERROR): Failed to parse:
:TS0000000,35.0,+21.3,0000.0,1489.0,000
2023-04-05T21:26:46.499Z,1680730006.499 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20230405T202317/Express0035.lzma
2023-04-05T21:26:47.502Z,1680730007.502 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Express0035.lzma.bak
2023-04-05T21:26:47.502Z,1680730007.502 [DataOverHttps](INFO): SBD MOMSN=18035587
2023-04-05T21:26:48.599Z,1680730008.599 [Default:CheckIn:Read_Iridium] Stopped
2023-04-05T21:26:48.600Z,1680730008.600 [Default:CheckIn:C.Wait] Running Loop=1
2023-04-05T21:26:48.600Z,1680730008.600 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-04-05T21:26:59.906Z,1680730019.906 [NAL9602](INFO): Not Powering down - fast GPS
2023-04-05T21:31:49.231Z,1680730309.231 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-04-05T21:31:49.231Z,1680730309.231 [Default:CheckIn:C.Wait] Stopped
2023-04-05T21:31:49.232Z,1680730309.232 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-04-05T21:31:49.232Z,1680730309.232 [Default:CheckIn:D] Running Loop=1
2023-04-05T21:31:49.634Z,1680730309.634 [Default:CheckIn:D] Stopped
2023-04-05T21:31:49.634Z,1680730309.634 [Default:CheckIn:E] Running Loop=1
2023-04-05T21:31:50.050Z,1680730310.050 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 62.957918 min 
2023-04-05T21:31:50.050Z,1680730310.050 [Default:CheckIn:E] Stopped
2023-04-05T21:31:50.051Z,1680730310.051 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-04-05T21:31:50.051Z,1680730310.051 [Default:CheckIn] Stopped
2023-04-05T21:31:50.051Z,1680730310.051 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-04-05T21:31:50.051Z,1680730310.051 [Default:CheckIn](INFO): Running loop #11
2023-04-05T21:31:50.051Z,1680730310.051 [Default:CheckIn] Running Loop=11
2023-04-05T21:31:50.051Z,1680730310.051 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-04-05T21:31:50.051Z,1680730310.051 [Default:CheckIn:Read_GPS] Running Loop=1
2023-04-05T21:31:52.052Z,1680730312.052 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213151.00,A,3648.15209,N,12147.22033,W,0.233,312.49,050423,,,D*74
2023-04-05T21:31:52.054Z,1680730312.054 [NAL9602](INFO): GPS fix at 20230405T213151: (36.802535, -121.787006)
2023-04-05T21:31:52.089Z,1680730312.089 [Default:CheckIn:Read_GPS] Stopped
2023-04-05T21:31:52.090Z,1680730312.090 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-04-05T21:32:02.751Z,1680730322.751 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20230405T202317/Courier0037.lzma
2023-04-05T21:32:03.754Z,1680730323.754 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Courier0037.lzma.bak
2023-04-05T21:32:03.754Z,1680730323.754 [DataOverHttps](INFO): SBD MOMSN=18035662
2023-04-05T21:32:05.056Z,1680730325.056 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-04-05T21:32:05.056Z,1680730325.056 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+21.2,000A
2023-04-05T21:32:21.207Z,1680730341.207 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20230405T202317/Express0038.lzma
2023-04-05T21:32:22.213Z,1680730342.213 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Express0038.lzma.bak
2023-04-05T21:32:22.213Z,1680730342.213 [DataOverHttps](INFO): SBD MOMSN=18035666
2023-04-05T21:32:23.306Z,1680730343.306 [Default:CheckIn:Read_Iridium] Stopped
2023-04-05T21:32:23.306Z,1680730343.306 [Default:CheckIn:C.Wait] Running Loop=1
2023-04-05T21:32:23.306Z,1680730343.306 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-04-05T21:32:44.276Z,1680730364.276 [NAL9602](INFO): SBD MO Status=2, MOMSN=14721, MT Status=2, MTMSN=0
2023-04-05T21:32:44.276Z,1680730364.276 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-04-05T21:32:51.163Z,1680730371.163 [DVL_micro](ERROR): only read 2 of 4 data items
2023-04-05T21:32:51.163Z,1680730371.163 [DVL_micro](ERROR): Failed to parse::RD,+99999.99,+99999.99
2023-04-05T21:32:54.407Z,1680730374.407 [NAL9602](INFO): SBD MO Status=0, MOMSN=14721, MT Status=0, MTMSN=0
2023-04-05T21:32:54.407Z,1680730374.407 [NAL9602](INFO): No messages in MT queue
2023-04-05T21:33:25.082Z,1680730405.082 [NAL9602](INFO): Not Powering down - fast GPS
2023-04-05T21:34:07.513Z,1680730447.513 [DVL_micro](ERROR): only read 3 of 4 data items
2023-04-05T21:34:07.513Z,1680730447.513 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,+9999.999
2023-04-05T21:36:12.792Z,1680730572.792 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-04-05T21:36:12.792Z,1680730572.792 [DVL_micro](ERROR): Failed to parse:
:TS,000000000.0,+21.2,0000.0,1489.0,000
2023-04-05T21:37:19.049Z,1680730639.049 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-04-05T21:37:19.049Z,1680730639.049 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+21.2,00000,000
2023-04-05T21:37:23.922Z,1680730643.922 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-04-05T21:37:23.922Z,1680730643.922 [Default:CheckIn:C.Wait] Stopped
2023-04-05T21:37:23.922Z,1680730643.922 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-04-05T21:37:23.922Z,1680730643.922 [Default:CheckIn:D] Running Loop=1
2023-04-05T21:37:24.312Z,1680730644.312 [Default:CheckIn:D] Stopped
2023-04-05T21:37:24.312Z,1680730644.312 [Default:CheckIn:E] Running Loop=1
2023-04-05T21:37:24.711Z,1680730644.711 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 68.535897 min 
2023-04-05T21:37:24.711Z,1680730644.711 [Default:CheckIn:E] Stopped
2023-04-05T21:37:24.712Z,1680730644.712 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-04-05T21:37:24.712Z,1680730644.712 [Default:CheckIn] Stopped
2023-04-05T21:37:24.712Z,1680730644.712 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-04-05T21:37:24.712Z,1680730644.712 [Default:CheckIn](INFO): Running loop #12
2023-04-05T21:37:24.712Z,1680730644.712 [Default:CheckIn] Running Loop=12
2023-04-05T21:37:24.712Z,1680730644.712 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-04-05T21:37:24.712Z,1680730644.712 [Default:CheckIn:Read_GPS] Running Loop=1
2023-04-05T21:37:26.741Z,1680730646.741 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213726.00,A,3648.19040,N,12147.17458,W,4.490,40.35,050423,,,D*4A
2023-04-05T21:37:26.743Z,1680730646.743 [NAL9602](INFO): GPS fix at 20230405T213726: (36.803173, -121.786243)
2023-04-05T21:37:26.754Z,1680730646.754 [Default:CheckIn:Read_GPS] Stopped
2023-04-05T21:37:26.754Z,1680730646.754 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-04-05T21:37:34.087Z,1680730654.087 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20230405T202317/Courier0040.lzma
2023-04-05T21:37:35.090Z,1680730655.090 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Courier0040.lzma.bak
2023-04-05T21:37:35.090Z,1680730655.090 [DataOverHttps](INFO): SBD MOMSN=18035678
2023-04-05T21:37:50.955Z,1680730670.955 [DataOverHttps](INFO): Sending 127 bytes from file Logs/20230405T202317/Express0041.lzma
2023-04-05T21:37:50.977Z,1680730670.977 [NAL9602](INFO): SBD MO Status=0, MOMSN=14722, MT Status=0, MTMSN=0
2023-04-05T21:37:50.977Z,1680730670.977 [NAL9602](INFO): No messages in MT queue
2023-04-05T21:37:51.958Z,1680730671.958 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Express0041.lzma.bak
2023-04-05T21:37:51.958Z,1680730671.958 [DataOverHttps](INFO): SBD MOMSN=18035681
2023-04-05T21:37:53.006Z,1680730673.006 [Default:CheckIn:Read_Iridium] Stopped
2023-04-05T21:37:53.006Z,1680730673.006 [Default:CheckIn:C.Wait] Running Loop=1
2023-04-05T21:37:53.006Z,1680730673.006 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-04-05T21:38:21.669Z,1680730701.669 [NAL9602](INFO): Not Powering down - fast GPS
2023-04-05T21:41:41.707Z,1680730901.707 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-04-05T21:41:41.707Z,1680730901.707 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+21.1,489.0,000
2023-04-05T21:42:53.635Z,1680730973.635 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-04-05T21:42:53.636Z,1680730973.636 [Default:CheckIn:C.Wait] Stopped
2023-04-05T21:42:53.636Z,1680730973.636 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-04-05T21:42:53.636Z,1680730973.636 [Default:CheckIn:D] Running Loop=1
2023-04-05T21:42:54.044Z,1680730974.044 [Default:CheckIn:D] Stopped
2023-04-05T21:42:54.044Z,1680730974.044 [Default:CheckIn:E] Running Loop=1
2023-04-05T21:42:54.449Z,1680730974.449 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 74.031429 min 
2023-04-05T21:42:54.449Z,1680730974.449 [Default:CheckIn:E] Stopped
2023-04-05T21:42:54.449Z,1680730974.449 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-04-05T21:42:54.449Z,1680730974.449 [Default:CheckIn] Stopped
2023-04-05T21:42:54.449Z,1680730974.449 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-04-05T21:42:54.449Z,1680730974.449 [Default:CheckIn](INFO): Running loop #13
2023-04-05T21:42:54.449Z,1680730974.449 [Default:CheckIn] Running Loop=13
2023-04-05T21:42:54.449Z,1680730974.449 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-04-05T21:42:54.449Z,1680730974.449 [Default:CheckIn:Read_GPS] Running Loop=1
2023-04-05T21:42:56.486Z,1680730976.486 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,214255.00,A,3648.45733,N,12147.32324,W,7.542,239.65,050423,,,D*79
2023-04-05T21:42:56.489Z,1680730976.489 [NAL9602](INFO): GPS fix at 20230405T214255: (36.807622, -121.788721)
2023-04-05T21:42:56.500Z,1680730976.500 [Default:CheckIn:Read_GPS] Stopped
2023-04-05T21:42:56.501Z,1680730976.501 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-04-05T21:43:04.111Z,1680730984.111 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230405T202317/Courier0043.lzma
2023-04-05T21:43:05.114Z,1680730985.114 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Courier0043.lzma.bak
2023-04-05T21:43:05.114Z,1680730985.114 [DataOverHttps](INFO): SBD MOMSN=18035701
2023-04-05T21:43:11.021Z,1680730991.021 [NAL9602](INFO): SBD MO Status=0, MOMSN=14723, MT Status=0, MTMSN=0
2023-04-05T21:43:11.021Z,1680730991.021 [NAL9602](INFO): No messages in MT queue
2023-04-05T21:43:23.107Z,1680731003.107 [DataOverHttps](INFO): Sending 134 bytes from file Logs/20230405T202317/Express0044.lzma
2023-04-05T21:43:24.110Z,1680731004.110 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Express0044.lzma.bak
2023-04-05T21:43:24.110Z,1680731004.110 [DataOverHttps](INFO): SBD MOMSN=18035704
2023-04-05T21:43:25.166Z,1680731005.166 [Default:CheckIn:Read_Iridium] Stopped
2023-04-05T21:43:25.166Z,1680731005.166 [Default:CheckIn:C.Wait] Running Loop=1
2023-04-05T21:43:25.166Z,1680731005.166 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-04-05T21:43:41.705Z,1680731021.705 [NAL9602](INFO): Not Powering down - fast GPS
2023-04-05T21:45:54.215Z,1680731154.215 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-04-05T21:45:54.215Z,1680731154.215 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+21.1,489.0,000
2023-04-05T21:46:01.892Z,1680731161.892 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-04-05T21:46:01.892Z,1680731161.892 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+2.0,1489.0,,-00766,-00424,+00770,+00000,A
2023-04-05T21:48:14.409Z,1680731294.409 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-04-05T21:48:14.409Z,1680731294.409 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+210,1489.0,0+01404,-0005,+00000,A
2023-04-05T21:48:25.723Z,1680731305.723 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-04-05T21:48:25.723Z,1680731305.723 [Default:CheckIn:C.Wait] Stopped
2023-04-05T21:48:25.723Z,1680731305.723 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-04-05T21:48:25.723Z,1680731305.723 [Default:CheckIn:D] Running Loop=1
2023-04-05T21:48:26.133Z,1680731306.133 [Default:CheckIn:D] Stopped
2023-04-05T21:48:26.133Z,1680731306.133 [Default:CheckIn:E] Running Loop=1
2023-04-05T21:48:26.539Z,1680731306.539 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 79.566235 min 
2023-04-05T21:48:26.539Z,1680731306.539 [Default:CheckIn:E] Stopped
2023-04-05T21:48:26.539Z,1680731306.539 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-04-05T21:48:26.539Z,1680731306.539 [Default:CheckIn] Stopped
2023-04-05T21:48:26.539Z,1680731306.539 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-04-05T21:48:26.539Z,1680731306.539 [Default:CheckIn](INFO): Running loop #14
2023-04-05T21:48:26.539Z,1680731306.539 [Default:CheckIn] Running Loop=14
2023-04-05T21:48:26.540Z,1680731306.540 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-04-05T21:48:26.540Z,1680731306.540 [Default:CheckIn:Read_GPS] Running Loop=1
2023-04-05T21:48:28.542Z,1680731308.542 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,214827.00,A,3648.42785,N,12148.12479,W,6.531,265.81,050423,,,D*78
2023-04-05T21:48:28.547Z,1680731308.547 [NAL9602](INFO): GPS fix at 20230405T214827: (36.807131, -121.802080)
2023-04-05T21:48:28.581Z,1680731308.581 [Default:CheckIn:Read_GPS] Stopped
2023-04-05T21:48:28.581Z,1680731308.581 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-04-05T21:48:40.052Z,1680731320.052 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T21:48:42.060Z,1680731322.060 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.251404
2023-04-05T21:48:44.703Z,1680731324.703 [NAL9602](INFO): SBD MO Status=0, MOMSN=14724, MT Status=0, MTMSN=0
2023-04-05T21:48:44.703Z,1680731324.703 [NAL9602](INFO): No messages in MT queue
2023-04-05T21:48:59.703Z,1680731339.703 [NAL9602](INFO): SBD MO Status=1, MOMSN=14725, MT Status=0, MTMSN=0
2023-04-05T21:48:59.752Z,1680731339.752 [NAL9602](INFO): Sent 74 bytes from file Logs/20230405T202317/Courier0046.lzma
2023-04-05T21:48:59.752Z,1680731339.752 [NAL9602](INFO): Packets left to send: 0
2023-04-05T21:49:13.105Z,1680731353.105 [NAL9602](INFO): SBD MO Status=1, MOMSN=14726, MT Status=0, MTMSN=0
2023-04-05T21:49:13.156Z,1680731353.156 [NAL9602](INFO): Sent 140 bytes from file Logs/20230405T202317/Express0047.lzma
2023-04-05T21:49:13.156Z,1680731353.156 [NAL9602](INFO): Packets left to send: 0
2023-04-05T21:49:13.184Z,1680731353.184 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T21:49:26.033Z,1680731366.033 [NAL9602](INFO): SBD MO Status=0, MOMSN=14727, MT Status=0, MTMSN=0
2023-04-05T21:49:26.119Z,1680731366.119 [Default:CheckIn:Read_Iridium] Stopped
2023-04-05T21:49:26.119Z,1680731366.119 [Default:CheckIn:C.Wait] Running Loop=1
2023-04-05T21:49:26.119Z,1680731366.119 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-04-05T21:49:48.332Z,1680731388.332 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T21:49:56.739Z,1680731396.739 [NAL9602](INFO): Not Powering down - fast GPS
2023-04-05T21:50:23.484Z,1680731423.484 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T21:50:24.611Z,1680731424.611 [DVL_micro](ERROR): Failed to parse:
00000000+20.9,0000.0,14
2023-04-05T21:50:58.628Z,1680731458.628 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T21:51:33.764Z,1680731493.764 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T21:52:08.916Z,1680731528.916 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T21:52:44.056Z,1680731564.056 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T21:53:19.200Z,1680731599.200 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T21:53:54.341Z,1680731634.341 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T21:54:26.613Z,1680731666.613 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-04-05T21:54:26.613Z,1680731666.613 [Default:CheckIn:C.Wait] Stopped
2023-04-05T21:54:26.613Z,1680731666.613 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-04-05T21:54:26.613Z,1680731666.613 [Default:CheckIn:D] Running Loop=1
2023-04-05T21:54:27.029Z,1680731667.029 [Default:CheckIn:D] Stopped
2023-04-05T21:54:27.029Z,1680731667.029 [Default:CheckIn:E] Running Loop=1
2023-04-05T21:54:27.425Z,1680731667.425 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 85.581169 min 
2023-04-05T21:54:27.425Z,1680731667.425 [Default:CheckIn:E] Stopped
2023-04-05T21:54:27.425Z,1680731667.425 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-04-05T21:54:27.425Z,1680731667.425 [Default:CheckIn] Stopped
2023-04-05T21:54:27.425Z,1680731667.425 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-04-05T21:54:27.425Z,1680731667.425 [Default:CheckIn](INFO): Running loop #15
2023-04-05T21:54:27.425Z,1680731667.425 [Default:CheckIn] Running Loop=15
2023-04-05T21:54:27.425Z,1680731667.425 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-04-05T21:54:27.425Z,1680731667.425 [Default:CheckIn:Read_GPS] Running Loop=1
2023-04-05T21:54:29.480Z,1680731669.480 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T21:54:52.486Z,1680731692.486 [NAL9602](INFO): SBD MO Status=2, MOMSN=14728, MT Status=2, MTMSN=0
2023-04-05T21:54:52.486Z,1680731692.486 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-04-05T21:55:04.640Z,1680731704.640 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T21:55:17.115Z,1680731717.115 [NAL9602](INFO): SBD MO Status=0, MOMSN=14728, MT Status=0, MTMSN=0
2023-04-05T21:55:17.115Z,1680731717.115 [NAL9602](INFO): No messages in MT queue
2023-04-05T21:55:18.315Z,1680731718.315 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,215517.00,A,3648.37148,N,12148.60620,W,2.158,81.83,050423,,,D*4C
2023-04-05T21:55:18.317Z,1680731718.317 [NAL9602](INFO): GPS fix at 20230405T215517: (36.806191, -121.810103)
2023-04-05T21:55:18.328Z,1680731718.328 [Default:CheckIn:Read_GPS] Stopped
2023-04-05T21:55:18.328Z,1680731718.328 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-04-05T21:55:34.531Z,1680731734.531 [NAL9602](INFO): SBD MO Status=1, MOMSN=14729, MT Status=0, MTMSN=0
2023-04-05T21:55:34.580Z,1680731734.580 [NAL9602](INFO): Sent 74 bytes from file Logs/20230405T202317/Courier0049.lzma
2023-04-05T21:55:34.580Z,1680731734.580 [NAL9602](INFO): Packets left to send: 0
2023-04-05T21:55:39.784Z,1680731739.784 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T21:55:43.484Z,1680731743.484 [NAL9602](INFO): SBD MO Status=1, MOMSN=14730, MT Status=0, MTMSN=0
2023-04-05T21:55:43.536Z,1680731743.536 [NAL9602](INFO): Sent 142 bytes from file Logs/20230405T202317/Express0050.lzma
2023-04-05T21:55:43.536Z,1680731743.536 [NAL9602](INFO): Packets left to send: 0
2023-04-05T21:56:02.054Z,1680731762.054 [NAL9602](INFO): SBD MO Status=0, MOMSN=14731, MT Status=0, MTMSN=0
2023-04-05T21:56:02.149Z,1680731762.149 [Default:CheckIn:Read_Iridium] Stopped
2023-04-05T21:56:02.149Z,1680731762.149 [Default:CheckIn:C.Wait] Running Loop=1
2023-04-05T21:56:02.149Z,1680731762.149 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-04-05T21:56:14.932Z,1680731774.932 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T21:56:32.766Z,1680731792.766 [NAL9602](INFO): Not Powering down - fast GPS
2023-04-05T21:56:50.072Z,1680731810.072 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T21:57:02.255Z,1680731822.255 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-04-05T21:57:02.256Z,1680731822.256 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+16.0,009.0,000
2023-04-05T21:57:14.392Z,1680731834.392 [DVL_micro](ERROR): Failed to parse:
8.93,+00443.99,+0038.37
2023-04-05T21:57:25.216Z,1680731845.216 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T21:58:00.356Z,1680731880.356 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T21:58:35.496Z,1680731915.496 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T21:59:10.636Z,1680731950.636 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T21:59:45.797Z,1680731985.797 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T22:00:20.940Z,1680732020.940 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T22:00:56.080Z,1680732056.080 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T22:01:02.655Z,1680732062.655 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-04-05T22:01:02.655Z,1680732062.655 [Default:CheckIn:C.Wait] Stopped
2023-04-05T22:01:02.655Z,1680732062.655 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-04-05T22:01:02.655Z,1680732062.655 [Default:CheckIn:D] Running Loop=1
2023-04-05T22:01:03.068Z,1680732063.068 [Default:CheckIn:D] Stopped
2023-04-05T22:01:03.068Z,1680732063.068 [Default:CheckIn:E] Running Loop=1
2023-04-05T22:01:03.474Z,1680732063.474 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 92.181828 min 
2023-04-05T22:01:03.474Z,1680732063.474 [Default:CheckIn:E] Stopped
2023-04-05T22:01:03.474Z,1680732063.474 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-04-05T22:01:03.474Z,1680732063.474 [Default:CheckIn] Stopped
2023-04-05T22:01:03.474Z,1680732063.474 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-04-05T22:01:03.474Z,1680732063.474 [Default:CheckIn](INFO): Running loop #16
2023-04-05T22:01:03.474Z,1680732063.474 [Default:CheckIn] Running Loop=16
2023-04-05T22:01:03.474Z,1680732063.474 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-04-05T22:01:03.475Z,1680732063.475 [Default:CheckIn:Read_GPS] Running Loop=1
2023-04-05T22:01:05.480Z,1680732065.480 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,220104.00,A,3648.39472,N,12148.56012,W,0.350,344.88,050423,,,D*75
2023-04-05T22:01:05.482Z,1680732065.482 [NAL9602](INFO): GPS fix at 20230405T220104: (36.806579, -121.809335)
2023-04-05T22:01:05.521Z,1680732065.521 [Default:CheckIn:Read_GPS] Stopped
2023-04-05T22:01:05.521Z,1680732065.521 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-04-05T22:01:31.236Z,1680732091.236 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T22:01:34.215Z,1680732094.215 [NAL9602](INFO): SBD MO Status=2, MOMSN=14732, MT Status=2, MTMSN=0
2023-04-05T22:01:34.215Z,1680732094.215 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-04-05T22:01:51.640Z,1680732111.640 [NAL9602](INFO): SBD MO Status=2, MOMSN=14732, MT Status=2, MTMSN=0
2023-04-05T22:01:51.640Z,1680732111.640 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-04-05T22:01:57.695Z,1680732117.695 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-04-05T22:01:57.696Z,1680732117.696 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,.8,0000.0,1489.0,000
2023-04-05T22:02:04.557Z,1680732124.557 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:02:06.376Z,1680732126.376 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T22:02:07.868Z,1680732127.868 [DVL_micro](ERROR): DVL uart error: serial timeout
2023-04-05T22:02:07.868Z,1680732127.868 [DVL_micro] Communications Fault, FailCount= 1
2023-04-05T22:02:07.868Z,1680732127.868 [DVL_micro](ERROR): Communications Fault
2023-04-05T22:02:07.869Z,1680732127.869 [DVL_micro](ERROR): Failed to parse:
2023-04-05T22:02:07.961Z,1680732127.961 [CBIT](ERROR): Communications Fault in component: DVL_micro
2023-04-05T22:02:08.260Z,1680732128.260 [DVL_micro](INFO): Powering down
2023-04-05T22:02:09.049Z,1680732129.049 [CBIT](INFO): Clearing failed state for component DVL_micro
2023-04-05T22:02:09.049Z,1680732129.049 [DVL_micro] No Fault, FailCount= 1
2023-04-05T22:02:09.404Z,1680732129.404 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:02:24.810Z,1680732144.810 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:02:31.687Z,1680732151.687 [NAL9602](INFO): SBD MO Status=2, MOMSN=14732, MT Status=2, MTMSN=0
2023-04-05T22:02:31.687Z,1680732151.687 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-04-05T22:02:39.758Z,1680732159.758 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:02:41.532Z,1680732161.532 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T22:02:54.713Z,1680732174.713 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:03:09.722Z,1680732189.722 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:03:16.679Z,1680732196.679 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T22:03:19.826Z,1680732199.826 [NAL9602](INFO): SBD MO Status=2, MOMSN=14732, MT Status=2, MTMSN=0
2023-04-05T22:03:19.826Z,1680732199.826 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-04-05T22:03:22.660Z,1680732202.660 [DVL_micro](ERROR): Failed to parse:
:BI,-00577,-02278,-00449,+00000,A
2023-04-05T22:03:24.670Z,1680732204.670 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:03:28.928Z,1680732208.928 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002671
2023-04-05T22:03:36.471Z,1680732216.471 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230405T202317/Courier0052.lzma
2023-04-05T22:03:37.474Z,1680732217.474 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Courier0052.lzma.bak
2023-04-05T22:03:37.474Z,1680732217.474 [DataOverHttps](INFO): SBD MOMSN=18035746
2023-04-05T22:03:40.085Z,1680732220.085 [NAL9602](INFO): SBD MO Status=2, MOMSN=14732, MT Status=2, MTMSN=0
2023-04-05T22:03:40.085Z,1680732220.085 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-04-05T22:03:40.901Z,1680732220.901 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:03:52.626Z,1680732232.626 [DVL_micro](ERROR): only read 3 of 4 data items
2023-04-05T22:03:52.626Z,1680732232.626 [DVL_micro](ERROR): Failed to parse:
:BI,+0000,+00000,+00BD,+0000000000000.00,+00000000.00,0000.20,000.00
2023-04-05T22:03:53.555Z,1680732233.555 [DataOverHttps](INFO): Sending 128 bytes from file Logs/20230405T202317/Express0053.lzma
2023-04-05T22:03:54.558Z,1680732234.558 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Express0053.lzma.bak
2023-04-05T22:03:54.558Z,1680732234.558 [DataOverHttps](INFO): SBD MOMSN=18035749
2023-04-05T22:03:55.933Z,1680732235.933 [Default:CheckIn:Read_Iridium] Stopped
2023-04-05T22:03:55.933Z,1680732235.933 [Default:CheckIn:C.Wait] Running Loop=1
2023-04-05T22:03:55.933Z,1680732235.933 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-04-05T22:03:56.237Z,1680732236.237 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:04:05.494Z,1680732245.494 [DataOverHttps](IMPORTANT): SBD MTMSN=20230405T220404
2023-04-05T22:04:10.902Z,1680732250.902 [NAL9602](INFO): Not Powering down - fast GPS
2023-04-05T22:04:11.219Z,1680732251.219 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:04:14.580Z,1680732254.580 [DataOverHttps](INFO): Received command: sched asap "load Transport/keepstation.tl;set keepstation.MissionTimeout 2 h;set keepstation.NeedCommsTime 20 min;set keepstation.Latitude 36.797 degree;set keepstation.Longitude -121.847 degree;set keepstation.Depth 15 m" 2pzym 1 2
2023-04-05T22:04:14.656Z,1680732254.656 [CommandExec](IMPORTANT): got command schedule asap "load Transport/keepstation.tl;set keepstation.MissionTimeout 2 h;set keepstation.NeedCommsTime 20 min;set keepstation.Latitude 36.797 degree;set keepstation.Longitude -121.847 degree;set keepstation.Depth 15 m" 2pzym 1 2.000000
2023-04-05T22:04:14.657Z,1680732254.657 [CommandExec](IMPORTANT): Scheduling command #1 of 2 with id=2pzym
2023-04-05T22:04:14.658Z,1680732254.658 [CommandExec](IMPORTANT): Scheduled #1 (#1 of 2 with id='2pzym'): "load Transport/keepstation.tl;set keepstation.MissionTimeout 2 h;set keepstation.NeedCommsTime 20 min;set keepstation.Latitude 36.797 degree;set keepstation.Longitude -121.847 degree;set keepstation.Depth 15 m", ASAP
2023-04-05T22:04:15.581Z,1680732255.581 [DataOverHttps](IMPORTANT): SBD MTMSN=20230405T220414
2023-04-05T22:04:26.215Z,1680732266.215 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:04:26.976Z,1680732266.976 [DataOverHttps](INFO): Received command: sched asap "set keepstation.Speed 1.0 m/s;run" 2pzym 2 2
2023-04-05T22:04:27.047Z,1680732267.047 [CommandExec](IMPORTANT): got command schedule asap "set keepstation.Speed 1.0 m/s;run" 2pzym 2 2.000000
2023-04-05T22:04:27.047Z,1680732267.047 [CommandExec](IMPORTANT): Scheduling command #2 of 2 with id=2pzym
2023-04-05T22:04:27.048Z,1680732267.048 [CommandExec](IMPORTANT): Scheduled #2 (#2 of 2 with id='2pzym'): "set keepstation.Speed 1.0 m/s;run", ASAP
2023-04-05T22:04:27.180Z,1680732267.180 [CommandExec](IMPORTANT): got command load ./Missions/Transport/keepstation.tl
2023-04-05T22:04:27.180Z,1680732267.180 [MissionManager](INFO): Loading Mission from file: ./Missions/Transport/keepstation.tl
2023-04-05T22:04:27.180Z,1680732267.180 [MissionManager](IMPORTANT): Loading Compiled TethysL script from file ./Missions/Transport/keepstation.tx
2023-04-05T22:04:27.290Z,1680732267.290 [MissionManager](INFO): DefineArg keepstation.MissionTimeout = 4.000000 h
2023-04-05T22:04:27.302Z,1680732267.302 [MissionManager](INFO): DefineArg keepstation.NeedCommsTime = 45.000000 min
2023-04-05T22:04:27.305Z,1680732267.305 [MissionManager](INFO): DefineArg keepstation.Latitude = nan arcdeg
2023-04-05T22:04:27.308Z,1680732267.308 [MissionManager](INFO): DefineArg keepstation.Longitude = nan arcdeg
2023-04-05T22:04:27.311Z,1680732267.311 [MissionManager](INFO): DefineArg keepstation.Depth = 30.000000 m
2023-04-05T22:04:27.351Z,1680732267.351 [MissionManager](INFO): DefineArg keepstation.ApproachDepth = 15.000000 m
2023-04-05T22:04:27.358Z,1680732267.358 [MissionManager](INFO): DefineArg keepstation.DepthDeadband = 4.000000 m
2023-04-05T22:04:27.400Z,1680732267.400 [MissionManager](INFO): DefineArg keepstation.Speed = 0.750000 m/s
2023-04-05T22:04:27.403Z,1680732267.403 [MissionManager](INFO): DefineArg keepstation.Radius = 200.000000 m
2023-04-05T22:04:27.410Z,1680732267.410 [MissionManager](INFO): DefineArg keepstation.MaxDepth = 45.000000 m
2023-04-05T22:04:27.457Z,1680732267.457 [MissionManager](INFO): DefineArg keepstation.MinOffshore = 2.000000 km
2023-04-05T22:04:27.458Z,1680732267.458 [MissionManager](INFO): Inserting Stack from file: Missions/Insert/NeedComms.xml
2023-04-05T22:04:27.766Z,1680732267.766 [MissionManager](INFO): DefineArg keepstation:NeedComms.DiveInterval = 3.000000 h
2023-04-05T22:04:27.769Z,1680732267.769 [MissionManager](INFO): DefineArg keepstation:NeedComms.WaitForPitchUp = 10.000000 min
2023-04-05T22:04:27.808Z,1680732267.808 [MissionManager](INFO): DefineArg keepstation:NeedComms.SurfacePitch = 20.000000 arcdeg
2023-04-05T22:04:27.814Z,1680732267.814 [MissionManager](INFO): DefineArg keepstation:NeedComms.SurfaceDepthRate = nan m/s
2023-04-05T22:04:27.817Z,1680732267.817 [MissionManager](INFO): DefineArg keepstation:NeedComms.SurfaceSpeed = 1.000000 m/s
2023-04-05T22:04:27.865Z,1680732267.865 [MissionManager](INFO): DefineArg keepstation:NeedComms.SurfacingTimeout = 1000.000000 s
2023-04-05T22:04:27.886Z,1680732267.886 [MissionManager](INFO): DefineArg keepstation:NeedComms.GPSTimeout = 7.000000 min
2023-04-05T22:04:27.925Z,1680732267.925 [MissionManager](INFO): DefineArg keepstation:NeedComms.CommsTimeout = 30.000000 min
2023-04-05T22:04:27.952Z,1680732267.952 [keepstation:NeedComms:B.GoToSurface](DEBUG): Construct GoToSurface.
2023-04-05T22:04:28.025Z,1680732268.025 [MissionManager](INFO): Inserting Stack from file: Missions/Insert/StandardEnvelopes.xml
2023-04-05T22:04:28.098Z,1680732268.098 [MissionManager](INFO): DefineArg keepstation:StandardEnvelopes.MinAltitude = 5.000000 m
2023-04-05T22:04:28.101Z,1680732268.101 [MissionManager](INFO): DefineArg keepstation:StandardEnvelopes.MaxDepth = 200.000000 m
2023-04-05T22:04:28.120Z,1680732268.120 [MissionManager](INFO): DefineArg keepstation:StandardEnvelopes.MinOffshore = 2000.000000 m
2023-04-05T22:04:28.122Z,1680732268.122 [keepstation:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2023-04-05T22:04:28.145Z,1680732268.145 [keepstation:StandardEnvelopes:B.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2023-04-05T22:04:28.170Z,1680732268.170 [keepstation:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2023-04-05T22:04:28.227Z,1680732268.227 [keepstation:F.Pitch](DEBUG): Construct.
2023-04-05T22:04:28.339Z,1680732268.339 [keepstation:TransitToStation:A.Buoyancy](DEBUG): Construct Buoyancy.
2023-04-05T22:04:28.366Z,1680732268.366 [keepstation:TransitToStation:B.Pitch](DEBUG): Construct.
2023-04-05T22:04:28.388Z,1680732268.388 [keepstation:TransitToStation:C.SetSpeed](DEBUG): Construct.
2023-04-05T22:04:28.391Z,1680732268.391 [keepstation:TransitToStation:Wpt1.Waypoint](DEBUG): Construct Waypoint.
2023-04-05T22:04:28.418Z,1680732268.418 [keepstation:KeepStation:B.Pitch](DEBUG): Construct.
2023-04-05T22:04:28.439Z,1680732268.439 [keepstation:KeepStation:C.KeepStation](DEBUG): Construct KeepStation.
2023-04-05T22:04:28.465Z,1680732268.465 [keepstation:KeepStation:D.Wait](DEBUG): Construct Wait.
2023-04-05T22:04:28.514Z,1680732268.514 [MissionManager](DEBUG): 
mission keepstation {
  """
  Vehicle transits to desired waypoint (or stays put if none is commanded)
  and stays within the specified radius.
  """

  arguments {
    MissionTimeout = 4 hour
      """
      Maximum duration of mission
      """

    NeedCommsTime = 45 minute
      """
      How often to surface for communications
      """

    Latitude = NaN degree
      """
      Latitude of waypoint to hold. If NaN, hold the latitude at start of
      mission.
      """

    Longitude = NaN degree
      """
      Longitude of waypoint to hold. If NaN, hold the longitude at start of
      mission.
      """

    Depth = 30 meter
      """
      Depth held during drift mode
      """

    ApproachDepth = 15 meter
      """
      Depth for initial approach to station.
      """

    DepthDeadband = 4 meter
      """
      How much vertical drift from the specified depth is allowed in drift
      mode
      """

    Speed = 0.75 meter_per_second
      """
      Vehicle transit speed.
      """

    Radius = 200 meter
      """
      Radius of circle around waypoint to hold.
      """

    MaxDepth = 45 meter
      """
      Maximum allowable depth during the mission.
      """

    MinOffshore = 2 kilometer
      """
      Minimum distance from the shoreline to maintain
      """
  }

  timeout duration=MissionTimeout

  insert id="NeedComms" Insert/NeedComms.xml

  assign in sequence NeedComms:DiveInterval = NeedCommsTime

  insert Insert/StandardEnvelopes.xml

  assign in sequence StandardEnvelopes:MaxDepth = MaxDepth

  assign in sequence StandardEnvelopes:MinOffshore = MinOffshore

  behavior Guidance:Pitch {
    run in parallel

    set massPosition = Control:VerticalControl.massDefault
  }

  call id="StartingMission" refId="NeedComms"

  aggregate TransitToStation {
    """
    Need a separate aggregate for transit if we want to specify a
    different depth for the approach.
    """

    run in sequence

    behavior Guidance:Buoyancy {
      run in parallel

      set position = Control:VerticalControl.buoyancyNeutral
    }

    behavior Guidance:Pitch {
      run in parallel

      set depth = ApproachDepth
    }

    behavior Guidance:SetSpeed {
      run in parallel

      set speed = Speed
    }

    behavior Guidance:Waypoint id="Wpt1" {
      run in sequence

      set latitude = Latitude
      set longitude = Longitude
    }
  }

  call id="OnStation" refId="NeedComms"

  aggregate KeepStation {
    run in sequence

    assign in parallel Control:VerticalControl.depthDeadband = DepthDeadband

    behavior Guidance:Pitch {
      run in parallel

      set depth = Depth
    }

    behavior Guidance:KeepStation {
      run in parallel

      set latitude = Latitude
      set longitude = Longitude
      set radius = Radius
      set speed = Speed
    }

    behavior Guidance:Wait {
      """
      Due to the way the KeepStation behavior is currently
      implemented, we must run it in parallel and use a Wait to keep
      from completing the mission before the timeout expires. However,
      this new version of the mission uses a top-level timeout so that
      the entire mission will not run for longer then MissionTimeout.
      """

      run in sequence

      set duration = MissionTimeout
    }
  }
}


2023-04-05T22:04:28.515Z,1680732268.515 [CommandExec](IMPORTANT): Loaded ./Missions/Transport/keepstation.tl
2023-04-05T22:04:38.636Z,1680732278.636 [CommandExec](IMPORTANT): got command set keepstation.MissionTimeout 2 hour
2023-04-05T22:04:38.637Z,1680732278.637 [CommandExec](IMPORTANT): got command set keepstation.NeedCommsTime 20 minute
2023-04-05T22:04:38.638Z,1680732278.638 [CommandExec](IMPORTANT): got command set keepstation.Latitude 36.797 degree
2023-04-05T22:04:38.638Z,1680732278.638 [CommandExec](IMPORTANT): got command set keepstation.Longitude -121.847 degree
2023-04-05T22:04:38.639Z,1680732278.639 [CommandExec](IMPORTANT): got command set keepstation.Depth 15 meter
2023-04-05T22:04:40.106Z,1680732280.106 [CommandExec](IMPORTANT): got command set keepstation.Speed 1.0 meter_per_second
2023-04-05T22:04:40.106Z,1680732280.106 [CommandExec](IMPORTANT): got command run
2023-04-05T22:04:40.109Z,1680732280.109 [CommandExec](IMPORTANT): Running 
2023-04-05T22:04:40.487Z,1680732280.487 [Default] Stopped
2023-04-05T22:04:40.488Z,1680732280.488 [Default](DEBUG): Aggregate::uninitialize Default
2023-04-05T22:04:40.488Z,1680732280.488 [Default:B.GoToSurface] Stopped
2023-04-05T22:04:40.488Z,1680732280.488 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2023-04-05T22:04:40.488Z,1680732280.488 [Default:CheckIn] Stopped
2023-04-05T22:04:40.488Z,1680732280.488 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-04-05T22:04:40.488Z,1680732280.488 [Default:CheckIn:C.Wait] Stopped
2023-04-05T22:04:40.488Z,1680732280.488 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-04-05T22:04:40.488Z,1680732280.488 [MissionManager](IMPORTANT): Started mission keepstation
2023-04-05T22:04:40.489Z,1680732280.489 [keepstation] Running Loop=1
2023-04-05T22:04:40.489Z,1680732280.489 [keepstation](DEBUG): Aggregate::initialize keepstation
2023-04-05T22:04:40.489Z,1680732280.489 [keepstation:StandardEnvelopes] Running Loop=1
2023-04-05T22:04:40.489Z,1680732280.489 [keepstation:StandardEnvelopes](DEBUG): Aggregate::initialize keepstation:StandardEnvelopes
2023-04-05T22:04:40.489Z,1680732280.489 [keepstation:StandardEnvelopes:A.AltitudeEnvelope] Running Loop=1
2023-04-05T22:04:40.489Z,1680732280.489 [keepstation:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2023-04-05T22:04:40.489Z,1680732280.489 [keepstation:StandardEnvelopes:B.DepthEnvelope] Running Loop=1
2023-04-05T22:04:40.490Z,1680732280.490 [keepstation:StandardEnvelopes:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2023-04-05T22:04:40.490Z,1680732280.490 [keepstation:StandardEnvelopes:C.OffshoreEnvelope] Running Loop=1
2023-04-05T22:04:40.490Z,1680732280.490 [keepstation:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2023-04-05T22:04:40.490Z,1680732280.490 [keepstation:F.Pitch] Running Loop=1
2023-04-05T22:04:40.490Z,1680732280.490 [keepstation:F.Pitch](DEBUG): Initialize.
2023-04-05T22:04:40.490Z,1680732280.490 [keepstation:B] Running Loop=1
2023-04-05T22:04:40.491Z,1680732280.491 [keepstation:F.Pitch] Running Loop=1
2023-04-05T22:04:40.491Z,1680732280.491 [keepstation:StandardEnvelopes] Running Loop=1
2023-04-05T22:04:40.491Z,1680732280.491 [keepstation:StandardEnvelopes:C.OffshoreEnvelope] Running Loop=1
2023-04-05T22:04:40.516Z,1680732280.516 [keepstation:StandardEnvelopes:B.DepthEnvelope] Running Loop=1
2023-04-05T22:04:40.517Z,1680732280.517 [keepstation:StandardEnvelopes:A.AltitudeEnvelope] Running Loop=1
2023-04-05T22:04:40.518Z,1680732280.518 [keepstation:B] Stopped
2023-04-05T22:04:40.518Z,1680732280.518 [keepstation:D] Running Loop=1
2023-04-05T22:04:40.821Z,1680732280.821 [keepstation:D] Stopped
2023-04-05T22:04:40.821Z,1680732280.821 [keepstation:E] Running Loop=1
2023-04-05T22:04:41.220Z,1680732281.220 [keepstation:E] Stopped
2023-04-05T22:04:41.221Z,1680732281.221 [keepstation:StartingMission] Running Loop=1
2023-04-05T22:04:41.221Z,1680732281.221 [keepstation:StartingMission](DEBUG): Aggregate::initialize keepstation:StartingMission
2023-04-05T22:04:41.647Z,1680732281.647 [keepstation:NeedComms] Running Loop=1
2023-04-05T22:04:41.647Z,1680732281.647 [keepstation:NeedComms](DEBUG): Aggregate::initialize keepstation:NeedComms
2023-04-05T22:04:41.647Z,1680732281.647 [keepstation:NeedComms:B.GoToSurface] Running Loop=1
2023-04-05T22:04:41.647Z,1680732281.647 [keepstation:NeedComms:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2023-04-05T22:04:41.648Z,1680732281.648 [keepstation:NeedComms:B.GoToSurface](INFO): Received depth rate setting nan m/s.
2023-04-05T22:04:41.649Z,1680732281.649 [keepstation:NeedComms:B.GoToSurface](INFO): Received pitch setting 19.999999 degrees.
2023-04-05T22:04:41.649Z,1680732281.649 [keepstation:NeedComms:B.GoToSurface](INFO): Received speed setting 1.000000 m/s.
2023-04-05T22:04:41.649Z,1680732281.649 [keepstation:NeedComms:B.GoToSurface](INFO): Received surface timeout setting 1000.000000 seconds.
2023-04-05T22:04:41.650Z,1680732281.650 [keepstation:NeedComms:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2023-04-05T22:04:41.650Z,1680732281.650 [keepstation:NeedComms:A] Running Loop=1
2023-04-05T22:04:41.651Z,1680732281.651 [keepstation:NeedComms:A](INFO): last time_fix was: 1680732064.000000 second since 1970/01/01T00:00:00Z 
2023-04-05T22:04:41.651Z,1680732281.651 [keepstation:NeedComms:A] Stopped
2023-04-05T22:04:42.026Z,1680732282.026 [keepstation:NeedComms:C] Running Loop=1
2023-04-05T22:04:42.431Z,1680732282.431 [keepstation:NeedComms:C](DEBUG): Initialize ReadDataComponent to sense time_fix
2023-04-05T22:04:44.019Z,1680732284.019 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,220443.00,A,3648.41232,N,12148.56210,W,0.175,5.27,050423,,,D*78
2023-04-05T22:04:44.022Z,1680732284.022 [NAL9602](INFO): GPS fix at 20230405T220443: (36.806872, -121.809368)
2023-04-05T22:04:44.043Z,1680732284.043 [keepstation:NeedComms:C] Stopped
2023-04-05T22:04:44.043Z,1680732284.043 [keepstation:NeedComms:D] Running Loop=1
2023-04-05T22:04:44.461Z,1680732284.461 [keepstation:NeedComms:D](DEBUG): Initialize ReadDataComponent to sense platform_communications
2023-04-05T22:04:51.999Z,1680732291.999 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20230405T202317/Courier0055.lzma
2023-04-05T22:04:53.002Z,1680732293.002 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Courier0055.lzma.bak
2023-04-05T22:04:53.002Z,1680732293.002 [DataOverHttps](INFO): SBD MOMSN=18035755
2023-04-05T22:05:09.232Z,1680732309.232 [DataOverHttps](INFO): Sending 552 bytes from file Logs/20230405T202317/Express0056.lzma
2023-04-05T22:05:10.234Z,1680732310.234 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Express0056.lzma.bak
2023-04-05T22:05:10.234Z,1680732310.234 [DataOverHttps](INFO): SBD MOMSN=18035758
2023-04-05T22:05:26.979Z,1680732326.979 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20230405T202317/Express0059.lzma
2023-04-05T22:05:27.982Z,1680732327.982 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Express0059.lzma.bak
2023-04-05T22:05:27.982Z,1680732327.982 [DataOverHttps](INFO): SBD MOMSN=18035780
2023-04-05T22:05:29.270Z,1680732329.270 [NAL9602](INFO): SBD MO Status=2, MOMSN=14732, MT Status=2, MTMSN=0
2023-04-05T22:05:29.270Z,1680732329.270 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-04-05T22:05:29.312Z,1680732329.312 [keepstation:NeedComms:D] Stopped
2023-04-05T22:05:29.312Z,1680732329.312 [keepstation:NeedComms:E] Running Loop=1
2023-04-05T22:05:29.719Z,1680732329.719 [keepstation:NeedComms:E](DEBUG): Initialize ReadDataComponent to sense time_fix
2023-04-05T22:05:57.552Z,1680732357.552 [NAL9602](INFO): SBD MO Status=2, MOMSN=14732, MT Status=2, MTMSN=0
2023-04-05T22:05:57.552Z,1680732357.552 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-04-05T22:07:05.846Z,1680732425.846 [NAL9602](INFO): SBD MO Status=2, MOMSN=14732, MT Status=2, MTMSN=0
2023-04-05T22:07:05.846Z,1680732425.846 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-04-05T22:09:46.234Z,1680732586.234 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-04-05T22:09:47.436Z,1680732587.436 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,220946.00,A,3648.43550,N,12148.56374,W,0.680,329.55,050423,,,D*77
2023-04-05T22:09:47.438Z,1680732587.438 [NAL9602](INFO): GPS fix at 20230405T220946: (36.807258, -121.809396)
2023-04-05T22:09:47.459Z,1680732587.459 [keepstation:NeedComms:E] Stopped
2023-04-05T22:09:47.460Z,1680732587.460 [keepstation:NeedComms](INFO): Completed keepstation:NeedComms
2023-04-05T22:09:47.460Z,1680732587.460 [keepstation:NeedComms] Stopped
2023-04-05T22:09:47.460Z,1680732587.460 [keepstation:NeedComms](DEBUG): Aggregate::uninitialize keepstation:NeedComms
2023-04-05T22:09:47.460Z,1680732587.460 [keepstation:NeedComms:B.GoToSurface] Stopped
2023-04-05T22:09:47.460Z,1680732587.460 [keepstation:NeedComms:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2023-04-05T22:09:47.890Z,1680732587.890 [keepstation:StartingMission](INFO): Completed keepstation:StartingMission
2023-04-05T22:09:47.890Z,1680732587.890 [keepstation:StartingMission] Stopped
2023-04-05T22:09:47.890Z,1680732587.890 [keepstation:StartingMission](DEBUG): Aggregate::uninitialize keepstation:StartingMission
2023-04-05T22:09:47.891Z,1680732587.891 [keepstation:TransitToStation] Running Loop=1
2023-04-05T22:09:47.891Z,1680732587.891 [keepstation:TransitToStation](DEBUG): Aggregate::initialize keepstation:TransitToStation
2023-04-05T22:09:47.891Z,1680732587.891 [keepstation:TransitToStation:A.Buoyancy] Running Loop=1
2023-04-05T22:09:47.891Z,1680732587.891 [keepstation:TransitToStation:A.Buoyancy](DEBUG): Initialize Buoyancy Component.
2023-04-05T22:09:47.891Z,1680732587.891 [keepstation:TransitToStation:B.Pitch] Running Loop=1
2023-04-05T22:09:47.891Z,1680732587.891 [keepstation:TransitToStation:B.Pitch](DEBUG): Initialize.
2023-04-05T22:09:47.891Z,1680732587.891 [keepstation:TransitToStation:C.SetSpeed] Running Loop=1
2023-04-05T22:09:47.891Z,1680732587.891 [keepstation:TransitToStation:C.SetSpeed](DEBUG): Initialize.
2023-04-05T22:09:47.892Z,1680732587.892 [keepstation:TransitToStation:Wpt1.Waypoint] Running Loop=1
2023-04-05T22:09:47.892Z,1680732587.892 [keepstation:TransitToStation:Wpt1.Waypoint](DEBUG): Initialize WaypointComponent.
2023-04-05T22:09:47.893Z,1680732587.893 [keepstation:TransitToStation:Wpt1.Waypoint](IMPORTANT): Navigating to waypoint: 36.797001,-121.847000
2023-04-05T22:09:48.259Z,1680732588.259 [keepstation:TransitToStation:C.SetSpeed] Running Loop=1
2023-04-05T22:09:48.259Z,1680732588.259 [keepstation:TransitToStation:B.Pitch] Running Loop=1
2023-04-05T22:09:48.259Z,1680732588.259 [keepstation:TransitToStation:A.Buoyancy] Running Loop=1
2023-04-05T22:10:16.570Z,1680732616.570 [ElevatorOffsetCalculator](INFO): New estimator for commanded vars: speed 1.00 m/s, pitch 30.00 deg, mass-position 32.50 mm (1 active estimators).
2023-04-05T22:10:19.386Z,1680732619.386 [NAL9602](INFO): Not Powering down - fast GPS
2023-04-05T22:10:44.852Z,1680732644.852 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T22:10:56.901Z,1680732656.901 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.251514
2023-04-05T22:11:21.190Z,1680732681.190 [DVL_micro](ERROR): Failed to parse:
:BI,+00116,+01133,+00171,+00000,A
2023-04-05T22:11:25.244Z,1680732685.244 [DVL_micro](ERROR): Failed to parse:
4.33,+0037.05,+0037.43,+0034.14
2023-04-05T22:11:27.265Z,1680732687.265 [DVL_micro](ERROR): No DVL communication! Re-initializing
2023-04-05T22:11:27.265Z,1680732687.265 [DVL_micro] Communications Fault, FailCount= 1
2023-04-05T22:11:27.265Z,1680732687.265 [DVL_micro](ERROR): Communications Fault
2023-04-05T22:11:27.411Z,1680732687.411 [CBIT](ERROR): Communications Fault in component: DVL_micro
2023-04-05T22:11:27.728Z,1680732687.728 [DVL_micro](INFO): Powering down
2023-04-05T22:11:28.647Z,1680732688.647 [CBIT](INFO): Clearing failed state for component DVL_micro
2023-04-05T22:11:28.647Z,1680732688.647 [DVL_micro] No Fault, FailCount= 1
2023-04-05T22:11:55.136Z,1680732715.136 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T22:12:06.030Z,1680732726.030 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:12:12.641Z,1680732732.641 [Radio_Surface](INFO): Powering down
2023-04-05T22:12:20.978Z,1680732740.978 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:12:30.276Z,1680732750.276 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T22:12:31.281Z,1680732751.281 [DataOverHttps](INFO): Radio surface powered OFF, will not connect.
2023-04-05T22:12:36.331Z,1680732756.331 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:12:51.296Z,1680732771.296 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:13:06.235Z,1680732786.235 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:13:20.771Z,1680732800.771 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:13:35.315Z,1680732815.315 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:13:50.262Z,1680732830.262 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:14:05.210Z,1680732845.210 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:14:20.562Z,1680732860.562 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:14:36.345Z,1680732876.345 [DVL_micro](ERROR): only read 3 of 4 data items
2023-04-05T22:14:36.346Z,1680732876.346 [DVL_micro](ERROR): Failed to parse:
:BI,+00003,+00951,+00038,
2023-04-05T22:14:38.352Z,1680732878.352 [DVL_micro](ERROR): only read 3 of 4 data items
2023-04-05T22:14:38.352Z,1680732878.352 [DVL_micro](ERROR): Failed to parse:
:RD,+00027.05,+0025.45,+0025.18
2023-04-05T22:20:23.395Z,1680733223.395 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.00,+00000000.00,0024.30,000.00
2023-04-05T22:20:33.459Z,1680733233.459 [DVL_micro](ERROR): DVL BIT error. See manual. Result code: 820
2023-04-05T22:20:33.474Z,1680733233.474 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.00,+000,0024.70,000.00
2023-04-05T22:22:01.930Z,1680733321.930 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:22:16.878Z,1680733336.878 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:22:31.882Z,1680733351.882 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:22:46.775Z,1680733366.775 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:23:02.126Z,1680733382.126 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:23:17.086Z,1680733397.086 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:23:32.022Z,1680733412.022 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:23:46.970Z,1680733426.970 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:24:01.514Z,1680733441.514 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:24:16.462Z,1680733456.462 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:24:31.006Z,1680733471.006 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-04-05T22:25:29.183Z,1680733529.183 [BPC1](INFO): Calculating totals. Valid battery stick count: 48. Valid reserve battery stick count: 5.
2023-04-05T22:25:29.185Z,1680733529.185 [BPC1](ERROR): Failed to receive data from all sticks prior to timeout. Will not retry this scan cycle.
2023-04-05T22:26:41.107Z,1680733601.107 [DVL_micro](ERROR): only read 3 of 4 data items
2023-04-05T22:26:41.108Z,1680733601.108 [DVL_micro](ERROR): Failed to parse:
:RD,+0031.939,+0030.95,+0030.68
2023-04-05T22:26:58.879Z,1680733618.879 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-04-05T22:26:58.879Z,1680733618.879 [DVL_micro](ERROR): Failed to parse:
:TS0000000,35.0,+09.9,0000.0,00
2023-04-05T22:29:47.767Z,1680733787.767 [keepstation:NeedComms] Running Loop=1
2023-04-05T22:29:47.767Z,1680733787.767 [keepstation:NeedComms](DEBUG): Aggregate::initialize keepstation:NeedComms
2023-04-05T22:29:47.767Z,1680733787.767 [keepstation:NeedComms:B.GoToSurface] Running Loop=1
2023-04-05T22:29:47.767Z,1680733787.767 [keepstation:NeedComms:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2023-04-05T22:29:47.784Z,1680733787.784 [keepstation:NeedComms:B.GoToSurface](INFO): Received depth rate setting nan m/s.
2023-04-05T22:29:47.784Z,1680733787.784 [keepstation:NeedComms:B.GoToSurface](INFO): Received pitch setting 19.999999 degrees.
2023-04-05T22:29:47.785Z,1680733787.785 [keepstation:NeedComms:B.GoToSurface](INFO): Received speed setting 1.000000 m/s.
2023-04-05T22:29:47.785Z,1680733787.785 [keepstation:NeedComms:B.GoToSurface](INFO): Received surface timeout setting 1000.000000 seconds.
2023-04-05T22:29:47.785Z,1680733787.785 [keepstation:NeedComms:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2023-04-05T22:29:47.786Z,1680733787.786 [keepstation:NeedComms:A] Running Loop=1
2023-04-05T22:29:47.787Z,1680733787.787 [keepstation:NeedComms:A](INFO): last time_fix was: 1680732586.000000 second since 1970/01/01T00:00:00Z 
2023-04-05T22:29:47.787Z,1680733787.787 [keepstation:NeedComms:A] Stopped
2023-04-05T22:30:39.875Z,1680733839.875 [keepstation:NeedComms:C] Running Loop=1
2023-04-05T22:30:40.416Z,1680733840.416 [Radio_Surface](INFO): Powering up
2023-04-05T22:30:45.788Z,1680733845.788 [DataOverHttps](INFO): Radio surface powered ON.
2023-04-05T22:31:13.393Z,1680733873.393 [NAL9602](INFO): SBD MO Status=2, MOMSN=14732, MT Status=2, MTMSN=0
2023-04-05T22:31:13.393Z,1680733873.393 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-04-05T22:31:15.917Z,1680733875.917 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T22:31:36.601Z,1680733896.601 [DAT](INFO): DAT read: Acoustic Wakeup

2023-04-05T22:31:36.601Z,1680733896.601 [DAT](INFO): unknown deviceResponse_: Acoustic Wakeup

2023-04-05T22:31:36.602Z,1680733896.602 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP

2023-04-05T22:31:36.603Z,1680733896.603 [DAT](INFO): commRate: 800
2023-04-05T22:31:37.356Z,1680733897.356 [DAT](INFO): DAT read: Lowpower

2023-04-05T22:31:37.357Z,1680733897.357 [DAT](INFO): unknown deviceResponse_: Lowpower

2023-04-05T22:31:51.058Z,1680733911.058 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T22:32:26.212Z,1680733946.212 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T22:32:32.982Z,1680733952.982 [NAL9602](INFO): SBD MO Status=2, MOMSN=14732, MT Status=2, MTMSN=0
2023-04-05T22:32:32.983Z,1680733952.983 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-04-05T22:32:54.007Z,1680733974.007 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-04-05T22:32:54.007Z,1680733974.007 [DVL_micro](ERROR): Failed to parse:
:TS,000000000000010.2,0000.,000
2023-04-05T22:33:01.360Z,1680733981.360 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T22:33:06.116Z,1680733986.116 [DVL_micro](ERROR): Failed to parse:
:W,+00086,-0060,A
2023-04-05T22:33:36.500Z,1680734016.500 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T22:33:49.112Z,1680734029.112 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002688
2023-04-05T22:35:44.545Z,1680734144.545 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-04-05T22:35:55.055Z,1680734155.055 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,223554.00,A,3648.16544,N,12149.28000,W,0.797,298.57,050423,,,A*7D
2023-04-05T22:35:55.057Z,1680734155.057 [NAL9602](INFO): GPS fix at 20230405T223554: (36.802757, -121.821333)
2023-04-05T22:35:55.096Z,1680734155.096 [UniversalFixResidualReporter](INFO): Fix residual: 9.8 %DT, over the last 1319.7 m. Residual distance 129.4 m at bearing -35.9 degrees. Fix at (36.8028, -121.8213) with 1174.8 m made good.
2023-04-05T22:35:55.099Z,1680734155.099 [keepstation:NeedComms:C] Stopped
2023-04-05T22:35:55.104Z,1680734155.104 [keepstation:NeedComms:D] Running Loop=1
2023-04-05T22:36:06.483Z,1680734166.483 [DataOverHttps](INFO): Sending 217 bytes from file Logs/20230405T202317/Courier0061.lzma
2023-04-05T22:36:07.486Z,1680734167.486 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Courier0061.lzma.bak
2023-04-05T22:36:07.486Z,1680734167.486 [DataOverHttps](INFO): SBD MOMSN=18035809
2023-04-05T22:36:27.070Z,1680734187.070 [NAL9602](INFO): Not Powering down - fast GPS
2023-04-05T22:36:27.204Z,1680734187.204 [DataOverHttps](INFO): Sending 336 bytes from file Logs/20230405T202317/Express0062.lzma
2023-04-05T22:36:28.206Z,1680734188.206 [DataOverHttps](INFO): Moved sent file to Logs/20230405T202317/Express0062.lzma.bak
2023-04-05T22:36:28.206Z,1680734188.206 [DataOverHttps](INFO): SBD MOMSN=18035812
2023-04-05T22:36:29.554Z,1680734189.554 [keepstation:NeedComms:D] Stopped
2023-04-05T22:36:29.560Z,1680734189.560 [keepstation:NeedComms:E] Running Loop=1
2023-04-05T22:36:31.511Z,1680734191.511 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,223630.00,A,3648.16475,N,12149.27979,W,0.836,347.73,050423,,,A*76
2023-04-05T22:36:31.513Z,1680734191.513 [NAL9602](INFO): GPS fix at 20230405T223630: (36.802746, -121.821330)
2023-04-05T22:36:31.582Z,1680734191.582 [keepstation:NeedComms:E] Stopped
2023-04-05T22:36:31.583Z,1680734191.583 [keepstation:NeedComms](INFO): Completed keepstation:NeedComms
2023-04-05T22:36:31.583Z,1680734191.583 [keepstation:NeedComms] Stopped
2023-04-05T22:36:31.583Z,1680734191.583 [keepstation:NeedComms](DEBUG): Aggregate::uninitialize keepstation:NeedComms
2023-04-05T22:36:31.583Z,1680734191.583 [keepstation:NeedComms:B.GoToSurface] Stopped
2023-04-05T22:36:31.583Z,1680734191.583 [keepstation:NeedComms:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2023-04-05T22:37:02.214Z,1680734222.214 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2023-04-05T22:37:02.292Z,1680734222.292 [NAL9602](ERROR): received: 
+CSQ:0

OK732, 2, 0, 0, 0

OK
2023-04-05T22:37:05.053Z,1680734225.053 [ElevatorOffsetCalculator](INFO): New estimator for commanded vars: speed 1.00 m/s, pitch 20.00 deg, mass-position 32.50 mm (2 active estimators).
2023-04-05T22:37:35.308Z,1680734255.308 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T22:37:37.316Z,1680734257.316 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.239243
2023-04-05T22:37:49.493Z,1680734269.493 [DVL_micro](ERROR): Failed to parse:
:BD,+.00,+00000000.00,+00000000.00,0042.40,000.00
2023-04-05T22:38:05.448Z,1680734285.448 [Radio_Surface](INFO): Powering down
2023-04-05T22:38:10.460Z,1680734290.460 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T22:38:11.464Z,1680734291.464 [DataOverHttps](INFO): Radio surface powered OFF, will not connect.
2023-04-05T22:41:33.306Z,1680734493.306 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-04-05T22:41:46.644Z,1680734506.644 [DVL_micro](ERROR): Failed to parse:
:0000.00,+00000000.00,+00000000.00,0029.90,000.00
2023-04-05T22:42:04.009Z,1680734524.009 [NAL9602](INFO): Not Powering down - fast GPS
2023-04-05T22:44:27.863Z,1680734667.863 [DVL_micro](ERROR): only read 3 of 4 data items
2023-04-05T22:44:27.863Z,1680734667.863 [DVL_micro](ERROR): Failed to parse:
:RD,+0032.55,+00331.64,+0031.55
2023-04-05T22:45:29.676Z,1680734729.676 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.00,+00000000.00,0030.00,000.00
2023-04-05T22:47:45.411Z,1680734865.411 [DVL_micro](ERROR): only read 3 of 4 data items
2023-04-05T22:47:45.411Z,1680734865.411 [DVL_micro](ERROR): Failed to parse:
:BI,+00033,+01011,+00016,+00000+00000000.00,+00000000.00,+00000000.00,0030.90,000.00
2023-04-05T22:49:55.075Z,1680734995.075 [DVL_micro](ERROR): only read 2 of 4 data items
2023-04-05T22:49:55.076Z,1680734995.076 [DVL_micro](ERROR): Failed to parse:
:BI,01133,+0000,A
2023-04-05T22:53:50.628Z,1680735230.628 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.00,+00000000.00,0041.40,000.00
2023-04-05T22:55:40.494Z,1680735340.494 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-04-05T22:55:40.494Z,1680735340.494 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35,0000.0,1489.0,000
2023-04-05T22:56:00.293Z,1680735360.293 [DVL_micro](ERROR): only read 3 of 4 data items
2023-04-05T22:56:00.293Z,1680735360.293 [DVL_micro](ERROR): Failed to parse:
:BI,+00024,+0033,+00000,A
2023-04-05T22:56:38.288Z,1680735398.288 [keepstation:NeedComms] Running Loop=1
2023-04-05T22:56:38.288Z,1680735398.288 [keepstation:NeedComms](DEBUG): Aggregate::initialize keepstation:NeedComms
2023-04-05T22:56:38.288Z,1680735398.288 [keepstation:NeedComms:B.GoToSurface] Running Loop=1
2023-04-05T22:56:38.288Z,1680735398.288 [keepstation:NeedComms:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2023-04-05T22:56:38.289Z,1680735398.289 [keepstation:NeedComms:B.GoToSurface](INFO): Received depth rate setting nan m/s.
2023-04-05T22:56:38.289Z,1680735398.289 [keepstation:NeedComms:B.GoToSurface](INFO): Received pitch setting 19.999999 degrees.
2023-04-05T22:56:38.290Z,1680735398.290 [keepstation:NeedComms:B.GoToSurface](INFO): Received speed setting 1.000000 m/s.
2023-04-05T22:56:38.290Z,1680735398.290 [keepstation:NeedComms:B.GoToSurface](INFO): Received surface timeout setting 1000.000000 seconds.
2023-04-05T22:56:38.290Z,1680735398.290 [keepstation:NeedComms:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2023-04-05T22:56:38.291Z,1680735398.291 [keepstation:NeedComms:A] Running Loop=1
2023-04-05T22:56:38.292Z,1680735398.292 [keepstation:NeedComms:A](INFO): last time_fix was: 1680734190.000000 second since 1970/01/01T00:00:00Z 
2023-04-05T22:56:38.292Z,1680735398.292 [keepstation:NeedComms:A] Stopped
2023-04-05T22:57:29.995Z,1680735449.995 [keepstation:NeedComms:C] Running Loop=1
2023-04-05T22:57:30.588Z,1680735450.588 [Radio_Surface](INFO): Powering up
2023-04-05T22:57:36.292Z,1680735456.292 [DataOverHttps](INFO): Radio surface powered ON.
2023-04-05T22:58:02.702Z,1680735482.702 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2023-04-05T22:58:02.776Z,1680735482.776 [NAL9602](ERROR): received: 
+CSQ:0

OK732, 2, 0, 0, 0

OK
2023-04-05T22:58:06.424Z,1680735486.424 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T22:58:41.564Z,1680735521.564 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T22:59:16.712Z,1680735556.712 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T22:59:27.971Z,1680735567.971 [NAL9602](INFO): SBD MO Status=2, MOMSN=14732, MT Status=2, MTMSN=0
2023-04-05T22:59:27.971Z,1680735567.971 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-04-05T22:59:51.856Z,1680735591.856 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-04-05T23:00:23.709Z,1680735623.709 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=14732, MT Status=1, MTMSN=1052
2023-04-05T23:00:23.709Z,1680735623.709 [NAL9602](INFO): Data available in MT queue
2023-04-05T23:00:24.200Z,1680735624.200 [NAL9602](INFO): Received command: restart logs