2015-05-05T20:54:32.376Z,1430859272.376 [Supervisor](DEBUG): Initializing supervisor.
2015-05-05T20:54:32.379Z,1430859272.379 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2015-05-05T20:54:32.379Z,1430859272.379 [SyncHandler](INFO): Protected caller Thread ID is 768
2015-05-05T20:54:32.380Z,1430859272.380 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2015-05-05T20:54:32.382Z,1430859272.382 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2015-05-05T20:54:32.382Z,1430859272.382 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 769
2015-05-05T20:54:32.385Z,1430859272.385 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2015-05-05T20:54:32.397Z,1430859272.397 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2015-05-05T20:54:32.402Z,1430859272.402 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2015-05-05T20:54:32.402Z,1430859272.402 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 770
2015-05-05T20:54:32.403Z,1430859272.403 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2015-05-05T20:54:32.406Z,1430859272.406 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2015-05-05T20:54:32.406Z,1430859272.406 [logger ThreadHandler](INFO): Protected caller Thread ID is 771
2015-05-05T20:54:32.408Z,1430859272.408 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2015-05-05T20:54:32.409Z,1430859272.409 [Supervisor](INFO): Looking for Config files in directory: Config/
2015-05-05T20:54:32.412Z,1430859272.412 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2015-05-05T20:54:32.778Z,1430859272.778 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2015-05-05T20:54:32.780Z,1430859272.780 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2015-05-05T20:54:32.967Z,1430859272.967 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2015-05-05T20:54:32.969Z,1430859272.969 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2015-05-05T20:54:33.096Z,1430859273.096 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2015-05-05T20:54:33.098Z,1430859273.098 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2015-05-05T20:54:33.238Z,1430859273.238 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2015-05-05T20:54:33.240Z,1430859273.240 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2015-05-05T20:54:33.335Z,1430859273.335 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2015-05-05T20:54:33.517Z,1430859273.517 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2015-05-05T20:54:33.518Z,1430859273.518 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2015-05-05T20:54:33.615Z,1430859273.615 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2015-05-05T20:54:33.617Z,1430859273.617 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2015-05-05T20:54:33.873Z,1430859273.873 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2015-05-05T20:54:33.874Z,1430859273.874 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2015-05-05T20:54:34.278Z,1430859274.278 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2015-05-05T20:54:34.279Z,1430859274.279 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2015-05-05T20:54:34.621Z,1430859274.621 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2015-05-05T20:54:34.621Z,1430859274.621 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2015-05-05T20:54:35.192Z,1430859275.192 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2015-05-05T20:54:35.193Z,1430859275.193 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2015-05-05T20:54:35.403Z,1430859275.403 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2015-05-05T20:54:35.404Z,1430859275.404 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2015-05-05T20:54:35.525Z,1430859275.525 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2015-05-05T20:54:35.525Z,1430859275.525 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2015-05-05T20:54:36.008Z,1430859276.008 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2015-05-05T20:54:36.008Z,1430859276.008 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2015-05-05T20:54:36.181Z,1430859276.181 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2015-05-05T20:54:36.183Z,1430859276.183 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2015-05-05T20:54:36.185Z,1430859276.185 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg
2015-05-05T20:54:36.457Z,1430859276.457 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2015-05-05T20:54:36.459Z,1430859276.459 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2015-05-05T20:54:36.597Z,1430859276.597 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Estimation.cfg
2015-05-05T20:54:36.722Z,1430859276.722 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2015-05-05T20:54:36.838Z,1430859276.838 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2015-05-05T20:54:36.950Z,1430859276.950 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2015-05-05T20:54:37.059Z,1430859277.059 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2015-05-05T20:54:37.211Z,1430859277.211 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2015-05-05T20:54:37.387Z,1430859277.387 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2015-05-05T20:54:37.491Z,1430859277.491 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2015-05-05T20:54:37.605Z,1430859277.605 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2015-05-05T20:54:37.715Z,1430859277.715 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2015-05-05T20:54:37.848Z,1430859277.848 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2015-05-05T20:54:37.938Z,1430859277.938 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2015-05-05T20:54:37.942Z,1430859277.942 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2015-05-05T20:54:38.021Z,1430859278.021 [VerticalControl](DEBUG): Construct VerticalControl.
2015-05-05T20:54:38.160Z,1430859278.160 [VerticalControl] Loaded
2015-05-05T20:54:38.161Z,1430859278.161 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2015-05-05T20:54:38.161Z,1430859278.161 [HorizontalControl](DEBUG): Construct HorizontalControl.
2015-05-05T20:54:38.244Z,1430859278.244 [HorizontalControl] Loaded
2015-05-05T20:54:38.245Z,1430859278.245 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2015-05-05T20:54:38.245Z,1430859278.245 [SpeedControl](DEBUG): Construct SpeedControl.
2015-05-05T20:54:38.251Z,1430859278.251 [SpeedControl] Loaded
2015-05-05T20:54:38.252Z,1430859278.252 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2015-05-05T20:54:38.252Z,1430859278.252 [LoopControl](DEBUG): Construct LoopControl.
2015-05-05T20:54:38.253Z,1430859278.253 [LoopControl] Loaded
2015-05-05T20:54:38.253Z,1430859278.253 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2015-05-05T20:54:38.254Z,1430859278.254 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2015-05-05T20:54:38.254Z,1430859278.254 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2015-05-05T20:54:38.418Z,1430859278.418 [SBIT](DEBUG): Construct Startup Built In Test.
2015-05-05T20:54:38.430Z,1430859278.430 [SBIT] Loaded
2015-05-05T20:54:38.430Z,1430859278.430 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2015-05-05T20:54:38.435Z,1430859278.435 [IBIT](DEBUG): Construct Initiated Built In Test.
2015-05-05T20:54:38.465Z,1430859278.465 [IBIT] Loaded
2015-05-05T20:54:38.466Z,1430859278.466 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2015-05-05T20:54:38.468Z,1430859278.468 [CBIT](DEBUG): Construct Continuous Built In Test.
2015-05-05T20:54:38.627Z,1430859278.627 [CBIT] Loaded
2015-05-05T20:54:38.627Z,1430859278.627 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2015-05-05T20:54:38.628Z,1430859278.628 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2015-05-05T20:54:38.628Z,1430859278.628 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2015-05-05T20:54:38.658Z,1430859278.658 [DepthRateCalculator] Loaded
2015-05-05T20:54:38.659Z,1430859278.659 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2015-05-05T20:54:38.670Z,1430859278.670 [PitchRateCalculator] Loaded
2015-05-05T20:54:38.670Z,1430859278.670 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2015-05-05T20:54:38.682Z,1430859278.682 [SpeedCalculator] Loaded
2015-05-05T20:54:38.682Z,1430859278.682 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2015-05-05T20:54:38.700Z,1430859278.700 [TempGradientCalculator] Loaded
2015-05-05T20:54:38.700Z,1430859278.700 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2015-05-05T20:54:38.705Z,1430859278.705 [YawRateCalculator] Loaded
2015-05-05T20:54:38.706Z,1430859278.706 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2015-05-05T20:54:38.706Z,1430859278.706 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2015-05-05T20:54:38.707Z,1430859278.707 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2015-05-05T20:54:43.445Z,1430859283.445 [HFRadarCompactModelForecaster] Loaded
2015-05-05T20:54:43.445Z,1430859283.445 [ComponentRegistry](DEBUG): SyncComponent "HFRadarCompactModelForecaster" handled in the control thread.
2015-05-05T20:54:44.576Z,1430859284.576 [HFRCMSpaceInterpolator] Loaded
2015-05-05T20:54:44.577Z,1430859284.577 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSpaceInterpolator" handled in the control thread.
2015-05-05T20:54:44.579Z,1430859284.579 [HFRCMTimeInterpolator] Loaded
2015-05-05T20:54:44.579Z,1430859284.579 [ComponentRegistry](DEBUG): SyncComponent "HFRCMTimeInterpolator" handled in the control thread.
2015-05-05T20:54:45.780Z,1430859285.780 [HFRCMReconstructedInterpolator] Loaded
2015-05-05T20:54:45.781Z,1430859285.781 [ComponentRegistry](DEBUG): SyncComponent "HFRCMReconstructedInterpolator" handled in the control thread.
2015-05-05T20:54:45.793Z,1430859285.793 [HFRCMSurfaceCurrentAtVehicleLocation] Loaded
2015-05-05T20:54:45.793Z,1430859285.793 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSurfaceCurrentAtVehicleLocation" handled in the control thread.
2015-05-05T20:54:45.825Z,1430859285.825 [HFRCMVirtualSurfaceDrifter] Loaded
2015-05-05T20:54:45.825Z,1430859285.825 [ComponentRegistry](DEBUG): SyncComponent "HFRCMVirtualSurfaceDrifter" handled in the control thread.
2015-05-05T20:54:45.826Z,1430859285.826 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2015-05-05T20:54:45.827Z,1430859285.827 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2015-05-05T20:54:46.133Z,1430859286.133 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2015-05-05T20:54:46.133Z,1430859286.133 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2015-05-05T20:54:46.254Z,1430859286.254 [DeadReckonUsingMultipleVelocitySources] Loaded
2015-05-05T20:54:46.254Z,1430859286.254 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2015-05-05T20:54:46.306Z,1430859286.306 [DeadReckonUsingSpeedCalculator] Loaded
2015-05-05T20:54:46.306Z,1430859286.306 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread.
2015-05-05T20:54:46.324Z,1430859286.324 [NavChart] Loaded
2015-05-05T20:54:46.324Z,1430859286.324 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2015-05-05T20:54:46.329Z,1430859286.329 [UniversalFixResidualReporter] Loaded
2015-05-05T20:54:46.329Z,1430859286.329 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2015-05-05T20:54:46.330Z,1430859286.330 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2015-05-05T20:54:46.330Z,1430859286.330 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2015-05-05T20:54:46.339Z,1430859286.339 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2015-05-05T20:54:46.340Z,1430859286.340 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2015-05-05T20:54:46.560Z,1430859286.560 [Aanderaa_O2] Loaded
2015-05-05T20:54:46.560Z,1430859286.560 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread.
2015-05-05T20:54:46.572Z,1430859286.572 [CANONSampler] Loaded
2015-05-05T20:54:46.572Z,1430859286.572 [ComponentRegistry](DEBUG): SyncComponent "CANONSampler" handled in the control thread.
2015-05-05T20:54:46.659Z,1430859286.659 [CTD_NeilBrown] Loaded
2015-05-05T20:54:46.659Z,1430859286.659 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2015-05-05T20:54:46.664Z,1430859286.664 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 406E94E0
2015-05-05T20:54:46.664Z,1430859286.664 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 856
2015-05-05T20:54:46.678Z,1430859286.678 [ISUS] Loaded
2015-05-05T20:54:46.678Z,1430859286.678 [ComponentRegistry](DEBUG): SyncComponent "ISUS" handled in the control thread.
2015-05-05T20:54:46.698Z,1430859286.698 [PAR_Licor] Loaded
2015-05-05T20:54:46.698Z,1430859286.698 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2015-05-05T20:54:46.751Z,1430859286.751 [WetLabsBB2FL] Loaded
2015-05-05T20:54:46.751Z,1430859286.751 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2015-05-05T20:54:46.756Z,1430859286.756 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407194E0
2015-05-05T20:54:46.756Z,1430859286.756 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 857
2015-05-05T20:54:46.757Z,1430859286.757 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2015-05-05T20:54:46.758Z,1430859286.758 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2015-05-05T20:54:47.493Z,1430859287.493 [AHRS_sp3003D] Loaded
2015-05-05T20:54:47.493Z,1430859287.493 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2015-05-05T20:54:47.684Z,1430859287.684 [DataOverHttps] Loaded
2015-05-05T20:54:47.684Z,1430859287.684 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2015-05-05T20:54:47.703Z,1430859287.703 [Depth_Keller] Loaded
2015-05-05T20:54:47.703Z,1430859287.703 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2015-05-05T20:54:47.709Z,1430859287.709 [DropWeight] Loaded
2015-05-05T20:54:47.709Z,1430859287.709 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2015-05-05T20:54:47.861Z,1430859287.861 [DVL_micro] Loaded
2015-05-05T20:54:47.861Z,1430859287.861 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2015-05-05T20:54:47.973Z,1430859287.973 [NAL9602] Loaded
2015-05-05T20:54:47.973Z,1430859287.973 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2015-05-05T20:54:48.021Z,1430859288.021 [Onboard] Loaded
2015-05-05T20:54:48.021Z,1430859288.021 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2015-05-05T20:54:48.032Z,1430859288.032 [Radio_Surface] Loaded
2015-05-05T20:54:48.032Z,1430859288.032 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2015-05-05T20:54:48.034Z,1430859288.034 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4095D4E0
2015-05-05T20:54:48.034Z,1430859288.034 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 858
2015-05-05T20:54:48.186Z,1430859288.186 [DAT] Loaded
2015-05-05T20:54:48.190Z,1430859288.190 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2015-05-05T20:54:50.348Z,1430859290.348 [BPC1] Loaded
2015-05-05T20:54:50.348Z,1430859290.348 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2015-05-05T20:54:50.349Z,1430859290.349 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2015-05-05T20:54:50.354Z,1430859290.354 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2015-05-05T20:54:50.487Z,1430859290.487 [BuoyancyServo] Loaded
2015-05-05T20:54:50.487Z,1430859290.487 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2015-05-05T20:54:50.500Z,1430859290.500 [ElevatorServo] Loaded
2015-05-05T20:54:50.500Z,1430859290.500 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2015-05-05T20:54:50.517Z,1430859290.517 [MassServo] Loaded
2015-05-05T20:54:50.517Z,1430859290.517 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2015-05-05T20:54:50.530Z,1430859290.530 [RudderServo] Loaded
2015-05-05T20:54:50.530Z,1430859290.530 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2015-05-05T20:54:50.542Z,1430859290.542 [ThrusterServo] Loaded
2015-05-05T20:54:50.543Z,1430859290.543 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2015-05-05T20:54:50.543Z,1430859290.543 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2015-05-05T20:54:50.544Z,1430859290.544 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2015-05-05T20:54:50.697Z,1430859290.697 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2015-05-05T20:54:50.698Z,1430859290.698 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2015-05-05T20:54:50.742Z,1430859290.742 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2015-05-05T20:54:50.746Z,1430859290.746 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2015-05-05T20:54:50.746Z,1430859290.746 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2015-05-05T20:54:50.753Z,1430859290.753 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2015-05-05T20:54:50.758Z,1430859290.758 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A0E4E0
2015-05-05T20:54:50.759Z,1430859290.759 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 859
2015-05-05T20:54:50.763Z,1430859290.763 [Supervisor](INFO): Main Thread ID is 764
2015-05-05T20:54:50.764Z,1430859290.764 [Supervisor](DEBUG): Running supervisor.
2015-05-05T20:54:50.764Z,1430859290.764 [CommandLine ThreadHandler](INFO): Handler Thread ID is 860
2015-05-05T20:54:50.771Z,1430859290.771 [controlThread ThreadHandler](INFO): Handler Thread ID is 861
2015-05-05T20:54:50.771Z,1430859290.771 [controlThread](DEBUG): Initializing ControlThread
2015-05-05T20:54:50.772Z,1430859290.772 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2015-05-05T20:54:50.774Z,1430859290.774 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2015-05-05T20:54:50.775Z,1430859290.775 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2015-05-05T20:54:50.775Z,1430859290.775 [LoopControl](DEBUG): Initialize LoopControlComponent.
2015-05-05T20:54:50.775Z,1430859290.775 [SBIT](INFO): Initialize SBIT Component.
2015-05-05T20:54:50.776Z,1430859290.776 [SBIT](IMPORTANT): Tethys CM Info: SVN revision:12194
2015-05-05T20:54:50.776Z,1430859290.776 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2015-05-05T20:54:50.776Z,1430859290.776 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2015-05-05T20:54:50.777Z,1430859290.777 [IBIT](INFO): Initialize IBIT Component.
2015-05-05T20:54:50.778Z,1430859290.778 [CBIT](DEBUG): Initialize CBIT Component.
2015-05-05T20:54:50.778Z,1430859290.778 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2015-05-05T20:54:50.783Z,1430859290.783 [logger ThreadHandler](INFO): Handler Thread ID is 862
2015-05-05T20:54:50.802Z,1430859290.802 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2015-05-05T20:54:50.803Z,1430859290.803 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2015-05-05T20:54:50.803Z,1430859290.803 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2015-05-05T20:54:50.804Z,1430859290.804 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2015-05-05T20:54:50.804Z,1430859290.804 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2015-05-05T20:54:50.812Z,1430859290.812 [HFRadarCompactModelForecaster](DEBUG): Found new ECs!
2015-05-05T20:54:50.822Z,1430859290.822 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 863
2015-05-05T20:54:50.826Z,1430859290.826 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2015-05-05T20:54:50.830Z,1430859290.830 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2015-05-05T20:54:50.844Z,1430859290.844 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 865
2015-05-05T20:54:50.848Z,1430859290.848 [WetLabsBB2FL](INFO): Powering down
2015-05-05T20:54:50.892Z,1430859290.892 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 866
2015-05-05T20:54:50.899Z,1430859290.899 [Radio_Surface](INFO): Powering up
2015-05-05T20:54:50.917Z,1430859290.917 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 867
2015-05-05T20:54:50.936Z,1430859290.936 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2015-05-05T20:54:50.936Z,1430859290.936 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2015-05-05T20:54:50.937Z,1430859290.937 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2015-05-05T20:54:50.937Z,1430859290.937 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2015-05-05T20:54:50.937Z,1430859290.937 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2015-05-05T20:54:50.937Z,1430859290.937 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2015-05-05T20:54:50.938Z,1430859290.938 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2015-05-05T20:54:50.938Z,1430859290.938 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2015-05-05T20:54:50.939Z,1430859290.939 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2015-05-05T20:54:50.975Z,1430859290.975 [CTD_NeilBrown](DEBUG): CTD uart timeout: serial timeout
2015-05-05T20:54:50.975Z,1430859290.975 [CTD_NeilBrown](ERROR): Could not get real or simulated CTD data. startTime.elapsed() = 0.143523
2015-05-05T20:55:00.110Z,1430859300.110 [HFRadarCompactModelForecaster](IMPORTANT): forecast time 201505051700 published
2015-05-05T20:55:00.113Z,1430859300.113 [HFRCMSpaceInterpolator](DEBUG): Initializing HFRCMSpaceInterpolator component with verbosity level 0.
2015-05-05T20:55:00.129Z,1430859300.129 [HFRCMTimeInterpolator](DEBUG): Initializing HFRCMTimeInterpolator component.
2015-05-05T20:55:00.130Z,1430859300.130 [HFRCMReconstructedInterpolator](INFO): Initializing HFRCMReconstructedInterpolator component with velocityAccuracy_ = 0.300000 m/s.
2015-05-05T20:55:00.131Z,1430859300.131 [HFRCMSurfaceCurrentAtVehicleLocation](DEBUG): Initializing HFRCMSurfaceCurrentAtVehicleLocation component.
2015-05-05T20:55:00.131Z,1430859300.131 [HFRCMVirtualSurfaceDrifter](DEBUG): Initializing HFRCMVirtualSurfaceDrifter component.
2015-05-05T20:55:00.132Z,1430859300.132 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2015-05-05T20:55:00.132Z,1430859300.132 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2015-05-05T20:55:00.133Z,1430859300.133 [NavChart](DEBUG): Initialize NavChart Navigation.
2015-05-05T20:55:00.133Z,1430859300.133 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2015-05-05T20:55:00.149Z,1430859300.149 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2015-05-05T20:55:00.194Z,1430859300.194 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2015-05-05T20:55:00.219Z,1430859300.219 [MissionManager](DEBUG):
2015-05-05T20:55:00.220Z,1430859300.220 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2015-05-05T20:55:00.297Z,1430859300.297 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2015-05-05T20:55:00.298Z,1430859300.298 [Default:A.GoToSurface](DEBUG): Construct GoToSurface.
2015-05-05T20:55:00.341Z,1430859300.341 [Default:CheckIn:A.SetSpeed](DEBUG): Construct.
2015-05-05T20:55:00.367Z,1430859300.367 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2015-05-05T20:55:00.395Z,1430859300.395 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Construct.
2015-05-05T20:55:00.417Z,1430859300.417 [MissionManager](DEBUG):
0
5.0
1.0
400
10
500
Default mission has been running for
Burn 300
Dropped weight due to communications timeout.
5
2015-05-05T20:55:00.424Z,1430859300.424 [controlThread](DEBUG): Component order: CycleStarter,Aanderaa_O2,CANONSampler,ISUS,PAR_Licor,AHRS_sp3003D,DataOverHttps,Depth_Keller,DropWeight,DVL_micro,NAL9602,Onboard,DAT,BPC1,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,HFRadarCompactModelForecaster,HFRCMSpaceInterpolator,HFRCMTimeInterpolator,HFRCMReconstructedInterpolator,HFRCMSurfaceCurrentAtVehicleLocation,HFRCMVirtualSurfaceDrifter,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2015-05-05T20:55:00.480Z,1430859300.480 [CANONSampler](INFO): Powering down
2015-05-05T20:55:00.603Z,1430859300.603 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2015-05-05T20:55:01.281Z,1430859301.281 [DVL_micro](INFO): Initializing
2015-05-05T20:55:01.293Z,1430859301.293 [NAL9602](INFO): Powering up NAL9602
2015-05-05T20:55:01.411Z,1430859301.411 [DAT](INFO): Powering up
2015-05-05T20:55:01.411Z,1430859301.411 [DAT](DEBUG): Initializing DAT.
2015-05-05T20:55:11.139Z,1430859311.139 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 0 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T20:55:11.290Z,1430859311.290 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2015-05-05T20:55:11.302Z,1430859311.302 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2015-05-05T20:55:11.309Z,1430859311.309 [ElevatorServo](DEBUG): Initializing EZServoServo.
2015-05-05T20:55:11.315Z,1430859311.315 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2015-05-05T20:55:11.321Z,1430859311.321 [MassServo](DEBUG): Initializing EZServoServo.
2015-05-05T20:55:11.326Z,1430859311.326 [MassServo](DEBUG): Initializing MassServo.
2015-05-05T20:55:11.340Z,1430859311.340 [RudderServo](DEBUG): Initializing EZServoServo.
2015-05-05T20:55:11.346Z,1430859311.346 [RudderServo](DEBUG): Initializing RudderServo.
2015-05-05T20:55:11.360Z,1430859311.360 [ThrusterServo](DEBUG): Initializing EZServoServo.
2015-05-05T20:55:11.366Z,1430859311.366 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2015-05-05T20:55:11.507Z,1430859311.507 [Aanderaa_O2](FAULT): Timed out starting
2015-05-05T20:55:11.507Z,1430859311.507 [Aanderaa_O2] Communications Fault, FailCount= 1
2015-05-05T20:55:11.508Z,1430859311.508 [Aanderaa_O2](ERROR): Communications Fault
2015-05-05T20:55:11.782Z,1430859311.782 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 1 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T20:55:12.127Z,1430859312.127 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2015-05-05T20:55:12.128Z,1430859312.128 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2015-05-05T20:55:12.128Z,1430859312.128 [BuoyancyServo] Communications Fault, FailCount= 1
2015-05-05T20:55:12.128Z,1430859312.128 [BuoyancyServo](ERROR): Communications Fault
2015-05-05T20:55:12.380Z,1430859312.380 [SBIT](IMPORTANT): Beginning Startup BIT
2015-05-05T20:55:12.383Z,1430859312.383 [CBIT](ERROR): Communications Fault in component: Aanderaa_O2
2015-05-05T20:55:12.383Z,1430859312.383 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2015-05-05T20:55:12.384Z,1430859312.384 [CBIT](IMPORTANT): Beginning GF scan
2015-05-05T20:55:12.528Z,1430859312.528 [Aanderaa_O2](INFO): Powering down
2015-05-05T20:55:12.981Z,1430859312.981 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 2 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T20:55:13.008Z,1430859313.008 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2015-05-05T20:55:13.014Z,1430859313.014 [BuoyancyServo](INFO): Powering down
2015-05-05T20:55:13.495Z,1430859313.495 [NAL9602](INFO): NAL9602 initialized
2015-05-05T20:55:13.570Z,1430859313.570 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 3 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T20:55:13.995Z,1430859313.995 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 4 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T20:55:14.153Z,1430859314.153 [CBIT](INFO): Clearing failed state for component Aanderaa_O2
2015-05-05T20:55:14.153Z,1430859314.153 [Aanderaa_O2] No Fault, FailCount= 1
2015-05-05T20:55:14.686Z,1430859314.686 [DAT](DEBUG):
2015-05-05T20:55:14.687Z,1430859314.687 [DAT](DEBUG): Teledyne Benthos ATM-900 Series
2015-05-05T20:55:14.687Z,1430859314.687 [DAT](DEBUG): MF Frequency Band
2015-05-05T20:55:14.689Z,1430859314.689 [DAT](DEBUG): Directional Acoustic Transponder version 8.3.1
2015-05-05T20:55:14.753Z,1430859314.753 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 5 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T20:55:15.223Z,1430859315.223 [DAT](DEBUG): May 5 2015 21:54:06
2015-05-05T20:55:15.441Z,1430859315.441 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2015-05-05T20:55:15.441Z,1430859315.441 [BuoyancyServo] No Fault, FailCount= 1
2015-05-05T20:55:15.903Z,1430859315.903 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2015-05-05T20:55:16.018Z,1430859316.018 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2015-05-05T20:55:16.595Z,1430859316.595 [DAT](INFO): entering command mode
2015-05-05T20:55:17.219Z,1430859317.219 [DAT](DEBUG): checking for command mode acknowledgment
2015-05-05T20:55:17.220Z,1430859317.220 [DAT](DEBUG): read user prompt 1: user:1>
2015-05-05T20:55:17.220Z,1430859317.220 [DAT](INFO): command mode acknowledged
2015-05-05T20:55:17.564Z,1430859317.564 [Aanderaa_O2](INFO): Powering down
2015-05-05T20:55:18.023Z,1430859318.023 [DAT](INFO): setting local address to 2
2015-05-05T20:55:18.604Z,1430859318.604 [DAT](DEBUG): checking for local address setting acknowledgment
2015-05-05T20:55:18.605Z,1430859318.605 [DAT](INFO): set local address to 2
2015-05-05T20:55:25.695Z,1430859325.695 [SBIT](FAULT): Mass: EXPECTED:0.003400 ACTUAL:0.003210
2015-05-05T20:55:39.939Z,1430859339.939 [CBIT](IMPORTANT): No ground fault detected
2015-05-05T20:56:06.387Z,1430859366.387 [SBIT](CRITICAL): SBIT FAILED
2015-05-05T20:56:06.388Z,1430859366.388 [CommandLine](FAULT): Scheduling is paused
2015-05-05T20:56:06.853Z,1430859366.853 [MissionManager](IMPORTANT): Started mission Startup
2015-05-05T20:56:06.853Z,1430859366.853 [Startup] Running Loop=1
2015-05-05T20:56:06.854Z,1430859366.854 [Startup](INFO): Aggregate::initialize Startup
2015-05-05T20:56:06.854Z,1430859366.854 [Startup:A.GoToSurface] Running Loop=1
2015-05-05T20:56:06.854Z,1430859366.854 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2015-05-05T20:56:06.854Z,1430859366.854 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2015-05-05T20:56:06.855Z,1430859366.855 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2015-05-05T20:56:06.855Z,1430859366.855 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2015-05-05T20:56:06.905Z,1430859366.905 [Startup:StartupSatComms] Running Loop=1
2015-05-05T20:56:06.905Z,1430859366.905 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2015-05-05T20:56:06.905Z,1430859366.905 [Startup:StartupSatComms:A] Running Loop=1
2015-05-05T20:56:07.347Z,1430859367.347 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2015-05-05T20:56:23.444Z,1430859383.444 [Depth_Keller](ERROR): Pressure reading out of range: 1830.315186 decibar
2015-05-05T20:56:24.790Z,1430859384.790 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003506
2015-05-05T20:56:28.458Z,1430859388.458 [BPC1](ERROR): Failed to receive battery data
2015-05-05T20:56:28.458Z,1430859388.458 [BPC1] Communications Fault, FailCount= 1
2015-05-05T20:56:28.459Z,1430859388.459 [BPC1](ERROR): Communications Fault
2015-05-05T20:56:28.522Z,1430859388.522 [CBIT](ERROR): Communications Fault in component: BPC1
2015-05-05T20:56:29.799Z,1430859389.799 [CBIT](INFO): Clearing failed state for component BPC1
2015-05-05T20:56:29.799Z,1430859389.799 [BPC1] No Fault, FailCount= 1
2015-05-05T20:57:06.913Z,1430859426.913 [Startup:StartupSatComms:A](INFO): Timed out from 2015-05-05T20:56:06.9Z
2015-05-05T20:57:06.914Z,1430859426.914 [Startup:StartupSatComms:A] Stopped
2015-05-05T20:57:06.914Z,1430859426.914 [Startup:StartupSatComms:B] Running Loop=1
2015-05-05T20:57:07.323Z,1430859427.323 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2015-05-05T20:57:11.648Z,1430859431.648 [Depth_Keller](ERROR): Pressure reading out of range: 1830.295166 decibar
2015-05-05T20:57:12.108Z,1430859432.108 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20150505T205032/Courier0000.lzma
2015-05-05T20:57:13.014Z,1430859433.014 [DataOverHttps](INFO): Moved sent file to Logs/20150505T205032/Courier0000.lzma.bak
2015-05-05T20:57:13.014Z,1430859433.014 [DataOverHttps](INFO): SBD MOMSN=3420575
2015-05-05T20:57:17.865Z,1430859437.865 [BPC1](ERROR): Failed to receive battery data
2015-05-05T20:57:17.866Z,1430859437.866 [BPC1] Communications Fault, FailCount= 1
2015-05-05T20:57:17.866Z,1430859437.866 [BPC1](ERROR): Communications Fault
2015-05-05T20:57:17.921Z,1430859437.921 [CBIT](ERROR): Communications Fault in component: BPC1
2015-05-05T20:57:19.215Z,1430859439.215 [CBIT](INFO): Clearing failed state for component BPC1
2015-05-05T20:57:19.215Z,1430859439.215 [BPC1] No Fault, FailCount= 1
2015-05-05T20:57:23.338Z,1430859443.338 [Depth_Keller](ERROR): Pressure reading out of range: 1830.317017 decibar
2015-05-05T20:57:23.817Z,1430859443.817 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20150505T205432/Courier0000.lzma
2015-05-05T20:57:24.688Z,1430859444.688 [DataOverHttps](INFO): Moved sent file to Logs/20150505T205432/Courier0000.lzma.bak
2015-05-05T20:57:24.688Z,1430859444.688 [DataOverHttps](INFO): SBD MOMSN=3420579
2015-05-05T20:57:35.047Z,1430859455.047 [Depth_Keller](ERROR): Pressure reading out of range: 1830.310913 decibar
2015-05-05T20:57:35.554Z,1430859455.554 [DataOverHttps](INFO): Sending 661 bytes from file Logs/20150505T205032/Express0001.lzma
2015-05-05T20:57:36.467Z,1430859456.467 [DataOverHttps](INFO): Moved sent file to Logs/20150505T205032/Express0001.lzma.bak
2015-05-05T20:57:36.467Z,1430859456.467 [DataOverHttps](INFO): SBD MOMSN=3420583
2015-05-05T20:57:47.241Z,1430859467.241 [DataOverHttps](INFO): Sending 636 bytes from file Logs/20150505T205432/Express0001.lzma
2015-05-05T20:57:48.104Z,1430859468.104 [DataOverHttps](INFO): Moved sent file to Logs/20150505T205432/Express0001.lzma.bak
2015-05-05T20:57:48.105Z,1430859468.105 [DataOverHttps](INFO): SBD MOMSN=3420599
2015-05-05T20:57:48.603Z,1430859468.603 [HFRadarCompactModelForecaster](DEBUG): Did not find new historical expansion coefficients.
2015-05-05T20:57:48.610Z,1430859468.610 [Startup:StartupSatComms:B] Stopped
2015-05-05T20:57:48.610Z,1430859468.610 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2015-05-05T20:57:48.611Z,1430859468.611 [Startup:StartupSatComms] Stopped
2015-05-05T20:57:48.611Z,1430859468.611 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2015-05-05T20:57:48.612Z,1430859468.612 [Startup](INFO): Completed Startup
2015-05-05T20:57:48.612Z,1430859468.612 [Startup] Stopped
2015-05-05T20:57:48.612Z,1430859468.612 [Startup](INFO): Aggregate::uninitialize Startup
2015-05-05T20:57:48.612Z,1430859468.612 [Startup:A.GoToSurface] Stopped
2015-05-05T20:57:48.612Z,1430859468.612 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2015-05-05T20:57:49.020Z,1430859469.020 [MissionManager](IMPORTANT): Started mission Default
2015-05-05T20:57:49.020Z,1430859469.020 [Default] Running Loop=1
2015-05-05T20:57:49.021Z,1430859469.021 [Default](INFO): Aggregate::initialize Default
2015-05-05T20:57:49.021Z,1430859469.021 [Default:A.GoToSurface] Running Loop=1
2015-05-05T20:57:49.021Z,1430859469.021 [Default:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2015-05-05T20:57:49.021Z,1430859469.021 [Default:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2015-05-05T20:57:49.021Z,1430859469.021 [Default:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2015-05-05T20:57:49.022Z,1430859469.022 [Default:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2015-05-05T20:57:49.028Z,1430859469.028 [Default:WaitAtTheSurface] Running Loop=1
2015-05-05T20:57:49.028Z,1430859469.028 [Default:WaitAtTheSurface](INFO): Aggregate::initialize Default:WaitAtTheSurface
2015-05-05T20:57:49.028Z,1430859469.028 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Running Loop=1
2015-05-05T20:57:49.028Z,1430859469.028 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Initialize.
2015-05-05T20:57:52.269Z,1430859472.269 [Depth_Keller](ERROR): Pressure reading out of range: 1372.604004 decibar
2015-05-05T20:57:52.394Z,1430859472.394 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Running Loop=1
2015-05-05T20:58:04.430Z,1430859484.430 [DeadReckonUsingMultipleVelocitySources](FAULT): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2015-05-05T20:58:04.430Z,1430859484.430 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2015-05-05T20:58:04.430Z,1430859484.430 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2015-05-05T20:58:04.432Z,1430859484.432 [DeadReckonUsingSpeedCalculator](FAULT): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2015-05-05T20:58:04.432Z,1430859484.432 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1
2015-05-05T20:58:04.433Z,1430859484.433 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2015-05-05T20:58:04.850Z,1430859484.850 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2015-05-05T20:58:04.851Z,1430859484.851 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2015-05-05T20:58:09.698Z,1430859489.698 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2015-05-05T20:58:09.698Z,1430859489.698 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2015-05-05T20:58:09.698Z,1430859489.698 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2015-05-05T20:58:09.699Z,1430859489.699 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1
2015-05-05T20:58:14.451Z,1430859494.451 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2015-05-05T20:58:14.452Z,1430859494.452 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2015-05-05T20:58:19.396Z,1430859499.396 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2015-05-05T20:58:19.396Z,1430859499.396 [DVL_micro] Data Fault, FailCount= 1
2015-05-05T20:58:19.396Z,1430859499.396 [DVL_micro](ERROR): Data Fault
2015-05-05T20:58:19.454Z,1430859499.454 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 0 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T20:58:19.496Z,1430859499.496 [CBIT](ERROR): Data Fault in component: DVL_micro
2015-05-05T20:58:24.462Z,1430859504.462 [DVL_micro](INFO): uninitialize:Powering down
2015-05-05T20:58:24.502Z,1430859504.502 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 1 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T20:58:29.453Z,1430859509.453 [BPC1](ERROR): Failed to receive battery data
2015-05-05T20:58:29.453Z,1430859509.453 [BPC1] Communications Fault, FailCount= 1
2015-05-05T20:58:29.453Z,1430859509.453 [BPC1](ERROR): Communications Fault
2015-05-05T20:58:29.500Z,1430859509.500 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 2 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T20:58:29.522Z,1430859509.522 [CBIT](ERROR): Communications Fault in component: BPC1
2015-05-05T20:58:34.442Z,1430859514.442 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 3 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T20:58:34.456Z,1430859514.456 [CBIT](INFO): Clearing failed state for component DVL_micro
2015-05-05T20:58:34.456Z,1430859514.456 [DVL_micro] No Fault, FailCount= 1
2015-05-05T20:58:39.397Z,1430859519.397 [DVL_micro](INFO): Initializing
2015-05-05T20:58:39.449Z,1430859519.449 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 4 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T20:58:44.436Z,1430859524.436 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 5 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T20:58:44.448Z,1430859524.448 [CBIT](INFO): Clearing failed state for component BPC1
2015-05-05T20:58:44.448Z,1430859524.448 [BPC1] No Fault, FailCount= 1
2015-05-05T20:59:14.390Z,1430859554.390 [DataOverHttps](IMPORTANT): SBD MTMSN=20150505T205808
2015-05-05T20:59:34.395Z,1430859574.395 [DataOverHttps](INFO): Received command:schedule list
2015-05-05T20:59:34.483Z,1430859574.483 [CommandLine](IMPORTANT): got command schedule list
2015-05-05T20:59:34.483Z,1430859574.483 [CommandLine](FAULT): Scheduling was paused by an error at 2015-05-05T20:56:06Z
2015-05-05T20:59:44.797Z,1430859584.797 [DVL_micro](ERROR): No DVL communication! Re-initializing
2015-05-05T20:59:44.797Z,1430859584.797 [DVL_micro] Communications Fault, FailCount= 1
2015-05-05T20:59:44.797Z,1430859584.797 [DVL_micro](ERROR): Communications Fault
2015-05-05T20:59:44.883Z,1430859584.883 [CBIT](ERROR): Communications Fault in component: DVL_micro
2015-05-05T20:59:49.869Z,1430859589.869 [DVL_micro](INFO): uninitialize:Powering down
2015-05-05T20:59:49.901Z,1430859589.901 [BPC1](ERROR): Failed to receive battery data
2015-05-05T20:59:49.901Z,1430859589.901 [BPC1] Communications Fault, FailCount= 1
2015-05-05T20:59:49.901Z,1430859589.901 [BPC1](ERROR): Communications Fault
2015-05-05T20:59:49.926Z,1430859589.926 [CBIT](ERROR): Communications Fault in component: BPC1
2015-05-05T20:59:59.865Z,1430859599.865 [CBIT](INFO): Clearing failed state for component DVL_micro
2015-05-05T20:59:59.865Z,1430859599.865 [DVL_micro] No Fault, FailCount= 1
2015-05-05T21:00:04.804Z,1430859604.804 [DVL_micro](INFO): Initializing
2015-05-05T21:00:04.928Z,1430859604.928 [CBIT](INFO): Clearing failed state for component BPC1
2015-05-05T21:00:04.928Z,1430859604.928 [BPC1] No Fault, FailCount= 1
2015-05-05T21:00:19.806Z,1430859619.806 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2015-05-05T21:00:32.682Z,1430859632.682 [BPC1](ERROR): Failed to receive battery data
2015-05-05T21:00:32.682Z,1430859632.682 [BPC1] Communications Fault, FailCount= 2
2015-05-05T21:00:32.682Z,1430859632.682 [BPC1](ERROR): Communications Fault
2015-05-05T21:00:32.747Z,1430859632.747 [CBIT](ERROR): Communications Fault in component: BPC1
2015-05-05T21:00:44.839Z,1430859644.839 [CBIT](INFO): Clearing failed state for component BPC1
2015-05-05T21:00:44.839Z,1430859644.839 [BPC1] No Fault, FailCount= 2
2015-05-05T21:01:09.857Z,1430859669.857 [BPC1](ERROR): Failed to parse bank B battery data
2015-05-05T21:01:09.857Z,1430859669.857 [BPC1] Data Fault, FailCount= 3
2015-05-05T21:01:09.857Z,1430859669.857 [BPC1](ERROR): Data Fault
2015-05-05T21:01:09.922Z,1430859669.922 [CBIT](ERROR): Data Fault in component: BPC1
2015-05-05T21:01:14.809Z,1430859674.809 [DeadReckonUsingMultipleVelocitySources](FAULT): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2015-05-05T21:01:14.809Z,1430859674.809 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2015-05-05T21:01:14.810Z,1430859674.810 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2015-05-05T21:01:14.811Z,1430859674.811 [DeadReckonUsingSpeedCalculator](FAULT): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2015-05-05T21:01:14.812Z,1430859674.812 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 2
2015-05-05T21:01:14.812Z,1430859674.812 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2015-05-05T21:01:14.857Z,1430859674.857 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2015-05-05T21:01:14.857Z,1430859674.857 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2015-05-05T21:01:19.896Z,1430859679.896 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2015-05-05T21:01:19.896Z,1430859679.896 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2015-05-05T21:01:19.897Z,1430859679.897 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2015-05-05T21:01:19.897Z,1430859679.897 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 2
2015-05-05T21:01:24.850Z,1430859684.850 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2015-05-05T21:01:24.851Z,1430859684.851 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2015-05-05T21:01:24.861Z,1430859684.861 [CBIT](INFO): Clearing failed state for component BPC1
2015-05-05T21:01:24.862Z,1430859684.862 [BPC1] No Fault, FailCount= 3
2015-05-05T21:01:29.952Z,1430859689.952 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 0 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T21:01:37.673Z,1430859697.673 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 1 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T21:01:39.815Z,1430859699.815 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 2 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T21:01:44.889Z,1430859704.889 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 3 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T21:01:49.892Z,1430859709.892 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 4 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T21:01:54.881Z,1430859714.881 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 5 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T21:02:04.800Z,1430859724.800 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2015-05-05T21:02:04.800Z,1430859724.800 [DVL_micro] Data Fault, FailCount= 1
2015-05-05T21:02:04.800Z,1430859724.800 [DVL_micro](ERROR): Data Fault
2015-05-05T21:02:04.852Z,1430859724.852 [CBIT](ERROR): Data Fault in component: DVL_micro
2015-05-05T21:02:09.862Z,1430859729.862 [DVL_micro](INFO): uninitialize:Powering down
2015-05-05T21:02:19.846Z,1430859739.846 [CBIT](INFO): Clearing failed state for component DVL_micro
2015-05-05T21:02:19.846Z,1430859739.846 [DVL_micro] No Fault, FailCount= 1
2015-05-05T21:02:24.813Z,1430859744.813 [DVL_micro](INFO): Initializing
2015-05-05T21:02:49.859Z,1430859769.859 [Default:CheckIn] Running Loop=1
2015-05-05T21:02:49.876Z,1430859769.876 [Default:CheckIn](INFO): Aggregate::initialize Default:CheckIn
2015-05-05T21:02:49.876Z,1430859769.876 [Default:CheckIn:A.SetSpeed] Running Loop=1
2015-05-05T21:02:49.876Z,1430859769.876 [Default:CheckIn:A.SetSpeed](DEBUG): Initialize.
2015-05-05T21:02:49.876Z,1430859769.876 [Default:CheckIn:Read_GPS] Running Loop=1
2015-05-05T21:02:49.877Z,1430859769.877 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2015-05-05T21:02:49.879Z,1430859769.879 [Default:CheckIn:A.SetSpeed] Running Loop=1
2015-05-05T21:03:28.506Z,1430859808.506 [Depth_Keller](ERROR): Pressure reading out of range: 1830.301270 decibar
2015-05-05T21:03:32.672Z,1430859812.672 [BPC1](ERROR): Failed to receive battery data
2015-05-05T21:03:32.672Z,1430859812.672 [BPC1] Communications Fault, FailCount= 1
2015-05-05T21:03:32.672Z,1430859812.672 [BPC1](ERROR): Communications Fault
2015-05-05T21:03:32.739Z,1430859812.739 [CBIT](ERROR): Communications Fault in component: BPC1
2015-05-05T21:03:34.026Z,1430859814.026 [CBIT](INFO): Clearing failed state for component BPC1
2015-05-05T21:03:34.026Z,1430859814.026 [BPC1] No Fault, FailCount= 1
2015-05-05T21:03:59.785Z,1430859839.785 [CommandLine](IMPORTANT): got command failComponent
2015-05-05T21:03:59.785Z,1430859839.785 [CommandLine](IMPORTANT): Failed components:
2015-05-05T21:03:59.786Z,1430859839.786 [CommandLine](IMPORTANT): No failed Components.
2015-05-05T21:04:04.089Z,1430859844.089 [BPC1](ERROR): Failed to receive battery data
2015-05-05T21:04:04.089Z,1430859844.089 [BPC1] Communications Fault, FailCount= 1
2015-05-05T21:04:04.089Z,1430859844.089 [BPC1](ERROR): Communications Fault
2015-05-05T21:04:04.112Z,1430859844.112 [CBIT](ERROR): Communications Fault in component: BPC1
2015-05-05T21:04:05.375Z,1430859845.375 [CBIT](INFO): Clearing failed state for component BPC1
2015-05-05T21:04:05.375Z,1430859845.375 [BPC1] No Fault, FailCount= 1
2015-05-05T21:04:21.565Z,1430859861.565 [BPC1](ERROR): Failed to receive battery data
2015-05-05T21:04:21.565Z,1430859861.565 [BPC1] Communications Fault, FailCount= 2
2015-05-05T21:04:21.565Z,1430859861.565 [BPC1](ERROR): Communications Fault
2015-05-05T21:04:21.621Z,1430859861.621 [CBIT](ERROR): Communications Fault in component: BPC1
2015-05-05T21:04:22.873Z,1430859862.873 [CBIT](INFO): Clearing failed state for component BPC1
2015-05-05T21:04:22.873Z,1430859862.873 [BPC1] No Fault, FailCount= 2
2015-05-05T21:04:25.169Z,1430859865.169 [DeadReckonUsingMultipleVelocitySources](FAULT): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2015-05-05T21:04:25.169Z,1430859865.169 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2015-05-05T21:04:25.170Z,1430859865.170 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2015-05-05T21:04:25.172Z,1430859865.172 [DeadReckonUsingSpeedCalculator](FAULT): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2015-05-05T21:04:25.172Z,1430859865.172 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 3
2015-05-05T21:04:25.172Z,1430859865.172 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2015-05-05T21:04:25.184Z,1430859865.184 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2015-05-05T21:04:25.184Z,1430859865.184 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2015-05-05T21:04:25.606Z,1430859865.606 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2015-05-05T21:04:25.606Z,1430859865.606 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2015-05-05T21:04:25.606Z,1430859865.606 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2015-05-05T21:04:25.606Z,1430859865.606 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 3
2015-05-05T21:04:28.833Z,1430859868.833 [Depth_Keller](ERROR): Pressure reading out of range: 1830.298706 decibar
2015-05-05T21:04:28.867Z,1430859868.867 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2015-05-05T21:04:28.867Z,1430859868.867 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2015-05-05T21:04:29.299Z,1430859869.299 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 0 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T21:04:29.744Z,1430859869.744 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 1 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T21:04:30.174Z,1430859870.174 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 2 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T21:04:30.678Z,1430859870.678 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 3 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T21:04:31.470Z,1430859871.470 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 4 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T21:04:32.102Z,1430859872.102 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 5 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T21:04:54.279Z,1430859894.279 [BPC1](ERROR): Failed to receive battery data
2015-05-05T21:04:54.279Z,1430859894.279 [BPC1] Communications Fault, FailCount= 1
2015-05-05T21:04:54.279Z,1430859894.279 [BPC1](ERROR): Communications Fault
2015-05-05T21:04:54.302Z,1430859894.302 [CBIT](ERROR): Communications Fault in component: BPC1
2015-05-05T21:04:55.596Z,1430859895.596 [CBIT](INFO): Clearing failed state for component BPC1
2015-05-05T21:04:55.597Z,1430859895.597 [BPC1] No Fault, FailCount= 1
2015-05-05T21:05:14.775Z,1430859914.775 [NAL9602](FAULT): GPS failed to acquire within timeout.
2015-05-05T21:05:14.775Z,1430859914.775 [NAL9602] Data Fault, FailCount= 1
2015-05-05T21:05:14.775Z,1430859914.775 [NAL9602](ERROR): Data Fault
2015-05-05T21:05:14.855Z,1430859914.855 [CBIT](ERROR): Data Fault in component: NAL9602
2015-05-05T21:05:15.181Z,1430859915.181 [NAL9602](INFO): Powering down
2015-05-05T21:05:16.093Z,1430859916.093 [CBIT](INFO): Clearing failed state for component NAL9602
2015-05-05T21:05:16.093Z,1430859916.093 [NAL9602] No Fault, FailCount= 1
2015-05-05T21:05:20.299Z,1430859920.299 [NAL9602](INFO): Powering up NAL9602
2015-05-05T21:05:29.138Z,1430859929.138 [Depth_Keller](ERROR): Pressure reading out of range: 1830.275024 decibar
2015-05-05T21:05:31.746Z,1430859931.746 [NAL9602](INFO): NAL9602 initialized
2015-05-05T21:05:40.981Z,1430859940.981 [BPC1](ERROR): Failed to receive battery data
2015-05-05T21:05:40.981Z,1430859940.981 [BPC1] Communications Fault, FailCount= 1
2015-05-05T21:05:40.981Z,1430859940.981 [BPC1](ERROR): Communications Fault
2015-05-05T21:05:41.004Z,1430859941.004 [CBIT](ERROR): Communications Fault in component: BPC1
2015-05-05T21:05:42.364Z,1430859942.364 [CBIT](INFO): Clearing failed state for component BPC1
2015-05-05T21:05:42.364Z,1430859942.364 [BPC1] No Fault, FailCount= 1
2015-05-05T21:05:45.415Z,1430859945.415 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2015-05-05T21:05:45.415Z,1430859945.415 [DVL_micro] Data Fault, FailCount= 1
2015-05-05T21:05:45.415Z,1430859945.415 [DVL_micro](ERROR): Data Fault
2015-05-05T21:05:45.516Z,1430859945.516 [CBIT](ERROR): Data Fault in component: DVL_micro
2015-05-05T21:05:45.921Z,1430859945.921 [DVL_micro](INFO): uninitialize:Powering down
2015-05-05T21:05:46.800Z,1430859946.800 [CBIT](INFO): Clearing failed state for component DVL_micro
2015-05-05T21:05:46.800Z,1430859946.800 [DVL_micro] No Fault, FailCount= 1
2015-05-05T21:05:47.195Z,1430859947.195 [DVL_micro](INFO): Initializing
2015-05-05T21:06:29.377Z,1430859989.377 [Depth_Keller](ERROR): Pressure reading out of range: 1830.321411 decibar
2015-05-05T21:06:52.434Z,1430860012.434 [CommandLine](INFO): End of History
2015-05-05T21:06:57.731Z,1430860017.731 [CommandLine](IMPORTANT): got command schedule list
2015-05-05T21:06:57.731Z,1430860017.731 [CommandLine](FAULT): Scheduling was paused by an error at 2015-05-05T20:56:06Z
2015-05-05T21:07:01.075Z,1430860021.075 [BPC1](ERROR): Failed to receive battery data
2015-05-05T21:07:01.075Z,1430860021.075 [BPC1] Communications Fault, FailCount= 1
2015-05-05T21:07:01.076Z,1430860021.076 [BPC1](ERROR): Communications Fault
2015-05-05T21:07:01.115Z,1430860021.115 [CBIT](ERROR): Communications Fault in component: BPC1
2015-05-05T21:07:02.394Z,1430860022.394 [CBIT](INFO): Clearing failed state for component BPC1
2015-05-05T21:07:02.394Z,1430860022.394 [BPC1] No Fault, FailCount= 1
2015-05-05T21:07:29.655Z,1430860049.655 [DeadReckonUsingMultipleVelocitySources](FAULT): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2015-05-05T21:07:29.655Z,1430860049.655 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2015-05-05T21:07:29.655Z,1430860049.655 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2015-05-05T21:07:29.657Z,1430860049.657 [DeadReckonUsingSpeedCalculator](FAULT): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2015-05-05T21:07:29.657Z,1430860049.657 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 4
2015-05-05T21:07:29.657Z,1430860049.657 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2015-05-05T21:07:29.691Z,1430860049.691 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2015-05-05T21:07:29.692Z,1430860049.692 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2015-05-05T21:07:30.110Z,1430860050.110 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2015-05-05T21:07:30.110Z,1430860050.110 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2015-05-05T21:07:30.111Z,1430860050.111 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2015-05-05T21:07:30.111Z,1430860050.111 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 4
2015-05-05T21:07:30.559Z,1430860050.559 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2015-05-05T21:07:30.560Z,1430860050.560 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2015-05-05T21:07:30.976Z,1430860050.976 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 0 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T21:07:31.391Z,1430860051.391 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 1 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T21:07:31.798Z,1430860051.798 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 2 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T21:07:32.229Z,1430860052.229 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 3 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T21:07:32.707Z,1430860052.707 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 4 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T21:07:33.139Z,1430860053.139 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 5 cycles since last successful read, accepting data for 5 cycles.
2015-05-05T21:07:33.541Z,1430860053.541 [BPC1](ERROR): Failed to receive battery data
2015-05-05T21:07:33.541Z,1430860053.541 [BPC1] Communications Fault, FailCount= 1
2015-05-05T21:07:33.541Z,1430860053.541 [BPC1](ERROR): Communications Fault
2015-05-05T21:07:33.581Z,1430860053.581 [CBIT](ERROR): Communications Fault in component: BPC1
2015-05-05T21:07:34.848Z,1430860054.848 [CBIT](INFO): Clearing failed state for component BPC1
2015-05-05T21:07:34.848Z,1430860054.848 [BPC1] No Fault, FailCount= 1
2015-05-05T21:07:50.058Z,1430860070.058 [Default:CheckIn:Read_GPS](INFO): Timed out from 2015-05-05T21:02:49.9Z
2015-05-05T21:07:50.058Z,1430860070.058 [Default:CheckIn:Read_GPS] Stopped
2015-05-05T21:07:50.058Z,1430860070.058 [Default:CheckIn:Read_Iridium] Running Loop=1
2015-05-05T21:07:50.531Z,1430860070.531 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2015-05-05T21:07:55.033Z,1430860075.033 [Depth_Keller](ERROR): Pressure reading out of range: 1830.306519 decibar
2015-05-05T21:07:55.447Z,1430860075.447 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20150505T205432/Courier0004.lzma
2015-05-05T21:07:56.322Z,1430860076.322 [DataOverHttps](INFO): Moved sent file to Logs/20150505T205432/Courier0004.lzma.bak
2015-05-05T21:07:56.323Z,1430860076.323 [DataOverHttps](IMPORTANT): SBD MOMSN=3420635, MTMSN=20150505T210755
2015-05-05T21:08:01.637Z,1430860081.637 [DataOverHttps](INFO): Received command:schedule resume
2015-05-05T21:08:01.691Z,1430860081.691 [CommandLine](IMPORTANT): got command schedule resume
2015-05-05T21:08:01.692Z,1430860081.692 [CommandLine](IMPORTANT): Scheduling is resumed
2015-05-05T21:08:06.916Z,1430860086.916 [Depth_Keller](ERROR): Pressure reading out of range: 1830.309082 decibar
2015-05-05T21:08:07.401Z,1430860087.401 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20150505T205432/Courier0008.lzma
2015-05-05T21:08:08.313Z,1430860088.313 [DataOverHttps](INFO): Moved sent file to Logs/20150505T205432/Courier0008.lzma.bak
2015-05-05T21:08:08.313Z,1430860088.313 [DataOverHttps](INFO): SBD MOMSN=3420638
2015-05-05T21:08:18.991Z,1430860098.991 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20150505T205432/Courier0012.lzma
2015-05-05T21:08:19.891Z,1430860099.891 [DataOverHttps](INFO): Moved sent file to Logs/20150505T205432/Courier0012.lzma.bak
2015-05-05T21:08:19.891Z,1430860099.891 [DataOverHttps](INFO): SBD MOMSN=3420640
2015-05-05T21:08:20.801Z,1430860100.801 [BPC1](DEBUG): Received data from all battery sticks
2015-05-05T21:08:30.126Z,1430860110.126 [DataOverHttps](INFO): Sending 674 bytes from file Logs/20150505T205432/Express0005.lzma
2015-05-05T21:08:30.996Z,1430860110.996 [DataOverHttps](INFO): Moved sent file to Logs/20150505T205432/Express0005.lzma.bak
2015-05-05T21:08:30.996Z,1430860110.996 [DataOverHttps](INFO): SBD MOMSN=3420642
2015-05-05T21:08:35.136Z,1430860115.136 [Depth_Keller](ERROR): Pressure reading out of range: 1830.280273 decibar
2015-05-05T21:08:41.667Z,1430860121.667 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20150505T205432/Express0009.lzma
2015-05-05T21:08:42.598Z,1430860122.598 [DataOverHttps](INFO): Moved sent file to Logs/20150505T205432/Express0009.lzma.bak
2015-05-05T21:08:42.598Z,1430860122.598 [DataOverHttps](INFO): SBD MOMSN=3420666
2015-05-05T21:08:46.796Z,1430860126.796 [Depth_Keller](ERROR): Pressure reading out of range: 1830.301270 decibar
2015-05-05T21:08:52.936Z,1430860132.936 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2015-05-05T21:08:52.936Z,1430860132.936 [DVL_micro] Data Fault, FailCount= 1
2015-05-05T21:08:52.936Z,1430860132.936 [DVL_micro](ERROR): Data Fault
2015-05-05T21:08:53.018Z,1430860133.018 [CBIT](ERROR): Data Fault in component: DVL_micro
2015-05-05T21:08:53.362Z,1430860133.362 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20150505T205432/Express0013.lzma
2015-05-05T21:08:53.444Z,1430860133.444 [DVL_micro](INFO): uninitialize:Powering down
2015-05-05T21:08:54.325Z,1430860134.325 [DataOverHttps](INFO): Moved sent file to Logs/20150505T205432/Express0013.lzma.bak
2015-05-05T21:08:54.325Z,1430860134.325 [DataOverHttps](INFO): SBD MOMSN=3420668
2015-05-05T21:08:54.434Z,1430860134.434 [CBIT](INFO): Clearing failed state for component DVL_micro
2015-05-05T21:08:54.434Z,1430860134.434 [DVL_micro] No Fault, FailCount= 1
2015-05-05T21:08:54.810Z,1430860134.810 [DVL_micro](INFO): Initializing
2015-05-05T21:08:54.860Z,1430860134.860 [HFRadarCompactModelForecaster](DEBUG): Found new ECs!
2015-05-05T21:08:57.834Z,1430860137.834 [HFRadarCompactModelForecaster](IMPORTANT): forecast time 201505051800 published
2015-05-05T21:09:00.913Z,1430860140.913 [Default:CheckIn:Read_Iridium] Stopped
2015-05-05T21:09:00.913Z,1430860140.913 [Default:CheckIn](INFO): Completed Default:CheckIn
2015-05-05T21:09:00.913Z,1430860140.913 [Default:CheckIn] Stopped
2015-05-05T21:09:00.913Z,1430860140.913 [Default:CheckIn](INFO): Aggregate::uninitialize Default:CheckIn
2015-05-05T21:09:00.913Z,1430860140.913 [Default:CheckIn:A.SetSpeed] Stopped
2015-05-05T21:09:00.913Z,1430860140.913 [Default:CheckIn:A.SetSpeed](DEBUG): Uninitialize.
2015-05-05T21:09:19.730Z,1430860159.730 [CommandLine](IMPORTANT): got command quit
2015-05-05T21:09:20.741Z,1430860160.741 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2015-05-05T21:09:20.741Z,1430860160.741 [CommandLine ThreadHandler](INFO): Thread cancelled.
2015-05-05T21:09:20.886Z,1430860160.886 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye!
2015-05-05T21:09:20.886Z,1430860160.886 [CommandLine ThreadHandler](INFO): Thread cancelled.
2015-05-05T21:09:20.887Z,1430860160.887 [CommandLine](INFO): Join timeout helper Thread ID is 1004
2015-05-05T21:09:20.892Z,1430860160.892 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2015-05-05T21:09:20.892Z,1430860160.892 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2015-05-05T21:09:20.893Z,1430860160.893 [NavChartDb](INFO): Join timeout helper Thread ID is 1005
2015-05-05T21:09:21.122Z,1430860161.122 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2015-05-05T21:09:21.123Z,1430860161.123 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2015-05-05T21:09:21.130Z,1430860161.130 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2015-05-05T21:09:21.130Z,1430860161.130 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2015-05-05T21:09:21.131Z,1430860161.131 [Radio_Surface](INFO): Join timeout helper Thread ID is 1006
2015-05-05T21:09:21.307Z,1430860161.307 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2015-05-05T21:09:21.308Z,1430860161.308 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2015-05-05T21:09:21.311Z,1430860161.311 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2015-05-05T21:09:21.311Z,1430860161.311 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2015-05-05T21:09:21.311Z,1430860161.311 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 1007
2015-05-05T21:09:21.579Z,1430860161.579 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2015-05-05T21:09:21.579Z,1430860161.579 [WetLabsBB2FL](INFO): Powering down
2015-05-05T21:09:21.580Z,1430860161.580 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2015-05-05T21:09:21.594Z,1430860161.594 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2015-05-05T21:09:21.594Z,1430860161.594 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2015-05-05T21:09:21.594Z,1430860161.594 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 1008
2015-05-05T21:09:21.595Z,1430860161.595 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2015-05-05T21:09:21.595Z,1430860161.595 [CTD_NeilBrown](INFO): Powering down
2015-05-05T21:09:21.596Z,1430860161.596 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2015-05-05T21:09:21.612Z,1430860161.612 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2015-05-05T21:09:21.612Z,1430860161.612 [logger ThreadHandler](INFO): Thread cancelled.
2015-05-05T21:09:21.613Z,1430860161.613 [logger](INFO): Join timeout helper Thread ID is 1009
2015-05-05T21:09:21.635Z,1430860161.635 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2015-05-05T21:09:21.635Z,1430860161.635 [logger ThreadHandler](INFO): Thread cancelled.
2015-05-05T21:09:21.652Z,1430860161.652 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2015-05-05T21:09:21.652Z,1430860161.652 [CommandLine ThreadHandler](INFO): Thread cancelled.
2015-05-05T21:09:21.652Z,1430860161.652 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2015-05-05T21:09:21.652Z,1430860161.652 [controlThread ThreadHandler](INFO): Thread cancelled.
2015-05-05T21:09:21.653Z,1430860161.653 [controlThread](INFO): Join timeout helper Thread ID is 1010
2015-05-05T21:09:25.958Z,1430860165.958 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2015-05-05T21:09:25.958Z,1430860165.958 [controlThread](DEBUG): Uninitializing ControlThread
2015-05-05T21:09:25.959Z,1430860165.959 [Aanderaa_O2](INFO): Powering down
2015-05-05T21:09:25.961Z,1430860165.961 [AHRS_sp3003D](INFO): Powering down
2015-05-05T21:09:26.118Z,1430860166.118 [DVL_micro](INFO): uninitialize:Powering down
2015-05-05T21:09:26.119Z,1430860166.119 [NAL9602](INFO): Powering down
2015-05-05T21:09:26.120Z,1430860166.120 [DAT](INFO): Powering down
2015-05-05T21:09:26.263Z,1430860166.263 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2015-05-05T21:09:26.265Z,1430860166.265 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2015-05-05T21:09:26.266Z,1430860166.266 [Default] Stopped
2015-05-05T21:09:26.266Z,1430860166.266 [Default](INFO): Aggregate::uninitialize Default
2015-05-05T21:09:26.266Z,1430860166.266 [Default:A.GoToSurface] Stopped
2015-05-05T21:09:26.266Z,1430860166.266 [Default:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2015-05-05T21:09:26.266Z,1430860166.266 [Default:WaitAtTheSurface] Stopped
2015-05-05T21:09:26.267Z,1430860166.267 [Default:WaitAtTheSurface](INFO): Aggregate::uninitialize Default:WaitAtTheSurface
2015-05-05T21:09:26.267Z,1430860166.267 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Stopped
2015-05-05T21:09:26.267Z,1430860166.267 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Uninitialize.
2015-05-05T21:09:26.270Z,1430860166.270 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2015-05-05T21:09:26.270Z,1430860166.270 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2015-05-05T21:09:26.270Z,1430860166.270 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2015-05-05T21:09:26.271Z,1430860166.271 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2015-05-05T21:09:26.271Z,1430860166.271 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2015-05-05T21:09:26.271Z,1430860166.271 [BuoyancyServo](INFO): Powering down
2015-05-05T21:09:26.282Z,1430860166.282 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2015-05-05T21:09:26.282Z,1430860166.282 [ElevatorServo](INFO): Powering down
2015-05-05T21:09:26.283Z,1430860166.283 [MassServo](DEBUG): Uninitialize Mass Servo.
2015-05-05T21:09:26.283Z,1430860166.283 [MassServo](INFO): Powering down
2015-05-05T21:09:26.284Z,1430860166.284 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2015-05-05T21:09:26.284Z,1430860166.284 [RudderServo](INFO): Powering down
2015-05-05T21:09:26.285Z,1430860166.285 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2015-05-05T21:09:26.285Z,1430860166.285 [ThrusterServo](INFO): Powering down
2015-05-05T21:09:26.286Z,1430860166.286 [SBIT](DEBUG): Uninitialize SBIT Component.
2015-05-05T21:09:26.286Z,1430860166.286 [IBIT](DEBUG): Uninitialize IBIT Component.
2015-05-05T21:09:26.287Z,1430860166.287 [CBIT](DEBUG): Uninitialize CBIT Component.
2015-05-05T21:09:26.319Z,1430860166.319 [controlThread ThreadHandler](INFO): Thread cancelled.
2015-05-05T21:09:26.392Z,1430860166.392 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2015-05-05T21:09:26.397Z,1430860166.397 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2015-05-05T21:09:26.457Z,1430860166.457 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2015-05-05T21:09:26.505Z,1430860166.505 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2015-05-05T21:09:26.553Z,1430860166.553 [logger ThreadHandler](INFO): Thread cancelled.