2022-03-15T18:06:12.258Z,1647367572.258 [Supervisor](DEBUG): Initializing supervisor. 2022-03-15T18:06:12.262Z,1647367572.263 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2022-03-15T18:06:12.263Z,1647367572.263 [SyncHandler](INFO): Protected caller Thread ID is 835 2022-03-15T18:06:12.263Z,1647367572.263 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2022-03-15T18:06:12.264Z,1647367572.264 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2022-03-15T18:06:12.265Z,1647367572.265 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 836 2022-03-15T18:06:12.269Z,1647367572.269 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2022-03-15T18:06:12.288Z,1647367572.288 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread. 2022-03-15T18:06:12.289Z,1647367572.289 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2022-03-15T18:06:12.290Z,1647367572.290 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 837 2022-03-15T18:06:12.294Z,1647367572.294 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2022-03-15T18:06:12.295Z,1647367572.295 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2022-03-15T18:06:12.296Z,1647367572.296 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 838 2022-03-15T18:06:12.298Z,1647367572.298 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2022-03-15T18:06:12.299Z,1647367572.299 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0 2022-03-15T18:06:12.299Z,1647367572.299 [logger ThreadHandler](INFO): Protected caller Thread ID is 839 2022-03-15T18:06:12.303Z,1647367572.303 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2022-03-15T18:06:12.304Z,1647367572.304 [Supervisor](INFO): Looking for Config files in directory: Config/ 2022-03-15T18:06:12.308Z,1647367572.308 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2022-03-15T18:06:12.543Z,1647367572.543 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2022-03-15T18:06:12.545Z,1647367572.545 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2022-03-15T18:06:12.627Z,1647367572.627 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2022-03-15T18:06:13.142Z,1647367573.142 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2022-03-15T18:06:13.143Z,1647367573.143 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2022-03-15T18:06:13.473Z,1647367573.473 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2022-03-15T18:06:13.474Z,1647367573.474 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2022-03-15T18:06:13.570Z,1647367573.570 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2022-03-15T18:06:13.572Z,1647367573.572 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2022-03-15T18:06:13.942Z,1647367573.942 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2022-03-15T18:06:13.944Z,1647367573.944 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2022-03-15T18:06:14.150Z,1647367574.150 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2022-03-15T18:06:14.150Z,1647367574.150 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2022-03-15T18:06:14.611Z,1647367574.611 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2022-03-15T18:06:14.612Z,1647367574.612 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2022-03-15T18:06:14.740Z,1647367574.740 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2022-03-15T18:06:14.742Z,1647367574.742 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2022-03-15T18:06:14.823Z,1647367574.823 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2022-03-15T18:06:15.515Z,1647367575.515 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2022-03-15T18:06:15.517Z,1647367575.517 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2022-03-15T18:06:15.883Z,1647367575.883 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2022-03-15T18:06:15.884Z,1647367575.884 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2022-03-15T18:06:16.605Z,1647367576.605 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2022-03-15T18:06:16.607Z,1647367576.607 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2022-03-15T18:06:16.718Z,1647367576.718 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2022-03-15T18:06:16.719Z,1647367576.719 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2022-03-15T18:06:16.872Z,1647367576.872 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2022-03-15T18:06:16.873Z,1647367576.873 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg 2022-03-15T18:06:17.102Z,1647367577.102 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock 2022-03-15T18:06:17.104Z,1647367577.104 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/ 2022-03-15T18:06:17.107Z,1647367577.107 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg 2022-03-15T18:06:17.198Z,1647367577.198 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg 2022-03-15T18:06:17.284Z,1647367577.284 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg 2022-03-15T18:06:17.387Z,1647367577.387 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg 2022-03-15T18:06:17.470Z,1647367577.470 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg 2022-03-15T18:06:17.567Z,1647367577.567 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg 2022-03-15T18:06:17.668Z,1647367577.668 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg 2022-03-15T18:06:17.851Z,1647367577.851 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg 2022-03-15T18:06:17.927Z,1647367577.927 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg 2022-03-15T18:06:18.075Z,1647367578.075 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg 2022-03-15T18:06:18.213Z,1647367578.213 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg 2022-03-15T18:06:18.329Z,1647367578.329 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg 2022-03-15T18:06:18.594Z,1647367578.594 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2022-03-15T18:06:18.594Z,1647367578.594 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg 2022-03-15T18:06:18.599Z,1647367578.599 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2022-03-15T18:06:18.672Z,1647367578.672 [VerticalControl](DEBUG): Construct VerticalControl. 2022-03-15T18:06:18.736Z,1647367578.736 [VerticalControl] Loaded 2022-03-15T18:06:18.736Z,1647367578.736 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2022-03-15T18:06:18.739Z,1647367578.739 [HorizontalControl](DEBUG): Construct HorizontalControl. 2022-03-15T18:06:18.779Z,1647367578.779 [HorizontalControl] Loaded 2022-03-15T18:06:18.779Z,1647367578.779 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2022-03-15T18:06:18.782Z,1647367578.782 [SpeedControl](DEBUG): Construct SpeedControl. 2022-03-15T18:06:18.785Z,1647367578.785 [SpeedControl] Loaded 2022-03-15T18:06:18.785Z,1647367578.785 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2022-03-15T18:06:18.788Z,1647367578.788 [LoopControl](DEBUG): Construct LoopControl. 2022-03-15T18:06:18.788Z,1647367578.788 [LoopControl] Loaded 2022-03-15T18:06:18.789Z,1647367578.789 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2022-03-15T18:06:18.789Z,1647367578.789 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2022-03-15T18:06:18.791Z,1647367578.791 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2022-03-15T18:06:18.807Z,1647367578.807 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2022-03-15T18:06:18.808Z,1647367578.808 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2022-03-15T18:06:18.940Z,1647367578.940 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2022-03-15T18:06:18.941Z,1647367578.941 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2022-03-15T18:06:19.120Z,1647367579.120 [BuoyancyServo] Loaded 2022-03-15T18:06:19.121Z,1647367579.121 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2022-03-15T18:06:19.141Z,1647367579.141 [ElevatorServo] Loaded 2022-03-15T18:06:19.141Z,1647367579.141 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2022-03-15T18:06:19.160Z,1647367579.160 [MassServo] Loaded 2022-03-15T18:06:19.160Z,1647367579.160 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2022-03-15T18:06:19.178Z,1647367579.178 [RudderServo] Loaded 2022-03-15T18:06:19.178Z,1647367579.178 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2022-03-15T18:06:19.196Z,1647367579.196 [ThrusterServo] Loaded 2022-03-15T18:06:19.196Z,1647367579.196 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2022-03-15T18:06:19.197Z,1647367579.197 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2022-03-15T18:06:19.198Z,1647367579.198 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2022-03-15T18:06:19.299Z,1647367579.299 [DeadReckonUsingMultipleVelocitySources] Loaded 2022-03-15T18:06:19.299Z,1647367579.299 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2022-03-15T18:06:19.313Z,1647367579.313 [NavChart] Loaded 2022-03-15T18:06:19.313Z,1647367579.313 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2022-03-15T18:06:19.319Z,1647367579.319 [UniversalFixResidualReporter] Loaded 2022-03-15T18:06:19.319Z,1647367579.319 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2022-03-15T18:06:19.320Z,1647367579.320 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2022-03-15T18:06:19.320Z,1647367579.320 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2022-03-15T18:06:19.405Z,1647367579.405 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2022-03-15T18:06:19.405Z,1647367579.405 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2022-03-15T18:06:20.097Z,1647367580.097 [AHRS_M2] Loaded 2022-03-15T18:06:20.098Z,1647367580.098 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2022-03-15T18:06:20.903Z,1647367580.903 [BPC1] Loaded 2022-03-15T18:06:20.903Z,1647367580.903 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2022-03-15T18:06:21.045Z,1647367581.045 [DataOverHttps] Loaded 2022-03-15T18:06:21.045Z,1647367581.045 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread. 2022-03-15T18:06:21.046Z,1647367581.046 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 408C64E0 2022-03-15T18:06:21.047Z,1647367581.047 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 924 2022-03-15T18:06:21.067Z,1647367581.067 [Depth_Keller] Loaded 2022-03-15T18:06:21.068Z,1647367581.068 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2022-03-15T18:06:21.073Z,1647367581.073 [DropWeight] Loaded 2022-03-15T18:06:21.073Z,1647367581.073 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2022-03-15T18:06:21.134Z,1647367581.134 [NAL9602] Loaded 2022-03-15T18:06:21.134Z,1647367581.134 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2022-03-15T18:06:21.164Z,1647367581.164 [Onboard] Loaded 2022-03-15T18:06:21.164Z,1647367581.164 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread. 2022-03-15T18:06:21.165Z,1647367581.165 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 408F64E0 2022-03-15T18:06:21.165Z,1647367581.165 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 925 2022-03-15T18:06:21.179Z,1647367581.179 [Power24vConverter] Loaded 2022-03-15T18:06:21.179Z,1647367581.179 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread. 2022-03-15T18:06:21.192Z,1647367581.192 [Radio_Surface] Loaded 2022-03-15T18:06:21.192Z,1647367581.192 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2022-03-15T18:06:21.193Z,1647367581.193 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 409264E0 2022-03-15T18:06:21.194Z,1647367581.194 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 926 2022-03-15T18:06:21.215Z,1647367581.215 [AMEcho] Loaded 2022-03-15T18:06:21.215Z,1647367581.215 [ComponentRegistry](DEBUG): SyncComponent "AMEcho" handled in the control thread. 2022-03-15T18:06:21.299Z,1647367581.299 [DAT] Loaded 2022-03-15T18:06:21.300Z,1647367581.300 [ComponentRegistry](DEBUG): Component "DAT" handled in its own thread. 2022-03-15T18:06:21.301Z,1647367581.301 [DAT ThreadHandler](DEBUG): Created PCaller Thread at 409564E0 2022-03-15T18:06:21.301Z,1647367581.301 [DAT ThreadHandler](INFO): Protected caller Thread ID is 927 2022-03-15T18:06:21.301Z,1647367581.301 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2022-03-15T18:06:21.302Z,1647367581.302 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2022-03-15T18:06:21.459Z,1647367581.459 [DepthRateCalculator] Loaded 2022-03-15T18:06:21.460Z,1647367581.460 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2022-03-15T18:06:21.500Z,1647367581.500 [PitchRateCalculator] Loaded 2022-03-15T18:06:21.500Z,1647367581.500 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2022-03-15T18:06:21.534Z,1647367581.534 [SpeedCalculator] Loaded 2022-03-15T18:06:21.534Z,1647367581.534 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2022-03-15T18:06:21.559Z,1647367581.559 [TempGradientCalculator] Loaded 2022-03-15T18:06:21.559Z,1647367581.559 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2022-03-15T18:06:21.584Z,1647367581.584 [YawRateCalculator] Loaded 2022-03-15T18:06:21.584Z,1647367581.584 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2022-03-15T18:06:21.627Z,1647367581.627 [ElevatorOffsetCalculator] Loaded 2022-03-15T18:06:21.627Z,1647367581.627 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2022-03-15T18:06:21.627Z,1647367581.627 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2022-03-15T18:06:21.656Z,1647367581.656 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2022-03-15T18:06:22.445Z,1647367582.445 [CTD_Seabird] Loaded 2022-03-15T18:06:22.445Z,1647367582.445 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread. 2022-03-15T18:06:22.446Z,1647367582.446 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40A0B4E0 2022-03-15T18:06:22.447Z,1647367582.447 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 928 2022-03-15T18:06:22.467Z,1647367582.467 [PAR_Licor] Loaded 2022-03-15T18:06:22.467Z,1647367582.467 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2022-03-15T18:06:22.500Z,1647367582.500 [WetLabsBB2FL] Loaded 2022-03-15T18:06:22.501Z,1647367582.501 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2022-03-15T18:06:22.502Z,1647367582.502 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40A3B4E0 2022-03-15T18:06:22.502Z,1647367582.502 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 929 2022-03-15T18:06:22.503Z,1647367582.503 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2022-03-15T18:06:22.503Z,1647367582.503 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2022-03-15T18:06:22.546Z,1647367582.546 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2022-03-15T18:06:22.547Z,1647367582.547 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2022-03-15T18:06:22.924Z,1647367582.924 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2022-03-15T18:06:22.925Z,1647367582.925 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2022-03-15T18:06:23.114Z,1647367583.114 [SBIT](DEBUG): Construct Startup Built In Test. 2022-03-15T18:06:23.124Z,1647367583.124 [SBIT] Loaded 2022-03-15T18:06:23.124Z,1647367583.124 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2022-03-15T18:06:23.127Z,1647367583.127 [IBIT](DEBUG): Construct Initiated Built In Test. 2022-03-15T18:06:23.140Z,1647367583.140 [IBIT] Loaded 2022-03-15T18:06:23.141Z,1647367583.141 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2022-03-15T18:06:23.147Z,1647367583.147 [CBIT](DEBUG): Construct Continuous Built In Test. 2022-03-15T18:06:23.254Z,1647367583.254 [CBIT] Loaded 2022-03-15T18:06:23.254Z,1647367583.254 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2022-03-15T18:06:23.255Z,1647367583.255 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2022-03-15T18:06:23.256Z,1647367583.256 [Module Loader](DEBUG): Loading Module at Modules/Dock.so 2022-03-15T18:06:23.376Z,1647367583.376 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking) 2022-03-15T18:06:23.382Z,1647367583.382 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2022-03-15T18:06:23.385Z,1647367583.385 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2022-03-15T18:06:23.396Z,1647367583.396 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2022-03-15T18:06:23.398Z,1647367583.398 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40B714E0 2022-03-15T18:06:23.398Z,1647367583.398 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 930 2022-03-15T18:06:23.403Z,1647367583.403 [Supervisor](INFO): Main Thread ID is 831 2022-03-15T18:06:23.403Z,1647367583.403 [Supervisor](DEBUG): Running supervisor. 2022-03-15T18:06:23.404Z,1647367583.404 [CommandExec ThreadHandler](INFO): Handler Thread ID is 931 2022-03-15T18:06:23.404Z,1647367583.404 [CommandExec](INFO): Initializing the command executive. 2022-03-15T18:06:23.406Z,1647367583.406 [CommandLine ThreadHandler](INFO): Handler Thread ID is 932 2022-03-15T18:06:23.408Z,1647367583.408 [controlThread ThreadHandler](INFO): Handler Thread ID is 933 2022-03-15T18:06:23.408Z,1647367583.408 [controlThread](DEBUG): Initializing ControlThread 2022-03-15T18:06:23.409Z,1647367583.409 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2022-03-15T18:06:23.411Z,1647367583.411 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2022-03-15T18:06:23.412Z,1647367583.412 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2022-03-15T18:06:23.413Z,1647367583.413 [LoopControl](DEBUG): Initialize LoopControlComponent. 2022-03-15T18:06:23.415Z,1647367583.415 [NavChart](DEBUG): Initialize NavChart Navigation. 2022-03-15T18:06:23.415Z,1647367583.415 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2022-03-15T18:06:23.422Z,1647367583.422 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2022-03-15T18:06:23.422Z,1647367583.422 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2022-03-15T18:06:23.422Z,1647367583.422 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2022-03-15T18:06:23.423Z,1647367583.423 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2022-03-15T18:06:23.424Z,1647367583.424 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2022-03-15T18:06:23.424Z,1647367583.424 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2022-03-15T18:06:23.428Z,1647367583.428 [SBIT](INFO): Initialize SBIT Component. 2022-03-15T18:06:23.429Z,1647367583.429 [SBIT](IMPORTANT): git: 2022-01-05 2022-03-15T18:06:23.429Z,1647367583.429 [SBIT](INFO): git hash: 4648efb7c0362dd4a6331fa887af857d1a6abffc 2022-03-15T18:06:23.429Z,1647367583.429 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2022-03-15T18:06:23.430Z,1647367583.430 [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 2022-03-15T18:06:23.432Z,1647367583.432 [SBIT](INFO): Beginning SBIT in 41.000000 seconds. 2022-03-15T18:06:23.432Z,1647367583.432 [IBIT](INFO): Initialize IBIT Component. 2022-03-15T18:06:23.433Z,1647367583.433 [CBIT](DEBUG): Initialize CBIT Component. 2022-03-15T18:06:23.434Z,1647367583.434 [logger ThreadHandler](INFO): Handler Thread ID is 934 2022-03-15T18:06:23.448Z,1647367583.448 [CBIT](DEBUG): Initialized mux pins. 2022-03-15T18:06:23.448Z,1647367583.448 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL. 2022-03-15T18:06:23.448Z,1647367583.448 [CBIT](DEBUG): Initializing the watchdog timer. 2022-03-15T18:06:23.452Z,1647367583.452 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 935 2022-03-15T18:06:23.453Z,1647367583.453 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2022-03-15T18:06:23.464Z,1647367583.464 [Onboard ThreadHandler](INFO): Handler Thread ID is 936 2022-03-15T18:06:23.473Z,1647367583.473 [CBIT](CRITICAL): LAST REBOOT DUE TO WATCHDOG TIMER RESET. 2022-03-15T18:06:23.473Z,1647367583.473 [CBIT](DEBUG): Initializing heartbeat. 2022-03-15T18:06:23.485Z,1647367583.485 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 937 2022-03-15T18:06:23.496Z,1647367583.496 [DAT ThreadHandler](INFO): Handler Thread ID is 938 2022-03-15T18:06:23.497Z,1647367583.497 [DAT](INFO): Powering up 2022-03-15T18:06:23.498Z,1647367583.498 [DAT](DEBUG): Initializing DAT. 2022-03-15T18:06:23.500Z,1647367583.500 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 940 2022-03-15T18:06:23.502Z,1647367583.502 [CTD_Seabird](DEBUG): Initializing CTD_Seabird. 2022-03-15T18:06:23.504Z,1647367583.504 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 942 2022-03-15T18:06:23.509Z,1647367583.509 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 944 2022-03-15T18:06:23.509Z,1647367583.509 [WetLabsBB2FL](INFO): Powering up 2022-03-15T18:06:23.518Z,1647367583.518 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2022-03-15T18:06:23.518Z,1647367583.518 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2022-03-15T18:06:23.518Z,1647367583.518 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2022-03-15T18:06:23.518Z,1647367583.518 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2022-03-15T18:06:23.519Z,1647367583.519 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2022-03-15T18:06:23.519Z,1647367583.519 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2022-03-15T18:06:23.519Z,1647367583.519 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2022-03-15T18:06:23.519Z,1647367583.519 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2022-03-15T18:06:23.520Z,1647367583.520 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2022-03-15T18:06:23.520Z,1647367583.520 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2022-03-15T18:06:23.520Z,1647367583.520 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2022-03-15T18:06:23.520Z,1647367583.520 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2022-03-15T18:06:23.521Z,1647367583.521 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2022-03-15T18:06:23.521Z,1647367583.521 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2022-03-15T18:06:23.521Z,1647367583.521 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2022-03-15T18:06:23.521Z,1647367583.521 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2022-03-15T18:06:23.544Z,1647367583.544 [CBIT](DEBUG): Deactivating GF circuits. 2022-03-15T18:06:23.544Z,1647367583.544 [CBIT](DEBUG): Deactivating emergency mode. 2022-03-15T18:06:23.580Z,1647367583.580 [CBIT](DEBUG): Backplane powered. 2022-03-15T18:06:23.581Z,1647367583.581 [MissionManager](INFO): Loading Mission from file: Missions/Startup.xml 2022-03-15T18:06:23.606Z,1647367583.606 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2022-03-15T18:06:23.636Z,1647367583.636 [MissionManager](DEBUG): 2022-03-15T18:06:23.637Z,1647367583.637 [MissionManager](INFO): Loading Mission from file: Missions/Default.xml 2022-03-15T18:06:23.719Z,1647367583.719 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2022-03-15T18:06:23.720Z,1647367583.720 [Default:A.Wait](DEBUG): Construct Wait. 2022-03-15T18:06:23.722Z,1647367583.722 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2022-03-15T18:06:23.766Z,1647367583.766 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2022-03-15T18:06:23.777Z,1647367583.777 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2022-03-15T18:06:23.783Z,1647367583.783 [Default:E.Execute](DEBUG): Construct Execute. 2022-03-15T18:06:23.802Z,1647367583.802 [MissionManager](DEBUG): 0 Wait a moment to see if the scheduler starts a new mission before starting to actually run Default. 13 Burn on Dropped weight due to communications timeout. 5 Default mission has been running for Restarting logs and Default mission. restart logs 2022-03-15T18:06:23.807Z,1647367583.807 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,DropWeight,NAL9602,Power24vConverter,AMEcho,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2022-03-15T18:06:23.820Z,1647367583.820 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2022-03-15T18:06:23.888Z,1647367583.888 [Radio_Surface](INFO): Powering up 2022-03-15T18:06:24.021Z,1647367584.021 [Depth_Keller](ERROR): Pressure reading out of range: 1831.023193 decibar 2022-03-15T18:06:24.022Z,1647367584.022 [Power24vConverter](INFO): Powering up. 2022-03-15T18:06:24.022Z,1647367584.022 [AMEcho](INFO): Powering up. 2022-03-15T18:06:24.144Z,1647367584.144 [DepthRateCalculator](ERROR): Depth measurement is not active 2022-03-15T18:06:24.172Z,1647367584.172 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2022-03-15T18:06:24.180Z,1647367584.180 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2022-03-15T18:06:24.181Z,1647367584.181 [ElevatorServo](DEBUG): Initializing EZServoServo. 2022-03-15T18:06:24.188Z,1647367584.188 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2022-03-15T18:06:24.189Z,1647367584.189 [MassServo](DEBUG): Initializing EZServoServo. 2022-03-15T18:06:24.196Z,1647367584.196 [MassServo](DEBUG): Initializing MassServo. 2022-03-15T18:06:24.197Z,1647367584.197 [RudderServo](DEBUG): Initializing EZServoServo. 2022-03-15T18:06:24.204Z,1647367584.204 [RudderServo](DEBUG): Initializing RudderServo. 2022-03-15T18:06:24.205Z,1647367584.205 [ThrusterServo](DEBUG): Initializing EZServoServo. 2022-03-15T18:06:24.212Z,1647367584.212 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2022-03-15T18:06:24.214Z,1647367584.214 [CommandExec](FAULT): Scheduling is paused 2022-03-15T18:06:24.214Z,1647367584.214 [CBIT](INFO): Critical error at 20220315T180623 2022-03-15T18:06:24.215Z,1647367584.215 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals 2022-03-15T18:06:24.568Z,1647367584.568 [AMEcho](INFO): Powering down. 2022-03-15T18:06:25.053Z,1647367585.053 [RudderServo](ERROR): Rudder initialization uart error serial timeout 2022-03-15T18:06:25.053Z,1647367585.053 [RudderServo](FAULT): Rudder failed to initialize 2022-03-15T18:06:25.053Z,1647367585.053 [RudderServo] Communications Fault, FailCount= 1 2022-03-15T18:06:25.053Z,1647367585.053 [RudderServo](ERROR): Communications Fault 2022-03-15T18:06:25.160Z,1647367585.160 [CBIT](ERROR): Communications Fault in component: RudderServo 2022-03-15T18:06:25.174Z,1647367585.174 [AMEcho](IMPORTANT): Setting 'depthThreshold' to 20.000000 2022-03-15T18:06:25.365Z,1647367585.365 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2022-03-15T18:06:25.365Z,1647367585.365 [RudderServo](INFO): Powering down 2022-03-15T18:06:25.616Z,1647367585.616 [WetLabsBB2FL](INFO): Powering down 2022-03-15T18:06:25.997Z,1647367585.997 [RudderServo](DEBUG): Initializing EZServoServo. 2022-03-15T18:06:26.117Z,1647367586.117 [RudderServo](DEBUG): Initializing RudderServo. 2022-03-15T18:06:26.121Z,1647367586.121 [CBIT](INFO): Clearing failed state for component RudderServo 2022-03-15T18:06:26.121Z,1647367586.121 [RudderServo] No Fault, FailCount= 1 2022-03-15T18:06:39.666Z,1647367599.666 [DAT](INFO): commRate: 1200 2022-03-15T18:06:41.680Z,1647367601.680 [DAT](INFO): entering command mode 2022-03-15T18:06:41.932Z,1647367601.932 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:42.184Z,1647367602.184 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:42.436Z,1647367602.436 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:42.688Z,1647367602.688 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:42.940Z,1647367602.940 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:43.192Z,1647367603.192 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:43.444Z,1647367603.444 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:43.696Z,1647367603.696 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:43.948Z,1647367603.948 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:44.200Z,1647367604.200 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:44.452Z,1647367604.452 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:44.704Z,1647367604.704 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:44.956Z,1647367604.956 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:45.208Z,1647367605.208 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:45.460Z,1647367605.460 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:45.712Z,1647367605.712 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:45.964Z,1647367605.964 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:46.216Z,1647367606.216 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:46.468Z,1647367606.468 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:46.720Z,1647367606.720 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:46.972Z,1647367606.972 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:47.224Z,1647367607.224 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:47.476Z,1647367607.476 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:47.729Z,1647367607.729 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:47.980Z,1647367607.980 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:48.232Z,1647367608.232 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:48.484Z,1647367608.484 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:48.736Z,1647367608.736 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:48.988Z,1647367608.988 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:49.240Z,1647367609.240 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:49.492Z,1647367609.492 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:49.744Z,1647367609.744 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:49.996Z,1647367609.996 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:50.248Z,1647367610.248 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:50.500Z,1647367610.500 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:50.752Z,1647367610.752 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:51.004Z,1647367611.004 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:51.256Z,1647367611.256 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:51.433Z,1647367611.433 [NAL9602](INFO): Powering up NAL9602 2022-03-15T18:06:51.508Z,1647367611.508 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:51.760Z,1647367611.760 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:52.013Z,1647367612.013 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:52.264Z,1647367612.264 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:52.517Z,1647367612.517 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:52.768Z,1647367612.768 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:53.020Z,1647367613.020 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:53.272Z,1647367613.272 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:53.524Z,1647367613.524 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:53.776Z,1647367613.776 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:54.028Z,1647367614.028 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:54.280Z,1647367614.280 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:54.532Z,1647367614.532 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:54.784Z,1647367614.784 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:55.036Z,1647367615.036 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:55.288Z,1647367615.288 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:55.540Z,1647367615.540 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:55.792Z,1647367615.792 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:56.044Z,1647367616.044 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:56.296Z,1647367616.296 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:56.548Z,1647367616.548 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:56.800Z,1647367616.800 [DAT](DEBUG): checking for command mode acknowledgment 2022-03-15T18:06:56.800Z,1647367616.800 [DAT](FAULT): failed to enter command mode 2022-03-15T18:06:57.052Z,1647367617.052 [DAT](INFO): entering command mode 2022-03-15T18:06:57.305Z,1647367617.305 [DAT](INFO): setting verbose to 3 2022-03-15T18:06:57.557Z,1647367617.557 [DAT](INFO): set verbose to 3 2022-03-15T18:06:57.558Z,1647367617.558 [DAT](INFO): setting DatVerbose to 27440 2022-03-15T18:06:57.809Z,1647367617.809 [DAT](INFO): set DatVerbose to 27440 2022-03-15T18:06:57.809Z,1647367617.809 [DAT](INFO): setting transmit power to 8 2022-03-15T18:06:58.061Z,1647367618.061 [DAT](INFO): set transmit power to 8 2022-03-15T18:06:58.062Z,1647367618.062 [DAT](INFO): setting local address to 7 2022-03-15T18:06:58.313Z,1647367618.313 [DAT](INFO): set local address to 7 2022-03-15T18:07:02.358Z,1647367622.358 [NAL9602](INFO): NAL9602 initialized 2022-03-15T18:07:05.222Z,1647367625.222 [SBIT](IMPORTANT): Beginning Startup BIT 2022-03-15T18:07:05.226Z,1647367625.226 [CBIT](IMPORTANT): Beginning ground fault scan 2022-03-15T18:07:16.144Z,1647367636.144 [CBIT](ERROR): Ground fault scan returned out of bounds value. Re-running scan. 2022-03-15T18:07:16.515Z,1647367636.515 [CBIT](IMPORTANT): Beginning ground fault scan 2022-03-15T18:07:16.887Z,1647367636.887 [NAL9602](INFO): SBD MO Status=0, MOMSN=31899, MT Status=0, MTMSN=0 2022-03-15T18:07:16.887Z,1647367636.887 [NAL9602](INFO): No messages in MT queue 2022-03-15T18:07:27.462Z,1647367647.462 [CBIT](ERROR): Ground fault scan returned out of bounds value. Re-running scan. 2022-03-15T18:07:27.849Z,1647367647.849 [CBIT](IMPORTANT): Beginning ground fault scan 2022-03-15T18:07:38.776Z,1647367658.776 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.002685 CHAN A1 (24V): 0.000128 CHAN A2 (12V): -0.002619 CHAN A3 (5V): -0.001554 CHAN B0 (3.3V): -0.000325 CHAN B1 (3.15aV): -0.000269 CHAN B2 (3.15bV): -0.000425 CHAN B3 (GND): -0.000104 OPEN: -0.000289 Full Scale: +/- 1 mA 2022-03-15T18:07:59.345Z,1647367679.345 [SBIT](IMPORTANT): SBIT PASSED 2022-03-15T18:07:59.345Z,1647367679.345 [SBIT](FAULT): Ignoring configuration overrides from Data/persisted.cfg 2022-03-15T18:07:59.747Z,1647367679.747 [MissionManager](IMPORTANT): Started mission Startup 2022-03-15T18:07:59.747Z,1647367679.747 [Startup] Running Loop=1 2022-03-15T18:07:59.748Z,1647367679.748 [Startup](DEBUG): Aggregate::initialize Startup 2022-03-15T18:07:59.748Z,1647367679.748 [Startup:A.GoToSurface] Running Loop=1 2022-03-15T18:07:59.748Z,1647367679.748 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2022-03-15T18:07:59.748Z,1647367679.748 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2022-03-15T18:07:59.749Z,1647367679.749 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2022-03-15T18:07:59.749Z,1647367679.749 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2022-03-15T18:07:59.750Z,1647367679.750 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2022-03-15T18:07:59.750Z,1647367679.750 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2022-03-15T18:07:59.752Z,1647367679.752 [Startup:StartupSatComms] Running Loop=1 2022-03-15T18:07:59.752Z,1647367679.752 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2022-03-15T18:07:59.752Z,1647367679.752 [Startup:StartupSatComms:A] Running Loop=1 2022-03-15T18:08:00.147Z,1647367680.147 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2022-03-15T18:08:00.526Z,1647367680.526 [AMEcho](INFO): Powering up. 2022-03-15T18:08:32.848Z,1647367712.848 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,180832.00,A,3647.77052,N,12150.97091,W,15.570,246.62,150322,,,A*49 2022-03-15T18:08:32.852Z,1647367712.852 [NAL9602](INFO): GPS fix at 20220315T180832: (36.796175, -121.849515) 2022-03-15T18:08:32.880Z,1647367712.880 [Startup:StartupSatComms:A] Stopped 2022-03-15T18:08:32.880Z,1647367712.880 [Startup:StartupSatComms:B] Running Loop=1 2022-03-15T18:08:33.301Z,1647367713.301 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2022-03-15T18:08:49.647Z,1647367729.647 [NAL9602](INFO): SBD MO Status=1, MOMSN=31900, MT Status=0, MTMSN=0 2022-03-15T18:08:49.832Z,1647367729.832 [NAL9602](INFO): Sent 18 bytes from file Logs/20220315T152427/Courier0085.lzma 2022-03-15T18:08:49.832Z,1647367729.832 [NAL9602](INFO): Packets left to send: 0 2022-03-15T18:09:01.435Z,1647367741.435 [NAL9602](INFO): SBD MO Status=1, MOMSN=31901, MT Status=0, MTMSN=0 2022-03-15T18:09:01.492Z,1647367741.492 [NAL9602](INFO): Sent 330 bytes from file Logs/20220315T180612/Courier0000.lzma 2022-03-15T18:09:01.492Z,1647367741.492 [NAL9602](INFO): Packets left to send: 0 2022-03-15T18:09:24.937Z,1647367764.937 [NAL9602](INFO): SBD MO Status=2, MOMSN=31902, MT Status=2, MTMSN=0 2022-03-15T18:09:24.938Z,1647367764.938 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-03-15T18:09:33.074Z,1647367773.074 [Startup:StartupSatComms:B](INFO): Timed out from 2022-03-15T18:08:32.9Z 2022-03-15T18:09:33.075Z,1647367773.075 [Startup:StartupSatComms:B] Stopped 2022-03-15T18:09:33.075Z,1647367773.075 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2022-03-15T18:09:33.075Z,1647367773.075 [Startup:StartupSatComms] Stopped 2022-03-15T18:09:33.075Z,1647367773.075 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2022-03-15T18:09:33.077Z,1647367773.077 [Startup](INFO): Completed Startup 2022-03-15T18:09:33.077Z,1647367773.077 [MissionManager](INFO): Startup is completed. 2022-03-15T18:09:33.077Z,1647367773.077 [MissionManager](INFO): Uninitializing Mission Startup 2022-03-15T18:09:33.077Z,1647367773.077 [Startup] Stopped 2022-03-15T18:09:33.077Z,1647367773.077 [Startup](DEBUG): Aggregate::uninitialize Startup 2022-03-15T18:09:33.077Z,1647367773.077 [Startup:A.GoToSurface] Stopped 2022-03-15T18:09:33.077Z,1647367773.077 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2022-03-15T18:09:33.566Z,1647367773.566 [MissionManager](IMPORTANT): Started mission Default 2022-03-15T18:09:33.566Z,1647367773.566 [Default] Running Loop=1 2022-03-15T18:09:33.566Z,1647367773.566 [Default](DEBUG): Aggregate::initialize Default 2022-03-15T18:09:33.567Z,1647367773.567 [Default:B.GoToSurface] Running Loop=1 2022-03-15T18:09:33.567Z,1647367773.567 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2022-03-15T18:09:33.567Z,1647367773.567 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2022-03-15T18:09:33.567Z,1647367773.567 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2022-03-15T18:09:33.568Z,1647367773.568 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2022-03-15T18:09:33.568Z,1647367773.568 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2022-03-15T18:09:33.569Z,1647367773.569 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2022-03-15T18:09:33.569Z,1647367773.569 [Default:A.Wait] Running Loop=1 2022-03-15T18:09:33.569Z,1647367773.569 [Default:A.Wait](DEBUG): Initialize Wait Component. 2022-03-15T18:09:34.024Z,1647367774.024 [AMEcho](INFO): Powering down. 2022-03-15T18:09:35.037Z,1647367775.037 [AMEcho](INFO): Powering up. 2022-03-15T18:09:46.892Z,1647367786.892 [Default:A.Wait](INFO): Done Waiting. 2022-03-15T18:09:46.892Z,1647367786.892 [Default:A.Wait] Stopped 2022-03-15T18:09:46.892Z,1647367786.892 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2022-03-15T18:09:47.197Z,1647367787.197 [AMEcho](ERROR): No EchoSounder communication! Re-initializing 2022-03-15T18:09:47.197Z,1647367787.197 [AMEcho] Communications Fault, FailCount= 1 2022-03-15T18:09:47.197Z,1647367787.197 [AMEcho](ERROR): Communications Fault 2022-03-15T18:09:47.222Z,1647367787.222 [Default:CheckIn] Running Loop=1 2022-03-15T18:09:47.222Z,1647367787.222 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-03-15T18:09:47.222Z,1647367787.222 [Default:CheckIn:Read_GPS] Running Loop=1 2022-03-15T18:09:47.240Z,1647367787.240 [CBIT](ERROR): Communications Fault in component: AMEcho 2022-03-15T18:09:47.760Z,1647367787.760 [AMEcho](INFO): Powering down. 2022-03-15T18:09:47.783Z,1647367787.783 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2022-03-15T18:09:48.400Z,1647367788.400 [CBIT](INFO): Clearing failed state for component AMEcho 2022-03-15T18:09:48.400Z,1647367788.400 [AMEcho] No Fault, FailCount= 1 2022-03-15T18:09:48.784Z,1647367788.784 [AMEcho](INFO): Powering up. 2022-03-15T18:09:49.174Z,1647367789.174 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,180948.00,A,3647.80115,N,12151.23503,W,7.037,2.25,150322,,,A*7B 2022-03-15T18:09:49.176Z,1647367789.176 [NAL9602](INFO): GPS fix at 20220315T180948: (36.796686, -121.853917) 2022-03-15T18:09:49.188Z,1647367789.188 [Default:CheckIn:Read_GPS] Stopped 2022-03-15T18:09:49.188Z,1647367789.188 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-03-15T18:09:49.618Z,1647367789.618 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2022-03-15T18:10:00.986Z,1647367800.986 [AMEcho](ERROR): No EchoSounder communication! Re-initializing 2022-03-15T18:10:00.986Z,1647367800.986 [AMEcho] Communications Fault, FailCount= 2 2022-03-15T18:10:00.986Z,1647367800.986 [AMEcho](ERROR): Communications Fault 2022-03-15T18:10:01.030Z,1647367801.030 [CBIT](ERROR): Communications Fault in component: AMEcho 2022-03-15T18:10:01.556Z,1647367801.556 [AMEcho](INFO): Powering down. 2022-03-15T18:10:02.190Z,1647367802.190 [CBIT](INFO): Clearing failed state for component AMEcho 2022-03-15T18:10:02.190Z,1647367802.190 [AMEcho] No Fault, FailCount= 2 2022-03-15T18:10:02.578Z,1647367802.578 [AMEcho](INFO): Powering up. 2022-03-15T18:10:10.254Z,1647367810.254 [NAL9602](INFO): SBD MO Status=1, MOMSN=31902, MT Status=0, MTMSN=0 2022-03-15T18:10:10.308Z,1647367810.308 [NAL9602](INFO): Sent 71 bytes from file Logs/20220315T180612/Courier0004.lzma 2022-03-15T18:10:10.308Z,1647367810.308 [NAL9602](INFO): Packets left to send: 0 2022-03-15T18:10:14.795Z,1647367814.795 [AMEcho](ERROR): No EchoSounder communication! Re-initializing 2022-03-15T18:10:14.795Z,1647367814.795 [AMEcho] Communications Fault, FailCount= 3 2022-03-15T18:10:14.795Z,1647367814.795 [AMEcho](ERROR): Communications Fault 2022-03-15T18:10:14.819Z,1647367814.819 [CBIT](ERROR): Communications Fault in component: AMEcho 2022-03-15T18:10:14.840Z,1647367814.840 [CBIT](CRITICAL): Communications Fault in component: AMEcho 2022-03-15T18:10:15.332Z,1647367815.332 [AMEcho](INFO): Powering down. 2022-03-15T18:10:15.369Z,1647367815.369 [CBIT](INFO): Critical error at 20220315T181014 2022-03-15T18:10:25.666Z,1647367825.666 [NAL9602](INFO): SBD MO Status=2, MOMSN=31903, MT Status=2, MTMSN=0 2022-03-15T18:10:25.667Z,1647367825.667 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-03-15T18:10:45.922Z,1647367845.922 [NAL9602](INFO): SBD MO Status=1, MOMSN=31903, MT Status=0, MTMSN=0 2022-03-15T18:10:46.040Z,1647367846.040 [NAL9602](INFO): Sent 18 bytes from file Logs/20220315T152427/Express0086.lzma 2022-03-15T18:10:46.040Z,1647367846.040 [NAL9602](INFO): Packets left to send: 0 2022-03-15T18:11:00.123Z,1647367860.123 [NAL9602](INFO): SBD MO Status=2, MOMSN=31904, MT Status=2, MTMSN=0 2022-03-15T18:11:00.123Z,1647367860.123 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-03-15T18:11:19.570Z,1647367879.570 [NAL9602](INFO): SBD MO Status=1, MOMSN=31904, MT Status=0, MTMSN=0 2022-03-15T18:11:19.636Z,1647367879.636 [NAL9602](INFO): Sent 332 bytes from file Logs/20220315T180612/Express0001.lzma 2022-03-15T18:11:19.636Z,1647367879.636 [NAL9602](INFO): Packets left to send: 2 2022-03-15T18:11:28.550Z,1647367888.550 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004481 2022-03-15T18:11:29.010Z,1647367889.010 [NAL9602](INFO): SBD MO Status=1, MOMSN=31905, MT Status=0, MTMSN=0 2022-03-15T18:11:29.064Z,1647367889.064 [NAL9602](INFO): Sent 332 bytes from file Logs/20220315T180612/Express0001.lzma 2022-03-15T18:11:29.064Z,1647367889.064 [NAL9602](INFO): Packets left to send: 1 2022-03-15T18:11:29.124Z,1647367889.124 [Default:CheckIn:Read_Iridium] Stopped 2022-03-15T18:11:29.124Z,1647367889.124 [Default:CheckIn:C.Wait] Running Loop=1 2022-03-15T18:11:29.124Z,1647367889.124 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-03-15T18:11:59.701Z,1647367919.701 [NAL9602](INFO): Not Powering down - fast GPS 2022-03-15T18:12:36.560Z,1647367956.560 [BPC1](ERROR): Battery stick #17 (s/n: 02D0) reported OVER_TEMP_ALARM. Status code: 0x1717. 2022-03-15T18:12:36.561Z,1647367956.561 [BPC1](INFO): Calculating totals. Valid battery stick count: 55. Valid reserve battery stick count: 6. 2022-03-15T18:12:36.572Z,1647367956.572 [BPC1](INFO): Received data from all battery sticks. 2022-03-15T18:13:15.028Z,1647367995.028 [CBIT](INFO): Clearing failed state for component AMEcho 2022-03-15T18:13:15.028Z,1647367995.028 [AMEcho] No Fault, FailCount= 3 2022-03-15T18:13:15.385Z,1647367995.385 [AMEcho](INFO): Powering up. 2022-03-15T18:13:27.099Z,1647368007.099 [AMEcho](INFO): Failure count cleared after critical for AMEcho 2022-03-15T18:13:53.020Z,1647368033.020 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:14:24.144Z,1647368064.144 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:14:55.268Z,1647368095.268 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:15:26.400Z,1647368126.400 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:15:31.420Z,1647368131.420 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=180.379440 2022-03-15T18:16:28.408Z,1647368188.408 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003181 2022-03-15T18:16:29.778Z,1647368189.778 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-03-15T18:16:29.778Z,1647368189.778 [Default:CheckIn:C.Wait] Stopped 2022-03-15T18:16:29.778Z,1647368189.778 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-03-15T18:16:29.779Z,1647368189.779 [Default:CheckIn:D] Running Loop=1 2022-03-15T18:16:30.177Z,1647368190.177 [Default:CheckIn:D] Stopped 2022-03-15T18:16:30.177Z,1647368190.177 [Default:CheckIn:E] Running Loop=1 2022-03-15T18:16:30.572Z,1647368190.572 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 6.943504 min 2022-03-15T18:16:30.573Z,1647368190.573 [Default:CheckIn:E] Stopped 2022-03-15T18:16:30.573Z,1647368190.573 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-03-15T18:16:30.573Z,1647368190.573 [Default:CheckIn] Stopped 2022-03-15T18:16:30.573Z,1647368190.573 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-03-15T18:16:30.573Z,1647368190.573 [Default:CheckIn](INFO): Running loop #2 2022-03-15T18:16:30.573Z,1647368190.573 [Default:CheckIn] Running Loop=2 2022-03-15T18:16:30.573Z,1647368190.573 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-03-15T18:16:30.573Z,1647368190.573 [Default:CheckIn:Read_GPS] Running Loop=1 2022-03-15T18:16:32.583Z,1647368192.583 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181633.00,A,3647.86346,N,12151.19157,W,0.486,334.18,150322,,,A*76 2022-03-15T18:16:32.597Z,1647368192.597 [NAL9602](INFO): GPS fix at 20220315T181633: (36.797724, -121.853193) 2022-03-15T18:16:32.613Z,1647368192.613 [Default:CheckIn:Read_GPS] Stopped 2022-03-15T18:16:32.613Z,1647368192.613 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-03-15T18:16:36.368Z,1647368196.368 [DataOverHttps](INFO): Sending 247 bytes from file Logs/20220315T180612/Courier0007.lzma 2022-03-15T18:16:37.370Z,1647368197.370 [DataOverHttps](INFO): Moved sent file to Logs/20220315T180612/Courier0007.lzma.bak 2022-03-15T18:16:37.370Z,1647368197.370 [DataOverHttps](INFO): SBD MOMSN=16572952 2022-03-15T18:16:47.739Z,1647368207.739 [NAL9602](INFO): SBD MO Status=0, MOMSN=31906, MT Status=0, MTMSN=0 2022-03-15T18:16:47.739Z,1647368207.739 [NAL9602](INFO): No messages in MT queue 2022-03-15T18:16:57.105Z,1647368217.105 [DataOverHttps](INFO): Sending 825 bytes from file Logs/20220315T180612/Express0001.lzma 2022-03-15T18:16:58.106Z,1647368218.106 [DataOverHttps](INFO): Moved sent file to Logs/20220315T180612/Express0001.lzma.bak 2022-03-15T18:16:58.107Z,1647368218.107 [DataOverHttps](INFO): SBD MOMSN=16572956 2022-03-15T18:17:14.535Z,1647368234.535 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20220315T180612/Express0005.lzma 2022-03-15T18:17:15.539Z,1647368235.539 [DataOverHttps](INFO): Moved sent file to Logs/20220315T180612/Express0005.lzma.bak 2022-03-15T18:17:15.539Z,1647368235.539 [DataOverHttps](INFO): SBD MOMSN=16572974 2022-03-15T18:17:18.493Z,1647368238.493 [NAL9602](INFO): Not Powering down - fast GPS 2022-03-15T18:17:32.627Z,1647368252.627 [DataOverHttps](INFO): Sending 176 bytes from file Logs/20220315T180612/Express0008.lzma 2022-03-15T18:17:33.630Z,1647368253.630 [DataOverHttps](INFO): Moved sent file to Logs/20220315T180612/Express0008.lzma.bak 2022-03-15T18:17:33.630Z,1647368253.630 [DataOverHttps](INFO): SBD MOMSN=16572978 2022-03-15T18:17:34.677Z,1647368254.677 [Default:CheckIn:Read_Iridium] Stopped 2022-03-15T18:17:34.677Z,1647368254.677 [Default:CheckIn:C.Wait] Running Loop=1 2022-03-15T18:17:34.677Z,1647368254.677 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-03-15T18:20:39.308Z,1647368439.308 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:21:10.432Z,1647368470.432 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:21:41.556Z,1647368501.556 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:22:12.704Z,1647368532.704 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:22:14.712Z,1647368534.712 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=180.367310 2022-03-15T18:22:35.273Z,1647368555.273 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-03-15T18:22:35.273Z,1647368555.273 [Default:CheckIn:C.Wait] Stopped 2022-03-15T18:22:35.273Z,1647368555.273 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-03-15T18:22:35.273Z,1647368555.273 [Default:CheckIn:D] Running Loop=1 2022-03-15T18:22:35.664Z,1647368555.664 [Default:CheckIn:D] Stopped 2022-03-15T18:22:35.664Z,1647368555.664 [Default:CheckIn:E] Running Loop=1 2022-03-15T18:22:36.073Z,1647368556.073 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 13.034950 min 2022-03-15T18:22:36.073Z,1647368556.073 [Default:CheckIn:E] Stopped 2022-03-15T18:22:36.073Z,1647368556.073 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-03-15T18:22:36.073Z,1647368556.073 [Default:CheckIn] Stopped 2022-03-15T18:22:36.073Z,1647368556.073 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-03-15T18:22:36.074Z,1647368556.074 [Default:CheckIn](INFO): Running loop #3 2022-03-15T18:22:36.074Z,1647368556.074 [Default:CheckIn] Running Loop=3 2022-03-15T18:22:36.074Z,1647368556.074 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-03-15T18:22:36.074Z,1647368556.074 [Default:CheckIn:Read_GPS] Running Loop=1 2022-03-15T18:22:38.089Z,1647368558.089 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182238.00,A,3647.88511,N,12151.15586,W,5.346,111.31,150322,,,A*74 2022-03-15T18:22:38.091Z,1647368558.091 [NAL9602](INFO): GPS fix at 20220315T182238: (36.798085, -121.852598) 2022-03-15T18:22:38.111Z,1647368558.111 [Default:CheckIn:Read_GPS] Stopped 2022-03-15T18:22:38.111Z,1647368558.111 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-03-15T18:23:08.840Z,1647368588.840 [NAL9602](INFO): SBD MO Status=1, MOMSN=31907, MT Status=0, MTMSN=0 2022-03-15T18:23:08.892Z,1647368588.892 [NAL9602](INFO): Sent 72 bytes from file Logs/20220315T180612/Courier0010.lzma 2022-03-15T18:23:08.892Z,1647368588.892 [NAL9602](INFO): Packets left to send: 0 2022-03-15T18:23:13.952Z,1647368593.952 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:23:27.903Z,1647368607.903 [NAL9602](INFO): SBD MO Status=2, MOMSN=31908, MT Status=2, MTMSN=0 2022-03-15T18:23:27.903Z,1647368607.903 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-03-15T18:23:45.076Z,1647368625.076 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:23:55.446Z,1647368635.446 [NAL9602](INFO): SBD MO Status=1, MOMSN=31908, MT Status=0, MTMSN=0 2022-03-15T18:23:55.500Z,1647368635.500 [NAL9602](INFO): Sent 146 bytes from file Logs/20220315T180612/Express0011.lzma 2022-03-15T18:23:55.500Z,1647368635.500 [NAL9602](INFO): Packets left to send: 0 2022-03-15T18:24:05.955Z,1647368645.955 [NAL9602](INFO): SBD MO Status=0, MOMSN=31909, MT Status=0, MTMSN=0 2022-03-15T18:24:06.053Z,1647368646.053 [Default:CheckIn:Read_Iridium] Stopped 2022-03-15T18:24:06.053Z,1647368646.053 [Default:CheckIn:C.Wait] Running Loop=1 2022-03-15T18:24:06.053Z,1647368646.053 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-03-15T18:24:16.220Z,1647368656.220 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:24:36.653Z,1647368676.653 [NAL9602](INFO): Not Powering down - fast GPS 2022-03-15T18:24:47.344Z,1647368687.344 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:25:18.488Z,1647368718.488 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:25:49.612Z,1647368749.612 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:26:20.764Z,1647368780.764 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:26:51.888Z,1647368811.888 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:27:23.016Z,1647368843.016 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:27:31.440Z,1647368851.440 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003168 2022-03-15T18:28:55.304Z,1647368935.304 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:29:06.544Z,1647368946.544 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-03-15T18:29:06.544Z,1647368946.544 [Default:CheckIn:C.Wait] Stopped 2022-03-15T18:29:06.544Z,1647368946.544 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-03-15T18:29:06.544Z,1647368946.544 [Default:CheckIn:D] Running Loop=1 2022-03-15T18:29:06.956Z,1647368946.956 [Default:CheckIn:D] Stopped 2022-03-15T18:29:06.956Z,1647368946.956 [Default:CheckIn:E] Running Loop=1 2022-03-15T18:29:07.345Z,1647368947.345 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 19.556486 min 2022-03-15T18:29:07.345Z,1647368947.345 [Default:CheckIn:E] Stopped 2022-03-15T18:29:07.345Z,1647368947.345 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-03-15T18:29:07.345Z,1647368947.345 [Default:CheckIn] Stopped 2022-03-15T18:29:07.345Z,1647368947.345 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-03-15T18:29:07.346Z,1647368947.346 [Default:CheckIn](INFO): Running loop #4 2022-03-15T18:29:07.346Z,1647368947.346 [Default:CheckIn] Running Loop=4 2022-03-15T18:29:07.346Z,1647368947.346 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-03-15T18:29:07.346Z,1647368947.346 [Default:CheckIn:Read_GPS] Running Loop=1 2022-03-15T18:29:09.357Z,1647368949.357 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182909.00,A,3647.83806,N,12150.79322,W,0.117,77.90,150322,,,A*47 2022-03-15T18:29:09.359Z,1647368949.359 [NAL9602](INFO): GPS fix at 20220315T182909: (36.797301, -121.846554) 2022-03-15T18:29:09.371Z,1647368949.371 [Default:CheckIn:Read_GPS] Stopped 2022-03-15T18:29:09.371Z,1647368949.371 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-03-15T18:29:26.415Z,1647368966.415 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20220315T180612/Courier0013.lzma 2022-03-15T18:29:27.418Z,1647368967.418 [DataOverHttps](INFO): Moved sent file to Logs/20220315T180612/Courier0013.lzma.bak 2022-03-15T18:29:27.418Z,1647368967.418 [DataOverHttps](INFO): SBD MOMSN=16573004 2022-03-15T18:29:36.019Z,1647368976.019 [NAL9602](INFO): SBD MO Status=0, MOMSN=31910, MT Status=0, MTMSN=0 2022-03-15T18:29:36.019Z,1647368976.019 [NAL9602](INFO): No messages in MT queue 2022-03-15T18:29:43.627Z,1647368983.627 [DataOverHttps](INFO): Sending 145 bytes from file Logs/20220315T180612/Express0014.lzma 2022-03-15T18:29:44.630Z,1647368984.630 [DataOverHttps](INFO): Moved sent file to Logs/20220315T180612/Express0014.lzma.bak 2022-03-15T18:29:44.631Z,1647368984.631 [DataOverHttps](INFO): SBD MOMSN=16573007 2022-03-15T18:29:45.729Z,1647368985.729 [Default:CheckIn:Read_Iridium] Stopped 2022-03-15T18:29:45.729Z,1647368985.729 [Default:CheckIn:C.Wait] Running Loop=1 2022-03-15T18:29:45.729Z,1647368985.729 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-03-15T18:30:06.729Z,1647369006.729 [NAL9602](INFO): Not Powering down - fast GPS 2022-03-15T18:31:48.300Z,1647369108.300 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:32:19.424Z,1647369139.424 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:32:50.548Z,1647369170.548 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:33:21.700Z,1647369201.700 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:33:52.824Z,1647369232.824 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:33:58.848Z,1647369238.848 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=180.747406 2022-03-15T18:34:46.430Z,1647369286.430 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-03-15T18:34:46.430Z,1647369286.430 [Default:CheckIn:C.Wait] Stopped 2022-03-15T18:34:46.430Z,1647369286.430 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-03-15T18:34:46.430Z,1647369286.430 [Default:CheckIn:D] Running Loop=1 2022-03-15T18:34:46.821Z,1647369286.821 [Default:CheckIn:D] Stopped 2022-03-15T18:34:46.822Z,1647369286.822 [Default:CheckIn:E] Running Loop=1 2022-03-15T18:34:47.229Z,1647369287.229 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 25.220917 min 2022-03-15T18:34:47.229Z,1647369287.229 [Default:CheckIn:E] Stopped 2022-03-15T18:34:47.229Z,1647369287.229 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-03-15T18:34:47.229Z,1647369287.229 [Default:CheckIn] Stopped 2022-03-15T18:34:47.229Z,1647369287.229 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-03-15T18:34:47.229Z,1647369287.229 [Default:CheckIn](INFO): Running loop #5 2022-03-15T18:34:47.229Z,1647369287.229 [Default:CheckIn] Running Loop=5 2022-03-15T18:34:47.229Z,1647369287.229 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-03-15T18:34:47.230Z,1647369287.230 [Default:CheckIn:Read_GPS] Running Loop=1 2022-03-15T18:34:49.243Z,1647369289.243 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183449.00,A,3647.85480,N,12150.56448,W,0.778,94.75,150322,,,A*44 2022-03-15T18:34:49.245Z,1647369289.245 [NAL9602](INFO): GPS fix at 20220315T183449: (36.797580, -121.842741) 2022-03-15T18:34:49.258Z,1647369289.258 [Default:CheckIn:Read_GPS] Stopped 2022-03-15T18:34:49.258Z,1647369289.258 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-03-15T18:34:54.072Z,1647369294.072 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:35:16.746Z,1647369316.746 [NAL9602](INFO): SBD MO Status=1, MOMSN=31911, MT Status=0, MTMSN=0 2022-03-15T18:35:16.796Z,1647369316.796 [NAL9602](INFO): Sent 72 bytes from file Logs/20220315T180612/Courier0016.lzma 2022-03-15T18:35:16.796Z,1647369316.796 [NAL9602](INFO): Packets left to send: 0 2022-03-15T18:35:24.486Z,1647369324.486 [NAL9602](INFO): SBD MO Status=1, MOMSN=31912, MT Status=0, MTMSN=0 2022-03-15T18:35:24.538Z,1647369324.538 [NAL9602](INFO): Sent 144 bytes from file Logs/20220315T180612/Express0017.lzma 2022-03-15T18:35:24.539Z,1647369324.539 [NAL9602](INFO): Packets left to send: 0 2022-03-15T18:35:25.205Z,1647369325.205 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:35:44.686Z,1647369344.686 [NAL9602](INFO): SBD MO Status=2, MOMSN=31913, MT Status=2, MTMSN=0 2022-03-15T18:35:44.686Z,1647369344.686 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-03-15T18:35:56.328Z,1647369356.328 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:36:06.495Z,1647369366.495 [NAL9602](INFO): SBD MO Status=2, MOMSN=31913, MT Status=2, MTMSN=0 2022-03-15T18:36:06.495Z,1647369366.495 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-03-15T18:36:26.294Z,1647369386.294 [NAL9602](INFO): SBD MO Status=2, MOMSN=31913, MT Status=2, MTMSN=0 2022-03-15T18:36:26.295Z,1647369386.295 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-03-15T18:36:27.452Z,1647369387.452 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:36:52.167Z,1647369412.167 [NAL9602](INFO): SBD MO Status=0, MOMSN=31913, MT Status=0, MTMSN=0 2022-03-15T18:36:52.300Z,1647369412.300 [Default:CheckIn:Read_Iridium] Stopped 2022-03-15T18:36:52.300Z,1647369412.300 [Default:CheckIn:C.Wait] Running Loop=1 2022-03-15T18:36:52.300Z,1647369412.300 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-03-15T18:36:59.228Z,1647369419.228 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003126 2022-03-15T18:37:22.901Z,1647369442.901 [NAL9602](INFO): Not Powering down - fast GPS 2022-03-15T18:40:03.904Z,1647369603.904 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:40:35.028Z,1647369635.028 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:41:06.160Z,1647369666.160 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:41:37.284Z,1647369697.284 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:41:52.784Z,1647369712.784 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-03-15T18:41:52.784Z,1647369712.784 [Default:CheckIn:C.Wait] Stopped 2022-03-15T18:41:52.784Z,1647369712.784 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-03-15T18:41:52.784Z,1647369712.784 [Default:CheckIn:D] Running Loop=1 2022-03-15T18:41:53.198Z,1647369713.198 [Default:CheckIn:D] Stopped 2022-03-15T18:41:53.198Z,1647369713.198 [Default:CheckIn:E] Running Loop=1 2022-03-15T18:41:53.608Z,1647369713.608 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 32.327187 min 2022-03-15T18:41:53.608Z,1647369713.608 [Default:CheckIn:E] Stopped 2022-03-15T18:41:53.609Z,1647369713.609 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-03-15T18:41:53.609Z,1647369713.609 [Default:CheckIn] Stopped 2022-03-15T18:41:53.609Z,1647369713.609 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-03-15T18:41:53.609Z,1647369713.609 [Default:CheckIn](INFO): Running loop #6 2022-03-15T18:41:53.609Z,1647369713.609 [Default:CheckIn] Running Loop=6 2022-03-15T18:41:53.609Z,1647369713.609 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-03-15T18:41:53.609Z,1647369713.609 [Default:CheckIn:Read_GPS] Running Loop=1 2022-03-15T18:41:55.615Z,1647369715.615 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184156.00,A,3647.80217,N,12150.48487,W,0.544,76.36,150322,,,A*4F 2022-03-15T18:41:55.617Z,1647369715.617 [NAL9602](INFO): GPS fix at 20220315T184156: (36.796703, -121.841414) 2022-03-15T18:41:55.650Z,1647369715.650 [Default:CheckIn:Read_GPS] Stopped 2022-03-15T18:41:55.650Z,1647369715.650 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-03-15T18:42:08.408Z,1647369728.408 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:42:09.339Z,1647369729.339 [NAL9602](INFO): SBD MO Status=0, MOMSN=31914, MT Status=0, MTMSN=0 2022-03-15T18:42:09.339Z,1647369729.339 [NAL9602](INFO): No messages in MT queue 2022-03-15T18:42:12.424Z,1647369732.424 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=180.735336 2022-03-15T18:42:27.966Z,1647369747.966 [NAL9602](INFO): SBD MO Status=1, MOMSN=31915, MT Status=0, MTMSN=0 2022-03-15T18:42:28.028Z,1647369748.028 [NAL9602](INFO): Sent 71 bytes from file Logs/20220315T180612/Courier0019.lzma 2022-03-15T18:42:28.028Z,1647369748.028 [NAL9602](INFO): Packets left to send: 0 2022-03-15T18:42:39.358Z,1647369759.358 [NAL9602](INFO): SBD MO Status=1, MOMSN=31916, MT Status=0, MTMSN=0 2022-03-15T18:42:39.412Z,1647369759.412 [NAL9602](INFO): Sent 144 bytes from file Logs/20220315T180612/Express0020.lzma 2022-03-15T18:42:39.412Z,1647369759.412 [NAL9602](INFO): Packets left to send: 0 2022-03-15T18:42:43.556Z,1647369763.556 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:42:49.043Z,1647369769.043 [NAL9602](INFO): SBD MO Status=0, MOMSN=31917, MT Status=0, MTMSN=0 2022-03-15T18:42:49.127Z,1647369769.127 [Default:CheckIn:Read_Iridium] Stopped 2022-03-15T18:42:49.127Z,1647369769.127 [Default:CheckIn:C.Wait] Running Loop=1 2022-03-15T18:42:49.127Z,1647369769.127 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-03-15T18:43:14.688Z,1647369794.688 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:43:19.745Z,1647369799.745 [NAL9602](INFO): Not Powering down - fast GPS 2022-03-15T18:43:45.812Z,1647369825.812 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:44:16.936Z,1647369856.936 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:44:48.060Z,1647369888.060 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:45:19.184Z,1647369919.184 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:45:50.324Z,1647369950.324 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-03-15T18:46:08.084Z,1647369968.084 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003081 2022-03-15T18:47:49.628Z,1647370069.628 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-03-15T18:47:49.628Z,1647370069.628 [Default:CheckIn:C.Wait] Stopped 2022-03-15T18:47:49.628Z,1647370069.628 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-03-15T18:47:49.628Z,1647370069.628 [Default:CheckIn:D] Running Loop=1 2022-03-15T18:47:50.035Z,1647370070.035 [Default:CheckIn:D] Stopped 2022-03-15T18:47:50.035Z,1647370070.035 [Default:CheckIn:E] Running Loop=1 2022-03-15T18:47:50.453Z,1647370070.453 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 38.274479 min 2022-03-15T18:47:50.453Z,1647370070.453 [Default:CheckIn:E] Stopped 2022-03-15T18:47:50.453Z,1647370070.453 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-03-15T18:47:50.453Z,1647370070.453 [Default:CheckIn] Stopped 2022-03-15T18:47:50.453Z,1647370070.453 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-03-15T18:47:50.454Z,1647370070.454 [Default:CheckIn](INFO): Running loop #7 2022-03-15T18:47:50.454Z,1647370070.454 [Default:CheckIn] Running Loop=7 2022-03-15T18:47:50.454Z,1647370070.454 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-03-15T18:47:50.454Z,1647370070.454 [Default:CheckIn:Read_GPS] Running Loop=1 2022-03-15T18:47:52.447Z,1647370072.447 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184752.00,A,3647.80829,N,12150.48629,W,0.467,152.85,150322,,,D*76 2022-03-15T18:47:52.450Z,1647370072.450 [NAL9602](INFO): GPS fix at 20220315T184752: (36.796805, -121.841438) 2022-03-15T18:47:52.461Z,1647370072.461 [Default:CheckIn:Read_GPS] Stopped 2022-03-15T18:47:52.461Z,1647370072.461 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-03-15T18:48:00.331Z,1647370080.331 [DataOverHttps](INFO): Sending 71 bytes from file Logs/20220315T180612/Courier0022.lzma 2022-03-15T18:48:01.333Z,1647370081.333 [DataOverHttps](INFO): Moved sent file to Logs/20220315T180612/Courier0022.lzma.bak 2022-03-15T18:48:01.334Z,1647370081.334 [DataOverHttps](INFO): SBD MOMSN=16573079 2022-03-15T18:48:18.413Z,1647370098.413 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20220315T180612/Express0023.lzma 2022-03-15T18:48:19.414Z,1647370099.414 [DataOverHttps](INFO): Moved sent file to Logs/20220315T180612/Express0023.lzma.bak 2022-03-15T18:48:19.414Z,1647370099.414 [DataOverHttps](INFO): SBD MOMSN=16573084 2022-03-15T18:48:20.754Z,1647370100.754 [Default:CheckIn:Read_Iridium] Stopped 2022-03-15T18:48:20.754Z,1647370100.754 [Default:CheckIn:C.Wait] Running Loop=1 2022-03-15T18:48:20.754Z,1647370100.754 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-03-15T18:48:21.547Z,1647370101.547 [NAL9602](INFO): SBD MO Status=2, MOMSN=31918, MT Status=2, MTMSN=0 2022-03-15T18:48:21.547Z,1647370101.547 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-03-15T18:48:47.831Z,1647370127.831 [NAL9602](INFO): SBD MO Status=2, MOMSN=31918, MT Status=2, MTMSN=0 2022-03-15T18:48:47.832Z,1647370127.832 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-03-15T18:50:46.651Z,1647370246.651 [NAL9602](INFO): SBD MO Status=2, MOMSN=31918, MT Status=2, MTMSN=0 2022-03-15T18:50:46.651Z,1647370246.651 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-03-15T18:51:07.255Z,1647370267.255 [NAL9602](IMPORTANT): SBD MO Status=0, MOMSN=31918, MT Status=1, MTMSN=2704 2022-03-15T18:51:07.255Z,1647370267.255 [NAL9602](INFO): Data available in MT queue 2022-03-15T18:51:07.756Z,1647370267.756 [NAL9602](INFO): Received command: restart logs