2023-03-22T21:04:46.358Z,1679519086.358 [Supervisor](DEBUG): Initializing supervisor.
2023-03-22T21:04:46.362Z,1679519086.362 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2023-03-22T21:04:46.363Z,1679519086.363 [SyncHandler](INFO): Protected caller Thread ID is 831
2023-03-22T21:04:46.363Z,1679519086.363 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2023-03-22T21:04:46.364Z,1679519086.364 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2023-03-22T21:04:46.365Z,1679519086.365 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 832
2023-03-22T21:04:46.369Z,1679519086.369 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2023-03-22T21:04:46.387Z,1679519086.387 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread.
2023-03-22T21:04:46.388Z,1679519086.388 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2023-03-22T21:04:46.389Z,1679519086.389 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 833
2023-03-22T21:04:46.393Z,1679519086.393 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2023-03-22T21:04:46.394Z,1679519086.394 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2023-03-22T21:04:46.394Z,1679519086.394 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 834
2023-03-22T21:04:46.397Z,1679519086.397 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2023-03-22T21:04:46.397Z,1679519086.397 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0
2023-03-22T21:04:46.398Z,1679519086.398 [logger ThreadHandler](INFO): Protected caller Thread ID is 835
2023-03-22T21:04:46.402Z,1679519086.402 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2023-03-22T21:04:46.402Z,1679519086.402 [Supervisor](INFO): Looking for Config files in directory: Config/
2023-03-22T21:04:46.406Z,1679519086.406 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2023-03-22T21:04:46.770Z,1679519086.770 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2023-03-22T21:04:46.772Z,1679519086.772 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2023-03-22T21:04:47.480Z,1679519087.480 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2023-03-22T21:04:47.481Z,1679519087.481 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2023-03-22T21:04:47.593Z,1679519087.593 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2023-03-22T21:04:47.595Z,1679519087.595 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2023-03-22T21:04:48.115Z,1679519088.115 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2023-03-22T21:04:48.117Z,1679519088.117 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2023-03-22T21:04:48.215Z,1679519088.215 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2023-03-22T21:04:48.216Z,1679519088.216 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2023-03-22T21:04:48.299Z,1679519088.299 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2023-03-22T21:04:48.726Z,1679519088.726 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2023-03-22T21:04:48.727Z,1679519088.727 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2023-03-22T21:04:48.959Z,1679519088.959 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2023-03-22T21:04:48.959Z,1679519088.959 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2023-03-22T21:04:49.100Z,1679519089.100 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2023-03-22T21:04:49.101Z,1679519089.101 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2023-03-22T21:04:49.347Z,1679519089.347 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2023-03-22T21:04:49.347Z,1679519089.347 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2023-03-22T21:04:49.896Z,1679519089.896 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2023-03-22T21:04:50.354Z,1679519090.354 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2023-03-22T21:04:50.784Z,1679519090.784 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2023-03-22T21:04:50.786Z,1679519090.786 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2023-03-22T21:04:50.868Z,1679519090.868 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2023-03-22T21:04:51.069Z,1679519091.069 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2023-03-22T21:04:51.071Z,1679519091.071 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2023-03-22T21:04:51.300Z,1679519091.300 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2023-03-22T21:04:51.301Z,1679519091.301 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2023-03-22T21:04:51.612Z,1679519091.612 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2023-03-22T21:04:51.614Z,1679519091.614 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-brizo/
2023-03-22T21:04:51.617Z,1679519091.617 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Control.cfg
2023-03-22T21:04:51.730Z,1679519091.730 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Sensor.cfg
2023-03-22T21:04:51.883Z,1679519091.883 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Simulator.cfg
2023-03-22T21:04:51.970Z,1679519091.970 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/secure.cfg
2023-03-22T21:04:52.054Z,1679519092.054 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Servo.cfg
2023-03-22T21:04:52.166Z,1679519092.166 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/vehicle.cfg
2023-03-22T21:04:52.350Z,1679519092.350 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Battery.cfg
2023-03-22T21:04:52.619Z,1679519092.619 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2023-03-22T21:04:52.619Z,1679519092.619 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Science.cfg
2023-03-22T21:04:52.757Z,1679519092.757 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/logger.cfg
2023-03-22T21:04:52.852Z,1679519092.852 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/BIT.cfg
2023-03-22T21:04:52.960Z,1679519092.960 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Navigation.cfg
2023-03-22T21:04:53.064Z,1679519093.064 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2023-03-22T21:04:53.081Z,1679519093.081 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2023-03-22T21:04:53.249Z,1679519093.249 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2023-03-22T21:04:53.249Z,1679519093.249 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2023-03-22T21:04:53.265Z,1679519093.265 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2023-03-22T21:04:53.266Z,1679519093.266 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2023-03-22T21:04:53.336Z,1679519093.336 [DepthRateCalculator] Loaded
2023-03-22T21:04:53.337Z,1679519093.337 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2023-03-22T21:04:53.342Z,1679519093.342 [PitchRateCalculator] Loaded
2023-03-22T21:04:53.343Z,1679519093.343 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2023-03-22T21:04:53.353Z,1679519093.353 [SpeedCalculator] Loaded
2023-03-22T21:04:53.354Z,1679519093.354 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2023-03-22T21:04:53.359Z,1679519093.359 [YawRateCalculator] Loaded
2023-03-22T21:04:53.359Z,1679519093.359 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2023-03-22T21:04:53.381Z,1679519093.381 [ElevatorOffsetCalculator] Loaded
2023-03-22T21:04:53.381Z,1679519093.381 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2023-03-22T21:04:53.382Z,1679519093.382 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2023-03-22T21:04:53.384Z,1679519093.384 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2023-03-22T21:04:53.453Z,1679519093.453 [VerticalControl](DEBUG): Construct VerticalControl.
2023-03-22T21:04:53.509Z,1679519093.509 [VerticalControl] Loaded
2023-03-22T21:04:53.510Z,1679519093.510 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2023-03-22T21:04:53.512Z,1679519093.512 [HorizontalControl](DEBUG): Construct HorizontalControl.
2023-03-22T21:04:53.553Z,1679519093.553 [HorizontalControl] Loaded
2023-03-22T21:04:53.554Z,1679519093.554 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2023-03-22T21:04:53.556Z,1679519093.556 [SpeedControl](DEBUG): Construct SpeedControl.
2023-03-22T21:04:53.559Z,1679519093.559 [SpeedControl] Loaded
2023-03-22T21:04:53.559Z,1679519093.559 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2023-03-22T21:04:53.562Z,1679519093.562 [LoopControl](DEBUG): Construct LoopControl.
2023-03-22T21:04:53.562Z,1679519093.562 [LoopControl] Loaded
2023-03-22T21:04:53.563Z,1679519093.563 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2023-03-22T21:04:53.563Z,1679519093.563 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2023-03-22T21:04:53.564Z,1679519093.564 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2023-03-22T21:04:53.702Z,1679519093.702 [DeadReckonUsingMultipleVelocitySources] Loaded
2023-03-22T21:04:53.703Z,1679519093.703 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2023-03-22T21:04:53.717Z,1679519093.717 [NavChart] Loaded
2023-03-22T21:04:53.717Z,1679519093.717 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2023-03-22T21:04:53.723Z,1679519093.723 [UniversalFixResidualReporter] Loaded
2023-03-22T21:04:53.723Z,1679519093.723 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2023-03-22T21:04:53.723Z,1679519093.723 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2023-03-22T21:04:53.724Z,1679519093.724 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2023-03-22T21:04:53.924Z,1679519093.924 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2023-03-22T21:04:53.924Z,1679519093.924 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2023-03-22T21:04:54.691Z,1679519094.691 [AHRS_M2] Loaded
2023-03-22T21:04:54.691Z,1679519094.691 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2023-03-22T21:04:54.941Z,1679519094.941 [BackseatComponent] Loaded
2023-03-22T21:04:54.941Z,1679519094.941 [ComponentRegistry](DEBUG): Component "BackseatComponent" handled in its own thread.
2023-03-22T21:04:54.942Z,1679519094.942 [BackseatComponent ThreadHandler](DEBUG): Created PCaller Thread at 408F64E0
2023-03-22T21:04:54.942Z,1679519094.942 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 918
2023-03-22T21:04:54.945Z,1679519094.945 [LcmUniversalReporter] Loaded
2023-03-22T21:04:54.946Z,1679519094.946 [ComponentRegistry](DEBUG): SyncComponent "LcmUniversalReporter" handled in the control thread.
2023-03-22T21:04:55.089Z,1679519095.089 [DataOverHttps] Loaded
2023-03-22T21:04:55.089Z,1679519095.089 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2023-03-22T21:04:55.090Z,1679519095.090 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 409264E0
2023-03-22T21:04:55.091Z,1679519095.091 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 919
2023-03-22T21:04:55.111Z,1679519095.111 [Depth_Keller] Loaded
2023-03-22T21:04:55.112Z,1679519095.112 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2023-03-22T21:04:55.117Z,1679519095.117 [DropWeight] Loaded
2023-03-22T21:04:55.117Z,1679519095.117 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2023-03-22T21:04:55.155Z,1679519095.155 [DVL_micro] Loaded
2023-03-22T21:04:55.156Z,1679519095.156 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2023-03-22T21:04:55.174Z,1679519095.174 [MultiRay] Loaded
2023-03-22T21:04:55.175Z,1679519095.175 [ComponentRegistry](DEBUG): SyncComponent "MultiRay" handled in the control thread.
2023-03-22T21:04:55.333Z,1679519095.333 [NAL9602] Loaded
2023-03-22T21:04:55.333Z,1679519095.333 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2023-03-22T21:04:55.415Z,1679519095.415 [Onboard] Loaded
2023-03-22T21:04:55.415Z,1679519095.415 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2023-03-22T21:04:55.419Z,1679519095.419 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 409564E0
2023-03-22T21:04:55.420Z,1679519095.420 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 920
2023-03-22T21:04:55.432Z,1679519095.432 [Power24vConverter] Loaded
2023-03-22T21:04:55.432Z,1679519095.432 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread.
2023-03-22T21:04:55.446Z,1679519095.446 [Radio_Surface] Loaded
2023-03-22T21:04:55.446Z,1679519095.446 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2023-03-22T21:04:55.447Z,1679519095.447 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 409864E0
2023-03-22T21:04:55.447Z,1679519095.447 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 921
2023-03-22T21:04:55.762Z,1679519095.762 [DAT] Loaded
2023-03-22T21:04:55.762Z,1679519095.762 [ComponentRegistry](DEBUG): Component "DAT" handled in its own thread.
2023-03-22T21:04:55.763Z,1679519095.763 [DAT ThreadHandler](DEBUG): Created PCaller Thread at 409B64E0
2023-03-22T21:04:55.763Z,1679519095.763 [DAT ThreadHandler](INFO): Protected caller Thread ID is 922
2023-03-22T21:04:55.764Z,1679519095.764 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2023-03-22T21:04:55.765Z,1679519095.765 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2023-03-22T21:04:55.970Z,1679519095.970 [BuoyancyServo] Loaded
2023-03-22T21:04:55.971Z,1679519095.971 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2023-03-22T21:04:55.991Z,1679519095.991 [ElevatorServo] Loaded
2023-03-22T21:04:55.991Z,1679519095.991 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2023-03-22T21:04:56.011Z,1679519096.011 [MassServo] Loaded
2023-03-22T21:04:56.012Z,1679519096.012 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2023-03-22T21:04:56.030Z,1679519096.030 [RudderServo] Loaded
2023-03-22T21:04:56.031Z,1679519096.031 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2023-03-22T21:04:56.045Z,1679519096.045 [ThrusterHE] Loaded
2023-03-22T21:04:56.046Z,1679519096.046 [ComponentRegistry](DEBUG): SyncComponent "ThrusterHE" handled in the control thread.
2023-03-22T21:04:56.046Z,1679519096.046 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2023-03-22T21:04:56.047Z,1679519096.047 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2023-03-22T21:04:56.129Z,1679519096.129 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2023-03-22T21:04:56.129Z,1679519096.129 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2023-03-22T21:04:56.173Z,1679519096.173 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2023-03-22T21:04:56.174Z,1679519096.174 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2023-03-22T21:04:56.536Z,1679519096.536 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2023-03-22T21:04:56.537Z,1679519096.537 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2023-03-22T21:04:56.758Z,1679519096.758 [CTD_Seabird] Loaded
2023-03-22T21:04:56.758Z,1679519096.758 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2023-03-22T21:04:56.759Z,1679519096.759 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40B404E0
2023-03-22T21:04:56.760Z,1679519096.760 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 923
2023-03-22T21:04:56.793Z,1679519096.793 [ESPComponent] Loaded
2023-03-22T21:04:56.793Z,1679519096.793 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2023-03-22T21:04:56.813Z,1679519096.813 [PAR_Licor] Loaded
2023-03-22T21:04:56.814Z,1679519096.814 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2023-03-22T21:04:56.845Z,1679519096.845 [WetLabsBB2FL] Loaded
2023-03-22T21:04:56.845Z,1679519096.845 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2023-03-22T21:04:56.846Z,1679519096.846 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40B704E0
2023-03-22T21:04:56.847Z,1679519096.847 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 924
2023-03-22T21:04:56.848Z,1679519096.848 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2023-03-22T21:04:56.848Z,1679519096.848 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2023-03-22T21:04:57.020Z,1679519097.020 [SBIT](DEBUG): Construct Startup Built In Test.
2023-03-22T21:04:57.029Z,1679519097.029 [SBIT] Loaded
2023-03-22T21:04:57.029Z,1679519097.029 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2023-03-22T21:04:57.032Z,1679519097.032 [IBIT](DEBUG): Construct Initiated Built In Test.
2023-03-22T21:04:57.046Z,1679519097.046 [IBIT] Loaded
2023-03-22T21:04:57.046Z,1679519097.046 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2023-03-22T21:04:57.052Z,1679519097.052 [CBIT](DEBUG): Construct Continuous Built In Test.
2023-03-22T21:04:57.286Z,1679519097.286 [CBIT] Loaded
2023-03-22T21:04:57.286Z,1679519097.286 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2023-03-22T21:04:57.286Z,1679519097.286 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2023-03-22T21:04:57.293Z,1679519097.293 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2023-03-22T21:04:57.296Z,1679519097.296 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2023-03-22T21:04:57.307Z,1679519097.307 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2023-03-22T21:04:57.308Z,1679519097.308 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40BDE4E0
2023-03-22T21:04:57.309Z,1679519097.309 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 925
2023-03-22T21:04:57.313Z,1679519097.313 [Supervisor](INFO): Main Thread ID is 827
2023-03-22T21:04:57.313Z,1679519097.313 [Supervisor](DEBUG): Running supervisor.
2023-03-22T21:04:57.314Z,1679519097.314 [CommandExec ThreadHandler](INFO): Handler Thread ID is 926
2023-03-22T21:04:57.315Z,1679519097.315 [CommandExec](INFO): Initializing the command executive.
2023-03-22T21:04:57.316Z,1679519097.316 [CommandLine ThreadHandler](INFO): Handler Thread ID is 927
2023-03-22T21:04:57.318Z,1679519097.318 [controlThread ThreadHandler](INFO): Handler Thread ID is 928
2023-03-22T21:04:57.318Z,1679519097.318 [controlThread](DEBUG): Initializing ControlThread
2023-03-22T21:04:57.319Z,1679519097.319 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2023-03-22T21:04:57.320Z,1679519097.320 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2023-03-22T21:04:57.320Z,1679519097.320 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2023-03-22T21:04:57.320Z,1679519097.320 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2023-03-22T21:04:57.321Z,1679519097.321 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2023-03-22T21:04:57.321Z,1679519097.321 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2023-03-22T21:04:57.323Z,1679519097.323 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2023-03-22T21:04:57.324Z,1679519097.324 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2023-03-22T21:04:57.324Z,1679519097.324 [LoopControl](DEBUG): Initialize LoopControlComponent.
2023-03-22T21:04:57.325Z,1679519097.325 [NavChart](DEBUG): Initialize NavChart Navigation.
2023-03-22T21:04:57.326Z,1679519097.326 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2023-03-22T21:04:57.332Z,1679519097.332 [SBIT](INFO): Initialize SBIT Component.
2023-03-22T21:04:57.333Z,1679519097.333 [SBIT](IMPORTANT): git: 2023-03-22
2023-03-22T21:04:57.333Z,1679519097.333 [SBIT](INFO): git hash: 5c491c0cb5eb82ad7031eef1a23773c9f4f92690
2023-03-22T21:04:57.333Z,1679519097.333 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2023-03-22T21:04:57.334Z,1679519097.334 [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-03-22T21:04:57.335Z,1679519097.335 [SBIT](INFO): Beginning SBIT in 91.000000 seconds.
2023-03-22T21:04:57.336Z,1679519097.336 [IBIT](INFO): Initialize IBIT Component.
2023-03-22T21:04:57.337Z,1679519097.337 [CBIT](DEBUG): Initialize CBIT Component.
2023-03-22T21:04:57.338Z,1679519097.338 [logger ThreadHandler](INFO): Handler Thread ID is 929
2023-03-22T21:04:57.348Z,1679519097.348 [CBIT](DEBUG): Initialized mux pins.
2023-03-22T21:04:57.348Z,1679519097.348 [CBIT](DEBUG): Initializing the watchdog timer.
2023-03-22T21:04:57.356Z,1679519097.356 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 930
2023-03-22T21:04:57.368Z,1679519097.368 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 931
2023-03-22T21:04:57.369Z,1679519097.369 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2023-03-22T21:04:57.372Z,1679519097.372 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2023-03-22T21:04:57.372Z,1679519097.372 [CBIT](DEBUG): Initializing heartbeat.
2023-03-22T21:04:57.380Z,1679519097.380 [Onboard ThreadHandler](INFO): Handler Thread ID is 932
2023-03-22T21:04:57.398Z,1679519097.398 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 933
2023-03-22T21:04:57.420Z,1679519097.420 [DAT ThreadHandler](INFO): Handler Thread ID is 934
2023-03-22T21:04:57.421Z,1679519097.421 [DAT](INFO): Powering up
2023-03-22T21:04:57.421Z,1679519097.421 [DAT](DEBUG): Initializing DAT.
2023-03-22T21:04:57.426Z,1679519097.426 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 936
2023-03-22T21:04:57.426Z,1679519097.426 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2023-03-22T21:04:57.433Z,1679519097.433 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 938
2023-03-22T21:04:57.437Z,1679519097.437 [WetLabsBB2FL](INFO): Powering up
2023-03-22T21:04:57.438Z,1679519097.438 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 940
2023-03-22T21:04:57.444Z,1679519097.444 [CBIT](DEBUG): Deactivating GF circuits.
2023-03-22T21:04:57.444Z,1679519097.444 [CBIT](DEBUG): Deactivating emergency mode.
2023-03-22T21:04:57.446Z,1679519097.446 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2023-03-22T21:04:57.446Z,1679519097.446 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2023-03-22T21:04:57.447Z,1679519097.447 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2023-03-22T21:04:57.447Z,1679519097.447 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2023-03-22T21:04:57.447Z,1679519097.447 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2023-03-22T21:04:57.447Z,1679519097.447 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2023-03-22T21:04:57.447Z,1679519097.447 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2023-03-22T21:04:57.447Z,1679519097.447 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2023-03-22T21:04:57.484Z,1679519097.484 [CBIT](DEBUG): Backplane powered.
2023-03-22T21:04:57.485Z,1679519097.485 [MissionManager](INFO): Loading Mission from file: Missions/Startup.xml
2023-03-22T21:04:57.524Z,1679519097.524 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2023-03-22T21:04:57.543Z,1679519097.543 [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-03-22T21:04:57.568Z,1679519097.568 [MissionManager](INFO): Loading Mission from file: Missions/Default.xml
2023-03-22T21:04:57.662Z,1679519097.662 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2023-03-22T21:04:57.663Z,1679519097.663 [Default:A.Wait](DEBUG): Construct Wait.
2023-03-22T21:04:57.665Z,1679519097.665 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2023-03-22T21:04:57.706Z,1679519097.706 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2023-03-22T21:04:57.708Z,1679519097.708 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2023-03-22T21:04:57.731Z,1679519097.731 [Default:E.Execute](DEBUG): Construct Execute.
2023-03-22T21:04:57.734Z,1679519097.734 [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-03-22T21:04:57.752Z,1679519097.752 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DVL_micro,MultiRay,NAL9602,Power24vConverter,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter,
2023-03-22T21:04:57.764Z,1679519097.764 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2023-03-22T21:04:57.804Z,1679519097.804 [Radio_Surface](INFO): Powering up
2023-03-22T21:04:57.901Z,1679519097.901 [MultiRay](INFO): Powering up MultiRay Lights
2023-03-22T21:04:57.940Z,1679519097.940 [Power24vConverter](INFO): Powering up.
2023-03-22T21:04:57.984Z,1679519097.984 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2023-03-22T21:04:57.992Z,1679519097.992 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2023-03-22T21:04:57.993Z,1679519097.993 [ElevatorServo](DEBUG): Initializing EZServoServo.
2023-03-22T21:04:58.000Z,1679519098.000 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2023-03-22T21:04:58.001Z,1679519098.001 [MassServo](DEBUG): Initializing EZServoServo.
2023-03-22T21:04:58.008Z,1679519098.008 [MassServo](DEBUG): Initializing MassServo.
2023-03-22T21:04:58.009Z,1679519098.009 [RudderServo](DEBUG): Initializing EZServoServo.
2023-03-22T21:04:58.016Z,1679519098.016 [RudderServo](DEBUG): Initializing RudderServo.
2023-03-22T21:04:58.017Z,1679519098.017 [ThrusterHE](DEBUG): Initializing EZServoServo.
2023-03-22T21:04:58.024Z,1679519098.024 [ThrusterHE](DEBUG): Initializing ThrusterHE.
2023-03-22T21:04:58.908Z,1679519098.908 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2023-03-22T21:04:58.908Z,1679519098.908 [RudderServo](FAULT): Rudder failed to initialize
2023-03-22T21:04:58.908Z,1679519098.908 [RudderServo] Communications Fault, FailCount= 1
2023-03-22T21:04:58.908Z,1679519098.908 [RudderServo](ERROR): Communications Fault
2023-03-22T21:04:58.912Z,1679519098.912 [CBIT](ERROR): Communications Fault in component: RudderServo
2023-03-22T21:04:59.381Z,1679519099.381 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2023-03-22T21:04:59.381Z,1679519099.381 [RudderServo](INFO): Powering down
2023-03-22T21:04:59.836Z,1679519099.836 [RudderServo](DEBUG): Initializing EZServoServo.
2023-03-22T21:04:59.957Z,1679519099.957 [RudderServo](DEBUG): Initializing RudderServo.
2023-03-22T21:04:59.961Z,1679519099.961 [CBIT](INFO): Clearing failed state for component RudderServo
2023-03-22T21:04:59.961Z,1679519099.961 [RudderServo] No Fault, FailCount= 1
2023-03-22T21:05:00.048Z,1679519100.048 [WetLabsBB2FL](INFO): Powering down
2023-03-22T21:05:03.557Z,1679519103.557 [ThrusterHE](ERROR): Zero Speed Commanded.
2023-03-22T21:05:09.269Z,1679519109.269 [DAT](INFO): DAT read: 

2023-03-22T21:05:09.270Z,1679519109.270 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series

2023-03-22T21:05:10.781Z,1679519110.781 [DAT](INFO): DAT read: MF Frequency Band

2023-03-22T21:05:10.782Z,1679519110.782 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.15.0

2023-03-22T21:05:10.783Z,1679519110.783 [DAT](INFO): DAT read: Mar 22 2023 21:05:07 

2023-03-22T21:05:12.041Z,1679519112.041 [DAT](INFO): DAT read: Features enabled [Bearing]

2023-03-22T21:05:12.042Z,1679519112.042 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP

2023-03-22T21:05:12.043Z,1679519112.043 [DAT](INFO): commRate: 800
2023-03-22T21:05:14.108Z,1679519114.108 [DAT](INFO): entering command mode
2023-03-22T21:05:14.308Z,1679519114.308 [DAT](INFO): DAT read: 

2023-03-22T21:05:14.309Z,1679519114.309 [DAT](INFO): DAT read: user:1>

2023-03-22T21:05:14.309Z,1679519114.309 [DAT](INFO): setting verbose to 3
2023-03-22T21:05:14.561Z,1679519114.561 [DAT](INFO): DAT read: user:1>

2023-03-22T21:05:14.562Z,1679519114.562 [DAT](INFO): DAT read: Verbose         | 3           

2023-03-22T21:05:14.562Z,1679519114.562 [DAT](INFO): set verbose to 3
2023-03-22T21:05:14.562Z,1679519114.562 [DAT](INFO): setting DatVerbose to 27440
2023-03-22T21:05:14.813Z,1679519114.813 [DAT](INFO): DAT read: user:2>

2023-03-22T21:05:14.814Z,1679519114.814 [DAT](INFO): DAT read: DatVerbose      | 27440       

2023-03-22T21:05:14.815Z,1679519114.815 [DAT](INFO): set DatVerbose to 27440
2023-03-22T21:05:14.815Z,1679519114.815 [DAT](INFO): setting transmit power to 8
2023-03-22T21:05:15.064Z,1679519115.064 [DAT](INFO): DAT read: user:3>

2023-03-22T21:05:15.065Z,1679519115.065 [DAT](INFO): DAT read: TxPower         | 8 (Max)     

2023-03-22T21:05:15.066Z,1679519115.066 [DAT](INFO): set transmit power to 8
2023-03-22T21:05:15.066Z,1679519115.066 [DAT](INFO): setting local address to 8
2023-03-22T21:05:15.317Z,1679519115.317 [DAT](INFO): DAT read: user:4>

2023-03-22T21:05:15.318Z,1679519115.318 [DAT](INFO): DAT read: LocalAddr       | 8           

2023-03-22T21:05:15.318Z,1679519115.318 [DAT](INFO): set local address to 8
2023-03-22T21:05:15.319Z,1679519115.319 [DAT](INFO): Setting time to: 21:5:15 And date to:3/22/2023
2023-03-22T21:05:15.568Z,1679519115.568 [DAT](INFO): DAT read: user:5>

2023-03-22T21:05:15.569Z,1679519115.569 [DAT](INFO): DAT read: Wed Mar 22, 2023  21:05:15  

2023-03-22T21:05:15.570Z,1679519115.570 [DAT](INFO): Local DAT time set to Wed Mar 22, 2023  21:05:15  

2023-03-22T21:05:25.681Z,1679519125.681 [NAL9602](INFO): Powering up NAL9602
2023-03-22T21:05:36.583Z,1679519136.583 [NAL9602](INFO): NAL9602 initialized
2023-03-22T21:05:51.150Z,1679519151.150 [DVL_micro](ERROR): only read 3 of 4 data items
2023-03-22T21:05:51.150Z,1679519151.150 [DVL_micro](ERROR): Failed to parse:
:BI,+00070,-0075,+00000,I
2023-03-22T21:06:24.658Z,1679519184.658 [DVL_micro](ERROR): only read 1 of 4 data items
2023-03-22T21:06:24.658Z,1679519184.658 [DVL_micro](ERROR): Failed to parse:
:RD,+9999..99,+9999.99,+9999.99
2023-03-22T21:06:29.126Z,1679519189.126 [SBIT](IMPORTANT): Beginning Startup BIT
2023-03-22T21:06:29.130Z,1679519189.130 [CBIT](IMPORTANT): Beginning ground fault scan
2023-03-22T21:06:40.435Z,1679519200.435 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): 0.022446
CHAN A1 (24V): 0.005910
CHAN A2 (12V): -0.010928
CHAN A3 (5V): -0.014442
CHAN B0 (3.3V): -0.006770
CHAN B1 (3.15aV): -0.002657
CHAN B2 (3.15bV): -0.002996
CHAN B3 (GND): -0.007409
OPEN: 0.000888
Full Scale: +/- 1 mA
2023-03-22T21:06:52.543Z,1679519212.543 [DVL_micro](ERROR): Failed to parse:
:000000000,.0,0000.0,10
2023-03-22T21:07:23.271Z,1679519243.271 [SBIT](IMPORTANT): SBIT PASSED
2023-03-22T21:07:23.272Z,1679519243.272 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2023-03-22T21:07:23.273Z,1679519243.273 [SBIT](IMPORTANT): BPC1.batteryMissingStickThreshold=35 count;

2023-03-22T21:07:23.273Z,1679519243.273 [SBIT](IMPORTANT): CBIT.runNavErrorCritical=0 bool;

2023-03-22T21:07:23.273Z,1679519243.273 [SBIT](IMPORTANT): CTD_Seabird.minSalinityBound=0 practical_salinity_unit;

2023-03-22T21:07:23.273Z,1679519243.273 [SBIT](IMPORTANT): DAT.sbdAddress=-1 enum;

2023-03-22T21:07:23.273Z,1679519243.273 [SBIT](IMPORTANT): Depth_Keller.offset=3.9 decibar;

2023-03-22T21:07:23.273Z,1679519243.273 [SBIT](IMPORTANT): Express mostRecent CBIT.ampHoursUsed;

2023-03-22T21:07:23.273Z,1679519243.273 [SBIT](IMPORTANT): Express none WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water;

2023-03-22T21:07:23.273Z,1679519243.273 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=547.568399 cubic_centimeter;

2023-03-22T21:07:23.274Z,1679519243.274 [SBIT](IMPORTANT): VerticalControl.massDefault=-1.8 centimeter;

2023-03-22T21:07:23.274Z,1679519243.274 [SBIT](IMPORTANT): VerticalControl.massPositionLimitAft=-28 millimeter;

2023-03-22T21:07:23.274Z,1679519243.274 [SBIT](IMPORTANT): VerticalControl.massPositionLimitFwd=32 millimeter;

2023-03-22T21:07:23.274Z,1679519243.274 [SBIT](IMPORTANT): VerticalControl.surfaceThreshold=1.5 meter;

2023-03-22T21:07:23.658Z,1679519243.658 [MissionManager](IMPORTANT): Started mission Startup
2023-03-22T21:07:23.658Z,1679519243.658 [Startup] Running Loop=1
2023-03-22T21:07:23.658Z,1679519243.658 [Startup](DEBUG): Aggregate::initialize Startup
2023-03-22T21:07:23.659Z,1679519243.659 [Startup:A.GoToSurface] Running Loop=1
2023-03-22T21:07:23.659Z,1679519243.659 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2023-03-22T21:07:23.659Z,1679519243.659 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2023-03-22T21:07:23.660Z,1679519243.660 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2023-03-22T21:07:23.660Z,1679519243.660 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2023-03-22T21:07:23.661Z,1679519243.661 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2023-03-22T21:07:23.661Z,1679519243.661 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2023-03-22T21:07:23.662Z,1679519243.662 [Startup:StartupSatComms] Running Loop=1
2023-03-22T21:07:23.662Z,1679519243.662 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2023-03-22T21:07:23.662Z,1679519243.662 [Startup:StartupSatComms:A] Running Loop=1
2023-03-22T21:07:24.078Z,1679519244.078 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2023-03-22T21:07:38.602Z,1679519258.602 [NAL9602](INFO): SBD MO Status=2, MOMSN=14611, MT Status=2, MTMSN=0
2023-03-22T21:07:38.602Z,1679519258.602 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T21:07:55.426Z,1679519275.426 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004051
2023-03-22T21:07:57.594Z,1679519277.594 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2023-03-22T21:07:57.594Z,1679519277.594 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-03-22T21:07:57.604Z,1679519277.604 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-03-22T21:07:58.013Z,1679519278.013 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-03-22T21:07:58.013Z,1679519278.013 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2023-03-22T21:08:15.533Z,1679519295.533 [DAT](INFO): DAT read: user:6>Lowpower

2023-03-22T21:08:15.533Z,1679519295.533 [DAT](DEBUG): Re-entering command mode due to deviceResponse_: user:6>Lowpower

2023-03-22T21:08:23.988Z,1679519303.988 [Startup:StartupSatComms:A](INFO): Timed out from 2023-03-22T21:07:23.7Z
2023-03-22T21:08:23.988Z,1679519303.988 [Startup:StartupSatComms:A] Stopped
2023-03-22T21:08:23.988Z,1679519303.988 [Startup:StartupSatComms:B] Running Loop=1
2023-03-22T21:08:24.343Z,1679519304.343 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2023-03-22T21:08:29.005Z,1679519309.005 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20230321T191328/Courier0421.lzma
2023-03-22T21:08:30.016Z,1679519310.016 [DataOverHttps](INFO): Moved sent file to Logs/20230321T191328/Courier0421.lzma.bak
2023-03-22T21:08:30.017Z,1679519310.017 [DataOverHttps](INFO): SBD MOMSN=17542625
2023-03-22T21:08:47.298Z,1679519327.298 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20230322T210446/Courier0000.lzma
2023-03-22T21:08:48.300Z,1679519328.300 [DataOverHttps](INFO): Moved sent file to Logs/20230322T210446/Courier0000.lzma.bak
2023-03-22T21:08:48.300Z,1679519328.300 [DataOverHttps](INFO): SBD MOMSN=17542627
2023-03-22T21:08:49.447Z,1679519329.447 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-03-22T21:08:49.447Z,1679519329.447 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+18.0,009.0,000
2023-03-22T21:09:07.915Z,1679519347.915 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20230321T191328/Express0419.lzma
2023-03-22T21:09:08.916Z,1679519348.916 [DataOverHttps](INFO): Moved sent file to Logs/20230321T191328/Express0419.lzma.bak
2023-03-22T21:09:08.916Z,1679519348.916 [DataOverHttps](INFO): SBD MOMSN=17542630
2023-03-22T21:09:24.224Z,1679519364.224 [Startup:StartupSatComms:B](INFO): Timed out from 2023-03-22T21:08:23.0Z
2023-03-22T21:09:24.224Z,1679519364.224 [Startup:StartupSatComms:B] Stopped
2023-03-22T21:09:24.224Z,1679519364.224 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2023-03-22T21:09:24.224Z,1679519364.224 [Startup:StartupSatComms] Stopped
2023-03-22T21:09:24.224Z,1679519364.224 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2023-03-22T21:09:24.225Z,1679519364.225 [Startup](INFO): Completed Startup
2023-03-22T21:09:24.225Z,1679519364.225 [MissionManager](INFO): Startup is completed.
2023-03-22T21:09:24.225Z,1679519364.225 [MissionManager](INFO): Uninitializing Mission Startup
2023-03-22T21:09:24.225Z,1679519364.225 [Startup] Stopped
2023-03-22T21:09:24.225Z,1679519364.225 [Startup](DEBUG): Aggregate::uninitialize Startup
2023-03-22T21:09:24.225Z,1679519364.225 [Startup:A.GoToSurface] Stopped
2023-03-22T21:09:24.225Z,1679519364.225 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2023-03-22T21:09:24.631Z,1679519364.631 [MissionManager](IMPORTANT): Started mission Default
2023-03-22T21:09:24.631Z,1679519364.631 [Default] Running Loop=1
2023-03-22T21:09:24.631Z,1679519364.631 [Default](DEBUG): Aggregate::initialize Default
2023-03-22T21:09:24.631Z,1679519364.631 [Default:B.GoToSurface] Running Loop=1
2023-03-22T21:09:24.631Z,1679519364.631 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2023-03-22T21:09:24.632Z,1679519364.632 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2023-03-22T21:09:24.632Z,1679519364.632 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2023-03-22T21:09:24.632Z,1679519364.632 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2023-03-22T21:09:24.633Z,1679519364.633 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2023-03-22T21:09:24.633Z,1679519364.633 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2023-03-22T21:09:24.633Z,1679519364.633 [Default:A.Wait] Running Loop=1
2023-03-22T21:09:24.633Z,1679519364.633 [Default:A.Wait](DEBUG): Initialize Wait Component.
2023-03-22T21:09:27.591Z,1679519367.591 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20230321T191328/Express0422.lzma
2023-03-22T21:09:28.592Z,1679519368.592 [DataOverHttps](INFO): Moved sent file to Logs/20230321T191328/Express0422.lzma.bak
2023-03-22T21:09:28.592Z,1679519368.592 [DataOverHttps](INFO): SBD MOMSN=17542635
2023-03-22T21:09:37.954Z,1679519377.954 [Default:A.Wait](INFO): Done Waiting.
2023-03-22T21:09:37.954Z,1679519377.954 [Default:A.Wait] Stopped
2023-03-22T21:09:37.954Z,1679519377.954 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T21:09:38.490Z,1679519378.490 [Default:CheckIn] Running Loop=1
2023-03-22T21:09:38.490Z,1679519378.490 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T21:09:38.491Z,1679519378.491 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T21:09:38.866Z,1679519378.866 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2023-03-22T21:10:40.141Z,1679519440.141 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-03-22T21:10:58.751Z,1679519458.751 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2023-03-22T21:10:58.751Z,1679519458.751 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-03-22T21:10:58.786Z,1679519458.786 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-03-22T21:10:59.169Z,1679519459.169 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-03-22T21:10:59.170Z,1679519459.170 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2023-03-22T21:12:49.826Z,1679519569.826 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-03-22T21:12:49.826Z,1679519569.826 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+1.0,1489.0,000
2023-03-22T21:13:59.773Z,1679519639.773 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2023-03-22T21:13:59.773Z,1679519639.773 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-03-22T21:13:59.789Z,1679519639.789 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-03-22T21:14:00.197Z,1679519640.197 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-03-22T21:14:00.197Z,1679519640.197 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2023-03-22T21:14:38.549Z,1679519678.549 [Default:CheckIn:Read_GPS](INFO): Timed out from 2023-03-22T21:09:38.5Z
2023-03-22T21:14:38.549Z,1679519678.549 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T21:14:38.549Z,1679519678.549 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T21:14:38.964Z,1679519678.964 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2023-03-22T21:14:47.469Z,1679519687.469 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20230322T210446/Courier0004.lzma
2023-03-22T21:14:48.472Z,1679519688.472 [DataOverHttps](INFO): Moved sent file to Logs/20230322T210446/Courier0004.lzma.bak
2023-03-22T21:14:48.472Z,1679519688.472 [DataOverHttps](INFO): SBD MOMSN=17542650
2023-03-22T21:15:07.389Z,1679519707.389 [DataOverHttps](INFO): Sending 145 bytes from file Logs/20230321T191328/Express0425.lzma
2023-03-22T21:15:08.064Z,1679519708.064 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,211504.00,A,3648.17525,N,12147.27474,W,0.019,168.97,220323,,,D*7F
2023-03-22T21:15:08.124Z,1679519708.124 [NAL9602](INFO): GPS fix at 20230322T211504: (36.802921, -121.787912)
2023-03-22T21:15:08.380Z,1679519708.380 [DataOverHttps](INFO): Moved sent file to Logs/20230321T191328/Express0425.lzma.bak
2023-03-22T21:15:08.380Z,1679519708.380 [DataOverHttps](INFO): SBD MOMSN=17542658
2023-03-22T21:15:30.391Z,1679519730.391 [DataOverHttps](INFO): Sending 980 bytes from file Logs/20230322T210446/Express0001.lzma
2023-03-22T21:15:31.380Z,1679519731.380 [DataOverHttps](INFO): Moved sent file to Logs/20230322T210446/Express0001.lzma.bak
2023-03-22T21:15:31.380Z,1679519731.380 [DataOverHttps](INFO): SBD MOMSN=17542661
2023-03-22T21:15:40.356Z,1679519740.356 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T21:15:56.313Z,1679519756.313 [DataOverHttps](INFO): Sending 188 bytes from file Logs/20230322T210446/Express0005.lzma
2023-03-22T21:15:57.316Z,1679519757.316 [DataOverHttps](INFO): Moved sent file to Logs/20230322T210446/Express0005.lzma.bak
2023-03-22T21:15:57.316Z,1679519757.316 [DataOverHttps](INFO): SBD MOMSN=17542685
2023-03-22T21:16:01.473Z,1679519761.473 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T21:16:01.473Z,1679519761.473 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T21:16:01.473Z,1679519761.473 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T21:16:29.343Z,1679519789.343 [DVL_micro](ERROR): only read 2 of 4 data items
2023-03-22T21:16:29.343Z,1679519789.343 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999..99,+9999.99
2023-03-22T21:19:56.924Z,1679519996.924 [CommandExec](IMPORTANT): got command get depth
2023-03-22T21:19:56.924Z,1679519996.924 [CommandExec](IMPORTANT): depth 0.222698 m
2023-03-22T21:20:31.618Z,1679520031.618 [CommandExec](IMPORTANT): got command failComponent
2023-03-22T21:20:31.619Z,1679520031.619 [CommandExec](IMPORTANT): Failed components:
2023-03-22T21:20:31.619Z,1679520031.619 [CommandExec](IMPORTANT): No failed Components.
2023-03-22T21:21:02.125Z,1679520062.125 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T21:21:02.126Z,1679520062.126 [Default:CheckIn:C.Wait] Stopped
2023-03-22T21:21:02.126Z,1679520062.126 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T21:21:02.126Z,1679520062.126 [Default:CheckIn:D] Running Loop=1
2023-03-22T21:21:02.545Z,1679520062.545 [Default:CheckIn:D] Stopped
2023-03-22T21:21:02.545Z,1679520062.545 [Default:CheckIn:E] Running Loop=1
2023-03-22T21:21:02.935Z,1679520062.935 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 11.631891 min 
2023-03-22T21:21:02.935Z,1679520062.935 [Default:CheckIn:E] Stopped
2023-03-22T21:21:02.935Z,1679520062.935 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T21:21:02.935Z,1679520062.935 [Default:CheckIn] Stopped
2023-03-22T21:21:02.935Z,1679520062.935 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T21:21:02.935Z,1679520062.935 [Default:CheckIn](INFO): Running loop #2
2023-03-22T21:21:02.935Z,1679520062.935 [Default:CheckIn] Running Loop=2
2023-03-22T21:21:02.936Z,1679520062.936 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T21:21:02.936Z,1679520062.936 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T21:21:04.942Z,1679520064.942 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,212104.00,A,3648.16646,N,12147.28592,W,0.078,168.97,220323,,,D*7E
2023-03-22T21:21:04.944Z,1679520064.944 [NAL9602](INFO): GPS fix at 20230322T212104: (36.802774, -121.788099)
2023-03-22T21:21:04.955Z,1679520064.955 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T21:21:04.955Z,1679520064.955 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T21:21:07.771Z,1679520067.771 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-03-22T21:21:07.771Z,1679520067.771 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+18.11489.0,000
2023-03-22T21:21:14.449Z,1679520074.449 [DataOverHttps](INFO): Sending 223 bytes from file Logs/20230322T210446/Courier0007.lzma
2023-03-22T21:21:15.452Z,1679520075.452 [DataOverHttps](INFO): Moved sent file to Logs/20230322T210446/Courier0007.lzma.bak
2023-03-22T21:21:15.452Z,1679520075.452 [DataOverHttps](INFO): SBD MOMSN=17542695
2023-03-22T21:21:34.902Z,1679520094.902 [DataOverHttps](INFO): Sending 443 bytes from file Logs/20230322T210446/Express0008.lzma
2023-03-22T21:21:35.657Z,1679520095.657 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2023-03-22T21:21:35.734Z,1679520095.734 [NAL9602](ERROR): received: 
+CSQ:0

OK611, 2, 0, 0, 0

OK
2023-03-22T21:21:35.904Z,1679520095.904 [DataOverHttps](INFO): Moved sent file to Logs/20230322T210446/Express0008.lzma.bak
2023-03-22T21:21:35.904Z,1679520095.904 [DataOverHttps](INFO): SBD MOMSN=17542698
2023-03-22T21:21:40.519Z,1679520100.519 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T21:21:40.519Z,1679520100.519 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T21:21:40.519Z,1679520100.519 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T21:21:48.598Z,1679520108.598 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-03-22T21:21:48.598Z,1679520108.598 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,31,0000.0,1489.0,000
2023-03-22T21:23:00.195Z,1679520180.195 [DVL_micro](ERROR): only read 3 of 4 data items
2023-03-22T21:23:00.195Z,1679520180.195 [DVL_micro](ERROR): Failed to parse:
:BI,+00319,+0040,+00000,I
2023-03-22T21:23:39.785Z,1679520219.785 [NAL9602](INFO): SBD MO Status=2, MOMSN=14611, MT Status=2, MTMSN=0
2023-03-22T21:23:39.785Z,1679520219.785 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T21:23:53.993Z,1679520233.993 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-03-22T21:23:53.994Z,1679520233.994 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000,+18.1,0000.0,1489.0,000
2023-03-22T21:25:46.322Z,1679520346.322 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-03-22T21:25:46.322Z,1679520346.322 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000,+18.1,0000.0,1489.0,000
2023-03-22T21:26:07.325Z,1679520367.325 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-03-22T21:26:38.023Z,1679520398.023 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T21:26:41.265Z,1679520401.265 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T21:26:41.265Z,1679520401.265 [Default:CheckIn:C.Wait] Stopped
2023-03-22T21:26:41.265Z,1679520401.265 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T21:26:41.265Z,1679520401.265 [Default:CheckIn:D] Running Loop=1
2023-03-22T21:26:41.674Z,1679520401.674 [Default:CheckIn:D] Stopped
2023-03-22T21:26:41.674Z,1679520401.674 [Default:CheckIn:E] Running Loop=1
2023-03-22T21:26:42.084Z,1679520402.084 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 17.284041 min 
2023-03-22T21:26:42.085Z,1679520402.085 [Default:CheckIn:E] Stopped
2023-03-22T21:26:42.085Z,1679520402.085 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T21:26:42.085Z,1679520402.085 [Default:CheckIn] Stopped
2023-03-22T21:26:42.085Z,1679520402.085 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T21:26:42.085Z,1679520402.085 [Default:CheckIn](INFO): Running loop #3
2023-03-22T21:26:42.085Z,1679520402.085 [Default:CheckIn] Running Loop=3
2023-03-22T21:26:42.085Z,1679520402.085 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T21:26:42.085Z,1679520402.085 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T21:26:44.085Z,1679520404.085 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,212643.00,A,3648.16901,N,12147.27980,W,0.622,150.76,220323,,,D*7B
2023-03-22T21:26:44.088Z,1679520404.088 [NAL9602](INFO): GPS fix at 20230322T212643: (36.802817, -121.787997)
2023-03-22T21:26:44.138Z,1679520404.138 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T21:26:44.139Z,1679520404.139 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T21:26:49.219Z,1679520409.219 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20230322T210446/Courier0010.lzma
2023-03-22T21:26:50.223Z,1679520410.224 [DataOverHttps](INFO): Moved sent file to Logs/20230322T210446/Courier0010.lzma.bak
2023-03-22T21:26:50.224Z,1679520410.224 [DataOverHttps](INFO): SBD MOMSN=17542720
2023-03-22T21:27:09.334Z,1679520429.334 [DataOverHttps](INFO): Sending 217 bytes from file Logs/20230322T210446/Express0011.lzma
2023-03-22T21:27:10.336Z,1679520430.336 [DataOverHttps](INFO): Moved sent file to Logs/20230322T210446/Express0011.lzma.bak
2023-03-22T21:27:10.336Z,1679520430.336 [DataOverHttps](INFO): SBD MOMSN=17542723
2023-03-22T21:27:14.898Z,1679520434.898 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T21:27:14.898Z,1679520434.898 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T21:27:14.899Z,1679520434.899 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T21:29:57.749Z,1679520597.749 [NAL9602](INFO): SBD MO Status=2, MOMSN=14611, MT Status=2, MTMSN=0
2023-03-22T21:29:57.750Z,1679520597.750 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T21:30:54.723Z,1679520654.723 [NAL9602](INFO): SBD MO Status=0, MOMSN=14611, MT Status=0, MTMSN=0
2023-03-22T21:30:54.723Z,1679520654.723 [NAL9602](INFO): No messages in MT queue
2023-03-22T21:31:07.539Z,1679520667.539 [DataOverHttps](IMPORTANT): SBD MTMSN=20230322T213106
2023-03-22T21:31:14.878Z,1679520674.878 [DataOverHttps](INFO): Received command: ibit
2023-03-22T21:31:14.959Z,1679520674.959 [CommandExec](IMPORTANT): got command ibit
2023-03-22T21:31:15.340Z,1679520675.340 [IBIT](IMPORTANT): Beginning Initiated BIT
2023-03-22T21:31:15.340Z,1679520675.340 [IBIT](IMPORTANT): Beginning control surface checks.
2023-03-22T21:31:15.343Z,1679520675.343 [CBIT](IMPORTANT): Beginning ground fault scan
2023-03-22T21:31:16.932Z,1679520676.932 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213116.00,A,3648.14634,N,12147.25403,W,2.022,146.86,220323,,,D*7E
2023-03-22T21:31:16.945Z,1679520676.945 [NAL9602](INFO): GPS fix at 20230322T213116: (36.802439, -121.787567)
2023-03-22T21:31:19.760Z,1679520679.760 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213119.00,A,3648.14548,N,12147.25236,W,1.594,132.01,220323,,,D*7E
2023-03-22T21:31:19.777Z,1679520679.777 [NAL9602](INFO): GPS fix at 20230322T213119: (36.802425, -121.787539)
2023-03-22T21:31:23.000Z,1679520683.000 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213122.00,A,3648.14465,N,12147.25093,W,2.177,120.62,220323,,,D*79
2023-03-22T21:31:23.003Z,1679520683.003 [NAL9602](INFO): GPS fix at 20230322T213122: (36.802411, -121.787515)
2023-03-22T21:31:25.840Z,1679520685.840 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213125.00,A,3648.14377,N,12147.24942,W,1.827,120.33,220323,,,D*75
2023-03-22T21:31:25.842Z,1679520685.842 [NAL9602](INFO): GPS fix at 20230322T213125: (36.802396, -121.787490)
2023-03-22T21:31:26.274Z,1679520686.274 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): 0.025237
CHAN A1 (24V): 0.007885
CHAN A2 (12V): -0.012247
CHAN A3 (5V): -0.017750
CHAN B0 (3.3V): -0.008598
CHAN B1 (3.15aV): -0.003163
CHAN B2 (3.15bV): -0.000708
CHAN B3 (GND): -0.008794
OPEN: 0.005965
Full Scale: +/- 1 mA
2023-03-22T21:31:29.052Z,1679520689.052 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213128.00,A,3648.14309,N,12147.24738,W,2.138,113.44,220323,,,D*76
2023-03-22T21:31:29.054Z,1679520689.054 [NAL9602](INFO): GPS fix at 20230322T213128: (36.802385, -121.787456)
2023-03-22T21:31:31.881Z,1679520691.881 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213131.00,A,3648.14241,N,12147.24514,W,2.060,110.46,220323,,,D*72
2023-03-22T21:31:31.883Z,1679520691.883 [NAL9602](INFO): GPS fix at 20230322T213131: (36.802374, -121.787419)
2023-03-22T21:31:35.114Z,1679520695.114 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213134.00,A,3648.14179,N,12147.24340,W,1.905,112.88,220323,,,D*71
2023-03-22T21:31:35.116Z,1679520695.116 [NAL9602](INFO): GPS fix at 20230322T213134: (36.802363, -121.787390)
2023-03-22T21:31:37.940Z,1679520697.940 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213137.00,A,3648.14182,N,12147.24303,W,0.272,112.88,220323,,,A*7E
2023-03-22T21:31:37.942Z,1679520697.942 [NAL9602](INFO): GPS fix at 20230322T213137: (36.802364, -121.787384)
2023-03-22T21:31:40.768Z,1679520700.768 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213140.00,A,3648.14176,N,12147.24302,W,0.097,112.88,220323,,,A*7D
2023-03-22T21:31:40.771Z,1679520700.771 [NAL9602](INFO): GPS fix at 20230322T213140: (36.802363, -121.787384)
2023-03-22T21:31:44.022Z,1679520704.022 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213143.00,A,3648.14186,N,12147.24325,W,0.136,112.88,220323,,,A*7E
2023-03-22T21:31:44.025Z,1679520704.025 [NAL9602](INFO): GPS fix at 20230322T213143: (36.802364, -121.787387)
2023-03-22T21:31:46.866Z,1679520706.866 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213146.00,A,3648.14203,N,12147.24349,W,0.097,112.88,220323,,,A*75
2023-03-22T21:31:46.868Z,1679520706.868 [NAL9602](INFO): GPS fix at 20230322T213146: (36.802367, -121.787391)
2023-03-22T21:31:50.129Z,1679520710.129 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213149.00,A,3648.14219,N,12147.24370,W,0.214,112.88,220323,,,A*72
2023-03-22T21:31:50.132Z,1679520710.132 [NAL9602](INFO): GPS fix at 20230322T213149: (36.802370, -121.787395)
2023-03-22T21:31:52.967Z,1679520712.967 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213152.00,A,3648.14246,N,12147.24400,W,0.117,112.88,220323,,,A*72
2023-03-22T21:31:52.969Z,1679520712.969 [NAL9602](INFO): GPS fix at 20230322T213152: (36.802374, -121.787400)
2023-03-22T21:31:55.788Z,1679520715.788 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213155.00,A,3648.14274,N,12147.24435,W,0.097,112.88,220323,,,A*7B
2023-03-22T21:31:55.791Z,1679520715.791 [NAL9602](INFO): GPS fix at 20230322T213155: (36.802379, -121.787406)
2023-03-22T21:31:59.055Z,1679520719.055 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213158.00,A,3648.14293,N,12147.24467,W,0.117,112.88,220323,,,A*71
2023-03-22T21:31:59.057Z,1679520719.057 [NAL9602](INFO): GPS fix at 20230322T213158: (36.802382, -121.787411)
2023-03-22T21:32:01.895Z,1679520721.895 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213201.00,A,3648.14301,N,12147.24519,W,0.486,112.88,220323,,,A*71
2023-03-22T21:32:01.897Z,1679520721.897 [NAL9602](INFO): GPS fix at 20230322T213201: (36.802383, -121.787420)
2023-03-22T21:32:01.971Z,1679520721.971 [IBIT](IMPORTANT): Communications Status:
Fix Status: 1
Iridium Signal Strength: 4
Latitude: 36.802383 Longitude: -121.787422
2023-03-22T21:32:02.312Z,1679520722.312 [IBIT](FAULT): Warning: Battery Data not active. Expected only when running primaries. Threshold checking not active.
2023-03-22T21:32:02.685Z,1679520722.685 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2023-03-22T21:32:02.685Z,1679520722.685 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2023-03-22T21:32:02.694Z,1679520722.694 [IBIT](IMPORTANT): Pressure:9.660338 PSI
2023-03-22T21:32:02.694Z,1679520722.694 [IBIT](IMPORTANT): Humidity:11.463801 %
2023-03-22T21:32:03.104Z,1679520723.104 [IBIT](IMPORTANT): Vehicle Pitch:-0.915858 degrees
2023-03-22T21:32:03.104Z,1679520723.104 [IBIT](IMPORTANT): Vehicle  Roll:-0.615088 degrees
2023-03-22T21:32:03.104Z,1679520723.104 [IBIT](IMPORTANT): Vehicle  Heading:187.229568 degrees
2023-03-22T21:32:03.488Z,1679520723.488 [IBIT](IMPORTANT): surfaceThreshold: 1.500000 m
2023-03-22T21:32:03.488Z,1679520723.488 [IBIT](IMPORTANT): buoyancyNeutral: 547.568420 cc
2023-03-22T21:32:03.489Z,1679520723.489 [IBIT](IMPORTANT): massDefault: -1.800000 cm
2023-03-22T21:32:03.489Z,1679520723.489 [IBIT](IMPORTANT): stopDepth: 265.000000 m
2023-03-22T21:32:03.489Z,1679520723.489 [IBIT](IMPORTANT): abortDepth: 300.000000 m
2023-03-22T21:32:03.489Z,1679520723.489 [IBIT](IMPORTANT): IBIT PASSED
2023-03-22T21:32:15.614Z,1679520735.614 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T21:32:15.614Z,1679520735.614 [Default:CheckIn:C.Wait] Stopped
2023-03-22T21:32:15.614Z,1679520735.614 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T21:32:15.614Z,1679520735.614 [Default:CheckIn:D] Running Loop=1
2023-03-22T21:32:16.001Z,1679520736.001 [Default:CheckIn:D] Stopped
2023-03-22T21:32:16.002Z,1679520736.002 [Default:CheckIn:E] Running Loop=1
2023-03-22T21:32:16.401Z,1679520736.401 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 22.856169 min 
2023-03-22T21:32:16.401Z,1679520736.401 [Default:CheckIn:E] Stopped
2023-03-22T21:32:16.401Z,1679520736.401 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T21:32:16.401Z,1679520736.401 [Default:CheckIn] Stopped
2023-03-22T21:32:16.402Z,1679520736.402 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T21:32:16.402Z,1679520736.402 [Default:CheckIn](INFO): Running loop #4
2023-03-22T21:32:16.402Z,1679520736.402 [Default:CheckIn] Running Loop=4
2023-03-22T21:32:16.402Z,1679520736.402 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T21:32:16.402Z,1679520736.402 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T21:32:18.413Z,1679520738.413 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213217.00,A,3648.14203,N,12147.24543,W,0.622,112.88,220323,,,A*76
2023-03-22T21:32:18.415Z,1679520738.415 [NAL9602](INFO): GPS fix at 20230322T213217: (36.802367, -121.787424)
2023-03-22T21:32:18.426Z,1679520738.426 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T21:32:18.426Z,1679520738.426 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T21:32:27.513Z,1679520747.513 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20230322T210446/Courier0013.lzma
2023-03-22T21:32:30.307Z,1679520750.307 [DataOverHttps](INFO): Moved sent file to Logs/20230322T210446/Courier0013.lzma.bak
2023-03-22T21:32:30.307Z,1679520750.307 [DataOverHttps](INFO): SBD MOMSN=17542736
2023-03-22T21:32:48.851Z,1679520768.851 [DataOverHttps](INFO): Sending 804 bytes from file Logs/20230322T210446/Express0014.lzma
2023-03-22T21:32:49.852Z,1679520769.852 [DataOverHttps](INFO): Moved sent file to Logs/20230322T210446/Express0014.lzma.bak
2023-03-22T21:32:49.852Z,1679520769.852 [DataOverHttps](INFO): SBD MOMSN=17542739
2023-03-22T21:32:50.348Z,1679520770.348 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T21:33:10.518Z,1679520790.518 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20230322T210446/Express0015.lzma
2023-03-22T21:33:11.520Z,1679520791.520 [DataOverHttps](INFO): Moved sent file to Logs/20230322T210446/Express0015.lzma.bak
2023-03-22T21:33:11.520Z,1679520791.520 [DataOverHttps](INFO): SBD MOMSN=17542763
2023-03-22T21:33:15.794Z,1679520795.794 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-03-22T21:33:15.794Z,1679520795.794 [DVL_micro](ERROR): Failed to parse:
:TS,000000,35.0,+18.2,0000.0,1489.WI,+00121,-00065,+00001,+00000,A
2023-03-22T21:33:15.846Z,1679520795.846 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T21:33:15.846Z,1679520795.846 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T21:33:15.846Z,1679520795.846 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T21:35:15.856Z,1679520915.856 [DVL_micro](ERROR): only read 3 of 4 data items
2023-03-22T21:35:15.856Z,1679520915.856 [DVL_micro](ERROR): Failed to parse:
:BI,+00212,-01616,+00297,+

2023-03-22T21:38:16.522Z,1679521096.522 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T21:38:16.522Z,1679521096.522 [Default:CheckIn:C.Wait] Stopped
2023-03-22T21:38:16.523Z,1679521096.523 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T21:38:16.523Z,1679521096.523 [Default:CheckIn:D] Running Loop=1
2023-03-22T21:38:16.940Z,1679521096.940 [Default:CheckIn:D] Stopped
2023-03-22T21:38:16.940Z,1679521096.940 [Default:CheckIn:E] Running Loop=1
2023-03-22T21:38:17.332Z,1679521097.332 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 28.871806 min 
2023-03-22T21:38:17.332Z,1679521097.332 [Default:CheckIn:E] Stopped
2023-03-22T21:38:17.332Z,1679521097.332 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T21:38:17.332Z,1679521097.332 [Default:CheckIn] Stopped
2023-03-22T21:38:17.332Z,1679521097.332 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T21:38:17.333Z,1679521097.333 [Default:CheckIn](INFO): Running loop #5
2023-03-22T21:38:17.333Z,1679521097.333 [Default:CheckIn] Running Loop=5
2023-03-22T21:38:17.333Z,1679521097.333 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T21:38:17.333Z,1679521097.333 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T21:38:19.345Z,1679521099.345 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213818.00,A,3648.15173,N,12147.22024,W,0.117,5.64,220323,,,A*70
2023-03-22T21:38:19.355Z,1679521099.355 [NAL9602](INFO): GPS fix at 20230322T213818: (36.802529, -121.787004)
2023-03-22T21:38:19.365Z,1679521099.365 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T21:38:19.365Z,1679521099.365 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T21:38:28.973Z,1679521108.973 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20230322T210446/Courier0018.lzma
2023-03-22T21:38:29.976Z,1679521109.976 [DataOverHttps](INFO): Moved sent file to Logs/20230322T210446/Courier0018.lzma.bak
2023-03-22T21:38:29.976Z,1679521109.976 [DataOverHttps](INFO): SBD MOMSN=17542780
2023-03-22T21:38:48.834Z,1679521128.834 [NAL9602](INFO): SBD MO Status=2, MOMSN=14612, MT Status=2, MTMSN=0
2023-03-22T21:38:48.834Z,1679521128.834 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T21:38:49.233Z,1679521129.233 [DataOverHttps](INFO): Sending 141 bytes from file Logs/20230322T210446/Express0019.lzma
2023-03-22T21:38:50.236Z,1679521130.236 [DataOverHttps](INFO): Moved sent file to Logs/20230322T210446/Express0019.lzma.bak
2023-03-22T21:38:50.236Z,1679521130.236 [DataOverHttps](INFO): SBD MOMSN=17542784
2023-03-22T21:38:54.920Z,1679521134.920 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T21:38:54.920Z,1679521134.920 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T21:38:54.920Z,1679521134.920 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T21:39:07.012Z,1679521147.012 [NAL9602](INFO): SBD MO Status=0, MOMSN=14612, MT Status=0, MTMSN=0
2023-03-22T21:39:07.012Z,1679521147.012 [NAL9602](INFO): No messages in MT queue
2023-03-22T21:39:37.720Z,1679521177.720 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T21:43:21.411Z,1679521401.411 [DataOverHttps](IMPORTANT): SBD MTMSN=20230322T214320
2023-03-22T21:43:28.850Z,1679521408.850 [DataOverHttps](INFO): Received command: configSet BPC1.loadAtStartup 1 bool persist
2023-03-22T21:43:29.096Z,1679521409.096 [CommandExec](IMPORTANT): got command configSet BPC1.loadAtStartup 1 bool persist
2023-03-22T21:43:29.096Z,1679521409.096 [CommandExec](IMPORTANT): configSet BPC1.loadAtStartup requires a restart to take effect.
2023-03-22T21:43:55.525Z,1679521435.525 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T21:43:55.525Z,1679521435.525 [Default:CheckIn:C.Wait] Stopped
2023-03-22T21:43:55.525Z,1679521435.525 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T21:43:55.525Z,1679521435.525 [Default:CheckIn:D] Running Loop=1
2023-03-22T21:43:55.922Z,1679521435.922 [Default:CheckIn:D] Stopped
2023-03-22T21:43:55.922Z,1679521435.922 [Default:CheckIn:E] Running Loop=1
2023-03-22T21:43:56.330Z,1679521436.330 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 34.521517 min 
2023-03-22T21:43:56.330Z,1679521436.330 [Default:CheckIn:E] Stopped
2023-03-22T21:43:56.330Z,1679521436.330 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T21:43:56.331Z,1679521436.331 [Default:CheckIn] Stopped
2023-03-22T21:43:56.331Z,1679521436.331 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T21:43:56.331Z,1679521436.331 [Default:CheckIn](INFO): Running loop #6
2023-03-22T21:43:56.331Z,1679521436.331 [Default:CheckIn] Running Loop=6
2023-03-22T21:43:56.331Z,1679521436.331 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T21:43:56.331Z,1679521436.331 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T21:43:58.330Z,1679521438.330 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,214357.00,A,3648.15096,N,12147.22114,W,0.019,352.32,220323,,,D*77
2023-03-22T21:43:58.332Z,1679521438.332 [NAL9602](INFO): GPS fix at 20230322T214357: (36.802516, -121.787019)
2023-03-22T21:43:58.351Z,1679521438.351 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T21:43:58.351Z,1679521438.351 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T21:44:11.893Z,1679521451.893 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20230322T210446/Courier0022.lzma
2023-03-22T21:44:12.896Z,1679521452.896 [DataOverHttps](INFO): Moved sent file to Logs/20230322T210446/Courier0022.lzma.bak
2023-03-22T21:44:12.896Z,1679521452.896 [DataOverHttps](IMPORTANT): SBD MOMSN=17542801, MTMSN=20230322T214412
2023-03-22T21:44:21.156Z,1679521461.156 [NAL9602](INFO): SBD MO Status=2, MOMSN=14613, MT Status=2, MTMSN=0
2023-03-22T21:44:21.156Z,1679521461.156 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T21:44:26.458Z,1679521466.458 [DataOverHttps](INFO): Received command: strobe on
2023-03-22T21:44:26.460Z,1679521466.460 [CommandExec](IMPORTANT): got command strobe on
2023-03-22T21:44:26.460Z,1679521466.460 [CommandExec](IMPORTANT): Activating strobe
2023-03-22T21:44:35.285Z,1679521475.285 [DataOverHttps](INFO): Sending 251 bytes from file Logs/20230322T210446/Express0023.lzma
2023-03-22T21:44:36.288Z,1679521476.288 [DataOverHttps](INFO): Moved sent file to Logs/20230322T210446/Express0023.lzma.bak
2023-03-22T21:44:36.288Z,1679521476.288 [DataOverHttps](INFO): SBD MOMSN=17542809
2023-03-22T21:44:56.257Z,1679521496.257 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20230322T210446/Courier0027.lzma
2023-03-22T21:44:57.260Z,1679521497.260 [DataOverHttps](INFO): Moved sent file to Logs/20230322T210446/Courier0027.lzma.bak
2023-03-22T21:44:57.260Z,1679521497.260 [DataOverHttps](INFO): SBD MOMSN=17542815
2023-03-22T21:45:07.213Z,1679521507.213 [NAL9602](INFO): SBD MO Status=2, MOMSN=14613, MT Status=2, MTMSN=0
2023-03-22T21:45:07.213Z,1679521507.213 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T21:45:16.305Z,1679521516.305 [DataOverHttps](INFO): Sending 51 bytes from file Logs/20230322T210446/Express0024.lzma
2023-03-22T21:45:17.308Z,1679521517.308 [DataOverHttps](INFO): Moved sent file to Logs/20230322T210446/Express0024.lzma.bak
2023-03-22T21:45:17.308Z,1679521517.308 [DataOverHttps](INFO): SBD MOMSN=17542817
2023-03-22T21:45:38.805Z,1679521538.805 [DataOverHttps](INFO): Sending 150 bytes from file Logs/20230322T210446/Express0028.lzma
2023-03-22T21:45:39.808Z,1679521539.808 [DataOverHttps](INFO): Moved sent file to Logs/20230322T210446/Express0028.lzma.bak
2023-03-22T21:45:39.808Z,1679521539.808 [DataOverHttps](INFO): SBD MOMSN=17542819
2023-03-22T21:45:45.258Z,1679521545.258 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T21:45:45.258Z,1679521545.258 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T21:45:45.259Z,1679521545.259 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T21:46:03.921Z,1679521563.921 [NAL9602](INFO): SBD MO Status=2, MOMSN=14613, MT Status=2, MTMSN=0
2023-03-22T21:46:03.921Z,1679521563.921 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T21:46:16.507Z,1679521576.507 [NAL9602](INFO): SBD MO Status=0, MOMSN=14613, MT Status=0, MTMSN=0
2023-03-22T21:46:16.507Z,1679521576.507 [NAL9602](INFO): No messages in MT queue
2023-03-22T21:46:47.208Z,1679521607.208 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T21:49:10.689Z,1679521750.689 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-03-22T21:49:10.690Z,1679521750.690 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+18.3,489.0,000
2023-03-22T21:49:46.661Z,1679521786.661 [DVL_micro](ERROR): only read 3 of 4 data items
2023-03-22T21:49:46.661Z,1679521786.661 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,+9999.99,
2023-03-22T21:50:46.041Z,1679521846.041 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T21:50:46.041Z,1679521846.041 [Default:CheckIn:C.Wait] Stopped
2023-03-22T21:50:46.041Z,1679521846.041 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T21:50:46.041Z,1679521846.041 [Default:CheckIn:D] Running Loop=1
2023-03-22T21:50:46.459Z,1679521846.459 [Default:CheckIn:D] Stopped
2023-03-22T21:50:46.459Z,1679521846.459 [Default:CheckIn:E] Running Loop=1
2023-03-22T21:50:46.855Z,1679521846.855 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 41.363794 min 
2023-03-22T21:50:46.855Z,1679521846.855 [Default:CheckIn:E] Stopped
2023-03-22T21:50:46.855Z,1679521846.855 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T21:50:46.855Z,1679521846.855 [Default:CheckIn] Stopped
2023-03-22T21:50:46.855Z,1679521846.855 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T21:50:46.855Z,1679521846.855 [Default:CheckIn](INFO): Running loop #7
2023-03-22T21:50:46.855Z,1679521846.855 [Default:CheckIn] Running Loop=7
2023-03-22T21:50:46.856Z,1679521846.856 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T21:50:46.856Z,1679521846.856 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T21:50:48.861Z,1679521848.861 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,215048.00,A,3648.38592,N,12147.11849,W,4.918,5.93,220323,,,D*72
2023-03-22T21:50:48.864Z,1679521848.864 [NAL9602](INFO): GPS fix at 20230322T215048: (36.806432, -121.785308)
2023-03-22T21:50:48.910Z,1679521848.910 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T21:50:48.910Z,1679521848.910 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T21:50:53.530Z,1679521853.530 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20230322T210446/Courier0031.lzma
2023-03-22T21:50:54.536Z,1679521854.536 [DataOverHttps](INFO): Moved sent file to Logs/20230322T210446/Courier0031.lzma.bak
2023-03-22T21:50:54.536Z,1679521854.536 [DataOverHttps](INFO): SBD MOMSN=17542832
2023-03-22T21:51:03.469Z,1679521863.469 [NAL9602](INFO): SBD MO Status=0, MOMSN=14614, MT Status=0, MTMSN=0
2023-03-22T21:51:03.469Z,1679521863.469 [NAL9602](INFO): No messages in MT queue
2023-03-22T21:51:13.557Z,1679521873.557 [DataOverHttps](INFO): Sending 142 bytes from file Logs/20230322T210446/Express0032.lzma
2023-03-22T21:51:14.560Z,1679521874.560 [DataOverHttps](INFO): Moved sent file to Logs/20230322T210446/Express0032.lzma.bak
2023-03-22T21:51:14.560Z,1679521874.560 [DataOverHttps](INFO): SBD MOMSN=17542835
2023-03-22T21:51:19.251Z,1679521879.251 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T21:51:19.251Z,1679521879.251 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T21:51:19.251Z,1679521879.251 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T21:51:34.173Z,1679521894.173 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T21:56:19.878Z,1679522179.878 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T21:56:19.900Z,1679522179.900 [Default:CheckIn:C.Wait] Stopped
2023-03-22T21:56:19.900Z,1679522179.900 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T21:56:19.901Z,1679522179.901 [Default:CheckIn:D] Running Loop=1
2023-03-22T21:56:20.287Z,1679522180.287 [Default:CheckIn:D] Stopped
2023-03-22T21:56:20.287Z,1679522180.287 [Default:CheckIn:E] Running Loop=1
2023-03-22T21:56:20.678Z,1679522180.678 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 46.927600 min 
2023-03-22T21:56:20.678Z,1679522180.678 [Default:CheckIn:E] Stopped
2023-03-22T21:56:20.678Z,1679522180.678 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T21:56:20.678Z,1679522180.678 [Default:CheckIn] Stopped
2023-03-22T21:56:20.678Z,1679522180.678 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T21:56:20.679Z,1679522180.679 [Default:CheckIn](INFO): Running loop #8
2023-03-22T21:56:20.679Z,1679522180.679 [Default:CheckIn] Running Loop=8
2023-03-22T21:56:20.679Z,1679522180.679 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T21:56:20.679Z,1679522180.679 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T21:56:22.712Z,1679522182.712 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,215622.00,A,3648.34652,N,12147.60039,W,9.836,258.54,220323,,,D*73
2023-03-22T21:56:22.714Z,1679522182.714 [NAL9602](INFO): GPS fix at 20230322T215622: (36.805775, -121.793340)
2023-03-22T21:56:22.725Z,1679522182.725 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T21:56:22.725Z,1679522182.725 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T21:56:31.605Z,1679522191.605 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20230322T210446/Courier0034.lzma
2023-03-22T21:56:32.608Z,1679522192.608 [DataOverHttps](INFO): Moved sent file to Logs/20230322T210446/Courier0034.lzma.bak
2023-03-22T21:56:32.608Z,1679522192.608 [DataOverHttps](INFO): SBD MOMSN=17542855
2023-03-22T21:56:39.721Z,1679522199.721 [NAL9602](INFO): SBD MO Status=0, MOMSN=14615, MT Status=0, MTMSN=0
2023-03-22T21:56:39.721Z,1679522199.721 [NAL9602](INFO): No messages in MT queue
2023-03-22T21:56:51.821Z,1679522211.821 [DataOverHttps](INFO): Sending 152 bytes from file Logs/20230322T210446/Express0035.lzma
2023-03-22T21:56:52.824Z,1679522212.824 [DataOverHttps](INFO): Moved sent file to Logs/20230322T210446/Express0035.lzma.bak
2023-03-22T21:56:52.824Z,1679522212.824 [DataOverHttps](INFO): SBD MOMSN=17542858
2023-03-22T21:56:57.527Z,1679522217.527 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T21:56:57.527Z,1679522217.527 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T21:56:57.527Z,1679522217.527 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T21:57:10.428Z,1679522230.428 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T21:58:48.265Z,1679522328.265 [DVL_micro](ERROR): Failed to parse:
:WI,-01656,+00026,+00961,+00000,A
2023-03-22T22:01:47.250Z,1679522507.250 [DVL_micro](ERROR): Failed to parse:
:WI,+00052,-00062,+00566,+00000,A
2023-03-22T22:01:58.240Z,1679522518.240 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T22:01:58.240Z,1679522518.240 [Default:CheckIn:C.Wait] Stopped
2023-03-22T22:01:58.240Z,1679522518.240 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T22:01:58.240Z,1679522518.240 [Default:CheckIn:D] Running Loop=1
2023-03-22T22:01:58.679Z,1679522518.679 [Default:CheckIn:D] Stopped
2023-03-22T22:01:58.680Z,1679522518.680 [Default:CheckIn:E] Running Loop=1
2023-03-22T22:01:59.086Z,1679522519.086 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 52.567041 min 
2023-03-22T22:01:59.086Z,1679522519.086 [Default:CheckIn:E] Stopped
2023-03-22T22:01:59.086Z,1679522519.086 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T22:01:59.086Z,1679522519.086 [Default:CheckIn] Stopped
2023-03-22T22:01:59.086Z,1679522519.086 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T22:01:59.086Z,1679522519.086 [Default:CheckIn](INFO): Running loop #9
2023-03-22T22:01:59.087Z,1679522519.087 [Default:CheckIn] Running Loop=9
2023-03-22T22:01:59.087Z,1679522519.087 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T22:01:59.087Z,1679522519.087 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T22:02:01.058Z,1679522521.058 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,220200.00,A,3647.97901,N,12148.81961,W,11.410,245.59,220323,,,A*4F
2023-03-22T22:02:01.060Z,1679522521.060 [NAL9602](INFO): GPS fix at 20230322T220200: (36.799650, -121.813660)
2023-03-22T22:02:01.119Z,1679522521.119 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T22:02:01.119Z,1679522521.119 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T22:02:03.835Z,1679522523.835 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20230322T210446/Courier0037.lzma
2023-03-22T22:02:04.840Z,1679522524.840 [DataOverHttps](INFO): Moved sent file to Logs/20230322T210446/Courier0037.lzma.bak
2023-03-22T22:02:04.840Z,1679522524.840 [DataOverHttps](INFO): SBD MOMSN=17542871
2023-03-22T22:02:37.097Z,1679522557.097 [NAL9602](INFO): SBD MO Status=0, MOMSN=14616, MT Status=0, MTMSN=0
2023-03-22T22:02:37.097Z,1679522557.097 [NAL9602](INFO): No messages in MT queue
2023-03-22T22:03:07.800Z,1679522587.800 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T22:03:48.091Z,1679522628.091 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.643456
2023-03-22T22:04:11.731Z,1679522651.731 [NAL9602](INFO): SBD MO Status=1, MOMSN=14617, MT Status=0, MTMSN=0
2023-03-22T22:04:11.782Z,1679522651.782 [NAL9602](INFO): Sent 145 bytes from file Logs/20230322T210446/Express0038.lzma
2023-03-22T22:04:11.783Z,1679522651.783 [NAL9602](INFO): Packets left to send: 0
2023-03-22T22:04:19.991Z,1679522659.991 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003501
2023-03-22T22:04:26.999Z,1679522666.999 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T22:04:26.999Z,1679522666.999 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T22:04:26.000Z,1679522667.000 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T22:04:29.405Z,1679522669.405 [NAL9602](INFO): SBD MO Status=0, MOMSN=14618, MT Status=0, MTMSN=0
2023-03-22T22:05:00.107Z,1679522700.107 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T22:05:44.962Z,1679522744.962 [DVL_micro](ERROR): only read 3 of 4 data items
2023-03-22T22:05:44.962Z,1679522744.962 [DVL_micro](ERROR): Failed to parse:
:BI,+00383,-00073,-0000,I
2023-03-22T22:09:27.672Z,1679522967.672 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T22:09:27.672Z,1679522967.672 [Default:CheckIn:C.Wait] Stopped
2023-03-22T22:09:27.673Z,1679522967.673 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T22:09:27.673Z,1679522967.673 [Default:CheckIn:D] Running Loop=1
2023-03-22T22:09:28.082Z,1679522968.082 [Default:CheckIn:D] Stopped
2023-03-22T22:09:28.082Z,1679522968.082 [Default:CheckIn:E] Running Loop=1
2023-03-22T22:09:28.483Z,1679522968.483 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 60.057507 min 
2023-03-22T22:09:28.483Z,1679522968.483 [Default:CheckIn:E] Stopped
2023-03-22T22:09:28.483Z,1679522968.483 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T22:09:28.483Z,1679522968.483 [Default:CheckIn] Stopped
2023-03-22T22:09:28.483Z,1679522968.483 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T22:09:28.483Z,1679522968.483 [Default:CheckIn](INFO): Running loop #10
2023-03-22T22:09:28.483Z,1679522968.483 [Default:CheckIn] Running Loop=10
2023-03-22T22:09:28.483Z,1679522968.483 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T22:09:28.484Z,1679522968.484 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T22:09:30.492Z,1679522970.492 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,220929.00,A,3647.76762,N,12150.85802,W,13.529,290.80,220323,,,A*47
2023-03-22T22:09:30.502Z,1679522970.502 [NAL9602](INFO): GPS fix at 20230322T220929: (36.796127, -121.847634)
2023-03-22T22:09:30.521Z,1679522970.521 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T22:09:30.521Z,1679522970.521 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T22:09:41.301Z,1679522981.301 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20230322T210446/Courier0040.lzma
2023-03-22T22:09:45.044Z,1679522985.044 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-03-22T22:09:45.044Z,1679522985.044 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.61489.0,000
2023-03-22T22:09:47.064Z,1679522987.064 [NAL9602](INFO): SBD MO Status=0, MOMSN=14619, MT Status=0, MTMSN=0
2023-03-22T22:09:47.064Z,1679522987.064 [NAL9602](INFO): No messages in MT queue
2023-03-22T22:09:55.354Z,1679522995.354 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting.
2023-03-22T22:10:01.379Z,1679523001.379 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.904140
2023-03-22T22:10:26.965Z,1679523026.965 [NAL9602](INFO): SBD MO Status=1, MOMSN=14620, MT Status=0, MTMSN=0
2023-03-22T22:10:27.018Z,1679523027.018 [NAL9602](INFO): Sent 74 bytes from file Logs/20230322T210446/Courier0040.lzma
2023-03-22T22:10:27.018Z,1679523027.018 [NAL9602](INFO): Packets left to send: 0
2023-03-22T22:10:44.045Z,1679523044.045 [NAL9602](INFO): SBD MO Status=1, MOMSN=14621, MT Status=0, MTMSN=0
2023-03-22T22:10:44.102Z,1679523044.102 [NAL9602](INFO): Sent 153 bytes from file Logs/20230322T210446/Express0041.lzma
2023-03-22T22:10:44.103Z,1679523044.103 [NAL9602](INFO): Packets left to send: 0
2023-03-22T22:10:57.757Z,1679523057.757 [NAL9602](INFO): SBD MO Status=2, MOMSN=14622, MT Status=2, MTMSN=0
2023-03-22T22:10:57.757Z,1679523057.757 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T22:11:08.338Z,1679523068.338 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:11:21.458Z,1679523081.458 [NAL9602](INFO): SBD MO Status=2, MOMSN=14622, MT Status=2, MTMSN=0
2023-03-22T22:11:21.458Z,1679523081.458 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T22:11:38.480Z,1679523098.480 [NAL9602](INFO): SBD MO Status=2, MOMSN=14622, MT Status=2, MTMSN=0
2023-03-22T22:11:38.481Z,1679523098.481 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T22:11:42.558Z,1679523102.558 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-03-22T22:11:42.558Z,1679523102.558 [DVL_micro](ERROR): Failed to parse:
:TS,000000,35.0,+1.0,1489.0,000
2023-03-22T22:11:43.486Z,1679523103.486 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:11:56.546Z,1679523116.546 [NAL9602](INFO): SBD MO Status=0, MOMSN=14622, MT Status=0, MTMSN=0
2023-03-22T22:11:56.635Z,1679523116.635 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T22:11:56.635Z,1679523116.635 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T22:11:56.635Z,1679523116.635 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T22:12:27.248Z,1679523147.248 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T22:13:27.290Z,1679523207.290 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002929
2023-03-22T22:13:45.217Z,1679523225.217 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-03-22T22:13:45.218Z,1679523225.218 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0000.0,1489.0,000
2023-03-22T22:16:57.142Z,1679523417.142 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T22:16:57.142Z,1679523417.142 [Default:CheckIn:C.Wait] Stopped
2023-03-22T22:16:57.142Z,1679523417.142 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T22:16:57.142Z,1679523417.142 [Default:CheckIn:D] Running Loop=1
2023-03-22T22:16:57.554Z,1679523417.554 [Default:CheckIn:D] Stopped
2023-03-22T22:16:57.554Z,1679523417.554 [Default:CheckIn:E] Running Loop=1
2023-03-22T22:16:57.946Z,1679523417.946 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 67.548706 min 
2023-03-22T22:16:57.947Z,1679523417.947 [Default:CheckIn:E] Stopped
2023-03-22T22:16:57.947Z,1679523417.947 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T22:16:57.947Z,1679523417.947 [Default:CheckIn] Stopped
2023-03-22T22:16:57.947Z,1679523417.947 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T22:16:57.947Z,1679523417.947 [Default:CheckIn](INFO): Running loop #11
2023-03-22T22:16:57.947Z,1679523417.947 [Default:CheckIn] Running Loop=11
2023-03-22T22:16:57.947Z,1679523417.947 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T22:16:57.947Z,1679523417.947 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T22:17:25.413Z,1679523445.413 [NAL9602](INFO): SBD MO Status=2, MOMSN=14623, MT Status=2, MTMSN=0
2023-03-22T22:17:25.414Z,1679523445.414 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T22:17:41.576Z,1679523461.576 [NAL9602](INFO): SBD MO Status=2, MOMSN=14623, MT Status=2, MTMSN=0
2023-03-22T22:17:41.576Z,1679523461.576 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T22:17:59.805Z,1679523479.805 [NAL9602](INFO): SBD MO Status=2, MOMSN=14623, MT Status=2, MTMSN=0
2023-03-22T22:17:59.805Z,1679523479.805 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T22:18:15.973Z,1679523495.973 [NAL9602](INFO): SBD MO Status=2, MOMSN=14623, MT Status=2, MTMSN=0
2023-03-22T22:18:15.973Z,1679523495.973 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T22:18:29.725Z,1679523509.724 [NAL9602](INFO): SBD MO Status=0, MOMSN=14623, MT Status=0, MTMSN=0
2023-03-22T22:18:29.725Z,1679523509.725 [NAL9602](INFO): No messages in MT queue
2023-03-22T22:18:30.949Z,1679523510.949 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,221830.00,A,3647.93650,N,12151.88511,W,1.127,60.04,220323,,,A*4F
2023-03-22T22:18:30.951Z,1679523510.951 [NAL9602](INFO): GPS fix at 20230322T221830: (36.798942, -121.864752)
2023-03-22T22:18:30.962Z,1679523510.962 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T22:18:30.962Z,1679523510.962 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T22:18:41.025Z,1679523521.025 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20230322T210446/Courier0043.lzma
2023-03-22T22:18:42.028Z,1679523522.028 [DataOverHttps](INFO): Moved sent file to Logs/20230322T210446/Courier0043.lzma.bak
2023-03-22T22:18:42.028Z,1679523522.028 [DataOverHttps](INFO): SBD MOMSN=17542916
2023-03-22T22:18:51.157Z,1679523531.157 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-03-22T22:18:51.157Z,1679523531.157 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,00.0,1489.0,000
2023-03-22T22:19:01.405Z,1679523541.405 [DataOverHttps](INFO): Sending 154 bytes from file Logs/20230322T210446/Express0044.lzma
2023-03-22T22:19:02.408Z,1679523542.408 [DataOverHttps](INFO): Moved sent file to Logs/20230322T210446/Express0044.lzma.bak
2023-03-22T22:19:02.408Z,1679523542.408 [DataOverHttps](INFO): SBD MOMSN=17542919
2023-03-22T22:19:03.256Z,1679523543.256 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T22:19:06.934Z,1679523546.934 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T22:19:06.934Z,1679523546.934 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T22:19:06.934Z,1679523546.934 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T22:20:47.435Z,1679523647.435 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.975193
2023-03-22T22:21:23.109Z,1679523683.109 [DVL_micro](ERROR): Failed to parse:
:RD,+0000.30,+0000.68,+0001.09,+9999.99
2023-03-22T22:22:09.258Z,1679523729.258 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:22:44.398Z,1679523764.398 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:23:20.050Z,1679523800.050 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting.
2023-03-22T22:23:55.190Z,1679523835.190 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:24:07.603Z,1679523847.603 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T22:24:07.603Z,1679523847.603 [Default:CheckIn:C.Wait] Stopped
2023-03-22T22:24:07.603Z,1679523847.603 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T22:24:07.604Z,1679523847.604 [Default:CheckIn:D] Running Loop=1
2023-03-22T22:24:08.006Z,1679523848.006 [Default:CheckIn:D] Stopped
2023-03-22T22:24:08.006Z,1679523848.006 [Default:CheckIn:E] Running Loop=1
2023-03-22T22:24:08.402Z,1679523848.402 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 74.722909 min 
2023-03-22T22:24:08.402Z,1679523848.402 [Default:CheckIn:E] Stopped
2023-03-22T22:24:08.402Z,1679523848.402 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T22:24:08.402Z,1679523848.402 [Default:CheckIn] Stopped
2023-03-22T22:24:08.402Z,1679523848.402 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T22:24:08.402Z,1679523848.402 [Default:CheckIn](INFO): Running loop #12
2023-03-22T22:24:08.403Z,1679523848.403 [Default:CheckIn] Running Loop=12
2023-03-22T22:24:08.403Z,1679523848.403 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T22:24:08.403Z,1679523848.403 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T22:24:10.414Z,1679523850.414 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,222409.00,A,3647.96141,N,12151.86495,W,0.855,298.52,220323,,,A*70
2023-03-22T22:24:10.416Z,1679523850.416 [NAL9602](INFO): GPS fix at 20230322T222409: (36.799357, -121.864416)
2023-03-22T22:24:10.427Z,1679523850.427 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T22:24:10.427Z,1679523850.427 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T22:24:30.505Z,1679523870.505 [NAL9602](INFO): SBD MO Status=1, MOMSN=14624, MT Status=0, MTMSN=0
2023-03-22T22:24:30.554Z,1679523870.554 [NAL9602](INFO): Sent 73 bytes from file Logs/20230322T210446/Courier0046.lzma
2023-03-22T22:24:30.554Z,1679523870.554 [NAL9602](INFO): Packets left to send: 0
2023-03-22T22:24:42.893Z,1679523882.893 [NAL9602](INFO): SBD MO Status=1, MOMSN=14625, MT Status=0, MTMSN=0
2023-03-22T22:24:42.942Z,1679523882.942 [NAL9602](INFO): Sent 128 bytes from file Logs/20230322T210446/Express0047.lzma
2023-03-22T22:24:42.942Z,1679523882.942 [NAL9602](INFO): Packets left to send: 0
2023-03-22T22:25:04.937Z,1679523904.937 [NAL9602](INFO): SBD MO Status=0, MOMSN=14626, MT Status=0, MTMSN=0
2023-03-22T22:25:05.034Z,1679523905.034 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T22:25:05.034Z,1679523905.034 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T22:25:05.035Z,1679523905.035 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T22:25:35.640Z,1679523935.640 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T22:25:41.698Z,1679523941.698 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:26:03.594Z,1679523963.594 [DVL_micro](ERROR): DVL uart error: serial timeout
2023-03-22T22:26:03.594Z,1679523963.594 [DVL_micro] Communications Fault, FailCount= 1
2023-03-22T22:26:03.594Z,1679523963.594 [DVL_micro](ERROR): Communications Fault
2023-03-22T22:26:03.594Z,1679523963.594 [DVL_micro](ERROR): Failed to parse:
2023-03-22T22:26:03.641Z,1679523963.641 [CBIT](ERROR): Communications Fault in component: DVL_micro
2023-03-22T22:26:03.979Z,1679523963.979 [DVL_micro](INFO): Powering down
2023-03-22T22:26:04.744Z,1679523964.744 [CBIT](INFO): Clearing failed state for component DVL_micro
2023-03-22T22:26:04.744Z,1679523964.744 [DVL_micro] No Fault, FailCount= 1
2023-03-22T22:26:16.838Z,1679523976.838 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:26:43.326Z,1679524003.326 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002963
2023-03-22T22:28:03.882Z,1679524083.882 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting.
2023-03-22T22:28:05.891Z,1679524085.891 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.731621
2023-03-22T22:28:39.030Z,1679524119.030 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:30:05.534Z,1679524205.534 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T22:30:05.535Z,1679524205.535 [Default:CheckIn:C.Wait] Stopped
2023-03-22T22:30:05.535Z,1679524205.535 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T22:30:05.535Z,1679524205.535 [Default:CheckIn:D] Running Loop=1
2023-03-22T22:30:05.952Z,1679524205.952 [Default:CheckIn:D] Stopped
2023-03-22T22:30:05.952Z,1679524205.952 [Default:CheckIn:E] Running Loop=1
2023-03-22T22:30:06.349Z,1679524206.349 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 80.688680 min 
2023-03-22T22:30:06.349Z,1679524206.349 [Default:CheckIn:E] Stopped
2023-03-22T22:30:06.349Z,1679524206.349 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T22:30:06.349Z,1679524206.349 [Default:CheckIn] Stopped
2023-03-22T22:30:06.349Z,1679524206.349 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T22:30:06.349Z,1679524206.349 [Default:CheckIn](INFO): Running loop #13
2023-03-22T22:30:06.349Z,1679524206.349 [Default:CheckIn] Running Loop=13
2023-03-22T22:30:06.349Z,1679524206.349 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T22:30:06.350Z,1679524206.350 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T22:30:08.353Z,1679524208.353 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,223007.00,A,3647.97911,N,12151.86185,W,1.400,358.27,220323,,,A*71
2023-03-22T22:30:08.356Z,1679524208.356 [NAL9602](INFO): GPS fix at 20230322T223007: (36.799652, -121.864364)
2023-03-22T22:30:08.366Z,1679524208.366 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T22:30:08.367Z,1679524208.367 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T22:30:24.474Z,1679524224.474 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:30:35.792Z,1679524235.792 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=14627, MT Status=1, MTMSN=1032
2023-03-22T22:30:35.858Z,1679524235.858 [NAL9602](INFO): Sent 73 bytes from file Logs/20230322T210446/Courier0049.lzma
2023-03-22T22:30:35.858Z,1679524235.858 [NAL9602](INFO): Packets left to send: 0
2023-03-22T22:30:36.478Z,1679524236.478 [NAL9602](INFO): Received command: restart logs