2018-05-15T18:00:49.222Z,1526407249.222 [Supervisor](DEBUG): Initializing supervisor. 2018-05-15T18:00:49.225Z,1526407249.225 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2018-05-15T18:00:49.226Z,1526407249.226 [SyncHandler](INFO): Protected caller Thread ID is 7638 2018-05-15T18:00:49.226Z,1526407249.226 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2018-05-15T18:00:49.227Z,1526407249.227 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2018-05-15T18:00:49.227Z,1526407249.227 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 7639 2018-05-15T18:00:49.231Z,1526407249.231 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2018-05-15T18:00:49.243Z,1526407249.243 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2018-05-15T18:00:49.244Z,1526407249.244 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2018-05-15T18:00:49.244Z,1526407249.244 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 7640 2018-05-15T18:00:49.245Z,1526407249.245 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2018-05-15T18:00:49.246Z,1526407249.246 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2018-05-15T18:00:49.247Z,1526407249.247 [logger ThreadHandler](INFO): Protected caller Thread ID is 7641 2018-05-15T18:00:49.249Z,1526407249.249 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2018-05-15T18:00:49.249Z,1526407249.249 [Supervisor](INFO): Looking for Config files in directory: Config/ 2018-05-15T18:00:49.251Z,1526407249.251 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2018-05-15T18:00:49.345Z,1526407249.345 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2018-05-15T18:00:49.346Z,1526407249.346 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2018-05-15T18:00:49.443Z,1526407249.443 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2018-05-15T18:00:49.444Z,1526407249.444 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2018-05-15T18:00:49.632Z,1526407249.632 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2018-05-15T18:00:49.633Z,1526407249.633 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2018-05-15T18:00:49.932Z,1526407249.932 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2018-05-15T18:00:49.932Z,1526407249.932 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2018-05-15T18:00:50.245Z,1526407250.245 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2018-05-15T18:00:50.246Z,1526407250.246 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2018-05-15T18:00:50.678Z,1526407250.678 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2018-05-15T18:00:50.679Z,1526407250.679 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2018-05-15T18:00:51.022Z,1526407251.022 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2018-05-15T18:00:51.023Z,1526407251.023 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2018-05-15T18:00:51.440Z,1526407251.440 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2018-05-15T18:00:51.440Z,1526407251.441 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2018-05-15T18:00:51.519Z,1526407251.519 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2018-05-15T18:00:51.810Z,1526407251.810 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2018-05-15T18:00:51.811Z,1526407251.811 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2018-05-15T18:00:51.949Z,1526407251.949 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2018-05-15T18:00:51.949Z,1526407251.949 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2018-05-15T18:00:52.150Z,1526407252.150 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2018-05-15T18:00:52.151Z,1526407252.151 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2018-05-15T18:00:52.352Z,1526407252.352 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2018-05-15T18:00:52.353Z,1526407252.353 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2018-05-15T18:00:52.447Z,1526407252.447 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2018-05-15T18:00:52.448Z,1526407252.448 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2018-05-15T18:00:52.583Z,1526407252.583 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2018-05-15T18:00:52.585Z,1526407252.585 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/ 2018-05-15T18:00:52.585Z,1526407252.585 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Battery.cfg 2018-05-15T18:00:52.812Z,1526407252.812 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2018-05-15T18:00:52.813Z,1526407252.813 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/logger.cfg 2018-05-15T18:00:52.889Z,1526407252.889 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Science.cfg 2018-05-15T18:00:53.025Z,1526407253.025 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Control.cfg 2018-05-15T18:00:53.201Z,1526407253.201 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Simulator.cfg 2018-05-15T18:00:53.498Z,1526407253.498 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Sensor.cfg 2018-05-15T18:00:53.820Z,1526407253.820 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/vehicle.cfg 2018-05-15T18:00:53.997Z,1526407253.997 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Servo.cfg 2018-05-15T18:00:54.093Z,1526407254.093 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Navigation.cfg 2018-05-15T18:00:54.183Z,1526407254.183 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/BIT.cfg 2018-05-15T18:00:54.277Z,1526407254.277 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/secure.cfg 2018-05-15T18:00:54.359Z,1526407254.359 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/root/ 2018-05-15T18:00:54.359Z,1526407254.359 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2018-05-15T18:00:54.372Z,1526407254.372 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2018-05-15T18:00:54.468Z,1526407254.468 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2018-05-15T18:00:54.468Z,1526407254.468 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2018-05-15T18:00:54.482Z,1526407254.482 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2018-05-15T18:00:54.482Z,1526407254.482 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2018-05-15T18:00:54.522Z,1526407254.522 [DepthRateCalculator] Loaded 2018-05-15T18:00:54.523Z,1526407254.523 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2018-05-15T18:00:54.528Z,1526407254.528 [PitchRateCalculator] Loaded 2018-05-15T18:00:54.529Z,1526407254.529 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2018-05-15T18:00:54.544Z,1526407254.544 [SpeedCalculator] Loaded 2018-05-15T18:00:54.544Z,1526407254.544 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2018-05-15T18:00:54.565Z,1526407254.565 [TempGradientCalculator] Loaded 2018-05-15T18:00:54.565Z,1526407254.565 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2018-05-15T18:00:54.580Z,1526407254.580 [VerticalTemperatureHomogeneityIndexCalculator] Loaded 2018-05-15T18:00:54.580Z,1526407254.580 [ComponentRegistry](DEBUG): SyncComponent "VerticalTemperatureHomogeneityIndexCalculator" handled in the control thread. 2018-05-15T18:00:54.586Z,1526407254.586 [YawRateCalculator] Loaded 2018-05-15T18:00:54.586Z,1526407254.586 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2018-05-15T18:00:54.624Z,1526407254.624 [ElevatorOffsetCalculator] Loaded 2018-05-15T18:00:54.624Z,1526407254.624 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2018-05-15T18:00:54.625Z,1526407254.625 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2018-05-15T18:00:54.625Z,1526407254.625 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2018-05-15T18:00:54.649Z,1526407254.649 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2018-05-15T18:00:54.650Z,1526407254.650 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2018-05-15T18:00:54.944Z,1526407254.944 [AHRS_M2] Loaded 2018-05-15T18:00:54.945Z,1526407254.945 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2018-05-15T18:00:54.987Z,1526407254.987 [AcousticModem_Benthos_ATM900] Loaded 2018-05-15T18:00:54.987Z,1526407254.987 [ComponentRegistry](DEBUG): SyncComponent "AcousticModem_Benthos_ATM900" handled in the control thread. 2018-05-15T18:00:55.053Z,1526407255.053 [DataOverHttps] Loaded 2018-05-15T18:00:55.053Z,1526407255.053 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread. 2018-05-15T18:00:55.066Z,1526407255.066 [Depth_Keller] Loaded 2018-05-15T18:00:55.066Z,1526407255.066 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2018-05-15T18:00:55.066Z,1526407255.066 [Module Loader](CRITICAL): Could not find element GobyModem.loadAtStartup 2018-05-15T18:00:55.159Z,1526407255.159 [NAL9602] Loaded 2018-05-15T18:00:55.160Z,1526407255.160 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2018-05-15T18:00:55.175Z,1526407255.175 [Onboard] Loaded 2018-05-15T18:00:55.175Z,1526407255.175 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2018-05-15T18:00:55.185Z,1526407255.185 [Radio_Surface] Loaded 2018-05-15T18:00:55.185Z,1526407255.185 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2018-05-15T18:00:55.186Z,1526407255.186 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 407B74E0 2018-05-15T18:00:55.187Z,1526407255.187 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 7720 2018-05-15T18:00:55.187Z,1526407255.187 [Module Loader](CRITICAL): Could not find element RDI_Pathfinder.loadAtStartup 2018-05-15T18:00:57.215Z,1526407257.215 [BPC1] Loaded 2018-05-15T18:00:57.216Z,1526407257.216 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2018-05-15T18:00:57.216Z,1526407257.216 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2018-05-15T18:00:57.229Z,1526407257.229 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2018-05-15T18:00:57.688Z,1526407257.688 [SBIT](DEBUG): Construct Startup Built In Test. 2018-05-15T18:00:57.766Z,1526407257.766 [SBIT] Loaded 2018-05-15T18:00:57.766Z,1526407257.766 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2018-05-15T18:00:57.767Z,1526407257.767 [IBIT](DEBUG): Construct Initiated Built In Test. 2018-05-15T18:00:57.790Z,1526407257.790 [IBIT] Loaded 2018-05-15T18:00:57.790Z,1526407257.790 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2018-05-15T18:00:57.813Z,1526407257.813 [CBIT](DEBUG): Construct Continuous Built In Test. 2018-05-15T18:00:58.097Z,1526407258.097 [CBIT] Loaded 2018-05-15T18:00:58.097Z,1526407258.097 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2018-05-15T18:00:58.097Z,1526407258.097 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2018-05-15T18:00:58.098Z,1526407258.098 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2018-05-15T18:00:58.266Z,1526407258.266 [CTD_Seabird] Loaded 2018-05-15T18:00:58.267Z,1526407258.267 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread. 2018-05-15T18:00:58.268Z,1526407258.268 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 408774E0 2018-05-15T18:00:58.268Z,1526407258.268 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 7721 2018-05-15T18:00:58.284Z,1526407258.284 [ESPComponent] Loaded 2018-05-15T18:00:58.285Z,1526407258.285 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread. 2018-05-15T18:00:58.298Z,1526407258.298 [PAR_Licor] Loaded 2018-05-15T18:00:58.299Z,1526407258.299 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2018-05-15T18:00:58.299Z,1526407258.299 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2018-05-15T18:00:58.300Z,1526407258.300 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2018-05-15T18:00:58.697Z,1526407258.697 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2018-05-15T18:00:58.697Z,1526407258.697 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2018-05-15T18:00:58.762Z,1526407258.762 [VerticalControl](DEBUG): Construct VerticalControl. 2018-05-15T18:00:58.854Z,1526407258.854 [VerticalControl] Loaded 2018-05-15T18:00:58.854Z,1526407258.854 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2018-05-15T18:00:58.855Z,1526407258.855 [HorizontalControl](DEBUG): Construct HorizontalControl. 2018-05-15T18:00:58.914Z,1526407258.914 [HorizontalControl] Loaded 2018-05-15T18:00:58.914Z,1526407258.914 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2018-05-15T18:00:58.914Z,1526407258.914 [SpeedControl](DEBUG): Construct SpeedControl. 2018-05-15T18:00:58.919Z,1526407258.919 [SpeedControl] Loaded 2018-05-15T18:00:58.920Z,1526407258.920 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2018-05-15T18:00:58.920Z,1526407258.920 [LoopControl](DEBUG): Construct LoopControl. 2018-05-15T18:00:58.921Z,1526407258.921 [LoopControl] Loaded 2018-05-15T18:00:58.921Z,1526407258.921 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2018-05-15T18:00:58.922Z,1526407258.922 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2018-05-15T18:00:58.922Z,1526407258.922 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2018-05-15T18:00:59.002Z,1526407259.002 [StratificationFrontDetector](INFO): threshold set to: 0.399988 degC 2018-05-15T18:00:59.002Z,1526407259.002 [StratificationFrontDetector](DEBUG): (re)initializing 2018-05-15T18:00:59.002Z,1526407259.002 [StratificationFrontDetector] Loaded 2018-05-15T18:00:59.003Z,1526407259.003 [ComponentRegistry](DEBUG): SyncComponent "StratificationFrontDetector" handled in the control thread. 2018-05-15T18:00:59.003Z,1526407259.003 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2018-05-15T18:00:59.004Z,1526407259.004 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2018-05-15T18:00:59.097Z,1526407259.097 [BuoyancyServo] Loaded 2018-05-15T18:00:59.097Z,1526407259.097 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2018-05-15T18:00:59.109Z,1526407259.109 [ElevatorServo] Loaded 2018-05-15T18:00:59.109Z,1526407259.109 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2018-05-15T18:00:59.120Z,1526407259.120 [MassServo] Loaded 2018-05-15T18:00:59.120Z,1526407259.120 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2018-05-15T18:00:59.131Z,1526407259.131 [RudderServo] Loaded 2018-05-15T18:00:59.131Z,1526407259.131 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2018-05-15T18:00:59.141Z,1526407259.141 [ThrusterServo] Loaded 2018-05-15T18:00:59.142Z,1526407259.142 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2018-05-15T18:00:59.142Z,1526407259.142 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2018-05-15T18:00:59.143Z,1526407259.143 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2018-05-15T18:00:59.236Z,1526407259.236 [DeadReckonUsingMultipleVelocitySources] Loaded 2018-05-15T18:00:59.236Z,1526407259.236 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2018-05-15T18:00:59.289Z,1526407259.289 [DeadReckonUsingSpeedCalculator] Loaded 2018-05-15T18:00:59.289Z,1526407259.289 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread. 2018-05-15T18:00:59.305Z,1526407259.305 [NavChart] Loaded 2018-05-15T18:00:59.306Z,1526407259.306 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2018-05-15T18:00:59.309Z,1526407259.309 [UniversalFixResidualReporter] Loaded 2018-05-15T18:00:59.310Z,1526407259.310 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2018-05-15T18:00:59.310Z,1526407259.310 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2018-05-15T18:00:59.314Z,1526407259.314 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2018-05-15T18:00:59.315Z,1526407259.315 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2018-05-15T18:00:59.322Z,1526407259.322 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2018-05-15T18:00:59.323Z,1526407259.323 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 409D04E0 2018-05-15T18:00:59.323Z,1526407259.323 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 7722 2018-05-15T18:00:59.328Z,1526407259.328 [Supervisor](INFO): Main Thread ID is 7496 2018-05-15T18:00:59.328Z,1526407259.328 [Supervisor](DEBUG): Running supervisor. 2018-05-15T18:00:59.329Z,1526407259.329 [CommandLine ThreadHandler](INFO): Handler Thread ID is 7723 2018-05-15T18:00:59.331Z,1526407259.331 [controlThread ThreadHandler](INFO): Handler Thread ID is 7724 2018-05-15T18:00:59.332Z,1526407259.332 [controlThread](DEBUG): Initializing ControlThread 2018-05-15T18:00:59.333Z,1526407259.333 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2018-05-15T18:00:59.333Z,1526407259.333 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2018-05-15T18:00:59.333Z,1526407259.333 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2018-05-15T18:00:59.334Z,1526407259.334 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2018-05-15T18:00:59.334Z,1526407259.334 [VerticalTemperatureHomogeneityIndexCalculator](DEBUG): (re)initializing 2018-05-15T18:00:59.335Z,1526407259.335 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2018-05-15T18:00:59.335Z,1526407259.335 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2018-05-15T18:00:59.342Z,1526407259.342 [SBIT](INFO): Initialize SBIT Component. 2018-05-15T18:00:59.342Z,1526407259.342 [SBIT](IMPORTANT): git: 2018-03-26-63-g035c652 2018-05-15T18:00:59.342Z,1526407259.342 [SBIT](INFO): git hash: 035c652db7f27c72339a0dc8ffe46f005dcbcd78 2018-05-15T18:00:59.343Z,1526407259.343 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2018-05-15T18:00:59.344Z,1526407259.344 [SBIT](INFO): Kernel Reporting Different Version From Configuration. Kernel Expected: #639 PREEMPT Wed Mar 12 12:53:33 PDT 2014 Kernel Reported: #16 PREEMPT Thu Apr 12 16:20:47 PDT 2018 2018-05-15T18:00:59.345Z,1526407259.345 [SBIT](INFO): Beginning SBIT in 52.000000 seconds. 2018-05-15T18:00:59.346Z,1526407259.346 [IBIT](INFO): Initialize IBIT Component. 2018-05-15T18:00:59.346Z,1526407259.346 [CBIT](DEBUG): Initialize CBIT Component. 2018-05-15T18:00:59.347Z,1526407259.347 [CBIT](CRITICAL): LAST REBOOT DUE TO WATCHDOG TIMER RESET. 2018-05-15T18:00:59.348Z,1526407259.348 [logger ThreadHandler](INFO): Handler Thread ID is 7725 2018-05-15T18:00:59.365Z,1526407259.365 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 7726 2018-05-15T18:00:59.371Z,1526407259.371 [Radio_Surface](INFO): Powering up 2018-05-15T18:00:59.377Z,1526407259.377 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 7727 2018-05-15T18:00:59.378Z,1526407259.378 [CTD_Seabird](INFO): Initializing 2018-05-15T18:00:59.378Z,1526407259.378 [CTD_Seabird](INFO): Checking LCM 2018-05-15T18:00:59.387Z,1526407259.387 [CTD_Seabird](INFO): LCM OK 2018-05-15T18:00:59.387Z,1526407259.387 [CTD_Seabird](INFO): Powering up 2018-05-15T18:00:59.393Z,1526407259.393 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 7728 2018-05-15T18:00:59.397Z,1526407259.397 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2018-05-15T18:00:59.397Z,1526407259.397 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2018-05-15T18:00:59.397Z,1526407259.397 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2018-05-15T18:00:59.397Z,1526407259.397 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2018-05-15T18:00:59.397Z,1526407259.397 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2018-05-15T18:00:59.398Z,1526407259.398 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2018-05-15T18:00:59.398Z,1526407259.398 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2018-05-15T18:00:59.398Z,1526407259.398 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2018-05-15T18:00:59.398Z,1526407259.398 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2018-05-15T18:00:59.398Z,1526407259.398 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2018-05-15T18:00:59.399Z,1526407259.399 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2018-05-15T18:00:59.399Z,1526407259.399 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2018-05-15T18:00:59.399Z,1526407259.399 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2018-05-15T18:00:59.399Z,1526407259.399 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2018-05-15T18:00:59.399Z,1526407259.399 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2018-05-15T18:00:59.400Z,1526407259.400 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2018-05-15T18:00:59.457Z,1526407259.457 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2018-05-15T18:00:59.459Z,1526407259.459 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2018-05-15T18:00:59.459Z,1526407259.459 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2018-05-15T18:00:59.460Z,1526407259.460 [LoopControl](DEBUG): Initialize LoopControlComponent. 2018-05-15T18:00:59.462Z,1526407259.462 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component. 2018-05-15T18:00:59.462Z,1526407259.462 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s. 2018-05-15T18:00:59.463Z,1526407259.463 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s. 2018-05-15T18:00:59.463Z,1526407259.463 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component. 2018-05-15T18:00:59.464Z,1526407259.464 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s. 2018-05-15T18:00:59.464Z,1526407259.464 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s. 2018-05-15T18:00:59.465Z,1526407259.465 [NavChart](DEBUG): Initialize NavChart Navigation. 2018-05-15T18:00:59.465Z,1526407259.465 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2018-05-15T18:00:59.466Z,1526407259.466 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2018-05-15T18:00:59.494Z,1526407259.494 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2018-05-15T18:00:59.529Z,1526407259.529 [MissionManager](DEBUG): 2018-05-15T18:00:59.530Z,1526407259.530 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2018-05-15T18:00:59.604Z,1526407259.604 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2018-05-15T18:00:59.605Z,1526407259.605 [Default:A.Wait](DEBUG): Construct Wait. 2018-05-15T18:00:59.607Z,1526407259.607 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2018-05-15T18:00:59.642Z,1526407259.642 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2018-05-15T18:00:59.644Z,1526407259.644 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2018-05-15T18:00:59.666Z,1526407259.666 [Default:E.Execute](DEBUG): Construct Execute. 2018-05-15T18:00:59.688Z,1526407259.688 [MissionManager](DEBUG): 0 Wait a moment to see if the scheduler starts a new mission before starting to actually run Default. 13 Burn 300 Dropped weight due to communications timeout. 5 Default mission has been running for Restarting logs and Default mission. restart logs 2018-05-15T18:00:59.717Z,1526407259.717 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,AcousticModem_Benthos_ATM900,DataOverHttps,Depth_Keller,NAL9602,Onboard,BPC1,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,VerticalTemperatureHomogeneityIndexCalculator,YawRateCalculator,ElevatorOffsetCalculator,StratificationFrontDetector,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2018-05-15T18:00:59.729Z,1526407259.729 [AHRS_M2](INFO): Start 2018-05-15T18:00:59.729Z,1526407259.729 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2018-05-15T18:00:59.783Z,1526407259.783 [AcousticModem_Benthos_ATM900](INFO): Powering up 2018-05-15T18:00:59.784Z,1526407259.784 [AcousticModem_Benthos_ATM900](DEBUG): Initializing AcousticModem_Benthos_ATM900. 2018-05-15T18:00:59.815Z,1526407259.815 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2018-05-15T18:01:00.063Z,1526407260.063 [ESPComponent](INFO): powering down ESP 2018-05-15T18:01:00.561Z,1526407260.561 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:00.589Z,1526407260.589 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:00.689Z,1526407260.689 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2018-05-15T18:01:00.697Z,1526407260.697 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2018-05-15T18:01:00.711Z,1526407260.711 [ElevatorServo](DEBUG): Initializing EZServoServo. 2018-05-15T18:01:00.717Z,1526407260.717 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2018-05-15T18:01:00.731Z,1526407260.731 [MassServo](DEBUG): Initializing EZServoServo. 2018-05-15T18:01:00.737Z,1526407260.737 [MassServo](DEBUG): Initializing MassServo. 2018-05-15T18:01:00.759Z,1526407260.759 [RudderServo](DEBUG): Initializing EZServoServo. 2018-05-15T18:01:00.765Z,1526407260.765 [RudderServo](DEBUG): Initializing RudderServo. 2018-05-15T18:01:00.778Z,1526407260.778 [ThrusterServo](DEBUG): Initializing EZServoServo. 2018-05-15T18:01:00.785Z,1526407260.785 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2018-05-15T18:01:00.822Z,1526407260.822 [CommandLine](FAULT): Scheduling is paused 2018-05-15T18:01:00.822Z,1526407260.822 [CBIT](INFO): Critical error at 20180515T180059 2018-05-15T18:01:00.823Z,1526407260.823 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals 2018-05-15T18:01:00.937Z,1526407260.937 [AHRS_M2](INFO): Starting 2018-05-15T18:01:01.029Z,1526407261.029 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:01.030Z,1526407261.030 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:01.277Z,1526407261.277 [AHRS_M2](INFO): Starting 2018-05-15T18:01:01.333Z,1526407261.333 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:01.334Z,1526407261.334 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:01.749Z,1526407261.749 [AHRS_M2](INFO): Starting 2018-05-15T18:01:01.833Z,1526407261.833 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:01.834Z,1526407261.834 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:02.153Z,1526407262.153 [AHRS_M2](INFO): Starting 2018-05-15T18:01:02.260Z,1526407262.260 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:02.261Z,1526407262.261 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:02.553Z,1526407262.553 [AHRS_M2](INFO): Starting 2018-05-15T18:01:02.637Z,1526407262.637 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:02.638Z,1526407262.638 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:02.953Z,1526407262.953 [AHRS_M2](INFO): Starting 2018-05-15T18:01:03.029Z,1526407263.029 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:03.030Z,1526407263.030 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:03.353Z,1526407263.353 [AHRS_M2](INFO): Starting 2018-05-15T18:01:03.440Z,1526407263.440 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:03.449Z,1526407263.449 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:03.753Z,1526407263.753 [AHRS_M2](INFO): Starting 2018-05-15T18:01:03.834Z,1526407263.834 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:03.835Z,1526407263.835 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:04.153Z,1526407264.153 [AHRS_M2](INFO): Starting 2018-05-15T18:01:04.205Z,1526407264.205 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:04.206Z,1526407264.206 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:04.553Z,1526407264.553 [AHRS_M2](INFO): Starting 2018-05-15T18:01:04.608Z,1526407264.608 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:04.610Z,1526407264.610 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:04.961Z,1526407264.961 [AHRS_M2](INFO): Starting 2018-05-15T18:01:04.961Z,1526407264.961 [AHRS_M2](FAULT): Failed to initialize 2018-05-15T18:01:04.961Z,1526407264.961 [AHRS_M2] Communications Fault, FailCount= 1 2018-05-15T18:01:04.961Z,1526407264.961 [AHRS_M2](ERROR): Communications Fault 2018-05-15T18:01:04.997Z,1526407264.997 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface 2018-05-15T18:01:05.046Z,1526407265.046 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:05.047Z,1526407265.047 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:05.099Z,1526407265.099 [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-05-15T18:01:05.142Z,1526407265.142 [CTD_Seabird](INFO): LCM subscribed to channel:ctd_t.seabird-gpctd 2018-05-15T18:01:05.197Z,1526407265.197 [CBIT](ERROR): Communications Fault in component: AHRS_M2 2018-05-15T18:01:05.353Z,1526407265.353 [AHRS_M2](INFO): Stop 2018-05-15T18:01:05.353Z,1526407265.353 [AHRS_M2](INFO): uninitialize 2018-05-15T18:01:05.377Z,1526407265.377 [AHRS_M2](INFO): Data-stream disabled. 2018-05-15T18:01:05.378Z,1526407265.378 [AHRS_M2](INFO): Powering down 2018-05-15T18:01:05.432Z,1526407265.432 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:05.433Z,1526407265.433 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:05.733Z,1526407265.733 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface 2018-05-15T18:01:05.733Z,1526407265.733 [CTD_Seabird](INFO): Powering down 2018-05-15T18:01:05.756Z,1526407265.756 [AHRS_M2](INFO): Stopping 2018-05-15T18:01:05.825Z,1526407265.825 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:05.826Z,1526407265.826 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:06.153Z,1526407266.153 [AHRS_M2](INFO): Stopping 2018-05-15T18:01:06.188Z,1526407266.188 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:06.189Z,1526407266.189 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:06.553Z,1526407266.553 [AHRS_M2](INFO): Stopping 2018-05-15T18:01:06.586Z,1526407266.586 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:06.587Z,1526407266.587 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:06.953Z,1526407266.953 [AHRS_M2](INFO): Stopped 2018-05-15T18:01:06.986Z,1526407266.986 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:06.987Z,1526407266.987 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:07.065Z,1526407267.065 [CBIT](INFO): Clearing failed state for component AHRS_M2 2018-05-15T18:01:07.065Z,1526407267.065 [AHRS_M2] No Fault, FailCount= 1 2018-05-15T18:01:07.353Z,1526407267.353 [AHRS_M2](INFO): Start 2018-05-15T18:01:07.353Z,1526407267.353 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2018-05-15T18:01:07.361Z,1526407267.361 [AcousticModem_Benthos_ATM900](DEBUG): 2018-05-15T18:01:07.429Z,1526407267.429 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:07.430Z,1526407267.430 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:07.753Z,1526407267.753 [AHRS_M2](INFO): Starting 2018-05-15T18:01:07.805Z,1526407267.805 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:07.810Z,1526407267.810 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:08.153Z,1526407268.153 [AHRS_M2](INFO): Starting 2018-05-15T18:01:08.221Z,1526407268.221 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:08.222Z,1526407268.222 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:08.553Z,1526407268.553 [AHRS_M2](INFO): Starting 2018-05-15T18:01:08.577Z,1526407268.577 [AHRS_M2](INFO): Data-stream active. 2018-05-15T18:01:08.579Z,1526407268.579 [AcousticModem_Benthos_ATM900](DEBUG): Teledyne Benthos ATM-900 Series OEM w/burn wire 2018-05-15T18:01:08.580Z,1526407268.580 [AcousticModem_Benthos_ATM900](DEBUG): MF Frequency Band 2018-05-15T18:01:08.580Z,1526407268.580 [AcousticModem_Benthos_ATM900](DEBUG): Standard version 8.6.3 2018-05-15T18:01:08.581Z,1526407268.581 [AcousticModem_Benthos_ATM900](DEBUG): Apr 6 2000 13:48:50 2018-05-15T18:01:08.649Z,1526407268.649 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:08.650Z,1526407268.650 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-15T18:01:08.957Z,1526407268.957 [AcousticModem_Benthos_ATM900](DEBUG): WARNING: battery low 2018-05-15T18:01:09.767Z,1526407269.767 [AcousticModem_Benthos_ATM900](INFO): entering command mode 2018-05-15T18:01:10.155Z,1526407270.155 [AcousticModem_Benthos_ATM900](DEBUG): checking for command mode acknowledgment 2018-05-15T18:01:10.156Z,1526407270.156 [AcousticModem_Benthos_ATM900](DEBUG): read user prompt 1: user:1> 2018-05-15T18:01:10.156Z,1526407270.156 [AcousticModem_Benthos_ATM900](INFO): command mode acknowledged 2018-05-15T18:01:10.555Z,1526407270.555 [AcousticModem_Benthos_ATM900](INFO): setting local address to 3 2018-05-15T18:01:10.966Z,1526407270.966 [AcousticModem_Benthos_ATM900](DEBUG): checking for local address setting acknowledgment 2018-05-15T18:01:10.967Z,1526407270.967 [AcousticModem_Benthos_ATM900](INFO): set local address to 3 2018-05-15T18:01:11.356Z,1526407271.356 [AcousticModem_Benthos_ATM900](DEBUG): read user prompt 2: user:2> 2018-05-15T18:01:30.970Z,1526407290.970 [NAL9602](INFO): No messages in MT queue 2018-05-15T18:01:51.821Z,1526407311.821 [SBIT](IMPORTANT): Beginning Startup BIT 2018-05-15T18:01:51.857Z,1526407311.857 [CBIT](IMPORTANT): Beginning ground fault scan 2018-05-15T18:01:54.182Z,1526407314.182 [CommandLine](IMPORTANT): got command configSet AHRS_M2.verbosity 1.000000 count 2018-05-15T18:01:54.265Z,1526407314.265 [AHRS_M2](INFO): CRC match. PITCH: -89.012063 deg, ROLL: -92.860506 deg, YAW: 243.737951 deg, TEMP: 27.910036 C. 2018-05-15T18:01:54.666Z,1526407314.666 [AHRS_M2](INFO): CRC match. PITCH: -89.008300 deg, ROLL: -92.672799 deg, YAW: 243.570065 deg, TEMP: 27.900856 C. 2018-05-15T18:01:55.066Z,1526407315.066 [AHRS_M2](INFO): CRC match. PITCH: -89.009085 deg, ROLL: -92.976503 deg, YAW: 243.881631 deg, TEMP: 27.928396 C. 2018-05-15T18:01:55.467Z,1526407315.467 [AHRS_M2](INFO): CRC match. PITCH: -89.015226 deg, ROLL: -93.410036 deg, YAW: 244.301632 deg, TEMP: 27.910036 C. 2018-05-15T18:01:55.866Z,1526407315.866 [AHRS_M2](INFO): CRC match. PITCH: -89.011469 deg, ROLL: -93.380495 deg, YAW: 244.287453 deg, TEMP: 27.894737 C. 2018-05-15T18:01:56.266Z,1526407316.266 [AHRS_M2](INFO): CRC match. PITCH: -89.012849 deg, ROLL: -93.237007 deg, YAW: 244.133063 deg, TEMP: 27.903917 C. 2018-05-15T18:01:56.667Z,1526407316.667 [AHRS_M2](INFO): CRC match. PITCH: -89.013641 deg, ROLL: -92.780409 deg, YAW: 243.662737 deg, TEMP: 27.910036 C. 2018-05-15T18:01:57.066Z,1526407317.066 [AHRS_M2](INFO): CRC match. PITCH: -89.012849 deg, ROLL: -92.815024 deg, YAW: 243.705466 deg, TEMP: 27.925337 C. 2018-05-15T18:01:57.466Z,1526407317.466 [AHRS_M2](INFO): CRC match. PITCH: -89.005937 deg, ROLL: -92.987841 deg, YAW: 243.915016 deg, TEMP: 27.906977 C. 2018-05-15T18:01:57.866Z,1526407317.866 [AHRS_M2](INFO): CRC match. PITCH: -89.012453 deg, ROLL: -93.036821 deg, YAW: 243.936545 deg, TEMP: 27.913097 C. 2018-05-15T18:01:58.266Z,1526407318.266 [AHRS_M2](INFO): CRC match. PITCH: -89.006920 deg, ROLL: -93.104884 deg, YAW: 244.031922 deg, TEMP: 27.910036 C. 2018-05-15T18:01:58.666Z,1526407318.666 [AHRS_M2](INFO): CRC match. PITCH: -89.010472 deg, ROLL: -92.813993 deg, YAW: 243.712624 deg, TEMP: 27.919216 C. 2018-05-15T18:01:59.066Z,1526407319.066 [AHRS_M2](INFO): CRC match. PITCH: -89.010472 deg, ROLL: -92.785272 deg, YAW: 243.688118 deg, TEMP: 27.913097 C. 2018-05-15T18:01:59.466Z,1526407319.466 [AHRS_M2](INFO): CRC match. PITCH: -89.006326 deg, ROLL: -93.115593 deg, YAW: 244.049981 deg, TEMP: 27.900856 C. 2018-05-15T18:01:59.866Z,1526407319.866 [AHRS_M2](INFO): CRC match. PITCH: -89.016032 deg, ROLL: -93.139342 deg, YAW: 244.027387 deg, TEMP: 27.910036 C. 2018-05-15T18:02:00.266Z,1526407320.266 [AHRS_M2](INFO): CRC match. PITCH: -89.013443 deg, ROLL: -92.843390 deg, YAW: 243.733880 deg, TEMP: 27.916157 C. 2018-05-15T18:02:00.666Z,1526407320.666 [AHRS_M2](INFO): CRC match. PITCH: -89.009680 deg, ROLL: -92.751626 deg, YAW: 243.667764 deg, TEMP: 27.882498 C. 2018-05-15T18:02:01.066Z,1526407321.066 [AHRS_M2](INFO): CRC match. PITCH: -89.009085 deg, ROLL: -92.492202 deg, YAW: 243.399938 deg, TEMP: 27.906977 C. 2018-05-15T18:02:01.466Z,1526407321.466 [AHRS_M2](INFO): CRC match. PITCH: -89.010076 deg, ROLL: -92.997404 deg, YAW: 243.918623 deg, TEMP: 27.916157 C. 2018-05-15T18:02:01.866Z,1526407321.866 [AHRS_M2](INFO): CRC match. PITCH: -89.013047 deg, ROLL: -92.762869 deg, YAW: 243.659403 deg, TEMP: 27.913097 C. 2018-05-15T18:02:02.266Z,1526407322.266 [AHRS_M2](INFO): CRC match. PITCH: -89.012651 deg, ROLL: -92.756913 deg, YAW: 243.655032 deg, TEMP: 27.919216 C. 2018-05-15T18:02:02.666Z,1526407322.666 [AHRS_M2](INFO): CRC match. PITCH: -89.016428 deg, ROLL: -93.014725 deg, YAW: 243.900536 deg, TEMP: 27.913097 C. 2018-05-15T18:02:02.786Z,1526407322.786 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.007205 CHAN A1 (24V): -0.011692 CHAN A2 (12V): -0.005413 CHAN A3 (5V): -0.003254 CHAN B0 (3.3V): -0.001011 CHAN B1 (3.15aV): -0.001452 CHAN B2 (3.15bV): -0.001252 CHAN B3 (GND): -0.000488 OPEN: -0.000766 Full Scale Calc: 4.765 mA, -1.589 mA 2018-05-15T18:02:03.066Z,1526407323.066 [AHRS_M2](INFO): CRC match. PITCH: -89.018812 deg, ROLL: -93.140722 deg, YAW: 244.024381 deg, TEMP: 27.922277 C. 2018-05-15T18:02:03.466Z,1526407323.466 [AHRS_M2](INFO): CRC match. PITCH: -89.018812 deg, ROLL: -93.224227 deg, YAW: 244.113666 deg, TEMP: 27.903917 C. 2018-05-15T18:02:03.866Z,1526407323.866 [AHRS_M2](INFO): CRC match. PITCH: -89.018013 deg, ROLL: -93.014411 deg, YAW: 243.899690 deg, TEMP: 27.897797 C. 2018-05-15T18:02:04.266Z,1526407324.266 [AHRS_M2](INFO): CRC match. PITCH: -89.018013 deg, ROLL: -92.968027 deg, YAW: 243.852124 deg, TEMP: 27.897797 C. 2018-05-15T18:02:04.666Z,1526407324.666 [AHRS_M2](INFO): CRC match. PITCH: -89.013641 deg, ROLL: -92.691466 deg, YAW: 243.581075 deg, TEMP: 27.922277 C. 2018-05-15T18:02:05.066Z,1526407325.066 [AHRS_M2](INFO): CRC match. PITCH: -89.018211 deg, ROLL: -92.930693 deg, YAW: 243.802865 deg, TEMP: 27.913097 C. 2018-05-15T18:02:05.466Z,1526407325.466 [AHRS_M2](INFO): CRC match. PITCH: -89.016626 deg, ROLL: -93.388903 deg, YAW: 244.293108 deg, TEMP: 27.913097 C. 2018-05-15T18:02:05.866Z,1526407325.866 [AHRS_M2](INFO): CRC match. PITCH: -89.009482 deg, ROLL: -93.530848 deg, YAW: 244.480283 deg, TEMP: 27.919216 C. 2018-05-15T18:02:06.266Z,1526407326.266 [AHRS_M2](INFO): CRC match. PITCH: -89.013641 deg, ROLL: -93.399558 deg, YAW: 244.332833 deg, TEMP: 27.913097 C. 2018-05-15T18:02:06.666Z,1526407326.666 [AHRS_M2](INFO): CRC match. PITCH: -89.021209 deg, ROLL: -93.707286 deg, YAW: 244.605904 deg, TEMP: 27.903917 C. 2018-05-15T18:02:07.066Z,1526407327.066 [AHRS_M2](INFO): CRC match. PITCH: -89.018812 deg, ROLL: -93.412153 deg, YAW: 244.314173 deg, TEMP: 27.910036 C. 2018-05-15T18:02:07.660Z,1526407327.660 [AHRS_M2](INFO): CRC match. PITCH: -89.018614 deg, ROLL: -93.316886 deg, YAW: 244.210709 deg, TEMP: 27.900856 C. 2018-05-15T18:02:08.062Z,1526407328.062 [AHRS_M2](INFO): CRC match. PITCH: -89.016428 deg, ROLL: -93.095581 deg, YAW: 243.999574 deg, TEMP: 27.913097 C. 2018-05-15T18:02:08.462Z,1526407328.462 [AHRS_M2](INFO): CRC match. PITCH: -89.015636 deg, ROLL: -92.991721 deg, YAW: 243.888461 deg, TEMP: 27.894737 C. 2018-05-15T18:02:08.863Z,1526407328.863 [AHRS_M2](INFO): CRC match. PITCH: -89.013443 deg, ROLL: -93.234555 deg, YAW: 244.156969 deg, TEMP: 27.922277 C. 2018-05-15T18:02:09.263Z,1526407329.263 [AHRS_M2](INFO): CRC match. PITCH: -89.006524 deg, ROLL: -92.755793 deg, YAW: 243.688664 deg, TEMP: 27.906977 C. 2018-05-15T18:02:09.663Z,1526407329.663 [AHRS_M2](INFO): CRC match. PITCH: -89.008887 deg, ROLL: -92.819102 deg, YAW: 243.743934 deg, TEMP: 27.919216 C. 2018-05-15T18:02:10.064Z,1526407330.064 [AHRS_M2](INFO): CRC match. PITCH: -89.010076 deg, ROLL: -92.300130 deg, YAW: 243.192956 deg, TEMP: 27.906977 C. 2018-05-15T18:02:10.465Z,1526407330.465 [AHRS_M2](INFO): CRC match. PITCH: -89.013839 deg, ROLL: -92.496942 deg, YAW: 243.380978 deg, TEMP: 27.891678 C. 2018-05-15T18:02:10.862Z,1526407330.862 [AHRS_M2](INFO): CRC match. PITCH: -89.018013 deg, ROLL: -91.837030 deg, YAW: 242.672632 deg, TEMP: 27.906977 C. 2018-05-15T18:02:11.263Z,1526407331.263 [AHRS_M2](INFO): CRC match. PITCH: -89.019208 deg, ROLL: -92.203790 deg, YAW: 243.041872 deg, TEMP: 27.916157 C. 2018-05-15T18:02:11.662Z,1526407331.662 [AHRS_M2](INFO): CRC match. PITCH: -89.015028 deg, ROLL: -92.647275 deg, YAW: 243.519139 deg, TEMP: 27.910036 C. 2018-05-15T18:02:12.062Z,1526407332.062 [AHRS_M2](INFO): CRC match. PITCH: -89.017814 deg, ROLL: -92.669507 deg, YAW: 243.533072 deg, TEMP: 27.937576 C. 2018-05-15T18:02:12.462Z,1526407332.462 [AHRS_M2](INFO): CRC match. PITCH: -89.016230 deg, ROLL: -92.850008 deg, YAW: 243.727459 deg, TEMP: 27.913097 C. 2018-05-15T18:02:12.862Z,1526407332.862 [AHRS_M2](INFO): CRC match. PITCH: -89.017814 deg, ROLL: -92.778168 deg, YAW: 243.652163 deg, TEMP: 27.906977 C. 2018-05-15T18:02:13.262Z,1526407333.262 [AHRS_M2](INFO): CRC match. PITCH: -89.022008 deg, ROLL: -93.299421 deg, YAW: 244.164373 deg, TEMP: 27.910036 C. 2018-05-15T18:02:13.370Z,1526407333.370 [CommandLine](IMPORTANT): got command configSet AHRS_M2.verbosity 0.000000 count 2018-05-15T18:02:45.812Z,1526407365.812 [SBIT](IMPORTANT): SBIT PASSED 2018-05-15T18:02:45.859Z,1526407365.859 [CommandLine](IMPORTANT): got command configSet list 2018-05-15T18:02:45.859Z,1526407365.859 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2018-05-15T18:02:45.860Z,1526407365.860 [CommandLine](IMPORTANT): Aanderaa_O2.loadAtStartup=0 bool; 2018-05-15T18:02:45.860Z,1526407365.860 [CommandLine](IMPORTANT): CBIT.abortDepth=300 meter; 2018-05-15T18:02:45.860Z,1526407365.860 [CommandLine](IMPORTANT): CBIT.gf24Offset=107 microampere; 2018-05-15T18:02:45.860Z,1526407365.860 [CommandLine](IMPORTANT): CBIT.stopDepth=285 meter; 2018-05-15T18:02:45.860Z,1526407365.860 [CommandLine](IMPORTANT): DropWeight.loadAtStartup=0 bool; 2018-05-15T18:02:45.861Z,1526407365.861 [CommandLine](IMPORTANT): ESPComponent.simulateHardware=0 bool; 2018-05-15T18:02:45.861Z,1526407365.861 [CommandLine](IMPORTANT): ElevatorOffsetCalculator.loadAtStartup=1 bool; 2018-05-15T18:02:45.861Z,1526407365.861 [CommandLine](IMPORTANT): NAL9602.simulateHardware=1 bool; 2018-05-15T18:02:45.861Z,1526407365.861 [CommandLine](IMPORTANT): Normal all CTD_Seabird.sea_water_salinity; 2018-05-15T18:02:45.861Z,1526407365.861 [CommandLine](IMPORTANT): Normal all CTD_Seabird.sea_water_temperature; 2018-05-15T18:02:45.861Z,1526407365.861 [CommandLine](IMPORTANT): Rowe_600LCM.loadAtStartup=0 bool; 2018-05-15T18:02:45.861Z,1526407365.861 [CommandLine](IMPORTANT): RudderServo.offsetAngle=0.5 degree; 2018-05-15T18:02:45.861Z,1526407365.861 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=130 cubic_centimeter; 2018-05-15T18:02:45.861Z,1526407365.861 [CommandLine](IMPORTANT): VerticalControl.massDefault=8 millimeter; 2018-05-15T18:02:45.862Z,1526407365.862 [CommandLine](IMPORTANT): WetLabsBB2FL.loadAtStartup=0 bool; 2018-05-15T18:02:46.189Z,1526407366.189 [MissionManager](IMPORTANT): Started mission Startup 2018-05-15T18:02:46.189Z,1526407366.189 [Startup] Running Loop=1 2018-05-15T18:02:46.189Z,1526407366.189 [Startup](DEBUG): Aggregate::initialize Startup 2018-05-15T18:02:46.189Z,1526407366.189 [Startup:A.GoToSurface] Running Loop=1 2018-05-15T18:02:46.189Z,1526407366.189 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2018-05-15T18:02:46.190Z,1526407366.190 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2018-05-15T18:02:46.191Z,1526407366.191 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2018-05-15T18:02:46.191Z,1526407366.191 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2018-05-15T18:02:46.191Z,1526407366.191 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2018-05-15T18:02:46.192Z,1526407366.192 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2018-05-15T18:02:46.214Z,1526407366.214 [Startup:StartupSatComms] Running Loop=1 2018-05-15T18:02:46.214Z,1526407366.214 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2018-05-15T18:02:46.214Z,1526407366.214 [Startup:StartupSatComms:A] Running Loop=1 2018-05-15T18:02:46.602Z,1526407366.602 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2018-05-15T18:03:13.214Z,1526407393.214 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/calibrateAHRS_M2.xml 2018-05-15T18:03:13.215Z,1526407393.215 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/calibrateAHRS_M2.xml 2018-05-15T18:03:13.275Z,1526407393.274 [MissionManager](ERROR): Cannot load Xml file ./Missions/Maintenance/calibrateAHRS_M2.xml due to: Error reading end tag. 2018-05-15T18:03:13.276Z,1526407393.276 [MissionManager](CRITICAL): Could not load mission ./Missions/Maintenance/calibrateAHRS_M2.xml 2018-05-15T18:03:13.276Z,1526407393.276 [CommandLine](CRITICAL): Could not load ./Missions/Maintenance/calibrateAHRS_M2.xml 2018-05-15T18:03:13.409Z,1526407393.409 [CBIT](INFO): Critical error at 20180515T180313 2018-05-15T18:03:46.234Z,1526407426.234 [Startup:StartupSatComms:A](INFO): Timed out from 2018-05-15T18:02:46.2Z 2018-05-15T18:03:46.234Z,1526407426.234 [Startup:StartupSatComms:A] Stopped 2018-05-15T18:03:46.234Z,1526407426.234 [Startup:StartupSatComms:B] Running Loop=1 2018-05-15T18:03:46.618Z,1526407426.618 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2018-05-15T18:03:59.707Z,1526407439.707 [DeadReckonUsingMultipleVelocitySources](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2018-05-15T18:03:59.707Z,1526407439.707 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1 2018-05-15T18:03:59.707Z,1526407439.707 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2018-05-15T18:03:59.709Z,1526407439.709 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2018-05-15T18:03:59.709Z,1526407439.709 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1 2018-05-15T18:03:59.710Z,1526407439.710 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault 2018-05-15T18:03:59.722Z,1526407439.722 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2018-05-15T18:03:59.722Z,1526407439.722 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator 2018-05-15T18:04:00.122Z,1526407440.122 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2018-05-15T18:04:00.122Z,1526407440.122 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1 2018-05-15T18:04:00.122Z,1526407440.122 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator 2018-05-15T18:04:00.122Z,1526407440.122 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1 2018-05-15T18:04:00.519Z,1526407440.519 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component. 2018-05-15T18:04:00.519Z,1526407440.519 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s. 2018-05-15T18:04:00.519Z,1526407440.519 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s. 2018-05-15T18:04:00.520Z,1526407440.520 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component. 2018-05-15T18:04:00.520Z,1526407440.520 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s. 2018-05-15T18:04:00.521Z,1526407440.521 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s. 2018-05-15T18:04:00.924Z,1526407440.924 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 1.2 s old, using for 20.0 s. 2018-05-15T18:04:04.020Z,1526407444.020 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 4.3 s old, using for 20.0 s. 2018-05-15T18:04:04.109Z,1526407444.109 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 4.4 s old, using for 20.0 s. 2018-05-15T18:04:04.482Z,1526407444.482 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 4.8 s old, using for 20.0 s. 2018-05-15T18:04:04.853Z,1526407444.853 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004092 2018-05-15T18:04:04.902Z,1526407444.902 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 5.2 s old, using for 20.0 s. 2018-05-15T18:04:05.587Z,1526407445.587 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 5.9 s old, using for 20.0 s. 2018-05-15T18:04:05.707Z,1526407445.707 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 6.0 s old, using for 20.0 s. 2018-05-15T18:04:08.859Z,1526407448.859 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 9.2 s old, using for 20.0 s. 2018-05-15T18:04:08.883Z,1526407448.883 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180515T175722/Courier0004.lzma 2018-05-15T18:04:08.970Z,1526407448.970 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 9.3 s old, using for 20.0 s. 2018-05-15T18:04:09.334Z,1526407449.334 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 9.6 s old, using for 20.0 s. 2018-05-15T18:04:09.713Z,1526407449.713 [DataOverHttps](INFO): Moved sent file to Logs/20180515T175722/Courier0004.lzma.bak 2018-05-15T18:04:09.714Z,1526407449.714 [DataOverHttps](INFO): SBD MOMSN=8282366 2018-05-15T18:04:09.783Z,1526407449.783 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 10.1 s old, using for 20.0 s. 2018-05-15T18:04:10.418Z,1526407450.418 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 10.7 s old, using for 20.0 s. 2018-05-15T18:04:10.526Z,1526407450.526 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 10.8 s old, using for 20.0 s. 2018-05-15T18:04:13.637Z,1526407453.637 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 13.9 s old, using for 20.0 s. 2018-05-15T18:04:13.754Z,1526407453.754 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 14.0 s old, using for 20.0 s. 2018-05-15T18:04:14.128Z,1526407454.128 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 14.4 s old, using for 20.0 s. 2018-05-15T18:04:14.524Z,1526407454.524 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 14.8 s old, using for 20.0 s. 2018-05-15T18:04:14.933Z,1526407454.933 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 15.2 s old, using for 20.0 s. 2018-05-15T18:04:15.323Z,1526407455.323 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 15.6 s old, using for 20.0 s. 2018-05-15T18:04:18.420Z,1526407458.420 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 18.7 s old, using for 20.0 s. 2018-05-15T18:04:18.446Z,1526407458.446 [DataOverHttps](INFO): Sending 279 bytes from file Logs/20180515T180049/Courier0000.lzma 2018-05-15T18:04:18.533Z,1526407458.533 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 18.8 s old, using for 20.0 s. 2018-05-15T18:04:18.888Z,1526407458.888 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 19.2 s old, using for 20.0 s. 2018-05-15T18:04:19.246Z,1526407459.246 [DataOverHttps](INFO): Moved sent file to Logs/20180515T180049/Courier0000.lzma.bak 2018-05-15T18:04:19.246Z,1526407459.246 [DataOverHttps](INFO): SBD MOMSN=8282368 2018-05-15T18:04:19.259Z,1526407459.259 [NAL9602](INFO): Sent 25 bytes from file Logs/20180515T175722/Courier0004.lzma 2018-05-15T18:04:19.259Z,1526407459.259 [NAL9602](INFO): Packets left to send: 0 2018-05-15T18:04:19.263Z,1526407459.263 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180515T175722/Courier0004.lzma.parts/0000.sbd 2018-05-15T18:04:19.263Z,1526407459.263 [NAL9602](DEBUG): Completed sending Logs/20180515T175722/Courier0004.lzma 2018-05-15T18:04:19.340Z,1526407459.340 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 19.6 s old, using for 20.0 s. 2018-05-15T18:04:19.347Z,1526407459.347 [Startup:StartupSatComms:B] Stopped 2018-05-15T18:04:19.347Z,1526407459.347 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2018-05-15T18:04:19.347Z,1526407459.347 [Startup:StartupSatComms] Stopped 2018-05-15T18:04:19.347Z,1526407459.347 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2018-05-15T18:04:19.348Z,1526407459.348 [Startup](INFO): Completed Startup 2018-05-15T18:04:19.348Z,1526407459.348 [MissionManager](INFO): Startup is completed. 2018-05-15T18:04:19.348Z,1526407459.348 [MissionManager](INFO): Uninitializing Mission Startup 2018-05-15T18:04:19.348Z,1526407459.348 [Startup] Stopped 2018-05-15T18:04:19.348Z,1526407459.348 [Startup](DEBUG): Aggregate::uninitialize Startup 2018-05-15T18:04:19.348Z,1526407459.348 [Startup:A.GoToSurface] Stopped 2018-05-15T18:04:19.349Z,1526407459.349 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2018-05-15T18:04:19.700Z,1526407459.700 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 20.0 s old, using for 20.0 s. 2018-05-15T18:04:19.702Z,1526407459.702 [MissionManager](IMPORTANT): Started mission Default 2018-05-15T18:04:19.703Z,1526407459.703 [Default] Running Loop=1 2018-05-15T18:04:19.703Z,1526407459.703 [Default](DEBUG): Aggregate::initialize Default 2018-05-15T18:04:19.703Z,1526407459.703 [Default:B.GoToSurface] Running Loop=1 2018-05-15T18:04:19.703Z,1526407459.703 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2018-05-15T18:04:19.703Z,1526407459.703 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2018-05-15T18:04:19.704Z,1526407459.704 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2018-05-15T18:04:19.704Z,1526407459.704 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2018-05-15T18:04:19.704Z,1526407459.704 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2018-05-15T18:04:19.705Z,1526407459.705 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2018-05-15T18:04:19.705Z,1526407459.705 [Default:A.Wait] Running Loop=1 2018-05-15T18:04:19.705Z,1526407459.705 [Default:A.Wait](DEBUG): Initialize Wait Component. 2018-05-15T18:04:24.411Z,1526407464.411 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/calibrateAHRS_M2.xml 2018-05-15T18:04:24.411Z,1526407464.411 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/calibrateAHRS_M2.xml 2018-05-15T18:04:24.508Z,1526407464.508 [MissionManager](ERROR): Cannot load Xml file ./Missions/Maintenance/calibrateAHRS_M2.xml due to: Error reading end tag. 2018-05-15T18:04:24.526Z,1526407464.526 [MissionManager](CRITICAL): Could not load mission ./Missions/Maintenance/calibrateAHRS_M2.xml 2018-05-15T18:04:24.526Z,1526407464.526 [CommandLine](CRITICAL): Could not load ./Missions/Maintenance/calibrateAHRS_M2.xml 2018-05-15T18:04:24.542Z,1526407464.542 [CBIT](INFO): Critical error at 20180515T180424 2018-05-15T18:04:32.890Z,1526407472.890 [Default:A.Wait](INFO): Done Waiting. 2018-05-15T18:04:32.890Z,1526407472.890 [Default:A.Wait] Stopped 2018-05-15T18:04:32.890Z,1526407472.890 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2018-05-15T18:04:33.290Z,1526407473.290 [Default:CheckIn] Running Loop=1 2018-05-15T18:04:33.290Z,1526407473.290 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-05-15T18:04:33.290Z,1526407473.290 [Default:CheckIn:Read_GPS] Running Loop=1 2018-05-15T18:04:33.686Z,1526407473.686 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2018-05-15T18:05:01.978Z,1526407501.978 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/calibrateAHRS_M2.xml 2018-05-15T18:05:01.979Z,1526407501.979 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/calibrateAHRS_M2.xml 2018-05-15T18:05:02.028Z,1526407502.028 [MissionManager](ERROR): Cannot load Xml file ./Missions/Maintenance/calibrateAHRS_M2.xml due to: Error reading end tag. 2018-05-15T18:05:02.030Z,1526407502.030 [MissionManager](CRITICAL): Could not load mission ./Missions/Maintenance/calibrateAHRS_M2.xml 2018-05-15T18:05:02.030Z,1526407502.030 [CommandLine](CRITICAL): Could not load ./Missions/Maintenance/calibrateAHRS_M2.xml 2018-05-15T18:05:02.136Z,1526407502.136 [CBIT](INFO): Critical error at 20180515T180502 2018-05-15T18:07:00.867Z,1526407620.867 [DeadReckonUsingMultipleVelocitySources](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2018-05-15T18:07:00.868Z,1526407620.868 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2 2018-05-15T18:07:00.868Z,1526407620.868 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2018-05-15T18:07:00.869Z,1526407620.869 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2018-05-15T18:07:00.869Z,1526407620.869 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 2 2018-05-15T18:07:00.869Z,1526407620.869 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault 2018-05-15T18:07:00.895Z,1526407620.895 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2018-05-15T18:07:00.896Z,1526407620.896 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator 2018-05-15T18:07:01.262Z,1526407621.262 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2018-05-15T18:07:01.262Z,1526407621.262 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2 2018-05-15T18:07:01.263Z,1526407621.263 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator 2018-05-15T18:07:01.263Z,1526407621.263 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 2 2018-05-15T18:07:01.627Z,1526407621.627 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component. 2018-05-15T18:07:01.627Z,1526407621.627 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s. 2018-05-15T18:07:01.627Z,1526407621.627 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s. 2018-05-15T18:07:01.628Z,1526407621.628 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component. 2018-05-15T18:07:01.628Z,1526407621.628 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s. 2018-05-15T18:07:01.629Z,1526407621.629 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s. 2018-05-15T18:07:02.035Z,1526407622.035 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 1.2 s old, using for 20.0 s. 2018-05-15T18:07:02.440Z,1526407622.440 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 1.6 s old, using for 20.0 s. 2018-05-15T18:07:02.835Z,1526407622.835 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 2.0 s old, using for 20.0 s. 2018-05-15T18:07:03.230Z,1526407623.230 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 2.4 s old, using for 20.0 s. 2018-05-15T18:07:03.629Z,1526407623.629 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 2.8 s old, using for 20.0 s. 2018-05-15T18:07:04.035Z,1526407624.035 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 3.2 s old, using for 20.0 s. 2018-05-15T18:07:04.430Z,1526407624.430 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 3.6 s old, using for 20.0 s. 2018-05-15T18:07:04.836Z,1526407624.836 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 4.0 s old, using for 20.0 s. 2018-05-15T18:07:05.226Z,1526407625.226 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 4.4 s old, using for 20.0 s. 2018-05-15T18:07:05.635Z,1526407625.635 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 4.8 s old, using for 20.0 s. 2018-05-15T18:07:06.029Z,1526407626.029 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 5.2 s old, using for 20.0 s. 2018-05-15T18:07:06.435Z,1526407626.435 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 5.6 s old, using for 20.0 s. 2018-05-15T18:07:06.845Z,1526407626.845 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 6.0 s old, using for 20.0 s. 2018-05-15T18:07:07.233Z,1526407627.233 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 6.4 s old, using for 20.0 s. 2018-05-15T18:07:07.630Z,1526407627.630 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 6.8 s old, using for 20.0 s. 2018-05-15T18:07:08.034Z,1526407628.034 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 7.2 s old, using for 20.0 s. 2018-05-15T18:07:08.432Z,1526407628.432 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 7.6 s old, using for 20.0 s. 2018-05-15T18:07:08.835Z,1526407628.835 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 8.0 s old, using for 20.0 s. 2018-05-15T18:07:09.233Z,1526407629.233 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 8.4 s old, using for 20.0 s. 2018-05-15T18:07:09.639Z,1526407629.639 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 8.8 s old, using for 20.0 s. 2018-05-15T18:07:10.035Z,1526407630.035 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 9.2 s old, using for 20.0 s. 2018-05-15T18:07:10.434Z,1526407630.434 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 9.6 s old, using for 20.0 s. 2018-05-15T18:07:10.843Z,1526407630.843 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 10.0 s old, using for 20.0 s. 2018-05-15T18:07:11.240Z,1526407631.240 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 10.4 s old, using for 20.0 s. 2018-05-15T18:07:11.641Z,1526407631.641 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 10.8 s old, using for 20.0 s. 2018-05-15T18:07:12.032Z,1526407632.032 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 11.2 s old, using for 20.0 s. 2018-05-15T18:07:12.443Z,1526407632.443 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 11.6 s old, using for 20.0 s. 2018-05-15T18:07:12.845Z,1526407632.845 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 12.0 s old, using for 20.0 s. 2018-05-15T18:07:13.240Z,1526407633.240 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 12.4 s old, using for 20.0 s. 2018-05-15T18:07:13.640Z,1526407633.640 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 12.8 s old, using for 20.0 s. 2018-05-15T18:07:14.038Z,1526407634.038 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 13.2 s old, using for 20.0 s. 2018-05-15T18:07:14.440Z,1526407634.440 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 13.6 s old, using for 20.0 s. 2018-05-15T18:07:14.839Z,1526407634.839 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 14.0 s old, using for 20.0 s. 2018-05-15T18:07:15.236Z,1526407635.236 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 14.4 s old, using for 20.0 s. 2018-05-15T18:07:15.636Z,1526407635.636 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 14.8 s old, using for 20.0 s. 2018-05-15T18:07:16.035Z,1526407636.035 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 15.2 s old, using for 20.0 s. 2018-05-15T18:07:16.442Z,1526407636.442 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 15.6 s old, using for 20.0 s. 2018-05-15T18:07:16.840Z,1526407636.840 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 16.0 s old, using for 20.0 s. 2018-05-15T18:07:17.235Z,1526407637.235 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 16.4 s old, using for 20.0 s. 2018-05-15T18:07:17.641Z,1526407637.641 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 16.8 s old, using for 20.0 s. 2018-05-15T18:07:18.040Z,1526407638.040 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 17.2 s old, using for 20.0 s. 2018-05-15T18:07:18.439Z,1526407638.439 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 17.6 s old, using for 20.0 s. 2018-05-15T18:07:18.850Z,1526407638.850 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 18.0 s old, using for 20.0 s. 2018-05-15T18:07:19.248Z,1526407639.248 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 18.4 s old, using for 20.0 s. 2018-05-15T18:07:19.638Z,1526407639.638 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 18.8 s old, using for 20.0 s. 2018-05-15T18:07:20.043Z,1526407640.043 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 19.2 s old, using for 20.0 s. 2018-05-15T18:07:20.439Z,1526407640.439 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 19.6 s old, using for 20.0 s. 2018-05-15T18:07:20.842Z,1526407640.842 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 20.0 s old, using for 20.0 s. 2018-05-15T18:07:29.286Z,1526407649.286 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/calibrateAHRS_M2.xml 2018-05-15T18:07:29.287Z,1526407649.287 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/calibrateAHRS_M2.xml 2018-05-15T18:07:29.370Z,1526407649.370 [MissionManager](INFO): DefineArg compassCal.MissionTimeout = 60.000000 min 2018-05-15T18:07:29.374Z,1526407649.374 [MissionManager](INFO): DefineArg compassCal.NeedCommsTime = 6.000000 min 2018-05-15T18:07:29.377Z,1526407649.377 [MissionManager](INFO): DefineArg compassCal.YoYoMinDepth = 2.000000 m 2018-05-15T18:07:29.380Z,1526407649.380 [MissionManager](INFO): DefineArg compassCal.YoYoMaxDepth = 200.000000 m 2018-05-15T18:07:29.383Z,1526407649.383 [MissionManager](INFO): DefineArg compassCal.YoYoMinAltitude = 7.000000 m 2018-05-15T18:07:29.386Z,1526407649.386 [MissionManager](INFO): DefineArg compassCal.YoYoPitch = 30.000000 arcdeg 2018-05-15T18:07:29.389Z,1526407649.389 [MissionManager](INFO): DefineArg compassCal.RudderAngle = 13.000000 arcdeg 2018-05-15T18:07:29.392Z,1526407649.392 [MissionManager](INFO): DefineArg compassCal.Speed = 1.000000 m/s 2018-05-15T18:07:29.395Z,1526407649.395 [MissionManager](INFO): DefineArg compassCal.CalibrationInitTimeout = 2.000000 min 2018-05-15T18:07:29.422Z,1526407649.422 [MissionManager](INFO): DefineArg compassCal.MinAltitude = 5.000000 m 2018-05-15T18:07:29.425Z,1526407649.425 [MissionManager](INFO): DefineArg compassCal.MaxDepth = 205.000000 m 2018-05-15T18:07:29.428Z,1526407649.428 [MissionManager](INFO): DefineArg compassCal.MinOffshore = 2.000000 km 2018-05-15T18:07:29.429Z,1526407649.429 [MissionManager](INFO): Inserting Stack: Missions/Insert/NeedComms.xml 2018-05-15T18:07:29.534Z,1526407649.534 [MissionManager](INFO): DefineArg compassCal:NeedComms.DiveInterval = 3.000000 h 2018-05-15T18:07:29.538Z,1526407649.538 [MissionManager](INFO): DefineArg compassCal:NeedComms.WaitForPitchUp = 10.000000 min 2018-05-15T18:07:29.545Z,1526407649.545 [MissionManager](INFO): DefineArg compassCal:NeedComms.SurfacePitch = 20.000000 arcdeg 2018-05-15T18:07:29.548Z,1526407649.548 [MissionManager](INFO): DefineArg compassCal:NeedComms.SurfaceDepthRate = nan m/s 2018-05-15T18:07:29.607Z,1526407649.607 [MissionManager](INFO): DefineArg compassCal:NeedComms.SurfaceSpeed = 1.000000 m/s 2018-05-15T18:07:29.614Z,1526407649.614 [MissionManager](INFO): DefineArg compassCal:NeedComms.GPSTimeout = 7.000000 min 2018-05-15T18:07:29.634Z,1526407649.634 [MissionManager](INFO): DefineArg compassCal:NeedComms.CommsTimeout = 30.000000 min 2018-05-15T18:07:29.652Z,1526407649.652 [compassCal:NeedComms:B.GoToSurface](DEBUG): Construct GoToSurface. 2018-05-15T18:07:29.707Z,1526407649.707 [MissionManager](INFO): Inserting Stack: Missions/Insert/StandardEnvelopes.xml 2018-05-15T18:07:29.748Z,1526407649.748 [MissionManager](INFO): DefineArg compassCal:StandardEnvelopes.MinAltitude = 5.000000 m 2018-05-15T18:07:29.751Z,1526407649.751 [MissionManager](INFO): DefineArg compassCal:StandardEnvelopes.MaxDepth = 200.000000 m 2018-05-15T18:07:29.776Z,1526407649.776 [MissionManager](INFO): DefineArg compassCal:StandardEnvelopes.MinOffshore = 2000.000000 m 2018-05-15T18:07:29.777Z,1526407649.777 [compassCal:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope. 2018-05-15T18:07:29.784Z,1526407649.784 [compassCal:StandardEnvelopes:B.DepthEnvelope](DEBUG): Construct DepthEnvelope. 2018-05-15T18:07:29.816Z,1526407649.816 [compassCal:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope. 2018-05-15T18:07:29.830Z,1526407649.830 [compassCal:H.Pitch](DEBUG): Construct. 2018-05-15T18:07:29.853Z,1526407649.853 [compassCal:I.Buoyancy](DEBUG): Construct Buoyancy. 2018-05-15T18:07:29.856Z,1526407649.856 [compassCal:J.DepthEnvelope](DEBUG): Construct DepthEnvelope. 2018-05-15T18:07:29.878Z,1526407649.878 [compassCal:K.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope. 2018-05-15T18:07:29.895Z,1526407649.895 [compassCal:L.YoYo](DEBUG): Construct YoYo. 2018-05-15T18:07:29.922Z,1526407649.922 [compassCal:Calibration:WaitForCalibrationInit:A_Timeout:B.Execute](DEBUG): Construct Execute. 2018-05-15T18:07:29.931Z,1526407649.931 [compassCal:Calibration:AcquireCalibrationPoints:A.Point](DEBUG): Construct. 2018-05-15T18:07:29.946Z,1526407649.946 [compassCal:Calibration:AcquireCalibrationPoints:B.SetSpeed](DEBUG): Construct. 2018-05-15T18:07:29.972Z,1526407649.972 [compassCal:Calibration:D.CalibrateAHRS_M2](DEBUG): Construct CalibrateSparton. 2018-05-15T18:07:30.026Z,1526407650.026 [MissionManager](DEBUG): This mission yoyos in a spiral while calibrating the Sparton AHRS-M2 Micro AHRS/IMU with AdaptCal. Maximum duration of mission 60 Elapsed time after previous surface communications when vehicle will begin to ascend for additional surface communications 6 Minimum depth while performing the YoYo behavior. 2 Maximum depth while performing the YoYo behavior. 200 Minimum altitude while performing the YoYo behavior (for bottom-terminated YoYos). 7 Pitch (plus and minus) for yo-yo behavior. 30 Rudder angle to use while performing the spiral cast. 13 Vehicle speed. 1 Elapsed time allowed for calibration to initialize 2 Minimum height above the sea floor for the entire mission. 5 Maximum depth for the entire mission. 205 Minimum offshore distance for the entire mission. 2 Another depth envelope for the YoYo behavior. This envelope should fall within the limits of the standard safety envelopes in Insert/StandardEnvelopes.xml in order to avoid commanding high pitch angles for depth-terminated YoYos. Another altitude envelope for the YoYo behavior. This envelope should fall within the limits of the standard safety envelopes in Insert/StandardEnvelopes.xml in order to avoid commanding high pitch angles for bottom-terminated YoYos. Failed to initialize calibration within timeout. Stopping mission. stop AdaptCal initialized. Acquiring calibration points. 2018-05-15T18:07:30.027Z,1526407650.027 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/calibrateAHRS_M2.xml 2018-05-15T18:08:04.691Z,1526407684.691 [CommandLine](IMPORTANT): got command maintain sensor NAL9602.latitude_fix 36.796001 degree 2018-05-15T18:08:04.692Z,1526407684.692 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.latitude_fix" handled in the control thread. 2018-05-15T18:08:04.694Z,1526407684.694 [CommandLine](IMPORTANT): got command maintain sensor NAL9602.longitude_fix -121.911003 degree 2018-05-15T18:08:04.695Z,1526407684.695 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.longitude_fix" handled in the control thread. 2018-05-15T18:08:04.835Z,1526407684.835 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,AcousticModem_Benthos_ATM900,DataOverHttps,Depth_Keller,NAL9602,Onboard,BPC1,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,Maintain_NAL9602.latitude_fix,Maintain_NAL9602.longitude_fix,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,VerticalTemperatureHomogeneityIndexCalculator,YawRateCalculator,ElevatorOffsetCalculator,StratificationFrontDetector,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2018-05-15T18:08:20.591Z,1526407700.591 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1526407680.000000 second 2018-05-15T18:08:20.819Z,1526407700.819 [Default:CheckIn:Read_GPS] Stopped 2018-05-15T18:08:20.819Z,1526407700.819 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-05-15T18:08:21.220Z,1526407701.220 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2018-05-15T18:08:24.912Z,1526407704.912 [DataOverHttps](INFO): Sending 230 bytes from file Logs/20180515T180049/Courier0004.lzma 2018-05-15T18:08:25.710Z,1526407705.710 [DataOverHttps](INFO): Moved sent file to Logs/20180515T180049/Courier0004.lzma.bak 2018-05-15T18:08:25.711Z,1526407705.711 [DataOverHttps](INFO): SBD MOMSN=8282376 2018-05-15T18:08:32.180Z,1526407712.180 [CommandLine](IMPORTANT): got command run 2018-05-15T18:08:32.183Z,1526407712.183 [CommandLine](IMPORTANT): Running 2018-05-15T18:08:32.241Z,1526407712.241 [Default] Stopped 2018-05-15T18:08:32.241Z,1526407712.241 [Default](DEBUG): Aggregate::uninitialize Default 2018-05-15T18:08:32.241Z,1526407712.241 [Default:B.GoToSurface] Stopped 2018-05-15T18:08:32.241Z,1526407712.241 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2018-05-15T18:08:32.241Z,1526407712.241 [Default:CheckIn] Stopped 2018-05-15T18:08:32.241Z,1526407712.241 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-05-15T18:08:32.241Z,1526407712.241 [Default:CheckIn:Read_Iridium] Stopped 2018-05-15T18:08:32.241Z,1526407712.241 [MissionManager](IMPORTANT): Started mission compassCal 2018-05-15T18:08:32.242Z,1526407712.242 [compassCal] Running Loop=1 2018-05-15T18:08:32.242Z,1526407712.242 [compassCal](DEBUG): Aggregate::initialize compassCal 2018-05-15T18:08:32.242Z,1526407712.242 [compassCal:StandardEnvelopes] Running Loop=1 2018-05-15T18:08:32.242Z,1526407712.242 [compassCal:StandardEnvelopes](DEBUG): Aggregate::initialize compassCal:StandardEnvelopes 2018-05-15T18:08:32.242Z,1526407712.242 [compassCal:StandardEnvelopes:A.AltitudeEnvelope] Running Loop=1 2018-05-15T18:08:32.242Z,1526407712.242 [compassCal:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent. 2018-05-15T18:08:32.242Z,1526407712.242 [compassCal:StandardEnvelopes:B.DepthEnvelope] Running Loop=1 2018-05-15T18:08:32.242Z,1526407712.242 [compassCal:StandardEnvelopes:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent. 2018-05-15T18:08:32.243Z,1526407712.243 [compassCal:StandardEnvelopes:C.OffshoreEnvelope] Running Loop=1 2018-05-15T18:08:32.243Z,1526407712.243 [compassCal:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent. 2018-05-15T18:08:32.243Z,1526407712.243 [compassCal:H.Pitch] Running Loop=1 2018-05-15T18:08:32.243Z,1526407712.243 [compassCal:H.Pitch](DEBUG): Initialize. 2018-05-15T18:08:32.243Z,1526407712.243 [compassCal:I.Buoyancy] Running Loop=1 2018-05-15T18:08:32.243Z,1526407712.243 [compassCal:I.Buoyancy](DEBUG): Initialize Buoyancy Component. 2018-05-15T18:08:32.243Z,1526407712.243 [compassCal:J.DepthEnvelope] Running Loop=1 2018-05-15T18:08:32.243Z,1526407712.243 [compassCal:J.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent. 2018-05-15T18:08:32.244Z,1526407712.244 [compassCal:K.AltitudeEnvelope] Running Loop=1 2018-05-15T18:08:32.244Z,1526407712.244 [compassCal:K.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent. 2018-05-15T18:08:32.244Z,1526407712.244 [compassCal:L.YoYo] Running Loop=1 2018-05-15T18:08:32.244Z,1526407712.244 [compassCal:L.YoYo](DEBUG): Initialize YoYoComponent. 2018-05-15T18:08:32.244Z,1526407712.244 [compassCal:B] Running Loop=1 2018-05-15T18:08:32.245Z,1526407712.245 [compassCal:L.YoYo] Running Loop=1 2018-05-15T18:08:32.250Z,1526407712.250 [compassCal:K.AltitudeEnvelope] Running Loop=1 2018-05-15T18:08:32.267Z,1526407712.267 [compassCal:J.DepthEnvelope] Running Loop=1 2018-05-15T18:08:32.272Z,1526407712.272 [compassCal:I.Buoyancy] Running Loop=1 2018-05-15T18:08:32.297Z,1526407712.297 [compassCal:H.Pitch] Running Loop=1 2018-05-15T18:08:32.301Z,1526407712.301 [compassCal:StandardEnvelopes] Running Loop=1 2018-05-15T18:08:32.301Z,1526407712.301 [compassCal:StandardEnvelopes:C.OffshoreEnvelope] Running Loop=1 2018-05-15T18:08:32.306Z,1526407712.306 [compassCal:StandardEnvelopes:B.DepthEnvelope] Running Loop=1 2018-05-15T18:08:32.322Z,1526407712.322 [compassCal:StandardEnvelopes:A.AltitudeEnvelope] Running Loop=1 2018-05-15T18:08:32.328Z,1526407712.328 [compassCal:B] Stopped 2018-05-15T18:08:32.328Z,1526407712.328 [compassCal:D] Running Loop=1 2018-05-15T18:08:32.627Z,1526407712.627 [compassCal:D] Stopped 2018-05-15T18:08:32.627Z,1526407712.627 [compassCal:E] Running Loop=1 2018-05-15T18:08:35.731Z,1526407715.731 [compassCal:E] Stopped 2018-05-15T18:08:35.731Z,1526407715.731 [compassCal:F] Running Loop=1 2018-05-15T18:08:35.798Z,1526407715.798 [DataOverHttps](INFO): Sending 1033 bytes from file Logs/20180515T050444/Express0001.lzma 2018-05-15T18:08:35.878Z,1526407715.878 [compassCal:F] Stopped 2018-05-15T18:08:35.878Z,1526407715.878 [compassCal:StartingMission] Running Loop=1 2018-05-15T18:08:35.878Z,1526407715.878 [compassCal:StartingMission](DEBUG): Aggregate::initialize compassCal:StartingMission 2018-05-15T18:08:36.242Z,1526407716.242 [compassCal:NeedComms] Running Loop=1 2018-05-15T18:08:36.242Z,1526407716.242 [compassCal:NeedComms](DEBUG): Aggregate::initialize compassCal:NeedComms 2018-05-15T18:08:36.242Z,1526407716.242 [compassCal:NeedComms:B.GoToSurface] Running Loop=1 2018-05-15T18:08:36.242Z,1526407716.242 [compassCal:NeedComms:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2018-05-15T18:08:36.242Z,1526407716.242 [compassCal:NeedComms:B.GoToSurface](INFO): Received depth rate setting nan m/s. 2018-05-15T18:08:36.243Z,1526407716.243 [compassCal:NeedComms:B.GoToSurface](INFO): Received pitch setting 19.999999 degrees. 2018-05-15T18:08:36.243Z,1526407716.243 [compassCal:NeedComms:B.GoToSurface](INFO): Received speed setting 1.000000 m/s. 2018-05-15T18:08:36.244Z,1526407716.244 [compassCal:NeedComms:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2018-05-15T18:08:36.244Z,1526407716.244 [compassCal:NeedComms:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2018-05-15T18:08:36.244Z,1526407716.244 [compassCal:NeedComms:A] Running Loop=1 2018-05-15T18:08:36.250Z,1526407716.250 [compassCal:NeedComms:A](INFO): last time_fix was: 1526407680.000000 second since 1970/01/01T00:00:00Z 2018-05-15T18:08:36.251Z,1526407716.251 [compassCal:NeedComms:A] Stopped 2018-05-15T18:08:36.590Z,1526407716.590 [DataOverHttps](INFO): Moved sent file to Logs/20180515T050444/Express0001.lzma.bak 2018-05-15T18:08:36.591Z,1526407716.591 [DataOverHttps](INFO): SBD MOMSN=8282382 2018-05-15T18:08:36.668Z,1526407716.668 [compassCal:NeedComms:C] Running Loop=1 2018-05-15T18:08:37.061Z,1526407717.061 [compassCal:NeedComms:C](DEBUG): Initialize ReadDataComponent to sense time_fix 2018-05-15T18:09:10.798Z,1526407750.798 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1526407680.000000 second 2018-05-15T18:09:10.859Z,1526407750.859 [compassCal:NeedComms:C] Stopped 2018-05-15T18:09:10.860Z,1526407750.860 [compassCal:NeedComms:D] Running Loop=1 2018-05-15T18:09:11.234Z,1526407751.234 [compassCal:NeedComms:D](DEBUG): Initialize ReadDataComponent to sense platform_communications 2018-05-15T18:09:17.509Z,1526407757.509 [DataOverHttps](INFO): Sending 43 bytes from file Logs/20180515T180049/Courier0007.lzma 2018-05-15T18:09:18.298Z,1526407758.298 [DataOverHttps](INFO): Moved sent file to Logs/20180515T180049/Courier0007.lzma.bak 2018-05-15T18:09:18.298Z,1526407758.298 [DataOverHttps](INFO): SBD MOMSN=8282414 2018-05-15T18:09:27.938Z,1526407767.938 [DataOverHttps](INFO): Sending 94 bytes from file Logs/20180515T050444/Express0005.lzma 2018-05-15T18:09:28.727Z,1526407768.727 [DataOverHttps](INFO): Moved sent file to Logs/20180515T050444/Express0005.lzma.bak 2018-05-15T18:09:28.727Z,1526407768.727 [DataOverHttps](INFO): SBD MOMSN=8282416 2018-05-15T18:09:29.106Z,1526407769.106 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1526407808.000000 second 2018-05-15T18:09:39.669Z,1526407779.669 [DataOverHttps](INFO): Sending 1026 bytes from file Logs/20180515T175722/Express0001.lzma 2018-05-15T18:09:40.454Z,1526407780.454 [DataOverHttps](INFO): Moved sent file to Logs/20180515T175722/Express0001.lzma.bak 2018-05-15T18:09:40.454Z,1526407780.454 [DataOverHttps](INFO): SBD MOMSN=8282420 2018-05-15T18:09:41.468Z,1526407781.468 [NAL9602](INFO): Powering down 2018-05-15T18:09:51.365Z,1526407791.365 [DataOverHttps](INFO): Sending 78 bytes from file Logs/20180515T175722/Express0005.lzma 2018-05-15T18:09:52.966Z,1526407792.966 [DataOverHttps](INFO): Moved sent file to Logs/20180515T175722/Express0005.lzma.bak 2018-05-15T18:09:52.966Z,1526407792.966 [DataOverHttps](INFO): SBD MOMSN=8282454 2018-05-15T18:10:03.693Z,1526407803.693 [DataOverHttps](INFO): Sending 1015 bytes from file Logs/20180515T180049/Express0001.lzma 2018-05-15T18:10:04.461Z,1526407804.461 [DataOverHttps](INFO): Moved sent file to Logs/20180515T180049/Express0001.lzma.bak 2018-05-15T18:10:04.462Z,1526407804.462 [DataOverHttps](INFO): SBD MOMSN=8282457 2018-05-15T18:10:09.758Z,1526407809.758 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1526407808.000000 second 2018-05-15T18:10:15.207Z,1526407815.207 [DataOverHttps](INFO): Sending 383 bytes from file Logs/20180515T180049/Express0005.lzma 2018-05-15T18:10:15.995Z,1526407815.995 [DataOverHttps](INFO): Moved sent file to Logs/20180515T180049/Express0005.lzma.bak 2018-05-15T18:10:15.995Z,1526407815.995 [DataOverHttps](INFO): SBD MOMSN=8282489 2018-05-15T18:10:26.929Z,1526407826.929 [DataOverHttps](INFO): Sending 175 bytes from file Logs/20180515T180049/Express0008.lzma 2018-05-15T18:10:27.694Z,1526407827.694 [DataOverHttps](INFO): Moved sent file to Logs/20180515T180049/Express0008.lzma.bak 2018-05-15T18:10:27.695Z,1526407827.695 [DataOverHttps](INFO): SBD MOMSN=8282499 2018-05-15T18:10:28.730Z,1526407828.730 [compassCal:NeedComms:D] Stopped 2018-05-15T18:10:28.731Z,1526407828.731 [compassCal:NeedComms:E] Running Loop=1 2018-05-15T18:10:28.865Z,1526407828.865 [compassCal:NeedComms:E](DEBUG): Initialize ReadDataComponent to sense time_fix 2018-05-15T18:10:31.927Z,1526407831.927 [NAL9602](INFO): Powering up 2018-05-15T18:10:32.791Z,1526407832.791 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1526407808.000000 second 2018-05-15T18:10:32.900Z,1526407832.900 [compassCal:NeedComms:E] Stopped 2018-05-15T18:10:32.901Z,1526407832.901 [compassCal:NeedComms](INFO): Completed compassCal:NeedComms 2018-05-15T18:10:32.901Z,1526407832.901 [compassCal:NeedComms] Stopped 2018-05-15T18:10:32.901Z,1526407832.901 [compassCal:NeedComms](DEBUG): Aggregate::uninitialize compassCal:NeedComms 2018-05-15T18:10:32.901Z,1526407832.901 [compassCal:NeedComms:B.GoToSurface] Stopped 2018-05-15T18:10:32.901Z,1526407832.901 [compassCal:NeedComms:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2018-05-15T18:10:33.292Z,1526407833.292 [compassCal:StartingMission](INFO): Completed compassCal:StartingMission 2018-05-15T18:10:33.292Z,1526407833.292 [compassCal:StartingMission] Stopped 2018-05-15T18:10:33.292Z,1526407833.292 [compassCal:StartingMission](DEBUG): Aggregate::uninitialize compassCal:StartingMission 2018-05-15T18:10:33.292Z,1526407833.292 [compassCal:Calibration] Running Loop=1 2018-05-15T18:10:33.292Z,1526407833.292 [compassCal:Calibration](DEBUG): Aggregate::initialize compassCal:Calibration 2018-05-15T18:10:33.292Z,1526407833.292 [compassCal:Calibration:D.CalibrateAHRS_M2] Running Loop=1 2018-05-15T18:10:33.292Z,1526407833.292 [compassCal:Calibration:D.CalibrateAHRS_M2](INFO): Initialize CalibrateSpartonComponent. 2018-05-15T18:10:33.297Z,1526407833.297 [compassCal:Calibration:WaitForCalibrationInit] Running Loop=1 2018-05-15T18:10:33.713Z,1526407833.713 [AHRS_M2](INFO): Data-stream disabled. 2018-05-15T18:10:33.749Z,1526407833.749 [AHRS_M2](INFO): Set clearPointCal. 2018-05-15T18:10:33.799Z,1526407833.799 [DeadReckonUsingMultipleVelocitySources](DEBUG): Most recent orientation data is 0.531042 seconds old. 2018-05-15T18:10:33.802Z,1526407833.802 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 0.531379 seconds old. 2018-05-15T18:10:33.805Z,1526407833.805 [compassCal:Calibration:D.CalibrateAHRS_M2] Running Loop=1 2018-05-15T18:10:33.805Z,1526407833.805 [compassCal:Calibration:D.CalibrateAHRS_M2](INFO): Initialize CalibrateSpartonComponent. 2018-05-15T18:10:33.811Z,1526407833.811 [compassCal:Calibration:WaitForCalibrationInit](DEBUG): Initialize ReadDataComponent to sense AHRS_M2.CompassCalState 2018-05-15T18:10:34.049Z,1526407834.049 [AHRS_M2](INFO): Set initCalPointBuffer. 2018-05-15T18:10:34.100Z,1526407834.100 [DeadReckonUsingMultipleVelocitySources](DEBUG): Most recent orientation data is 0.831762 seconds old. 2018-05-15T18:10:34.107Z,1526407834.107 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 0.836450 seconds old. 2018-05-15T18:10:34.115Z,1526407834.115 [compassCal:Calibration:D.CalibrateAHRS_M2](INFO): Initialize CalibrateSpartonComponent. 2018-05-15T18:10:34.449Z,1526407834.449 [AHRS_M2](INFO): Set autoFieldCalActive. 2018-05-15T18:10:34.473Z,1526407834.473 [AHRS_M2](INFO): Data-stream active. 2018-05-15T18:10:34.542Z,1526407834.542 [DeadReckonUsingMultipleVelocitySources](DEBUG): Most recent orientation data is 1.274431 seconds old. 2018-05-15T18:10:34.545Z,1526407834.545 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 1.274644 seconds old. 2018-05-15T18:10:34.559Z,1526407834.559 [compassCal:Calibration:D.CalibrateAHRS_M2](INFO): Initialize CalibrateSpartonComponent. 2018-05-15T18:10:34.559Z,1526407834.559 [compassCal:Calibration:WaitForCalibrationInit] Stopped 2018-05-15T18:10:34.559Z,1526407834.559 [compassCal:Calibration:B] Running Loop=1 2018-05-15T18:10:34.902Z,1526407834.902 [compassCal:Calibration:B](IMPORTANT): AdaptCal initialized. Acquiring calibration points. 2018-05-15T18:10:34.903Z,1526407834.903 [compassCal:Calibration:B] Stopped 2018-05-15T18:10:34.903Z,1526407834.903 [compassCal:Calibration:AcquireCalibrationPoints] Running Loop=1 2018-05-15T18:10:34.903Z,1526407834.903 [compassCal:Calibration:AcquireCalibrationPoints](DEBUG): Aggregate::initialize compassCal:Calibration:AcquireCalibrationPoints 2018-05-15T18:10:34.903Z,1526407834.903 [compassCal:Calibration:AcquireCalibrationPoints:A.Point] Running Loop=1 2018-05-15T18:10:34.903Z,1526407834.903 [compassCal:Calibration:AcquireCalibrationPoints:A.Point](DEBUG): Initialize. 2018-05-15T18:10:34.903Z,1526407834.903 [compassCal:Calibration:AcquireCalibrationPoints:B.SetSpeed] Running Loop=1 2018-05-15T18:10:34.904Z,1526407834.904 [compassCal:Calibration:AcquireCalibrationPoints:B.SetSpeed](DEBUG): Initialize. 2018-05-15T18:10:35.284Z,1526407835.284 [compassCal:Calibration:AcquireCalibrationPoints:B.SetSpeed] Running Loop=1 2018-05-15T18:10:35.297Z,1526407835.297 [compassCal:Calibration:AcquireCalibrationPoints:A.Point] Running Loop=1 2018-05-15T18:11:04.048Z,1526407864.048 [NAL9602](INFO): Powering down 2018-05-15T18:11:39.370Z,1526407899.370 [CommandLine](IMPORTANT): got command stop 2018-05-15T18:11:39.370Z,1526407899.370 [CommandLine](IMPORTANT): Scheduling is paused 2018-05-15T18:11:39.371Z,1526407899.371 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop 2018-05-15T18:11:39.734Z,1526407899.734 [MissionManager](INFO): MissionManager is completed. 2018-05-15T18:11:39.734Z,1526407899.734 [MissionManager](INFO): Uninitializing Mission compassCal 2018-05-15T18:11:39.735Z,1526407899.735 [compassCal] Stopped 2018-05-15T18:11:39.735Z,1526407899.735 [compassCal](DEBUG): Aggregate::uninitialize compassCal 2018-05-15T18:11:39.735Z,1526407899.735 [compassCal:StandardEnvelopes] Stopped 2018-05-15T18:11:39.735Z,1526407899.735 [compassCal:StandardEnvelopes](DEBUG): Aggregate::uninitialize compassCal:StandardEnvelopes 2018-05-15T18:11:39.735Z,1526407899.735 [compassCal:StandardEnvelopes:A.AltitudeEnvelope] Stopped 2018-05-15T18:11:39.735Z,1526407899.735 [compassCal:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent. 2018-05-15T18:11:39.735Z,1526407899.735 [compassCal:StandardEnvelopes:B.DepthEnvelope] Stopped 2018-05-15T18:11:39.735Z,1526407899.735 [compassCal:StandardEnvelopes:B.DepthEnvelope](DEBUG): Uninitialize. 2018-05-15T18:11:39.735Z,1526407899.735 [compassCal:StandardEnvelopes:C.OffshoreEnvelope] Stopped 2018-05-15T18:11:39.735Z,1526407899.735 [compassCal:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent. 2018-05-15T18:11:39.735Z,1526407899.735 [compassCal:H.Pitch] Stopped 2018-05-15T18:11:39.735Z,1526407899.735 [compassCal:I.Buoyancy] Stopped 2018-05-15T18:11:39.735Z,1526407899.735 [compassCal:I.Buoyancy](DEBUG): Uninitialize Buoyancy Component. 2018-05-15T18:11:39.736Z,1526407899.736 [compassCal:J.DepthEnvelope] Stopped 2018-05-15T18:11:39.736Z,1526407899.736 [compassCal:J.DepthEnvelope](DEBUG): Uninitialize. 2018-05-15T18:11:39.736Z,1526407899.736 [compassCal:K.AltitudeEnvelope] Stopped 2018-05-15T18:11:39.736Z,1526407899.736 [compassCal:K.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent. 2018-05-15T18:11:39.736Z,1526407899.736 [compassCal:L.YoYo] Stopped 2018-05-15T18:11:39.736Z,1526407899.736 [compassCal:L.YoYo](DEBUG): Uninitialize YoYoComponent. 2018-05-15T18:11:39.736Z,1526407899.736 [compassCal:Calibration] Stopped 2018-05-15T18:11:39.736Z,1526407899.736 [compassCal:Calibration](DEBUG): Aggregate::uninitialize compassCal:Calibration 2018-05-15T18:11:39.736Z,1526407899.736 [compassCal:Calibration:AcquireCalibrationPoints] Stopped 2018-05-15T18:11:39.736Z,1526407899.736 [compassCal:Calibration:AcquireCalibrationPoints](DEBUG): Aggregate::uninitialize compassCal:Calibration:AcquireCalibrationPoints 2018-05-15T18:11:39.737Z,1526407899.737 [compassCal:Calibration:AcquireCalibrationPoints:A.Point] Stopped 2018-05-15T18:11:39.737Z,1526407899.737 [compassCal:Calibration:AcquireCalibrationPoints:B.SetSpeed] Stopped 2018-05-15T18:11:39.737Z,1526407899.737 [compassCal:Calibration:AcquireCalibrationPoints:B.SetSpeed](DEBUG): Uninitialize. 2018-05-15T18:11:39.737Z,1526407899.737 [compassCal:Calibration:D.CalibrateAHRS_M2] Stopped 2018-05-15T18:11:39.737Z,1526407899.737 [compassCal:Calibration:D.CalibrateAHRS_M2](INFO): Uninitialize CalibrateSpartonComponent. 2018-05-15T18:11:40.101Z,1526407900.101 [AHRS_M2](INFO): Data-stream disabled. 2018-05-15T18:11:40.127Z,1526407900.127 [AHRS_M2](INFO): Un-set autoFieldCalActive. 2018-05-15T18:11:40.161Z,1526407900.161 [DeadReckonUsingMultipleVelocitySources](DEBUG): Most recent orientation data is 0.437101 seconds old. 2018-05-15T18:11:40.164Z,1526407900.164 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 0.437219 seconds old. 2018-05-15T18:11:40.167Z,1526407900.167 [MissionManager](IMPORTANT): Started mission Default 2018-05-15T18:11:40.167Z,1526407900.167 [Default] Running Loop=1 2018-05-15T18:11:40.167Z,1526407900.167 [Default](DEBUG): Aggregate::initialize Default 2018-05-15T18:11:40.167Z,1526407900.167 [Default:B.GoToSurface] Running Loop=1 2018-05-15T18:11:40.168Z,1526407900.168 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2018-05-15T18:11:40.168Z,1526407900.168 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2018-05-15T18:11:40.168Z,1526407900.168 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2018-05-15T18:11:40.185Z,1526407900.185 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2018-05-15T18:11:40.185Z,1526407900.185 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2018-05-15T18:11:40.186Z,1526407900.186 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2018-05-15T18:11:40.186Z,1526407900.186 [Default:A.Wait] Running Loop=1 2018-05-15T18:11:40.186Z,1526407900.186 [Default:A.Wait](DEBUG): Initialize Wait Component. 2018-05-15T18:11:40.501Z,1526407900.501 [AHRS_M2](INFO): magFieldCalErr di. - Response was aFiedaErri. 2018-05-15T18:11:40.502Z,1526407900.502 [AHRS_M2](IMPORTANT): Magnetic calibration quality (0[best] to 10000) is 0.000000. 2018-05-15T18:11:40.529Z,1526407900.529 [AHRS_M2](INFO): Data-stream active. 2018-05-15T18:11:40.587Z,1526407900.587 [DeadReckonUsingMultipleVelocitySources](DEBUG): Most recent orientation data is 0.862780 seconds old. 2018-05-15T18:11:40.589Z,1526407900.589 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 0.863010 seconds old. 2018-05-15T18:11:40.924Z,1526407900.924 [DeadReckonUsingMultipleVelocitySources](DEBUG): Most recent orientation data is 1.199419 seconds old. 2018-05-15T18:11:40.942Z,1526407900.942 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 1.215613 seconds old. 2018-05-15T18:11:53.346Z,1526407913.346 [Default:A.Wait](INFO): Done Waiting. 2018-05-15T18:11:53.346Z,1526407913.346 [Default:A.Wait] Stopped 2018-05-15T18:11:53.347Z,1526407913.347 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2018-05-15T18:11:53.742Z,1526407913.742 [Default:CheckIn] Running Loop=1 2018-05-15T18:11:53.742Z,1526407913.742 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-05-15T18:11:53.742Z,1526407913.742 [Default:CheckIn:Read_GPS] Running Loop=1 2018-05-15T18:11:54.486Z,1526407914.486 [NAL9602](INFO): Powering up 2018-05-15T18:11:56.490Z,1526407916.490 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-05-15T18:11:56.490Z,1526407916.490 [NAL9602] Data Fault, FailCount= 1 2018-05-15T18:11:56.490Z,1526407916.490 [NAL9602](ERROR): Data Fault 2018-05-15T18:11:56.606Z,1526407916.606 [CBIT](ERROR): Data Fault in component: NAL9602 2018-05-15T18:11:56.890Z,1526407916.890 [NAL9602](INFO): Powering down 2018-05-15T18:11:57.772Z,1526407917.772 [CBIT](INFO): Clearing failed state for component NAL9602 2018-05-15T18:11:57.772Z,1526407917.772 [NAL9602] No Fault, FailCount= 1 2018-05-15T18:12:32.950Z,1526407952.950 [NAL9602](INFO): No messages in MT queue 2018-05-15T18:14:20.030Z,1526408060.030 [CommandLine](IMPORTANT): got command quit 2018-05-15T18:14:21.040Z,1526408061.040 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2018-05-15T18:14:21.040Z,1526408061.040 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-05-15T18:14:21.228Z,1526408061.228 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2018-05-15T18:14:21.229Z,1526408061.229 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-05-15T18:14:21.229Z,1526408061.229 [CommandLine](INFO): Join timeout helper Thread ID is 7795 2018-05-15T18:14:21.230Z,1526408061.230 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2018-05-15T18:14:21.230Z,1526408061.230 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-05-15T18:14:21.230Z,1526408061.230 [NavChartDb](INFO): Join timeout helper Thread ID is 7796 2018-05-15T18:14:21.561Z,1526408061.561 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2018-05-15T18:14:21.561Z,1526408061.561 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-05-15T18:14:21.577Z,1526408061.577 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler 2018-05-15T18:14:21.577Z,1526408061.577 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2018-05-15T18:14:21.577Z,1526408061.577 [CTD_Seabird](INFO): Join timeout helper Thread ID is 7797 2018-05-15T18:14:21.625Z,1526408061.625 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread. 2018-05-15T18:14:21.710Z,1526408061.710 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface 2018-05-15T18:14:21.710Z,1526408061.710 [CTD_Seabird](INFO): Powering down 2018-05-15T18:14:21.711Z,1526408061.711 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2018-05-15T18:14:21.717Z,1526408061.717 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2018-05-15T18:14:21.717Z,1526408061.717 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2018-05-15T18:14:21.717Z,1526408061.717 [Radio_Surface](INFO): Join timeout helper Thread ID is 7799 2018-05-15T18:14:21.933Z,1526408061.933 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2018-05-15T18:14:21.933Z,1526408061.933 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2018-05-15T18:14:21.949Z,1526408061.949 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2018-05-15T18:14:21.949Z,1526408061.949 [logger ThreadHandler](INFO): Thread cancelled. 2018-05-15T18:14:21.949Z,1526408061.949 [logger](INFO): Join timeout helper Thread ID is 7800 2018-05-15T18:14:21.953Z,1526408061.953 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2018-05-15T18:14:21.953Z,1526408061.953 [logger ThreadHandler](INFO): Thread cancelled. 2018-05-15T18:14:21.970Z,1526408061.970 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2018-05-15T18:14:21.970Z,1526408061.970 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-05-15T18:14:21.970Z,1526408061.970 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2018-05-15T18:14:21.970Z,1526408061.970 [controlThread ThreadHandler](INFO): Thread cancelled. 2018-05-15T18:14:21.970Z,1526408061.970 [controlThread](INFO): Join timeout helper Thread ID is 7801 2018-05-15T18:14:22.117Z,1526408062.117 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2018-05-15T18:14:22.117Z,1526408062.117 [controlThread](DEBUG): Uninitializing ControlThread 2018-05-15T18:14:22.117Z,1526408062.117 [AHRS_M2](INFO): uninitialize 2018-05-15T18:14:22.149Z,1526408062.149 [AHRS_M2](INFO): Data-stream disabled. 2018-05-15T18:14:22.150Z,1526408062.150 [AHRS_M2](INFO): Powering down 2018-05-15T18:14:22.221Z,1526408062.221 [AcousticModem_Benthos_ATM900](INFO): Powering down 2018-05-15T18:14:22.341Z,1526408062.341 [NAL9602](INFO): Powering down 2018-05-15T18:14:22.345Z,1526408062.345 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2018-05-15T18:14:22.346Z,1526408062.346 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2018-05-15T18:14:22.347Z,1526408062.347 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2018-05-15T18:14:22.347Z,1526408062.347 [MissionManager](INFO): Uninitializing Mission Default 2018-05-15T18:14:22.347Z,1526408062.347 [Default] Stopped 2018-05-15T18:14:22.347Z,1526408062.347 [Default](DEBUG): Aggregate::uninitialize Default 2018-05-15T18:14:22.347Z,1526408062.347 [Default:B.GoToSurface] Stopped 2018-05-15T18:14:22.348Z,1526408062.348 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2018-05-15T18:14:22.348Z,1526408062.348 [Default:CheckIn] Stopped 2018-05-15T18:14:22.348Z,1526408062.348 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-05-15T18:14:22.348Z,1526408062.348 [Default:CheckIn:Read_GPS] Stopped 2018-05-15T18:14:22.351Z,1526408062.351 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2018-05-15T18:14:22.351Z,1526408062.351 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2018-05-15T18:14:22.352Z,1526408062.352 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2018-05-15T18:14:22.352Z,1526408062.352 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2018-05-15T18:14:22.352Z,1526408062.352 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2018-05-15T18:14:22.353Z,1526408062.353 [BuoyancyServo](INFO): Powering down 2018-05-15T18:14:22.365Z,1526408062.365 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2018-05-15T18:14:22.365Z,1526408062.365 [ElevatorServo](INFO): Powering down 2018-05-15T18:14:22.366Z,1526408062.366 [MassServo](DEBUG): Uninitialize Mass Servo. 2018-05-15T18:14:22.366Z,1526408062.366 [MassServo](INFO): Powering down 2018-05-15T18:14:22.367Z,1526408062.367 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2018-05-15T18:14:22.367Z,1526408062.367 [RudderServo](INFO): Powering down 2018-05-15T18:14:22.368Z,1526408062.368 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2018-05-15T18:14:22.368Z,1526408062.368 [ThrusterServo](INFO): Powering down 2018-05-15T18:14:22.369Z,1526408062.369 [SBIT](DEBUG): Uninitialize SBIT Component. 2018-05-15T18:14:22.369Z,1526408062.369 [IBIT](DEBUG): Uninitialize IBIT Component. 2018-05-15T18:14:22.370Z,1526408062.370 [CBIT](DEBUG): Uninitialize CBIT Component. 2018-05-15T18:14:22.371Z,1526408062.371 [controlThread ThreadHandler](INFO): Thread cancelled. 2018-05-15T18:14:22.473Z,1526408062.473 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2018-05-15T18:14:22.514Z,1526408062.514 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2018-05-15T18:14:22.560Z,1526408062.560 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-05-15T18:14:22.618Z,1526408062.618 [logger ThreadHandler](INFO): Thread cancelled.