2025-05-29T18:16:14.799Z,1748542574.799 [Supervisor](DEBUG): Initializing supervisor.
2025-05-29T18:16:14.803Z,1748542574.803 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2025-05-29T18:16:14.804Z,1748542574.804 [SyncHandler](INFO): Protected caller Thread ID is 829
2025-05-29T18:16:14.804Z,1748542574.804 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2025-05-29T18:16:14.805Z,1748542574.805 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2025-05-29T18:16:14.805Z,1748542574.805 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 830
2025-05-29T18:16:14.809Z,1748542574.809 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2025-05-29T18:16:14.830Z,1748542574.830 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread.
2025-05-29T18:16:14.831Z,1748542574.831 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2025-05-29T18:16:14.831Z,1748542574.831 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 831
2025-05-29T18:16:14.835Z,1748542574.835 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2025-05-29T18:16:14.836Z,1748542574.836 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2025-05-29T18:16:14.837Z,1748542574.837 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 832
2025-05-29T18:16:14.839Z,1748542574.839 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2025-05-29T18:16:14.840Z,1748542574.840 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0
2025-05-29T18:16:14.840Z,1748542574.840 [logger ThreadHandler](INFO): Protected caller Thread ID is 833
2025-05-29T18:16:14.844Z,1748542574.844 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2025-05-29T18:16:14.844Z,1748542574.844 [Supervisor](INFO): Looking for Config files in directory: Config/
2025-05-29T18:16:14.850Z,1748542574.850 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2025-05-29T18:16:14.957Z,1748542574.957 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2025-05-29T18:16:14.959Z,1748542574.959 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2025-05-29T18:16:15.195Z,1748542575.195 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2025-05-29T18:16:15.197Z,1748542575.197 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2025-05-29T18:16:15.473Z,1748542575.473 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2025-05-29T18:16:15.475Z,1748542575.475 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2025-05-29T18:16:15.592Z,1748542575.592 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2025-05-29T18:16:15.594Z,1748542575.594 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2025-05-29T18:16:16.373Z,1748542576.373 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2025-05-29T18:16:16.374Z,1748542576.374 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2025-05-29T18:16:16.902Z,1748542576.902 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2025-05-29T18:16:16.903Z,1748542576.903 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2025-05-29T18:16:17.474Z,1748542577.474 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2025-05-29T18:16:17.474Z,1748542577.474 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2025-05-29T18:16:17.910Z,1748542577.910 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2025-05-29T18:16:18.194Z,1748542578.194 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2025-05-29T18:16:18.706Z,1748542578.706 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2025-05-29T18:16:18.708Z,1748542578.708 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2025-05-29T18:16:19.102Z,1748542579.102 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2025-05-29T18:16:19.103Z,1748542579.103 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2025-05-29T18:16:19.341Z,1748542579.341 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2025-05-29T18:16:19.343Z,1748542579.343 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2025-05-29T18:16:19.495Z,1748542579.495 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2025-05-29T18:16:19.496Z,1748542579.496 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2025-05-29T18:16:19.589Z,1748542579.589 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2025-05-29T18:16:19.680Z,1748542579.680 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2025-05-29T18:16:19.882Z,1748542579.882 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2025-05-29T18:16:19.882Z,1748542579.882 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2025-05-29T18:16:20.148Z,1748542580.148 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2025-05-29T18:16:20.150Z,1748542580.150 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/
2025-05-29T18:16:20.153Z,1748542580.153 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/secure.cfg
2025-05-29T18:16:20.247Z,1748542580.247 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Battery.cfg
2025-05-29T18:16:20.525Z,1748542580.525 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2025-05-29T18:16:20.526Z,1748542580.526 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Navigation.cfg
2025-05-29T18:16:20.620Z,1748542580.620 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Sensor.cfg
2025-05-29T18:16:20.801Z,1748542580.801 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/vehicle.cfg
2025-05-29T18:16:20.911Z,1748542580.911 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Simulator.cfg
2025-05-29T18:16:21.031Z,1748542581.031 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Servo.cfg
2025-05-29T18:16:21.154Z,1748542581.154 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Control.cfg
2025-05-29T18:16:21.258Z,1748542581.258 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Science.cfg
2025-05-29T18:16:21.430Z,1748542581.430 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Derivation.cfg
2025-05-29T18:16:21.537Z,1748542581.537 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/workSite.cfg
2025-05-29T18:16:21.632Z,1748542581.632 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/logger.cfg
2025-05-29T18:16:21.740Z,1748542581.740 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/BIT.cfg
2025-05-29T18:16:21.838Z,1748542581.838 [Supervisor](IMPORTANT): Reloading configuration overrides from Data/persisted.cfg
2025-05-29T18:16:21.855Z,1748542581.855 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2025-05-29T18:16:22.077Z,1748542582.077 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2025-05-29T18:16:22.078Z,1748542582.078 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2025-05-29T18:16:22.311Z,1748542582.311 [BuoyancyServo] Loaded
2025-05-29T18:16:22.311Z,1748542582.311 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2025-05-29T18:16:22.335Z,1748542582.335 [ElevatorServo] Loaded
2025-05-29T18:16:22.335Z,1748542582.335 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2025-05-29T18:16:22.357Z,1748542582.357 [MassServo] Loaded
2025-05-29T18:16:22.358Z,1748542582.358 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2025-05-29T18:16:22.380Z,1748542582.380 [RudderServo] Loaded
2025-05-29T18:16:22.380Z,1748542582.380 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2025-05-29T18:16:22.398Z,1748542582.398 [ThrusterHE] Loaded
2025-05-29T18:16:22.398Z,1748542582.398 [ComponentRegistry](DEBUG): SyncComponent "ThrusterHE" handled in the control thread.
2025-05-29T18:16:22.399Z,1748542582.399 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2025-05-29T18:16:22.400Z,1748542582.400 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2025-05-29T18:16:22.600Z,1748542582.600 [SBIT](DEBUG): Construct Startup Built In Test.
2025-05-29T18:16:22.615Z,1748542582.615 [SBIT] Loaded
2025-05-29T18:16:22.615Z,1748542582.615 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2025-05-29T18:16:22.618Z,1748542582.618 [IBIT](DEBUG): Construct Initiated Built In Test.
2025-05-29T18:16:22.639Z,1748542582.639 [IBIT] Loaded
2025-05-29T18:16:22.640Z,1748542582.640 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2025-05-29T18:16:22.645Z,1748542582.645 [CBIT](DEBUG): Construct Continuous Built In Test.
2025-05-29T18:16:22.837Z,1748542582.837 [CBIT] Loaded
2025-05-29T18:16:22.837Z,1748542582.837 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2025-05-29T18:16:22.868Z,1748542582.868 [GFScanner] Loaded
2025-05-29T18:16:22.869Z,1748542582.869 [ComponentRegistry](DEBUG): SyncComponent "GFScanner" handled in the control thread.
2025-05-29T18:16:22.869Z,1748542582.869 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2025-05-29T18:16:22.870Z,1748542582.870 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2025-05-29T18:16:23.086Z,1748542583.086 [CTD_Seabird] Loaded
2025-05-29T18:16:23.086Z,1748542583.086 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2025-05-29T18:16:23.087Z,1748542583.087 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 406834E0
2025-05-29T18:16:23.088Z,1748542583.088 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 921
2025-05-29T18:16:23.122Z,1748542583.122 [ESPComponent] Loaded
2025-05-29T18:16:23.123Z,1748542583.123 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2025-05-29T18:16:23.145Z,1748542583.145 [PAR_Licor] Loaded
2025-05-29T18:16:23.145Z,1748542583.145 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2025-05-29T18:16:23.191Z,1748542583.191 [WetLabsBB2FL] Loaded
2025-05-29T18:16:23.191Z,1748542583.191 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2025-05-29T18:16:23.192Z,1748542583.192 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 406B34E0
2025-05-29T18:16:23.192Z,1748542583.192 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 922
2025-05-29T18:16:23.193Z,1748542583.193 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2025-05-29T18:16:23.194Z,1748542583.194 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2025-05-29T18:16:23.387Z,1748542583.387 [DepthRateCalculator] Loaded
2025-05-29T18:16:23.388Z,1748542583.388 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2025-05-29T18:16:23.402Z,1748542583.402 [PitchRateCalculator] Loaded
2025-05-29T18:16:23.402Z,1748542583.402 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2025-05-29T18:16:23.428Z,1748542583.428 [SpeedCalculator] Loaded
2025-05-29T18:16:23.428Z,1748542583.428 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2025-05-29T18:16:23.481Z,1748542583.481 [YawRateCalculator] Loaded
2025-05-29T18:16:23.481Z,1748542583.481 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2025-05-29T18:16:23.540Z,1748542583.540 [ElevatorOffsetCalculator] Loaded
2025-05-29T18:16:23.540Z,1748542583.540 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2025-05-29T18:16:23.541Z,1748542583.541 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2025-05-29T18:16:23.542Z,1748542583.542 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2025-05-29T18:16:23.959Z,1748542583.959 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2025-05-29T18:16:23.960Z,1748542583.960 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2025-05-29T18:16:24.008Z,1748542584.008 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2025-05-29T18:16:24.008Z,1748542584.008 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2025-05-29T18:16:24.148Z,1748542584.148 [DeadReckonUsingMultipleVelocitySources] Loaded
2025-05-29T18:16:24.148Z,1748542584.148 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2025-05-29T18:16:24.162Z,1748542584.162 [NavChart] Loaded
2025-05-29T18:16:24.162Z,1748542584.162 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2025-05-29T18:16:24.168Z,1748542584.168 [UniversalFixResidualReporter] Loaded
2025-05-29T18:16:24.168Z,1748542584.168 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2025-05-29T18:16:24.169Z,1748542584.169 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2025-05-29T18:16:24.169Z,1748542584.169 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2025-05-29T18:16:25.050Z,1748542585.050 [AHRS_M2] Loaded
2025-05-29T18:16:25.050Z,1748542585.050 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2025-05-29T18:16:25.303Z,1748542585.303 [BackseatComponent] Loaded
2025-05-29T18:16:25.303Z,1748542585.303 [ComponentRegistry](DEBUG): Component "BackseatComponent" handled in its own thread.
2025-05-29T18:16:25.304Z,1748542585.304 [BackseatComponent ThreadHandler](DEBUG): Created PCaller Thread at 40A7F4E0
2025-05-29T18:16:25.305Z,1748542585.305 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 923
2025-05-29T18:16:25.308Z,1748542585.308 [LcmUniversalReporter] Loaded
2025-05-29T18:16:25.308Z,1748542585.308 [ComponentRegistry](DEBUG): SyncComponent "LcmUniversalReporter" handled in the control thread.
2025-05-29T18:16:26.045Z,1748542586.045 [BPC1] Loaded
2025-05-29T18:16:26.045Z,1748542586.045 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2025-05-29T18:16:26.146Z,1748542586.146 [DAT] Loaded
2025-05-29T18:16:26.146Z,1748542586.146 [ComponentRegistry](DEBUG): Component "DAT" handled in its own thread.
2025-05-29T18:16:26.147Z,1748542586.147 [DAT ThreadHandler](DEBUG): Created PCaller Thread at 40AAF4E0
2025-05-29T18:16:26.148Z,1748542586.148 [DAT ThreadHandler](INFO): Protected caller Thread ID is 924
2025-05-29T18:16:26.290Z,1748542586.290 [DataOverHttps] Loaded
2025-05-29T18:16:26.290Z,1748542586.290 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2025-05-29T18:16:26.291Z,1748542586.291 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 40ADF4E0
2025-05-29T18:16:26.291Z,1748542586.291 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 925
2025-05-29T18:16:26.315Z,1748542586.315 [Depth_Keller] Loaded
2025-05-29T18:16:26.315Z,1748542586.315 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2025-05-29T18:16:26.320Z,1748542586.320 [DropWeight] Loaded
2025-05-29T18:16:26.320Z,1748542586.320 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2025-05-29T18:16:26.362Z,1748542586.362 [DVL_micro] Loaded
2025-05-29T18:16:26.362Z,1748542586.362 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2025-05-29T18:16:26.425Z,1748542586.425 [NAL9602] Loaded
2025-05-29T18:16:26.425Z,1748542586.425 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2025-05-29T18:16:26.451Z,1748542586.451 [Onboard] Loaded
2025-05-29T18:16:26.452Z,1748542586.452 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2025-05-29T18:16:26.453Z,1748542586.453 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 40B0F4E0
2025-05-29T18:16:26.453Z,1748542586.453 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 926
2025-05-29T18:16:26.459Z,1748542586.459 [PowerOnly](INFO): Adding load control power supply at /dev/loadB1
2025-05-29T18:16:26.473Z,1748542586.473 [PowerOnly] Loaded
2025-05-29T18:16:26.473Z,1748542586.473 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2025-05-29T18:16:26.487Z,1748542586.487 [Power24vConverter] Loaded
2025-05-29T18:16:26.487Z,1748542586.487 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread.
2025-05-29T18:16:26.504Z,1748542586.504 [Radio_Surface] Loaded
2025-05-29T18:16:26.504Z,1748542586.504 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2025-05-29T18:16:26.505Z,1748542586.505 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 40B3F4E0
2025-05-29T18:16:26.505Z,1748542586.505 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 927
2025-05-29T18:16:26.521Z,1748542586.521 [Sonardyne_Nano] Loaded
2025-05-29T18:16:26.521Z,1748542586.521 [ComponentRegistry](DEBUG): SyncComponent "Sonardyne_Nano" handled in the control thread.
2025-05-29T18:16:26.522Z,1748542586.522 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2025-05-29T18:16:26.523Z,1748542586.523 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2025-05-29T18:16:26.610Z,1748542586.610 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2025-05-29T18:16:26.611Z,1748542586.611 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2025-05-29T18:16:26.683Z,1748542586.683 [VerticalControl](DEBUG): Construct VerticalControl.
2025-05-29T18:16:26.736Z,1748542586.736 [VerticalControl] Loaded
2025-05-29T18:16:26.737Z,1748542586.737 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2025-05-29T18:16:26.740Z,1748542586.740 [HorizontalControl](DEBUG): Construct HorizontalControl.
2025-05-29T18:16:26.784Z,1748542586.784 [HorizontalControl] Loaded
2025-05-29T18:16:26.784Z,1748542586.784 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2025-05-29T18:16:26.787Z,1748542586.787 [SpeedControl](DEBUG): Construct SpeedControl.
2025-05-29T18:16:26.789Z,1748542586.789 [SpeedControl] Loaded
2025-05-29T18:16:26.789Z,1748542586.789 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2025-05-29T18:16:26.792Z,1748542586.792 [LoopControl](DEBUG): Construct LoopControl.
2025-05-29T18:16:26.792Z,1748542586.792 [LoopControl] Loaded
2025-05-29T18:16:26.792Z,1748542586.792 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2025-05-29T18:16:26.793Z,1748542586.793 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2025-05-29T18:16:26.794Z,1748542586.794 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2025-05-29T18:16:26.809Z,1748542586.809 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2025-05-29T18:16:26.810Z,1748542586.810 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2025-05-29T18:16:27.224Z,1748542587.224 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2025-05-29T18:16:27.231Z,1748542587.231 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2025-05-29T18:16:27.234Z,1748542587.234 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2025-05-29T18:16:27.245Z,1748542587.245 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2025-05-29T18:16:27.246Z,1748542587.246 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40C654E0
2025-05-29T18:16:27.246Z,1748542587.246 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 928
2025-05-29T18:16:27.251Z,1748542587.251 [Supervisor](INFO): Main Thread ID is 822
2025-05-29T18:16:27.251Z,1748542587.251 [Supervisor](DEBUG): Running supervisor.
2025-05-29T18:16:27.251Z,1748542587.251 [CommandExec ThreadHandler](INFO): Handler Thread ID is 929
2025-05-29T18:16:27.252Z,1748542587.252 [CommandExec](INFO): Initializing the command executive.
2025-05-29T18:16:27.254Z,1748542587.254 [CommandLine ThreadHandler](INFO): Handler Thread ID is 930
2025-05-29T18:16:27.256Z,1748542587.256 [controlThread ThreadHandler](INFO): Handler Thread ID is 931
2025-05-29T18:16:27.256Z,1748542587.256 [controlThread](DEBUG): Initializing ControlThread
2025-05-29T18:16:27.258Z,1748542587.258 [SBIT](INFO): Initialize SBIT Component.
2025-05-29T18:16:27.258Z,1748542587.258 [SBIT](IMPORTANT): git: 2025-05-12_B
2025-05-29T18:16:27.259Z,1748542587.259 [SBIT](INFO): git hash: 7c5b1c07405cfe7ca09821eb029d166d25d65d57
2025-05-29T18:16:27.259Z,1748542587.259 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2025-05-29T18:16:27.260Z,1748542587.260 [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
2025-05-29T18:16:27.261Z,1748542587.261 [SBIT](INFO): Beginning SBIT in 125.000000 seconds.
2025-05-29T18:16:27.262Z,1748542587.262 [IBIT](INFO): Initialize IBIT Component.
2025-05-29T18:16:27.263Z,1748542587.263 [CBIT](DEBUG): Initialize CBIT Component.
2025-05-29T18:16:27.264Z,1748542587.264 [logger ThreadHandler](INFO): Handler Thread ID is 932
2025-05-29T18:16:27.277Z,1748542587.277 [CBIT](DEBUG): Initialized mux pins.
2025-05-29T18:16:27.277Z,1748542587.277 [CBIT](DEBUG): Initializing the watchdog timer.
2025-05-29T18:16:27.289Z,1748542587.289 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 933
2025-05-29T18:16:27.290Z,1748542587.290 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2025-05-29T18:16:27.295Z,1748542587.295 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 935
2025-05-29T18:16:27.297Z,1748542587.297 [WetLabsBB2FL](INFO): Powering up
2025-05-29T18:16:27.299Z,1748542587.299 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 937
2025-05-29T18:16:27.301Z,1748542587.301 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2025-05-29T18:16:27.302Z,1748542587.302 [CBIT](DEBUG): Initializing heartbeat.
2025-05-29T18:16:27.315Z,1748542587.315 [DAT ThreadHandler](INFO): Handler Thread ID is 938
2025-05-29T18:16:27.316Z,1748542587.316 [DAT](INFO): Powering up
2025-05-29T18:16:27.316Z,1748542587.316 [DAT](DEBUG): Initializing DAT.
2025-05-29T18:16:27.322Z,1748542587.322 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 940
2025-05-29T18:16:27.324Z,1748542587.324 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2025-05-29T18:16:27.337Z,1748542587.337 [Onboard ThreadHandler](INFO): Handler Thread ID is 941
2025-05-29T18:16:27.356Z,1748542587.356 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 942
2025-05-29T18:16:27.373Z,1748542587.373 [CBIT](DEBUG): Deactivating emergency mode.
2025-05-29T18:16:27.385Z,1748542587.385 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 943
2025-05-29T18:16:27.393Z,1748542587.393 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2025-05-29T18:16:27.394Z,1748542587.394 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2025-05-29T18:16:27.394Z,1748542587.394 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2025-05-29T18:16:27.394Z,1748542587.394 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2025-05-29T18:16:27.394Z,1748542587.394 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2025-05-29T18:16:27.394Z,1748542587.394 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2025-05-29T18:16:27.394Z,1748542587.394 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2025-05-29T18:16:27.395Z,1748542587.395 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2025-05-29T18:16:27.413Z,1748542587.413 [CBIT](DEBUG): Backplane powered.
2025-05-29T18:16:27.413Z,1748542587.413 [GFScanner](DEBUG): Initializing GFScanner
2025-05-29T18:16:27.413Z,1748542587.413 [GFScanner](DEBUG): Deactivating GF circuits.
2025-05-29T18:16:27.421Z,1748542587.421 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2025-05-29T18:16:27.422Z,1748542587.422 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2025-05-29T18:16:27.422Z,1748542587.422 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2025-05-29T18:16:27.422Z,1748542587.422 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2025-05-29T18:16:27.423Z,1748542587.423 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2025-05-29T18:16:27.424Z,1748542587.424 [NavChart](DEBUG): Initialize NavChart Navigation.
2025-05-29T18:16:27.424Z,1748542587.424 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2025-05-29T18:16:27.432Z,1748542587.432 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2025-05-29T18:16:27.438Z,1748542587.438 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2025-05-29T18:16:27.439Z,1748542587.439 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2025-05-29T18:16:27.439Z,1748542587.439 [LoopControl](DEBUG): Initialize LoopControlComponent.
2025-05-29T18:16:27.440Z,1748542587.440 [MissionManager](IMPORTANT): Using TethysL tl-to-tx parser
2025-05-29T18:16:27.440Z,1748542587.440 [MissionManager](INFO): Loading Mission from file: Missions/Startup.tl
2025-05-29T18:16:27.449Z,1748542587.449 [MissionManager](DEBUG): TethyslAPI: loading: Missions/Startup.tl
2025-05-29T18:16:27.454Z,1748542587.454 [MissionManager](DEBUG): TethyslAPI: mission file loaded: Missions/Startup.tl
2025-05-29T18:16:27.542Z,1748542587.542 [MissionManager](DEBUG): TethyslAPI: Missions/Startup.tl translated into:
2025-05-29T18:16:27.546Z,1748542587.546 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2025-05-29T18:16:27.594Z,1748542587.594 [MissionManager](DEBUG):
# Copyright (c) 2024 MBARI
# MBARI Proprietary Information. Confidential. All Rights Reserved
# Unauthorized copying or distribution of this file via any medium is strictly
# prohibited.
#
# WARNING - This file contains information whose export is restricted by the
# Export Administration Act of 1979 (Title 50, U.S.C., App. 2401 et seq.), as
# amended. Violations of these export laws are subject to severe civil and/or
# criminal penalties.
mission Startup {
behavior Guidance:GoToSurface {
run in progression
}
aggregate StartupSatComms {
run in sequence
readDatum {
timeout duration=P1M
Universal:latitude_fix
}
readDatum {
timeout duration=P1M
Universal:platform_communications
}
}
}
2025-05-29T18:16:27.595Z,1748542587.595 [MissionManager](INFO): Loading Mission from file: Missions/Default.tl
2025-05-29T18:16:27.595Z,1748542587.595 [MissionManager](DEBUG): TethyslAPI: loading: Missions/Default.tl
2025-05-29T18:16:27.598Z,1748542587.598 [MissionManager](DEBUG): TethyslAPI: mission file loaded: Missions/Default.tl
2025-05-29T18:16:27.761Z,1748542587.761 [Radio_Surface](INFO): Powering up
2025-05-29T18:16:27.897Z,1748542587.897 [MissionManager](DEBUG): TethyslAPI: Missions/Default.tl translated into:
0
13
Burn on
Dropped weight due to communications timeout.
5
Default mission has been running for
Restarting logs and Default mission.
restart logs
2025-05-29T18:16:27.903Z,1748542587.903 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2025-05-29T18:16:27.904Z,1748542587.904 [Default:A.Wait](DEBUG): Construct Wait.
2025-05-29T18:16:27.927Z,1748542587.927 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2025-05-29T18:16:27.951Z,1748542587.951 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2025-05-29T18:16:27.978Z,1748542587.978 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2025-05-29T18:16:27.984Z,1748542587.984 [Default:E.Execute](DEBUG): Construct Execute.
2025-05-29T18:16:28.004Z,1748542588.004 [MissionManager](DEBUG):
# Copyright (c) 2024 MBARI
# MBARI Proprietary Information. Confidential. All Rights Reserved
# Unauthorized copying or distribution of this file via any medium is strictly
# prohibited.
#
# WARNING - This file contains information whose export is restricted by the
# Export Administration Act of 1979 (Title 50, U.S.C., App. 2401 et seq.), as
# amended. Violations of these export laws are subject to severe civil and/or
# criminal penalties.
mission Default {
arguments {
ElapsedSinceDefaultStarted = 0 minute
}
behavior Guidance:Wait {
"""
Wait a moment to see if the scheduler starts a new mission before
starting to actually run Default.
"""
run in sequence
set duration = 13 second
}
behavior Guidance:GoToSurface {
run in progression
}
aggregate CheckIn {
run in sequence repeat=288
readDatum id="Read_GPS" {
timeout duration=P5M
Universal:time_fix
}
readDatum id="Read_Iridium" {
timeout duration=P4H {
behavior Guidance:Execute {
run in sequence
set command = "Burn on"
}
syslog critical "Dropped weight due to communications timeout."
}
Universal:platform_communications
}
behavior Guidance:Wait {
run in sequence
set duration = 5 minute
}
assign in sequence ElapsedSinceDefaultStarted = elapsed ( Universal:mission_started )
syslog important "Default mission has been running for " + ElapsedSinceDefaultStarted~minute
}
syslog important "Restarting logs and Default mission."
behavior Guidance:Execute {
run in sequence
set command = "restart logs"
}
}
2025-05-29T18:16:28.008Z,1748542588.008 [controlThread](DEBUG): Component order: CycleStarter,ESPComponent,PAR_Licor,AHRS_M2,BPC1,Depth_Keller,DropWeight,DVL_micro,NAL9602,PowerOnly,Power24vConverter,Sonardyne_Nano,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,GFScanner,LcmUniversalReporter,Reporter,LogSplitter,
2025-05-29T18:16:28.042Z,1748542588.042 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2025-05-29T18:16:28.162Z,1748542588.162 [Depth_Keller](INFO): Initializing.
2025-05-29T18:16:28.171Z,1748542588.171 [PowerOnly](INFO): Powering up loadControl
2025-05-29T18:16:28.190Z,1748542588.190 [Power24vConverter](INFO): Powering up.
2025-05-29T18:16:28.190Z,1748542588.190 [Sonardyne_Nano](INFO): Initializing.
2025-05-29T18:16:28.217Z,1748542588.217 [DepthRateCalculator](ERROR): Depth measurement is not active
2025-05-29T18:16:28.257Z,1748542588.257 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2025-05-29T18:16:28.265Z,1748542588.265 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2025-05-29T18:16:28.266Z,1748542588.266 [ElevatorServo](DEBUG): Initializing EZServoServo.
2025-05-29T18:16:28.273Z,1748542588.273 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2025-05-29T18:16:28.274Z,1748542588.274 [MassServo](DEBUG): Initializing EZServoServo.
2025-05-29T18:16:28.281Z,1748542588.281 [MassServo](DEBUG): Initializing MassServo.
2025-05-29T18:16:28.282Z,1748542588.282 [RudderServo](DEBUG): Initializing EZServoServo.
2025-05-29T18:16:28.290Z,1748542588.290 [RudderServo](DEBUG): Initializing RudderServo.
2025-05-29T18:16:28.291Z,1748542588.291 [ThrusterHE](DEBUG): Initializing EZServoServo.
2025-05-29T18:16:28.297Z,1748542588.297 [ThrusterHE](DEBUG): Initializing ThrusterHE.
2025-05-29T18:16:28.482Z,1748542588.482 [Depth_Keller](ERROR): Pressure or depth reading out of range: 1895.444336 decibar, 0.000000 m
2025-05-29T18:16:28.493Z,1748542588.493 [DepthRateCalculator](ERROR): Depth measurement is not active
2025-05-29T18:16:29.909Z,1748542589.909 [WetLabsBB2FL](INFO): Powering down
2025-05-29T18:16:30.448Z,1748542590.448 [Sonardyne_Nano](ERROR): Failed to get valid response or reached max queue size, flushing UART
2025-05-29T18:16:31.698Z,1748542591.698 [Sonardyne_Nano](IMPORTANT): Found beacon with acoustic ID 2213
2025-05-29T18:16:33.783Z,1748542593.783 [ThrusterHE](ERROR): Zero Speed Commanded.
2025-05-29T18:16:34.321Z,1748542594.321 [CTD_Seabird](ERROR): Device message queue exceeded the allowed limit.
2025-05-29T18:16:39.414Z,1748542599.414 [DAT](INFO): DAT read:
2025-05-29T18:16:39.415Z,1748542599.415 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series
2025-05-29T18:16:41.178Z,1748542601.178 [DAT](INFO): DAT read: MF Frequency Band
2025-05-29T18:16:41.179Z,1748542601.179 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.15.0
2025-05-29T18:16:41.180Z,1748542601.180 [DAT](INFO): DAT read: May 29 2025 18:16:36
2025-05-29T18:16:42.438Z,1748542602.438 [DAT](INFO): DAT read: Features enabled [Bearing]
2025-05-29T18:16:42.439Z,1748542602.439 [DAT](INFO): DAT read: CONNECT 01200 bits/sec 1 of 4, Rate 1/2 CC
2025-05-29T18:16:42.439Z,1748542602.439 [DAT](INFO): commRate: 1200
2025-05-29T18:16:44.505Z,1748542604.505 [DAT](INFO): entering command mode
2025-05-29T18:16:44.706Z,1748542604.706 [DAT](INFO): DAT read:
2025-05-29T18:16:44.706Z,1748542604.706 [DAT](INFO): DAT read: user:1>
2025-05-29T18:16:44.707Z,1748542604.707 [DAT](INFO): setting verbose to 3
2025-05-29T18:16:44.958Z,1748542604.958 [DAT](INFO): DAT read: user:1>
2025-05-29T18:16:44.959Z,1748542604.959 [DAT](INFO): DAT read: Verbose | 3
2025-05-29T18:16:44.959Z,1748542604.959 [DAT](INFO): set verbose to 3
2025-05-29T18:16:44.959Z,1748542604.959 [DAT](INFO): setting DatVerbose to 27440
2025-05-29T18:16:45.210Z,1748542605.210 [DAT](INFO): DAT read: user:2>
2025-05-29T18:16:45.211Z,1748542605.211 [DAT](INFO): DAT read: DatVerbose | 27440
2025-05-29T18:16:45.211Z,1748542605.211 [DAT](INFO): set DatVerbose to 27440
2025-05-29T18:16:45.211Z,1748542605.211 [DAT](INFO): setting transmit power to 8
2025-05-29T18:16:45.462Z,1748542605.462 [DAT](INFO): DAT read: user:3>
2025-05-29T18:16:45.463Z,1748542605.463 [DAT](INFO): DAT read: TxPower | 8 (Max)
2025-05-29T18:16:45.463Z,1748542605.463 [DAT](INFO): set transmit power to 8
2025-05-29T18:16:45.463Z,1748542605.463 [DAT](INFO): setting local address to 5
2025-05-29T18:16:45.714Z,1748542605.714 [DAT](INFO): DAT read: user:4>
2025-05-29T18:16:45.715Z,1748542605.715 [DAT](INFO): DAT read: LocalAddr | 5
2025-05-29T18:16:45.715Z,1748542605.715 [DAT](INFO): set local address to 5
2025-05-29T18:16:45.716Z,1748542605.716 [DAT](INFO): Setting time to: 18:16:45 And date to:5/29/2025
2025-05-29T18:16:45.966Z,1748542605.966 [DAT](INFO): DAT read: user:5>
2025-05-29T18:16:45.967Z,1748542605.967 [DAT](INFO): DAT read: Thu May 29, 2025 18:16:45
2025-05-29T18:16:45.967Z,1748542605.967 [DAT](INFO): Local DAT time set to Thu May 29, 2025 18:16:45
2025-05-29T18:16:56.721Z,1748542616.721 [NAL9602](INFO): Powering up NAL9602
2025-05-29T18:17:07.629Z,1748542627.629 [NAL9602](INFO): NAL9602 initialized
2025-05-29T18:17:29.850Z,1748542649.850 [NAL9602](INFO): SBD MO Status=0, MOMSN=20743, MT Status=0, MTMSN=0
2025-05-29T18:17:29.850Z,1748542649.850 [NAL9602](INFO): No messages in MT queue
2025-05-29T18:18:32.912Z,1748542712.912 [SBIT](IMPORTANT): Beginning Startup BIT
2025-05-29T18:18:32.916Z,1748542712.916 [GFScanner](IMPORTANT): Beginning ground fault scan
2025-05-29T18:18:34.387Z,1748542714.387 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004805
2025-05-29T18:18:37.470Z,1748542717.470 [GFScanner](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): -0.002027
CHAN A1 (24V): 0.003541
CHAN A2 (12V): -0.006082
CHAN A3 (5V): -0.019696
CHAN B0 (3.3V): -0.003052
CHAN B1 (3.15aV): -0.001570
CHAN B2 (3.15bV): -0.001452
CHAN B3 (GND): 0.000147
OPEN: 0.011951
Full Scale: +/- 1 mA
2025-05-29T18:18:47.878Z,1748542727.878 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181832.00,A,3648.16714,N,12147.28530,W,0.311,90.56,290525,,,A*4C
2025-05-29T18:18:47.881Z,1748542727.881 [NAL9602](INFO): GPS fix at 20250529T181832: (36.802786, -121.788088)
2025-05-29T18:19:20.322Z,1748542760.322 [NAL9602](INFO): Not Powering down - fast GPS
2025-05-29T18:19:27.240Z,1748542767.240 [SBIT](IMPORTANT): SBIT PASSED
2025-05-29T18:19:27.240Z,1748542767.240 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2025-05-29T18:19:27.241Z,1748542767.241 [SBIT](IMPORTANT): BPC1.batteryMissingStickThreshold=5 count;
2025-05-29T18:19:27.241Z,1748542767.241 [SBIT](IMPORTANT): CBIT.runNavErrorCritical=0 bool;
2025-05-29T18:19:27.241Z,1748542767.241 [SBIT](IMPORTANT): DVL_micro.loadAtStartup=1 bool;
2025-05-29T18:19:27.242Z,1748542767.242 [SBIT](IMPORTANT): ESPComponent.loadAtStartup=1 bool;
2025-05-29T18:19:27.242Z,1748542767.242 [SBIT](IMPORTANT): ESPComponent.sampleTimeout=5 minute;
2025-05-29T18:19:27.242Z,1748542767.242 [SBIT](IMPORTANT): ESPComponent.simulateHardware=1 bool;
2025-05-29T18:19:27.242Z,1748542767.242 [SBIT](IMPORTANT): Express linearApproximation height_above_sea_floor 5.000000 meter;
2025-05-29T18:19:27.242Z,1748542767.242 [SBIT](IMPORTANT): GFScanner.loadAtStartup=1 bool;
2025-05-29T18:19:27.242Z,1748542767.242 [SBIT](IMPORTANT): GFScanner.simulateHardware=0 bool;
2025-05-29T18:19:27.242Z,1748542767.242 [SBIT](IMPORTANT): ThrusterHE.bestEffortMode=0 bool;
2025-05-29T18:19:27.242Z,1748542767.242 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=266.500578 cubic_centimeter;
2025-05-29T18:19:27.242Z,1748542767.242 [SBIT](IMPORTANT): VerticalControl.massDefault=26.489817 millimeter;
2025-05-29T18:19:27.614Z,1748542767.614 [MissionManager](IMPORTANT): Started mission Startup
2025-05-29T18:19:27.614Z,1748542767.614 [Startup] Running Loop=1
2025-05-29T18:19:27.614Z,1748542767.614 [Startup](DEBUG): Aggregate::initialize Startup
2025-05-29T18:19:27.614Z,1748542767.614 [Startup:A.GoToSurface] Running Loop=1
2025-05-29T18:19:27.614Z,1748542767.614 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2025-05-29T18:19:27.615Z,1748542767.615 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2025-05-29T18:19:27.615Z,1748542767.615 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2025-05-29T18:19:27.615Z,1748542767.615 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2025-05-29T18:19:27.616Z,1748542767.616 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2025-05-29T18:19:27.616Z,1748542767.616 [Startup:A.GoToSurface](DEBUG): No altitude timeout specified. Using default value of 600.000000 seconds.
2025-05-29T18:19:27.616Z,1748542767.616 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2025-05-29T18:19:27.618Z,1748542767.618 [Startup:StartupSatComms] Running Loop=1
2025-05-29T18:19:27.618Z,1748542767.618 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2025-05-29T18:19:27.619Z,1748542767.619 [Startup:StartupSatComms:A] Running Loop=1
2025-05-29T18:19:28.020Z,1748542768.020 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2025-05-29T18:19:29.620Z,1748542769.620 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181917.00,A,3648.16523,N,12147.28125,W,0.039,107.69,290525,,,A*76
2025-05-29T18:19:29.622Z,1748542769.622 [NAL9602](INFO): GPS fix at 20250529T181917: (36.802754, -121.788021)
2025-05-29T18:19:29.653Z,1748542769.653 [Startup:StartupSatComms:A] Stopped
2025-05-29T18:19:29.653Z,1748542769.653 [Startup:StartupSatComms:B] Running Loop=1
2025-05-29T18:19:30.067Z,1748542770.067 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2025-05-29T18:19:37.881Z,1748542777.881 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20250529T164446/Courier0040.lzma
2025-05-29T18:19:38.883Z,1748542778.883 [DataOverHttps](INFO): Moved sent file to Logs/20250529T164446/Courier0040.lzma.bak
2025-05-29T18:19:38.883Z,1748542778.883 [DataOverHttps](INFO): SBD MOMSN=25032764
2025-05-29T18:19:56.873Z,1748542796.873 [DataOverHttps](INFO): Sending 270 bytes from file Logs/20250529T181614/Courier0000.lzma
2025-05-29T18:19:57.875Z,1748542797.875 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Courier0000.lzma.bak
2025-05-29T18:19:57.875Z,1748542797.875 [DataOverHttps](INFO): SBD MOMSN=25032766
2025-05-29T18:20:14.404Z,1748542814.404 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20250529T164446/Express0041.lzma
2025-05-29T18:20:15.407Z,1748542815.407 [DataOverHttps](INFO): Moved sent file to Logs/20250529T164446/Express0041.lzma.bak
2025-05-29T18:20:15.407Z,1748542815.407 [DataOverHttps](INFO): SBD MOMSN=25032770
2025-05-29T18:20:29.901Z,1748542829.901 [Startup:StartupSatComms:B](INFO): Timed out from 2025-05-29T18:19:29.7Z
2025-05-29T18:20:29.902Z,1748542829.902 [Startup:StartupSatComms:B] Stopped
2025-05-29T18:20:29.902Z,1748542829.902 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2025-05-29T18:20:29.902Z,1748542829.902 [Startup:StartupSatComms] Stopped
2025-05-29T18:20:29.902Z,1748542829.902 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2025-05-29T18:20:29.903Z,1748542829.903 [Startup](INFO): Completed Startup
2025-05-29T18:20:29.903Z,1748542829.903 [MissionManager](INFO): Startup is completed.
2025-05-29T18:20:29.903Z,1748542829.903 [MissionManager](INFO): Uninitializing Mission Startup
2025-05-29T18:20:29.903Z,1748542829.903 [Startup] Stopped
2025-05-29T18:20:29.903Z,1748542829.903 [Startup](DEBUG): Aggregate::uninitialize Startup
2025-05-29T18:20:29.903Z,1748542829.903 [Startup:A.GoToSurface] Stopped
2025-05-29T18:20:29.903Z,1748542829.903 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2025-05-29T18:20:30.310Z,1748542830.310 [MissionManager](IMPORTANT): Started mission Default
2025-05-29T18:20:30.310Z,1748542830.310 [Default] Running Loop=1
2025-05-29T18:20:30.310Z,1748542830.310 [Default](DEBUG): Aggregate::initialize Default
2025-05-29T18:20:30.310Z,1748542830.310 [Default:B.GoToSurface] Running Loop=1
2025-05-29T18:20:30.311Z,1748542830.311 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2025-05-29T18:20:30.311Z,1748542830.311 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2025-05-29T18:20:30.311Z,1748542830.311 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2025-05-29T18:20:30.311Z,1748542830.311 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2025-05-29T18:20:30.312Z,1748542830.312 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2025-05-29T18:20:30.312Z,1748542830.312 [Default:B.GoToSurface](DEBUG): No altitude timeout specified. Using default value of 600.000000 seconds.
2025-05-29T18:20:30.312Z,1748542830.312 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2025-05-29T18:20:30.313Z,1748542830.313 [Default:A.Wait] Running Loop=1
2025-05-29T18:20:30.313Z,1748542830.313 [Default:A.Wait](DEBUG): Initialize Wait Component.
2025-05-29T18:20:31.972Z,1748542831.972 [DataOverHttps](INFO): Sending 1216 bytes from file Logs/20250529T181614/Express0001.lzma
2025-05-29T18:20:32.972Z,1748542832.972 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Express0001.lzma.bak
2025-05-29T18:20:32.972Z,1748542832.972 [DataOverHttps](INFO): SBD MOMSN=25032772
2025-05-29T18:20:43.681Z,1748542843.681 [Default:A.Wait](INFO): Done Waiting.
2025-05-29T18:20:43.681Z,1748542843.681 [Default:A.Wait] Stopped
2025-05-29T18:20:43.681Z,1748542843.681 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2025-05-29T18:20:44.031Z,1748542844.031 [Default:CheckIn] Running Loop=1
2025-05-29T18:20:44.031Z,1748542844.031 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2025-05-29T18:20:44.031Z,1748542844.031 [Default:CheckIn:Read_GPS] Running Loop=1
2025-05-29T18:20:44.442Z,1748542844.442 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2025-05-29T18:22:56.120Z,1748542976.120 [BPC1](ERROR): Battery stick #2 (s/n: 0124) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0.
2025-05-29T18:22:56.121Z,1748542976.121 [BPC1](INFO): Calculating totals. Valid battery stick count: 54. Valid reserve battery stick count: 6.
2025-05-29T18:22:56.125Z,1748542976.125 [BPC1](INFO): Received data from all battery sticks.
2025-05-29T18:24:31.465Z,1748543071.465 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2025-05-29T18:24:35.909Z,1748543075.909 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182423.00,A,3648.16197,N,12147.27710,W,0.039,134.95,290525,,,A*78
2025-05-29T18:24:35.911Z,1748543075.911 [NAL9602](INFO): GPS fix at 20250529T182423: (36.802700, -121.787952)
2025-05-29T18:24:35.922Z,1748543075.922 [Default:CheckIn:Read_GPS] Stopped
2025-05-29T18:24:35.922Z,1748543075.922 [Default:CheckIn:Read_Iridium] Running Loop=1
2025-05-29T18:24:36.387Z,1748543076.387 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2025-05-29T18:24:39.986Z,1748543079.986 [CommandExec](IMPORTANT): got command gfscan
2025-05-29T18:24:40.037Z,1748543080.037 [GFScanner](IMPORTANT): Beginning ground fault scan
2025-05-29T18:24:44.086Z,1748543084.086 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20250529T181614/Courier0004.lzma
2025-05-29T18:24:44.488Z,1748543084.488 [GFScanner](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.003612
CHAN A1 (24V): 0.003773
CHAN A2 (12V): -0.007654
CHAN A3 (5V): -0.017436
CHAN B0 (3.3V): -0.002532
CHAN B1 (3.15aV): -0.002156
CHAN B2 (3.15bV): -0.001556
CHAN B3 (GND): 0.001423
OPEN: 0.011450
Full Scale: +/- 1 mA
2025-05-29T18:24:45.087Z,1748543085.087 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Courier0004.lzma.bak
2025-05-29T18:24:45.087Z,1748543085.087 [DataOverHttps](INFO): SBD MOMSN=25032867
2025-05-29T18:25:01.069Z,1748543101.069 [DataOverHttps](INFO): Sending 293 bytes from file Logs/20250529T181614/Express0005.lzma
2025-05-29T18:25:02.071Z,1748543102.071 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Express0005.lzma.bak
2025-05-29T18:25:02.071Z,1748543102.071 [DataOverHttps](INFO): SBD MOMSN=25032870
2025-05-29T18:25:03.403Z,1748543103.403 [Default:CheckIn:Read_Iridium] Stopped
2025-05-29T18:25:03.403Z,1748543103.403 [Default:CheckIn:C.Wait] Running Loop=1
2025-05-29T18:25:03.403Z,1748543103.403 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2025-05-29T18:25:08.655Z,1748543108.655 [NAL9602](INFO): Not Powering down - fast GPS
2025-05-29T18:25:44.536Z,1748543144.536 [CommandLine](INFO): End of History
2025-05-29T18:25:44.543Z,1748543144.543 [CommandLine](INFO): End of History
2025-05-29T18:25:46.942Z,1748543146.942 [CommandExec](IMPORTANT): got command gfscan
2025-05-29T18:25:47.053Z,1748543147.053 [GFScanner](IMPORTANT): Beginning ground fault scan
2025-05-29T18:25:51.500Z,1748543151.500 [GFScanner](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.010916
CHAN A1 (24V): 0.003758
CHAN A2 (12V): -0.008062
CHAN A3 (5V): -0.011797
CHAN B0 (3.3V): -0.004300
CHAN B1 (3.15aV): -0.002061
CHAN B2 (3.15bV): -0.001653
CHAN B3 (GND): -0.001442
OPEN: 0.011919
Full Scale: +/- 1 mA
2025-05-29T18:25:55.698Z,1748543155.698 [CommandExec](IMPORTANT): got command gfscan
2025-05-29T18:25:55.927Z,1748543155.927 [GFScanner](IMPORTANT): Beginning ground fault scan
2025-05-29T18:26:00.379Z,1748543160.379 [GFScanner](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.003816
CHAN A1 (24V): 0.002881
CHAN A2 (12V): -0.007883
CHAN A3 (5V): -0.007557
CHAN B0 (3.3V): -0.003324
CHAN B1 (3.15aV): -0.002073
CHAN B2 (3.15bV): -0.001594
CHAN B3 (GND): -0.001083
OPEN: 0.011885
Full Scale: +/- 1 mA
2025-05-29T18:30:04.009Z,1748543404.009 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2025-05-29T18:30:04.009Z,1748543404.009 [Default:CheckIn:C.Wait] Stopped
2025-05-29T18:30:04.009Z,1748543404.009 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2025-05-29T18:30:04.010Z,1748543404.010 [Default:CheckIn:D] Running Loop=1
2025-05-29T18:30:04.384Z,1748543404.384 [Default:CheckIn:D] Stopped
2025-05-29T18:30:04.384Z,1748543404.384 [Default:CheckIn:E] Running Loop=1
2025-05-29T18:30:04.794Z,1748543404.794 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 9.567894 min
2025-05-29T18:30:04.794Z,1748543404.794 [Default:CheckIn:E] Stopped
2025-05-29T18:30:04.794Z,1748543404.794 [Default:CheckIn](INFO): Completed Default:CheckIn
2025-05-29T18:30:04.794Z,1748543404.794 [Default:CheckIn] Stopped
2025-05-29T18:30:04.794Z,1748543404.794 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2025-05-29T18:30:04.794Z,1748543404.794 [Default:CheckIn](INFO): Running loop #2
2025-05-29T18:30:04.794Z,1748543404.794 [Default:CheckIn] Running Loop=2
2025-05-29T18:30:04.795Z,1748543404.795 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2025-05-29T18:30:04.795Z,1748543404.795 [Default:CheckIn:Read_GPS] Running Loop=1
2025-05-29T18:30:06.800Z,1748543406.800 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182954.00,A,3648.16351,N,12147.28183,W,0.117,95.65,290525,,,D*43
2025-05-29T18:30:06.802Z,1748543406.802 [NAL9602](INFO): GPS fix at 20250529T182954: (36.802725, -121.788031)
2025-05-29T18:30:06.812Z,1748543406.812 [Default:CheckIn:Read_GPS] Stopped
2025-05-29T18:30:06.812Z,1748543406.812 [Default:CheckIn:Read_Iridium] Running Loop=1
2025-05-29T18:30:14.788Z,1748543414.788 [DataOverHttps](INFO): Sending 76 bytes from file Logs/20250529T181614/Courier0007.lzma
2025-05-29T18:30:15.791Z,1748543415.791 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Courier0007.lzma.bak
2025-05-29T18:30:15.791Z,1748543415.791 [DataOverHttps](INFO): SBD MOMSN=25032888
2025-05-29T18:30:31.962Z,1748543431.962 [DataOverHttps](INFO): Sending 515 bytes from file Logs/20250529T181614/Express0008.lzma
2025-05-29T18:30:32.963Z,1748543432.963 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Express0008.lzma.bak
2025-05-29T18:30:32.963Z,1748543432.963 [DataOverHttps](INFO): SBD MOMSN=25032896
2025-05-29T18:30:34.288Z,1748543434.288 [Default:CheckIn:Read_Iridium] Stopped
2025-05-29T18:30:34.288Z,1748543434.288 [Default:CheckIn:C.Wait] Running Loop=1
2025-05-29T18:30:34.288Z,1748543434.288 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2025-05-29T18:30:37.503Z,1748543437.503 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2025-05-29T18:30:37.581Z,1748543437.581 [NAL9602](ERROR): received:
+CSQ:0
OK743, 0, 0, 0, 0
OK
2025-05-29T18:35:09.426Z,1748543709.426 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2025-05-29T18:35:34.880Z,1748543734.880 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2025-05-29T18:35:34.880Z,1748543734.880 [Default:CheckIn:C.Wait] Stopped
2025-05-29T18:35:34.880Z,1748543734.880 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2025-05-29T18:35:34.880Z,1748543734.880 [Default:CheckIn:D] Running Loop=1
2025-05-29T18:35:35.296Z,1748543735.296 [Default:CheckIn:D] Stopped
2025-05-29T18:35:35.296Z,1748543735.296 [Default:CheckIn:E] Running Loop=1
2025-05-29T18:35:35.699Z,1748543735.699 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 15.083101 min
2025-05-29T18:35:35.699Z,1748543735.699 [Default:CheckIn:E] Stopped
2025-05-29T18:35:35.699Z,1748543735.699 [Default:CheckIn](INFO): Completed Default:CheckIn
2025-05-29T18:35:35.699Z,1748543735.699 [Default:CheckIn] Stopped
2025-05-29T18:35:35.699Z,1748543735.699 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2025-05-29T18:35:35.699Z,1748543735.699 [Default:CheckIn](INFO): Running loop #3
2025-05-29T18:35:35.700Z,1748543735.700 [Default:CheckIn] Running Loop=3
2025-05-29T18:35:35.700Z,1748543735.700 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2025-05-29T18:35:35.700Z,1748543735.700 [Default:CheckIn:Read_GPS] Running Loop=1
2025-05-29T18:35:37.699Z,1748543737.699 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183525.00,A,3648.16552,N,12147.28134,W,0.039,95.65,290525,,,D*4C
2025-05-29T18:35:37.701Z,1748543737.701 [NAL9602](INFO): GPS fix at 20250529T183525: (36.802759, -121.788022)
2025-05-29T18:35:37.736Z,1748543737.736 [Default:CheckIn:Read_GPS] Stopped
2025-05-29T18:35:37.736Z,1748543737.736 [Default:CheckIn:Read_Iridium] Running Loop=1
2025-05-29T18:35:46.177Z,1748543746.177 [DataOverHttps](INFO): Sending 76 bytes from file Logs/20250529T181614/Courier0010.lzma
2025-05-29T18:35:47.179Z,1748543747.179 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Courier0010.lzma.bak
2025-05-29T18:35:47.180Z,1748543747.180 [DataOverHttps](INFO): SBD MOMSN=25032978
2025-05-29T18:36:03.521Z,1748543763.521 [DataOverHttps](INFO): Sending 242 bytes from file Logs/20250529T181614/Express0011.lzma
2025-05-29T18:36:04.523Z,1748543764.523 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Express0011.lzma.bak
2025-05-29T18:36:04.523Z,1748543764.523 [DataOverHttps](INFO): SBD MOMSN=25032981
2025-05-29T18:36:06.026Z,1748543766.026 [Default:CheckIn:Read_Iridium] Stopped
2025-05-29T18:36:06.026Z,1748543766.026 [Default:CheckIn:C.Wait] Running Loop=1
2025-05-29T18:36:06.026Z,1748543766.026 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2025-05-29T18:36:09.644Z,1748543769.644 [NAL9602](INFO): Not Powering down - fast GPS
2025-05-29T18:39:28.828Z,1748543968.828 [DVL_micro](ERROR): Failed to parse:
:BI,+00006,+00070,+00007,+00000,A
2025-05-29T18:41:06.637Z,1748544066.637 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2025-05-29T18:41:06.637Z,1748544066.637 [Default:CheckIn:C.Wait] Stopped
2025-05-29T18:41:06.637Z,1748544066.637 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2025-05-29T18:41:06.638Z,1748544066.638 [Default:CheckIn:D] Running Loop=1
2025-05-29T18:41:07.038Z,1748544067.038 [Default:CheckIn:D] Stopped
2025-05-29T18:41:07.038Z,1748544067.038 [Default:CheckIn:E] Running Loop=1
2025-05-29T18:41:07.432Z,1748544067.432 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 20.612124 min
2025-05-29T18:41:07.432Z,1748544067.432 [Default:CheckIn:E] Stopped
2025-05-29T18:41:07.432Z,1748544067.432 [Default:CheckIn](INFO): Completed Default:CheckIn
2025-05-29T18:41:07.432Z,1748544067.432 [Default:CheckIn] Stopped
2025-05-29T18:41:07.433Z,1748544067.433 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2025-05-29T18:41:07.433Z,1748544067.433 [Default:CheckIn](INFO): Running loop #4
2025-05-29T18:41:07.433Z,1748544067.433 [Default:CheckIn] Running Loop=4
2025-05-29T18:41:07.434Z,1748544067.434 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2025-05-29T18:41:07.434Z,1748544067.434 [Default:CheckIn:Read_GPS] Running Loop=1
2025-05-29T18:41:09.451Z,1748544069.451 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184056.00,A,3648.16449,N,12147.27866,W,0.253,95.65,290525,,,D*4E
2025-05-29T18:41:09.454Z,1748544069.454 [NAL9602](INFO): GPS fix at 20250529T184056: (36.802742, -121.787978)
2025-05-29T18:41:09.464Z,1748544069.464 [Default:CheckIn:Read_GPS] Stopped
2025-05-29T18:41:09.464Z,1748544069.464 [Default:CheckIn:Read_Iridium] Running Loop=1
2025-05-29T18:41:17.413Z,1748544077.413 [DataOverHttps](INFO): Sending 75 bytes from file Logs/20250529T181614/Courier0013.lzma
2025-05-29T18:41:18.415Z,1748544078.415 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Courier0013.lzma.bak
2025-05-29T18:41:18.415Z,1748544078.415 [DataOverHttps](INFO): SBD MOMSN=25033000
2025-05-29T18:41:34.561Z,1748544094.561 [DataOverHttps](INFO): Sending 172 bytes from file Logs/20250529T181614/Express0014.lzma
2025-05-29T18:41:35.563Z,1748544095.563 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Express0014.lzma.bak
2025-05-29T18:41:35.563Z,1748544095.563 [DataOverHttps](INFO): SBD MOMSN=25033003
2025-05-29T18:41:36.929Z,1748544096.929 [Default:CheckIn:Read_Iridium] Stopped
2025-05-29T18:41:36.929Z,1748544096.929 [Default:CheckIn:C.Wait] Running Loop=1
2025-05-29T18:41:36.929Z,1748544096.929 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2025-05-29T18:41:40.148Z,1748544100.148 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2025-05-29T18:41:40.221Z,1748544100.221 [NAL9602](ERROR): received:
+CSQ:0
OK743, 0, 0, 0, 0
OK
2025-05-29T18:43:06.786Z,1748544186.786 [CommandExec](IMPORTANT): got command gfscan
2025-05-29T18:43:07.052Z,1748544187.052 [GFScanner](IMPORTANT): Beginning ground fault scan
2025-05-29T18:43:11.532Z,1748544191.532 [GFScanner](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.004065
CHAN A1 (24V): 0.002705
CHAN A2 (12V): -0.008565
CHAN A3 (5V): -0.009908
CHAN B0 (3.3V): -0.002297
CHAN B1 (3.15aV): -0.002211
CHAN B2 (3.15bV): -0.001647
CHAN B3 (GND): -0.001410
OPEN: 0.011865
Full Scale: +/- 1 mA
2025-05-29T18:43:18.134Z,1748544198.134 [CommandExec](IMPORTANT): got command failComponent
2025-05-29T18:43:18.134Z,1748544198.134 [CommandExec](IMPORTANT): Failed components:
2025-05-29T18:43:18.134Z,1748544198.134 [CommandExec](IMPORTANT): No failed Components.
2025-05-29T18:43:28.052Z,1748544208.052 [DVL_micro](ERROR): Failed to parse:
:R11.90
2025-05-29T18:46:11.738Z,1748544371.738 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2025-05-29T18:46:37.686Z,1748544397.686 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2025-05-29T18:46:37.686Z,1748544397.686 [Default:CheckIn:C.Wait] Stopped
2025-05-29T18:46:37.686Z,1748544397.686 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2025-05-29T18:46:37.686Z,1748544397.686 [Default:CheckIn:D] Running Loop=1
2025-05-29T18:46:38.034Z,1748544398.034 [Default:CheckIn:D] Stopped
2025-05-29T18:46:38.034Z,1748544398.034 [Default:CheckIn:E] Running Loop=1
2025-05-29T18:46:38.478Z,1748544398.478 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 26.128731 min
2025-05-29T18:46:38.478Z,1748544398.478 [Default:CheckIn:E] Stopped
2025-05-29T18:46:38.478Z,1748544398.478 [Default:CheckIn](INFO): Completed Default:CheckIn
2025-05-29T18:46:38.478Z,1748544398.478 [Default:CheckIn] Stopped
2025-05-29T18:46:38.478Z,1748544398.478 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2025-05-29T18:46:38.478Z,1748544398.478 [Default:CheckIn](INFO): Running loop #5
2025-05-29T18:46:38.478Z,1748544398.478 [Default:CheckIn] Running Loop=5
2025-05-29T18:46:38.479Z,1748544398.479 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2025-05-29T18:46:38.479Z,1748544398.479 [Default:CheckIn:Read_GPS] Running Loop=1
2025-05-29T18:46:40.432Z,1748544400.432 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184627.00,A,3648.16462,N,12147.28293,W,0.272,340.46,290525,,,D*71
2025-05-29T18:46:40.443Z,1748544400.443 [NAL9602](INFO): GPS fix at 20250529T184627: (36.802744, -121.788049)
2025-05-29T18:46:40.454Z,1748544400.454 [Default:CheckIn:Read_GPS] Stopped
2025-05-29T18:46:40.454Z,1748544400.454 [Default:CheckIn:Read_Iridium] Running Loop=1
2025-05-29T18:46:55.772Z,1748544415.772 [DataOverHttps](INFO): Sending 76 bytes from file Logs/20250529T181614/Courier0016.lzma
2025-05-29T18:46:56.775Z,1748544416.775 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Courier0016.lzma.bak
2025-05-29T18:46:56.776Z,1748544416.776 [DataOverHttps](INFO): SBD MOMSN=25033076
2025-05-29T18:47:12.707Z,1748544432.707 [NAL9602](INFO): Not Powering down - fast GPS
2025-05-29T18:47:20.514Z,1748544440.514 [DataOverHttps](INFO): Sending 484 bytes from file Logs/20250529T181614/Express0017.lzma
2025-05-29T18:47:21.511Z,1748544441.511 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Express0017.lzma.bak
2025-05-29T18:47:21.511Z,1748544441.511 [DataOverHttps](INFO): SBD MOMSN=25033079
2025-05-29T18:47:23.243Z,1748544443.243 [Default:CheckIn:Read_Iridium] Stopped
2025-05-29T18:47:23.243Z,1748544443.243 [Default:CheckIn:C.Wait] Running Loop=1
2025-05-29T18:47:23.243Z,1748544443.243 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2025-05-29T18:52:24.035Z,1748544744.035 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2025-05-29T18:52:24.035Z,1748544744.035 [Default:CheckIn:C.Wait] Stopped
2025-05-29T18:52:24.035Z,1748544744.035 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2025-05-29T18:52:24.035Z,1748544744.035 [Default:CheckIn:D] Running Loop=1
2025-05-29T18:52:24.437Z,1748544744.437 [Default:CheckIn:D] Stopped
2025-05-29T18:52:24.437Z,1748544744.437 [Default:CheckIn:E] Running Loop=1
2025-05-29T18:52:24.848Z,1748544744.848 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 31.902108 min
2025-05-29T18:52:24.849Z,1748544744.849 [Default:CheckIn:E] Stopped
2025-05-29T18:52:24.849Z,1748544744.849 [Default:CheckIn](INFO): Completed Default:CheckIn
2025-05-29T18:52:24.850Z,1748544744.850 [Default:CheckIn] Stopped
2025-05-29T18:52:24.852Z,1748544744.852 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2025-05-29T18:52:24.852Z,1748544744.852 [Default:CheckIn](INFO): Running loop #6
2025-05-29T18:52:24.852Z,1748544744.852 [Default:CheckIn] Running Loop=6
2025-05-29T18:52:24.853Z,1748544744.853 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2025-05-29T18:52:24.853Z,1748544744.853 [Default:CheckIn:Read_GPS] Running Loop=1
2025-05-29T18:52:26.851Z,1748544746.851 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185214.00,A,3648.16500,N,12147.28198,W,0.039,308.33,290525,,,D*7A
2025-05-29T18:52:26.855Z,1748544746.855 [NAL9602](INFO): GPS fix at 20250529T185214: (36.802750, -121.788033)
2025-05-29T18:52:26.888Z,1748544746.888 [Default:CheckIn:Read_GPS] Stopped
2025-05-29T18:52:26.888Z,1748544746.888 [Default:CheckIn:Read_Iridium] Running Loop=1
2025-05-29T18:52:34.616Z,1748544754.616 [DataOverHttps](INFO): Sending 76 bytes from file Logs/20250529T181614/Courier0019.lzma
2025-05-29T18:52:35.619Z,1748544755.619 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Courier0019.lzma.bak
2025-05-29T18:52:35.619Z,1748544755.619 [DataOverHttps](INFO): SBD MOMSN=25033103
2025-05-29T18:52:51.750Z,1748544771.750 [DataOverHttps](INFO): Sending 284 bytes from file Logs/20250529T181614/Express0020.lzma
2025-05-29T18:52:52.763Z,1748544772.763 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Express0020.lzma.bak
2025-05-29T18:52:52.763Z,1748544772.763 [DataOverHttps](INFO): SBD MOMSN=25033106
2025-05-29T18:52:54.343Z,1748544774.343 [Default:CheckIn:Read_Iridium] Stopped
2025-05-29T18:52:54.343Z,1748544774.343 [Default:CheckIn:C.Wait] Running Loop=1
2025-05-29T18:52:54.343Z,1748544774.343 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2025-05-29T18:52:57.611Z,1748544777.611 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2025-05-29T18:52:57.685Z,1748544777.685 [NAL9602](ERROR): received:
+CSQ:0
OK743, 0, 0, 0, 0
OK
2025-05-29T18:57:29.462Z,1748545049.462 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2025-05-29T18:57:54.915Z,1748545074.915 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2025-05-29T18:57:54.915Z,1748545074.915 [Default:CheckIn:C.Wait] Stopped
2025-05-29T18:57:54.915Z,1748545074.915 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2025-05-29T18:57:54.915Z,1748545074.915 [Default:CheckIn:D] Running Loop=1
2025-05-29T18:57:55.321Z,1748545075.321 [Default:CheckIn:D] Stopped
2025-05-29T18:57:55.321Z,1748545075.321 [Default:CheckIn:E] Running Loop=1
2025-05-29T18:57:55.738Z,1748545075.738 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 37.416850 min
2025-05-29T18:57:55.738Z,1748545075.738 [Default:CheckIn:E] Stopped
2025-05-29T18:57:55.738Z,1748545075.738 [Default:CheckIn](INFO): Completed Default:CheckIn
2025-05-29T18:57:55.738Z,1748545075.738 [Default:CheckIn] Stopped
2025-05-29T18:57:55.739Z,1748545075.739 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2025-05-29T18:57:55.739Z,1748545075.739 [Default:CheckIn](INFO): Running loop #7
2025-05-29T18:57:55.739Z,1748545075.739 [Default:CheckIn] Running Loop=7
2025-05-29T18:57:55.739Z,1748545075.739 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2025-05-29T18:57:55.739Z,1748545075.739 [Default:CheckIn:Read_GPS] Running Loop=1
2025-05-29T18:57:57.735Z,1748545077.735 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185744.00,A,3648.16357,N,12147.28320,W,0.156,355.62,290525,,,D*7B
2025-05-29T18:57:57.737Z,1748545077.737 [NAL9602](INFO): GPS fix at 20250529T185744: (36.802726, -121.788053)
2025-05-29T18:57:57.748Z,1748545077.748 [Default:CheckIn:Read_GPS] Stopped
2025-05-29T18:57:57.748Z,1748545077.748 [Default:CheckIn:Read_Iridium] Running Loop=1
2025-05-29T18:58:05.448Z,1748545085.448 [DataOverHttps](INFO): Sending 75 bytes from file Logs/20250529T181614/Courier0022.lzma
2025-05-29T18:58:06.451Z,1748545086.451 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Courier0022.lzma.bak
2025-05-29T18:58:06.451Z,1748545086.451 [DataOverHttps](INFO): SBD MOMSN=25033179
2025-05-29T18:58:22.933Z,1748545102.933 [DataOverHttps](INFO): Sending 363 bytes from file Logs/20250529T181614/Express0023.lzma
2025-05-29T18:58:23.935Z,1748545103.935 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Express0023.lzma.bak
2025-05-29T18:58:23.935Z,1748545103.935 [DataOverHttps](INFO): SBD MOMSN=25033182
2025-05-29T18:58:25.225Z,1748545105.225 [Default:CheckIn:Read_Iridium] Stopped
2025-05-29T18:58:25.225Z,1748545105.225 [Default:CheckIn:C.Wait] Running Loop=1
2025-05-29T18:58:25.225Z,1748545105.225 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2025-05-29T18:58:30.476Z,1748545110.476 [NAL9602](INFO): Not Powering down - fast GPS
2025-05-29T19:03:25.817Z,1748545405.817 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2025-05-29T19:03:25.818Z,1748545405.818 [Default:CheckIn:C.Wait] Stopped
2025-05-29T19:03:25.818Z,1748545405.818 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2025-05-29T19:03:25.818Z,1748545405.818 [Default:CheckIn:D] Running Loop=1
2025-05-29T19:03:26.218Z,1748545406.218 [Default:CheckIn:D] Stopped
2025-05-29T19:03:26.218Z,1748545406.218 [Default:CheckIn:E] Running Loop=1
2025-05-29T19:03:26.615Z,1748545406.615 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 42.931775 min
2025-05-29T19:03:26.615Z,1748545406.615 [Default:CheckIn:E] Stopped
2025-05-29T19:03:26.615Z,1748545406.615 [Default:CheckIn](INFO): Completed Default:CheckIn
2025-05-29T19:03:26.615Z,1748545406.615 [Default:CheckIn] Stopped
2025-05-29T19:03:26.615Z,1748545406.615 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2025-05-29T19:03:26.615Z,1748545406.615 [Default:CheckIn](INFO): Running loop #8
2025-05-29T19:03:26.615Z,1748545406.615 [Default:CheckIn] Running Loop=8
2025-05-29T19:03:26.615Z,1748545406.615 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2025-05-29T19:03:26.616Z,1748545406.616 [Default:CheckIn:Read_GPS] Running Loop=1
2025-05-29T19:03:28.631Z,1748545408.631 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190315.00,A,3648.16183,N,12147.28419,W,0.156,69.81,290525,,,D*48
2025-05-29T19:03:28.633Z,1748545408.633 [NAL9602](INFO): GPS fix at 20250529T190315: (36.802697, -121.788070)
2025-05-29T19:03:28.644Z,1748545408.644 [Default:CheckIn:Read_GPS] Stopped
2025-05-29T19:03:28.644Z,1748545408.644 [Default:CheckIn:Read_Iridium] Running Loop=1
2025-05-29T19:03:36.004Z,1748545416.004 [DataOverHttps](INFO): Sending 75 bytes from file Logs/20250529T181614/Courier0025.lzma
2025-05-29T19:03:37.007Z,1748545417.007 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Courier0025.lzma.bak
2025-05-29T19:03:37.007Z,1748545417.007 [DataOverHttps](INFO): SBD MOMSN=25033200
2025-05-29T19:03:52.953Z,1748545432.953 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20250529T181614/Express0026.lzma
2025-05-29T19:03:53.955Z,1748545433.955 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Express0026.lzma.bak
2025-05-29T19:03:53.955Z,1748545433.955 [DataOverHttps](INFO): SBD MOMSN=25033212
2025-05-29T19:03:55.717Z,1748545435.717 [Default:CheckIn:Read_Iridium] Stopped
2025-05-29T19:03:55.717Z,1748545435.717 [Default:CheckIn:C.Wait] Running Loop=1
2025-05-29T19:03:55.717Z,1748545435.717 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2025-05-29T19:03:59.343Z,1748545439.343 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2025-05-29T19:03:59.421Z,1748545439.421 [NAL9602](ERROR): received:
+CSQ:0
OK743, 0, 0, 0, 0
OK
2025-05-29T19:05:05.190Z,1748545505.190 [DVL_micro](ERROR): Failed to parse:
:WI,+00080,-00140,-00041,+00000,A
2025-05-29T19:05:07.225Z,1748545507.225 [DVL_micro](ERROR): Failed to parse:
:WI,+00129,-00070,-00037,+00000,A
2025-05-29T19:05:09.256Z,1748545509.256 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.00,+00000000.00,0009.30,000.00
2025-05-29T19:05:11.250Z,1748545511.250 [DVL_micro](ERROR): Failed to parse:
:RD,+0010.70,+0010.14,+0010.89,+0011.83
2025-05-29T19:05:11.645Z,1748545511.645 [DVL_micro](ERROR): No DVL communication! Re-initializing
2025-05-29T19:05:11.645Z,1748545511.645 [DVL_micro] Communications Fault, FailCount= 1
2025-05-29T19:05:11.645Z,1748545511.645 [DVL_micro](ERROR): Communications Fault
2025-05-29T19:05:11.665Z,1748545511.665 [CBIT](ERROR): Communications Fault in component: DVL_micro
2025-05-29T19:05:12.157Z,1748545512.157 [DVL_micro](INFO): Powering down
2025-05-29T19:05:12.918Z,1748545512.918 [CBIT](INFO): Clearing failed state for component DVL_micro
2025-05-29T19:05:12.918Z,1748545512.918 [DVL_micro] No Fault, FailCount= 1
2025-05-29T19:08:30.427Z,1748545710.427 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2025-05-29T19:08:56.282Z,1748545736.282 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2025-05-29T19:08:56.282Z,1748545736.282 [Default:CheckIn:C.Wait] Stopped
2025-05-29T19:08:56.282Z,1748545736.282 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2025-05-29T19:08:56.282Z,1748545736.282 [Default:CheckIn:D] Running Loop=1
2025-05-29T19:08:56.705Z,1748545736.705 [Default:CheckIn:D] Stopped
2025-05-29T19:08:56.705Z,1748545736.705 [Default:CheckIn:E] Running Loop=1
2025-05-29T19:08:57.108Z,1748545737.108 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 48.439905 min
2025-05-29T19:08:57.108Z,1748545737.108 [Default:CheckIn:E] Stopped
2025-05-29T19:08:57.108Z,1748545737.108 [Default:CheckIn](INFO): Completed Default:CheckIn
2025-05-29T19:08:57.108Z,1748545737.108 [Default:CheckIn] Stopped
2025-05-29T19:08:57.108Z,1748545737.108 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2025-05-29T19:08:57.108Z,1748545737.108 [Default:CheckIn](INFO): Running loop #9
2025-05-29T19:08:57.108Z,1748545737.108 [Default:CheckIn] Running Loop=9
2025-05-29T19:08:57.108Z,1748545737.108 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2025-05-29T19:08:57.109Z,1748545737.109 [Default:CheckIn:Read_GPS] Running Loop=1
2025-05-29T19:08:59.108Z,1748545739.108 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190846.00,A,3648.16098,N,12147.28369,W,0.097,69.81,290525,,,D*42
2025-05-29T19:08:59.111Z,1748545739.111 [NAL9602](INFO): GPS fix at 20250529T190846: (36.802683, -121.788061)
2025-05-29T19:08:59.121Z,1748545739.121 [Default:CheckIn:Read_GPS] Stopped
2025-05-29T19:08:59.122Z,1748545739.122 [Default:CheckIn:Read_Iridium] Running Loop=1
2025-05-29T19:09:07.133Z,1748545747.133 [DataOverHttps](INFO): Sending 76 bytes from file Logs/20250529T181614/Courier0028.lzma
2025-05-29T19:09:08.135Z,1748545748.135 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Courier0028.lzma.bak
2025-05-29T19:09:08.135Z,1748545748.135 [DataOverHttps](INFO): SBD MOMSN=25033282
2025-05-29T19:09:24.255Z,1748545764.255 [DataOverHttps](INFO): Sending 250 bytes from file Logs/20250529T181614/Express0029.lzma
2025-05-29T19:09:25.255Z,1748545765.255 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Express0029.lzma.bak
2025-05-29T19:09:25.255Z,1748545765.255 [DataOverHttps](INFO): SBD MOMSN=25033288
2025-05-29T19:09:26.597Z,1748545766.597 [Default:CheckIn:Read_Iridium] Stopped
2025-05-29T19:09:26.597Z,1748545766.597 [Default:CheckIn:C.Wait] Running Loop=1
2025-05-29T19:09:26.597Z,1748545766.597 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2025-05-29T19:09:31.833Z,1748545771.833 [NAL9602](INFO): Not Powering down - fast GPS
2025-05-29T19:14:27.178Z,1748546067.178 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2025-05-29T19:14:27.178Z,1748546067.178 [Default:CheckIn:C.Wait] Stopped
2025-05-29T19:14:27.178Z,1748546067.178 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2025-05-29T19:14:27.178Z,1748546067.178 [Default:CheckIn:D] Running Loop=1
2025-05-29T19:14:27.585Z,1748546067.585 [Default:CheckIn:D] Stopped
2025-05-29T19:14:27.585Z,1748546067.585 [Default:CheckIn:E] Running Loop=1
2025-05-29T19:14:28.007Z,1748546068.007 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 53.954586 min
2025-05-29T19:14:28.007Z,1748546068.007 [Default:CheckIn:E] Stopped
2025-05-29T19:14:28.008Z,1748546068.008 [Default:CheckIn](INFO): Completed Default:CheckIn
2025-05-29T19:14:28.008Z,1748546068.008 [Default:CheckIn] Stopped
2025-05-29T19:14:28.008Z,1748546068.008 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2025-05-29T19:14:28.008Z,1748546068.008 [Default:CheckIn](INFO): Running loop #10
2025-05-29T19:14:28.008Z,1748546068.008 [Default:CheckIn] Running Loop=10
2025-05-29T19:14:28.008Z,1748546068.008 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2025-05-29T19:14:28.008Z,1748546068.008 [Default:CheckIn:Read_GPS] Running Loop=1
2025-05-29T19:14:30.003Z,1748546070.003 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191417.00,A,3648.16360,N,12147.27843,W,0.233,69.81,290525,,,D*4F
2025-05-29T19:14:30.006Z,1748546070.006 [NAL9602](INFO): GPS fix at 20250529T191417: (36.802727, -121.787974)
2025-05-29T19:14:30.016Z,1748546070.016 [Default:CheckIn:Read_GPS] Stopped
2025-05-29T19:14:30.016Z,1748546070.016 [Default:CheckIn:Read_Iridium] Running Loop=1
2025-05-29T19:14:38.005Z,1748546078.005 [DataOverHttps](INFO): Sending 76 bytes from file Logs/20250529T181614/Courier0031.lzma
2025-05-29T19:14:39.007Z,1748546079.007 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Courier0031.lzma.bak
2025-05-29T19:14:39.007Z,1748546079.007 [DataOverHttps](INFO): SBD MOMSN=25033313
2025-05-29T19:14:56.749Z,1748546096.749 [DataOverHttps](INFO): Sending 180 bytes from file Logs/20250529T181614/Express0032.lzma
2025-05-29T19:14:57.751Z,1748546097.751 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Express0032.lzma.bak
2025-05-29T19:14:57.751Z,1748546097.751 [DataOverHttps](INFO): SBD MOMSN=25033316
2025-05-29T19:14:59.104Z,1748546099.104 [Default:CheckIn:Read_Iridium] Stopped
2025-05-29T19:14:59.104Z,1748546099.104 [Default:CheckIn:C.Wait] Running Loop=1
2025-05-29T19:14:59.104Z,1748546099.104 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2025-05-29T19:15:00.711Z,1748546100.711 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2025-05-29T19:15:00.785Z,1748546100.785 [NAL9602](ERROR): received:
+CSQ:0
OK743, 0, 0, 0, 0
OK
2025-05-29T19:19:32.618Z,1748546372.618 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2025-05-29T19:19:59.694Z,1748546399.694 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2025-05-29T19:19:59.694Z,1748546399.694 [Default:CheckIn:C.Wait] Stopped
2025-05-29T19:19:59.694Z,1748546399.694 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2025-05-29T19:19:59.694Z,1748546399.694 [Default:CheckIn:D] Running Loop=1
2025-05-29T19:20:00.091Z,1748546400.091 [Default:CheckIn:D] Stopped
2025-05-29T19:20:00.091Z,1748546400.091 [Default:CheckIn:E] Running Loop=1
2025-05-29T19:20:00.500Z,1748546400.500 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 59.496350 min
2025-05-29T19:20:00.500Z,1748546400.500 [Default:CheckIn:E] Stopped
2025-05-29T19:20:00.500Z,1748546400.500 [Default:CheckIn](INFO): Completed Default:CheckIn
2025-05-29T19:20:00.500Z,1748546400.500 [Default:CheckIn] Stopped
2025-05-29T19:20:00.500Z,1748546400.500 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2025-05-29T19:20:00.500Z,1748546400.500 [Default:CheckIn](INFO): Running loop #11
2025-05-29T19:20:00.500Z,1748546400.500 [Default:CheckIn] Running Loop=11
2025-05-29T19:20:00.501Z,1748546400.501 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2025-05-29T19:20:00.501Z,1748546400.501 [Default:CheckIn:Read_GPS] Running Loop=1
2025-05-29T19:20:02.512Z,1748546402.512 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191949.00,A,3648.16035,N,12147.28475,W,0.078,69.81,290525,,,D*41
2025-05-29T19:20:02.514Z,1748546402.514 [NAL9602](INFO): GPS fix at 20250529T191949: (36.802672, -121.788079)
2025-05-29T19:20:02.526Z,1748546402.526 [Default:CheckIn:Read_GPS] Stopped
2025-05-29T19:20:02.526Z,1748546402.526 [Default:CheckIn:Read_Iridium] Running Loop=1
2025-05-29T19:20:10.296Z,1748546410.296 [DataOverHttps](INFO): Sending 76 bytes from file Logs/20250529T181614/Courier0034.lzma
2025-05-29T19:20:11.299Z,1748546411.299 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Courier0034.lzma.bak
2025-05-29T19:20:11.299Z,1748546411.299 [DataOverHttps](INFO): SBD MOMSN=25033393
2025-05-29T19:20:29.549Z,1748546429.549 [DataOverHttps](INFO): Sending 250 bytes from file Logs/20250529T181614/Express0035.lzma
2025-05-29T19:20:30.551Z,1748546430.551 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Express0035.lzma.bak
2025-05-29T19:20:30.551Z,1748546430.551 [DataOverHttps](INFO): SBD MOMSN=25033396
2025-05-29T19:20:32.032Z,1748546432.032 [Default:CheckIn:Read_Iridium] Stopped
2025-05-29T19:20:32.032Z,1748546432.032 [Default:CheckIn:C.Wait] Running Loop=1
2025-05-29T19:20:32.032Z,1748546432.032 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2025-05-29T19:20:34.887Z,1748546434.887 [NAL9602](INFO): Not Powering down - fast GPS
2025-05-29T19:25:32.761Z,1748546732.761 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2025-05-29T19:25:32.762Z,1748546732.762 [Default:CheckIn:C.Wait] Stopped
2025-05-29T19:25:32.762Z,1748546732.762 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2025-05-29T19:25:32.762Z,1748546732.762 [Default:CheckIn:D] Running Loop=1
2025-05-29T19:25:33.144Z,1748546733.144 [Default:CheckIn:D] Stopped
2025-05-29T19:25:33.144Z,1748546733.144 [Default:CheckIn:E] Running Loop=1
2025-05-29T19:25:33.550Z,1748546733.550 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 65.047221 min
2025-05-29T19:25:33.550Z,1748546733.550 [Default:CheckIn:E] Stopped
2025-05-29T19:25:33.550Z,1748546733.550 [Default:CheckIn](INFO): Completed Default:CheckIn
2025-05-29T19:25:33.550Z,1748546733.550 [Default:CheckIn] Stopped
2025-05-29T19:25:33.551Z,1748546733.551 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2025-05-29T19:25:33.551Z,1748546733.551 [Default:CheckIn](INFO): Running loop #12
2025-05-29T19:25:33.551Z,1748546733.551 [Default:CheckIn] Running Loop=12
2025-05-29T19:25:33.551Z,1748546733.551 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2025-05-29T19:25:33.551Z,1748546733.551 [Default:CheckIn:Read_GPS] Running Loop=1
2025-05-29T19:25:35.567Z,1748546735.567 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,192522.00,A,3648.16219,N,12147.28523,W,0.058,0.00,290525,,,D*79
2025-05-29T19:25:35.569Z,1748546735.569 [NAL9602](INFO): GPS fix at 20250529T192522: (36.802703, -121.788087)
2025-05-29T19:25:35.580Z,1748546735.580 [Default:CheckIn:Read_GPS] Stopped
2025-05-29T19:25:35.580Z,1748546735.580 [Default:CheckIn:Read_Iridium] Running Loop=1
2025-05-29T19:25:43.585Z,1748546743.585 [DataOverHttps](INFO): Sending 76 bytes from file Logs/20250529T181614/Courier0037.lzma
2025-05-29T19:25:44.587Z,1748546744.587 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Courier0037.lzma.bak
2025-05-29T19:25:44.587Z,1748546744.587 [DataOverHttps](INFO): SBD MOMSN=25033415
2025-05-29T19:26:00.814Z,1748546760.814 [DataOverHttps](INFO): Sending 174 bytes from file Logs/20250529T181614/Express0038.lzma
2025-05-29T19:26:01.815Z,1748546761.815 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Express0038.lzma.bak
2025-05-29T19:26:01.815Z,1748546761.815 [DataOverHttps](INFO): SBD MOMSN=25033420
2025-05-29T19:26:03.066Z,1748546763.066 [Default:CheckIn:Read_Iridium] Stopped
2025-05-29T19:26:03.066Z,1748546763.066 [Default:CheckIn:C.Wait] Running Loop=1
2025-05-29T19:26:03.066Z,1748546763.066 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2025-05-29T19:26:06.287Z,1748546766.287 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2025-05-29T19:26:06.361Z,1748546766.361 [NAL9602](ERROR): received:
+CSQ:0
OK743, 0, 0, 0, 0
OK
2025-05-29T19:30:31.746Z,1748547031.746 [BPC1](ERROR): Battery stick #2 (s/n: 0124) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0.
2025-05-29T19:30:31.747Z,1748547031.747 [BPC1](INFO): Calculating totals. Valid battery stick count: 54. Valid reserve battery stick count: 6.
2025-05-29T19:30:31.749Z,1748547031.749 [BPC1](INFO): Received data from all battery sticks.
2025-05-29T19:30:37.387Z,1748547037.387 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2025-05-29T19:31:03.666Z,1748547063.666 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2025-05-29T19:31:03.666Z,1748547063.666 [Default:CheckIn:C.Wait] Stopped
2025-05-29T19:31:03.666Z,1748547063.666 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2025-05-29T19:31:03.666Z,1748547063.666 [Default:CheckIn:D] Running Loop=1
2025-05-29T19:31:04.078Z,1748547064.078 [Default:CheckIn:D] Stopped
2025-05-29T19:31:04.078Z,1748547064.078 [Default:CheckIn:E] Running Loop=1
2025-05-29T19:31:04.463Z,1748547064.463 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 70.562793 min
2025-05-29T19:31:04.463Z,1748547064.463 [Default:CheckIn:E] Stopped
2025-05-29T19:31:04.464Z,1748547064.464 [Default:CheckIn](INFO): Completed Default:CheckIn
2025-05-29T19:31:04.464Z,1748547064.464 [Default:CheckIn] Stopped
2025-05-29T19:31:04.464Z,1748547064.464 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2025-05-29T19:31:04.464Z,1748547064.464 [Default:CheckIn](INFO): Running loop #13
2025-05-29T19:31:04.464Z,1748547064.464 [Default:CheckIn] Running Loop=13
2025-05-29T19:31:04.464Z,1748547064.464 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2025-05-29T19:31:04.464Z,1748547064.464 [Default:CheckIn:Read_GPS] Running Loop=1
2025-05-29T19:31:06.496Z,1748547066.496 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,193053.00,A,3648.16307,N,12147.28617,W,0.078,64.08,290525,,,D*49
2025-05-29T19:31:06.499Z,1748547066.499 [NAL9602](INFO): GPS fix at 20250529T193053: (36.802718, -121.788103)
2025-05-29T19:31:06.540Z,1748547066.540 [Default:CheckIn:Read_GPS] Stopped
2025-05-29T19:31:06.540Z,1748547066.540 [Default:CheckIn:Read_Iridium] Running Loop=1
2025-05-29T19:31:14.297Z,1748547074.297 [DataOverHttps](INFO): Sending 88 bytes from file Logs/20250529T181614/Courier0040.lzma
2025-05-29T19:31:15.299Z,1748547075.299 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Courier0040.lzma.bak
2025-05-29T19:31:15.299Z,1748547075.299 [DataOverHttps](INFO): SBD MOMSN=25033487
2025-05-29T19:31:31.426Z,1748547091.426 [DataOverHttps](INFO): Sending 243 bytes from file Logs/20250529T181614/Express0041.lzma
2025-05-29T19:31:32.428Z,1748547092.428 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Express0041.lzma.bak
2025-05-29T19:31:32.428Z,1748547092.428 [DataOverHttps](INFO): SBD MOMSN=25033492
2025-05-29T19:31:33.968Z,1748547093.968 [Default:CheckIn:Read_Iridium] Stopped
2025-05-29T19:31:33.968Z,1748547093.968 [Default:CheckIn:C.Wait] Running Loop=1
2025-05-29T19:31:33.968Z,1748547093.968 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2025-05-29T19:31:38.393Z,1748547098.393 [NAL9602](INFO): Not Powering down - fast GPS
2025-05-29T19:36:34.531Z,1748547394.531 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2025-05-29T19:36:34.531Z,1748547394.531 [Default:CheckIn:C.Wait] Stopped
2025-05-29T19:36:34.531Z,1748547394.531 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2025-05-29T19:36:34.531Z,1748547394.531 [Default:CheckIn:D] Running Loop=1
2025-05-29T19:36:34.948Z,1748547394.948 [Default:CheckIn:D] Stopped
2025-05-29T19:36:34.948Z,1748547394.948 [Default:CheckIn:E] Running Loop=1
2025-05-29T19:36:35.342Z,1748547395.342 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 76.077287 min
2025-05-29T19:36:35.342Z,1748547395.342 [Default:CheckIn:E] Stopped
2025-05-29T19:36:35.342Z,1748547395.342 [Default:CheckIn](INFO): Completed Default:CheckIn
2025-05-29T19:36:35.342Z,1748547395.342 [Default:CheckIn] Stopped
2025-05-29T19:36:35.342Z,1748547395.342 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2025-05-29T19:36:35.342Z,1748547395.342 [Default:CheckIn](INFO): Running loop #14
2025-05-29T19:36:35.342Z,1748547395.342 [Default:CheckIn] Running Loop=14
2025-05-29T19:36:35.342Z,1748547395.342 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2025-05-29T19:36:35.342Z,1748547395.342 [Default:CheckIn:Read_GPS] Running Loop=1
2025-05-29T19:36:37.351Z,1748547397.351 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,193624.00,A,3648.16247,N,12147.28397,W,0.272,64.08,290525,,,D*4F
2025-05-29T19:36:37.354Z,1748547397.354 [NAL9602](INFO): GPS fix at 20250529T193624: (36.802708, -121.788066)
2025-05-29T19:36:37.391Z,1748547397.391 [Default:CheckIn:Read_GPS] Stopped
2025-05-29T19:36:37.391Z,1748547397.391 [Default:CheckIn:Read_Iridium] Running Loop=1
2025-05-29T19:36:45.036Z,1748547405.036 [DataOverHttps](INFO): Sending 75 bytes from file Logs/20250529T181614/Courier0043.lzma
2025-05-29T19:36:46.040Z,1748547406.040 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Courier0043.lzma.bak
2025-05-29T19:36:46.040Z,1748547406.040 [DataOverHttps](INFO): SBD MOMSN=25033523
2025-05-29T19:37:02.097Z,1748547422.097 [DataOverHttps](INFO): Sending 165 bytes from file Logs/20250529T181614/Express0044.lzma
2025-05-29T19:37:03.099Z,1748547423.099 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Express0044.lzma.bak
2025-05-29T19:37:03.099Z,1748547423.099 [DataOverHttps](INFO): SBD MOMSN=25033532
2025-05-29T19:37:04.429Z,1748547424.429 [Default:CheckIn:Read_Iridium] Stopped
2025-05-29T19:37:04.429Z,1748547424.429 [Default:CheckIn:C.Wait] Running Loop=1
2025-05-29T19:37:04.429Z,1748547424.429 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2025-05-29T19:37:08.051Z,1748547428.051 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2025-05-29T19:37:08.125Z,1748547428.125 [NAL9602](ERROR): received:
+CSQ:0
OK743, 0, 0, 0, 0
OK
2025-05-29T19:39:33.950Z,1748547573.950 [NAL9602](INFO): SBD MO Status=2, MOMSN=20744, MT Status=2, MTMSN=0
2025-05-29T19:39:33.950Z,1748547573.950 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2025-05-29T19:41:14.151Z,1748547674.151 [NAL9602](INFO): SBD MO Status=2, MOMSN=20744, MT Status=2, MTMSN=0
2025-05-29T19:41:14.151Z,1748547674.151 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2025-05-29T19:41:39.608Z,1748547699.608 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2025-05-29T19:42:05.071Z,1748547725.071 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2025-05-29T19:42:05.071Z,1748547725.071 [Default:CheckIn:C.Wait] Stopped
2025-05-29T19:42:05.071Z,1748547725.071 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2025-05-29T19:42:05.072Z,1748547725.072 [Default:CheckIn:D] Running Loop=1
2025-05-29T19:42:05.468Z,1748547725.468 [Default:CheckIn:D] Stopped
2025-05-29T19:42:05.468Z,1748547725.468 [Default:CheckIn:E] Running Loop=1
2025-05-29T19:42:05.880Z,1748547725.880 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 81.585962 min
2025-05-29T19:42:05.880Z,1748547725.880 [Default:CheckIn:E] Stopped
2025-05-29T19:42:05.880Z,1748547725.880 [Default:CheckIn](INFO): Completed Default:CheckIn
2025-05-29T19:42:05.880Z,1748547725.880 [Default:CheckIn] Stopped
2025-05-29T19:42:05.880Z,1748547725.880 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2025-05-29T19:42:05.880Z,1748547725.880 [Default:CheckIn](INFO): Running loop #15
2025-05-29T19:42:05.880Z,1748547725.880 [Default:CheckIn] Running Loop=15
2025-05-29T19:42:05.881Z,1748547725.881 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2025-05-29T19:42:05.881Z,1748547725.881 [Default:CheckIn:Read_GPS] Running Loop=1
2025-05-29T19:42:07.883Z,1748547727.883 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,194155.00,A,3648.16270,N,12147.28245,W,0.330,64.08,290525,,,D*44
2025-05-29T19:42:07.886Z,1748547727.886 [NAL9602](INFO): GPS fix at 20250529T194155: (36.802712, -121.788041)
2025-05-29T19:42:07.905Z,1748547727.905 [Default:CheckIn:Read_GPS] Stopped
2025-05-29T19:42:07.905Z,1748547727.905 [Default:CheckIn:Read_Iridium] Running Loop=1
2025-05-29T19:42:15.721Z,1748547735.721 [DataOverHttps](INFO): Sending 76 bytes from file Logs/20250529T181614/Courier0046.lzma
2025-05-29T19:42:16.723Z,1748547736.723 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Courier0046.lzma.bak
2025-05-29T19:42:16.723Z,1748547736.723 [DataOverHttps](INFO): SBD MOMSN=25033586
2025-05-29T19:42:33.241Z,1748547753.241 [DataOverHttps](INFO): Sending 242 bytes from file Logs/20250529T181614/Express0047.lzma
2025-05-29T19:42:34.243Z,1748547754.243 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Express0047.lzma.bak
2025-05-29T19:42:34.243Z,1748547754.243 [DataOverHttps](INFO): SBD MOMSN=25033589
2025-05-29T19:42:35.797Z,1748547755.797 [Default:CheckIn:Read_Iridium] Stopped
2025-05-29T19:42:35.797Z,1748547755.797 [Default:CheckIn:C.Wait] Running Loop=1
2025-05-29T19:42:35.797Z,1748547755.797 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2025-05-29T19:42:40.606Z,1748547760.606 [NAL9602](INFO): Not Powering down - fast GPS
2025-05-29T19:47:36.371Z,1748548056.371 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2025-05-29T19:47:36.371Z,1748548056.371 [Default:CheckIn:C.Wait] Stopped
2025-05-29T19:47:36.371Z,1748548056.371 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2025-05-29T19:47:36.371Z,1748548056.371 [Default:CheckIn:D] Running Loop=1
2025-05-29T19:47:36.779Z,1748548056.779 [Default:CheckIn:D] Stopped
2025-05-29T19:47:36.779Z,1748548056.779 [Default:CheckIn:E] Running Loop=1
2025-05-29T19:47:37.190Z,1748548057.190 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 87.107804 min
2025-05-29T19:47:37.190Z,1748548057.190 [Default:CheckIn:E] Stopped
2025-05-29T19:47:37.190Z,1748548057.190 [Default:CheckIn](INFO): Completed Default:CheckIn
2025-05-29T19:47:37.190Z,1748548057.190 [Default:CheckIn] Stopped
2025-05-29T19:47:37.191Z,1748548057.191 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2025-05-29T19:47:37.191Z,1748548057.191 [Default:CheckIn](INFO): Running loop #16
2025-05-29T19:47:37.191Z,1748548057.191 [Default:CheckIn] Running Loop=16
2025-05-29T19:47:37.191Z,1748548057.191 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2025-05-29T19:47:37.191Z,1748548057.191 [Default:CheckIn:Read_GPS] Running Loop=1
2025-05-29T19:47:39.187Z,1748548059.187 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,194726.00,A,3648.16589,N,12147.28769,W,0.622,84.40,290525,,,D*48
2025-05-29T19:47:39.189Z,1748548059.189 [NAL9602](INFO): GPS fix at 20250529T194726: (36.802765, -121.788128)
2025-05-29T19:47:39.200Z,1748548059.200 [Default:CheckIn:Read_GPS] Stopped
2025-05-29T19:47:39.200Z,1748548059.200 [Default:CheckIn:Read_Iridium] Running Loop=1
2025-05-29T19:47:49.158Z,1748548069.158 [DataOverHttps](INFO): Sending 76 bytes from file Logs/20250529T181614/Courier0049.lzma
2025-05-29T19:47:50.171Z,1748548070.171 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Courier0049.lzma.bak
2025-05-29T19:47:50.171Z,1748548070.171 [DataOverHttps](INFO): SBD MOMSN=25033667
2025-05-29T19:48:05.068Z,1748548085.068 [NAL9602](INFO): SBD MO Status=2, MOMSN=20744, MT Status=2, MTMSN=0
2025-05-29T19:48:05.068Z,1748548085.068 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2025-05-29T19:48:06.413Z,1748548086.413 [DataOverHttps](INFO): Sending 166 bytes from file Logs/20250529T181614/Express0050.lzma
2025-05-29T19:48:07.416Z,1748548087.416 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Express0050.lzma.bak
2025-05-29T19:48:07.416Z,1748548087.416 [DataOverHttps](INFO): SBD MOMSN=25033670
2025-05-29T19:48:08.723Z,1748548088.723 [Default:CheckIn:Read_Iridium] Stopped
2025-05-29T19:48:08.723Z,1748548088.723 [Default:CheckIn:C.Wait] Running Loop=1
2025-05-29T19:48:08.723Z,1748548088.723 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2025-05-29T19:50:05.526Z,1748548205.526 [NAL9602](INFO): SBD MO Status=2, MOMSN=20744, MT Status=2, MTMSN=0
2025-05-29T19:50:05.526Z,1748548205.526 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2025-05-29T19:50:27.343Z,1748548227.343 [NAL9602](INFO): SBD MO Status=2, MOMSN=20744, MT Status=2, MTMSN=0
2025-05-29T19:50:27.343Z,1748548227.343 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2025-05-29T19:52:14.885Z,1748548334.885 [NAL9602](INFO): SBD MO Status=2, MOMSN=20744, MT Status=2, MTMSN=0
2025-05-29T19:52:14.889Z,1748548334.889 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2025-05-29T19:52:46.914Z,1748548366.914 [NAL9602](INFO): SBD MO Status=2, MOMSN=20744, MT Status=2, MTMSN=0
2025-05-29T19:52:46.915Z,1748548366.915 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2025-05-29T19:52:47.212Z,1748548367.212 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2025-05-29T19:53:09.147Z,1748548389.147 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2025-05-29T19:53:09.147Z,1748548389.147 [Default:CheckIn:C.Wait] Stopped
2025-05-29T19:53:09.147Z,1748548389.147 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2025-05-29T19:53:09.147Z,1748548389.147 [Default:CheckIn:D] Running Loop=1
2025-05-29T19:53:09.448Z,1748548389.448 [Default:CheckIn:D] Stopped
2025-05-29T19:53:09.448Z,1748548389.448 [Default:CheckIn:E] Running Loop=1
2025-05-29T19:53:09.879Z,1748548389.879 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 92.652303 min
2025-05-29T19:53:09.879Z,1748548389.879 [Default:CheckIn:E] Stopped
2025-05-29T19:53:09.879Z,1748548389.879 [Default:CheckIn](INFO): Completed Default:CheckIn
2025-05-29T19:53:09.879Z,1748548389.879 [Default:CheckIn] Stopped
2025-05-29T19:53:09.879Z,1748548389.879 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2025-05-29T19:53:09.879Z,1748548389.879 [Default:CheckIn](INFO): Running loop #17
2025-05-29T19:53:09.879Z,1748548389.879 [Default:CheckIn] Running Loop=17
2025-05-29T19:53:09.879Z,1748548389.879 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2025-05-29T19:53:09.879Z,1748548389.879 [Default:CheckIn:Read_GPS] Running Loop=1
2025-05-29T19:53:11.940Z,1748548391.940 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,195259.00,A,3648.16136,N,12147.28892,W,0.622,84.40,290525,,,D*4F
2025-05-29T19:53:11.951Z,1748548391.951 [NAL9602](INFO): GPS fix at 20250529T195259: (36.802689, -121.788149)
2025-05-29T19:53:11.990Z,1748548391.990 [Default:CheckIn:Read_GPS] Stopped
2025-05-29T19:53:11.990Z,1748548391.990 [Default:CheckIn:Read_Iridium] Running Loop=1
2025-05-29T19:53:25.909Z,1748548405.909 [DataOverHttps](INFO): Sending 76 bytes from file Logs/20250529T181614/Courier0052.lzma
2025-05-29T19:53:26.911Z,1748548406.911 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Courier0052.lzma.bak
2025-05-29T19:53:26.911Z,1748548406.911 [DataOverHttps](INFO): SBD MOMSN=25033689
2025-05-29T19:53:44.418Z,1748548424.418 [NAL9602](INFO): Not Powering down - fast GPS
2025-05-29T19:53:57.169Z,1748548437.169 [DataOverHttps](INFO): Sending 249 bytes from file Logs/20250529T181614/Express0053.lzma
2025-05-29T19:53:58.163Z,1748548438.163 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Express0053.lzma.bak
2025-05-29T19:53:58.163Z,1748548438.163 [DataOverHttps](INFO): SBD MOMSN=25033692
2025-05-29T19:53:59.840Z,1748548439.840 [Default:CheckIn:Read_Iridium] Stopped
2025-05-29T19:53:59.841Z,1748548439.841 [Default:CheckIn:C.Wait] Running Loop=1
2025-05-29T19:53:59.841Z,1748548439.841 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2025-05-29T19:59:00.363Z,1748548740.363 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2025-05-29T19:59:00.363Z,1748548740.363 [Default:CheckIn:C.Wait] Stopped
2025-05-29T19:59:00.363Z,1748548740.363 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2025-05-29T19:59:00.363Z,1748548740.363 [Default:CheckIn:D] Running Loop=1
2025-05-29T19:59:00.733Z,1748548740.733 [Default:CheckIn:D] Stopped
2025-05-29T19:59:00.733Z,1748548740.733 [Default:CheckIn:E] Running Loop=1
2025-05-29T19:59:01.124Z,1748548741.124 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 98.507039 min
2025-05-29T19:59:01.124Z,1748548741.124 [Default:CheckIn:E] Stopped
2025-05-29T19:59:01.124Z,1748548741.124 [Default:CheckIn](INFO): Completed Default:CheckIn
2025-05-29T19:59:01.124Z,1748548741.124 [Default:CheckIn] Stopped
2025-05-29T19:59:01.124Z,1748548741.124 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2025-05-29T19:59:01.125Z,1748548741.125 [Default:CheckIn](INFO): Running loop #18
2025-05-29T19:59:01.125Z,1748548741.125 [Default:CheckIn] Running Loop=18
2025-05-29T19:59:01.125Z,1748548741.125 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2025-05-29T19:59:01.125Z,1748548741.125 [Default:CheckIn:Read_GPS] Running Loop=1
2025-05-29T19:59:03.137Z,1748548743.137 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,195850.00,A,3648.15959,N,12147.28456,W,0.117,106.37,290525,,,D*70
2025-05-29T19:59:03.199Z,1748548743.199 [NAL9602](INFO): GPS fix at 20250529T195850: (36.802660, -121.788076)
2025-05-29T19:59:03.278Z,1748548743.278 [Default:CheckIn:Read_GPS] Stopped
2025-05-29T19:59:03.278Z,1748548743.278 [Default:CheckIn:Read_Iridium] Running Loop=1
2025-05-29T19:59:20.157Z,1748548760.157 [DataOverHttps](INFO): Sending 76 bytes from file Logs/20250529T181614/Courier0055.lzma
2025-05-29T19:59:21.159Z,1748548761.159 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Courier0055.lzma.bak
2025-05-29T19:59:21.159Z,1748548761.159 [DataOverHttps](INFO): SBD MOMSN=25033764
2025-05-29T19:59:52.970Z,1748548792.970 [DataOverHttps](INFO): Sending 171 bytes from file Logs/20250529T181614/Express0056.lzma
2025-05-29T19:59:53.971Z,1748548793.971 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Express0056.lzma.bak
2025-05-29T19:59:53.971Z,1748548793.971 [DataOverHttps](INFO): SBD MOMSN=25033767
2025-05-29T19:59:55.794Z,1748548795.794 [Default:CheckIn:Read_Iridium] Stopped
2025-05-29T19:59:55.794Z,1748548795.794 [Default:CheckIn:C.Wait] Running Loop=1
2025-05-29T19:59:55.794Z,1748548795.794 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2025-05-29T19:59:57.796Z,1748548797.796 [NAL9602](INFO): SBD MO Status=2, MOMSN=20744, MT Status=2, MTMSN=0
2025-05-29T19:59:57.796Z,1748548797.796 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2025-05-29T20:00:20.110Z,1748548820.110 [NAL9602](INFO): SBD MO Status=2, MOMSN=20744, MT Status=2, MTMSN=0
2025-05-29T20:00:20.110Z,1748548820.110 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2025-05-29T20:01:30.368Z,1748548890.368 [NAL9602](INFO): SBD MO Status=0, MOMSN=20744, MT Status=0, MTMSN=0
2025-05-29T20:01:30.368Z,1748548890.368 [NAL9602](INFO): No messages in MT queue
2025-05-29T20:02:00.845Z,1748548920.845 [NAL9602](INFO): Not Powering down - fast GPS
2025-05-29T20:04:56.462Z,1748549096.462 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2025-05-29T20:04:56.463Z,1748549096.463 [Default:CheckIn:C.Wait] Stopped
2025-05-29T20:04:56.463Z,1748549096.463 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2025-05-29T20:04:56.463Z,1748549096.463 [Default:CheckIn:D] Running Loop=1
2025-05-29T20:04:56.866Z,1748549096.866 [Default:CheckIn:D] Stopped
2025-05-29T20:04:56.866Z,1748549096.866 [Default:CheckIn:E] Running Loop=1
2025-05-29T20:04:57.299Z,1748549097.299 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 104.442594 min
2025-05-29T20:04:57.299Z,1748549097.299 [Default:CheckIn:E] Stopped
2025-05-29T20:04:57.300Z,1748549097.300 [Default:CheckIn](INFO): Completed Default:CheckIn
2025-05-29T20:04:57.300Z,1748549097.300 [Default:CheckIn] Stopped
2025-05-29T20:04:57.300Z,1748549097.300 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2025-05-29T20:04:57.300Z,1748549097.300 [Default:CheckIn](INFO): Running loop #19
2025-05-29T20:04:57.300Z,1748549097.300 [Default:CheckIn] Running Loop=19
2025-05-29T20:04:57.300Z,1748549097.300 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2025-05-29T20:04:57.300Z,1748549097.300 [Default:CheckIn:Read_GPS] Running Loop=1
2025-05-29T20:04:59.327Z,1748549099.327 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,200446.00,A,3648.16388,N,12147.28158,W,0.739,106.37,290525,,,D*70
2025-05-29T20:04:59.329Z,1748549099.329 [NAL9602](INFO): GPS fix at 20250529T200446: (36.802731, -121.788026)
2025-05-29T20:04:59.346Z,1748549099.346 [Default:CheckIn:Read_GPS] Stopped
2025-05-29T20:04:59.346Z,1748549099.346 [Default:CheckIn:Read_Iridium] Running Loop=1
2025-05-29T20:05:07.805Z,1748549107.805 [DataOverHttps](INFO): Sending 76 bytes from file Logs/20250529T181614/Courier0058.lzma
2025-05-29T20:05:08.807Z,1748549108.807 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Courier0058.lzma.bak
2025-05-29T20:05:08.807Z,1748549108.807 [DataOverHttps](INFO): SBD MOMSN=25033786
2025-05-29T20:05:34.137Z,1748549134.137 [DataOverHttps](INFO): Sending 168 bytes from file Logs/20250529T181614/Express0059.lzma
2025-05-29T20:05:35.141Z,1748549135.141 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Express0059.lzma.bak
2025-05-29T20:05:35.141Z,1748549135.141 [DataOverHttps](INFO): SBD MOMSN=25033789
2025-05-29T20:05:36.588Z,1748549136.588 [Default:CheckIn:Read_Iridium] Stopped
2025-05-29T20:05:36.588Z,1748549136.588 [Default:CheckIn:C.Wait] Running Loop=1
2025-05-29T20:05:36.588Z,1748549136.588 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2025-05-29T20:09:45.618Z,1748549385.618 [NAL9602](INFO): SBD MO Status=2, MOMSN=20745, MT Status=2, MTMSN=0
2025-05-29T20:09:45.619Z,1748549385.619 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2025-05-29T20:10:03.348Z,1748549403.348 [NAL9602](INFO): SBD MO Status=2, MOMSN=20745, MT Status=2, MTMSN=0
2025-05-29T20:10:03.348Z,1748549403.348 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2025-05-29T20:10:03.746Z,1748549403.746 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2025-05-29T20:10:34.449Z,1748549434.449 [NAL9602](INFO): Not Powering down - fast GPS
2025-05-29T20:10:37.298Z,1748549437.298 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2025-05-29T20:10:37.298Z,1748549437.298 [Default:CheckIn:C.Wait] Stopped
2025-05-29T20:10:37.299Z,1748549437.299 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2025-05-29T20:10:37.299Z,1748549437.299 [Default:CheckIn:D] Running Loop=1
2025-05-29T20:10:37.695Z,1748549437.695 [Default:CheckIn:D] Stopped
2025-05-29T20:10:37.695Z,1748549437.695 [Default:CheckIn:E] Running Loop=1
2025-05-29T20:10:38.096Z,1748549438.096 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 110.123079 min
2025-05-29T20:10:38.096Z,1748549438.096 [Default:CheckIn:E] Stopped
2025-05-29T20:10:38.096Z,1748549438.096 [Default:CheckIn](INFO): Completed Default:CheckIn
2025-05-29T20:10:38.096Z,1748549438.096 [Default:CheckIn] Stopped
2025-05-29T20:10:38.096Z,1748549438.096 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2025-05-29T20:10:38.096Z,1748549438.096 [Default:CheckIn](INFO): Running loop #20
2025-05-29T20:10:38.096Z,1748549438.096 [Default:CheckIn] Running Loop=20
2025-05-29T20:10:38.097Z,1748549438.097 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2025-05-29T20:10:38.097Z,1748549438.097 [Default:CheckIn:Read_GPS] Running Loop=1
2025-05-29T20:10:40.113Z,1748549440.113 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,201027.00,A,3648.16192,N,12147.28389,W,0.117,111.46,290525,,,D*7F
2025-05-29T20:10:40.115Z,1748549440.115 [NAL9602](INFO): GPS fix at 20250529T201027: (36.802699, -121.788065)
2025-05-29T20:10:40.127Z,1748549440.127 [Default:CheckIn:Read_GPS] Stopped
2025-05-29T20:10:40.127Z,1748549440.127 [Default:CheckIn:Read_Iridium] Running Loop=1
2025-05-29T20:10:50.684Z,1748549450.684 [DataOverHttps](INFO): Sending 76 bytes from file Logs/20250529T181614/Courier0061.lzma
2025-05-29T20:10:51.687Z,1748549451.687 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Courier0061.lzma.bak
2025-05-29T20:10:51.687Z,1748549451.687 [DataOverHttps](INFO): SBD MOMSN=25033866
2025-05-29T20:11:02.754Z,1748549462.754 [NAL9602](INFO): SBD MO Status=2, MOMSN=20745, MT Status=2, MTMSN=0
2025-05-29T20:11:02.755Z,1748549462.755 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2025-05-29T20:11:08.253Z,1748549468.253 [DataOverHttps](INFO): Sending 251 bytes from file Logs/20250529T181614/Express0062.lzma
2025-05-29T20:11:09.255Z,1748549469.255 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Express0062.lzma.bak
2025-05-29T20:11:09.255Z,1748549469.255 [DataOverHttps](INFO): SBD MOMSN=25033869
2025-05-29T20:11:10.845Z,1748549470.845 [Default:CheckIn:Read_Iridium] Stopped
2025-05-29T20:11:10.845Z,1748549470.845 [Default:CheckIn:C.Wait] Running Loop=1
2025-05-29T20:11:10.845Z,1748549470.845 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2025-05-29T20:11:30.218Z,1748549490.218 [NAL9602](INFO): SBD MO Status=2, MOMSN=20745, MT Status=2, MTMSN=0
2025-05-29T20:11:30.218Z,1748549490.218 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2025-05-29T20:11:55.288Z,1748549515.288 [NAL9602](INFO): SBD MO Status=2, MOMSN=20745, MT Status=2, MTMSN=0
2025-05-29T20:11:55.288Z,1748549515.288 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2025-05-29T20:12:35.691Z,1748549555.691 [NAL9602](INFO): SBD MO Status=2, MOMSN=20745, MT Status=2, MTMSN=0
2025-05-29T20:12:35.691Z,1748549555.691 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2025-05-29T20:15:42.360Z,1748549742.360 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2025-05-29T20:16:11.474Z,1748549771.474 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2025-05-29T20:16:11.475Z,1748549771.475 [Default:CheckIn:C.Wait] Stopped
2025-05-29T20:16:11.475Z,1748549771.475 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2025-05-29T20:16:11.475Z,1748549771.475 [Default:CheckIn:D] Running Loop=1
2025-05-29T20:16:11.897Z,1748549771.897 [Default:CheckIn:D] Stopped
2025-05-29T20:16:11.897Z,1748549771.897 [Default:CheckIn:E] Running Loop=1
2025-05-29T20:16:12.276Z,1748549772.276 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 115.693107 min
2025-05-29T20:16:12.276Z,1748549772.276 [Default:CheckIn:E] Stopped
2025-05-29T20:16:12.277Z,1748549772.277 [Default:CheckIn](INFO): Completed Default:CheckIn
2025-05-29T20:16:12.277Z,1748549772.277 [Default:CheckIn] Stopped
2025-05-29T20:16:12.277Z,1748549772.277 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2025-05-29T20:16:12.277Z,1748549772.277 [Default:CheckIn](INFO): Running loop #21
2025-05-29T20:16:12.277Z,1748549772.277 [Default:CheckIn] Running Loop=21
2025-05-29T20:16:12.277Z,1748549772.277 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2025-05-29T20:16:12.277Z,1748549772.277 [Default:CheckIn:Read_GPS] Running Loop=1
2025-05-29T20:16:14.279Z,1748549774.279 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,201601.00,A,3648.16079,N,12147.28529,W,0.233,111.46,290525,,,D*70
2025-05-29T20:16:14.282Z,1748549774.282 [NAL9602](INFO): GPS fix at 20250529T201601: (36.802680, -121.788088)
2025-05-29T20:16:14.319Z,1748549774.319 [Default:CheckIn:Read_GPS] Stopped
2025-05-29T20:16:14.319Z,1748549774.319 [Default:CheckIn:Read_Iridium] Running Loop=1
2025-05-29T20:16:22.473Z,1748549782.473 [DataOverHttps](INFO): Sending 76 bytes from file Logs/20250529T181614/Courier0064.lzma
2025-05-29T20:16:23.475Z,1748549783.475 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Courier0064.lzma.bak
2025-05-29T20:16:23.475Z,1748549783.475 [DataOverHttps](INFO): SBD MOMSN=25033887
2025-05-29T20:16:39.454Z,1748549799.454 [DataOverHttps](INFO): Sending 260 bytes from file Logs/20250529T181614/Express0065.lzma
2025-05-29T20:16:40.456Z,1748549800.456 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Express0065.lzma.bak
2025-05-29T20:16:40.456Z,1748549800.456 [DataOverHttps](INFO): SBD MOMSN=25033890
2025-05-29T20:16:41.779Z,1748549801.779 [Default:CheckIn:Read_Iridium] Stopped
2025-05-29T20:16:41.779Z,1748549801.779 [Default:CheckIn:C.Wait] Running Loop=1
2025-05-29T20:16:41.779Z,1748549801.779 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2025-05-29T20:16:46.698Z,1748549806.698 [NAL9602](INFO): Not Powering down - fast GPS
2025-05-29T20:21:42.419Z,1748550102.419 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2025-05-29T20:21:42.419Z,1748550102.419 [Default:CheckIn:C.Wait] Stopped
2025-05-29T20:21:42.419Z,1748550102.419 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2025-05-29T20:21:42.419Z,1748550102.419 [Default:CheckIn:D] Running Loop=1
2025-05-29T20:21:42.828Z,1748550102.828 [Default:CheckIn:D] Stopped
2025-05-29T20:21:42.828Z,1748550102.828 [Default:CheckIn:E] Running Loop=1
2025-05-29T20:21:43.239Z,1748550103.239 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 121.208634 min
2025-05-29T20:21:43.239Z,1748550103.239 [Default:CheckIn:E] Stopped
2025-05-29T20:21:43.239Z,1748550103.239 [Default:CheckIn](INFO): Completed Default:CheckIn
2025-05-29T20:21:43.239Z,1748550103.239 [Default:CheckIn] Stopped
2025-05-29T20:21:43.239Z,1748550103.239 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2025-05-29T20:21:43.240Z,1748550103.240 [Default:CheckIn](INFO): Running loop #22
2025-05-29T20:21:43.240Z,1748550103.240 [Default:CheckIn] Running Loop=22
2025-05-29T20:21:43.240Z,1748550103.240 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2025-05-29T20:21:43.240Z,1748550103.240 [Default:CheckIn:Read_GPS] Running Loop=1
2025-05-29T20:21:45.252Z,1748550105.252 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,202132.00,A,3648.16236,N,12147.28722,W,0.292,111.46,290525,,,D*7F
2025-05-29T20:21:45.275Z,1748550105.275 [NAL9602](INFO): GPS fix at 20250529T202132: (36.802706, -121.788120)
2025-05-29T20:21:45.294Z,1748550105.294 [Default:CheckIn:Read_GPS] Stopped
2025-05-29T20:21:45.295Z,1748550105.295 [Default:CheckIn:Read_Iridium] Running Loop=1
2025-05-29T20:21:52.952Z,1748550112.952 [DataOverHttps](INFO): Sending 75 bytes from file Logs/20250529T181614/Courier0067.lzma
2025-05-29T20:21:53.955Z,1748550113.955 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Courier0067.lzma.bak
2025-05-29T20:21:53.955Z,1748550113.955 [DataOverHttps](INFO): SBD MOMSN=25033969
2025-05-29T20:22:11.135Z,1748550131.135 [DataOverHttps](INFO): Sending 180 bytes from file Logs/20250529T181614/Express0068.lzma
2025-05-29T20:22:12.135Z,1748550132.135 [DataOverHttps](INFO): Moved sent file to Logs/20250529T181614/Express0068.lzma.bak
2025-05-29T20:22:12.135Z,1748550132.135 [DataOverHttps](INFO): SBD MOMSN=25033972
2025-05-29T20:22:13.620Z,1748550133.620 [Default:CheckIn:Read_Iridium] Stopped
2025-05-29T20:22:13.620Z,1748550133.620 [Default:CheckIn:C.Wait] Running Loop=1
2025-05-29T20:22:13.620Z,1748550133.620 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2025-05-29T20:22:16.031Z,1748550136.031 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2025-05-29T20:22:16.113Z,1748550136.113 [NAL9602](ERROR): received:
+CSQ:0
OK745, 2, 0, 0, 0
OK
2025-05-29T20:23:03.712Z,1748550183.712 [NAL9602](INFO): SBD MO Status=2, MOMSN=20745, MT Status=2, MTMSN=0
2025-05-29T20:23:03.712Z,1748550183.712 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2025-05-29T20:23:33.046Z,1748550213.046 [CommandExec](IMPORTANT): got command restart system
2025-05-29T20:23:35.189Z,1748550215.189 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2025-05-29T20:23:35.189Z,1748550215.189 [CommandExec ThreadHandler](INFO): Uninitializing protected caller thread.
2025-05-29T20:23:35.190Z,1748550215.190 [CommandExec](INFO): Uninitializing the command executive.
2025-05-29T20:23:35.190Z,1748550215.190 [CommandExec](INFO): Uninitializing the command scheduler.
2025-05-29T20:23:35.190Z,1748550215.190 [CommandExec ThreadHandler](INFO): Thread cancelled.
2025-05-29T20:23:35.369Z,1748550215.369 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye!
2025-05-29T20:23:35.369Z,1748550215.369 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2025-05-29T20:23:35.369Z,1748550215.369 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2025-05-29T20:23:35.370Z,1748550215.370 [NavChartDb](INFO): Join timeout helper Thread ID is 3109
2025-05-29T20:23:35.725Z,1748550215.725 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2025-05-29T20:23:35.725Z,1748550215.725 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2025-05-29T20:23:35.737Z,1748550215.737 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2025-05-29T20:23:35.737Z,1748550215.737 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2025-05-29T20:23:35.738Z,1748550215.737 [Radio_Surface](INFO): Join timeout helper Thread ID is 3110
202