2021-11-18T19:39:33.826Z,1637264373.826 [Supervisor](DEBUG): Initializing supervisor. 2021-11-18T19:39:33.841Z,1637264373.841 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2021-11-18T19:39:33.842Z,1637264373.842 [SyncHandler](INFO): Protected caller Thread ID is 833 2021-11-18T19:39:33.842Z,1637264373.842 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2021-11-18T19:39:33.853Z,1637264373.853 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2021-11-18T19:39:33.853Z,1637264373.853 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 834 2021-11-18T19:39:33.858Z,1637264373.858 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2021-11-18T19:39:33.888Z,1637264373.888 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread. 2021-11-18T19:39:33.893Z,1637264373.893 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2021-11-18T19:39:33.893Z,1637264373.893 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 835 2021-11-18T19:39:33.909Z,1637264373.909 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2021-11-18T19:39:33.921Z,1637264373.921 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2021-11-18T19:39:33.921Z,1637264373.921 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 836 2021-11-18T19:39:33.923Z,1637264373.923 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2021-11-18T19:39:33.933Z,1637264373.933 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0 2021-11-18T19:39:33.933Z,1637264373.933 [logger ThreadHandler](INFO): Protected caller Thread ID is 837 2021-11-18T19:39:33.937Z,1637264373.937 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2021-11-18T19:39:33.938Z,1637264373.938 [Supervisor](INFO): Looking for Config files in directory: Config/ 2021-11-18T19:39:33.951Z,1637264373.951 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2021-11-18T19:39:34.397Z,1637264374.397 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2021-11-18T19:39:34.400Z,1637264374.400 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2021-11-18T19:39:34.533Z,1637264374.533 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2021-11-18T19:39:35.520Z,1637264375.520 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2021-11-18T19:39:35.522Z,1637264375.522 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2021-11-18T19:39:36.154Z,1637264376.154 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2021-11-18T19:39:36.157Z,1637264376.157 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2021-11-18T19:39:36.354Z,1637264376.354 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2021-11-18T19:39:36.355Z,1637264376.355 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2021-11-18T19:39:37.252Z,1637264377.252 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2021-11-18T19:39:37.254Z,1637264377.254 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2021-11-18T19:39:37.448Z,1637264377.448 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2021-11-18T19:39:37.450Z,1637264377.450 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2021-11-18T19:39:37.894Z,1637264377.894 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2021-11-18T19:39:37.895Z,1637264377.895 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2021-11-18T19:39:38.021Z,1637264378.021 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2021-11-18T19:39:38.021Z,1637264378.021 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2021-11-18T19:39:38.100Z,1637264378.100 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2021-11-18T19:39:38.749Z,1637264378.749 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2021-11-18T19:39:38.750Z,1637264378.750 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2021-11-18T19:39:39.099Z,1637264379.099 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2021-11-18T19:39:39.100Z,1637264379.100 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2021-11-18T19:39:39.285Z,1637264379.285 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2021-11-18T19:39:39.287Z,1637264379.287 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2021-11-18T19:39:39.397Z,1637264379.397 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2021-11-18T19:39:39.398Z,1637264379.398 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2021-11-18T19:39:39.546Z,1637264379.546 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2021-11-18T19:39:39.548Z,1637264379.548 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg 2021-11-18T19:39:39.768Z,1637264379.768 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock 2021-11-18T19:39:39.770Z,1637264379.770 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/ 2021-11-18T19:39:39.772Z,1637264379.772 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg 2021-11-18T19:39:39.863Z,1637264379.863 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg 2021-11-18T19:39:39.948Z,1637264379.948 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg 2021-11-18T19:39:40.048Z,1637264380.048 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg 2021-11-18T19:39:40.130Z,1637264380.130 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg 2021-11-18T19:39:40.224Z,1637264380.224 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg 2021-11-18T19:39:40.324Z,1637264380.324 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg 2021-11-18T19:39:40.507Z,1637264380.507 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg 2021-11-18T19:39:40.585Z,1637264380.585 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg 2021-11-18T19:39:40.730Z,1637264380.730 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg 2021-11-18T19:39:40.864Z,1637264380.864 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg 2021-11-18T19:39:40.979Z,1637264380.979 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg 2021-11-18T19:39:41.235Z,1637264381.235 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2021-11-18T19:39:41.235Z,1637264381.235 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2021-11-18T19:39:41.254Z,1637264381.254 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2021-11-18T19:39:41.326Z,1637264381.326 [VerticalControl](DEBUG): Construct VerticalControl. 2021-11-18T19:39:41.389Z,1637264381.389 [VerticalControl] Loaded 2021-11-18T19:39:41.389Z,1637264381.389 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2021-11-18T19:39:41.392Z,1637264381.392 [HorizontalControl](DEBUG): Construct HorizontalControl. 2021-11-18T19:39:41.430Z,1637264381.430 [HorizontalControl] Loaded 2021-11-18T19:39:41.430Z,1637264381.430 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2021-11-18T19:39:41.432Z,1637264381.432 [SpeedControl](DEBUG): Construct SpeedControl. 2021-11-18T19:39:41.435Z,1637264381.435 [SpeedControl] Loaded 2021-11-18T19:39:41.436Z,1637264381.436 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2021-11-18T19:39:41.438Z,1637264381.438 [LoopControl](DEBUG): Construct LoopControl. 2021-11-18T19:39:41.439Z,1637264381.439 [LoopControl] Loaded 2021-11-18T19:39:41.439Z,1637264381.439 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2021-11-18T19:39:41.439Z,1637264381.439 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2021-11-18T19:39:41.440Z,1637264381.440 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2021-11-18T19:39:41.456Z,1637264381.456 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2021-11-18T19:39:41.458Z,1637264381.458 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2021-11-18T19:39:42.094Z,1637264382.094 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2021-11-18T19:39:42.094Z,1637264382.094 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2021-11-18T19:39:42.313Z,1637264382.313 [BuoyancyServo] Loaded 2021-11-18T19:39:42.313Z,1637264382.313 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2021-11-18T19:39:42.333Z,1637264382.333 [ElevatorServo] Loaded 2021-11-18T19:39:42.333Z,1637264382.333 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2021-11-18T19:39:42.352Z,1637264382.352 [MassServo] Loaded 2021-11-18T19:39:42.352Z,1637264382.352 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2021-11-18T19:39:42.370Z,1637264382.370 [RudderServo] Loaded 2021-11-18T19:39:42.370Z,1637264382.370 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2021-11-18T19:39:42.388Z,1637264382.388 [ThrusterServo] Loaded 2021-11-18T19:39:42.388Z,1637264382.388 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2021-11-18T19:39:42.388Z,1637264382.388 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2021-11-18T19:39:42.389Z,1637264382.389 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2021-11-18T19:39:42.488Z,1637264382.488 [DeadReckonUsingMultipleVelocitySources] Loaded 2021-11-18T19:39:42.488Z,1637264382.488 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2021-11-18T19:39:42.502Z,1637264382.502 [NavChart] Loaded 2021-11-18T19:39:42.502Z,1637264382.502 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2021-11-18T19:39:42.508Z,1637264382.508 [UniversalFixResidualReporter] Loaded 2021-11-18T19:39:42.508Z,1637264382.508 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2021-11-18T19:39:42.508Z,1637264382.508 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2021-11-18T19:39:42.509Z,1637264382.509 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2021-11-18T19:39:42.592Z,1637264382.592 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2021-11-18T19:39:42.594Z,1637264382.594 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2021-11-18T19:39:43.279Z,1637264383.279 [AHRS_M2] Loaded 2021-11-18T19:39:43.279Z,1637264383.279 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2021-11-18T19:39:44.064Z,1637264384.064 [BPC1] Loaded 2021-11-18T19:39:44.064Z,1637264384.064 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2021-11-18T19:39:44.084Z,1637264384.084 [Depth_Keller] Loaded 2021-11-18T19:39:44.084Z,1637264384.084 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2021-11-18T19:39:44.088Z,1637264384.088 [DropWeight] Loaded 2021-11-18T19:39:44.089Z,1637264384.089 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2021-11-18T19:39:44.147Z,1637264384.147 [NAL9602] Loaded 2021-11-18T19:39:44.147Z,1637264384.147 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2021-11-18T19:39:44.176Z,1637264384.176 [Onboard] Loaded 2021-11-18T19:39:44.177Z,1637264384.177 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread. 2021-11-18T19:39:44.178Z,1637264384.178 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 408C64E0 2021-11-18T19:39:44.178Z,1637264384.178 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 922 2021-11-18T19:39:44.191Z,1637264384.191 [Power24vConverter] Loaded 2021-11-18T19:39:44.191Z,1637264384.191 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread. 2021-11-18T19:39:44.205Z,1637264384.205 [Radio_Surface] Loaded 2021-11-18T19:39:44.205Z,1637264384.205 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2021-11-18T19:39:44.206Z,1637264384.206 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408F64E0 2021-11-18T19:39:44.206Z,1637264384.206 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 923 2021-11-18T19:39:44.287Z,1637264384.287 [DAT] Loaded 2021-11-18T19:39:44.287Z,1637264384.287 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread. 2021-11-18T19:39:44.288Z,1637264384.288 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2021-11-18T19:39:44.288Z,1637264384.288 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2021-11-18T19:39:44.348Z,1637264384.348 [DepthRateCalculator] Loaded 2021-11-18T19:39:44.348Z,1637264384.348 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2021-11-18T19:39:44.353Z,1637264384.353 [PitchRateCalculator] Loaded 2021-11-18T19:39:44.354Z,1637264384.354 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2021-11-18T19:39:44.363Z,1637264384.363 [SpeedCalculator] Loaded 2021-11-18T19:39:44.363Z,1637264384.363 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2021-11-18T19:39:44.377Z,1637264384.377 [TempGradientCalculator] Loaded 2021-11-18T19:39:44.378Z,1637264384.378 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2021-11-18T19:39:44.382Z,1637264384.382 [YawRateCalculator] Loaded 2021-11-18T19:39:44.382Z,1637264384.382 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2021-11-18T19:39:44.400Z,1637264384.400 [ElevatorOffsetCalculator] Loaded 2021-11-18T19:39:44.400Z,1637264384.400 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2021-11-18T19:39:44.401Z,1637264384.401 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2021-11-18T19:39:44.401Z,1637264384.401 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2021-11-18T19:39:44.581Z,1637264384.581 [CANONSampler] Loaded 2021-11-18T19:39:44.581Z,1637264384.581 [ComponentRegistry](DEBUG): SyncComponent "CANONSampler" handled in the control thread. 2021-11-18T19:39:44.639Z,1637264384.639 [CTD_Seabird] Loaded 2021-11-18T19:39:44.639Z,1637264384.639 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread. 2021-11-18T19:39:44.640Z,1637264384.640 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 409AB4E0 2021-11-18T19:39:44.641Z,1637264384.641 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 924 2021-11-18T19:39:44.661Z,1637264384.661 [PAR_Licor] Loaded 2021-11-18T19:39:44.661Z,1637264384.661 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2021-11-18T19:39:44.693Z,1637264384.693 [WetLabsBB2FL] Loaded 2021-11-18T19:39:44.693Z,1637264384.693 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2021-11-18T19:39:44.695Z,1637264384.695 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 409DB4E0 2021-11-18T19:39:44.695Z,1637264384.695 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 925 2021-11-18T19:39:44.696Z,1637264384.696 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2021-11-18T19:39:44.696Z,1637264384.696 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2021-11-18T19:39:44.738Z,1637264384.738 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2021-11-18T19:39:44.739Z,1637264384.739 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2021-11-18T19:39:45.112Z,1637264385.112 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2021-11-18T19:39:45.114Z,1637264385.114 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2021-11-18T19:39:45.290Z,1637264385.290 [SBIT](DEBUG): Construct Startup Built In Test. 2021-11-18T19:39:45.299Z,1637264385.299 [SBIT] Loaded 2021-11-18T19:39:45.299Z,1637264385.299 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2021-11-18T19:39:45.302Z,1637264385.302 [IBIT](DEBUG): Construct Initiated Built In Test. 2021-11-18T19:39:45.315Z,1637264385.315 [IBIT] Loaded 2021-11-18T19:39:45.315Z,1637264385.315 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2021-11-18T19:39:45.321Z,1637264385.321 [CBIT](DEBUG): Construct Continuous Built In Test. 2021-11-18T19:39:45.424Z,1637264385.424 [CBIT] Loaded 2021-11-18T19:39:45.424Z,1637264385.424 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2021-11-18T19:39:45.424Z,1637264385.424 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2021-11-18T19:39:45.425Z,1637264385.425 [Module Loader](DEBUG): Loading Module at Modules/Dock.so 2021-11-18T19:39:45.543Z,1637264385.543 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking) 2021-11-18T19:39:45.549Z,1637264385.549 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2021-11-18T19:39:45.552Z,1637264385.552 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2021-11-18T19:39:45.562Z,1637264385.562 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2021-11-18T19:39:45.563Z,1637264385.563 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40B104E0 2021-11-18T19:39:45.563Z,1637264385.563 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 926 2021-11-18T19:39:45.568Z,1637264385.568 [Supervisor](INFO): Main Thread ID is 829 2021-11-18T19:39:45.568Z,1637264385.568 [Supervisor](DEBUG): Running supervisor. 2021-11-18T19:39:45.569Z,1637264385.569 [CommandExec ThreadHandler](INFO): Handler Thread ID is 927 2021-11-18T19:39:45.569Z,1637264385.569 [CommandExec](INFO): Initializing the command executive. 2021-11-18T19:39:45.571Z,1637264385.571 [CommandLine ThreadHandler](INFO): Handler Thread ID is 928 2021-11-18T19:39:45.573Z,1637264385.573 [controlThread ThreadHandler](INFO): Handler Thread ID is 929 2021-11-18T19:39:45.574Z,1637264385.574 [controlThread](DEBUG): Initializing ControlThread 2021-11-18T19:39:45.574Z,1637264385.574 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2021-11-18T19:39:45.576Z,1637264385.576 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2021-11-18T19:39:45.577Z,1637264385.577 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2021-11-18T19:39:45.578Z,1637264385.578 [LoopControl](DEBUG): Initialize LoopControlComponent. 2021-11-18T19:39:45.580Z,1637264385.580 [NavChart](DEBUG): Initialize NavChart Navigation. 2021-11-18T19:39:45.580Z,1637264385.580 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2021-11-18T19:39:45.587Z,1637264385.587 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2021-11-18T19:39:45.588Z,1637264385.588 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2021-11-18T19:39:45.588Z,1637264385.588 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2021-11-18T19:39:45.588Z,1637264385.588 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2021-11-18T19:39:45.589Z,1637264385.589 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2021-11-18T19:39:45.589Z,1637264385.589 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2021-11-18T19:39:45.593Z,1637264385.593 [SBIT](INFO): Initialize SBIT Component. 2021-11-18T19:39:45.594Z,1637264385.594 [SBIT](IMPORTANT): git: 2021-10-11a 2021-11-18T19:39:45.594Z,1637264385.594 [SBIT](INFO): git hash: 36f3a97de7a122c995f034a375e3cefac6406048 2021-11-18T19:39:45.594Z,1637264385.594 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2021-11-18T19:39:45.596Z,1637264385.596 [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 2021-11-18T19:39:45.598Z,1637264385.598 [logger ThreadHandler](INFO): Handler Thread ID is 930 2021-11-18T19:39:45.597Z,1637264385.597 [SBIT](INFO): Beginning SBIT in 84.000000 seconds. 2021-11-18T19:39:45.613Z,1637264385.613 [IBIT](INFO): Initialize IBIT Component. 2021-11-18T19:39:45.614Z,1637264385.614 [CBIT](DEBUG): Initialize CBIT Component. 2021-11-18T19:39:45.622Z,1637264385.622 [Onboard ThreadHandler](INFO): Handler Thread ID is 931 2021-11-18T19:39:45.626Z,1637264385.626 [CBIT](DEBUG): Initialized mux pins. 2021-11-18T19:39:45.626Z,1637264385.626 [CBIT](DEBUG): Initializing the watchdog timer. 2021-11-18T19:39:45.642Z,1637264385.642 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 932 2021-11-18T19:39:45.653Z,1637264385.653 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2021-11-18T19:39:45.654Z,1637264385.654 [CBIT](DEBUG): Initializing heartbeat. 2021-11-18T19:39:45.657Z,1637264385.657 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 933 2021-11-18T19:39:45.658Z,1637264385.658 [CTD_Seabird](DEBUG): Initializing CTD_Seabird. 2021-11-18T19:39:45.662Z,1637264385.662 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 935 2021-11-18T19:39:45.665Z,1637264385.665 [WetLabsBB2FL](INFO): Powering up 2021-11-18T19:39:45.666Z,1637264385.666 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 937 2021-11-18T19:39:45.675Z,1637264385.675 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2021-11-18T19:39:45.676Z,1637264385.676 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2021-11-18T19:39:45.676Z,1637264385.676 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2021-11-18T19:39:45.676Z,1637264385.676 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2021-11-18T19:39:45.676Z,1637264385.676 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2021-11-18T19:39:45.676Z,1637264385.676 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2021-11-18T19:39:45.677Z,1637264385.677 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2021-11-18T19:39:45.677Z,1637264385.677 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2021-11-18T19:39:45.677Z,1637264385.677 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2021-11-18T19:39:45.678Z,1637264385.678 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2021-11-18T19:39:45.678Z,1637264385.678 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2021-11-18T19:39:45.678Z,1637264385.678 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2021-11-18T19:39:45.678Z,1637264385.678 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2021-11-18T19:39:45.678Z,1637264385.678 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2021-11-18T19:39:45.679Z,1637264385.679 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2021-11-18T19:39:45.679Z,1637264385.679 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2021-11-18T19:39:45.725Z,1637264385.725 [CBIT](DEBUG): Deactivating GF circuits. 2021-11-18T19:39:45.725Z,1637264385.725 [CBIT](DEBUG): Deactivating emergency mode. 2021-11-18T19:39:45.761Z,1637264385.761 [CBIT](DEBUG): Backplane powered. 2021-11-18T19:39:45.762Z,1637264385.762 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2021-11-18T19:39:45.788Z,1637264385.788 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2021-11-18T19:39:45.816Z,1637264385.816 [MissionManager](DEBUG): 2021-11-18T19:39:45.816Z,1637264385.816 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2021-11-18T19:39:45.901Z,1637264385.901 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2021-11-18T19:39:45.903Z,1637264385.903 [Default:A.Wait](DEBUG): Construct Wait. 2021-11-18T19:39:45.923Z,1637264385.923 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2021-11-18T19:39:45.951Z,1637264385.951 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2021-11-18T19:39:45.977Z,1637264385.977 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2021-11-18T19:39:45.983Z,1637264385.983 [Default:E.Execute](DEBUG): Construct Execute. 2021-11-18T19:39:45.999Z,1637264385.999 [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. 1 Default mission has been running for Restarting logs and Default mission. restart logs 2021-11-18T19:39:46.013Z,1637264386.013 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,DropWeight,NAL9602,Power24vConverter,DAT,CANONSampler,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, 2021-11-18T19:39:46.020Z,1637264386.020 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2021-11-18T19:39:46.045Z,1637264386.045 [Radio_Surface](INFO): Powering up 2021-11-18T19:39:46.156Z,1637264386.156 [Power24vConverter](INFO): Powering up. 2021-11-18T19:39:46.156Z,1637264386.156 [DAT](INFO): Powering up 2021-11-18T19:39:46.157Z,1637264386.157 [DAT](DEBUG): Initializing DAT. 2021-11-18T19:39:46.173Z,1637264386.173 [CANONSampler](INFO): Powering down 2021-11-18T19:39:46.227Z,1637264386.227 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2021-11-18T19:39:46.238Z,1637264386.238 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2021-11-18T19:39:46.239Z,1637264386.239 [ElevatorServo](DEBUG): Initializing EZServoServo. 2021-11-18T19:39:46.246Z,1637264386.246 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2021-11-18T19:39:46.247Z,1637264386.247 [MassServo](DEBUG): Initializing EZServoServo. 2021-11-18T19:39:46.253Z,1637264386.253 [MassServo](DEBUG): Initializing MassServo. 2021-11-18T19:39:46.254Z,1637264386.254 [RudderServo](DEBUG): Initializing EZServoServo. 2021-11-18T19:39:46.261Z,1637264386.261 [RudderServo](DEBUG): Initializing RudderServo. 2021-11-18T19:39:46.262Z,1637264386.262 [ThrusterServo](DEBUG): Initializing EZServoServo. 2021-11-18T19:39:46.269Z,1637264386.269 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2021-11-18T19:39:46.446Z,1637264386.446 [DropWeight](CRITICAL): DROP WEIGHT MISSING. 2021-11-18T19:39:46.446Z,1637264386.446 [DropWeight] Hardware Fault, FailCount= 1 2021-11-18T19:39:46.447Z,1637264386.447 [DropWeight](ERROR): Hardware Fault 2021-11-18T19:39:46.473Z,1637264386.473 [CommandExec](FAULT): Scheduling is paused 2021-11-18T19:39:46.473Z,1637264386.473 [CBIT](INFO): Critical error at 20211118T193946 2021-11-18T19:39:46.473Z,1637264386.473 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals 2021-11-18T19:39:46.476Z,1637264386.476 [CBIT](ERROR): Hardware Fault in component: DropWeight 2021-11-18T19:39:46.476Z,1637264386.476 [CBIT](CRITICAL): Hardware Fault in component: DropWeight 2021-11-18T19:39:47.153Z,1637264387.153 [RudderServo](ERROR): Rudder initialization uart error serial timeout 2021-11-18T19:39:47.153Z,1637264387.153 [RudderServo](FAULT): Rudder failed to initialize 2021-11-18T19:39:47.153Z,1637264387.153 [RudderServo] Communications Fault, FailCount= 1 2021-11-18T19:39:47.153Z,1637264387.153 [RudderServo](ERROR): Communications Fault 2021-11-18T19:39:47.251Z,1637264387.251 [CBIT](INFO): Critical error at 20211118T193946 2021-11-18T19:39:47.254Z,1637264387.254 [CBIT](ERROR): Communications Fault in component: RudderServo 2021-11-18T19:39:47.462Z,1637264387.462 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2021-11-18T19:39:47.462Z,1637264387.462 [RudderServo](INFO): Powering down 2021-11-18T19:39:47.773Z,1637264387.773 [WetLabsBB2FL](INFO): Powering down 2021-11-18T19:39:48.091Z,1637264388.091 [RudderServo](DEBUG): Initializing EZServoServo. 2021-11-18T19:39:48.210Z,1637264388.210 [RudderServo](DEBUG): Initializing RudderServo. 2021-11-18T19:39:48.214Z,1637264388.214 [CBIT](INFO): Clearing failed state for component RudderServo 2021-11-18T19:39:48.214Z,1637264388.214 [RudderServo] No Fault, FailCount= 1 2021-11-18T19:39:52.689Z,1637264392.689 [CTD_Seabird](ERROR): Device message queue exceeded the allowed limit. 2021-11-18T19:39:57.775Z,1637264397.775 [DAT](INFO): DAT read: 2021-11-18T19:39:57.777Z,1637264397.777 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series 2021-11-18T19:39:59.387Z,1637264399.387 [DAT](INFO): DAT read: MF Frequency Band 2021-11-18T19:39:59.389Z,1637264399.389 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.14.2 2021-11-18T19:39:59.389Z,1637264399.389 [DAT](INFO): DAT read: Nov 18 2021 19:39:12 2021-11-18T19:40:00.599Z,1637264400.599 [DAT](INFO): DAT read: Features enabled [Bearing] 2021-11-18T19:40:00.601Z,1637264400.601 [DAT](INFO): DAT read: CONNECT 01200 bits/sec 1 of 4, Rate 1/2 CC 2021-11-18T19:40:00.601Z,1637264400.601 [DAT](INFO): commRate: 1200 2021-11-18T19:40:02.619Z,1637264402.619 [DAT](INFO): entering command mode 2021-11-18T19:40:03.023Z,1637264403.023 [DAT](INFO): DAT read: 2021-11-18T19:40:03.023Z,1637264403.023 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:03.427Z,1637264403.427 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:03.831Z,1637264403.831 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:04.235Z,1637264404.235 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:04.639Z,1637264404.639 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:05.043Z,1637264405.043 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:05.447Z,1637264405.447 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:05.851Z,1637264405.851 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:06.255Z,1637264406.255 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:06.665Z,1637264406.665 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:07.063Z,1637264407.063 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:07.467Z,1637264407.467 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:07.871Z,1637264407.871 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:08.279Z,1637264408.279 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:08.679Z,1637264408.679 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:09.083Z,1637264409.083 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:09.487Z,1637264409.487 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:09.891Z,1637264409.891 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:10.295Z,1637264410.295 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:10.699Z,1637264410.699 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:11.103Z,1637264411.103 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:11.507Z,1637264411.507 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:11.911Z,1637264411.911 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:12.315Z,1637264412.315 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:12.723Z,1637264412.723 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:13.123Z,1637264413.123 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:13.527Z,1637264413.527 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:13.931Z,1637264413.931 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:14.359Z,1637264414.359 [NAL9602](INFO): Powering up NAL9602 2021-11-18T19:40:14.361Z,1637264414.361 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:14.763Z,1637264414.763 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:15.167Z,1637264415.167 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:15.316Z,1637264415.316 [CommandExec](IMPORTANT): got command get depth 2021-11-18T19:40:15.316Z,1637264415.316 [CommandExec](IMPORTANT): depth 0.025173 m 2021-11-18T19:40:15.571Z,1637264415.571 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:15.975Z,1637264415.975 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:16.379Z,1637264416.379 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:16.791Z,1637264416.791 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:17.191Z,1637264417.191 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:17.591Z,1637264417.591 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:17.995Z,1637264417.995 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-18T19:40:17.995Z,1637264417.995 [DAT](FAULT): failed to enter command mode 2021-11-18T19:40:18.246Z,1637264418.246 [CommandExec](IMPORTANT): got command get depth 2021-11-18T19:40:18.247Z,1637264418.247 [CommandExec](IMPORTANT): depth 0.025173 m 2021-11-18T19:40:18.399Z,1637264418.399 [DAT](INFO): entering command mode 2021-11-18T19:40:18.803Z,1637264418.803 [DAT](INFO): DAT read: user:1> 2021-11-18T19:40:18.804Z,1637264418.804 [DAT](INFO): DAT read: Command '+++' not found 2021-11-18T19:40:18.805Z,1637264418.805 [DAT](INFO): DAT read: Error 2021-11-18T19:40:18.805Z,1637264418.805 [DAT](INFO): setting verbose to 3 2021-11-18T19:40:19.215Z,1637264419.215 [DAT](INFO): DAT read: user:2> 2021-11-18T19:40:19.216Z,1637264419.216 [DAT](INFO): DAT read: Verbose | 3 2021-11-18T19:40:19.217Z,1637264419.217 [DAT](INFO): set verbose to 3 2021-11-18T19:40:19.217Z,1637264419.217 [DAT](INFO): setting DatVerbose to 27440 2021-11-18T19:40:19.623Z,1637264419.623 [DAT](INFO): DAT read: user:3> 2021-11-18T19:40:19.624Z,1637264419.624 [DAT](INFO): DAT read: DatVerbose | 27440 2021-11-18T19:40:19.625Z,1637264419.625 [DAT](INFO): set DatVerbose to 27440 2021-11-18T19:40:19.625Z,1637264419.625 [DAT](INFO): setting transmit power to 8 2021-11-18T19:40:20.015Z,1637264420.015 [DAT](INFO): DAT read: user:4> 2021-11-18T19:40:20.016Z,1637264420.016 [DAT](INFO): DAT read: TxPower | 8 (Max) 2021-11-18T19:40:20.016Z,1637264420.016 [DAT](INFO): set transmit power to 8 2021-11-18T19:40:20.018Z,1637264420.018 [DAT](INFO): setting local address to 7 2021-11-18T19:40:20.419Z,1637264420.419 [DAT](INFO): DAT read: user:5> 2021-11-18T19:40:20.420Z,1637264420.420 [DAT](INFO): DAT read: LocalAddr | 7 2021-11-18T19:40:20.420Z,1637264420.420 [DAT](INFO): set local address to 7 2021-11-18T19:40:25.267Z,1637264425.267 [NAL9602](INFO): NAL9602 initialized 2021-11-18T19:41:10.166Z,1637264470.166 [SBIT](IMPORTANT): Beginning Startup BIT 2021-11-18T19:41:10.170Z,1637264470.170 [CBIT](IMPORTANT): Beginning ground fault scan 2021-11-18T19:41:21.065Z,1637264481.065 [CBIT](ERROR): Ground fault scan returned out of bounds value. Re-running scan. 2021-11-18T19:41:21.481Z,1637264481.481 [CBIT](IMPORTANT): Beginning ground fault scan 2021-11-18T19:41:32.414Z,1637264492.414 [CBIT](ERROR): Ground fault scan returned out of bounds value. Re-running scan. 2021-11-18T19:41:32.799Z,1637264492.799 [CBIT](IMPORTANT): Beginning ground fault scan 2021-11-18T19:41:44.092Z,1637264504.092 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.002407 CHAN A1 (24V): 0.000263 CHAN A2 (12V): -0.001844 CHAN A3 (5V): -0.001445 CHAN B0 (3.3V): 0.000054 CHAN B1 (3.15aV): 0.000057 CHAN B2 (3.15bV): 0.000163 CHAN B3 (GND): 0.000449 OPEN: -0.000570 Full Scale: +/- 1 mA 2021-11-18T19:42:04.265Z,1637264524.265 [SBIT](IMPORTANT): SBIT PASSED 2021-11-18T19:42:04.266Z,1637264524.266 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2021-11-18T19:42:04.267Z,1637264524.267 [SBIT](IMPORTANT): AMEcho.loadAtStartup=0 bool; 2021-11-18T19:42:04.268Z,1637264524.268 [SBIT](IMPORTANT): BuoyancyServo.fastPumpDepth=6 meter; 2021-11-18T19:42:04.268Z,1637264524.268 [SBIT](IMPORTANT): CANONSampler.loadAtStartup=1 bool; 2021-11-18T19:42:04.268Z,1637264524.268 [SBIT](IMPORTANT): DAT.baud=9600 bit_per_second; 2021-11-18T19:42:04.268Z,1637264524.268 [SBIT](IMPORTANT): DAT.loadAtStartup=1 bool; 2021-11-18T19:42:04.268Z,1637264524.268 [SBIT](IMPORTANT): DAT.sbdAddress=1 enum; 2021-11-18T19:42:04.268Z,1637264524.268 [SBIT](IMPORTANT): DAT.surfaceThreshold=0 meter; 2021-11-18T19:42:04.268Z,1637264524.268 [SBIT](IMPORTANT): DAT.verbosity=3 count; 2021-11-18T19:42:04.269Z,1637264524.269 [SBIT](IMPORTANT): DataOverHttps.loadAtStartup=0 bool; 2021-11-18T19:42:04.269Z,1637264524.269 [SBIT](IMPORTANT): ESPComponent.loadAtStartup=0 bool; 2021-11-18T19:42:04.269Z,1637264524.269 [SBIT](IMPORTANT): ESPComponent.simulateHardware=1 bool; 2021-11-18T19:42:04.271Z,1637264524.271 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=296 cubic_centimeter; 2021-11-18T19:42:04.271Z,1637264524.271 [SBIT](IMPORTANT): VerticalControl.massDefault=-16 millimeter; 2021-11-18T19:42:04.271Z,1637264524.271 [SBIT](IMPORTANT): VerticalControl.surfaceThreshold=2 meter; 2021-11-18T19:42:04.660Z,1637264524.660 [MissionManager](IMPORTANT): Started mission Startup 2021-11-18T19:42:04.660Z,1637264524.660 [Startup] Running Loop=1 2021-11-18T19:42:04.660Z,1637264524.660 [Startup](DEBUG): Aggregate::initialize Startup 2021-11-18T19:42:04.660Z,1637264524.660 [Startup:A.GoToSurface] Running Loop=1 2021-11-18T19:42:04.661Z,1637264524.661 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2021-11-18T19:42:04.661Z,1637264524.661 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2021-11-18T19:42:04.662Z,1637264524.662 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2021-11-18T19:42:04.662Z,1637264524.662 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2021-11-18T19:42:04.663Z,1637264524.663 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2021-11-18T19:42:04.663Z,1637264524.663 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2021-11-18T19:42:04.664Z,1637264524.664 [Startup:StartupSatComms] Running Loop=1 2021-11-18T19:42:04.665Z,1637264524.665 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2021-11-18T19:42:04.665Z,1637264524.665 [Startup:StartupSatComms:A] Running Loop=1 2021-11-18T19:42:05.121Z,1637264525.121 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2021-11-18T19:42:45.891Z,1637264565.891 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1 2021-11-18T19:42:45.891Z,1637264565.891 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-11-18T19:42:45.903Z,1637264565.903 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-11-18T19:42:46.331Z,1637264566.331 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-11-18T19:42:46.331Z,1637264566.331 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1 2021-11-18T19:43:04.860Z,1637264584.860 [Startup:StartupSatComms:A](INFO): Timed out from 2021-11-18T19:42:04.7Z 2021-11-18T19:43:04.860Z,1637264584.860 [Startup:StartupSatComms:A] Stopped 2021-11-18T19:43:04.860Z,1637264584.860 [Startup:StartupSatComms:B] Running Loop=1 2021-11-18T19:43:05.268Z,1637264585.268 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2021-11-18T19:43:06.478Z,1637264586.478 [DAT](INFO): #Outgoing data=1 2021-11-18T19:43:06.478Z,1637264586.478 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T19:43:06.575Z,1637264586.575 [DAT](INFO): setting remote address to 1 2021-11-18T19:43:06.991Z,1637264586.991 [DAT](INFO): DAT read: user:6> 2021-11-18T19:43:06.992Z,1637264586.992 [DAT](INFO): DAT read: RemoteAddr | 1 2021-11-18T19:43:06.992Z,1637264586.992 [DAT](INFO): set remote address to 1 2021-11-18T19:43:06.993Z,1637264586.993 [DAT](INFO): entering online mode 2021-11-18T19:43:07.407Z,1637264587.407 [DAT](INFO): DAT read: user:7> 2021-11-18T19:43:07.407Z,1637264587.407 [DAT](INFO): DAT read: 2021-11-18T19:43:07.408Z,1637264587.408 [DAT](INFO): DAT read: CONNECT 01200 bits/sec 1 of 4, Rate 1/2 CC 2021-11-18T19:43:07.409Z,1637264587.409 [DAT](INFO): commRate: 1200 2021-11-18T19:43:07.409Z,1637264587.409 [DAT](INFO): online mode acknowledged 2021-11-18T19:43:07.409Z,1637264587.409 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T19:43:10.959Z,1637264590.959 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:42:33.5356 2021-11-18T19:43:10.960Z,1637264590.960 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T19:43:21.080Z,1637264601.080 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T19:43:21.080Z,1637264601.080 [DAT](DEBUG): In sendingAckWaiting, timeout so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T19:43:21.963Z,1637264601.963 [DAT](INFO): #Outgoing data=1 2021-11-18T19:43:21.963Z,1637264601.963 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T19:43:22.063Z,1637264602.063 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T19:43:25.633Z,1637264605.633 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:42:48.1853 2021-11-18T19:43:25.633Z,1637264605.633 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T19:43:35.736Z,1637264615.736 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T19:43:35.736Z,1637264615.736 [DAT](DEBUG): In sendingAckWaiting, timeout so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T19:43:36.618Z,1637264616.618 [DAT](INFO): #Outgoing data=2 2021-11-18T19:43:36.619Z,1637264616.619 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T19:43:36.705Z,1637264616.705 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T19:43:39.909Z,1637264619.909 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:43:02.8351 2021-11-18T19:43:39.909Z,1637264619.909 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T19:43:50.019Z,1637264630.019 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T19:43:50.019Z,1637264630.019 [DAT](DEBUG): In sendingAckWaiting, timeout so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T19:43:50.906Z,1637264630.906 [DAT](INFO): #Outgoing data=3 2021-11-18T19:43:50.906Z,1637264630.906 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T19:43:50.989Z,1637264630.989 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T19:43:54.191Z,1637264634.191 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:43:17.1363 2021-11-18T19:43:54.191Z,1637264634.191 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T19:44:04.296Z,1637264644.296 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T19:44:04.296Z,1637264644.296 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T19:44:04.691Z,1637264644.691 [DAT](INFO): Sent 18 bytes from file Logs/20211117T223619/Courier0013.lzma.parts 2021-11-18T19:44:04.691Z,1637264644.691 [DAT](INFO): Packets left to send: 0 2021-11-18T19:44:04.694Z,1637264644.694 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T19:44:05.584Z,1637264645.584 [DAT](INFO): #Outgoing data=4 2021-11-18T19:44:05.584Z,1637264645.584 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T19:44:05.601Z,1637264645.601 [Startup:StartupSatComms:B](INFO): Timed out from 2021-11-18T19:43:04.9Z 2021-11-18T19:44:05.601Z,1637264645.601 [Startup:StartupSatComms:B] Stopped 2021-11-18T19:44:05.601Z,1637264645.601 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2021-11-18T19:44:05.601Z,1637264645.601 [Startup:StartupSatComms] Stopped 2021-11-18T19:44:05.601Z,1637264645.601 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2021-11-18T19:44:05.602Z,1637264645.602 [Startup](INFO): Completed Startup 2021-11-18T19:44:05.602Z,1637264645.602 [MissionManager](INFO): Startup is completed. 2021-11-18T19:44:05.602Z,1637264645.602 [MissionManager](INFO): Uninitializing Mission Startup 2021-11-18T19:44:05.603Z,1637264645.603 [Startup] Stopped 2021-11-18T19:44:05.603Z,1637264645.603 [Startup](DEBUG): Aggregate::uninitialize Startup 2021-11-18T19:44:05.603Z,1637264645.603 [Startup:A.GoToSurface] Stopped 2021-11-18T19:44:05.603Z,1637264645.603 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2021-11-18T19:44:05.691Z,1637264645.691 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T19:44:05.778Z,1637264645.778 [MissionManager](IMPORTANT): Started mission Default 2021-11-18T19:44:05.779Z,1637264645.779 [Default] Running Loop=1 2021-11-18T19:44:05.780Z,1637264645.780 [Default](DEBUG): Aggregate::initialize Default 2021-11-18T19:44:05.780Z,1637264645.780 [Default:B.GoToSurface] Running Loop=1 2021-11-18T19:44:05.781Z,1637264645.781 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2021-11-18T19:44:05.787Z,1637264645.787 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2021-11-18T19:44:05.788Z,1637264645.788 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2021-11-18T19:44:05.794Z,1637264645.794 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2021-11-18T19:44:05.796Z,1637264645.796 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2021-11-18T19:44:05.806Z,1637264645.806 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2021-11-18T19:44:05.808Z,1637264645.808 [Default:A.Wait] Running Loop=1 2021-11-18T19:44:05.808Z,1637264645.808 [Default:A.Wait](DEBUG): Initialize Wait Component. 2021-11-18T19:44:09.291Z,1637264649.291 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:43:31.9847 2021-11-18T19:44:09.291Z,1637264649.291 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T19:44:18.973Z,1637264658.973 [Default:A.Wait](INFO): Done Waiting. 2021-11-18T19:44:18.973Z,1637264658.973 [Default:A.Wait] Stopped 2021-11-18T19:44:18.973Z,1637264658.973 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T19:44:19.365Z,1637264659.365 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T19:44:19.365Z,1637264659.365 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T19:44:19.381Z,1637264659.381 [Default:CheckIn] Running Loop=1 2021-11-18T19:44:19.381Z,1637264659.381 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T19:44:19.382Z,1637264659.382 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T19:44:19.791Z,1637264659.791 [DAT](INFO): Sent 184 bytes from file Logs/20211118T193226/Courier0000.lzma.parts 2021-11-18T19:44:19.791Z,1637264659.791 [DAT](INFO): Packets left to send: 1 2021-11-18T19:44:19.793Z,1637264659.793 [DAT](DEBUG): In sendingVerified, sbd done so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T19:44:19.809Z,1637264659.809 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2021-11-18T19:44:20.188Z,1637264660.188 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T19:44:20.591Z,1637264660.591 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T19:44:23.873Z,1637264663.873 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:43:46.7344 2021-11-18T19:44:23.873Z,1637264663.873 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T19:44:33.924Z,1637264673.924 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T19:44:33.924Z,1637264673.924 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T19:44:34.316Z,1637264674.316 [DAT](DEBUG): In sendingVerified, sbd done so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T19:44:34.720Z,1637264674.720 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T19:44:35.121Z,1637264675.121 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T19:44:38.372Z,1637264678.372 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:44:01.2842 2021-11-18T19:44:38.372Z,1637264678.372 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T19:44:48.456Z,1637264688.456 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T19:44:48.456Z,1637264688.456 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T19:44:48.860Z,1637264688.860 [DAT](DEBUG): In sendingVerified, sbd done so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T19:44:49.268Z,1637264689.268 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T19:44:49.665Z,1637264689.665 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T19:44:52.901Z,1637264692.901 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:44:15.7840 2021-11-18T19:44:52.901Z,1637264692.901 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T19:45:03.015Z,1637264703.015 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T19:45:03.015Z,1637264703.015 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T19:45:03.407Z,1637264703.407 [DAT](DEBUG): In sendingVerified, sbd done so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T19:45:19.578Z,1637264719.578 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T19:44:19.4Z 2021-11-18T19:45:19.578Z,1637264719.578 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T19:45:19.578Z,1637264719.578 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T19:45:19.991Z,1637264719.991 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2021-11-18T19:45:20.848Z,1637264720.848 [DAT](INFO): #Outgoing data=1 2021-11-18T19:45:20.848Z,1637264720.848 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T19:45:20.972Z,1637264720.972 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T19:45:24.541Z,1637264724.541 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:44:47.1835 2021-11-18T19:45:24.541Z,1637264724.541 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T19:45:28.576Z,1637264728.576 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2021-11-18T19:45:34.642Z,1637264734.642 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T19:45:34.642Z,1637264734.642 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T19:45:35.056Z,1637264735.056 [DAT](INFO): Sent 59 bytes from file Logs/20211118T193226/Courier0000.lzma.parts 2021-11-18T19:45:35.057Z,1637264735.057 [DAT](INFO): Packets left to send: 0 2021-11-18T19:45:35.059Z,1637264735.059 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T19:45:35.928Z,1637264735.928 [DAT](INFO): #Outgoing data=1 2021-11-18T19:45:35.929Z,1637264735.929 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T19:45:36.018Z,1637264736.018 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T19:45:39.605Z,1637264739.605 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:45:02.3333 2021-11-18T19:45:39.605Z,1637264739.605 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T19:45:46.884Z,1637264746.884 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2 2021-11-18T19:45:46.884Z,1637264746.884 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-11-18T19:45:46.895Z,1637264746.895 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-11-18T19:45:47.358Z,1637264747.358 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-11-18T19:45:47.358Z,1637264747.358 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2 2021-11-18T19:45:49.704Z,1637264749.704 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T19:45:49.704Z,1637264749.704 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T19:45:50.108Z,1637264750.108 [DAT](INFO): Sent 184 bytes from file Logs/20211118T193339/Courier0000.lzma.parts 2021-11-18T19:45:50.108Z,1637264750.108 [DAT](INFO): Packets left to send: 2 2021-11-18T19:45:50.111Z,1637264750.111 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T19:45:51.006Z,1637264751.006 [DAT](INFO): #Outgoing data=1 2021-11-18T19:45:51.006Z,1637264751.006 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T19:45:51.101Z,1637264751.101 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T19:45:54.677Z,1637264754.677 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:45:17.4332 2021-11-18T19:45:54.677Z,1637264754.677 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T19:46:00.330Z,1637264760.330 [NAL9602](ERROR): Queried for signal strength and failed to receive proper response. 2021-11-18T19:46:00.406Z,1637264760.406 [NAL9602](ERROR): received: +CSQ:0 OK 2021-11-18T19:46:04.863Z,1637264764.863 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T19:46:04.863Z,1637264764.863 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T19:46:04.949Z,1637264764.949 [DAT](INFO): Sent 184 bytes from file Logs/20211118T193339/Courier0000.lzma.parts 2021-11-18T19:46:04.949Z,1637264764.949 [DAT](INFO): Packets left to send: 1 2021-11-18T19:46:04.951Z,1637264764.951 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T19:46:05.786Z,1637264765.786 [DAT](INFO): #Outgoing data=1 2021-11-18T19:46:05.786Z,1637264765.786 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T19:46:05.887Z,1637264765.887 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T19:46:09.180Z,1637264769.180 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:45:32.0843 2021-11-18T19:46:09.180Z,1637264769.180 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T19:46:19.230Z,1637264779.230 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T19:46:19.231Z,1637264779.231 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T19:46:19.616Z,1637264779.616 [DAT](INFO): Sent 80 bytes from file Logs/20211118T193339/Courier0000.lzma.parts 2021-11-18T19:46:19.616Z,1637264779.616 [DAT](INFO): Packets left to send: 0 2021-11-18T19:46:19.635Z,1637264779.635 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T19:46:20.574Z,1637264780.574 [DAT](INFO): #Outgoing data=1 2021-11-18T19:46:20.574Z,1637264780.574 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T19:46:20.679Z,1637264780.679 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T19:46:24.084Z,1637264784.084 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:45:46.8328 2021-11-18T19:46:24.084Z,1637264784.084 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T19:46:34.663Z,1637264794.663 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T19:46:34.663Z,1637264794.663 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T19:46:34.748Z,1637264794.748 [DAT](INFO): Sent 18 bytes from file Logs/20211118T193750/Courier0000.lzma.parts 2021-11-18T19:46:34.749Z,1637264794.749 [DAT](INFO): Packets left to send: 0 2021-11-18T19:46:34.751Z,1637264794.751 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T19:46:35.636Z,1637264795.636 [DAT](INFO): #Outgoing data=1 2021-11-18T19:46:35.637Z,1637264795.637 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T19:46:35.739Z,1637264795.739 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T19:46:39.504Z,1637264799.504 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:46:02.0826 2021-11-18T19:46:39.504Z,1637264799.504 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T19:46:49.850Z,1637264809.850 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T19:46:49.850Z,1637264809.850 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T19:46:50.727Z,1637264810.727 [DAT](INFO): Sent 184 bytes from file Logs/20211118T193933/Courier0000.lzma.parts 2021-11-18T19:46:50.727Z,1637264810.727 [DAT](INFO): Packets left to send: 1 2021-11-18T19:46:50.729Z,1637264810.729 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T19:46:51.310Z,1637264811.310 [DAT](INFO): #Outgoing data=1 2021-11-18T19:46:51.311Z,1637264811.311 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T19:46:51.448Z,1637264811.448 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T19:46:54.735Z,1637264814.735 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:46:17.6323 2021-11-18T19:46:54.736Z,1637264814.736 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T19:47:04.776Z,1637264824.776 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T19:47:04.776Z,1637264824.776 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T19:47:05.218Z,1637264825.218 [DAT](INFO): Sent 57 bytes from file Logs/20211118T193933/Courier0000.lzma.parts 2021-11-18T19:47:05.218Z,1637264825.218 [DAT](INFO): Packets left to send: 0 2021-11-18T19:47:05.220Z,1637264825.220 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T19:47:06.082Z,1637264826.082 [DAT](INFO): #Outgoing data=1 2021-11-18T19:47:06.083Z,1637264826.083 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T19:47:06.219Z,1637264826.219 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T19:47:09.571Z,1637264829.571 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:46:32.3821 2021-11-18T19:47:09.572Z,1637264829.572 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T19:47:19.694Z,1637264839.694 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T19:47:19.695Z,1637264839.695 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T19:47:20.160Z,1637264840.160 [DAT](INFO): Sent 39 bytes from file Logs/20211118T193933/Courier0004.lzma.parts 2021-11-18T19:47:20.160Z,1637264840.160 [DAT](INFO): Packets left to send: 0 2021-11-18T19:47:20.162Z,1637264840.162 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T19:47:21.000Z,1637264841.000 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T19:47:21.000Z,1637264841.000 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T19:47:21.000Z,1637264841.000 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T19:47:48.095Z,1637264868.095 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2021-11-18T19:47:48.099Z,1637264868.099 [BPC1](INFO): Received data from all battery sticks. 2021-11-18T19:48:21.241Z,1637264901.241 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T19:48:21.241Z,1637264901.241 [Default:CheckIn:C.Wait] Stopped 2021-11-18T19:48:21.241Z,1637264901.241 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T19:48:21.241Z,1637264901.241 [Default:CheckIn:D] Running Loop=1 2021-11-18T19:48:21.658Z,1637264901.658 [Default:CheckIn:D] Stopped 2021-11-18T19:48:21.658Z,1637264901.658 [Default:CheckIn:E] Running Loop=1 2021-11-18T19:48:22.057Z,1637264902.057 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 4.264654 min 2021-11-18T19:48:22.057Z,1637264902.057 [Default:CheckIn:E] Stopped 2021-11-18T19:48:22.057Z,1637264902.057 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T19:48:22.057Z,1637264902.057 [Default:CheckIn] Stopped 2021-11-18T19:48:22.057Z,1637264902.057 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T19:48:22.074Z,1637264902.074 [Default:CheckIn](INFO): Running loop #2 2021-11-18T19:48:22.074Z,1637264902.074 [Default:CheckIn] Running Loop=2 2021-11-18T19:48:22.074Z,1637264902.074 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T19:48:22.074Z,1637264902.074 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T19:48:47.892Z,1637264927.892 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3 2021-11-18T19:48:47.892Z,1637264927.892 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-11-18T19:48:47.903Z,1637264927.903 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-11-18T19:48:48.317Z,1637264928.317 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-11-18T19:48:48.317Z,1637264928.317 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3 2021-11-18T19:49:22.257Z,1637264962.257 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T19:48:22.1Z 2021-11-18T19:49:22.257Z,1637264962.257 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T19:49:22.258Z,1637264962.258 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T19:49:23.506Z,1637264963.506 [DAT](INFO): #Outgoing data=1 2021-11-18T19:49:23.507Z,1637264963.507 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T19:49:23.592Z,1637264963.592 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T19:49:27.182Z,1637264967.182 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:48:49.8801 2021-11-18T19:49:27.182Z,1637264967.182 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T19:49:37.671Z,1637264977.671 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T19:49:37.671Z,1637264977.671 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T19:49:37.761Z,1637264977.761 [DAT](INFO): Sent 167 bytes from file Logs/20211118T193933/Courier0007.lzma.parts 2021-11-18T19:49:37.761Z,1637264977.761 [DAT](INFO): Packets left to send: 0 2021-11-18T19:49:37.763Z,1637264977.763 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T19:49:38.652Z,1637264978.652 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T19:49:38.653Z,1637264978.653 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T19:49:38.653Z,1637264978.653 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T19:50:26.351Z,1637265026.351 [NAL9602](FAULT): GPS failed to acquire within timeout. 2021-11-18T19:50:26.351Z,1637265026.351 [NAL9602] Data Fault, FailCount= 1 2021-11-18T19:50:26.351Z,1637265026.351 [NAL9602](ERROR): Data Fault 2021-11-18T19:50:26.371Z,1637265026.371 [CBIT](ERROR): Data Fault in component: NAL9602 2021-11-18T19:50:26.755Z,1637265026.755 [NAL9602](INFO): Powering down 2021-11-18T19:50:27.594Z,1637265027.594 [CBIT](INFO): Clearing failed state for component NAL9602 2021-11-18T19:50:27.594Z,1637265027.594 [NAL9602] No Fault, FailCount= 1 2021-11-18T19:50:38.884Z,1637265038.884 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T19:50:38.884Z,1637265038.884 [Default:CheckIn:C.Wait] Stopped 2021-11-18T19:50:38.884Z,1637265038.884 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T19:50:38.884Z,1637265038.884 [Default:CheckIn:D] Running Loop=1 2021-11-18T19:50:39.291Z,1637265039.291 [Default:CheckIn:D] Stopped 2021-11-18T19:50:39.291Z,1637265039.291 [Default:CheckIn:E] Running Loop=1 2021-11-18T19:50:39.705Z,1637265039.705 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 6.558535 min 2021-11-18T19:50:39.706Z,1637265039.706 [Default:CheckIn:E] Stopped 2021-11-18T19:50:39.706Z,1637265039.706 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T19:50:39.706Z,1637265039.706 [Default:CheckIn] Stopped 2021-11-18T19:50:39.706Z,1637265039.706 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T19:50:39.706Z,1637265039.706 [Default:CheckIn](INFO): Running loop #3 2021-11-18T19:50:39.706Z,1637265039.706 [Default:CheckIn] Running Loop=3 2021-11-18T19:50:39.706Z,1637265039.706 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T19:50:39.706Z,1637265039.706 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T19:50:57.057Z,1637265057.057 [NAL9602](INFO): Powering up NAL9602 2021-11-18T19:51:07.970Z,1637265067.970 [NAL9602](INFO): NAL9602 initialized 2021-11-18T19:51:39.885Z,1637265099.885 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T19:50:39.7Z 2021-11-18T19:51:39.885Z,1637265099.885 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T19:51:39.885Z,1637265099.885 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T19:51:41.185Z,1637265101.185 [DAT](INFO): #Outgoing data=1 2021-11-18T19:51:41.186Z,1637265101.186 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T19:51:41.283Z,1637265101.283 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T19:51:44.591Z,1637265104.591 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:51:07.4281 2021-11-18T19:51:44.592Z,1637265104.592 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T19:51:48.766Z,1637265108.766 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4 2021-11-18T19:51:48.766Z,1637265108.766 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-11-18T19:51:48.777Z,1637265108.777 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-11-18T19:51:48.879Z,1637265108.879 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-11-18T19:51:48.879Z,1637265108.879 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4 2021-11-18T19:51:54.605Z,1637265114.605 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T19:51:54.605Z,1637265114.605 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T19:51:55.031Z,1637265115.031 [DAT](INFO): Sent 39 bytes from file Logs/20211118T193933/Courier0010.lzma.parts 2021-11-18T19:51:55.031Z,1637265115.031 [DAT](INFO): Packets left to send: 0 2021-11-18T19:51:55.034Z,1637265115.034 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T19:51:55.910Z,1637265115.910 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T19:51:55.910Z,1637265115.910 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T19:51:55.910Z,1637265115.910 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T19:52:56.080Z,1637265176.080 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T19:52:56.080Z,1637265176.080 [Default:CheckIn:C.Wait] Stopped 2021-11-18T19:52:56.081Z,1637265176.081 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T19:52:56.081Z,1637265176.081 [Default:CheckIn:D] Running Loop=1 2021-11-18T19:52:56.471Z,1637265176.471 [Default:CheckIn:D] Stopped 2021-11-18T19:52:56.471Z,1637265176.471 [Default:CheckIn:E] Running Loop=1 2021-11-18T19:52:56.864Z,1637265176.864 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 8.844878 min 2021-11-18T19:52:56.864Z,1637265176.864 [Default:CheckIn:E] Stopped 2021-11-18T19:52:56.865Z,1637265176.865 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T19:52:56.865Z,1637265176.865 [Default:CheckIn] Stopped 2021-11-18T19:52:56.865Z,1637265176.865 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T19:52:56.865Z,1637265176.865 [Default:CheckIn](INFO): Running loop #4 2021-11-18T19:52:56.865Z,1637265176.865 [Default:CheckIn] Running Loop=4 2021-11-18T19:52:56.865Z,1637265176.865 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T19:52:56.865Z,1637265176.865 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T19:53:57.060Z,1637265237.060 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T19:52:56.9Z 2021-11-18T19:53:57.061Z,1637265237.061 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T19:53:57.061Z,1637265237.061 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T19:53:58.356Z,1637265238.356 [DAT](INFO): #Outgoing data=1 2021-11-18T19:53:58.356Z,1637265238.356 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T19:53:58.456Z,1637265238.456 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T19:54:01.775Z,1637265241.775 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:53:24.6259 2021-11-18T19:54:01.776Z,1637265241.776 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T19:54:11.781Z,1637265251.781 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T19:54:11.781Z,1637265251.781 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T19:54:12.203Z,1637265252.203 [DAT](INFO): Sent 39 bytes from file Logs/20211118T193933/Courier0013.lzma.parts 2021-11-18T19:54:12.203Z,1637265252.203 [DAT](INFO): Packets left to send: 0 2021-11-18T19:54:12.205Z,1637265252.205 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T19:54:13.087Z,1637265253.087 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T19:54:13.087Z,1637265253.087 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T19:54:13.087Z,1637265253.087 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T19:54:46.486Z,1637265286.486 [CBIT](INFO): Clearing failed state for component DropWeight 2021-11-18T19:54:46.486Z,1637265286.486 [DropWeight] No Fault, FailCount= 1 2021-11-18T19:54:49.307Z,1637265289.307 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5 2021-11-18T19:54:49.307Z,1637265289.307 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-11-18T19:54:49.351Z,1637265289.351 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-11-18T19:54:49.723Z,1637265289.723 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-11-18T19:54:49.723Z,1637265289.723 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5 2021-11-18T19:55:13.552Z,1637265313.552 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T19:55:13.552Z,1637265313.552 [Default:CheckIn:C.Wait] Stopped 2021-11-18T19:55:13.552Z,1637265313.552 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T19:55:13.552Z,1637265313.552 [Default:CheckIn:D] Running Loop=1 2021-11-18T19:55:13.961Z,1637265313.961 [Default:CheckIn:D] Stopped 2021-11-18T19:55:13.961Z,1637265313.961 [Default:CheckIn:E] Running Loop=1 2021-11-18T19:55:14.353Z,1637265314.353 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 11.136367 min 2021-11-18T19:55:14.353Z,1637265314.353 [Default:CheckIn:E] Stopped 2021-11-18T19:55:14.353Z,1637265314.353 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T19:55:14.354Z,1637265314.354 [Default:CheckIn] Stopped 2021-11-18T19:55:14.354Z,1637265314.354 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T19:55:14.354Z,1637265314.354 [Default:CheckIn](INFO): Running loop #5 2021-11-18T19:55:14.354Z,1637265314.354 [Default:CheckIn] Running Loop=5 2021-11-18T19:55:14.354Z,1637265314.354 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T19:55:14.354Z,1637265314.354 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T19:56:14.553Z,1637265374.553 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T19:55:14.4Z 2021-11-18T19:56:14.553Z,1637265374.553 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T19:56:14.553Z,1637265374.553 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T19:56:15.839Z,1637265375.839 [DAT](INFO): #Outgoing data=1 2021-11-18T19:56:15.839Z,1637265375.839 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T19:56:15.935Z,1637265375.935 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T19:56:19.635Z,1637265379.635 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:55:42.1238 2021-11-18T19:56:19.636Z,1637265379.636 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T19:56:29.641Z,1637265389.641 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T19:56:29.641Z,1637265389.641 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T19:56:30.063Z,1637265390.063 [DAT](INFO): Sent 39 bytes from file Logs/20211118T193933/Courier0016.lzma.parts 2021-11-18T19:56:30.063Z,1637265390.063 [DAT](INFO): Packets left to send: 0 2021-11-18T19:56:30.066Z,1637265390.066 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T19:56:30.944Z,1637265390.944 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T19:56:30.944Z,1637265390.944 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T19:56:30.944Z,1637265390.944 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T19:57:31.124Z,1637265451.124 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T19:57:31.124Z,1637265451.124 [Default:CheckIn:C.Wait] Stopped 2021-11-18T19:57:31.124Z,1637265451.124 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T19:57:31.124Z,1637265451.124 [Default:CheckIn:D] Running Loop=1 2021-11-18T19:57:31.517Z,1637265451.517 [Default:CheckIn:D] Stopped 2021-11-18T19:57:31.517Z,1637265451.517 [Default:CheckIn:E] Running Loop=1 2021-11-18T19:57:31.914Z,1637265451.914 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 13.428967 min 2021-11-18T19:57:31.914Z,1637265451.914 [Default:CheckIn:E] Stopped 2021-11-18T19:57:31.914Z,1637265451.914 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T19:57:31.914Z,1637265451.914 [Default:CheckIn] Stopped 2021-11-18T19:57:31.914Z,1637265451.914 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T19:57:31.915Z,1637265451.915 [Default:CheckIn](INFO): Running loop #6 2021-11-18T19:57:31.915Z,1637265451.915 [Default:CheckIn] Running Loop=6 2021-11-18T19:57:31.915Z,1637265451.915 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T19:57:31.915Z,1637265451.915 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T19:57:50.487Z,1637265470.487 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6 2021-11-18T19:57:50.487Z,1637265470.487 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-11-18T19:57:50.523Z,1637265470.523 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-11-18T19:57:50.902Z,1637265470.902 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-11-18T19:57:50.902Z,1637265470.902 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6 2021-11-18T19:58:32.121Z,1637265512.121 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T19:57:31.9Z 2021-11-18T19:58:32.121Z,1637265512.121 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T19:58:32.121Z,1637265512.121 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T19:58:33.393Z,1637265513.393 [DAT](INFO): #Outgoing data=1 2021-11-18T19:58:33.393Z,1637265513.393 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T19:58:33.482Z,1637265513.482 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T19:58:36.831Z,1637265516.831 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:57:59.6716 2021-11-18T19:58:36.832Z,1637265516.832 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T19:58:47.711Z,1637265527.711 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T19:58:47.711Z,1637265527.711 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T19:58:47.801Z,1637265527.801 [DAT](INFO): Sent 39 bytes from file Logs/20211118T193933/Courier0019.lzma.parts 2021-11-18T19:58:47.801Z,1637265527.801 [DAT](INFO): Packets left to send: 0 2021-11-18T19:58:47.804Z,1637265527.804 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T19:58:48.687Z,1637265528.687 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T19:58:48.687Z,1637265528.687 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T19:58:48.687Z,1637265528.687 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T19:59:48.924Z,1637265588.924 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T19:59:48.924Z,1637265588.924 [Default:CheckIn:C.Wait] Stopped 2021-11-18T19:59:48.924Z,1637265588.924 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T19:59:48.924Z,1637265588.924 [Default:CheckIn:D] Running Loop=1 2021-11-18T19:59:49.334Z,1637265589.334 [Default:CheckIn:D] Stopped 2021-11-18T19:59:49.334Z,1637265589.334 [Default:CheckIn:E] Running Loop=1 2021-11-18T19:59:49.733Z,1637265589.733 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 15.725915 min 2021-11-18T19:59:49.733Z,1637265589.733 [Default:CheckIn:E] Stopped 2021-11-18T19:59:49.733Z,1637265589.733 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T19:59:49.733Z,1637265589.733 [Default:CheckIn] Stopped 2021-11-18T19:59:49.750Z,1637265589.750 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T19:59:49.750Z,1637265589.750 [Default:CheckIn](INFO): Running loop #7 2021-11-18T19:59:49.750Z,1637265589.750 [Default:CheckIn] Running Loop=7 2021-11-18T19:59:49.750Z,1637265589.750 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T19:59:49.750Z,1637265589.750 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T20:00:49.948Z,1637265649.948 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T19:59:49.8Z 2021-11-18T20:00:49.948Z,1637265649.948 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T20:00:49.948Z,1637265649.948 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T20:00:51.226Z,1637265651.226 [DAT](INFO): #Outgoing data=1 2021-11-18T20:00:51.226Z,1637265651.226 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:00:51.310Z,1637265651.310 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:00:51.356Z,1637265651.356 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 7 2021-11-18T20:00:51.356Z,1637265651.356 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-11-18T20:00:51.376Z,1637265651.376 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-11-18T20:00:51.694Z,1637265651.694 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-11-18T20:00:51.694Z,1637265651.694 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 7 2021-11-18T20:00:54.672Z,1637265654.672 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:00:17.4694 2021-11-18T20:00:54.673Z,1637265654.673 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:01:04.698Z,1637265664.698 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:01:04.699Z,1637265664.699 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:01:05.607Z,1637265665.607 [DAT](INFO): Sent 39 bytes from file Logs/20211118T193933/Courier0022.lzma.parts 2021-11-18T20:01:05.608Z,1637265665.608 [DAT](INFO): Packets left to send: 0 2021-11-18T20:01:05.610Z,1637265665.610 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:01:06.201Z,1637265666.201 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T20:01:06.201Z,1637265666.201 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T20:01:06.202Z,1637265666.202 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T20:01:09.055Z,1637265669.055 [NAL9602](FAULT): GPS failed to acquire within timeout. 2021-11-18T20:01:09.055Z,1637265669.055 [NAL9602] Data Fault, FailCount= 2 2021-11-18T20:01:09.055Z,1637265669.055 [NAL9602](ERROR): Data Fault 2021-11-18T20:01:09.074Z,1637265669.074 [CBIT](ERROR): Data Fault in component: NAL9602 2021-11-18T20:01:09.460Z,1637265669.460 [NAL9602](INFO): Powering down 2021-11-18T20:01:10.294Z,1637265670.294 [CBIT](INFO): Clearing failed state for component NAL9602 2021-11-18T20:01:10.294Z,1637265670.294 [NAL9602] No Fault, FailCount= 2 2021-11-18T20:01:39.759Z,1637265699.759 [NAL9602](INFO): Powering up NAL9602 2021-11-18T20:01:50.667Z,1637265710.667 [NAL9602](INFO): NAL9602 initialized 2021-11-18T20:02:06.442Z,1637265726.442 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T20:02:06.443Z,1637265726.443 [Default:CheckIn:C.Wait] Stopped 2021-11-18T20:02:06.443Z,1637265726.443 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T20:02:06.443Z,1637265726.443 [Default:CheckIn:D] Running Loop=1 2021-11-18T20:02:06.840Z,1637265726.840 [Default:CheckIn:D] Stopped 2021-11-18T20:02:06.841Z,1637265726.841 [Default:CheckIn:E] Running Loop=1 2021-11-18T20:02:07.240Z,1637265727.240 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 18.017698 min 2021-11-18T20:02:07.240Z,1637265727.240 [Default:CheckIn:E] Stopped 2021-11-18T20:02:07.240Z,1637265727.240 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T20:02:07.241Z,1637265727.241 [Default:CheckIn] Stopped 2021-11-18T20:02:07.241Z,1637265727.241 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T20:02:07.241Z,1637265727.241 [Default:CheckIn](INFO): Running loop #8 2021-11-18T20:02:07.241Z,1637265727.241 [Default:CheckIn] Running Loop=8 2021-11-18T20:02:07.241Z,1637265727.241 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T20:02:07.241Z,1637265727.241 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T20:03:07.440Z,1637265787.440 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T20:02:07.2Z 2021-11-18T20:03:07.440Z,1637265787.440 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T20:03:07.440Z,1637265787.440 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T20:03:08.751Z,1637265788.751 [DAT](INFO): #Outgoing data=1 2021-11-18T20:03:08.751Z,1637265788.751 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:03:08.842Z,1637265788.842 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:03:12.197Z,1637265792.197 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:02:35.0172 2021-11-18T20:03:12.197Z,1637265792.197 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:03:22.246Z,1637265802.246 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:03:22.247Z,1637265802.247 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:03:22.662Z,1637265802.662 [DAT](INFO): Sent 38 bytes from file Logs/20211118T193933/Courier0025.lzma.parts 2021-11-18T20:03:22.662Z,1637265802.662 [DAT](INFO): Packets left to send: 0 2021-11-18T20:03:22.665Z,1637265802.665 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:03:24.603Z,1637265804.603 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T20:03:24.603Z,1637265804.603 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T20:03:24.603Z,1637265804.603 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T20:03:52.169Z,1637265832.169 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 8 2021-11-18T20:03:52.169Z,1637265832.169 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-11-18T20:03:52.205Z,1637265832.205 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-11-18T20:03:52.567Z,1637265832.567 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-11-18T20:03:52.567Z,1637265832.567 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 8 2021-11-18T20:04:24.880Z,1637265864.880 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T20:04:24.880Z,1637265864.880 [Default:CheckIn:C.Wait] Stopped 2021-11-18T20:04:24.880Z,1637265864.880 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T20:04:24.880Z,1637265864.880 [Default:CheckIn:D] Running Loop=1 2021-11-18T20:04:25.305Z,1637265865.305 [Default:CheckIn:D] Stopped 2021-11-18T20:04:25.305Z,1637265865.305 [Default:CheckIn:E] Running Loop=1 2021-11-18T20:04:25.717Z,1637265865.717 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 20.325433 min 2021-11-18T20:04:25.717Z,1637265865.717 [Default:CheckIn:E] Stopped 2021-11-18T20:04:25.717Z,1637265865.717 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T20:04:25.717Z,1637265865.717 [Default:CheckIn] Stopped 2021-11-18T20:04:25.717Z,1637265865.717 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T20:04:25.718Z,1637265865.718 [Default:CheckIn](INFO): Running loop #9 2021-11-18T20:04:25.718Z,1637265865.718 [Default:CheckIn] Running Loop=9 2021-11-18T20:04:25.718Z,1637265865.718 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T20:04:25.718Z,1637265865.718 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T20:05:25.884Z,1637265925.884 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T20:04:25.7Z 2021-11-18T20:05:25.884Z,1637265925.884 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T20:05:25.885Z,1637265925.885 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T20:05:27.202Z,1637265927.202 [DAT](INFO): #Outgoing data=1 2021-11-18T20:05:27.202Z,1637265927.202 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:05:27.303Z,1637265927.303 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:05:30.872Z,1637265930.872 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:04:53.4651 2021-11-18T20:05:30.872Z,1637265930.872 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:05:41.355Z,1637265941.355 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:05:41.355Z,1637265941.355 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:05:41.438Z,1637265941.438 [DAT](INFO): Sent 39 bytes from file Logs/20211118T193933/Courier0028.lzma.parts 2021-11-18T20:05:41.438Z,1637265941.438 [DAT](INFO): Packets left to send: 0 2021-11-18T20:05:41.440Z,1637265941.440 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:05:42.330Z,1637265942.330 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T20:05:42.330Z,1637265942.330 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T20:05:42.330Z,1637265942.330 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T20:06:42.584Z,1637266002.584 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T20:06:42.584Z,1637266002.584 [Default:CheckIn:C.Wait] Stopped 2021-11-18T20:06:42.585Z,1637266002.585 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T20:06:42.585Z,1637266002.585 [Default:CheckIn:D] Running Loop=1 2021-11-18T20:06:42.983Z,1637266002.983 [Default:CheckIn:D] Stopped 2021-11-18T20:06:42.983Z,1637266002.983 [Default:CheckIn:E] Running Loop=1 2021-11-18T20:06:43.369Z,1637266003.369 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 22.620081 min 2021-11-18T20:06:43.369Z,1637266003.369 [Default:CheckIn:E] Stopped 2021-11-18T20:06:43.369Z,1637266003.369 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T20:06:43.370Z,1637266003.370 [Default:CheckIn] Stopped 2021-11-18T20:06:43.370Z,1637266003.370 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T20:06:43.370Z,1637266003.370 [Default:CheckIn](INFO): Running loop #10 2021-11-18T20:06:43.370Z,1637266003.370 [Default:CheckIn] Running Loop=10 2021-11-18T20:06:43.370Z,1637266003.370 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T20:06:43.370Z,1637266003.370 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T20:06:53.063Z,1637266013.063 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 9 2021-11-18T20:06:53.063Z,1637266013.063 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-11-18T20:06:53.091Z,1637266013.091 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-11-18T20:06:53.514Z,1637266013.514 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-11-18T20:06:53.514Z,1637266013.514 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 9 2021-11-18T20:07:43.568Z,1637266063.568 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T20:06:43.4Z 2021-11-18T20:07:43.568Z,1637266063.568 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T20:07:43.568Z,1637266063.568 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T20:07:44.879Z,1637266064.879 [DAT](INFO): #Outgoing data=1 2021-11-18T20:07:44.879Z,1637266064.879 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:07:44.987Z,1637266064.987 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:07:48.277Z,1637266068.277 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:07:11.1628 2021-11-18T20:07:48.278Z,1637266068.278 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:07:58.311Z,1637266078.311 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:07:58.311Z,1637266078.311 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:07:58.401Z,1637266078.401 [DAT](INFO): Sent 39 bytes from file Logs/20211118T193933/Courier0031.lzma.parts 2021-11-18T20:07:58.401Z,1637266078.401 [DAT](INFO): Packets left to send: 0 2021-11-18T20:07:58.404Z,1637266078.404 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:07:59.254Z,1637266079.254 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T20:07:59.254Z,1637266079.254 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T20:07:59.254Z,1637266079.254 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T20:08:59.485Z,1637266139.485 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T20:08:59.485Z,1637266139.485 [Default:CheckIn:C.Wait] Stopped 2021-11-18T20:08:59.485Z,1637266139.485 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T20:08:59.486Z,1637266139.486 [Default:CheckIn:D] Running Loop=1 2021-11-18T20:08:59.911Z,1637266139.911 [Default:CheckIn:D] Stopped 2021-11-18T20:08:59.911Z,1637266139.911 [Default:CheckIn:E] Running Loop=1 2021-11-18T20:09:00.313Z,1637266140.313 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 24.902214 min 2021-11-18T20:09:00.314Z,1637266140.314 [Default:CheckIn:E] Stopped 2021-11-18T20:09:00.314Z,1637266140.314 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T20:09:00.314Z,1637266140.314 [Default:CheckIn] Stopped 2021-11-18T20:09:00.314Z,1637266140.314 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T20:09:00.314Z,1637266140.314 [Default:CheckIn](INFO): Running loop #11 2021-11-18T20:09:00.314Z,1637266140.314 [Default:CheckIn] Running Loop=11 2021-11-18T20:09:00.314Z,1637266140.314 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T20:09:00.315Z,1637266140.315 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T20:09:54.023Z,1637266194.023 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 10 2021-11-18T20:09:54.024Z,1637266194.024 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-11-18T20:09:54.035Z,1637266194.035 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-11-18T20:09:54.446Z,1637266194.446 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-11-18T20:09:54.446Z,1637266194.446 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 10 2021-11-18T20:10:00.489Z,1637266200.489 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T20:09:00.3Z 2021-11-18T20:10:00.489Z,1637266200.489 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T20:10:00.489Z,1637266200.489 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T20:10:01.805Z,1637266201.805 [DAT](INFO): #Outgoing data=1 2021-11-18T20:10:01.805Z,1637266201.805 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:10:01.903Z,1637266201.903 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:10:05.792Z,1637266205.792 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:09:28.0607 2021-11-18T20:10:05.792Z,1637266205.792 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:10:16.184Z,1637266216.184 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:10:16.184Z,1637266216.184 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:10:16.337Z,1637266216.337 [DAT](INFO): Sent 39 bytes from file Logs/20211118T193933/Courier0034.lzma.parts 2021-11-18T20:10:16.337Z,1637266216.337 [DAT](INFO): Packets left to send: 0 2021-11-18T20:10:16.340Z,1637266216.340 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:10:17.858Z,1637266217.858 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T20:10:17.858Z,1637266217.858 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T20:10:17.858Z,1637266217.858 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T20:11:18.112Z,1637266278.112 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T20:11:18.112Z,1637266278.112 [Default:CheckIn:C.Wait] Stopped 2021-11-18T20:11:18.113Z,1637266278.113 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T20:11:18.113Z,1637266278.113 [Default:CheckIn:D] Running Loop=1 2021-11-18T20:11:18.531Z,1637266278.531 [Default:CheckIn:D] Stopped 2021-11-18T20:11:18.531Z,1637266278.531 [Default:CheckIn:E] Running Loop=1 2021-11-18T20:11:18.939Z,1637266278.939 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 27.212533 min 2021-11-18T20:11:18.939Z,1637266278.939 [Default:CheckIn:E] Stopped 2021-11-18T20:11:18.939Z,1637266278.939 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T20:11:18.939Z,1637266278.939 [Default:CheckIn] Stopped 2021-11-18T20:11:18.939Z,1637266278.939 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T20:11:18.939Z,1637266278.939 [Default:CheckIn](INFO): Running loop #12 2021-11-18T20:11:18.939Z,1637266278.939 [Default:CheckIn] Running Loop=12 2021-11-18T20:11:18.940Z,1637266278.940 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T20:11:18.940Z,1637266278.940 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T20:11:51.643Z,1637266311.643 [NAL9602](FAULT): GPS failed to acquire within timeout. 2021-11-18T20:11:51.643Z,1637266311.643 [NAL9602] Data Fault, FailCount= 3 2021-11-18T20:11:51.643Z,1637266311.643 [NAL9602](ERROR): Data Fault 2021-11-18T20:11:51.667Z,1637266311.667 [CBIT](ERROR): Data Fault in component: NAL9602 2021-11-18T20:11:52.039Z,1637266312.039 [NAL9602](INFO): Powering down 2021-11-18T20:11:52.874Z,1637266312.874 [CBIT](INFO): Clearing failed state for component NAL9602 2021-11-18T20:11:52.874Z,1637266312.874 [NAL9602] No Fault, FailCount= 3 2021-11-18T20:12:19.114Z,1637266339.114 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T20:11:18.9Z 2021-11-18T20:12:19.114Z,1637266339.114 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T20:12:19.114Z,1637266339.114 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T20:12:20.450Z,1637266340.450 [DAT](INFO): #Outgoing data=1 2021-11-18T20:12:20.451Z,1637266340.451 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:12:20.533Z,1637266340.533 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:12:22.099Z,1637266342.099 [NAL9602](INFO): Powering up NAL9602 2021-11-18T20:12:24.118Z,1637266344.118 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:11:46.7085 2021-11-18T20:12:24.118Z,1637266344.118 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:12:33.006Z,1637266353.006 [NAL9602](INFO): NAL9602 initialized 2021-11-18T20:12:34.239Z,1637266354.239 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:12:34.239Z,1637266354.239 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:12:34.623Z,1637266354.623 [DAT](INFO): Sent 39 bytes from file Logs/20211118T193933/Courier0037.lzma.parts 2021-11-18T20:12:34.623Z,1637266354.623 [DAT](INFO): Packets left to send: 0 2021-11-18T20:12:34.631Z,1637266354.631 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:12:35.577Z,1637266355.577 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T20:12:35.577Z,1637266355.577 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T20:12:35.578Z,1637266355.578 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T20:12:55.226Z,1637266375.226 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 11 2021-11-18T20:12:55.226Z,1637266375.226 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-11-18T20:12:55.238Z,1637266375.238 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-11-18T20:12:55.657Z,1637266375.657 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-11-18T20:12:55.657Z,1637266375.657 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 11 2021-11-18T20:13:36.018Z,1637266416.018 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T20:13:36.018Z,1637266416.018 [Default:CheckIn:C.Wait] Stopped 2021-11-18T20:13:36.018Z,1637266416.018 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T20:13:36.018Z,1637266416.018 [Default:CheckIn:D] Running Loop=1 2021-11-18T20:13:36.429Z,1637266416.429 [Default:CheckIn:D] Stopped 2021-11-18T20:13:36.429Z,1637266416.429 [Default:CheckIn:E] Running Loop=1 2021-11-18T20:13:36.841Z,1637266416.841 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 29.510838 min 2021-11-18T20:13:36.842Z,1637266416.842 [Default:CheckIn:E] Stopped 2021-11-18T20:13:36.842Z,1637266416.842 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T20:13:36.842Z,1637266416.842 [Default:CheckIn] Stopped 2021-11-18T20:13:36.842Z,1637266416.842 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T20:13:36.842Z,1637266416.842 [Default:CheckIn](INFO): Running loop #13 2021-11-18T20:13:36.842Z,1637266416.842 [Default:CheckIn] Running Loop=13 2021-11-18T20:13:36.842Z,1637266416.842 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T20:13:36.843Z,1637266416.843 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T20:14:37.028Z,1637266477.028 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T20:13:36.8Z 2021-11-18T20:14:37.028Z,1637266477.028 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T20:14:37.028Z,1637266477.028 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T20:14:38.339Z,1637266478.339 [DAT](INFO): #Outgoing data=1 2021-11-18T20:14:38.339Z,1637266478.339 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:14:38.447Z,1637266478.447 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:14:41.770Z,1637266481.770 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:14:04.6078 2021-11-18T20:14:41.770Z,1637266481.770 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:14:52.022Z,1637266492.022 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:14:52.022Z,1637266492.022 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:14:52.923Z,1637266492.923 [DAT](INFO): Sent 39 bytes from file Logs/20211118T193933/Courier0040.lzma.parts 2021-11-18T20:14:52.923Z,1637266492.923 [DAT](INFO): Packets left to send: 0 2021-11-18T20:14:52.926Z,1637266492.926 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:14:53.560Z,1637266493.560 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T20:14:53.560Z,1637266493.560 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T20:14:53.560Z,1637266493.560 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T20:15:53.820Z,1637266553.820 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T20:15:53.820Z,1637266553.820 [Default:CheckIn:C.Wait] Stopped 2021-11-18T20:15:53.820Z,1637266553.820 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T20:15:53.820Z,1637266553.820 [Default:CheckIn:D] Running Loop=1 2021-11-18T20:15:54.208Z,1637266554.208 [Default:CheckIn:D] Stopped 2021-11-18T20:15:54.208Z,1637266554.208 [Default:CheckIn:E] Running Loop=1 2021-11-18T20:15:54.633Z,1637266554.633 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 31.807151 min 2021-11-18T20:15:54.633Z,1637266554.633 [Default:CheckIn:E] Stopped 2021-11-18T20:15:54.633Z,1637266554.633 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T20:15:54.633Z,1637266554.633 [Default:CheckIn] Stopped 2021-11-18T20:15:54.633Z,1637266554.633 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T20:15:54.634Z,1637266554.634 [Default:CheckIn](INFO): Running loop #14 2021-11-18T20:15:54.634Z,1637266554.634 [Default:CheckIn] Running Loop=14 2021-11-18T20:15:54.634Z,1637266554.634 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T20:15:54.634Z,1637266554.634 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T20:15:56.250Z,1637266556.250 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 12 2021-11-18T20:15:56.250Z,1637266556.250 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-11-18T20:15:56.268Z,1637266556.268 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-11-18T20:15:56.660Z,1637266556.660 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-11-18T20:15:56.660Z,1637266556.660 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 12 2021-11-18T20:16:54.834Z,1637266614.834 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T20:15:54.6Z 2021-11-18T20:16:54.834Z,1637266614.834 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T20:16:54.834Z,1637266614.834 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T20:16:56.146Z,1637266616.146 [DAT](INFO): #Outgoing data=1 2021-11-18T20:16:56.146Z,1637266616.146 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:16:56.237Z,1637266616.237 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:16:59.583Z,1637266619.583 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:16:22.4042 2021-11-18T20:16:59.583Z,1637266619.583 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:17:09.864Z,1637266629.864 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:17:09.864Z,1637266629.864 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:17:10.319Z,1637266630.319 [DAT](INFO): Sent 39 bytes from file Logs/20211118T193933/Courier0043.lzma.parts 2021-11-18T20:17:10.319Z,1637266630.319 [DAT](INFO): Packets left to send: 0 2021-11-18T20:17:10.321Z,1637266630.321 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:17:13.059Z,1637266633.059 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T20:17:13.059Z,1637266633.059 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T20:17:13.059Z,1637266633.059 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T20:18:13.318Z,1637266693.318 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T20:18:13.318Z,1637266693.318 [Default:CheckIn:C.Wait] Stopped 2021-11-18T20:18:13.318Z,1637266693.318 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T20:18:13.319Z,1637266693.319 [Default:CheckIn:D] Running Loop=1 2021-11-18T20:18:13.715Z,1637266693.715 [Default:CheckIn:D] Stopped 2021-11-18T20:18:13.715Z,1637266693.715 [Default:CheckIn:E] Running Loop=1 2021-11-18T20:18:14.108Z,1637266694.108 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 34.132277 min 2021-11-18T20:18:14.109Z,1637266694.109 [Default:CheckIn:E] Stopped 2021-11-18T20:18:14.109Z,1637266694.109 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T20:18:14.109Z,1637266694.109 [Default:CheckIn] Stopped 2021-11-18T20:18:14.109Z,1637266694.109 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T20:18:14.109Z,1637266694.109 [Default:CheckIn](INFO): Running loop #15 2021-11-18T20:18:14.109Z,1637266694.109 [Default:CheckIn] Running Loop=15 2021-11-18T20:18:14.109Z,1637266694.109 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T20:18:14.110Z,1637266694.110 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T20:18:57.344Z,1637266737.344 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 13 2021-11-18T20:18:57.344Z,1637266737.344 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-11-18T20:18:57.364Z,1637266737.364 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-11-18T20:18:57.781Z,1637266737.781 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-11-18T20:18:57.781Z,1637266737.781 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 13 2021-11-18T20:19:14.313Z,1637266754.313 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T20:18:14.1Z 2021-11-18T20:19:14.313Z,1637266754.313 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T20:19:14.314Z,1637266754.314 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T20:19:15.643Z,1637266755.643 [DAT](INFO): #Outgoing data=1 2021-11-18T20:19:15.643Z,1637266755.643 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:19:15.747Z,1637266755.747 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:19:19.451Z,1637266759.451 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:18:41.9020 2021-11-18T20:19:19.452Z,1637266759.452 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:19:29.516Z,1637266769.516 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:19:29.516Z,1637266769.516 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:19:29.922Z,1637266769.922 [DAT](INFO): Sent 39 bytes from file Logs/20211118T193933/Courier0046.lzma.parts 2021-11-18T20:19:29.922Z,1637266769.922 [DAT](INFO): Packets left to send: 0 2021-11-18T20:19:29.925Z,1637266769.925 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:19:30.898Z,1637266770.898 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T20:19:30.899Z,1637266770.899 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T20:19:30.899Z,1637266770.899 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T20:20:31.038Z,1637266831.038 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T20:20:31.038Z,1637266831.038 [Default:CheckIn:C.Wait] Stopped 2021-11-18T20:20:31.038Z,1637266831.038 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T20:20:31.038Z,1637266831.038 [Default:CheckIn:D] Running Loop=1 2021-11-18T20:20:31.450Z,1637266831.450 [Default:CheckIn:D] Stopped 2021-11-18T20:20:31.450Z,1637266831.450 [Default:CheckIn:E] Running Loop=1 2021-11-18T20:20:31.835Z,1637266831.835 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 36.427580 min 2021-11-18T20:20:31.835Z,1637266831.835 [Default:CheckIn:E] Stopped 2021-11-18T20:20:31.835Z,1637266831.835 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T20:20:31.835Z,1637266831.835 [Default:CheckIn] Stopped 2021-11-18T20:20:31.836Z,1637266831.836 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T20:20:31.836Z,1637266831.836 [Default:CheckIn](INFO): Running loop #16 2021-11-18T20:20:31.836Z,1637266831.836 [Default:CheckIn] Running Loop=16 2021-11-18T20:20:31.836Z,1637266831.836 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T20:20:31.836Z,1637266831.836 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T20:21:32.047Z,1637266892.047 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T20:20:31.8Z 2021-11-18T20:21:32.047Z,1637266892.047 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T20:21:32.047Z,1637266892.047 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T20:21:33.333Z,1637266893.333 [DAT](INFO): #Outgoing data=1 2021-11-18T20:21:33.333Z,1637266893.333 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:21:33.418Z,1637266893.418 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:21:36.823Z,1637266896.823 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:20:59.5999 2021-11-18T20:21:36.823Z,1637266896.823 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:21:47.703Z,1637266907.703 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:21:47.703Z,1637266907.703 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:21:47.785Z,1637266907.785 [DAT](INFO): Sent 39 bytes from file Logs/20211118T193933/Courier0049.lzma.parts 2021-11-18T20:21:47.786Z,1637266907.786 [DAT](INFO): Packets left to send: 0 2021-11-18T20:21:47.788Z,1637266907.788 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:21:48.692Z,1637266908.692 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T20:21:48.692Z,1637266908.692 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T20:21:48.692Z,1637266908.692 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T20:21:58.432Z,1637266918.432 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 14 2021-11-18T20:21:58.432Z,1637266918.432 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-11-18T20:21:58.443Z,1637266918.443 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-11-18T20:21:58.855Z,1637266918.855 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-11-18T20:21:58.855Z,1637266918.855 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 14 2021-11-18T20:22:33.968Z,1637266953.968 [NAL9602](FAULT): GPS failed to acquire within timeout. 2021-11-18T20:22:33.968Z,1637266953.968 [NAL9602] Data Fault, FailCount= 4 2021-11-18T20:22:33.968Z,1637266953.968 [NAL9602](ERROR): Data Fault 2021-11-18T20:22:34.015Z,1637266954.015 [CBIT](ERROR): Data Fault in component: NAL9602 2021-11-18T20:22:34.367Z,1637266954.367 [NAL9602](INFO): Powering down 2021-11-18T20:22:35.202Z,1637266955.202 [CBIT](INFO): Clearing failed state for component NAL9602 2021-11-18T20:22:35.202Z,1637266955.202 [NAL9602] No Fault, FailCount= 4 2021-11-18T20:22:48.923Z,1637266968.923 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T20:22:48.924Z,1637266968.924 [Default:CheckIn:C.Wait] Stopped 2021-11-18T20:22:48.924Z,1637266968.924 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T20:22:48.924Z,1637266968.924 [Default:CheckIn:D] Running Loop=1 2021-11-18T20:22:49.328Z,1637266969.328 [Default:CheckIn:D] Stopped 2021-11-18T20:22:49.328Z,1637266969.328 [Default:CheckIn:E] Running Loop=1 2021-11-18T20:22:49.737Z,1637266969.737 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 38.725822 min 2021-11-18T20:22:49.737Z,1637266969.737 [Default:CheckIn:E] Stopped 2021-11-18T20:22:49.738Z,1637266969.738 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T20:22:49.738Z,1637266969.738 [Default:CheckIn] Stopped 2021-11-18T20:22:49.738Z,1637266969.738 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T20:22:49.738Z,1637266969.738 [Default:CheckIn](INFO): Running loop #17 2021-11-18T20:22:49.738Z,1637266969.738 [Default:CheckIn] Running Loop=17 2021-11-18T20:22:49.738Z,1637266969.738 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T20:22:49.738Z,1637266969.738 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T20:23:04.673Z,1637266984.673 [NAL9602](INFO): Powering up NAL9602 2021-11-18T20:23:15.576Z,1637266995.576 [NAL9602](INFO): NAL9602 initialized 2021-11-18T20:23:49.943Z,1637267029.943 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T20:22:49.7Z 2021-11-18T20:23:49.943Z,1637267029.943 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T20:23:49.943Z,1637267029.943 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T20:23:51.231Z,1637267031.231 [DAT](INFO): #Outgoing data=1 2021-11-18T20:23:51.231Z,1637267031.231 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:23:51.313Z,1637267031.313 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:23:54.925Z,1637267034.925 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:23:17.4977 2021-11-18T20:23:54.925Z,1637267034.925 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:24:05.431Z,1637267045.431 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:24:05.431Z,1637267045.431 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:24:05.525Z,1637267045.525 [DAT](INFO): Sent 39 bytes from file Logs/20211118T193933/Courier0052.lzma.parts 2021-11-18T20:24:05.525Z,1637267045.525 [DAT](INFO): Packets left to send: 0 2021-11-18T20:24:05.528Z,1637267045.528 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:24:06.452Z,1637267046.452 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T20:24:06.452Z,1637267046.452 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T20:24:06.452Z,1637267046.452 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T20:24:47.687Z,1637267087.687 [DropWeight](CRITICAL): DROP WEIGHT MISSING. 2021-11-18T20:24:47.687Z,1637267087.687 [DropWeight] Hardware Fault, FailCount= 1 2021-11-18T20:24:47.687Z,1637267087.687 [DropWeight](ERROR): Hardware Fault 2021-11-18T20:24:47.705Z,1637267087.705 [CBIT](INFO): Critical error at 20211118T202447 2021-11-18T20:24:47.723Z,1637267087.723 [CBIT](ERROR): Hardware Fault in component: DropWeight 2021-11-18T20:24:47.724Z,1637267087.724 [CBIT](CRITICAL): Hardware Fault in component: DropWeight 2021-11-18T20:24:48.140Z,1637267088.140 [CBIT](INFO): Critical error at 20211118T202447 2021-11-18T20:24:59.412Z,1637267099.412 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 15 2021-11-18T20:24:59.412Z,1637267099.412 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-11-18T20:24:59.423Z,1637267099.423 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-11-18T20:24:59.833Z,1637267099.833 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-11-18T20:24:59.834Z,1637267099.834 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 15 2021-11-18T20:25:06.707Z,1637267106.707 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T20:25:06.708Z,1637267106.708 [Default:CheckIn:C.Wait] Stopped 2021-11-18T20:25:06.708Z,1637267106.708 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T20:25:06.708Z,1637267106.708 [Default:CheckIn:D] Running Loop=1 2021-11-18T20:25:07.115Z,1637267107.115 [Default:CheckIn:D] Stopped 2021-11-18T20:25:07.115Z,1637267107.115 [Default:CheckIn:E] Running Loop=1 2021-11-18T20:25:07.492Z,1637267107.492 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 41.022270 min 2021-11-18T20:25:07.492Z,1637267107.492 [Default:CheckIn:E] Stopped 2021-11-18T20:25:07.493Z,1637267107.493 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T20:25:07.493Z,1637267107.493 [Default:CheckIn] Stopped 2021-11-18T20:25:07.493Z,1637267107.493 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T20:25:07.493Z,1637267107.493 [Default:CheckIn](INFO): Running loop #18 2021-11-18T20:25:07.493Z,1637267107.493 [Default:CheckIn] Running Loop=18 2021-11-18T20:25:07.493Z,1637267107.493 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T20:25:07.494Z,1637267107.494 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T20:26:07.693Z,1637267167.693 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T20:25:07.5Z 2021-11-18T20:26:07.693Z,1637267167.693 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T20:26:07.693Z,1637267167.693 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T20:26:08.983Z,1637267168.983 [DAT](INFO): #Outgoing data=1 2021-11-18T20:26:08.984Z,1637267168.984 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:26:09.095Z,1637267169.095 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:26:12.823Z,1637267172.823 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:25:35.3456 2021-11-18T20:26:12.824Z,1637267172.824 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:26:23.715Z,1637267183.715 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:26:23.715Z,1637267183.715 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:26:23.800Z,1637267183.800 [DAT](INFO): Sent 114 bytes from file Logs/20211118T193933/Courier0055.lzma.parts 2021-11-18T20:26:23.801Z,1637267183.801 [DAT](INFO): Packets left to send: 0 2021-11-18T20:26:23.803Z,1637267183.803 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:26:24.671Z,1637267184.671 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T20:26:24.671Z,1637267184.671 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T20:26:24.671Z,1637267184.671 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T20:27:24.914Z,1637267244.914 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T20:27:24.914Z,1637267244.914 [Default:CheckIn:C.Wait] Stopped 2021-11-18T20:27:24.914Z,1637267244.914 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T20:27:24.915Z,1637267244.915 [Default:CheckIn:D] Running Loop=1 2021-11-18T20:27:25.317Z,1637267245.317 [Default:CheckIn:D] Stopped 2021-11-18T20:27:25.317Z,1637267245.317 [Default:CheckIn:E] Running Loop=1 2021-11-18T20:27:25.721Z,1637267245.721 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 43.325643 min 2021-11-18T20:27:25.721Z,1637267245.721 [Default:CheckIn:E] Stopped 2021-11-18T20:27:25.721Z,1637267245.721 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T20:27:25.721Z,1637267245.721 [Default:CheckIn] Stopped 2021-11-18T20:27:25.721Z,1637267245.721 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T20:27:25.721Z,1637267245.721 [Default:CheckIn](INFO): Running loop #19 2021-11-18T20:27:25.722Z,1637267245.722 [Default:CheckIn] Running Loop=19 2021-11-18T20:27:25.722Z,1637267245.722 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T20:27:25.722Z,1637267245.722 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T20:28:00.473Z,1637267280.473 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 16 2021-11-18T20:28:00.473Z,1637267280.473 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-11-18T20:28:00.485Z,1637267280.485 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-11-18T20:28:00.882Z,1637267280.882 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-11-18T20:28:00.882Z,1637267280.882 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 16 2021-11-18T20:28:25.928Z,1637267305.928 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T20:27:25.7Z 2021-11-18T20:28:25.928Z,1637267305.928 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T20:28:25.928Z,1637267305.928 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T20:28:27.188Z,1637267307.188 [DAT](INFO): #Outgoing data=1 2021-11-18T20:28:27.189Z,1637267307.189 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:28:27.295Z,1637267307.295 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:28:31.003Z,1637267311.003 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:27:53.4435 2021-11-18T20:28:31.004Z,1637267311.004 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:28:41.427Z,1637267321.427 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:28:41.427Z,1637267321.427 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:28:41.831Z,1637267321.831 [DAT](INFO): Sent 39 bytes from file Logs/20211118T193933/Courier0058.lzma.parts 2021-11-18T20:28:41.831Z,1637267321.831 [DAT](INFO): Packets left to send: 0 2021-11-18T20:28:41.850Z,1637267321.850 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:28:42.699Z,1637267322.699 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T20:28:42.699Z,1637267322.699 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T20:28:42.699Z,1637267322.699 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T20:29:43.120Z,1637267383.120 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T20:29:43.120Z,1637267383.120 [Default:CheckIn:C.Wait] Stopped 2021-11-18T20:29:43.120Z,1637267383.120 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T20:29:43.120Z,1637267383.120 [Default:CheckIn:D] Running Loop=1 2021-11-18T20:29:43.533Z,1637267383.533 [Default:CheckIn:D] Stopped 2021-11-18T20:29:43.538Z,1637267383.538 [Default:CheckIn:E] Running Loop=1 2021-11-18T20:29:43.943Z,1637267383.943 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 45.629244 min 2021-11-18T20:29:43.943Z,1637267383.943 [Default:CheckIn:E] Stopped 2021-11-18T20:29:43.943Z,1637267383.943 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T20:29:43.943Z,1637267383.943 [Default:CheckIn] Stopped 2021-11-18T20:29:43.943Z,1637267383.943 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T20:29:43.944Z,1637267383.944 [Default:CheckIn](INFO): Running loop #20 2021-11-18T20:29:43.944Z,1637267383.944 [Default:CheckIn] Running Loop=20 2021-11-18T20:29:43.944Z,1637267383.944 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T20:29:43.944Z,1637267383.944 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T20:30:44.146Z,1637267444.146 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T20:29:43.9Z 2021-11-18T20:30:44.146Z,1637267444.146 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T20:30:44.146Z,1637267444.146 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T20:30:45.410Z,1637267445.410 [DAT](INFO): #Outgoing data=1 2021-11-18T20:30:45.410Z,1637267445.410 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:30:45.491Z,1637267445.491 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:30:48.839Z,1637267448.839 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:30:11.6415 2021-11-18T20:30:48.839Z,1637267448.839 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:30:59.233Z,1637267459.233 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:30:59.233Z,1637267459.233 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:30:59.663Z,1637267459.663 [DAT](INFO): Sent 39 bytes from file Logs/20211118T193933/Courier0061.lzma.parts 2021-11-18T20:30:59.663Z,1637267459.663 [DAT](INFO): Packets left to send: 0 2021-11-18T20:30:59.666Z,1637267459.666 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:31:00.542Z,1637267460.542 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T20:31:00.542Z,1637267460.542 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T20:31:00.542Z,1637267460.542 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T20:31:01.825Z,1637267461.825 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 17 2021-11-18T20:31:01.825Z,1637267461.825 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-11-18T20:31:01.837Z,1637267461.837 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-11-18T20:31:01.932Z,1637267461.932 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-11-18T20:31:01.932Z,1637267461.932 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 17 2021-11-18T20:32:02.091Z,1637267522.091 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T20:32:02.092Z,1637267522.092 [Default:CheckIn:C.Wait] Stopped 2021-11-18T20:32:02.092Z,1637267522.092 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T20:32:02.092Z,1637267522.092 [Default:CheckIn:D] Running Loop=1 2021-11-18T20:32:02.484Z,1637267522.484 [Default:CheckIn:D] Stopped 2021-11-18T20:32:02.484Z,1637267522.484 [Default:CheckIn:E] Running Loop=1 2021-11-18T20:32:02.891Z,1637267522.891 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 47.945085 min 2021-11-18T20:32:02.891Z,1637267522.891 [Default:CheckIn:E] Stopped 2021-11-18T20:32:02.891Z,1637267522.891 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T20:32:02.891Z,1637267522.891 [Default:CheckIn] Stopped 2021-11-18T20:32:02.891Z,1637267522.891 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T20:32:02.891Z,1637267522.891 [Default:CheckIn](INFO): Running loop #21 2021-11-18T20:32:02.892Z,1637267522.892 [Default:CheckIn] Running Loop=21 2021-11-18T20:32:02.892Z,1637267522.892 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T20:32:02.892Z,1637267522.892 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T20:33:03.081Z,1637267583.081 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T20:32:02.9Z 2021-11-18T20:33:03.081Z,1637267583.081 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T20:33:03.081Z,1637267583.081 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T20:33:04.346Z,1637267584.346 [DAT](INFO): #Outgoing data=1 2021-11-18T20:33:04.346Z,1637267584.346 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:33:04.434Z,1637267584.434 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:33:07.765Z,1637267587.765 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:32:30.5894 2021-11-18T20:33:07.765Z,1637267587.765 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:33:17.824Z,1637267597.824 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:33:17.824Z,1637267597.824 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:33:18.197Z,1637267598.197 [DAT](INFO): Sent 39 bytes from file Logs/20211118T193933/Courier0064.lzma.parts 2021-11-18T20:33:18.197Z,1637267598.197 [DAT](INFO): Packets left to send: 0 2021-11-18T20:33:18.200Z,1637267598.200 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:33:19.091Z,1637267599.091 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T20:33:19.091Z,1637267599.091 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T20:33:19.091Z,1637267599.091 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T20:33:21.082Z,1637267601.082 [NAL9602](FAULT): GPS failed to acquire within timeout. 2021-11-18T20:33:21.083Z,1637267601.083 [NAL9602] Data Fault, FailCount= 5 2021-11-18T20:33:21.083Z,1637267601.083 [NAL9602](ERROR): Data Fault 2021-11-18T20:33:21.134Z,1637267601.134 [CBIT](ERROR): Data Fault in component: NAL9602 2021-11-18T20:33:21.134Z,1637267601.134 [CBIT](CRITICAL): Data Fault in component: NAL9602 2021-11-18T20:33:21.483Z,1637267601.483 [NAL9602](INFO): Powering down 2021-11-18T20:33:21.500Z,1637267601.500 [CBIT](INFO): Critical error at 20211118T203321 2021-11-18T20:34:02.692Z,1637267642.692 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 18 2021-11-18T20:34:02.692Z,1637267642.692 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-11-18T20:34:02.703Z,1637267642.703 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-11-18T20:34:03.120Z,1637267643.120 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-11-18T20:34:03.120Z,1637267643.120 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 18 2021-11-18T20:34:19.262Z,1637267659.262 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T20:34:19.262Z,1637267659.262 [Default:CheckIn:C.Wait] Stopped 2021-11-18T20:34:19.262Z,1637267659.262 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T20:34:19.262Z,1637267659.262 [Default:CheckIn:D] Running Loop=1 2021-11-18T20:34:19.656Z,1637267659.656 [Default:CheckIn:D] Stopped 2021-11-18T20:34:19.656Z,1637267659.656 [Default:CheckIn:E] Running Loop=1 2021-11-18T20:34:20.059Z,1637267660.059 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 50.231295 min 2021-11-18T20:34:20.060Z,1637267660.060 [Default:CheckIn:E] Stopped 2021-11-18T20:34:20.060Z,1637267660.060 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T20:34:20.060Z,1637267660.060 [Default:CheckIn] Stopped 2021-11-18T20:34:20.060Z,1637267660.060 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T20:34:20.060Z,1637267660.060 [Default:CheckIn](INFO): Running loop #22 2021-11-18T20:34:20.060Z,1637267660.060 [Default:CheckIn] Running Loop=22 2021-11-18T20:34:20.060Z,1637267660.060 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T20:34:20.060Z,1637267660.060 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T20:35:20.255Z,1637267720.255 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T20:34:20.1Z 2021-11-18T20:35:20.255Z,1637267720.255 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T20:35:20.256Z,1637267720.256 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T20:35:21.571Z,1637267721.571 [DAT](INFO): #Outgoing data=1 2021-11-18T20:35:21.571Z,1637267721.571 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:35:21.589Z,1637267721.589 [CBIT](INFO): Clearing failed state for component NAL9602 2021-11-18T20:35:21.590Z,1637267721.590 [NAL9602] No Fault, FailCount= 5 2021-11-18T20:35:21.662Z,1637267721.662 [NAL9602](INFO): Powering up NAL9602 2021-11-18T20:35:21.665Z,1637267721.665 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:35:25.238Z,1637267725.238 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:34:47.8874 2021-11-18T20:35:25.238Z,1637267725.238 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:35:32.515Z,1637267732.515 [NAL9602](INFO): NAL9602 initialized 2021-11-18T20:35:35.345Z,1637267735.345 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:35:35.345Z,1637267735.345 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:35:35.779Z,1637267735.779 [DAT](INFO): Sent 81 bytes from file Logs/20211118T193933/Courier0067.lzma.parts 2021-11-18T20:35:35.779Z,1637267735.779 [DAT](INFO): Packets left to send: 0 2021-11-18T20:35:35.782Z,1637267735.782 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:35:36.713Z,1637267736.713 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T20:35:36.713Z,1637267736.713 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T20:35:36.714Z,1637267736.714 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T20:36:37.990Z,1637267797.990 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T20:36:37.990Z,1637267797.990 [Default:CheckIn:C.Wait] Stopped 2021-11-18T20:36:37.991Z,1637267797.991 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T20:36:37.991Z,1637267797.991 [Default:CheckIn:D] Running Loop=1 2021-11-18T20:36:38.409Z,1637267798.409 [Default:CheckIn:D] Stopped 2021-11-18T20:36:38.409Z,1637267798.409 [Default:CheckIn:E] Running Loop=1 2021-11-18T20:36:38.801Z,1637267798.801 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 52.543844 min 2021-11-18T20:36:38.801Z,1637267798.801 [Default:CheckIn:E] Stopped 2021-11-18T20:36:38.801Z,1637267798.801 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T20:36:38.801Z,1637267798.801 [Default:CheckIn] Stopped 2021-11-18T20:36:38.802Z,1637267798.802 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T20:36:38.802Z,1637267798.802 [Default:CheckIn](INFO): Running loop #23 2021-11-18T20:36:38.802Z,1637267798.802 [Default:CheckIn] Running Loop=23 2021-11-18T20:36:38.802Z,1637267798.802 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T20:36:38.802Z,1637267798.802 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T20:37:03.843Z,1637267823.843 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 19 2021-11-18T20:37:03.843Z,1637267823.843 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-11-18T20:37:03.878Z,1637267823.878 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-11-18T20:37:04.296Z,1637267824.296 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-11-18T20:37:04.296Z,1637267824.296 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 19 2021-11-18T20:37:38.997Z,1637267858.997 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T20:36:38.8Z 2021-11-18T20:37:38.997Z,1637267858.997 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T20:37:38.998Z,1637267858.998 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T20:37:40.288Z,1637267860.288 [DAT](INFO): #Outgoing data=1 2021-11-18T20:37:40.289Z,1637267860.289 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:37:40.383Z,1637267860.383 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:37:44.067Z,1637267864.067 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:37:06.5352 2021-11-18T20:37:44.068Z,1637267864.068 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:37:54.160Z,1637267874.160 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:37:54.160Z,1637267874.160 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:37:54.562Z,1637267874.562 [DAT](INFO): Sent 39 bytes from file Logs/20211118T193933/Courier0070.lzma.parts 2021-11-18T20:37:54.563Z,1637267874.563 [DAT](INFO): Packets left to send: 0 2021-11-18T20:37:54.565Z,1637267874.565 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:37:55.492Z,1637267875.492 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T20:37:55.492Z,1637267875.492 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T20:37:55.492Z,1637267875.492 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T20:38:55.955Z,1637267935.955 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T20:38:55.955Z,1637267935.955 [Default:CheckIn:C.Wait] Stopped 2021-11-18T20:38:55.955Z,1637267935.955 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T20:38:55.955Z,1637267935.955 [Default:CheckIn:D] Running Loop=1 2021-11-18T20:38:56.379Z,1637267936.379 [Default:CheckIn:D] Stopped 2021-11-18T20:38:56.379Z,1637267936.379 [Default:CheckIn:E] Running Loop=1 2021-11-18T20:38:56.753Z,1637267936.753 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 54.843339 min 2021-11-18T20:38:56.753Z,1637267936.753 [Default:CheckIn:E] Stopped 2021-11-18T20:38:56.753Z,1637267936.753 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T20:38:56.753Z,1637267936.753 [Default:CheckIn] Stopped 2021-11-18T20:38:56.753Z,1637267936.753 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T20:38:56.754Z,1637267936.754 [Default:CheckIn](INFO): Running loop #24 2021-11-18T20:38:56.754Z,1637267936.754 [Default:CheckIn] Running Loop=24 2021-11-18T20:38:56.754Z,1637267936.754 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T20:38:56.754Z,1637267936.754 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T20:39:47.704Z,1637267987.704 [CBIT](INFO): Clearing failed state for component DropWeight 2021-11-18T20:39:47.704Z,1637267987.704 [DropWeight] No Fault, FailCount= 1 2021-11-18T20:39:56.972Z,1637267996.972 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T20:38:56.8Z 2021-11-18T20:39:56.972Z,1637267996.972 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T20:39:56.973Z,1637267996.973 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T20:39:58.239Z,1637267998.239 [DAT](INFO): #Outgoing data=1 2021-11-18T20:39:58.240Z,1637267998.240 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:39:58.323Z,1637267998.323 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:40:01.669Z,1637268001.669 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:39:24.4832 2021-11-18T20:40:01.670Z,1637268001.670 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:40:04.683Z,1637268004.683 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 20 2021-11-18T20:40:04.683Z,1637268004.683 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-11-18T20:40:04.723Z,1637268004.723 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-11-18T20:40:04.723Z,1637268004.723 [CBIT](FAULT): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-11-18T20:40:12.471Z,1637268012.471 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:40:12.472Z,1637268012.472 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:40:12.597Z,1637268012.597 [DAT](INFO): Sent 39 bytes from file Logs/20211118T193933/Courier0073.lzma.parts 2021-11-18T20:40:12.597Z,1637268012.597 [DAT](INFO): Packets left to send: 0 2021-11-18T20:40:12.600Z,1637268012.600 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:40:14.049Z,1637268014.049 [DAT](INFO): #Outgoing data=1 2021-11-18T20:40:14.049Z,1637268014.049 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:40:14.163Z,1637268014.163 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:40:17.640Z,1637268017.640 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:39:40.4830 2021-11-18T20:40:17.640Z,1637268017.640 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:40:27.799Z,1637268027.799 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:40:27.799Z,1637268027.799 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:40:28.196Z,1637268028.196 [DAT](INFO): Sent 184 bytes from file Logs/20211118T193933/Courier9001.lzma.parts 2021-11-18T20:40:28.197Z,1637268028.197 [DAT](INFO): Packets left to send: 14 2021-11-18T20:40:28.201Z,1637268028.201 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:40:29.090Z,1637268029.090 [DAT](INFO): #Outgoing data=1 2021-11-18T20:40:29.090Z,1637268029.090 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:40:29.199Z,1637268029.199 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:40:32.903Z,1637268032.903 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:39:55.5328 2021-11-18T20:40:32.904Z,1637268032.904 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:40:43.395Z,1637268043.395 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:40:43.395Z,1637268043.395 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:40:43.481Z,1637268043.481 [DAT](INFO): Sent 184 bytes from file Logs/20211118T193933/Courier9001.lzma.parts 2021-11-18T20:40:43.481Z,1637268043.481 [DAT](INFO): Packets left to send: 13 2021-11-18T20:40:43.483Z,1637268043.483 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:40:44.371Z,1637268044.371 [DAT](INFO): #Outgoing data=1 2021-11-18T20:40:44.372Z,1637268044.372 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:40:44.471Z,1637268044.471 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:40:48.211Z,1637268048.211 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:40:10.7825 2021-11-18T20:40:48.211Z,1637268048.211 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:40:58.610Z,1637268058.610 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:40:58.610Z,1637268058.610 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:40:59.503Z,1637268059.503 [DAT](INFO): Sent 184 bytes from file Logs/20211118T193933/Courier9001.lzma.parts 2021-11-18T20:40:59.503Z,1637268059.503 [DAT](INFO): Packets left to send: 12 2021-11-18T20:40:59.505Z,1637268059.505 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:41:00.082Z,1637268060.082 [DAT](INFO): #Outgoing data=1 2021-11-18T20:41:00.083Z,1637268060.083 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:41:00.184Z,1637268060.184 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:41:04.299Z,1637268064.299 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:40:26.4823 2021-11-18T20:41:04.300Z,1637268064.300 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:41:14.322Z,1637268074.322 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:41:14.322Z,1637268074.322 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:41:14.751Z,1637268074.751 [DAT](INFO): Sent 184 bytes from file Logs/20211118T193933/Courier9001.lzma.parts 2021-11-18T20:41:14.751Z,1637268074.751 [DAT](INFO): Packets left to send: 11 2021-11-18T20:41:14.753Z,1637268074.753 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:41:15.614Z,1637268075.614 [DAT](INFO): #Outgoing data=1 2021-11-18T20:41:15.614Z,1637268075.614 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:41:15.715Z,1637268075.715 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:41:19.963Z,1637268079.963 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:40:42.0320 2021-11-18T20:41:19.964Z,1637268079.964 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:41:29.993Z,1637268089.993 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:41:29.993Z,1637268089.993 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:41:30.398Z,1637268090.398 [DAT](INFO): Sent 184 bytes from file Logs/20211118T193933/Courier9001.lzma.parts 2021-11-18T20:41:30.398Z,1637268090.398 [DAT](INFO): Packets left to send: 10 2021-11-18T20:41:30.400Z,1637268090.400 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:41:31.309Z,1637268091.309 [DAT](INFO): #Outgoing data=1 2021-11-18T20:41:31.309Z,1637268091.309 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:41:31.411Z,1637268091.411 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:41:35.147Z,1637268095.147 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:40:57.7318 2021-11-18T20:41:35.147Z,1637268095.147 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:41:45.515Z,1637268105.515 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:41:45.515Z,1637268105.515 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:41:45.917Z,1637268105.917 [DAT](INFO): Sent 184 bytes from file Logs/20211118T193933/Courier9001.lzma.parts 2021-11-18T20:41:45.917Z,1637268105.917 [DAT](INFO): Packets left to send: 9 2021-11-18T20:41:45.919Z,1637268105.919 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:41:46.834Z,1637268106.834 [DAT](INFO): #Outgoing data=1 2021-11-18T20:41:46.835Z,1637268106.835 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:41:46.943Z,1637268106.943 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:41:50.685Z,1637268110.685 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:41:13.2816 2021-11-18T20:41:50.685Z,1637268110.685 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:42:01.159Z,1637268121.159 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:42:01.159Z,1637268121.159 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:42:01.249Z,1637268121.249 [DAT](INFO): Sent 184 bytes from file Logs/20211118T193933/Courier9001.lzma.parts 2021-11-18T20:42:01.249Z,1637268121.249 [DAT](INFO): Packets left to send: 8 2021-11-18T20:42:01.251Z,1637268121.251 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:42:02.126Z,1637268122.126 [DAT](INFO): #Outgoing data=1 2021-11-18T20:42:02.127Z,1637268122.127 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:42:02.223Z,1637268122.223 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:42:05.589Z,1637268125.589 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:41:28.5313 2021-11-18T20:42:05.590Z,1637268125.590 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:42:15.955Z,1637268135.955 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:42:15.955Z,1637268135.955 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:42:16.347Z,1637268136.347 [DAT](INFO): Sent 184 bytes from file Logs/20211118T193933/Courier9001.lzma.parts 2021-11-18T20:42:16.347Z,1637268136.347 [DAT](INFO): Packets left to send: 7 2021-11-18T20:42:16.349Z,1637268136.349 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:42:17.728Z,1637268137.728 [DAT](INFO): #Outgoing data=1 2021-11-18T20:42:17.728Z,1637268137.728 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:42:17.829Z,1637268137.829 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:42:21.419Z,1637268141.419 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:41:44.1310 2021-11-18T20:42:21.419Z,1637268141.419 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:42:31.515Z,1637268151.515 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:42:31.515Z,1637268151.515 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:42:31.912Z,1637268151.912 [DAT](INFO): Sent 184 bytes from file Logs/20211118T193933/Courier9001.lzma.parts 2021-11-18T20:42:31.913Z,1637268151.913 [DAT](INFO): Packets left to send: 6 2021-11-18T20:42:31.914Z,1637268151.914 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:42:32.803Z,1637268152.803 [DAT](INFO): #Outgoing data=1 2021-11-18T20:42:32.803Z,1637268152.803 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:42:32.915Z,1637268152.915 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:42:36.655Z,1637268156.655 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:41:59.2308 2021-11-18T20:42:36.655Z,1637268156.655 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:42:46.783Z,1637268166.783 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:42:46.783Z,1637268166.783 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:42:47.191Z,1637268167.191 [DAT](INFO): Sent 184 bytes from file Logs/20211118T193933/Courier9001.lzma.parts 2021-11-18T20:42:47.191Z,1637268167.191 [DAT](INFO): Packets left to send: 5 2021-11-18T20:42:47.229Z,1637268167.229 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:42:48.075Z,1637268168.075 [DAT](INFO): #Outgoing data=1 2021-11-18T20:42:48.075Z,1637268168.075 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:42:48.158Z,1637268168.158 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:42:51.891Z,1637268171.891 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:42:14.4806 2021-11-18T20:42:51.892Z,1637268171.892 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:43:01.979Z,1637268181.979 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:43:01.979Z,1637268181.979 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:43:02.375Z,1637268182.375 [DAT](INFO): Sent 184 bytes from file Logs/20211118T193933/Courier9001.lzma.parts 2021-11-18T20:43:02.375Z,1637268182.375 [DAT](INFO): Packets left to send: 4 2021-11-18T20:43:02.376Z,1637268182.376 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:43:03.746Z,1637268183.746 [DAT](INFO): #Outgoing data=1 2021-11-18T20:43:03.746Z,1637268183.746 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:43:03.837Z,1637268183.837 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:43:07.943Z,1637268187.943 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:42:30.1303 2021-11-18T20:43:07.944Z,1637268187.944 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:43:18.008Z,1637268198.008 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:43:18.008Z,1637268198.008 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:43:18.413Z,1637268198.413 [DAT](INFO): Sent 184 bytes from file Logs/20211118T193933/Courier9001.lzma.parts 2021-11-18T20:43:18.414Z,1637268198.414 [DAT](INFO): Packets left to send: 3 2021-11-18T20:43:18.415Z,1637268198.415 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:43:19.320Z,1637268199.320 [DAT](INFO): #Outgoing data=1 2021-11-18T20:43:19.321Z,1637268199.321 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:43:19.413Z,1637268199.413 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:43:23.162Z,1637268203.162 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:42:45.7314 2021-11-18T20:43:23.162Z,1637268203.162 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:43:33.215Z,1637268213.215 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:43:33.215Z,1637268213.215 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:43:33.305Z,1637268213.305 [DAT](INFO): Sent 184 bytes from file Logs/20211118T193933/Courier9001.lzma.parts 2021-11-18T20:43:33.305Z,1637268213.305 [DAT](INFO): Packets left to send: 2 2021-11-18T20:43:33.307Z,1637268213.307 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:43:34.146Z,1637268214.146 [DAT](INFO): #Outgoing data=1 2021-11-18T20:43:34.146Z,1637268214.146 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:43:34.247Z,1637268214.247 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:43:37.983Z,1637268217.983 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:43:00.5798 2021-11-18T20:43:37.984Z,1637268217.984 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:43:48.193Z,1637268228.193 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:43:48.193Z,1637268228.193 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:43:48.605Z,1637268228.605 [DAT](INFO): Sent 184 bytes from file Logs/20211118T193933/Courier9001.lzma.parts 2021-11-18T20:43:48.605Z,1637268228.605 [DAT](INFO): Packets left to send: 1 2021-11-18T20:43:48.615Z,1637268228.615 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:43:49.758Z,1637268229.758 [DAT](INFO): #Outgoing data=1 2021-11-18T20:43:49.758Z,1637268229.758 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:43:49.868Z,1637268229.868 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:43:53.041Z,1637268233.041 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:43:15.9795 2021-11-18T20:43:53.041Z,1637268233.041 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:44:03.127Z,1637268243.127 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:44:03.127Z,1637268243.127 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:44:03.209Z,1637268243.209 [DAT](INFO): Sent 7 bytes from file Logs/20211118T193933/Courier9001.lzma.parts 2021-11-18T20:44:03.209Z,1637268243.209 [DAT](INFO): Packets left to send: 0 2021-11-18T20:44:03.212Z,1637268243.212 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:44:04.115Z,1637268244.115 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T20:44:04.115Z,1637268244.115 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T20:44:04.115Z,1637268244.115 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T20:45:04.347Z,1637268304.347 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T20:45:04.347Z,1637268304.347 [Default:CheckIn:C.Wait] Stopped 2021-11-18T20:45:04.348Z,1637268304.348 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T20:45:04.348Z,1637268304.348 [Default:CheckIn:D] Running Loop=1 2021-11-18T20:45:04.760Z,1637268304.760 [Default:CheckIn:D] Stopped 2021-11-18T20:45:04.760Z,1637268304.760 [Default:CheckIn:E] Running Loop=1 2021-11-18T20:45:05.170Z,1637268305.170 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 60.983016 min 2021-11-18T20:45:05.171Z,1637268305.171 [Default:CheckIn:E] Stopped 2021-11-18T20:45:05.171Z,1637268305.171 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T20:45:05.171Z,1637268305.171 [Default:CheckIn] Stopped 2021-11-18T20:45:05.171Z,1637268305.171 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T20:45:05.171Z,1637268305.171 [Default:CheckIn](INFO): Running loop #25 2021-11-18T20:45:05.171Z,1637268305.171 [Default:CheckIn] Running Loop=25 2021-11-18T20:45:05.171Z,1637268305.171 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T20:45:05.171Z,1637268305.171 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T20:45:33.428Z,1637268333.428 [NAL9602](FAULT): GPS failed to acquire within timeout. 2021-11-18T20:45:33.428Z,1637268333.428 [NAL9602] Data Fault, FailCount= 1 2021-11-18T20:45:33.428Z,1637268333.428 [NAL9602](ERROR): Data Fault 2021-11-18T20:45:33.498Z,1637268333.498 [CBIT](ERROR): Data Fault in component: NAL9602 2021-11-18T20:45:33.831Z,1637268333.831 [NAL9602](INFO): Powering down 2021-11-18T20:45:34.669Z,1637268334.669 [CBIT](INFO): Clearing failed state for component NAL9602 2021-11-18T20:45:34.669Z,1637268334.669 [NAL9602] No Fault, FailCount= 1 2021-11-18T20:46:04.135Z,1637268364.135 [NAL9602](INFO): Powering up NAL9602 2021-11-18T20:46:05.351Z,1637268365.351 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T20:45:05.2Z 2021-11-18T20:46:05.351Z,1637268365.351 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T20:46:05.351Z,1637268365.351 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T20:46:06.643Z,1637268366.643 [DAT](INFO): #Outgoing data=1 2021-11-18T20:46:06.644Z,1637268366.644 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:46:06.739Z,1637268366.739 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:46:10.322Z,1637268370.322 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:45:32.9275 2021-11-18T20:46:10.322Z,1637268370.322 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:46:15.159Z,1637268375.159 [NAL9602](INFO): NAL9602 initialized 2021-11-18T20:46:20.590Z,1637268380.590 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:46:20.591Z,1637268380.591 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:46:20.991Z,1637268380.991 [DAT](INFO): Sent 39 bytes from file Logs/20211118T193933/Courier0076.lzma.parts 2021-11-18T20:46:20.991Z,1637268380.991 [DAT](INFO): Packets left to send: 0 2021-11-18T20:46:20.994Z,1637268380.994 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:46:21.921Z,1637268381.921 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T20:46:21.922Z,1637268381.922 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T20:46:21.922Z,1637268381.922 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T20:47:22.151Z,1637268442.151 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T20:47:22.151Z,1637268442.151 [Default:CheckIn:C.Wait] Stopped 2021-11-18T20:47:22.152Z,1637268442.152 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T20:47:22.152Z,1637268442.152 [Default:CheckIn:D] Running Loop=1 2021-11-18T20:47:22.566Z,1637268442.566 [Default:CheckIn:D] Stopped 2021-11-18T20:47:22.566Z,1637268442.566 [Default:CheckIn:E] Running Loop=1 2021-11-18T20:47:22.984Z,1637268442.984 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 63.279781 min 2021-11-18T20:47:22.984Z,1637268442.984 [Default:CheckIn:E] Stopped 2021-11-18T20:47:22.984Z,1637268442.984 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T20:47:22.984Z,1637268442.984 [Default:CheckIn] Stopped 2021-11-18T20:47:22.984Z,1637268442.984 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T20:47:22.984Z,1637268442.984 [Default:CheckIn](INFO): Running loop #26 2021-11-18T20:47:22.985Z,1637268442.985 [Default:CheckIn] Running Loop=26 2021-11-18T20:47:22.985Z,1637268442.985 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T20:47:22.985Z,1637268442.985 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T20:48:23.184Z,1637268503.184 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-18T20:47:22.0Z 2021-11-18T20:48:23.184Z,1637268503.184 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T20:48:23.184Z,1637268503.184 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-18T20:48:25.912Z,1637268505.912 [DAT](INFO): #Outgoing data=1 2021-11-18T20:48:25.912Z,1637268505.912 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-18T20:48:26.139Z,1637268506.139 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-18T20:48:29.863Z,1637268509.863 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:47:52.3252 2021-11-18T20:48:29.864Z,1637268509.864 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-18T20:48:39.870Z,1637268519.870 [DAT](FAULT): Ack receipt timeout failure. 2021-11-18T20:48:39.870Z,1637268519.870 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2021-11-18T20:48:40.243Z,1637268520.243 [DAT](INFO): Sent 39 bytes from file Logs/20211118T193933/Courier0079.lzma.parts 2021-11-18T20:48:40.243Z,1637268520.243 [DAT](INFO): Packets left to send: 0 2021-11-18T20:48:40.246Z,1637268520.246 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-18T20:48:42.458Z,1637268522.458 [Default:CheckIn:Read_Iridium] Stopped 2021-11-18T20:48:42.458Z,1637268522.458 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-18T20:48:42.458Z,1637268522.458 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-18T20:49:42.744Z,1637268582.744 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-18T20:49:42.744Z,1637268582.744 [Default:CheckIn:C.Wait] Stopped 2021-11-18T20:49:42.744Z,1637268582.744 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-18T20:49:42.744Z,1637268582.744 [Default:CheckIn:D] Running Loop=1 2021-11-18T20:49:43.147Z,1637268583.147 [Default:CheckIn:D] Stopped 2021-11-18T20:49:43.147Z,1637268583.147 [Default:CheckIn:E] Running Loop=1 2021-11-18T20:49:43.555Z,1637268583.555 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 65.622811 min 2021-11-18T20:49:43.555Z,1637268583.555 [Default:CheckIn:E] Stopped 2021-11-18T20:49:43.555Z,1637268583.555 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-18T20:49:43.555Z,1637268583.555 [Default:CheckIn] Stopped 2021-11-18T20:49:43.556Z,1637268583.556 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T20:49:43.556Z,1637268583.556 [Default:CheckIn](INFO): Running loop #27 2021-11-18T20:49:43.556Z,1637268583.556 [Default:CheckIn] Running Loop=27 2021-11-18T20:49:43.556Z,1637268583.556 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-18T20:49:43.556Z,1637268583.556 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-18T20:50:27.875Z,1637268627.875 [CommandExec](IMPORTANT): got command restart application 2021-11-18T20:50:28.878Z,1637268628.878 [CommandExec ThreadHandler](INFO): Uninitializing protected caller thread. 2021-11-18T20:50:28.878Z,1637268628.878 [CommandExec](INFO): Uninitializing the command executive. 2021-11-18T20:50:28.878Z,1637268628.878 [CommandExec](INFO): Uninitializing the command scheduler. 2021-11-18T20:50:28.878Z,1637268628.878 [CommandExec ThreadHandler](INFO): Thread cancelled. 2021-11-18T20:50:28.930Z,1637268628.930 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2021-11-18T20:50:28.931Z,1637268628.931 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2021-11-18T20:50:28.931Z,1637268628.931 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2021-11-18T20:50:28.932Z,1637268628.932 [NavChartDb](INFO): Join timeout helper Thread ID is 1087 2021-11-18T20:50:29.034Z,1637268629.034 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2021-11-18T20:50:29.034Z,1637268629.034 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2021-11-18T20:50:29.050Z,1637268629.050 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler 2021-11-18T20:50:29.050Z,1637268629.050 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2021-11-18T20:50:29.051Z,1637268629.051 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 1088 2021-11-18T20:50:29.490Z,1637268629.490 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread. 2021-11-18T20:50:29.490Z,1637268629.490 [WetLabsBB2FL](INFO): Powering down 2021-11-18T20:50:29.491Z,1637268629.491 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2021-11-18T20:50:29.502Z,1637268629.502 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler 2021-11-18T20:50:29.502Z,1637268629.502 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2021-11-18T20:50:29.502Z,1637268629.502 [CTD_Seabird](INFO): Join timeout helper Thread ID is 1089 2021-11-18T20:50:30.022Z,1637268630.022 [CTD_Seabird](INFO): Powering down 2021-11-18T20:50:30.034Z,1637268630.034 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread. 2021-11-18T20:50:30.034Z,1637268630.034 [CTD_Seabird](INFO): Powering down 2021-11-18T20:50:30.046Z,1637268630.046 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2021-11-18T20:50:30.063Z,1637268630.063 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2021-11-18T20:50:30.064Z,1637268630.064 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2021-11-18T20:50:30.064Z,1637268630.064 [Radio_Surface](INFO): Join timeout helper Thread ID is 1090 2021-11-18T20:50:30.142Z,1637268630.142 [Radio_Surface](INFO): Powering down 2021-11-18T20:50:30.143Z,1637268630.143 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2021-11-18T20:50:30.143Z,1637268630.143 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2021-11-18T20:50:30.170Z,1637268630.170 [ComponentRegistry](INFO): Shutting down Onboard ThreadHandler 2021-11-18T20:50:30.170Z,1637268630.170 [Onboard ThreadHandler](INFO): Thread cancelled. 2021-11-18T20:50:30.171Z,1637268630.171 [Onboard](INFO): Join timeout helper Thread ID is 1091 2021-11-18T20:50:31.914Z,1637268631.914 [Onboard ThreadHandler](INFO): Uninitializing protected caller thread. 2021-11-18T20:50:31.914Z,1637268631.914 [Onboard ThreadHandler](INFO): Thread cancelled. 2021-11-18T20:50:31.919Z,1637268631.919 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2021-11-18T20:50:31.919Z,1637268631.919 [logger ThreadHandler](INFO): Thread cancelled. 2021-11-18T20:50:31.919Z,1637268631.919 [logger](INFO): Join timeout helper Thread ID is 1092 2021-11-18T20:50:31.926Z,1637268631.926 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2021-11-18T20:50:31.926Z,1637268631.926 [logger ThreadHandler](INFO): Thread cancelled. 2021-11-18T20:50:31.938Z,1637268631.938 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2021-11-18T20:50:31.938Z,1637268631.938 [CommandLine ThreadHandler](INFO): Thread cancelled. 2021-11-18T20:50:31.939Z,1637268631.939 [CommandLine](INFO): Join timeout helper Thread ID is 1093 2021-11-18T20:50:31.958Z,1637268631.958 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2021-11-18T20:50:31.958Z,1637268631.958 [CommandLine ThreadHandler](INFO): Thread cancelled. 2021-11-18T20:50:31.978Z,1637268631.978 [ComponentRegistry](INFO): Shutting down CommandExec ThreadHandler 2021-11-18T20:50:31.978Z,1637268631.978 [CommandExec ThreadHandler](INFO): Thread cancelled. 2021-11-18T20:50:31.979Z,1637268631.979 [CommandExec](INFO): Join timeout helper Thread ID is 1094 2021-11-18T20:50:31.980Z,1637268631.980 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2021-11-18T20:50:31.980Z,1637268631.980 [controlThread ThreadHandler](INFO): Thread cancelled. 2021-11-18T20:50:31.980Z,1637268631.980 [controlThread](INFO): Join timeout helper Thread ID is 1095 2021-11-18T20:50:32.006Z,1637268632.006 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2021-11-18T20:50:32.006Z,1637268632.006 [controlThread](DEBUG): Uninitializing ControlThread 2021-11-18T20:50:32.006Z,1637268632.006 [AHRS_M2](INFO): Powering down 2021-11-18T20:50:32.079Z,1637268632.079 [NAL9602](INFO): Powering down 2021-11-18T20:50:32.080Z,1637268632.080 [DAT](INFO): Powering down 2021-11-18T20:50:32.199Z,1637268632.199 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator. 2021-11-18T20:50:32.200Z,1637268632.200 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2021-11-18T20:50:32.201Z,1637268632.201 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2021-11-18T20:50:32.201Z,1637268632.201 [MissionManager](INFO): Uninitializing Mission Default 2021-11-18T20:50:32.202Z,1637268632.202 [Default] Stopped 2021-11-18T20:50:32.202Z,1637268632.202 [Default](DEBUG): Aggregate::uninitialize Default 2021-11-18T20:50:32.202Z,1637268632.202 [Default:B.GoToSurface] Stopped 2021-11-18T20:50:32.202Z,1637268632.202 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2021-11-18T20:50:32.202Z,1637268632.202 [Default:CheckIn] Stopped 2021-11-18T20:50:32.202Z,1637268632.202 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-18T20:50:32.202Z,1637268632.202 [Default:CheckIn:Read_GPS] Stopped 2021-11-18T20:50:32.206Z,1637268632.206 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2021-11-18T20:50:32.206Z,1637268632.206 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2021-11-18T20:50:32.206Z,1637268632.206 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2021-11-18T20:50:32.207Z,1637268632.207 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2021-11-18T20:50:32.207Z,1637268632.207 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2021-11-18T20:50:32.207Z,1637268632.207 [BuoyancyServo](INFO): Powering down 2021-11-18T20:50:32.222Z,1637268632.222 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2021-11-18T20:50:32.222Z,1637268632.222 [ElevatorServo](INFO): Powering down 2021-11-18T20:50:32.223Z,1637268632.223 [MassServo](DEBUG): Uninitialize Mass Servo. 2021-11-18T20:50:32.223Z,1637268632.223 [MassServo](INFO): Powering down 2021-11-18T20:50:32.224Z,1637268632.224 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2021-11-18T20:50:32.224Z,1637268632.224 [RudderServo](INFO): Powering down 2021-11-18T20:50:32.225Z,1637268632.225 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2021-11-18T20:50:32.225Z,1637268632.225 [ThrusterServo](INFO): Powering down 2021-11-18T20:50:32.226Z,1637268632.226 [SBIT](DEBUG): Uninitialize SBIT Component. 2021-11-18T20:50:32.226Z,1637268632.226 [IBIT](DEBUG): Uninitialize IBIT Component. 2021-11-18T20:50:32.226Z,1637268632.226 [CBIT](DEBUG): Uninitialize CBIT Component. 2021-11-18T20:50:32.227Z,1637268632.227 [CBIT](DEBUG): Powering off loads. 2021-11-18T20:50:32.238Z,1637268632.238 [CBIT](DEBUG): Disabling WDT. 2021-11-18T20:50:32.249Z,1637268632.249 [CBIT](DEBUG): Opening all GF detection circuits. 2021-11-18T20:50:32.250Z,1637268632.250 [controlThread ThreadHandler](INFO): Thread cancelled. 2021-11-18T20:50:32.307Z,1637268632.307 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2021-11-18T20:50:32.310Z,1637268632.310 [Onboard ThreadHandler](INFO): Thread cancelled. 2021-11-18T20:50:32.385Z,1637268632.385 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2021-11-18T20:50:32.389Z,1637268632.389 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2021-11-18T20:50:32.436Z,1637268632.436 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2021-11-18T20:50:32.498Z,1637268632.498 [logger ThreadHandler](INFO): Thread cancelled.