2019-05-29T22:19:35.035Z,1559168375.035 [Supervisor](DEBUG): Initializing supervisor. 2019-05-29T22:19:35.038Z,1559168375.038 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2019-05-29T22:19:35.039Z,1559168375.039 [SyncHandler](INFO): Protected caller Thread ID is 806 2019-05-29T22:19:35.039Z,1559168375.039 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2019-05-29T22:19:35.040Z,1559168375.040 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2019-05-29T22:19:35.040Z,1559168375.040 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 807 2019-05-29T22:19:35.043Z,1559168375.043 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2019-05-29T22:19:35.055Z,1559168375.055 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2019-05-29T22:19:35.056Z,1559168375.056 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2019-05-29T22:19:35.056Z,1559168375.056 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 808 2019-05-29T22:19:35.057Z,1559168375.057 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2019-05-29T22:19:35.058Z,1559168375.058 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2019-05-29T22:19:35.059Z,1559168375.059 [logger ThreadHandler](INFO): Protected caller Thread ID is 809 2019-05-29T22:19:35.061Z,1559168375.061 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2019-05-29T22:19:35.061Z,1559168375.061 [Supervisor](INFO): Looking for Config files in directory: Config/ 2019-05-29T22:19:35.065Z,1559168375.065 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2019-05-29T22:19:35.504Z,1559168375.504 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2019-05-29T22:19:35.505Z,1559168375.505 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2019-05-29T22:19:35.605Z,1559168375.605 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2019-05-29T22:19:35.605Z,1559168375.605 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2019-05-29T22:19:35.941Z,1559168375.941 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2019-05-29T22:19:35.943Z,1559168375.943 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2019-05-29T22:19:36.087Z,1559168376.087 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2019-05-29T22:19:36.089Z,1559168376.089 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2019-05-29T22:19:36.285Z,1559168376.285 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2019-05-29T22:19:36.287Z,1559168376.287 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2019-05-29T22:19:36.753Z,1559168376.753 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2019-05-29T22:19:36.755Z,1559168376.755 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2019-05-29T22:19:36.970Z,1559168376.970 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2019-05-29T22:19:36.971Z,1559168376.971 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2019-05-29T22:19:37.119Z,1559168377.119 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2019-05-29T22:19:37.121Z,1559168377.121 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2019-05-29T22:19:37.321Z,1559168377.321 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2019-05-29T22:19:37.322Z,1559168377.322 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2019-05-29T22:19:37.419Z,1559168377.419 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2019-05-29T22:19:37.421Z,1559168377.421 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2019-05-29T22:19:37.752Z,1559168377.752 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2019-05-29T22:19:37.754Z,1559168377.754 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2019-05-29T22:19:37.835Z,1559168377.835 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2019-05-29T22:19:37.941Z,1559168377.941 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2019-05-29T22:19:37.943Z,1559168377.943 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2019-05-29T22:19:38.583Z,1559168378.583 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2019-05-29T22:19:39.285Z,1559168379.285 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2019-05-29T22:19:39.927Z,1559168379.927 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2019-05-29T22:19:39.928Z,1559168379.928 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/ 2019-05-29T22:19:39.931Z,1559168379.931 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg 2019-05-29T22:19:40.147Z,1559168380.147 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg 2019-05-29T22:19:40.248Z,1559168380.248 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg 2019-05-29T22:19:40.348Z,1559168380.348 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg 2019-05-29T22:19:40.577Z,1559168380.577 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2019-05-29T22:19:40.577Z,1559168380.577 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg 2019-05-29T22:19:40.663Z,1559168380.663 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg 2019-05-29T22:19:40.758Z,1559168380.758 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg 2019-05-29T22:19:40.856Z,1559168380.856 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg 2019-05-29T22:19:40.941Z,1559168380.941 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg 2019-05-29T22:19:41.051Z,1559168381.051 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg 2019-05-29T22:19:41.225Z,1559168381.225 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg 2019-05-29T22:19:41.359Z,1559168381.359 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2019-05-29T22:19:41.379Z,1559168381.379 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2019-05-29T22:19:42.085Z,1559168382.085 [AHRS_M2] Loaded 2019-05-29T22:19:42.085Z,1559168382.085 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2019-05-29T22:19:42.227Z,1559168382.227 [DataOverHttps] Loaded 2019-05-29T22:19:42.227Z,1559168382.227 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread. 2019-05-29T22:19:42.228Z,1559168382.228 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075A4E0 2019-05-29T22:19:42.229Z,1559168382.229 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 889 2019-05-29T22:19:42.242Z,1559168382.242 [Depth_Keller] Loaded 2019-05-29T22:19:42.242Z,1559168382.242 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2019-05-29T22:19:42.247Z,1559168382.247 [DropWeight] Loaded 2019-05-29T22:19:42.247Z,1559168382.247 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2019-05-29T22:19:42.304Z,1559168382.304 [DUSBL_Hydroid] Loaded 2019-05-29T22:19:42.304Z,1559168382.304 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread. 2019-05-29T22:19:42.344Z,1559168382.344 [Micromodem] Loaded 2019-05-29T22:19:42.345Z,1559168382.345 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread. 2019-05-29T22:19:42.443Z,1559168382.443 [NAL9602] Loaded 2019-05-29T22:19:42.443Z,1559168382.443 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2019-05-29T22:19:42.459Z,1559168382.459 [Onboard] Loaded 2019-05-29T22:19:42.459Z,1559168382.459 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2019-05-29T22:19:42.465Z,1559168382.465 [PowerOnly] Loaded 2019-05-29T22:19:42.465Z,1559168382.465 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread. 2019-05-29T22:19:42.472Z,1559168382.472 [Radio_Surface] Loaded 2019-05-29T22:19:42.472Z,1559168382.472 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2019-05-29T22:19:42.473Z,1559168382.473 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078A4E0 2019-05-29T22:19:42.473Z,1559168382.473 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 890 2019-05-29T22:19:42.518Z,1559168382.518 [RDI_Pathfinder] Loaded 2019-05-29T22:19:42.518Z,1559168382.518 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread. 2019-05-29T22:19:44.339Z,1559168384.339 [BPC1] Loaded 2019-05-29T22:19:44.339Z,1559168384.339 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2019-05-29T22:19:44.340Z,1559168384.340 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2019-05-29T22:19:44.340Z,1559168384.340 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2019-05-29T22:19:44.481Z,1559168384.481 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2019-05-29T22:19:44.482Z,1559168384.482 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2019-05-29T22:19:44.604Z,1559168384.604 [DeadReckonUsingMultipleVelocitySources] Loaded 2019-05-29T22:19:44.605Z,1559168384.605 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2019-05-29T22:19:44.625Z,1559168384.625 [NavChart] Loaded 2019-05-29T22:19:44.626Z,1559168384.626 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2019-05-29T22:19:44.630Z,1559168384.630 [UniversalFixResidualReporter] Loaded 2019-05-29T22:19:44.630Z,1559168384.630 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2019-05-29T22:19:44.630Z,1559168384.630 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2019-05-29T22:19:44.631Z,1559168384.631 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2019-05-29T22:19:44.763Z,1559168384.763 [BuoyancyServo] Loaded 2019-05-29T22:19:44.763Z,1559168384.763 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2019-05-29T22:19:44.779Z,1559168384.779 [ElevatorServo] Loaded 2019-05-29T22:19:44.779Z,1559168384.779 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2019-05-29T22:19:44.794Z,1559168384.794 [MassServo] Loaded 2019-05-29T22:19:44.794Z,1559168384.794 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2019-05-29T22:19:44.810Z,1559168384.810 [RudderServo] Loaded 2019-05-29T22:19:44.810Z,1559168384.810 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2019-05-29T22:19:44.824Z,1559168384.824 [ThrusterServo] Loaded 2019-05-29T22:19:44.825Z,1559168384.825 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2019-05-29T22:19:44.825Z,1559168384.825 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2019-05-29T22:19:44.826Z,1559168384.826 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2019-05-29T22:19:45.145Z,1559168385.145 [CTD_NeilBrown] Loaded 2019-05-29T22:19:45.145Z,1559168385.145 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread. 2019-05-29T22:19:45.147Z,1559168385.147 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408CC4E0 2019-05-29T22:19:45.147Z,1559168385.147 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 891 2019-05-29T22:19:45.278Z,1559168385.278 [WetLabsSeaOWL_UV_A] Loaded 2019-05-29T22:19:45.278Z,1559168385.278 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread. 2019-05-29T22:19:45.279Z,1559168385.279 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408FC4E0 2019-05-29T22:19:45.279Z,1559168385.279 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 892 2019-05-29T22:19:45.280Z,1559168385.280 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2019-05-29T22:19:45.281Z,1559168385.281 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2019-05-29T22:19:46.101Z,1559168386.101 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2019-05-29T22:19:46.101Z,1559168386.101 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2019-05-29T22:19:46.156Z,1559168386.156 [DepthRateCalculator] Loaded 2019-05-29T22:19:46.157Z,1559168386.157 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2019-05-29T22:19:46.162Z,1559168386.162 [PitchRateCalculator] Loaded 2019-05-29T22:19:46.163Z,1559168386.163 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2019-05-29T22:19:46.175Z,1559168386.175 [SpeedCalculator] Loaded 2019-05-29T22:19:46.176Z,1559168386.176 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2019-05-29T22:19:46.196Z,1559168386.196 [TempGradientCalculator] Loaded 2019-05-29T22:19:46.197Z,1559168386.197 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2019-05-29T22:19:46.202Z,1559168386.202 [YawRateCalculator] Loaded 2019-05-29T22:19:46.202Z,1559168386.202 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2019-05-29T22:19:46.243Z,1559168386.243 [ElevatorOffsetCalculator] Loaded 2019-05-29T22:19:46.243Z,1559168386.243 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2019-05-29T22:19:46.243Z,1559168386.243 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2019-05-29T22:19:46.244Z,1559168386.244 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2019-05-29T22:19:46.405Z,1559168386.405 [SBIT](DEBUG): Construct Startup Built In Test. 2019-05-29T22:19:46.427Z,1559168386.427 [SBIT] Loaded 2019-05-29T22:19:46.427Z,1559168386.427 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2019-05-29T22:19:46.428Z,1559168386.428 [IBIT](DEBUG): Construct Initiated Built In Test. 2019-05-29T22:19:46.440Z,1559168386.440 [IBIT] Loaded 2019-05-29T22:19:46.440Z,1559168386.440 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2019-05-29T22:19:46.443Z,1559168386.443 [CBIT](DEBUG): Construct Continuous Built In Test. 2019-05-29T22:19:46.582Z,1559168386.582 [CBIT] Loaded 2019-05-29T22:19:46.583Z,1559168386.583 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2019-05-29T22:19:46.583Z,1559168386.583 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2019-05-29T22:19:46.584Z,1559168386.584 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2019-05-29T22:19:46.707Z,1559168386.707 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2019-05-29T22:19:46.707Z,1559168386.707 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2019-05-29T22:19:46.831Z,1559168386.831 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2019-05-29T22:19:46.832Z,1559168386.832 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2019-05-29T22:19:46.918Z,1559168386.918 [VerticalControl](DEBUG): Construct VerticalControl. 2019-05-29T22:19:47.002Z,1559168387.002 [VerticalControl] Loaded 2019-05-29T22:19:47.003Z,1559168387.003 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2019-05-29T22:19:47.003Z,1559168387.003 [HorizontalControl](DEBUG): Construct HorizontalControl. 2019-05-29T22:19:47.062Z,1559168387.062 [HorizontalControl] Loaded 2019-05-29T22:19:47.062Z,1559168387.062 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2019-05-29T22:19:47.063Z,1559168387.063 [SpeedControl](DEBUG): Construct SpeedControl. 2019-05-29T22:19:47.064Z,1559168387.064 [SpeedControl] Loaded 2019-05-29T22:19:47.065Z,1559168387.065 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2019-05-29T22:19:47.065Z,1559168387.065 [LoopControl](DEBUG): Construct LoopControl. 2019-05-29T22:19:47.066Z,1559168387.066 [LoopControl] Loaded 2019-05-29T22:19:47.066Z,1559168387.066 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2019-05-29T22:19:47.067Z,1559168387.067 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2019-05-29T22:19:47.069Z,1559168387.069 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2019-05-29T22:19:47.109Z,1559168387.109 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2019-05-29T22:19:47.113Z,1559168387.113 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2019-05-29T22:19:47.114Z,1559168387.114 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2019-05-29T22:19:47.121Z,1559168387.121 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2019-05-29T22:19:47.122Z,1559168387.122 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AD54E0 2019-05-29T22:19:47.122Z,1559168387.122 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 893 2019-05-29T22:19:47.127Z,1559168387.127 [Supervisor](INFO): Main Thread ID is 802 2019-05-29T22:19:47.127Z,1559168387.127 [Supervisor](DEBUG): Running supervisor. 2019-05-29T22:19:47.128Z,1559168387.128 [CommandLine ThreadHandler](INFO): Handler Thread ID is 894 2019-05-29T22:19:47.130Z,1559168387.130 [controlThread ThreadHandler](INFO): Handler Thread ID is 895 2019-05-29T22:19:47.130Z,1559168387.130 [controlThread](DEBUG): Initializing ControlThread 2019-05-29T22:19:47.137Z,1559168387.137 [NavChart](DEBUG): Initialize NavChart Navigation. 2019-05-29T22:19:47.138Z,1559168387.138 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2019-05-29T22:19:47.139Z,1559168387.139 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2019-05-29T22:19:47.139Z,1559168387.139 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2019-05-29T22:19:47.139Z,1559168387.139 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2019-05-29T22:19:47.140Z,1559168387.140 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2019-05-29T22:19:47.140Z,1559168387.140 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2019-05-29T22:19:47.141Z,1559168387.141 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2019-05-29T22:19:47.141Z,1559168387.141 [SBIT](INFO): Initialize SBIT Component. 2019-05-29T22:19:47.142Z,1559168387.142 [SBIT](IMPORTANT): git: 2019-05-29 2019-05-29T22:19:47.142Z,1559168387.142 [SBIT](INFO): git hash: 3a408d161d85e02f941062c72493668314c507d3 2019-05-29T22:19:47.142Z,1559168387.142 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2019-05-29T22:19:47.143Z,1559168387.143 [SBIT](INFO): Kernel Reporting Different Version From Configuration. Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018 Kernel Reported: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019 2019-05-29T22:19:47.144Z,1559168387.144 [SBIT](INFO): Beginning SBIT in 39.000000 seconds. 2019-05-29T22:19:47.145Z,1559168387.145 [IBIT](INFO): Initialize IBIT Component. 2019-05-29T22:19:47.146Z,1559168387.146 [CBIT](DEBUG): Initialize CBIT Component. 2019-05-29T22:19:47.147Z,1559168387.147 [logger ThreadHandler](INFO): Handler Thread ID is 896 2019-05-29T22:19:47.158Z,1559168387.158 [CBIT](DEBUG): Initialized mux pins. 2019-05-29T22:19:47.158Z,1559168387.158 [CBIT](DEBUG): Initializing the watchdog timer. 2019-05-29T22:19:47.167Z,1559168387.167 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 897 2019-05-29T22:19:47.168Z,1559168387.168 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2019-05-29T22:19:47.179Z,1559168387.179 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 898 2019-05-29T22:19:47.182Z,1559168387.182 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2019-05-29T22:19:47.182Z,1559168387.182 [CBIT](DEBUG): Initializing heartbeat. 2019-05-29T22:19:47.191Z,1559168387.191 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 899 2019-05-29T22:19:47.192Z,1559168387.192 [CTD_NeilBrown](INFO): Powering down 2019-05-29T22:19:47.219Z,1559168387.219 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 900 2019-05-29T22:19:47.220Z,1559168387.220 [WetLabsSeaOWL_UV_A](INFO): Powering down 2019-05-29T22:19:47.251Z,1559168387.251 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 901 2019-05-29T22:19:47.254Z,1559168387.254 [CBIT](DEBUG): Deactivating GF circuits. 2019-05-29T22:19:47.254Z,1559168387.254 [CBIT](DEBUG): Deactivating emergency mode. 2019-05-29T22:19:47.260Z,1559168387.260 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2019-05-29T22:19:47.260Z,1559168387.260 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2019-05-29T22:19:47.260Z,1559168387.260 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2019-05-29T22:19:47.260Z,1559168387.260 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2019-05-29T22:19:47.260Z,1559168387.260 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2019-05-29T22:19:47.261Z,1559168387.261 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2019-05-29T22:19:47.261Z,1559168387.261 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2019-05-29T22:19:47.261Z,1559168387.261 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2019-05-29T22:19:47.261Z,1559168387.261 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2019-05-29T22:19:47.261Z,1559168387.261 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2019-05-29T22:19:47.262Z,1559168387.262 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2019-05-29T22:19:47.262Z,1559168387.262 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2019-05-29T22:19:47.262Z,1559168387.262 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2019-05-29T22:19:47.262Z,1559168387.262 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2019-05-29T22:19:47.263Z,1559168387.263 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2019-05-29T22:19:47.263Z,1559168387.263 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2019-05-29T22:19:47.290Z,1559168387.290 [CBIT](DEBUG): Backplane powered. 2019-05-29T22:19:47.291Z,1559168387.291 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2019-05-29T22:19:47.292Z,1559168387.292 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2019-05-29T22:19:47.293Z,1559168387.293 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2019-05-29T22:19:47.293Z,1559168387.293 [LoopControl](DEBUG): Initialize LoopControlComponent. 2019-05-29T22:19:47.294Z,1559168387.294 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2019-05-29T22:19:47.316Z,1559168387.316 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2019-05-29T22:19:47.351Z,1559168387.351 [MissionManager](DEBUG): 2019-05-29T22:19:47.352Z,1559168387.352 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2019-05-29T22:19:47.417Z,1559168387.417 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2019-05-29T22:19:47.418Z,1559168387.418 [Default:A.Wait](DEBUG): Construct Wait. 2019-05-29T22:19:47.435Z,1559168387.435 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2019-05-29T22:19:47.465Z,1559168387.465 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2019-05-29T22:19:47.467Z,1559168387.467 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2019-05-29T22:19:47.481Z,1559168387.481 [Default:E.Execute](DEBUG): Construct Execute. 2019-05-29T22:19:47.484Z,1559168387.484 [MissionManager](DEBUG): 0 Wait a moment to see if the scheduler starts a new mission before starting to actually run Default. 13 Burn on Dropped weight due to communications timeout. 5 Default mission has been running for Restarting logs and Default mission. restart logs 2019-05-29T22:19:47.504Z,1559168387.504 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,BPC1,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2019-05-29T22:19:47.522Z,1559168387.522 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2019-05-29T22:19:47.582Z,1559168387.582 [Radio_Surface](INFO): Powering up 2019-05-29T22:19:47.607Z,1559168387.607 [Depth_Keller](ERROR): Pressure reading out of range: 957.962097 decibar 2019-05-29T22:19:47.608Z,1559168387.608 [DUSBL_Hydroid](INFO): Powering up 2019-05-29T22:19:47.608Z,1559168387.608 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid. 2019-05-29T22:19:47.679Z,1559168387.679 [DepthRateCalculator](ERROR): Depth measurement is not active 2019-05-29T22:19:47.744Z,1559168387.744 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2019-05-29T22:19:47.747Z,1559168387.747 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2019-05-29T22:19:47.748Z,1559168387.748 [ElevatorServo](DEBUG): Initializing EZServoServo. 2019-05-29T22:19:47.755Z,1559168387.755 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2019-05-29T22:19:47.755Z,1559168387.755 [MassServo](DEBUG): Initializing EZServoServo. 2019-05-29T22:19:47.763Z,1559168387.763 [MassServo](DEBUG): Initializing MassServo. 2019-05-29T22:19:47.763Z,1559168387.763 [RudderServo](DEBUG): Initializing EZServoServo. 2019-05-29T22:19:47.771Z,1559168387.771 [RudderServo](DEBUG): Initializing RudderServo. 2019-05-29T22:19:47.771Z,1559168387.771 [ThrusterServo](DEBUG): Initializing EZServoServo. 2019-05-29T22:19:47.779Z,1559168387.779 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2019-05-29T22:19:48.030Z,1559168388.030 [Micromodem](INFO): Powering up 2019-05-29T22:19:48.030Z,1559168388.030 [Micromodem](DEBUG): Initializing Micromodem. 2019-05-29T22:19:48.674Z,1559168388.674 [RudderServo](ERROR): Rudder initialization uart error serial timeout 2019-05-29T22:19:48.674Z,1559168388.674 [RudderServo](FAULT): Rudder failed to initialize 2019-05-29T22:19:48.675Z,1559168388.675 [RudderServo] Communications Fault, FailCount= 1 2019-05-29T22:19:48.675Z,1559168388.675 [RudderServo](ERROR): Communications Fault 2019-05-29T22:19:48.786Z,1559168388.786 [CBIT](ERROR): Communications Fault in component: RudderServo 2019-05-29T22:19:48.943Z,1559168388.943 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2019-05-29T22:19:48.943Z,1559168388.943 [RudderServo](INFO): Powering down 2019-05-29T22:19:49.660Z,1559168389.660 [RudderServo](DEBUG): Initializing EZServoServo. 2019-05-29T22:19:49.779Z,1559168389.779 [RudderServo](DEBUG): Initializing RudderServo. 2019-05-29T22:19:49.783Z,1559168389.783 [CBIT](INFO): Clearing failed state for component RudderServo 2019-05-29T22:19:49.784Z,1559168389.784 [RudderServo] No Fault, FailCount= 1 2019-05-29T22:20:00.958Z,1559168400.958 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder 2019-05-29T22:20:04.165Z,1559168404.165 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33 2019-05-29T22:20:05.780Z,1559168405.780 [DUSBL_Hydroid](INFO): DUSBL Version:O 2019-05-29T22:20:12.645Z,1559168412.645 [NAL9602](INFO): Powering up NAL9602 2019-05-29T22:20:15.472Z,1559168415.472 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33 2019-05-29T22:20:23.561Z,1559168423.561 [NAL9602](INFO): NAL9602 initialized 2019-05-29T22:20:24.382Z,1559168424.382 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:20:26.824Z,1559168426.824 [SBIT](IMPORTANT): Beginning Startup BIT 2019-05-29T22:20:26.833Z,1559168426.833 [CBIT](IMPORTANT): Beginning ground fault scan 2019-05-29T22:20:37.591Z,1559168437.591 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.012008 CHAN A1 (24V): -0.025898 CHAN A2 (12V): -0.007497 CHAN A3 (5V): -0.003040 CHAN B0 (3.3V): -0.000143 CHAN B1 (3.15aV): -0.000293 CHAN B2 (3.15bV): 0.000217 CHAN B3 (GND): 0.001480 OPEN: 0.005686 Full Scale Calc: 4.765 mA, -1.589 mA 2019-05-29T22:20:53.453Z,1559168453.453 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CAREV,222045,AUV,2.0.2769016 2019-05-29T22:20:54.257Z,1559168454.257 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CREV2224,CORC,0.10.0.46*43 2019-05-29T22:21:12.221Z,1559168472.221 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-05-29T22:21:12.222Z,1559168472.222 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19052915294471,35.0, 0.0,1448.9, 0 2019-05-29T22:21:20.321Z,1559168480.321 [SBIT](IMPORTANT): SBIT PASSED 2019-05-29T22:21:20.383Z,1559168480.383 [CommandLine](IMPORTANT): got command configSet list 2019-05-29T22:21:20.384Z,1559168480.384 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2019-05-29T22:21:20.384Z,1559168480.384 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour; 2019-05-29T22:21:20.385Z,1559168480.385 [CommandLine](IMPORTANT): BPC1.loadAtStartup=1 bool; 2019-05-29T22:21:20.385Z,1559168480.385 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=40 count; 2019-05-29T22:21:20.385Z,1559168480.385 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter; 2019-05-29T22:21:20.385Z,1559168480.385 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree; 2019-05-29T22:21:20.385Z,1559168480.385 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.BottomVelocityFlag 0.000000 count; 2019-05-29T22:21:20.385Z,1559168480.385 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter; 2019-05-29T22:21:20.385Z,1559168480.385 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_latitude; 2019-05-29T22:21:20.385Z,1559168480.385 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_longitude; 2019-05-29T22:21:20.386Z,1559168480.386 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter; 2019-05-29T22:21:20.386Z,1559168480.386 [CommandLine](IMPORTANT): Express linearApproximation mass_concentration_of_chlorophyll_in_sea_water 5.000000 microgram_per_liter; 2019-05-29T22:21:20.386Z,1559168480.386 [CommandLine](IMPORTANT): Express none mass_concentration_of_oxygen_in_sea_water; 2019-05-29T22:21:20.386Z,1559168480.386 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool; 2019-05-29T22:21:20.386Z,1559168480.386 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=190 cubic_centimeter; 2019-05-29T22:21:20.386Z,1559168480.386 [CommandLine](IMPORTANT): VerticalControl.massDefault=5 millimeter; 2019-05-29T22:21:20.711Z,1559168480.711 [MissionManager](IMPORTANT): Started mission Startup 2019-05-29T22:21:20.712Z,1559168480.712 [Startup] Running Loop=1 2019-05-29T22:21:20.712Z,1559168480.712 [Startup](DEBUG): Aggregate::initialize Startup 2019-05-29T22:21:20.712Z,1559168480.712 [Startup:A.GoToSurface] Running Loop=1 2019-05-29T22:21:20.712Z,1559168480.712 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-05-29T22:21:20.712Z,1559168480.712 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-05-29T22:21:20.713Z,1559168480.713 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-05-29T22:21:20.713Z,1559168480.713 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-05-29T22:21:20.714Z,1559168480.714 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-05-29T22:21:20.714Z,1559168480.714 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-05-29T22:21:20.715Z,1559168480.715 [Startup:StartupSatComms] Running Loop=1 2019-05-29T22:21:20.716Z,1559168480.716 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2019-05-29T22:21:20.716Z,1559168480.716 [Startup:StartupSatComms:A] Running Loop=1 2019-05-29T22:21:21.140Z,1559168481.140 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2019-05-29T22:21:28.371Z,1559168488.371 [NAL9602](INFO): SBD MO Status=2, MOMSN=5542, MT Status=2, MTMSN=0 2019-05-29T22:21:28.371Z,1559168488.371 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-05-29T22:22:03.914Z,1559168523.914 [NAL9602](INFO): SBD MO Status=2, MOMSN=5542, MT Status=2, MTMSN=0 2019-05-29T22:22:03.914Z,1559168523.914 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-05-29T22:22:13.227Z,1559168533.227 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-05-29T22:22:13.227Z,1559168533.227 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00, BI,-32768,-32768,-32768,-32768,V 2019-05-29T22:22:20.482Z,1559168540.482 [NAL9602](INFO): SBD MO Status=2, MOMSN=5542, MT Status=2, MTMSN=0 2019-05-29T22:22:20.482Z,1559168540.482 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-05-29T22:22:20.925Z,1559168540.925 [Startup:StartupSatComms:A](INFO): Timed out from 2019-05-29T22:21:20.7Z 2019-05-29T22:22:20.925Z,1559168540.925 [Startup:StartupSatComms:A] Stopped 2019-05-29T22:22:20.925Z,1559168540.925 [Startup:StartupSatComms:B] Running Loop=1 2019-05-29T22:22:21.312Z,1559168541.312 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2019-05-29T22:22:29.941Z,1559168549.941 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005378 2019-05-29T22:22:35.003Z,1559168555.003 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190529T081022/Courier0417.lzma 2019-05-29T22:22:35.809Z,1559168555.809 [DataOverHttps](INFO): Moved sent file to Logs/20190529T081022/Courier0417.lzma.bak 2019-05-29T22:22:35.810Z,1559168555.810 [DataOverHttps](INFO): SBD MOMSN=11216988 2019-05-29T22:22:47.186Z,1559168567.186 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1 2019-05-29T22:22:47.186Z,1559168567.186 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-05-29T22:22:47.196Z,1559168567.196 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-05-29T22:22:47.600Z,1559168567.600 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-05-29T22:22:47.600Z,1559168567.600 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1 2019-05-29T22:23:21.148Z,1559168601.148 [Startup:StartupSatComms:B](INFO): Timed out from 2019-05-29T22:22:20.9Z 2019-05-29T22:23:21.148Z,1559168601.148 [Startup:StartupSatComms:B] Stopped 2019-05-29T22:23:21.148Z,1559168601.148 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2019-05-29T22:23:21.148Z,1559168601.148 [Startup:StartupSatComms] Stopped 2019-05-29T22:23:21.149Z,1559168601.149 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2019-05-29T22:23:21.149Z,1559168601.149 [Startup](INFO): Completed Startup 2019-05-29T22:23:21.149Z,1559168601.149 [MissionManager](INFO): Startup is completed. 2019-05-29T22:23:21.150Z,1559168601.150 [MissionManager](INFO): Uninitializing Mission Startup 2019-05-29T22:23:21.150Z,1559168601.150 [Startup] Stopped 2019-05-29T22:23:21.150Z,1559168601.150 [Startup](DEBUG): Aggregate::uninitialize Startup 2019-05-29T22:23:21.150Z,1559168601.150 [Startup:A.GoToSurface] Stopped 2019-05-29T22:23:21.150Z,1559168601.150 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-05-29T22:23:21.527Z,1559168601.527 [MissionManager](IMPORTANT): Started mission Default 2019-05-29T22:23:21.527Z,1559168601.527 [Default] Running Loop=1 2019-05-29T22:23:21.528Z,1559168601.528 [Default](DEBUG): Aggregate::initialize Default 2019-05-29T22:23:21.528Z,1559168601.528 [Default:B.GoToSurface] Running Loop=1 2019-05-29T22:23:21.528Z,1559168601.528 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-05-29T22:23:21.528Z,1559168601.528 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-05-29T22:23:21.528Z,1559168601.528 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-05-29T22:23:21.529Z,1559168601.529 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-05-29T22:23:21.529Z,1559168601.529 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-05-29T22:23:21.529Z,1559168601.529 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-05-29T22:23:21.530Z,1559168601.530 [Default:A.Wait] Running Loop=1 2019-05-29T22:23:21.530Z,1559168601.530 [Default:A.Wait](DEBUG): Initialize Wait Component. 2019-05-29T22:23:34.879Z,1559168614.879 [Default:A.Wait](INFO): Done Waiting. 2019-05-29T22:23:34.880Z,1559168614.880 [Default:A.Wait] Stopped 2019-05-29T22:23:34.880Z,1559168614.880 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2019-05-29T22:23:35.257Z,1559168615.257 [Default:CheckIn] Running Loop=1 2019-05-29T22:23:35.258Z,1559168615.258 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-05-29T22:23:35.258Z,1559168615.258 [Default:CheckIn:Read_GPS] Running Loop=1 2019-05-29T22:23:35.648Z,1559168615.648 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2019-05-29T22:23:56.244Z,1559168636.244 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-05-29T22:23:56.244Z,1559168636.244 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-05-29T22:24:05.120Z,1559168645.120 [NAL9602](INFO): SBD MO Status=2, MOMSN=5542, MT Status=2, MTMSN=0 2019-05-29T22:24:05.120Z,1559168645.120 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-05-29T22:24:22.890Z,1559168662.890 [NAL9602](INFO): SBD MO Status=0, MOMSN=5542, MT Status=0, MTMSN=0 2019-05-29T22:24:22.890Z,1559168662.890 [NAL9602](INFO): No messages in MT queue 2019-05-29T22:24:23.710Z,1559168663.710 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:24:26.950Z,1559168666.950 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:24:29.774Z,1559168669.774 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:24:32.606Z,1559168672.606 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:24:35.839Z,1559168675.839 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:24:38.662Z,1559168678.662 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:24:40.493Z,1559168680.493 [DataOverHttps](INFO): Sending 964 bytes from file Logs/20190529T081022/Express0415.lzma 2019-05-29T22:24:41.296Z,1559168681.296 [DataOverHttps](INFO): Moved sent file to Logs/20190529T081022/Express0415.lzma.bak 2019-05-29T22:24:41.296Z,1559168681.296 [DataOverHttps](INFO): SBD MOMSN=11216991 2019-05-29T22:24:41.890Z,1559168681.890 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:24:44.722Z,1559168684.722 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:24:47.950Z,1559168687.950 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:24:50.778Z,1559168690.778 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:24:53.606Z,1559168693.606 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:24:56.850Z,1559168696.850 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:24:59.666Z,1559168699.666 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:25:02.910Z,1559168702.910 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:25:05.730Z,1559168705.730 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:25:08.958Z,1559168708.958 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:25:11.782Z,1559168711.782 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:25:14.614Z,1559168714.614 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:25:17.846Z,1559168717.846 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:25:20.674Z,1559168720.674 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:25:23.910Z,1559168723.910 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:25:26.738Z,1559168726.738 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:25:29.572Z,1559168729.572 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-05-29T22:25:29.572Z,1559168729.572 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-05-29T22:25:29.966Z,1559168729.966 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:25:32.794Z,1559168732.794 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:25:36.046Z,1559168736.046 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:25:38.854Z,1559168738.854 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:25:41.682Z,1559168741.682 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:25:44.918Z,1559168744.918 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:25:47.746Z,1559168747.746 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:25:48.195Z,1559168748.195 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2 2019-05-29T22:25:48.195Z,1559168748.195 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-05-29T22:25:48.213Z,1559168748.213 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-05-29T22:25:48.608Z,1559168748.608 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-05-29T22:25:48.608Z,1559168748.608 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2 2019-05-29T22:25:50.978Z,1559168750.978 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:25:53.815Z,1559168753.815 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:25:57.046Z,1559168757.046 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:25:59.866Z,1559168759.866 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:26:02.690Z,1559168762.690 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:26:05.922Z,1559168765.922 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:26:08.754Z,1559168768.754 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:26:09.204Z,1559168769.204 [RDI_Pathfinder](ERROR): Failed to parse: :B,-32768,-32768,V 2019-05-29T22:26:11.982Z,1559168771.982 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:26:14.823Z,1559168774.823 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:26:18.050Z,1559168778.050 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:26:20.878Z,1559168780.878 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:26:23.702Z,1559168783.702 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:26:24.094Z,1559168784.094 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,222526.00,A,3648.16676,N,12147.28623,W,0.233,0.00,290519,,,A*7E 2019-05-29T22:26:24.097Z,1559168784.097 [NAL9602](INFO): GPS fix at 20190529T222526: (36.802779, -121.788104) 2019-05-29T22:26:24.169Z,1559168784.169 [Default:CheckIn:Read_GPS] Stopped 2019-05-29T22:26:24.170Z,1559168784.170 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-05-29T22:26:24.553Z,1559168784.553 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2019-05-29T22:26:35.342Z,1559168795.342 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20190529T221935/Courier0004.lzma 2019-05-29T22:26:36.148Z,1559168796.148 [DataOverHttps](INFO): Moved sent file to Logs/20190529T221935/Courier0004.lzma.bak 2019-05-29T22:26:36.148Z,1559168796.148 [DataOverHttps](INFO): SBD MOMSN=11216997 2019-05-29T22:26:51.143Z,1559168811.143 [DataOverHttps](INFO): Sending 160 bytes from file Logs/20190529T081022/Express0418.lzma 2019-05-29T22:26:51.944Z,1559168811.944 [DataOverHttps](INFO): Moved sent file to Logs/20190529T081022/Express0418.lzma.bak 2019-05-29T22:26:51.944Z,1559168811.944 [DataOverHttps](INFO): SBD MOMSN=11217002 2019-05-29T22:26:56.608Z,1559168816.608 [NAL9602](INFO): Not Powering down - fast GPS 2019-05-29T22:28:12.124Z,1559168892.124 [DataOverHttps](INFO): Sending 1289 bytes from file Logs/20190529T221935/Express0001.lzma 2019-05-29T22:28:12.928Z,1559168892.928 [DataOverHttps](INFO): Moved sent file to Logs/20190529T221935/Express0001.lzma.bak 2019-05-29T22:28:12.928Z,1559168892.928 [DataOverHttps](INFO): SBD MOMSN=11217006 2019-05-29T22:28:18.281Z,1559168898.281 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-05-29T22:28:18.289Z,1559168898.289 [BPC1](INFO): Received data from all battery sticks. 2019-05-29T22:28:25.295Z,1559168905.295 [DataOverHttps](INFO): Sending 560 bytes from file Logs/20190529T221935/Express0005.lzma 2019-05-29T22:28:26.100Z,1559168906.100 [DataOverHttps](INFO): Moved sent file to Logs/20190529T221935/Express0005.lzma.bak 2019-05-29T22:28:26.100Z,1559168906.100 [DataOverHttps](INFO): SBD MOMSN=11217034 2019-05-29T22:28:27.153Z,1559168907.153 [Default:CheckIn:Read_Iridium] Stopped 2019-05-29T22:28:27.153Z,1559168907.153 [Default:CheckIn:C.Wait] Running Loop=1 2019-05-29T22:28:27.154Z,1559168907.154 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-05-29T22:32:00.882Z,1559169120.882 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-05-29T22:32:00.883Z,1559169120.883 [RDI_Pathfinder](ERROR): Failed to parse: :BD, +0.00, ,+0.00, 0.00,719.98 2019-05-29T22:33:27.719Z,1559169207.719 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-05-29T22:33:27.719Z,1559169207.719 [Default:CheckIn:C.Wait] Stopped 2019-05-29T22:33:27.719Z,1559169207.719 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-29T22:33:27.719Z,1559169207.719 [Default:CheckIn:D] Running Loop=1 2019-05-29T22:33:28.139Z,1559169208.139 [Default:CheckIn:D] Stopped 2019-05-29T22:33:28.140Z,1559169208.140 [Default:CheckIn:E] Running Loop=1 2019-05-29T22:33:28.519Z,1559169208.519 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 10.110198 min 2019-05-29T22:33:28.519Z,1559169208.519 [Default:CheckIn:E] Stopped 2019-05-29T22:33:28.519Z,1559169208.519 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-05-29T22:33:28.519Z,1559169208.519 [Default:CheckIn] Stopped 2019-05-29T22:33:28.520Z,1559169208.520 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-05-29T22:33:28.520Z,1559169208.520 [Default:CheckIn](INFO): Running loop #2 2019-05-29T22:33:28.520Z,1559169208.520 [Default:CheckIn] Running Loop=2 2019-05-29T22:33:28.520Z,1559169208.520 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-05-29T22:33:28.520Z,1559169208.520 [Default:CheckIn:Read_GPS] Running Loop=1 2019-05-29T22:33:30.130Z,1559169210.130 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:33:30.519Z,1559169210.519 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,223233.00,A,3648.16959,N,12147.28583,W,0.311,0.00,290519,,,A*76 2019-05-29T22:33:30.521Z,1559169210.521 [NAL9602](INFO): GPS fix at 20190529T223233: (36.802827, -121.788097) 2019-05-29T22:33:30.540Z,1559169210.540 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00, 0.00 2019-05-29T22:33:30.554Z,1559169210.554 [Default:CheckIn:Read_GPS] Stopped 2019-05-29T22:33:30.554Z,1559169210.554 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-05-29T22:33:36.158Z,1559169216.158 [DataOverHttps](INFO): Sending 221 bytes from file Logs/20190529T221935/Courier0007.lzma 2019-05-29T22:33:36.964Z,1559169216.964 [DataOverHttps](INFO): Moved sent file to Logs/20190529T221935/Courier0007.lzma.bak 2019-05-29T22:33:36.964Z,1559169216.964 [DataOverHttps](INFO): SBD MOMSN=11217037 2019-05-29T22:33:49.244Z,1559169229.244 [DataOverHttps](INFO): Sending 702 bytes from file Logs/20190529T221935/Express0008.lzma 2019-05-29T22:33:50.048Z,1559169230.048 [DataOverHttps](INFO): Moved sent file to Logs/20190529T221935/Express0008.lzma.bak 2019-05-29T22:33:50.048Z,1559169230.048 [DataOverHttps](INFO): SBD MOMSN=11217041 2019-05-29T22:33:51.277Z,1559169231.277 [Default:CheckIn:Read_Iridium] Stopped 2019-05-29T22:33:51.277Z,1559169231.277 [Default:CheckIn:C.Wait] Running Loop=1 2019-05-29T22:33:51.278Z,1559169231.278 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-05-29T22:38:32.846Z,1559169512.846 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-05-29T22:38:51.881Z,1559169531.881 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-05-29T22:38:51.881Z,1559169531.881 [Default:CheckIn:C.Wait] Stopped 2019-05-29T22:38:51.881Z,1559169531.881 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-29T22:38:51.881Z,1559169531.881 [Default:CheckIn:D] Running Loop=1 2019-05-29T22:38:52.253Z,1559169532.253 [Default:CheckIn:D] Stopped 2019-05-29T22:38:52.253Z,1559169532.253 [Default:CheckIn:E] Running Loop=1 2019-05-29T22:38:52.654Z,1559169532.654 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 15.512095 min 2019-05-29T22:38:52.655Z,1559169532.655 [Default:CheckIn:E] Stopped 2019-05-29T22:38:52.655Z,1559169532.655 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-05-29T22:38:52.655Z,1559169532.655 [Default:CheckIn] Stopped 2019-05-29T22:38:52.655Z,1559169532.655 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-05-29T22:38:52.655Z,1559169532.655 [Default:CheckIn](INFO): Running loop #3 2019-05-29T22:38:52.655Z,1559169532.655 [Default:CheckIn] Running Loop=3 2019-05-29T22:38:52.655Z,1559169532.655 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-05-29T22:38:52.655Z,1559169532.655 [Default:CheckIn:Read_GPS] Running Loop=1 2019-05-29T22:38:54.262Z,1559169534.262 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:38:54.654Z,1559169534.654 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,223757.00,A,3648.16882,N,12147.28454,W,0.583,0.00,290519,,,A*70 2019-05-29T22:38:54.656Z,1559169534.656 [NAL9602](INFO): GPS fix at 20190529T223757: (36.802814, -121.788076) 2019-05-29T22:38:54.703Z,1559169534.703 [Default:CheckIn:Read_GPS] Stopped 2019-05-29T22:38:54.703Z,1559169534.703 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-05-29T22:39:01.034Z,1559169541.034 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190529T221935/Courier0010.lzma 2019-05-29T22:39:01.843Z,1559169541.843 [DataOverHttps](INFO): Moved sent file to Logs/20190529T221935/Courier0010.lzma.bak 2019-05-29T22:39:01.843Z,1559169541.843 [DataOverHttps](INFO): SBD MOMSN=11217051 2019-05-29T22:39:14.159Z,1559169554.159 [DataOverHttps](INFO): Sending 684 bytes from file Logs/20190529T221935/Express0011.lzma 2019-05-29T22:39:14.964Z,1559169554.964 [DataOverHttps](INFO): Moved sent file to Logs/20190529T221935/Express0011.lzma.bak 2019-05-29T22:39:14.964Z,1559169554.964 [DataOverHttps](INFO): SBD MOMSN=11217059 2019-05-29T22:39:16.098Z,1559169556.098 [Default:CheckIn:Read_Iridium] Stopped 2019-05-29T22:39:16.098Z,1559169556.098 [Default:CheckIn:C.Wait] Running Loop=1 2019-05-29T22:39:16.102Z,1559169556.102 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-05-29T22:39:26.968Z,1559169566.968 [NAL9602](INFO): Not Powering down - fast GPS 2019-05-29T22:44:16.681Z,1559169856.681 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-05-29T22:44:16.681Z,1559169856.681 [Default:CheckIn:C.Wait] Stopped 2019-05-29T22:44:16.681Z,1559169856.681 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-29T22:44:16.681Z,1559169856.681 [Default:CheckIn:D] Running Loop=1 2019-05-29T22:44:17.101Z,1559169857.101 [Default:CheckIn:D] Stopped 2019-05-29T22:44:17.101Z,1559169857.101 [Default:CheckIn:E] Running Loop=1 2019-05-29T22:44:17.502Z,1559169857.502 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 20.926229 min 2019-05-29T22:44:17.502Z,1559169857.502 [Default:CheckIn:E] Stopped 2019-05-29T22:44:17.502Z,1559169857.502 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-05-29T22:44:17.502Z,1559169857.502 [Default:CheckIn] Stopped 2019-05-29T22:44:17.502Z,1559169857.502 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-05-29T22:44:17.502Z,1559169857.502 [Default:CheckIn](INFO): Running loop #4 2019-05-29T22:44:17.503Z,1559169857.503 [Default:CheckIn] Running Loop=4 2019-05-29T22:44:17.503Z,1559169857.503 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-05-29T22:44:17.503Z,1559169857.503 [Default:CheckIn:Read_GPS] Running Loop=1 2019-05-29T22:44:19.094Z,1559169859.094 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:44:19.482Z,1559169859.482 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,224322.00,A,3648.17104,N,12147.27980,W,0.719,43.54,290519,,,A*4B 2019-05-29T22:44:19.484Z,1559169859.484 [NAL9602](INFO): GPS fix at 20190529T224322: (36.802851, -121.787997) 2019-05-29T22:44:19.518Z,1559169859.518 [Default:CheckIn:Read_GPS] Stopped 2019-05-29T22:44:19.519Z,1559169859.519 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-05-29T22:44:25.678Z,1559169865.678 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190529T221935/Courier0013.lzma 2019-05-29T22:44:26.484Z,1559169866.484 [DataOverHttps](INFO): Moved sent file to Logs/20190529T221935/Courier0013.lzma.bak 2019-05-29T22:44:26.484Z,1559169866.484 [DataOverHttps](INFO): SBD MOMSN=11217065 2019-05-29T22:44:38.755Z,1559169878.755 [DataOverHttps](INFO): Sending 552 bytes from file Logs/20190529T221935/Express0014.lzma 2019-05-29T22:44:39.560Z,1559169879.560 [DataOverHttps](INFO): Moved sent file to Logs/20190529T221935/Express0014.lzma.bak 2019-05-29T22:44:39.560Z,1559169879.560 [DataOverHttps](INFO): SBD MOMSN=11217068 2019-05-29T22:44:40.553Z,1559169880.553 [Default:CheckIn:Read_Iridium] Stopped 2019-05-29T22:44:40.553Z,1559169880.553 [Default:CheckIn:C.Wait] Running Loop=1 2019-05-29T22:44:40.554Z,1559169880.554 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-05-29T22:44:50.213Z,1559169890.213 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-05-29T22:44:50.286Z,1559169890.286 [NAL9602](FAULT): received: +CSQ:0 OK42, 0, 0, 0, 0 OK 2019-05-29T22:44:50.286Z,1559169890.286 [NAL9602] Data Fault, FailCount= 1 2019-05-29T22:44:50.287Z,1559169890.287 [NAL9602](ERROR): Data Fault 2019-05-29T22:44:50.384Z,1559169890.384 [CBIT](ERROR): Data Fault in component: NAL9602 2019-05-29T22:44:50.616Z,1559169890.616 [NAL9602](INFO): Powering down 2019-05-29T22:44:51.020Z,1559169891.020 [NAL9602](FAULT): LCB fault: LCB Watchdog Reset. Hardware Overcurrent Shutdown. 2019-05-29T22:44:51.020Z,1559169891.020 [NAL9602] Hardware Fault, FailCount= 1 2019-05-29T22:44:51.020Z,1559169891.020 [NAL9602](ERROR): Hardware Fault 2019-05-29T22:44:51.479Z,1559169891.478 [CBIT](INFO): Clearing failed state for component NAL9602 2019-05-29T22:44:51.479Z,1559169891.479 [NAL9602] No Fault, FailCount= 1 2019-05-29T22:45:20.916Z,1559169920.916 [NAL9602](INFO): Powering up NAL9602 2019-05-29T22:45:29.451Z,1559169929.451 [CommandLine](IMPORTANT): got command failComponent 2019-05-29T22:45:29.451Z,1559169929.451 [CommandLine](IMPORTANT): Failed components: 2019-05-29T22:45:29.452Z,1559169929.452 [CommandLine](IMPORTANT): No failed Components. 2019-05-29T22:45:31.844Z,1559169931.844 [NAL9602](INFO): NAL9602 initialized 2019-05-29T22:45:52.058Z,1559169952.058 [RDI_Pathfinder](ERROR): Failed to parse: :SA, +0.00, +0.00, 0.00 2019-05-29T22:46:02.945Z,1559169962.945 [NAL9602](INFO): Not Powering down - fast GPS 2019-05-29T22:46:31.233Z,1559169991.233 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-05-29T22:46:31.233Z,1559169991.233 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-32768, 2019-05-29T22:49:41.137Z,1559170181.137 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-05-29T22:49:41.137Z,1559170181.137 [Default:CheckIn:C.Wait] Stopped 2019-05-29T22:49:41.137Z,1559170181.137 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-29T22:49:41.137Z,1559170181.137 [Default:CheckIn:D] Running Loop=1 2019-05-29T22:49:41.533Z,1559170181.533 [Default:CheckIn:D] Stopped 2019-05-29T22:49:41.533Z,1559170181.533 [Default:CheckIn:E] Running Loop=1 2019-05-29T22:49:41.942Z,1559170181.942 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 26.333429 min 2019-05-29T22:49:41.942Z,1559170181.942 [Default:CheckIn:E] Stopped 2019-05-29T22:49:41.942Z,1559170181.942 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-05-29T22:49:41.942Z,1559170181.942 [Default:CheckIn] Stopped 2019-05-29T22:49:41.943Z,1559170181.943 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-05-29T22:49:41.943Z,1559170181.943 [Default:CheckIn](INFO): Running loop #5 2019-05-29T22:49:41.943Z,1559170181.943 [Default:CheckIn] Running Loop=5 2019-05-29T22:49:41.943Z,1559170181.943 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-05-29T22:49:41.943Z,1559170181.943 [Default:CheckIn:Read_GPS] Running Loop=1 2019-05-29T22:49:43.542Z,1559170183.542 [NAL9602](DEBUG): Fix Requested 2019-05-29T22:49:43.931Z,1559170183.931 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,224845.00,A,3648.17628,N,12147.28178,W,0.719,349.72,290519,,,A*75 2019-05-29T22:49:43.933Z,1559170183.933 [NAL9602](INFO): GPS fix at 20190529T224845: (36.802938, -121.788030) 2019-05-29T22:49:44.001Z,1559170184.001 [Default:CheckIn:Read_GPS] Stopped 2019-05-29T22:49:44.001Z,1559170184.001 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-05-29T22:49:45.600Z,1559170185.600 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-05-29T22:49:49.558Z,1559170189.558 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190529T221935/Courier0016.lzma 2019-05-29T22:49:50.364Z,1559170190.364 [DataOverHttps](INFO): Moved sent file to Logs/20190529T221935/Courier0016.lzma.bak 2019-05-29T22:49:50.364Z,1559170190.364 [DataOverHttps](INFO): SBD MOMSN=11217074 2019-05-29T22:50:02.711Z,1559170202.711 [DataOverHttps](INFO): Sending 732 bytes from file Logs/20190529T221935/Express0017.lzma 2019-05-29T22:50:03.516Z,1559170203.516 [DataOverHttps](INFO): Moved sent file to Logs/20190529T221935/Express0017.lzma.bak 2019-05-29T22:50:03.516Z,1559170203.516 [DataOverHttps](INFO): SBD MOMSN=11217077 2019-05-29T22:50:04.610Z,1559170204.610 [Default:CheckIn:Read_Iridium] Stopped 2019-05-29T22:50:04.610Z,1559170204.610 [Default:CheckIn:C.Wait] Running Loop=1 2019-05-29T22:50:04.610Z,1559170204.610 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-05-29T22:50:16.292Z,1559170216.292 [NAL9602](INFO): Not Powering down - fast GPS 2019-05-29T22:53:17.229Z,1559170397.229 [CommandLine](IMPORTANT): got command restart application 2019-05-29T22:53:18.235Z,1559170398.235 [Supervisor](INFO): Stop Mission called by Supervisor::terminate 2019-05-29T22:53:18.236Z,1559170398.236 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2019-05-29T22:53:18.236Z,1559170398.236 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-05-29T22:53:18.252Z,1559170398.252 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2019-05-29T22:53:18.252Z,1559170398.252 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-05-29T22:53:18.253Z,1559170398.253 [CommandLine](INFO): Join timeout helper Thread ID is 983 2019-05-29T22:53:18.253Z,1559170398.253 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2019-05-29T22:53:18.254Z,1559170398.254 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-05-29T22:53:18.274Z,1559170398.274 [NavChartDb](INFO): Join timeout helper Thread ID is 984 2019-05-29T22:53:48.538Z,1559170428.538 [ 2019-05-29T22:53:48.539Z,1559170428.539 [ 2019-05-29T22:53:48.539Z,1559170428.539 [ 2019-05-29T22:53:48.541Z,1559170428.541 [Unknown] 2019-05-29T22:53:48.541Z,1559170428.541 [ 2019-05-29T22:53:48.552Z,1559170428.552 [ 2019-05-29T22:53:48.553Z,1559170428.553 [ 2019-05-29T22:53:48.553Z,1559170428.553 [ 2019-05-29T22:53:48.567Z,1559170428.567 [ 2019-05-29T22:53:48.568Z,1559170428.568 [ 2019-05-29T22:53:48.577Z,1559170428.577 [ 2019-05-29T22:53:48.578Z,1559170428.578 [ 2019-05-29T22:53:48.578Z,1559170428.578 [ 2019-05-29T22:53:48.578Z,1559170428.578 [Unknown] 2019-05-29T22:53:48.578Z,1559170428.578 [ 2019-05-29T22:53:48.585Z,1559170428.585 [ 2019-05-29T22:53:48.586Z,1559170428.586 [ 2019-05-29T22:53:48.586Z,1559170428.586 [ 2019-05-29T22:53:48.596Z,1559170428.596 [ 2019-05-29T22:53:48.596Z,1559170428.596 [ 2019-05-29T22:53:48.604Z,1559170428.604 [ 2019-05-29T22:53:48.604Z,1559170428.604 [ 2019-05-29T22:53:48.604Z,1559170428.604 [ 2019-05-29T22:53:48.604Z,1559170428.604 [Unknown] 2019-05-29T22:53:48.604Z,1559170428.604 [ 2019-05-29T22:53:48.615Z,1559170428.615 [ 2019-05-29T22:53:48.616Z,1559170428.616 [ 2019-05-29T22:53:48.631Z,1559170428.631 [ 2019-05-29T22:53:48.631Z,1559170428.631 [ 2019-05-29T22:53:48.631Z,1559170428.631 [ 2019-05-29T22:53:48.632Z,1559170428.632 [ 2019-05-29T22:53:48.632Z,1559170428.632 [ 2019-05-29T22:53:48.643Z,1559170428.643 [ 2019-05-29T22:53:48.644Z,1559170428.644 [ 2019-05-29T22:53:48.651Z,1559170428.651 [ 2019-05-29T22:53:48.652Z,1559170428.652 [