2018-09-12T18:13:35.442Z,1536776015.442 [Supervisor](DEBUG): Initializing supervisor. 2018-09-12T18:13:35.445Z,1536776015.445 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2018-09-12T18:13:35.446Z,1536776015.446 [SyncHandler](INFO): Protected caller Thread ID is 800 2018-09-12T18:13:35.446Z,1536776015.446 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2018-09-12T18:13:35.447Z,1536776015.447 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2018-09-12T18:13:35.447Z,1536776015.447 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 801 2018-09-12T18:13:35.450Z,1536776015.450 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2018-09-12T18:13:35.462Z,1536776015.462 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2018-09-12T18:13:35.463Z,1536776015.463 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2018-09-12T18:13:35.463Z,1536776015.463 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 802 2018-09-12T18:13:35.464Z,1536776015.464 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2018-09-12T18:13:35.465Z,1536776015.465 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2018-09-12T18:13:35.465Z,1536776015.465 [logger ThreadHandler](INFO): Protected caller Thread ID is 803 2018-09-12T18:13:35.467Z,1536776015.467 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2018-09-12T18:13:35.468Z,1536776015.468 [Supervisor](INFO): Looking for Config files in directory: Config/ 2018-09-12T18:13:35.474Z,1536776015.474 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2018-09-12T18:13:35.862Z,1536776015.862 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2018-09-12T18:13:35.864Z,1536776015.864 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2018-09-12T18:13:36.083Z,1536776016.083 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2018-09-12T18:13:36.084Z,1536776016.084 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2018-09-12T18:13:36.600Z,1536776016.600 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2018-09-12T18:13:36.601Z,1536776016.601 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2018-09-12T18:13:36.705Z,1536776016.705 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2018-09-12T18:13:36.706Z,1536776016.706 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2018-09-12T18:13:36.940Z,1536776016.940 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2018-09-12T18:13:36.941Z,1536776016.941 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2018-09-12T18:13:37.087Z,1536776017.087 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2018-09-12T18:13:37.088Z,1536776017.088 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2018-09-12T18:13:37.467Z,1536776017.467 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2018-09-12T18:13:37.468Z,1536776017.468 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2018-09-12T18:13:37.552Z,1536776017.552 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2018-09-12T18:13:37.655Z,1536776017.655 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2018-09-12T18:13:37.656Z,1536776017.656 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2018-09-12T18:13:37.767Z,1536776017.767 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2018-09-12T18:13:37.768Z,1536776017.768 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2018-09-12T18:13:38.122Z,1536776018.122 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2018-09-12T18:13:38.123Z,1536776018.123 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2018-09-12T18:13:38.354Z,1536776018.354 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2018-09-12T18:13:38.355Z,1536776018.355 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2018-09-12T18:13:38.854Z,1536776018.854 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2018-09-12T18:13:38.855Z,1536776018.855 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2018-09-12T18:13:39.448Z,1536776019.448 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2018-09-12T18:13:39.449Z,1536776019.449 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2018-09-12T18:13:39.995Z,1536776019.995 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2018-09-12T18:13:39.997Z,1536776019.997 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-tethys/ 2018-09-12T18:13:40.002Z,1536776020.002 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Control.cfg 2018-09-12T18:13:40.104Z,1536776020.104 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Navigation.cfg 2018-09-12T18:13:40.200Z,1536776020.200 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Simulator.cfg 2018-09-12T18:13:40.289Z,1536776020.289 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/logger.cfg 2018-09-12T18:13:40.372Z,1536776020.372 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Battery.cfg 2018-09-12T18:13:40.619Z,1536776020.619 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2018-09-12T18:13:40.620Z,1536776020.620 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Science.cfg 2018-09-12T18:13:40.771Z,1536776020.771 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/secure.cfg 2018-09-12T18:13:40.857Z,1536776020.857 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/workSite.cfg 2018-09-12T18:13:40.954Z,1536776020.954 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Servo.cfg 2018-09-12T18:13:41.056Z,1536776021.056 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/BIT.cfg 2018-09-12T18:13:41.157Z,1536776021.157 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Sensor.cfg 2018-09-12T18:13:41.313Z,1536776021.313 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/vehicle.cfg 2018-09-12T18:13:41.530Z,1536776021.530 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg 2018-09-12T18:13:41.535Z,1536776021.535 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2018-09-12T18:13:41.708Z,1536776021.708 [SBIT](DEBUG): Construct Startup Built In Test. 2018-09-12T18:13:41.740Z,1536776021.740 [SBIT] Loaded 2018-09-12T18:13:41.740Z,1536776021.740 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2018-09-12T18:13:41.741Z,1536776021.741 [IBIT](DEBUG): Construct Initiated Built In Test. 2018-09-12T18:13:41.770Z,1536776021.770 [IBIT] Loaded 2018-09-12T18:13:41.770Z,1536776021.770 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2018-09-12T18:13:41.774Z,1536776021.774 [CBIT](DEBUG): Construct Continuous Built In Test. 2018-09-12T18:13:41.940Z,1536776021.940 [CBIT] Loaded 2018-09-12T18:13:41.940Z,1536776021.940 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2018-09-12T18:13:41.941Z,1536776021.941 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2018-09-12T18:13:41.943Z,1536776021.943 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2018-09-12T18:13:41.983Z,1536776021.983 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2018-09-12T18:13:41.983Z,1536776021.983 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2018-09-12T18:13:42.237Z,1536776022.237 [CTD_Seabird] Loaded 2018-09-12T18:13:42.237Z,1536776022.237 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread. 2018-09-12T18:13:42.239Z,1536776022.239 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 405B74E0 2018-09-12T18:13:42.239Z,1536776022.239 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 885 2018-09-12T18:13:42.258Z,1536776022.258 [ESPComponent] Loaded 2018-09-12T18:13:42.258Z,1536776022.258 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread. 2018-09-12T18:13:42.273Z,1536776022.273 [PAR_Licor] Loaded 2018-09-12T18:13:42.274Z,1536776022.274 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2018-09-12T18:13:42.327Z,1536776022.327 [WetLabsBB2FL] Loaded 2018-09-12T18:13:42.327Z,1536776022.327 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2018-09-12T18:13:42.328Z,1536776022.328 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 405E74E0 2018-09-12T18:13:42.328Z,1536776022.328 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 886 2018-09-12T18:13:42.329Z,1536776022.329 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2018-09-12T18:13:42.329Z,1536776022.329 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2018-09-12T18:13:42.464Z,1536776022.464 [BuoyancyServo] Loaded 2018-09-12T18:13:42.464Z,1536776022.464 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2018-09-12T18:13:42.479Z,1536776022.479 [ElevatorServo] Loaded 2018-09-12T18:13:42.480Z,1536776022.480 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2018-09-12T18:13:42.495Z,1536776022.495 [MassServo] Loaded 2018-09-12T18:13:42.495Z,1536776022.495 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2018-09-12T18:13:42.511Z,1536776022.511 [RudderServo] Loaded 2018-09-12T18:13:42.511Z,1536776022.511 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2018-09-12T18:13:42.527Z,1536776022.527 [ThrusterServo] Loaded 2018-09-12T18:13:42.527Z,1536776022.527 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2018-09-12T18:13:42.527Z,1536776022.527 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2018-09-12T18:13:42.528Z,1536776022.528 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2018-09-12T18:13:42.837Z,1536776022.837 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2018-09-12T18:13:42.838Z,1536776022.838 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2018-09-12T18:13:43.479Z,1536776023.479 [AHRS_M2] Loaded 2018-09-12T18:13:43.479Z,1536776023.479 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2018-09-12T18:13:43.615Z,1536776023.615 [DataOverHttps] Loaded 2018-09-12T18:13:43.615Z,1536776023.615 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread. 2018-09-12T18:13:43.629Z,1536776023.629 [Depth_Keller] Loaded 2018-09-12T18:13:43.629Z,1536776023.629 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2018-09-12T18:13:43.634Z,1536776023.634 [DropWeight] Loaded 2018-09-12T18:13:43.634Z,1536776023.634 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2018-09-12T18:13:43.732Z,1536776023.732 [NAL9602] Loaded 2018-09-12T18:13:43.733Z,1536776023.733 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2018-09-12T18:13:43.738Z,1536776023.738 [Onboard] Loaded 2018-09-12T18:13:43.738Z,1536776023.738 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2018-09-12T18:13:43.745Z,1536776023.745 [Radio_Surface] Loaded 2018-09-12T18:13:43.746Z,1536776023.746 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2018-09-12T18:13:43.747Z,1536776023.747 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408CE4E0 2018-09-12T18:13:43.747Z,1536776023.747 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 887 2018-09-12T18:13:43.778Z,1536776023.778 [RDI_Pathfinder] Loaded 2018-09-12T18:13:43.779Z,1536776023.779 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread. 2018-09-12T18:13:43.918Z,1536776023.918 [DAT] Loaded 2018-09-12T18:13:43.918Z,1536776023.918 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread. 2018-09-12T18:13:45.899Z,1536776025.899 [BPC1] Loaded 2018-09-12T18:13:45.899Z,1536776025.899 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2018-09-12T18:13:45.900Z,1536776025.900 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2018-09-12T18:13:45.900Z,1536776025.900 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2018-09-12T18:13:45.926Z,1536776025.926 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2018-09-12T18:13:45.929Z,1536776025.929 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2018-09-12T18:13:46.040Z,1536776026.040 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2018-09-12T18:13:46.041Z,1536776026.041 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2018-09-12T18:13:46.166Z,1536776026.166 [DeadReckonUsingMultipleVelocitySources] Loaded 2018-09-12T18:13:46.166Z,1536776026.166 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2018-09-12T18:13:46.226Z,1536776026.226 [DeadReckonUsingSpeedCalculator] Loaded 2018-09-12T18:13:46.226Z,1536776026.226 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread. 2018-09-12T18:13:46.243Z,1536776026.243 [NavChart] Loaded 2018-09-12T18:13:46.244Z,1536776026.244 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2018-09-12T18:13:46.248Z,1536776026.248 [UniversalFixResidualReporter] Loaded 2018-09-12T18:13:46.248Z,1536776026.248 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2018-09-12T18:13:46.249Z,1536776026.249 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2018-09-12T18:13:46.249Z,1536776026.249 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2018-09-12T18:13:46.391Z,1536776026.391 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2018-09-12T18:13:46.391Z,1536776026.391 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2018-09-12T18:13:46.489Z,1536776026.489 [VerticalControl](DEBUG): Construct VerticalControl. 2018-09-12T18:13:46.583Z,1536776026.583 [VerticalControl] Loaded 2018-09-12T18:13:46.583Z,1536776026.583 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2018-09-12T18:13:46.584Z,1536776026.584 [HorizontalControl](DEBUG): Construct HorizontalControl. 2018-09-12T18:13:46.646Z,1536776026.646 [HorizontalControl] Loaded 2018-09-12T18:13:46.646Z,1536776026.646 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2018-09-12T18:13:46.647Z,1536776026.647 [SpeedControl](DEBUG): Construct SpeedControl. 2018-09-12T18:13:46.649Z,1536776026.649 [SpeedControl] Loaded 2018-09-12T18:13:46.649Z,1536776026.649 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2018-09-12T18:13:46.650Z,1536776026.650 [LoopControl](DEBUG): Construct LoopControl. 2018-09-12T18:13:46.650Z,1536776026.650 [LoopControl] Loaded 2018-09-12T18:13:46.651Z,1536776026.651 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2018-09-12T18:13:46.651Z,1536776026.651 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2018-09-12T18:13:46.652Z,1536776026.652 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2018-09-12T18:13:46.711Z,1536776026.711 [DepthRateCalculator] Loaded 2018-09-12T18:13:46.712Z,1536776026.712 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2018-09-12T18:13:46.718Z,1536776026.718 [PitchRateCalculator] Loaded 2018-09-12T18:13:46.718Z,1536776026.718 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2018-09-12T18:13:46.731Z,1536776026.731 [SpeedCalculator] Loaded 2018-09-12T18:13:46.731Z,1536776026.731 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2018-09-12T18:13:46.754Z,1536776026.754 [TempGradientCalculator] Loaded 2018-09-12T18:13:46.754Z,1536776026.754 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2018-09-12T18:13:46.771Z,1536776026.771 [VerticalTemperatureHomogeneityIndexCalculator] Loaded 2018-09-12T18:13:46.771Z,1536776026.771 [ComponentRegistry](DEBUG): SyncComponent "VerticalTemperatureHomogeneityIndexCalculator" handled in the control thread. 2018-09-12T18:13:46.777Z,1536776026.777 [YawRateCalculator] Loaded 2018-09-12T18:13:46.777Z,1536776026.777 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2018-09-12T18:13:46.809Z,1536776026.809 [ElevatorOffsetCalculator] Loaded 2018-09-12T18:13:46.809Z,1536776026.809 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2018-09-12T18:13:46.810Z,1536776026.810 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2018-09-12T18:13:46.814Z,1536776026.814 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2018-09-12T18:13:46.814Z,1536776026.814 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2018-09-12T18:13:46.821Z,1536776026.821 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2018-09-12T18:13:46.822Z,1536776026.822 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A064E0 2018-09-12T18:13:46.823Z,1536776026.823 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 888 2018-09-12T18:13:46.827Z,1536776026.827 [Supervisor](INFO): Main Thread ID is 796 2018-09-12T18:13:46.827Z,1536776026.827 [Supervisor](DEBUG): Running supervisor. 2018-09-12T18:13:46.828Z,1536776026.828 [CommandLine ThreadHandler](INFO): Handler Thread ID is 889 2018-09-12T18:13:46.830Z,1536776026.830 [controlThread ThreadHandler](INFO): Handler Thread ID is 890 2018-09-12T18:13:46.831Z,1536776026.831 [controlThread](DEBUG): Initializing ControlThread 2018-09-12T18:13:46.832Z,1536776026.832 [SBIT](INFO): Initialize SBIT Component. 2018-09-12T18:13:46.832Z,1536776026.832 [SBIT](IMPORTANT): git: 2018-09-06 2018-09-12T18:13:46.833Z,1536776026.833 [SBIT](INFO): git hash: 66a1d3cbc6e0267838eeaa8d8b2ab3dc44228fef 2018-09-12T18:13:46.833Z,1536776026.833 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2018-09-12T18:13:46.834Z,1536776026.834 [SBIT](INFO): Kernel Reporting Different Version From Configuration. Kernel Expected: #639 PREEMPT Wed Mar 12 12:53:33 PDT 2014 Kernel Reported: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018 2018-09-12T18:13:46.836Z,1536776026.836 [SBIT](INFO): Beginning SBIT in 28.000000 seconds. 2018-09-12T18:13:46.836Z,1536776026.836 [IBIT](INFO): Initialize IBIT Component. 2018-09-12T18:13:46.837Z,1536776026.837 [CBIT](DEBUG): Initialize CBIT Component. 2018-09-12T18:13:46.837Z,1536776026.837 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL. 2018-09-12T18:13:46.837Z,1536776026.837 [CBIT](CRITICAL): LAST REBOOT DUE TO WATCHDOG TIMER RESET. 2018-09-12T18:13:46.838Z,1536776026.838 [logger ThreadHandler](INFO): Handler Thread ID is 891 2018-09-12T18:13:46.867Z,1536776026.867 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 892 2018-09-12T18:13:46.868Z,1536776026.868 [CTD_Seabird](INFO): Initializing 2018-09-12T18:13:46.868Z,1536776026.868 [CTD_Seabird](INFO): Checking LCM 2018-09-12T18:13:46.953Z,1536776026.953 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 893 2018-09-12T18:13:46.960Z,1536776026.960 [WetLabsBB2FL](INFO): Powering down 2018-09-12T18:13:46.979Z,1536776026.979 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 894 2018-09-12T18:13:46.985Z,1536776026.985 [Radio_Surface](INFO): Powering up 2018-09-12T18:13:46.994Z,1536776026.994 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component. 2018-09-12T18:13:46.000Z,1536776027.000 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s. 2018-09-12T18:13:46.000Z,1536776027.000 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s. 2018-09-12T18:13:47.001Z,1536776027.001 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component. 2018-09-12T18:13:47.086Z,1536776027.086 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s. 2018-09-12T18:13:47.086Z,1536776027.086 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s. 2018-09-12T18:13:47.087Z,1536776027.087 [NavChart](DEBUG): Initialize NavChart Navigation. 2018-09-12T18:13:47.087Z,1536776027.087 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2018-09-12T18:13:47.088Z,1536776027.088 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2018-09-12T18:13:47.090Z,1536776027.090 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2018-09-12T18:13:47.090Z,1536776027.090 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2018-09-12T18:13:47.091Z,1536776027.091 [LoopControl](DEBUG): Initialize LoopControlComponent. 2018-09-12T18:13:47.091Z,1536776027.091 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2018-09-12T18:13:47.092Z,1536776027.092 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2018-09-12T18:13:47.092Z,1536776027.092 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2018-09-12T18:13:47.092Z,1536776027.092 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2018-09-12T18:13:47.093Z,1536776027.093 [VerticalTemperatureHomogeneityIndexCalculator](DEBUG): (re)initializing 2018-09-12T18:13:47.094Z,1536776027.094 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2018-09-12T18:13:47.094Z,1536776027.094 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2018-09-12T18:13:47.095Z,1536776027.095 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 895 2018-09-12T18:13:47.097Z,1536776027.097 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2018-09-12T18:13:47.201Z,1536776027.201 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2018-09-12T18:13:47.201Z,1536776027.201 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2018-09-12T18:13:47.202Z,1536776027.202 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2018-09-12T18:13:47.202Z,1536776027.202 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2018-09-12T18:13:47.202Z,1536776027.202 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2018-09-12T18:13:47.202Z,1536776027.202 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2018-09-12T18:13:47.202Z,1536776027.202 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2018-09-12T18:13:47.202Z,1536776027.202 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2018-09-12T18:13:47.203Z,1536776027.203 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2018-09-12T18:13:47.203Z,1536776027.203 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2018-09-12T18:13:47.203Z,1536776027.203 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2018-09-12T18:13:47.203Z,1536776027.203 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2018-09-12T18:13:47.204Z,1536776027.204 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2018-09-12T18:13:47.204Z,1536776027.204 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2018-09-12T18:13:47.204Z,1536776027.204 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2018-09-12T18:13:47.204Z,1536776027.204 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2018-09-12T18:13:47.283Z,1536776027.283 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2018-09-12T18:13:47.311Z,1536776027.311 [CTD_Seabird](INFO): LCM OK 2018-09-12T18:13:47.311Z,1536776027.311 [CTD_Seabird](INFO): Powering up 2018-09-12T18:13:47.319Z,1536776027.319 [MissionManager](DEBUG): 2018-09-12T18:13:47.320Z,1536776027.320 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2018-09-12T18:13:47.398Z,1536776027.398 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2018-09-12T18:13:47.419Z,1536776027.419 [Default:A.Wait](DEBUG): Construct Wait. 2018-09-12T18:13:47.421Z,1536776027.421 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2018-09-12T18:13:47.456Z,1536776027.456 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2018-09-12T18:13:47.459Z,1536776027.459 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2018-09-12T18:13:47.477Z,1536776027.477 [Default:E.Execute](DEBUG): Construct Execute. 2018-09-12T18:13:47.501Z,1536776027.501 [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 2018-09-12T18:13:47.506Z,1536776027.506 [controlThread](DEBUG): Component order: CycleStarter,ESPComponent,PAR_Licor,AHRS_M2,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,RDI_Pathfinder,DAT,BPC1,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,VerticalTemperatureHomogeneityIndexCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2018-09-12T18:13:47.531Z,1536776027.531 [ESPComponent](INFO): powering down ESP 2018-09-12T18:13:47.908Z,1536776027.908 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2018-09-12T18:13:48.065Z,1536776028.065 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2018-09-12T18:13:48.108Z,1536776028.108 [Depth_Keller](ERROR): Pressure reading out of range: 2102.507080 decibar 2018-09-12T18:13:48.208Z,1536776028.208 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2 2018-09-12T18:13:48.208Z,1536776028.208 [DAT](INFO): Powering up 2018-09-12T18:13:48.208Z,1536776028.208 [DAT](DEBUG): Initializing DAT. 2018-09-12T18:13:48.239Z,1536776028.239 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2 2018-09-12T18:13:48.403Z,1536776028.403 [DepthRateCalculator](ERROR): Depth measurement is not active 2018-09-12T18:13:48.483Z,1536776028.483 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-09-12T18:13:48.543Z,1536776028.543 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-09-12T18:13:48.655Z,1536776028.655 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2018-09-12T18:13:48.663Z,1536776028.663 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2018-09-12T18:13:48.678Z,1536776028.678 [ElevatorServo](DEBUG): Initializing EZServoServo. 2018-09-12T18:13:48.699Z,1536776028.699 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2018-09-12T18:13:48.714Z,1536776028.714 [MassServo](DEBUG): Initializing EZServoServo. 2018-09-12T18:13:48.719Z,1536776028.719 [MassServo](DEBUG): Initializing MassServo. 2018-09-12T18:13:48.742Z,1536776028.742 [RudderServo](DEBUG): Initializing EZServoServo. 2018-09-12T18:13:48.747Z,1536776028.747 [RudderServo](DEBUG): Initializing RudderServo. 2018-09-12T18:13:48.761Z,1536776028.761 [ThrusterServo](DEBUG): Initializing EZServoServo. 2018-09-12T18:13:48.767Z,1536776028.767 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2018-09-12T18:13:48.812Z,1536776028.812 [CommandLine](FAULT): Scheduling is paused 2018-09-12T18:13:48.812Z,1536776028.812 [CBIT](INFO): Critical error at 20180912T181346 2018-09-12T18:13:48.813Z,1536776028.813 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals 2018-09-12T18:13:49.079Z,1536776029.079 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-09-12T18:13:49.080Z,1536776029.080 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-09-12T18:13:49.307Z,1536776029.307 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-09-12T18:13:49.308Z,1536776029.308 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-09-12T18:13:49.647Z,1536776029.647 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout 2018-09-12T18:13:49.647Z,1536776029.647 [BuoyancyServo](FAULT): Buoyancy failed to initialize 2018-09-12T18:13:49.647Z,1536776029.647 [BuoyancyServo] Communications Fault, FailCount= 1 2018-09-12T18:13:49.647Z,1536776029.647 [BuoyancyServo](ERROR): Communications Fault 2018-09-12T18:13:49.859Z,1536776029.859 [CBIT](ERROR): Communications Fault in component: BuoyancyServo 2018-09-12T18:13:49.935Z,1536776029.935 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-09-12T18:13:49.936Z,1536776029.936 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-09-12T18:13:49.953Z,1536776029.953 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2018-09-12T18:13:49.954Z,1536776029.954 [BuoyancyServo](INFO): Powering down 2018-09-12T18:13:50.303Z,1536776030.303 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-09-12T18:13:50.319Z,1536776030.319 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-09-12T18:13:50.703Z,1536776030.703 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-09-12T18:13:50.719Z,1536776030.719 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-09-12T18:13:51.139Z,1536776031.139 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-09-12T18:13:51.151Z,1536776031.151 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-09-12T18:13:52.022Z,1536776032.022 [CBIT](INFO): Clearing failed state for component BuoyancyServo 2018-09-12T18:13:52.022Z,1536776032.022 [BuoyancyServo] No Fault, FailCount= 1 2018-09-12T18:13:52.405Z,1536776032.405 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2018-09-12T18:13:52.406Z,1536776032.406 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2018-09-12T18:13:52.462Z,1536776032.462 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface 2018-09-12T18:13:52.574Z,1536776032.574 [CTD_Seabird](INFO): Started Seabird LCM interface with command:nohup ./lrauv-framework/onboard/bin/gpctd -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyC6 -b 9600 >& /dev/null & 2018-09-12T18:13:52.640Z,1536776032.640 [Radio_Surface](INFO): Powering down 2018-09-12T18:13:52.765Z,1536776032.765 [CTD_Seabird](INFO): LCM subscribed to channel:seabird_gpctd_t.seabird-gpctd 2018-09-12T18:13:53.214Z,1536776033.214 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface 2018-09-12T18:13:53.214Z,1536776033.214 [CTD_Seabird](INFO): Powering down 2018-09-12T18:14:01.902Z,1536776041.902 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder 2018-09-12T18:14:13.881Z,1536776053.881 [NAL9602](INFO): Powering up NAL9602 2018-09-12T18:14:15.582Z,1536776055.582 [SBIT](IMPORTANT): Beginning Startup BIT 2018-09-12T18:14:15.587Z,1536776055.587 [CBIT](IMPORTANT): Beginning ground fault scan 2018-09-12T18:14:24.869Z,1536776064.869 [NAL9602](INFO): NAL9602 initialized 2018-09-12T18:14:26.998Z,1536776066.998 [CBIT](IMPORTANT): Ground fault detected mA: CHAN A0 (Batt): -0.018441 CHAN A1 (24V): 0.181239 CHAN A2 (12V): -0.004739 CHAN A3 (5V): -0.002736 CHAN B0 (3.3V): -0.001048 CHAN B1 (3.15aV): -0.001090 CHAN B2 (3.15bV): -0.001255 CHAN B3 (GND): -0.000753 OPEN: 0.004962 Full Scale Calc: 4.765 mA, -1.589 mA 2018-09-12T18:14:53.532Z,1536776093.532 [DAT](FAULT): failed to initialize; deviceResponse_ loaded: 00:00:06.0066 , LVL= 21296, 27041, 21522, 19667, PHS= 1.709, 1.435, 2.450, RAW= 194.9,-65.2 Rx Time:00:00:06.0066 bearing request TX time:00:00:07.6090 user:1>, available: 2018-09-12T18:14:53.532Z,1536776093.532 [DAT] Communications Fault, FailCount= 1 2018-09-12T18:14:53.533Z,1536776093.533 [DAT](ERROR): Communications Fault 2018-09-12T18:14:53.606Z,1536776093.606 [CBIT](ERROR): Communications Fault in component: DAT 2018-09-12T18:14:53.934Z,1536776093.934 [DAT](INFO): Powering down 2018-09-12T18:14:54.830Z,1536776094.830 [CBIT](INFO): Clearing failed state for component DAT 2018-09-12T18:14:54.830Z,1536776094.830 [DAT] No Fault, FailCount= 1 2018-09-12T18:14:57.128Z,1536776097.128 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2 2018-09-12T18:14:57.128Z,1536776097.128 [DAT](INFO): Powering up 2018-09-12T18:14:57.128Z,1536776097.128 [DAT](DEBUG): Initializing DAT. 2018-09-12T18:14:57.196Z,1536776097.196 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2 2018-09-12T18:15:09.337Z,1536776109.337 [SBIT](IMPORTANT): SBIT PASSED 2018-09-12T18:15:09.408Z,1536776109.408 [CommandLine](IMPORTANT): got command configSet list 2018-09-12T18:15:09.408Z,1536776109.408 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2018-09-12T18:15:09.412Z,1536776109.412 [CommandLine](IMPORTANT): CBIT.gf24Offset=180 microampere; 2018-09-12T18:15:09.412Z,1536776109.412 [CommandLine](IMPORTANT): DataOverHttps.connectionTimeout=60 second; 2018-09-12T18:15:09.413Z,1536776109.413 [CommandLine](IMPORTANT): DataOverHttps.period=30 second; 2018-09-12T18:15:09.413Z,1536776109.413 [CommandLine](IMPORTANT): DataOverHttps.timeout=1 minute; 2018-09-12T18:15:09.413Z,1536776109.413 [CommandLine](IMPORTANT): Express none ESPComponent.sample_number; 2018-09-12T18:15:09.413Z,1536776109.413 [CommandLine](IMPORTANT): Express none ESPComponent.sampling; 2018-09-12T18:15:09.413Z,1536776109.413 [CommandLine](IMPORTANT): Express linearApproximation depth 5.000000 meter; 2018-09-12T18:15:09.413Z,1536776109.413 [CommandLine](IMPORTANT): Express linearApproximation latitude 0.005000 angular_degree; 2018-09-12T18:15:09.413Z,1536776109.413 [CommandLine](IMPORTANT): Express linearApproximation longitude 0.005000 angular_degree; 2018-09-12T18:15:09.414Z,1536776109.414 [CommandLine](IMPORTANT): RDI_Pathfinder.loadAtStartup=0 bool; 2018-09-12T18:15:09.731Z,1536776109.731 [MissionManager](IMPORTANT): Started mission Startup 2018-09-12T18:15:09.731Z,1536776109.731 [Startup] Running Loop=1 2018-09-12T18:15:09.732Z,1536776109.732 [Startup](DEBUG): Aggregate::initialize Startup 2018-09-12T18:15:09.732Z,1536776109.732 [Startup:A.GoToSurface] Running Loop=1 2018-09-12T18:15:09.732Z,1536776109.732 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2018-09-12T18:15:09.732Z,1536776109.732 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2018-09-12T18:15:09.733Z,1536776109.733 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2018-09-12T18:15:09.733Z,1536776109.733 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2018-09-12T18:15:09.734Z,1536776109.734 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2018-09-12T18:15:09.734Z,1536776109.734 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2018-09-12T18:15:10.122Z,1536776110.122 [ElevatorOffsetCalculator](INFO): New estimator for commanded vars: speed 1.00 m/s, pitch 30.00 deg, mass-position -35.00 mm (1 active estimators). 2018-09-12T18:15:11.864Z,1536776111.864 [DAT](INFO): setting local address to 6 2018-09-12T18:15:12.241Z,1536776112.241 [DAT](INFO): set local address to 6 2018-09-12T18:16:11.446Z,1536776171.446 [RDI_Pathfinder](ERROR): only read 3 of 5 data items 2018-09-12T18:16:11.447Z,1536776171.447 [RDI_Pathfinder](ERROR): Failed to parse: :BI,-32768,-32768,-3278,V 2018-09-12T18:16:47.058Z,1536776207.058 [DeadReckonUsingMultipleVelocitySources](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2018-09-12T18:16:47.058Z,1536776207.058 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1 2018-09-12T18:16:47.058Z,1536776207.058 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2018-09-12T18:16:47.060Z,1536776207.060 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2018-09-12T18:16:47.060Z,1536776207.060 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1 2018-09-12T18:16:47.060Z,1536776207.060 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault 2018-09-12T18:16:47.148Z,1536776207.148 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2018-09-12T18:16:47.148Z,1536776207.148 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator 2018-09-12T18:16:47.530Z,1536776207.530 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2018-09-12T18:16:47.530Z,1536776207.530 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1 2018-09-12T18:16:47.531Z,1536776207.531 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator 2018-09-12T18:16:47.531Z,1536776207.531 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1 2018-09-12T18:16:47.891Z,1536776207.891 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component. 2018-09-12T18:16:47.892Z,1536776207.892 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s. 2018-09-12T18:16:47.892Z,1536776207.892 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s. 2018-09-12T18:16:47.892Z,1536776207.892 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component. 2018-09-12T18:16:47.893Z,1536776207.893 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s. 2018-09-12T18:16:47.893Z,1536776207.893 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s. 2018-09-12T18:16:48.285Z,1536776208.285 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 1.2 s old, using for 20.0 s. 2018-09-12T18:16:48.662Z,1536776208.662 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 1.6 s old, using for 20.0 s. 2018-09-12T18:16:49.094Z,1536776209.094 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 2.0 s old, using for 20.0 s. 2018-09-12T18:16:49.470Z,1536776209.470 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 2.4 s old, using for 20.0 s. 2018-09-12T18:16:49.854Z,1536776209.854 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 2.8 s old, using for 20.0 s. 2018-09-12T18:16:50.259Z,1536776210.259 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 3.2 s old, using for 20.0 s. 2018-09-12T18:16:50.678Z,1536776210.678 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 3.6 s old, using for 20.0 s. 2018-09-12T18:16:51.083Z,1536776211.083 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 4.0 s old, using for 20.0 s. 2018-09-12T18:16:51.465Z,1536776211.465 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 4.4 s old, using for 20.0 s. 2018-09-12T18:16:51.859Z,1536776211.859 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 4.8 s old, using for 20.0 s. 2018-09-12T18:16:52.255Z,1536776212.255 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 5.2 s old, using for 20.0 s. 2018-09-12T18:16:52.656Z,1536776212.656 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 5.6 s old, using for 20.0 s. 2018-09-12T18:16:53.045Z,1536776213.045 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 6.0 s old, using for 20.0 s. 2018-09-12T18:16:53.470Z,1536776213.470 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 6.4 s old, using for 20.0 s. 2018-09-12T18:16:53.889Z,1536776213.889 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 6.8 s old, using for 20.0 s. 2018-09-12T18:16:54.254Z,1536776214.254 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 7.2 s old, using for 20.0 s. 2018-09-12T18:16:54.688Z,1536776214.688 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 7.6 s old, using for 20.0 s. 2018-09-12T18:16:55.047Z,1536776215.047 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 8.0 s old, using for 20.0 s. 2018-09-12T18:16:55.439Z,1536776215.439 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 8.4 s old, using for 20.0 s. 2018-09-12T18:16:55.861Z,1536776215.861 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 8.8 s old, using for 20.0 s. 2018-09-12T18:16:56.248Z,1536776216.248 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 9.2 s old, using for 20.0 s. 2018-09-12T18:16:56.654Z,1536776216.654 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 9.6 s old, using for 20.0 s. 2018-09-12T18:16:57.059Z,1536776217.059 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 10.0 s old, using for 20.0 s. 2018-09-12T18:16:57.454Z,1536776217.454 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 10.4 s old, using for 20.0 s. 2018-09-12T18:16:57.860Z,1536776217.860 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 10.8 s old, using for 20.0 s. 2018-09-12T18:16:58.250Z,1536776218.250 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 11.2 s old, using for 20.0 s. 2018-09-12T18:16:58.665Z,1536776218.665 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 11.6 s old, using for 20.0 s. 2018-09-12T18:16:59.067Z,1536776219.067 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 12.0 s old, using for 20.0 s. 2018-09-12T18:16:59.470Z,1536776219.470 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 12.4 s old, using for 20.0 s. 2018-09-12T18:16:59.869Z,1536776219.869 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 12.8 s old, using for 20.0 s. 2018-09-12T18:17:00.260Z,1536776220.260 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 13.2 s old, using for 20.0 s. 2018-09-12T18:17:00.656Z,1536776220.656 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 13.6 s old, using for 20.0 s. 2018-09-12T18:17:01.093Z,1536776221.093 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 14.0 s old, using for 20.0 s. 2018-09-12T18:17:01.474Z,1536776221.474 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 14.4 s old, using for 20.0 s. 2018-09-12T18:17:01.859Z,1536776221.859 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 14.8 s old, using for 20.0 s. 2018-09-12T18:17:02.265Z,1536776222.265 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 15.2 s old, using for 20.0 s. 2018-09-12T18:17:02.656Z,1536776222.656 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 15.6 s old, using for 20.0 s. 2018-09-12T18:17:03.066Z,1536776223.066 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 16.0 s old, using for 20.0 s. 2018-09-12T18:17:03.436Z,1536776223.436 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 16.4 s old, using for 20.0 s. 2018-09-12T18:17:03.868Z,1536776223.868 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 16.8 s old, using for 20.0 s. 2018-09-12T18:17:04.269Z,1536776224.269 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 17.2 s old, using for 20.0 s. 2018-09-12T18:17:04.680Z,1536776224.680 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 17.6 s old, using for 20.0 s. 2018-09-12T18:17:05.073Z,1536776225.073 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 18.0 s old, using for 20.0 s. 2018-09-12T18:17:05.464Z,1536776225.464 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 18.4 s old, using for 20.0 s. 2018-09-12T18:17:05.872Z,1536776225.872 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 18.8 s old, using for 20.0 s. 2018-09-12T18:17:06.242Z,1536776226.242 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 19.2 s old, using for 20.0 s. 2018-09-12T18:17:06.664Z,1536776226.664 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 19.6 s old, using for 20.0 s. 2018-09-12T18:17:07.045Z,1536776227.045 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 20.0 s old, using for 20.0 s. 2018-09-12T18:17:35.077Z,1536776255.077 [Startup:StartupSatComms] Running Loop=1 2018-09-12T18:17:35.077Z,1536776255.077 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2018-09-12T18:17:35.077Z,1536776255.077 [Startup:StartupSatComms:A] Running Loop=1 2018-09-12T18:17:35.416Z,1536776255.416 [Radio_Surface](INFO): Powering up 2018-09-12T18:17:35.467Z,1536776255.467 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2018-09-12T18:18:32.748Z,1536776312.748 [NAL9602](INFO): SBD MO Status=0, MOMSN=49384, MT Status=0, MTMSN=0 2018-09-12T18:18:32.748Z,1536776312.748 [NAL9602](INFO): No messages in MT queue 2018-09-12T18:18:35.192Z,1536776315.192 [Startup:StartupSatComms:A](INFO): Timed out from 2018-09-12T18:17:35.1Z 2018-09-12T18:18:35.192Z,1536776315.192 [Startup:StartupSatComms:A] Stopped 2018-09-12T18:18:35.192Z,1536776315.192 [Startup:StartupSatComms:B] Running Loop=1 2018-09-12T18:18:35.587Z,1536776315.587 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2018-09-12T18:19:03.930Z,1536776343.930 [NAL9602](INFO): SBD MO Status=1, MOMSN=49385, MT Status=0, MTMSN=0 2018-09-12T18:19:03.985Z,1536776343.985 [NAL9602](INFO): Sent 18 bytes from file Logs/20180912T171743/Courier0016.lzma 2018-09-12T18:19:03.985Z,1536776343.985 [NAL9602](INFO): Packets left to send: 0 2018-09-12T18:19:03.987Z,1536776343.987 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180912T171743/Courier0016.lzma.parts/0000.sbd 2018-09-12T18:19:03.987Z,1536776343.987 [NAL9602](DEBUG): Completed sending Logs/20180912T171743/Courier0016.lzma 2018-09-12T18:19:10.510Z,1536776350.510 [NAL9602](INFO): SBD MO Status=1, MOMSN=49386, MT Status=0, MTMSN=0 2018-09-12T18:19:10.563Z,1536776350.563 [NAL9602](INFO): Sent 99 bytes from file Logs/20180912T181335/Courier0000.lzma 2018-09-12T18:19:10.563Z,1536776350.563 [NAL9602](INFO): Packets left to send: 0 2018-09-12T18:19:10.565Z,1536776350.565 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180912T181335/Courier0000.lzma.parts/0000.sbd 2018-09-12T18:19:10.565Z,1536776350.565 [NAL9602](DEBUG): Completed sending Logs/20180912T181335/Courier0000.lzma 2018-09-12T18:19:27.978Z,1536776367.978 [NAL9602](INFO): SBD MO Status=1, MOMSN=49387, MT Status=0, MTMSN=0 2018-09-12T18:19:28.041Z,1536776368.041 [NAL9602](INFO): Sent 18 bytes from file Logs/20180912T171743/Express0017.lzma 2018-09-12T18:19:28.041Z,1536776368.041 [NAL9602](INFO): Packets left to send: 0 2018-09-12T18:19:28.043Z,1536776368.043 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180912T171743/Express0017.lzma.parts/0000.sbd 2018-09-12T18:19:28.043Z,1536776368.043 [NAL9602](DEBUG): Completed sending Logs/20180912T171743/Express0017.lzma 2018-09-12T18:19:35.502Z,1536776375.502 [Startup:StartupSatComms:B](INFO): Timed out from 2018-09-12T18:18:35.2Z 2018-09-12T18:19:35.502Z,1536776375.502 [Startup:StartupSatComms:B] Stopped 2018-09-12T18:19:35.502Z,1536776375.502 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2018-09-12T18:19:35.502Z,1536776375.502 [Startup:StartupSatComms] Stopped 2018-09-12T18:19:35.503Z,1536776375.503 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2018-09-12T18:19:35.504Z,1536776375.504 [Startup](INFO): Completed Startup 2018-09-12T18:19:35.504Z,1536776375.504 [MissionManager](INFO): Startup is completed. 2018-09-12T18:19:35.504Z,1536776375.504 [MissionManager](INFO): Uninitializing Mission Startup 2018-09-12T18:19:35.504Z,1536776375.504 [Startup] Stopped 2018-09-12T18:19:35.504Z,1536776375.504 [Startup](DEBUG): Aggregate::uninitialize Startup 2018-09-12T18:19:35.505Z,1536776375.505 [Startup:A.GoToSurface] Stopped 2018-09-12T18:19:35.505Z,1536776375.505 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2018-09-12T18:19:35.914Z,1536776375.914 [MissionManager](IMPORTANT): Started mission Default 2018-09-12T18:19:35.914Z,1536776375.914 [Default] Running Loop=1 2018-09-12T18:19:35.914Z,1536776375.914 [Default](DEBUG): Aggregate::initialize Default 2018-09-12T18:19:35.914Z,1536776375.914 [Default:B.GoToSurface] Running Loop=1 2018-09-12T18:19:35.915Z,1536776375.915 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2018-09-12T18:19:35.915Z,1536776375.915 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2018-09-12T18:19:35.915Z,1536776375.915 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2018-09-12T18:19:35.916Z,1536776375.916 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2018-09-12T18:19:35.916Z,1536776375.916 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2018-09-12T18:19:35.917Z,1536776375.917 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2018-09-12T18:19:35.917Z,1536776375.917 [Default:A.Wait] Running Loop=1 2018-09-12T18:19:35.917Z,1536776375.917 [Default:A.Wait](DEBUG): Initialize Wait Component. 2018-09-12T18:19:37.462Z,1536776377.462 [NAL9602](INFO): SBD MO Status=1, MOMSN=49388, MT Status=0, MTMSN=0 2018-09-12T18:19:37.511Z,1536776377.511 [NAL9602](INFO): Sent 332 bytes from file Logs/20180912T181335/Express0001.lzma 2018-09-12T18:19:37.511Z,1536776377.511 [NAL9602](INFO): Packets left to send: 3 2018-09-12T18:19:37.513Z,1536776377.513 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180912T181335/Express0001.lzma.parts/0003.sbd 2018-09-12T18:19:47.918Z,1536776387.918 [DeadReckonUsingMultipleVelocitySources](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2018-09-12T18:19:47.918Z,1536776387.918 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2 2018-09-12T18:19:47.918Z,1536776387.918 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2018-09-12T18:19:47.924Z,1536776387.924 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2018-09-12T18:19:47.924Z,1536776387.924 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 2 2018-09-12T18:19:47.924Z,1536776387.924 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault 2018-09-12T18:19:47.950Z,1536776387.950 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2018-09-12T18:19:47.951Z,1536776387.951 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator 2018-09-12T18:19:48.327Z,1536776388.327 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2018-09-12T18:19:48.327Z,1536776388.327 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2 2018-09-12T18:19:48.328Z,1536776388.328 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator 2018-09-12T18:19:48.328Z,1536776388.328 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 2 2018-09-12T18:19:48.692Z,1536776388.692 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component. 2018-09-12T18:19:48.692Z,1536776388.692 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s. 2018-09-12T18:19:48.692Z,1536776388.692 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s. 2018-09-12T18:19:48.693Z,1536776388.693 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component. 2018-09-12T18:19:48.693Z,1536776388.693 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s. 2018-09-12T18:19:48.694Z,1536776388.694 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s. 2018-09-12T18:19:49.105Z,1536776389.105 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 1.2 s old, using for 20.0 s. 2018-09-12T18:19:49.125Z,1536776389.125 [Default:A.Wait](INFO): Done Waiting. 2018-09-12T18:19:49.125Z,1536776389.125 [Default:A.Wait] Stopped 2018-09-12T18:19:49.125Z,1536776389.125 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2018-09-12T18:19:49.498Z,1536776389.498 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 1.6 s old, using for 20.0 s. 2018-09-12T18:19:49.502Z,1536776389.502 [Default:CheckIn] Running Loop=1 2018-09-12T18:19:49.502Z,1536776389.502 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-09-12T18:19:49.502Z,1536776389.502 [Default:CheckIn:Read_GPS] Running Loop=1 2018-09-12T18:19:49.905Z,1536776389.905 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 2.0 s old, using for 20.0 s. 2018-09-12T18:19:49.909Z,1536776389.909 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2018-09-12T18:19:50.323Z,1536776390.323 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 2.4 s old, using for 20.0 s. 2018-09-12T18:19:50.700Z,1536776390.700 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 2.8 s old, using for 20.0 s. 2018-09-12T18:19:51.114Z,1536776391.114 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 3.2 s old, using for 20.0 s. 2018-09-12T18:19:51.505Z,1536776391.505 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 3.6 s old, using for 20.0 s. 2018-09-12T18:19:51.913Z,1536776391.913 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 4.0 s old, using for 20.0 s. 2018-09-12T18:19:52.299Z,1536776392.299 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 4.4 s old, using for 20.0 s. 2018-09-12T18:19:52.733Z,1536776392.733 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 4.8 s old, using for 20.0 s. 2018-09-12T18:19:53.159Z,1536776393.159 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 5.2 s old, using for 20.0 s. 2018-09-12T18:19:53.509Z,1536776393.509 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 5.6 s old, using for 20.0 s. 2018-09-12T18:19:53.910Z,1536776393.910 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 6.0 s old, using for 20.0 s. 2018-09-12T18:19:54.302Z,1536776394.302 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 6.4 s old, using for 20.0 s. 2018-09-12T18:19:54.722Z,1536776394.722 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 6.8 s old, using for 20.0 s. 2018-09-12T18:19:55.109Z,1536776395.109 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 7.2 s old, using for 20.0 s. 2018-09-12T18:19:55.500Z,1536776395.500 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 7.6 s old, using for 20.0 s. 2018-09-12T18:19:55.952Z,1536776395.952 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 8.0 s old, using for 20.0 s. 2018-09-12T18:19:56.336Z,1536776396.336 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 8.4 s old, using for 20.0 s. 2018-09-12T18:19:56.760Z,1536776396.760 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 8.8 s old, using for 20.0 s. 2018-09-12T18:19:57.146Z,1536776397.146 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 9.2 s old, using for 20.0 s. 2018-09-12T18:19:57.503Z,1536776397.503 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 9.6 s old, using for 20.0 s. 2018-09-12T18:19:57.914Z,1536776397.914 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 10.0 s old, using for 20.0 s. 2018-09-12T18:19:58.286Z,1536776398.286 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 10.4 s old, using for 20.0 s. 2018-09-12T18:19:58.717Z,1536776398.717 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 10.8 s old, using for 20.0 s. 2018-09-12T18:19:59.120Z,1536776399.120 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 11.2 s old, using for 20.0 s. 2018-09-12T18:19:59.521Z,1536776399.521 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 11.6 s old, using for 20.0 s. 2018-09-12T18:19:59.886Z,1536776399.886 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 12.0 s old, using for 20.0 s. 2018-09-12T18:20:00.313Z,1536776400.313 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 12.4 s old, using for 20.0 s. 2018-09-12T18:20:00.687Z,1536776400.687 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 12.8 s old, using for 20.0 s. 2018-09-12T18:20:01.125Z,1536776401.125 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 13.2 s old, using for 20.0 s. 2018-09-12T18:20:01.490Z,1536776401.490 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 13.6 s old, using for 20.0 s. 2018-09-12T18:20:01.921Z,1536776401.921 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 14.0 s old, using for 20.0 s. 2018-09-12T18:20:02.320Z,1536776402.320 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 14.4 s old, using for 20.0 s. 2018-09-12T18:20:02.761Z,1536776402.761 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 14.8 s old, using for 20.0 s. 2018-09-12T18:20:03.092Z,1536776403.092 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 15.2 s old, using for 20.0 s. 2018-09-12T18:20:03.491Z,1536776403.491 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 15.6 s old, using for 20.0 s. 2018-09-12T18:20:03.920Z,1536776403.920 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 16.0 s old, using for 20.0 s. 2018-09-12T18:20:04.287Z,1536776404.287 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 16.4 s old, using for 20.0 s. 2018-09-12T18:20:04.737Z,1536776404.737 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 16.8 s old, using for 20.0 s. 2018-09-12T18:20:05.116Z,1536776405.116 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 17.2 s old, using for 20.0 s. 2018-09-12T18:20:05.523Z,1536776405.523 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 17.6 s old, using for 20.0 s. 2018-09-12T18:20:05.906Z,1536776405.906 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 18.0 s old, using for 20.0 s. 2018-09-12T18:20:06.296Z,1536776406.296 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 18.4 s old, using for 20.0 s. 2018-09-12T18:20:06.730Z,1536776406.730 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 18.8 s old, using for 20.0 s. 2018-09-12T18:20:07.117Z,1536776407.117 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 19.2 s old, using for 20.0 s. 2018-09-12T18:20:07.507Z,1536776407.507 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 19.6 s old, using for 20.0 s. 2018-09-12T18:20:47.068Z,1536776447.068 [NAL9602](INFO): GPS fix at 20180912T182003: (36.813026, -122.192220) 2018-09-12T18:20:47.141Z,1536776447.141 [Default:CheckIn:Read_GPS] Stopped 2018-09-12T18:20:47.141Z,1536776447.141 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-09-12T18:20:47.540Z,1536776447.540 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2018-09-12T18:21:11.374Z,1536776471.374 [NAL9602](INFO): SBD MO Status=1, MOMSN=49389, MT Status=0, MTMSN=0 2018-09-12T18:21:11.427Z,1536776471.427 [NAL9602](INFO): Sent 305 bytes from file Logs/20180912T181335/Courier0004.lzma 2018-09-12T18:21:11.427Z,1536776471.427 [NAL9602](INFO): Packets left to send: 0 2018-09-12T18:21:11.429Z,1536776471.429 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180912T181335/Courier0004.lzma.parts/0000.sbd 2018-09-12T18:21:11.429Z,1536776471.429 [NAL9602](DEBUG): Completed sending Logs/20180912T181335/Courier0004.lzma 2018-09-12T18:21:22.751Z,1536776482.751 [NAL9602](INFO): SBD MO Status=1, MOMSN=49390, MT Status=0, MTMSN=0 2018-09-12T18:21:22.807Z,1536776482.807 [NAL9602](INFO): Sent 332 bytes from file Logs/20180912T181335/Express0001.lzma 2018-09-12T18:21:22.807Z,1536776482.807 [NAL9602](INFO): Packets left to send: 2 2018-09-12T18:21:22.808Z,1536776482.808 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180912T181335/Express0001.lzma.parts/0002.sbd 2018-09-12T18:21:37.799Z,1536776497.799 [NAL9602](INFO): SBD MO Status=1, MOMSN=49391, MT Status=0, MTMSN=0 2018-09-12T18:21:37.863Z,1536776497.863 [NAL9602](INFO): Sent 332 bytes from file Logs/20180912T181335/Express0001.lzma 2018-09-12T18:21:37.863Z,1536776497.863 [NAL9602](INFO): Packets left to send: 1 2018-09-12T18:21:37.865Z,1536776497.865 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180912T181335/Express0001.lzma.parts/0001.sbd 2018-09-12T18:21:53.725Z,1536776513.725 [NAL9602](INFO): SBD MO Status=1, MOMSN=49392, MT Status=0, MTMSN=0 2018-09-12T18:21:53.779Z,1536776513.779 [NAL9602](INFO): Sent 102 bytes from file Logs/20180912T181335/Express0001.lzma 2018-09-12T18:21:53.779Z,1536776513.779 [NAL9602](INFO): Packets left to send: 0 2018-09-12T18:21:53.780Z,1536776513.780 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180912T181335/Express0001.lzma.parts/0000.sbd 2018-09-12T18:21:53.781Z,1536776513.781 [NAL9602](DEBUG): Completed sending Logs/20180912T181335/Express0001.lzma 2018-09-12T18:22:06.258Z,1536776526.258 [NAL9602](INFO): SBD MO Status=1, MOMSN=49393, MT Status=0, MTMSN=0 2018-09-12T18:22:06.311Z,1536776526.311 [NAL9602](INFO): Sent 210 bytes from file Logs/20180912T181335/Express0005.lzma 2018-09-12T18:22:06.311Z,1536776526.311 [NAL9602](INFO): Packets left to send: 0 2018-09-12T18:22:06.313Z,1536776526.313 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180912T181335/Express0005.lzma.parts/0000.sbd 2018-09-12T18:22:06.313Z,1536776526.313 [NAL9602](DEBUG): Completed sending Logs/20180912T181335/Express0005.lzma 2018-09-12T18:22:16.262Z,1536776536.262 [NAL9602](INFO): SBD MO Status=0, MOMSN=49394, MT Status=0, MTMSN=0 2018-09-12T18:22:16.371Z,1536776536.371 [Default:CheckIn:Read_Iridium] Stopped 2018-09-12T18:22:16.371Z,1536776536.371 [Default:CheckIn:C.Wait] Running Loop=1 2018-09-12T18:22:16.371Z,1536776536.371 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-09-12T18:22:47.053Z,1536776567.053 [NAL9602](INFO): Powering down 2018-09-12T18:27:17.119Z,1536776837.119 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-09-12T18:27:17.120Z,1536776837.120 [Default:CheckIn:C.Wait] Stopped 2018-09-12T18:27:17.120Z,1536776837.120 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-09-12T18:27:17.120Z,1536776837.120 [Default:CheckIn:D] Running Loop=1 2018-09-12T18:27:17.510Z,1536776837.510 [Default:CheckIn:D] Stopped 2018-09-12T18:27:17.510Z,1536776837.510 [Default:CheckIn:E] Running Loop=1 2018-09-12T18:27:17.919Z,1536776837.919 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 7.693223 min 2018-09-12T18:27:17.921Z,1536776837.921 [Default:CheckIn:E] Stopped 2018-09-12T18:27:17.921Z,1536776837.921 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-09-12T18:27:17.921Z,1536776837.921 [Default:CheckIn] Stopped 2018-09-12T18:27:17.922Z,1536776837.922 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-09-12T18:27:17.922Z,1536776837.922 [Default:CheckIn](INFO): Running loop #2 2018-09-12T18:27:17.922Z,1536776837.922 [Default:CheckIn] Running Loop=2 2018-09-12T18:27:17.922Z,1536776837.922 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-09-12T18:27:17.922Z,1536776837.922 [Default:CheckIn:Read_GPS] Running Loop=1 2018-09-12T18:27:18.654Z,1536776838.654 [NAL9602](INFO): Powering up 2018-09-12T18:27:29.852Z,1536776849.852 [NAL9602](INFO): NAL9602 initialized 2018-09-12T18:27:43.863Z,1536776863.863 [NAL9602](IMPORTANT): SBD MO Status=0, MOMSN=49395, MT Status=1, MTMSN=1540 2018-09-12T18:27:43.863Z,1536776863.863 [NAL9602](INFO): Data available in MT queue 2018-09-12T18:27:44.340Z,1536776864.340 [NAL9602](INFO): Received command:restart sys 2018-09-12T18:27:44.424Z,1536776864.424 [CommandLine](IMPORTANT): got command restart system 2018-09-12T18:27:46.755Z,1536776866.755 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2018-09-12T18:27:46.755Z,1536776866.755 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-09-12T18:27:46.923Z,1536776866.923 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2018-09-12T18:27:46.923Z,1536776866.923 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-09-12T18:27:46.924Z,1536776866.924 [CommandLine](INFO): Join timeout helper Thread ID is 959 2018-09-12T18:27:46.924Z,1536776866.924 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2018-09-12T18:27:46.924Z,1536776866.924 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-09-12T18:27:46.925Z,1536776866.925 [NavChartDb](INFO): Join timeout helper Thread ID is 960 2018-09-12T18:27:47.127Z,1536776867.127 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2018-09-12T18:27:47.127Z,1536776867.127 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-09-12T18:27:47.143Z,1536776867.143 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2018-09-12T18:27:47.143Z,1536776867.143 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2018-09-12T18:27:47.144Z,1536776867.144 [Radio_Surface](INFO): Join timeout helper Thread ID is 961 2018-09-12T18:27:47.343Z,1536776867.343 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2018-09-12T18:27:47.343Z,1536776867.343 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2018-09-12T18:27:47.363Z,1536776867.363 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler 2018-09-12T18:27:47.363Z,1536776867.363 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2018-09-12T18:27:47.363Z,1536776867.363 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 962 2018-09-12T18:27:47.567Z,1536776867.567 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread. 2018-09-12T18:27:47.567Z,1536776867.567 [WetLabsBB2FL](INFO): Powering down 2018-09-12T18:27:47.568Z,1536776867.568 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2018-09-12T18:27:47.575Z,1536776867.575 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler 2018-09-12T18:27:47.575Z,1536776867.575 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2018-09-12T18:27:47.575Z,1536776867.575 [CTD_Seabird](INFO): Join timeout helper Thread ID is 963 2018-09-12T18:27:47.959Z,1536776867.959 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread. 2018-09-12T18:27:48.065Z,1536776868.065 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface 2018-09-12T18:27:48.065Z,1536776868.065 [CTD_Seabird](INFO): Powering down 2018-09-12T18:27:48.067Z,1536776868.067 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2018-09-12T18:27:48.080Z,1536776868.080 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2018-09-12T18:27:48.080Z,1536776868.080 [logger ThreadHandler](INFO): Thread cancelled. 2018-09-12T18:27:48.080Z,1536776868.080 [logger](INFO): Join timeout helper Thread ID is 965 2018-09-12T18:27:48.107Z,1536776868.107 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2018-09-12T18:27:48.107Z,1536776868.107 [logger ThreadHandler](INFO): Thread cancelled. 2018-09-12T18:27:48.120Z,1536776868.120 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2018-09-12T18:27:48.120Z,1536776868.120 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-09-12T18:27:48.120Z,1536776868.120 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2018-09-12T18:27:48.120Z,1536776868.120 [controlThread ThreadHandler](INFO): Thread cancelled. 2018-09-12T18:27:48.121Z,1536776868.121 [controlThread](INFO): Join timeout helper Thread ID is 966 2018-09-12T18:27:48.227Z,1536776868.227 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2018-09-12T18:27:48.227Z,1536776868.227 [controlThread](DEBUG): Uninitializing ControlThread 2018-09-12T18:27:48.230Z,1536776868.230 [AHRS_M2](INFO): Powering down 2018-09-12T18:27:48.300Z,1536776868.300 [NAL9602](INFO): Powering down 2018-09-12T18:27:48.371Z,1536776868.371 [RDI_Pathfinder](INFO): Powering down 2018-09-12T18:27:48.372Z,1536776868.372 [DAT](INFO): Powering down 2018-09-12T18:27:48.492Z,1536776868.492 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2018-09-12T18:27:48.493Z,1536776868.493 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2018-09-12T18:27:48.494Z,1536776868.494 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2018-09-12T18:27:48.495Z,1536776868.495 [MissionManager](INFO): Uninitializing Mission Default 2018-09-12T18:27:48.495Z,1536776868.495 [Default] Stopped 2018-09-12T18:27:48.495Z,1536776868.495 [Default](DEBUG): Aggregate::uninitialize Default 2018-09-12T18:27:48.495Z,1536776868.495 [Default:B.GoToSurface] Stopped 2018-09-12T18:27:48.495Z,1536776868.495 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2018-09-12T18:27:48.496Z,1536776868.496 [Default:CheckIn] Stopped 2018-09-12T18:27:48.496Z,1536776868.496 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-09-12T18:27:48.496Z,1536776868.496 [Default:CheckIn:Read_GPS] Stopped 2018-09-12T18:27:48.500Z,1536776868.500 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2018-09-12T18:27:48.500Z,1536776868.500 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2018-09-12T18:27:48.501Z,1536776868.501 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2018-09-12T18:27:48.501Z,1536776868.501 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2018-09-12T18:27:48.501Z,1536776868.501 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2018-09-12T18:27:48.502Z,1536776868.502 [BuoyancyServo](INFO): Powering down 2018-09-12T18:27:48.515Z,1536776868.515 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2018-09-12T18:27:48.515Z,1536776868.515 [ElevatorServo](INFO): Powering down 2018-09-12T18:27:48.516Z,1536776868.516 [MassServo](DEBUG): Uninitialize Mass Servo. 2018-09-12T18:27:48.516Z,1536776868.516 [MassServo](INFO): Powering down 2018-09-12T18:27:48.517Z,1536776868.517 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2018-09-12T18:27:48.517Z,1536776868.517 [RudderServo](INFO): Powering down 2018-09-12T18:27:48.518Z,1536776868.518 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2018-09-12T18:27:48.519Z,1536776868.519 [ThrusterServo](INFO): Powering down 2018-09-12T18:27:48.520Z,1536776868.520 [SBIT](DEBUG): Uninitialize SBIT Component. 2018-09-12T18:27:48.520Z,1536776868.520 [IBIT](DEBUG): Uninitialize IBIT Component. 2018-09-12T18:27:48.520Z,1536776868.520 [CBIT](DEBUG): Uninitialize CBIT Component. 2018-09-12T18:27:48.521Z,1536776868.521 [controlThread ThreadHandler](INFO): Thread cancelled. 2018-09-12T18:27:48.566Z,1536776868.566 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2018-09-12T18:27:48.572Z,1536776868.572 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2018-09-12T18:27:48.660Z,1536776868.660 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2018-09-12T18:27:48.723Z,1536776868.723 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-09-12T18:27:48.795Z,1536776868.795 [logger ThreadHandler](INFO): Thread cancelled.