2023-03-22T20:47:27.199Z,1679518047.199 [Supervisor](DEBUG): Initializing supervisor.
2023-03-22T20:47:27.203Z,1679518047.203 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2023-03-22T20:47:27.204Z,1679518047.204 [SyncHandler](INFO): Protected caller Thread ID is 827
2023-03-22T20:47:27.204Z,1679518047.204 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2023-03-22T20:47:27.205Z,1679518047.205 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2023-03-22T20:47:27.206Z,1679518047.206 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 828
2023-03-22T20:47:27.210Z,1679518047.210 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2023-03-22T20:47:27.228Z,1679518047.228 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread.
2023-03-22T20:47:27.229Z,1679518047.229 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2023-03-22T20:47:27.229Z,1679518047.229 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 829
2023-03-22T20:47:27.233Z,1679518047.233 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2023-03-22T20:47:27.234Z,1679518047.234 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2023-03-22T20:47:27.235Z,1679518047.235 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 830
2023-03-22T20:47:27.237Z,1679518047.237 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2023-03-22T20:47:27.238Z,1679518047.238 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0
2023-03-22T20:47:27.238Z,1679518047.238 [logger ThreadHandler](INFO): Protected caller Thread ID is 831
2023-03-22T20:47:27.242Z,1679518047.242 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2023-03-22T20:47:27.242Z,1679518047.242 [Supervisor](INFO): Looking for Config files in directory: Config/
2023-03-22T20:47:27.248Z,1679518047.248 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2023-03-22T20:47:27.345Z,1679518047.345 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2023-03-22T20:47:27.347Z,1679518047.347 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2023-03-22T20:47:27.559Z,1679518047.559 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2023-03-22T20:47:27.561Z,1679518047.561 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2023-03-22T20:47:27.811Z,1679518047.811 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2023-03-22T20:47:27.813Z,1679518047.813 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2023-03-22T20:47:27.926Z,1679518047.926 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2023-03-22T20:47:27.927Z,1679518047.927 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2023-03-22T20:47:28.589Z,1679518048.589 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2023-03-22T20:47:28.590Z,1679518048.590 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2023-03-22T20:47:29.054Z,1679518049.054 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2023-03-22T20:47:29.055Z,1679518049.055 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2023-03-22T20:47:29.529Z,1679518049.529 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2023-03-22T20:47:29.531Z,1679518049.531 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2023-03-22T20:47:29.920Z,1679518049.920 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2023-03-22T20:47:29.920Z,1679518049.920 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2023-03-22T20:47:30.237Z,1679518050.237 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2023-03-22T20:47:30.238Z,1679518050.238 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2023-03-22T20:47:30.600Z,1679518050.600 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2023-03-22T20:47:30.601Z,1679518050.601 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2023-03-22T20:47:31.611Z,1679518051.611 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2023-03-22T20:47:31.612Z,1679518051.612 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2023-03-22T20:47:31.885Z,1679518051.885 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2023-03-22T20:47:31.887Z,1679518051.887 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2023-03-22T20:47:31.967Z,1679518051.967 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2023-03-22T20:47:32.047Z,1679518052.047 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2023-03-22T20:47:32.278Z,1679518052.278 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2023-03-22T20:47:32.278Z,1679518052.278 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2023-03-22T20:47:32.498Z,1679518052.498 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2023-03-22T20:47:32.500Z,1679518052.500 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/
2023-03-22T20:47:32.502Z,1679518052.502 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/secure.cfg
2023-03-22T20:47:32.586Z,1679518052.586 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Battery.cfg
2023-03-22T20:47:32.845Z,1679518052.845 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2023-03-22T20:47:32.845Z,1679518052.845 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Navigation.cfg
2023-03-22T20:47:32.944Z,1679518052.944 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Sensor.cfg
2023-03-22T20:47:33.099Z,1679518053.099 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/vehicle.cfg
2023-03-22T20:47:33.273Z,1679518053.273 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Simulator.cfg
2023-03-22T20:47:33.357Z,1679518053.357 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Servo.cfg
2023-03-22T20:47:33.465Z,1679518053.465 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Control.cfg
2023-03-22T20:47:33.568Z,1679518053.568 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Science.cfg
2023-03-22T20:47:33.720Z,1679518053.720 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/logger.cfg
2023-03-22T20:47:33.820Z,1679518053.820 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/BIT.cfg
2023-03-22T20:47:33.917Z,1679518053.917 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2023-03-22T20:47:33.931Z,1679518053.931 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2023-03-22T20:47:34.115Z,1679518054.115 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2023-03-22T20:47:34.116Z,1679518054.116 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2023-03-22T20:47:34.302Z,1679518054.302 [BuoyancyServo] Loaded
2023-03-22T20:47:34.302Z,1679518054.302 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2023-03-22T20:47:34.323Z,1679518054.323 [ElevatorServo] Loaded
2023-03-22T20:47:34.324Z,1679518054.324 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2023-03-22T20:47:34.344Z,1679518054.344 [MassServo] Loaded
2023-03-22T20:47:34.344Z,1679518054.344 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2023-03-22T20:47:34.364Z,1679518054.364 [RudderServo] Loaded
2023-03-22T20:47:34.365Z,1679518054.365 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2023-03-22T20:47:34.380Z,1679518054.380 [ThrusterHE] Loaded
2023-03-22T20:47:34.380Z,1679518054.380 [ComponentRegistry](DEBUG): SyncComponent "ThrusterHE" handled in the control thread.
2023-03-22T20:47:34.381Z,1679518054.381 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2023-03-22T20:47:34.382Z,1679518054.382 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2023-03-22T20:47:34.553Z,1679518054.553 [SBIT](DEBUG): Construct Startup Built In Test.
2023-03-22T20:47:34.568Z,1679518054.568 [SBIT] Loaded
2023-03-22T20:47:34.569Z,1679518054.569 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2023-03-22T20:47:34.571Z,1679518054.571 [IBIT](DEBUG): Construct Initiated Built In Test.
2023-03-22T20:47:34.593Z,1679518054.593 [IBIT] Loaded
2023-03-22T20:47:34.593Z,1679518054.593 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2023-03-22T20:47:34.599Z,1679518054.599 [CBIT](DEBUG): Construct Continuous Built In Test.
2023-03-22T20:47:34.816Z,1679518054.816 [CBIT] Loaded
2023-03-22T20:47:34.816Z,1679518054.816 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2023-03-22T20:47:34.817Z,1679518054.817 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2023-03-22T20:47:34.817Z,1679518054.817 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2023-03-22T20:47:35.031Z,1679518055.031 [CTD_Seabird] Loaded
2023-03-22T20:47:35.031Z,1679518055.031 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2023-03-22T20:47:35.032Z,1679518055.032 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 406644E0
2023-03-22T20:47:35.033Z,1679518055.033 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 914
2023-03-22T20:47:35.064Z,1679518055.064 [ESPComponent] Loaded
2023-03-22T20:47:35.065Z,1679518055.065 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2023-03-22T20:47:35.084Z,1679518055.084 [PAR_Licor] Loaded
2023-03-22T20:47:35.084Z,1679518055.084 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2023-03-22T20:47:35.115Z,1679518055.115 [WetLabsBB2FL] Loaded
2023-03-22T20:47:35.116Z,1679518055.116 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2023-03-22T20:47:35.117Z,1679518055.117 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 406944E0
2023-03-22T20:47:35.117Z,1679518055.117 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 915
2023-03-22T20:47:35.118Z,1679518055.118 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2023-03-22T20:47:35.119Z,1679518055.119 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2023-03-22T20:47:35.188Z,1679518055.188 [DepthRateCalculator] Loaded
2023-03-22T20:47:35.189Z,1679518055.189 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2023-03-22T20:47:35.194Z,1679518055.194 [PitchRateCalculator] Loaded
2023-03-22T20:47:35.194Z,1679518055.194 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2023-03-22T20:47:35.205Z,1679518055.205 [SpeedCalculator] Loaded
2023-03-22T20:47:35.205Z,1679518055.205 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2023-03-22T20:47:35.210Z,1679518055.210 [YawRateCalculator] Loaded
2023-03-22T20:47:35.210Z,1679518055.210 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2023-03-22T20:47:35.229Z,1679518055.229 [ElevatorOffsetCalculator] Loaded
2023-03-22T20:47:35.230Z,1679518055.230 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2023-03-22T20:47:35.230Z,1679518055.230 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2023-03-22T20:47:35.231Z,1679518055.231 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2023-03-22T20:47:35.354Z,1679518055.354 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2023-03-22T20:47:35.355Z,1679518055.355 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2023-03-22T20:47:35.398Z,1679518055.398 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2023-03-22T20:47:35.398Z,1679518055.398 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2023-03-22T20:47:35.537Z,1679518055.537 [DeadReckonUsingMultipleVelocitySources] Loaded
2023-03-22T20:47:35.537Z,1679518055.537 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2023-03-22T20:47:35.551Z,1679518055.551 [NavChart] Loaded
2023-03-22T20:47:35.551Z,1679518055.551 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2023-03-22T20:47:35.557Z,1679518055.557 [UniversalFixResidualReporter] Loaded
2023-03-22T20:47:35.557Z,1679518055.557 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2023-03-22T20:47:35.558Z,1679518055.558 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2023-03-22T20:47:35.558Z,1679518055.558 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2023-03-22T20:47:36.357Z,1679518056.357 [AHRS_M2] Loaded
2023-03-22T20:47:36.357Z,1679518056.357 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2023-03-22T20:47:36.606Z,1679518056.606 [BackseatComponent] Loaded
2023-03-22T20:47:36.606Z,1679518056.606 [ComponentRegistry](DEBUG): Component "BackseatComponent" handled in its own thread.
2023-03-22T20:47:36.607Z,1679518056.607 [BackseatComponent ThreadHandler](DEBUG): Created PCaller Thread at 40A244E0
2023-03-22T20:47:36.608Z,1679518056.608 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 916
2023-03-22T20:47:36.611Z,1679518056.611 [LcmUniversalReporter] Loaded
2023-03-22T20:47:36.611Z,1679518056.611 [ComponentRegistry](DEBUG): SyncComponent "LcmUniversalReporter" handled in the control thread.
2023-03-22T20:47:37.342Z,1679518057.342 [BPC1] Loaded
2023-03-22T20:47:37.342Z,1679518057.342 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2023-03-22T20:47:37.492Z,1679518057.492 [DataOverHttps] Loaded
2023-03-22T20:47:37.492Z,1679518057.492 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2023-03-22T20:47:37.493Z,1679518057.493 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 40A544E0
2023-03-22T20:47:37.493Z,1679518057.493 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 917
2023-03-22T20:47:37.514Z,1679518057.514 [Depth_Keller] Loaded
2023-03-22T20:47:37.515Z,1679518057.515 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2023-03-22T20:47:37.520Z,1679518057.520 [DropWeight] Loaded
2023-03-22T20:47:37.520Z,1679518057.520 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2023-03-22T20:47:37.558Z,1679518057.558 [DVL_micro] Loaded
2023-03-22T20:47:37.558Z,1679518057.558 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2023-03-22T20:47:37.577Z,1679518057.577 [MultiRay] Loaded
2023-03-22T20:47:37.578Z,1679518057.578 [ComponentRegistry](DEBUG): SyncComponent "MultiRay" handled in the control thread.
2023-03-22T20:47:37.637Z,1679518057.637 [NAL9602] Loaded
2023-03-22T20:47:37.637Z,1679518057.637 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2023-03-22T20:47:37.663Z,1679518057.663 [Onboard] Loaded
2023-03-22T20:47:37.663Z,1679518057.663 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2023-03-22T20:47:37.665Z,1679518057.665 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 40A844E0
2023-03-22T20:47:37.665Z,1679518057.665 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 918
2023-03-22T20:47:37.678Z,1679518057.678 [Power24vConverter] Loaded
2023-03-22T20:47:37.678Z,1679518057.678 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread.
2023-03-22T20:47:37.692Z,1679518057.692 [Radio_Surface] Loaded
2023-03-22T20:47:37.692Z,1679518057.692 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2023-03-22T20:47:37.693Z,1679518057.693 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 40AB44E0
2023-03-22T20:47:37.693Z,1679518057.693 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 919
2023-03-22T20:47:37.787Z,1679518057.787 [DAT] Loaded
2023-03-22T20:47:37.787Z,1679518057.787 [ComponentRegistry](DEBUG): Component "DAT" handled in its own thread.
2023-03-22T20:47:37.788Z,1679518057.788 [DAT ThreadHandler](DEBUG): Created PCaller Thread at 40AE44E0
2023-03-22T20:47:37.789Z,1679518057.789 [DAT ThreadHandler](INFO): Protected caller Thread ID is 920
2023-03-22T20:47:37.789Z,1679518057.789 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2023-03-22T20:47:37.790Z,1679518057.790 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2023-03-22T20:47:38.079Z,1679518058.079 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2023-03-22T20:47:38.080Z,1679518058.080 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2023-03-22T20:47:39.384Z,1679518059.384 [VerticalControl](DEBUG): Construct VerticalControl.
2023-03-22T20:47:39.436Z,1679518059.436 [VerticalControl] Loaded
2023-03-22T20:47:39.436Z,1679518059.436 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2023-03-22T20:47:39.439Z,1679518059.439 [HorizontalControl](DEBUG): Construct HorizontalControl.
2023-03-22T20:47:39.477Z,1679518059.477 [HorizontalControl] Loaded
2023-03-22T20:47:39.477Z,1679518059.477 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2023-03-22T20:47:39.479Z,1679518059.479 [SpeedControl](DEBUG): Construct SpeedControl.
2023-03-22T20:47:39.481Z,1679518059.481 [SpeedControl] Loaded
2023-03-22T20:47:39.482Z,1679518059.482 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2023-03-22T20:47:39.484Z,1679518059.484 [LoopControl](DEBUG): Construct LoopControl.
2023-03-22T20:47:39.485Z,1679518059.485 [LoopControl] Loaded
2023-03-22T20:47:39.485Z,1679518059.485 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2023-03-22T20:47:39.486Z,1679518059.486 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2023-03-22T20:47:39.486Z,1679518059.486 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2023-03-22T20:47:39.502Z,1679518059.502 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2023-03-22T20:47:39.503Z,1679518059.503 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2023-03-22T20:47:39.860Z,1679518059.860 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2023-03-22T20:47:39.866Z,1679518059.866 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2023-03-22T20:47:39.869Z,1679518059.869 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2023-03-22T20:47:39.880Z,1679518059.880 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2023-03-22T20:47:39.881Z,1679518059.881 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40BDE4E0
2023-03-22T20:47:39.882Z,1679518059.882 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 921
2023-03-22T20:47:39.886Z,1679518059.886 [Supervisor](INFO): Main Thread ID is 822
2023-03-22T20:47:39.886Z,1679518059.886 [Supervisor](DEBUG): Running supervisor.
2023-03-22T20:47:39.887Z,1679518059.887 [CommandExec ThreadHandler](INFO): Handler Thread ID is 922
2023-03-22T20:47:39.888Z,1679518059.888 [CommandExec](INFO): Initializing the command executive.
2023-03-22T20:47:39.889Z,1679518059.889 [CommandLine ThreadHandler](INFO): Handler Thread ID is 923
2023-03-22T20:47:39.891Z,1679518059.891 [controlThread ThreadHandler](INFO): Handler Thread ID is 924
2023-03-22T20:47:39.892Z,1679518059.892 [controlThread](DEBUG): Initializing ControlThread
2023-03-22T20:47:39.893Z,1679518059.893 [SBIT](INFO): Initialize SBIT Component.
2023-03-22T20:47:39.894Z,1679518059.894 [SBIT](IMPORTANT): git: 2023-03-22
2023-03-22T20:47:39.894Z,1679518059.894 [SBIT](INFO): git hash: 5c491c0cb5eb82ad7031eef1a23773c9f4f92690
2023-03-22T20:47:39.894Z,1679518059.894 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2023-03-22T20:47:39.896Z,1679518059.896 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Wed Mar 17 08:23:48 PDT 2021
2023-03-22T20:47:39.897Z,1679518059.897 [SBIT](INFO): Beginning SBIT in 160.000000 seconds.
2023-03-22T20:47:39.898Z,1679518059.898 [IBIT](INFO): Initialize IBIT Component.
2023-03-22T20:47:39.898Z,1679518059.898 [CBIT](DEBUG): Initialize CBIT Component.
2023-03-22T20:47:39.899Z,1679518059.899 [logger ThreadHandler](INFO): Handler Thread ID is 925
2023-03-22T20:47:39.912Z,1679518059.912 [CBIT](DEBUG): Initialized mux pins.
2023-03-22T20:47:39.913Z,1679518059.913 [CBIT](DEBUG): Initializing the watchdog timer.
2023-03-22T20:47:39.925Z,1679518059.925 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 926
2023-03-22T20:47:39.926Z,1679518059.926 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2023-03-22T20:47:39.930Z,1679518059.930 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 928
2023-03-22T20:47:39.933Z,1679518059.933 [WetLabsBB2FL](INFO): Powering up
2023-03-22T20:47:39.934Z,1679518059.934 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 930
2023-03-22T20:47:39.937Z,1679518059.937 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2023-03-22T20:47:39.937Z,1679518059.937 [CBIT](DEBUG): Initializing heartbeat.
2023-03-22T20:47:39.951Z,1679518059.951 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 931
2023-03-22T20:47:39.952Z,1679518059.952 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2023-03-22T20:47:39.965Z,1679518059.965 [Onboard ThreadHandler](INFO): Handler Thread ID is 932
2023-03-22T20:47:39.982Z,1679518059.982 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 933
2023-03-22T20:47:40.005Z,1679518060.005 [DAT ThreadHandler](INFO): Handler Thread ID is 934
2023-03-22T20:47:40.008Z,1679518060.008 [CBIT](DEBUG): Deactivating GF circuits.
2023-03-22T20:47:40.009Z,1679518060.009 [CBIT](DEBUG): Deactivating emergency mode.
2023-03-22T20:47:40.009Z,1679518060.009 [DAT](INFO): Powering up
2023-03-22T20:47:40.010Z,1679518060.010 [DAT](DEBUG): Initializing DAT.
2023-03-22T20:47:40.013Z,1679518060.013 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 936
2023-03-22T20:47:40.020Z,1679518060.020 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2023-03-22T20:47:40.020Z,1679518060.020 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2023-03-22T20:47:40.020Z,1679518060.020 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2023-03-22T20:47:40.021Z,1679518060.021 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2023-03-22T20:47:40.021Z,1679518060.021 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2023-03-22T20:47:40.021Z,1679518060.021 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2023-03-22T20:47:40.021Z,1679518060.021 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2023-03-22T20:47:40.021Z,1679518060.021 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2023-03-22T20:47:40.021Z,1679518060.021 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA69M.000
2023-03-22T20:47:40.022Z,1679518060.022 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA69M.000
2023-03-22T20:47:40.049Z,1679518060.049 [CBIT](DEBUG): Backplane powered.
2023-03-22T20:47:40.053Z,1679518060.053 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2023-03-22T20:47:40.053Z,1679518060.053 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2023-03-22T20:47:40.054Z,1679518060.054 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2023-03-22T20:47:40.054Z,1679518060.054 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2023-03-22T20:47:40.054Z,1679518060.054 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2023-03-22T20:47:40.056Z,1679518060.056 [NavChart](DEBUG): Initialize NavChart Navigation.
2023-03-22T20:47:40.056Z,1679518060.056 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2023-03-22T20:47:40.063Z,1679518060.063 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2023-03-22T20:47:40.073Z,1679518060.073 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2023-03-22T20:47:40.074Z,1679518060.074 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2023-03-22T20:47:40.074Z,1679518060.074 [LoopControl](DEBUG): Initialize LoopControlComponent.
2023-03-22T20:47:40.075Z,1679518060.075 [MissionManager](INFO): Loading Mission from file: Missions/Startup.xml
2023-03-22T20:47:40.122Z,1679518060.122 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2023-03-22T20:47:40.149Z,1679518060.149 [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-22T20:47:40.150Z,1679518060.150 [MissionManager](INFO): Loading Mission from file: Missions/Default.xml
2023-03-22T20:47:40.248Z,1679518060.248 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2023-03-22T20:47:40.249Z,1679518060.249 [Default:A.Wait](DEBUG): Construct Wait.
2023-03-22T20:47:40.251Z,1679518060.251 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2023-03-22T20:47:40.294Z,1679518060.294 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2023-03-22T20:47:40.309Z,1679518060.309 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2023-03-22T20:47:40.315Z,1679518060.315 [Default:E.Execute](DEBUG): Construct Execute.
2023-03-22T20:47:40.328Z,1679518060.328 [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-22T20:47:40.353Z,1679518060.353 [controlThread](DEBUG): Component order: CycleStarter,ESPComponent,PAR_Licor,AHRS_M2,BPC1,Depth_Keller,DropWeight,DVL_micro,MultiRay,NAL9602,Power24vConverter,PAR_Licor,Depth_Keller,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-22T20:47:40.377Z,1679518060.377 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2023-03-22T20:47:40.389Z,1679518060.389 [Radio_Surface](INFO): Powering up
2023-03-22T20:47:40.498Z,1679518060.498 [Depth_Keller](ERROR): Pressure or depth reading out of range: 1895.444336 decibar, 0.000000 m
2023-03-22T20:47:40.501Z,1679518060.501 [MultiRay](INFO): Powering up MultiRay Lights
2023-03-22T20:47:40.545Z,1679518060.545 [Power24vConverter](INFO): Powering up.
2023-03-22T20:47:40.553Z,1679518060.553 [DepthRateCalculator](ERROR): Depth measurement is not active
2023-03-22T20:47:40.594Z,1679518060.594 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2023-03-22T20:47:40.601Z,1679518060.601 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2023-03-22T20:47:40.602Z,1679518060.602 [ElevatorServo](DEBUG): Initializing EZServoServo.
2023-03-22T20:47:40.609Z,1679518060.609 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2023-03-22T20:47:40.610Z,1679518060.610 [MassServo](DEBUG): Initializing EZServoServo.
2023-03-22T20:47:40.617Z,1679518060.617 [MassServo](DEBUG): Initializing MassServo.
2023-03-22T20:47:40.618Z,1679518060.618 [RudderServo](DEBUG): Initializing EZServoServo.
2023-03-22T20:47:40.625Z,1679518060.625 [RudderServo](DEBUG): Initializing RudderServo.
2023-03-22T20:47:40.626Z,1679518060.626 [ThrusterHE](DEBUG): Initializing EZServoServo.
2023-03-22T20:47:40.633Z,1679518060.633 [ThrusterHE](DEBUG): Initializing ThrusterHE.
2023-03-22T20:47:41.501Z,1679518061.501 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2023-03-22T20:47:41.501Z,1679518061.501 [RudderServo](FAULT): Rudder failed to initialize
2023-03-22T20:47:41.501Z,1679518061.501 [RudderServo] Communications Fault, FailCount= 1
2023-03-22T20:47:41.501Z,1679518061.501 [RudderServo](ERROR): Communications Fault
2023-03-22T20:47:41.505Z,1679518061.505 [CBIT](ERROR): Communications Fault in component: RudderServo
2023-03-22T20:47:41.986Z,1679518061.986 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2023-03-22T20:47:41.986Z,1679518061.986 [RudderServo](INFO): Powering down
2023-03-22T20:47:42.041Z,1679518062.041 [WetLabsBB2FL](INFO): Powering down
2023-03-22T20:47:42.429Z,1679518062.429 [RudderServo](DEBUG): Initializing EZServoServo.
2023-03-22T20:47:42.549Z,1679518062.549 [RudderServo](DEBUG): Initializing RudderServo.
2023-03-22T20:47:42.553Z,1679518062.553 [CBIT](INFO): Clearing failed state for component RudderServo
2023-03-22T20:47:42.554Z,1679518062.554 [RudderServo] No Fault, FailCount= 1
2023-03-22T20:47:46.289Z,1679518066.289 [ThrusterHE](ERROR): Zero Speed Commanded.
2023-03-22T20:47:51.853Z,1679518071.853 [DAT](INFO): DAT read: 

2023-03-22T20:47:51.855Z,1679518071.855 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series

2023-03-22T20:47:53.366Z,1679518073.366 [DAT](INFO): DAT read: MF Frequency Band

2023-03-22T20:47:53.367Z,1679518073.367 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.15.0

2023-03-22T20:47:53.367Z,1679518073.367 [DAT](INFO): DAT read: Mar 22 2023 20:47:47 

2023-03-22T20:47:54.374Z,1679518074.374 [DAT](INFO): DAT read: Features enabled [Bearing]

2023-03-22T20:47:54.375Z,1679518074.375 [DAT](INFO): DAT read: CONNECT 01200 bits/sec 1 of 4, Rate 1/2 CC

2023-03-22T20:47:54.375Z,1679518074.375 [DAT](INFO): commRate: 1200
2023-03-22T20:47:56.441Z,1679518076.441 [DAT](INFO): entering command mode
2023-03-22T20:47:56.641Z,1679518076.641 [DAT](INFO): DAT read: 

2023-03-22T20:47:56.642Z,1679518076.642 [DAT](INFO): DAT read: user:1>

2023-03-22T20:47:56.642Z,1679518076.642 [DAT](INFO): setting verbose to 3
2023-03-22T20:47:56.893Z,1679518076.893 [DAT](INFO): DAT read: user:1>

2023-03-22T20:47:56.895Z,1679518076.895 [DAT](INFO): DAT read: Verbose         | 3           

2023-03-22T20:47:56.895Z,1679518076.895 [DAT](INFO): set verbose to 3
2023-03-22T20:47:56.895Z,1679518076.895 [DAT](INFO): setting DatVerbose to 27440
2023-03-22T20:47:57.145Z,1679518077.145 [DAT](INFO): DAT read: user:2>

2023-03-22T20:47:57.146Z,1679518077.146 [DAT](INFO): DAT read: DatVerbose      | 27440       

2023-03-22T20:47:57.147Z,1679518077.147 [DAT](INFO): set DatVerbose to 27440
2023-03-22T20:47:57.147Z,1679518077.147 [DAT](INFO): setting transmit power to 8
2023-03-22T20:47:57.398Z,1679518077.398 [DAT](INFO): DAT read: user:3>

2023-03-22T20:47:57.399Z,1679518077.399 [DAT](INFO): DAT read: TxPower         | 8 (Max)     

2023-03-22T20:47:57.399Z,1679518077.399 [DAT](INFO): set transmit power to 8
2023-03-22T20:47:57.400Z,1679518077.400 [DAT](INFO): setting local address to 4
2023-03-22T20:47:57.649Z,1679518077.649 [DAT](INFO): DAT read: user:4>

2023-03-22T20:47:57.650Z,1679518077.650 [DAT](INFO): DAT read: LocalAddr       | 4           

2023-03-22T20:47:57.650Z,1679518077.650 [DAT](INFO): set local address to 4
2023-03-22T20:47:57.652Z,1679518077.652 [DAT](INFO): Setting time to: 20:47:57 And date to:3/22/2023
2023-03-22T20:47:57.901Z,1679518077.901 [DAT](INFO): DAT read: user:5>

2023-03-22T20:47:57.902Z,1679518077.902 [DAT](INFO): DAT read: Wed Mar 22, 2023  20:47:57  

2023-03-22T20:47:57.903Z,1679518077.903 [DAT](INFO): Local DAT time set to Wed Mar 22, 2023  20:47:57  

2023-03-22T20:48:07.883Z,1679518087.883 [NAL9602](INFO): Powering up NAL9602
2023-03-22T20:48:18.776Z,1679518098.776 [NAL9602](INFO): NAL9602 initialized
2023-03-22T20:48:41.811Z,1679518121.811 [NAL9602](INFO): SBD MO Status=2, MOMSN=47475, MT Status=2, MTMSN=0
2023-03-22T20:48:41.811Z,1679518121.811 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T20:49:08.477Z,1679518148.477 [NAL9602](INFO): SBD MO Status=2, MOMSN=47475, MT Status=2, MTMSN=0
2023-03-22T20:49:08.477Z,1679518148.477 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T20:49:16.959Z,1679518156.959 [NAL9602](INFO): SBD MO Status=2, MOMSN=47475, MT Status=2, MTMSN=0
2023-03-22T20:49:16.959Z,1679518156.959 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T20:49:33.114Z,1679518173.114 [NAL9602](INFO): SBD MO Status=2, MOMSN=47475, MT Status=2, MTMSN=0
2023-03-22T20:49:33.114Z,1679518173.114 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T20:49:52.116Z,1679518192.116 [NAL9602](INFO): SBD MO Status=2, MOMSN=47475, MT Status=2, MTMSN=0
2023-03-22T20:49:52.116Z,1679518192.116 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T20:50:01.806Z,1679518201.806 [NAL9602](INFO): SBD MO Status=0, MOMSN=47475, MT Status=0, MTMSN=0
2023-03-22T20:50:01.806Z,1679518201.806 [NAL9602](INFO): No messages in MT queue
2023-03-22T20:50:03.027Z,1679518203.027 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,205003.00,A,3648.15143,N,12147.22330,W,0.039,0.00,220323,,,D*7F
2023-03-22T20:50:03.030Z,1679518203.030 [NAL9602](INFO): GPS fix at 20230322T205003: (36.802524, -121.787055)
2023-03-22T20:50:20.425Z,1679518220.425 [SBIT](IMPORTANT): Beginning Startup BIT
2023-03-22T20:50:20.433Z,1679518220.433 [CBIT](IMPORTANT): Beginning ground fault scan
2023-03-22T20:50:31.326Z,1679518231.326 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): 0.034247
CHAN A1 (24V): 0.052973
CHAN A2 (12V): -0.014428
CHAN A3 (5V): -0.025323
CHAN B0 (3.3V): -0.015168
CHAN B1 (3.15aV): -0.010634
CHAN B2 (3.15bV): -0.006820
CHAN B3 (GND): -0.015615
OPEN: 0.007848
Full Scale: +/- 1 mA
2023-03-22T20:50:35.839Z,1679518235.839 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T20:50:47.867Z,1679518247.867 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-03-22T20:50:47.867Z,1679518247.867 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+15.6,0000.0,1489.WI,-00034,+00048,-02076,+00000,A
2023-03-22T20:51:14.564Z,1679518274.564 [SBIT](IMPORTANT): SBIT PASSED
2023-03-22T20:51:14.569Z,1679518274.569 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2023-03-22T20:51:14.569Z,1679518274.569 [SBIT](IMPORTANT): CBIT.gfScanTimeout=1 hour;

2023-03-22T20:51:14.570Z,1679518274.570 [SBIT](IMPORTANT): Depth_Keller.offset=-0.8 decibar;

2023-03-22T20:51:14.570Z,1679518274.570 [SBIT](IMPORTANT): ESPComponent.sampleTimeout=4 minute;

2023-03-22T20:51:14.570Z,1679518274.570 [SBIT](IMPORTANT): ESPComponent.simulateHardware=1 bool;

2023-03-22T20:51:14.570Z,1679518274.570 [SBIT](IMPORTANT): ElevatorServo.offsetAngle=1 degree;

2023-03-22T20:51:14.570Z,1679518274.570 [SBIT](IMPORTANT): Express none WetLabsBB2FL.BackscatteringCoeff470nm;

2023-03-22T20:51:14.570Z,1679518274.570 [SBIT](IMPORTANT): Express none WetLabsBB2FL.BackscatteringCoeff650nm;

2023-03-22T20:51:14.570Z,1679518274.570 [SBIT](IMPORTANT): VerticalControl.massDefault=3.5 centimeter;

2023-03-22T20:51:14.946Z,1679518274.946 [MissionManager](IMPORTANT): Started mission Startup
2023-03-22T20:51:14.947Z,1679518274.947 [Startup] Running Loop=1
2023-03-22T20:51:14.947Z,1679518274.947 [Startup](DEBUG): Aggregate::initialize Startup
2023-03-22T20:51:14.947Z,1679518274.947 [Startup:A.GoToSurface] Running Loop=1
2023-03-22T20:51:14.947Z,1679518274.947 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2023-03-22T20:51:14.948Z,1679518274.948 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2023-03-22T20:51:14.948Z,1679518274.948 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2023-03-22T20:51:14.953Z,1679518274.953 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2023-03-22T20:51:14.953Z,1679518274.953 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2023-03-22T20:51:14.953Z,1679518274.953 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2023-03-22T20:51:14.955Z,1679518274.955 [Startup:StartupSatComms] Running Loop=1
2023-03-22T20:51:14.955Z,1679518274.955 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2023-03-22T20:51:14.955Z,1679518274.955 [Startup:StartupSatComms:A] Running Loop=1
2023-03-22T20:51:15.361Z,1679518275.361 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2023-03-22T20:51:16.984Z,1679518276.984 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,205117.00,A,3648.15175,N,12147.22308,W,0.019,0.00,220323,,,D*77
2023-03-22T20:51:16.987Z,1679518276.987 [NAL9602](INFO): GPS fix at 20230322T205117: (36.802529, -121.787051)
2023-03-22T20:51:17.015Z,1679518277.015 [Startup:StartupSatComms:A] Stopped
2023-03-22T20:51:17.015Z,1679518277.015 [Startup:StartupSatComms:B] Running Loop=1
2023-03-22T20:51:17.406Z,1679518277.406 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2023-03-22T20:51:17.426Z,1679518277.426 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004278
2023-03-22T20:51:25.018Z,1679518285.018 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20230322T183857/Courier0079.lzma
2023-03-22T20:51:26.015Z,1679518286.015 [DataOverHttps](INFO): Moved sent file to Logs/20230322T183857/Courier0079.lzma.bak
2023-03-22T20:51:26.015Z,1679518286.015 [DataOverHttps](INFO): SBD MOMSN=17542505
2023-03-22T20:51:46.444Z,1679518306.444 [DataOverHttps](INFO): Sending 268 bytes from file Logs/20230322T204727/Courier0000.lzma
2023-03-22T20:51:47.446Z,1679518307.446 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Courier0000.lzma.bak
2023-03-22T20:51:47.446Z,1679518307.446 [DataOverHttps](INFO): SBD MOMSN=17542510
2023-03-22T20:51:54.176Z,1679518314.176 [NAL9602](INFO): SBD MO Status=0, MOMSN=47476, MT Status=0, MTMSN=0
2023-03-22T20:51:54.176Z,1679518314.176 [NAL9602](INFO): No messages in MT queue
2023-03-22T20:52:03.646Z,1679518323.646 [DataOverHttps](INFO): Sending 219 bytes from file Logs/20230322T183857/Express0080.lzma
2023-03-22T20:52:04.631Z,1679518324.631 [DataOverHttps](INFO): Moved sent file to Logs/20230322T183857/Express0080.lzma.bak
2023-03-22T20:52:04.631Z,1679518324.631 [DataOverHttps](INFO): SBD MOMSN=17542522
2023-03-22T20:52:17.238Z,1679518337.238 [Startup:StartupSatComms:B](INFO): Timed out from 2023-03-22T20:51:17.0Z
2023-03-22T20:52:17.238Z,1679518337.238 [Startup:StartupSatComms:B] Stopped
2023-03-22T20:52:17.238Z,1679518337.238 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2023-03-22T20:52:17.238Z,1679518337.238 [Startup:StartupSatComms] Stopped
2023-03-22T20:52:17.238Z,1679518337.238 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2023-03-22T20:52:17.239Z,1679518337.239 [Startup](INFO): Completed Startup
2023-03-22T20:52:17.239Z,1679518337.239 [MissionManager](INFO): Startup is completed.
2023-03-22T20:52:17.239Z,1679518337.239 [MissionManager](INFO): Uninitializing Mission Startup
2023-03-22T20:52:17.239Z,1679518337.239 [Startup] Stopped
2023-03-22T20:52:17.240Z,1679518337.240 [Startup](DEBUG): Aggregate::uninitialize Startup
2023-03-22T20:52:17.240Z,1679518337.240 [Startup:A.GoToSurface] Stopped
2023-03-22T20:52:17.240Z,1679518337.240 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2023-03-22T20:52:17.647Z,1679518337.647 [MissionManager](IMPORTANT): Started mission Default
2023-03-22T20:52:17.648Z,1679518337.648 [Default] Running Loop=1
2023-03-22T20:52:17.648Z,1679518337.648 [Default](DEBUG): Aggregate::initialize Default
2023-03-22T20:52:17.648Z,1679518337.648 [Default:B.GoToSurface] Running Loop=1
2023-03-22T20:52:17.648Z,1679518337.648 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2023-03-22T20:52:17.648Z,1679518337.648 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2023-03-22T20:52:17.653Z,1679518337.653 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2023-03-22T20:52:17.653Z,1679518337.653 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2023-03-22T20:52:17.653Z,1679518337.653 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2023-03-22T20:52:17.654Z,1679518337.654 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2023-03-22T20:52:17.654Z,1679518337.654 [Default:A.Wait] Running Loop=1
2023-03-22T20:52:17.654Z,1679518337.654 [Default:A.Wait](DEBUG): Initialize Wait Component.
2023-03-22T20:52:20.958Z,1679518340.958 [DataOverHttps](INFO): Sending 916 bytes from file Logs/20230322T204727/Express0001.lzma
2023-03-22T20:52:21.959Z,1679518341.959 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Express0001.lzma.bak
2023-03-22T20:52:21.959Z,1679518341.959 [DataOverHttps](INFO): SBD MOMSN=17542557
2023-03-22T20:52:24.894Z,1679518344.894 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T20:52:26.923Z,1679518346.923 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-03-22T20:52:26.924Z,1679518346.924 [DVL_micro](ERROR): Failed to parse:
:TS,000000000000015.6,0000.0,1489.0,000
2023-03-22T20:52:30.979Z,1679518350.979 [Default:A.Wait](INFO): Done Waiting.
2023-03-22T20:52:30.979Z,1679518350.979 [Default:A.Wait] Stopped
2023-03-22T20:52:30.979Z,1679518350.979 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T20:52:31.383Z,1679518351.383 [Default:CheckIn] Running Loop=1
2023-03-22T20:52:31.384Z,1679518351.384 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T20:52:31.384Z,1679518351.384 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T20:52:31.801Z,1679518351.801 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2023-03-22T20:52:33.371Z,1679518353.371 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,205233.00,A,3648.15121,N,12147.22332,W,0.039,0.00,220323,,,D*78
2023-03-22T20:52:33.373Z,1679518353.373 [NAL9602](INFO): GPS fix at 20230322T205233: (36.802520, -121.787055)
2023-03-22T20:52:33.382Z,1679518353.382 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T20:52:33.382Z,1679518353.382 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T20:52:33.786Z,1679518353.786 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2023-03-22T20:52:44.268Z,1679518364.268 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230322T204727/Courier0004.lzma
2023-03-22T20:52:45.270Z,1679518365.270 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Courier0004.lzma.bak
2023-03-22T20:52:45.271Z,1679518365.271 [DataOverHttps](INFO): SBD MOMSN=17542581
2023-03-22T20:52:47.959Z,1679518367.959 [NAL9602](INFO): SBD MO Status=0, MOMSN=47477, MT Status=0, MTMSN=0
2023-03-22T20:52:47.960Z,1679518367.960 [NAL9602](INFO): No messages in MT queue
2023-03-22T20:53:01.592Z,1679518381.592 [DataOverHttps](INFO): Sending 105 bytes from file Logs/20230322T204727/Express0005.lzma
2023-03-22T20:53:02.598Z,1679518382.598 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Express0005.lzma.bak
2023-03-22T20:53:02.598Z,1679518382.598 [DataOverHttps](INFO): SBD MOMSN=17542584
2023-03-22T20:53:03.804Z,1679518383.804 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T20:53:03.804Z,1679518383.804 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T20:53:03.804Z,1679518383.804 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T20:53:18.686Z,1679518398.686 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T20:53:57.075Z,1679518437.075 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2023-03-22T20:53:57.078Z,1679518437.078 [BPC1](INFO): Received data from all battery sticks.
2023-03-22T20:54:00.344Z,1679518440.344 [DVL_micro](ERROR): only read 2 of 4 data items
2023-03-22T20:54:00.345Z,1679518440.345 [DVL_micro](ERROR): Failed to parse:
:RD,+99999.99,+99999.99
2023-03-22T20:58:04.377Z,1679518684.377 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T20:58:04.377Z,1679518684.377 [Default:CheckIn:C.Wait] Stopped
2023-03-22T20:58:04.377Z,1679518684.377 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T20:58:04.377Z,1679518684.377 [Default:CheckIn:D] Running Loop=1
2023-03-22T20:58:04.774Z,1679518684.774 [Default:CheckIn:D] Stopped
2023-03-22T20:58:04.774Z,1679518684.774 [Default:CheckIn:E] Running Loop=1
2023-03-22T20:58:05.174Z,1679518685.174 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 5.785439 min 
2023-03-22T20:58:05.174Z,1679518685.174 [Default:CheckIn:E] Stopped
2023-03-22T20:58:05.174Z,1679518685.174 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T20:58:05.174Z,1679518685.174 [Default:CheckIn] Stopped
2023-03-22T20:58:05.174Z,1679518685.174 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T20:58:05.174Z,1679518685.174 [Default:CheckIn](INFO): Running loop #2
2023-03-22T20:58:05.175Z,1679518685.175 [Default:CheckIn] Running Loop=2
2023-03-22T20:58:05.175Z,1679518685.175 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T20:58:05.175Z,1679518685.175 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T20:58:07.192Z,1679518687.192 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,205807.00,A,3648.15081,N,12147.22232,W,0.019,0.00,220323,,,D*7D
2023-03-22T20:58:07.195Z,1679518687.195 [NAL9602](INFO): GPS fix at 20230322T205807: (36.802514, -121.787039)
2023-03-22T20:58:07.204Z,1679518687.204 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T20:58:07.204Z,1679518687.204 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T20:58:14.144Z,1679518694.144 [DataOverHttps](INFO): Sending 202 bytes from file Logs/20230322T204727/Courier0007.lzma
2023-03-22T20:58:15.146Z,1679518695.146 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Courier0007.lzma.bak
2023-03-22T20:58:15.147Z,1679518695.147 [DataOverHttps](INFO): SBD MOMSN=17542589
2023-03-22T20:58:31.068Z,1679518711.068 [DataOverHttps](INFO): Sending 161 bytes from file Logs/20230322T204727/Express0008.lzma
2023-03-22T20:58:32.071Z,1679518712.071 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Express0008.lzma.bak
2023-03-22T20:58:32.071Z,1679518712.071 [DataOverHttps](INFO): SBD MOMSN=17542592
2023-03-22T20:58:33.466Z,1679518713.466 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T20:58:33.466Z,1679518713.466 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T20:58:33.466Z,1679518713.466 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T20:59:19.581Z,1679518759.581 [NAL9602](INFO): SBD MO Status=2, MOMSN=47478, MT Status=2, MTMSN=0
2023-03-22T20:59:19.581Z,1679518759.581 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T21:00:12.940Z,1679518812.940 [NAL9602](INFO): SBD MO Status=2, MOMSN=47478, MT Status=2, MTMSN=0
2023-03-22T21:00:12.940Z,1679518812.940 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T21:00:31.912Z,1679518831.912 [NAL9602](INFO): SBD MO Status=0, MOMSN=47478, MT Status=0, MTMSN=0
2023-03-22T21:00:31.912Z,1679518831.912 [NAL9602](INFO): No messages in MT queue
2023-03-22T21:01:02.647Z,1679518862.647 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T21:03:34.177Z,1679519014.177 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T21:03:34.177Z,1679519014.177 [Default:CheckIn:C.Wait] Stopped
2023-03-22T21:03:34.177Z,1679519014.177 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T21:03:34.177Z,1679519014.177 [Default:CheckIn:D] Running Loop=1
2023-03-22T21:03:34.562Z,1679519014.562 [Default:CheckIn:D] Stopped
2023-03-22T21:03:34.562Z,1679519014.562 [Default:CheckIn:E] Running Loop=1
2023-03-22T21:03:34.967Z,1679519014.967 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 11.281902 min 
2023-03-22T21:03:34.967Z,1679519014.967 [Default:CheckIn:E] Stopped
2023-03-22T21:03:34.968Z,1679519014.968 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T21:03:34.968Z,1679519014.968 [Default:CheckIn] Stopped
2023-03-22T21:03:34.968Z,1679519014.968 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T21:03:34.968Z,1679519014.968 [Default:CheckIn](INFO): Running loop #3
2023-03-22T21:03:34.968Z,1679519014.968 [Default:CheckIn] Running Loop=3
2023-03-22T21:03:34.968Z,1679519014.968 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T21:03:34.968Z,1679519014.968 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T21:03:36.971Z,1679519016.971 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,210337.00,A,3648.14979,N,12147.22321,W,0.000,0.00,220323,,,D*75
2023-03-22T21:03:36.981Z,1679519016.981 [NAL9602](INFO): GPS fix at 20230322T210337: (36.802496, -121.787053)
2023-03-22T21:03:37.011Z,1679519017.011 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T21:03:37.011Z,1679519017.011 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T21:03:45.300Z,1679519025.300 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230322T204727/Courier0010.lzma
2023-03-22T21:03:46.302Z,1679519026.302 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Courier0010.lzma.bak
2023-03-22T21:03:46.303Z,1679519026.303 [DataOverHttps](INFO): SBD MOMSN=17542618
2023-03-22T21:04:02.360Z,1679519042.360 [DataOverHttps](INFO): Sending 128 bytes from file Logs/20230322T204727/Express0011.lzma
2023-03-22T21:04:03.362Z,1679519043.362 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Express0011.lzma.bak
2023-03-22T21:04:03.363Z,1679519043.363 [DataOverHttps](INFO): SBD MOMSN=17542621
2023-03-22T21:04:04.451Z,1679519044.451 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T21:04:04.451Z,1679519044.451 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T21:04:04.451Z,1679519044.451 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T21:04:06.059Z,1679519046.059 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-03-22T21:04:06.059Z,1679519046.059 [DVL_micro](ERROR): Failed to parse:
:TS,000000000000005.8,0000.0,1489.0,000
2023-03-22T21:05:13.973Z,1679519113.973 [NAL9602](INFO): SBD MO Status=2, MOMSN=47479, MT Status=2, MTMSN=0
2023-03-22T21:05:13.973Z,1679519113.973 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T21:05:53.162Z,1679519153.162 [NAL9602](INFO): SBD MO Status=0, MOMSN=47479, MT Status=0, MTMSN=0
2023-03-22T21:05:53.163Z,1679519153.163 [NAL9602](INFO): No messages in MT queue
2023-03-22T21:06:23.869Z,1679519183.869 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T21:09:05.087Z,1679519345.087 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T21:09:05.087Z,1679519345.087 [Default:CheckIn:C.Wait] Stopped
2023-03-22T21:09:05.087Z,1679519345.087 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T21:09:05.087Z,1679519345.087 [Default:CheckIn:D] Running Loop=1
2023-03-22T21:09:05.483Z,1679519345.483 [Default:CheckIn:D] Stopped
2023-03-22T21:09:05.483Z,1679519345.483 [Default:CheckIn:E] Running Loop=1
2023-03-22T21:09:05.884Z,1679519345.884 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 16.797247 min 
2023-03-22T21:09:05.884Z,1679519345.884 [Default:CheckIn:E] Stopped
2023-03-22T21:09:05.885Z,1679519345.885 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T21:09:05.885Z,1679519345.885 [Default:CheckIn] Stopped
2023-03-22T21:09:05.885Z,1679519345.885 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T21:09:05.886Z,1679519345.886 [Default:CheckIn](INFO): Running loop #4
2023-03-22T21:09:05.886Z,1679519345.886 [Default:CheckIn] Running Loop=4
2023-03-22T21:09:05.886Z,1679519345.886 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T21:09:05.886Z,1679519345.886 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T21:09:07.907Z,1679519347.907 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,210908.00,A,3648.15057,N,12147.22235,W,0.253,0.00,220323,,,D*77
2023-03-22T21:09:07.910Z,1679519347.910 [NAL9602](INFO): GPS fix at 20230322T210908: (36.802509, -121.787039)
2023-03-22T21:09:07.919Z,1679519347.919 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T21:09:07.919Z,1679519347.919 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T21:09:15.668Z,1679519355.668 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230322T204727/Courier0013.lzma
2023-03-22T21:09:16.670Z,1679519356.670 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Courier0013.lzma.bak
2023-03-22T21:09:16.671Z,1679519356.671 [DataOverHttps](INFO): SBD MOMSN=17542632
2023-03-22T21:09:33.020Z,1679519373.020 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20230322T204727/Express0014.lzma
2023-03-22T21:09:34.023Z,1679519374.023 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Express0014.lzma.bak
2023-03-22T21:09:34.023Z,1679519374.023 [DataOverHttps](INFO): SBD MOMSN=17542639
2023-03-22T21:09:34.559Z,1679519374.559 [NAL9602](INFO): SBD MO Status=2, MOMSN=47480, MT Status=2, MTMSN=0
2023-03-22T21:09:34.559Z,1679519374.559 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T21:09:35.407Z,1679519375.407 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T21:09:35.408Z,1679519375.408 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T21:09:35.408Z,1679519375.408 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T21:09:45.107Z,1679519385.107 [NAL9602](INFO): SBD MO Status=0, MOMSN=47480, MT Status=0, MTMSN=0
2023-03-22T21:09:45.107Z,1679519385.107 [NAL9602](INFO): No messages in MT queue
2023-03-22T21:10:15.822Z,1679519415.822 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T21:14:36.002Z,1679519676.002 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T21:14:36.002Z,1679519676.002 [Default:CheckIn:C.Wait] Stopped
2023-03-22T21:14:36.002Z,1679519676.002 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T21:14:36.003Z,1679519676.003 [Default:CheckIn:D] Running Loop=1
2023-03-22T21:14:36.443Z,1679519676.443 [Default:CheckIn:D] Stopped
2023-03-22T21:14:36.444Z,1679519676.444 [Default:CheckIn:E] Running Loop=1
2023-03-22T21:14:36.852Z,1679519676.852 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 22.313263 min 
2023-03-22T21:14:36.852Z,1679519676.852 [Default:CheckIn:E] Stopped
2023-03-22T21:14:36.853Z,1679519676.853 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T21:14:36.853Z,1679519676.853 [Default:CheckIn] Stopped
2023-03-22T21:14:36.853Z,1679519676.853 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T21:14:36.853Z,1679519676.853 [Default:CheckIn](INFO): Running loop #5
2023-03-22T21:14:36.853Z,1679519676.853 [Default:CheckIn] Running Loop=5
2023-03-22T21:14:36.853Z,1679519676.853 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T21:14:36.853Z,1679519676.853 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T21:14:38.831Z,1679519678.831 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,211438.00,A,3648.15120,N,12147.22353,W,0.039,0.00,220323,,,D*76
2023-03-22T21:14:38.838Z,1679519678.838 [NAL9602](INFO): GPS fix at 20230322T211438: (36.802520, -121.787059)
2023-03-22T21:14:38.881Z,1679519678.881 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T21:14:38.881Z,1679519678.881 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T21:14:46.800Z,1679519686.800 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230322T204727/Courier0016.lzma
2023-03-22T21:14:47.802Z,1679519687.802 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Courier0016.lzma.bak
2023-03-22T21:14:47.803Z,1679519687.803 [DataOverHttps](INFO): SBD MOMSN=17542651
2023-03-22T21:15:03.844Z,1679519703.844 [DataOverHttps](INFO): Sending 128 bytes from file Logs/20230322T204727/Express0017.lzma
2023-03-22T21:15:04.847Z,1679519704.847 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Express0017.lzma.bak
2023-03-22T21:15:04.847Z,1679519704.847 [DataOverHttps](INFO): SBD MOMSN=17542655
2023-03-22T21:15:05.937Z,1679519705.937 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T21:15:05.937Z,1679519705.937 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T21:15:05.937Z,1679519705.937 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T21:16:12.578Z,1679519772.578 [NAL9602](INFO): SBD MO Status=2, MOMSN=47481, MT Status=2, MTMSN=0
2023-03-22T21:16:12.579Z,1679519772.579 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T21:18:49.756Z,1679519929.756 [NAL9602](INFO): SBD MO Status=2, MOMSN=47481, MT Status=2, MTMSN=0
2023-03-22T21:18:49.756Z,1679519929.756 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T21:19:07.941Z,1679519947.941 [NAL9602](INFO): SBD MO Status=0, MOMSN=47481, MT Status=0, MTMSN=0
2023-03-22T21:19:07.941Z,1679519947.941 [NAL9602](INFO): No messages in MT queue
2023-03-22T21:19:38.634Z,1679519978.634 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T21:20:06.529Z,1679520006.529 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T21:20:06.529Z,1679520006.529 [Default:CheckIn:C.Wait] Stopped
2023-03-22T21:20:06.529Z,1679520006.529 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T21:20:06.529Z,1679520006.529 [Default:CheckIn:D] Running Loop=1
2023-03-22T21:20:06.927Z,1679520006.927 [Default:CheckIn:D] Stopped
2023-03-22T21:20:06.927Z,1679520006.927 [Default:CheckIn:E] Running Loop=1
2023-03-22T21:20:07.330Z,1679520007.330 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 27.821320 min 
2023-03-22T21:20:07.330Z,1679520007.330 [Default:CheckIn:E] Stopped
2023-03-22T21:20:07.330Z,1679520007.330 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T21:20:07.330Z,1679520007.330 [Default:CheckIn] Stopped
2023-03-22T21:20:07.331Z,1679520007.331 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T21:20:07.331Z,1679520007.331 [Default:CheckIn](INFO): Running loop #6
2023-03-22T21:20:07.331Z,1679520007.331 [Default:CheckIn] Running Loop=6
2023-03-22T21:20:07.331Z,1679520007.331 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T21:20:07.331Z,1679520007.331 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T21:20:09.345Z,1679520009.345 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,212009.00,A,3648.15125,N,12147.22367,W,0.019,0.00,220323,,,D*73
2023-03-22T21:20:09.347Z,1679520009.347 [NAL9602](INFO): GPS fix at 20230322T212009: (36.802521, -121.787061)
2023-03-22T21:20:09.356Z,1679520009.356 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T21:20:09.356Z,1679520009.356 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T21:20:16.920Z,1679520016.920 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230322T204727/Courier0019.lzma
2023-03-22T21:20:17.922Z,1679520017.922 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Courier0019.lzma.bak
2023-03-22T21:20:17.923Z,1679520017.923 [DataOverHttps](INFO): SBD MOMSN=17542689
2023-03-22T21:20:35.956Z,1679520035.956 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20230322T204727/Express0020.lzma
2023-03-22T21:20:36.959Z,1679520036.959 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Express0020.lzma.bak
2023-03-22T21:20:36.959Z,1679520036.959 [DataOverHttps](INFO): SBD MOMSN=17542692
2023-03-22T21:20:38.102Z,1679520038.102 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T21:20:38.103Z,1679520038.103 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T21:20:38.103Z,1679520038.103 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T21:20:54.250Z,1679520054.250 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-03-22T21:20:54.250Z,1679520054.250 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+16.3,0000.0,1489.0I,+01348,+00165,-01669,+00000,A
2023-03-22T21:22:30.379Z,1679520150.379 [NAL9602](INFO): SBD MO Status=2, MOMSN=47482, MT Status=2, MTMSN=0
2023-03-22T21:22:30.379Z,1679520150.379 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T21:23:48.348Z,1679520228.348 [NAL9602](INFO): SBD MO Status=0, MOMSN=47482, MT Status=0, MTMSN=0
2023-03-22T21:23:48.348Z,1679520228.348 [NAL9602](INFO): No messages in MT queue
2023-03-22T21:24:19.046Z,1679520259.046 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T21:25:38.668Z,1679520338.668 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T21:25:38.668Z,1679520338.668 [Default:CheckIn:C.Wait] Stopped
2023-03-22T21:25:38.668Z,1679520338.668 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T21:25:38.668Z,1679520338.668 [Default:CheckIn:D] Running Loop=1
2023-03-22T21:25:39.073Z,1679520339.073 [Default:CheckIn:D] Stopped
2023-03-22T21:25:39.073Z,1679520339.073 [Default:CheckIn:E] Running Loop=1
2023-03-22T21:25:39.482Z,1679520339.482 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 33.357094 min 
2023-03-22T21:25:39.482Z,1679520339.482 [Default:CheckIn:E] Stopped
2023-03-22T21:25:39.482Z,1679520339.482 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T21:25:39.483Z,1679520339.483 [Default:CheckIn] Stopped
2023-03-22T21:25:39.483Z,1679520339.483 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T21:25:39.483Z,1679520339.483 [Default:CheckIn](INFO): Running loop #7
2023-03-22T21:25:39.483Z,1679520339.483 [Default:CheckIn] Running Loop=7
2023-03-22T21:25:39.483Z,1679520339.483 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T21:25:39.483Z,1679520339.483 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T21:25:41.471Z,1679520341.471 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,212541.00,A,3648.15121,N,12147.22437,W,0.019,0.00,220323,,,D*7C
2023-03-22T21:25:41.473Z,1679520341.473 [NAL9602](INFO): GPS fix at 20230322T212541: (36.802520, -121.787073)
2023-03-22T21:25:41.503Z,1679520341.503 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T21:25:41.503Z,1679520341.503 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T21:25:48.792Z,1679520348.792 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230322T204727/Courier0022.lzma
2023-03-22T21:25:49.794Z,1679520349.794 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Courier0022.lzma.bak
2023-03-22T21:25:49.795Z,1679520349.795 [DataOverHttps](INFO): SBD MOMSN=17542713
2023-03-22T21:26:05.708Z,1679520365.708 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20230322T204727/Express0023.lzma
2023-03-22T21:26:06.710Z,1679520366.710 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Express0023.lzma.bak
2023-03-22T21:26:06.711Z,1679520366.711 [DataOverHttps](INFO): SBD MOMSN=17542716
2023-03-22T21:26:08.173Z,1679520368.173 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T21:26:08.173Z,1679520368.173 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T21:26:08.174Z,1679520368.174 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T21:26:59.072Z,1679520419.072 [NAL9602](INFO): SBD MO Status=0, MOMSN=47483, MT Status=0, MTMSN=0
2023-03-22T21:26:59.072Z,1679520419.072 [NAL9602](INFO): No messages in MT queue
2023-03-22T21:27:29.784Z,1679520449.784 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T21:31:08.838Z,1679520668.838 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T21:31:08.838Z,1679520668.838 [Default:CheckIn:C.Wait] Stopped
2023-03-22T21:31:08.838Z,1679520668.838 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T21:31:08.838Z,1679520668.838 [Default:CheckIn:D] Running Loop=1
2023-03-22T21:31:09.251Z,1679520669.251 [Default:CheckIn:D] Stopped
2023-03-22T21:31:09.251Z,1679520669.251 [Default:CheckIn:E] Running Loop=1
2023-03-22T21:31:09.656Z,1679520669.656 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 38.860055 min 
2023-03-22T21:31:09.656Z,1679520669.656 [Default:CheckIn:E] Stopped
2023-03-22T21:31:09.656Z,1679520669.656 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T21:31:09.656Z,1679520669.656 [Default:CheckIn] Stopped
2023-03-22T21:31:09.656Z,1679520669.656 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T21:31:09.657Z,1679520669.657 [Default:CheckIn](INFO): Running loop #8
2023-03-22T21:31:09.657Z,1679520669.657 [Default:CheckIn] Running Loop=8
2023-03-22T21:31:09.657Z,1679520669.657 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T21:31:09.657Z,1679520669.657 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T21:31:11.659Z,1679520671.659 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213111.00,A,3648.15115,N,12147.22272,W,0.000,0.00,220323,,,D*74
2023-03-22T21:31:11.662Z,1679520671.662 [NAL9602](INFO): GPS fix at 20230322T213111: (36.802519, -121.787045)
2023-03-22T21:31:11.671Z,1679520671.671 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T21:31:11.671Z,1679520671.671 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T21:31:19.376Z,1679520679.376 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20230322T204727/Courier0025.lzma
2023-03-22T21:31:20.378Z,1679520680.378 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Courier0025.lzma.bak
2023-03-22T21:31:20.379Z,1679520680.379 [DataOverHttps](INFO): SBD MOMSN=17542730
2023-03-22T21:31:34.712Z,1679520694.712 [NAL9602](INFO): SBD MO Status=2, MOMSN=47484, MT Status=2, MTMSN=0
2023-03-22T21:31:34.713Z,1679520694.713 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T21:31:39.272Z,1679520699.272 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20230322T204727/Express0026.lzma
2023-03-22T21:31:40.275Z,1679520700.275 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Express0026.lzma.bak
2023-03-22T21:31:40.275Z,1679520700.275 [DataOverHttps](INFO): SBD MOMSN=17542733
2023-03-22T21:31:41.621Z,1679520701.621 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T21:31:41.621Z,1679520701.621 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T21:31:41.621Z,1679520701.621 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T21:32:20.384Z,1679520740.384 [NAL9602](INFO): SBD MO Status=2, MOMSN=47484, MT Status=2, MTMSN=0
2023-03-22T21:32:20.384Z,1679520740.384 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T21:33:19.450Z,1679520799.450 [NAL9602](INFO): SBD MO Status=2, MOMSN=47484, MT Status=2, MTMSN=0
2023-03-22T21:33:19.450Z,1679520799.450 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T21:34:06.711Z,1679520846.711 [NAL9602](INFO): SBD MO Status=2, MOMSN=47484, MT Status=2, MTMSN=0
2023-03-22T21:34:06.711Z,1679520846.711 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T21:34:30.145Z,1679520870.145 [DVL_micro](ERROR): only read 3 of 4 data items
2023-03-22T21:34:30.145Z,1679520870.145 [DVL_micro](ERROR): Failed to parse:
:BI,+00758,01816,+00000,I
2023-03-22T21:34:54.388Z,1679520894.388 [NAL9602](INFO): SBD MO Status=2, MOMSN=47484, MT Status=2, MTMSN=0
2023-03-22T21:34:54.388Z,1679520894.388 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T21:35:44.488Z,1679520944.488 [NAL9602](INFO): SBD MO Status=2, MOMSN=47484, MT Status=2, MTMSN=0
2023-03-22T21:35:44.489Z,1679520944.489 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T21:36:20.844Z,1679520980.844 [NAL9602](INFO): SBD MO Status=0, MOMSN=47484, MT Status=0, MTMSN=0
2023-03-22T21:36:20.844Z,1679520980.844 [NAL9602](INFO): No messages in MT queue
2023-03-22T21:36:42.265Z,1679521002.265 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T21:36:42.266Z,1679521002.266 [Default:CheckIn:C.Wait] Stopped
2023-03-22T21:36:42.266Z,1679521002.266 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T21:36:42.266Z,1679521002.266 [Default:CheckIn:D] Running Loop=1
2023-03-22T21:36:42.672Z,1679521002.672 [Default:CheckIn:D] Stopped
2023-03-22T21:36:42.672Z,1679521002.672 [Default:CheckIn:E] Running Loop=1
2023-03-22T21:36:43.084Z,1679521003.084 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 44.417065 min 
2023-03-22T21:36:43.085Z,1679521003.085 [Default:CheckIn:E] Stopped
2023-03-22T21:36:43.085Z,1679521003.085 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T21:36:43.085Z,1679521003.085 [Default:CheckIn] Stopped
2023-03-22T21:36:43.085Z,1679521003.085 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T21:36:43.085Z,1679521003.085 [Default:CheckIn](INFO): Running loop #9
2023-03-22T21:36:43.085Z,1679521003.085 [Default:CheckIn] Running Loop=9
2023-03-22T21:36:43.085Z,1679521003.085 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T21:36:43.085Z,1679521003.085 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T21:36:45.087Z,1679521005.087 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213645.00,A,3648.15148,N,12147.22009,W,0.505,36.47,220323,,,A*47
2023-03-22T21:36:45.089Z,1679521005.089 [NAL9602](INFO): GPS fix at 20230322T213645: (36.802525, -121.787002)
2023-03-22T21:36:45.099Z,1679521005.099 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T21:36:45.099Z,1679521005.099 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T21:36:52.489Z,1679521012.489 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230322T204727/Courier0028.lzma
2023-03-22T21:36:53.491Z,1679521013.491 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Courier0028.lzma.bak
2023-03-22T21:36:53.491Z,1679521013.491 [DataOverHttps](INFO): SBD MOMSN=17542774
2023-03-22T21:37:09.372Z,1679521029.372 [DataOverHttps](INFO): Sending 128 bytes from file Logs/20230322T204727/Express0029.lzma
2023-03-22T21:37:10.374Z,1679521030.374 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Express0029.lzma.bak
2023-03-22T21:37:10.375Z,1679521030.375 [DataOverHttps](INFO): SBD MOMSN=17542777
2023-03-22T21:37:11.755Z,1679521031.755 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T21:37:11.755Z,1679521031.755 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T21:37:11.755Z,1679521031.755 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T21:37:17.806Z,1679521037.806 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T21:37:57.885Z,1679521077.885 [DVL_micro](ERROR): DVL uart error: serial timeout
2023-03-22T21:37:57.885Z,1679521077.885 [DVL_micro] Communications Fault, FailCount= 1
2023-03-22T21:37:57.885Z,1679521077.885 [DVL_micro](ERROR): Communications Fault
2023-03-22T21:37:57.885Z,1679521077.885 [DVL_micro](ERROR): Failed to parse:
2023-03-22T21:37:57.935Z,1679521077.935 [CBIT](ERROR): Communications Fault in component: DVL_micro
2023-03-22T21:37:58.273Z,1679521078.273 [DVL_micro](INFO): Powering down
2023-03-22T21:37:59.034Z,1679521079.034 [CBIT](INFO): Clearing failed state for component DVL_micro
2023-03-22T21:37:59.034Z,1679521079.034 [DVL_micro] No Fault, FailCount= 1
2023-03-22T21:39:22.699Z,1679521162.699 [DVL_micro](ERROR): Failed to parse:
0000000000,35.0,+16.8,0000.0,1489.0,000
2023-03-22T21:42:12.388Z,1679521332.388 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T21:42:12.388Z,1679521332.388 [Default:CheckIn:C.Wait] Stopped
2023-03-22T21:42:12.388Z,1679521332.388 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T21:42:12.388Z,1679521332.388 [Default:CheckIn:D] Running Loop=1
2023-03-22T21:42:12.779Z,1679521332.779 [Default:CheckIn:D] Stopped
2023-03-22T21:42:12.779Z,1679521332.779 [Default:CheckIn:E] Running Loop=1
2023-03-22T21:42:13.188Z,1679521333.188 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 49.918860 min 
2023-03-22T21:42:13.188Z,1679521333.188 [Default:CheckIn:E] Stopped
2023-03-22T21:42:13.188Z,1679521333.188 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T21:42:13.189Z,1679521333.189 [Default:CheckIn] Stopped
2023-03-22T21:42:13.189Z,1679521333.189 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T21:42:13.189Z,1679521333.189 [Default:CheckIn](INFO): Running loop #10
2023-03-22T21:42:13.189Z,1679521333.189 [Default:CheckIn] Running Loop=10
2023-03-22T21:42:13.189Z,1679521333.189 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T21:42:13.189Z,1679521333.189 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T21:42:15.221Z,1679521335.221 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,214215.00,A,3648.15036,N,12147.22276,W,0.019,185.53,220323,,,D*72
2023-03-22T21:42:15.223Z,1679521335.223 [NAL9602](INFO): GPS fix at 20230322T214215: (36.802506, -121.787046)
2023-03-22T21:42:15.249Z,1679521335.249 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T21:42:15.249Z,1679521335.249 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T21:42:22.580Z,1679521342.580 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230322T204727/Courier0031.lzma
2023-03-22T21:42:23.583Z,1679521343.583 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Courier0031.lzma.bak
2023-03-22T21:42:23.583Z,1679521343.583 [DataOverHttps](INFO): SBD MOMSN=17542788
2023-03-22T21:42:42.580Z,1679521362.580 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20230322T204727/Express0032.lzma
2023-03-22T21:42:43.582Z,1679521363.582 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Express0032.lzma.bak
2023-03-22T21:42:43.583Z,1679521363.583 [DataOverHttps](INFO): SBD MOMSN=17542791
2023-03-22T21:42:44.787Z,1679521364.787 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T21:42:44.787Z,1679521364.787 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T21:42:44.787Z,1679521364.787 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T21:45:10.233Z,1679521510.233 [NAL9602](INFO): SBD MO Status=2, MOMSN=47485, MT Status=2, MTMSN=0
2023-03-22T21:45:10.233Z,1679521510.233 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T21:45:36.098Z,1679521536.098 [NAL9602](INFO): SBD MO Status=2, MOMSN=47485, MT Status=2, MTMSN=0
2023-03-22T21:45:36.098Z,1679521536.098 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T21:46:33.067Z,1679521593.067 [DVL_micro](ERROR): DVL BIT error. See manual. Result code: 1130
2023-03-22T21:46:33.069Z,1679521593.069 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.00,+00000000.00,9999.99,000.00
2023-03-22T21:47:13.871Z,1679521633.871 [NAL9602](INFO): SBD MO Status=2, MOMSN=47485, MT Status=2, MTMSN=0
2023-03-22T21:47:13.871Z,1679521633.871 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T21:47:17.490Z,1679521637.490 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-03-22T21:47:45.381Z,1679521665.381 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T21:47:45.381Z,1679521665.381 [Default:CheckIn:C.Wait] Stopped
2023-03-22T21:47:45.382Z,1679521665.382 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T21:47:45.382Z,1679521665.382 [Default:CheckIn:D] Running Loop=1
2023-03-22T21:47:45.783Z,1679521665.783 [Default:CheckIn:D] Stopped
2023-03-22T21:47:45.783Z,1679521665.783 [Default:CheckIn:E] Running Loop=1
2023-03-22T21:47:46.195Z,1679521666.195 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 55.468921 min 
2023-03-22T21:47:46.195Z,1679521666.195 [Default:CheckIn:E] Stopped
2023-03-22T21:47:46.195Z,1679521666.195 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T21:47:46.195Z,1679521666.195 [Default:CheckIn] Stopped
2023-03-22T21:47:46.195Z,1679521666.195 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T21:47:46.196Z,1679521666.196 [Default:CheckIn](INFO): Running loop #11
2023-03-22T21:47:46.196Z,1679521666.196 [Default:CheckIn] Running Loop=11
2023-03-22T21:47:46.196Z,1679521666.196 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T21:47:46.196Z,1679521666.196 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T21:47:48.199Z,1679521668.199 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,214748.00,A,3648.16342,N,12147.19629,W,0.603,92.14,220323,,,D*43
2023-03-22T21:47:48.213Z,1679521668.213 [NAL9602](INFO): GPS fix at 20230322T214748: (36.802724, -121.786605)
2023-03-22T21:47:48.223Z,1679521668.223 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T21:47:48.223Z,1679521668.223 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T21:47:56.208Z,1679521676.208 [DataOverHttps](INFO): Sending 71 bytes from file Logs/20230322T204727/Courier0034.lzma
2023-03-22T21:47:57.210Z,1679521677.210 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Courier0034.lzma.bak
2023-03-22T21:47:57.211Z,1679521677.211 [DataOverHttps](INFO): SBD MOMSN=17542824
2023-03-22T21:48:13.354Z,1679521693.354 [DataOverHttps](INFO): Sending 243 bytes from file Logs/20230322T204727/Express0035.lzma
2023-03-22T21:48:14.230Z,1679521694.230 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Express0035.lzma.bak
2023-03-22T21:48:14.231Z,1679521694.231 [DataOverHttps](INFO): SBD MOMSN=17542827
2023-03-22T21:48:15.684Z,1679521695.684 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T21:48:15.684Z,1679521695.684 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T21:48:15.684Z,1679521695.684 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T21:48:20.518Z,1679521700.518 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T21:50:31.449Z,1679521831.449 [CBIT](IMPORTANT): Beginning ground fault scan
2023-03-22T21:50:42.349Z,1679521842.349 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): 0.033162
CHAN A1 (24V): 0.053633
CHAN A2 (12V): -0.008141
CHAN A3 (5V): -0.019935
CHAN B0 (3.3V): -0.013485
CHAN B1 (3.15aV): -0.009962
CHAN B2 (3.15bV): -0.006609
CHAN B3 (GND): -0.013910
OPEN: 0.007584
Full Scale: +/- 1 mA
2023-03-22T21:53:16.334Z,1679521996.334 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T21:53:16.334Z,1679521996.334 [Default:CheckIn:C.Wait] Stopped
2023-03-22T21:53:16.334Z,1679521996.334 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T21:53:16.335Z,1679521996.335 [Default:CheckIn:D] Running Loop=1
2023-03-22T21:53:16.722Z,1679521996.722 [Default:CheckIn:D] Stopped
2023-03-22T21:53:16.722Z,1679521996.722 [Default:CheckIn:E] Running Loop=1
2023-03-22T21:53:17.124Z,1679521997.124 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 60.984570 min 
2023-03-22T21:53:17.124Z,1679521997.124 [Default:CheckIn:E] Stopped
2023-03-22T21:53:17.124Z,1679521997.124 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T21:53:17.124Z,1679521997.124 [Default:CheckIn] Stopped
2023-03-22T21:53:17.124Z,1679521997.124 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T21:53:17.124Z,1679521997.124 [Default:CheckIn](INFO): Running loop #12
2023-03-22T21:53:17.124Z,1679521997.124 [Default:CheckIn] Running Loop=12
2023-03-22T21:53:17.125Z,1679521997.125 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T21:53:17.125Z,1679521997.125 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T21:53:19.146Z,1679521999.146 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,215319.00,A,3648.49910,N,12147.22826,W,6.842,236.50,220323,,,D*7D
2023-03-22T21:53:19.148Z,1679521999.148 [NAL9602](INFO): GPS fix at 20230322T215319: (36.808318, -121.787138)
2023-03-22T21:53:19.158Z,1679521999.158 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T21:53:19.158Z,1679521999.158 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T21:53:26.800Z,1679522006.800 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230322T204727/Courier0037.lzma
2023-03-22T21:53:27.802Z,1679522007.802 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Courier0037.lzma.bak
2023-03-22T21:53:27.803Z,1679522007.803 [DataOverHttps](INFO): SBD MOMSN=17542839
2023-03-22T21:53:33.276Z,1679522013.276 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-03-22T21:53:33.276Z,1679522013.276 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.1,489.0,000
2023-03-22T21:53:46.962Z,1679522026.962 [DataOverHttps](INFO): Sending 321 bytes from file Logs/20230322T204727/Express0038.lzma
2023-03-22T21:53:47.962Z,1679522027.962 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Express0038.lzma.bak
2023-03-22T21:53:47.963Z,1679522027.963 [DataOverHttps](INFO): SBD MOMSN=17542842
2023-03-22T21:53:49.095Z,1679522029.095 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T21:53:49.095Z,1679522029.095 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T21:53:49.095Z,1679522029.095 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T21:53:49.878Z,1679522029.878 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2023-03-22T21:53:49.961Z,1679522029.961 [NAL9602](ERROR): received: 
+SBDI: 2, 47485, 2, 0, 0, 0

OK
2023-03-22T21:56:10.481Z,1679522170.481 [NAL9602](INFO): SBD MO Status=2, MOMSN=47485, MT Status=2, MTMSN=0
2023-03-22T21:56:10.481Z,1679522170.481 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T21:56:48.459Z,1679522208.459 [DVL_micro](ERROR): Failed to parse:
45,+00640,-01594,+00000,I
2023-03-22T21:57:26.445Z,1679522246.445 [DVL_micro](ERROR): Failed to parse:
48,-0013,+00000,A
2023-03-22T21:57:40.164Z,1679522260.164 [NAL9602](INFO): SBD MO Status=2, MOMSN=47485, MT Status=2, MTMSN=0
2023-03-22T21:57:40.164Z,1679522260.164 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T21:58:16.524Z,1679522296.524 [NAL9602](INFO): SBD MO Status=0, MOMSN=47485, MT Status=0, MTMSN=0
2023-03-22T21:58:16.524Z,1679522296.524 [NAL9602](INFO): No messages in MT queue
2023-03-22T21:58:47.249Z,1679522327.249 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T21:58:49.668Z,1679522329.668 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T21:58:49.668Z,1679522329.668 [Default:CheckIn:C.Wait] Stopped
2023-03-22T21:58:49.669Z,1679522329.669 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T21:58:49.670Z,1679522329.670 [Default:CheckIn:D] Running Loop=1
2023-03-22T21:58:50.087Z,1679522330.087 [Default:CheckIn:D] Stopped
2023-03-22T21:58:50.087Z,1679522330.087 [Default:CheckIn:E] Running Loop=1
2023-03-22T21:58:50.490Z,1679522330.490 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 66.540653 min 
2023-03-22T21:58:50.490Z,1679522330.490 [Default:CheckIn:E] Stopped
2023-03-22T21:58:50.490Z,1679522330.490 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T21:58:50.490Z,1679522330.490 [Default:CheckIn] Stopped
2023-03-22T21:58:50.490Z,1679522330.490 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T21:58:50.490Z,1679522330.490 [Default:CheckIn](INFO): Running loop #13
2023-03-22T21:58:50.491Z,1679522330.491 [Default:CheckIn] Running Loop=13
2023-03-22T21:58:50.491Z,1679522330.491 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T21:58:50.491Z,1679522330.491 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T21:58:52.524Z,1679522332.524 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,215852.00,A,3648.23718,N,12148.08366,W,10.711,245.73,220323,,,D*40
2023-03-22T21:58:52.527Z,1679522332.527 [NAL9602](INFO): GPS fix at 20230322T215852: (36.803953, -121.801394)
2023-03-22T21:58:52.536Z,1679522332.536 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T21:58:52.536Z,1679522332.536 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T21:58:59.908Z,1679522339.908 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20230322T204727/Courier0040.lzma
2023-03-22T21:59:00.911Z,1679522340.911 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Courier0040.lzma.bak
2023-03-22T21:59:00.911Z,1679522340.911 [DataOverHttps](INFO): SBD MOMSN=17542863
2023-03-22T21:59:16.858Z,1679522356.858 [DataOverHttps](INFO): Sending 144 bytes from file Logs/20230322T204727/Express0041.lzma
2023-03-22T21:59:17.859Z,1679522357.859 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Express0041.lzma.bak
2023-03-22T21:59:17.859Z,1679522357.859 [DataOverHttps](INFO): SBD MOMSN=17542866
2023-03-22T21:59:19.183Z,1679522359.183 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T21:59:19.183Z,1679522359.183 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T21:59:19.183Z,1679522359.183 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T21:59:24.807Z,1679522364.807 [NAL9602](INFO): SBD MO Status=0, MOMSN=47486, MT Status=0, MTMSN=0
2023-03-22T21:59:24.807Z,1679522364.807 [NAL9602](INFO): No messages in MT queue
2023-03-22T21:59:55.507Z,1679522395.507 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T22:00:51.353Z,1679522451.353 [DVL_micro](ERROR): Failed to parse:
9.99,+9999.99,+9999.99,+9999.99
2023-03-22T22:01:35.709Z,1679522495.709 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2023-03-22T22:01:35.711Z,1679522495.711 [BPC1](INFO): Received data from all battery sticks.
2023-03-22T22:03:53.770Z,1679522633.770 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:04:19.737Z,1679522659.737 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T22:04:19.737Z,1679522659.737 [Default:CheckIn:C.Wait] Stopped
2023-03-22T22:04:19.738Z,1679522659.738 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T22:04:19.738Z,1679522659.738 [Default:CheckIn:D] Running Loop=1
2023-03-22T22:04:20.152Z,1679522660.152 [Default:CheckIn:D] Stopped
2023-03-22T22:04:20.152Z,1679522660.152 [Default:CheckIn:E] Running Loop=1
2023-03-22T22:04:20.541Z,1679522660.541 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 72.041740 min 
2023-03-22T22:04:20.541Z,1679522660.541 [Default:CheckIn:E] Stopped
2023-03-22T22:04:20.541Z,1679522660.541 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T22:04:20.542Z,1679522660.542 [Default:CheckIn] Stopped
2023-03-22T22:04:20.542Z,1679522660.542 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T22:04:20.542Z,1679522660.542 [Default:CheckIn](INFO): Running loop #14
2023-03-22T22:04:20.542Z,1679522660.542 [Default:CheckIn] Running Loop=14
2023-03-22T22:04:20.542Z,1679522660.542 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T22:04:20.542Z,1679522660.542 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T22:04:22.556Z,1679522662.556 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,220422.00,A,3647.78324,N,12149.45502,W,13.801,247.67,220323,,,A*44
2023-03-22T22:04:22.559Z,1679522662.559 [NAL9602](INFO): GPS fix at 20230322T220422: (36.796387, -121.824250)
2023-03-22T22:04:22.568Z,1679522662.568 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T22:04:22.568Z,1679522662.568 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T22:04:24.897Z,1679522664.897 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:04:56.021Z,1679522696.021 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:05:27.173Z,1679522727.173 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:05:45.384Z,1679522745.384 [NAL9602](INFO): SBD MO Status=0, MOMSN=47487, MT Status=0, MTMSN=0
2023-03-22T22:05:45.384Z,1679522745.384 [NAL9602](INFO): No messages in MT queue
2023-03-22T22:05:58.305Z,1679522758.305 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:06:13.365Z,1679522773.365 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=180.783508
2023-03-22T22:06:44.501Z,1679522804.501 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:06:45.652Z,1679522805.652 [NAL9602](INFO): SBD MO Status=2, MOMSN=47488, MT Status=2, MTMSN=0
2023-03-22T22:06:45.652Z,1679522805.652 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T22:07:07.117Z,1679522827.117 [NAL9602](INFO): SBD MO Status=1, MOMSN=47488, MT Status=0, MTMSN=0
2023-03-22T22:07:07.169Z,1679522827.169 [NAL9602](INFO): Sent 85 bytes from file Logs/20230322T204727/Courier0043.lzma
2023-03-22T22:07:07.169Z,1679522827.169 [NAL9602](INFO): Packets left to send: 0
2023-03-22T22:07:15.629Z,1679522835.629 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:07:20.900Z,1679522840.900 [NAL9602](INFO): SBD MO Status=2, MOMSN=47489, MT Status=2, MTMSN=0
2023-03-22T22:07:20.900Z,1679522840.900 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T22:07:34.278Z,1679522854.278 [DVL_micro](ERROR): only read 3 of 4 data items
2023-03-22T22:07:34.278Z,1679522854.278 [DVL_micro](ERROR): Failed to parse:
:BI,-00186,+00408,-01452,+00000+00000000.00,+00000000.00,+00000000.00,999900
2023-03-22T22:07:46.762Z,1679522866.762 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:07:46.825Z,1679522866.825 [NAL9602](INFO): SBD MO Status=2, MOMSN=47489, MT Status=2, MTMSN=0
2023-03-22T22:07:46.825Z,1679522866.825 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T22:08:05.553Z,1679522885.553 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003215
2023-03-22T22:08:12.783Z,1679522892.783 [NAL9602](INFO): SBD MO Status=2, MOMSN=47489, MT Status=2, MTMSN=0
2023-03-22T22:08:12.783Z,1679522892.783 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T22:08:16.116Z,1679522896.116 [DataOverHttps](INFO): Sending 146 bytes from file Logs/20230322T204727/Express0044.lzma
2023-03-22T22:08:17.119Z,1679522897.119 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Express0044.lzma.bak
2023-03-22T22:08:17.119Z,1679522897.119 [DataOverHttps](INFO): SBD MOMSN=17542889
2023-03-22T22:08:18.419Z,1679522898.419 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T22:08:18.419Z,1679522898.419 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T22:08:18.419Z,1679522898.419 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T22:08:43.453Z,1679522923.453 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T22:08:48.585Z,1679522928.585 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting.
2023-03-22T22:09:19.717Z,1679522959.717 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:09:50.857Z,1679522990.857 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:10:21.981Z,1679523021.981 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:10:53.113Z,1679523053.113 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:11:17.209Z,1679523077.209 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=180.090805
2023-03-22T22:11:54.361Z,1679523114.361 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:12:25.485Z,1679523145.485 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:12:56.617Z,1679523176.617 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:13:18.999Z,1679523198.999 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T22:13:18.999Z,1679523198.999 [Default:CheckIn:C.Wait] Stopped
2023-03-22T22:13:18.999Z,1679523198.999 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T22:13:18.000Z,1679523199.000 [Default:CheckIn:D] Running Loop=1
2023-03-22T22:13:19.403Z,1679523199.403 [Default:CheckIn:D] Stopped
2023-03-22T22:13:19.403Z,1679523199.403 [Default:CheckIn:E] Running Loop=1
2023-03-22T22:13:19.805Z,1679523199.805 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 81.029256 min 
2023-03-22T22:13:19.805Z,1679523199.805 [Default:CheckIn:E] Stopped
2023-03-22T22:13:19.805Z,1679523199.805 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T22:13:19.805Z,1679523199.805 [Default:CheckIn] Stopped
2023-03-22T22:13:19.805Z,1679523199.805 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T22:13:19.805Z,1679523199.805 [Default:CheckIn](INFO): Running loop #15
2023-03-22T22:13:19.805Z,1679523199.805 [Default:CheckIn] Running Loop=15
2023-03-22T22:13:19.805Z,1679523199.805 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T22:13:19.806Z,1679523199.806 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T22:13:21.829Z,1679523201.829 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,221321.00,A,3647.92702,N,12151.90975,W,8.533,257.75,220323,,,A*7C
2023-03-22T22:13:21.831Z,1679523201.831 [NAL9602](INFO): GPS fix at 20230322T221321: (36.798784, -121.865162)
2023-03-22T22:13:21.846Z,1679523201.846 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T22:13:21.846Z,1679523201.846 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T22:13:27.749Z,1679523207.749 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:13:57.011Z,1679523237.011 [NAL9602](INFO): SBD MO Status=1, MOMSN=47489, MT Status=0, MTMSN=0
2023-03-22T22:13:57.061Z,1679523237.061 [NAL9602](INFO): Sent 72 bytes from file Logs/20230322T204727/Courier0046.lzma
2023-03-22T22:13:57.061Z,1679523237.061 [NAL9602](INFO): Packets left to send: 0
2023-03-22T22:13:58.889Z,1679523238.889 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:14:16.893Z,1679523256.893 [NAL9602](INFO): SBD MO Status=1, MOMSN=47490, MT Status=0, MTMSN=0
2023-03-22T22:14:16.957Z,1679523256.957 [NAL9602](INFO): Sent 145 bytes from file Logs/20230322T204727/Express0047.lzma
2023-03-22T22:14:16.957Z,1679523256.957 [NAL9602](INFO): Packets left to send: 0
2023-03-22T22:14:26.973Z,1679523266.973 [NAL9602](INFO): SBD MO Status=0, MOMSN=47491, MT Status=0, MTMSN=0
2023-03-22T22:14:27.061Z,1679523267.061 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T22:14:27.061Z,1679523267.061 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T22:14:27.061Z,1679523267.061 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T22:14:30.013Z,1679523270.013 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:14:57.679Z,1679523297.679 [NAL9602](INFO): Not Powering down - fast GPS
2023-03-22T22:15:01.149Z,1679523301.149 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:15:32.277Z,1679523332.277 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:16:03.401Z,1679523363.401 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-03-22T22:17:01.557Z,1679523421.557 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003187
2023-03-22T22:17:09.794Z,1679523429.794 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-03-22T22:17:09.795Z,1679523429.795 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+1.0,1489.0,000
2023-03-22T22:18:52.410Z,1679523532.410 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-03-22T22:18:52.411Z,1679523532.411 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+0.0,1489.0,000
2023-03-22T22:18:55.240Z,1679523535.240 [DVL_micro](ERROR): Failed to parse:
:.38,+0000.35,+0000.34,+9999.99
2023-03-22T22:19:27.574Z,1679523567.574 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-03-22T22:19:27.574Z,1679523567.574 [Default:CheckIn:C.Wait] Stopped
2023-03-22T22:19:27.574Z,1679523567.574 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-03-22T22:19:27.574Z,1679523567.574 [Default:CheckIn:D] Running Loop=1
2023-03-22T22:19:27.962Z,1679523567.962 [Default:CheckIn:D] Stopped
2023-03-22T22:19:27.962Z,1679523567.962 [Default:CheckIn:E] Running Loop=1
2023-03-22T22:19:28.373Z,1679523568.373 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 87.171899 min 
2023-03-22T22:19:28.373Z,1679523568.373 [Default:CheckIn:E] Stopped
2023-03-22T22:19:28.373Z,1679523568.373 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-03-22T22:19:28.373Z,1679523568.373 [Default:CheckIn] Stopped
2023-03-22T22:19:28.373Z,1679523568.373 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-03-22T22:19:28.373Z,1679523568.373 [Default:CheckIn](INFO): Running loop #16
2023-03-22T22:19:28.373Z,1679523568.373 [Default:CheckIn] Running Loop=16
2023-03-22T22:19:28.374Z,1679523568.374 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-03-22T22:19:28.374Z,1679523568.374 [Default:CheckIn:Read_GPS] Running Loop=1
2023-03-22T22:19:30.391Z,1679523570.391 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,221930.00,A,3647.93393,N,12151.88983,W,1.419,354.37,220323,,,A*7F
2023-03-22T22:19:30.394Z,1679523570.394 [NAL9602](INFO): GPS fix at 20230322T221930: (36.798899, -121.864830)
2023-03-22T22:19:30.403Z,1679523570.403 [Default:CheckIn:Read_GPS] Stopped
2023-03-22T22:19:30.403Z,1679523570.403 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-03-22T22:19:52.372Z,1679523592.372 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230322T204727/Courier0049.lzma
2023-03-22T22:19:53.374Z,1679523593.374 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Courier0049.lzma.bak
2023-03-22T22:19:53.375Z,1679523593.375 [DataOverHttps](INFO): SBD MOMSN=17542922
2023-03-22T22:20:08.824Z,1679523608.824 [NAL9602](INFO): SBD MO Status=2, MOMSN=47492, MT Status=2, MTMSN=0
2023-03-22T22:20:08.824Z,1679523608.824 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T22:20:09.576Z,1679523609.576 [DataOverHttps](INFO): Sending 181 bytes from file Logs/20230322T204727/Express0050.lzma
2023-03-22T22:20:10.579Z,1679523610.579 [DataOverHttps](INFO): Moved sent file to Logs/20230322T204727/Express0050.lzma.bak
2023-03-22T22:20:10.579Z,1679523610.579 [DataOverHttps](INFO): SBD MOMSN=17542925
2023-03-22T22:20:11.679Z,1679523611.679 [Default:CheckIn:Read_Iridium] Stopped
2023-03-22T22:20:11.679Z,1679523611.679 [Default:CheckIn:C.Wait] Running Loop=1
2023-03-22T22:20:11.680Z,1679523611.680 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-03-22T22:20:24.591Z,1679523624.591 [NAL9602](INFO): SBD MO Status=2, MOMSN=47492, MT Status=2, MTMSN=0
2023-03-22T22:20:24.591Z,1679523624.591 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T22:20:41.947Z,1679523641.947 [NAL9602](INFO): SBD MO Status=2, MOMSN=47492, MT Status=2, MTMSN=0
2023-03-22T22:20:41.947Z,1679523641.947 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T22:20:50.107Z,1679523650.107 [DataOverHttps](IMPORTANT): SBD MTMSN=20230322T222049
2023-03-22T22:20:54.876Z,1679523654.876 [NAL9602](INFO): SBD MO Status=2, MOMSN=47492, MT Status=2, MTMSN=0
2023-03-22T22:20:54.876Z,1679523654.876 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-03-22T22:20:57.781Z,1679523657.781 [DataOverHttps](INFO): Received command: restart logs