2021-11-29T17:38:40.421Z,1638207520.421 [Supervisor](DEBUG): Initializing supervisor.
2021-11-29T17:38:40.425Z,1638207520.425 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2021-11-29T17:38:40.426Z,1638207520.426 [SyncHandler](INFO): Protected caller Thread ID is 833
2021-11-29T17:38:40.426Z,1638207520.426 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2021-11-29T17:38:40.427Z,1638207520.427 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2021-11-29T17:38:40.428Z,1638207520.428 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 834
2021-11-29T17:38:40.432Z,1638207520.432 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2021-11-29T17:38:40.450Z,1638207520.450 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread.
2021-11-29T17:38:40.451Z,1638207520.451 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2021-11-29T17:38:40.451Z,1638207520.451 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 835
2021-11-29T17:38:40.455Z,1638207520.455 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2021-11-29T17:38:40.456Z,1638207520.456 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2021-11-29T17:38:40.457Z,1638207520.457 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 836
2021-11-29T17:38:40.459Z,1638207520.459 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2021-11-29T17:38:40.460Z,1638207520.460 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0
2021-11-29T17:38:40.460Z,1638207520.460 [logger ThreadHandler](INFO): Protected caller Thread ID is 837
2021-11-29T17:38:40.464Z,1638207520.464 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2021-11-29T17:38:40.465Z,1638207520.465 [Supervisor](INFO): Looking for Config files in directory: Config/
2021-11-29T17:38:40.469Z,1638207520.469 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2021-11-29T17:38:40.694Z,1638207520.694 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2021-11-29T17:38:40.696Z,1638207520.696 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2021-11-29T17:38:40.776Z,1638207520.776 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2021-11-29T17:38:41.275Z,1638207521.275 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2021-11-29T17:38:41.277Z,1638207521.277 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2021-11-29T17:38:41.597Z,1638207521.597 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2021-11-29T17:38:41.599Z,1638207521.599 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2021-11-29T17:38:41.695Z,1638207521.695 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2021-11-29T17:38:41.695Z,1638207521.695 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2021-11-29T17:38:42.052Z,1638207522.052 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2021-11-29T17:38:42.054Z,1638207522.053 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2021-11-29T17:38:42.246Z,1638207522.246 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2021-11-29T17:38:42.247Z,1638207522.247 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2021-11-29T17:38:42.692Z,1638207522.692 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2021-11-29T17:38:42.694Z,1638207522.694 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2021-11-29T17:38:42.820Z,1638207522.820 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2021-11-29T17:38:42.822Z,1638207522.822 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2021-11-29T17:38:42.902Z,1638207522.902 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2021-11-29T17:38:43.554Z,1638207523.554 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2021-11-29T17:38:43.554Z,1638207523.554 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2021-11-29T17:38:43.925Z,1638207523.925 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2021-11-29T17:38:43.925Z,1638207523.925 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2021-11-29T17:38:44.829Z,1638207524.829 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2021-11-29T17:38:44.831Z,1638207524.831 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2021-11-29T17:38:44.940Z,1638207524.940 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2021-11-29T17:38:44.942Z,1638207524.942 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2021-11-29T17:38:45.095Z,1638207525.095 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2021-11-29T17:38:45.096Z,1638207525.096 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2021-11-29T17:38:45.318Z,1638207525.318 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2021-11-29T17:38:45.320Z,1638207525.320 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2021-11-29T17:38:45.323Z,1638207525.323 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2021-11-29T17:38:45.414Z,1638207525.414 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2021-11-29T17:38:45.499Z,1638207525.499 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2021-11-29T17:38:45.599Z,1638207525.599 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2021-11-29T17:38:45.683Z,1638207525.683 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2021-11-29T17:38:45.777Z,1638207525.777 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2021-11-29T17:38:45.877Z,1638207525.877 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2021-11-29T17:38:46.058Z,1638207526.058 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2021-11-29T17:38:46.136Z,1638207526.136 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2021-11-29T17:38:46.280Z,1638207526.280 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2021-11-29T17:38:46.415Z,1638207526.415 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2021-11-29T17:38:46.529Z,1638207526.529 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg
2021-11-29T17:38:46.786Z,1638207526.786 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2021-11-29T17:38:46.787Z,1638207526.787 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2021-11-29T17:38:46.806Z,1638207526.806 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2021-11-29T17:38:46.878Z,1638207526.878 [VerticalControl](DEBUG): Construct VerticalControl.
2021-11-29T17:38:46.941Z,1638207526.941 [VerticalControl] Loaded
2021-11-29T17:38:46.941Z,1638207526.941 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2021-11-29T17:38:46.944Z,1638207526.944 [HorizontalControl](DEBUG): Construct HorizontalControl.
2021-11-29T17:38:46.982Z,1638207526.982 [HorizontalControl] Loaded
2021-11-29T17:38:46.982Z,1638207526.982 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2021-11-29T17:38:46.984Z,1638207526.984 [SpeedControl](DEBUG): Construct SpeedControl.
2021-11-29T17:38:46.988Z,1638207526.988 [SpeedControl] Loaded
2021-11-29T17:38:46.988Z,1638207526.988 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2021-11-29T17:38:46.990Z,1638207526.990 [LoopControl](DEBUG): Construct LoopControl.
2021-11-29T17:38:46.991Z,1638207526.991 [LoopControl] Loaded
2021-11-29T17:38:46.991Z,1638207526.991 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2021-11-29T17:38:46.992Z,1638207526.992 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2021-11-29T17:38:46.993Z,1638207526.993 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2021-11-29T17:38:47.010Z,1638207527.010 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2021-11-29T17:38:47.011Z,1638207527.011 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2021-11-29T17:38:47.146Z,1638207527.146 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2021-11-29T17:38:47.148Z,1638207527.148 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2021-11-29T17:38:47.329Z,1638207527.329 [BuoyancyServo] Loaded
2021-11-29T17:38:47.330Z,1638207527.330 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2021-11-29T17:38:47.349Z,1638207527.349 [ElevatorServo] Loaded
2021-11-29T17:38:47.350Z,1638207527.350 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2021-11-29T17:38:47.368Z,1638207527.368 [MassServo] Loaded
2021-11-29T17:38:47.368Z,1638207527.368 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2021-11-29T17:38:47.386Z,1638207527.386 [RudderServo] Loaded
2021-11-29T17:38:47.386Z,1638207527.386 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2021-11-29T17:38:47.403Z,1638207527.403 [ThrusterServo] Loaded
2021-11-29T17:38:47.404Z,1638207527.404 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2021-11-29T17:38:47.404Z,1638207527.404 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2021-11-29T17:38:47.405Z,1638207527.405 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2021-11-29T17:38:47.505Z,1638207527.505 [DeadReckonUsingMultipleVelocitySources] Loaded
2021-11-29T17:38:47.505Z,1638207527.505 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2021-11-29T17:38:47.518Z,1638207527.518 [NavChart] Loaded
2021-11-29T17:38:47.518Z,1638207527.518 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2021-11-29T17:38:47.524Z,1638207527.524 [UniversalFixResidualReporter] Loaded
2021-11-29T17:38:47.524Z,1638207527.524 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2021-11-29T17:38:47.525Z,1638207527.525 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2021-11-29T17:38:47.526Z,1638207527.526 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2021-11-29T17:38:47.610Z,1638207527.610 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2021-11-29T17:38:47.610Z,1638207527.610 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2021-11-29T17:38:48.304Z,1638207528.304 [AHRS_M2] Loaded
2021-11-29T17:38:48.304Z,1638207528.304 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2021-11-29T17:38:49.179Z,1638207529.179 [BPC1] Loaded
2021-11-29T17:38:49.179Z,1638207529.179 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2021-11-29T17:38:49.227Z,1638207529.227 [Depth_Keller] Loaded
2021-11-29T17:38:49.227Z,1638207529.227 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2021-11-29T17:38:49.232Z,1638207529.232 [DropWeight] Loaded
2021-11-29T17:38:49.232Z,1638207529.232 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2021-11-29T17:38:49.380Z,1638207529.380 [NAL9602] Loaded
2021-11-29T17:38:49.380Z,1638207529.380 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2021-11-29T17:38:49.523Z,1638207529.523 [Onboard] Loaded
2021-11-29T17:38:49.524Z,1638207529.524 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2021-11-29T17:38:49.525Z,1638207529.525 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 408C64E0
2021-11-29T17:38:49.525Z,1638207529.525 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 922
2021-11-29T17:38:49.561Z,1638207529.561 [Power24vConverter] Loaded
2021-11-29T17:38:49.561Z,1638207529.561 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread.
2021-11-29T17:38:49.603Z,1638207529.603 [Radio_Surface] Loaded
2021-11-29T17:38:49.603Z,1638207529.603 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2021-11-29T17:38:49.604Z,1638207529.604 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408F64E0
2021-11-29T17:38:49.605Z,1638207529.605 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 923
2021-11-29T17:38:49.690Z,1638207529.690 [DAT] Loaded
2021-11-29T17:38:49.691Z,1638207529.691 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2021-11-29T17:38:49.691Z,1638207529.691 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2021-11-29T17:38:49.692Z,1638207529.692 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2021-11-29T17:38:49.755Z,1638207529.755 [DepthRateCalculator] Loaded
2021-11-29T17:38:49.756Z,1638207529.756 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2021-11-29T17:38:49.760Z,1638207529.760 [PitchRateCalculator] Loaded
2021-11-29T17:38:49.761Z,1638207529.761 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2021-11-29T17:38:49.770Z,1638207529.770 [SpeedCalculator] Loaded
2021-11-29T17:38:49.770Z,1638207529.770 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2021-11-29T17:38:49.784Z,1638207529.784 [TempGradientCalculator] Loaded
2021-11-29T17:38:49.784Z,1638207529.784 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2021-11-29T17:38:49.789Z,1638207529.789 [YawRateCalculator] Loaded
2021-11-29T17:38:49.789Z,1638207529.789 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2021-11-29T17:38:49.807Z,1638207529.807 [ElevatorOffsetCalculator] Loaded
2021-11-29T17:38:49.808Z,1638207529.808 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2021-11-29T17:38:49.808Z,1638207529.808 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2021-11-29T17:38:49.809Z,1638207529.809 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2021-11-29T17:38:49.992Z,1638207529.992 [CANONSampler] Loaded
2021-11-29T17:38:49.993Z,1638207529.993 [ComponentRegistry](DEBUG): SyncComponent "CANONSampler" handled in the control thread.
2021-11-29T17:38:50.052Z,1638207530.052 [CTD_Seabird] Loaded
2021-11-29T17:38:50.052Z,1638207530.052 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2021-11-29T17:38:50.053Z,1638207530.053 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 409AB4E0
2021-11-29T17:38:50.053Z,1638207530.053 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 924
2021-11-29T17:38:50.074Z,1638207530.074 [PAR_Licor] Loaded
2021-11-29T17:38:50.074Z,1638207530.074 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2021-11-29T17:38:50.107Z,1638207530.107 [WetLabsBB2FL] Loaded
2021-11-29T17:38:50.108Z,1638207530.108 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2021-11-29T17:38:50.109Z,1638207530.109 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 409DB4E0
2021-11-29T17:38:50.109Z,1638207530.109 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 925
2021-11-29T17:38:50.110Z,1638207530.110 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2021-11-29T17:38:50.111Z,1638207530.111 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2021-11-29T17:38:50.153Z,1638207530.153 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2021-11-29T17:38:50.154Z,1638207530.154 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2021-11-29T17:38:50.532Z,1638207530.532 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2021-11-29T17:38:50.533Z,1638207530.533 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2021-11-29T17:38:50.711Z,1638207530.711 [SBIT](DEBUG): Construct Startup Built In Test.
2021-11-29T17:38:50.720Z,1638207530.720 [SBIT] Loaded
2021-11-29T17:38:50.721Z,1638207530.721 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2021-11-29T17:38:50.723Z,1638207530.723 [IBIT](DEBUG): Construct Initiated Built In Test.
2021-11-29T17:38:50.737Z,1638207530.737 [IBIT] Loaded
2021-11-29T17:38:50.737Z,1638207530.737 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2021-11-29T17:38:50.743Z,1638207530.743 [CBIT](DEBUG): Construct Continuous Built In Test.
2021-11-29T17:38:50.846Z,1638207530.846 [CBIT] Loaded
2021-11-29T17:38:50.847Z,1638207530.847 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2021-11-29T17:38:50.847Z,1638207530.847 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2021-11-29T17:38:50.848Z,1638207530.848 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2021-11-29T17:38:50.967Z,1638207530.967 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2021-11-29T17:38:50.973Z,1638207530.973 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2021-11-29T17:38:50.976Z,1638207530.976 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2021-11-29T17:38:50.986Z,1638207530.986 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2021-11-29T17:38:50.987Z,1638207530.987 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40B104E0
2021-11-29T17:38:50.988Z,1638207530.988 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 926
2021-11-29T17:38:50.992Z,1638207530.992 [Supervisor](INFO): Main Thread ID is 829
2021-11-29T17:38:50.992Z,1638207530.992 [Supervisor](DEBUG): Running supervisor.
2021-11-29T17:38:50.993Z,1638207530.993 [CommandExec ThreadHandler](INFO): Handler Thread ID is 927
2021-11-29T17:38:50.994Z,1638207530.994 [CommandExec](INFO): Initializing the command executive.
2021-11-29T17:38:50.995Z,1638207530.995 [CommandLine ThreadHandler](INFO): Handler Thread ID is 928
2021-11-29T17:38:50.997Z,1638207530.997 [controlThread ThreadHandler](INFO): Handler Thread ID is 929
2021-11-29T17:38:50.998Z,1638207530.998 [controlThread](DEBUG): Initializing ControlThread
2021-11-29T17:38:50.999Z,1638207530.999 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2021-11-29T17:38:51.001Z,1638207531.001 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2021-11-29T17:38:51.002Z,1638207531.002 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2021-11-29T17:38:51.002Z,1638207531.002 [LoopControl](DEBUG): Initialize LoopControlComponent.
2021-11-29T17:38:51.004Z,1638207531.004 [NavChart](DEBUG): Initialize NavChart Navigation.
2021-11-29T17:38:51.004Z,1638207531.004 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2021-11-29T17:38:51.011Z,1638207531.011 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2021-11-29T17:38:51.011Z,1638207531.011 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2021-11-29T17:38:51.012Z,1638207531.012 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2021-11-29T17:38:51.012Z,1638207531.012 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2021-11-29T17:38:51.013Z,1638207531.013 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2021-11-29T17:38:51.013Z,1638207531.013 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2021-11-29T17:38:51.017Z,1638207531.017 [SBIT](INFO): Initialize SBIT Component.
2021-11-29T17:38:51.018Z,1638207531.018 [SBIT](IMPORTANT): git: 2021-11-29
2021-11-29T17:38:51.018Z,1638207531.018 [SBIT](INFO): git hash: f462e1af5d4560b0531ff1e41adede0f51e7b106
2021-11-29T17:38:51.018Z,1638207531.018 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2021-11-29T17:38:51.020Z,1638207531.020 [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-29T17:38:51.022Z,1638207531.022 [SBIT](INFO): Beginning SBIT in 84.000000 seconds.
2021-11-29T17:38:51.022Z,1638207531.022 [logger ThreadHandler](INFO): Handler Thread ID is 930
2021-11-29T17:38:51.037Z,1638207531.037 [IBIT](INFO): Initialize IBIT Component.
2021-11-29T17:38:51.038Z,1638207531.038 [CBIT](DEBUG): Initialize CBIT Component.
2021-11-29T17:38:51.046Z,1638207531.046 [Onboard ThreadHandler](INFO): Handler Thread ID is 931
2021-11-29T17:38:51.050Z,1638207531.050 [CBIT](DEBUG): Initialized mux pins.
2021-11-29T17:38:51.050Z,1638207531.050 [CBIT](DEBUG): Initializing the watchdog timer.
2021-11-29T17:38:51.066Z,1638207531.066 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 932
2021-11-29T17:38:51.077Z,1638207531.077 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2021-11-29T17:38:51.078Z,1638207531.078 [CBIT](DEBUG): Initializing heartbeat.
2021-11-29T17:38:51.078Z,1638207531.078 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 933
2021-11-29T17:38:51.079Z,1638207531.079 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2021-11-29T17:38:51.085Z,1638207531.085 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 935
2021-11-29T17:38:51.090Z,1638207531.090 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 937
2021-11-29T17:38:51.090Z,1638207531.090 [WetLabsBB2FL](INFO): Powering up
2021-11-29T17:38:51.099Z,1638207531.099 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2021-11-29T17:38:51.100Z,1638207531.100 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2021-11-29T17:38:51.100Z,1638207531.100 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2021-11-29T17:38:51.100Z,1638207531.100 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2021-11-29T17:38:51.100Z,1638207531.100 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2021-11-29T17:38:51.100Z,1638207531.100 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2021-11-29T17:38:51.101Z,1638207531.101 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2021-11-29T17:38:51.101Z,1638207531.101 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2021-11-29T17:38:51.101Z,1638207531.101 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2021-11-29T17:38:51.102Z,1638207531.102 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2021-11-29T17:38:51.102Z,1638207531.102 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2021-11-29T17:38:51.102Z,1638207531.102 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2021-11-29T17:38:51.102Z,1638207531.102 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2021-11-29T17:38:51.102Z,1638207531.102 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2021-11-29T17:38:51.103Z,1638207531.103 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2021-11-29T17:38:51.103Z,1638207531.103 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2021-11-29T17:38:51.149Z,1638207531.149 [CBIT](DEBUG): Deactivating GF circuits.
2021-11-29T17:38:51.149Z,1638207531.149 [CBIT](DEBUG): Deactivating emergency mode.
2021-11-29T17:38:51.185Z,1638207531.185 [CBIT](DEBUG): Backplane powered.
2021-11-29T17:38:51.186Z,1638207531.186 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2021-11-29T17:38:51.221Z,1638207531.221 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2021-11-29T17:38:51.233Z,1638207531.233 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

    <Guidance:GoToSurface>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="StartupSatComms">

        <Sequence/>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:latitude_fix/>
        </ReadDatum>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:platform_communications/>
        </ReadDatum>

    </Aggregate>

</Mission>


2021-11-29T17:38:51.234Z,1638207531.234 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2021-11-29T17:38:51.303Z,1638207531.303 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2021-11-29T17:38:51.304Z,1638207531.304 [Default:A.Wait](DEBUG): Construct Wait.
2021-11-29T17:38:51.323Z,1638207531.323 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2021-11-29T17:38:51.350Z,1638207531.350 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2021-11-29T17:38:51.373Z,1638207531.373 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2021-11-29T17:38:51.379Z,1638207531.379 [Default:E.Execute](DEBUG): Construct Execute.
2021-11-29T17:38:51.395Z,1638207531.395 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Universal="Tethys/Universal"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
         Id="Default">

    <DefineArg Name="ElapsedSinceDefaultStarted"><Units:minute/><Value>0</Value></DefineArg>

    <Guidance:Wait>
        <Description>
            Wait a moment to see if the scheduler starts a new mission before
            starting to actually run Default.
        </Description>
        <Sequence/>
        <Setting><Guidance:Wait.duration/><Units:second/><Value>13</Value></Setting>
    </Guidance:Wait>

    <Guidance:GoToSurface>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="CheckIn">

        <Sequence Repeat="288"/>

        <ReadDatum Id="Read_GPS">
            <Timeout Duration="P5M"/>
            <Universal:time_fix/>
        </ReadDatum>

        <ReadDatum Id="Read_Iridium">
            <Timeout Duration="P2H">
                <Guidance:Execute>
                    <Sequence/>
                    <Setting><Guidance:Execute.command/><String>Burn on</String></Setting>
                </Guidance:Execute>
                <Syslog Severity="Critical">Dropped weight due to communications timeout.</Syslog>
            </Timeout>
            <Universal:platform_communications/>
        </ReadDatum>

        <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Units:minute/><Value>5</Value></Setting>
        </Guidance:Wait>

        <Assign><Sequence/><Arg Name="ElapsedSinceDefaultStarted"/><Elapsed><Universal:mission_started/></Elapsed></Assign>

        <Syslog Severity="Important">Default mission has been running for <Arg Name="ElapsedSinceDefaultStarted"/><Units:minute/></Syslog>

    </Aggregate>

    <Syslog Severity="Important">Restarting logs and Default mission.</Syslog>

    <Guidance:Execute>
        <Sequence/>
        <Setting><Guidance:Execute.command/><String>restart logs</String></Setting>
    </Guidance:Execute>

</Mission>


2021-11-29T17:38:51.400Z,1638207531.400 [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-29T17:38:51.425Z,1638207531.425 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2021-11-29T17:38:51.469Z,1638207531.469 [Radio_Surface](INFO): Powering up
2021-11-29T17:38:51.568Z,1638207531.568 [Power24vConverter](INFO): Powering up.
2021-11-29T17:38:51.569Z,1638207531.569 [DAT](INFO): Powering up
2021-11-29T17:38:51.573Z,1638207531.573 [DAT](DEBUG): Initializing DAT.
2021-11-29T17:38:51.593Z,1638207531.593 [CANONSampler](INFO): Powering down
2021-11-29T17:38:51.649Z,1638207531.649 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2021-11-29T17:38:51.657Z,1638207531.657 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2021-11-29T17:38:51.659Z,1638207531.659 [ElevatorServo](DEBUG): Initializing EZServoServo.
2021-11-29T17:38:51.665Z,1638207531.665 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2021-11-29T17:38:51.666Z,1638207531.666 [MassServo](DEBUG): Initializing EZServoServo.
2021-11-29T17:38:51.677Z,1638207531.677 [MassServo](DEBUG): Initializing MassServo.
2021-11-29T17:38:51.678Z,1638207531.678 [RudderServo](DEBUG): Initializing EZServoServo.
2021-11-29T17:38:51.689Z,1638207531.689 [RudderServo](DEBUG): Initializing RudderServo.
2021-11-29T17:38:51.690Z,1638207531.690 [ThrusterServo](DEBUG): Initializing EZServoServo.
2021-11-29T17:38:51.697Z,1638207531.697 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2021-11-29T17:38:52.537Z,1638207532.537 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2021-11-29T17:38:52.537Z,1638207532.537 [RudderServo](FAULT): Rudder failed to initialize
2021-11-29T17:38:52.537Z,1638207532.537 [RudderServo] Communications Fault, FailCount= 1
2021-11-29T17:38:52.537Z,1638207532.537 [RudderServo](ERROR): Communications Fault
2021-11-29T17:38:52.639Z,1638207532.639 [CBIT](ERROR): Communications Fault in component: RudderServo
2021-11-29T17:38:52.818Z,1638207532.818 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2021-11-29T17:38:52.818Z,1638207532.818 [RudderServo](INFO): Powering down
2021-11-29T17:38:53.197Z,1638207533.197 [WetLabsBB2FL](INFO): Powering down
2021-11-29T17:38:53.478Z,1638207533.478 [RudderServo](DEBUG): Initializing EZServoServo.
2021-11-29T17:38:53.598Z,1638207533.598 [RudderServo](DEBUG): Initializing RudderServo.
2021-11-29T17:38:53.603Z,1638207533.603 [CBIT](INFO): Clearing failed state for component RudderServo
2021-11-29T17:38:53.603Z,1638207533.603 [RudderServo] No Fault, FailCount= 1
2021-11-29T17:39:03.563Z,1638207543.563 [DAT](INFO): DAT read: 

2021-11-29T17:39:03.565Z,1638207543.565 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series

2021-11-29T17:39:05.179Z,1638207545.179 [DAT](INFO): DAT read: MF Frequency Band

2021-11-29T17:39:05.181Z,1638207545.181 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.14.2

2021-11-29T17:39:05.181Z,1638207545.181 [DAT](INFO): DAT read: Nov 29 2021 17:38:25 

2021-11-29T17:39:06.391Z,1638207546.391 [DAT](INFO): DAT read: Features enabled [Bearing]

2021-11-29T17:39:06.393Z,1638207546.393 [DAT](INFO): DAT read: CONNECT 01200 bits/sec 1 of 4, Rate 1/2 CC

2021-11-29T17:39:06.394Z,1638207546.394 [DAT](INFO): commRate: 1200
2021-11-29T17:39:08.411Z,1638207548.411 [DAT](INFO): entering command mode
2021-11-29T17:39:08.815Z,1638207548.815 [DAT](INFO): DAT read: 

2021-11-29T17:39:08.815Z,1638207548.815 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:09.219Z,1638207549.219 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:09.623Z,1638207549.623 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:10.027Z,1638207550.027 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:10.431Z,1638207550.431 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:10.835Z,1638207550.835 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:11.239Z,1638207551.239 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:11.643Z,1638207551.643 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:12.047Z,1638207552.047 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:12.451Z,1638207552.451 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:12.855Z,1638207552.855 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:13.266Z,1638207553.266 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:13.663Z,1638207553.663 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:14.067Z,1638207554.067 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:14.471Z,1638207554.471 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:14.879Z,1638207554.879 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:15.279Z,1638207555.279 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:15.683Z,1638207555.683 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:16.096Z,1638207556.096 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:16.499Z,1638207556.499 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:16.895Z,1638207556.895 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:17.299Z,1638207557.299 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:17.703Z,1638207557.703 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:18.112Z,1638207558.112 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:18.511Z,1638207558.511 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:18.915Z,1638207558.915 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:19.319Z,1638207559.319 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:19.727Z,1638207559.727 [NAL9602](INFO): Powering up NAL9602
2021-11-29T17:39:19.729Z,1638207559.729 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:20.127Z,1638207560.127 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:20.531Z,1638207560.531 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:20.935Z,1638207560.935 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:21.343Z,1638207561.343 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:21.743Z,1638207561.743 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:22.147Z,1638207562.147 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:22.551Z,1638207562.551 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:22.955Z,1638207562.955 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:23.377Z,1638207563.377 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:23.764Z,1638207563.764 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-29T17:39:23.764Z,1638207563.764 [DAT](FAULT): failed to enter command mode
2021-11-29T17:39:24.167Z,1638207564.167 [DAT](INFO): entering command mode
2021-11-29T17:39:24.575Z,1638207564.575 [DAT](INFO): DAT read: user:1>

2021-11-29T17:39:24.576Z,1638207564.576 [DAT](INFO): DAT read: Command '+++' not found

2021-11-29T17:39:24.577Z,1638207564.577 [DAT](INFO): DAT read: Error

2021-11-29T17:39:24.577Z,1638207564.577 [DAT](INFO): setting verbose to 3
2021-11-29T17:39:24.975Z,1638207564.975 [DAT](INFO): DAT read: user:2>

2021-11-29T17:39:24.976Z,1638207564.976 [DAT](INFO): DAT read: Verbose         | 3           

2021-11-29T17:39:24.977Z,1638207564.977 [DAT](INFO): set verbose to 3
2021-11-29T17:39:24.977Z,1638207564.977 [DAT](INFO): setting DatVerbose to 27440
2021-11-29T17:39:25.379Z,1638207565.379 [DAT](INFO): DAT read: user:3>

2021-11-29T17:39:25.380Z,1638207565.380 [DAT](INFO): DAT read: DatVerbose      | 27440       

2021-11-29T17:39:25.381Z,1638207565.381 [DAT](INFO): set DatVerbose to 27440
2021-11-29T17:39:25.381Z,1638207565.381 [DAT](INFO): setting transmit power to 8
2021-11-29T17:39:25.783Z,1638207565.783 [DAT](INFO): DAT read: user:4>

2021-11-29T17:39:25.784Z,1638207565.784 [DAT](INFO): DAT read: TxPower         | 8 (Max)     

2021-11-29T17:39:25.784Z,1638207565.784 [DAT](INFO): set transmit power to 8
2021-11-29T17:39:25.785Z,1638207565.785 [DAT](INFO): setting local address to 7
2021-11-29T17:39:26.191Z,1638207566.191 [DAT](INFO): DAT read: user:5>

2021-11-29T17:39:26.192Z,1638207566.192 [DAT](INFO): DAT read: LocalAddr       | 7           

2021-11-29T17:39:26.193Z,1638207566.193 [DAT](INFO): set local address to 7
2021-11-29T17:39:30.631Z,1638207570.631 [NAL9602](INFO): NAL9602 initialized
2021-11-29T17:39:48.008Z,1638207588.008 [NAL9602](INFO): SBD MO Status=0, MOMSN=30447, MT Status=0, MTMSN=0
2021-11-29T17:39:48.008Z,1638207588.008 [NAL9602](INFO): No messages in MT queue
2021-11-29T17:40:04.169Z,1638207604.169 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174003.00,A,3648.14168,N,12147.22518,W,0.078,0.00,291121,,,A*74
2021-11-29T17:40:04.172Z,1638207604.172 [NAL9602](INFO): GPS fix at 20211129T174003: (36.802361, -121.787086)
2021-11-29T17:40:15.519Z,1638207615.519 [SBIT](IMPORTANT): Beginning Startup BIT
2021-11-29T17:40:15.523Z,1638207615.523 [CBIT](IMPORTANT): Beginning ground fault scan
2021-11-29T17:40:26.502Z,1638207626.502 [CBIT](ERROR): Ground fault scan returned out of bounds value. Re-running scan.
2021-11-29T17:40:26.887Z,1638207626.887 [CBIT](IMPORTANT): Beginning ground fault scan
2021-11-29T17:40:36.486Z,1638207636.486 [NAL9602](INFO): Not Powering down - fast GPS
2021-11-29T17:40:37.767Z,1638207637.767 [CBIT](ERROR): Ground fault scan returned out of bounds value. Re-running scan.
2021-11-29T17:40:38.159Z,1638207638.159 [CBIT](IMPORTANT): Beginning ground fault scan
2021-11-29T17:40:49.043Z,1638207649.043 [CBIT](ERROR): Ground fault scan returned out of bounds value. Re-running scan.
2021-11-29T17:40:49.043Z,1638207649.043 [CBIT](IMPORTANT): Ground fault scan returned out of bounds value in succession 3 times. Will re-run scan on normal schedule.
2021-11-29T17:41:09.634Z,1638207669.634 [SBIT](IMPORTANT): SBIT PASSED
2021-11-29T17:41:09.634Z,1638207669.634 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2021-11-29T17:41:09.635Z,1638207669.635 [SBIT](IMPORTANT): AMEcho.loadAtStartup=0 bool;

2021-11-29T17:41:09.635Z,1638207669.635 [SBIT](IMPORTANT): BuoyancyServo.fastPumpDepth=6 meter;

2021-11-29T17:41:09.635Z,1638207669.635 [SBIT](IMPORTANT): CANONSampler.loadAtStartup=1 bool;

2021-11-29T17:41:09.635Z,1638207669.635 [SBIT](IMPORTANT): DAT.baud=9600 bit_per_second;

2021-11-29T17:41:09.635Z,1638207669.635 [SBIT](IMPORTANT): DAT.loadAtStartup=1 bool;

2021-11-29T17:41:09.636Z,1638207669.636 [SBIT](IMPORTANT): DAT.sbdAddress=1 enum;

2021-11-29T17:41:09.636Z,1638207669.636 [SBIT](IMPORTANT): DAT.surfaceThreshold=0 meter;

2021-11-29T17:41:09.636Z,1638207669.636 [SBIT](IMPORTANT): DAT.verbosity=3 count;

2021-11-29T17:41:09.636Z,1638207669.636 [SBIT](IMPORTANT): DataOverHttps.loadAtStartup=0 bool;

2021-11-29T17:41:09.636Z,1638207669.636 [SBIT](IMPORTANT): ESPComponent.loadAtStartup=0 bool;

2021-11-29T17:41:09.636Z,1638207669.636 [SBIT](IMPORTANT): ESPComponent.simulateHardware=1 bool;

2021-11-29T17:41:09.636Z,1638207669.636 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=296 cubic_centimeter;

2021-11-29T17:41:09.636Z,1638207669.636 [SBIT](IMPORTANT): VerticalControl.massDefault=-16 millimeter;

2021-11-29T17:41:09.637Z,1638207669.637 [SBIT](IMPORTANT): VerticalControl.surfaceThreshold=2 meter;

2021-11-29T17:41:10.095Z,1638207670.095 [MissionManager](IMPORTANT): Started mission Startup
2021-11-29T17:41:10.095Z,1638207670.095 [Startup] Running Loop=1
2021-11-29T17:41:10.095Z,1638207670.095 [Startup](DEBUG): Aggregate::initialize Startup
2021-11-29T17:41:10.095Z,1638207670.095 [Startup:A.GoToSurface] Running Loop=1
2021-11-29T17:41:10.095Z,1638207670.095 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2021-11-29T17:41:10.096Z,1638207670.096 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2021-11-29T17:41:10.096Z,1638207670.096 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2021-11-29T17:41:10.097Z,1638207670.097 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2021-11-29T17:41:10.097Z,1638207670.097 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2021-11-29T17:41:10.098Z,1638207670.098 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2021-11-29T17:41:10.099Z,1638207670.099 [Startup:StartupSatComms] Running Loop=1
2021-11-29T17:41:10.099Z,1638207670.099 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2021-11-29T17:41:10.099Z,1638207670.099 [Startup:StartupSatComms:A] Running Loop=1
2021-11-29T17:41:10.443Z,1638207670.443 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2021-11-29T17:41:12.138Z,1638207672.138 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174111.00,A,3648.14321,N,12147.22712,W,0.156,0.00,291121,,,A*7C
2021-11-29T17:41:12.140Z,1638207672.140 [NAL9602](INFO): GPS fix at 20211129T174111: (36.802387, -121.787119)
2021-11-29T17:41:12.152Z,1638207672.152 [Startup:StartupSatComms:A] Stopped
2021-11-29T17:41:12.152Z,1638207672.152 [Startup:StartupSatComms:B] Running Loop=1
2021-11-29T17:41:12.514Z,1638207672.514 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2021-11-29T17:41:12.881Z,1638207672.881 [DAT](INFO): #Outgoing data=1
2021-11-29T17:41:12.882Z,1638207672.882 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-29T17:41:13.268Z,1638207673.268 [DAT](INFO): setting remote address to 1
2021-11-29T17:41:13.660Z,1638207673.660 [DAT](INFO): DAT read: user:6>

2021-11-29T17:41:13.662Z,1638207673.662 [DAT](INFO): DAT read: RemoteAddr      | 1           

2021-11-29T17:41:13.662Z,1638207673.662 [DAT](INFO): set remote address to 1
2021-11-29T17:41:13.663Z,1638207673.663 [DAT](INFO): entering online mode
2021-11-29T17:41:14.078Z,1638207674.078 [DAT](INFO): DAT read: user:7>

2021-11-29T17:41:14.078Z,1638207674.078 [DAT](INFO): DAT read: 

2021-11-29T17:41:14.080Z,1638207674.080 [DAT](INFO): DAT read: CONNECT 01200 bits/sec 1 of 4, Rate 1/2 CC

2021-11-29T17:41:14.080Z,1638207674.080 [DAT](INFO): commRate: 1200
2021-11-29T17:41:14.080Z,1638207674.080 [DAT](INFO): online mode acknowledged
2021-11-29T17:41:14.081Z,1638207674.081 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-29T17:41:17.297Z,1638207677.297 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:40:40.3342

2021-11-29T17:41:17.304Z,1638207677.304 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-29T17:41:26.652Z,1638207686.652 [NAL9602](INFO): SBD MO Status=1, MOMSN=30448, MT Status=0, MTMSN=0
2021-11-29T17:41:26.701Z,1638207686.701 [NAL9602](INFO): Sent 39 bytes from file Logs/20211129T161830/Courier0037.lzma
2021-11-29T17:41:26.702Z,1638207686.702 [NAL9602](INFO): Packets left to send: 0
2021-11-29T17:41:27.440Z,1638207687.440 [DAT](FAULT): Ack receipt timeout failure.
2021-11-29T17:41:27.440Z,1638207687.440 [DAT](DEBUG): In sendingAckWaiting, timeout so set commsState_ = SENDING_FILL_BUFFER
2021-11-29T17:41:29.864Z,1638207689.864 [DAT](INFO): #Outgoing data=1
2021-11-29T17:41:29.865Z,1638207689.865 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-29T17:41:30.004Z,1638207690.004 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-29T17:41:33.606Z,1638207693.606 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:40:56.2840

2021-11-29T17:41:33.607Z,1638207693.607 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-29T17:41:34.416Z,1638207694.416 [NAL9602](INFO): SBD MO Status=1, MOMSN=30449, MT Status=0, MTMSN=0
2021-11-29T17:41:34.465Z,1638207694.465 [NAL9602](INFO): Sent 268 bytes from file Logs/20211129T173840/Courier0000.lzma
2021-11-29T17:41:34.465Z,1638207694.465 [NAL9602](INFO): Packets left to send: 0
2021-11-29T17:41:42.948Z,1638207702.948 [NAL9602](INFO): SBD MO Status=1, MOMSN=30450, MT Status=0, MTMSN=0
2021-11-29T17:41:42.997Z,1638207702.997 [NAL9602](INFO): Sent 332 bytes from file Logs/20211129T161830/Express0001.lzma
2021-11-29T17:41:42.997Z,1638207702.997 [NAL9602](INFO): Packets left to send: 2
2021-11-29T17:41:43.622Z,1638207703.622 [DAT](FAULT): Ack receipt timeout failure.
2021-11-29T17:41:43.622Z,1638207703.622 [DAT](DEBUG): In sendingAckWaiting, timeout so set commsState_ = SENDING_FILL_BUFFER
2021-11-29T17:41:43.769Z,1638207703.769 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-29T17:41:43.780Z,1638207703.780 [Startup:StartupSatComms:B] Stopped
2021-11-29T17:41:43.780Z,1638207703.780 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2021-11-29T17:41:43.780Z,1638207703.780 [Startup:StartupSatComms] Stopped
2021-11-29T17:41:43.780Z,1638207703.780 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2021-11-29T17:41:43.782Z,1638207703.782 [Startup](INFO): Completed Startup
2021-11-29T17:41:43.782Z,1638207703.782 [MissionManager](INFO): Startup is completed.
2021-11-29T17:41:43.782Z,1638207703.782 [MissionManager](INFO): Uninitializing Mission Startup
2021-11-29T17:41:43.782Z,1638207703.782 [Startup] Stopped
2021-11-29T17:41:43.782Z,1638207703.782 [Startup](DEBUG): Aggregate::uninitialize Startup
2021-11-29T17:41:43.782Z,1638207703.782 [Startup:A.GoToSurface] Stopped
2021-11-29T17:41:43.782Z,1638207703.782 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2021-11-29T17:41:46.187Z,1638207706.187 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-29T17:41:46.274Z,1638207706.274 [MissionManager](IMPORTANT): Started mission Default
2021-11-29T17:41:46.274Z,1638207706.274 [Default] Running Loop=1
2021-11-29T17:41:46.274Z,1638207706.274 [Default](DEBUG): Aggregate::initialize Default
2021-11-29T17:41:46.274Z,1638207706.274 [Default:B.GoToSurface] Running Loop=1
2021-11-29T17:41:46.275Z,1638207706.275 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2021-11-29T17:41:46.275Z,1638207706.275 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2021-11-29T17:41:46.275Z,1638207706.275 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2021-11-29T17:41:46.276Z,1638207706.276 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2021-11-29T17:41:46.276Z,1638207706.276 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2021-11-29T17:41:46.276Z,1638207706.276 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2021-11-29T17:41:46.276Z,1638207706.276 [Default:A.Wait] Running Loop=1
2021-11-29T17:41:46.277Z,1638207706.277 [Default:A.Wait](DEBUG): Initialize Wait Component.
2021-11-29T17:41:49.540Z,1638207709.540 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:41:12.4338

2021-11-29T17:41:49.540Z,1638207709.540 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-29T17:41:53.984Z,1638207713.984 [NAL9602](INFO): SBD MO Status=1, MOMSN=30451, MT Status=0, MTMSN=0
2021-11-29T17:41:54.050Z,1638207714.050 [NAL9602](INFO): Sent 332 bytes from file Logs/20211129T161830/Express0001.lzma
2021-11-29T17:41:54.050Z,1638207714.050 [NAL9602](INFO): Packets left to send: 1
2021-11-29T17:41:59.639Z,1638207719.639 [DAT](FAULT): Ack receipt timeout failure.
2021-11-29T17:41:59.639Z,1638207719.639 [DAT](DEBUG): In sendingAckWaiting, timeout so set commsState_ = SENDING_FILL_BUFFER
2021-11-29T17:41:59.650Z,1638207719.650 [Default:A.Wait](INFO): Done Waiting.
2021-11-29T17:41:59.650Z,1638207719.650 [Default:A.Wait] Stopped
2021-11-29T17:41:59.650Z,1638207719.650 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2021-11-29T17:42:00.044Z,1638207720.044 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-29T17:42:00.060Z,1638207720.060 [Default:CheckIn] Running Loop=1
2021-11-29T17:42:00.061Z,1638207720.061 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-29T17:42:00.061Z,1638207720.061 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-29T17:42:00.448Z,1638207720.448 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-29T17:42:00.515Z,1638207720.515 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2021-11-29T17:42:02.064Z,1638207722.064 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174201.00,A,3648.13973,N,12147.22669,W,0.117,0.00,291121,,,A*7C
2021-11-29T17:42:02.067Z,1638207722.067 [NAL9602](INFO): GPS fix at 20211129T174201: (36.802329, -121.787111)
2021-11-29T17:42:02.090Z,1638207722.090 [Default:CheckIn:Read_GPS] Stopped
2021-11-29T17:42:02.090Z,1638207722.090 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-29T17:42:02.511Z,1638207722.511 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2021-11-29T17:42:03.681Z,1638207723.681 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:41:26.6851

2021-11-29T17:42:03.681Z,1638207723.681 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-29T17:42:15.390Z,1638207735.390 [DAT](FAULT): Ack receipt timeout failure.
2021-11-29T17:42:15.390Z,1638207735.390 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED
2021-11-29T17:42:15.479Z,1638207735.479 [DAT](DEBUG): In sendingVerified, sbd done so set commsState_ = SENDING_FILL_BUFFER
2021-11-29T17:42:15.873Z,1638207735.873 [DAT](INFO): #Outgoing data=2
2021-11-29T17:42:15.874Z,1638207735.874 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-29T17:42:16.268Z,1638207736.268 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-29T17:42:19.916Z,1638207739.916 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:41:42.5834

2021-11-29T17:42:19.916Z,1638207739.916 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-29T17:42:22.324Z,1638207742.324 [NAL9602](INFO): SBD MO Status=1, MOMSN=30452, MT Status=0, MTMSN=0
2021-11-29T17:42:22.382Z,1638207742.382 [NAL9602](INFO): Sent 73 bytes from file Logs/20211129T173840/Courier0004.lzma
2021-11-29T17:42:22.382Z,1638207742.382 [NAL9602](INFO): Packets left to send: 0
2021-11-29T17:42:30.035Z,1638207750.035 [DAT](FAULT): Ack receipt timeout failure.
2021-11-29T17:42:30.035Z,1638207750.035 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED
2021-11-29T17:42:30.452Z,1638207750.452 [DAT](INFO): Sent 73 bytes from file Logs/20211129T173840/Courier0004.lzma.parts
2021-11-29T17:42:30.452Z,1638207750.452 [DAT](INFO): Packets left to send: 0
2021-11-29T17:42:30.453Z,1638207750.453 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-29T17:42:30.848Z,1638207750.848 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-29T17:42:31.344Z,1638207751.344 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-29T17:42:32.119Z,1638207752.119 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2021-11-29T17:42:32.873Z,1638207752.873 [NAL9602](INFO): SBD MO Status=1, MOMSN=30453, MT Status=0, MTMSN=0
2021-11-29T17:42:32.925Z,1638207752.925 [NAL9602](INFO): Sent 241 bytes from file Logs/20211129T161830/Express0001.lzma
2021-11-29T17:42:32.925Z,1638207752.925 [NAL9602](INFO): Packets left to send: 0
2021-11-29T17:42:36.103Z,1638207756.103 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:41:57.7333

2021-11-29T17:42:36.103Z,1638207756.103 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-29T17:42:40.616Z,1638207760.616 [NAL9602](INFO): SBD MO Status=1, MOMSN=30454, MT Status=0, MTMSN=0
2021-11-29T17:42:40.665Z,1638207760.665 [NAL9602](INFO): Sent 320 bytes from file Logs/20211129T161830/Express0005.lzma
2021-11-29T17:42:40.665Z,1638207760.665 [NAL9602](INFO): Packets left to send: 0
2021-11-29T17:42:46.324Z,1638207766.324 [DAT](FAULT): Ack receipt timeout failure.
2021-11-29T17:42:46.324Z,1638207766.324 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED
2021-11-29T17:42:46.719Z,1638207766.719 [DAT](DEBUG): In sendingVerified, sbd done so set commsState_ = SENDING_FILL_BUFFER
2021-11-29T17:42:52.376Z,1638207772.376 [NAL9602](INFO): SBD MO Status=1, MOMSN=30455, MT Status=0, MTMSN=0
2021-11-29T17:42:52.429Z,1638207772.429 [NAL9602](INFO): Sent 257 bytes from file Logs/20211129T161830/Express0008.lzma
2021-11-29T17:42:52.430Z,1638207772.430 [NAL9602](INFO): Packets left to send: 0
2021-11-29T17:43:00.516Z,1638207780.516 [NAL9602](INFO): SBD MO Status=1, MOMSN=30456, MT Status=0, MTMSN=0
2021-11-29T17:43:00.566Z,1638207780.566 [NAL9602](INFO): Sent 176 bytes from file Logs/20211129T161830/Express0011.lzma
2021-11-29T17:43:00.566Z,1638207780.566 [NAL9602](INFO): Packets left to send: 0
2021-11-29T17:43:20.432Z,1638207800.432 [NAL9602](INFO): SBD MO Status=1, MOMSN=30457, MT Status=0, MTMSN=0
2021-11-29T17:43:20.485Z,1638207800.485 [NAL9602](INFO): Sent 332 bytes from file Logs/20211129T161830/Express0014.lzma
2021-11-29T17:43:20.485Z,1638207800.485 [NAL9602](INFO): Packets left to send: 2
2021-11-29T17:43:37.812Z,1638207817.812 [NAL9602](INFO): SBD MO Status=2, MOMSN=30458, MT Status=2, MTMSN=0
2021-11-29T17:43:37.812Z,1638207817.812 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T17:44:00.504Z,1638207840.504 [NAL9602](INFO): SBD MO Status=2, MOMSN=30458, MT Status=2, MTMSN=0
2021-11-29T17:44:00.504Z,1638207840.504 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T17:44:22.397Z,1638207862.397 [NAL9602](INFO): SBD MO Status=2, MOMSN=30458, MT Status=2, MTMSN=0
2021-11-29T17:44:22.398Z,1638207862.398 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T17:45:11.667Z,1638207911.667 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2021-11-29T17:45:11.670Z,1638207911.670 [BPC1](INFO): Received data from all battery sticks.
2021-11-29T17:45:34.761Z,1638207934.761 [DAT](INFO): DAT read: Lowpower

2021-11-29T17:45:34.762Z,1638207934.762 [DAT](INFO): unknown deviceResponse_: Lowpower

2021-11-29T17:45:44.455Z,1638207944.455 [NAL9602](INFO): SBD MO Status=2, MOMSN=30458, MT Status=2, MTMSN=0
2021-11-29T17:45:44.455Z,1638207944.455 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T17:46:09.963Z,1638207969.963 [NAL9602](INFO): SBD MO Status=2, MOMSN=30458, MT Status=2, MTMSN=0
2021-11-29T17:46:09.963Z,1638207969.963 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T17:46:53.644Z,1638208013.644 [NAL9602](INFO): SBD MO Status=1, MOMSN=30458, MT Status=0, MTMSN=0
2021-11-29T17:46:53.694Z,1638208013.694 [NAL9602](INFO): Sent 332 bytes from file Logs/20211129T161830/Express0014.lzma
2021-11-29T17:46:53.694Z,1638208013.694 [NAL9602](INFO): Packets left to send: 1
2021-11-29T17:47:01.787Z,1638208021.787 [NAL9602](INFO): SBD MO Status=1, MOMSN=30459, MT Status=0, MTMSN=0
2021-11-29T17:47:01.837Z,1638208021.837 [NAL9602](INFO): Sent 205 bytes from file Logs/20211129T161830/Express0014.lzma
2021-11-29T17:47:01.838Z,1638208021.838 [NAL9602](INFO): Packets left to send: 0
2021-11-29T17:47:13.298Z,1638208033.298 [CommandExec](IMPORTANT): got command failComponent
2021-11-29T17:47:13.298Z,1638208033.298 [CommandExec](IMPORTANT): Failed components:
2021-11-29T17:47:13.298Z,1638208033.298 [CommandExec](IMPORTANT): No failed Components.
2021-11-29T17:47:22.067Z,1638208042.067 [NAL9602](INFO): SBD MO Status=2, MOMSN=30460, MT Status=2, MTMSN=0
2021-11-29T17:47:22.067Z,1638208042.067 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T17:47:48.006Z,1638208068.006 [NAL9602](INFO): SBD MO Status=2, MOMSN=30460, MT Status=2, MTMSN=0
2021-11-29T17:47:48.006Z,1638208068.006 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T17:48:27.264Z,1638208107.264 [NAL9602](INFO): SBD MO Status=2, MOMSN=30460, MT Status=2, MTMSN=0
2021-11-29T17:48:27.264Z,1638208107.264 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T17:48:44.296Z,1638208124.296 [NAL9602](INFO): SBD MO Status=1, MOMSN=30460, MT Status=0, MTMSN=0
2021-11-29T17:48:44.345Z,1638208124.345 [NAL9602](INFO): Sent 166 bytes from file Logs/20211129T161830/Express0017.lzma
2021-11-29T17:48:44.345Z,1638208124.345 [NAL9602](INFO): Packets left to send: 0
2021-11-29T17:48:53.660Z,1638208133.660 [NAL9602](INFO): SBD MO Status=1, MOMSN=30461, MT Status=0, MTMSN=0
2021-11-29T17:48:53.721Z,1638208133.721 [NAL9602](INFO): Sent 161 bytes from file Logs/20211129T161830/Express0020.lzma
2021-11-29T17:48:53.722Z,1638208133.722 [NAL9602](INFO): Packets left to send: 0
2021-11-29T17:48:56.486Z,1638208136.486 [CommandExec](IMPORTANT): got command ibit
2021-11-29T17:48:56.906Z,1638208136.906 [IBIT](IMPORTANT): Beginning Initiated BIT
2021-11-29T17:48:56.906Z,1638208136.906 [IBIT](IMPORTANT): Beginning control surface checks.
2021-11-29T17:48:56.909Z,1638208136.909 [CBIT](IMPORTANT): Beginning ground fault scan
2021-11-29T17:49:02.179Z,1638208142.179 [NAL9602](INFO): SBD MO Status=1, MOMSN=30462, MT Status=0, MTMSN=0
2021-11-29T17:49:02.237Z,1638208142.237 [NAL9602](INFO): Sent 172 bytes from file Logs/20211129T161830/Express0023.lzma
2021-11-29T17:49:02.237Z,1638208142.237 [NAL9602](INFO): Packets left to send: 0
2021-11-29T17:49:09.297Z,1638208149.297 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.002373
CHAN A1 (24V): 0.000381
CHAN A2 (12V): -0.002176
CHAN A3 (5V): -0.001024
CHAN B0 (3.3V): -0.000033
CHAN B1 (3.15aV): -0.000152
CHAN B2 (3.15bV): -0.000361
CHAN B3 (GND): 0.000111
OPEN: -0.000341
Full Scale: +/- 1 mA
2021-11-29T17:49:11.680Z,1638208151.680 [NAL9602](INFO): SBD MO Status=1, MOMSN=30463, MT Status=0, MTMSN=0
2021-11-29T17:49:11.733Z,1638208151.733 [NAL9602](INFO): Sent 172 bytes from file Logs/20211129T161830/Express0026.lzma
2021-11-29T17:49:11.733Z,1638208151.733 [NAL9602](INFO): Packets left to send: 0
2021-11-29T17:49:19.005Z,1638208159.005 [NAL9602](INFO): SBD MO Status=1, MOMSN=30464, MT Status=0, MTMSN=0
2021-11-29T17:49:19.062Z,1638208159.062 [NAL9602](INFO): Sent 163 bytes from file Logs/20211129T161830/Express0029.lzma
2021-11-29T17:49:19.062Z,1638208159.062 [NAL9602](INFO): Packets left to send: 0
2021-11-29T17:49:29.320Z,1638208169.320 [NAL9602](INFO): SBD MO Status=1, MOMSN=30465, MT Status=0, MTMSN=0
2021-11-29T17:49:29.383Z,1638208169.383 [NAL9602](INFO): Sent 173 bytes from file Logs/20211129T161830/Express0032.lzma
2021-11-29T17:49:29.384Z,1638208169.384 [NAL9602](INFO): Packets left to send: 0
2021-11-29T17:49:40.422Z,1638208180.422 [NAL9602](INFO): SBD MO Status=1, MOMSN=30466, MT Status=0, MTMSN=0
2021-11-29T17:49:40.475Z,1638208180.475 [NAL9602](INFO): Sent 177 bytes from file Logs/20211129T161830/Express0035.lzma
2021-11-29T17:49:40.475Z,1638208180.475 [NAL9602](INFO): Packets left to send: 0
2021-11-29T17:49:43.357Z,1638208183.357 [IBIT](IMPORTANT): Communications Status:
Fix Status: 1
Iridium Signal Strength: 4
Latitude: 36.802330 Longitude: -121.787109
2021-11-29T17:49:43.720Z,1638208183.720 [IBIT](IMPORTANT): Battery Status:
Battery Charge (AH): 0.000000
Voltage: 16.334000
2021-11-29T17:49:43.721Z,1638208183.721 [IBIT](IMPORTANT): batteryCapacityThreshold: 50.000000 Ah
2021-11-29T17:49:43.721Z,1638208183.721 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.700000 V
2021-11-29T17:49:44.186Z,1638208184.186 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2021-11-29T17:49:44.186Z,1638208184.186 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2021-11-29T17:49:44.187Z,1638208184.187 [IBIT](IMPORTANT): Pressure:9.916073 PSI
2021-11-29T17:49:44.187Z,1638208184.187 [IBIT](IMPORTANT): Humidity:8.527653 %
2021-11-29T17:49:44.522Z,1638208184.522 [IBIT](IMPORTANT): Vehicle Pitch:-0.705869 degrees
2021-11-29T17:49:44.522Z,1638208184.522 [IBIT](IMPORTANT): Vehicle  Roll:3.056427 degrees
2021-11-29T17:49:44.523Z,1638208184.523 [IBIT](IMPORTANT): Vehicle  Heading:230.732971 degrees
2021-11-29T17:49:44.927Z,1638208184.927 [IBIT](IMPORTANT): surfaceThreshold: 2.000000 m
2021-11-29T17:49:44.927Z,1638208184.927 [IBIT](IMPORTANT): buoyancyNeutral: 296.000000 cc
2021-11-29T17:49:44.927Z,1638208184.927 [IBIT](IMPORTANT): massDefault: -1.600000 cm
2021-11-29T17:49:44.928Z,1638208184.928 [IBIT](IMPORTANT): stopDepth: 205.000000 m
2021-11-29T17:49:44.928Z,1638208184.928 [IBIT](IMPORTANT): abortDepth: 250.000000 m
2021-11-29T17:49:44.928Z,1638208184.928 [IBIT](IMPORTANT): IBIT PASSED
2021-11-29T17:49:50.964Z,1638208190.964 [NAL9602](INFO): SBD MO Status=1, MOMSN=30467, MT Status=0, MTMSN=0
2021-11-29T17:49:51.013Z,1638208191.013 [NAL9602](INFO): Sent 139 bytes from file Logs/20211129T161830/Express0038.lzma
2021-11-29T17:49:51.014Z,1638208191.014 [NAL9602](INFO): Packets left to send: 0
2021-11-29T17:50:12.425Z,1638208212.425 [NAL9602](INFO): SBD MO Status=1, MOMSN=30468, MT Status=0, MTMSN=0
2021-11-29T17:50:12.476Z,1638208212.476 [NAL9602](INFO): Sent 332 bytes from file Logs/20211129T173840/Express0001.lzma
2021-11-29T17:50:12.476Z,1638208212.476 [NAL9602](INFO): Packets left to send: 2
2021-11-29T17:50:30.275Z,1638208230.275 [NAL9602](INFO): SBD MO Status=1, MOMSN=30469, MT Status=0, MTMSN=0
2021-11-29T17:50:30.325Z,1638208230.325 [NAL9602](INFO): Sent 332 bytes from file Logs/20211129T173840/Express0001.lzma
2021-11-29T17:50:30.325Z,1638208230.325 [NAL9602](INFO): Packets left to send: 1
2021-11-29T17:50:42.453Z,1638208242.453 [NAL9602](INFO): SBD MO Status=1, MOMSN=30470, MT Status=0, MTMSN=0
2021-11-29T17:50:42.515Z,1638208242.515 [NAL9602](INFO): Sent 279 bytes from file Logs/20211129T173840/Express0001.lzma
2021-11-29T17:50:42.515Z,1638208242.515 [NAL9602](INFO): Packets left to send: 0
2021-11-29T17:50:55.048Z,1638208255.048 [NAL9602](INFO): SBD MO Status=1, MOMSN=30471, MT Status=0, MTMSN=0
2021-11-29T17:50:55.105Z,1638208255.105 [NAL9602](INFO): Sent 149 bytes from file Logs/20211129T173840/Express0005.lzma
2021-11-29T17:50:55.106Z,1638208255.106 [NAL9602](INFO): Packets left to send: 0
2021-11-29T17:50:58.154Z,1638208258.154 [CommandExec](IMPORTANT): got command failComponent
2021-11-29T17:50:58.154Z,1638208258.154 [CommandExec](IMPORTANT): Failed components:
2021-11-29T17:50:58.154Z,1638208258.154 [CommandExec](IMPORTANT): No failed Components.
2021-11-29T17:51:03.139Z,1638208263.139 [NAL9602](INFO): SBD MO Status=0, MOMSN=30472, MT Status=0, MTMSN=0
2021-11-29T17:51:03.223Z,1638208263.223 [Default:CheckIn:Read_Iridium] Stopped
2021-11-29T17:51:03.224Z,1638208263.224 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-29T17:51:03.224Z,1638208263.224 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-29T17:51:33.829Z,1638208293.829 [NAL9602](INFO): Not Powering down - fast GPS
2021-11-29T17:56:03.756Z,1638208563.756 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-29T17:56:03.756Z,1638208563.756 [Default:CheckIn:C.Wait] Stopped
2021-11-29T17:56:03.756Z,1638208563.756 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-29T17:56:03.756Z,1638208563.756 [Default:CheckIn:D] Running Loop=1
2021-11-29T17:56:04.133Z,1638208564.133 [Default:CheckIn:D] Stopped
2021-11-29T17:56:04.133Z,1638208564.133 [Default:CheckIn:E] Running Loop=1
2021-11-29T17:56:04.539Z,1638208564.539 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 14.297640 min 
2021-11-29T17:56:04.539Z,1638208564.539 [Default:CheckIn:E] Stopped
2021-11-29T17:56:04.539Z,1638208564.539 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-29T17:56:04.539Z,1638208564.539 [Default:CheckIn] Stopped
2021-11-29T17:56:04.539Z,1638208564.539 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-29T17:56:04.539Z,1638208564.539 [Default:CheckIn](INFO): Running loop #2
2021-11-29T17:56:04.539Z,1638208564.539 [Default:CheckIn] Running Loop=2
2021-11-29T17:56:04.540Z,1638208564.540 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-29T17:56:04.540Z,1638208564.540 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-29T17:56:06.552Z,1638208566.552 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175606.00,A,3648.14110,N,12147.22886,W,0.019,0.00,291121,,,D*71
2021-11-29T17:56:06.564Z,1638208566.564 [NAL9602](INFO): GPS fix at 20211129T175606: (36.802352, -121.787148)
2021-11-29T17:56:06.576Z,1638208566.576 [Default:CheckIn:Read_GPS] Stopped
2021-11-29T17:56:06.576Z,1638208566.576 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-29T17:56:07.363Z,1638208567.363 [DAT](INFO): #Outgoing data=1
2021-11-29T17:56:07.363Z,1638208567.363 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-29T17:56:07.782Z,1638208567.782 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-29T17:56:08.190Z,1638208568.190 [DAT](INFO): DAT read: UART Waeu

2021-11-29T17:56:08.191Z,1638208568.191 [DAT](INFO): unknown deviceResponse_: UART Waeu

2021-11-29T17:56:11.396Z,1638208571.396 [DAT](INFO): DAT read: CONECT 0120 its/ec  o 4,at/CCForwarding Delay UpTx time:17:55:35.4812

2021-11-29T17:56:11.397Z,1638208571.397 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-29T17:56:21.555Z,1638208581.555 [DAT](FAULT): Ack receipt timeout failure.
2021-11-29T17:56:21.555Z,1638208581.555 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED
2021-11-29T17:56:21.991Z,1638208581.991 [DAT](INFO): Sent 184 bytes from file Logs/20211129T173840/Courier0007.lzma.parts
2021-11-29T17:56:21.991Z,1638208581.991 [DAT](INFO): Packets left to send: 1
2021-11-29T17:56:21.993Z,1638208581.993 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-29T17:56:22.383Z,1638208582.383 [DAT](INFO): #Outgoing data=1
2021-11-29T17:56:22.384Z,1638208582.384 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-29T17:56:22.770Z,1638208582.770 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-29T17:56:24.384Z,1638208584.384 [NAL9602](INFO): SBD MO Status=1, MOMSN=30473, MT Status=0, MTMSN=0
2021-11-29T17:56:24.437Z,1638208584.437 [NAL9602](INFO): Sent 203 bytes from file Logs/20211129T173840/Courier0007.lzma
2021-11-29T17:56:24.437Z,1638208584.437 [NAL9602](INFO): Packets left to send: 0
2021-11-29T17:56:27.615Z,1638208587.615 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:55:50.2794

2021-11-29T17:56:27.615Z,1638208587.615 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-29T17:56:33.750Z,1638208593.750 [NAL9602](INFO): SBD MO Status=1, MOMSN=30474, MT Status=0, MTMSN=0
2021-11-29T17:56:33.801Z,1638208593.801 [NAL9602](INFO): Sent 332 bytes from file Logs/20211129T173840/Express0008.lzma
2021-11-29T17:56:33.802Z,1638208593.802 [NAL9602](INFO): Packets left to send: 2
2021-11-29T17:56:37.843Z,1638208597.843 [DAT](FAULT): Ack receipt timeout failure.
2021-11-29T17:56:37.843Z,1638208597.843 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED
2021-11-29T17:56:38.248Z,1638208598.248 [DAT](INFO): Sent 19 bytes from file Logs/20211129T173840/Courier0007.lzma.parts
2021-11-29T17:56:38.248Z,1638208598.248 [DAT](INFO): Packets left to send: 0
2021-11-29T17:56:38.258Z,1638208598.258 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-29T17:56:52.392Z,1638208612.392 [NAL9602](INFO): SBD MO Status=2, MOMSN=30475, MT Status=2, MTMSN=0
2021-11-29T17:56:52.393Z,1638208612.393 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T17:58:08.020Z,1638208688.020 [NAL9602](INFO): SBD MO Status=1, MOMSN=30475, MT Status=0, MTMSN=0
2021-11-29T17:58:08.065Z,1638208688.065 [NAL9602](INFO): Sent 332 bytes from file Logs/20211129T173840/Express0008.lzma
2021-11-29T17:58:08.066Z,1638208688.066 [NAL9602](INFO): Packets left to send: 1
2021-11-29T17:58:29.096Z,1638208709.096 [NAL9602](INFO): SBD MO Status=1, MOMSN=30476, MT Status=0, MTMSN=0
2021-11-29T17:58:29.150Z,1638208709.150 [NAL9602](INFO): Sent 213 bytes from file Logs/20211129T173840/Express0008.lzma
2021-11-29T17:58:29.150Z,1638208709.150 [NAL9602](INFO): Packets left to send: 0
2021-11-29T17:58:39.192Z,1638208719.192 [NAL9602](INFO): SBD MO Status=0, MOMSN=30477, MT Status=0, MTMSN=0
2021-11-29T17:58:39.298Z,1638208719.298 [Default:CheckIn:Read_Iridium] Stopped
2021-11-29T17:58:39.298Z,1638208719.298 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-29T17:58:39.298Z,1638208719.298 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-29T17:59:09.894Z,1638208749.894 [NAL9602](INFO): Not Powering down - fast GPS
2021-11-29T17:59:26.051Z,1638208766.051 [DAT](INFO): DAT read: Lowpower

2021-11-29T17:59:26.052Z,1638208766.052 [DAT](INFO): unknown deviceResponse_: Lowpower

2021-11-29T18:03:39.777Z,1638209019.777 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-29T18:03:39.777Z,1638209019.777 [Default:CheckIn:C.Wait] Stopped
2021-11-29T18:03:39.777Z,1638209019.777 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-29T18:03:39.777Z,1638209019.777 [Default:CheckIn:D] Running Loop=1
2021-11-29T18:03:40.183Z,1638209020.183 [Default:CheckIn:D] Stopped
2021-11-29T18:03:40.183Z,1638209020.183 [Default:CheckIn:E] Running Loop=1
2021-11-29T18:03:40.594Z,1638209020.594 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 21.898472 min 
2021-11-29T18:03:40.594Z,1638209020.594 [Default:CheckIn:E] Stopped
2021-11-29T18:03:40.594Z,1638209020.594 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-29T18:03:40.594Z,1638209020.594 [Default:CheckIn] Stopped
2021-11-29T18:03:40.594Z,1638209020.594 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-29T18:03:40.594Z,1638209020.594 [Default:CheckIn](INFO): Running loop #3
2021-11-29T18:03:40.594Z,1638209020.594 [Default:CheckIn] Running Loop=3
2021-11-29T18:03:40.595Z,1638209020.595 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-29T18:03:40.595Z,1638209020.595 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-29T18:03:42.596Z,1638209022.596 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,180342.00,A,3648.14029,N,12147.22889,W,0.078,196.73,291121,,,D*77
2021-11-29T18:03:42.598Z,1638209022.598 [NAL9602](INFO): GPS fix at 20211129T180342: (36.802338, -121.787148)
2021-11-29T18:03:42.610Z,1638209022.610 [Default:CheckIn:Read_GPS] Stopped
2021-11-29T18:03:42.610Z,1638209022.610 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-29T18:03:43.414Z,1638209023.414 [DAT](INFO): #Outgoing data=1
2021-11-29T18:03:43.414Z,1638209023.414 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-29T18:03:43.827Z,1638209023.827 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-29T18:03:44.238Z,1638209024.238 [DAT](INFO): DAT read: UART Wakeup

2021-11-29T18:03:44.239Z,1638209024.239 [DAT](INFO): DAT read: CONNECT 01200 bits/sec 1 of 4, Rate 1/2 CC

2021-11-29T18:03:44.240Z,1638209024.240 [DAT](INFO): commRate: 1200
2021-11-29T18:03:47.444Z,1638209027.444 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:03:11.3281

2021-11-29T18:03:47.445Z,1638209027.445 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-29T18:03:57.579Z,1638209037.579 [DAT](FAULT): Ack receipt timeout failure.
2021-11-29T18:03:57.579Z,1638209037.579 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED
2021-11-29T18:03:57.966Z,1638209037.966 [DAT](INFO): Sent 73 bytes from file Logs/20211129T173840/Courier0010.lzma.parts
2021-11-29T18:03:57.966Z,1638209037.966 [DAT](INFO): Packets left to send: 0
2021-11-29T18:03:57.969Z,1638209037.969 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-29T18:04:58.208Z,1638209098.208 [NAL9602](INFO): SBD MO Status=2, MOMSN=30478, MT Status=2, MTMSN=0
2021-11-29T18:04:58.208Z,1638209098.208 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T18:05:38.268Z,1638209138.268 [NAL9602](INFO): SBD MO Status=1, MOMSN=30478, MT Status=0, MTMSN=0
2021-11-29T18:05:38.321Z,1638209138.321 [NAL9602](INFO): Sent 168 bytes from file Logs/20211129T173840/Express0011.lzma
2021-11-29T18:05:38.321Z,1638209138.321 [NAL9602](INFO): Packets left to send: 0
2021-11-29T18:05:56.856Z,1638209156.856 [NAL9602](INFO): SBD MO Status=2, MOMSN=30479, MT Status=2, MTMSN=0
2021-11-29T18:05:56.856Z,1638209156.856 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T18:06:01.721Z,1638209161.721 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2021-11-29T18:06:24.324Z,1638209184.324 [NAL9602](INFO): SBD MO Status=2, MOMSN=30479, MT Status=2, MTMSN=0
2021-11-29T18:06:24.324Z,1638209184.324 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T18:06:43.313Z,1638209203.313 [NAL9602](INFO): SBD MO Status=0, MOMSN=30479, MT Status=0, MTMSN=0
2021-11-29T18:06:43.546Z,1638209203.546 [Default:CheckIn:Read_Iridium] Stopped
2021-11-29T18:06:43.546Z,1638209203.546 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-29T18:06:43.546Z,1638209203.546 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-29T18:06:47.351Z,1638209207.351 [DAT](INFO): DAT read: Lowpower

2021-11-29T18:06:47.352Z,1638209207.352 [DAT](INFO): unknown deviceResponse_: Lowpower

2021-11-29T18:07:14.018Z,1638209234.018 [NAL9602](INFO): Not Powering down - fast GPS
2021-11-29T18:08:53.398Z,1638209333.398 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2021-11-29T18:08:53.398Z,1638209333.398 [DropWeight] Hardware Fault, FailCount= 1
2021-11-29T18:08:53.398Z,1638209333.398 [DropWeight](ERROR): Hardware Fault
2021-11-29T18:08:53.491Z,1638209333.491 [CommandExec](FAULT): Scheduling is paused
2021-11-29T18:08:53.491Z,1638209333.491 [CBIT](INFO): Critical error at 20211129T180853
2021-11-29T18:08:53.492Z,1638209333.492 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2021-11-29T18:08:53.499Z,1638209333.499 [CBIT](ERROR): Hardware Fault in component: DropWeight
2021-11-29T18:08:53.499Z,1638209333.499 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2021-11-29T18:08:53.857Z,1638209333.857 [CBIT](INFO): Critical error at 20211129T180853
2021-11-29T18:11:43.913Z,1638209503.913 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-29T18:11:43.913Z,1638209503.913 [Default:CheckIn:C.Wait] Stopped
2021-11-29T18:11:43.913Z,1638209503.913 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-29T18:11:43.914Z,1638209503.914 [Default:CheckIn:D] Running Loop=1
2021-11-29T18:11:44.306Z,1638209504.306 [Default:CheckIn:D] Stopped
2021-11-29T18:11:44.306Z,1638209504.306 [Default:CheckIn:E] Running Loop=1
2021-11-29T18:11:44.709Z,1638209504.709 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 29.967196 min 
2021-11-29T18:11:44.709Z,1638209504.709 [Default:CheckIn:E] Stopped
2021-11-29T18:11:44.709Z,1638209504.709 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-29T18:11:44.709Z,1638209504.709 [Default:CheckIn] Stopped
2021-11-29T18:11:44.709Z,1638209504.709 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-29T18:11:44.710Z,1638209504.710 [Default:CheckIn](INFO): Running loop #4
2021-11-29T18:11:44.710Z,1638209504.710 [Default:CheckIn] Running Loop=4
2021-11-29T18:11:44.710Z,1638209504.710 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-29T18:11:44.710Z,1638209504.710 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-29T18:16:05.679Z,1638209765.679 [NAL9602](INFO): SBD MO Status=0, MOMSN=30480, MT Status=0, MTMSN=0
2021-11-29T18:16:05.679Z,1638209765.679 [NAL9602](INFO): No messages in MT queue
2021-11-29T18:16:06.896Z,1638209766.896 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181607.00,A,3648.14073,N,12147.22904,W,0.194,0.00,291121,,,D*70
2021-11-29T18:16:06.908Z,1638209766.908 [NAL9602](INFO): GPS fix at 20211129T181607: (36.802346, -121.787151)
2021-11-29T18:16:06.920Z,1638209766.920 [Default:CheckIn:Read_GPS] Stopped
2021-11-29T18:16:06.920Z,1638209766.920 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-29T18:16:07.707Z,1638209767.707 [DAT](INFO): #Outgoing data=1
2021-11-29T18:16:07.707Z,1638209767.707 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-29T18:16:08.112Z,1638209768.112 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-29T18:16:08.511Z,1638209768.511 [DAT](INFO): DAT read: UART Wakeup

2021-11-29T18:16:08.512Z,1638209768.512 [DAT](INFO): DAT read: CONNECT 01200 bits/sec 1 of 4, Rate 1/2 CC

2021-11-29T18:16:08.513Z,1638209768.513 [DAT](INFO): commRate: 1200
2021-11-29T18:16:12.955Z,1638209772.955 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:15:36.4298

2021-11-29T18:16:12.955Z,1638209772.955 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-29T18:16:23.126Z,1638209783.126 [DAT](FAULT): Ack receipt timeout failure.
2021-11-29T18:16:23.126Z,1638209783.126 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED
2021-11-29T18:16:23.528Z,1638209783.528 [DAT](INFO): Sent 179 bytes from file Logs/20211129T173840/Courier0013.lzma.parts
2021-11-29T18:16:23.528Z,1638209783.528 [DAT](INFO): Packets left to send: 0
2021-11-29T18:16:23.543Z,1638209783.543 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-29T18:16:25.550Z,1638209785.550 [NAL9602](INFO): SBD MO Status=1, MOMSN=30481, MT Status=0, MTMSN=0
2021-11-29T18:16:25.606Z,1638209785.606 [NAL9602](INFO): Sent 179 bytes from file Logs/20211129T173840/Courier0013.lzma
2021-11-29T18:16:25.607Z,1638209785.607 [NAL9602](INFO): Packets left to send: 0
2021-11-29T18:16:41.768Z,1638209801.768 [NAL9602](INFO): SBD MO Status=1, MOMSN=30482, MT Status=0, MTMSN=0
2021-11-29T18:16:41.822Z,1638209801.822 [NAL9602](INFO): Sent 190 bytes from file Logs/20211129T173840/Express0014.lzma
2021-11-29T18:16:41.822Z,1638209801.822 [NAL9602](INFO): Packets left to send: 0
2021-11-29T18:16:51.460Z,1638209811.460 [NAL9602](INFO): SBD MO Status=0, MOMSN=30483, MT Status=0, MTMSN=0
2021-11-29T18:16:51.556Z,1638209811.556 [Default:CheckIn:Read_Iridium] Stopped
2021-11-29T18:16:51.556Z,1638209811.556 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-29T18:16:51.556Z,1638209811.556 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-29T18:17:22.166Z,1638209842.166 [NAL9602](INFO): Not Powering down - fast GPS
2021-11-29T18:19:11.651Z,1638209951.651 [DAT](INFO): DAT read: Lowpower

2021-11-29T18:19:11.651Z,1638209951.651 [DAT](INFO): unknown deviceResponse_: Lowpower

2021-11-29T18:21:52.049Z,1638210112.049 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-29T18:21:52.049Z,1638210112.049 [Default:CheckIn:C.Wait] Stopped
2021-11-29T18:21:52.049Z,1638210112.049 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-29T18:21:52.049Z,1638210112.049 [Default:CheckIn:D] Running Loop=1
2021-11-29T18:21:52.461Z,1638210112.461 [Default:CheckIn:D] Stopped
2021-11-29T18:21:52.461Z,1638210112.461 [Default:CheckIn:E] Running Loop=1
2021-11-29T18:21:52.868Z,1638210112.868 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 40.103117 min 
2021-11-29T18:21:52.868Z,1638210112.868 [Default:CheckIn:E] Stopped
2021-11-29T18:21:52.868Z,1638210112.868 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-29T18:21:52.868Z,1638210112.868 [Default:CheckIn] Stopped
2021-11-29T18:21:52.868Z,1638210112.868 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-29T18:21:52.869Z,1638210112.869 [Default:CheckIn](INFO): Running loop #5
2021-11-29T18:21:52.869Z,1638210112.869 [Default:CheckIn] Running Loop=5
2021-11-29T18:21:52.869Z,1638210112.869 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-29T18:21:52.869Z,1638210112.869 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-29T18:21:54.871Z,1638210114.871 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182155.00,A,3648.13701,N,12147.22941,W,0.233,0.00,291121,,,D*79
2021-11-29T18:21:54.874Z,1638210114.874 [NAL9602](INFO): GPS fix at 20211129T182155: (36.802284, -121.787157)
2021-11-29T18:21:54.886Z,1638210114.886 [Default:CheckIn:Read_GPS] Stopped
2021-11-29T18:21:54.886Z,1638210114.886 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-29T18:21:55.688Z,1638210115.688 [DAT](INFO): #Outgoing data=1
2021-11-29T18:21:55.689Z,1638210115.689 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-29T18:21:56.080Z,1638210116.080 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-29T18:21:56.491Z,1638210116.491 [DAT](INFO): DAT read: UART Wakeup

2021-11-29T18:21:56.493Z,1638210116.493 [DAT](INFO): DAT read: CONNECT 01200 bits/sec 1 of 4, Rate 1/2 CC

2021-11-29T18:21:56.493Z,1638210116.493 [DAT](INFO): commRate: 1200
2021-11-29T18:21:59.722Z,1638210119.722 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:21:24.3320

2021-11-29T18:21:59.722Z,1638210119.722 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-29T18:22:09.820Z,1638210129.820 [DAT](FAULT): Ack receipt timeout failure.
2021-11-29T18:22:09.820Z,1638210129.820 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED
2021-11-29T18:22:10.221Z,1638210130.221 [DAT](INFO): Sent 73 bytes from file Logs/20211129T173840/Courier0016.lzma.parts
2021-11-29T18:22:10.221Z,1638210130.221 [DAT](INFO): Packets left to send: 0
2021-11-29T18:22:10.224Z,1638210130.224 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-29T18:22:49.056Z,1638210169.056 [NAL9602](INFO): SBD MO Status=2, MOMSN=30484, MT Status=2, MTMSN=0
2021-11-29T18:22:49.056Z,1638210169.056 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T18:23:52.556Z,1638210232.556 [NAL9602](INFO): SBD MO Status=2, MOMSN=30484, MT Status=2, MTMSN=0
2021-11-29T18:23:52.556Z,1638210232.556 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T18:23:53.480Z,1638210233.480 [CBIT](INFO): Clearing failed state for component DropWeight
2021-11-29T18:23:53.480Z,1638210233.480 [DropWeight] No Fault, FailCount= 1
2021-11-29T18:24:18.502Z,1638210258.502 [NAL9602](INFO): SBD MO Status=2, MOMSN=30484, MT Status=2, MTMSN=0
2021-11-29T18:24:18.502Z,1638210258.502 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T18:24:43.584Z,1638210283.584 [NAL9602](INFO): SBD MO Status=2, MOMSN=30484, MT Status=2, MTMSN=0
2021-11-29T18:24:43.584Z,1638210283.584 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T18:24:59.461Z,1638210299.461 [DAT](INFO): DAT read: Lowpower

2021-11-29T18:24:59.461Z,1638210299.461 [DAT](INFO): unknown deviceResponse_: Lowpower

2021-11-29T18:25:03.520Z,1638210303.520 [NAL9602](INFO): SBD MO Status=1, MOMSN=30484, MT Status=0, MTMSN=0
2021-11-29T18:25:03.573Z,1638210303.573 [NAL9602](INFO): Sent 162 bytes from file Logs/20211129T173840/Express0017.lzma
2021-11-29T18:25:03.573Z,1638210303.573 [NAL9602](INFO): Packets left to send: 0
2021-11-29T18:25:22.492Z,1638210322.492 [NAL9602](INFO): SBD MO Status=2, MOMSN=30485, MT Status=2, MTMSN=0
2021-11-29T18:25:22.492Z,1638210322.492 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T18:25:26.955Z,1638210326.955 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2021-11-29T18:25:52.392Z,1638210352.392 [NAL9602](INFO): SBD MO Status=0, MOMSN=30485, MT Status=0, MTMSN=0
2021-11-29T18:25:52.670Z,1638210352.670 [Default:CheckIn:Read_Iridium] Stopped
2021-11-29T18:25:52.670Z,1638210352.670 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-29T18:25:52.670Z,1638210352.670 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-29T18:26:23.091Z,1638210383.091 [NAL9602](INFO): Not Powering down - fast GPS
2021-11-29T18:30:53.046Z,1638210653.046 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-29T18:30:53.046Z,1638210653.046 [Default:CheckIn:C.Wait] Stopped
2021-11-29T18:30:53.046Z,1638210653.046 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-29T18:30:53.046Z,1638210653.046 [Default:CheckIn:D] Running Loop=1
2021-11-29T18:30:53.387Z,1638210653.387 [Default:CheckIn:D] Stopped
2021-11-29T18:30:53.387Z,1638210653.387 [Default:CheckIn:E] Running Loop=1
2021-11-29T18:30:53.863Z,1638210653.863 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 49.118542 min 
2021-11-29T18:30:53.863Z,1638210653.863 [Default:CheckIn:E] Stopped
2021-11-29T18:30:53.863Z,1638210653.863 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-29T18:30:53.863Z,1638210653.863 [Default:CheckIn] Stopped
2021-11-29T18:30:53.863Z,1638210653.863 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-29T18:30:53.863Z,1638210653.863 [Default:CheckIn](INFO): Running loop #6
2021-11-29T18:30:53.864Z,1638210653.864 [Default:CheckIn] Running Loop=6
2021-11-29T18:30:53.864Z,1638210653.864 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-29T18:30:53.864Z,1638210653.864 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-29T18:30:55.804Z,1638210655.804 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183055.00,A,3648.14173,N,12147.22521,W,0.039,0.00,291121,,,D*7F
2021-11-29T18:30:55.807Z,1638210655.807 [NAL9602](INFO): GPS fix at 20211129T183055: (36.802362, -121.787087)
2021-11-29T18:30:55.819Z,1638210655.819 [Default:CheckIn:Read_GPS] Stopped
2021-11-29T18:30:55.819Z,1638210655.819 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-29T18:30:56.628Z,1638210656.628 [DAT](INFO): #Outgoing data=1
2021-11-29T18:30:56.628Z,1638210656.628 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-29T18:30:57.012Z,1638210657.012 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-29T18:30:57.422Z,1638210657.422 [DAT](INFO): DAT read: UART Wakeup

2021-11-29T18:30:57.423Z,1638210657.423 [DAT](INFO): DAT read: CONNECT 01200 bits/sec 1 of 4, Rate 1/2 CC

2021-11-29T18:30:57.424Z,1638210657.424 [DAT](INFO): commRate: 1200
2021-11-29T18:31:00.655Z,1638210660.655 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:30:24.3353

2021-11-29T18:31:00.655Z,1638210660.655 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-29T18:31:10.815Z,1638210670.815 [DAT](FAULT): Ack receipt timeout failure.
2021-11-29T18:31:10.816Z,1638210670.816 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED
2021-11-29T18:31:11.220Z,1638210671.220 [DAT](INFO): Sent 73 bytes from file Logs/20211129T173840/Courier0019.lzma.parts
2021-11-29T18:31:11.220Z,1638210671.220 [DAT](INFO): Packets left to send: 0
2021-11-29T18:31:11.223Z,1638210671.223 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-29T18:31:15.672Z,1638210675.672 [NAL9602](INFO): SBD MO Status=1, MOMSN=30486, MT Status=0, MTMSN=0
2021-11-29T18:31:15.726Z,1638210675.726 [NAL9602](INFO): Sent 73 bytes from file Logs/20211129T173840/Courier0019.lzma
2021-11-29T18:31:15.727Z,1638210675.727 [NAL9602](INFO): Packets left to send: 0
2021-11-29T18:31:34.299Z,1638210694.299 [NAL9602](INFO): SBD MO Status=2, MOMSN=30487, MT Status=2, MTMSN=0
2021-11-29T18:31:34.299Z,1638210694.299 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T18:31:58.988Z,1638210718.988 [NAL9602](INFO): SBD MO Status=2, MOMSN=30487, MT Status=2, MTMSN=0
2021-11-29T18:31:58.988Z,1638210718.988 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T18:32:10.756Z,1638210730.756 [NAL9602](INFO): SBD MO Status=1, MOMSN=30487, MT Status=0, MTMSN=0
2021-11-29T18:32:10.813Z,1638210730.813 [NAL9602](INFO): Sent 163 bytes from file Logs/20211129T173840/Express0020.lzma
2021-11-29T18:32:10.814Z,1638210730.814 [NAL9602](INFO): Packets left to send: 0
2021-11-29T18:32:29.743Z,1638210749.743 [NAL9602](INFO): SBD MO Status=2, MOMSN=30488, MT Status=2, MTMSN=0
2021-11-29T18:32:29.744Z,1638210749.744 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T18:32:41.056Z,1638210761.056 [NAL9602](INFO): SBD MO Status=0, MOMSN=30488, MT Status=0, MTMSN=0
2021-11-29T18:32:41.155Z,1638210761.155 [Default:CheckIn:Read_Iridium] Stopped
2021-11-29T18:32:41.155Z,1638210761.155 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-29T18:32:41.155Z,1638210761.155 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-29T18:33:11.766Z,1638210791.766 [NAL9602](INFO): Not Powering down - fast GPS
2021-11-29T18:34:00.247Z,1638210840.247 [DAT](INFO): DAT read: Lowpower

2021-11-29T18:34:00.247Z,1638210840.247 [DAT](INFO): unknown deviceResponse_: Lowpower

2021-11-29T18:37:41.661Z,1638211061.661 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-29T18:37:41.661Z,1638211061.661 [Default:CheckIn:C.Wait] Stopped
2021-11-29T18:37:41.661Z,1638211061.661 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-29T18:37:41.661Z,1638211061.661 [Default:CheckIn:D] Running Loop=1
2021-11-29T18:37:42.081Z,1638211062.081 [Default:CheckIn:D] Stopped
2021-11-29T18:37:42.081Z,1638211062.081 [Default:CheckIn:E] Running Loop=1
2021-11-29T18:37:42.462Z,1638211062.462 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 55.930111 min 
2021-11-29T18:37:42.462Z,1638211062.462 [Default:CheckIn:E] Stopped
2021-11-29T18:37:42.462Z,1638211062.462 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-29T18:37:42.462Z,1638211062.462 [Default:CheckIn] Stopped
2021-11-29T18:37:42.462Z,1638211062.462 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-29T18:37:42.462Z,1638211062.462 [Default:CheckIn](INFO): Running loop #7
2021-11-29T18:37:42.463Z,1638211062.463 [Default:CheckIn] Running Loop=7
2021-11-29T18:37:42.463Z,1638211062.463 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-29T18:37:42.463Z,1638211062.463 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-29T18:37:44.475Z,1638211064.475 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183744.00,A,3648.13946,N,12147.22837,W,0.019,0.00,291121,,,D*79
2021-11-29T18:37:44.477Z,1638211064.477 [NAL9602](INFO): GPS fix at 20211129T183744: (36.802324, -121.787139)
2021-11-29T18:37:44.489Z,1638211064.489 [Default:CheckIn:Read_GPS] Stopped
2021-11-29T18:37:44.489Z,1638211064.489 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-29T18:37:45.289Z,1638211065.289 [DAT](INFO): #Outgoing data=1
2021-11-29T18:37:45.289Z,1638211065.289 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-29T18:37:45.692Z,1638211065.692 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-29T18:37:46.103Z,1638211066.103 [DAT](INFO): DAT read: UART Wakeup

2021-11-29T18:37:46.105Z,1638211066.105 [DAT](INFO): DAT read: CONNECT 01200 bits/sec 1 of 4, Rate 1/2 CC

2021-11-29T18:37:46.106Z,1638211066.106 [DAT](INFO): commRate: 1200
2021-11-29T18:37:48.932Z,1638211068.932 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:37:13.3295

2021-11-29T18:37:48.932Z,1638211068.932 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-29T18:37:59.068Z,1638211079.068 [DAT](FAULT): Ack receipt timeout failure.
2021-11-29T18:37:59.068Z,1638211079.068 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED
2021-11-29T18:37:59.472Z,1638211079.472 [DAT](INFO): Sent 72 bytes from file Logs/20211129T173840/Courier0022.lzma.parts
2021-11-29T18:37:59.472Z,1638211079.472 [DAT](INFO): Packets left to send: 0
2021-11-29T18:37:59.475Z,1638211079.475 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-29T18:38:07.960Z,1638211087.960 [NAL9602](INFO): SBD MO Status=1, MOMSN=30489, MT Status=0, MTMSN=0
2021-11-29T18:38:08.014Z,1638211088.014 [NAL9602](INFO): Sent 72 bytes from file Logs/20211129T173840/Courier0022.lzma
2021-11-29T18:38:08.014Z,1638211088.014 [NAL9602](INFO): Packets left to send: 0
2021-11-29T18:38:28.632Z,1638211108.632 [NAL9602](INFO): SBD MO Status=1, MOMSN=30490, MT Status=0, MTMSN=0
2021-11-29T18:38:28.701Z,1638211108.701 [NAL9602](INFO): Sent 163 bytes from file Logs/20211129T173840/Express0023.lzma
2021-11-29T18:38:28.702Z,1638211108.702 [NAL9602](INFO): Packets left to send: 0
2021-11-29T18:38:38.328Z,1638211118.328 [NAL9602](INFO): SBD MO Status=0, MOMSN=30491, MT Status=0, MTMSN=0
2021-11-29T18:38:38.462Z,1638211118.462 [Default:CheckIn:Read_Iridium] Stopped
2021-11-29T18:38:38.462Z,1638211118.462 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-29T18:38:38.462Z,1638211118.462 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-29T18:39:09.030Z,1638211149.030 [NAL9602](INFO): Not Powering down - fast GPS
2021-11-29T18:40:49.235Z,1638211249.235 [DAT](INFO): DAT read: Lowpower

2021-11-29T18:40:49.235Z,1638211249.235 [DAT](INFO): unknown deviceResponse_: Lowpower

2021-11-29T18:43:38.938Z,1638211418.938 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-29T18:43:38.938Z,1638211418.938 [Default:CheckIn:C.Wait] Stopped
2021-11-29T18:43:38.938Z,1638211418.938 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-29T18:43:38.939Z,1638211418.939 [Default:CheckIn:D] Running Loop=1
2021-11-29T18:43:39.330Z,1638211419.330 [Default:CheckIn:D] Stopped
2021-11-29T18:43:39.330Z,1638211419.330 [Default:CheckIn:E] Running Loop=1
2021-11-29T18:43:39.738Z,1638211419.738 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 61.884261 min 
2021-11-29T18:43:39.738Z,1638211419.738 [Default:CheckIn:E] Stopped
2021-11-29T18:43:39.738Z,1638211419.738 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-29T18:43:39.738Z,1638211419.738 [Default:CheckIn] Stopped
2021-11-29T18:43:39.739Z,1638211419.739 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-29T18:43:39.739Z,1638211419.739 [Default:CheckIn](INFO): Running loop #8
2021-11-29T18:43:39.739Z,1638211419.739 [Default:CheckIn] Running Loop=8
2021-11-29T18:43:39.739Z,1638211419.739 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-29T18:43:39.739Z,1638211419.739 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-29T18:43:41.752Z,1638211421.752 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184341.00,A,3648.14152,N,12147.22853,W,0.019,0.00,291121,,,D*77
2021-11-29T18:43:41.754Z,1638211421.754 [NAL9602](INFO): GPS fix at 20211129T184341: (36.802359, -121.787142)
2021-11-29T18:43:41.767Z,1638211421.767 [Default:CheckIn:Read_GPS] Stopped
2021-11-29T18:43:41.767Z,1638211421.767 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-29T18:43:42.561Z,1638211422.561 [DAT](INFO): #Outgoing data=1
2021-11-29T18:43:42.561Z,1638211422.561 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-29T18:43:42.956Z,1638211422.956 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-29T18:43:43.368Z,1638211423.368 [DAT](INFO): DAT read: UART Wakeup

2021-11-29T18:43:43.369Z,1638211423.369 [DAT](INFO): DAT read: CONNECT 01200 bits/sec 1 of 4, Rate 1/2 CC

2021-11-29T18:43:43.369Z,1638211423.369 [DAT](INFO): commRate: 1200
2021-11-29T18:43:46.198Z,1638211426.198 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:43:10.3300

2021-11-29T18:43:46.198Z,1638211426.198 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-29T18:43:56.351Z,1638211436.351 [DAT](FAULT): Ack receipt timeout failure.
2021-11-29T18:43:56.351Z,1638211436.351 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED
2021-11-29T18:43:56.763Z,1638211436.763 [DAT](INFO): Sent 74 bytes from file Logs/20211129T173840/Courier0025.lzma.parts
2021-11-29T18:43:56.763Z,1638211436.763 [DAT](INFO): Packets left to send: 0
2021-11-29T18:43:56.765Z,1638211436.765 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-29T18:44:08.473Z,1638211448.473 [NAL9602](INFO): SBD MO Status=1, MOMSN=30492, MT Status=0, MTMSN=0
2021-11-29T18:44:08.541Z,1638211448.541 [NAL9602](INFO): Sent 74 bytes from file Logs/20211129T173840/Courier0025.lzma
2021-11-29T18:44:08.541Z,1638211448.541 [NAL9602](INFO): Packets left to send: 0
2021-11-29T18:44:17.032Z,1638211457.032 [NAL9602](INFO): SBD MO Status=1, MOMSN=30493, MT Status=0, MTMSN=0
2021-11-29T18:44:17.082Z,1638211457.082 [NAL9602](INFO): Sent 165 bytes from file Logs/20211129T173840/Express0026.lzma
2021-11-29T18:44:17.082Z,1638211457.082 [NAL9602](INFO): Packets left to send: 0
2021-11-29T18:44:34.408Z,1638211474.408 [NAL9602](INFO): SBD MO Status=2, MOMSN=30494, MT Status=2, MTMSN=0
2021-11-29T18:44:34.408Z,1638211474.408 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T18:44:52.588Z,1638211492.588 [NAL9602](INFO): SBD MO Status=0, MOMSN=30494, MT Status=0, MTMSN=0
2021-11-29T18:44:52.680Z,1638211492.680 [Default:CheckIn:Read_Iridium] Stopped
2021-11-29T18:44:52.680Z,1638211492.680 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-29T18:44:52.680Z,1638211492.680 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-29T18:45:23.286Z,1638211523.286 [NAL9602](INFO): Not Powering down - fast GPS
2021-11-29T18:46:46.195Z,1638211606.195 [DAT](INFO): DAT read: Lowpower

2021-11-29T18:46:46.195Z,1638211606.195 [DAT](INFO): unknown deviceResponse_: Lowpower

2021-11-29T18:49:42.252Z,1638211782.252 [BPC1](ERROR): BPC1B: No match for serial number 1717 in BPC1B's battery stick inventory (sticks 32-63 in onboard configuration file).
2021-11-29T18:49:53.222Z,1638211793.222 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-29T18:49:53.222Z,1638211793.222 [Default:CheckIn:C.Wait] Stopped
2021-11-29T18:49:53.222Z,1638211793.222 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-29T18:49:53.223Z,1638211793.223 [Default:CheckIn:D] Running Loop=1
2021-11-29T18:49:53.594Z,1638211793.594 [Default:CheckIn:D] Stopped
2021-11-29T18:49:53.594Z,1638211793.594 [Default:CheckIn:E] Running Loop=1
2021-11-29T18:49:54.004Z,1638211794.004 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 68.122001 min 
2021-11-29T18:49:54.004Z,1638211794.004 [Default:CheckIn:E] Stopped
2021-11-29T18:49:54.004Z,1638211794.004 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-29T18:49:54.004Z,1638211794.004 [Default:CheckIn] Stopped
2021-11-29T18:49:54.004Z,1638211794.004 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-29T18:49:54.004Z,1638211794.004 [Default:CheckIn](INFO): Running loop #9
2021-11-29T18:49:54.004Z,1638211794.004 [Default:CheckIn] Running Loop=9
2021-11-29T18:49:54.004Z,1638211794.004 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-29T18:49:54.005Z,1638211794.005 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-29T18:49:56.000Z,1638211796.000 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184956.00,A,3648.14024,N,12147.22895,W,0.039,0.00,291121,,,D*73
2021-11-29T18:49:56.003Z,1638211796.003 [NAL9602](INFO): GPS fix at 20211129T184956: (36.802337, -121.787149)
2021-11-29T18:49:56.015Z,1638211796.015 [Default:CheckIn:Read_GPS] Stopped
2021-11-29T18:49:56.015Z,1638211796.015 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-29T18:49:56.830Z,1638211796.830 [DAT](INFO): #Outgoing data=1
2021-11-29T18:49:56.830Z,1638211796.830 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-29T18:49:57.231Z,1638211797.231 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-29T18:49:57.604Z,1638211797.604 [DAT](INFO): DAT read: UAR Wakeup

2021-11-29T18:49:57.604Z,1638211797.604 [DAT](INFO): unknown deviceResponse_: UAR Wakeup

2021-11-29T18:49:57.605Z,1638211797.605 [DAT](INFO): DAT read: CONECT 01200 bits/sec 1 of 4, Rate 1/2 CC

2021-11-29T18:49:57.606Z,1638211797.606 [DAT](INFO): unknown deviceResponse_: CONECT 01200 bits/sec 1 of 4, Rate 1/2 CC

2021-11-29T18:50:00.836Z,1638211800.836 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:49:25.3320

2021-11-29T18:50:00.836Z,1638211800.836 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-29T18:50:10.979Z,1638211810.979 [DAT](FAULT): Ack receipt timeout failure.
2021-11-29T18:50:10.979Z,1638211810.979 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED
2021-11-29T18:50:11.380Z,1638211811.380 [DAT](INFO): Sent 72 bytes from file Logs/20211129T173840/Courier0028.lzma.parts
2021-11-29T18:50:11.380Z,1638211811.380 [DAT](INFO): Packets left to send: 0
2021-11-29T18:50:11.383Z,1638211811.383 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-29T18:50:12.192Z,1638211812.192 [NAL9602](INFO): SBD MO Status=1, MOMSN=30495, MT Status=0, MTMSN=0
2021-11-29T18:50:12.249Z,1638211812.249 [NAL9602](INFO): Sent 72 bytes from file Logs/20211129T173840/Courier0028.lzma
2021-11-29T18:50:12.250Z,1638211812.250 [NAL9602](INFO): Packets left to send: 0
2021-11-29T18:50:29.209Z,1638211829.209 [NAL9602](INFO): SBD MO Status=2, MOMSN=30496, MT Status=2, MTMSN=0
2021-11-29T18:50:29.209Z,1638211829.209 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T18:50:47.880Z,1638211847.880 [NAL9602](INFO): SBD MO Status=1, MOMSN=30496, MT Status=0, MTMSN=0
2021-11-29T18:50:47.930Z,1638211847.930 [NAL9602](INFO): Sent 161 bytes from file Logs/20211129T173840/Express0029.lzma
2021-11-29T18:50:47.930Z,1638211847.930 [NAL9602](INFO): Packets left to send: 0
2021-11-29T18:50:56.348Z,1638211856.348 [NAL9602](INFO): SBD MO Status=0, MOMSN=30497, MT Status=0, MTMSN=0
2021-11-29T18:50:56.495Z,1638211856.495 [Default:CheckIn:Read_Iridium] Stopped
2021-11-29T18:50:56.495Z,1638211856.495 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-29T18:50:56.495Z,1638211856.495 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-29T18:51:27.057Z,1638211887.057 [NAL9602](INFO): Not Powering down - fast GPS
2021-11-29T18:52:35.744Z,1638211955.744 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2021-11-29T18:52:35.747Z,1638211955.747 [BPC1](INFO): Received data from all battery sticks.
2021-11-29T18:53:00.788Z,1638211980.788 [DAT](INFO): DAT read: Lowpower

2021-11-29T18:53:00.788Z,1638211980.788 [DAT](INFO): unknown deviceResponse_: Lowpower

2021-11-29T18:55:56.949Z,1638212156.949 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-29T18:55:56.949Z,1638212156.949 [Default:CheckIn:C.Wait] Stopped
2021-11-29T18:55:56.949Z,1638212156.949 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-29T18:55:56.949Z,1638212156.949 [Default:CheckIn:D] Running Loop=1
2021-11-29T18:55:57.358Z,1638212157.358 [Default:CheckIn:D] Stopped
2021-11-29T18:55:57.358Z,1638212157.358 [Default:CheckIn:E] Running Loop=1
2021-11-29T18:55:57.764Z,1638212157.764 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 74.184733 min 
2021-11-29T18:55:57.765Z,1638212157.765 [Default:CheckIn:E] Stopped
2021-11-29T18:55:57.765Z,1638212157.765 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-29T18:55:57.765Z,1638212157.765 [Default:CheckIn] Stopped
2021-11-29T18:55:57.765Z,1638212157.765 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-29T18:55:57.765Z,1638212157.765 [Default:CheckIn](INFO): Running loop #10
2021-11-29T18:55:57.765Z,1638212157.765 [Default:CheckIn] Running Loop=10
2021-11-29T18:55:57.765Z,1638212157.765 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-29T18:55:57.766Z,1638212157.766 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-29T18:55:59.772Z,1638212159.772 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185600.00,A,3648.13903,N,12147.22805,W,0.039,0.00,291121,,,D*7C
2021-11-29T18:55:59.783Z,1638212159.783 [NAL9602](INFO): GPS fix at 20211129T185600: (36.802317, -121.787134)
2021-11-29T18:55:59.796Z,1638212159.796 [Default:CheckIn:Read_GPS] Stopped
2021-11-29T18:55:59.796Z,1638212159.796 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-29T18:56:00.586Z,1638212160.586 [DAT](INFO): #Outgoing data=1
2021-11-29T18:56:00.586Z,1638212160.586 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-29T18:56:00.980Z,1638212160.980 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-29T18:56:01.388Z,1638212161.388 [DAT](INFO): DAT read: UART Wakeup

2021-11-29T18:56:01.389Z,1638212161.389 [DAT](INFO): DAT read: CONNECT 01200 bits/sec 1 of 4, Rate 1/2 CC

2021-11-29T18:56:01.389Z,1638212161.389 [DAT](INFO): commRate: 1200
2021-11-29T18:56:04.616Z,1638212164.616 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:55:28.3329

2021-11-29T18:56:04.616Z,1638212164.616 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-29T18:56:14.769Z,1638212174.769 [DAT](FAULT): Ack receipt timeout failure.
2021-11-29T18:56:14.769Z,1638212174.769 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED
2021-11-29T18:56:15.180Z,1638212175.180 [DAT](INFO): Sent 85 bytes from file Logs/20211129T173840/Courier0031.lzma.parts
2021-11-29T18:56:15.180Z,1638212175.180 [DAT](INFO): Packets left to send: 0
2021-11-29T18:56:15.183Z,1638212175.183 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-29T18:56:23.656Z,1638212183.656 [NAL9602](INFO): SBD MO Status=2, MOMSN=30498, MT Status=2, MTMSN=0
2021-11-29T18:56:23.656Z,1638212183.656 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T18:56:48.768Z,1638212208.768 [NAL9602](INFO): SBD MO Status=2, MOMSN=30498, MT Status=2, MTMSN=0
2021-11-29T18:56:48.768Z,1638212208.768 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T18:57:00.536Z,1638212220.536 [NAL9602](INFO): SBD MO Status=1, MOMSN=30498, MT Status=0, MTMSN=0
2021-11-29T18:57:00.605Z,1638212220.605 [NAL9602](INFO): Sent 163 bytes from file Logs/20211129T173840/Express0032.lzma
2021-11-29T18:57:00.606Z,1638212220.606 [NAL9602](INFO): Packets left to send: 0
2021-11-29T18:57:07.805Z,1638212227.805 [NAL9602](INFO): SBD MO Status=0, MOMSN=30499, MT Status=0, MTMSN=0
2021-11-29T18:57:07.901Z,1638212227.901 [Default:CheckIn:Read_Iridium] Stopped
2021-11-29T18:57:07.913Z,1638212227.913 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-29T18:57:07.913Z,1638212227.913 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-29T18:57:38.512Z,1638212258.512 [NAL9602](INFO): Not Powering down - fast GPS
2021-11-29T18:59:04.163Z,1638212344.163 [DAT](INFO): DAT read: Lowpower

2021-11-29T18:59:04.164Z,1638212344.164 [DAT](INFO): unknown deviceResponse_: Lowpower

2021-11-29T19:02:08.394Z,1638212528.394 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-29T19:02:08.394Z,1638212528.394 [Default:CheckIn:C.Wait] Stopped
2021-11-29T19:02:08.394Z,1638212528.394 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-29T19:02:08.394Z,1638212528.394 [Default:CheckIn:D] Running Loop=1
2021-11-29T19:02:08.799Z,1638212528.799 [Default:CheckIn:D] Stopped
2021-11-29T19:02:08.799Z,1638212528.799 [Default:CheckIn:E] Running Loop=1
2021-11-29T19:02:09.210Z,1638212529.210 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 80.375415 min 
2021-11-29T19:02:09.210Z,1638212529.210 [Default:CheckIn:E] Stopped
2021-11-29T19:02:09.210Z,1638212529.210 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-29T19:02:09.210Z,1638212529.210 [Default:CheckIn] Stopped
2021-11-29T19:02:09.210Z,1638212529.210 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-29T19:02:09.211Z,1638212529.211 [Default:CheckIn](INFO): Running loop #11
2021-11-29T19:02:09.211Z,1638212529.211 [Default:CheckIn] Running Loop=11
2021-11-29T19:02:09.211Z,1638212529.211 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-29T19:02:09.211Z,1638212529.211 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-29T19:02:11.212Z,1638212531.212 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190211.00,A,3648.16450,N,12147.21359,W,0.039,51.09,291121,,,D*4E
2021-11-29T19:02:11.214Z,1638212531.214 [NAL9602](INFO): GPS fix at 20211129T190211: (36.802742, -121.786893)
2021-11-29T19:02:11.226Z,1638212531.226 [Default:CheckIn:Read_GPS] Stopped
2021-11-29T19:02:11.226Z,1638212531.226 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-29T19:02:12.027Z,1638212532.027 [DAT](INFO): #Outgoing data=1
2021-11-29T19:02:12.027Z,1638212532.027 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-29T19:02:12.419Z,1638212532.419 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-29T19:02:12.837Z,1638212532.837 [DAT](INFO): DAT read: UART Wakeup

2021-11-29T19:02:12.838Z,1638212532.838 [DAT](INFO): DAT read: CONNECT 01200 bits/sec 1 of 4, Rate 1/2 CC

2021-11-29T19:02:12.838Z,1638212532.838 [DAT](INFO): commRate: 1200
2021-11-29T19:02:16.060Z,1638212536.060 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:01:40.3338

2021-11-29T19:02:16.060Z,1638212536.060 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-29T19:02:26.200Z,1638212546.200 [DAT](FAULT): Ack receipt timeout failure.
2021-11-29T19:02:26.200Z,1638212546.200 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED
2021-11-29T19:02:26.604Z,1638212546.604 [DAT](INFO): Sent 73 bytes from file Logs/20211129T173840/Courier0034.lzma.parts
2021-11-29T19:02:26.604Z,1638212546.604 [DAT](INFO): Packets left to send: 0
2021-11-29T19:02:26.607Z,1638212546.607 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-29T19:02:37.523Z,1638212557.523 [NAL9602](INFO): SBD MO Status=2, MOMSN=30500, MT Status=2, MTMSN=0
2021-11-29T19:02:37.523Z,1638212557.523 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T19:03:46.648Z,1638212626.648 [NAL9602](INFO): SBD MO Status=2, MOMSN=30500, MT Status=2, MTMSN=0
2021-11-29T19:03:46.648Z,1638212626.648 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T19:04:03.682Z,1638212643.682 [NAL9602](INFO): SBD MO Status=2, MOMSN=30500, MT Status=2, MTMSN=0
2021-11-29T19:04:03.682Z,1638212643.682 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T19:04:29.596Z,1638212669.596 [NAL9602](INFO): SBD MO Status=2, MOMSN=30500, MT Status=2, MTMSN=0
2021-11-29T19:04:29.596Z,1638212669.596 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T19:04:49.444Z,1638212689.444 [NAL9602](INFO): SBD MO Status=1, MOMSN=30500, MT Status=0, MTMSN=0
2021-11-29T19:04:49.497Z,1638212689.497 [NAL9602](INFO): Sent 176 bytes from file Logs/20211129T173840/Express0035.lzma
2021-11-29T19:04:49.498Z,1638212689.498 [NAL9602](INFO): Packets left to send: 0
2021-11-29T19:05:04.397Z,1638212704.397 [NAL9602](INFO): SBD MO Status=2, MOMSN=30501, MT Status=2, MTMSN=0
2021-11-29T19:05:04.398Z,1638212704.398 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T19:05:08.856Z,1638212708.856 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2021-11-29T19:05:12.089Z,1638212712.089 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2021-11-29T19:05:15.706Z,1638212715.706 [DAT](INFO): DAT read: Lowpower

2021-11-29T19:05:15.706Z,1638212715.706 [DAT](INFO): unknown deviceResponse_: Lowpower

2021-11-29T19:05:30.250Z,1638212730.250 [NAL9602](INFO): SBD MO Status=2, MOMSN=30501, MT Status=2, MTMSN=0
2021-11-29T19:05:30.250Z,1638212730.250 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T19:05:35.116Z,1638212735.116 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2021-11-29T19:05:42.792Z,1638212742.792 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2021-11-29T19:05:52.484Z,1638212752.484 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2021-11-29T19:06:11.864Z,1638212771.864 [NAL9602](INFO): SBD MO Status=0, MOMSN=30501, MT Status=0, MTMSN=0
2021-11-29T19:06:12.094Z,1638212772.094 [Default:CheckIn:Read_Iridium] Stopped
2021-11-29T19:06:12.094Z,1638212772.094 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-29T19:06:12.094Z,1638212772.094 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-29T19:06:42.562Z,1638212802.562 [NAL9602](INFO): Not Powering down - fast GPS
2021-11-29T19:11:12.455Z,1638213072.455 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-29T19:11:12.455Z,1638213072.455 [Default:CheckIn:C.Wait] Stopped
2021-11-29T19:11:12.455Z,1638213072.455 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-29T19:11:12.455Z,1638213072.455 [Default:CheckIn:D] Running Loop=1
2021-11-29T19:11:12.866Z,1638213072.866 [Default:CheckIn:D] Stopped
2021-11-29T19:11:12.866Z,1638213072.866 [Default:CheckIn:E] Running Loop=1
2021-11-29T19:11:13.270Z,1638213073.270 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 89.443197 min 
2021-11-29T19:11:13.270Z,1638213073.270 [Default:CheckIn:E] Stopped
2021-11-29T19:11:13.270Z,1638213073.270 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-29T19:11:13.270Z,1638213073.270 [Default:CheckIn] Stopped
2021-11-29T19:11:13.270Z,1638213073.270 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-29T19:11:13.270Z,1638213073.270 [Default:CheckIn](INFO): Running loop #12
2021-11-29T19:11:13.270Z,1638213073.270 [Default:CheckIn] Running Loop=12
2021-11-29T19:11:13.271Z,1638213073.271 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-29T19:11:13.271Z,1638213073.271 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-29T19:11:15.276Z,1638213075.276 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191115.00,A,3648.16374,N,12147.21432,W,0.019,339.08,291121,,,D*7D
2021-11-29T19:11:15.279Z,1638213075.279 [NAL9602](INFO): GPS fix at 20211129T191115: (36.802729, -121.786905)
2021-11-29T19:11:15.319Z,1638213075.319 [Default:CheckIn:Read_GPS] Stopped
2021-11-29T19:11:15.319Z,1638213075.319 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-29T19:11:16.092Z,1638213076.092 [DAT](INFO): #Outgoing data=1
2021-11-29T19:11:16.092Z,1638213076.092 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-29T19:11:16.492Z,1638213076.492 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-29T19:11:16.910Z,1638213076.910 [DAT](INFO): DAT read: UART Wakeup

2021-11-29T19:11:16.911Z,1638213076.911 [DAT](INFO): DAT read: CONNECT 01200 bits/sec 1 of 4, Rate 1/2 CC

2021-11-29T19:11:16.912Z,1638213076.912 [DAT](INFO): commRate: 1200
2021-11-29T19:11:20.120Z,1638213080.120 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:10:44.3343

2021-11-29T19:11:20.120Z,1638213080.120 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-29T19:11:30.268Z,1638213090.268 [DAT](FAULT): Ack receipt timeout failure.
2021-11-29T19:11:30.268Z,1638213090.268 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED
2021-11-29T19:11:30.676Z,1638213090.676 [DAT](INFO): Sent 73 bytes from file Logs/20211129T173840/Courier0037.lzma.parts
2021-11-29T19:11:30.676Z,1638213090.676 [DAT](INFO): Packets left to send: 0
2021-11-29T19:11:30.679Z,1638213090.679 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-29T19:11:41.981Z,1638213101.981 [NAL9602](INFO): SBD MO Status=1, MOMSN=30502, MT Status=0, MTMSN=0
2021-11-29T19:11:42.041Z,1638213102.041 [NAL9602](INFO): Sent 73 bytes from file Logs/20211129T173840/Courier0037.lzma
2021-11-29T19:11:42.042Z,1638213102.042 [NAL9602](INFO): Packets left to send: 0
2021-11-29T19:11:50.132Z,1638213110.132 [NAL9602](INFO): SBD MO Status=1, MOMSN=30503, MT Status=0, MTMSN=0
2021-11-29T19:11:50.194Z,1638213110.194 [NAL9602](INFO): Sent 163 bytes from file Logs/20211129T173840/Express0038.lzma
2021-11-29T19:11:50.194Z,1638213110.194 [NAL9602](INFO): Packets left to send: 0
2021-11-29T19:11:59.424Z,1638213119.424 [NAL9602](INFO): SBD MO Status=0, MOMSN=30504, MT Status=0, MTMSN=0
2021-11-29T19:11:59.515Z,1638213119.515 [Default:CheckIn:Read_Iridium] Stopped
2021-11-29T19:11:59.515Z,1638213119.515 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-29T19:11:59.515Z,1638213119.515 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-29T19:12:30.126Z,1638213150.126 [NAL9602](INFO): Not Powering down - fast GPS
2021-11-29T19:14:20.015Z,1638213260.015 [DAT](INFO): DAT read: Lowpower

2021-11-29T19:14:20.016Z,1638213260.016 [DAT](INFO): unknown deviceResponse_: Lowpower

2021-11-29T19:17:00.018Z,1638213420.018 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-29T19:17:00.018Z,1638213420.018 [Default:CheckIn:C.Wait] Stopped
2021-11-29T19:17:00.018Z,1638213420.018 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-29T19:17:00.018Z,1638213420.018 [Default:CheckIn:D] Running Loop=1
2021-11-29T19:17:00.423Z,1638213420.423 [Default:CheckIn:D] Stopped
2021-11-29T19:17:00.423Z,1638213420.423 [Default:CheckIn:E] Running Loop=1
2021-11-29T19:17:00.828Z,1638213420.828 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 95.235807 min 
2021-11-29T19:17:00.828Z,1638213420.828 [Default:CheckIn:E] Stopped
2021-11-29T19:17:00.828Z,1638213420.828 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-29T19:17:00.828Z,1638213420.828 [Default:CheckIn] Stopped
2021-11-29T19:17:00.829Z,1638213420.829 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-29T19:17:00.829Z,1638213420.829 [Default:CheckIn](INFO): Running loop #13
2021-11-29T19:17:00.829Z,1638213420.829 [Default:CheckIn] Running Loop=13
2021-11-29T19:17:00.829Z,1638213420.829 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-29T19:17:00.829Z,1638213420.829 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-29T19:17:02.832Z,1638213422.832 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191703.00,A,3648.14270,N,12147.20185,W,0.039,222.17,291121,,,D*74
2021-11-29T19:17:02.835Z,1638213422.835 [NAL9602](INFO): GPS fix at 20211129T191703: (36.802378, -121.786698)
2021-11-29T19:17:02.846Z,1638213422.846 [Default:CheckIn:Read_GPS] Stopped
2021-11-29T19:17:02.846Z,1638213422.846 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-29T19:17:03.653Z,1638213423.653 [DAT](INFO): #Outgoing data=1
2021-11-29T19:17:03.653Z,1638213423.653 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-29T19:17:04.044Z,1638213424.044 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-29T19:17:04.452Z,1638213424.452 [DAT](INFO): DAT read: UART Wakeup

2021-11-29T19:17:04.453Z,1638213424.453 [DAT](INFO): DAT read: CONNECT 01200 bits/sec 1 of 4, Rate 1/2 CC

2021-11-29T19:17:04.453Z,1638213424.453 [DAT](INFO): commRate: 1200
2021-11-29T19:17:07.687Z,1638213427.687 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:16:32.3278

2021-11-29T19:17:07.687Z,1638213427.687 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-29T19:17:17.779Z,1638213437.779 [DAT](FAULT): Ack receipt timeout failure.
2021-11-29T19:17:17.779Z,1638213437.779 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED
2021-11-29T19:17:18.188Z,1638213438.188 [DAT](INFO): Sent 73 bytes from file Logs/20211129T173840/Courier0040.lzma.parts
2021-11-29T19:17:18.188Z,1638213438.188 [DAT](INFO): Packets left to send: 0
2021-11-29T19:17:18.190Z,1638213438.190 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-29T19:17:37.633Z,1638213457.633 [NAL9602](INFO): SBD MO Status=1, MOMSN=30505, MT Status=0, MTMSN=0
2021-11-29T19:17:37.690Z,1638213457.690 [NAL9602](INFO): Sent 176 bytes from file Logs/20211129T173840/Express0041.lzma
2021-11-29T19:17:37.690Z,1638213457.690 [NAL9602](INFO): Packets left to send: 0
2021-11-29T19:17:51.368Z,1638213471.368 [NAL9602](INFO): SBD MO Status=2, MOMSN=30506, MT Status=2, MTMSN=0
2021-11-29T19:17:51.368Z,1638213471.368 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T19:18:03.092Z,1638213483.092 [NAL9602](INFO): SBD MO Status=0, MOMSN=30506, MT Status=0, MTMSN=0
2021-11-29T19:18:03.200Z,1638213483.200 [Default:CheckIn:Read_Iridium] Stopped
2021-11-29T19:18:03.200Z,1638213483.200 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-29T19:18:03.200Z,1638213483.200 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-29T19:18:33.790Z,1638213513.790 [NAL9602](INFO): Not Powering down - fast GPS
2021-11-29T19:20:07.522Z,1638213607.522 [DAT](INFO): DAT read: Lowpower

2021-11-29T19:20:07.523Z,1638213607.523 [DAT](INFO): unknown deviceResponse_: Lowpower

2021-11-29T19:23:03.693Z,1638213783.693 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-29T19:23:03.693Z,1638213783.693 [Default:CheckIn:C.Wait] Stopped
2021-11-29T19:23:03.693Z,1638213783.693 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-29T19:23:03.694Z,1638213783.694 [Default:CheckIn:D] Running Loop=1
2021-11-29T19:23:04.098Z,1638213784.098 [Default:CheckIn:D] Stopped
2021-11-29T19:23:04.098Z,1638213784.098 [Default:CheckIn:E] Running Loop=1
2021-11-29T19:23:04.509Z,1638213784.509 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 101.297054 min 
2021-11-29T19:23:04.509Z,1638213784.509 [Default:CheckIn:E] Stopped
2021-11-29T19:23:04.510Z,1638213784.510 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-29T19:23:04.510Z,1638213784.510 [Default:CheckIn] Stopped
2021-11-29T19:23:04.510Z,1638213784.510 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-29T19:23:04.510Z,1638213784.510 [Default:CheckIn](INFO): Running loop #14
2021-11-29T19:23:04.510Z,1638213784.510 [Default:CheckIn] Running Loop=14
2021-11-29T19:23:04.510Z,1638213784.510 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-29T19:23:04.510Z,1638213784.510 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-29T19:23:06.513Z,1638213786.513 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,192306.00,A,3648.14280,N,12147.20147,W,0.019,222.17,291121,,,D*75
2021-11-29T19:23:06.515Z,1638213786.515 [NAL9602](INFO): GPS fix at 20211129T192306: (36.802380, -121.786691)
2021-11-29T19:23:06.526Z,1638213786.526 [Default:CheckIn:Read_GPS] Stopped
2021-11-29T19:23:06.527Z,1638213786.527 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-29T19:23:07.340Z,1638213787.340 [DAT](INFO): #Outgoing data=1
2021-11-29T19:23:07.340Z,1638213787.340 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-29T19:23:07.742Z,1638213787.742 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-29T19:23:08.154Z,1638213788.154 [DAT](INFO): DAT read: URT Wakeup

2021-11-29T19:23:08.155Z,1638213788.155 [DAT](INFO): unknown deviceResponse_: URT Wakeup

2021-11-29T19:23:08.156Z,1638213788.156 [DAT](INFO): DAT read: ONNECT 01200 bits/sec 1 f 4, Rate 1/2 CC

2021-11-29T19:23:08.156Z,1638213788.156 [DAT](INFO): unknown deviceResponse_: ONNECT 01200 bits/sec 1 f 4, Rate 1/2 CC

2021-11-29T19:23:11.360Z,1638213791.360 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:22:35.3291

2021-11-29T19:23:11.360Z,1638213791.360 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-29T19:23:21.494Z,1638213801.494 [DAT](FAULT): Ack receipt timeout failure.
2021-11-29T19:23:21.494Z,1638213801.494 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED
2021-11-29T19:23:21.881Z,1638213801.881 [DAT](INFO): Sent 72 bytes from file Logs/20211129T173840/Courier0043.lzma.parts
2021-11-29T19:23:21.881Z,1638213801.881 [DAT](INFO): Packets left to send: 0
2021-11-29T19:23:21.884Z,1638213801.884 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-29T19:23:56.664Z,1638213836.664 [NAL9602](INFO): SBD MO Status=1, MOMSN=30507, MT Status=0, MTMSN=0
2021-11-29T19:23:56.721Z,1638213836.721 [NAL9602](INFO): Sent 162 bytes from file Logs/20211129T173840/Express0044.lzma
2021-11-29T19:23:56.721Z,1638213836.721 [NAL9602](INFO): Packets left to send: 0
2021-11-29T19:24:08.788Z,1638213848.788 [NAL9602](INFO): SBD MO Status=0, MOMSN=30508, MT Status=0, MTMSN=0
2021-11-29T19:24:08.887Z,1638213848.887 [Default:CheckIn:Read_Iridium] Stopped
2021-11-29T19:24:08.887Z,1638213848.887 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-29T19:24:08.888Z,1638213848.888 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-29T19:24:39.488Z,1638213879.488 [NAL9602](INFO): Not Powering down - fast GPS
2021-11-29T19:26:11.205Z,1638213971.205 [DAT](INFO): DAT read: Lowpower

2021-11-29T19:26:11.205Z,1638213971.205 [DAT](INFO): unknown deviceResponse_: Lowpower

2021-11-29T19:29:09.379Z,1638214149.379 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-29T19:29:09.379Z,1638214149.379 [Default:CheckIn:C.Wait] Stopped
2021-11-29T19:29:09.379Z,1638214149.379 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-29T19:29:09.380Z,1638214149.380 [Default:CheckIn:D] Running Loop=1
2021-11-29T19:29:09.781Z,1638214149.781 [Default:CheckIn:D] Stopped
2021-11-29T19:29:09.782Z,1638214149.782 [Default:CheckIn:E] Running Loop=1
2021-11-29T19:29:10.187Z,1638214150.187 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 107.391789 min 
2021-11-29T19:29:10.187Z,1638214150.187 [Default:CheckIn:E] Stopped
2021-11-29T19:29:10.187Z,1638214150.187 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-29T19:29:10.187Z,1638214150.187 [Default:CheckIn] Stopped
2021-11-29T19:29:10.187Z,1638214150.187 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-29T19:29:10.187Z,1638214150.187 [Default:CheckIn](INFO): Running loop #15
2021-11-29T19:29:10.187Z,1638214150.187 [Default:CheckIn] Running Loop=15
2021-11-29T19:29:10.187Z,1638214150.187 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-29T19:29:10.188Z,1638214150.188 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-29T19:29:12.209Z,1638214152.209 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,192912.00,A,3648.14226,N,12147.20369,W,0.039,222.17,291121,,,D*7A
2021-11-29T19:29:12.211Z,1638214152.211 [NAL9602](INFO): GPS fix at 20211129T192912: (36.802371, -121.786728)
2021-11-29T19:29:12.223Z,1638214152.223 [Default:CheckIn:Read_GPS] Stopped
2021-11-29T19:29:12.224Z,1638214152.224 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-29T19:29:13.012Z,1638214153.012 [DAT](INFO): #Outgoing data=1
2021-11-29T19:29:13.012Z,1638214153.012 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-29T19:29:13.404Z,1638214153.404 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-29T19:29:13.816Z,1638214153.816 [DAT](INFO): DAT read: UART Wakeup

2021-11-29T19:29:13.818Z,1638214153.818 [DAT](INFO): DAT read: CONNECT 01200 bits/sec 1 of 4, Rate 1/2 CC

2021-11-29T19:29:13.818Z,1638214153.818 [DAT](INFO): commRate: 1200
2021-11-29T19:29:17.051Z,1638214157.051 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:28:41.3315

2021-11-29T19:29:17.051Z,1638214157.051 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-29T19:29:27.187Z,1638214167.187 [DAT](FAULT): Ack receipt timeout failure.
2021-11-29T19:29:27.187Z,1638214167.187 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED
2021-11-29T19:29:27.592Z,1638214167.592 [DAT](INFO): Sent 72 bytes from file Logs/20211129T173840/Courier0046.lzma.parts
2021-11-29T19:29:27.592Z,1638214167.592 [DAT](INFO): Packets left to send: 0
2021-11-29T19:29:27.595Z,1638214167.595 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-29T19:29:40.925Z,1638214180.925 [NAL9602](INFO): SBD MO Status=2, MOMSN=30509, MT Status=2, MTMSN=0
2021-11-29T19:29:40.926Z,1638214180.926 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T19:30:01.598Z,1638214201.598 [NAL9602](INFO): SBD MO Status=2, MOMSN=30509, MT Status=2, MTMSN=0
2021-11-29T19:30:01.598Z,1638214201.598 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T19:30:40.452Z,1638214240.452 [NAL9602](INFO): SBD MO Status=2, MOMSN=30509, MT Status=2, MTMSN=0
2021-11-29T19:30:40.452Z,1638214240.452 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T19:30:57.927Z,1638214257.927 [NAL9602](INFO): SBD MO Status=2, MOMSN=30509, MT Status=2, MTMSN=0
2021-11-29T19:30:57.927Z,1638214257.927 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T19:32:16.786Z,1638214336.786 [DAT](INFO): DAT read: Lowpower

2021-11-29T19:32:16.787Z,1638214336.787 [DAT](INFO): unknown deviceResponse_: Lowpower

2021-11-29T19:33:03.680Z,1638214383.680 [NAL9602](INFO): SBD MO Status=2, MOMSN=30509, MT Status=2, MTMSN=0
2021-11-29T19:33:03.680Z,1638214383.680 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T19:33:44.552Z,1638214424.552 [NAL9602](INFO): SBD MO Status=2, MOMSN=30509, MT Status=2, MTMSN=0
2021-11-29T19:33:44.552Z,1638214424.552 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T19:33:55.522Z,1638214435.522 [NAL9602](INFO): SBD MO Status=1, MOMSN=30509, MT Status=0, MTMSN=0
2021-11-29T19:33:55.578Z,1638214435.578 [NAL9602](INFO): Sent 164 bytes from file Logs/20211129T173840/Express0047.lzma
2021-11-29T19:33:55.578Z,1638214435.578 [NAL9602](INFO): Packets left to send: 0
2021-11-29T19:34:05.612Z,1638214445.612 [NAL9602](INFO): SBD MO Status=0, MOMSN=30510, MT Status=0, MTMSN=0
2021-11-29T19:34:05.697Z,1638214445.697 [Default:CheckIn:Read_Iridium] Stopped
2021-11-29T19:34:05.697Z,1638214445.697 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-29T19:34:05.697Z,1638214445.697 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-29T19:34:36.318Z,1638214476.318 [NAL9602](INFO): Not Powering down - fast GPS
2021-11-29T19:39:06.218Z,1638214746.218 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-29T19:39:06.218Z,1638214746.218 [Default:CheckIn:C.Wait] Stopped
2021-11-29T19:39:06.218Z,1638214746.218 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-29T19:39:06.218Z,1638214746.218 [Default:CheckIn:D] Running Loop=1
2021-11-29T19:39:06.622Z,1638214746.622 [Default:CheckIn:D] Stopped
2021-11-29T19:39:06.622Z,1638214746.622 [Default:CheckIn:E] Running Loop=1
2021-11-29T19:39:07.021Z,1638214747.021 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 117.339128 min 
2021-11-29T19:39:07.021Z,1638214747.021 [Default:CheckIn:E] Stopped
2021-11-29T19:39:07.022Z,1638214747.022 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-29T19:39:07.022Z,1638214747.022 [Default:CheckIn] Stopped
2021-11-29T19:39:07.022Z,1638214747.022 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-29T19:39:07.022Z,1638214747.022 [Default:CheckIn](INFO): Running loop #16
2021-11-29T19:39:07.022Z,1638214747.022 [Default:CheckIn] Running Loop=16
2021-11-29T19:39:07.022Z,1638214747.022 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-29T19:39:07.022Z,1638214747.022 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-29T19:39:09.032Z,1638214749.032 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,193909.00,A,3648.20637,N,12147.15831,W,2.857,32.84,291121,,,D*49
2021-11-29T19:39:09.035Z,1638214749.035 [NAL9602](INFO): GPS fix at 20211129T193909: (36.803440, -121.785972)
2021-11-29T19:39:09.046Z,1638214749.046 [Default:CheckIn:Read_GPS] Stopped
2021-11-29T19:39:09.046Z,1638214749.046 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-29T19:39:09.852Z,1638214749.852 [DAT](INFO): #Outgoing data=1
2021-11-29T19:39:09.852Z,1638214749.852 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-29T19:39:10.246Z,1638214750.246 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-29T19:39:10.644Z,1638214750.644 [DAT](INFO): DAT read: UART Wakeup

2021-11-29T19:39:10.645Z,1638214750.645 [DAT](INFO): DAT read: CONNECT 01200 bits/sec 1 of 4, Rate1/2 CC

2021-11-29T19:39:10.645Z,1638214750.645 [DAT](INFO): commRate: 1200
2021-11-29T19:39:13.883Z,1638214753.883 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:38:38.3318

2021-11-29T19:39:13.883Z,1638214753.883 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-29T19:39:24.027Z,1638214764.027 [DAT](FAULT): Ack receipt timeout failure.
2021-11-29T19:39:24.027Z,1638214764.027 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED
2021-11-29T19:39:24.432Z,1638214764.432 [DAT](INFO): Sent 74 bytes from file Logs/20211129T173840/Courier0049.lzma.parts
2021-11-29T19:39:24.432Z,1638214764.432 [DAT](INFO): Packets left to send: 0
2021-11-29T19:39:24.435Z,1638214764.435 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-29T19:39:32.508Z,1638214772.508 [NAL9602](INFO): SBD MO Status=2, MOMSN=30511, MT Status=2, MTMSN=0
2021-11-29T19:39:32.508Z,1638214772.508 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-11-29T19:39:54.003Z,1638214794.003 [NAL9602](INFO): SBD MO Status=1, MOMSN=30511, MT Status=0, MTMSN=0
2021-11-29T19:39:54.053Z,1638214794.053 [NAL9602](INFO): Sent 182 bytes from file Logs/20211129T173840/Express0050.lzma
2021-11-29T19:39:54.054Z,1638214794.054 [NAL9602](INFO): Packets left to send: 0
2021-11-29T19:40:04.148Z,1638214804.148 [NAL9602](INFO): SBD MO Status=0, MOMSN=30512, MT Status=0, MTMSN=0
2021-11-29T19:40:04.242Z,1638214804.242 [Default:CheckIn:Read_Iridium] Stopped
2021-11-29T19:40:04.242Z,1638214804.242 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-29T19:40:04.242Z,1638214804.242 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-29T19:40:34.801Z,1638214834.801 [NAL9602](INFO): Not Powering down - fast GPS
2021-11-29T19:42:13.785Z,1638214933.785 [DAT](INFO): DAT read: Lowpower

2021-11-29T19:42:13.786Z,1638214933.786 [DAT](INFO): unknown deviceResponse_: Lowpower

2021-11-29T19:45:04.725Z,1638215104.725 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-29T19:45:04.725Z,1638215104.725 [Default:CheckIn:C.Wait] Stopped
2021-11-29T19:45:04.725Z,1638215104.725 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-29T19:45:04.725Z,1638215104.725 [Default:CheckIn:D] Running Loop=1
2021-11-29T19:45:05.130Z,1638215105.130 [Default:CheckIn:D] Stopped
2021-11-29T19:45:05.131Z,1638215105.131 [Default:CheckIn:E] Running Loop=1
2021-11-29T19:45:05.541Z,1638215105.541 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 123.314266 min 
2021-11-29T19:45:05.541Z,1638215105.541 [Default:CheckIn:E] Stopped
2021-11-29T19:45:05.542Z,1638215105.542 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-29T19:45:05.542Z,1638215105.542 [Default:CheckIn] Stopped
2021-11-29T19:45:05.542Z,1638215105.542 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-29T19:45:05.542Z,1638215105.542 [Default:CheckIn](INFO): Running loop #17
2021-11-29T19:45:05.542Z,1638215105.542 [Default:CheckIn] Running Loop=17
2021-11-29T19:45:05.542Z,1638215105.542 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-29T19:45:05.542Z,1638215105.542 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-29T19:45:07.548Z,1638215107.548 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,194507.00,A,3648.51106,N,12147.13512,W,6.201,302.76,291121,,,D*75
2021-11-29T19:45:07.551Z,1638215107.551 [NAL9602](INFO): GPS fix at 20211129T194507: (36.808518, -121.785585)
2021-11-29T19:45:07.591Z,1638215107.591 [Default:CheckIn:Read_GPS] Stopped
2021-11-29T19:45:07.591Z,1638215107.591 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-29T19:45:08.366Z,1638215108.366 [DAT](INFO): #Outgoing data=1
2021-11-29T19:45:08.366Z,1638215108.366 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-29T19:45:08.774Z,1638215108.774 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-29T19:45:09.193Z,1638215109.193 [DAT](INFO): DAT read: ART Waep

2021-11-29T19:45:09.194Z,1638215109.194 [DAT](INFO): unknown deviceResponse_: ART Waep

2021-11-29T19:45:09.195Z,1638215109.195 [DAT](INFO): DAT read: COC 1200 is/ec1o ,Ra1/2 CC

2021-11-29T19:45:09.195Z,1638215109.195 [DAT](INFO): unknown deviceResponse_: COC 1200 is/ec1o ,Ra1/2 CC

2021-11-29T19:45:12.407Z,1638215112.407 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:44:36.3327

2021-11-29T19:45:12.407Z,1638215112.407 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-29T19:45:23.302Z,1638215123.302 [DAT](FAULT): Ack receipt timeout failure.
2021-11-29T19:45:23.302Z,1638215123.302 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED
2021-11-29T19:45:23.393Z,1638215123.393 [DAT](INFO): Sent 72 bytes from file Logs/20211129T173840/Courier0052.lzma.parts
2021-11-29T19:45:23.393Z,1638215123.393 [DAT](INFO): Packets left to send: 0
2021-11-29T19:45:23.396Z,1638215123.396 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-29T19:45:31.020Z,1638215131.020 [NAL9602](INFO): SBD MO Status=1, MOMSN=30513, MT Status=0, MTMSN=0
2021-11-29T19:45:31.073Z,1638215131.073 [NAL9602](INFO): Sent 72 bytes from file Logs/20211129T173840/Courier0052.lzma
2021-11-29T19:45:31.074Z,1638215131.074 [NAL9602](INFO): Packets left to send: 0
2021-11-29T19:45:49.680Z,1638215149.680 [NAL9602](INFO): SBD MO Status=1, MOMSN=30514, MT Status=0, MTMSN=0
2021-11-29T19:45:49.734Z,1638215149.734 [NAL9602](INFO): Sent 177 bytes from file Logs/20211129T173840/Express0053.lzma
2021-11-29T19:45:49.734Z,1638215149.734 [NAL9602](INFO): Packets left to send: 0
2021-11-29T19:45:55.338Z,1638215155.338 [NAL9602](INFO): SBD MO Status=0, MOMSN=30515, MT Status=0, MTMSN=0
2021-11-29T19:45:55.440Z,1638215155.440 [Default:CheckIn:Read_Iridium] Stopped
2021-11-29T19:45:55.440Z,1638215155.440 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-29T19:45:55.440Z,1638215155.440 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-29T19:46:26.038Z,1638215186.038 [NAL9602](INFO): Not Powering down - fast GPS
2021-11-29T19:48:12.295Z,1638215292.295 [DAT](INFO): DAT read: Lowpower

2021-11-29T19:48:12.296Z,1638215292.296 [DAT](INFO): unknown deviceResponse_: Lowpower

2021-11-29T19:49:12.983Z,1638215352.983 [CommandExec](IMPORTANT): got command restart application
2021-11-29T19:49:13.985Z,1638215353.985 [CommandExec ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-29T19:49:13.985Z,1638215353.985 [CommandExec](INFO): Uninitializing the command executive.
2021-11-29T19:49:13.985Z,1638215353.985 [CommandExec](INFO): Uninitializing the command scheduler.
2021-11-29T19:49:13.986Z,1638215353.986 [CommandExec ThreadHandler](INFO): Thread cancelled.
2021-11-29T19:49:14.042Z,1638215354.042 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2021-11-29T19:49:14.043Z,1638215354.043 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2021-11-29T19:49:14.043Z,1638215354.043 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2021-11-29T19:49:14.044Z,1638215354.044 [NavChartDb](INFO): Join timeout helper Thread ID is 1611
2021-11-29T19:49:14.217Z,1638215354.217 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-29T19:49:14.218Z,1638215354.218 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2021-11-29T19:49:14.237Z,1638215354.237 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2021-11-29T19:49:14.237Z,1638215354.237 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2021-11-29T19:49:14.238Z,1638215354.238 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 1612
2021-11-29T19:49:14.613Z,1638215354.613 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-29T19:49:14.613Z,1638215354.613 [WetLabsBB2FL](INFO): Powering down
2021-11-29T19:49:14.614Z,1638215354.614 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2021-11-29T19:49:14.629Z,1638215354.629 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2021-11-29T19:49:14.629Z,1638215354.629 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2021-11-29T19:49:14.629Z,1638215354.629 [CTD_Seabird](INFO): Join timeout helper Thread ID is 1613
2021-11-29T19:49:15.193Z,1638215355.193 [CTD_Seabird](INFO): Powering down
2021-11-29T19:49:15.205Z,1638215355.205 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-29T19:49:15.205Z,1638215355.205 [CTD_Seabird](INFO): Powering down
2021-11-29T19:49:15.217Z,1638215355.217 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2021-11-29T19:49:15.221Z,1638215355.221 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2021-11-29T19:49:15.221Z,1638215355.221 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2021-11-29T19:49:15.221Z,1638215355.221 [Radio_Surface](INFO): Join timeout helper Thread ID is 1614
2021-11-29T19:49:15.441Z,1638215355.441 [Radio_Surface](INFO): Powering down
2021-11-29T19:49:15.442Z,1638215355.442 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-29T19:49:15.443Z,1638215355.443 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2021-11-29T19:49:15.457Z,1638215355.457 [ComponentRegistry](INFO): Shutting down Onboard ThreadHandler
2021-11-29T19:49:15.457Z,1638215355.457 [Onboard ThreadHandler](INFO): Thread cancelled.
2021-11-29T19:49:15.457Z,1638215355.457 [Onboard](INFO): Join timeout helper Thread ID is 1615
2021-11-29T19:49:17.849Z,1638215357.849 [Onboard ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-29T19:49:17.850Z,1638215357.850 [Onboard ThreadHandler](INFO): Thread cancelled.
2021-11-29T19:49:17.866Z,1638215357.866 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2021-11-29T19:49:17.866Z,1638215357.866 [logger ThreadHandler](INFO): Thread cancelled.
2021-11-29T19:49:17.866Z,1638215357.866 [logger](INFO): Join timeout helper Thread ID is 1616
2021-11-29T19:49:17.897Z,1638215357.897 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-29T19:49:17.897Z,1638215357.897 [logger ThreadHandler](INFO): Thread cancelled.
2021-11-29T19:49:17.906Z,1638215357.906 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2021-11-29T19:49:17.906Z,1638215357.906 [CommandLine ThreadHandler](INFO): Thread cancelled.
2021-11-29T19:49:17.906Z,1638215357.906 [CommandLine](INFO): Join timeout helper Thread ID is 1617
2021-11-29T19:49:17.989Z,1638215357.989 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-29T19:49:17.989Z,1638215357.989 [CommandLine ThreadHandler](INFO): Thread cancelled.
2021-11-29T19:49:18.006Z,1638215358.006 [ComponentRegistry](INFO): Shutting down CommandExec ThreadHandler
2021-11-29T19:49:18.006Z,1638215358.006 [CommandExec ThreadHandler](INFO): Thread cancelled.
2021-11-29T19:49:18.006Z,1638215358.006 [CommandExec](INFO): Join timeout helper Thread ID is 1618
2021-11-29T19:49:18.007Z,1638215358.007 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2021-11-29T19:49:18.007Z,1638215358.007 [controlThread ThreadHandler](INFO): Thread cancelled.
2021-11-29T19:49:18.008Z,1638215358.008 [controlThread](INFO): Join timeout helper Thread ID is 1619
2021-11-29T19:49:18.133Z,1638215358.133 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-29T19:49:18.133Z,1638215358.133 [controlThread](DEBUG): Uninitializing ControlThread
2021-11-29T19:49:18.134Z,1638215358.134 [AHRS_M2](INFO): Powering down
2021-11-29T19:49:18.206Z,1638215358.206 [NAL9602](INFO): Powering down
2021-11-29T19:49:18.207Z,1638215358.207 [DAT](INFO): Powering down
2021-11-29T19:49:18.327Z,1638215358.327 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2021-11-29T19:49:18.328Z,1638215358.328 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2021-11-29T19:49:18.328Z,1638215358.328 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2021-11-29T19:49:18.329Z,1638215358.329 [MissionManager](INFO): Uninitializing Mission Default
2021-11-29T19:49:18.329Z,1638215358.329 [Default] Stopped
2021-11-29T19:49:18.329Z,1638215358.329 [Default](DEBUG): Aggregate::uninitialize Default
2021-11-29T19:49:18.329Z,1638215358.329 [Default:B.GoToSurface] Stopped
2021-11-29T19:49:18.329Z,1638215358.329 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2021-11-29T19:49:18.329Z,1638215358.329 [Default:CheckIn] Stopped
2021-11-29T19:49:18.329Z,1638215358.329 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-29T19:49:18.329Z,1638215358.329 [Default:CheckIn:C.Wait] Stopped
2021-11-29T19:49:18.330Z,1638215358.330 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-29T19:49:18.333Z,1638215358.333 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2021-11-29T19:49:18.334Z,1638215358.334 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2021-11-29T19:49:18.334Z,1638215358.334 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2021-11-29T19:49:18.334Z,1638215358.334 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2021-11-29T19:49:18.335Z,1638215358.335 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2021-11-29T19:49:18.335Z,1638215358.335 [BuoyancyServo](INFO): Powering down
2021-11-29T19:49:18.349Z,1638215358.349 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2021-11-29T19:49:18.349Z,1638215358.349 [ElevatorServo](INFO): Powering down
2021-11-29T19:49:18.350Z,1638215358.350 [MassServo](DEBUG): Uninitialize Mass Servo.
2021-11-29T19:49:18.350Z,1638215358.350 [MassServo](INFO): Powering down
2021-11-29T19:49:18.351Z,1638215358.351 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2021-11-29T19:49:18.351Z,1638215358.351 [RudderServo](INFO): Powering down
2021-11-29T19:49:18.352Z,1638215358.352 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2021-11-29T19:49:18.352Z,1638215358.352 [ThrusterServo](INFO): Powering down
2021-11-29T19:49:18.353Z,1638215358.353 [SBIT](DEBUG): Uninitialize SBIT Component.
2021-11-29T19:49:18.354Z,1638215358.354 [IBIT](DEBUG): Uninitialize IBIT Component.
2021-11-29T19:49:18.354Z,1638215358.354 [CBIT](DEBUG): Uninitialize CBIT Component.
2021-11-29T19:49:18.354Z,1638215358.354 [CBIT](DEBUG): Powering off loads.
2021-11-29T19:49:18.365Z,1638215358.365 [CBIT](DEBUG): Disabling WDT.
2021-11-29T19:49:18.377Z,1638215358.377 [CBIT](DEBUG): Opening all GF detection circuits.
2021-11-29T19:49:18.378Z,1638215358.378 [controlThread ThreadHandler](INFO): Thread cancelled.
2021-11-29T19:49:18.424Z,1638215358.424 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2021-11-29T19:49:18.427Z,1638215358.427 [Onboard ThreadHandler](INFO): Thread cancelled.
2021-11-29T19:49:18.495Z,1638215358.495 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2021-11-29T19:49:18.499Z,1638215358.499 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2021-11-29T19:49:18.538Z,1638215358.538 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2021-11-29T19:49:18.606Z,1638215358.606 [logger ThreadHandler](INFO): Thread cancelled.