2023-05-12T16:17:16.949Z,1683908236.949 [Supervisor](DEBUG): Initializing supervisor.
2023-05-12T16:17:16.953Z,1683908236.953 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2023-05-12T16:17:16.953Z,1683908236.953 [SyncHandler](INFO): Protected caller Thread ID is 7056
2023-05-12T16:17:16.954Z,1683908236.954 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2023-05-12T16:17:16.955Z,1683908236.955 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2023-05-12T16:17:16.955Z,1683908236.955 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 7057
2023-05-12T16:17:16.959Z,1683908236.959 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2023-05-12T16:17:16.976Z,1683908236.976 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread.
2023-05-12T16:17:16.977Z,1683908236.977 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2023-05-12T16:17:16.977Z,1683908236.977 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 7058
2023-05-12T16:17:16.981Z,1683908236.981 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2023-05-12T16:17:16.982Z,1683908236.982 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2023-05-12T16:17:16.983Z,1683908236.983 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 7059
2023-05-12T16:17:16.985Z,1683908236.985 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2023-05-12T16:17:16.986Z,1683908236.986 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0
2023-05-12T16:17:16.986Z,1683908236.986 [logger ThreadHandler](INFO): Protected caller Thread ID is 7060
2023-05-12T16:17:16.990Z,1683908236.990 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2023-05-12T16:17:16.990Z,1683908236.990 [Supervisor](INFO): Looking for Config files in directory: Config/
2023-05-12T16:17:16.992Z,1683908236.992 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2023-05-12T16:17:17.090Z,1683908237.090 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2023-05-12T16:17:17.091Z,1683908237.091 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2023-05-12T16:17:17.310Z,1683908237.310 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2023-05-12T16:17:17.311Z,1683908237.311 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2023-05-12T16:17:17.568Z,1683908237.569 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2023-05-12T16:17:17.569Z,1683908237.569 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2023-05-12T16:17:17.680Z,1683908237.680 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2023-05-12T16:17:17.681Z,1683908237.681 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2023-05-12T16:17:18.365Z,1683908238.365 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2023-05-12T16:17:18.366Z,1683908238.366 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2023-05-12T16:17:18.843Z,1683908238.843 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2023-05-12T16:17:18.844Z,1683908238.844 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2023-05-12T16:17:19.329Z,1683908239.329 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2023-05-12T16:17:19.330Z,1683908239.330 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2023-05-12T16:17:19.729Z,1683908239.729 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2023-05-12T16:17:19.730Z,1683908239.730 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2023-05-12T16:17:20.056Z,1683908240.056 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2023-05-12T16:17:20.057Z,1683908240.057 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2023-05-12T16:17:20.429Z,1683908240.429 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2023-05-12T16:17:20.429Z,1683908240.429 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2023-05-12T16:17:20.657Z,1683908240.657 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2023-05-12T16:17:20.657Z,1683908240.657 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2023-05-12T16:17:20.799Z,1683908240.799 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2023-05-12T16:17:20.799Z,1683908240.799 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2023-05-12T16:17:20.906Z,1683908240.906 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2023-05-12T16:17:21.096Z,1683908241.096 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2023-05-12T16:17:21.608Z,1683908241.608 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2023-05-12T16:17:21.609Z,1683908241.609 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2023-05-12T16:17:21.874Z,1683908241.874 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2023-05-12T16:17:21.876Z,1683908241.876 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/
2023-05-12T16:17:21.877Z,1683908241.877 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/secure.cfg
2023-05-12T16:17:21.963Z,1683908241.963 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Battery.cfg
2023-05-12T16:17:22.226Z,1683908242.226 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2023-05-12T16:17:22.227Z,1683908242.227 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Navigation.cfg
2023-05-12T16:17:22.328Z,1683908242.328 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Sensor.cfg
2023-05-12T16:17:22.491Z,1683908242.491 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/vehicle.cfg
2023-05-12T16:17:22.672Z,1683908242.672 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Simulator.cfg
2023-05-12T16:17:22.760Z,1683908242.760 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Servo.cfg
2023-05-12T16:17:22.873Z,1683908242.873 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Control.cfg
2023-05-12T16:17:22.980Z,1683908242.980 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Science.cfg
2023-05-12T16:17:23.139Z,1683908243.139 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/logger.cfg
2023-05-12T16:17:23.238Z,1683908243.238 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/BIT.cfg
2023-05-12T16:17:23.340Z,1683908243.340 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/root/
2023-05-12T16:17:23.340Z,1683908243.340 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2023-05-12T16:17:23.358Z,1683908243.358 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2023-05-12T16:17:23.499Z,1683908243.499 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2023-05-12T16:17:23.499Z,1683908243.499 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2023-05-12T16:17:23.649Z,1683908243.649 [BuoyancyServo] Loaded
2023-05-12T16:17:23.649Z,1683908243.649 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2023-05-12T16:17:23.670Z,1683908243.670 [ElevatorServo] Loaded
2023-05-12T16:17:23.670Z,1683908243.670 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2023-05-12T16:17:23.690Z,1683908243.690 [MassServo] Loaded
2023-05-12T16:17:23.690Z,1683908243.690 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2023-05-12T16:17:23.710Z,1683908243.710 [RudderServo] Loaded
2023-05-12T16:17:23.710Z,1683908243.710 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2023-05-12T16:17:23.726Z,1683908243.726 [ThrusterHE] Loaded
2023-05-12T16:17:23.726Z,1683908243.726 [ComponentRegistry](DEBUG): SyncComponent "ThrusterHE" handled in the control thread.
2023-05-12T16:17:23.726Z,1683908243.726 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2023-05-12T16:17:23.727Z,1683908243.727 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2023-05-12T16:17:23.863Z,1683908243.863 [SBIT](DEBUG): Construct Startup Built In Test.
2023-05-12T16:17:23.877Z,1683908243.877 [SBIT] Loaded
2023-05-12T16:17:23.878Z,1683908243.878 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2023-05-12T16:17:23.880Z,1683908243.880 [IBIT](DEBUG): Construct Initiated Built In Test.
2023-05-12T16:17:23.901Z,1683908243.901 [IBIT] Loaded
2023-05-12T16:17:23.901Z,1683908243.901 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2023-05-12T16:17:23.906Z,1683908243.906 [CBIT](DEBUG): Construct Continuous Built In Test.
2023-05-12T16:17:24.121Z,1683908244.121 [CBIT] Loaded
2023-05-12T16:17:24.122Z,1683908244.122 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2023-05-12T16:17:24.122Z,1683908244.122 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2023-05-12T16:17:24.122Z,1683908244.122 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2023-05-12T16:17:24.283Z,1683908244.283 [CTD_Seabird] Loaded
2023-05-12T16:17:24.283Z,1683908244.283 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2023-05-12T16:17:24.284Z,1683908244.284 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 406644E0
2023-05-12T16:17:24.285Z,1683908244.285 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 7142
2023-05-12T16:17:24.316Z,1683908244.316 [ESPComponent] Loaded
2023-05-12T16:17:24.316Z,1683908244.316 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2023-05-12T16:17:24.336Z,1683908244.336 [PAR_Licor] Loaded
2023-05-12T16:17:24.336Z,1683908244.336 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2023-05-12T16:17:24.366Z,1683908244.366 [WetLabsBB2FL] Loaded
2023-05-12T16:17:24.367Z,1683908244.367 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2023-05-12T16:17:24.368Z,1683908244.368 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 406944E0
2023-05-12T16:17:24.368Z,1683908244.368 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 7143
2023-05-12T16:17:24.369Z,1683908244.369 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2023-05-12T16:17:24.369Z,1683908244.369 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2023-05-12T16:17:24.417Z,1683908244.417 [DepthRateCalculator] Loaded
2023-05-12T16:17:24.418Z,1683908244.418 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2023-05-12T16:17:24.423Z,1683908244.423 [PitchRateCalculator] Loaded
2023-05-12T16:17:24.423Z,1683908244.423 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2023-05-12T16:17:24.433Z,1683908244.433 [SpeedCalculator] Loaded
2023-05-12T16:17:24.433Z,1683908244.433 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2023-05-12T16:17:24.448Z,1683908244.448 [VerticalHomogeneityIndexCalculator] Loaded
2023-05-12T16:17:24.448Z,1683908244.448 [ComponentRegistry](DEBUG): SyncComponent "VerticalHomogeneityIndexCalculator" handled in the control thread.
2023-05-12T16:17:24.452Z,1683908244.452 [YawRateCalculator] Loaded
2023-05-12T16:17:24.453Z,1683908244.453 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2023-05-12T16:17:24.471Z,1683908244.471 [ElevatorOffsetCalculator] Loaded
2023-05-12T16:17:24.471Z,1683908244.471 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2023-05-12T16:17:24.472Z,1683908244.472 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2023-05-12T16:17:24.472Z,1683908244.472 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2023-05-12T16:17:24.567Z,1683908244.567 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2023-05-12T16:17:24.567Z,1683908244.567 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2023-05-12T16:17:24.594Z,1683908244.594 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2023-05-12T16:17:24.594Z,1683908244.594 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2023-05-12T16:17:24.703Z,1683908244.703 [DeadReckonUsingMultipleVelocitySources] Loaded
2023-05-12T16:17:24.704Z,1683908244.704 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2023-05-12T16:17:24.717Z,1683908244.717 [NavChart] Loaded
2023-05-12T16:17:24.718Z,1683908244.718 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2023-05-12T16:17:24.723Z,1683908244.723 [UniversalFixResidualReporter] Loaded
2023-05-12T16:17:24.723Z,1683908244.723 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2023-05-12T16:17:24.724Z,1683908244.724 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2023-05-12T16:17:24.724Z,1683908244.724 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2023-05-12T16:17:25.125Z,1683908245.125 [AHRS_M2] Loaded
2023-05-12T16:17:25.125Z,1683908245.125 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2023-05-12T16:17:25.159Z,1683908245.159 [BackseatComponent] Loaded
2023-05-12T16:17:25.159Z,1683908245.159 [ComponentRegistry](DEBUG): Component "BackseatComponent" handled in its own thread.
2023-05-12T16:17:25.160Z,1683908245.160 [BackseatComponent ThreadHandler](DEBUG): Created PCaller Thread at 40A244E0
2023-05-12T16:17:25.160Z,1683908245.160 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 7144
2023-05-12T16:17:25.163Z,1683908245.163 [LcmUniversalReporter] Loaded
2023-05-12T16:17:25.163Z,1683908245.163 [ComponentRegistry](DEBUG): SyncComponent "LcmUniversalReporter" handled in the control thread.
2023-05-12T16:17:25.892Z,1683908245.892 [BPC1] Loaded
2023-05-12T16:17:25.892Z,1683908245.892 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2023-05-12T16:17:25.965Z,1683908245.965 [DataOverHttps] Loaded
2023-05-12T16:17:25.966Z,1683908245.966 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2023-05-12T16:17:25.967Z,1683908245.967 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 40A544E0
2023-05-12T16:17:25.967Z,1683908245.967 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 7145
2023-05-12T16:17:25.988Z,1683908245.988 [Depth_Keller] Loaded
2023-05-12T16:17:25.988Z,1683908245.988 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2023-05-12T16:17:25.993Z,1683908245.993 [DropWeight] Loaded
2023-05-12T16:17:25.993Z,1683908245.993 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2023-05-12T16:17:26.031Z,1683908246.031 [DVL_micro] Loaded
2023-05-12T16:17:26.032Z,1683908246.032 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2023-05-12T16:17:26.091Z,1683908246.091 [NAL9602] Loaded
2023-05-12T16:17:26.091Z,1683908246.091 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2023-05-12T16:17:26.118Z,1683908246.118 [Onboard] Loaded
2023-05-12T16:17:26.118Z,1683908246.118 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2023-05-12T16:17:26.119Z,1683908246.119 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 40A844E0
2023-05-12T16:17:26.120Z,1683908246.120 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 7146
2023-05-12T16:17:26.132Z,1683908246.132 [Power24vConverter] Loaded
2023-05-12T16:17:26.132Z,1683908246.132 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread.
2023-05-12T16:17:26.145Z,1683908246.145 [Radio_Surface] Loaded
2023-05-12T16:17:26.145Z,1683908246.145 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2023-05-12T16:17:26.146Z,1683908246.146 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 40AB44E0
2023-05-12T16:17:26.147Z,1683908246.147 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 7147
2023-05-12T16:17:26.239Z,1683908246.239 [DAT] Loaded
2023-05-12T16:17:26.239Z,1683908246.239 [ComponentRegistry](DEBUG): Component "DAT" handled in its own thread.
2023-05-12T16:17:26.240Z,1683908246.240 [DAT ThreadHandler](DEBUG): Created PCaller Thread at 40AE44E0
2023-05-12T16:17:26.241Z,1683908246.241 [DAT ThreadHandler](INFO): Protected caller Thread ID is 7148
2023-05-12T16:17:26.241Z,1683908246.241 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2023-05-12T16:17:26.242Z,1683908246.242 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2023-05-12T16:17:26.415Z,1683908246.415 [StratificationFrontDetector](IMPORTANT): thresholdVTHI set to: 0.050012 degC
2023-05-12T16:17:26.415Z,1683908246.415 [StratificationFrontDetector](INFO): (re)initializing
2023-05-12T16:17:26.415Z,1683908246.415 [StratificationFrontDetector] Loaded
2023-05-12T16:17:26.416Z,1683908246.416 [ComponentRegistry](DEBUG): SyncComponent "StratificationFrontDetector" handled in the control thread.
2023-05-12T16:17:26.416Z,1683908246.416 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2023-05-12T16:17:26.417Z,1683908246.417 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2023-05-12T16:17:26.538Z,1683908246.538 [VerticalControl](DEBUG): Construct VerticalControl.
2023-05-12T16:17:26.725Z,1683908246.725 [VerticalControl] Loaded
2023-05-12T16:17:26.725Z,1683908246.725 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2023-05-12T16:17:26.772Z,1683908246.772 [HorizontalControl](DEBUG): Construct HorizontalControl.
2023-05-12T16:17:26.859Z,1683908246.859 [HorizontalControl] Loaded
2023-05-12T16:17:26.860Z,1683908246.860 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2023-05-12T16:17:26.862Z,1683908246.862 [SpeedControl](DEBUG): Construct SpeedControl.
2023-05-12T16:17:26.864Z,1683908246.864 [SpeedControl] Loaded
2023-05-12T16:17:26.864Z,1683908246.864 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2023-05-12T16:17:26.867Z,1683908246.867 [LoopControl](DEBUG): Construct LoopControl.
2023-05-12T16:17:26.867Z,1683908246.867 [LoopControl] Loaded
2023-05-12T16:17:26.868Z,1683908246.868 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2023-05-12T16:17:26.868Z,1683908246.868 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2023-05-12T16:17:26.869Z,1683908246.869 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2023-05-12T16:17:26.941Z,1683908246.941 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2023-05-12T16:17:26.942Z,1683908246.942 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2023-05-12T16:17:27.234Z,1683908247.234 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2023-05-12T16:17:27.240Z,1683908247.240 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2023-05-12T16:17:27.243Z,1683908247.243 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2023-05-12T16:17:27.254Z,1683908247.254 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2023-05-12T16:17:27.255Z,1683908247.255 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40BE74E0
2023-05-12T16:17:27.255Z,1683908247.255 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 7149
2023-05-12T16:17:27.260Z,1683908247.260 [Supervisor](INFO): Main Thread ID is 6916
2023-05-12T16:17:27.260Z,1683908247.260 [Supervisor](DEBUG): Running supervisor.
2023-05-12T16:17:27.260Z,1683908247.260 [CommandExec ThreadHandler](INFO): Handler Thread ID is 7150
2023-05-12T16:17:27.261Z,1683908247.261 [CommandExec](INFO): Initializing the command executive.
2023-05-12T16:17:27.262Z,1683908247.262 [CommandLine ThreadHandler](INFO): Handler Thread ID is 7151
2023-05-12T16:17:27.265Z,1683908247.265 [controlThread ThreadHandler](INFO): Handler Thread ID is 7152
2023-05-12T16:17:27.266Z,1683908247.266 [controlThread](DEBUG): Initializing ControlThread
2023-05-12T16:17:27.268Z,1683908247.268 [SBIT](INFO): Initialize SBIT Component.
2023-05-12T16:17:27.268Z,1683908247.268 [SBIT](IMPORTANT): git: 2023-04-25
2023-05-12T16:17:27.268Z,1683908247.268 [SBIT](INFO): git hash: 15e7c6db5dbfb895fa1b021f5e782a0f712701bf
2023-05-12T16:17:27.269Z,1683908247.269 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2023-05-12T16:17:27.270Z,1683908247.270 [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-05-12T16:17:27.271Z,1683908247.271 [SBIT](INFO): Beginning SBIT in 71.000000 seconds.
2023-05-12T16:17:27.272Z,1683908247.272 [IBIT](INFO): Initialize IBIT Component.
2023-05-12T16:17:27.272Z,1683908247.272 [CBIT](DEBUG): Initialize CBIT Component.
2023-05-12T16:17:27.273Z,1683908247.273 [logger ThreadHandler](INFO): Handler Thread ID is 7153
2023-05-12T16:17:27.284Z,1683908247.284 [CBIT](DEBUG): Initialized mux pins.
2023-05-12T16:17:27.284Z,1683908247.284 [CBIT](DEBUG): Initializing the watchdog timer.
2023-05-12T16:17:27.292Z,1683908247.292 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 7154
2023-05-12T16:17:27.293Z,1683908247.293 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2023-05-12T16:17:27.297Z,1683908247.297 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 7156
2023-05-12T16:17:27.300Z,1683908247.300 [WetLabsBB2FL](INFO): Powering up
2023-05-12T16:17:27.302Z,1683908247.302 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 7158
2023-05-12T16:17:27.308Z,1683908247.308 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2023-05-12T16:17:27.308Z,1683908247.308 [CBIT](DEBUG): Initializing heartbeat.
2023-05-12T16:17:27.309Z,1683908247.309 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 7159
2023-05-12T16:17:27.310Z,1683908247.310 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2023-05-12T16:17:27.324Z,1683908247.324 [Onboard ThreadHandler](INFO): Handler Thread ID is 7160
2023-05-12T16:17:27.341Z,1683908247.341 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 7161
2023-05-12T16:17:27.365Z,1683908247.365 [DAT ThreadHandler](INFO): Handler Thread ID is 7162
2023-05-12T16:17:27.365Z,1683908247.365 [DAT](INFO): Powering up
2023-05-12T16:17:27.366Z,1683908247.366 [DAT](DEBUG): Initializing DAT.
2023-05-12T16:17:27.369Z,1683908247.369 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 7164
2023-05-12T16:17:27.371Z,1683908247.371 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2023-05-12T16:17:27.372Z,1683908247.372 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2023-05-12T16:17:27.372Z,1683908247.372 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2023-05-12T16:17:27.372Z,1683908247.372 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2023-05-12T16:17:27.372Z,1683908247.372 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2023-05-12T16:17:27.372Z,1683908247.372 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2023-05-12T16:17:27.372Z,1683908247.372 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2023-05-12T16:17:27.373Z,1683908247.373 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2023-05-12T16:17:27.373Z,1683908247.373 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA69M.000
2023-05-12T16:17:27.373Z,1683908247.373 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA69M.000
2023-05-12T16:17:27.380Z,1683908247.380 [CBIT](DEBUG): Deactivating GF circuits.
2023-05-12T16:17:27.380Z,1683908247.380 [CBIT](DEBUG): Deactivating emergency mode.
2023-05-12T16:17:27.420Z,1683908247.420 [CBIT](DEBUG): Backplane powered.
2023-05-12T16:17:27.424Z,1683908247.424 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2023-05-12T16:17:27.425Z,1683908247.425 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2023-05-12T16:17:27.425Z,1683908247.425 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2023-05-12T16:17:27.425Z,1683908247.425 [VerticalHomogeneityIndexCalculator](DEBUG): (re)initializing
2023-05-12T16:17:27.426Z,1683908247.426 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2023-05-12T16:17:27.426Z,1683908247.426 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2023-05-12T16:17:27.427Z,1683908247.427 [NavChart](DEBUG): Initialize NavChart Navigation.
2023-05-12T16:17:27.428Z,1683908247.428 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2023-05-12T16:17:27.438Z,1683908247.438 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2023-05-12T16:17:27.448Z,1683908247.448 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2023-05-12T16:17:27.449Z,1683908247.449 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2023-05-12T16:17:27.449Z,1683908247.449 [LoopControl](DEBUG): Initialize LoopControlComponent.
2023-05-12T16:17:27.450Z,1683908247.450 [MissionManager](INFO): Loading Mission from file: Missions/Startup.xml
2023-05-12T16:17:27.491Z,1683908247.491 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2023-05-12T16:17:27.560Z,1683908247.560 [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-05-12T16:17:27.561Z,1683908247.561 [MissionManager](INFO): Loading Mission from file: Missions/Default.xml
2023-05-12T16:17:27.639Z,1683908247.639 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2023-05-12T16:17:27.665Z,1683908247.665 [Default:A.Wait](DEBUG): Construct Wait.
2023-05-12T16:17:27.667Z,1683908247.667 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2023-05-12T16:17:27.683Z,1683908247.683 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2023-05-12T16:17:27.718Z,1683908247.718 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2023-05-12T16:17:27.723Z,1683908247.723 [Default:E.Execute](DEBUG): Construct Execute.
2023-05-12T16:17:27.743Z,1683908247.743 [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-05-12T16:17:27.748Z,1683908247.748 [Radio_Surface](INFO): Powering up
2023-05-12T16:17:27.748Z,1683908247.748 [controlThread](DEBUG): Component order: CycleStarter,ESPComponent,PAR_Licor,AHRS_M2,BPC1,Depth_Keller,DropWeight,DVL_micro,NAL9602,Power24vConverter,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,VerticalHomogeneityIndexCalculator,YawRateCalculator,ElevatorOffsetCalculator,StratificationFrontDetector,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter,
2023-05-12T16:17:27.785Z,1683908247.785 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2023-05-12T16:17:27.865Z,1683908247.865 [Depth_Keller](ERROR): Pressure or depth reading out of range: 1895.444336 decibar, 0.000000 m
2023-05-12T16:17:27.877Z,1683908247.877 [Power24vConverter](INFO): Powering up.
2023-05-12T16:17:27.881Z,1683908247.881 [DepthRateCalculator](ERROR): Depth measurement is not active
2023-05-12T16:17:27.922Z,1683908247.922 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2023-05-12T16:17:27.928Z,1683908247.928 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2023-05-12T16:17:27.929Z,1683908247.929 [ElevatorServo](DEBUG): Initializing EZServoServo.
2023-05-12T16:17:27.936Z,1683908247.936 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2023-05-12T16:17:27.937Z,1683908247.937 [MassServo](DEBUG): Initializing EZServoServo.
2023-05-12T16:17:27.944Z,1683908247.944 [MassServo](DEBUG): Initializing MassServo.
2023-05-12T16:17:27.945Z,1683908247.945 [RudderServo](DEBUG): Initializing EZServoServo.
2023-05-12T16:17:27.952Z,1683908247.952 [RudderServo](DEBUG): Initializing RudderServo.
2023-05-12T16:17:27.953Z,1683908247.953 [ThrusterHE](DEBUG): Initializing EZServoServo.
2023-05-12T16:17:27.960Z,1683908247.960 [ThrusterHE](DEBUG): Initializing ThrusterHE.
2023-05-12T16:17:28.218Z,1683908248.218 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2023-05-12T16:17:28.218Z,1683908248.218 [DropWeight] Hardware Fault, FailCount= 1
2023-05-12T16:17:28.218Z,1683908248.218 [DropWeight](ERROR): Hardware Fault
2023-05-12T16:17:28.277Z,1683908248.277 [CommandExec](FAULT): Scheduling is paused
2023-05-12T16:17:28.278Z,1683908248.278 [CBIT](INFO): Critical error at 20230512T161728
2023-05-12T16:17:28.278Z,1683908248.278 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2023-05-12T16:17:28.289Z,1683908248.289 [CBIT](ERROR): Hardware Fault in component: DropWeight
2023-05-12T16:17:28.289Z,1683908248.289 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2023-05-12T16:17:28.586Z,1683908248.586 [CBIT](INFO): Critical error at 20230512T161728
2023-05-12T16:17:29.408Z,1683908249.408 [WetLabsBB2FL](INFO): Powering down
2023-05-12T16:17:33.665Z,1683908253.665 [ThrusterHE](ERROR): Zero Speed Commanded.
2023-05-12T16:17:39.212Z,1683908259.212 [DAT](INFO): DAT read: 

2023-05-12T16:17:39.214Z,1683908259.214 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series

2023-05-12T16:17:40.977Z,1683908260.977 [DAT](INFO): DAT read: MF Frequency Band

2023-05-12T16:17:40.978Z,1683908260.978 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.15.0

2023-05-12T16:17:40.978Z,1683908260.978 [DAT](INFO): DAT read: May 12 2023 16:17:36 

2023-05-12T16:17:41.985Z,1683908261.985 [DAT](INFO): DAT read: Features enabled [Bearing]

2023-05-12T16:17:41.986Z,1683908261.986 [DAT](INFO): DAT read: CONNECT 01200 bits/sec 1 of 4, Rate 1/2 CC

2023-05-12T16:17:41.986Z,1683908261.986 [DAT](INFO): commRate: 1200
2023-05-12T16:17:44.052Z,1683908264.052 [DAT](INFO): entering command mode
2023-05-12T16:17:44.252Z,1683908264.252 [DAT](INFO): DAT read: 

2023-05-12T16:17:44.253Z,1683908264.253 [DAT](INFO): DAT read: user:1>

2023-05-12T16:17:44.253Z,1683908264.253 [DAT](INFO): setting verbose to 3
2023-05-12T16:17:44.505Z,1683908264.505 [DAT](INFO): DAT read: user:1>

2023-05-12T16:17:44.506Z,1683908264.506 [DAT](INFO): DAT read: Verbose         | 3           

2023-05-12T16:17:44.506Z,1683908264.506 [DAT](INFO): set verbose to 3
2023-05-12T16:17:44.506Z,1683908264.506 [DAT](INFO): setting DatVerbose to 27440
2023-05-12T16:17:44.757Z,1683908264.757 [DAT](INFO): DAT read: user:2>

2023-05-12T16:17:44.758Z,1683908264.758 [DAT](INFO): DAT read: DatVerbose      | 27440       

2023-05-12T16:17:44.758Z,1683908264.758 [DAT](INFO): set DatVerbose to 27440
2023-05-12T16:17:44.758Z,1683908264.758 [DAT](INFO): setting transmit power to 8
2023-05-12T16:17:45.008Z,1683908265.008 [DAT](INFO): DAT read: user:3>

2023-05-12T16:17:45.009Z,1683908265.009 [DAT](INFO): DAT read: TxPower         | 8 (Max)     

2023-05-12T16:17:45.010Z,1683908265.010 [DAT](INFO): set transmit power to 8
2023-05-12T16:17:45.010Z,1683908265.010 [DAT](INFO): setting local address to 4
2023-05-12T16:17:45.261Z,1683908265.261 [DAT](INFO): DAT read: user:4>

2023-05-12T16:17:45.262Z,1683908265.262 [DAT](INFO): DAT read: LocalAddr       | 4           

2023-05-12T16:17:45.262Z,1683908265.262 [DAT](INFO): set local address to 4
2023-05-12T16:17:45.263Z,1683908265.263 [DAT](INFO): Setting time to: 16:17:45 And date to:5/12/2023
2023-05-12T16:17:45.513Z,1683908265.513 [DAT](INFO): DAT read: user:5>

2023-05-12T16:17:45.513Z,1683908265.513 [DAT](INFO): DAT read: Fri May 12, 2023  16:17:45  

2023-05-12T16:17:45.514Z,1683908265.514 [DAT](INFO): Local DAT time set to Fri May 12, 2023  16:17:45  

2023-05-12T16:17:50.407Z,1683908270.407 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T16:17:50.407Z,1683908270.407 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+2.0,1489.0,000
2023-05-12T16:17:56.462Z,1683908276.462 [NAL9602](INFO): Powering up NAL9602
2023-05-12T16:17:58.071Z,1683908278.071 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.00,+00000000.00,9999.99,000.00
2023-05-12T16:18:05.756Z,1683908285.756 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T16:18:05.756Z,1683908285.756 [DVL_micro](ERROR): Failed to parse:
:BI,-00016,-00197,-0000,I
2023-05-12T16:18:07.381Z,1683908287.381 [NAL9602](INFO): NAL9602 initialized
2023-05-12T16:18:38.894Z,1683908318.894 [SBIT](IMPORTANT): Beginning Startup BIT
2023-05-12T16:18:38.898Z,1683908318.898 [CBIT](IMPORTANT): Beginning ground fault scan
2023-05-12T16:18:49.829Z,1683908329.829 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): 0.002492
CHAN A1 (24V): 0.000865
CHAN A2 (12V): -0.005623
CHAN A3 (5V): -0.003243
CHAN B0 (3.3V): -0.001288
CHAN B1 (3.15aV): -0.001543
CHAN B2 (3.15bV): -0.001143
CHAN B3 (GND): 0.000109
OPEN: 0.002564
Full Scale: +/- 1 mA
2023-05-12T16:19:33.031Z,1683908373.031 [SBIT](IMPORTANT): SBIT PASSED
2023-05-12T16:19:33.031Z,1683908373.031 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2023-05-12T16:19:33.032Z,1683908373.032 [SBIT](IMPORTANT): CBIT.gfScanTimeout=2 hour;

2023-05-12T16:19:33.032Z,1683908373.032 [SBIT](IMPORTANT): DVL_micro.loadAtStartup=1 bool;

2023-05-12T16:19:33.032Z,1683908373.032 [SBIT](IMPORTANT): Depth_Keller.offset=-0.8 decibar;

2023-05-12T16:19:33.032Z,1683908373.032 [SBIT](IMPORTANT): ESPComponent.sampleTimeout=4 minute;

2023-05-12T16:19:33.032Z,1683908373.032 [SBIT](IMPORTANT): ElevatorServo.offsetAngle=1 degree;

2023-05-12T16:19:33.033Z,1683908373.033 [SBIT](IMPORTANT): Express linearApproximation VerticalHomogeneityIndexCalculator.vertical_salinity_homogeneity_index 0.050000 practical_salinity_unit;

2023-05-12T16:19:33.033Z,1683908373.033 [SBIT](IMPORTANT): Express linearApproximation VerticalHomogeneityIndexCalculator.vertical_temperature_homogeneity_index 0.050000 celsius;

2023-05-12T16:19:33.033Z,1683908373.033 [SBIT](IMPORTANT): Express none WetLabsBB2FL.BackscatteringCoeff470nm;

2023-05-12T16:19:33.033Z,1683908373.033 [SBIT](IMPORTANT): Express none WetLabsBB2FL.BackscatteringCoeff650nm;

2023-05-12T16:19:33.033Z,1683908373.033 [SBIT](IMPORTANT): Express linearApproximation depth 5.000000 meter;

2023-05-12T16:19:33.033Z,1683908373.033 [SBIT](IMPORTANT): Express linearApproximation latitude 0.005000 degree;

2023-05-12T16:19:33.033Z,1683908373.033 [SBIT](IMPORTANT): Express linearApproximation longitude 0.005000 degree;

2023-05-12T16:19:33.033Z,1683908373.033 [SBIT](IMPORTANT): StratificationFrontDetector.loadAtStartup=1 bool;

2023-05-12T16:19:33.033Z,1683908373.033 [SBIT](IMPORTANT): StratificationFrontDetector.threshold_VTHI=0.05 celsius;

2023-05-12T16:19:33.034Z,1683908373.034 [SBIT](IMPORTANT): StratificationFrontDetector.verbosity=1 count;

2023-05-12T16:19:33.034Z,1683908373.034 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=191.501740 cubic_centimeter;

2023-05-12T16:19:33.034Z,1683908373.034 [SBIT](IMPORTANT): VerticalControl.massDefault=12.944775 millimeter;

2023-05-12T16:19:33.034Z,1683908373.034 [SBIT](IMPORTANT): VerticalHomogeneityIndexCalculator.depth3=20 meter;

2023-05-12T16:19:33.034Z,1683908373.034 [SBIT](IMPORTANT): VerticalHomogeneityIndexCalculator.depth4=30 meter;

2023-05-12T16:19:33.034Z,1683908373.034 [SBIT](IMPORTANT): VerticalHomogeneityIndexCalculator.loadAtStartup=1 bool;

2023-05-12T16:19:33.426Z,1683908373.426 [MissionManager](IMPORTANT): Started mission Startup
2023-05-12T16:19:33.426Z,1683908373.426 [Startup] Running Loop=1
2023-05-12T16:19:33.426Z,1683908373.426 [Startup](DEBUG): Aggregate::initialize Startup
2023-05-12T16:19:33.426Z,1683908373.426 [Startup:A.GoToSurface] Running Loop=1
2023-05-12T16:19:33.427Z,1683908373.427 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2023-05-12T16:19:33.427Z,1683908373.427 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2023-05-12T16:19:33.428Z,1683908373.428 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2023-05-12T16:19:33.428Z,1683908373.428 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2023-05-12T16:19:33.429Z,1683908373.429 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2023-05-12T16:19:33.429Z,1683908373.429 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2023-05-12T16:19:33.430Z,1683908373.430 [Startup:StartupSatComms] Running Loop=1
2023-05-12T16:19:33.430Z,1683908373.430 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2023-05-12T16:19:33.431Z,1683908373.431 [Startup:StartupSatComms:A] Running Loop=1
2023-05-12T16:19:33.825Z,1683908373.825 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2023-05-12T16:20:10.181Z,1683908410.181 [DVL_micro](ERROR): Failed to parse:
9.99,+9999.99,+99999.99
2023-05-12T16:20:10.283Z,1683908410.283 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005373
2023-05-12T16:20:27.635Z,1683908427.635 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2023-05-12T16:20:27.635Z,1683908427.635 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-12T16:20:27.681Z,1683908427.681 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-12T16:20:28.327Z,1683908428.327 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-12T16:20:28.327Z,1683908428.327 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2023-05-12T16:20:33.634Z,1683908433.634 [Startup:StartupSatComms:A](INFO): Timed out from 2023-05-12T16:19:33.4Z
2023-05-12T16:20:33.634Z,1683908433.634 [Startup:StartupSatComms:A] Stopped
2023-05-12T16:20:33.634Z,1683908433.634 [Startup:StartupSatComms:B] Running Loop=1
2023-05-12T16:20:34.046Z,1683908434.046 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2023-05-12T16:20:39.784Z,1683908439.784 [DataOverHttps](INFO): Sending 242 bytes from file Logs/20230512T161343/Courier0000.lzma
2023-05-12T16:20:40.786Z,1683908440.786 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161343/Courier0000.lzma.bak
2023-05-12T16:20:40.786Z,1683908440.786 [DataOverHttps](INFO): SBD MOMSN=18295218
2023-05-12T16:20:56.579Z,1683908456.579 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20230512T161343/Courier0004.lzma
2023-05-12T16:20:57.582Z,1683908457.582 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161343/Courier0004.lzma.bak
2023-05-12T16:20:57.582Z,1683908457.582 [DataOverHttps](INFO): SBD MOMSN=18295225
2023-05-12T16:21:13.000Z,1683908474.000 [DataOverHttps](INFO): Sending 242 bytes from file Logs/20230512T161716/Courier0000.lzma
2023-05-12T16:21:15.002Z,1683908475.002 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0000.lzma.bak
2023-05-12T16:21:15.002Z,1683908475.002 [DataOverHttps](INFO): SBD MOMSN=18295230
2023-05-12T16:21:30.924Z,1683908490.924 [DataOverHttps](INFO): Sending 508 bytes from file Logs/20230511T210823/Express0032.lzma
2023-05-12T16:21:31.926Z,1683908491.926 [DataOverHttps](INFO): Moved sent file to Logs/20230511T210823/Express0032.lzma.bak
2023-05-12T16:21:31.926Z,1683908491.926 [DataOverHttps](INFO): SBD MOMSN=18295235
2023-05-12T16:21:33.874Z,1683908493.874 [Startup:StartupSatComms:B](INFO): Timed out from 2023-05-12T16:20:33.6Z
2023-05-12T16:21:33.874Z,1683908493.874 [Startup:StartupSatComms:B] Stopped
2023-05-12T16:21:33.875Z,1683908493.875 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2023-05-12T16:21:33.875Z,1683908493.875 [Startup:StartupSatComms] Stopped
2023-05-12T16:21:33.875Z,1683908493.875 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2023-05-12T16:21:33.875Z,1683908493.875 [Startup](INFO): Completed Startup
2023-05-12T16:21:33.876Z,1683908493.876 [MissionManager](INFO): Startup is completed.
2023-05-12T16:21:33.876Z,1683908493.876 [MissionManager](INFO): Uninitializing Mission Startup
2023-05-12T16:21:33.876Z,1683908493.876 [Startup] Stopped
2023-05-12T16:21:33.876Z,1683908493.876 [Startup](DEBUG): Aggregate::uninitialize Startup
2023-05-12T16:21:33.876Z,1683908493.876 [Startup:A.GoToSurface] Stopped
2023-05-12T16:21:33.876Z,1683908493.876 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2023-05-12T16:21:34.342Z,1683908494.342 [MissionManager](IMPORTANT): Started mission Default
2023-05-12T16:21:34.342Z,1683908494.342 [Default] Running Loop=1
2023-05-12T16:21:34.342Z,1683908494.342 [Default](DEBUG): Aggregate::initialize Default
2023-05-12T16:21:34.342Z,1683908494.342 [Default:B.GoToSurface] Running Loop=1
2023-05-12T16:21:34.342Z,1683908494.342 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2023-05-12T16:21:34.342Z,1683908494.342 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2023-05-12T16:21:34.343Z,1683908494.343 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2023-05-12T16:21:34.343Z,1683908494.343 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2023-05-12T16:21:34.343Z,1683908494.343 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2023-05-12T16:21:34.344Z,1683908494.344 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2023-05-12T16:21:34.344Z,1683908494.344 [Default:A.Wait] Running Loop=1
2023-05-12T16:21:34.344Z,1683908494.344 [Default:A.Wait](DEBUG): Initialize Wait Component.
2023-05-12T16:21:47.688Z,1683908507.688 [Default:A.Wait](INFO): Done Waiting.
2023-05-12T16:21:47.688Z,1683908507.688 [Default:A.Wait] Stopped
2023-05-12T16:21:47.688Z,1683908507.688 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T16:21:48.045Z,1683908508.045 [Default:CheckIn] Running Loop=1
2023-05-12T16:21:48.046Z,1683908508.046 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T16:21:48.046Z,1683908508.046 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T16:21:48.402Z,1683908508.402 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2023-05-12T16:22:09.749Z,1683908529.749 [DataOverHttps](INFO): Sending 1303 bytes from file Logs/20230512T161343/Express0001.lzma
2023-05-12T16:22:10.749Z,1683908530.749 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161343/Express0001.lzma.bak
2023-05-12T16:22:10.750Z,1683908530.750 [DataOverHttps](INFO): SBD MOMSN=18295297
2023-05-12T16:23:00.329Z,1683908580.329 [DVL_micro](ERROR): Failed to parse:
:SA,-03.47,+08.66,185.9
2023-05-12T16:23:11.208Z,1683908591.208 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-12T16:23:28.599Z,1683908608.599 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2023-05-12T16:23:28.599Z,1683908608.599 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-12T16:23:28.609Z,1683908608.609 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-12T16:23:28.998Z,1683908608.998 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-12T16:23:28.998Z,1683908608.998 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2023-05-12T16:24:08.188Z,1683908648.188 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2023-05-12T16:24:08.196Z,1683908648.196 [BPC1](INFO): Received data from all battery sticks.
2023-05-12T16:24:31.608Z,1683908671.608 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T16:24:31.609Z,1683908671.609 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+21.3,089.0,000
2023-05-12T16:26:29.600Z,1683908789.600 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2023-05-12T16:26:29.601Z,1683908789.601 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-12T16:26:29.635Z,1683908789.635 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-12T16:26:30.014Z,1683908790.014 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-12T16:26:30.014Z,1683908790.014 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2023-05-12T16:26:48.194Z,1683908808.194 [Default:CheckIn:Read_GPS](INFO): Timed out from 2023-05-12T16:21:48.0Z
2023-05-12T16:26:48.194Z,1683908808.194 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T16:26:48.195Z,1683908808.195 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T16:26:48.587Z,1683908808.587 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2023-05-12T16:26:55.879Z,1683908815.879 [DataOverHttps](INFO): Sending 168 bytes from file Logs/20230512T161716/Courier0004.lzma
2023-05-12T16:26:56.882Z,1683908816.882 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0004.lzma.bak
2023-05-12T16:26:56.882Z,1683908816.882 [DataOverHttps](INFO): SBD MOMSN=18295356
2023-05-12T16:27:12.507Z,1683908832.507 [DataOverHttps](INFO): Sending 78 bytes from file Logs/20230512T161343/Express0005.lzma
2023-05-12T16:27:13.510Z,1683908833.510 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161343/Express0005.lzma.bak
2023-05-12T16:27:13.510Z,1683908833.510 [DataOverHttps](INFO): SBD MOMSN=18295358
2023-05-12T16:27:31.333Z,1683908851.333 [DataOverHttps](INFO): Sending 1101 bytes from file Logs/20230512T161716/Express0001.lzma
2023-05-12T16:27:32.334Z,1683908852.334 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0001.lzma.bak
2023-05-12T16:27:32.334Z,1683908852.334 [DataOverHttps](INFO): SBD MOMSN=18295361
2023-05-12T16:27:47.911Z,1683908867.911 [DataOverHttps](INFO): Sending 187 bytes from file Logs/20230512T161716/Express0005.lzma
2023-05-12T16:27:48.914Z,1683908868.914 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0005.lzma.bak
2023-05-12T16:27:48.914Z,1683908868.914 [DataOverHttps](INFO): SBD MOMSN=18295394
2023-05-12T16:27:50.402Z,1683908870.402 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T16:27:50.402Z,1683908870.402 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T16:27:50.402Z,1683908870.402 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T16:28:08.555Z,1683908888.555 [NAL9602](FAULT): GPS failed to acquire within timeout.
2023-05-12T16:28:08.555Z,1683908888.555 [NAL9602] Data Fault, FailCount= 1
2023-05-12T16:28:08.555Z,1683908888.555 [NAL9602](ERROR): Data Fault
2023-05-12T16:28:08.572Z,1683908888.572 [CBIT](ERROR): Data Fault in component: NAL9602
2023-05-12T16:28:08.966Z,1683908888.966 [NAL9602](INFO): Powering down
2023-05-12T16:28:09.782Z,1683908889.782 [CBIT](INFO): Clearing failed state for component NAL9602
2023-05-12T16:28:09.782Z,1683908889.782 [NAL9602] No Fault, FailCount= 1
2023-05-12T16:28:39.258Z,1683908919.258 [NAL9602](INFO): Powering up NAL9602
2023-05-12T16:28:48.228Z,1683908928.228 [DVL_micro](ERROR): DVL uart error: serial timeout
2023-05-12T16:28:48.228Z,1683908928.228 [DVL_micro] Communications Fault, FailCount= 1
2023-05-12T16:28:48.228Z,1683908928.228 [DVL_micro](ERROR): Communications Fault
2023-05-12T16:28:48.228Z,1683908928.228 [DVL_micro](ERROR): Failed to parse:
2023-05-12T16:28:48.251Z,1683908928.251 [CBIT](ERROR): Communications Fault in component: DVL_micro
2023-05-12T16:28:48.636Z,1683908928.636 [DVL_micro](INFO): Powering down
2023-05-12T16:28:49.384Z,1683908929.384 [CBIT](INFO): Clearing failed state for component DVL_micro
2023-05-12T16:28:49.385Z,1683908929.385 [DVL_micro] No Fault, FailCount= 1
2023-05-12T16:28:50.185Z,1683908930.185 [NAL9602](INFO): NAL9602 initialized
2023-05-12T16:29:30.605Z,1683908970.605 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2023-05-12T16:29:30.605Z,1683908970.605 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-12T16:29:30.617Z,1683908970.617 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-12T16:29:31.015Z,1683908971.015 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-12T16:29:31.015Z,1683908971.015 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2023-05-12T16:29:37.854Z,1683908977.854 [DVL_micro](ERROR): only read 1 of 4 data items
2023-05-12T16:29:37.854Z,1683908977.854 [DVL_micro](ERROR): Failed to parse:
:BI,-00094-00464,+00000,I
2023-05-12T16:32:28.420Z,1683909148.420 [CBIT](INFO): Clearing failed state for component DropWeight
2023-05-12T16:32:28.420Z,1683909148.420 [DropWeight] No Fault, FailCount= 1
2023-05-12T16:32:31.609Z,1683909151.609 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5
2023-05-12T16:32:31.609Z,1683909151.609 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-12T16:32:31.644Z,1683909151.644 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-12T16:32:32.026Z,1683909152.026 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-12T16:32:32.027Z,1683909152.027 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5
2023-05-12T16:32:50.978Z,1683909170.978 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-12T16:32:50.978Z,1683909170.978 [Default:CheckIn:C.Wait] Stopped
2023-05-12T16:32:50.978Z,1683909170.978 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T16:32:50.978Z,1683909170.978 [Default:CheckIn:D] Running Loop=1
2023-05-12T16:32:51.382Z,1683909171.382 [Default:CheckIn:D] Stopped
2023-05-12T16:32:51.382Z,1683909171.382 [Default:CheckIn:E] Running Loop=1
2023-05-12T16:32:51.793Z,1683909171.793 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 11.284008 min 
2023-05-12T16:32:51.793Z,1683909171.793 [Default:CheckIn:E] Stopped
2023-05-12T16:32:51.793Z,1683909171.793 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-12T16:32:51.794Z,1683909171.794 [Default:CheckIn] Stopped
2023-05-12T16:32:51.794Z,1683909171.794 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T16:32:51.794Z,1683909171.794 [Default:CheckIn](INFO): Running loop #2
2023-05-12T16:32:51.794Z,1683909171.794 [Default:CheckIn] Running Loop=2
2023-05-12T16:32:51.794Z,1683909171.794 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T16:32:51.794Z,1683909171.794 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T16:32:58.252Z,1683909178.252 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T16:32:58.252Z,1683909178.252 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+21.3,0000.0,10
2023-05-12T16:35:32.580Z,1683909332.580 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6
2023-05-12T16:35:32.581Z,1683909332.581 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-12T16:35:32.591Z,1683909332.591 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-12T16:35:33.008Z,1683909333.008 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-12T16:35:33.008Z,1683909333.008 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6
2023-05-12T16:36:00.876Z,1683909360.876 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T16:36:00.876Z,1683909360.876 [DVL_micro](ERROR): Failed to parse:
:BI,-00016,-00049,-00371,+

2023-05-12T16:37:51.995Z,1683909471.995 [Default:CheckIn:Read_GPS](INFO): Timed out from 2023-05-12T16:32:51.8Z
2023-05-12T16:37:51.995Z,1683909471.995 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T16:37:51.996Z,1683909471.996 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T16:37:58.775Z,1683909478.775 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20230512T161716/Courier0007.lzma
2023-05-12T16:37:59.778Z,1683909479.778 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0007.lzma.bak
2023-05-12T16:37:59.778Z,1683909479.778 [DataOverHttps](INFO): SBD MOMSN=18295416
2023-05-12T16:38:15.427Z,1683909495.427 [DataOverHttps](INFO): Sending 182 bytes from file Logs/20230512T161716/Express0008.lzma
2023-05-12T16:38:16.430Z,1683909496.430 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0008.lzma.bak
2023-05-12T16:38:16.430Z,1683909496.430 [DataOverHttps](INFO): SBD MOMSN=18295418
2023-05-12T16:38:17.913Z,1683909497.913 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T16:38:17.913Z,1683909497.913 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T16:38:17.913Z,1683909497.913 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T16:38:33.644Z,1683909513.644 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 7
2023-05-12T16:38:33.644Z,1683909513.644 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-12T16:38:33.654Z,1683909513.654 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-12T16:38:34.059Z,1683909514.059 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-12T16:38:34.059Z,1683909514.059 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 7
2023-05-12T16:38:51.024Z,1683909531.024 [NAL9602](FAULT): GPS failed to acquire within timeout.
2023-05-12T16:38:51.024Z,1683909531.024 [NAL9602] Data Fault, FailCount= 2
2023-05-12T16:38:51.024Z,1683909531.024 [NAL9602](ERROR): Data Fault
2023-05-12T16:38:51.117Z,1683909531.117 [CBIT](ERROR): Data Fault in component: NAL9602
2023-05-12T16:38:51.414Z,1683909531.414 [NAL9602](INFO): Powering down
2023-05-12T16:38:52.270Z,1683909532.270 [CBIT](INFO): Clearing failed state for component NAL9602
2023-05-12T16:38:52.270Z,1683909532.270 [NAL9602] No Fault, FailCount= 2
2023-05-12T16:39:21.718Z,1683909561.718 [NAL9602](INFO): Powering up NAL9602
2023-05-12T16:39:32.619Z,1683909572.619 [NAL9602](INFO): NAL9602 initialized
2023-05-12T16:41:34.674Z,1683909694.674 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 8
2023-05-12T16:41:34.674Z,1683909694.674 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-12T16:41:34.684Z,1683909694.684 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-12T16:41:35.095Z,1683909695.095 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-12T16:41:35.095Z,1683909695.095 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 8
2023-05-12T16:42:03.763Z,1683909723.763 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T16:42:03.763Z,1683909723.763 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+21.4,009.0,000
2023-05-12T16:43:18.501Z,1683909798.501 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-12T16:43:18.501Z,1683909798.501 [Default:CheckIn:C.Wait] Stopped
2023-05-12T16:43:18.501Z,1683909798.501 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T16:43:18.502Z,1683909798.502 [Default:CheckIn:D] Running Loop=1
2023-05-12T16:43:18.910Z,1683909798.910 [Default:CheckIn:D] Stopped
2023-05-12T16:43:18.910Z,1683909798.910 [Default:CheckIn:E] Running Loop=1
2023-05-12T16:43:19.312Z,1683909799.312 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 21.742798 min 
2023-05-12T16:43:19.312Z,1683909799.312 [Default:CheckIn:E] Stopped
2023-05-12T16:43:19.312Z,1683909799.312 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-12T16:43:19.312Z,1683909799.312 [Default:CheckIn] Stopped
2023-05-12T16:43:19.312Z,1683909799.312 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T16:43:19.312Z,1683909799.312 [Default:CheckIn](INFO): Running loop #3
2023-05-12T16:43:19.313Z,1683909799.313 [Default:CheckIn] Running Loop=3
2023-05-12T16:43:19.313Z,1683909799.313 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T16:43:19.313Z,1683909799.313 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T16:44:35.692Z,1683909875.692 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 9
2023-05-12T16:44:35.693Z,1683909875.693 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-12T16:44:35.703Z,1683909875.703 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-12T16:44:36.118Z,1683909876.118 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-12T16:44:36.118Z,1683909876.118 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 9
2023-05-12T16:45:03.949Z,1683909903.949 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T16:45:03.949Z,1683909903.949 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.999,+9999.99,+9999.99
2023-05-12T16:47:36.673Z,1683910056.673 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 10
2023-05-12T16:47:36.673Z,1683910056.673 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-12T16:47:36.684Z,1683910056.684 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-12T16:47:37.083Z,1683910057.083 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-12T16:47:37.083Z,1683910057.083 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 10
2023-05-12T16:48:19.527Z,1683910099.527 [Default:CheckIn:Read_GPS](INFO): Timed out from 2023-05-12T16:43:19.3Z
2023-05-12T16:48:19.527Z,1683910099.527 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T16:48:19.527Z,1683910099.527 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T16:48:26.799Z,1683910106.799 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20230512T161716/Courier0010.lzma
2023-05-12T16:48:27.802Z,1683910107.802 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0010.lzma.bak
2023-05-12T16:48:27.802Z,1683910107.802 [DataOverHttps](INFO): SBD MOMSN=18295530
2023-05-12T16:48:44.015Z,1683910124.015 [DataOverHttps](INFO): Sending 150 bytes from file Logs/20230512T161716/Express0011.lzma
2023-05-12T16:48:45.018Z,1683910125.018 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0011.lzma.bak
2023-05-12T16:48:45.018Z,1683910125.018 [DataOverHttps](INFO): SBD MOMSN=18295532
2023-05-12T16:48:46.579Z,1683910126.579 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T16:48:46.579Z,1683910126.579 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T16:48:46.579Z,1683910126.579 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T16:49:33.814Z,1683910173.814 [NAL9602](FAULT): GPS failed to acquire within timeout.
2023-05-12T16:49:33.814Z,1683910173.814 [NAL9602] Data Fault, FailCount= 3
2023-05-12T16:49:33.814Z,1683910173.814 [NAL9602](ERROR): Data Fault
2023-05-12T16:49:33.860Z,1683910173.860 [CBIT](ERROR): Data Fault in component: NAL9602
2023-05-12T16:49:34.218Z,1683910174.218 [NAL9602](INFO): Powering down
2023-05-12T16:49:35.040Z,1683910175.040 [CBIT](INFO): Clearing failed state for component NAL9602
2023-05-12T16:49:35.040Z,1683910175.040 [NAL9602] No Fault, FailCount= 3
2023-05-12T16:50:04.514Z,1683910204.514 [NAL9602](INFO): Powering up NAL9602
2023-05-12T16:50:15.422Z,1683910215.422 [NAL9602](INFO): NAL9602 initialized
2023-05-12T16:50:37.825Z,1683910237.825 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 11
2023-05-12T16:50:37.825Z,1683910237.825 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-12T16:50:37.888Z,1683910237.888 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-12T16:50:38.251Z,1683910238.251 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-12T16:50:38.251Z,1683910238.251 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 11
2023-05-12T16:51:11.724Z,1683910271.724 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T16:51:11.724Z,1683910271.724 [DVL_micro](ERROR): Failed to parse:
:TS,000000,35,0000.0,1489.WI,+00078,-00066,-00426,+00000,A0078,-00066,-00426,+00000,I
2023-05-12T16:53:38.781Z,1683910418.781 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 12
2023-05-12T16:53:38.781Z,1683910418.781 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-12T16:53:38.792Z,1683910418.792 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-12T16:53:39.255Z,1683910419.255 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-12T16:53:39.255Z,1683910419.255 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 12
2023-05-12T16:53:47.286Z,1683910427.286 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-12T16:53:47.286Z,1683910427.286 [Default:CheckIn:C.Wait] Stopped
2023-05-12T16:53:47.286Z,1683910427.286 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T16:53:47.286Z,1683910427.286 [Default:CheckIn:D] Running Loop=1
2023-05-12T16:53:47.679Z,1683910427.679 [Default:CheckIn:D] Stopped
2023-05-12T16:53:47.679Z,1683910427.679 [Default:CheckIn:E] Running Loop=1
2023-05-12T16:53:48.074Z,1683910428.074 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 32.222270 min 
2023-05-12T16:53:48.074Z,1683910428.074 [Default:CheckIn:E] Stopped
2023-05-12T16:53:48.074Z,1683910428.074 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-12T16:53:48.074Z,1683910428.074 [Default:CheckIn] Stopped
2023-05-12T16:53:48.074Z,1683910428.074 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T16:53:48.075Z,1683910428.075 [Default:CheckIn](INFO): Running loop #4
2023-05-12T16:53:48.075Z,1683910428.075 [Default:CheckIn] Running Loop=4
2023-05-12T16:53:48.075Z,1683910428.075 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T16:53:48.075Z,1683910428.075 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T16:54:09.490Z,1683910449.490 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T16:54:09.490Z,1683910449.490 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,+99999.99
2023-05-12T16:56:39.772Z,1683910599.772 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 13
2023-05-12T16:56:39.772Z,1683910599.772 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-12T16:56:39.783Z,1683910599.783 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-12T16:56:40.184Z,1683910600.184 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-12T16:56:40.184Z,1683910600.184 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 13
2023-05-12T16:58:48.286Z,1683910728.286 [Default:CheckIn:Read_GPS](INFO): Timed out from 2023-05-12T16:53:48.1Z
2023-05-12T16:58:48.286Z,1683910728.286 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T16:58:48.286Z,1683910728.286 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T16:58:55.568Z,1683910735.568 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20230512T161716/Courier0013.lzma
2023-05-12T16:58:56.570Z,1683910736.570 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0013.lzma.bak
2023-05-12T16:58:56.570Z,1683910736.570 [DataOverHttps](INFO): SBD MOMSN=18296222
2023-05-12T16:59:12.403Z,1683910752.403 [DataOverHttps](INFO): Sending 148 bytes from file Logs/20230512T161716/Express0014.lzma
2023-05-12T16:59:13.406Z,1683910753.406 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0014.lzma.bak
2023-05-12T16:59:13.406Z,1683910753.406 [DataOverHttps](INFO): SBD MOMSN=18296224
2023-05-12T16:59:14.930Z,1683910754.930 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T16:59:14.930Z,1683910754.930 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T16:59:14.930Z,1683910754.930 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T16:59:40.805Z,1683910780.805 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 14
2023-05-12T16:59:40.805Z,1683910780.805 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-12T16:59:40.817Z,1683910780.817 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-12T16:59:41.220Z,1683910781.220 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-12T16:59:41.220Z,1683910781.220 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 14
2023-05-12T17:00:14.713Z,1683910814.713 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T17:00:14.713Z,1683910814.713 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,+99999.99
2023-05-12T17:00:16.727Z,1683910816.727 [NAL9602](FAULT): GPS failed to acquire within timeout.
2023-05-12T17:00:16.727Z,1683910816.727 [NAL9602] Data Fault, FailCount= 4
2023-05-12T17:00:16.727Z,1683910816.727 [NAL9602](ERROR): Data Fault
2023-05-12T17:00:16.744Z,1683910816.744 [CBIT](ERROR): Data Fault in component: NAL9602
2023-05-12T17:00:17.149Z,1683910817.149 [NAL9602](INFO): Powering down
2023-05-12T17:00:18.003Z,1683910818.003 [CBIT](INFO): Clearing failed state for component NAL9602
2023-05-12T17:00:18.003Z,1683910818.003 [NAL9602] No Fault, FailCount= 4
2023-05-12T17:00:19.677Z,1683910819.677 [DVL_micro](ERROR): only read 1 of 4 data items
2023-05-12T17:00:19.677Z,1683910819.677 [DVL_micro](ERROR): Failed to parse:
:BI,+00232-00367,+00000+00000000.00,+0000+00000000.00,9999.99,000.00
2023-05-12T17:00:47.471Z,1683910847.471 [NAL9602](INFO): Powering up NAL9602
2023-05-12T17:00:58.382Z,1683910858.382 [NAL9602](INFO): NAL9602 initialized
2023-05-12T17:02:29.686Z,1683910949.686 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2023-05-12T17:02:29.687Z,1683910949.687 [DropWeight] Hardware Fault, FailCount= 1
2023-05-12T17:02:29.687Z,1683910949.687 [DropWeight](ERROR): Hardware Fault
2023-05-12T17:02:29.763Z,1683910949.763 [CBIT](INFO): Critical error at 20230512T170229
2023-05-12T17:02:29.769Z,1683910949.769 [CBIT](ERROR): Hardware Fault in component: DropWeight
2023-05-12T17:02:29.770Z,1683910949.770 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2023-05-12T17:02:30.104Z,1683910950.104 [CBIT](INFO): Critical error at 20230512T170229
2023-05-12T17:02:41.841Z,1683910961.841 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 15
2023-05-12T17:02:41.841Z,1683910961.841 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-12T17:02:41.885Z,1683910961.885 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-12T17:02:42.242Z,1683910962.242 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-12T17:02:42.242Z,1683910962.242 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 15
2023-05-12T17:03:22.615Z,1683911002.615 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T17:03:22.616Z,1683911002.616 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+21.5,0000.0,00
2023-05-12T17:03:25.040Z,1683911005.040 [DVL_micro](ERROR): Failed to parse:
:T00000000,35.0,+21.5,0000.0,1489.0,000
2023-05-12T17:04:15.595Z,1683911055.595 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-12T17:04:15.595Z,1683911055.595 [Default:CheckIn:C.Wait] Stopped
2023-05-12T17:04:15.595Z,1683911055.595 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T17:04:15.595Z,1683911055.595 [Default:CheckIn:D] Running Loop=1
2023-05-12T17:04:15.970Z,1683911055.970 [Default:CheckIn:D] Stopped
2023-05-12T17:04:15.970Z,1683911055.970 [Default:CheckIn:E] Running Loop=1
2023-05-12T17:04:16.365Z,1683911056.365 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 42.693803 min 
2023-05-12T17:04:16.365Z,1683911056.365 [Default:CheckIn:E] Stopped
2023-05-12T17:04:16.365Z,1683911056.365 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-12T17:04:16.365Z,1683911056.365 [Default:CheckIn] Stopped
2023-05-12T17:04:16.366Z,1683911056.366 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T17:04:16.366Z,1683911056.366 [Default:CheckIn](INFO): Running loop #5
2023-05-12T17:04:16.366Z,1683911056.366 [Default:CheckIn] Running Loop=5
2023-05-12T17:04:16.366Z,1683911056.366 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T17:04:16.366Z,1683911056.366 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T17:05:42.834Z,1683911142.834 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 16
2023-05-12T17:05:42.834Z,1683911142.834 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-12T17:05:42.845Z,1683911142.845 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-12T17:05:43.266Z,1683911143.266 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-12T17:05:43.266Z,1683911143.266 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 16
2023-05-12T17:06:15.146Z,1683911175.146 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T17:06:15.147Z,1683911175.147 [DVL_micro](ERROR): Failed to parse:
:BI,+0125,-00313,+00000,I
2023-05-12T17:08:28.201Z,1683911308.201 [CommandExec](IMPORTANT): got command burn on
2023-05-12T17:08:28.201Z,1683911308.201 [CommandExec](IMPORTANT): Activating dropweight wire
2023-05-12T17:08:43.841Z,1683911323.841 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 17
2023-05-12T17:08:43.841Z,1683911323.841 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-12T17:08:43.851Z,1683911323.851 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-12T17:08:44.258Z,1683911324.258 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-12T17:08:44.258Z,1683911324.258 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 17
2023-05-12T17:08:50.889Z,1683911330.889 [CommandExec](IMPORTANT): got command burn off
2023-05-12T17:08:50.889Z,1683911330.889 [CommandExec](IMPORTANT): Deactivating dropweight wire
2023-05-12T17:09:16.570Z,1683911356.570 [Default:CheckIn:Read_GPS](INFO): Timed out from 2023-05-12T17:04:16.4Z
2023-05-12T17:09:16.570Z,1683911356.570 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T17:09:16.570Z,1683911356.570 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T17:09:23.755Z,1683911363.755 [DataOverHttps](INFO): Sending 114 bytes from file Logs/20230512T161716/Courier0016.lzma
2023-05-12T17:09:24.758Z,1683911364.758 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0016.lzma.bak
2023-05-12T17:09:24.758Z,1683911364.758 [DataOverHttps](INFO): SBD MOMSN=18297594
2023-05-12T17:09:40.907Z,1683911380.907 [DataOverHttps](INFO): Sending 216 bytes from file Logs/20230512T161716/Express0017.lzma
2023-05-12T17:09:41.910Z,1683911381.910 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0017.lzma.bak
2023-05-12T17:09:41.910Z,1683911381.910 [DataOverHttps](INFO): SBD MOMSN=18297598
2023-05-12T17:09:43.627Z,1683911383.627 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T17:09:43.628Z,1683911383.628 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T17:09:43.628Z,1683911383.628 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T17:10:59.559Z,1683911459.559 [NAL9602](FAULT): GPS failed to acquire within timeout.
2023-05-12T17:10:59.559Z,1683911459.559 [NAL9602] Data Fault, FailCount= 5
2023-05-12T17:10:59.559Z,1683911459.559 [NAL9602](ERROR): Data Fault
2023-05-12T17:10:59.576Z,1683911459.576 [CBIT](ERROR): Data Fault in component: NAL9602
2023-05-12T17:10:59.577Z,1683911459.577 [CBIT](CRITICAL): Data Fault in component: NAL9602
2023-05-12T17:10:59.964Z,1683911459.964 [NAL9602](INFO): Powering down
2023-05-12T17:10:59.979Z,1683911459.979 [CBIT](INFO): Critical error at 20230512T171059
2023-05-12T17:11:44.828Z,1683911504.828 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 18
2023-05-12T17:11:44.828Z,1683911504.828 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-12T17:11:44.839Z,1683911504.839 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-12T17:11:45.247Z,1683911505.247 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-12T17:11:45.247Z,1683911505.247 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 18
2023-05-12T17:12:25.228Z,1683911545.228 [DVL_micro](ERROR): only read 0 of 4 data items
2023-05-12T17:12:25.229Z,1683911545.229 [DVL_micro](ERROR): Failed to parse:
:RD9,+9999.99,+9999.99,+9999.99
2023-05-12T17:12:59.569Z,1683911579.569 [CBIT](INFO): Clearing failed state for component NAL9602
2023-05-12T17:12:59.569Z,1683911579.569 [NAL9602] No Fault, FailCount= 5
2023-05-12T17:12:59.951Z,1683911579.951 [NAL9602](INFO): Powering up NAL9602
2023-05-12T17:13:10.880Z,1683911590.880 [NAL9602](INFO): NAL9602 initialized
2023-05-12T17:14:44.210Z,1683911684.210 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-12T17:14:44.210Z,1683911684.210 [Default:CheckIn:C.Wait] Stopped
2023-05-12T17:14:44.210Z,1683911684.210 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T17:14:44.210Z,1683911684.210 [Default:CheckIn:D] Running Loop=1
2023-05-12T17:14:44.614Z,1683911684.614 [Default:CheckIn:D] Stopped
2023-05-12T17:14:44.614Z,1683911684.614 [Default:CheckIn:E] Running Loop=1
2023-05-12T17:14:45.030Z,1683911685.030 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 53.171204 min 
2023-05-12T17:14:45.030Z,1683911685.030 [Default:CheckIn:E] Stopped
2023-05-12T17:14:45.031Z,1683911685.031 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-12T17:14:45.031Z,1683911685.031 [Default:CheckIn] Stopped
2023-05-12T17:14:45.031Z,1683911685.031 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T17:14:45.031Z,1683911685.031 [Default:CheckIn](INFO): Running loop #6
2023-05-12T17:14:45.031Z,1683911685.031 [Default:CheckIn] Running Loop=6
2023-05-12T17:14:45.031Z,1683911685.031 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T17:14:45.031Z,1683911685.031 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T17:14:45.806Z,1683911685.806 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 19
2023-05-12T17:14:45.806Z,1683911685.806 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-12T17:14:45.817Z,1683911685.817 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-12T17:14:46.229Z,1683911686.229 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-12T17:14:46.229Z,1683911686.229 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 19
2023-05-12T17:17:29.892Z,1683911849.892 [CBIT](INFO): Clearing failed state for component DropWeight
2023-05-12T17:17:29.892Z,1683911849.892 [DropWeight] No Fault, FailCount= 1
2023-05-12T17:17:46.802Z,1683911866.802 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 20
2023-05-12T17:17:46.802Z,1683911866.802 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-12T17:17:46.819Z,1683911866.819 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-12T17:17:47.218Z,1683911867.218 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-12T17:17:47.218Z,1683911867.218 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 20
2023-05-12T17:18:00.068Z,1683911880.068 [CommandExec](IMPORTANT): got command set NAL9602.latitude_fix 36.803 degree
2023-05-12T17:18:00.069Z,1683911880.069 [CommandExec](IMPORTANT): got command set NAL9602.longitude_fix -121.788 degree
2023-05-12T17:18:00.070Z,1683911880.070 [CommandExec](IMPORTANT): got command set NAL9602.time_fix 1683911849 second
2023-05-12T17:18:00.071Z,1683911880.071 [CommandExec](IMPORTANT): got command set NAL9602.goodFix 1 bool
2023-05-12T17:18:00.205Z,1683911880.205 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T17:18:00.205Z,1683911880.205 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T17:18:01.792Z,1683911881.792 [CommandExec](IMPORTANT): got command get NAL9602.latitude_fix
2023-05-12T17:18:01.792Z,1683911881.792 [CommandExec](IMPORTANT): NAL9602.latitude_fix 36.803001 arcdeg
2023-05-12T17:18:08.092Z,1683911888.092 [DataOverHttps](INFO): Sending 266 bytes from file Logs/20230512T161716/Courier0019.lzma
2023-05-12T17:18:09.078Z,1683911889.078 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0019.lzma.bak
2023-05-12T17:18:09.078Z,1683911889.078 [DataOverHttps](INFO): SBD MOMSN=18297619
2023-05-12T17:18:11.928Z,1683911891.928 [CommandExec](IMPORTANT): got command failComponent
2023-05-12T17:18:11.929Z,1683911891.929 [CommandExec](IMPORTANT): Failed components:
2023-05-12T17:18:11.929Z,1683911891.929 [CommandExec](IMPORTANT): No failed Components.
2023-05-12T17:18:19.045Z,1683911899.045 [CommandExec](IMPORTANT): got command strobe off
2023-05-12T17:18:19.045Z,1683911899.045 [CommandExec](IMPORTANT): Deactivating strobe
2023-05-12T17:18:25.752Z,1683911905.752 [DataOverHttps](INFO): Sending 377 bytes from file Logs/20230512T161716/Express0020.lzma
2023-05-12T17:18:26.754Z,1683911906.754 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0020.lzma.bak
2023-05-12T17:18:26.754Z,1683911906.754 [DataOverHttps](INFO): SBD MOMSN=18297647
2023-05-12T17:18:28.267Z,1683911908.267 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T17:18:28.267Z,1683911908.267 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T17:18:28.267Z,1683911908.267 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T17:18:30.663Z,1683911910.663 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-12T17:19:06.045Z,1683911946.045 [DataOverHttps](IMPORTANT): SBD MTMSN=20230512T171854
2023-05-12T17:19:13.488Z,1683911953.488 [DataOverHttps](INFO): Received command: load Maintenance/sample_lab.xml;set sample_lab.CartridgeType -1 count;run
2023-05-12T17:19:13.561Z,1683911953.561 [CommandExec](IMPORTANT): got command load ./Missions/Maintenance/sample_lab.xml
2023-05-12T17:19:13.561Z,1683911953.561 [MissionManager](INFO): Loading Mission from file: ./Missions/Maintenance/sample_lab.xml
2023-05-12T17:19:13.583Z,1683911953.583 [MissionManager](INFO): DefineArg sample_lab.MissionTimeout = 90.000000 min
2023-05-12T17:19:13.634Z,1683911953.634 [MissionManager](INFO): DefineArg sample_lab.CartridgeType = -4.000000 count
2023-05-12T17:19:13.638Z,1683911953.638 [MissionManager](INFO): DefineArg sample_lab.NumberOfSamples = 1.000000 count
2023-05-12T17:19:13.639Z,1683911953.639 [sample_lab:A.AbortSample](DEBUG): Construct.
2023-05-12T17:19:13.672Z,1683911953.672 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](DEBUG): Construct.
2023-05-12T17:19:13.681Z,1683911953.681 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Sample="Tethys/Sample"
         xmlns:Science="Tethys/Science"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Sample http://okeanids.mbari.org/tethys/Xml/Sample.xsd
                             Tethys/Science http://okeanids.mbari.org/tethys/Xml/Science.xsd"
       Id="sample_lab">

    <Description>
        This mission is designed to run in the lab only and triggers an ESP
        sample with specified type.
    </Description>

    <DefineArg Name="MissionTimeout"><Description>
        How long to let the mission run.
    </Description><Units:minute/><Value>90</Value></DefineArg>

    <DefineArg Name="CartridgeType"><Description>
        Specifies ESP cartridge type code (defaults to archiveHiBiomass_bac: -4)
    </Description><Units:count/><Value>-4</Value></DefineArg>

    <DefineArg Name="NumberOfSamples"><Description>
        Number of samples to take.
    </Description><Units:count/><Value>1</Value></DefineArg>

    <Timeout Duration="MissionTimeout"/>

    <Sample:AbortSample>
        <Parallel/>
    </Sample:AbortSample>

    <Aggregate Id="SampleRepeater">

        <Sequence Repeat="NumberOfSamples"/>

        <Syslog Severity="Important">Sampling ESP cartridge type <Arg Name="CartridgeType"/><Units:count/></Syslog>

        <Science:ESPCartridgeSelect>
            <Sequence/>
            <Timeout Duration="P1M"/>
            <Setting><Science:ESPCartridgeSelect.cartridgeType/><Arg Name="CartridgeType"/></Setting>
        </Science:ESPCartridgeSelect>

        <ReadDatum Id="TriggerESP">
            <Science:ESPComponent.sampling/>
        </ReadDatum>

        <ReadDatum Id="WaitForESP">
            <Science:ESPComponent.sample_number/>
        </ReadDatum>

    </Aggregate>

</Mission>


2023-05-12T17:19:13.682Z,1683911953.682 [CommandExec](IMPORTANT): Loaded ./Missions/Maintenance/sample_lab.xml
2023-05-12T17:19:15.445Z,1683911955.445 [CommandExec](IMPORTANT): got command set sample_lab.CartridgeType -1 count
2023-05-12T17:19:15.446Z,1683911955.446 [CommandExec](IMPORTANT): got command run
2023-05-12T17:19:15.448Z,1683911955.448 [CommandExec](IMPORTANT): Running 
2023-05-12T17:19:15.573Z,1683911955.573 [Default] Stopped
2023-05-12T17:19:15.574Z,1683911955.574 [Default](DEBUG): Aggregate::uninitialize Default
2023-05-12T17:19:15.574Z,1683911955.574 [Default:B.GoToSurface] Stopped
2023-05-12T17:19:15.574Z,1683911955.574 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2023-05-12T17:19:15.574Z,1683911955.574 [Default:CheckIn] Stopped
2023-05-12T17:19:15.574Z,1683911955.574 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T17:19:15.574Z,1683911955.574 [Default:CheckIn:C.Wait] Stopped
2023-05-12T17:19:15.574Z,1683911955.574 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T17:19:15.574Z,1683911955.574 [MissionManager](IMPORTANT): Started mission sample_lab
2023-05-12T17:19:15.575Z,1683911955.575 [sample_lab] Running Loop=1
2023-05-12T17:19:15.575Z,1683911955.575 [sample_lab](DEBUG): Aggregate::initialize sample_lab
2023-05-12T17:19:15.575Z,1683911955.575 [sample_lab:A.AbortSample] Running Loop=1
2023-05-12T17:19:15.575Z,1683911955.575 [sample_lab:A.AbortSample](INFO): Initializing AbortSample.
2023-05-12T17:19:15.575Z,1683911955.575 [sample_lab:SampleRepeater] Running Loop=1
2023-05-12T17:19:15.575Z,1683911955.575 [sample_lab:SampleRepeater](DEBUG): Aggregate::initialize sample_lab:SampleRepeater
2023-05-12T17:19:15.575Z,1683911955.575 [sample_lab:SampleRepeater:A] Running Loop=1
2023-05-12T17:19:15.576Z,1683911955.576 [sample_lab:SampleRepeater:A](IMPORTANT): Sampling ESP cartridge type -1.000000 count 
2023-05-12T17:19:15.576Z,1683911955.576 [sample_lab:SampleRepeater:A] Stopped
2023-05-12T17:19:15.576Z,1683911955.576 [sample_lab:SampleRepeater:B.ESPCartridgeSelect] Running Loop=1
2023-05-12T17:19:15.576Z,1683911955.576 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Initializing ESPCartridgeSelect.
2023-05-12T17:19:15.577Z,1683911955.577 [sample_lab:A.AbortSample] Running Loop=1
2023-05-12T17:19:15.931Z,1683911955.931 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Issuing request for ESP cartridge type: -1.
2023-05-12T17:19:15.931Z,1683911955.931 [sample_lab:SampleRepeater:B.ESPCartridgeSelect] Stopped
2023-05-12T17:19:15.932Z,1683911955.932 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Uninitializing ESPCartridgeSelect.
2023-05-12T17:19:15.932Z,1683911955.932 [sample_lab:SampleRepeater:TriggerESP] Running Loop=1
2023-05-12T17:19:16.336Z,1683911956.336 [sample_lab:SampleRepeater:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling
2023-05-12T17:19:17.093Z,1683911957.093 [ESPComponent](IMPORTANT): Setting regex for ESP Log summary: 'Selecting Cartridge|Sampled|Error|Underpressure|Overpressure|Fail|Retry|Cmd::|Sampler::|summary:'
2023-05-12T17:19:17.096Z,1683911957.096 [ESPComponent](INFO): compiled regex: "Selecting Cartridge|Sampled|Error|Underpressure|Overpressure|Fail|Retry|Cmd::|Sampler::|summary:"
2023-05-12T17:19:17.097Z,1683911957.097 [ESPComponent](DEBUG): (612) Will wait for 10.0000 before power-up/connection sequence
2023-05-12T17:19:27.194Z,1683911967.194 [ESPComponent](DEBUG): (612) Done with wait. Will continue with general power-up/connection sequence
2023-05-12T17:19:27.196Z,1683911967.196 [ESPComponent](INFO): powering up ESP
2023-05-12T17:19:27.212Z,1683911967.212 [ESPComponent](INFO): powering up ESP secondary power supply
2023-05-12T17:19:27.228Z,1683911967.228 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 /dev/ttyTX1 linkname esp noauth local lock 115200 10.89.5.2:10.89.5.3 persist maxfail 0 holdoff 10 lcp-echo-interval 60 lcp-echo-failure 3 proxyarp ktune deflate 12 ms-dns 8.8.8.8
2023-05-12T17:19:27.364Z,1683911967.364 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=150.0000)
2023-05-12T17:19:28.405Z,1683911968.405 [ESPComponent](INFO): console:

2023-05-12T17:19:28.815Z,1683911968.815 [ESPComponent](INFO): console:NAND:  256 MiB
2023-05-12T17:19:29.214Z,1683911969.214 [ESPComponent](INFO): console:
BOOTMODE: SPI
2023-05-12T17:19:29.618Z,1683911969.618 [ESPComponent](INFO): console:
reading SPI NOR..Done
2023-05-12T17:19:30.021Z,1683911970.021 [ESPComponent](INFO): console:

2023-05-12T17:19:30.426Z,1683911970.426 [ESPComponent](INFO): console:

2023-05-12T17:19:30.830Z,1683911970.830 [ESPComponent](INFO): console:
U-Boot 2009.11-mbariD (Jun 28 2020 - 19:44:45)
2023-05-12T17:19:31.233Z,1683911971.233 [ESPComponent](INFO): console:

2023-05-12T17:19:31.638Z,1683911971.638 [ESPComponent](INFO): console:
MBARI LPC31xx ESP 3G
2023-05-12T17:19:32.042Z,1683911972.042 [ESPComponent](INFO): console:
flash params are already written into flash
2023-05-12T17:19:32.445Z,1683911972.445 [ESPComponent](INFO): console:
DRAM:  64 MB
2023-05-12T17:19:32.850Z,1683911972.850 [ESPComponent](INFO): console:
In:    serial
2023-05-12T17:19:33.253Z,1683911973.253 [ESPComponent](INFO): console:
Out:   serial
2023-05-12T17:19:33.658Z,1683911973.658 [ESPComponent](INFO): console:
Err:   serial
2023-05-12T17:19:34.062Z,1683911974.062 [ESPComponent](INFO): console:
Net:   ks8851_mll
2023-05-12T17:19:34.466Z,1683911974.466 [ESPComponent](INFO): console:
Hit <ctrl-C> to stop autoboot:  1  0 
2023-05-12T17:19:34.870Z,1683911974.870 [ESPComponent](INFO): console:
4096 KiB S25FL032P at 0:0 is now current device
2023-05-12T17:19:35.274Z,1683911975.274 [ESPComponent](INFO): console:
Loading kernel from SPI flash...done
2023-05-12T17:19:35.678Z,1683911975.678 [ESPComponent](INFO): console:
## Booting kernel from Legacy Image at 31000000 ...
2023-05-12T17:19:36.082Z,1683911976.082 [ESPComponent](INFO): console:
   Image Name:   Linux-3.18.140-lpc31-mbari4
2023-05-12T17:19:36.486Z,1683911976.486 [ESPComponent](INFO): console:
   Image Type:   ARM Linux Kernel Image (uncompressed)
2023-05-12T17:19:36.890Z,1683911976.890 [ESPComponent](INFO): console:
   Data Size:    2336368 Bytes =  2.2 MB
2023-05-12T17:19:37.293Z,1683911977.293 [ESPComponent](INFO): console:
   Load Address: 30008000
2023-05-12T17:19:37.698Z,1683911977.698 [ESPComponent](INFO): console:
   Entry Point:  30008000
2023-05-12T17:19:38.102Z,1683911978.102 [ESPComponent](INFO): console:
   Verifying Checksum ... OK
2023-05-12T17:19:38.505Z,1683911978.505 [ESPComponent](INFO): console:
   Loading Kernel Image ... OK
2023-05-12T17:19:38.910Z,1683911978.910 [ESPComponent](INFO): console:
OK
2023-05-12T17:19:39.313Z,1683911979.313 [ESPComponent](INFO): console:

2023-05-12T17:19:39.718Z,1683911979.718 [ESPComponent](INFO): console:
Starting kernel ...
2023-05-12T17:19:40.122Z,1683911980.122 [ESPComponent](INFO): console:

2023-05-12T17:19:40.526Z,1683911980.526 [ESPComponent](INFO): console:
Uncompressing Linux... Booting kernel...
2023-05-12T17:19:40.929Z,1683911980.929 [ESPComponent](INFO): console:
[    0.06] MBARI ESP 3G
2023-05-12T17:19:41.334Z,1683911981.334 [ESPComponent](INFO): console:

2023-05-12T17:19:41.738Z,1683911981.738 [ESPComponent](INFO): console:INIT: version 2.85 booting
2023-05-12T17:19:42.141Z,1683911982.141 [ESPComponent](INFO): console:

2023-05-12T17:19:42.547Z,1683911982.547 [ESPComponent](INFO): console:MBARI ESP Embedded Linux    http://www.mbari.org   mailto:brent@mbari.org
2023-05-12T17:19:42.949Z,1683911982.949 [ESPComponent](INFO): console:
ESPmv1
2023-05-12T17:19:43.353Z,1683911983.353 [ESPComponent](INFO): console:

2023-05-12T17:19:43.758Z,1683911983.758 [ESPComponent](INFO): console:INIT: Entering runlevel: 3
2023-05-12T17:19:44.161Z,1683911984.161 [ESPComponent](INFO): console:

2023-05-12T17:19:44.565Z,1683911984.565 [ESPComponent](INFO): console:Loading kernel modules
2023-05-12T17:19:44.970Z,1683911984.970 [ESPComponent](INFO): console:
Mounting filesystems and adding swapfiles listed in /etc/fstab
2023-05-12T17:19:45.376Z,1683911985.376 [ESPComponent](INFO): console:
[    4.25] EXT4-fs: Warning: mounting with data=journal disables delayed allocation and O_DIRECT support!
2023-05-12T17:19:45.777Z,1683911985.777 [ESPComponent](INFO): console:
Starting device events handler
2023-05-12T17:19:46.252Z,1683911986.252 [ESPComponent](INFO): console:

2023-05-12T17:19:49.818Z,1683911989.818 [ESPComponent](INFO): console:Set system clock to:  Fri May 12 10:19:39 PDT 2023
2023-05-12T17:19:50.222Z,1683911990.222 [ESPComponent](INFO): console:
Starting syslogd klogd...
2023-05-12T17:19:50.625Z,1683911990.625 [ESPComponent](INFO): console:
stopped syslogd (pid 679)
2023-05-12T17:19:51.030Z,1683911991.030 [ESPComponent](INFO): console:
Bringing up lo ...
2023-05-12T17:19:51.433Z,1683911991.433 [ESPComponent](INFO): console:
lo IP=127.0.0.1
2023-05-12T17:19:51.837Z,1683911991.837 [ESPComponent](INFO): console:
Packet forwarding enabled
2023-05-12T17:19:52.242Z,1683911992.242 [ESPComponent](INFO): console:
Bringing up platform ...
2023-05-12T17:19:52.716Z,1683911992.716 [ESPComponent](INFO): console:

2023-05-12T17:19:54.262Z,1683911994.262 [ESPComponent](INFO): console:[#] ip link add wg2shore type wireguard
2023-05-12T17:19:54.728Z,1683911994.728 [ESPComponent](INFO): console:

2023-05-12T17:19:57.090Z,1683911997.090 [ESPComponent](INFO): console:[#] wg setconf wg2shore /dev/fd/63
2023-05-12T17:19:57.494Z,1683911997.494 [ESPComponent](INFO): console:
[#] ip -4 address add 192.168.5.31 dev wg2shore
2023-05-12T17:19:57.898Z,1683911997.898 [ESPComponent](INFO): console:
[#] ip link set mtu 1376 up dev wg2shore
2023-05-12T17:19:58.302Z,1683911998.302 [ESPComponent](INFO): console:
[#] ip -4 route add 192.168.4.0/23 dev wg2shore
2023-05-12T17:19:58.705Z,1683911998.705 [ESPComponent](INFO): console:
Bringing up wg2shore ...
2023-05-12T17:19:59.109Z,1683911999.109 [ESPComponent](INFO): console:
Starting netplugd...
2023-05-12T17:19:59.514Z,1683911999.514 [ESPComponent](INFO): console:
Starting portmap...
2023-05-12T17:19:59.918Z,1683911999.918 [ESPComponent](INFO): console:
NTP sycn'd with ESPshore at Fri May 12 10:19:49 PDT 2023
2023-05-12T17:20:00.392Z,1683912000.392 [ESPComponent](INFO): console:

2023-05-12T17:20:01.938Z,1683912001.938 [ESPComponent](INFO): console:Starting chronyd...
2023-05-12T17:20:02.412Z,1683912002.412 [ESPComponent](INFO): console:

2023-05-12T17:20:03.150Z,1683912003.150 [ESPComponent](INFO): console:Starting darkhttpd...
2023-05-12T17:20:03.554Z,1683912003.554 [ESPComponent](INFO): console:
darkhttpd/1.14, copyright (c) 2003-2022 Emil Mikulic.
2023-05-12T17:20:03.957Z,1683912003.957 [ESPComponent](INFO): console:
listening on: http://0.0.0.0:80/
2023-05-12T17:20:04.362Z,1683912004.362 [ESPComponent](INFO): console:
set gid to 1
2023-05-12T17:20:04.765Z,1683912004.765 [ESPComponent](INFO): console:
set uid to 65534
2023-05-12T17:20:05.169Z,1683912005.169 [ESPComponent](INFO): console:
Starting dnsmasq...
2023-05-12T17:20:05.644Z,1683912005.644 [ESPComponent](INFO): console:

2023-05-12T17:20:09.210Z,1683912009.210 [ESPComponent](INFO): console:

2023-05-12T17:20:09.614Z,1683912009.614 [ESPComponent](INFO): console:
MBARI ESP Embedded Linux 2.81 -- 3/22/23 brent@mbari.org
2023-05-12T17:20:10.017Z,1683912010.017 [ESPComponent](INFO): console:

2023-05-12T17:20:10.493Z,1683912010.493 [ESPComponent](INFO): console:ESPmv1 login: 
2023-05-12T17:20:20.129Z,1683912020.129 [ESPComponent](IMPORTANT): ESP has connected as client
2023-05-12T17:20:20.938Z,1683912020.938 [ESPComponent](IMPORTANT): [sample #1] Setting cartridge argument to -1
2023-05-12T17:20:20.939Z,1683912020.939 [ESPComponent](IMPORTANT): [sample #1] ESP sampling sequence starting. Sampling state: S_WAITING_INITIAL_PROMPT
2023-05-12T17:20:20.939Z,1683912020.939 [ESPComponent](DEBUG): Writing samplingActive=1, sampleNumber=1
2023-05-12T17:20:21.034Z,1683912021.034 [sample_lab:SampleRepeater:TriggerESP] Stopped
2023-05-12T17:20:21.035Z,1683912021.035 [sample_lab:SampleRepeater:WaitForESP] Running Loop=1
2023-05-12T17:20:21.388Z,1683912021.388 [sample_lab:SampleRepeater:WaitForESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sample_number
2023-05-12T17:20:22.147Z,1683912022.147 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_LOG
2023-05-12T17:20:22.550Z,1683912022.550 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_STATUS
2023-05-12T17:20:24.165Z,1683912024.165 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_LOADING_CARTRIDGE
2023-05-12T17:20:27.419Z,1683912027.419 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T17:20:27.419Z,1683912027.419 [DVL_micro](ERROR): Failed to parse:
:TS,00000
2023-05-12T17:20:56.081Z,1683912056.081 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PRIMING (@60,aRNAl_bac)
2023-05-12T17:20:58.910Z,1683912058.910 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PRIMING (@100.0)
2023-05-12T17:20:58.911Z,1683912058.911 [ESPComponent](IMPORTANT): Filtering timeoutMinutes=92.070000 issuedCmd_=Cmd.startFiltering
2023-05-12T17:20:59.313Z,1683912059.313 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_FILTERING (@100.0)
2023-05-12T17:23:52.226Z,1683912232.226 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_FILTERING (@0.0)
2023-05-12T17:23:52.641Z,1683912232.641 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PAUSED (@0.0)
2023-05-12T17:24:03.154Z,1683912243.154 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T17:24:03.154Z,1683912243.154 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.999,+9999.99,+9999.99
2023-05-12T17:25:31.642Z,1683912331.642 [DVL_micro](ERROR): Failed to parse:
:SA,-03.52,+08.78,185.7
2023-05-12T17:27:51.458Z,1683912471.458 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.00,+00000000.00,9999.99,000.00
2023-05-12T17:30:46.416Z,1683912646.416 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T17:30:46.416Z,1683912646.416 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,.7,0000.0,1489.0,000
2023-05-12T17:31:45.805Z,1683912705.805 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2023-05-12T17:31:45.825Z,1683912705.825 [BPC1](INFO): Received data from all battery sticks.
2023-05-12T17:31:47.027Z,1683912707.027 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T17:31:47.028Z,1683912707.028 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+210,1489.0,000
2023-05-12T17:37:27.189Z,1683913047.189 [DVL_micro](ERROR): Failed to parse:
:SA,-03.55,+08.71,185.7
2023-05-12T17:43:09.378Z,1683913389.378 [DVL_micro](ERROR): DVL BIT error. See manual. Result code: 182
2023-05-12T17:43:09.387Z,1683913389.387 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.00,+00000000.00,9999.99,000.00
2023-05-12T17:44:20.482Z,1683913460.482 [DVL_micro](ERROR): Failed to parse:
:WI,-00052,+00269,-00347,+00000,A
2023-05-12T17:46:14.821Z,1683913574.821 [DVL_micro](ERROR): Failed to parse:99.99,+9999..99,+9999.99
2023-05-12T17:47:58.651Z,1683913678.651 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T17:47:58.651Z,1683913678.651 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+21.8,0000.0000
2023-05-12T17:49:27.147Z,1683913767.147 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.00,+00000000.00,9999.99,000.00
2023-05-12T17:52:11.970Z,1683913931.970 [DVL_micro](ERROR): only read 2 of 4 data items
2023-05-12T17:52:11.970Z,1683913931.970 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,,+9999.99
2023-05-12T17:52:35.002Z,1683913955.002 [DVL_micro](ERROR): Failed to parse:
:R99,+99999.99,+9999.99
2023-05-12T17:55:47.698Z,1683914147.698 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T17:55:47.698Z,1683914147.698 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+21.9,0000.0000
2023-05-12T17:56:02.667Z,1683914162.667 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T17:56:02.667Z,1683914162.667 [DVL_micro](ERROR): Failed to parse:
:BI,-0017,-00258,+00000,I
2023-05-12T17:59:30.727Z,1683914370.727 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T17:59:30.728Z,1683914370.728 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000,+22.0,0000.0,1489.0,000
2023-05-12T18:00:44.274Z,1683914444.274 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PAUSED (@1000.0)
2023-05-12T18:00:44.275Z,1683914444.275 [ESPComponent](DEBUG): Writing sampleVolume=1000.000000
2023-05-12T18:00:44.678Z,1683914444.678 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PROCESSING (@1000.0)
2023-05-12T18:00:46.702Z,1683914446.702 [ESPComponent](IMPORTANT): Processing timeoutMinutes=30.000000 issuedCmd_=Cmd.startProcessing
2023-05-12T18:00:47.103Z,1683914447.103 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PROCESSED (@60,aRNAl_bac)
2023-05-12T18:02:18.021Z,1683914538.021 [DVL_micro](ERROR): Failed to parse:
:WI,+00070,+00173,-00242,+00000,A
2023-05-12T18:02:22.041Z,1683914542.041 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_STOPPING (@60,aRNAl_bac)
2023-05-12T18:02:29.719Z,1683914549.719 [ESPComponent](IMPORTANT): Syncing ESP logs with command: rsync -azPq --timeout=60 esp@esp:'/var/log/esp/real /var/log/esp/real.out /var/log/esp/real.slot /var/log/esp/*.spr*' /LRAUV/ESPlogs &
2023-05-12T18:02:29.752Z,1683914549.752 [ESPComponent](INFO): closing pipe.
2023-05-12T18:02:30.123Z,1683914550.123 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_STOPPED
2023-05-12T18:05:00.056Z,1683914700.056 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.00,+00000000.00,9999.99,000.00
2023-05-12T18:05:40.449Z,1683914740.449 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T18:05:40.449Z,1683914740.449 [DVL_micro](ERROR): Failed to parse:
:BI,+00032,-00026,-00241,+00BD,+00000000.00,+00000000.00,+00000000.00,9999.99,000.00999.99,+9999.99,+9999.99,+9999.99
2023-05-12T18:07:29.889Z,1683914849.889 [ESPComponent](IMPORTANT): [sample #1] ESP sampling sequence completed normally.
2023-05-12T18:07:29.889Z,1683914849.889 [ESPComponent](DEBUG): Writing samplingActive=1, sampleNumber=1
2023-05-12T18:07:29.922Z,1683914849.922 [sample_lab:SampleRepeater:WaitForESP] Stopped
2023-05-12T18:07:29.923Z,1683914849.923 [sample_lab:SampleRepeater](INFO): Completed sample_lab:SampleRepeater
2023-05-12T18:07:29.923Z,1683914849.923 [sample_lab:SampleRepeater] Stopped
2023-05-12T18:07:29.923Z,1683914849.923 [sample_lab:SampleRepeater](DEBUG): Aggregate::uninitialize sample_lab:SampleRepeater
2023-05-12T18:07:29.924Z,1683914849.924 [sample_lab](INFO): Completed sample_lab
2023-05-12T18:07:29.924Z,1683914849.924 [MissionManager](INFO): sample_lab is completed.
2023-05-12T18:07:29.924Z,1683914849.924 [MissionManager](INFO): Uninitializing Mission sample_lab
2023-05-12T18:07:29.924Z,1683914849.924 [sample_lab] Stopped
2023-05-12T18:07:29.924Z,1683914849.924 [sample_lab](DEBUG): Aggregate::uninitialize sample_lab
2023-05-12T18:07:29.924Z,1683914849.924 [sample_lab:A.AbortSample] Stopped
2023-05-12T18:07:29.924Z,1683914849.924 [sample_lab:A.AbortSample](INFO): Uninitializing AbortSample.
2023-05-12T18:07:30.294Z,1683914850.294 [ESPComponent](IMPORTANT): [sample #1] ESP log summary report (2 messages):
@10:20:23.91 Selecting Cartridge 60
@11:00:32.74 Sampled  1000.0ml

2023-05-12T18:07:30.294Z,1683914850.294 [ESPComponent](INFO): powering down ESP
2023-05-12T18:07:30.295Z,1683914850.295 [ESPComponent](INFO): powering down ESP secondary power supply
2023-05-12T18:07:30.486Z,1683914850.486 [MissionManager](IMPORTANT): Started mission Default
2023-05-12T18:07:30.486Z,1683914850.486 [Default] Running Loop=1
2023-05-12T18:07:30.486Z,1683914850.486 [Default](DEBUG): Aggregate::initialize Default
2023-05-12T18:07:30.486Z,1683914850.486 [Default:B.GoToSurface] Running Loop=1
2023-05-12T18:07:30.486Z,1683914850.486 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2023-05-12T18:07:30.487Z,1683914850.487 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2023-05-12T18:07:30.487Z,1683914850.487 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2023-05-12T18:07:30.487Z,1683914850.487 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2023-05-12T18:07:30.488Z,1683914850.488 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2023-05-12T18:07:30.488Z,1683914850.488 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2023-05-12T18:07:30.489Z,1683914850.489 [Default:A.Wait] Running Loop=1
2023-05-12T18:07:30.489Z,1683914850.489 [Default:A.Wait](DEBUG): Initialize Wait Component.
2023-05-12T18:07:43.660Z,1683914863.660 [Default:A.Wait](INFO): Done Waiting.
2023-05-12T18:07:43.660Z,1683914863.660 [Default:A.Wait] Stopped
2023-05-12T18:07:43.660Z,1683914863.660 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T18:07:44.054Z,1683914864.054 [Default:CheckIn] Running Loop=1
2023-05-12T18:07:44.054Z,1683914864.054 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T18:07:44.054Z,1683914864.054 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T18:07:45.664Z,1683914865.664 [NAL9602](FAULT): GPS failed to acquire within timeout.
2023-05-12T18:07:45.664Z,1683914865.664 [NAL9602] Data Fault, FailCount= 1
2023-05-12T18:07:45.664Z,1683914865.664 [NAL9602](ERROR): Data Fault
2023-05-12T18:07:45.728Z,1683914865.728 [CBIT](ERROR): Data Fault in component: NAL9602
2023-05-12T18:07:46.070Z,1683914866.070 [NAL9602](INFO): Powering down
2023-05-12T18:07:46.900Z,1683914866.900 [CBIT](INFO): Clearing failed state for component NAL9602
2023-05-12T18:07:46.900Z,1683914866.900 [NAL9602] No Fault, FailCount= 1
2023-05-12T18:08:16.367Z,1683914896.367 [NAL9602](INFO): Powering up NAL9602
2023-05-12T18:08:27.272Z,1683914907.272 [NAL9602](INFO): NAL9602 initialized
2023-05-12T18:09:03.233Z,1683914943.233 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T18:09:03.233Z,1683914943.233 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+22.1,0000.0000
2023-05-12T18:09:18.601Z,1683914958.601 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T18:09:18.601Z,1683914958.601 [DVL_micro](ERROR): Failed to parse:
:BI,+0021,-00207,+00000,I
2023-05-12T18:12:38.577Z,1683915158.577 [DVL_micro](ERROR): Failed to parse:
:SA,-03.60,+08.76,185.5
2023-05-12T18:12:44.251Z,1683915164.251 [Default:CheckIn:Read_GPS](INFO): Timed out from 2023-05-12T18:07:44.1Z
2023-05-12T18:12:44.251Z,1683915164.251 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T18:12:44.251Z,1683915164.251 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T18:12:51.567Z,1683915171.567 [DataOverHttps](INFO): Sending 190 bytes from file Logs/20230512T161716/Courier0022.lzma
2023-05-12T18:12:52.570Z,1683915172.570 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0022.lzma.bak
2023-05-12T18:12:52.570Z,1683915172.570 [DataOverHttps](INFO): SBD MOMSN=18297808
2023-05-12T18:13:07.653Z,1683915187.653 [DataOverHttps](INFO): Sending 1382 bytes from file Logs/20230512T161716/Express0023.lzma
2023-05-12T18:13:08.654Z,1683915188.654 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0023.lzma.bak
2023-05-12T18:13:08.654Z,1683915188.654 [DataOverHttps](INFO): SBD MOMSN=18297811
2023-05-12T18:13:24.691Z,1683915204.691 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20230512T161716/Express0026.lzma
2023-05-12T18:13:25.694Z,1683915205.694 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0026.lzma.bak
2023-05-12T18:13:25.694Z,1683915205.694 [DataOverHttps](INFO): SBD MOMSN=18297853
2023-05-12T18:13:27.469Z,1683915207.469 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T18:13:27.470Z,1683915207.470 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T18:13:27.470Z,1683915207.470 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T18:13:31.094Z,1683915211.094 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-12T18:14:01.803Z,1683915241.803 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-12T18:15:58.556Z,1683915358.556 [DVL_micro](ERROR): Failed to parse:026,-00180,-00272,+00000,I
2023-05-12T18:18:28.075Z,1683915508.075 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-12T18:18:28.075Z,1683915508.075 [Default:CheckIn:C.Wait] Stopped
2023-05-12T18:18:28.075Z,1683915508.075 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T18:18:28.075Z,1683915508.075 [Default:CheckIn:D] Running Loop=1
2023-05-12T18:18:28.542Z,1683915508.542 [Default:CheckIn:D] Stopped
2023-05-12T18:18:28.542Z,1683915508.542 [Default:CheckIn:E] Running Loop=1
2023-05-12T18:18:28.861Z,1683915508.861 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 10.967601 min 
2023-05-12T18:18:28.861Z,1683915508.861 [Default:CheckIn:E] Stopped
2023-05-12T18:18:28.861Z,1683915508.861 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-12T18:18:28.862Z,1683915508.862 [Default:CheckIn] Stopped
2023-05-12T18:18:28.862Z,1683915508.862 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T18:18:28.862Z,1683915508.862 [Default:CheckIn](INFO): Running loop #2
2023-05-12T18:18:28.862Z,1683915508.862 [Default:CheckIn] Running Loop=2
2023-05-12T18:18:28.862Z,1683915508.862 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T18:18:28.862Z,1683915508.862 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T18:18:30.495Z,1683915510.495 [NAL9602](FAULT): GPS failed to acquire within timeout.
2023-05-12T18:18:30.495Z,1683915510.495 [NAL9602] Data Fault, FailCount= 2
2023-05-12T18:18:30.495Z,1683915510.495 [NAL9602](ERROR): Data Fault
2023-05-12T18:18:30.551Z,1683915510.551 [CBIT](ERROR): Data Fault in component: NAL9602
2023-05-12T18:18:30.869Z,1683915510.869 [NAL9602](INFO): Powering down
2023-05-12T18:18:31.695Z,1683915511.695 [CBIT](INFO): Clearing failed state for component NAL9602
2023-05-12T18:18:31.695Z,1683915511.695 [NAL9602] No Fault, FailCount= 2
2023-05-12T18:18:49.895Z,1683915529.895 [CBIT](IMPORTANT): Beginning ground fault scan
2023-05-12T18:19:00.799Z,1683915540.799 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.012339
CHAN A1 (24V): 0.001112
CHAN A2 (12V): -0.005499
CHAN A3 (5V): -0.002910
CHAN B0 (3.3V): -0.000979
CHAN B1 (3.15aV): -0.000775
CHAN B2 (3.15bV): -0.000982
CHAN B3 (GND): -0.000342
OPEN: 0.002563
Full Scale: +/- 1 mA
2023-05-12T18:19:01.175Z,1683915541.175 [NAL9602](INFO): Powering up NAL9602
2023-05-12T18:19:12.084Z,1683915552.084 [NAL9602](INFO): NAL9602 initialized
2023-05-12T18:19:28.647Z,1683915568.647 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T18:19:28.647Z,1683915568.647 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,+9999.99,
2023-05-12T18:20:36.965Z,1683915636.965 [DVL_micro](ERROR): only read 2 of 4 data items
2023-05-12T18:20:36.965Z,1683915636.965 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,+
2023-05-12T18:22:03.010Z,1683915723.010 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T18:22:03.010Z,1683915723.010 [DVL_micro](ERROR): Failed to parse:
:BI,-00156,-00145,-0000,I
2023-05-12T18:23:29.094Z,1683915809.094 [Default:CheckIn:Read_GPS](INFO): Timed out from 2023-05-12T18:18:28.9Z
2023-05-12T18:23:29.095Z,1683915809.095 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T18:23:29.095Z,1683915809.095 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T18:23:36.723Z,1683915816.723 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20230512T161716/Courier0028.lzma
2023-05-12T18:23:37.726Z,1683915817.726 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0028.lzma.bak
2023-05-12T18:23:37.726Z,1683915817.726 [DataOverHttps](INFO): SBD MOMSN=18297943
2023-05-12T18:23:53.680Z,1683915833.680 [DataOverHttps](INFO): Sending 394 bytes from file Logs/20230512T161716/Express0029.lzma
2023-05-12T18:23:54.682Z,1683915834.682 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0029.lzma.bak
2023-05-12T18:23:54.682Z,1683915834.682 [DataOverHttps](INFO): SBD MOMSN=18297945
2023-05-12T18:23:56.507Z,1683915836.507 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T18:23:56.507Z,1683915836.507 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T18:23:56.508Z,1683915836.508 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T18:24:15.893Z,1683915855.893 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-12T18:24:46.593Z,1683915886.593 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-12T18:26:51.838Z,1683916011.838 [DVL_micro](ERROR): only read 2 of 4 data items
2023-05-12T18:26:51.838Z,1683916011.838 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,++9999.99
2023-05-12T18:26:56.688Z,1683916016.688 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T18:26:56.688Z,1683916016.688 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+22.2,0000.0,1489:WI,-00017,+00137,-00197,+00BI,-00017,+00137,-00197,+00000,I
2023-05-12T18:26:59.102Z,1683916019.102 [DVL_micro](ERROR): No DVL communication! Re-initializing
2023-05-12T18:26:59.103Z,1683916019.103 [DVL_micro] Communications Fault, FailCount= 1
2023-05-12T18:26:59.103Z,1683916019.103 [DVL_micro](ERROR): Communications Fault
2023-05-12T18:26:59.122Z,1683916019.122 [CBIT](ERROR): Communications Fault in component: DVL_micro
2023-05-12T18:26:59.572Z,1683916019.572 [DVL_micro](INFO): Powering down
2023-05-12T18:27:00.335Z,1683916020.335 [CBIT](INFO): Clearing failed state for component DVL_micro
2023-05-12T18:27:00.335Z,1683916020.335 [DVL_micro] No Fault, FailCount= 1
2023-05-12T18:28:57.104Z,1683916137.104 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-12T18:28:57.104Z,1683916137.104 [Default:CheckIn:C.Wait] Stopped
2023-05-12T18:28:57.104Z,1683916137.104 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T18:28:57.105Z,1683916137.105 [Default:CheckIn:D] Running Loop=1
2023-05-12T18:28:57.491Z,1683916137.491 [Default:CheckIn:D] Stopped
2023-05-12T18:28:57.491Z,1683916137.491 [Default:CheckIn:E] Running Loop=1
2023-05-12T18:28:57.891Z,1683916137.891 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 21.450083 min 
2023-05-12T18:28:57.891Z,1683916137.891 [Default:CheckIn:E] Stopped
2023-05-12T18:28:57.892Z,1683916137.892 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-12T18:28:57.892Z,1683916137.892 [Default:CheckIn] Stopped
2023-05-12T18:28:57.892Z,1683916137.892 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T18:28:57.892Z,1683916137.892 [Default:CheckIn](INFO): Running loop #3
2023-05-12T18:28:57.892Z,1683916137.892 [Default:CheckIn] Running Loop=3
2023-05-12T18:28:57.892Z,1683916137.892 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T18:28:57.892Z,1683916137.892 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T18:29:30.617Z,1683916170.617 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2023-05-12T18:29:30.700Z,1683916170.700 [NAL9602](ERROR): received: 
+CSQ:0

OK
2023-05-12T18:30:33.231Z,1683916233.231 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T18:30:33.231Z,1683916233.231 [DVL_micro](ERROR): Failed to parse:
:TS,000000005.0000.0,1489.0,000
2023-05-12T18:32:24.330Z,1683916344.330 [DVL_micro](ERROR): Failed to parse:
:WI,+00040,+00038,-00173,+00000,A
2023-05-12T18:33:58.137Z,1683916438.137 [Default:CheckIn:Read_GPS](INFO): Timed out from 2023-05-12T18:28:57.9Z
2023-05-12T18:33:58.137Z,1683916438.137 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T18:33:58.138Z,1683916438.138 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T18:34:01.741Z,1683916441.741 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-12T18:34:06.055Z,1683916446.055 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20230512T161716/Courier0031.lzma
2023-05-12T18:34:07.058Z,1683916447.058 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0031.lzma.bak
2023-05-12T18:34:07.059Z,1683916447.059 [DataOverHttps](INFO): SBD MOMSN=18297979
2023-05-12T18:34:23.655Z,1683916463.655 [DataOverHttps](INFO): Sending 204 bytes from file Logs/20230512T161716/Express0032.lzma
2023-05-12T18:34:24.658Z,1683916464.658 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0032.lzma.bak
2023-05-12T18:34:24.658Z,1683916464.658 [DataOverHttps](INFO): SBD MOMSN=18297981
2023-05-12T18:34:26.371Z,1683916466.371 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T18:34:26.371Z,1683916466.371 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T18:34:26.371Z,1683916466.371 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T18:34:32.416Z,1683916472.416 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-12T18:39:26.979Z,1683916766.979 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-12T18:39:26.979Z,1683916766.979 [Default:CheckIn:C.Wait] Stopped
2023-05-12T18:39:26.979Z,1683916766.979 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T18:39:26.979Z,1683916766.979 [Default:CheckIn:D] Running Loop=1
2023-05-12T18:39:27.389Z,1683916767.389 [Default:CheckIn:D] Stopped
2023-05-12T18:39:27.389Z,1683916767.389 [Default:CheckIn:E] Running Loop=1
2023-05-12T18:39:27.770Z,1683916767.770 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2023-05-12T18:39:27.773Z,1683916767.773 [BPC1](INFO): Received data from all battery sticks.
2023-05-12T18:39:27.818Z,1683916767.818 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 31.948385 min 
2023-05-12T18:39:27.818Z,1683916767.818 [Default:CheckIn:E] Stopped
2023-05-12T18:39:27.818Z,1683916767.818 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-12T18:39:27.818Z,1683916767.818 [Default:CheckIn] Stopped
2023-05-12T18:39:27.818Z,1683916767.818 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T18:39:27.818Z,1683916767.818 [Default:CheckIn](INFO): Running loop #4
2023-05-12T18:39:27.818Z,1683916767.818 [Default:CheckIn] Running Loop=4
2023-05-12T18:39:27.818Z,1683916767.818 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T18:39:27.819Z,1683916767.819 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T18:39:29.404Z,1683916769.404 [NAL9602](FAULT): GPS failed to acquire within timeout.
2023-05-12T18:39:29.404Z,1683916769.404 [NAL9602] Data Fault, FailCount= 3
2023-05-12T18:39:29.404Z,1683916769.404 [NAL9602](ERROR): Data Fault
2023-05-12T18:39:29.424Z,1683916769.424 [CBIT](ERROR): Data Fault in component: NAL9602
2023-05-12T18:39:29.783Z,1683916769.783 [NAL9602](INFO): Powering down
2023-05-12T18:39:30.613Z,1683916770.613 [CBIT](INFO): Clearing failed state for component NAL9602
2023-05-12T18:39:30.613Z,1683916770.613 [NAL9602] No Fault, FailCount= 3
2023-05-12T18:40:00.084Z,1683916800.084 [NAL9602](INFO): Powering up NAL9602
2023-05-12T18:40:10.988Z,1683916810.988 [NAL9602](INFO): NAL9602 initialized
2023-05-12T18:40:22.324Z,1683916822.324 [DVL_micro](ERROR): Failed to parse:
:SA,-03.63,+08.67,185.5
2023-05-12T18:41:07.959Z,1683916867.959 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T18:41:07.960Z,1683916867.960 [DVL_micro](ERROR): Failed to parse:
:TS,000000000.0,+22.5,0000.0,1489.0,000
2023-05-12T18:44:27.967Z,1683917067.967 [Default:CheckIn:Read_GPS](INFO): Timed out from 2023-05-12T18:39:27.8Z
2023-05-12T18:44:27.967Z,1683917067.967 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T18:44:27.967Z,1683917067.967 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T18:44:34.923Z,1683917074.923 [DataOverHttps](INFO): Sending 50 bytes from file Logs/20230512T161716/Courier0034.lzma
2023-05-12T18:44:35.926Z,1683917075.926 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0034.lzma.bak
2023-05-12T18:44:35.926Z,1683917075.926 [DataOverHttps](INFO): SBD MOMSN=18298094
2023-05-12T18:44:37.657Z,1683917077.657 [DVL_micro](ERROR): Failed to parse:
9.99,+9999.99,+9999.99,+9999.99
2023-05-12T18:44:51.954Z,1683917091.954 [DataOverHttps](INFO): Sending 224 bytes from file Logs/20230512T161716/Express0035.lzma
2023-05-12T18:44:52.954Z,1683917092.954 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0035.lzma.bak
2023-05-12T18:44:52.954Z,1683917092.954 [DataOverHttps](INFO): SBD MOMSN=18298099
2023-05-12T18:44:54.654Z,1683917094.654 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T18:44:54.654Z,1683917094.654 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T18:44:54.654Z,1683917094.654 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T18:45:14.844Z,1683917114.844 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-12T18:45:45.539Z,1683917145.539 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-12T18:49:55.223Z,1683917395.223 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-12T18:49:55.223Z,1683917395.223 [Default:CheckIn:C.Wait] Stopped
2023-05-12T18:49:55.223Z,1683917395.223 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T18:49:55.224Z,1683917395.224 [Default:CheckIn:D] Running Loop=1
2023-05-12T18:49:55.647Z,1683917395.647 [Default:CheckIn:D] Stopped
2023-05-12T18:49:55.647Z,1683917395.647 [Default:CheckIn:E] Running Loop=1
2023-05-12T18:49:56.029Z,1683917396.029 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 42.419352 min 
2023-05-12T18:49:56.029Z,1683917396.029 [Default:CheckIn:E] Stopped
2023-05-12T18:49:56.030Z,1683917396.030 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-12T18:49:56.030Z,1683917396.030 [Default:CheckIn] Stopped
2023-05-12T18:49:56.030Z,1683917396.030 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T18:49:56.030Z,1683917396.030 [Default:CheckIn](INFO): Running loop #5
2023-05-12T18:49:56.030Z,1683917396.030 [Default:CheckIn] Running Loop=5
2023-05-12T18:49:56.030Z,1683917396.030 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T18:49:56.030Z,1683917396.030 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T18:50:28.746Z,1683917428.746 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2023-05-12T18:50:28.820Z,1683917428.820 [NAL9602](ERROR): received: 
+CSQ:0

OK
2023-05-12T18:50:43.700Z,1683917443.700 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T18:50:43.700Z,1683917443.700 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000,+22.7,0000.0,1489.0,000
2023-05-12T18:52:21.870Z,1683917541.870 [DVL_micro](ERROR): Failed to parse:
:4,-00177,-00110,+00000,I
2023-05-12T18:54:30.745Z,1683917670.745 [DVL_micro](ERROR): Failed to parse:
:WI,-00032,+00158,-00081,+00000,A
2023-05-12T18:54:56.214Z,1683917696.214 [Default:CheckIn:Read_GPS](INFO): Timed out from 2023-05-12T18:49:56.0Z
2023-05-12T18:54:56.214Z,1683917696.214 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T18:54:56.215Z,1683917696.215 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T18:55:04.271Z,1683917704.271 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20230512T161716/Courier0037.lzma
2023-05-12T18:55:05.274Z,1683917705.274 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0037.lzma.bak
2023-05-12T18:55:05.274Z,1683917705.274 [DataOverHttps](INFO): SBD MOMSN=18298344
2023-05-12T18:55:05.899Z,1683917705.899 [NAL9602](INFO): SBD MO Status=2, MOMSN=3656, MT Status=2, MTMSN=0
2023-05-12T18:55:05.899Z,1683917705.899 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-12T18:55:06.330Z,1683917706.330 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-12T18:55:21.159Z,1683917721.159 [DataOverHttps](INFO): Sending 204 bytes from file Logs/20230512T161716/Express0038.lzma
2023-05-12T18:55:22.162Z,1683917722.162 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0038.lzma.bak
2023-05-12T18:55:22.162Z,1683917722.162 [DataOverHttps](INFO): SBD MOMSN=18298822
2023-05-12T18:55:23.693Z,1683917723.693 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T18:55:23.693Z,1683917723.693 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T18:55:23.693Z,1683917723.693 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T18:55:36.000Z,1683917737.000 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-12T18:59:43.461Z,1683917983.461 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T18:59:43.461Z,1683917983.461 [DVL_micro](ERROR): Failed to parse:
:BI,+00020,+0089,+00000,I
2023-05-12T19:00:16.191Z,1683918016.191 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T19:00:16.191Z,1683918016.191 [DVL_micro](ERROR): Failed to parse:
:BI,-0032,-00135,+00000,I
2023-05-12T19:00:24.297Z,1683918024.297 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-12T19:00:24.297Z,1683918024.297 [Default:CheckIn:C.Wait] Stopped
2023-05-12T19:00:24.297Z,1683918024.297 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T19:00:24.297Z,1683918024.297 [Default:CheckIn:D] Running Loop=1
2023-05-12T19:00:24.681Z,1683918024.681 [Default:CheckIn:D] Stopped
2023-05-12T19:00:24.681Z,1683918024.681 [Default:CheckIn:E] Running Loop=1
2023-05-12T19:00:25.080Z,1683918025.080 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 52.903251 min 
2023-05-12T19:00:25.080Z,1683918025.080 [Default:CheckIn:E] Stopped
2023-05-12T19:00:25.080Z,1683918025.080 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-12T19:00:25.080Z,1683918025.080 [Default:CheckIn] Stopped
2023-05-12T19:00:25.081Z,1683918025.081 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T19:00:25.081Z,1683918025.081 [Default:CheckIn](INFO): Running loop #6
2023-05-12T19:00:25.081Z,1683918025.081 [Default:CheckIn] Running Loop=6
2023-05-12T19:00:25.081Z,1683918025.081 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T19:00:25.081Z,1683918025.081 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T19:00:26.683Z,1683918026.683 [NAL9602](FAULT): GPS failed to acquire within timeout.
2023-05-12T19:00:26.683Z,1683918026.683 [NAL9602] Data Fault, FailCount= 4
2023-05-12T19:00:26.683Z,1683918026.683 [NAL9602](ERROR): Data Fault
2023-05-12T19:00:26.702Z,1683918026.702 [CBIT](ERROR): Data Fault in component: NAL9602
2023-05-12T19:00:27.085Z,1683918027.085 [NAL9602](INFO): Powering down
2023-05-12T19:00:27.961Z,1683918027.961 [CBIT](INFO): Clearing failed state for component NAL9602
2023-05-12T19:00:27.961Z,1683918027.961 [NAL9602] No Fault, FailCount= 4
2023-05-12T19:00:57.385Z,1683918057.385 [NAL9602](INFO): Powering up NAL9602
2023-05-12T19:01:08.303Z,1683918068.303 [NAL9602](INFO): NAL9602 initialized
2023-05-12T19:02:19.809Z,1683918139.809 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T19:02:19.809Z,1683918139.809 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,+9999..99
2023-05-12T19:04:18.581Z,1683918258.581 [NAL9602](INFO): SBD MO Status=2, MOMSN=3656, MT Status=2, MTMSN=0
2023-05-12T19:04:18.582Z,1683918258.582 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-12T19:04:36.783Z,1683918276.783 [NAL9602](INFO): SBD MO Status=2, MOMSN=3656, MT Status=2, MTMSN=0
2023-05-12T19:04:36.783Z,1683918276.783 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-12T19:05:01.019Z,1683918301.019 [DVL_micro](ERROR): only read 2 of 4 data items
2023-05-12T19:05:01.019Z,1683918301.019 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.999,+9999.99,
2023-05-12T19:05:11.133Z,1683918311.133 [NAL9602](INFO): SBD MO Status=2, MOMSN=3656, MT Status=2, MTMSN=0
2023-05-12T19:05:11.133Z,1683918311.133 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-12T19:05:25.289Z,1683918325.289 [Default:CheckIn:Read_GPS](INFO): Timed out from 2023-05-12T19:00:25.1Z
2023-05-12T19:05:25.289Z,1683918325.289 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T19:05:25.290Z,1683918325.290 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T19:05:26.552Z,1683918326.552 [DVL_micro](ERROR): DVL uart error: serial timeout
2023-05-12T19:05:26.552Z,1683918326.552 [DVL_micro] Communications Fault, FailCount= 1
2023-05-12T19:05:26.552Z,1683918326.552 [DVL_micro](ERROR): Communications Fault
2023-05-12T19:05:26.552Z,1683918326.552 [DVL_micro](ERROR): Failed to parse:
2023-05-12T19:05:26.622Z,1683918326.622 [CBIT](ERROR): Communications Fault in component: DVL_micro
2023-05-12T19:05:26.940Z,1683918326.940 [DVL_micro](INFO): Powering down
2023-05-12T19:05:27.702Z,1683918327.702 [CBIT](INFO): Clearing failed state for component DVL_micro
2023-05-12T19:05:27.702Z,1683918327.702 [DVL_micro] No Fault, FailCount= 1
2023-05-12T19:05:32.807Z,1683918332.807 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20230512T161716/Courier0040.lzma
2023-05-12T19:05:33.811Z,1683918333.811 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0040.lzma.bak
2023-05-12T19:05:33.811Z,1683918333.811 [DataOverHttps](INFO): SBD MOMSN=18300425
2023-05-12T19:05:50.028Z,1683918350.028 [DataOverHttps](INFO): Sending 224 bytes from file Logs/20230512T161716/Express0041.lzma
2023-05-12T19:05:51.030Z,1683918351.030 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0041.lzma.bak
2023-05-12T19:05:51.030Z,1683918351.030 [DataOverHttps](INFO): SBD MOMSN=18300427
2023-05-12T19:05:52.739Z,1683918352.739 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T19:05:52.739Z,1683918352.739 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T19:05:52.739Z,1683918352.739 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T19:05:53.139Z,1683918353.139 [DVL_micro](ERROR): Failed to parse:
:WI,+00053,+00042,-00068,+00000,A
2023-05-12T19:06:12.117Z,1683918372.117 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-12T19:06:42.827Z,1683918402.827 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-12T19:06:46.061Z,1683918406.061 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.00,+00000000.00,9999.99,000.00
2023-05-12T19:10:53.399Z,1683918653.399 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-12T19:10:53.399Z,1683918653.399 [Default:CheckIn:C.Wait] Stopped
2023-05-12T19:10:53.399Z,1683918653.399 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T19:10:53.399Z,1683918653.399 [Default:CheckIn:D] Running Loop=1
2023-05-12T19:10:53.793Z,1683918653.793 [Default:CheckIn:D] Stopped
2023-05-12T19:10:53.793Z,1683918653.793 [Default:CheckIn:E] Running Loop=1
2023-05-12T19:10:54.206Z,1683918654.206 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 63.388452 min 
2023-05-12T19:10:54.206Z,1683918654.206 [Default:CheckIn:E] Stopped
2023-05-12T19:10:54.206Z,1683918654.206 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-12T19:10:54.206Z,1683918654.206 [Default:CheckIn] Stopped
2023-05-12T19:10:54.207Z,1683918654.207 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T19:10:54.207Z,1683918654.207 [Default:CheckIn](INFO): Running loop #7
2023-05-12T19:10:54.207Z,1683918654.207 [Default:CheckIn] Running Loop=7
2023-05-12T19:10:54.207Z,1683918654.207 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T19:10:54.207Z,1683918654.207 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T19:12:06.513Z,1683918726.513 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T19:12:06.513Z,1683918726.513 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+22.7,489.0,000
2023-05-12T19:14:07.705Z,1683918847.705 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T19:14:07.705Z,1683918847.705 [DVL_micro](ERROR): Failed to parse:
:TS,000000000000002.6,0000.0,1489.0,000
2023-05-12T19:15:54.391Z,1683918954.391 [Default:CheckIn:Read_GPS](INFO): Timed out from 2023-05-12T19:10:54.2Z
2023-05-12T19:15:54.391Z,1683918954.391 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T19:15:54.391Z,1683918954.391 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T19:15:57.994Z,1683918957.994 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-12T19:16:00.785Z,1683918960.785 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20230512T161716/Courier0043.lzma
2023-05-12T19:16:01.770Z,1683918961.770 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0043.lzma.bak
2023-05-12T19:16:01.770Z,1683918961.770 [DataOverHttps](INFO): SBD MOMSN=18300489
2023-05-12T19:16:17.804Z,1683918977.804 [DataOverHttps](INFO): Sending 207 bytes from file Logs/20230512T161716/Express0044.lzma
2023-05-12T19:16:18.806Z,1683918978.806 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0044.lzma.bak
2023-05-12T19:16:18.806Z,1683918978.806 [DataOverHttps](INFO): SBD MOMSN=18300491
2023-05-12T19:16:20.643Z,1683918980.643 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T19:16:20.643Z,1683918980.643 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T19:16:20.643Z,1683918980.643 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T19:16:28.705Z,1683918988.705 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-12T19:17:24.468Z,1683919044.468 [DVL_micro](ERROR): Failed to parse:99.99,++9999.99,+9999.99
2023-05-12T19:21:21.231Z,1683919281.231 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-12T19:21:21.231Z,1683919281.231 [Default:CheckIn:C.Wait] Stopped
2023-05-12T19:21:21.231Z,1683919281.231 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T19:21:21.232Z,1683919281.232 [Default:CheckIn:D] Running Loop=1
2023-05-12T19:21:21.613Z,1683919281.613 [Default:CheckIn:D] Stopped
2023-05-12T19:21:21.614Z,1683919281.614 [Default:CheckIn:E] Running Loop=1
2023-05-12T19:21:22.027Z,1683919282.027 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 73.852124 min 
2023-05-12T19:21:22.027Z,1683919282.027 [Default:CheckIn:E] Stopped
2023-05-12T19:21:22.027Z,1683919282.027 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-12T19:21:22.027Z,1683919282.027 [Default:CheckIn] Stopped
2023-05-12T19:21:22.027Z,1683919282.027 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T19:21:22.027Z,1683919282.027 [Default:CheckIn](INFO): Running loop #8
2023-05-12T19:21:22.027Z,1683919282.027 [Default:CheckIn] Running Loop=8
2023-05-12T19:21:22.027Z,1683919282.027 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T19:21:22.027Z,1683919282.027 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T19:21:23.629Z,1683919283.629 [NAL9602](FAULT): GPS failed to acquire within timeout.
2023-05-12T19:21:23.629Z,1683919283.629 [NAL9602] Data Fault, FailCount= 5
2023-05-12T19:21:23.629Z,1683919283.629 [NAL9602](ERROR): Data Fault
2023-05-12T19:21:23.702Z,1683919283.702 [CBIT](ERROR): Data Fault in component: NAL9602
2023-05-12T19:21:23.703Z,1683919283.703 [CBIT](CRITICAL): Data Fault in component: NAL9602
2023-05-12T19:21:24.041Z,1683919284.041 [NAL9602](INFO): Powering down
2023-05-12T19:21:24.058Z,1683919284.058 [CBIT](INFO): Critical error at 20230512T192123
2023-05-12T19:21:24.059Z,1683919284.059 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2023-05-12T19:23:23.630Z,1683919403.630 [CBIT](INFO): Clearing failed state for component NAL9602
2023-05-12T19:23:23.630Z,1683919403.630 [NAL9602] No Fault, FailCount= 5
2023-05-12T19:23:24.017Z,1683919404.017 [NAL9602](INFO): Powering up NAL9602
2023-05-12T19:23:34.942Z,1683919414.942 [NAL9602](INFO): NAL9602 initialized
2023-05-12T19:24:25.438Z,1683919465.438 [DVL_micro](ERROR): Failed to parse:
:B,-00126,-00098,+00000,I
2023-05-12T19:26:22.213Z,1683919582.213 [Default:CheckIn:Read_GPS](INFO): Timed out from 2023-05-12T19:21:22.0Z
2023-05-12T19:26:22.213Z,1683919582.213 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T19:26:22.213Z,1683919582.213 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T19:26:29.555Z,1683919589.555 [DataOverHttps](INFO): Sending 82 bytes from file Logs/20230512T161716/Courier0046.lzma
2023-05-12T19:26:30.558Z,1683919590.558 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0046.lzma.bak
2023-05-12T19:26:30.558Z,1683919590.558 [DataOverHttps](INFO): SBD MOMSN=18300608
2023-05-12T19:26:46.541Z,1683919606.541 [DataOverHttps](INFO): Sending 224 bytes from file Logs/20230512T161716/Express0047.lzma
2023-05-12T19:26:47.542Z,1683919607.542 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0047.lzma.bak
2023-05-12T19:26:47.542Z,1683919607.542 [DataOverHttps](INFO): SBD MOMSN=18300611
2023-05-12T19:26:49.317Z,1683919609.317 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T19:26:49.317Z,1683919609.317 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T19:26:49.317Z,1683919609.317 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T19:27:57.128Z,1683919677.128 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T19:27:57.128Z,1683919677.128 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+22.71489.0,000
2023-05-12T19:28:38.737Z,1683919718.737 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-12T19:29:09.448Z,1683919749.448 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-12T19:30:00.749Z,1683919800.749 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T19:30:00.749Z,1683919800.749 [DVL_micro](ERROR): Failed to parse:
:BI,+00012,-0086,+00000,I
2023-05-12T19:31:49.863Z,1683919909.863 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-12T19:31:49.863Z,1683919909.863 [Default:CheckIn:C.Wait] Stopped
2023-05-12T19:31:49.863Z,1683919909.863 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T19:31:49.863Z,1683919909.863 [Default:CheckIn:D] Running Loop=1
2023-05-12T19:31:50.248Z,1683919910.248 [Default:CheckIn:D] Stopped
2023-05-12T19:31:50.248Z,1683919910.248 [Default:CheckIn:E] Running Loop=1
2023-05-12T19:31:50.643Z,1683919910.643 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 84.329362 min 
2023-05-12T19:31:50.643Z,1683919910.643 [Default:CheckIn:E] Stopped
2023-05-12T19:31:50.643Z,1683919910.643 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-12T19:31:50.643Z,1683919910.643 [Default:CheckIn] Stopped
2023-05-12T19:31:50.644Z,1683919910.644 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T19:31:50.644Z,1683919910.644 [Default:CheckIn](INFO): Running loop #9
2023-05-12T19:31:50.644Z,1683919910.644 [Default:CheckIn] Running Loop=9
2023-05-12T19:31:50.644Z,1683919910.644 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T19:31:50.644Z,1683919910.644 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T19:31:56.704Z,1683919916.704 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T19:31:56.704Z,1683919916.704 [DVL_micro](ERROR): Failed to parse:
:BI,-00126,-0009,+00000,I
2023-05-12T19:33:32.464Z,1683920012.464 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T19:33:32.464Z,1683920012.464 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.999,+9999.99
2023-05-12T19:36:50.824Z,1683920210.824 [Default:CheckIn:Read_GPS](INFO): Timed out from 2023-05-12T19:31:50.6Z
2023-05-12T19:36:50.824Z,1683920210.824 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T19:36:50.824Z,1683920210.824 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T19:36:54.442Z,1683920214.442 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-12T19:36:58.011Z,1683920218.011 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20230512T161716/Courier0049.lzma
2023-05-12T19:36:59.014Z,1683920219.014 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0049.lzma.bak
2023-05-12T19:36:59.014Z,1683920219.014 [DataOverHttps](INFO): SBD MOMSN=18300682
2023-05-12T19:37:15.044Z,1683920235.044 [DataOverHttps](INFO): Sending 205 bytes from file Logs/20230512T161716/Express0050.lzma
2023-05-12T19:37:16.046Z,1683920236.046 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0050.lzma.bak
2023-05-12T19:37:16.046Z,1683920236.046 [DataOverHttps](INFO): SBD MOMSN=18300699
2023-05-12T19:37:17.885Z,1683920237.885 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T19:37:17.885Z,1683920237.885 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T19:37:17.885Z,1683920237.885 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T19:37:25.144Z,1683920245.144 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-12T19:37:34.063Z,1683920254.063 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T19:37:34.079Z,1683920254.079 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+22.7,089.0,000
2023-05-12T19:40:37.926Z,1683920437.926 [DVL_micro](ERROR): Failed to parse:
:WI,-00082,-0060,+00000,A
2023-05-12T19:42:18.551Z,1683920538.551 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-12T19:42:18.556Z,1683920538.556 [Default:CheckIn:C.Wait] Stopped
2023-05-12T19:42:18.556Z,1683920538.556 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T19:42:18.556Z,1683920538.556 [Default:CheckIn:D] Running Loop=1
2023-05-12T19:42:18.927Z,1683920538.927 [Default:CheckIn:D] Stopped
2023-05-12T19:42:18.927Z,1683920538.927 [Default:CheckIn:E] Running Loop=1
2023-05-12T19:42:19.336Z,1683920539.336 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 94.807357 min 
2023-05-12T19:42:19.336Z,1683920539.336 [Default:CheckIn:E] Stopped
2023-05-12T19:42:19.336Z,1683920539.336 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-12T19:42:19.336Z,1683920539.336 [Default:CheckIn] Stopped
2023-05-12T19:42:19.336Z,1683920539.336 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T19:42:19.337Z,1683920539.337 [Default:CheckIn](INFO): Running loop #10
2023-05-12T19:42:19.337Z,1683920539.337 [Default:CheckIn] Running Loop=10
2023-05-12T19:42:19.337Z,1683920539.337 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T19:42:19.337Z,1683920539.337 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T19:42:20.954Z,1683920540.954 [NAL9602](FAULT): GPS failed to acquire within timeout.
2023-05-12T19:42:20.954Z,1683920540.954 [NAL9602] Data Fault, FailCount= 1
2023-05-12T19:42:20.954Z,1683920540.954 [NAL9602](ERROR): Data Fault
2023-05-12T19:42:20.973Z,1683920540.973 [CBIT](ERROR): Data Fault in component: NAL9602
2023-05-12T19:42:21.410Z,1683920541.410 [NAL9602](INFO): Powering down
2023-05-12T19:42:22.204Z,1683920542.204 [CBIT](INFO): Clearing failed state for component NAL9602
2023-05-12T19:42:22.204Z,1683920542.204 [NAL9602] No Fault, FailCount= 1
2023-05-12T19:42:51.662Z,1683920571.662 [NAL9602](INFO): Powering up NAL9602
2023-05-12T19:43:02.574Z,1683920582.574 [NAL9602](INFO): NAL9602 initialized
2023-05-12T19:47:08.201Z,1683920828.201 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2023-05-12T19:47:08.203Z,1683920828.203 [BPC1](INFO): Received data from all battery sticks.
2023-05-12T19:47:19.512Z,1683920839.512 [Default:CheckIn:Read_GPS](INFO): Timed out from 2023-05-12T19:42:19.3Z
2023-05-12T19:47:19.512Z,1683920839.512 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T19:47:19.512Z,1683920839.512 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T19:47:22.737Z,1683920842.737 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.00,+00000000.00,9999.99,000.00
2023-05-12T19:47:27.415Z,1683920847.415 [DataOverHttps](INFO): Sending 49 bytes from file Logs/20230512T161716/Courier0052.lzma
2023-05-12T19:47:28.418Z,1683920848.418 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0052.lzma.bak
2023-05-12T19:47:28.418Z,1683920848.418 [DataOverHttps](INFO): SBD MOMSN=18300807
2023-05-12T19:47:44.976Z,1683920864.976 [DataOverHttps](INFO): Sending 224 bytes from file Logs/20230512T161716/Express0053.lzma
2023-05-12T19:47:45.978Z,1683920865.978 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0053.lzma.bak
2023-05-12T19:47:45.978Z,1683920865.978 [DataOverHttps](INFO): SBD MOMSN=18300809
2023-05-12T19:47:47.814Z,1683920867.814 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T19:47:47.814Z,1683920867.814 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T19:47:47.814Z,1683920867.814 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T19:48:03.149Z,1683920883.149 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T19:48:03.150Z,1683920883.150 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,+99999.99
2023-05-12T19:48:06.363Z,1683920886.363 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-12T19:48:37.070Z,1683920917.070 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-12T19:49:23.531Z,1683920963.531 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T19:49:23.531Z,1683920963.531 [DVL_micro](ERROR): Failed to parse:
:RD,9,+9999.99,+9999.99
2023-05-12T19:52:46.814Z,1683921166.814 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T19:52:46.814Z,1683921166.814 [DVL_micro](ERROR): Failed to parse:
:BI,00260,-00035,+00000,I
2023-05-12T19:52:48.429Z,1683921168.429 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-12T19:52:48.429Z,1683921168.429 [Default:CheckIn:C.Wait] Stopped
2023-05-12T19:52:48.430Z,1683921168.430 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T19:52:48.430Z,1683921168.430 [Default:CheckIn:D] Running Loop=1
2023-05-12T19:52:48.827Z,1683921168.827 [Default:CheckIn:D] Stopped
2023-05-12T19:52:48.827Z,1683921168.827 [Default:CheckIn:E] Running Loop=1
2023-05-12T19:52:49.265Z,1683921169.265 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 105.305688 min 
2023-05-12T19:52:49.265Z,1683921169.265 [Default:CheckIn:E] Stopped
2023-05-12T19:52:49.266Z,1683921169.266 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-12T19:52:49.266Z,1683921169.266 [Default:CheckIn] Stopped
2023-05-12T19:52:49.266Z,1683921169.266 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T19:52:49.266Z,1683921169.266 [Default:CheckIn](INFO): Running loop #11
2023-05-12T19:52:49.266Z,1683921169.266 [Default:CheckIn] Running Loop=11
2023-05-12T19:52:49.266Z,1683921169.266 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T19:52:49.266Z,1683921169.266 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T19:53:21.947Z,1683921201.947 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2023-05-12T19:53:22.028Z,1683921202.028 [NAL9602](ERROR): received: 
+CSQ:0

OK56, 2, 0, 0, 0

OK
2023-05-12T19:54:14.473Z,1683921254.473 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T19:54:14.473Z,1683921254.473 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+99999.99,+9999.99
2023-05-12T19:57:49.403Z,1683921469.403 [Default:CheckIn:Read_GPS](INFO): Timed out from 2023-05-12T19:52:49.3Z
2023-05-12T19:57:49.403Z,1683921469.403 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T19:57:49.403Z,1683921469.403 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T19:57:53.430Z,1683921473.430 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-12T19:57:57.115Z,1683921477.115 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20230512T161716/Courier0055.lzma
2023-05-12T19:57:58.118Z,1683921478.118 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0055.lzma.bak
2023-05-12T19:57:58.118Z,1683921478.118 [DataOverHttps](INFO): SBD MOMSN=18300820
2023-05-12T19:58:14.095Z,1683921494.095 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20230512T161716/Express0056.lzma
2023-05-12T19:58:15.098Z,1683921495.098 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0056.lzma.bak
2023-05-12T19:58:15.098Z,1683921495.098 [DataOverHttps](INFO): SBD MOMSN=18300825
2023-05-12T19:58:16.882Z,1683921496.882 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T19:58:16.882Z,1683921496.882 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T19:58:16.882Z,1683921496.882 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T19:58:24.141Z,1683921504.141 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-12T19:58:47.688Z,1683921527.688 [DVL_micro](ERROR): only read 0 of 4 data items
2023-05-12T19:58:47.688Z,1683921527.688 [DVL_micro](ERROR): Failed to parse:
:RD,,+9999.99,+9999.99,+9999.99
2023-05-12T19:59:47.356Z,1683921587.356 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-12T20:00:18.480Z,1683921618.480 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-12T20:00:49.624Z,1683921649.624 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-12T20:01:20.756Z,1683921680.756 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-12T20:01:51.896Z,1683921711.896 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-12T20:01:54.908Z,1683921714.908 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=180.787369
2023-05-12T20:02:53.168Z,1683921773.168 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-12T20:03:17.449Z,1683921797.449 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-12T20:03:17.449Z,1683921797.449 [Default:CheckIn:C.Wait] Stopped
2023-05-12T20:03:17.449Z,1683921797.449 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T20:03:17.450Z,1683921797.450 [Default:CheckIn:D] Running Loop=1
2023-05-12T20:03:17.851Z,1683921797.851 [Default:CheckIn:D] Stopped
2023-05-12T20:03:17.851Z,1683921797.851 [Default:CheckIn:E] Running Loop=1
2023-05-12T20:03:18.272Z,1683921798.272 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 115.789421 min 
2023-05-12T20:03:18.272Z,1683921798.272 [Default:CheckIn:E] Stopped
2023-05-12T20:03:18.272Z,1683921798.272 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-12T20:03:18.272Z,1683921798.272 [Default:CheckIn] Stopped
2023-05-12T20:03:18.273Z,1683921798.273 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T20:03:18.273Z,1683921798.273 [Default:CheckIn](INFO): Running loop #12
2023-05-12T20:03:18.273Z,1683921798.273 [Default:CheckIn] Running Loop=12
2023-05-12T20:03:18.273Z,1683921798.273 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T20:03:18.273Z,1683921798.273 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T20:03:19.866Z,1683921799.866 [NAL9602](FAULT): GPS failed to acquire within timeout.
2023-05-12T20:03:19.866Z,1683921799.866 [NAL9602] Data Fault, FailCount= 2
2023-05-12T20:03:19.866Z,1683921799.866 [NAL9602](ERROR): Data Fault
2023-05-12T20:03:19.885Z,1683921799.885 [CBIT](ERROR): Data Fault in component: NAL9602
2023-05-12T20:03:20.269Z,1683921800.269 [NAL9602](INFO): Powering down
2023-05-12T20:03:21.092Z,1683921801.092 [CBIT](INFO): Clearing failed state for component NAL9602
2023-05-12T20:03:21.092Z,1683921801.092 [NAL9602] No Fault, FailCount= 2
2023-05-12T20:03:24.292Z,1683921804.292 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-12T20:03:50.578Z,1683921830.578 [NAL9602](INFO): Powering up NAL9602
2023-05-12T20:03:55.416Z,1683921835.416 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-12T20:04:01.473Z,1683921841.473 [NAL9602](INFO): NAL9602 initialized
2023-05-12T20:04:26.556Z,1683921866.556 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-12T20:04:57.693Z,1683921897.693 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-12T20:05:28.824Z,1683921928.824 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-12T20:05:59.957Z,1683921959.957 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-12T20:06:31.084Z,1683921991.084 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-12T20:06:40.271Z,1683922000.271 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T20:06:40.271Z,1683922000.271 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+20.1,0000.0,10
2023-05-12T20:06:57.640Z,1683922017.640 [NAL9602](INFO): SBD MO Status=2, MOMSN=3656, MT Status=2, MTMSN=0
2023-05-12T20:06:57.640Z,1683922017.640 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-12T20:07:02.221Z,1683922022.221 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-12T20:07:16.740Z,1683922036.740 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.00,+00000000.00,0000.20,000.00
2023-05-12T20:07:22.228Z,1683922042.228 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002931
2023-05-12T20:07:34.042Z,1683922054.042 [NAL9602](INFO): SBD MO Status=0, MOMSN=3656, MT Status=0, MTMSN=0
2023-05-12T20:07:34.042Z,1683922054.042 [NAL9602](INFO): No messages in MT queue
2023-05-12T20:08:09.204Z,1683922089.204 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T20:08:09.205Z,1683922089.205 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000,+19.7,0000.0,1489.0,000
2023-05-12T20:08:14.456Z,1683922094.456 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T20:08:14.457Z,1683922094.457 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+19.7,089.0,000
2023-05-12T20:08:18.519Z,1683922098.519 [Default:CheckIn:Read_GPS](INFO): Timed out from 2023-05-12T20:03:18.3Z
2023-05-12T20:08:18.519Z,1683922098.519 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T20:08:18.520Z,1683922098.520 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T20:08:26.495Z,1683922106.495 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20230512T161716/Courier0058.lzma
2023-05-12T20:08:27.498Z,1683922107.498 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0058.lzma.bak
2023-05-12T20:08:27.498Z,1683922107.498 [DataOverHttps](INFO): SBD MOMSN=18300884
2023-05-12T20:08:48.157Z,1683922128.157 [DataOverHttps](INFO): Sending 226 bytes from file Logs/20230512T161716/Express0059.lzma
2023-05-12T20:08:49.155Z,1683922129.155 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0059.lzma.bak
2023-05-12T20:08:49.155Z,1683922129.155 [DataOverHttps](INFO): SBD MOMSN=18300889
2023-05-12T20:08:50.938Z,1683922130.938 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T20:08:50.939Z,1683922130.939 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T20:08:50.939Z,1683922130.939 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T20:08:51.724Z,1683922131.724 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-12T20:09:38.690Z,1683922178.690 [CommandExec](IMPORTANT): got command maintain control VerticalControl.buoyancyAction 150 cubic_centimeter
2023-05-12T20:09:38.694Z,1683922178.694 [ComponentRegistry](DEBUG): SyncComponent "Maintain_VerticalControl.buoyancyAction" handled in the control thread.
2023-05-12T20:09:39.053Z,1683922179.053 [controlThread](DEBUG): Component order: CycleStarter,ESPComponent,PAR_Licor,AHRS_M2,BPC1,Depth_Keller,DropWeight,DVL_micro,NAL9602,Power24vConverter,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,VerticalHomogeneityIndexCalculator,YawRateCalculator,ElevatorOffsetCalculator,StratificationFrontDetector,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,Maintain_VerticalControl.buoyancyAction,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter,
2023-05-12T20:09:49.518Z,1683922189.518 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T20:09:49.518Z,1683922189.518 [DVL_micro](ERROR): Failed to parse:
:TS,000000000000019.5,0000.0,1489.0,000
2023-05-12T20:09:57.238Z,1683922197.238 [DVL_micro](ERROR): Failed to parse:193,+00433,+00289,+00000,A
2023-05-12T20:10:14.481Z,1683922214.481 [CommandExec](IMPORTANT): got command report mod VerticalControl.buoyancyAction 
2023-05-12T20:10:14.638Z,1683922214.638 [Reporter](INFO): VerticalControl.buoyancyAction 150.000000 cc
2023-05-12T20:10:20.438Z,1683922220.438 [CommandExec](IMPORTANT): got command report clear
2023-05-12T20:10:41.107Z,1683922241.107 [CommandExec](IMPORTANT): got command show variable platform_buoyancy
2023-05-12T20:10:41.120Z,1683922241.120 [CommandExec](IMPORTANT): platform_buoyancy_position (cubic_centimeter)
2023-05-12T20:10:41.474Z,1683922241.474 [CommandExec](IMPORTANT): BuoyancyServo.platform_buoyancy_position (cubic_centimeter)
2023-05-12T20:10:46.901Z,1683922246.901 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T20:10:46.902Z,1683922246.902 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,.4,0000.0,1489.0,000
2023-05-12T20:10:57.655Z,1683922257.655 [CommandExec](IMPORTANT): got command report mod platform_buoyancy_position
2023-05-12T20:10:57.914Z,1683922257.914 [Reporter](INFO): platform_buoyancy_position 159.269714 cc
2023-05-12T20:11:05.273Z,1683922265.273 [CommandExec](IMPORTANT): got command maintain 
2023-05-12T20:11:05.274Z,1683922265.274 [Maintain_VerticalControl.buoyancyAction](INFO): VerticalControl.buoyancyAction maintaining 150.000000 cc
2023-05-12T20:11:17.631Z,1683922277.631 [DVL_micro](ERROR): Failed to parse:00000000000,35.0,+19.4,0000.0,1489.0,000
2023-05-12T20:11:23.417Z,1683922283.417 [CommandExec](IMPORTANT): got command get platform_mass_position
2023-05-12T20:11:23.417Z,1683922283.417 [CommandExec](IMPORTANT): platform_mass_position 0.012946 m
2023-05-12T20:11:45.403Z,1683922305.403 [CommandExec](IMPORTANT): got command get VerticalControl.massPositionLimitFwd
2023-05-12T20:11:45.404Z,1683922305.404 [CommandExec](IMPORTANT): VerticalControl.massPositionLimitFwd 39.000000 mm
2023-05-12T20:12:09.827Z,1683922329.827 [CommandExec](IMPORTANT): got command maintain control VerticalControl.massPositionAction 32 millimeter
2023-05-12T20:12:09.830Z,1683922329.830 [ComponentRegistry](DEBUG): SyncComponent "Maintain_VerticalControl.massPositionAction" handled in the control thread.
2023-05-12T20:12:10.183Z,1683922330.183 [controlThread](DEBUG): Component order: CycleStarter,ESPComponent,PAR_Licor,AHRS_M2,BPC1,Depth_Keller,DropWeight,DVL_micro,NAL9602,Power24vConverter,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,VerticalHomogeneityIndexCalculator,YawRateCalculator,ElevatorOffsetCalculator,StratificationFrontDetector,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,Maintain_VerticalControl.buoyancyAction,Maintain_VerticalControl.massPositionAction,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter,
2023-05-12T20:13:23.706Z,1683922403.706 [DVL_micro](ERROR): Failed to parse:
:WI,+00000,+00000,+00000,+00000,I
2023-05-12T20:13:51.583Z,1683922431.583 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-12T20:13:51.584Z,1683922431.584 [Default:CheckIn:C.Wait] Stopped
2023-05-12T20:13:51.584Z,1683922431.584 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T20:13:51.584Z,1683922431.584 [Default:CheckIn:D] Running Loop=1
2023-05-12T20:13:51.982Z,1683922431.982 [Default:CheckIn:D] Stopped
2023-05-12T20:13:51.982Z,1683922431.982 [Default:CheckIn:E] Running Loop=1
2023-05-12T20:13:52.391Z,1683922432.391 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 126.358260 min 
2023-05-12T20:13:52.392Z,1683922432.392 [Default:CheckIn:E] Stopped
2023-05-12T20:13:52.392Z,1683922432.392 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-12T20:13:52.392Z,1683922432.392 [Default:CheckIn] Stopped
2023-05-12T20:13:52.392Z,1683922432.392 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T20:13:52.392Z,1683922432.392 [Default:CheckIn](INFO): Running loop #13
2023-05-12T20:13:52.392Z,1683922432.392 [Default:CheckIn] Running Loop=13
2023-05-12T20:13:52.392Z,1683922432.392 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T20:13:52.393Z,1683922432.393 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T20:13:54.457Z,1683922434.457 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,201340.00,A,3648.16832,N,12147.28262,W,2.566,204.96,120523,,,A*7B
2023-05-12T20:13:54.460Z,1683922434.460 [NAL9602](INFO): GPS fix at 20230512T201340: (36.802805, -121.788044)
2023-05-12T20:13:54.473Z,1683922434.473 [UniversalFixResidualReporter](INFO): Fix residual: 11.5 %DT, over the last 678.1 m. Residual distance 77.9 m at bearing 93.5 degrees. Fix at (36.8028, -121.7880) with 22.1 m made good.
2023-05-12T20:13:54.473Z,1683922434.473 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T20:13:54.473Z,1683922434.473 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T20:14:02.524Z,1683922442.524 [DataOverHttps](INFO): Sending 202 bytes from file Logs/20230512T161716/Courier0061.lzma
2023-05-12T20:14:03.526Z,1683922443.526 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0061.lzma.bak
2023-05-12T20:14:03.526Z,1683922443.526 [DataOverHttps](INFO): SBD MOMSN=18301147
2023-05-12T20:14:19.845Z,1683922459.845 [DataOverHttps](INFO): Sending 409 bytes from file Logs/20230512T161716/Express0062.lzma
2023-05-12T20:14:19.891Z,1683922459.891 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T20:14:19.891Z,1683922459.891 [DVL_micro](ERROR): Failed to parse:
:RD,+0000.32,+00000.34,+0011.42
2023-05-12T20:14:20.838Z,1683922460.838 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0062.lzma.bak
2023-05-12T20:14:20.838Z,1683922460.838 [DataOverHttps](INFO): SBD MOMSN=18301150
2023-05-12T20:14:22.688Z,1683922462.688 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T20:14:22.688Z,1683922462.688 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T20:14:22.689Z,1683922462.689 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T20:15:17.655Z,1683922517.655 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T20:15:17.655Z,1683922517.655 [DVL_micro](ERROR): Failed to parse:
:RD,+0000.32,+0009.83,+00009.99
2023-05-12T20:16:04.246Z,1683922564.246 [CommandExec](IMPORTANT): got command maintain control VerticalControl.massPositionAction 22 millimeter
2023-05-12T20:16:14.781Z,1683922574.781 [CommandExec](IMPORTANT): got command get platform_buoyancy_position
2023-05-12T20:16:14.781Z,1683922574.781 [CommandExec](IMPORTANT): platform_buoyancy_position 159.269714 cc
2023-05-12T20:16:39.661Z,1683922599.661 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T20:16:39.661Z,1683922599.661 [DVL_micro](ERROR): Failed to parse:
:BI,+00000,+0000,+00000,I
2023-05-12T20:18:17.027Z,1683922697.027 [NAL9602](INFO): SBD MO Status=2, MOMSN=3657, MT Status=2, MTMSN=0
2023-05-12T20:18:17.027Z,1683922697.027 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-12T20:18:24.707Z,1683922704.707 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T20:18:24.707Z,1683922704.707 [DVL_micro](ERROR): Failed to parse:
:BI,+00482,+00560,+00317,+00BD,+00000000.00,+00000000.00,+00000000.00,0000.20,000.00
2023-05-12T20:18:37.643Z,1683922717.643 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T20:18:37.643Z,1683922717.643 [DVL_micro](ERROR): Failed to parse:
:RD,+0000.32,+0001.59,+0000.304
2023-05-12T20:18:42.489Z,1683922722.489 [DVL_micro](ERROR): Failed to parse:000,+00000,+00000,+00000,I
2023-05-12T20:18:56.623Z,1683922736.623 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-12T20:19:01.094Z,1683922741.094 [CBIT](IMPORTANT): Beginning ground fault scan
2023-05-12T20:19:11.990Z,1683922751.990 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.005127
CHAN A1 (24V): 0.002245
CHAN A2 (12V): -0.005478
CHAN A3 (5V): -0.004085
CHAN B0 (3.3V): -0.002223
CHAN B1 (3.15aV): -0.000996
CHAN B2 (3.15bV): -0.001228
CHAN B3 (GND): -0.001092
OPEN: 0.012142
Full Scale: +/- 1 mA
2023-05-12T20:19:23.312Z,1683922763.312 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-12T20:19:23.312Z,1683922763.312 [Default:CheckIn:C.Wait] Stopped
2023-05-12T20:19:23.312Z,1683922763.312 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T20:19:23.312Z,1683922763.312 [Default:CheckIn:D] Running Loop=1
2023-05-12T20:19:23.692Z,1683922763.692 [Default:CheckIn:D] Stopped
2023-05-12T20:19:23.692Z,1683922763.692 [Default:CheckIn:E] Running Loop=1
2023-05-12T20:19:24.123Z,1683922764.123 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 131.886768 min 
2023-05-12T20:19:24.123Z,1683922764.123 [Default:CheckIn:E] Stopped
2023-05-12T20:19:24.128Z,1683922764.128 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-12T20:19:24.128Z,1683922764.128 [Default:CheckIn] Stopped
2023-05-12T20:19:24.128Z,1683922764.128 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T20:19:24.128Z,1683922764.128 [Default:CheckIn](INFO): Running loop #14
2023-05-12T20:19:24.128Z,1683922764.128 [Default:CheckIn] Running Loop=14
2023-05-12T20:19:24.128Z,1683922764.128 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T20:19:24.128Z,1683922764.128 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T20:19:26.131Z,1683922766.131 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,201912.00,A,3648.16592,N,12147.28353,W,1.613,223.81,120523,,,A*73
2023-05-12T20:19:26.137Z,1683922766.137 [NAL9602](INFO): GPS fix at 20230512T201912: (36.802765, -121.788059)
2023-05-12T20:19:26.151Z,1683922766.151 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T20:19:26.156Z,1683922766.156 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T20:19:34.725Z,1683922774.725 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230512T161716/Courier0064.lzma
2023-05-12T20:19:35.726Z,1683922775.726 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0064.lzma.bak
2023-05-12T20:19:35.726Z,1683922775.726 [DataOverHttps](INFO): SBD MOMSN=18301166
2023-05-12T20:19:52.048Z,1683922792.048 [DataOverHttps](INFO): Sending 489 bytes from file Logs/20230512T161716/Express0065.lzma
2023-05-12T20:19:53.249Z,1683922793.249 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0065.lzma.bak
2023-05-12T20:19:53.249Z,1683922793.249 [DataOverHttps](INFO): SBD MOMSN=18301169
2023-05-12T20:19:54.950Z,1683922794.950 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T20:19:54.950Z,1683922794.950 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T20:19:54.950Z,1683922794.950 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T20:19:58.578Z,1683922798.578 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-12T20:19:59.805Z,1683922799.805 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+0000000000000.00,0000.00,000.00
2023-05-12T20:21:48.074Z,1683922908.074 [ElevatorOffsetCalculator](INFO): New estimator for commanded vars: speed 1.00 m/s, pitch 30.00 deg, mass-position -15.00 mm (1 active estimators).
2023-05-12T20:21:57.520Z,1683922917.520 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-12T20:22:28.644Z,1683922948.644 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-12T20:24:00.227Z,1683923040.227 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T20:24:00.227Z,1683923040.227 [DVL_micro](ERROR): Failed to parse:
:TS,000000,35.0,00.0,1489.0,000
2023-05-12T20:24:55.647Z,1683923095.647 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-12T20:24:55.647Z,1683923095.647 [Default:CheckIn:C.Wait] Stopped
2023-05-12T20:24:55.647Z,1683923095.647 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T20:24:55.647Z,1683923095.647 [Default:CheckIn:D] Running Loop=1
2023-05-12T20:24:56.038Z,1683923096.038 [Default:CheckIn:D] Stopped
2023-05-12T20:24:56.038Z,1683923096.038 [Default:CheckIn:E] Running Loop=1
2023-05-12T20:24:56.451Z,1683923096.451 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 137.425863 min 
2023-05-12T20:24:56.452Z,1683923096.452 [Default:CheckIn:E] Stopped
2023-05-12T20:24:56.452Z,1683923096.452 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-12T20:24:56.452Z,1683923096.452 [Default:CheckIn] Stopped
2023-05-12T20:24:56.452Z,1683923096.452 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T20:24:56.452Z,1683923096.452 [Default:CheckIn](INFO): Running loop #15
2023-05-12T20:24:56.453Z,1683923096.453 [Default:CheckIn] Running Loop=15
2023-05-12T20:24:56.453Z,1683923096.453 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T20:24:56.453Z,1683923096.453 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T20:24:58.468Z,1683923098.468 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,202447.00,A,3648.16129,N,12147.28197,W,0.389,226.17,120523,,,D*7B
2023-05-12T20:24:58.471Z,1683923098.471 [NAL9602](INFO): GPS fix at 20230512T202447: (36.802688, -121.788033)
2023-05-12T20:24:58.481Z,1683923098.481 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T20:24:58.481Z,1683923098.481 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T20:25:07.419Z,1683923107.419 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230512T161716/Courier0067.lzma
2023-05-12T20:25:08.422Z,1683923108.422 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0067.lzma.bak
2023-05-12T20:25:08.422Z,1683923108.422 [DataOverHttps](INFO): SBD MOMSN=18301190
2023-05-12T20:25:28.415Z,1683923128.415 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20230512T161716/Express0068.lzma
2023-05-12T20:25:29.214Z,1683923129.214 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2023-05-12T20:25:29.292Z,1683923129.292 [NAL9602](ERROR): received: 
+CSQ:0

OK57, 2, 0, 0, 0

OK
2023-05-12T20:25:29.418Z,1683923129.418 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0068.lzma.bak
2023-05-12T20:25:29.418Z,1683923129.418 [DataOverHttps](INFO): SBD MOMSN=18301193
2023-05-12T20:25:31.245Z,1683923131.245 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T20:25:31.245Z,1683923131.245 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T20:25:31.245Z,1683923131.245 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T20:27:54.346Z,1683923274.346 [NAL9602](INFO): SBD MO Status=2, MOMSN=3657, MT Status=2, MTMSN=0
2023-05-12T20:27:54.346Z,1683923274.346 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-12T20:29:15.667Z,1683923355.667 [NAL9602](INFO): SBD MO Status=2, MOMSN=3657, MT Status=2, MTMSN=0
2023-05-12T20:29:15.667Z,1683923355.667 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-12T20:30:00.509Z,1683923400.509 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-12T20:30:31.212Z,1683923431.212 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-12T20:30:32.035Z,1683923432.035 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-12T20:30:32.035Z,1683923432.035 [Default:CheckIn:C.Wait] Stopped
2023-05-12T20:30:32.035Z,1683923432.035 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T20:30:32.035Z,1683923432.035 [Default:CheckIn:D] Running Loop=1
2023-05-12T20:30:32.445Z,1683923432.445 [Default:CheckIn:D] Stopped
2023-05-12T20:30:32.445Z,1683923432.445 [Default:CheckIn:E] Running Loop=1
2023-05-12T20:30:32.870Z,1683923432.870 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 143.032650 min 
2023-05-12T20:30:32.870Z,1683923432.870 [Default:CheckIn:E] Stopped
2023-05-12T20:30:32.870Z,1683923432.870 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-12T20:30:32.870Z,1683923432.870 [Default:CheckIn] Stopped
2023-05-12T20:30:32.870Z,1683923432.870 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T20:30:32.870Z,1683923432.870 [Default:CheckIn](INFO): Running loop #16
2023-05-12T20:30:32.870Z,1683923432.870 [Default:CheckIn] Running Loop=16
2023-05-12T20:30:32.870Z,1683923432.870 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T20:30:32.870Z,1683923432.870 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T20:30:34.850Z,1683923434.850 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,203024.00,A,3648.16459,N,12147.28765,W,0.214,249.20,120523,,,D*7A
2023-05-12T20:30:34.861Z,1683923434.861 [NAL9602](INFO): GPS fix at 20230512T203024: (36.802743, -121.788128)
2023-05-12T20:30:34.871Z,1683923434.871 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T20:30:34.871Z,1683923434.871 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T20:30:38.139Z,1683923438.139 [DVL_micro](ERROR): Failed to parse:
9.99,+9999..99,+9999.99
2023-05-12T20:30:45.859Z,1683923445.859 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230512T161716/Courier0070.lzma
2023-05-12T20:30:46.862Z,1683923446.862 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0070.lzma.bak
2023-05-12T20:30:46.862Z,1683923446.862 [DataOverHttps](INFO): SBD MOMSN=18301196
2023-05-12T20:31:02.879Z,1683923462.879 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20230512T161716/Express0071.lzma
2023-05-12T20:31:03.882Z,1683923463.882 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0071.lzma.bak
2023-05-12T20:31:03.883Z,1683923463.883 [DataOverHttps](INFO): SBD MOMSN=18301202
2023-05-12T20:31:05.281Z,1683923465.281 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2023-05-12T20:31:05.357Z,1683923465.357 [NAL9602](ERROR): received: 
+CSQ:0

OK57, 2, 0, 0, 0

OK
2023-05-12T20:31:06.123Z,1683923466.123 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T20:31:06.123Z,1683923466.123 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T20:31:06.123Z,1683923466.123 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T20:34:28.137Z,1683923668.137 [DVL_micro](ERROR): only read 1 of 4 data items
2023-05-12T20:34:28.137Z,1683923668.137 [DVL_micro](ERROR): Failed to parse:
:RD,+99999.99,++9999.99
2023-05-12T20:35:37.597Z,1683923737.597 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-12T20:35:48.910Z,1683923748.910 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T20:35:48.911Z,1683923748.911 [DVL_micro](ERROR): Failed to parse:
:BI,-0877,-00249,+00000,A
2023-05-12T20:35:55.780Z,1683923755.780 [DVL_micro](ERROR): Failed to parse:
:0,+00000,+00000,+00000,I
2023-05-12T20:35:58.018Z,1683923758.018 [CommandExec](IMPORTANT): got command maintain clear
2023-05-12T20:35:58.247Z,1683923758.247 [controlThread](DEBUG): Component order: CycleStarter,ESPComponent,PAR_Licor,AHRS_M2,BPC1,Depth_Keller,DropWeight,DVL_micro,NAL9602,Power24vConverter,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,VerticalHomogeneityIndexCalculator,YawRateCalculator,ElevatorOffsetCalculator,StratificationFrontDetector,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter,
2023-05-12T20:36:00.342Z,1683923760.342 [Reporter](INFO): platform_buoyancy_position 148.257111 cc
2023-05-12T20:36:00.634Z,1683923760.634 [DVL_micro](ERROR): only read 2 of 4 data items
2023-05-12T20:36:00.634Z,1683923760.634 [DVL_micro](ERROR): Failed to parse:
:RD,+0000.309,+0011.23,
2023-05-12T20:36:00.727Z,1683923760.727 [Reporter](INFO): platform_buoyancy_position 148.525726 cc
2023-05-12T20:36:01.549Z,1683923761.549 [Reporter](INFO): platform_buoyancy_position 152.823303 cc
2023-05-12T20:36:01.914Z,1683923761.914 [Reporter](INFO): platform_buoyancy_position 157.255219 cc
2023-05-12T20:36:02.326Z,1683923762.326 [Reporter](INFO): platform_buoyancy_position 161.418518 cc
2023-05-12T20:36:02.742Z,1683923762.742 [Reporter](INFO): platform_buoyancy_position 167.864929 cc
2023-05-12T20:36:03.150Z,1683923763.150 [Reporter](INFO): platform_buoyancy_position 172.296814 cc
2023-05-12T20:36:03.539Z,1683923763.539 [Reporter](INFO): platform_buoyancy_position 178.608917 cc
2023-05-12T20:36:03.951Z,1683923763.951 [Reporter](INFO): platform_buoyancy_position 182.906525 cc
2023-05-12T20:36:04.342Z,1683923764.342 [Reporter](INFO): platform_buoyancy_position 189.352936 cc
2023-05-12T20:36:04.784Z,1683923764.784 [Reporter](INFO): platform_buoyancy_position 193.784821 cc
2023-05-12T20:36:05.150Z,1683923765.150 [Reporter](INFO): platform_buoyancy_position 199.828339 cc
2023-05-12T20:36:05.558Z,1683923765.558 [Reporter](INFO): platform_buoyancy_position 204.663116 cc
2023-05-12T20:36:05.974Z,1683923765.974 [Reporter](INFO): platform_buoyancy_position 210.840912 cc
2023-05-12T20:36:06.374Z,1683923766.374 [Reporter](INFO): platform_buoyancy_position 215.138519 cc
2023-05-12T20:36:06.724Z,1683923766.724 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-12T20:36:06.724Z,1683923766.724 [Default:CheckIn:C.Wait] Stopped
2023-05-12T20:36:06.724Z,1683923766.724 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T20:36:06.725Z,1683923766.725 [Default:CheckIn:D] Running Loop=1
2023-05-12T20:36:06.802Z,1683923766.802 [Reporter](INFO): platform_buoyancy_position 221.584930 cc
2023-05-12T20:36:07.110Z,1683923767.110 [Default:CheckIn:D] Stopped
2023-05-12T20:36:07.110Z,1683923767.110 [Default:CheckIn:E] Running Loop=1
2023-05-12T20:36:07.187Z,1683923767.187 [Reporter](INFO): platform_buoyancy_position 226.016815 cc
2023-05-12T20:36:07.525Z,1683923767.525 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 148.610400 min 
2023-05-12T20:36:07.525Z,1683923767.525 [Default:CheckIn:E] Stopped
2023-05-12T20:36:07.525Z,1683923767.525 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-12T20:36:07.525Z,1683923767.525 [Default:CheckIn] Stopped
2023-05-12T20:36:07.525Z,1683923767.525 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T20:36:07.525Z,1683923767.525 [Default:CheckIn](INFO): Running loop #17
2023-05-12T20:36:07.525Z,1683923767.525 [Default:CheckIn] Running Loop=17
2023-05-12T20:36:07.525Z,1683923767.525 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T20:36:07.525Z,1683923767.525 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T20:36:07.603Z,1683923767.603 [Reporter](INFO): platform_buoyancy_position 232.328918 cc
2023-05-12T20:36:07.981Z,1683923767.981 [Reporter](INFO): platform_buoyancy_position 236.760834 cc
2023-05-12T20:36:08.350Z,1683923768.350 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.00,+00000000.00,0000.00,000.00
2023-05-12T20:36:08.435Z,1683923768.435 [Reporter](INFO): platform_buoyancy_position 240.924133 cc
2023-05-12T20:36:08.797Z,1683923768.797 [Reporter](INFO): platform_buoyancy_position 247.504822 cc
2023-05-12T20:36:09.230Z,1683923769.230 [Reporter](INFO): platform_buoyancy_position 252.071045 cc
2023-05-12T20:36:09.528Z,1683923769.528 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,203558.00,A,3648.16307,N,12147.28416,W,2.294,168.93,120523,,,D*7D
2023-05-12T20:36:09.530Z,1683923769.530 [NAL9602](INFO): GPS fix at 20230512T203558: (36.802718, -121.788069)
2023-05-12T20:36:09.541Z,1683923769.541 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T20:36:09.541Z,1683923769.541 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T20:36:09.613Z,1683923769.613 [Reporter](INFO): platform_buoyancy_position 258.114532 cc
2023-05-12T20:36:10.018Z,1683923770.018 [Reporter](INFO): platform_buoyancy_position 262.546417 cc
2023-05-12T20:36:10.455Z,1683923770.455 [Reporter](INFO): platform_buoyancy_position 268.992828 cc
2023-05-12T20:36:10.822Z,1683923770.822 [Reporter](INFO): platform_buoyancy_position 273.290436 cc
2023-05-12T20:36:11.230Z,1683923771.230 [Reporter](INFO): platform_buoyancy_position 279.602539 cc
2023-05-12T20:36:11.638Z,1683923771.638 [Reporter](INFO): platform_buoyancy_position 284.034424 cc
2023-05-12T20:36:12.006Z,1683923772.006 [Reporter](INFO): platform_buoyancy_position 288.332031 cc
2023-05-12T20:36:12.568Z,1683923772.568 [Reporter](INFO): platform_buoyancy_position 294.778442 cc
2023-05-12T20:36:12.814Z,1683923772.814 [Reporter](INFO): platform_buoyancy_position 298.941742 cc
2023-05-12T20:36:13.225Z,1683923773.225 [Reporter](INFO): platform_buoyancy_position 305.388123 cc
2023-05-12T20:36:13.634Z,1683923773.634 [Reporter](INFO): platform_buoyancy_position 309.820038 cc
2023-05-12T20:36:14.014Z,1683923774.014 [Reporter](INFO): platform_buoyancy_position 316.132141 cc
2023-05-12T20:36:14.434Z,1683923774.434 [Reporter](INFO): platform_buoyancy_position 320.564026 cc
2023-05-12T20:36:14.858Z,1683923774.858 [Reporter](INFO): platform_buoyancy_position 327.010437 cc
2023-05-12T20:36:15.230Z,1683923775.230 [Reporter](INFO): platform_buoyancy_position 331.308044 cc
2023-05-12T20:36:15.705Z,1683923775.705 [Reporter](INFO): platform_buoyancy_position 337.620148 cc
2023-05-12T20:36:16.061Z,1683923776.061 [Reporter](INFO): platform_buoyancy_position 342.052032 cc
2023-05-12T20:36:16.446Z,1683923776.446 [Reporter](INFO): platform_buoyancy_position 346.886841 cc
2023-05-12T20:36:16.862Z,1683923776.862 [Reporter](INFO): platform_buoyancy_position 352.661743 cc
2023-05-12T20:36:17.103Z,1683923777.103 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230512T161716/Courier0073.lzma
2023-05-12T20:36:17.235Z,1683923777.235 [Reporter](INFO): platform_buoyancy_position 359.108124 cc
2023-05-12T20:36:17.647Z,1683923777.647 [Reporter](INFO): platform_buoyancy_position 363.540039 cc
2023-05-12T20:36:18.058Z,1683923778.058 [Reporter](INFO): platform_buoyancy_position 368.240540 cc
2023-05-12T20:36:18.106Z,1683923778.106 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0073.lzma.bak
2023-05-12T20:36:18.106Z,1683923778.106 [DataOverHttps](INFO): SBD MOMSN=18301217
2023-05-12T20:36:18.470Z,1683923778.470 [Reporter](INFO): platform_buoyancy_position 374.418335 cc
2023-05-12T20:36:18.851Z,1683923778.851 [Reporter](INFO): platform_buoyancy_position 378.715942 cc
2023-05-12T20:36:19.290Z,1683923779.290 [Reporter](INFO): platform_buoyancy_position 385.028046 cc
2023-05-12T20:36:19.687Z,1683923779.687 [Reporter](INFO): platform_buoyancy_position 389.325653 cc
2023-05-12T20:36:20.082Z,1683923780.082 [Reporter](INFO): platform_buoyancy_position 395.637726 cc
2023-05-12T20:36:20.499Z,1683923780.499 [Reporter](INFO): platform_buoyancy_position 402.218445 cc
2023-05-12T20:36:20.874Z,1683923780.874 [Reporter](INFO): platform_buoyancy_position 406.516052 cc
2023-05-12T20:36:21.342Z,1683923781.342 [Reporter](INFO): platform_buoyancy_position 412.828156 cc
2023-05-12T20:36:21.708Z,1683923781.708 [Reporter](INFO): platform_buoyancy_position 417.125763 cc
2023-05-12T20:36:22.113Z,1683923782.113 [Reporter](INFO): platform_buoyancy_position 421.557648 cc
2023-05-12T20:36:22.539Z,1683923782.539 [Reporter](INFO): platform_buoyancy_position 427.869720 cc
2023-05-12T20:36:22.916Z,1683923782.916 [Reporter](INFO): platform_buoyancy_position 432.435944 cc
2023-05-12T20:36:23.322Z,1683923783.322 [Reporter](INFO): platform_buoyancy_position 438.613739 cc
2023-05-12T20:36:23.750Z,1683923783.750 [Reporter](INFO): platform_buoyancy_position 442.911346 cc
2023-05-12T20:36:24.154Z,1683923784.154 [Reporter](INFO): platform_buoyancy_position 449.492035 cc
2023-05-12T20:36:24.572Z,1683923784.572 [Reporter](INFO): platform_buoyancy_position 453.789642 cc
2023-05-12T20:36:24.942Z,1683923784.942 [Reporter](INFO): platform_buoyancy_position 459.698822 cc
2023-05-12T20:36:25.314Z,1683923785.314 [Reporter](INFO): platform_buoyancy_position 464.533661 cc
2023-05-12T20:36:25.730Z,1683923785.730 [Reporter](INFO): platform_buoyancy_position 469.905670 cc
2023-05-12T20:36:26.145Z,1683923786.145 [Reporter](INFO): platform_buoyancy_position 475.277618 cc
2023-05-12T20:36:26.565Z,1683923786.565 [Reporter](INFO): platform_buoyancy_position 480.246735 cc
2023-05-12T20:36:26.930Z,1683923786.930 [Reporter](INFO): platform_buoyancy_position 485.887360 cc
2023-05-12T20:36:27.346Z,1683923787.346 [Reporter](INFO): platform_buoyancy_position 490.184998 cc
2023-05-12T20:36:27.762Z,1683923787.762 [Reporter](INFO): platform_buoyancy_position 496.631378 cc
2023-05-12T20:36:28.138Z,1683923788.138 [Reporter](INFO): platform_buoyancy_position 501.063232 cc
2023-05-12T20:36:28.579Z,1683923788.579 [Reporter](INFO): platform_buoyancy_position 507.375336 cc
2023-05-12T20:36:28.966Z,1683923788.966 [Reporter](INFO): platform_buoyancy_position 511.941559 cc
2023-05-12T20:36:29.386Z,1683923789.386 [Reporter](INFO): platform_buoyancy_position 518.119324 cc
2023-05-12T20:36:29.786Z,1683923789.786 [Reporter](INFO): platform_buoyancy_position 522.551208 cc
2023-05-12T20:36:30.208Z,1683923790.208 [Reporter](INFO): platform_buoyancy_position 528.997620 cc
2023-05-12T20:36:30.655Z,1683923790.655 [Reporter](INFO): platform_buoyancy_position 535.309692 cc
2023-05-12T20:36:30.994Z,1683923790.994 [Reporter](INFO): platform_buoyancy_position 539.338745 cc
2023-05-12T20:36:31.452Z,1683923791.452 [Reporter](INFO): platform_buoyancy_position 544.039246 cc
2023-05-12T20:36:31.821Z,1683923791.821 [Reporter](INFO): platform_buoyancy_position 550.351318 cc
2023-05-12T20:36:32.224Z,1683923792.224 [Reporter](INFO): platform_buoyancy_position 554.783203 cc
2023-05-12T20:36:32.650Z,1683923792.650 [Reporter](INFO): platform_buoyancy_position 561.095337 cc
2023-05-12T20:36:33.019Z,1683923793.019 [Reporter](INFO): platform_buoyancy_position 565.392944 cc
2023-05-12T20:36:33.437Z,1683923793.437 [Reporter](INFO): platform_buoyancy_position 569.824829 cc
2023-05-12T20:36:33.814Z,1683923793.814 [Reporter](INFO): platform_buoyancy_position 576.136902 cc
2023-05-12T20:36:34.222Z,1683923794.222 [Reporter](INFO): platform_buoyancy_position 580.568848 cc
2023-05-12T20:36:34.638Z,1683923794.638 [Reporter](INFO): platform_buoyancy_position 586.880920 cc
2023-05-12T20:36:34.875Z,1683923794.875 [DataOverHttps](INFO): Sending 233 bytes from file Logs/20230512T161716/Express0074.lzma
2023-05-12T20:36:35.010Z,1683923795.010 [Reporter](INFO): platform_buoyancy_position 591.178528 cc
2023-05-12T20:36:35.478Z,1683923795.478 [Reporter](INFO): platform_buoyancy_position 597.624939 cc
2023-05-12T20:36:35.842Z,1683923795.842 [Reporter](INFO): platform_buoyancy_position 601.922546 cc
2023-05-12T20:36:35.878Z,1683923795.878 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0074.lzma.bak
2023-05-12T20:36:35.878Z,1683923795.878 [DataOverHttps](INFO): SBD MOMSN=18301221
2023-05-12T20:36:36.250Z,1683923796.250 [Reporter](INFO): platform_buoyancy_position 606.354431 cc
2023-05-12T20:36:36.678Z,1683923796.678 [Reporter](INFO): platform_buoyancy_position 612.666504 cc
2023-05-12T20:36:37.105Z,1683923797.105 [Reporter](INFO): platform_buoyancy_position 619.112915 cc
2023-05-12T20:36:37.590Z,1683923797.590 [Reporter](INFO): platform_buoyancy_position 625.559326 cc
2023-05-12T20:36:37.933Z,1683923797.933 [Reporter](INFO): platform_buoyancy_position 629.856934 cc
2023-05-12T20:36:38.316Z,1683923798.316 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T20:36:38.317Z,1683923798.317 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T20:36:38.317Z,1683923798.317 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T20:36:38.410Z,1683923798.410 [Reporter](INFO): platform_buoyancy_position 634.691711 cc
2023-05-12T20:36:38.745Z,1683923798.745 [Reporter](INFO): platform_buoyancy_position 640.735229 cc
2023-05-12T20:36:39.082Z,1683923799.082 [Reporter](INFO): platform_buoyancy_position 644.898499 cc
2023-05-12T20:36:39.502Z,1683923799.502 [Reporter](INFO): platform_buoyancy_position 649.464722 cc
2023-05-12T20:36:39.886Z,1683923799.886 [Reporter](INFO): platform_buoyancy_position 655.642517 cc
2023-05-12T20:36:40.386Z,1683923800.386 [Reporter](INFO): platform_buoyancy_position 661.820312 cc
2023-05-12T20:36:40.866Z,1683923800.866 [Reporter](INFO): platform_buoyancy_position 667.998108 cc
2023-05-12T20:36:41.187Z,1683923801.187 [Reporter](INFO): platform_buoyancy_position 671.087036 cc
2023-05-12T20:36:41.559Z,1683923801.559 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-12T20:36:41.778Z,1683923801.778 [Reporter](INFO): platform_buoyancy_position 679.413635 cc
2023-05-12T20:36:42.056Z,1683923802.056 [Reporter](INFO): platform_buoyancy_position 683.576904 cc
2023-05-12T20:36:42.561Z,1683923802.561 [Reporter](INFO): platform_buoyancy_position 690.023315 cc
2023-05-12T20:36:42.816Z,1683923802.816 [Reporter](INFO): platform_buoyancy_position 692.575012 cc
2023-05-12T20:36:43.233Z,1683923803.233 [Reporter](INFO): platform_buoyancy_position 698.752808 cc
2023-05-12T20:36:43.653Z,1683923803.653 [Reporter](INFO): platform_buoyancy_position 704.662048 cc
2023-05-12T20:36:43.995Z,1683923803.995 [Reporter](INFO): platform_buoyancy_position 709.362549 cc
2023-05-12T20:36:44.505Z,1683923804.505 [Reporter](INFO): platform_buoyancy_position 715.808960 cc
2023-05-12T20:36:44.834Z,1683923804.834 [Reporter](INFO): platform_buoyancy_position 720.240845 cc
2023-05-12T20:36:45.266Z,1683923805.266 [Reporter](INFO): platform_buoyancy_position 725.881409 cc
2023-05-12T20:36:45.741Z,1683923805.741 [Reporter](INFO): platform_buoyancy_position 730.984863 cc
2023-05-12T20:36:46.077Z,1683923806.077 [Reporter](INFO): platform_buoyancy_position 735.282410 cc
2023-05-12T20:36:46.527Z,1683923806.527 [Reporter](INFO): platform_buoyancy_position 741.594543 cc
2023-05-12T20:36:46.894Z,1683923806.894 [Reporter](INFO): platform_buoyancy_position 746.160706 cc
2023-05-12T20:36:47.302Z,1683923807.302 [Reporter](INFO): platform_buoyancy_position 752.472839 cc
2023-05-12T20:36:47.726Z,1683923807.726 [Reporter](INFO): platform_buoyancy_position 756.904724 cc
2023-05-12T20:36:48.071Z,1683923808.071 [Reporter](INFO): platform_buoyancy_position 761.202332 cc
2023-05-12T20:36:48.483Z,1683923808.483 [Reporter](INFO): platform_buoyancy_position 767.380127 cc
2023-05-12T20:36:48.838Z,1683923808.838 [Reporter](INFO): platform_buoyancy_position 771.812012 cc
2023-05-12T20:36:49.263Z,1683923809.263 [Reporter](INFO): platform_buoyancy_position 778.124146 cc
2023-05-12T20:36:49.639Z,1683923809.639 [Reporter](INFO): platform_buoyancy_position 782.690369 cc
2023-05-12T20:36:50.078Z,1683923810.078 [Reporter](INFO): platform_buoyancy_position 788.868164 cc
2023-05-12T20:36:50.502Z,1683923810.502 [Reporter](INFO): platform_buoyancy_position 793.434326 cc
2023-05-12T20:36:50.870Z,1683923810.870 [Reporter](INFO): platform_buoyancy_position 799.612122 cc
2023-05-12T20:36:51.322Z,1683923811.322 [Reporter](INFO): platform_buoyancy_position 804.178345 cc
2023-05-12T20:36:51.686Z,1683923811.686 [Reporter](INFO): platform_buoyancy_position 810.356140 cc
2023-05-12T20:36:52.082Z,1683923812.082 [Reporter](INFO): platform_buoyancy_position 814.788025 cc
2023-05-12T20:36:52.530Z,1683923812.530 [Reporter](INFO): platform_buoyancy_position 821.100159 cc
2023-05-12T20:36:52.958Z,1683923812.958 [Reporter](INFO): platform_buoyancy_position 826.069214 cc
2023-05-12T20:36:53.507Z,1683923813.507 [Reporter](INFO): platform_buoyancy_position 833.992920 cc
2023-05-12T20:36:53.812Z,1683923813.812 [Reporter](INFO): platform_buoyancy_position 838.290527 cc
2023-05-12T20:36:54.247Z,1683923814.247 [Reporter](INFO): platform_buoyancy_position 842.588135 cc
2023-05-12T20:36:54.611Z,1683923814.611 [Reporter](INFO): platform_buoyancy_position 847.825867 cc
2023-05-12T20:36:55.034Z,1683923815.034 [Reporter](INFO): platform_buoyancy_position 853.332153 cc
2023-05-12T20:36:55.445Z,1683923815.445 [Reporter](INFO): platform_buoyancy_position 859.375671 cc
2023-05-12T20:36:55.878Z,1683923815.878 [Reporter](INFO): platform_buoyancy_position 864.344727 cc
2023-05-12T20:36:56.284Z,1683923816.284 [Reporter](INFO): platform_buoyancy_position 868.373718 cc
2023-05-12T20:36:56.645Z,1683923816.645 [Reporter](INFO): platform_buoyancy_position 874.820129 cc
2023-05-12T20:36:57.015Z,1683923817.015 [Reporter](INFO): platform_buoyancy_position 879.252075 cc
2023-05-12T20:36:57.464Z,1683923817.464 [Reporter](INFO): platform_buoyancy_position 885.564148 cc
2023-05-12T20:36:57.918Z,1683923817.918 [Reporter](INFO): platform_buoyancy_position 892.010559 cc
2023-05-12T20:36:58.444Z,1683923818.444 [Reporter](INFO): platform_buoyancy_position 898.591248 cc
2023-05-12T20:36:58.638Z,1683923818.638 [Reporter](INFO): platform_buoyancy_position 900.740051 cc
2023-05-12T20:36:59.046Z,1683923819.046 [Reporter](INFO): platform_buoyancy_position 907.052124 cc
2023-05-12T20:36:59.641Z,1683923819.641 [Reporter](INFO): platform_buoyancy_position 913.632874 cc
2023-05-12T20:36:59.863Z,1683923819.863 [Reporter](INFO): platform_buoyancy_position 917.796143 cc
2023-05-12T20:37:00.343Z,1683923820.343 [Reporter](INFO): platform_buoyancy_position 924.108276 cc
2023-05-12T20:37:00.722Z,1683923820.722 [Reporter](INFO): platform_buoyancy_position 928.540161 cc
2023-05-12T20:37:01.135Z,1683923821.135 [Reporter](INFO): platform_buoyancy_position 933.106323 cc
2023-05-12T20:37:01.566Z,1683923821.566 [Reporter](INFO): platform_buoyancy_position 939.284180 cc
2023-05-12T20:37:01.946Z,1683923821.946 [Reporter](INFO): platform_buoyancy_position 943.581787 cc
2023-05-12T20:37:02.362Z,1683923822.362 [Reporter](INFO): platform_buoyancy_position 947.879395 cc
2023-05-12T20:37:45.842Z,1683923865.842 [DVL_micro](ERROR): only read 2 of 4 data items
2023-05-12T20:37:45.842Z,1683923865.842 [DVL_micro](ERROR): Failed to parse:
:RD,+0000.32,+0010..04,+0011.25
2023-05-12T20:39:16.787Z,1683923956.787 [DVL_micro](ERROR): Failed to parse:
:SA,-04.14,+05.81,084.6
2023-05-12T20:40:46.093Z,1683924046.093 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T20:40:46.093Z,1683924046.093 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,.1,0000.0,1489.0,000
2023-05-12T20:41:04.660Z,1683924064.660 [DVL_micro](ERROR): only read 1 of 4 data items
2023-05-12T20:41:04.660Z,1683924064.660 [DVL_micro](ERROR): Failed to parse:
:RD,+0000.32,,+0005.59,+0005.53
2023-05-12T20:41:38.998Z,1683924098.998 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-12T20:41:38.998Z,1683924098.998 [Default:CheckIn:C.Wait] Stopped
2023-05-12T20:41:38.998Z,1683924098.998 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T20:41:38.998Z,1683924098.998 [Default:CheckIn:D] Running Loop=1
2023-05-12T20:41:39.412Z,1683924099.412 [Default:CheckIn:D] Stopped
2023-05-12T20:41:39.413Z,1683924099.413 [Default:CheckIn:E] Running Loop=1
2023-05-12T20:41:39.812Z,1683924099.812 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 154.148779 min 
2023-05-12T20:41:39.812Z,1683924099.812 [Default:CheckIn:E] Stopped
2023-05-12T20:41:39.813Z,1683924099.813 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-12T20:41:39.813Z,1683924099.813 [Default:CheckIn] Stopped
2023-05-12T20:41:39.813Z,1683924099.813 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T20:41:39.813Z,1683924099.813 [Default:CheckIn](INFO): Running loop #18
2023-05-12T20:41:39.813Z,1683924099.813 [Default:CheckIn] Running Loop=18
2023-05-12T20:41:39.813Z,1683924099.813 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T20:41:39.813Z,1683924099.813 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T20:41:41.816Z,1683924101.816 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204131.00,A,3648.16211,N,12147.28886,W,0.622,49.68,120523,,,D*4F
2023-05-12T20:41:41.818Z,1683924101.818 [NAL9602](INFO): GPS fix at 20230512T204131: (36.802702, -121.788148)
2023-05-12T20:41:41.829Z,1683924101.829 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T20:41:41.829Z,1683924101.829 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T20:41:49.879Z,1683924109.879 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230512T161716/Courier0076.lzma
2023-05-12T20:41:50.882Z,1683924110.882 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0076.lzma.bak
2023-05-12T20:41:50.882Z,1683924110.882 [DataOverHttps](INFO): SBD MOMSN=18301227
2023-05-12T20:42:07.015Z,1683924127.015 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20230512T161716/Express0077.lzma
2023-05-12T20:42:08.018Z,1683924128.018 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0077.lzma.bak
2023-05-12T20:42:08.018Z,1683924128.018 [DataOverHttps](INFO): SBD MOMSN=18301230
2023-05-12T20:42:09.707Z,1683924129.707 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T20:42:09.708Z,1683924129.708 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T20:42:09.708Z,1683924129.708 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T20:42:12.533Z,1683924132.533 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2023-05-12T20:42:12.616Z,1683924132.616 [NAL9602](ERROR): received: 
+CSQ:0

OK57, 2, 0, 0, 0

OK
2023-05-12T20:43:08.763Z,1683924188.763 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T20:43:08.764Z,1683924188.764 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+19.1,489.0,000
2023-05-12T20:43:51.175Z,1683924231.175 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T20:43:51.176Z,1683924231.176 [DVL_micro](ERROR): Failed to parse:
:TS00000009.1,0000.0,10
2023-05-12T20:44:41.714Z,1683924281.714 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T20:44:41.714Z,1683924281.714 [DVL_micro](ERROR): Failed to parse:
:RD,+00010.43,+0006.08,+0005.30
2023-05-12T20:45:21.343Z,1683924321.343 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T20:45:21.343Z,1683924321.343 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+19.1,0000.0,148

2023-05-12T20:45:57.792Z,1683924357.792 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,0.00,+00000000.00,0000.20,000.00
2023-05-12T20:46:44.580Z,1683924404.580 [DVL_micro](ERROR): Failed to parse:
05,-01034,-00417,+00000,I
2023-05-12T20:46:44.582Z,1683924404.582 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-12T20:46:56.355Z,1683924416.355 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T20:46:56.355Z,1683924416.355 [DVL_micro](ERROR): Failed to parse:
:BI,-00611,+00277,+00082,+0:BD,+00000000.00,+00000000.00,+00000000.20,000.00
2023-05-12T20:46:59.179Z,1683924419.179 [DVL_micro](ERROR): Failed to parse:
:WI,+00142,+00343,+00138,+00000,A
2023-05-12T20:47:10.120Z,1683924430.120 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-12T20:47:10.120Z,1683924430.120 [Default:CheckIn:C.Wait] Stopped
2023-05-12T20:47:10.120Z,1683924430.120 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T20:47:10.120Z,1683924430.120 [Default:CheckIn:D] Running Loop=1
2023-05-12T20:47:10.499Z,1683924430.499 [Default:CheckIn:D] Stopped
2023-05-12T20:47:10.499Z,1683924430.499 [Default:CheckIn:E] Running Loop=1
2023-05-12T20:47:10.903Z,1683924430.903 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 159.666878 min 
2023-05-12T20:47:10.903Z,1683924430.903 [Default:CheckIn:E] Stopped
2023-05-12T20:47:10.903Z,1683924430.903 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-12T20:47:10.903Z,1683924430.903 [Default:CheckIn] Stopped
2023-05-12T20:47:10.904Z,1683924430.904 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T20:47:10.904Z,1683924430.904 [Default:CheckIn](INFO): Running loop #19
2023-05-12T20:47:10.904Z,1683924430.904 [Default:CheckIn] Running Loop=19
2023-05-12T20:47:10.904Z,1683924430.904 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T20:47:10.904Z,1683924430.904 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T20:47:12.942Z,1683924432.942 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204702.00,A,3648.15797,N,12147.28447,W,0.797,49.68,120523,,,A*4A
2023-05-12T20:47:12.944Z,1683924432.944 [NAL9602](INFO): GPS fix at 20230512T204702: (36.802633, -121.788074)
2023-05-12T20:47:12.955Z,1683924432.955 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T20:47:12.955Z,1683924432.955 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T20:47:20.315Z,1683924440.315 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230512T161716/Courier0079.lzma
2023-05-12T20:47:21.314Z,1683924441.314 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0079.lzma.bak
2023-05-12T20:47:21.314Z,1683924441.314 [DataOverHttps](INFO): SBD MOMSN=18301239
2023-05-12T20:47:37.371Z,1683924457.371 [DataOverHttps](INFO): Sending 205 bytes from file Logs/20230512T161716/Express0080.lzma
2023-05-12T20:47:38.374Z,1683924458.374 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0080.lzma.bak
2023-05-12T20:47:38.374Z,1683924458.374 [DataOverHttps](INFO): SBD MOMSN=18301242
2023-05-12T20:47:40.004Z,1683924460.004 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T20:47:40.004Z,1683924460.004 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T20:47:40.004Z,1683924460.004 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T20:47:45.671Z,1683924465.671 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-12T20:48:26.467Z,1683924506.467 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T20:48:26.468Z,1683924506.468 [DVL_micro](ERROR): Failed to parse:
:BI,+00282,-00187,+00031,+00000+00000000.00,+00000000.00,+00000000.00,0000.20,000.00
2023-05-12T20:49:56.308Z,1683924596.308 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T20:49:56.309Z,1683924596.309 [DVL_micro](ERROR): Failed to parse:
:TS,000000,35.0,+19.2,0000.0,1489.0I,+0000,+00000,+00000,I
2023-05-12T20:52:40.853Z,1683924760.853 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-12T20:52:40.853Z,1683924760.853 [Default:CheckIn:C.Wait] Stopped
2023-05-12T20:52:40.853Z,1683924760.853 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T20:52:40.853Z,1683924760.853 [Default:CheckIn:D] Running Loop=1
2023-05-12T20:52:41.233Z,1683924761.233 [Default:CheckIn:D] Stopped
2023-05-12T20:52:41.233Z,1683924761.233 [Default:CheckIn:E] Running Loop=1
2023-05-12T20:52:41.651Z,1683924761.651 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 165.179118 min 
2023-05-12T20:52:41.651Z,1683924761.651 [Default:CheckIn:E] Stopped
2023-05-12T20:52:41.651Z,1683924761.651 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-12T20:52:41.656Z,1683924761.656 [Default:CheckIn] Stopped
2023-05-12T20:52:41.656Z,1683924761.656 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T20:52:41.656Z,1683924761.656 [Default:CheckIn](INFO): Running loop #20
2023-05-12T20:52:41.656Z,1683924761.656 [Default:CheckIn] Running Loop=20
2023-05-12T20:52:41.656Z,1683924761.656 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T20:52:41.657Z,1683924761.657 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T20:52:43.621Z,1683924763.621 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,205232.00,A,3648.16121,N,12147.28637,W,0.816,49.68,120523,,,A*46
2023-05-12T20:52:43.623Z,1683924763.623 [NAL9602](INFO): GPS fix at 20230512T205232: (36.802687, -121.788106)
2023-05-12T20:52:43.638Z,1683924763.638 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T20:52:43.638Z,1683924763.638 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T20:52:52.751Z,1683924772.751 [DVL_micro](ERROR): Failed to parse:
:WI,-00958,+00979,+00395,+00000,A
2023-05-12T20:52:55.267Z,1683924775.267 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230512T161716/Courier0082.lzma
2023-05-12T20:52:56.270Z,1683924776.270 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0082.lzma.bak
2023-05-12T20:52:56.270Z,1683924776.270 [DataOverHttps](INFO): SBD MOMSN=18301250
2023-05-12T20:53:13.295Z,1683924793.295 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20230512T161716/Express0083.lzma
2023-05-12T20:53:14.290Z,1683924794.290 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Express0083.lzma.bak
2023-05-12T20:53:14.290Z,1683924794.290 [DataOverHttps](INFO): SBD MOMSN=18301253
2023-05-12T20:53:15.767Z,1683924795.767 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T20:53:15.796Z,1683924795.796 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-12T20:53:15.796Z,1683924795.796 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-12T20:54:33.315Z,1683924873.315 [BPC1](ERROR): BPC1A: No match for serial number 1717 in BPC1A's battery stick inventory (sticks 1-31 in onboard configuration file).
2023-05-12T20:54:47.062Z,1683924887.062 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2023-05-12T20:54:47.064Z,1683924887.064 [BPC1](INFO): Received data from all battery sticks.
2023-05-12T20:56:01.890Z,1683924961.890 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-12T20:56:01.890Z,1683924961.890 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+19.1,0000.0000
2023-05-12T20:57:40.920Z,1683925060.920 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T20:57:40.920Z,1683925060.920 [DVL_micro](ERROR): Failed to parse:
:RD,+0000.32,+0001.18,+00001.22
2023-05-12T20:57:42.943Z,1683925062.943 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-12T20:57:42.943Z,1683925062.943 [DVL_micro](ERROR): Failed to parse:
:BI,+00000,+0000,+00000,I
2023-05-12T20:57:45.825Z,1683925065.825 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-12T20:58:16.473Z,1683925096.473 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-12T20:58:16.513Z,1683925096.513 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-12T20:58:16.513Z,1683925096.513 [Default:CheckIn:C.Wait] Stopped
2023-05-12T20:58:16.513Z,1683925096.513 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T20:58:16.513Z,1683925096.513 [Default:CheckIn:D] Running Loop=1
2023-05-12T20:58:16.879Z,1683925096.879 [Default:CheckIn:D] Stopped
2023-05-12T20:58:16.879Z,1683925096.879 [Default:CheckIn:E] Running Loop=1
2023-05-12T20:58:17.291Z,1683925097.291 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 170.773210 min 
2023-05-12T20:58:17.291Z,1683925097.291 [Default:CheckIn:E] Stopped
2023-05-12T20:58:17.291Z,1683925097.291 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-12T20:58:17.291Z,1683925097.291 [Default:CheckIn] Stopped
2023-05-12T20:58:17.291Z,1683925097.291 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T20:58:17.292Z,1683925097.292 [Default:CheckIn](INFO): Running loop #21
2023-05-12T20:58:17.292Z,1683925097.292 [Default:CheckIn] Running Loop=21
2023-05-12T20:58:17.292Z,1683925097.292 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T20:58:17.292Z,1683925097.292 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T20:58:19.294Z,1683925099.294 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,205808.00,A,3648.15472,N,12147.28313,W,0.428,49.68,120523,,,A*47
2023-05-12T20:58:19.297Z,1683925099.297 [NAL9602](INFO): GPS fix at 20230512T205808: (36.802579, -121.788052)
2023-05-12T20:58:19.353Z,1683925099.353 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T20:58:19.353Z,1683925099.353 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T20:58:26.705Z,1683925106.705 [DataOverHttps](INFO): Sending 84 bytes from file Logs/20230512T161716/Courier0085.lzma
2023-05-12T20:58:27.702Z,1683925107.702 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161716/Courier0085.lzma.bak
2023-05-12T20:58:27.702Z,1683925107.702 [DataOverHttps](IMPORTANT): SBD MOMSN=18301266, MTMSN=20230512T205816
2023-05-12T20:58:35.176Z,1683925115.176 [DataOverHttps](INFO): Received command: restart sys
2023-05-12T20:58:35.225Z,1683925115.225 [CommandExec](IMPORTANT): got command restart system
2023-05-12T20:58:37.464Z,1683925117.464 [CommandExec ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-12T20:58:37.464Z,1683925117.464 [CommandExec](INFO): Uninitializing the command executive.
2023-05-12T20:58:37.464Z,1683925117.464 [CommandExec](INFO): Uninitializing the command scheduler.
2023-05-12T20:58:37.465Z,1683925117.465 [CommandExec ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:37.528Z,1683925117.528 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2023-05-12T20:58:37.528Z,1683925117.528 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2023-05-12T20:58:37.528Z,1683925117.528 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:37.530Z,1683925117.530 [NavChartDb](INFO): Join timeout helper Thread ID is 8416
2023-05-12T20:58:37.688Z,1683925117.688 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-12T20:58:37.688Z,1683925117.688 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:37.704Z,1683925117.704 [ComponentRegistry](INFO): Shutting down DAT ThreadHandler
2023-05-12T20:58:37.704Z,1683925117.704 [DAT ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:37.705Z,1683925117.705 [DAT](INFO): Join timeout helper Thread ID is 8417
2023-05-12T20:58:37.732Z,1683925117.732 [DAT](INFO): Powering down
2023-05-12T20:58:37.733Z,1683925117.733 [DAT ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-12T20:58:37.733Z,1683925117.733 [DAT](INFO): Powering down
2023-05-12T20:58:37.734Z,1683925117.734 [DAT ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:37.752Z,1683925117.752 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2023-05-12T20:58:37.752Z,1683925117.752 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:37.752Z,1683925117.752 [Radio_Surface](INFO): Join timeout helper Thread ID is 8418
2023-05-12T20:58:38.072Z,1683925118.072 [Radio_Surface](INFO): Powering down
2023-05-12T20:58:38.073Z,1683925118.073 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-12T20:58:38.074Z,1683925118.074 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:38.088Z,1683925118.088 [ComponentRegistry](INFO): Shutting down Onboard ThreadHandler
2023-05-12T20:58:38.088Z,1683925118.088 [Onboard ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:38.088Z,1683925118.088 [Onboard](INFO): Join timeout helper Thread ID is 8419
2023-05-12T20:58:41.700Z,1683925121.700 [Onboard ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-12T20:58:41.700Z,1683925121.700 [Onboard ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:41.701Z,1683925121.701 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2023-05-12T20:58:41.701Z,1683925121.701 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:41.701Z,1683925121.701 [DataOverHttps](INFO): Join timeout helper Thread ID is 8420
2023-05-12T20:58:42.200Z,1683925122.200 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-12T20:58:42.201Z,1683925122.201 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:42.209Z,1683925122.209 [ComponentRegistry](INFO): Shutting down BackseatComponent ThreadHandler
2023-05-12T20:58:42.209Z,1683925122.209 [BackseatComponent ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:42.209Z,1683925122.209 [BackseatComponent](INFO): Join timeout helper Thread ID is 8421
2023-05-12T20:58:42.404Z,1683925122.404 [BackseatComponent ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-12T20:58:42.404Z,1683925122.404 [BackseatComponent ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:42.409Z,1683925122.409 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2023-05-12T20:58:42.409Z,1683925122.409 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:42.409Z,1683925122.409 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 8422
2023-05-12T20:58:42.580Z,1683925122.580 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-12T20:58:42.580Z,1683925122.580 [WetLabsBB2FL](INFO): Powering down
2023-05-12T20:58:42.581Z,1683925122.581 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:42.597Z,1683925122.597 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2023-05-12T20:58:42.597Z,1683925122.597 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:42.597Z,1683925122.597 [CTD_Seabird](INFO): Join timeout helper Thread ID is 8423
2023-05-12T20:58:42.608Z,1683925122.608 [CTD_Seabird](INFO): Powering down
2023-05-12T20:58:42.620Z,1683925122.620 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-12T20:58:42.620Z,1683925122.620 [CTD_Seabird](INFO): Powering down
2023-05-12T20:58:42.632Z,1683925122.632 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:42.645Z,1683925122.645 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2023-05-12T20:58:42.645Z,1683925122.645 [logger ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:42.645Z,1683925122.645 [logger](INFO): Join timeout helper Thread ID is 8424
2023-05-12T20:58:42.678Z,1683925122.678 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-12T20:58:42.678Z,1683925122.678 [logger ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:42.689Z,1683925122.689 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2023-05-12T20:58:42.689Z,1683925122.689 [CommandLine ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:42.689Z,1683925122.689 [CommandLine](INFO): Join timeout helper Thread ID is 8425
2023-05-12T20:58:42.776Z,1683925122.776 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-12T20:58:42.776Z,1683925122.776 [CommandLine ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:42.789Z,1683925122.789 [ComponentRegistry](INFO): Shutting down CommandExec ThreadHandler
2023-05-12T20:58:42.789Z,1683925122.789 [CommandExec ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:42.789Z,1683925122.789 [CommandExec](INFO): Join timeout helper Thread ID is 8426
2023-05-12T20:58:42.790Z,1683925122.790 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2023-05-12T20:58:42.790Z,1683925122.790 [controlThread ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:42.791Z,1683925122.791 [controlThread](INFO): Join timeout helper Thread ID is 8427
2023-05-12T20:58:42.880Z,1683925122.880 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-12T20:58:42.880Z,1683925122.880 [controlThread](DEBUG): Uninitializing ControlThread
2023-05-12T20:58:42.882Z,1683925122.882 [AHRS_M2](INFO): Powering down
2023-05-12T20:58:43.024Z,1683925123.024 [DVL_micro](INFO): Powering down
2023-05-12T20:58:43.025Z,1683925123.025 [NAL9602](INFO): Powering down
2023-05-12T20:58:43.027Z,1683925123.027 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2023-05-12T20:58:43.028Z,1683925123.028 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2023-05-12T20:58:43.029Z,1683925123.029 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2023-05-12T20:58:43.029Z,1683925123.029 [MissionManager](INFO): Uninitializing Mission Default
2023-05-12T20:58:43.029Z,1683925123.029 [Default] Stopped
2023-05-12T20:58:43.029Z,1683925123.029 [Default](DEBUG): Aggregate::uninitialize Default
2023-05-12T20:58:43.029Z,1683925123.029 [Default:B.GoToSurface] Stopped
2023-05-12T20:58:43.030Z,1683925123.030 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2023-05-12T20:58:43.030Z,1683925123.030 [Default:CheckIn] Stopped
2023-05-12T20:58:43.030Z,1683925123.030 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-12T20:58:43.030Z,1683925123.030 [Default:CheckIn:Read_Iridium] Stopped
2023-05-12T20:58:43.033Z,1683925123.033 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2023-05-12T20:58:43.033Z,1683925123.033 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2023-05-12T20:58:43.033Z,1683925123.033 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2023-05-12T20:58:43.034Z,1683925123.034 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2023-05-12T20:58:43.034Z,1683925123.034 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2023-05-12T20:58:43.034Z,1683925123.034 [BuoyancyServo](INFO): Powering down
2023-05-12T20:58:43.048Z,1683925123.048 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2023-05-12T20:58:43.048Z,1683925123.048 [ElevatorServo](INFO): Powering down
2023-05-12T20:58:43.049Z,1683925123.049 [MassServo](DEBUG): Uninitialize Mass Servo.
2023-05-12T20:58:43.049Z,1683925123.049 [MassServo](INFO): Powering down
2023-05-12T20:58:43.050Z,1683925123.050 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2023-05-12T20:58:43.050Z,1683925123.050 [RudderServo](INFO): Powering down
2023-05-12T20:58:43.051Z,1683925123.051 [ThrusterHE](DEBUG): Uninitialize Thruster Servo.
2023-05-12T20:58:43.052Z,1683925123.052 [ThrusterHE](INFO): Powering down
2023-05-12T20:58:43.053Z,1683925123.053 [SBIT](DEBUG): Uninitialize SBIT Component.
2023-05-12T20:58:43.053Z,1683925123.053 [IBIT](DEBUG): Uninitialize IBIT Component.
2023-05-12T20:58:43.053Z,1683925123.053 [CBIT](DEBUG): Uninitialize CBIT Component.
2023-05-12T20:58:43.053Z,1683925123.053 [CBIT](DEBUG): Powering off loads.
2023-05-12T20:58:43.068Z,1683925123.068 [CBIT](DEBUG): Disabling WDT.
2023-05-12T20:58:43.080Z,1683925123.080 [CBIT](DEBUG): Opening all GF detection circuits.
2023-05-12T20:58:43.081Z,1683925123.081 [controlThread ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:43.138Z,1683925123.138 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:43.289Z,1683925123.289 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:43.334Z,1683925123.334 [DAT ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:43.338Z,1683925123.338 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:43.346Z,1683925123.346 [Onboard ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:43.354Z,1683925123.354 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:43.424Z,1683925123.424 [BackseatComponent ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:43.509Z,1683925123.509 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2023-05-12T20:58:43.620Z,1683925123.620 [logger ThreadHandler](INFO): Thread cancelled.