2021-04-12T15:12:36.773Z,1618240356.773 [Supervisor](DEBUG): Initializing supervisor.
2021-04-12T15:12:36.778Z,1618240356.778 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2021-04-12T15:12:36.778Z,1618240356.778 [SyncHandler](INFO): Protected caller Thread ID is 1210
2021-04-12T15:12:36.779Z,1618240356.779 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2021-04-12T15:12:36.780Z,1618240356.780 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2021-04-12T15:12:36.780Z,1618240356.780 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1211
2021-04-12T15:12:36.784Z,1618240356.784 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2021-04-12T15:12:36.803Z,1618240356.803 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2021-04-12T15:12:36.804Z,1618240356.804 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2021-04-12T15:12:36.804Z,1618240356.804 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1212
2021-04-12T15:12:36.806Z,1618240356.806 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2021-04-12T15:12:36.807Z,1618240356.807 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2021-04-12T15:12:36.807Z,1618240356.807 [logger ThreadHandler](INFO): Protected caller Thread ID is 1213
2021-04-12T15:12:36.811Z,1618240356.811 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2021-04-12T15:12:36.811Z,1618240356.811 [Supervisor](INFO): Looking for Config files in directory: Config/
2021-04-12T15:12:36.813Z,1618240356.813 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2021-04-12T15:12:36.910Z,1618240356.910 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2021-04-12T15:12:36.911Z,1618240356.911 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2021-04-12T15:12:37.509Z,1618240357.509 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2021-04-12T15:12:37.510Z,1618240357.510 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2021-04-12T15:12:37.723Z,1618240357.723 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2021-04-12T15:12:37.724Z,1618240357.724 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2021-04-12T15:12:37.802Z,1618240357.802 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2021-04-12T15:12:37.925Z,1618240357.925 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2021-04-12T15:12:37.926Z,1618240357.926 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2021-04-12T15:12:38.007Z,1618240358.007 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2021-04-12T15:12:38.106Z,1618240358.106 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2021-04-12T15:12:38.107Z,1618240358.107 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2021-04-12T15:12:38.457Z,1618240358.457 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2021-04-12T15:12:38.457Z,1618240358.457 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2021-04-12T15:12:38.980Z,1618240358.980 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2021-04-12T15:12:38.980Z,1618240358.980 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2021-04-12T15:12:39.128Z,1618240359.128 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2021-04-12T15:12:39.128Z,1618240359.128 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2021-04-12T15:12:39.326Z,1618240359.326 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2021-04-12T15:12:39.327Z,1618240359.327 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2021-04-12T15:12:39.766Z,1618240359.766 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2021-04-12T15:12:39.766Z,1618240359.766 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2021-04-12T15:12:40.011Z,1618240360.011 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2021-04-12T15:12:40.012Z,1618240360.012 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2021-04-12T15:12:40.222Z,1618240360.222 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2021-04-12T15:12:40.223Z,1618240360.223 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2021-04-12T15:12:40.581Z,1618240360.581 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2021-04-12T15:12:40.581Z,1618240360.581 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2021-04-12T15:12:40.944Z,1618240360.944 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2021-04-12T15:12:40.946Z,1618240360.946 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-pontus/
2021-04-12T15:12:40.947Z,1618240360.947 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/secure.cfg
2021-04-12T15:12:41.179Z,1618240361.179 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Sensor.cfg
2021-04-12T15:12:41.423Z,1618240361.423 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Servo.cfg
2021-04-12T15:12:41.683Z,1618240361.683 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Simulator.cfg
2021-04-12T15:12:41.921Z,1618240361.921 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/logger.cfg
2021-04-12T15:12:42.035Z,1618240362.035 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/vehicle.cfg
2021-04-12T15:12:42.340Z,1618240362.340 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Battery.cfg
2021-04-12T15:12:42.599Z,1618240362.599 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2021-04-12T15:12:42.600Z,1618240362.600 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Navigation.cfg
2021-04-12T15:12:42.694Z,1618240362.694 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/BIT.cfg
2021-04-12T15:12:42.794Z,1618240362.794 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Science.cfg
2021-04-12T15:12:42.935Z,1618240362.935 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Control.cfg
2021-04-12T15:12:43.035Z,1618240363.035 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2021-04-12T15:12:43.041Z,1618240363.041 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2021-04-12T15:12:43.126Z,1618240363.126 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2021-04-12T15:12:43.127Z,1618240363.127 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2021-04-12T15:12:43.176Z,1618240363.176 [VerticalControl](DEBUG): Construct VerticalControl.
2021-04-12T15:12:43.236Z,1618240363.236 [VerticalControl] Loaded
2021-04-12T15:12:43.237Z,1618240363.237 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2021-04-12T15:12:43.239Z,1618240363.239 [HorizontalControl](DEBUG): Construct HorizontalControl.
2021-04-12T15:12:43.277Z,1618240363.277 [HorizontalControl] Loaded
2021-04-12T15:12:43.277Z,1618240363.277 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2021-04-12T15:12:43.279Z,1618240363.279 [SpeedControl](DEBUG): Construct SpeedControl.
2021-04-12T15:12:43.282Z,1618240363.282 [SpeedControl] Loaded
2021-04-12T15:12:43.283Z,1618240363.283 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2021-04-12T15:12:43.285Z,1618240363.285 [LoopControl](DEBUG): Construct LoopControl.
2021-04-12T15:12:43.285Z,1618240363.285 [LoopControl] Loaded
2021-04-12T15:12:43.286Z,1618240363.286 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2021-04-12T15:12:43.286Z,1618240363.286 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2021-04-12T15:12:43.287Z,1618240363.287 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2021-04-12T15:12:43.326Z,1618240363.326 [DepthRateCalculator] Loaded
2021-04-12T15:12:43.326Z,1618240363.326 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2021-04-12T15:12:43.331Z,1618240363.331 [PitchRateCalculator] Loaded
2021-04-12T15:12:43.331Z,1618240363.331 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2021-04-12T15:12:43.341Z,1618240363.341 [SpeedCalculator] Loaded
2021-04-12T15:12:43.341Z,1618240363.341 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2021-04-12T15:12:43.354Z,1618240363.354 [TempGradientCalculator] Loaded
2021-04-12T15:12:43.354Z,1618240363.354 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2021-04-12T15:12:43.358Z,1618240363.358 [YawRateCalculator] Loaded
2021-04-12T15:12:43.358Z,1618240363.358 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2021-04-12T15:12:43.376Z,1618240363.376 [ElevatorOffsetCalculator] Loaded
2021-04-12T15:12:43.376Z,1618240363.376 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2021-04-12T15:12:43.376Z,1618240363.376 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2021-04-12T15:12:43.377Z,1618240363.377 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2021-04-12T15:12:43.403Z,1618240363.403 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2021-04-12T15:12:43.404Z,1618240363.404 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2021-04-12T15:12:43.459Z,1618240363.459 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2021-04-12T15:12:43.459Z,1618240363.459 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2021-04-12T15:12:43.761Z,1618240363.761 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2021-04-12T15:12:43.761Z,1618240363.761 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2021-04-12T15:12:43.862Z,1618240363.862 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2021-04-12T15:12:43.862Z,1618240363.862 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2021-04-12T15:12:44.210Z,1618240364.210 [AHRS_M2] Loaded
2021-04-12T15:12:44.211Z,1618240364.211 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2021-04-12T15:12:44.240Z,1618240364.240 [BackseatComponent] Loaded
2021-04-12T15:12:44.240Z,1618240364.240 [ComponentRegistry](DEBUG): Component "BackseatComponent" handled in its own thread.
2021-04-12T15:12:44.241Z,1618240364.241 [BackseatComponent ThreadHandler](DEBUG): Created PCaller Thread at 408FE4E0
2021-04-12T15:12:44.241Z,1618240364.241 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 1295
2021-04-12T15:12:44.244Z,1618240364.244 [LcmUniversalReporter] Loaded
2021-04-12T15:12:44.244Z,1618240364.244 [ComponentRegistry](DEBUG): SyncComponent "LcmUniversalReporter" handled in the control thread.
2021-04-12T15:12:44.999Z,1618240364.999 [BPC1] Loaded
2021-04-12T15:12:44.999Z,1618240364.999 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2021-04-12T15:12:45.072Z,1618240365.072 [DataOverHttps] Loaded
2021-04-12T15:12:45.073Z,1618240365.073 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2021-04-12T15:12:45.074Z,1618240365.074 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4092E4E0
2021-04-12T15:12:45.074Z,1618240365.074 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 1296
2021-04-12T15:12:45.093Z,1618240365.093 [Depth_Keller] Loaded
2021-04-12T15:12:45.093Z,1618240365.093 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2021-04-12T15:12:45.097Z,1618240365.097 [DropWeight] Loaded
2021-04-12T15:12:45.098Z,1618240365.098 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2021-04-12T15:12:45.154Z,1618240365.154 [NAL9602] Loaded
2021-04-12T15:12:45.155Z,1618240365.155 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2021-04-12T15:12:45.182Z,1618240365.182 [Onboard] Loaded
2021-04-12T15:12:45.183Z,1618240365.183 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2021-04-12T15:12:45.184Z,1618240365.184 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 4095E4E0
2021-04-12T15:12:45.184Z,1618240365.184 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 1297
2021-04-12T15:12:45.197Z,1618240365.197 [Radio_Surface] Loaded
2021-04-12T15:12:45.197Z,1618240365.197 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2021-04-12T15:12:45.198Z,1618240365.198 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4098E4E0
2021-04-12T15:12:45.198Z,1618240365.198 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1298
2021-04-12T15:12:45.239Z,1618240365.239 [RDI_Pathfinder] Loaded
2021-04-12T15:12:45.240Z,1618240365.240 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2021-04-12T15:12:45.318Z,1618240365.318 [DAT] Loaded
2021-04-12T15:12:45.318Z,1618240365.318 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2021-04-12T15:12:45.319Z,1618240365.319 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2021-04-12T15:12:45.319Z,1618240365.319 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2021-04-12T15:12:45.396Z,1618240365.396 [DeadReckonUsingMultipleVelocitySources] Loaded
2021-04-12T15:12:45.397Z,1618240365.397 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2021-04-12T15:12:45.410Z,1618240365.410 [NavChart] Loaded
2021-04-12T15:12:45.410Z,1618240365.410 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2021-04-12T15:12:45.416Z,1618240365.416 [UniversalFixResidualReporter] Loaded
2021-04-12T15:12:45.416Z,1618240365.416 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2021-04-12T15:12:45.416Z,1618240365.416 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2021-04-12T15:12:45.417Z,1618240365.417 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2021-04-12T15:12:45.552Z,1618240365.552 [SBIT](DEBUG): Construct Startup Built In Test.
2021-04-12T15:12:45.561Z,1618240365.561 [SBIT] Loaded
2021-04-12T15:12:45.561Z,1618240365.561 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2021-04-12T15:12:45.564Z,1618240365.564 [IBIT](DEBUG): Construct Initiated Built In Test.
2021-04-12T15:12:45.576Z,1618240365.576 [IBIT] Loaded
2021-04-12T15:12:45.577Z,1618240365.577 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2021-04-12T15:12:45.582Z,1618240365.582 [CBIT](DEBUG): Construct Continuous Built In Test.
2021-04-12T15:12:45.679Z,1618240365.679 [CBIT] Loaded
2021-04-12T15:12:45.680Z,1618240365.680 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2021-04-12T15:12:45.680Z,1618240365.680 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2021-04-12T15:12:45.681Z,1618240365.681 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2021-04-12T15:12:45.790Z,1618240365.790 [BuoyancyServo] Loaded
2021-04-12T15:12:45.790Z,1618240365.790 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2021-04-12T15:12:45.809Z,1618240365.809 [ElevatorServo] Loaded
2021-04-12T15:12:45.810Z,1618240365.810 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2021-04-12T15:12:45.828Z,1618240365.828 [MassServo] Loaded
2021-04-12T15:12:45.828Z,1618240365.828 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2021-04-12T15:12:45.846Z,1618240365.846 [RudderServo] Loaded
2021-04-12T15:12:45.846Z,1618240365.846 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2021-04-12T15:12:45.863Z,1618240365.863 [ThrusterServo] Loaded
2021-04-12T15:12:45.863Z,1618240365.863 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2021-04-12T15:12:45.864Z,1618240365.864 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2021-04-12T15:12:45.864Z,1618240365.864 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2021-04-12T15:12:45.875Z,1618240365.875 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2021-04-12T15:12:45.875Z,1618240365.875 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2021-04-12T15:12:46.045Z,1618240366.045 [CTD_Seabird] Loaded
2021-04-12T15:12:46.046Z,1618240366.046 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2021-04-12T15:12:46.047Z,1618240366.047 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40ABB4E0
2021-04-12T15:12:46.047Z,1618240366.047 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 1299
2021-04-12T15:12:46.066Z,1618240366.066 [PAR_Licor] Loaded
2021-04-12T15:12:46.066Z,1618240366.066 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2021-04-12T15:12:46.097Z,1618240366.097 [WetLabsBB2FL] Loaded
2021-04-12T15:12:46.098Z,1618240366.098 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2021-04-12T15:12:46.099Z,1618240366.099 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40AEB4E0
2021-04-12T15:12:46.099Z,1618240366.099 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 1300
2021-04-12T15:12:46.119Z,1618240366.119 [WetLabsUBAT] Loaded
2021-04-12T15:12:46.119Z,1618240366.119 [ComponentRegistry](DEBUG): Component "WetLabsUBAT" handled in its own thread.
2021-04-12T15:12:46.120Z,1618240366.120 [WetLabsUBAT ThreadHandler](DEBUG): Created PCaller Thread at 40B1B4E0
2021-04-12T15:12:46.120Z,1618240366.120 [WetLabsUBAT ThreadHandler](INFO): Protected caller Thread ID is 1301
2021-04-12T15:12:46.121Z,1618240366.121 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2021-04-12T15:12:46.132Z,1618240366.132 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2021-04-12T15:12:46.137Z,1618240366.137 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2021-04-12T15:12:46.163Z,1618240366.163 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2021-04-12T15:12:46.164Z,1618240366.164 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40B4B4E0
2021-04-12T15:12:46.164Z,1618240366.164 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1302
2021-04-12T15:12:46.169Z,1618240366.169 [Supervisor](INFO): Main Thread ID is 829
2021-04-12T15:12:46.169Z,1618240366.169 [Supervisor](DEBUG): Running supervisor.
2021-04-12T15:12:46.170Z,1618240366.170 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1303
2021-04-12T15:12:46.179Z,1618240366.179 [controlThread ThreadHandler](INFO): Handler Thread ID is 1304
2021-04-12T15:12:46.180Z,1618240366.180 [controlThread](DEBUG): Initializing ControlThread
2021-04-12T15:12:46.180Z,1618240366.180 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2021-04-12T15:12:46.182Z,1618240366.182 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2021-04-12T15:12:46.183Z,1618240366.183 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2021-04-12T15:12:46.183Z,1618240366.183 [LoopControl](DEBUG): Initialize LoopControlComponent.
2021-04-12T15:12:46.183Z,1618240366.183 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2021-04-12T15:12:46.184Z,1618240366.184 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2021-04-12T15:12:46.184Z,1618240366.184 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2021-04-12T15:12:46.184Z,1618240366.184 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2021-04-12T15:12:46.185Z,1618240366.185 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2021-04-12T15:12:46.185Z,1618240366.185 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2021-04-12T15:12:46.190Z,1618240366.190 [NavChart](DEBUG): Initialize NavChart Navigation.
2021-04-12T15:12:46.190Z,1618240366.190 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2021-04-12T15:12:46.191Z,1618240366.191 [SBIT](INFO): Initialize SBIT Component.
2021-04-12T15:12:46.191Z,1618240366.191 [SBIT](IMPORTANT): git: 2021-04-12
2021-04-12T15:12:46.191Z,1618240366.191 [SBIT](INFO): git hash: 4d37ca66b772b9605b4b6eba7ca05c94731fcf29
2021-04-12T15:12:46.192Z,1618240366.192 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2021-04-12T15:12:46.193Z,1618240366.193 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019
Kernel Reported: #1 PREEMPT Thu Aug 6 12:04:53 PDT 2020
2021-04-12T15:12:46.194Z,1618240366.194 [SBIT](INFO): Beginning SBIT in 55.000000 seconds.
2021-04-12T15:12:46.194Z,1618240366.194 [IBIT](INFO): Initialize IBIT Component.
2021-04-12T15:12:46.196Z,1618240366.196 [CBIT](DEBUG): Initialize CBIT Component.
2021-04-12T15:12:46.197Z,1618240366.197 [logger ThreadHandler](INFO): Handler Thread ID is 1305
2021-04-12T15:12:46.197Z,1618240366.197 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 1306
2021-04-12T15:12:46.198Z,1618240366.198 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 1307
2021-04-12T15:12:46.199Z,1618240366.199 [Onboard ThreadHandler](INFO): Handler Thread ID is 1308
2021-04-12T15:12:46.211Z,1618240366.211 [CBIT](DEBUG): Initialized mux pins.
2021-04-12T15:12:46.211Z,1618240366.211 [CBIT](DEBUG): Initializing the watchdog timer.
2021-04-12T15:12:46.216Z,1618240366.216 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2021-04-12T15:12:46.237Z,1618240366.237 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2021-04-12T15:12:46.241Z,1618240366.241 [CBIT](DEBUG): Initializing heartbeat.
2021-04-12T15:12:46.251Z,1618240366.251 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1309
2021-04-12T15:12:46.253Z,1618240366.253 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 1310
2021-04-12T15:12:46.254Z,1618240366.254 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2021-04-12T15:12:46.256Z,1618240366.256 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 1312
2021-04-12T15:12:46.258Z,1618240366.258 [WetLabsUBAT ThreadHandler](INFO): Handler Thread ID is 1313
2021-04-12T15:12:46.259Z,1618240366.259 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1314
2021-04-12T15:12:46.262Z,1618240366.262 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2021-04-12T15:12:46.263Z,1618240366.263 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2021-04-12T15:12:46.263Z,1618240366.263 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2021-04-12T15:12:46.263Z,1618240366.263 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2021-04-12T15:12:46.263Z,1618240366.263 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2021-04-12T15:12:46.264Z,1618240366.264 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2021-04-12T15:12:46.264Z,1618240366.264 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2021-04-12T15:12:46.264Z,1618240366.264 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2021-04-12T15:12:46.264Z,1618240366.264 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2021-04-12T15:12:46.264Z,1618240366.264 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2021-04-12T15:12:46.265Z,1618240366.265 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2021-04-12T15:12:46.265Z,1618240366.265 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2021-04-12T15:12:46.265Z,1618240366.265 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2021-04-12T15:12:46.265Z,1618240366.265 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2021-04-12T15:12:46.265Z,1618240366.265 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2021-04-12T15:12:46.265Z,1618240366.265 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2021-04-12T15:12:46.298Z,1618240366.298 [WetLabsBB2FL](INFO): Powering up
2021-04-12T15:12:46.304Z,1618240366.304 [WetLabsUBAT](INFO): Powering up
2021-04-12T15:12:46.311Z,1618240366.311 [CBIT](DEBUG): Deactivating GF circuits.
2021-04-12T15:12:46.311Z,1618240366.311 [CBIT](DEBUG): Deactivating emergency mode.
2021-04-12T15:12:46.347Z,1618240366.347 [CBIT](DEBUG): Backplane powered.
2021-04-12T15:12:46.352Z,1618240366.352 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2021-04-12T15:12:46.373Z,1618240366.373 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2021-04-12T15:12:46.412Z,1618240366.412 [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-04-12T15:12:46.413Z,1618240366.413 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2021-04-12T15:12:46.533Z,1618240366.533 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2021-04-12T15:12:46.534Z,1618240366.534 [Default:A.Wait](DEBUG): Construct Wait.
2021-04-12T15:12:46.536Z,1618240366.536 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2021-04-12T15:12:46.618Z,1618240366.618 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2021-04-12T15:12:46.640Z,1618240366.640 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2021-04-12T15:12:46.650Z,1618240366.650 [Default:E.Execute](DEBUG): Construct Execute.
2021-04-12T15:12:46.655Z,1618240366.655 [Radio_Surface](INFO): Powering up
2021-04-12T15:12:46.666Z,1618240366.666 [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-04-12T15:12:46.671Z,1618240366.671 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,DropWeight,NAL9602,RDI_Pathfinder,DAT,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,LcmUniversalReporter,Reporter,LogSplitter,
2021-04-12T15:12:46.712Z,1618240366.712 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2021-04-12T15:12:46.878Z,1618240366.878 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2
2021-04-12T15:12:46.878Z,1618240366.878 [DAT](INFO): Powering up
2021-04-12T15:12:46.878Z,1618240366.878 [DAT](DEBUG): Initializing DAT.
2021-04-12T15:12:46.973Z,1618240366.973 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2021-04-12T15:12:46.974Z,1618240366.974 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2
2021-04-12T15:12:46.992Z,1618240366.992 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2021-04-12T15:12:46.994Z,1618240366.994 [ElevatorServo](DEBUG): Initializing EZServoServo.
2021-04-12T15:12:47.007Z,1618240367.007 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2021-04-12T15:12:47.008Z,1618240367.008 [MassServo](DEBUG): Initializing EZServoServo.
2021-04-12T15:12:47.019Z,1618240367.019 [MassServo](DEBUG): Initializing MassServo.
2021-04-12T15:12:47.020Z,1618240367.020 [RudderServo](DEBUG): Initializing EZServoServo.
2021-04-12T15:12:47.031Z,1618240367.031 [RudderServo](DEBUG): Initializing RudderServo.
2021-04-12T15:12:47.032Z,1618240367.032 [ThrusterServo](DEBUG): Initializing EZServoServo.
2021-04-12T15:12:47.043Z,1618240367.043 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2021-04-12T15:12:48.871Z,1618240368.871 [WetLabsBB2FL](INFO): Powering down
2021-04-12T15:12:54.288Z,1618240374.288 [CTD_Seabird](ERROR): Device message queue exceeded the allowed limit.
2021-04-12T15:12:55.571Z,1618240375.571 [WetLabsUBAT](INFO): Powering down
2021-04-12T15:13:01.227Z,1618240381.227 [DAT](INFO): commRate: 800
2021-04-12T15:13:03.257Z,1618240383.257 [DAT](INFO): entering command mode
2021-04-12T15:13:03.649Z,1618240383.649 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:04.053Z,1618240384.053 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:04.476Z,1618240384.476 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:04.861Z,1618240384.861 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:05.265Z,1618240385.265 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:05.681Z,1618240385.681 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:06.073Z,1618240386.073 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:06.516Z,1618240386.516 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:06.881Z,1618240386.881 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:07.285Z,1618240387.285 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:07.695Z,1618240387.695 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:08.093Z,1618240388.093 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:08.539Z,1618240388.539 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:08.901Z,1618240388.901 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:09.305Z,1618240389.305 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:09.709Z,1618240389.709 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:10.113Z,1618240390.113 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:10.584Z,1618240390.584 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:10.921Z,1618240390.921 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:11.325Z,1618240391.325 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:11.729Z,1618240391.729 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:12.133Z,1618240392.133 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:12.581Z,1618240392.581 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:12.949Z,1618240392.949 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:13.349Z,1618240393.349 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:13.749Z,1618240393.749 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:14.161Z,1618240394.161 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:14.593Z,1618240394.593 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:14.962Z,1618240394.962 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:15.364Z,1618240395.364 [NAL9602](INFO): Powering up NAL9602
2021-04-12T15:13:15.366Z,1618240395.366 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:15.774Z,1618240395.774 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:16.173Z,1618240396.173 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:16.596Z,1618240396.596 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:16.981Z,1618240396.981 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:17.391Z,1618240397.391 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:17.789Z,1618240397.789 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:18.193Z,1618240398.193 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:18.628Z,1618240398.628 [DAT](DEBUG): checking for command mode acknowledgment
2021-04-12T15:13:18.628Z,1618240398.628 [DAT](FAULT): failed to enter command mode
2021-04-12T15:13:19.013Z,1618240399.013 [DAT](INFO): entering command mode
2021-04-12T15:13:19.406Z,1618240399.406 [DAT](INFO): setting verbose to 3
2021-04-12T15:13:19.810Z,1618240399.810 [DAT](INFO): set verbose to 3
2021-04-12T15:13:19.811Z,1618240399.811 [DAT](INFO): setting DatVerbose to 27440
2021-04-12T15:13:20.214Z,1618240400.214 [DAT](INFO): set DatVerbose to 27440
2021-04-12T15:13:20.214Z,1618240400.214 [DAT](INFO): setting transmit power to 8
2021-04-12T15:13:20.654Z,1618240400.654 [DAT](INFO): set transmit power to 8
2021-04-12T15:13:20.659Z,1618240400.659 [DAT](INFO): setting local address to 9
2021-04-12T15:13:21.022Z,1618240401.022 [DAT](INFO): set local address to 9
2021-04-12T15:13:26.285Z,1618240406.285 [NAL9602](INFO): NAL9602 initialized
2021-04-12T15:13:41.657Z,1618240421.657 [SBIT](IMPORTANT): Beginning Startup BIT
2021-04-12T15:13:41.661Z,1618240421.661 [CBIT](IMPORTANT): Beginning ground fault scan
2021-04-12T15:13:52.644Z,1618240432.644 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.011317
CHAN A1 (24V): -0.000467
CHAN A2 (12V): -0.007567
CHAN A3 (5V): -0.002816
CHAN B0 (3.3V): 0.000506
CHAN B1 (3.15aV): -0.000057
CHAN B2 (3.15bV): -0.000329
CHAN B3 (GND): 0.001878
OPEN: 0.004944
Full Scale Calc: 4.765 mA, -1.589 mA
2021-04-12T15:14:35.801Z,1618240475.801 [SBIT](IMPORTANT): SBIT PASSED
2021-04-12T15:14:35.801Z,1618240475.801 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2021-04-12T15:14:35.802Z,1618240475.802 [SBIT](IMPORTANT): BPC1.batteryMissingStickThreshold=6 count;

2021-04-12T15:14:35.802Z,1618240475.802 [SBIT](IMPORTANT): CBIT.gf24Offset=143 microampere;

2021-04-12T15:14:35.807Z,1618240475.807 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=182.141093 cubic_centimeter;

2021-04-12T15:14:35.807Z,1618240475.807 [SBIT](IMPORTANT): VerticalControl.massDefault=8.793170 millimeter;

2021-04-12T15:14:36.202Z,1618240476.202 [MissionManager](IMPORTANT): Started mission Startup
2021-04-12T15:14:36.202Z,1618240476.202 [Startup] Running Loop=1
2021-04-12T15:14:36.202Z,1618240476.202 [Startup](DEBUG): Aggregate::initialize Startup
2021-04-12T15:14:36.202Z,1618240476.202 [Startup:A.GoToSurface] Running Loop=1
2021-04-12T15:14:36.202Z,1618240476.202 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2021-04-12T15:14:36.203Z,1618240476.203 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2021-04-12T15:14:36.204Z,1618240476.204 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2021-04-12T15:14:36.204Z,1618240476.204 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2021-04-12T15:14:36.204Z,1618240476.204 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2021-04-12T15:14:36.205Z,1618240476.205 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2021-04-12T15:14:36.206Z,1618240476.206 [Startup:StartupSatComms] Running Loop=1
2021-04-12T15:14:36.206Z,1618240476.206 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2021-04-12T15:14:36.206Z,1618240476.206 [Startup:StartupSatComms:A] Running Loop=1
2021-04-12T15:14:36.625Z,1618240476.625 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2021-04-12T15:15:36.471Z,1618240536.471 [Startup:StartupSatComms:A](INFO): Timed out from 2021-04-12T15:14:36.2Z
2021-04-12T15:15:36.471Z,1618240536.471 [Startup:StartupSatComms:A] Stopped
2021-04-12T15:15:36.471Z,1618240536.471 [Startup:StartupSatComms:B] Running Loop=1
2021-04-12T15:15:36.794Z,1618240536.794 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2021-04-12T15:15:46.499Z,1618240546.499 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2021-04-12T15:15:46.499Z,1618240546.499 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-04-12T15:15:46.510Z,1618240546.510 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-04-12T15:15:46.897Z,1618240546.897 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-04-12T15:15:46.897Z,1618240546.897 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2021-04-12T15:16:10.358Z,1618240570.358 [NAL9602](INFO): SBD MO Status=0, MOMSN=12724, MT Status=0, MTMSN=0
2021-04-12T15:16:10.358Z,1618240570.358 [NAL9602](INFO): No messages in MT queue
2021-04-12T15:16:12.193Z,1618240572.193 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004457
2021-04-12T15:16:22.875Z,1618240582.875 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20210412T145759/Courier0007.lzma
2021-04-12T15:16:23.877Z,1618240583.877 [DataOverHttps](INFO): Moved sent file to Logs/20210412T145759/Courier0007.lzma.bak
2021-04-12T15:16:23.877Z,1618240583.877 [DataOverHttps](INFO): SBD MOMSN=15559978
2021-04-12T15:16:36.792Z,1618240596.792 [Startup:StartupSatComms:B](INFO): Timed out from 2021-04-12T15:15:36.5Z
2021-04-12T15:16:36.792Z,1618240596.792 [Startup:StartupSatComms:B] Stopped
2021-04-12T15:16:36.792Z,1618240596.792 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2021-04-12T15:16:36.792Z,1618240596.792 [Startup:StartupSatComms] Stopped
2021-04-12T15:16:36.792Z,1618240596.792 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2021-04-12T15:16:36.793Z,1618240596.793 [Startup](INFO): Completed Startup
2021-04-12T15:16:36.793Z,1618240596.793 [MissionManager](INFO): Startup is completed.
2021-04-12T15:16:36.793Z,1618240596.793 [MissionManager](INFO): Uninitializing Mission Startup
2021-04-12T15:16:36.793Z,1618240596.793 [Startup] Stopped
2021-04-12T15:16:36.794Z,1618240596.794 [Startup](DEBUG): Aggregate::uninitialize Startup
2021-04-12T15:16:36.794Z,1618240596.794 [Startup:A.GoToSurface] Stopped
2021-04-12T15:16:36.794Z,1618240596.794 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2021-04-12T15:16:37.165Z,1618240597.165 [MissionManager](IMPORTANT): Started mission Default
2021-04-12T15:16:37.165Z,1618240597.165 [Default] Running Loop=1
2021-04-12T15:16:37.165Z,1618240597.165 [Default](DEBUG): Aggregate::initialize Default
2021-04-12T15:16:37.165Z,1618240597.165 [Default:B.GoToSurface] Running Loop=1
2021-04-12T15:16:37.165Z,1618240597.165 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2021-04-12T15:16:37.165Z,1618240597.165 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2021-04-12T15:16:37.166Z,1618240597.166 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2021-04-12T15:16:37.166Z,1618240597.166 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2021-04-12T15:16:37.166Z,1618240597.166 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2021-04-12T15:16:37.167Z,1618240597.167 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2021-04-12T15:16:37.167Z,1618240597.167 [Default:A.Wait] Running Loop=1
2021-04-12T15:16:37.167Z,1618240597.167 [Default:A.Wait](DEBUG): Initialize Wait Component.
2021-04-12T15:16:47.310Z,1618240607.310 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20210412T151236/Courier0000.lzma
2021-04-12T15:16:48.314Z,1618240608.314 [DataOverHttps](INFO): Moved sent file to Logs/20210412T151236/Courier0000.lzma.bak
2021-04-12T15:16:48.314Z,1618240608.314 [DataOverHttps](INFO): SBD MOMSN=15559980
2021-04-12T15:16:50.204Z,1618240610.204 [Default:A.Wait](INFO): Done Waiting.
2021-04-12T15:16:50.204Z,1618240610.204 [Default:A.Wait] Stopped
2021-04-12T15:16:50.204Z,1618240610.204 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2021-04-12T15:16:50.634Z,1618240610.634 [Default:CheckIn] Running Loop=1
2021-04-12T15:16:50.634Z,1618240610.634 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-04-12T15:16:50.634Z,1618240610.634 [Default:CheckIn:Read_GPS] Running Loop=1
2021-04-12T15:16:51.010Z,1618240611.010 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2021-04-12T15:18:47.428Z,1618240727.428 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2021-04-12T15:18:47.428Z,1618240727.428 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-04-12T15:18:47.439Z,1618240727.439 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-04-12T15:18:47.852Z,1618240727.852 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-04-12T15:18:47.852Z,1618240727.852 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2021-04-12T15:19:30.603Z,1618240770.603 [CommandLine](IMPORTANT): got command failComponent
2021-04-12T15:19:30.604Z,1618240770.604 [CommandLine](IMPORTANT): Failed components:
2021-04-12T15:19:30.604Z,1618240770.604 [CommandLine](IMPORTANT): No failed Components.
2021-04-12T15:19:51.670Z,1618240791.670 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,151950.00,A,3648.16708,N,12147.21140,W,0.019,56.15,120421,,,A*48
2021-04-12T15:19:51.673Z,1618240791.673 [NAL9602](INFO): GPS fix at 20210412T151950: (36.802785, -121.786857)
2021-04-12T15:19:51.685Z,1618240791.685 [Default:CheckIn:Read_GPS] Stopped
2021-04-12T15:19:51.685Z,1618240791.685 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-04-12T15:19:52.084Z,1618240792.084 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2021-04-12T15:20:01.702Z,1618240801.702 [DataOverHttps](INFO): Sending 221 bytes from file Logs/20210412T151236/Courier0004.lzma
2021-04-12T15:20:02.705Z,1618240802.705 [DataOverHttps](INFO): Moved sent file to Logs/20210412T151236/Courier0004.lzma.bak
2021-04-12T15:20:02.705Z,1618240802.705 [DataOverHttps](INFO): SBD MOMSN=15559991
2021-04-12T15:20:03.814Z,1618240803.814 [BPC1](INFO): Calculating totals. Valid battery stick count: 52. Valid reserve battery stick count: 6.
2021-04-12T15:20:03.833Z,1618240803.833 [BPC1](INFO): Received data from all battery sticks.
2021-04-12T15:20:06.224Z,1618240806.224 [CommandLine](IMPORTANT): got command ibit
2021-04-12T15:20:06.297Z,1618240806.297 [IBIT](IMPORTANT): Beginning Initiated BIT
2021-04-12T15:20:06.297Z,1618240806.297 [IBIT](IMPORTANT): Beginning control surface checks.
2021-04-12T15:20:06.312Z,1618240806.312 [CBIT](IMPORTANT): Beginning ground fault scan
2021-04-12T15:20:07.818Z,1618240807.818 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,152006.00,A,3648.16526,N,12147.21491,W,0.700,56.15,120421,,,A*49
2021-04-12T15:20:07.820Z,1618240807.820 [NAL9602](INFO): GPS fix at 20210412T152006: (36.802754, -121.786915)
2021-04-12T15:20:11.050Z,1618240811.050 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,152009.00,A,3648.16538,N,12147.21489,W,0.156,56.15,120421,,,A*45
2021-04-12T15:20:11.052Z,1618240811.052 [NAL9602](INFO): GPS fix at 20210412T152009: (36.802756, -121.786915)
2021-04-12T15:20:13.882Z,1618240813.882 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,152012.00,A,3648.16555,N,12147.21524,W,0.019,56.15,120421,,,A*48
2021-04-12T15:20:13.895Z,1618240813.895 [NAL9602](INFO): GPS fix at 20210412T152012: (36.802759, -121.786921)
2021-04-12T15:20:17.122Z,1618240817.122 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,152015.00,A,3648.16556,N,12147.21525,W,0.117,56.15,120421,,,A*42
2021-04-12T15:20:17.124Z,1618240817.124 [NAL9602](INFO): GPS fix at 20210412T152015: (36.802759, -121.786921)
2021-04-12T15:20:17.255Z,1618240817.255 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.011072
CHAN A1 (24V): -0.000549
CHAN A2 (12V): -0.007639
CHAN A3 (5V): -0.002421
CHAN B0 (3.3V): -0.000128
CHAN B1 (3.15aV): -0.000182
CHAN B2 (3.15bV): -0.000319
CHAN B3 (GND): 0.002078
OPEN: 0.005386
Full Scale Calc: 4.765 mA, -1.589 mA
2021-04-12T15:20:19.962Z,1618240819.962 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,152018.00,A,3648.16570,N,12147.21549,W,0.078,56.15,120421,,,A*49
2021-04-12T15:20:19.964Z,1618240819.964 [NAL9602](INFO): GPS fix at 20210412T152018: (36.802762, -121.786925)
2021-04-12T15:20:22.814Z,1618240822.814 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,152021.00,A,3648.16582,N,12147.21562,W,0.097,56.15,120421,,,A*46
2021-04-12T15:20:22.816Z,1618240822.816 [NAL9602](INFO): GPS fix at 20210412T152021: (36.802764, -121.786927)
2021-04-12T15:20:24.512Z,1618240824.512 [DataOverHttps](INFO): Sending 146 bytes from file Logs/20210412T145759/Express0008.lzma
2021-04-12T15:20:25.509Z,1618240825.509 [DataOverHttps](INFO): Moved sent file to Logs/20210412T145759/Express0008.lzma.bak
2021-04-12T15:20:25.509Z,1618240825.509 [DataOverHttps](INFO): SBD MOMSN=15559994
2021-04-12T15:20:26.042Z,1618240826.042 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,152024.00,A,3648.16576,N,12147.21555,W,0.253,56.15,120421,,,A*46
2021-04-12T15:20:26.044Z,1618240826.044 [NAL9602](INFO): GPS fix at 20210412T152024: (36.802763, -121.786926)
2021-04-12T15:20:28.878Z,1618240828.878 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,152027.00,A,3648.16553,N,12147.21547,W,0.039,56.15,120421,,,A*4F
2021-04-12T15:20:28.880Z,1618240828.880 [NAL9602](INFO): GPS fix at 20210412T152027: (36.802759, -121.786924)
2021-04-12T15:20:32.142Z,1618240832.142 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,152030.00,A,3648.16564,N,12147.21577,W,0.194,56.15,120421,,,A*48
2021-04-12T15:20:32.144Z,1618240832.144 [NAL9602](INFO): GPS fix at 20210412T152030: (36.802761, -121.786929)
2021-04-12T15:20:34.998Z,1618240834.998 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,152033.00,A,3648.16582,N,12147.21614,W,0.117,56.15,120421,,,A*4E
2021-04-12T15:20:35.000Z,1618240835.000 [NAL9602](INFO): GPS fix at 20210412T152033: (36.802764, -121.786936)
2021-04-12T15:20:37.827Z,1618240837.827 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,152036.00,A,3648.16581,N,12147.21630,W,0.058,56.15,120421,,,A*44
2021-04-12T15:20:37.830Z,1618240837.830 [NAL9602](INFO): GPS fix at 20210412T152036: (36.802763, -121.786938)
2021-04-12T15:20:41.064Z,1618240841.064 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,152039.00,A,3648.16578,N,12147.21645,W,0.019,56.15,120421,,,A*4A
2021-04-12T15:20:41.066Z,1618240841.066 [NAL9602](INFO): GPS fix at 20210412T152039: (36.802763, -121.786941)
2021-04-12T15:20:43.918Z,1618240843.918 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,152042.00,A,3648.16564,N,12147.21648,W,0.136,56.15,120421,,,A*4A
2021-04-12T15:20:43.941Z,1618240843.941 [NAL9602](INFO): GPS fix at 20210412T152042: (36.802761, -121.786941)
2021-04-12T15:20:46.758Z,1618240846.758 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,152045.00,A,3648.16540,N,12147.21631,W,0.039,56.15,120421,,,A*4B
2021-04-12T15:20:46.760Z,1618240846.760 [NAL9602](INFO): GPS fix at 20210412T152045: (36.802757, -121.786939)
2021-04-12T15:20:48.856Z,1618240848.856 [DataOverHttps](INFO): Sending 797 bytes from file Logs/20210412T151236/Express0001.lzma
2021-04-12T15:20:49.856Z,1618240849.856 [DataOverHttps](INFO): Moved sent file to Logs/20210412T151236/Express0001.lzma.bak
2021-04-12T15:20:49.857Z,1618240849.857 [DataOverHttps](INFO): SBD MOMSN=15560000
2021-04-12T15:20:49.978Z,1618240849.978 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,152048.00,A,3648.16525,N,12147.21635,W,0.078,56.15,120421,,,A*44
2021-04-12T15:20:49.980Z,1618240849.980 [NAL9602](INFO): GPS fix at 20210412T152048: (36.802754, -121.786939)
2021-04-12T15:20:52.496Z,1618240852.496 [IBIT](IMPORTANT): Communications Status:
Fix Status: 1
Iridium Signal Strength: 2
Latitude: 36.802753 Longitude: -121.786942
2021-04-12T15:20:52.806Z,1618240852.806 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,152051.00,A,3648.16519,N,12147.21647,W,0.117,56.15,120421,,,A*4E
2021-04-12T15:20:52.808Z,1618240852.808 [NAL9602](INFO): GPS fix at 20210412T152051: (36.802753, -121.786941)
2021-04-12T15:20:52.829Z,1618240852.829 [IBIT](IMPORTANT): Battery Status:
Battery Charge (AH): 0.000000
Voltage: 16.730000
2021-04-12T15:20:52.829Z,1618240852.829 [IBIT](IMPORTANT): batteryCapacityThreshold: 50.000000 Ah
2021-04-12T15:20:52.830Z,1618240852.830 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.700000 V
2021-04-12T15:20:53.276Z,1618240853.276 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2021-04-12T15:20:53.276Z,1618240853.276 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2021-04-12T15:20:53.277Z,1618240853.277 [IBIT](IMPORTANT): Pressure:7.642631 PSI
2021-04-12T15:20:53.277Z,1618240853.277 [IBIT](IMPORTANT): Humidity:20.522524 %
2021-04-12T15:20:53.706Z,1618240853.706 [IBIT](IMPORTANT): Vehicle Pitch:1.208181 degrees
2021-04-12T15:20:53.706Z,1618240853.706 [IBIT](IMPORTANT): Vehicle  Roll:-0.828970 degrees
2021-04-12T15:20:53.715Z,1618240853.715 [IBIT](IMPORTANT): Vehicle  Heading:210.844849 degrees
2021-04-12T15:20:54.048Z,1618240854.048 [IBIT](IMPORTANT): surfaceThreshold: 1.000000 m
2021-04-12T15:20:54.048Z,1618240854.048 [IBIT](IMPORTANT): buoyancyNeutral: 182.141098 cc
2021-04-12T15:20:54.049Z,1618240854.049 [IBIT](IMPORTANT): massDefault: 0.879317 cm
2021-04-12T15:20:54.049Z,1618240854.049 [IBIT](IMPORTANT): stopDepth: 215.000000 m
2021-04-12T15:20:54.049Z,1618240854.049 [IBIT](IMPORTANT): abortDepth: 255.000000 m
2021-04-12T15:20:54.049Z,1618240854.049 [IBIT](IMPORTANT): IBIT PASSED
2021-04-12T15:21:06.695Z,1618240866.695 [DataOverHttps](INFO): Sending 274 bytes from file Logs/20210412T151236/Express0005.lzma
2021-04-12T15:21:07.696Z,1618240867.696 [DataOverHttps](INFO): Moved sent file to Logs/20210412T151236/Express0005.lzma.bak
2021-04-12T15:21:07.697Z,1618240867.697 [DataOverHttps](INFO): SBD MOMSN=15560017
2021-04-12T15:21:08.975Z,1618240868.975 [Default:CheckIn:Read_Iridium] Stopped
2021-04-12T15:21:08.975Z,1618240868.975 [Default:CheckIn:C.Wait] Running Loop=1
2021-04-12T15:21:08.975Z,1618240868.975 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-04-12T15:21:25.526Z,1618240885.526 [NAL9602](INFO): Not Powering down - fast GPS
2021-04-12T15:26:09.644Z,1618241169.644 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-04-12T15:26:09.644Z,1618241169.644 [Default:CheckIn:C.Wait] Stopped
2021-04-12T15:26:09.644Z,1618241169.644 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-04-12T15:26:09.644Z,1618241169.644 [Default:CheckIn:D] Running Loop=1
2021-04-12T15:26:10.064Z,1618241170.064 [Default:CheckIn:D] Stopped
2021-04-12T15:26:10.064Z,1618241170.064 [Default:CheckIn:E] Running Loop=1
2021-04-12T15:26:10.485Z,1618241170.485 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 9.548311 min 
2021-04-12T15:26:10.485Z,1618241170.485 [Default:CheckIn:E] Stopped
2021-04-12T15:26:10.485Z,1618241170.485 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-04-12T15:26:10.485Z,1618241170.485 [Default:CheckIn] Stopped
2021-04-12T15:26:10.485Z,1618241170.485 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-04-12T15:26:10.485Z,1618241170.485 [Default:CheckIn](INFO): Running loop #2
2021-04-12T15:26:10.485Z,1618241170.485 [Default:CheckIn] Running Loop=2
2021-04-12T15:26:10.485Z,1618241170.485 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-04-12T15:26:10.485Z,1618241170.485 [Default:CheckIn:Read_GPS] Running Loop=1
2021-04-12T15:26:12.462Z,1618241172.462 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,152610.00,A,3648.27496,N,12147.12933,W,4.626,11.24,120421,,,D*40
2021-04-12T15:26:12.464Z,1618241172.464 [NAL9602](INFO): GPS fix at 20210412T152610: (36.804583, -121.785489)
2021-04-12T15:26:12.494Z,1618241172.494 [Default:CheckIn:Read_GPS] Stopped
2021-04-12T15:26:12.494Z,1618241172.494 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-04-12T15:26:22.707Z,1618241182.707 [DataOverHttps](INFO): Sending 202 bytes from file Logs/20210412T151236/Courier0007.lzma
2021-04-12T15:26:23.705Z,1618241183.705 [DataOverHttps](INFO): Moved sent file to Logs/20210412T151236/Courier0007.lzma.bak
2021-04-12T15:26:23.705Z,1618241183.705 [DataOverHttps](INFO): SBD MOMSN=15560030
2021-04-12T15:26:26.226Z,1618241186.226 [NAL9602](INFO): SBD MO Status=0, MOMSN=12725, MT Status=0, MTMSN=0
2021-04-12T15:26:26.226Z,1618241186.226 [NAL9602](INFO): No messages in MT queue
2021-04-12T15:26:44.924Z,1618241204.924 [DataOverHttps](INFO): Sending 784 bytes from file Logs/20210412T151236/Express0008.lzma
2021-04-12T15:26:45.925Z,1618241205.925 [DataOverHttps](INFO): Moved sent file to Logs/20210412T151236/Express0008.lzma.bak
2021-04-12T15:26:45.926Z,1618241205.926 [DataOverHttps](INFO): SBD MOMSN=15560034
2021-04-12T15:26:47.310Z,1618241207.310 [Default:CheckIn:Read_Iridium] Stopped
2021-04-12T15:26:47.310Z,1618241207.310 [Default:CheckIn:C.Wait] Running Loop=1
2021-04-12T15:26:47.311Z,1618241207.311 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-04-12T15:26:56.995Z,1618241216.995 [NAL9602](INFO): Not Powering down - fast GPS
2021-04-12T15:31:48.004Z,1618241508.004 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-04-12T15:31:48.004Z,1618241508.004 [Default:CheckIn:C.Wait] Stopped
2021-04-12T15:31:48.004Z,1618241508.004 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-04-12T15:31:48.004Z,1618241508.004 [Default:CheckIn:D] Running Loop=1
2021-04-12T15:31:48.480Z,1618241508.480 [Default:CheckIn:D] Stopped
2021-04-12T15:31:48.480Z,1618241508.480 [Default:CheckIn:E] Running Loop=1
2021-04-12T15:31:48.819Z,1618241508.819 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 15.188589 min 
2021-04-12T15:31:48.819Z,1618241508.819 [Default:CheckIn:E] Stopped
2021-04-12T15:31:48.819Z,1618241508.819 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-04-12T15:31:48.820Z,1618241508.820 [Default:CheckIn] Stopped
2021-04-12T15:31:48.820Z,1618241508.820 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-04-12T15:31:48.820Z,1618241508.820 [Default:CheckIn](INFO): Running loop #3
2021-04-12T15:31:48.820Z,1618241508.820 [Default:CheckIn] Running Loop=3
2021-04-12T15:31:48.820Z,1618241508.820 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-04-12T15:31:48.820Z,1618241508.820 [Default:CheckIn:Read_GPS] Running Loop=1
2021-04-12T15:31:50.818Z,1618241510.818 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,153150.00,A,3648.33707,N,12147.57836,W,9.991,279.44,120421,,,D*7D
2021-04-12T15:31:50.820Z,1618241510.820 [NAL9602](INFO): GPS fix at 20210412T153150: (36.805618, -121.792973)
2021-04-12T15:31:50.856Z,1618241510.856 [Default:CheckIn:Read_GPS] Stopped
2021-04-12T15:31:50.856Z,1618241510.856 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-04-12T15:31:59.014Z,1618241519.014 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210412T151236/Courier0010.lzma
2021-04-12T15:32:00.017Z,1618241520.017 [DataOverHttps](INFO): Moved sent file to Logs/20210412T151236/Courier0010.lzma.bak
2021-04-12T15:32:00.017Z,1618241520.017 [DataOverHttps](INFO): SBD MOMSN=15560066
2021-04-12T15:32:06.173Z,1618241526.173 [NAL9602](INFO): SBD MO Status=0, MOMSN=12726, MT Status=0, MTMSN=0
2021-04-12T15:32:06.174Z,1618241526.174 [NAL9602](INFO): No messages in MT queue
2021-04-12T15:32:16.290Z,1618241536.290 [DataOverHttps](INFO): Sending 139 bytes from file Logs/20210412T151236/Express0011.lzma
2021-04-12T15:32:17.301Z,1618241537.301 [DataOverHttps](INFO): Moved sent file to Logs/20210412T151236/Express0011.lzma.bak
2021-04-12T15:32:17.301Z,1618241537.301 [DataOverHttps](INFO): SBD MOMSN=15560070
2021-04-12T15:32:19.114Z,1618241539.114 [Default:CheckIn:Read_Iridium] Stopped
2021-04-12T15:32:19.114Z,1618241539.114 [Default:CheckIn:C.Wait] Running Loop=1
2021-04-12T15:32:19.114Z,1618241539.114 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-04-12T15:32:36.945Z,1618241556.945 [NAL9602](INFO): Not Powering down - fast GPS
2021-04-12T15:37:19.840Z,1618241839.840 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-04-12T15:37:19.840Z,1618241839.840 [Default:CheckIn:C.Wait] Stopped
2021-04-12T15:37:19.840Z,1618241839.840 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-04-12T15:37:19.840Z,1618241839.840 [Default:CheckIn:D] Running Loop=1
2021-04-12T15:37:20.248Z,1618241840.248 [Default:CheckIn:D] Stopped
2021-04-12T15:37:20.248Z,1618241840.248 [Default:CheckIn:E] Running Loop=1
2021-04-12T15:37:20.667Z,1618241840.667 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 20.718046 min 
2021-04-12T15:37:20.668Z,1618241840.668 [Default:CheckIn:E] Stopped
2021-04-12T15:37:20.668Z,1618241840.668 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-04-12T15:37:20.668Z,1618241840.668 [Default:CheckIn] Stopped
2021-04-12T15:37:20.668Z,1618241840.668 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-04-12T15:37:20.668Z,1618241840.668 [Default:CheckIn](INFO): Running loop #4
2021-04-12T15:37:20.668Z,1618241840.668 [Default:CheckIn] Running Loop=4
2021-04-12T15:37:20.668Z,1618241840.668 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-04-12T15:37:20.668Z,1618241840.668 [Default:CheckIn:Read_GPS] Running Loop=1
2021-04-12T15:37:22.654Z,1618241842.654 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,153721.00,A,3648.01833,N,12149.49729,W,18.952,262.72,120421,,,D*44
2021-04-12T15:37:22.656Z,1618241842.656 [NAL9602](INFO): GPS fix at 20210412T153721: (36.800306, -121.824955)
2021-04-12T15:37:22.706Z,1618241842.706 [Default:CheckIn:Read_GPS] Stopped
2021-04-12T15:37:22.706Z,1618241842.706 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-04-12T15:37:31.110Z,1618241851.110 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210412T151236/Courier0013.lzma
2021-04-12T15:37:32.113Z,1618241852.113 [DataOverHttps](INFO): Moved sent file to Logs/20210412T151236/Courier0013.lzma.bak
2021-04-12T15:37:32.113Z,1618241852.113 [DataOverHttps](INFO): SBD MOMSN=15560082
2021-04-12T15:37:35.178Z,1618241855.178 [NAL9602](INFO): SBD MO Status=0, MOMSN=12727, MT Status=0, MTMSN=0
2021-04-12T15:37:35.178Z,1618241855.178 [NAL9602](INFO): No messages in MT queue
2021-04-12T15:37:48.266Z,1618241868.266 [DataOverHttps](INFO): Sending 146 bytes from file Logs/20210412T151236/Express0014.lzma
2021-04-12T15:37:49.285Z,1618241869.285 [DataOverHttps](INFO): Moved sent file to Logs/20210412T151236/Express0014.lzma.bak
2021-04-12T15:37:49.285Z,1618241869.285 [DataOverHttps](INFO): SBD MOMSN=15560085
2021-04-12T15:37:50.557Z,1618241870.557 [Default:CheckIn:Read_Iridium] Stopped
2021-04-12T15:37:50.557Z,1618241870.557 [Default:CheckIn:C.Wait] Running Loop=1
2021-04-12T15:37:50.557Z,1618241870.557 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-04-12T15:38:05.878Z,1618241885.878 [NAL9602](INFO): Not Powering down - fast GPS
2021-04-12T15:42:51.240Z,1618242171.240 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-04-12T15:42:51.240Z,1618242171.240 [Default:CheckIn:C.Wait] Stopped
2021-04-12T15:42:51.240Z,1618242171.240 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-04-12T15:42:51.240Z,1618242171.240 [Default:CheckIn:D] Running Loop=1
2021-04-12T15:42:51.642Z,1618242171.642 [Default:CheckIn:D] Stopped
2021-04-12T15:42:51.642Z,1618242171.642 [Default:CheckIn:E] Running Loop=1
2021-04-12T15:42:52.043Z,1618242172.043 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 26.241284 min 
2021-04-12T15:42:52.043Z,1618242172.043 [Default:CheckIn:E] Stopped
2021-04-12T15:42:52.043Z,1618242172.043 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-04-12T15:42:52.043Z,1618242172.043 [Default:CheckIn] Stopped
2021-04-12T15:42:52.044Z,1618242172.044 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-04-12T15:42:52.044Z,1618242172.044 [Default:CheckIn](INFO): Running loop #5
2021-04-12T15:42:52.044Z,1618242172.044 [Default:CheckIn] Running Loop=5
2021-04-12T15:42:52.044Z,1618242172.044 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-04-12T15:42:52.044Z,1618242172.044 [Default:CheckIn:Read_GPS] Running Loop=1
2021-04-12T15:42:54.058Z,1618242174.058 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,154253.00,A,3647.86686,N,12150.98319,W,0.603,249.04,120421,,,D*7A
2021-04-12T15:42:54.073Z,1618242174.073 [NAL9602](INFO): GPS fix at 20210412T154253: (36.797781, -121.849720)
2021-04-12T15:42:54.085Z,1618242174.085 [Default:CheckIn:Read_GPS] Stopped
2021-04-12T15:42:54.085Z,1618242174.085 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-04-12T15:43:04.154Z,1618242184.154 [NAL9602](INFO): SBD MO Status=0, MOMSN=12728, MT Status=0, MTMSN=0
2021-04-12T15:43:04.154Z,1618242184.154 [NAL9602](INFO): No messages in MT queue
2021-04-12T15:43:08.272Z,1618242188.272 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.915543
2021-04-12T15:43:22.459Z,1618242202.459 [NAL9602](INFO): SBD MO Status=1, MOMSN=12729, MT Status=0, MTMSN=0
2021-04-12T15:43:22.507Z,1618242202.507 [NAL9602](INFO): Sent 72 bytes from file Logs/20210412T151236/Courier0016.lzma
2021-04-12T15:43:22.507Z,1618242202.507 [NAL9602](INFO): Packets left to send: 0
2021-04-12T15:43:39.050Z,1618242219.050 [NAL9602](INFO): SBD MO Status=1, MOMSN=12730, MT Status=0, MTMSN=0
2021-04-12T15:43:39.101Z,1618242219.101 [NAL9602](INFO): Sent 141 bytes from file Logs/20210412T151236/Express0017.lzma
2021-04-12T15:43:39.101Z,1618242219.101 [NAL9602](INFO): Packets left to send: 0
2021-04-12T15:43:39.399Z,1618242219.399 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-12T15:43:47.533Z,1618242227.533 [NAL9602](INFO): SBD MO Status=0, MOMSN=12731, MT Status=0, MTMSN=0
2021-04-12T15:43:47.612Z,1618242227.612 [Default:CheckIn:Read_Iridium] Stopped
2021-04-12T15:43:47.612Z,1618242227.612 [Default:CheckIn:C.Wait] Running Loop=1
2021-04-12T15:43:47.612Z,1618242227.612 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-04-12T15:44:14.559Z,1618242254.559 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-12T15:44:18.273Z,1618242258.273 [NAL9602](INFO): Not Powering down - fast GPS
2021-04-12T15:44:49.715Z,1618242289.715 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-12T15:45:24.867Z,1618242324.867 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-04-12T15:45:58.331Z,1618242358.331 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003285
2021-04-12T15:47:12.770Z,1618242432.770 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2021-04-12T15:48:48.182Z,1618242528.182 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-04-12T15:48:48.182Z,1618242528.182 [Default:CheckIn:C.Wait] Stopped
2021-04-12T15:48:48.182Z,1618242528.182 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-04-12T15:48:48.182Z,1618242528.182 [Default:CheckIn:D] Running Loop=1
2021-04-12T15:48:48.604Z,1618242528.604 [Default:CheckIn:D] Stopped
2021-04-12T15:48:48.604Z,1618242528.604 [Default:CheckIn:E] Running Loop=1
2021-04-12T15:48:49.021Z,1618242529.021 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 32.190656 min 
2021-04-12T15:48:49.021Z,1618242529.021 [Default:CheckIn:E] Stopped
2021-04-12T15:48:49.021Z,1618242529.021 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-04-12T15:48:49.021Z,1618242529.021 [Default:CheckIn] Stopped
2021-04-12T15:48:49.021Z,1618242529.021 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-04-12T15:48:49.022Z,1618242529.022 [Default:CheckIn](INFO): Running loop #6
2021-04-12T15:48:49.022Z,1618242529.022 [Default:CheckIn] Running Loop=6
2021-04-12T15:48:49.022Z,1618242529.022 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-04-12T15:48:49.022Z,1618242529.022 [Default:CheckIn:Read_GPS] Running Loop=1
2021-04-12T15:48:50.998Z,1618242530.998 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,154850.00,A,3647.89691,N,12150.99360,W,0.292,351.40,120421,,,D*71
2021-04-12T15:48:51.000Z,1618242531.000 [NAL9602](INFO): GPS fix at 20210412T154850: (36.798282, -121.849893)
2021-04-12T15:48:51.012Z,1618242531.012 [Default:CheckIn:Read_GPS] Stopped
2021-04-12T15:48:51.012Z,1618242531.012 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-04-12T15:48:58.974Z,1618242538.974 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210412T151236/Courier0019.lzma
2021-04-12T15:48:59.977Z,1618242539.977 [DataOverHttps](INFO): Moved sent file to Logs/20210412T151236/Courier0019.lzma.bak
2021-04-12T15:48:59.977Z,1618242539.977 [DataOverHttps](IMPORTANT): SBD MOMSN=15560118, MTMSN=20210412T154859
2021-04-12T15:49:07.455Z,1618242547.455 [DataOverHttps](INFO): Received command:restart logs