2021-06-28T17:49:38.746Z,1624902578.746 [Supervisor](DEBUG): Initializing supervisor.
2021-06-28T17:49:38.751Z,1624902578.751 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2021-06-28T17:49:38.751Z,1624902578.751 [SyncHandler](INFO): Protected caller Thread ID is 837
2021-06-28T17:49:38.752Z,1624902578.752 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2021-06-28T17:49:38.753Z,1624902578.753 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2021-06-28T17:49:38.753Z,1624902578.753 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 838
2021-06-28T17:49:38.757Z,1624902578.757 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2021-06-28T17:49:38.778Z,1624902578.778 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2021-06-28T17:49:38.779Z,1624902578.779 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2021-06-28T17:49:38.779Z,1624902578.779 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 839
2021-06-28T17:49:38.781Z,1624902578.781 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2021-06-28T17:49:38.782Z,1624902578.782 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2021-06-28T17:49:38.783Z,1624902578.783 [logger ThreadHandler](INFO): Protected caller Thread ID is 840
2021-06-28T17:49:38.786Z,1624902578.786 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2021-06-28T17:49:38.787Z,1624902578.787 [Supervisor](INFO): Looking for Config files in directory: Config/
2021-06-28T17:49:38.791Z,1624902578.791 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2021-06-28T17:49:39.073Z,1624902579.073 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2021-06-28T17:49:39.074Z,1624902579.074 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2021-06-28T17:49:39.156Z,1624902579.156 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2021-06-28T17:49:39.668Z,1624902579.668 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2021-06-28T17:49:39.669Z,1624902579.669 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2021-06-28T17:49:40.006Z,1624902580.006 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2021-06-28T17:49:40.006Z,1624902580.006 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2021-06-28T17:49:40.104Z,1624902580.104 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2021-06-28T17:49:40.106Z,1624902580.106 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2021-06-28T17:49:40.483Z,1624902580.483 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2021-06-28T17:49:40.483Z,1624902580.483 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2021-06-28T17:49:40.686Z,1624902580.686 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2021-06-28T17:49:40.687Z,1624902580.687 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2021-06-28T17:49:41.158Z,1624902581.158 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2021-06-28T17:49:41.159Z,1624902581.159 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2021-06-28T17:49:41.287Z,1624902581.287 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2021-06-28T17:49:41.289Z,1624902581.289 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2021-06-28T17:49:41.369Z,1624902581.369 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2021-06-28T17:49:42.067Z,1624902582.067 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2021-06-28T17:49:42.068Z,1624902582.068 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2021-06-28T17:49:43.022Z,1624902583.022 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2021-06-28T17:49:43.023Z,1624902583.023 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2021-06-28T17:49:43.218Z,1624902583.218 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2021-06-28T17:49:43.219Z,1624902583.219 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2021-06-28T17:49:43.331Z,1624902583.331 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2021-06-28T17:49:43.332Z,1624902583.332 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2021-06-28T17:49:43.486Z,1624902583.486 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2021-06-28T17:49:43.486Z,1624902583.486 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2021-06-28T17:49:43.720Z,1624902583.720 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2021-06-28T17:49:43.722Z,1624902583.722 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2021-06-28T17:49:43.725Z,1624902583.725 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2021-06-28T17:49:43.817Z,1624902583.817 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2021-06-28T17:49:43.903Z,1624902583.903 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2021-06-28T17:49:44.006Z,1624902584.006 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2021-06-28T17:49:44.090Z,1624902584.090 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2021-06-28T17:49:44.187Z,1624902584.187 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2021-06-28T17:49:44.334Z,1624902584.334 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2021-06-28T17:49:44.527Z,1624902584.527 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2021-06-28T17:49:44.604Z,1624902584.604 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2021-06-28T17:49:44.755Z,1624902584.755 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2021-06-28T17:49:44.896Z,1624902584.896 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2021-06-28T17:49:45.014Z,1624902585.014 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg
2021-06-28T17:49:45.281Z,1624902585.281 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2021-06-28T17:49:45.282Z,1624902585.282 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2021-06-28T17:49:45.294Z,1624902585.294 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2021-06-28T17:49:45.369Z,1624902585.369 [VerticalControl](DEBUG): Construct VerticalControl.
2021-06-28T17:49:45.434Z,1624902585.434 [VerticalControl] Loaded
2021-06-28T17:49:45.434Z,1624902585.434 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2021-06-28T17:49:45.437Z,1624902585.437 [HorizontalControl](DEBUG): Construct HorizontalControl.
2021-06-28T17:49:45.478Z,1624902585.478 [HorizontalControl] Loaded
2021-06-28T17:49:45.478Z,1624902585.478 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2021-06-28T17:49:45.481Z,1624902585.481 [SpeedControl](DEBUG): Construct SpeedControl.
2021-06-28T17:49:45.484Z,1624902585.484 [SpeedControl] Loaded
2021-06-28T17:49:45.484Z,1624902585.484 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2021-06-28T17:49:45.487Z,1624902585.487 [LoopControl](DEBUG): Construct LoopControl.
2021-06-28T17:49:45.487Z,1624902585.487 [LoopControl] Loaded
2021-06-28T17:49:45.488Z,1624902585.488 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2021-06-28T17:49:45.488Z,1624902585.488 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2021-06-28T17:49:45.490Z,1624902585.490 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2021-06-28T17:49:45.507Z,1624902585.507 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2021-06-28T17:49:45.508Z,1624902585.508 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2021-06-28T17:49:45.646Z,1624902585.646 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2021-06-28T17:49:45.647Z,1624902585.647 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2021-06-28T17:49:45.825Z,1624902585.825 [BuoyancyServo] Loaded
2021-06-28T17:49:45.825Z,1624902585.825 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2021-06-28T17:49:45.845Z,1624902585.845 [ElevatorServo] Loaded
2021-06-28T17:49:45.846Z,1624902585.846 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2021-06-28T17:49:45.864Z,1624902585.864 [MassServo] Loaded
2021-06-28T17:49:45.865Z,1624902585.865 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2021-06-28T17:49:45.883Z,1624902585.883 [RudderServo] Loaded
2021-06-28T17:49:45.884Z,1624902585.884 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2021-06-28T17:49:45.902Z,1624902585.902 [ThrusterServo] Loaded
2021-06-28T17:49:45.902Z,1624902585.902 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2021-06-28T17:49:45.903Z,1624902585.903 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2021-06-28T17:49:45.903Z,1624902585.903 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2021-06-28T17:49:46.005Z,1624902586.005 [DeadReckonUsingMultipleVelocitySources] Loaded
2021-06-28T17:49:46.006Z,1624902586.006 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2021-06-28T17:49:46.019Z,1624902586.019 [NavChart] Loaded
2021-06-28T17:49:46.020Z,1624902586.020 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2021-06-28T17:49:46.026Z,1624902586.026 [UniversalFixResidualReporter] Loaded
2021-06-28T17:49:46.026Z,1624902586.026 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2021-06-28T17:49:46.026Z,1624902586.026 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2021-06-28T17:49:46.027Z,1624902586.027 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2021-06-28T17:49:46.112Z,1624902586.112 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2021-06-28T17:49:46.113Z,1624902586.113 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2021-06-28T17:49:46.982Z,1624902586.982 [AHRS_M2] Loaded
2021-06-28T17:49:46.982Z,1624902586.982 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2021-06-28T17:49:48.184Z,1624902588.184 [BPC1] Loaded
2021-06-28T17:49:48.184Z,1624902588.184 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2021-06-28T17:49:48.512Z,1624902588.512 [DataOverHttps] Loaded
2021-06-28T17:49:48.512Z,1624902588.512 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2021-06-28T17:49:48.513Z,1624902588.513 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 408854E0
2021-06-28T17:49:48.514Z,1624902588.514 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 925
2021-06-28T17:49:48.534Z,1624902588.534 [Depth_Keller] Loaded
2021-06-28T17:49:48.534Z,1624902588.534 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2021-06-28T17:49:48.539Z,1624902588.539 [DropWeight] Loaded
2021-06-28T17:49:48.539Z,1624902588.539 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2021-06-28T17:49:48.600Z,1624902588.600 [NAL9602] Loaded
2021-06-28T17:49:48.600Z,1624902588.600 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2021-06-28T17:49:48.630Z,1624902588.630 [Onboard] Loaded
2021-06-28T17:49:48.631Z,1624902588.631 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2021-06-28T17:49:48.632Z,1624902588.632 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 408B54E0
2021-06-28T17:49:48.632Z,1624902588.632 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 926
2021-06-28T17:49:48.645Z,1624902588.645 [Power24vConverter] Loaded
2021-06-28T17:49:48.645Z,1624902588.645 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread.
2021-06-28T17:49:48.659Z,1624902588.659 [Radio_Surface] Loaded
2021-06-28T17:49:48.659Z,1624902588.659 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2021-06-28T17:49:48.660Z,1624902588.660 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408E54E0
2021-06-28T17:49:48.660Z,1624902588.660 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 927
2021-06-28T17:49:48.661Z,1624902588.661 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2021-06-28T17:49:48.662Z,1624902588.662 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2021-06-28T17:49:48.724Z,1624902588.724 [DepthRateCalculator] Loaded
2021-06-28T17:49:48.724Z,1624902588.724 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2021-06-28T17:49:48.729Z,1624902588.729 [PitchRateCalculator] Loaded
2021-06-28T17:49:48.729Z,1624902588.729 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2021-06-28T17:49:48.739Z,1624902588.739 [SpeedCalculator] Loaded
2021-06-28T17:49:48.739Z,1624902588.739 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2021-06-28T17:49:48.753Z,1624902588.753 [TempGradientCalculator] Loaded
2021-06-28T17:49:48.754Z,1624902588.754 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2021-06-28T17:49:48.758Z,1624902588.758 [YawRateCalculator] Loaded
2021-06-28T17:49:48.759Z,1624902588.759 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2021-06-28T17:49:48.777Z,1624902588.777 [ElevatorOffsetCalculator] Loaded
2021-06-28T17:49:48.777Z,1624902588.777 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2021-06-28T17:49:48.777Z,1624902588.777 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2021-06-28T17:49:48.778Z,1624902588.778 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2021-06-28T17:49:48.971Z,1624902588.971 [CANONSampler] Loaded
2021-06-28T17:49:48.972Z,1624902588.972 [ComponentRegistry](DEBUG): SyncComponent "CANONSampler" handled in the control thread.
2021-06-28T17:49:49.032Z,1624902589.032 [CTD_Seabird] Loaded
2021-06-28T17:49:49.032Z,1624902589.032 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2021-06-28T17:49:49.033Z,1624902589.033 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 4099A4E0
2021-06-28T17:49:49.034Z,1624902589.034 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 928
2021-06-28T17:49:49.054Z,1624902589.054 [PAR_Licor] Loaded
2021-06-28T17:49:49.054Z,1624902589.054 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2021-06-28T17:49:49.087Z,1624902589.087 [WetLabsBB2FL] Loaded
2021-06-28T17:49:49.088Z,1624902589.088 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2021-06-28T17:49:49.089Z,1624902589.089 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 409CA4E0
2021-06-28T17:49:49.089Z,1624902589.089 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 929
2021-06-28T17:49:49.090Z,1624902589.090 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2021-06-28T17:49:49.091Z,1624902589.091 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2021-06-28T17:49:49.134Z,1624902589.134 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2021-06-28T17:49:49.135Z,1624902589.135 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2021-06-28T17:49:49.535Z,1624902589.535 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2021-06-28T17:49:49.537Z,1624902589.537 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2021-06-28T17:49:49.727Z,1624902589.727 [SBIT](DEBUG): Construct Startup Built In Test.
2021-06-28T17:49:49.736Z,1624902589.736 [SBIT] Loaded
2021-06-28T17:49:49.737Z,1624902589.737 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2021-06-28T17:49:49.740Z,1624902589.740 [IBIT](DEBUG): Construct Initiated Built In Test.
2021-06-28T17:49:49.753Z,1624902589.753 [IBIT] Loaded
2021-06-28T17:49:49.753Z,1624902589.753 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2021-06-28T17:49:49.759Z,1624902589.759 [CBIT](DEBUG): Construct Continuous Built In Test.
2021-06-28T17:49:49.863Z,1624902589.863 [CBIT] Loaded
2021-06-28T17:49:49.863Z,1624902589.863 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2021-06-28T17:49:49.864Z,1624902589.864 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2021-06-28T17:49:49.864Z,1624902589.864 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2021-06-28T17:49:49.990Z,1624902589.990 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2021-06-28T17:49:49.997Z,1624902589.997 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2021-06-28T17:49:49.999Z,1624902589.999 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2021-06-28T17:49:50.011Z,1624902590.011 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2021-06-28T17:49:50.012Z,1624902590.012 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AFD4E0
2021-06-28T17:49:50.013Z,1624902590.013 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 930
2021-06-28T17:49:50.017Z,1624902590.017 [Supervisor](INFO): Main Thread ID is 833
2021-06-28T17:49:50.018Z,1624902590.018 [Supervisor](DEBUG): Running supervisor.
2021-06-28T17:49:50.018Z,1624902590.018 [CommandLine ThreadHandler](INFO): Handler Thread ID is 931
2021-06-28T17:49:50.021Z,1624902590.021 [controlThread ThreadHandler](INFO): Handler Thread ID is 932
2021-06-28T17:49:50.021Z,1624902590.021 [controlThread](DEBUG): Initializing ControlThread
2021-06-28T17:49:50.022Z,1624902590.022 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2021-06-28T17:49:50.024Z,1624902590.024 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2021-06-28T17:49:50.025Z,1624902590.025 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2021-06-28T17:49:50.025Z,1624902590.025 [LoopControl](DEBUG): Initialize LoopControlComponent.
2021-06-28T17:49:50.027Z,1624902590.027 [NavChart](DEBUG): Initialize NavChart Navigation.
2021-06-28T17:49:50.028Z,1624902590.028 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2021-06-28T17:49:50.031Z,1624902590.031 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2021-06-28T17:49:50.031Z,1624902590.031 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2021-06-28T17:49:50.032Z,1624902590.032 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2021-06-28T17:49:50.032Z,1624902590.032 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2021-06-28T17:49:50.032Z,1624902590.032 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2021-06-28T17:49:50.033Z,1624902590.033 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2021-06-28T17:49:50.037Z,1624902590.037 [SBIT](INFO): Initialize SBIT Component.
2021-06-28T17:49:50.038Z,1624902590.038 [SBIT](IMPORTANT): git: 2021-06-25
2021-06-28T17:49:50.038Z,1624902590.038 [SBIT](INFO): git hash: ce6655dd71cbacf6863957f250954322ec92cc29
2021-06-28T17:49:50.038Z,1624902590.038 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2021-06-28T17:49:50.040Z,1624902590.040 [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-06-28T17:49:50.041Z,1624902590.041 [SBIT](INFO): Beginning SBIT in 81.000000 seconds.
2021-06-28T17:49:50.042Z,1624902590.042 [IBIT](INFO): Initialize IBIT Component.
2021-06-28T17:49:50.043Z,1624902590.043 [CBIT](DEBUG): Initialize CBIT Component.
2021-06-28T17:49:50.043Z,1624902590.043 [logger ThreadHandler](INFO): Handler Thread ID is 933
2021-06-28T17:49:50.057Z,1624902590.057 [CBIT](DEBUG): Initialized mux pins.
2021-06-28T17:49:50.057Z,1624902590.057 [CBIT](DEBUG): Initializing the watchdog timer.
2021-06-28T17:49:50.062Z,1624902590.062 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 934
2021-06-28T17:49:50.063Z,1624902590.063 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2021-06-28T17:49:50.070Z,1624902590.070 [Onboard ThreadHandler](INFO): Handler Thread ID is 935
2021-06-28T17:49:50.082Z,1624902590.082 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2021-06-28T17:49:50.083Z,1624902590.083 [CBIT](DEBUG): Initializing heartbeat.
2021-06-28T17:49:50.091Z,1624902590.091 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 936
2021-06-28T17:49:50.105Z,1624902590.105 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 937
2021-06-28T17:49:50.106Z,1624902590.106 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2021-06-28T17:49:50.111Z,1624902590.111 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 939
2021-06-28T17:49:50.114Z,1624902590.114 [WetLabsBB2FL](INFO): Powering up
2021-06-28T17:49:50.115Z,1624902590.115 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 941
2021-06-28T17:49:50.123Z,1624902590.123 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2021-06-28T17:49:50.123Z,1624902590.123 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2021-06-28T17:49:50.124Z,1624902590.124 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2021-06-28T17:49:50.124Z,1624902590.124 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2021-06-28T17:49:50.124Z,1624902590.124 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2021-06-28T17:49:50.124Z,1624902590.124 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2021-06-28T17:49:50.124Z,1624902590.124 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2021-06-28T17:49:50.124Z,1624902590.124 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2021-06-28T17:49:50.125Z,1624902590.125 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2021-06-28T17:49:50.125Z,1624902590.125 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2021-06-28T17:49:50.125Z,1624902590.125 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2021-06-28T17:49:50.125Z,1624902590.125 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2021-06-28T17:49:50.126Z,1624902590.126 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2021-06-28T17:49:50.126Z,1624902590.126 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2021-06-28T17:49:50.126Z,1624902590.126 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2021-06-28T17:49:50.126Z,1624902590.126 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2021-06-28T17:49:50.153Z,1624902590.153 [CBIT](DEBUG): Deactivating GF circuits.
2021-06-28T17:49:50.153Z,1624902590.153 [CBIT](DEBUG): Deactivating emergency mode.
2021-06-28T17:49:50.189Z,1624902590.189 [CBIT](DEBUG): Backplane powered.
2021-06-28T17:49:50.190Z,1624902590.190 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2021-06-28T17:49:50.223Z,1624902590.223 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2021-06-28T17:49:50.252Z,1624902590.252 [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-06-28T17:49:50.253Z,1624902590.253 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2021-06-28T17:49:50.339Z,1624902590.339 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2021-06-28T17:49:50.340Z,1624902590.340 [Default:A.Wait](DEBUG): Construct Wait.
2021-06-28T17:49:50.343Z,1624902590.343 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2021-06-28T17:49:50.382Z,1624902590.382 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2021-06-28T17:49:50.401Z,1624902590.401 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2021-06-28T17:49:50.407Z,1624902590.407 [Default:E.Execute](DEBUG): Construct Execute.
2021-06-28T17:49:50.427Z,1624902590.427 [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-06-28T17:49:50.432Z,1624902590.432 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,DropWeight,NAL9602,Power24vConverter,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-06-28T17:49:50.454Z,1624902590.454 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2021-06-28T17:49:50.497Z,1624902590.497 [Radio_Surface](INFO): Powering up
2021-06-28T17:49:50.510Z,1624902590.510 [Depth_Keller](ERROR): Pressure reading out of range: 915.616455 decibar
2021-06-28T17:49:50.511Z,1624902590.511 [Power24vConverter](INFO): Powering up.
2021-06-28T17:49:50.512Z,1624902590.512 [CANONSampler](INFO): Powering down
2021-06-28T17:49:50.657Z,1624902590.657 [DepthRateCalculator](ERROR): Depth measurement is not active
2021-06-28T17:49:50.724Z,1624902590.724 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2021-06-28T17:49:50.729Z,1624902590.729 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2021-06-28T17:49:50.731Z,1624902590.731 [ElevatorServo](DEBUG): Initializing EZServoServo.
2021-06-28T17:49:50.737Z,1624902590.737 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2021-06-28T17:49:50.738Z,1624902590.738 [MassServo](DEBUG): Initializing EZServoServo.
2021-06-28T17:49:50.745Z,1624902590.745 [MassServo](DEBUG): Initializing MassServo.
2021-06-28T17:49:50.746Z,1624902590.746 [RudderServo](DEBUG): Initializing EZServoServo.
2021-06-28T17:49:50.753Z,1624902590.753 [RudderServo](DEBUG): Initializing RudderServo.
2021-06-28T17:49:50.754Z,1624902590.754 [ThrusterServo](DEBUG): Initializing EZServoServo.
2021-06-28T17:49:50.761Z,1624902590.761 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2021-06-28T17:49:51.569Z,1624902591.569 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2021-06-28T17:49:51.569Z,1624902591.569 [RudderServo](FAULT): Rudder failed to initialize
2021-06-28T17:49:51.569Z,1624902591.569 [RudderServo] Communications Fault, FailCount= 1
2021-06-28T17:49:51.569Z,1624902591.569 [RudderServo](ERROR): Communications Fault
2021-06-28T17:49:51.669Z,1624902591.669 [CBIT](ERROR): Communications Fault in component: RudderServo
2021-06-28T17:49:51.886Z,1624902591.886 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2021-06-28T17:49:51.886Z,1624902591.886 [RudderServo](INFO): Powering down
2021-06-28T17:49:52.221Z,1624902592.221 [WetLabsBB2FL](INFO): Powering down
2021-06-28T17:49:52.504Z,1624902592.504 [RudderServo](DEBUG): Initializing EZServoServo.
2021-06-28T17:49:52.622Z,1624902592.622 [RudderServo](DEBUG): Initializing RudderServo.
2021-06-28T17:49:52.626Z,1624902592.626 [CBIT](INFO): Clearing failed state for component RudderServo
2021-06-28T17:49:52.626Z,1624902592.626 [RudderServo] No Fault, FailCount= 1
2021-06-28T17:50:03.157Z,1624902603.157 [MassServo](ERROR): getPosition uart error serial timeout
2021-06-28T17:50:03.158Z,1624902603.158 [MassServo](FAULT): Invalid EZ Servo response:"\r"
2021-06-28T17:50:03.158Z,1624902603.158 [MassServo] Communications Fault, FailCount= 1
2021-06-28T17:50:03.158Z,1624902603.158 [MassServo](ERROR): Communications Fault
2021-06-28T17:50:03.226Z,1624902603.226 [CBIT](ERROR): Communications Fault in component: MassServo
2021-06-28T17:50:03.431Z,1624902603.431 [MassServo](DEBUG): Uninitialize Mass Servo.
2021-06-28T17:50:03.432Z,1624902603.432 [MassServo](INFO): Powering down
2021-06-28T17:50:04.244Z,1624902604.244 [MassServo](DEBUG): Initializing EZServoServo.
2021-06-28T17:50:04.362Z,1624902604.362 [MassServo](DEBUG): Initializing MassServo.
2021-06-28T17:50:04.429Z,1624902604.429 [CBIT](INFO): Clearing failed state for component MassServo
2021-06-28T17:50:04.429Z,1624902604.429 [MassServo] No Fault, FailCount= 1
2021-06-28T17:50:18.755Z,1624902618.755 [NAL9602](INFO): Powering up NAL9602
2021-06-28T17:50:29.659Z,1624902629.659 [NAL9602](INFO): NAL9602 initialized
2021-06-28T17:51:11.713Z,1624902671.713 [SBIT](IMPORTANT): Beginning Startup BIT
2021-06-28T17:51:11.718Z,1624902671.718 [CBIT](IMPORTANT): Beginning ground fault scan
2021-06-28T17:51:23.016Z,1624902683.016 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): 4.663072
CHAN A1 (24V): -0.180496
CHAN A2 (12V): -0.001592
CHAN A3 (5V): -0.001362
CHAN B0 (3.3V): -0.000116
CHAN B1 (3.15aV): -0.000166
CHAN B2 (3.15bV): -0.000137
CHAN B3 (GND): -0.000015
OPEN: -0.000397
Full Scale Calc: 4.765 mA, -1.589 mA
2021-06-28T17:51:27.615Z,1624902687.615 [CommandLine](IMPORTANT): got command burn on
2021-06-28T17:51:27.615Z,1624902687.615 [CommandLine](IMPORTANT): Activating dropweight wire
2021-06-28T17:51:37.995Z,1624902697.995 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2021-06-28T17:51:59.143Z,1624902719.143 [CommandLine](IMPORTANT): got command burn off
2021-06-28T17:51:59.143Z,1624902719.143 [CommandLine](IMPORTANT): Deactivating dropweight wire
2021-06-28T17:52:05.840Z,1624902725.840 [SBIT](IMPORTANT): SBIT PASSED
2021-06-28T17:52:05.841Z,1624902725.841 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2021-06-28T17:52:05.842Z,1624902725.842 [SBIT](IMPORTANT): AMEcho.loadAtStartup=0 bool;

2021-06-28T17:52:05.842Z,1624902725.842 [SBIT](IMPORTANT): CANONSampler.loadAtStartup=1 bool;

2021-06-28T17:52:05.842Z,1624902725.842 [SBIT](IMPORTANT): DAT.loadAtStartup=0 bool;

2021-06-28T17:52:05.842Z,1624902725.842 [SBIT](IMPORTANT): DAT.verbosity=3 count;

2021-06-28T17:52:05.842Z,1624902725.842 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=250.140291 cubic_centimeter;

2021-06-28T17:52:05.843Z,1624902725.843 [SBIT](IMPORTANT): VerticalControl.massDefault=-15.313086 millimeter;

2021-06-28T17:52:06.252Z,1624902726.252 [MissionManager](IMPORTANT): Started mission Startup
2021-06-28T17:52:06.252Z,1624902726.252 [Startup] Running Loop=1
2021-06-28T17:52:06.252Z,1624902726.252 [Startup](DEBUG): Aggregate::initialize Startup
2021-06-28T17:52:06.253Z,1624902726.253 [Startup:A.GoToSurface] Running Loop=1
2021-06-28T17:52:06.253Z,1624902726.253 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2021-06-28T17:52:06.254Z,1624902726.254 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2021-06-28T17:52:06.254Z,1624902726.254 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2021-06-28T17:52:06.254Z,1624902726.254 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2021-06-28T17:52:06.255Z,1624902726.255 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2021-06-28T17:52:06.255Z,1624902726.255 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2021-06-28T17:52:06.257Z,1624902726.257 [Startup:StartupSatComms] Running Loop=1
2021-06-28T17:52:06.257Z,1624902726.257 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2021-06-28T17:52:06.257Z,1624902726.257 [Startup:StartupSatComms:A] Running Loop=1
2021-06-28T17:52:06.635Z,1624902726.635 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2021-06-28T17:52:24.766Z,1624902744.766 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005094
2021-06-28T17:52:50.176Z,1624902770.176 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2021-06-28T17:52:50.176Z,1624902770.176 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-06-28T17:52:50.199Z,1624902770.199 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-06-28T17:52:50.598Z,1624902770.598 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-06-28T17:52:50.598Z,1624902770.598 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2021-06-28T17:53:06.330Z,1624902786.330 [Startup:StartupSatComms:A](INFO): Timed out from 2021-06-28T17:52:06.3Z
2021-06-28T17:53:06.330Z,1624902786.330 [Startup:StartupSatComms:A] Stopped
2021-06-28T17:53:06.330Z,1624902786.330 [Startup:StartupSatComms:B] Running Loop=1
2021-06-28T17:53:06.798Z,1624902786.798 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2021-06-28T17:53:13.612Z,1624902793.612 [DataOverHttps](INFO): Sending 150 bytes from file Logs/20010913T200137/Courier0000.lzma
2021-06-28T17:53:14.609Z,1624902794.609 [DataOverHttps](INFO): Moved sent file to Logs/20010913T200137/Courier0000.lzma.bak
2021-06-28T17:53:14.609Z,1624902794.609 [DataOverHttps](INFO): SBD MOMSN=15735298
2021-06-28T17:53:30.312Z,1624902810.312 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20210603T181230/Courier0063.lzma
2021-06-28T17:53:31.313Z,1624902811.313 [DataOverHttps](INFO): Moved sent file to Logs/20210603T181230/Courier0063.lzma.bak
2021-06-28T17:53:31.313Z,1624902811.313 [DataOverHttps](INFO): SBD MOMSN=15735301
2021-06-28T17:54:06.505Z,1624902846.505 [Startup:StartupSatComms:B](INFO): Timed out from 2021-06-28T17:53:06.3Z
2021-06-28T17:54:06.505Z,1624902846.505 [Startup:StartupSatComms:B] Stopped
2021-06-28T17:54:06.505Z,1624902846.505 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2021-06-28T17:54:06.505Z,1624902846.505 [Startup:StartupSatComms] Stopped
2021-06-28T17:54:06.506Z,1624902846.506 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2021-06-28T17:54:06.506Z,1624902846.506 [Startup](INFO): Completed Startup
2021-06-28T17:54:06.507Z,1624902846.507 [MissionManager](INFO): Startup is completed.
2021-06-28T17:54:06.507Z,1624902846.507 [MissionManager](INFO): Uninitializing Mission Startup
2021-06-28T17:54:06.507Z,1624902846.507 [Startup] Stopped
2021-06-28T17:54:06.507Z,1624902846.507 [Startup](DEBUG): Aggregate::uninitialize Startup
2021-06-28T17:54:06.507Z,1624902846.507 [Startup:A.GoToSurface] Stopped
2021-06-28T17:54:06.508Z,1624902846.508 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2021-06-28T17:54:06.918Z,1624902846.918 [MissionManager](IMPORTANT): Started mission Default
2021-06-28T17:54:06.919Z,1624902846.919 [Default] Running Loop=1
2021-06-28T17:54:06.919Z,1624902846.919 [Default](DEBUG): Aggregate::initialize Default
2021-06-28T17:54:06.919Z,1624902846.919 [Default:B.GoToSurface] Running Loop=1
2021-06-28T17:54:06.919Z,1624902846.919 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2021-06-28T17:54:06.919Z,1624902846.919 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2021-06-28T17:54:06.920Z,1624902846.920 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2021-06-28T17:54:06.920Z,1624902846.920 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2021-06-28T17:54:06.920Z,1624902846.920 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2021-06-28T17:54:06.921Z,1624902846.921 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2021-06-28T17:54:06.921Z,1624902846.921 [Default:A.Wait] Running Loop=1
2021-06-28T17:54:06.921Z,1624902846.921 [Default:A.Wait](DEBUG): Initialize Wait Component.
2021-06-28T17:54:20.307Z,1624902860.307 [Default:A.Wait](INFO): Done Waiting.
2021-06-28T17:54:20.307Z,1624902860.307 [Default:A.Wait] Stopped
2021-06-28T17:54:20.307Z,1624902860.307 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2021-06-28T17:54:20.678Z,1624902860.678 [Default:CheckIn] Running Loop=1
2021-06-28T17:54:20.678Z,1624902860.678 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-06-28T17:54:20.679Z,1624902860.679 [Default:CheckIn:Read_GPS] Running Loop=1
2021-06-28T17:54:21.057Z,1624902861.057 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2021-06-28T17:54:43.299Z,1624902883.299 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-06-28T17:55:14.423Z,1624902914.423 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-06-28T17:55:33.003Z,1624902933.003 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-06-28T17:55:45.547Z,1624902945.547 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-06-28T17:55:51.153Z,1624902951.153 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2021-06-28T17:55:51.153Z,1624902951.153 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-06-28T17:55:51.164Z,1624902951.164 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-06-28T17:55:51.583Z,1624902951.583 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-06-28T17:55:51.584Z,1624902951.584 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2021-06-28T17:56:16.683Z,1624902976.683 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-06-28T17:56:41.800Z,1624903001.800 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=180.943436
2021-06-28T17:56:47.689Z,1624903007.689 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2021-06-28T17:56:47.692Z,1624903007.692 [BPC1](INFO): Received data from all battery sticks.
2021-06-28T17:57:17.943Z,1624903037.943 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-06-28T17:57:49.067Z,1624903069.067 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-06-28T17:58:20.199Z,1624903100.199 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-06-28T17:58:51.323Z,1624903131.323 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-06-28T17:58:52.150Z,1624903132.150 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2021-06-28T17:58:52.150Z,1624903132.150 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-06-28T17:58:52.187Z,1624903132.187 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-06-28T17:58:52.545Z,1624903132.545 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-06-28T17:58:52.545Z,1624903132.545 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2021-06-28T17:59:20.813Z,1624903160.813 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-06-28T17:54:20.7Z
2021-06-28T17:59:20.813Z,1624903160.813 [Default:CheckIn:Read_GPS] Stopped
2021-06-28T17:59:20.813Z,1624903160.813 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-06-28T17:59:21.218Z,1624903161.218 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2021-06-28T17:59:22.463Z,1624903162.463 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-06-28T17:59:50.701Z,1624903190.701 [NAL9602](ERROR): Queried for signal strength and failed to receive proper response. 
2021-06-28T17:59:50.775Z,1624903190.775 [NAL9602](ERROR): received: 
+CSQ:0

OK
2021-06-28T17:59:51.539Z,1624903191.539 [Power24vConverter](INFO): Powering down.
2021-06-28T17:59:53.611Z,1624903193.611 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-06-28T18:00:24.735Z,1624903224.735 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-06-28T18:00:33.489Z,1624903233.489 [NAL9602](FAULT): GPS failed to acquire within timeout.
2021-06-28T18:00:33.489Z,1624903233.489 [NAL9602] Data Fault, FailCount= 1
2021-06-28T18:00:33.489Z,1624903233.489 [NAL9602](ERROR): Data Fault
2021-06-28T18:00:33.508Z,1624903233.508 [CBIT](ERROR): Data Fault in component: NAL9602
2021-06-28T18:00:33.892Z,1624903233.892 [NAL9602](INFO): Powering down
2021-06-28T18:00:34.736Z,1624903234.736 [CBIT](INFO): Clearing failed state for component NAL9602
2021-06-28T18:00:34.736Z,1624903234.736 [NAL9602] No Fault, FailCount= 1
2021-06-28T18:00:55.883Z,1624903255.883 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-06-28T18:01:04.068Z,1624903264.068 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002898
2021-06-28T18:01:04.193Z,1624903264.193 [NAL9602](INFO): Powering up NAL9602
2021-06-28T18:01:11.214Z,1624903271.214 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20210628T174938/Courier0000.lzma
2021-06-28T18:01:12.217Z,1624903272.217 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Courier0000.lzma.bak
2021-06-28T18:01:12.217Z,1624903272.217 [DataOverHttps](INFO): SBD MOMSN=15735308
2021-06-28T18:01:15.105Z,1624903275.105 [NAL9602](INFO): NAL9602 initialized
2021-06-28T18:01:27.675Z,1624903287.675 [DataOverHttps](INFO): Sending 169 bytes from file Logs/20210628T174938/Courier0004.lzma
2021-06-28T18:01:28.677Z,1624903288.677 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Courier0004.lzma.bak
2021-06-28T18:01:28.677Z,1624903288.677 [DataOverHttps](INFO): SBD MOMSN=15735311
2021-06-28T18:01:44.108Z,1624903304.108 [DataOverHttps](INFO): Sending 337 bytes from file Logs/20010913T200137/Express0001.lzma
2021-06-28T18:01:45.109Z,1624903305.109 [DataOverHttps](INFO): Moved sent file to Logs/20010913T200137/Express0001.lzma.bak
2021-06-28T18:01:45.109Z,1624903305.109 [DataOverHttps](INFO): SBD MOMSN=15735313
2021-06-28T18:01:53.100Z,1624903313.100 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2021-06-28T18:01:53.100Z,1624903313.100 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-06-28T18:01:53.131Z,1624903313.131 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-06-28T18:01:53.502Z,1624903313.502 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-06-28T18:01:53.502Z,1624903313.502 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2021-06-28T18:02:02.104Z,1624903322.104 [DataOverHttps](INFO): Sending 246 bytes from file Logs/20210603T181230/Express0064.lzma
2021-06-28T18:02:03.105Z,1624903323.105 [DataOverHttps](INFO): Moved sent file to Logs/20210603T181230/Express0064.lzma.bak
2021-06-28T18:02:03.105Z,1624903323.105 [DataOverHttps](INFO): SBD MOMSN=15735320
2021-06-28T18:02:22.717Z,1624903342.717 [DataOverHttps](INFO): Sending 878 bytes from file Logs/20210628T174938/Express0001.lzma
2021-06-28T18:02:23.717Z,1624903343.717 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Express0001.lzma.bak
2021-06-28T18:02:23.717Z,1624903343.717 [DataOverHttps](INFO): SBD MOMSN=15735326
2021-06-28T18:02:44.383Z,1624903364.383 [DataOverHttps](INFO): Sending 188 bytes from file Logs/20210628T174938/Express0005.lzma
2021-06-28T18:02:45.385Z,1624903365.385 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Express0005.lzma.bak
2021-06-28T18:02:45.385Z,1624903365.385 [DataOverHttps](INFO): SBD MOMSN=15735349
2021-06-28T18:02:48.199Z,1624903368.199 [Default:CheckIn:Read_Iridium] Stopped
2021-06-28T18:02:48.203Z,1624903368.203 [Default:CheckIn:C.Wait] Running Loop=1
2021-06-28T18:02:48.203Z,1624903368.203 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-06-28T18:04:54.226Z,1624903494.226 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5
2021-06-28T18:04:54.226Z,1624903494.226 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-06-28T18:04:54.237Z,1624903494.237 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-06-28T18:04:54.650Z,1624903494.650 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-06-28T18:04:54.650Z,1624903494.650 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5
2021-06-28T18:07:48.760Z,1624903668.760 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-06-28T18:07:48.760Z,1624903668.760 [Default:CheckIn:C.Wait] Stopped
2021-06-28T18:07:48.761Z,1624903668.761 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-06-28T18:07:48.761Z,1624903668.761 [Default:CheckIn:D] Running Loop=1
2021-06-28T18:07:49.169Z,1624903669.169 [Default:CheckIn:D] Stopped
2021-06-28T18:07:49.169Z,1624903669.169 [Default:CheckIn:E] Running Loop=1
2021-06-28T18:07:49.581Z,1624903669.581 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 13.704168 min 
2021-06-28T18:07:49.581Z,1624903669.581 [Default:CheckIn:E] Stopped
2021-06-28T18:07:49.581Z,1624903669.581 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-06-28T18:07:49.581Z,1624903669.581 [Default:CheckIn] Stopped
2021-06-28T18:07:49.582Z,1624903669.582 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-06-28T18:07:49.582Z,1624903669.582 [Default:CheckIn](INFO): Running loop #2
2021-06-28T18:07:49.582Z,1624903669.582 [Default:CheckIn] Running Loop=2
2021-06-28T18:07:49.582Z,1624903669.582 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-06-28T18:07:49.582Z,1624903669.582 [Default:CheckIn:Read_GPS] Running Loop=1
2021-06-28T18:07:55.228Z,1624903675.228 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6
2021-06-28T18:07:55.228Z,1624903675.228 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-06-28T18:07:55.259Z,1624903675.259 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-06-28T18:07:55.647Z,1624903675.647 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-06-28T18:07:55.647Z,1624903675.647 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6
2021-06-28T18:08:08.264Z,1624903688.264 [DataOverHttps](IMPORTANT): SBD MTMSN=20210628T180807
2021-06-28T18:08:18.251Z,1624903698.251 [DataOverHttps](INFO): Received command:ibit
2021-06-28T18:08:18.280Z,1624903698.280 [CommandLine](IMPORTANT): got command ibit
2021-06-28T18:08:18.370Z,1624903698.370 [IBIT](IMPORTANT): Beginning Initiated BIT
2021-06-28T18:08:18.370Z,1624903698.370 [IBIT](IMPORTANT): Beginning control surface checks.
2021-06-28T18:08:18.373Z,1624903698.373 [CBIT](IMPORTANT): Beginning ground fault scan
2021-06-28T18:08:29.269Z,1624903709.269 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): -0.002742
CHAN A1 (24V): -0.180547
CHAN A2 (12V): -0.002321
CHAN A3 (5V): 4.753929
CHAN B0 (3.3V): 0.001715
CHAN B1 (3.15aV): 0.000167
CHAN B2 (3.15bV): -0.000826
CHAN B3 (GND): -0.000019
OPEN: -0.000329
Full Scale Calc: 4.765 mA, -1.589 mA
2021-06-28T18:10:09.431Z,1624903809.431 [IBIT](FAULT): Error acquiring IBIT communications status. Timeout expired.
2021-06-28T18:10:09.811Z,1624903809.811 [IBIT](IMPORTANT): Battery Status:
Battery Charge (AH): 0.000000
Voltage: 16.016001
2021-06-28T18:10:09.812Z,1624903809.812 [IBIT](IMPORTANT): batteryCapacityThreshold: 50.000000 Ah
2021-06-28T18:10:09.812Z,1624903809.812 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.700000 V
2021-06-28T18:10:10.221Z,1624903810.221 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2021-06-28T18:10:10.222Z,1624903810.222 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2021-06-28T18:10:10.222Z,1624903810.222 [IBIT](IMPORTANT): Pressure:9.979419 PSI
2021-06-28T18:10:10.222Z,1624903810.222 [IBIT](IMPORTANT): Humidity:6.342327 %
2021-06-28T18:10:10.644Z,1624903810.644 [IBIT](IMPORTANT): Vehicle Pitch:0.448113 degrees
2021-06-28T18:10:10.644Z,1624903810.644 [IBIT](IMPORTANT): Vehicle  Roll:5.172916 degrees
2021-06-28T18:10:10.644Z,1624903810.644 [IBIT](IMPORTANT): Vehicle  Heading:205.740707 degrees
2021-06-28T18:10:11.023Z,1624903811.023 [IBIT](IMPORTANT): surfaceThreshold: 1.000000 m
2021-06-28T18:10:11.024Z,1624903811.024 [IBIT](IMPORTANT): buoyancyNeutral: 250.140289 cc
2021-06-28T18:10:11.024Z,1624903811.024 [IBIT](IMPORTANT): massDefault: -1.531309 cm
2021-06-28T18:10:11.024Z,1624903811.024 [IBIT](IMPORTANT): stopDepth: 205.000000 m
2021-06-28T18:10:11.024Z,1624903811.024 [IBIT](IMPORTANT): abortDepth: 250.000000 m
2021-06-28T18:10:11.025Z,1624903811.025 [IBIT](IMPORTANT): IBIT FAILED
2021-06-28T18:10:56.264Z,1624903856.264 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 7
2021-06-28T18:10:56.264Z,1624903856.264 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-06-28T18:10:56.275Z,1624903856.275 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-06-28T18:10:56.698Z,1624903856.698 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-06-28T18:10:56.698Z,1624903856.698 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 7
2021-06-28T18:11:04.515Z,1624903864.515 [CommandLine](IMPORTANT): got command failComponent
2021-06-28T18:11:04.516Z,1624903864.516 [CommandLine](IMPORTANT): Failed components:
2021-06-28T18:11:04.516Z,1624903864.516 [CommandLine](IMPORTANT): No failed Components.
2021-06-28T18:11:10.276Z,1624903870.276 [CommandLine](IMPORTANT): got command ibit
2021-06-28T18:11:10.412Z,1624903870.412 [IBIT](IMPORTANT): Beginning Initiated BIT
2021-06-28T18:11:10.412Z,1624903870.412 [IBIT](IMPORTANT): Beginning control surface checks.
2021-06-28T18:11:10.432Z,1624903870.432 [CBIT](IMPORTANT): Beginning ground fault scan
2021-06-28T18:11:17.669Z,1624903877.669 [NAL9602](FAULT): GPS failed to acquire within timeout.
2021-06-28T18:11:17.669Z,1624903877.669 [NAL9602] Data Fault, FailCount= 2
2021-06-28T18:11:17.669Z,1624903877.669 [NAL9602](ERROR): Data Fault
2021-06-28T18:11:17.720Z,1624903877.720 [CBIT](ERROR): Data Fault in component: NAL9602
2021-06-28T18:11:18.072Z,1624903878.072 [NAL9602](INFO): Powering down
2021-06-28T18:11:18.911Z,1624903878.911 [CBIT](INFO): Clearing failed state for component NAL9602
2021-06-28T18:11:18.911Z,1624903878.911 [NAL9602] No Fault, FailCount= 2
2021-06-28T18:11:21.325Z,1624903881.325 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): -0.002660
CHAN A1 (24V): 4.610929
CHAN A2 (12V): -0.002233
CHAN A3 (5V): 4.753929
CHAN B0 (3.3V): 0.001102
CHAN B1 (3.15aV): -0.000723
CHAN B2 (3.15bV): 0.000269
CHAN B3 (GND): 0.000288
OPEN: -0.000604
Full Scale Calc: 4.765 mA, -1.589 mA
2021-06-28T18:11:48.373Z,1624903908.373 [NAL9602](INFO): Powering up NAL9602
2021-06-28T18:11:59.281Z,1624903919.281 [NAL9602](INFO): NAL9602 initialized
2021-06-28T18:12:31.865Z,1624903951.865 [CommandLine](INFO): End of History
2021-06-28T18:12:31.879Z,1624903951.879 [CommandLine](INFO): End of History
2021-06-28T18:12:31.884Z,1624903951.884 [CommandLine](INFO): End of History
2021-06-28T18:12:31.889Z,1624903951.889 [CommandLine](INFO): End of History
2021-06-28T18:12:31.894Z,1624903951.894 [CommandLine](INFO): End of History
2021-06-28T18:13:01.522Z,1624903981.522 [IBIT](FAULT): Error acquiring IBIT communications status. Timeout expired.
2021-06-28T18:13:01.912Z,1624903981.912 [IBIT](IMPORTANT): Battery Status:
Battery Charge (AH): 0.000000
Voltage: 16.016001
2021-06-28T18:13:01.913Z,1624903981.913 [IBIT](IMPORTANT): batteryCapacityThreshold: 50.000000 Ah
2021-06-28T18:13:01.913Z,1624903981.913 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.700000 V
2021-06-28T18:13:02.348Z,1624903982.348 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2021-06-28T18:13:02.348Z,1624903982.348 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2021-06-28T18:13:02.349Z,1624903982.349 [IBIT](IMPORTANT): Pressure:9.979419 PSI
2021-06-28T18:13:02.349Z,1624903982.349 [IBIT](IMPORTANT): Humidity:6.372848 %
2021-06-28T18:13:02.744Z,1624903982.744 [IBIT](IMPORTANT): Vehicle Pitch:0.442765 degrees
2021-06-28T18:13:02.744Z,1624903982.744 [IBIT](IMPORTANT): Vehicle  Roll:5.172875 degrees
2021-06-28T18:13:02.744Z,1624903982.744 [IBIT](IMPORTANT): Vehicle  Heading:205.809296 degrees
2021-06-28T18:13:03.144Z,1624903983.144 [IBIT](IMPORTANT): surfaceThreshold: 1.000000 m
2021-06-28T18:13:03.145Z,1624903983.145 [IBIT](IMPORTANT): buoyancyNeutral: 250.140289 cc
2021-06-28T18:13:03.145Z,1624903983.145 [IBIT](IMPORTANT): massDefault: -1.531309 cm
2021-06-28T18:13:03.145Z,1624903983.145 [IBIT](IMPORTANT): stopDepth: 205.000000 m
2021-06-28T18:13:03.146Z,1624903983.146 [IBIT](IMPORTANT): abortDepth: 250.000000 m
2021-06-28T18:13:03.146Z,1624903983.146 [IBIT](IMPORTANT): IBIT FAILED
2021-06-28T18:13:03.522Z,1624903983.522 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-06-28T18:07:49.6Z
2021-06-28T18:13:03.522Z,1624903983.522 [Default:CheckIn:Read_GPS] Stopped
2021-06-28T18:13:03.522Z,1624903983.522 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-06-28T18:13:11.620Z,1624903991.620 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20210628T174938/Courier0007.lzma
2021-06-28T18:13:12.621Z,1624903992.621 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Courier0007.lzma.bak
2021-06-28T18:13:12.621Z,1624903992.621 [DataOverHttps](INFO): SBD MOMSN=15735355
2021-06-28T18:13:26.947Z,1624904006.947 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181325.00,A,3648.19026,N,12147.27962,W,0.233,175.94,280621,,,A*7F
2021-06-28T18:13:26.950Z,1624904006.950 [NAL9602](INFO): GPS fix at 20210628T181325: (36.803171, -121.787994)
2021-06-28T18:13:29.960Z,1624904009.960 [DataOverHttps](INFO): Sending 1022 bytes from file Logs/20210628T174938/Express0008.lzma
2021-06-28T18:13:30.957Z,1624904010.957 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Express0008.lzma.bak
2021-06-28T18:13:30.957Z,1624904010.957 [DataOverHttps](INFO): SBD MOMSN=15735357
2021-06-28T18:13:50.822Z,1624904030.822 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20210628T174938/Express0011.lzma
2021-06-28T18:13:51.825Z,1624904031.825 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Express0011.lzma.bak
2021-06-28T18:13:51.825Z,1624904031.825 [DataOverHttps](INFO): SBD MOMSN=15735410
2021-06-28T18:13:54.859Z,1624904034.859 [Default:CheckIn:Read_Iridium] Stopped
2021-06-28T18:13:54.860Z,1624904034.860 [Default:CheckIn:C.Wait] Running Loop=1
2021-06-28T18:13:54.860Z,1624904034.860 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-06-28T18:13:59.272Z,1624904039.272 [NAL9602](INFO): Not Powering down - fast GPS
2021-06-28T18:18:55.422Z,1624904335.422 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-06-28T18:18:55.422Z,1624904335.422 [Default:CheckIn:C.Wait] Stopped
2021-06-28T18:18:55.422Z,1624904335.422 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-06-28T18:18:55.422Z,1624904335.422 [Default:CheckIn:D] Running Loop=1
2021-06-28T18:18:55.821Z,1624904335.821 [Default:CheckIn:D] Stopped
2021-06-28T18:18:55.821Z,1624904335.821 [Default:CheckIn:E] Running Loop=1
2021-06-28T18:18:56.226Z,1624904336.226 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 24.815033 min 
2021-06-28T18:18:56.226Z,1624904336.226 [Default:CheckIn:E] Stopped
2021-06-28T18:18:56.226Z,1624904336.226 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-06-28T18:18:56.227Z,1624904336.227 [Default:CheckIn] Stopped
2021-06-28T18:18:56.227Z,1624904336.227 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-06-28T18:18:56.227Z,1624904336.227 [Default:CheckIn](INFO): Running loop #3
2021-06-28T18:18:56.227Z,1624904336.227 [Default:CheckIn] Running Loop=3
2021-06-28T18:18:56.227Z,1624904336.227 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-06-28T18:18:56.227Z,1624904336.227 [Default:CheckIn:Read_GPS] Running Loop=1
2021-06-28T18:18:58.238Z,1624904338.238 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181857.00,A,3648.15026,N,12147.25584,W,1.788,172.86,280621,,,A*7B
2021-06-28T18:18:58.241Z,1624904338.241 [NAL9602](INFO): GPS fix at 20210628T181857: (36.802504, -121.787597)
2021-06-28T18:18:58.279Z,1624904338.279 [Default:CheckIn:Read_GPS] Stopped
2021-06-28T18:18:58.279Z,1624904338.279 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-06-28T18:19:06.635Z,1624904346.635 [DataOverHttps](INFO): Sending 222 bytes from file Logs/20210628T174938/Courier0013.lzma
2021-06-28T18:19:07.637Z,1624904347.637 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Courier0013.lzma.bak
2021-06-28T18:19:07.637Z,1624904347.637 [DataOverHttps](INFO): SBD MOMSN=15735412
2021-06-28T18:19:18.438Z,1624904358.438 [NAL9602](INFO): SBD MO Status=2, MOMSN=27974, MT Status=2, MTMSN=0
2021-06-28T18:19:18.438Z,1624904358.438 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-06-28T18:19:25.243Z,1624904365.243 [DataOverHttps](INFO): Sending 269 bytes from file Logs/20210628T174938/Express0014.lzma
2021-06-28T18:19:26.245Z,1624904366.245 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Express0014.lzma.bak
2021-06-28T18:19:26.245Z,1624904366.245 [DataOverHttps](INFO): SBD MOMSN=15735415
2021-06-28T18:19:29.799Z,1624904369.799 [Default:CheckIn:Read_Iridium] Stopped
2021-06-28T18:19:29.799Z,1624904369.799 [Default:CheckIn:C.Wait] Running Loop=1
2021-06-28T18:19:29.799Z,1624904369.799 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-06-28T18:19:36.622Z,1624904376.622 [NAL9602](INFO): SBD MO Status=2, MOMSN=27974, MT Status=2, MTMSN=0
2021-06-28T18:19:36.622Z,1624904376.622 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-06-28T18:19:47.557Z,1624904387.557 [NAL9602](INFO): SBD MO Status=0, MOMSN=27974, MT Status=0, MTMSN=0
2021-06-28T18:19:47.557Z,1624904387.557 [NAL9602](INFO): No messages in MT queue
2021-06-28T18:20:18.227Z,1624904418.227 [NAL9602](INFO): Not Powering down - fast GPS
2021-06-28T18:22:32.079Z,1624904552.079 [CommandLine](IMPORTANT): got command ibit
2021-06-28T18:22:32.412Z,1624904552.412 [IBIT](IMPORTANT): Beginning Initiated BIT
2021-06-28T18:22:32.412Z,1624904552.412 [IBIT](IMPORTANT): Beginning control surface checks.
2021-06-28T18:22:32.463Z,1624904552.463 [CBIT](IMPORTANT): Beginning ground fault scan
2021-06-28T18:22:33.987Z,1624904553.987 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182233.00,A,3648.13824,N,12147.22749,W,0.097,85.67,280621,,,D*43
2021-06-28T18:22:33.989Z,1624904553.989 [NAL9602](INFO): GPS fix at 20210628T182233: (36.802304, -121.787125)
2021-06-28T18:22:43.714Z,1624904563.714 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): -0.002262
CHAN A1 (24V): -0.181021
CHAN A2 (12V): 4.697929
CHAN A3 (5V): -0.001253
CHAN B0 (3.3V): -0.000002
CHAN B1 (3.15aV): -0.000578
CHAN B2 (3.15bV): -0.000181
CHAN B3 (GND): -0.000504
OPEN: -0.000356
Full Scale Calc: 4.765 mA, -1.589 mA
2021-06-28T18:23:01.458Z,1624904581.458 [NAL9602](INFO): SBD MO Status=0, MOMSN=27975, MT Status=0, MTMSN=0
2021-06-28T18:23:01.458Z,1624904581.458 [NAL9602](INFO): No messages in MT queue
2021-06-28T18:23:02.670Z,1624904582.670 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182301.00,A,3648.13849,N,12147.22835,W,0.078,85.67,280621,,,D*4D
2021-06-28T18:23:02.708Z,1624904582.708 [NAL9602](INFO): GPS fix at 20210628T182301: (36.802308, -121.787139)
2021-06-28T18:23:05.898Z,1624904585.898 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182305.00,A,3648.13852,N,12147.22830,W,0.019,85.67,280621,,,D*41
2021-06-28T18:23:05.900Z,1624904585.900 [NAL9602](INFO): GPS fix at 20210628T182305: (36.802309, -121.787138)
2021-06-28T18:23:09.134Z,1624904589.134 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182308.00,A,3648.13848,N,12147.22835,W,0.019,85.67,280621,,,D*42
2021-06-28T18:23:09.137Z,1624904589.137 [NAL9602](INFO): GPS fix at 20210628T182308: (36.802308, -121.787139)
2021-06-28T18:23:11.958Z,1624904591.958 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182311.00,A,3648.13848,N,12147.22833,W,0.078,85.67,280621,,,D*4B
2021-06-28T18:23:11.960Z,1624904591.960 [NAL9602](INFO): GPS fix at 20210628T182311: (36.802308, -121.787139)
2021-06-28T18:23:15.190Z,1624904595.190 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182314.00,A,3648.13844,N,12147.22839,W,0.039,85.67,280621,,,D*4D
2021-06-28T18:23:15.193Z,1624904595.193 [NAL9602](INFO): GPS fix at 20210628T182314: (36.802307, -121.787140)
2021-06-28T18:23:18.036Z,1624904598.036 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182317.00,A,3648.13837,N,12147.22844,W,0.019,85.67,280621,,,D*42
2021-06-28T18:23:18.038Z,1624904598.038 [NAL9602](INFO): GPS fix at 20210628T182317: (36.802306, -121.787141)
2021-06-28T18:23:18.471Z,1624904598.471 [IBIT](IMPORTANT): Communications Status:
Fix Status: 1
Iridium Signal Strength: 2
Latitude: 36.802307 Longitude: -121.787140
2021-06-28T18:23:18.854Z,1624904598.854 [IBIT](IMPORTANT): Battery Status:
Battery Charge (AH): 0.000000
Voltage: 15.977000
2021-06-28T18:23:18.855Z,1624904598.855 [IBIT](IMPORTANT): batteryCapacityThreshold: 50.000000 Ah
2021-06-28T18:23:18.855Z,1624904598.855 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.700000 V
2021-06-28T18:23:19.276Z,1624904599.276 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2021-06-28T18:23:19.277Z,1624904599.277 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2021-06-28T18:23:19.277Z,1624904599.277 [IBIT](IMPORTANT): Pressure:9.970106 PSI
2021-06-28T18:23:19.277Z,1624904599.277 [IBIT](IMPORTANT): Humidity:6.446099 %
2021-06-28T18:23:19.661Z,1624904599.661 [IBIT](IMPORTANT): Vehicle Pitch:0.043590 degrees
2021-06-28T18:23:19.662Z,1624904599.662 [IBIT](IMPORTANT): Vehicle  Roll:4.188673 degrees
2021-06-28T18:23:19.662Z,1624904599.662 [IBIT](IMPORTANT): Vehicle  Heading:14.912531 degrees
2021-06-28T18:23:20.069Z,1624904600.069 [IBIT](IMPORTANT): surfaceThreshold: 1.000000 m
2021-06-28T18:23:20.069Z,1624904600.069 [IBIT](IMPORTANT): buoyancyNeutral: 250.140289 cc
2021-06-28T18:23:20.070Z,1624904600.070 [IBIT](IMPORTANT): massDefault: -1.531309 cm
2021-06-28T18:23:20.070Z,1624904600.070 [IBIT](IMPORTANT): stopDepth: 205.000000 m
2021-06-28T18:23:20.070Z,1624904600.070 [IBIT](IMPORTANT): abortDepth: 250.000000 m
2021-06-28T18:23:20.070Z,1624904600.070 [IBIT](IMPORTANT): IBIT PASSED
2021-06-28T18:23:50.344Z,1624904630.344 [NAL9602](INFO): Not Powering down - fast GPS
2021-06-28T18:24:30.386Z,1624904670.386 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-06-28T18:24:30.386Z,1624904670.386 [Default:CheckIn:C.Wait] Stopped
2021-06-28T18:24:30.386Z,1624904670.386 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-06-28T18:24:30.386Z,1624904670.386 [Default:CheckIn:D] Running Loop=1
2021-06-28T18:24:30.778Z,1624904670.778 [Default:CheckIn:D] Stopped
2021-06-28T18:24:30.778Z,1624904670.778 [Default:CheckIn:E] Running Loop=1
2021-06-28T18:24:31.243Z,1624904671.243 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 30.397660 min 
2021-06-28T18:24:31.243Z,1624904671.243 [Default:CheckIn:E] Stopped
2021-06-28T18:24:31.243Z,1624904671.243 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-06-28T18:24:31.243Z,1624904671.243 [Default:CheckIn] Stopped
2021-06-28T18:24:31.243Z,1624904671.243 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-06-28T18:24:31.244Z,1624904671.244 [Default:CheckIn](INFO): Running loop #4
2021-06-28T18:24:31.244Z,1624904671.244 [Default:CheckIn] Running Loop=4
2021-06-28T18:24:31.244Z,1624904671.244 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-06-28T18:24:31.244Z,1624904671.244 [Default:CheckIn:Read_GPS] Running Loop=1
2021-06-28T18:24:33.194Z,1624904673.194 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182432.00,A,3648.13844,N,12147.22910,W,0.078,85.67,280621,,,D*41
2021-06-28T18:24:33.197Z,1624904673.197 [NAL9602](INFO): GPS fix at 20210628T182432: (36.802307, -121.787152)
2021-06-28T18:24:33.253Z,1624904673.253 [Default:CheckIn:Read_GPS] Stopped
2021-06-28T18:24:33.253Z,1624904673.253 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-06-28T18:24:42.321Z,1624904682.321 [CommandLine](IMPORTANT): got command gfscan
2021-06-28T18:24:42.458Z,1624904682.458 [DataOverHttps](INFO): Sending 71 bytes from file Logs/20210628T174938/Courier0016.lzma
2021-06-28T18:24:42.524Z,1624904682.524 [CBIT](IMPORTANT): Beginning ground fault scan
2021-06-28T18:24:43.461Z,1624904683.461 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Courier0016.lzma.bak
2021-06-28T18:24:43.461Z,1624904683.461 [DataOverHttps](INFO): SBD MOMSN=15735420
2021-06-28T18:24:53.446Z,1624904693.446 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): -0.002593
CHAN A1 (24V): -0.180402
CHAN A2 (12V): -0.001897
CHAN A3 (5V): -0.001813
CHAN B0 (3.3V): -0.000119
CHAN B1 (3.15aV): -0.000226
CHAN B2 (3.15bV): 0.000040
CHAN B3 (GND): 0.000173
OPEN: -0.000403
Full Scale Calc: 4.765 mA, -1.589 mA
2021-06-28T18:25:01.032Z,1624904701.032 [DataOverHttps](INFO): Sending 776 bytes from file Logs/20210628T174938/Express0017.lzma
2021-06-28T18:25:02.033Z,1624904702.033 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Express0017.lzma.bak
2021-06-28T18:25:02.033Z,1624904702.033 [DataOverHttps](INFO): SBD MOMSN=15735423
2021-06-28T18:25:04.723Z,1624904704.723 [Default:CheckIn:Read_Iridium] Stopped
2021-06-28T18:25:04.723Z,1624904704.723 [Default:CheckIn:C.Wait] Running Loop=1
2021-06-28T18:25:04.724Z,1624904704.724 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-06-28T18:25:28.140Z,1624904728.140 [NAL9602](INFO): SBD MO Status=0, MOMSN=27976, MT Status=0, MTMSN=0
2021-06-28T18:25:28.141Z,1624904728.141 [NAL9602](INFO): No messages in MT queue
2021-06-28T18:25:44.055Z,1624904744.055 [CommandLine](IMPORTANT): got command show variable amecho
2021-06-28T18:25:44.150Z,1624904744.150 [CommandLine](IMPORTANT): AMEcho.loadControl (none)
2021-06-28T18:25:44.150Z,1624904744.150 [CommandLine](IMPORTANT): AMEcho.uart (none)
2021-06-28T18:25:44.151Z,1624904744.151 [CommandLine](IMPORTANT): AMEcho.baud (bit_per_second)
2021-06-28T18:25:44.187Z,1624904744.187 [CommandLine](IMPORTANT): AMEcho.loadAtStartup (bool)
2021-06-28T18:25:44.188Z,1624904744.188 [CommandLine](IMPORTANT): AMEcho.simulateHardware (bool)
2021-06-28T18:25:44.188Z,1624904744.188 [CommandLine](IMPORTANT): AMEcho.enabled (bool)
2021-06-28T18:25:44.189Z,1624904744.188 [CommandLine](IMPORTANT): AMEcho.depthThreshold (meter)
2021-06-28T18:25:58.840Z,1624904758.840 [NAL9602](INFO): Not Powering down - fast GPS
2021-06-28T18:26:00.374Z,1624904760.374 [CommandLine](IMPORTANT): got command get AMEcho.loadAtStartup
2021-06-28T18:26:00.375Z,1624904760.375 [CommandLine](IMPORTANT): AMEcho.loadAtStartup 0 bool
2021-06-28T18:26:28.853Z,1624904788.853 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2
2021-06-28T18:26:32.687Z,1624904792.687 [CommandLine](IMPORTANT): got command gfscan
2021-06-28T18:26:32.929Z,1624904792.929 [CBIT](IMPORTANT): Beginning ground fault scan
2021-06-28T18:26:43.815Z,1624904803.815 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.002567
CHAN A1 (24V): 0.000630
CHAN A2 (12V): -0.002492
CHAN A3 (5V): -0.001500
CHAN B0 (3.3V): 0.000322
CHAN B1 (3.15aV): 0.000390
CHAN B2 (3.15bV): -0.000067
CHAN B3 (GND): -0.000219
OPEN: -0.000244
Full Scale Calc: 4.765 mA, -1.589 mA
2021-06-28T18:30:05.410Z,1624905005.410 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-06-28T18:30:05.410Z,1624905005.410 [Default:CheckIn:C.Wait] Stopped
2021-06-28T18:30:05.410Z,1624905005.410 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-06-28T18:30:05.410Z,1624905005.410 [Default:CheckIn:D] Running Loop=1
2021-06-28T18:30:05.816Z,1624905005.816 [Default:CheckIn:D] Stopped
2021-06-28T18:30:05.816Z,1624905005.816 [Default:CheckIn:E] Running Loop=1
2021-06-28T18:30:06.233Z,1624905006.233 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 35.981620 min 
2021-06-28T18:30:06.233Z,1624905006.233 [Default:CheckIn:E] Stopped
2021-06-28T18:30:06.233Z,1624905006.233 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-06-28T18:30:06.233Z,1624905006.233 [Default:CheckIn] Stopped
2021-06-28T18:30:06.233Z,1624905006.233 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-06-28T18:30:06.233Z,1624905006.233 [Default:CheckIn](INFO): Running loop #5
2021-06-28T18:30:06.233Z,1624905006.233 [Default:CheckIn] Running Loop=5
2021-06-28T18:30:06.234Z,1624905006.234 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-06-28T18:30:06.234Z,1624905006.234 [Default:CheckIn:Read_GPS] Running Loop=1
2021-06-28T18:30:08.234Z,1624905008.234 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183007.00,A,3648.13957,N,12147.22712,W,0.019,85.67,280621,,,D*4A
2021-06-28T18:30:08.237Z,1624905008.237 [NAL9602](INFO): GPS fix at 20210628T183007: (36.802326, -121.787119)
2021-06-28T18:30:08.272Z,1624905008.272 [Default:CheckIn:Read_GPS] Stopped
2021-06-28T18:30:08.272Z,1624905008.272 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-06-28T18:30:16.419Z,1624905016.419 [DataOverHttps](INFO): Sending 71 bytes from file Logs/20210628T174938/Courier0019.lzma
2021-06-28T18:30:17.421Z,1624905017.421 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Courier0019.lzma.bak
2021-06-28T18:30:17.421Z,1624905017.421 [DataOverHttps](INFO): SBD MOMSN=15735450
2021-06-28T18:30:21.594Z,1624905021.594 [NAL9602](INFO): SBD MO Status=0, MOMSN=27977, MT Status=0, MTMSN=0
2021-06-28T18:30:21.594Z,1624905021.594 [NAL9602](INFO): No messages in MT queue
2021-06-28T18:30:42.448Z,1624905042.448 [DataOverHttps](INFO): Sending 596 bytes from file Logs/20210628T174938/Express0020.lzma
2021-06-28T18:30:43.449Z,1624905043.449 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Express0020.lzma.bak
2021-06-28T18:30:43.449Z,1624905043.449 [DataOverHttps](INFO): SBD MOMSN=15735453
2021-06-28T18:30:46.346Z,1624905046.346 [Default:CheckIn:Read_Iridium] Stopped
2021-06-28T18:30:46.346Z,1624905046.346 [Default:CheckIn:C.Wait] Running Loop=1
2021-06-28T18:30:46.346Z,1624905046.346 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-06-28T18:30:52.396Z,1624905052.396 [NAL9602](INFO): Not Powering down - fast GPS
2021-06-28T18:35:47.002Z,1624905347.002 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-06-28T18:35:47.002Z,1624905347.002 [Default:CheckIn:C.Wait] Stopped
2021-06-28T18:35:47.002Z,1624905347.002 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-06-28T18:35:47.002Z,1624905347.002 [Default:CheckIn:D] Running Loop=1
2021-06-28T18:35:47.406Z,1624905347.406 [Default:CheckIn:D] Stopped
2021-06-28T18:35:47.406Z,1624905347.406 [Default:CheckIn:E] Running Loop=1
2021-06-28T18:35:47.809Z,1624905347.809 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 41.674788 min 
2021-06-28T18:35:47.809Z,1624905347.809 [Default:CheckIn:E] Stopped
2021-06-28T18:35:47.809Z,1624905347.809 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-06-28T18:35:47.809Z,1624905347.809 [Default:CheckIn] Stopped
2021-06-28T18:35:47.809Z,1624905347.809 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-06-28T18:35:47.809Z,1624905347.809 [Default:CheckIn](INFO): Running loop #6
2021-06-28T18:35:47.809Z,1624905347.809 [Default:CheckIn] Running Loop=6
2021-06-28T18:35:47.810Z,1624905347.810 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-06-28T18:35:47.810Z,1624905347.810 [Default:CheckIn:Read_GPS] Running Loop=1
2021-06-28T18:35:49.822Z,1624905349.822 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183549.00,A,3648.13808,N,12147.22955,W,0.078,85.67,280621,,,D*44
2021-06-28T18:35:49.836Z,1624905349.836 [NAL9602](INFO): GPS fix at 20210628T183549: (36.802301, -121.787159)
2021-06-28T18:35:49.847Z,1624905349.847 [Default:CheckIn:Read_GPS] Stopped
2021-06-28T18:35:49.847Z,1624905349.847 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-06-28T18:35:58.663Z,1624905358.663 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210628T174938/Courier0022.lzma
2021-06-28T18:35:59.665Z,1624905359.665 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Courier0022.lzma.bak
2021-06-28T18:35:59.665Z,1624905359.665 [DataOverHttps](INFO): SBD MOMSN=15735475
2021-06-28T18:36:06.786Z,1624905366.786 [NAL9602](INFO): SBD MO Status=0, MOMSN=27978, MT Status=0, MTMSN=0
2021-06-28T18:36:06.786Z,1624905366.786 [NAL9602](INFO): No messages in MT queue
2021-06-28T18:36:18.935Z,1624905378.935 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20210628T174938/Express0023.lzma
2021-06-28T18:36:19.937Z,1624905379.937 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Express0023.lzma.bak
2021-06-28T18:36:19.937Z,1624905379.937 [DataOverHttps](INFO): SBD MOMSN=15735485
2021-06-28T18:36:24.233Z,1624905384.233 [Default:CheckIn:Read_Iridium] Stopped
2021-06-28T18:36:24.233Z,1624905384.233 [Default:CheckIn:C.Wait] Running Loop=1
2021-06-28T18:36:24.233Z,1624905384.233 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-06-28T18:36:37.592Z,1624905397.592 [NAL9602](INFO): Not Powering down - fast GPS
2021-06-28T18:41:24.858Z,1624905684.858 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-06-28T18:41:24.858Z,1624905684.858 [Default:CheckIn:C.Wait] Stopped
2021-06-28T18:41:24.858Z,1624905684.858 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-06-28T18:41:24.859Z,1624905684.859 [Default:CheckIn:D] Running Loop=1
2021-06-28T18:41:25.268Z,1624905685.268 [Default:CheckIn:D] Stopped
2021-06-28T18:41:25.268Z,1624905685.268 [Default:CheckIn:E] Running Loop=1
2021-06-28T18:41:25.677Z,1624905685.677 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 47.305819 min 
2021-06-28T18:41:25.677Z,1624905685.677 [Default:CheckIn:E] Stopped
2021-06-28T18:41:25.678Z,1624905685.678 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-06-28T18:41:25.678Z,1624905685.678 [Default:CheckIn] Stopped
2021-06-28T18:41:25.678Z,1624905685.678 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-06-28T18:41:25.678Z,1624905685.678 [Default:CheckIn](INFO): Running loop #7
2021-06-28T18:41:25.678Z,1624905685.678 [Default:CheckIn] Running Loop=7
2021-06-28T18:41:25.678Z,1624905685.678 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-06-28T18:41:25.678Z,1624905685.678 [Default:CheckIn:Read_GPS] Running Loop=1
2021-06-28T18:41:27.682Z,1624905687.682 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184126.00,A,3648.13884,N,12147.22848,W,0.039,85.67,280621,,,D*42
2021-06-28T18:41:27.694Z,1624905687.694 [NAL9602](INFO): GPS fix at 20210628T184126: (36.802314, -121.787141)
2021-06-28T18:41:27.705Z,1624905687.705 [Default:CheckIn:Read_GPS] Stopped
2021-06-28T18:41:27.706Z,1624905687.706 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-06-28T18:41:35.458Z,1624905695.458 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210628T174938/Courier0025.lzma
2021-06-28T18:41:36.461Z,1624905696.461 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Courier0025.lzma.bak
2021-06-28T18:41:36.461Z,1624905696.461 [DataOverHttps](INFO): SBD MOMSN=15735498
2021-06-28T18:41:41.822Z,1624905701.822 [NAL9602](INFO): SBD MO Status=0, MOMSN=27979, MT Status=0, MTMSN=0
2021-06-28T18:41:41.822Z,1624905701.822 [NAL9602](INFO): No messages in MT queue
2021-06-28T18:41:53.900Z,1624905713.900 [DataOverHttps](INFO): Sending 128 bytes from file Logs/20210628T174938/Express0026.lzma
2021-06-28T18:41:54.901Z,1624905714.901 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Express0026.lzma.bak
2021-06-28T18:41:54.901Z,1624905714.901 [DataOverHttps](INFO): SBD MOMSN=15735501
2021-06-28T18:41:57.607Z,1624905717.607 [Default:CheckIn:Read_Iridium] Stopped
2021-06-28T18:41:57.607Z,1624905717.607 [Default:CheckIn:C.Wait] Running Loop=1
2021-06-28T18:41:57.607Z,1624905717.607 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-06-28T18:42:12.532Z,1624905732.532 [NAL9602](INFO): Not Powering down - fast GPS
2021-06-28T18:46:58.182Z,1624906018.182 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-06-28T18:46:58.182Z,1624906018.182 [Default:CheckIn:C.Wait] Stopped
2021-06-28T18:46:58.183Z,1624906018.183 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-06-28T18:46:58.183Z,1624906018.183 [Default:CheckIn:D] Running Loop=1
2021-06-28T18:46:58.588Z,1624906018.588 [Default:CheckIn:D] Stopped
2021-06-28T18:46:58.588Z,1624906018.588 [Default:CheckIn:E] Running Loop=1
2021-06-28T18:46:59.009Z,1624906019.009 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 52.861153 min 
2021-06-28T18:46:59.009Z,1624906019.009 [Default:CheckIn:E] Stopped
2021-06-28T18:46:59.009Z,1624906019.009 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-06-28T18:46:59.009Z,1624906019.009 [Default:CheckIn] Stopped
2021-06-28T18:46:59.009Z,1624906019.009 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-06-28T18:46:59.009Z,1624906019.009 [Default:CheckIn](INFO): Running loop #8
2021-06-28T18:46:59.009Z,1624906019.009 [Default:CheckIn] Running Loop=8
2021-06-28T18:46:59.010Z,1624906019.010 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-06-28T18:46:59.010Z,1624906019.010 [Default:CheckIn:Read_GPS] Running Loop=1
2021-06-28T18:47:00.998Z,1624906020.998 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184700.00,A,3648.13781,N,12147.22908,W,0.019,85.67,280621,,,D*4D
2021-06-28T18:47:01.001Z,1624906021.001 [NAL9602](INFO): GPS fix at 20210628T184700: (36.802297, -121.787151)
2021-06-28T18:47:01.040Z,1624906021.040 [Default:CheckIn:Read_GPS] Stopped
2021-06-28T18:47:01.040Z,1624906021.040 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-06-28T18:47:10.630Z,1624906030.630 [DataOverHttps](INFO): Sending 71 bytes from file Logs/20210628T174938/Courier0028.lzma
2021-06-28T18:47:11.633Z,1624906031.633 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Courier0028.lzma.bak
2021-06-28T18:47:11.633Z,1624906031.633 [DataOverHttps](INFO): SBD MOMSN=15735509
2021-06-28T18:47:20.386Z,1624906040.386 [NAL9602](INFO): SBD MO Status=0, MOMSN=27980, MT Status=0, MTMSN=0
2021-06-28T18:47:20.386Z,1624906040.386 [NAL9602](INFO): No messages in MT queue
2021-06-28T18:47:29.211Z,1624906049.211 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20210628T174938/Express0029.lzma
2021-06-28T18:47:30.213Z,1624906050.213 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Express0029.lzma.bak
2021-06-28T18:47:30.213Z,1624906050.213 [DataOverHttps](INFO): SBD MOMSN=15735513
2021-06-28T18:47:32.984Z,1624906052.984 [Default:CheckIn:Read_Iridium] Stopped
2021-06-28T18:47:32.984Z,1624906052.984 [Default:CheckIn:C.Wait] Running Loop=1
2021-06-28T18:47:32.984Z,1624906052.984 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-06-28T18:47:51.092Z,1624906071.092 [NAL9602](INFO): Not Powering down - fast GPS
2021-06-28T18:52:33.618Z,1624906353.618 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-06-28T18:52:33.618Z,1624906353.618 [Default:CheckIn:C.Wait] Stopped
2021-06-28T18:52:33.618Z,1624906353.618 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-06-28T18:52:33.618Z,1624906353.618 [Default:CheckIn:D] Running Loop=1
2021-06-28T18:52:34.015Z,1624906354.015 [Default:CheckIn:D] Stopped
2021-06-28T18:52:34.015Z,1624906354.015 [Default:CheckIn:E] Running Loop=1
2021-06-28T18:52:34.432Z,1624906354.432 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 58.451599 min 
2021-06-28T18:52:34.432Z,1624906354.432 [Default:CheckIn:E] Stopped
2021-06-28T18:52:34.432Z,1624906354.432 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-06-28T18:52:34.432Z,1624906354.432 [Default:CheckIn] Stopped
2021-06-28T18:52:34.432Z,1624906354.432 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-06-28T18:52:34.433Z,1624906354.433 [Default:CheckIn](INFO): Running loop #9
2021-06-28T18:52:34.433Z,1624906354.433 [Default:CheckIn] Running Loop=9
2021-06-28T18:52:34.433Z,1624906354.433 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-06-28T18:52:34.433Z,1624906354.433 [Default:CheckIn:Read_GPS] Running Loop=1
2021-06-28T18:52:36.426Z,1624906356.426 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185235.00,A,3648.14104,N,12147.20709,W,0.544,58.99,280621,,,D*42
2021-06-28T18:52:36.429Z,1624906356.429 [NAL9602](INFO): GPS fix at 20210628T185235: (36.802351, -121.786785)
2021-06-28T18:52:36.484Z,1624906356.484 [Default:CheckIn:Read_GPS] Stopped
2021-06-28T18:52:36.484Z,1624906356.484 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-06-28T18:52:44.070Z,1624906364.070 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210628T174938/Courier0031.lzma
2021-06-28T18:52:45.073Z,1624906365.073 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Courier0031.lzma.bak
2021-06-28T18:52:45.073Z,1624906365.073 [DataOverHttps](INFO): SBD MOMSN=15735545
2021-06-28T18:52:50.970Z,1624906370.970 [NAL9602](INFO): SBD MO Status=0, MOMSN=27981, MT Status=0, MTMSN=0
2021-06-28T18:52:50.970Z,1624906370.970 [NAL9602](INFO): No messages in MT queue
2021-06-28T18:53:02.519Z,1624906382.519 [DataOverHttps](INFO): Sending 140 bytes from file Logs/20210628T174938/Express0032.lzma
2021-06-28T18:53:04.237Z,1624906384.237 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Express0032.lzma.bak
2021-06-28T18:53:04.237Z,1624906384.237 [DataOverHttps](INFO): SBD MOMSN=15735548
2021-06-28T18:53:06.371Z,1624906386.371 [Default:CheckIn:Read_Iridium] Stopped
2021-06-28T18:53:06.371Z,1624906386.371 [Default:CheckIn:C.Wait] Running Loop=1
2021-06-28T18:53:06.371Z,1624906386.371 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-06-28T18:53:21.676Z,1624906401.676 [NAL9602](INFO): Not Powering down - fast GPS
2021-06-28T18:58:07.030Z,1624906687.030 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-06-28T18:58:07.030Z,1624906687.030 [Default:CheckIn:C.Wait] Stopped
2021-06-28T18:58:07.030Z,1624906687.030 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-06-28T18:58:07.030Z,1624906687.030 [Default:CheckIn:D] Running Loop=1
2021-06-28T18:58:07.439Z,1624906687.439 [Default:CheckIn:D] Stopped
2021-06-28T18:58:07.439Z,1624906687.439 [Default:CheckIn:E] Running Loop=1
2021-06-28T18:58:07.848Z,1624906687.848 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 64.008663 min 
2021-06-28T18:58:07.848Z,1624906687.848 [Default:CheckIn:E] Stopped
2021-06-28T18:58:07.848Z,1624906687.848 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-06-28T18:58:07.848Z,1624906687.848 [Default:CheckIn] Stopped
2021-06-28T18:58:07.848Z,1624906687.848 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-06-28T18:58:07.849Z,1624906687.849 [Default:CheckIn](INFO): Running loop #10
2021-06-28T18:58:07.849Z,1624906687.849 [Default:CheckIn] Running Loop=10
2021-06-28T18:58:07.849Z,1624906687.849 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-06-28T18:58:07.849Z,1624906687.849 [Default:CheckIn:Read_GPS] Running Loop=1
2021-06-28T18:58:09.874Z,1624906689.874 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185809.00,A,3648.13859,N,12147.20381,W,0.330,96.20,280621,,,A*45
2021-06-28T18:58:09.877Z,1624906689.877 [NAL9602](INFO): GPS fix at 20210628T185809: (36.802310, -121.786730)
2021-06-28T18:58:09.908Z,1624906689.908 [Default:CheckIn:Read_GPS] Stopped
2021-06-28T18:58:09.908Z,1624906689.908 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-06-28T18:58:17.627Z,1624906697.627 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210628T174938/Courier0034.lzma
2021-06-28T18:58:18.629Z,1624906698.629 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Courier0034.lzma.bak
2021-06-28T18:58:18.630Z,1624906698.630 [DataOverHttps](INFO): SBD MOMSN=15735580
2021-06-28T18:58:22.562Z,1624906702.562 [BPC1](ERROR): BPC1B: No match for serial number 1717 in BPC1B's battery stick inventory (sticks 32-63 in onboard configuration file).
2021-06-28T18:58:33.029Z,1624906713.029 [NAL9602](INFO): SBD MO Status=2, MOMSN=27982, MT Status=2, MTMSN=0
2021-06-28T18:58:33.029Z,1624906713.029 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-06-28T18:58:43.503Z,1624906723.503 [DataOverHttps](INFO): Sending 128 bytes from file Logs/20210628T174938/Express0035.lzma
2021-06-28T18:58:44.505Z,1624906724.505 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Express0035.lzma.bak
2021-06-28T18:58:44.505Z,1624906724.505 [DataOverHttps](INFO): SBD MOMSN=15735583
2021-06-28T18:58:47.629Z,1624906727.629 [Default:CheckIn:Read_Iridium] Stopped
2021-06-28T18:58:47.629Z,1624906727.629 [Default:CheckIn:C.Wait] Running Loop=1
2021-06-28T18:58:47.629Z,1624906727.629 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-06-28T19:02:25.798Z,1624906945.798 [NAL9602](INFO): SBD MO Status=0, MOMSN=27982, MT Status=0, MTMSN=0
2021-06-28T19:02:25.798Z,1624906945.798 [NAL9602](INFO): No messages in MT queue
2021-06-28T19:02:56.508Z,1624906976.508 [NAL9602](INFO): Not Powering down - fast GPS
2021-06-28T19:03:48.230Z,1624907028.230 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-06-28T19:03:48.247Z,1624907028.247 [Default:CheckIn:C.Wait] Stopped
2021-06-28T19:03:48.247Z,1624907028.247 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-06-28T19:03:48.247Z,1624907028.247 [Default:CheckIn:D] Running Loop=1
2021-06-28T19:03:48.626Z,1624907028.626 [Default:CheckIn:D] Stopped
2021-06-28T19:03:48.626Z,1624907028.626 [Default:CheckIn:E] Running Loop=1
2021-06-28T19:03:49.033Z,1624907029.033 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 69.695125 min 
2021-06-28T19:03:49.033Z,1624907029.033 [Default:CheckIn:E] Stopped
2021-06-28T19:03:49.033Z,1624907029.033 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-06-28T19:03:49.033Z,1624907029.033 [Default:CheckIn] Stopped
2021-06-28T19:03:49.033Z,1624907029.033 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-06-28T19:03:49.033Z,1624907029.033 [Default:CheckIn](INFO): Running loop #11
2021-06-28T19:03:49.033Z,1624907029.033 [Default:CheckIn] Running Loop=11
2021-06-28T19:03:49.034Z,1624907029.034 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-06-28T19:03:49.034Z,1624907029.034 [Default:CheckIn:Read_GPS] Running Loop=1
2021-06-28T19:03:51.042Z,1624907031.042 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190350.00,A,3648.13787,N,12147.20511,W,0.156,96.20,280621,,,D*42
2021-06-28T19:03:51.056Z,1624907031.056 [NAL9602](INFO): GPS fix at 20210628T190350: (36.802298, -121.786752)
2021-06-28T19:03:51.067Z,1624907031.067 [Default:CheckIn:Read_GPS] Stopped
2021-06-28T19:03:51.067Z,1624907031.067 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-06-28T19:03:59.075Z,1624907039.075 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210628T174938/Courier0037.lzma
2021-06-28T19:04:00.077Z,1624907040.077 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Courier0037.lzma.bak
2021-06-28T19:04:00.077Z,1624907040.077 [DataOverHttps](INFO): SBD MOMSN=15735587
2021-06-28T19:04:12.054Z,1624907052.054 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2021-06-28T19:04:12.057Z,1624907052.057 [BPC1](INFO): Received data from all battery sticks.
2021-06-28T19:04:18.111Z,1624907058.111 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20210628T174938/Express0038.lzma
2021-06-28T19:04:19.113Z,1624907059.113 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Express0038.lzma.bak
2021-06-28T19:04:19.113Z,1624907059.113 [DataOverHttps](INFO): SBD MOMSN=15735590
2021-06-28T19:04:23.425Z,1624907063.425 [Default:CheckIn:Read_Iridium] Stopped
2021-06-28T19:04:23.425Z,1624907063.425 [Default:CheckIn:C.Wait] Running Loop=1
2021-06-28T19:04:23.425Z,1624907063.425 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-06-28T19:04:52.174Z,1624907092.174 [NAL9602](INFO): SBD MO Status=2, MOMSN=27983, MT Status=2, MTMSN=0
2021-06-28T19:04:52.174Z,1624907092.174 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-06-28T19:05:40.662Z,1624907140.662 [NAL9602](INFO): SBD MO Status=0, MOMSN=27983, MT Status=0, MTMSN=0
2021-06-28T19:05:40.662Z,1624907140.662 [NAL9602](INFO): No messages in MT queue
2021-06-28T19:06:11.356Z,1624907171.356 [NAL9602](INFO): Not Powering down - fast GPS
2021-06-28T19:09:24.096Z,1624907364.096 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-06-28T19:09:24.096Z,1624907364.096 [Default:CheckIn:C.Wait] Stopped
2021-06-28T19:09:24.096Z,1624907364.096 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-06-28T19:09:24.096Z,1624907364.096 [Default:CheckIn:D] Running Loop=1
2021-06-28T19:09:24.490Z,1624907364.490 [Default:CheckIn:D] Stopped
2021-06-28T19:09:24.490Z,1624907364.490 [Default:CheckIn:E] Running Loop=1
2021-06-28T19:09:24.891Z,1624907364.891 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 75.292855 min 
2021-06-28T19:09:24.891Z,1624907364.891 [Default:CheckIn:E] Stopped
2021-06-28T19:09:24.891Z,1624907364.891 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-06-28T19:09:24.891Z,1624907364.891 [Default:CheckIn] Stopped
2021-06-28T19:09:24.891Z,1624907364.891 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-06-28T19:09:24.891Z,1624907364.891 [Default:CheckIn](INFO): Running loop #12
2021-06-28T19:09:24.892Z,1624907364.892 [Default:CheckIn] Running Loop=12
2021-06-28T19:09:24.892Z,1624907364.892 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-06-28T19:09:24.892Z,1624907364.892 [Default:CheckIn:Read_GPS] Running Loop=1
2021-06-28T19:09:26.905Z,1624907366.905 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190926.00,A,3648.45398,N,12147.10580,W,4.860,3.94,280621,,,D*70
2021-06-28T19:09:26.907Z,1624907366.907 [NAL9602](INFO): GPS fix at 20210628T190926: (36.807566, -121.785097)
2021-06-28T19:09:26.918Z,1624907366.918 [Default:CheckIn:Read_GPS] Stopped
2021-06-28T19:09:26.918Z,1624907366.918 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-06-28T19:09:35.135Z,1624907375.135 [DataOverHttps](INFO): Sending 85 bytes from file Logs/20210628T174938/Courier0040.lzma
2021-06-28T19:09:36.137Z,1624907376.137 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Courier0040.lzma.bak
2021-06-28T19:09:36.137Z,1624907376.137 [DataOverHttps](INFO): SBD MOMSN=15735594
2021-06-28T19:09:46.757Z,1624907386.757 [NAL9602](INFO): SBD MO Status=2, MOMSN=27984, MT Status=2, MTMSN=0
2021-06-28T19:09:46.758Z,1624907386.758 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-06-28T19:09:53.535Z,1624907393.535 [DataOverHttps](INFO): Sending 145 bytes from file Logs/20210628T174938/Express0041.lzma
2021-06-28T19:09:54.537Z,1624907394.537 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Express0041.lzma.bak
2021-06-28T19:09:54.537Z,1624907394.537 [DataOverHttps](INFO): SBD MOMSN=15735597
2021-06-28T19:09:57.270Z,1624907397.270 [Default:CheckIn:Read_Iridium] Stopped
2021-06-28T19:09:57.270Z,1624907397.270 [Default:CheckIn:C.Wait] Running Loop=1
2021-06-28T19:09:57.271Z,1624907397.271 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-06-28T19:10:10.998Z,1624907410.998 [NAL9602](INFO): SBD MO Status=2, MOMSN=27984, MT Status=2, MTMSN=0
2021-06-28T19:10:10.998Z,1624907410.998 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-06-28T19:10:57.866Z,1624907457.866 [NAL9602](INFO): SBD MO Status=2, MOMSN=27984, MT Status=2, MTMSN=0
2021-06-28T19:10:57.866Z,1624907457.866 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-06-28T19:11:31.402Z,1624907491.402 [NAL9602](INFO): SBD MO Status=2, MOMSN=27984, MT Status=2, MTMSN=0
2021-06-28T19:11:31.403Z,1624907491.403 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-06-28T19:11:48.778Z,1624907508.778 [NAL9602](INFO): SBD MO Status=2, MOMSN=27984, MT Status=2, MTMSN=0
2021-06-28T19:11:48.778Z,1624907508.778 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-06-28T19:12:31.597Z,1624907551.597 [NAL9602](INFO): SBD MO Status=2, MOMSN=27984, MT Status=2, MTMSN=0
2021-06-28T19:12:31.598Z,1624907551.598 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-06-28T19:12:42.106Z,1624907562.106 [NAL9602](INFO): SBD MO Status=0, MOMSN=27984, MT Status=0, MTMSN=0
2021-06-28T19:12:42.106Z,1624907562.106 [NAL9602](INFO): No messages in MT queue
2021-06-28T19:13:12.804Z,1624907592.804 [NAL9602](INFO): Not Powering down - fast GPS
2021-06-28T19:14:57.858Z,1624907697.858 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-06-28T19:14:57.858Z,1624907697.858 [Default:CheckIn:C.Wait] Stopped
2021-06-28T19:14:57.858Z,1624907697.858 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-06-28T19:14:57.858Z,1624907697.858 [Default:CheckIn:D] Running Loop=1
2021-06-28T19:14:58.263Z,1624907698.263 [Default:CheckIn:D] Stopped
2021-06-28T19:14:58.263Z,1624907698.263 [Default:CheckIn:E] Running Loop=1
2021-06-28T19:14:58.680Z,1624907698.680 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 80.855729 min 
2021-06-28T19:14:58.680Z,1624907698.680 [Default:CheckIn:E] Stopped
2021-06-28T19:14:58.681Z,1624907698.681 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-06-28T19:14:58.681Z,1624907698.681 [Default:CheckIn] Stopped
2021-06-28T19:14:58.681Z,1624907698.681 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-06-28T19:14:58.681Z,1624907698.681 [Default:CheckIn](INFO): Running loop #13
2021-06-28T19:14:58.681Z,1624907698.681 [Default:CheckIn] Running Loop=13
2021-06-28T19:14:58.681Z,1624907698.681 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-06-28T19:14:58.681Z,1624907698.681 [Default:CheckIn:Read_GPS] Running Loop=1
2021-06-28T19:15:00.680Z,1624907700.680 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191459.00,A,3648.31487,N,12147.95435,W,13.335,270.64,280621,,,D*48
2021-06-28T19:15:00.682Z,1624907700.682 [NAL9602](INFO): GPS fix at 20210628T191459: (36.805248, -121.799239)
2021-06-28T19:15:00.693Z,1624907700.693 [Default:CheckIn:Read_GPS] Stopped
2021-06-28T19:15:00.693Z,1624907700.693 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-06-28T19:15:08.837Z,1624907708.837 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210628T174938/Courier0043.lzma
2021-06-28T19:15:09.837Z,1624907709.837 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Courier0043.lzma.bak
2021-06-28T19:15:09.837Z,1624907709.837 [DataOverHttps](INFO): SBD MOMSN=15735602
2021-06-28T19:15:28.271Z,1624907728.271 [DataOverHttps](INFO): Sending 143 bytes from file Logs/20210628T174938/Express0044.lzma
2021-06-28T19:15:29.273Z,1624907729.273 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Express0044.lzma.bak
2021-06-28T19:15:29.273Z,1624907729.273 [DataOverHttps](INFO): SBD MOMSN=15735605
2021-06-28T19:15:32.217Z,1624907732.217 [Default:CheckIn:Read_Iridium] Stopped
2021-06-28T19:15:32.217Z,1624907732.217 [Default:CheckIn:C.Wait] Running Loop=1
2021-06-28T19:15:32.217Z,1624907732.217 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-06-28T19:15:58.050Z,1624907758.050 [NAL9602](INFO): SBD MO Status=2, MOMSN=27985, MT Status=2, MTMSN=0
2021-06-28T19:15:58.050Z,1624907758.050 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-06-28T19:16:48.165Z,1624907808.165 [NAL9602](INFO): SBD MO Status=2, MOMSN=27985, MT Status=2, MTMSN=0
2021-06-28T19:16:48.165Z,1624907808.165 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-06-28T19:16:57.854Z,1624907817.854 [NAL9602](INFO): SBD MO Status=0, MOMSN=27985, MT Status=0, MTMSN=0
2021-06-28T19:16:57.854Z,1624907817.854 [NAL9602](INFO): No messages in MT queue
2021-06-28T19:17:28.552Z,1624907848.552 [NAL9602](INFO): Not Powering down - fast GPS
2021-06-28T19:20:32.886Z,1624908032.886 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-06-28T19:20:32.887Z,1624908032.887 [Default:CheckIn:C.Wait] Stopped
2021-06-28T19:20:32.887Z,1624908032.887 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-06-28T19:20:32.887Z,1624908032.887 [Default:CheckIn:D] Running Loop=1
2021-06-28T19:20:33.294Z,1624908033.294 [Default:CheckIn:D] Stopped
2021-06-28T19:20:33.294Z,1624908033.294 [Default:CheckIn:E] Running Loop=1
2021-06-28T19:20:33.697Z,1624908033.697 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 86.439583 min 
2021-06-28T19:20:33.697Z,1624908033.697 [Default:CheckIn:E] Stopped
2021-06-28T19:20:33.697Z,1624908033.697 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-06-28T19:20:33.698Z,1624908033.698 [Default:CheckIn] Stopped
2021-06-28T19:20:33.698Z,1624908033.698 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-06-28T19:20:33.698Z,1624908033.698 [Default:CheckIn](INFO): Running loop #14
2021-06-28T19:20:33.698Z,1624908033.698 [Default:CheckIn] Running Loop=14
2021-06-28T19:20:33.698Z,1624908033.698 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-06-28T19:20:33.698Z,1624908033.698 [Default:CheckIn:Read_GPS] Running Loop=1
2021-06-28T19:20:35.730Z,1624908035.730 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,192034.00,A,3648.18129,N,12149.48138,W,14.112,261.57,280621,,,D*48
2021-06-28T19:20:35.741Z,1624908035.741 [NAL9602](INFO): GPS fix at 20210628T192034: (36.803021, -121.824690)
2021-06-28T19:20:35.778Z,1624908035.778 [Default:CheckIn:Read_GPS] Stopped
2021-06-28T19:20:35.778Z,1624908035.778 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-06-28T19:20:46.178Z,1624908046.178 [DataOverHttps](INFO): Sending 71 bytes from file Logs/20210628T174938/Courier0046.lzma
2021-06-28T19:20:57.254Z,1624908057.254 [NAL9602](INFO): SBD MO Status=2, MOMSN=27986, MT Status=2, MTMSN=0
2021-06-28T19:20:57.254Z,1624908057.254 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-06-28T19:21:00.233Z,1624908060.233 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Courier0046.lzma.bak
2021-06-28T19:21:00.233Z,1624908060.233 [DataOverHttps](INFO): SBD MOMSN=15735610
2021-06-28T19:21:11.816Z,1624908071.816 [NAL9602](INFO): SBD MO Status=0, MOMSN=27986, MT Status=0, MTMSN=0
2021-06-28T19:21:11.816Z,1624908071.816 [NAL9602](INFO): No messages in MT queue
2021-06-28T19:21:17.960Z,1624908077.960 [DataOverHttps](INFO): Sending 146 bytes from file Logs/20210628T174938/Express0047.lzma
2021-06-28T19:21:19.210Z,1624908079.210 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Express0047.lzma.bak
2021-06-28T19:21:19.210Z,1624908079.210 [DataOverHttps](INFO): SBD MOMSN=15735613
2021-06-28T19:21:21.993Z,1624908081.993 [Default:CheckIn:Read_Iridium] Stopped
2021-06-28T19:21:21.993Z,1624908081.993 [Default:CheckIn:C.Wait] Running Loop=1
2021-06-28T19:21:21.993Z,1624908081.993 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-06-28T19:21:42.522Z,1624908102.522 [NAL9602](INFO): Not Powering down - fast GPS
2021-06-28T19:26:05.252Z,1624908365.252 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-06-28T19:26:22.532Z,1624908382.532 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-06-28T19:26:22.532Z,1624908382.532 [Default:CheckIn:C.Wait] Stopped
2021-06-28T19:26:22.532Z,1624908382.532 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-06-28T19:26:22.532Z,1624908382.532 [Default:CheckIn:D] Running Loop=1
2021-06-28T19:26:22.922Z,1624908382.922 [Default:CheckIn:D] Stopped
2021-06-28T19:26:22.922Z,1624908382.922 [Default:CheckIn:E] Running Loop=1
2021-06-28T19:26:23.327Z,1624908383.327 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 92.266724 min 
2021-06-28T19:26:23.327Z,1624908383.327 [Default:CheckIn:E] Stopped
2021-06-28T19:26:23.327Z,1624908383.327 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-06-28T19:26:23.327Z,1624908383.327 [Default:CheckIn] Stopped
2021-06-28T19:26:23.328Z,1624908383.328 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-06-28T19:26:23.328Z,1624908383.328 [Default:CheckIn](INFO): Running loop #15
2021-06-28T19:26:23.328Z,1624908383.328 [Default:CheckIn] Running Loop=15
2021-06-28T19:26:23.328Z,1624908383.328 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-06-28T19:26:23.328Z,1624908383.328 [Default:CheckIn:Read_GPS] Running Loop=1
2021-06-28T19:26:25.349Z,1624908385.349 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,192624.00,A,3648.05560,N,12150.84554,W,3.441,180.43,280621,,,A*75
2021-06-28T19:26:25.351Z,1624908385.351 [NAL9602](INFO): GPS fix at 20210628T192624: (36.800927, -121.847426)
2021-06-28T19:26:25.362Z,1624908385.362 [Default:CheckIn:Read_GPS] Stopped
2021-06-28T19:26:25.362Z,1624908385.362 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-06-28T19:26:36.387Z,1624908396.387 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-06-28T19:26:50.394Z,1624908410.394 [NAL9602](INFO): SBD MO Status=2, MOMSN=27987, MT Status=2, MTMSN=0
2021-06-28T19:26:50.395Z,1624908410.395 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-06-28T19:26:55.766Z,1624908415.766 [DataOverHttps](INFO): Sending 71 bytes from file Logs/20210628T174938/Courier0049.lzma
2021-06-28T19:26:56.769Z,1624908416.769 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Courier0049.lzma.bak
2021-06-28T19:26:56.769Z,1624908416.769 [DataOverHttps](INFO): SBD MOMSN=15735620
2021-06-28T19:27:08.970Z,1624908428.970 [NAL9602](INFO): SBD MO Status=0, MOMSN=27987, MT Status=0, MTMSN=0
2021-06-28T19:27:08.970Z,1624908428.970 [NAL9602](INFO): No messages in MT queue
2021-06-28T19:27:39.672Z,1624908459.672 [NAL9602](INFO): Not Powering down - fast GPS
2021-06-28T19:28:01.135Z,1624908481.135 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-06-28T19:28:16.859Z,1624908496.859 [DataOverHttps](INFO): Sending 145 bytes from file Logs/20210628T174938/Express0050.lzma
2021-06-28T19:28:17.861Z,1624908497.861 [DataOverHttps](INFO): Moved sent file to Logs/20210628T174938/Express0050.lzma.bak
2021-06-28T19:28:17.861Z,1624908497.861 [DataOverHttps](INFO): SBD MOMSN=15735623
2021-06-28T19:28:22.138Z,1624908502.138 [Default:CheckIn:Read_Iridium] Stopped
2021-06-28T19:28:22.138Z,1624908502.138 [Default:CheckIn:C.Wait] Running Loop=1
2021-06-28T19:28:22.138Z,1624908502.138 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-06-28T19:29:37.067Z,1624908577.067 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-06-28T19:30:08.203Z,1624908608.203 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-06-28T19:30:39.363Z,1624908639.363 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-06-28T19:31:10.495Z,1624908670.495 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-06-28T19:31:41.627Z,1624908701.627 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-06-28T19:31:46.648Z,1624908706.648 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=180.783508
2021-06-28T19:32:41.149Z,1624908761.149 [DataOverHttps](IMPORTANT): SBD MTMSN=20210628T193240
2021-06-28T19:32:41.152Z,1624908761.152 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003591
2021-06-28T19:32:48.659Z,1624908768.659 [DataOverHttps](INFO): Received command:restart logs