2014-05-13T15:24:39.748Z,1399994679.748 [Supervisor](DEBUG): Initializing supervisor.
2014-05-13T15:24:39.751Z,1399994679.751 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2014-05-13T15:24:39.751Z,1399994679.751 [SyncHandler](INFO): Protected caller Thread ID is 937
2014-05-13T15:24:39.752Z,1399994679.752 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2014-05-13T15:24:39.753Z,1399994679.753 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2014-05-13T15:24:39.753Z,1399994679.753 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 938
2014-05-13T15:24:39.756Z,1399994679.756 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2014-05-13T15:24:39.768Z,1399994679.768 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2014-05-13T15:24:39.769Z,1399994679.769 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2014-05-13T15:24:39.769Z,1399994679.769 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 939
2014-05-13T15:24:39.770Z,1399994679.770 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2014-05-13T15:24:39.771Z,1399994679.771 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2014-05-13T15:24:39.771Z,1399994679.771 [logger ThreadHandler](INFO): Protected caller Thread ID is 940
2014-05-13T15:24:39.774Z,1399994679.774 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2014-05-13T15:24:39.774Z,1399994679.774 [Supervisor](INFO): Looking for Config files in directory: Config/
2014-05-13T15:24:39.775Z,1399994679.775 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2014-05-13T15:24:40.152Z,1399994680.152 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2014-05-13T15:24:40.152Z,1399994680.152 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2014-05-13T15:24:40.446Z,1399994680.446 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2014-05-13T15:24:40.446Z,1399994680.446 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2014-05-13T15:24:40.533Z,1399994680.533 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2014-05-13T15:24:40.534Z,1399994680.534 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2014-05-13T15:24:40.726Z,1399994680.726 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2014-05-13T15:24:40.726Z,1399994680.726 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2014-05-13T15:24:40.892Z,1399994680.892 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2014-05-13T15:24:40.893Z,1399994680.893 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2014-05-13T15:24:41.238Z,1399994681.238 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2014-05-13T15:24:41.238Z,1399994681.238 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2014-05-13T15:24:41.427Z,1399994681.427 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2014-05-13T15:24:41.428Z,1399994681.428 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2014-05-13T15:24:41.791Z,1399994681.791 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2014-05-13T15:24:41.791Z,1399994681.791 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2014-05-13T15:24:41.904Z,1399994681.904 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2014-05-13T15:24:41.904Z,1399994681.904 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2014-05-13T15:24:42.419Z,1399994682.419 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2014-05-13T15:24:42.420Z,1399994682.420 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2014-05-13T15:24:42.532Z,1399994682.532 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2014-05-13T15:24:42.533Z,1399994682.533 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2014-05-13T15:24:42.621Z,1399994682.621 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2014-05-13T15:24:42.732Z,1399994682.732 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2014-05-13T15:24:42.733Z,1399994682.733 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2014-05-13T15:24:42.838Z,1399994682.838 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2014-05-13T15:24:42.839Z,1399994682.839 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2014-05-13T15:24:42.981Z,1399994682.981 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2014-05-13T15:24:42.983Z,1399994682.983 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2014-05-13T15:24:42.984Z,1399994682.984 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2014-05-13T15:24:43.096Z,1399994683.096 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2014-05-13T15:24:43.233Z,1399994683.233 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2014-05-13T15:24:43.334Z,1399994683.334 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2014-05-13T15:24:43.430Z,1399994683.430 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2014-05-13T15:24:43.583Z,1399994683.583 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2014-05-13T15:24:43.706Z,1399994683.706 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2014-05-13T15:24:43.795Z,1399994683.795 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2014-05-13T15:24:43.903Z,1399994683.903 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2014-05-13T15:24:44.008Z,1399994684.008 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2014-05-13T15:24:44.108Z,1399994684.108 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2014-05-13T15:24:44.198Z,1399994684.198 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Estimation.cfg
2014-05-13T15:24:44.300Z,1399994684.300 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/root/
2014-05-13T15:24:44.300Z,1399994684.300 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2014-05-13T15:24:44.302Z,1399994684.302 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2014-05-13T15:24:44.638Z,1399994684.638 [AHRS_sp3003D] Loaded
2014-05-13T15:24:44.638Z,1399994684.638 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2014-05-13T15:24:44.936Z,1399994684.936 [Batt_Ocean_Server] Loaded
2014-05-13T15:24:44.937Z,1399994684.937 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2014-05-13T15:24:44.951Z,1399994684.951 [Depth_Keller] Loaded
2014-05-13T15:24:44.951Z,1399994684.951 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2014-05-13T15:24:44.956Z,1399994684.956 [DropWeight] Loaded
2014-05-13T15:24:44.956Z,1399994684.956 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2014-05-13T15:24:45.101Z,1399994685.101 [DVL_micro] Loaded
2014-05-13T15:24:45.101Z,1399994685.101 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2014-05-13T15:24:45.201Z,1399994685.201 [NAL9602] Loaded
2014-05-13T15:24:45.202Z,1399994685.202 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2014-05-13T15:24:45.255Z,1399994685.255 [Onboard] Loaded
2014-05-13T15:24:45.255Z,1399994685.255 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2014-05-13T15:24:45.262Z,1399994685.262 [Radio_Freewave] Loaded
2014-05-13T15:24:45.263Z,1399994685.263 [ComponentRegistry](DEBUG): Component "Radio_Freewave" handled in its own thread.
2014-05-13T15:24:45.264Z,1399994685.264 [Radio_Freewave ThreadHandler](DEBUG): Created PCaller Thread at 406074E0
2014-05-13T15:24:45.264Z,1399994685.264 [Radio_Freewave ThreadHandler](INFO): Protected caller Thread ID is 1022
2014-05-13T15:24:45.271Z,1399994685.271 [SCPI] Loaded
2014-05-13T15:24:45.272Z,1399994685.272 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread.
2014-05-13T15:24:45.272Z,1399994685.272 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2014-05-13T15:24:45.273Z,1399994685.273 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2014-05-13T15:24:45.437Z,1399994685.437 [InternalSim] Loaded
2014-05-13T15:24:45.438Z,1399994685.438 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2014-05-13T15:24:45.438Z,1399994685.438 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2014-05-13T15:24:45.439Z,1399994685.439 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2014-05-13T15:24:45.686Z,1399994685.686 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2014-05-13T15:24:45.687Z,1399994685.687 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2014-05-13T15:24:45.693Z,1399994685.693 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2014-05-13T15:24:45.698Z,1399994685.698 [AsyncPiEstimator] Loaded
2014-05-13T15:24:45.698Z,1399994685.698 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2014-05-13T15:24:45.699Z,1399994685.699 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406E44E0
2014-05-13T15:24:45.700Z,1399994685.700 [AsyncPiEstimator ThreadHandler](INFO): Protected caller Thread ID is 1023
2014-05-13T15:24:45.700Z,1399994685.700 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2014-05-13T15:24:45.701Z,1399994685.701 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2014-05-13T15:24:45.783Z,1399994685.783 [DeadReckonUsingMultipleVelocitySources] Loaded
2014-05-13T15:24:45.783Z,1399994685.783 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2014-05-13T15:24:45.830Z,1399994685.830 [DeadReckonWithRespectToWater] Loaded
2014-05-13T15:24:45.830Z,1399994685.830 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToWater" handled in the control thread.
2014-05-13T15:24:45.877Z,1399994685.877 [DeadReckonWithRespectToSeafloor] Loaded
2014-05-13T15:24:45.878Z,1399994685.878 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToSeafloor" handled in the control thread.
2014-05-13T15:24:45.926Z,1399994685.926 [DeadReckonUsingDVLWaterTrack] Loaded
2014-05-13T15:24:45.927Z,1399994685.927 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingDVLWaterTrack" handled in the control thread.
2014-05-13T15:24:45.943Z,1399994685.943 [NavChart] Loaded
2014-05-13T15:24:45.944Z,1399994685.944 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2014-05-13T15:24:45.948Z,1399994685.948 [UniversalFixResidualReporter] Loaded
2014-05-13T15:24:45.948Z,1399994685.948 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2014-05-13T15:24:45.949Z,1399994685.949 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2014-05-13T15:24:45.949Z,1399994685.949 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2014-05-13T15:24:45.000Z,1399994686.000 [VerticalControl](DEBUG): Construct VerticalControl.
2014-05-13T15:24:46.114Z,1399994686.114 [VerticalControl] Loaded
2014-05-13T15:24:46.115Z,1399994686.115 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2014-05-13T15:24:46.115Z,1399994686.115 [HorizontalControl](DEBUG): Construct HorizontalControl.
2014-05-13T15:24:46.186Z,1399994686.186 [HorizontalControl] Loaded
2014-05-13T15:24:46.187Z,1399994686.187 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2014-05-13T15:24:46.187Z,1399994686.187 [SpeedControl](DEBUG): Construct SpeedControl.
2014-05-13T15:24:46.189Z,1399994686.189 [SpeedControl] Loaded
2014-05-13T15:24:46.190Z,1399994686.190 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2014-05-13T15:24:46.190Z,1399994686.190 [LoopControl](DEBUG): Construct LoopControl.
2014-05-13T15:24:46.191Z,1399994686.191 [LoopControl] Loaded
2014-05-13T15:24:46.191Z,1399994686.191 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2014-05-13T15:24:46.192Z,1399994686.192 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2014-05-13T15:24:46.192Z,1399994686.192 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2014-05-13T15:24:46.211Z,1399994686.211 [DepthRateCalculator] Loaded
2014-05-13T15:24:46.212Z,1399994686.212 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2014-05-13T15:24:46.217Z,1399994686.217 [PitchRateCalculator] Loaded
2014-05-13T15:24:46.218Z,1399994686.218 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2014-05-13T15:24:46.225Z,1399994686.225 [SpeedCalculator] Loaded
2014-05-13T15:24:46.226Z,1399994686.226 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2014-05-13T15:24:46.242Z,1399994686.242 [TempGradientCalculator] Loaded
2014-05-13T15:24:46.243Z,1399994686.243 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2014-05-13T15:24:46.248Z,1399994686.248 [YawRateCalculator] Loaded
2014-05-13T15:24:46.248Z,1399994686.248 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2014-05-13T15:24:46.249Z,1399994686.249 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2014-05-13T15:24:46.249Z,1399994686.249 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2014-05-13T15:24:46.372Z,1399994686.372 [CTD_NeilBrown] Loaded
2014-05-13T15:24:46.372Z,1399994686.372 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2014-05-13T15:24:46.373Z,1399994686.373 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 407864E0
2014-05-13T15:24:46.374Z,1399994686.374 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 1024
2014-05-13T15:24:46.387Z,1399994686.387 [ISUS] Loaded
2014-05-13T15:24:46.387Z,1399994686.387 [ComponentRegistry](DEBUG): SyncComponent "ISUS" handled in the control thread.
2014-05-13T15:24:46.403Z,1399994686.403 [PAR_Licor] Loaded
2014-05-13T15:24:46.403Z,1399994686.403 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2014-05-13T15:24:46.440Z,1399994686.440 [WetLabsBB2FL] Loaded
2014-05-13T15:24:46.440Z,1399994686.440 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2014-05-13T15:24:46.441Z,1399994686.441 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407B64E0
2014-05-13T15:24:46.442Z,1399994686.442 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 1025
2014-05-13T15:24:46.442Z,1399994686.442 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2014-05-13T15:24:46.443Z,1399994686.443 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2014-05-13T15:24:46.553Z,1399994686.553 [SBIT](DEBUG): Construct Startup Built In Test.
2014-05-13T15:24:46.565Z,1399994686.565 [SBIT] Loaded
2014-05-13T15:24:46.565Z,1399994686.565 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2014-05-13T15:24:46.566Z,1399994686.566 [IBIT](DEBUG): Construct Initiated Built In Test.
2014-05-13T15:24:46.579Z,1399994686.579 [IBIT] Loaded
2014-05-13T15:24:46.579Z,1399994686.579 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2014-05-13T15:24:46.582Z,1399994686.582 [CBIT](DEBUG): Construct CBIT Built In Test.
2014-05-13T15:24:46.653Z,1399994686.653 [CBIT] Loaded
2014-05-13T15:24:46.653Z,1399994686.653 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2014-05-13T15:24:46.654Z,1399994686.654 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2014-05-13T15:24:46.654Z,1399994686.654 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2014-05-13T15:24:46.696Z,1399994686.696 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2014-05-13T15:24:46.697Z,1399994686.697 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2014-05-13T15:24:46.798Z,1399994686.798 [BuoyancyServo] Loaded
2014-05-13T15:24:46.798Z,1399994686.798 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2014-05-13T15:24:46.811Z,1399994686.811 [ElevatorServo] Loaded
2014-05-13T15:24:46.811Z,1399994686.811 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2014-05-13T15:24:46.824Z,1399994686.824 [MassServo] Loaded
2014-05-13T15:24:46.824Z,1399994686.824 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2014-05-13T15:24:46.836Z,1399994686.836 [RudderServo] Loaded
2014-05-13T15:24:46.837Z,1399994686.837 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2014-05-13T15:24:46.849Z,1399994686.849 [ThrusterServo] Loaded
2014-05-13T15:24:46.849Z,1399994686.849 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2014-05-13T15:24:46.850Z,1399994686.850 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2014-05-13T15:24:46.850Z,1399994686.850 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2014-05-13T15:24:46.874Z,1399994686.874 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2014-05-13T15:24:46.876Z,1399994686.876 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2014-05-13T15:24:46.877Z,1399994686.877 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2014-05-13T15:24:46.883Z,1399994686.883 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2014-05-13T15:24:46.885Z,1399994686.885 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 408854E0
2014-05-13T15:24:46.885Z,1399994686.885 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1026
2014-05-13T15:24:46.890Z,1399994686.890 [Supervisor](INFO): Main Thread ID is 772
2014-05-13T15:24:46.890Z,1399994686.890 [Supervisor](DEBUG): Running supervisor.
2014-05-13T15:24:46.891Z,1399994686.891 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1027
2014-05-13T15:24:46.895Z,1399994686.895 [controlThread ThreadHandler](INFO): Handler Thread ID is 1028
2014-05-13T15:24:46.895Z,1399994686.895 [controlThread](DEBUG): Initializing ControlThread
2014-05-13T15:24:46.898Z,1399994686.898 [logger ThreadHandler](INFO): Handler Thread ID is 1029
2014-05-13T15:24:46.918Z,1399994686.918 [Radio_Freewave ThreadHandler](INFO): Handler Thread ID is 1030
2014-05-13T15:24:46.934Z,1399994686.934 [AsyncPiEstimator ThreadHandler](INFO): Handler Thread ID is 1031
2014-05-13T15:24:46.934Z,1399994686.934 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2014-05-13T15:24:46.958Z,1399994686.958 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 1032
2014-05-13T15:24:46.958Z,1399994686.958 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2014-05-13T15:24:46.962Z,1399994686.962 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2014-05-13T15:24:46.971Z,1399994686.971 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 1034
2014-05-13T15:24:46.972Z,1399994686.972 [WetLabsBB2FL](INFO): Powering down
2014-05-13T15:24:47.000Z,1399994687.000 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1035
2014-05-13T15:24:47.003Z,1399994687.003 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2014-05-13T15:24:47.004Z,1399994687.004 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2014-05-13T15:24:47.004Z,1399994687.004 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2014-05-13T15:24:47.004Z,1399994687.004 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2014-05-13T15:24:47.004Z,1399994687.004 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2014-05-13T15:24:47.005Z,1399994687.005 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2014-05-13T15:24:47.005Z,1399994687.005 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2014-05-13T15:24:47.006Z,1399994687.006 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2014-05-13T15:24:47.006Z,1399994687.006 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2014-05-13T15:24:48.461Z,1399994688.461 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2014-05-13T15:24:48.494Z,1399994688.494 [InternalSim](DEBUG):  InternalSim initializing...
2014-05-13T15:24:48.612Z,1399994688.612 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-05-13T15:24:48.612Z,1399994688.612 [DeadReckonWithRespectToWater](DEBUG): Initializing DeadReckonWithRespectToWater component.
2014-05-13T15:24:48.613Z,1399994688.613 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component.
2014-05-13T15:24:48.613Z,1399994688.613 [DeadReckonUsingDVLWaterTrack](DEBUG): Initializing DeadReckonUsingDVLWaterTrack component.
2014-05-13T15:24:48.614Z,1399994688.614 [NavChart](DEBUG): Initialize NavChart Navigation.
2014-05-13T15:24:48.614Z,1399994688.614 [UniversalFixResidualReporter](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-05-13T15:24:48.614Z,1399994688.614 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2014-05-13T15:24:48.616Z,1399994688.616 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2014-05-13T15:24:48.617Z,1399994688.617 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2014-05-13T15:24:48.617Z,1399994688.617 [LoopControl](DEBUG): Initialize LoopControlComponent.
2014-05-13T15:24:48.618Z,1399994688.618 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-05-13T15:24:48.618Z,1399994688.618 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2014-05-13T15:24:48.618Z,1399994688.618 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2014-05-13T15:24:48.619Z,1399994688.619 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2014-05-13T15:24:48.619Z,1399994688.619 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2014-05-13T15:24:48.622Z,1399994688.622 [SBIT](INFO): Initialize SBIT Component.
2014-05-13T15:24:48.622Z,1399994688.622 [SBIT](IMPORTANT): Tethys CM Info: 
 $Rev:11288
2014-05-13T15:24:48.623Z,1399994688.623 [SBIT](IMPORTANT): Kernel Release:2.6.27.8
2014-05-13T15:24:48.623Z,1399994688.623 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2014-05-13T15:24:48.623Z,1399994688.623 [IBIT](INFO): Initialize IBIT Component.
2014-05-13T15:24:48.633Z,1399994688.633 [CBIT](DEBUG): Initialize CBIT Component.
2014-05-13T15:24:48.633Z,1399994688.633 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2014-05-13T15:24:48.658Z,1399994688.658 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2014-05-13T15:24:48.676Z,1399994688.676 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-13T15:24:48.709Z,1399994688.709 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

    <Guidance:GoToSurface>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="StartupSatComms">

        <Sequence/>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:latitude_fix/>
        </ReadDatum>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:platform_communications/>
        </ReadDatum>

    </Aggregate>

</Mission>


2014-05-13T15:24:48.709Z,1399994688.709 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2014-05-13T15:24:48.797Z,1399994688.797 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2014-05-13T15:24:48.799Z,1399994688.799 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2014-05-13T15:24:48.826Z,1399994688.826 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-13T15:24:48.835Z,1399994688.835 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2014-05-13T15:24:48.866Z,1399994688.866 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-13T15:24:48.889Z,1399994688.889 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2014-05-13T15:24:48.914Z,1399994688.914 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Construct.
2014-05-13T15:24:48.917Z,1399994688.917 [Default:WaitAtTheSurface:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-13T15:24:48.988Z,1399994688.988 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
xmlns:Control="Tethys/Control"
xmlns:Guidance="Tethys/Guidance" 
xmlns:Units="Tethys/Units"
xmlns:Universal="Tethys/Universal"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
Id="Default">

    <DefineArg Name="NeedGPS"><True/></DefineArg>

    <Aggregate Id="GPS">

        <When>
            <Arg Name="NeedGPS"/>
        </When>

<!-- Run at high speed -->

        <Guidance:SetSpeed>
            <Parallel/>
            <Setting><Guidance:SetSpeed.period/><Units:millisecond/><Value>400</Value></Setting>
        </Guidance:SetSpeed>

<!-- Get to the surface -->

        <Guidance:GoToSurface>
            <Sequence/>
        </Guidance:GoToSurface>

<!-- Get GPS fix -->

        <ReadDatum Id="Read_GPS">
            <Universal:latitude_fix/>
        </ReadDatum>

        <Assign><Sequence/><Arg Name="NeedGPS"/><False/></Assign>

    </Aggregate>

    <Aggregate Id="Iridium">

        <Sequence/>

<!-- Run at high speed -->

        <Guidance:SetSpeed>
            <Parallel/>
            <Setting><Guidance:SetSpeed.period/><Units:millisecond/><Value>400</Value></Setting>
        </Guidance:SetSpeed>

<!-- Get to the surface -->

        <Guidance:GoToSurface>
            <Sequence/>
        </Guidance:GoToSurface>

<!-- Do data comms -->

        <ReadDatum Id="Read_Iridium">
            <Timeout Duration="P2H">
                <Guidance:Execute>
                    <Sequence/>
                    <Setting><Guidance:Execute.command/><String>Burn 300</String></Setting>
                </Guidance:Execute>
                <Syslog Severity="Critical">Dropped drop weight due to communications timeout</Syslog>
            </Timeout>
            <Universal:platform_communications/>
        </ReadDatum>

    </Aggregate>

    <Aggregate Id="CallIridium">

        <When>
            <Elapsed><Universal:platform_communications/></Elapsed>
            <Gt><Units:minute/><Value>5.0</Value></Gt>
            <And><Universal:platform_conversation/><Eq><True/></Eq></And>
            <Or><Elapsed><Universal:platform_communications/></Elapsed><Gt><Units:hour/><Value>1.0</Value></Gt></Or>
        </When>

        <Assign><Sequence/><Arg Name="NeedGPS"/><True/></Assign>

        <Call RefId="Iridium"/>

    </Aggregate>

    <Aggregate Id="WaitAtTheSurface">

        <Sequence/>

        <Guidance:SetSpeed Id="RunAtLowSpeed">
            <Parallel/>
            <Setting><Guidance:SetSpeed.period/><Units:second/><Value>5</Value></Setting>
        </Guidance:SetSpeed>

        <Guidance:GoToSurface>
            <Parallel/>
        </Guidance:GoToSurface>

    </Aggregate>

</Mission>


2014-05-13T15:24:48.994Z,1399994688.994 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,DropWeight,DVL_micro,NAL9602,Onboard,SCPI,ISUS,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,DeadReckonUsingMultipleVelocitySources,DeadReckonWithRespectToWater,DeadReckonWithRespectToSeafloor,DeadReckonUsingDVLWaterTrack,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2014-05-13T15:24:49.089Z,1399994689.089 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-05-13T15:24:49.215Z,1399994689.215 [Radio_Freewave](INFO): Powering up
2014-05-13T15:24:49.295Z,1399994689.295 [DVL_micro](INFO): Initializing
2014-05-13T15:24:49.874Z,1399994689.874 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-05-13T15:24:49.882Z,1399994689.882 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-05-13T15:24:49.896Z,1399994689.896 [ElevatorServo](DEBUG): Initializing EZServoServo.
2014-05-13T15:24:49.902Z,1399994689.902 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2014-05-13T15:24:49.916Z,1399994689.916 [MassServo](DEBUG): Initializing EZServoServo.
2014-05-13T15:24:49.922Z,1399994689.922 [MassServo](DEBUG): Initializing MassServo.
2014-05-13T15:24:49.958Z,1399994689.958 [RudderServo](DEBUG): Initializing EZServoServo.
2014-05-13T15:24:49.967Z,1399994689.967 [RudderServo](DEBUG): Initializing RudderServo.
2014-05-13T15:24:49.972Z,1399994689.972 [ThrusterServo](DEBUG): Initializing EZServoServo.
2014-05-13T15:24:49.978Z,1399994689.978 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2014-05-13T15:24:50.019Z,1399994690.019 [Radio_Freewave](IMPORTANT): Starting PPPD with command:/sbin/pppd nocrtscts /dev/ttyS1 noauth 115200 10.1.1.2:10.1.1.1 persist maxfail 0
2014-05-13T15:24:50.305Z,1399994690.305 [NAL9602](INFO): Powering up NAL9602
2014-05-13T15:24:50.715Z,1399994690.715 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2014-05-13T15:24:50.715Z,1399994690.715 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2014-05-13T15:24:50.715Z,1399994690.715 [BuoyancyServo] Communications Fault, FailCount= 1
2014-05-13T15:24:50.715Z,1399994690.715 [BuoyancyServo](ERROR): Communications Fault
2014-05-13T15:24:50.941Z,1399994690.941 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2014-05-13T15:24:51.402Z,1399994691.402 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2014-05-13T15:24:51.403Z,1399994691.403 [BuoyancyServo](INFO): Powering down
2014-05-13T15:24:53.891Z,1399994693.891 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2014-05-13T15:24:53.891Z,1399994693.891 [BuoyancyServo] No Fault, FailCount= 1
2014-05-13T15:24:54.336Z,1399994694.336 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-05-13T15:24:54.337Z,1399994694.337 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-05-13T15:25:01.300Z,1399994701.300 [NAL9602](INFO): NAL9602 initialized
2014-05-13T15:25:04.296Z,1399994704.296 [SBIT](IMPORTANT): Beginning Startup BIT
2014-05-13T15:25:04.299Z,1399994704.299 [CBIT](IMPORTANT): Beginning GF scan
2014-05-13T15:25:31.754Z,1399994731.754 [CBIT](IMPORTANT): No ground fault detected
2014-05-13T15:25:58.535Z,1399994758.535 [SBIT](IMPORTANT): SBIT PASSED
2014-05-13T15:25:58.904Z,1399994758.904 [MissionManager](IMPORTANT): Started mission Startup
2014-05-13T15:25:58.904Z,1399994758.904 [Startup] Running Loop=1
2014-05-13T15:25:58.905Z,1399994758.905 [Startup](INFO): Aggregate::initialize Startup
2014-05-13T15:25:58.905Z,1399994758.905 [Startup:A.GoToSurface] Running Loop=1
2014-05-13T15:25:58.905Z,1399994758.905 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-13T15:25:58.927Z,1399994758.927 [Startup:StartupSatComms] Running Loop=1
2014-05-13T15:25:58.927Z,1399994758.927 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2014-05-13T15:25:58.927Z,1399994758.927 [Startup:StartupSatComms:A] Running Loop=1
2014-05-13T15:25:59.353Z,1399994759.353 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-05-13T15:26:59.187Z,1399994819.187 [Startup:StartupSatComms:A](INFO): Timed out from 2014-05-13T15:25:58.9Z
2014-05-13T15:26:59.188Z,1399994819.188 [Startup:StartupSatComms:A] Stopped
2014-05-13T15:26:59.188Z,1399994819.188 [Startup:StartupSatComms:B] Running Loop=1
2014-05-13T15:26:59.590Z,1399994819.590 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-05-13T15:27:54.281Z,1399994874.281 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-05-13T15:27:54.282Z,1399994874.282 [DVL_micro] Data Fault, FailCount= 1
2014-05-13T15:27:54.282Z,1399994874.282 [DVL_micro](ERROR): Data Fault
2014-05-13T15:27:54.356Z,1399994874.356 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-05-13T15:27:54.710Z,1399994874.710 [DVL_micro](INFO): uninitialize:Powering down
2014-05-13T15:27:55.111Z,1399994875.111 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-05-13T15:27:55.111Z,1399994875.111 [DVL_micro] Hardware Fault, FailCount= 1
2014-05-13T15:27:55.111Z,1399994875.111 [DVL_micro](ERROR): Hardware Fault
2014-05-13T15:27:55.577Z,1399994875.577 [DVL_micro](INFO): Initializing
2014-05-13T15:27:55.606Z,1399994875.606 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-05-13T15:27:55.606Z,1399994875.606 [DVL_micro] No Fault, FailCount= 1
2014-05-13T15:27:58.535Z,1399994878.535 [CommandLine](IMPORTANT): got command ibit
2014-05-13T15:27:58.945Z,1399994878.945 [IBIT](IMPORTANT): Beginning Initiated BIT
2014-05-13T15:27:58.945Z,1399994878.945 [IBIT](IMPORTANT): Beginning control surface checks.
2014-05-13T15:27:58.947Z,1399994878.947 [CBIT](IMPORTANT): Beginning GF scan
2014-05-13T15:28:25.265Z,1399994905.265 [CBIT](IMPORTANT): No ground fault detected
2014-05-13T15:29:49.354Z,1399994989.354 [IBIT](FAULT): Error acquiring IBIT communications status. Timeout expired.
2014-05-13T15:29:49.766Z,1399994989.766 [IBIT](IMPORTANT): Battery Status:
Battery Charge (AH): 234.690002
Voltage: 16.100813
2014-05-13T15:29:49.766Z,1399994989.766 [IBIT](IMPORTANT): batteryCapacityThreshold: 5.000000 Ah
2014-05-13T15:29:49.766Z,1399994989.766 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.500000 V
2014-05-13T15:29:50.162Z,1399994990.162 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2014-05-13T15:29:50.162Z,1399994990.162 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2014-05-13T15:29:50.162Z,1399994990.162 [IBIT](IMPORTANT): Pressure:10.734123 PSI
2014-05-13T15:29:50.163Z,1399994990.163 [IBIT](IMPORTANT): Humidity:9.153950 %
2014-05-13T15:29:50.683Z,1399994990.683 [IBIT](IMPORTANT): surfaceThreshold: 0.500000 m
2014-05-13T15:29:50.684Z,1399994990.684 [IBIT](IMPORTANT): buoyancyNeutral: 300.000000 cc
2014-05-13T15:29:50.684Z,1399994990.684 [IBIT](IMPORTANT): massDefault: 0.000000 cm
2014-05-13T15:29:50.684Z,1399994990.684 [IBIT](IMPORTANT): stopDepth: 112.000000 m
2014-05-13T15:29:50.685Z,1399994990.685 [IBIT](IMPORTANT): abortDepth: 130.000000 m
2014-05-13T15:29:50.685Z,1399994990.685 [IBIT](IMPORTANT): IBIT FAILED
2014-05-13T15:29:51.120Z,1399994991.120 [Startup:StartupSatComms:B](INFO): Timed out from 2014-05-13T15:26:59.2Z
2014-05-13T15:29:51.120Z,1399994991.120 [Startup:StartupSatComms:B] Stopped
2014-05-13T15:29:51.120Z,1399994991.120 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2014-05-13T15:29:51.120Z,1399994991.120 [Startup:StartupSatComms] Stopped
2014-05-13T15:29:51.120Z,1399994991.120 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2014-05-13T15:29:51.149Z,1399994991.149 [Startup](INFO): Completed Startup
2014-05-13T15:29:51.149Z,1399994991.149 [Startup] Stopped
2014-05-13T15:29:51.149Z,1399994991.149 [Startup](INFO): Aggregate::uninitialize Startup
2014-05-13T15:29:51.150Z,1399994991.150 [Startup:A.GoToSurface] Stopped
2014-05-13T15:29:51.150Z,1399994991.150 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-13T15:29:51.584Z,1399994991.584 [MissionManager](IMPORTANT): Started mission Default
2014-05-13T15:29:51.584Z,1399994991.584 [Default] Running Loop=1
2014-05-13T15:29:51.584Z,1399994991.584 [Default](INFO): Aggregate::initialize Default
2014-05-13T15:29:51.584Z,1399994991.584 [Default:Iridium] Running Loop=1
2014-05-13T15:29:51.584Z,1399994991.584 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-05-13T15:29:51.584Z,1399994991.584 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-05-13T15:29:51.584Z,1399994991.584 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-05-13T15:29:51.584Z,1399994991.584 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-05-13T15:29:51.584Z,1399994991.584 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-13T15:29:51.585Z,1399994991.585 [Default:CallIridium] Running Loop=1
2014-05-13T15:29:51.585Z,1399994991.585 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-05-13T15:29:51.585Z,1399994991.585 [Default:CallIridium:A] Running Loop=1
2014-05-13T15:29:51.608Z,1399994991.608 [Default:CallIridium:A] Stopped
2014-05-13T15:29:51.608Z,1399994991.608 [Default:CallIridium:B] Running Loop=1
2014-05-13T15:29:51.608Z,1399994991.608 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-05-13T15:29:51.640Z,1399994991.640 [Default:Iridium:B.GoToSurface] Stopped
2014-05-13T15:29:51.640Z,1399994991.640 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-13T15:29:51.641Z,1399994991.641 [Default:Iridium:Read_Iridium] Running Loop=1
2014-05-13T15:29:51.641Z,1399994991.641 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-05-13T15:29:51.662Z,1399994991.662 [Default:GPS] Running Loop=1
2014-05-13T15:29:51.662Z,1399994991.662 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-05-13T15:29:51.663Z,1399994991.663 [Default:GPS:A.SetSpeed] Running Loop=1
2014-05-13T15:29:51.663Z,1399994991.663 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-05-13T15:29:51.663Z,1399994991.663 [Default:GPS:B.GoToSurface] Running Loop=1
2014-05-13T15:29:51.663Z,1399994991.663 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-13T15:29:51.673Z,1399994991.673 [Default:GPS:B.GoToSurface] Stopped
2014-05-13T15:29:51.673Z,1399994991.673 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-13T15:29:51.673Z,1399994991.673 [Default:GPS:Read_GPS] Running Loop=1
2014-05-13T15:29:51.673Z,1399994991.673 [Default:GPS:A.SetSpeed] Running Loop=1
2014-05-13T15:29:52.120Z,1399994992.120 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-05-13T15:29:52.123Z,1399994992.123 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-05-13T15:30:04.719Z,1399995004.719 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2014-05-13T15:30:36.839Z,1399995036.839 [NAL9602](FAULT): Queried for signal strength and failed to receive proper response. no error
2014-05-13T15:30:36.912Z,1399995036.912 [NAL9602](ERROR): received: 
+CSQ:0

OK: Started
2014-05-13T15:30:36.912Z,1399995036.912 [NAL9602] Data Fault, FailCount= 1
2014-05-13T15:30:36.912Z,1399995036.912 [NAL9602](ERROR): Data Fault
2014-05-13T15:30:37.000Z,1399995037.000 [CBIT](ERROR): Data Fault in component: NAL9602
2014-05-13T15:30:37.355Z,1399995037.355 [NAL9602](INFO): Powering down
2014-05-13T15:30:38.194Z,1399995038.194 [CBIT](INFO): Clearing failed state for component NAL9602
2014-05-13T15:30:38.194Z,1399995038.194 [NAL9602] No Fault, FailCount= 1
2014-05-13T15:30:42.667Z,1399995042.667 [NAL9602](INFO): Powering up NAL9602
2014-05-13T15:30:50.049Z,1399995050.049 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#9 STATUS: 65535
2014-05-13T15:30:53.438Z,1399995053.438 [NAL9602](INFO): NAL9602 initialized
2014-05-13T15:31:00.091Z,1399995060.091 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-05-13T15:31:00.091Z,1399995060.091 [DVL_micro] Data Fault, FailCount= 1
2014-05-13T15:31:00.091Z,1399995060.091 [DVL_micro](ERROR): Data Fault
2014-05-13T15:31:00.175Z,1399995060.175 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-05-13T15:31:00.547Z,1399995060.547 [DVL_micro](INFO): uninitialize:Powering down
2014-05-13T15:31:00.955Z,1399995060.955 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-05-13T15:31:00.955Z,1399995060.955 [DVL_micro] Hardware Fault, FailCount= 1
2014-05-13T15:31:00.955Z,1399995060.955 [DVL_micro](ERROR): Hardware Fault
2014-05-13T15:31:01.374Z,1399995061.374 [DVL_micro](INFO): Initializing
2014-05-13T15:31:01.435Z,1399995061.435 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-05-13T15:31:01.435Z,1399995061.435 [DVL_micro] No Fault, FailCount= 1
2014-05-13T15:32:39.931Z,1399995159.931 [CommandLine](IMPORTANT): got command load 
2014-05-13T15:32:39.932Z,1399995159.932 [CommandLine](FAULT): Incomplete syntax. Try: help load
2014-05-13T15:32:40.032Z,1399995160.032 [CommandLine](IMPORTANT): got command ibit mcp5553 
2014-05-13T15:32:40.093Z,1399995160.093 [CommandLine](IMPORTANT): got command ibit mcp5553 
2014-05-13T15:32:40.186Z,1399995160.186 [CommandLine](IMPORTANT): got command configSet 
2014-05-13T15:32:40.186Z,1399995160.186 [CommandLine](FAULT): Incomplete syntax. Try: help configSet
2014-05-13T15:32:40.280Z,1399995160.280 [CommandLine](IMPORTANT): got command load 
2014-05-13T15:32:40.281Z,1399995160.281 [CommandLine](FAULT): Incomplete syntax. Try: help load
2014-05-13T15:32:40.352Z,1399995160.352 [CommandLine](IMPORTANT): got command ibit mcp5553 
2014-05-13T15:32:40.385Z,1399995160.385 [CommandLine](IMPORTANT): got command ibit mcp5553 
2014-05-13T15:32:40.446Z,1399995160.446 [CommandLine](IMPORTANT): got command burn 234.690002
2014-05-13T15:32:40.528Z,1399995160.528 [CommandLine](IMPORTANT): got command load 
2014-05-13T15:32:40.528Z,1399995160.528 [CommandLine](FAULT): Incomplete syntax. Try: help load
2014-05-13T15:32:40.590Z,1399995160.590 [IBIT](IMPORTANT): Beginning Initiated BIT
2014-05-13T15:32:40.590Z,1399995160.590 [IBIT](IMPORTANT): Beginning control surface checks.
2014-05-13T15:32:40.612Z,1399995160.612 [CBIT](IMPORTANT): Beginning GF scan
2014-05-13T15:32:40.661Z,1399995160.661 [CommandLine](IMPORTANT): got command burn 5.000000
2014-05-13T15:32:40.742Z,1399995160.742 [CommandLine](IMPORTANT): got command ibit mcp5553 13500000
2014-05-13T15:32:40.830Z,1399995160.830 [CommandLine](IMPORTANT): got command ibit mcp5553 55000000
2014-05-13T15:32:40.886Z,1399995160.886 [CommandLine](IMPORTANT): got command ibit mcp5553 750000
2014-05-13T15:32:40.917Z,1399995160.917 [CommandLine](IMPORTANT): got command ibit mcp5553 
2014-05-13T15:32:40.962Z,1399995160.962 [CommandLine](IMPORTANT): got command ibit mcp5553 
2014-05-13T15:32:40.995Z,1399995160.995 [CommandLine](IMPORTANT): got command ibit mcp5553 500000
2014-05-13T15:32:41.063Z,1399995161.063 [CommandLine](IMPORTANT): got command ibit mcp5553 300000000
2014-05-13T15:32:41.177Z,1399995161.177 [CommandLine](IMPORTANT): got command ibit mcp5553 0
2014-05-13T15:32:41.234Z,1399995161.234 [CommandLine](IMPORTANT): got command ibit mcp5553 112000000
2014-05-13T15:32:41.305Z,1399995161.305 [CommandLine](IMPORTANT): got command ibit mcp5553 130000000
2014-05-13T15:32:41.366Z,1399995161.366 [CommandLine](IMPORTANT): got command ibit mcp5553 
2014-05-13T15:32:45.683Z,1399995165.683 [CommandLine](IMPORTANT): Deactivating dropweight wire
2014-05-13T15:33:07.365Z,1399995187.365 [CBIT](IMPORTANT): No ground fault detected
2014-05-13T15:33:10.314Z,1399995190.314 [CommandLine](IMPORTANT): got command failComponent
2014-05-13T15:33:10.314Z,1399995190.314 [CommandLine](IMPORTANT): Failed components:
2014-05-13T15:33:10.314Z,1399995190.314 [CommandLine](IMPORTANT): No failed Components.
2014-05-13T15:34:05.561Z,1399995245.561 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-05-13T15:34:05.561Z,1399995245.561 [DVL_micro] Data Fault, FailCount= 1
2014-05-13T15:34:05.561Z,1399995245.561 [DVL_micro](ERROR): Data Fault
2014-05-13T15:34:05.624Z,1399995245.624 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-05-13T15:34:05.965Z,1399995245.965 [DVL_micro](INFO): uninitialize:Powering down
2014-05-13T15:34:06.382Z,1399995246.382 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-05-13T15:34:06.382Z,1399995246.382 [DVL_micro] Hardware Fault, FailCount= 1
2014-05-13T15:34:06.382Z,1399995246.382 [DVL_micro](ERROR): Hardware Fault
2014-05-13T15:34:06.822Z,1399995246.822 [DVL_micro](INFO): Initializing
2014-05-13T15:34:06.848Z,1399995246.848 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-05-13T15:34:06.849Z,1399995246.849 [DVL_micro] No Fault, FailCount= 1
2014-05-13T15:34:32.006Z,1399995272.006 [IBIT](FAULT): Error acquiring IBIT communications status. Timeout expired.
2014-05-13T15:34:32.409Z,1399995272.409 [IBIT](IMPORTANT): Battery Status:
Battery Charge (AH): 234.549988
Voltage: 16.099375
2014-05-13T15:34:32.409Z,1399995272.409 [IBIT](IMPORTANT): batteryCapacityThreshold: 5.000000 Ah
2014-05-13T15:34:32.410Z,1399995272.410 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.500000 V
2014-05-13T15:34:32.808Z,1399995272.808 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2014-05-13T15:34:32.809Z,1399995272.809 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2014-05-13T15:34:32.809Z,1399995272.809 [IBIT](IMPORTANT): Pressure:10.203115 PSI
2014-05-13T15:34:32.810Z,1399995272.810 [IBIT](IMPORTANT): Humidity:10.131342 %
2014-05-13T15:34:33.297Z,1399995273.297 [IBIT](IMPORTANT): surfaceThreshold: 0.500000 m
2014-05-13T15:34:33.298Z,1399995273.298 [IBIT](IMPORTANT): buoyancyNeutral: 300.000000 cc
2014-05-13T15:34:33.298Z,1399995273.298 [IBIT](IMPORTANT): massDefault: 0.000000 cm
2014-05-13T15:34:33.302Z,1399995273.302 [IBIT](IMPORTANT): stopDepth: 112.000000 m
2014-05-13T15:34:33.303Z,1399995273.303 [IBIT](IMPORTANT): abortDepth: 130.000000 m
2014-05-13T15:34:33.303Z,1399995273.303 [IBIT](IMPORTANT): IBIT FAILED
2014-05-13T15:34:49.945Z,1399995289.945 [NAL9602](INFO): SBD MO Status=2, MOMSN=28343, MT Status=2, MTMSN=0
2014-05-13T15:34:49.945Z,1399995289.945 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-05-13T15:34:59.584Z,1399995299.584 [DVL_micro](ERROR): DVL Failure: Failed to read in all data items. Got 45 of 46
2014-05-13T15:34:59.584Z,1399995299.584 [DVL_micro](ERROR): Failed to parse DVL response:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 -536 -395 -516 -499 3 2 3 3 -26.7 138.8 -524.7 2 88.5 -110.2 -524.7 2 -224 2 88 -110 -524 2 0.27 -1.17 207.9 -3.0 19.5 0.005 35.0 1489 97
2014-05-13T15:35:04.581Z,1399995304.581 [NAL9602](FAULT): GPS failed to acquire within timeout.
2014-05-13T15:35:04.581Z,1399995304.581 [NAL9602] Data Fault, FailCount= 2
2014-05-13T15:35:04.581Z,1399995304.581 [NAL9602](ERROR): Data Fault
2014-05-13T15:35:04.611Z,1399995304.611 [CBIT](ERROR): Data Fault in component: NAL9602
2014-05-13T15:35:04.611Z,1399995304.611 [CBIT](CRITICAL): Data Fault in component: NAL9602
2014-05-13T15:35:04.995Z,1399995304.995 [NAL9602](INFO): Powering down
2014-05-13T15:35:05.052Z,1399995305.052 [CommandLine](FAULT): Scheduling is paused
2014-05-13T15:37:04.596Z,1399995424.596 [CBIT](INFO): Clearing failed count for component NAL9602
2014-05-13T15:37:04.596Z,1399995424.596 [NAL9602] No Fault, FailCount= 2
2014-05-13T15:37:04.952Z,1399995424.952 [NAL9602](INFO): Powering up NAL9602
2014-05-13T15:37:11.105Z,1399995431.105 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-05-13T15:37:11.105Z,1399995431.105 [DVL_micro] Data Fault, FailCount= 1
2014-05-13T15:37:11.105Z,1399995431.105 [DVL_micro](ERROR): Data Fault
2014-05-13T15:37:11.132Z,1399995431.132 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-05-13T15:37:11.502Z,1399995431.502 [DVL_micro](INFO): uninitialize:Powering down
2014-05-13T15:37:11.899Z,1399995431.899 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-05-13T15:37:11.899Z,1399995431.899 [DVL_micro] Hardware Fault, FailCount= 1
2014-05-13T15:37:11.899Z,1399995431.899 [DVL_micro](ERROR): Hardware Fault
2014-05-13T15:37:12.307Z,1399995432.307 [DVL_micro](INFO): Initializing
2014-05-13T15:37:12.334Z,1399995432.334 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-05-13T15:37:12.334Z,1399995432.334 [DVL_micro] No Fault, FailCount= 1
2014-05-13T15:37:15.610Z,1399995435.610 [NAL9602](INFO): NAL9602 initialized
2014-05-13T15:39:06.557Z,1399995546.557 [NAL9602](IMPORTANT): GPS fix at: 1399995544.00
2014-05-13T15:39:06.583Z,1399995546.583 [Default:GPS:Read_GPS] Stopped
2014-05-13T15:39:06.583Z,1399995546.583 [Default:GPS:D] Running Loop=1
2014-05-13T15:39:07.142Z,1399995547.142 [Default:GPS:D] Stopped
2014-05-13T15:39:07.142Z,1399995547.142 [Default:GPS](INFO): Completed Default:GPS
2014-05-13T15:39:07.142Z,1399995547.142 [Default:GPS] Stopped
2014-05-13T15:39:07.142Z,1399995547.142 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-05-13T15:39:07.142Z,1399995547.142 [Default:GPS:A.SetSpeed] Stopped
2014-05-13T15:39:07.143Z,1399995547.143 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-05-13T15:40:17.193Z,1399995617.193 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-05-13T15:40:17.193Z,1399995617.193 [DVL_micro] Data Fault, FailCount= 1
2014-05-13T15:40:17.193Z,1399995617.193 [DVL_micro](ERROR): Data Fault
2014-05-13T15:40:17.252Z,1399995617.252 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-05-13T15:40:17.626Z,1399995617.626 [DVL_micro](INFO): uninitialize:Powering down
2014-05-13T15:40:18.059Z,1399995618.059 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-05-13T15:40:18.059Z,1399995618.059 [DVL_micro] Hardware Fault, FailCount= 1
2014-05-13T15:40:18.059Z,1399995618.059 [DVL_micro](ERROR): Hardware Fault
2014-05-13T15:40:19.055Z,1399995619.055 [DVL_micro](INFO): Initializing
2014-05-13T15:40:19.186Z,1399995619.186 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-05-13T15:40:19.187Z,1399995619.187 [DVL_micro] No Fault, FailCount= 1
2014-05-13T15:40:36.472Z,1399995636.472 [NAL9602](INFO): SBD MO Status=2, MOMSN=28343, MT Status=2, MTMSN=0
2014-05-13T15:40:36.472Z,1399995636.472 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-05-13T15:41:10.680Z,1399995670.680 [NAL9602](INFO): SBD MO Status=2, MOMSN=28343, MT Status=2, MTMSN=0
2014-05-13T15:41:10.680Z,1399995670.680 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-05-13T15:42:05.331Z,1399995725.331 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=28343, MT Status=1, MTMSN=1842
2014-05-13T15:42:05.388Z,1399995725.388 [NAL9602](INFO): Sent 193 bytes from file Logs/20140513T003556/Courier0000.lzma
2014-05-13T15:42:05.389Z,1399995725.389 [NAL9602](INFO): Packets left to send: 0
2014-05-13T15:42:05.391Z,1399995725.391 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T003556/Courier0000.lzma.parts/0000.sbd
2014-05-13T15:42:05.391Z,1399995725.391 [NAL9602](INFO): Completed sending Logs/20140513T003556/Courier0000.lzma
2014-05-13T15:42:05.937Z,1399995725.937 [NAL9602](INFO): Received command:ibit
2014-05-13T15:42:05.980Z,1399995725.980 [CommandLine](IMPORTANT): got command ibit
2014-05-13T15:42:05.991Z,1399995725.991 [IBIT](IMPORTANT): Beginning Initiated BIT
2014-05-13T15:42:05.992Z,1399995725.992 [IBIT](IMPORTANT): Beginning control surface checks.
2014-05-13T15:42:05.993Z,1399995725.993 [CBIT](IMPORTANT): Beginning GF scan
2014-05-13T15:42:07.326Z,1399995727.326 [NAL9602](IMPORTANT): GPS fix at: 1399995726.00
2014-05-13T15:42:07.346Z,1399995727.346 [Radio_Freewave](INFO): Powering down
2014-05-13T15:42:08.254Z,1399995728.254 [Radio_Freewave](INFO): Powering up
2014-05-13T15:42:09.459Z,1399995729.459 [Radio_Freewave](IMPORTANT): Starting PPPD with command:/sbin/pppd nocrtscts /dev/ttyS1 noauth 115200 10.1.1.2:10.1.1.1 persist maxfail 0
2014-05-13T15:42:23.692Z,1399995743.692 [NAL9602](INFO): SBD MO Status=1, MOMSN=28344, MT Status=0, MTMSN=0
2014-05-13T15:42:23.740Z,1399995743.740 [NAL9602](INFO): Sent 45 bytes from file Logs/20140513T003556/Courier0004.lzma
2014-05-13T15:42:23.740Z,1399995743.740 [NAL9602](INFO): Packets left to send: 0
2014-05-13T15:42:23.742Z,1399995743.742 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T003556/Courier0004.lzma.parts/0000.sbd
2014-05-13T15:42:23.742Z,1399995743.742 [NAL9602](INFO): Completed sending Logs/20140513T003556/Courier0004.lzma
2014-05-13T15:42:32.396Z,1399995752.396 [CBIT](IMPORTANT): No ground fault detected
2014-05-13T15:42:34.906Z,1399995754.906 [NAL9602](INFO): SBD MO Status=1, MOMSN=28345, MT Status=0, MTMSN=0
2014-05-13T15:42:34.961Z,1399995754.961 [NAL9602](INFO): Sent 193 bytes from file Logs/20140513T150300/Courier0000.lzma
2014-05-13T15:42:34.962Z,1399995754.962 [NAL9602](INFO): Packets left to send: 0
2014-05-13T15:42:34.963Z,1399995754.963 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T150300/Courier0000.lzma.parts/0000.sbd
2014-05-13T15:42:34.964Z,1399995754.964 [NAL9602](INFO): Completed sending Logs/20140513T150300/Courier0000.lzma
2014-05-13T15:42:42.717Z,1399995762.717 [NAL9602](INFO): SBD MO Status=1, MOMSN=28346, MT Status=0, MTMSN=0
2014-05-13T15:42:42.774Z,1399995762.774 [NAL9602](INFO): Sent 45 bytes from file Logs/20140513T150300/Courier0004.lzma
2014-05-13T15:42:42.774Z,1399995762.774 [NAL9602](INFO): Packets left to send: 0
2014-05-13T15:42:42.776Z,1399995762.776 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T150300/Courier0004.lzma.parts/0000.sbd
2014-05-13T15:42:42.776Z,1399995762.776 [NAL9602](INFO): Completed sending Logs/20140513T150300/Courier0004.lzma
2014-05-13T15:42:53.680Z,1399995773.680 [IBIT](IMPORTANT): Communications Status:
Fix Status: 1
Iridium Signal Strength: 5
Latitude: 36.802841 Longitude: -121.787811
2014-05-13T15:42:54.124Z,1399995774.124 [IBIT](IMPORTANT): Battery Status:
Battery Charge (AH): 234.519989
Voltage: 16.098249
2014-05-13T15:42:54.124Z,1399995774.124 [IBIT](IMPORTANT): batteryCapacityThreshold: 5.000000 Ah
2014-05-13T15:42:54.124Z,1399995774.124 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.500000 V
2014-05-13T15:42:54.527Z,1399995774.527 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2014-05-13T15:42:54.527Z,1399995774.527 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2014-05-13T15:42:54.528Z,1399995774.528 [IBIT](IMPORTANT): Pressure:10.734123 PSI
2014-05-13T15:42:54.528Z,1399995774.528 [IBIT](IMPORTANT): Humidity:9.996469 %
2014-05-13T15:42:54.933Z,1399995774.933 [IBIT](IMPORTANT): surfaceThreshold: 0.500000 m
2014-05-13T15:42:54.933Z,1399995774.933 [IBIT](IMPORTANT): buoyancyNeutral: 300.000000 cc
2014-05-13T15:42:54.933Z,1399995774.933 [IBIT](IMPORTANT): massDefault: 0.000000 cm
2014-05-13T15:42:54.934Z,1399995774.934 [IBIT](IMPORTANT): stopDepth: 112.000000 m
2014-05-13T15:42:54.934Z,1399995774.934 [IBIT](IMPORTANT): abortDepth: 130.000000 m
2014-05-13T15:42:54.934Z,1399995774.934 [IBIT](IMPORTANT): IBIT PASSED
2014-05-13T15:42:58.357Z,1399995778.357 [NAL9602](INFO): SBD MO Status=2, MOMSN=28347, MT Status=2, MTMSN=0
2014-05-13T15:42:58.357Z,1399995778.357 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-05-13T15:43:23.059Z,1399995803.059 [NAL9602](INFO): SBD MO Status=1, MOMSN=28347, MT Status=0, MTMSN=0
2014-05-13T15:43:23.116Z,1399995803.116 [NAL9602](INFO): Sent 110 bytes from file Logs/20140513T150300/Courier0008.lzma
2014-05-13T15:43:23.116Z,1399995803.116 [NAL9602](INFO): Packets left to send: 0
2014-05-13T15:43:23.118Z,1399995803.118 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T150300/Courier0008.lzma.parts/0000.sbd
2014-05-13T15:43:23.118Z,1399995803.118 [NAL9602](INFO): Completed sending Logs/20140513T150300/Courier0008.lzma
2014-05-13T15:43:23.550Z,1399995803.550 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-05-13T15:43:23.550Z,1399995803.550 [DVL_micro] Data Fault, FailCount= 1
2014-05-13T15:43:23.550Z,1399995803.550 [DVL_micro](ERROR): Data Fault
2014-05-13T15:43:23.689Z,1399995803.689 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-05-13T15:43:24.051Z,1399995804.051 [DVL_micro](INFO): uninitialize:Powering down
2014-05-13T15:43:26.550Z,1399995806.550 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-05-13T15:43:26.551Z,1399995806.551 [DVL_micro] Hardware Fault, FailCount= 1
2014-05-13T15:43:26.551Z,1399995806.551 [DVL_micro](ERROR): Hardware Fault
2014-05-13T15:43:26.969Z,1399995806.969 [DVL_micro](INFO): Initializing
2014-05-13T15:43:27.030Z,1399995807.030 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-05-13T15:43:27.030Z,1399995807.030 [DVL_micro] No Fault, FailCount= 1
2014-05-13T15:43:35.503Z,1399995815.503 [NAL9602](INFO): SBD MO Status=1, MOMSN=28348, MT Status=0, MTMSN=0
2014-05-13T15:43:35.547Z,1399995815.547 [NAL9602](INFO): Sent 193 bytes from file Logs/20140513T152439/Courier0000.lzma
2014-05-13T15:43:35.548Z,1399995815.548 [NAL9602](INFO): Packets left to send: 0
2014-05-13T15:43:35.549Z,1399995815.549 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T152439/Courier0000.lzma.parts/0000.sbd
2014-05-13T15:43:35.549Z,1399995815.549 [NAL9602](INFO): Completed sending Logs/20140513T152439/Courier0000.lzma
2014-05-13T15:43:51.391Z,1399995831.391 [NAL9602](INFO): SBD MO Status=2, MOMSN=28349, MT Status=2, MTMSN=0
2014-05-13T15:43:51.391Z,1399995831.391 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-05-13T15:44:08.133Z,1399995848.133 [NAL9602](INFO): SBD MO Status=1, MOMSN=28349, MT Status=0, MTMSN=0
2014-05-13T15:44:08.186Z,1399995848.186 [NAL9602](INFO): Sent 45 bytes from file Logs/20140513T152439/Courier0004.lzma
2014-05-13T15:44:08.186Z,1399995848.186 [NAL9602](INFO): Packets left to send: 0
2014-05-13T15:44:08.188Z,1399995848.188 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T152439/Courier0004.lzma.parts/0000.sbd
2014-05-13T15:44:08.188Z,1399995848.188 [NAL9602](INFO): Completed sending Logs/20140513T152439/Courier0004.lzma
2014-05-13T15:44:17.911Z,1399995857.911 [NAL9602](INFO): SBD MO Status=1, MOMSN=28350, MT Status=0, MTMSN=0
2014-05-13T15:44:17.965Z,1399995857.965 [NAL9602](INFO): Sent 332 bytes from file Logs/20140513T003556/Express0001.lzma
2014-05-13T15:44:17.965Z,1399995857.965 [NAL9602](INFO): Packets left to send: 2
2014-05-13T15:44:17.967Z,1399995857.967 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T003556/Express0001.lzma.parts/0002.sbd
2014-05-13T15:44:32.880Z,1399995872.880 [NAL9602](INFO): SBD MO Status=2, MOMSN=28351, MT Status=2, MTMSN=0
2014-05-13T15:44:32.880Z,1399995872.880 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-05-13T15:44:46.257Z,1399995886.257 [NAL9602](INFO): SBD MO Status=1, MOMSN=28351, MT Status=0, MTMSN=0
2014-05-13T15:44:46.309Z,1399995886.309 [NAL9602](INFO): Sent 332 bytes from file Logs/20140513T003556/Express0001.lzma
2014-05-13T15:44:46.309Z,1399995886.309 [NAL9602](INFO): Packets left to send: 1
2014-05-13T15:44:46.310Z,1399995886.310 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T003556/Express0001.lzma.parts/0001.sbd
2014-05-13T15:45:33.435Z,1399995933.435 [NAL9602](INFO): SBD MO Status=2, MOMSN=28352, MT Status=2, MTMSN=0
2014-05-13T15:45:33.435Z,1399995933.435 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-05-13T15:45:49.407Z,1399995949.407 [NAL9602](INFO): SBD MO Status=1, MOMSN=28352, MT Status=0, MTMSN=0
2014-05-13T15:45:49.455Z,1399995949.455 [NAL9602](INFO): Sent 18 bytes from file Logs/20140513T003556/Express0001.lzma
2014-05-13T15:45:49.455Z,1399995949.455 [NAL9602](INFO): Packets left to send: 0
2014-05-13T15:45:49.456Z,1399995949.456 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T003556/Express0001.lzma.parts/0000.sbd
2014-05-13T15:45:49.456Z,1399995949.456 [NAL9602](INFO): Completed sending Logs/20140513T003556/Express0001.lzma
2014-05-13T15:46:11.169Z,1399995971.169 [NAL9602](INFO): SBD MO Status=1, MOMSN=28353, MT Status=0, MTMSN=0
2014-05-13T15:46:11.225Z,1399995971.225 [NAL9602](INFO): Sent 207 bytes from file Logs/20140513T003556/Express0005.lzma
2014-05-13T15:46:11.225Z,1399995971.225 [NAL9602](INFO): Packets left to send: 0
2014-05-13T15:46:11.228Z,1399995971.228 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T003556/Express0005.lzma.parts/0000.sbd
2014-05-13T15:46:11.228Z,1399995971.228 [NAL9602](INFO): Completed sending Logs/20140513T003556/Express0005.lzma
2014-05-13T15:46:28.343Z,1399995988.343 [NAL9602](INFO): SBD MO Status=2, MOMSN=28354, MT Status=2, MTMSN=0
2014-05-13T15:46:28.343Z,1399995988.343 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-05-13T15:46:30.840Z,1399995990.840 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-05-13T15:46:30.840Z,1399995990.840 [DVL_micro] Data Fault, FailCount= 1
2014-05-13T15:46:30.841Z,1399995990.841 [DVL_micro](ERROR): Data Fault
2014-05-13T15:46:30.871Z,1399995990.871 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-05-13T15:46:31.293Z,1399995991.293 [DVL_micro](INFO): uninitialize:Powering down
2014-05-13T15:46:31.710Z,1399995991.710 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-05-13T15:46:31.710Z,1399995991.710 [DVL_micro] Hardware Fault, FailCount= 1
2014-05-13T15:46:31.710Z,1399995991.710 [DVL_micro](ERROR): Hardware Fault
2014-05-13T15:46:32.146Z,1399995992.146 [DVL_micro](INFO): Initializing
2014-05-13T15:46:32.236Z,1399995992.236 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-05-13T15:46:32.236Z,1399995992.236 [DVL_micro] No Fault, FailCount= 1
2014-05-13T15:46:51.696Z,1399996011.696 [NAL9602](INFO): SBD MO Status=1, MOMSN=28354, MT Status=0, MTMSN=0
2014-05-13T15:46:51.743Z,1399996011.743 [NAL9602](INFO): Sent 332 bytes from file Logs/20140513T150300/Express0001.lzma
2014-05-13T15:46:51.744Z,1399996011.744 [NAL9602](INFO): Packets left to send: 2
2014-05-13T15:46:51.745Z,1399996011.745 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T150300/Express0001.lzma.parts/0002.sbd
2014-05-13T15:47:00.271Z,1399996020.271 [NAL9602](INFO): SBD MO Status=1, MOMSN=28355, MT Status=0, MTMSN=0
2014-05-13T15:47:00.329Z,1399996020.329 [NAL9602](INFO): Sent 332 bytes from file Logs/20140513T150300/Express0001.lzma
2014-05-13T15:47:00.329Z,1399996020.329 [NAL9602](INFO): Packets left to send: 1
2014-05-13T15:47:00.331Z,1399996020.331 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T150300/Express0001.lzma.parts/0001.sbd
2014-05-13T15:47:07.235Z,1399996027.235 [NAL9602](INFO): SBD MO Status=1, MOMSN=28356, MT Status=0, MTMSN=0
2014-05-13T15:47:07.296Z,1399996027.296 [NAL9602](INFO): Sent 23 bytes from file Logs/20140513T150300/Express0001.lzma
2014-05-13T15:47:07.296Z,1399996027.296 [NAL9602](INFO): Packets left to send: 0
2014-05-13T15:47:07.297Z,1399996027.297 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T150300/Express0001.lzma.parts/0000.sbd
2014-05-13T15:47:07.297Z,1399996027.297 [NAL9602](INFO): Completed sending Logs/20140513T150300/Express0001.lzma
2014-05-13T15:47:14.951Z,1399996034.951 [NAL9602](INFO): SBD MO Status=1, MOMSN=28357, MT Status=0, MTMSN=0
2014-05-13T15:47:15.004Z,1399996035.004 [NAL9602](INFO): Sent 194 bytes from file Logs/20140513T150300/Express0005.lzma
2014-05-13T15:47:15.004Z,1399996035.004 [NAL9602](INFO): Packets left to send: 0
2014-05-13T15:47:15.005Z,1399996035.005 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T150300/Express0005.lzma.parts/0000.sbd
2014-05-13T15:47:15.006Z,1399996035.006 [NAL9602](INFO): Completed sending Logs/20140513T150300/Express0005.lzma
2014-05-13T15:47:51.911Z,1399996071.911 [NAL9602](INFO): SBD MO Status=2, MOMSN=28358, MT Status=2, MTMSN=0
2014-05-13T15:47:51.912Z,1399996071.912 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-05-13T15:48:04.316Z,1399996084.316 [NAL9602](INFO): SBD MO Status=1, MOMSN=28358, MT Status=0, MTMSN=0
2014-05-13T15:48:04.376Z,1399996084.376 [NAL9602](INFO): Sent 332 bytes from file Logs/20140513T150300/Express0009.lzma
2014-05-13T15:48:04.376Z,1399996084.376 [NAL9602](INFO): Packets left to send: 1
2014-05-13T15:48:04.378Z,1399996084.378 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T150300/Express0009.lzma.parts/0001.sbd
2014-05-13T15:48:20.156Z,1399996100.156 [NAL9602](INFO): SBD MO Status=1, MOMSN=28359, MT Status=0, MTMSN=0
2014-05-13T15:48:20.237Z,1399996100.237 [NAL9602](INFO): Sent 263 bytes from file Logs/20140513T150300/Express0009.lzma
2014-05-13T15:48:20.237Z,1399996100.237 [NAL9602](INFO): Packets left to send: 0
2014-05-13T15:48:20.238Z,1399996100.238 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T150300/Express0009.lzma.parts/0000.sbd
2014-05-13T15:48:20.238Z,1399996100.238 [NAL9602](INFO): Completed sending Logs/20140513T150300/Express0009.lzma
2014-05-13T15:48:40.704Z,1399996120.704 [NAL9602](INFO): SBD MO Status=1, MOMSN=28360, MT Status=0, MTMSN=0
2014-05-13T15:48:40.753Z,1399996120.753 [NAL9602](INFO): Sent 332 bytes from file Logs/20140513T152439/Express0001.lzma
2014-05-13T15:48:40.753Z,1399996120.753 [NAL9602](INFO): Packets left to send: 2
2014-05-13T15:48:40.754Z,1399996120.754 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T152439/Express0001.lzma.parts/0002.sbd
2014-05-13T15:48:53.011Z,1399996133.011 [NAL9602](INFO): SBD MO Status=1, MOMSN=28361, MT Status=0, MTMSN=0
2014-05-13T15:48:53.060Z,1399996133.060 [NAL9602](INFO): Sent 332 bytes from file Logs/20140513T152439/Express0001.lzma
2014-05-13T15:48:53.060Z,1399996133.060 [NAL9602](INFO): Packets left to send: 1
2014-05-13T15:48:53.061Z,1399996133.061 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T152439/Express0001.lzma.parts/0001.sbd
2014-05-13T15:48:59.141Z,1399996139.141 [NAL9602](INFO): SBD MO Status=1, MOMSN=28362, MT Status=0, MTMSN=0
2014-05-13T15:48:59.191Z,1399996139.191 [NAL9602](INFO): Sent 16 bytes from file Logs/20140513T152439/Express0001.lzma
2014-05-13T15:48:59.192Z,1399996139.192 [NAL9602](INFO): Packets left to send: 0
2014-05-13T15:48:59.196Z,1399996139.196 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T152439/Express0001.lzma.parts/0000.sbd
2014-05-13T15:48:59.198Z,1399996139.198 [NAL9602](INFO): Completed sending Logs/20140513T152439/Express0001.lzma
2014-05-13T15:49:11.368Z,1399996151.368 [NAL9602](INFO): SBD MO Status=1, MOMSN=28363, MT Status=0, MTMSN=0
2014-05-13T15:49:11.416Z,1399996151.416 [NAL9602](INFO): Sent 332 bytes from file Logs/20140513T152439/Express0005.lzma
2014-05-13T15:49:11.416Z,1399996151.416 [NAL9602](INFO): Packets left to send: 1
2014-05-13T15:49:11.418Z,1399996151.418 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T152439/Express0005.lzma.parts/0001.sbd
2014-05-13T15:49:24.545Z,1399996164.545 [NAL9602](INFO): SBD MO Status=1, MOMSN=28364, MT Status=0, MTMSN=0
2014-05-13T15:49:24.598Z,1399996164.598 [NAL9602](INFO): Sent 281 bytes from file Logs/20140513T152439/Express0005.lzma
2014-05-13T15:49:24.598Z,1399996164.598 [NAL9602](INFO): Packets left to send: 0
2014-05-13T15:49:24.599Z,1399996164.599 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T152439/Express0005.lzma.parts/0000.sbd
2014-05-13T15:49:24.599Z,1399996164.599 [NAL9602](INFO): Completed sending Logs/20140513T152439/Express0005.lzma
2014-05-13T15:49:38.219Z,1399996178.219 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-05-13T15:49:38.219Z,1399996178.219 [DVL_micro] Data Fault, FailCount= 1
2014-05-13T15:49:38.219Z,1399996178.219 [DVL_micro](ERROR): Data Fault
2014-05-13T15:49:38.250Z,1399996178.250 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-05-13T15:49:38.628Z,1399996178.628 [DVL_micro](INFO): uninitialize:Powering down
2014-05-13T15:49:39.032Z,1399996179.032 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-05-13T15:49:39.032Z,1399996179.032 [DVL_micro] Hardware Fault, FailCount= 1
2014-05-13T15:49:39.032Z,1399996179.032 [DVL_micro](ERROR): Hardware Fault
2014-05-13T15:49:39.455Z,1399996179.455 [DVL_micro](INFO): Initializing
2014-05-13T15:49:39.510Z,1399996179.510 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-05-13T15:49:39.510Z,1399996179.510 [DVL_micro] No Fault, FailCount= 1
2014-05-13T15:49:41.189Z,1399996181.189 [NAL9602](INFO): SBD MO Status=2, MOMSN=28365, MT Status=2, MTMSN=0
2014-05-13T15:49:41.190Z,1399996181.190 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-05-13T15:49:53.166Z,1399996193.166 [NAL9602](INFO): SBD MO Status=0, MOMSN=28365, MT Status=0, MTMSN=0
2014-05-13T15:50:11.834Z,1399996211.834 [NAL9602](INFO): SBD MO Status=1, MOMSN=28366, MT Status=0, MTMSN=0
2014-05-13T15:50:11.886Z,1399996211.886 [NAL9602](INFO): Sent 281 bytes from file Logs/20140513T152439/Courier0008.lzma
2014-05-13T15:50:11.886Z,1399996211.886 [NAL9602](INFO): Packets left to send: 0
2014-05-13T15:50:11.888Z,1399996211.888 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T152439/Courier0008.lzma.parts/0000.sbd
2014-05-13T15:50:11.888Z,1399996211.888 [NAL9602](INFO): Completed sending Logs/20140513T152439/Courier0008.lzma
2014-05-13T15:50:24.189Z,1399996224.189 [NAL9602](INFO): SBD MO Status=1, MOMSN=28367, MT Status=0, MTMSN=0
2014-05-13T15:50:24.245Z,1399996224.245 [NAL9602](INFO): Sent 332 bytes from file Logs/20140513T152439/Express0009.lzma
2014-05-13T15:50:24.245Z,1399996224.245 [NAL9602](INFO): Packets left to send: 5
2014-05-13T15:50:24.247Z,1399996224.247 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T152439/Express0009.lzma.parts/0005.sbd
2014-05-13T15:50:36.720Z,1399996236.720 [NAL9602](INFO): SBD MO Status=1, MOMSN=28368, MT Status=0, MTMSN=0
2014-05-13T15:50:36.772Z,1399996236.772 [NAL9602](INFO): Sent 332 bytes from file Logs/20140513T152439/Express0009.lzma
2014-05-13T15:50:36.773Z,1399996236.773 [NAL9602](INFO): Packets left to send: 4
2014-05-13T15:50:36.774Z,1399996236.774 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T152439/Express0009.lzma.parts/0004.sbd
2014-05-13T15:50:45.178Z,1399996245.178 [NAL9602](INFO): SBD MO Status=1, MOMSN=28369, MT Status=0, MTMSN=0
2014-05-13T15:50:45.230Z,1399996245.230 [NAL9602](INFO): Sent 332 bytes from file Logs/20140513T152439/Express0009.lzma
2014-05-13T15:50:45.230Z,1399996245.230 [NAL9602](INFO): Packets left to send: 3
2014-05-13T15:50:45.231Z,1399996245.231 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T152439/Express0009.lzma.parts/0003.sbd
2014-05-13T15:51:03.578Z,1399996263.578 [NAL9602](INFO): SBD MO Status=2, MOMSN=28370, MT Status=0, MTMSN=0
2014-05-13T15:51:03.578Z,1399996263.578 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-05-13T15:51:30.063Z,1399996290.063 [NAL9602](INFO): SBD MO Status=2, MOMSN=28370, MT Status=2, MTMSN=0
2014-05-13T15:51:30.063Z,1399996290.063 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-05-13T15:51:50.510Z,1399996310.510 [NAL9602](INFO): SBD MO Status=1, MOMSN=28370, MT Status=0, MTMSN=0
2014-05-13T15:51:50.559Z,1399996310.559 [NAL9602](INFO): Sent 332 bytes from file Logs/20140513T152439/Express0009.lzma
2014-05-13T15:51:50.559Z,1399996310.559 [NAL9602](INFO): Packets left to send: 2
2014-05-13T15:51:50.560Z,1399996310.560 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T152439/Express0009.lzma.parts/0002.sbd
2014-05-13T15:52:19.597Z,1399996339.597 [NAL9602](INFO): SBD MO Status=2, MOMSN=28371, MT Status=2, MTMSN=0
2014-05-13T15:52:19.598Z,1399996339.598 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-05-13T15:52:40.444Z,1399996360.444 [NAL9602](INFO): SBD MO Status=1, MOMSN=28371, MT Status=0, MTMSN=0
2014-05-13T15:52:40.493Z,1399996360.493 [NAL9602](INFO): Sent 332 bytes from file Logs/20140513T152439/Express0009.lzma
2014-05-13T15:52:40.493Z,1399996360.493 [NAL9602](INFO): Packets left to send: 1
2014-05-13T15:52:40.494Z,1399996360.494 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T152439/Express0009.lzma.parts/0001.sbd
2014-05-13T15:52:43.907Z,1399996363.907 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-05-13T15:52:43.907Z,1399996363.907 [DVL_micro] Data Fault, FailCount= 1
2014-05-13T15:52:43.907Z,1399996363.907 [DVL_micro](ERROR): Data Fault
2014-05-13T15:52:43.961Z,1399996363.961 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-05-13T15:52:44.449Z,1399996364.449 [DVL_micro](INFO): uninitialize:Powering down
2014-05-13T15:52:44.872Z,1399996364.872 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-05-13T15:52:44.872Z,1399996364.872 [DVL_micro] Hardware Fault, FailCount= 1
2014-05-13T15:52:44.872Z,1399996364.872 [DVL_micro](ERROR): Hardware Fault
2014-05-13T15:52:45.299Z,1399996365.299 [DVL_micro](INFO): Initializing
2014-05-13T15:52:45.343Z,1399996365.343 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-05-13T15:52:45.344Z,1399996365.344 [DVL_micro] No Fault, FailCount= 1
2014-05-13T15:52:51.906Z,1399996371.906 [NAL9602](INFO): SBD MO Status=1, MOMSN=28372, MT Status=0, MTMSN=0
2014-05-13T15:52:51.950Z,1399996371.950 [NAL9602](INFO): Sent 10 bytes from file Logs/20140513T152439/Express0009.lzma
2014-05-13T15:52:51.950Z,1399996371.950 [NAL9602](INFO): Packets left to send: 0
2014-05-13T15:52:51.951Z,1399996371.951 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T152439/Express0009.lzma.parts/0000.sbd
2014-05-13T15:52:51.952Z,1399996371.952 [NAL9602](INFO): Completed sending Logs/20140513T152439/Express0009.lzma
2014-05-13T15:53:00.503Z,1399996380.503 [NAL9602](INFO): SBD MO Status=0, MOMSN=28373, MT Status=0, MTMSN=0
2014-05-13T15:53:00.665Z,1399996380.665 [Default:Iridium:Read_Iridium] Stopped
2014-05-13T15:53:00.665Z,1399996380.665 [Default:Iridium](INFO): Completed Default:Iridium
2014-05-13T15:53:00.666Z,1399996380.666 [Default:Iridium] Stopped
2014-05-13T15:53:00.666Z,1399996380.666 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-05-13T15:53:00.666Z,1399996380.666 [Default:Iridium:A.SetSpeed] Stopped
2014-05-13T15:53:00.666Z,1399996380.666 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-05-13T15:53:00.666Z,1399996380.666 [Default:WaitAtTheSurface] Running Loop=1
2014-05-13T15:53:00.666Z,1399996380.666 [Default:WaitAtTheSurface](INFO): Aggregate::initialize Default:WaitAtTheSurface
2014-05-13T15:53:00.666Z,1399996380.666 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed] Running Loop=1
2014-05-13T15:53:00.666Z,1399996380.666 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Initialize.
2014-05-13T15:53:00.666Z,1399996380.666 [Default:WaitAtTheSurface:B.GoToSurface] Running Loop=1
2014-05-13T15:53:00.666Z,1399996380.666 [Default:WaitAtTheSurface:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-13T15:53:01.118Z,1399996381.118 [Default:WaitAtTheSurface:B.GoToSurface] Running Loop=1
2014-05-13T15:53:01.123Z,1399996381.123 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed] Running Loop=1
2014-05-13T15:53:01.130Z,1399996381.130 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-05-13T15:53:01.130Z,1399996381.130 [Default:CallIridium:B] Stopped
2014-05-13T15:53:01.130Z,1399996381.130 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-05-13T15:53:01.130Z,1399996381.130 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-05-13T15:53:01.130Z,1399996381.130 [Default:CallIridium] Stopped
2014-05-13T15:53:01.130Z,1399996381.130 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-05-13T15:53:11.211Z,1399996391.211 [NAL9602](INFO): Powering down
2014-05-13T15:55:56.165Z,1399996556.165 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-05-13T15:55:56.165Z,1399996556.165 [DVL_micro] Data Fault, FailCount= 1
2014-05-13T15:55:56.165Z,1399996556.165 [DVL_micro](ERROR): Data Fault
2014-05-13T15:55:56.245Z,1399996556.245 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-05-13T15:56:01.212Z,1399996561.212 [DVL_micro](INFO): uninitialize:Powering down
2014-05-13T15:56:06.164Z,1399996566.164 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-05-13T15:56:06.164Z,1399996566.164 [DVL_micro] Hardware Fault, FailCount= 1
2014-05-13T15:56:06.164Z,1399996566.164 [DVL_micro](ERROR): Hardware Fault
2014-05-13T15:56:11.239Z,1399996571.239 [DVL_micro](INFO): Initializing
2014-05-13T15:56:11.293Z,1399996571.293 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-05-13T15:56:11.293Z,1399996571.293 [DVL_micro] No Fault, FailCount= 1
2014-05-13T15:58:01.266Z,1399996681.266 [Default:CallIridium] Running Loop=1
2014-05-13T15:58:01.266Z,1399996681.266 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-05-13T15:58:01.266Z,1399996681.266 [Default:CallIridium:A] Running Loop=1
2014-05-13T15:58:01.267Z,1399996681.267 [Default:CallIridium:A] Stopped
2014-05-13T15:58:01.267Z,1399996681.267 [Default:CallIridium:B] Running Loop=1
2014-05-13T15:58:01.267Z,1399996681.267 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-05-13T15:58:06.332Z,1399996686.332 [Default:Iridium] Running Loop=1
2014-05-13T15:58:06.332Z,1399996686.332 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-05-13T15:58:06.332Z,1399996686.332 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-05-13T15:58:06.332Z,1399996686.332 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-05-13T15:58:06.332Z,1399996686.332 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-05-13T15:58:06.332Z,1399996686.332 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-13T15:58:06.333Z,1399996686.333 [Default:Iridium:B.GoToSurface] Stopped
2014-05-13T15:58:06.333Z,1399996686.333 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-13T15:58:06.333Z,1399996686.333 [Default:Iridium:Read_Iridium] Running Loop=1
2014-05-13T15:58:06.334Z,1399996686.334 [Default:GPS] Running Loop=1
2014-05-13T15:58:06.334Z,1399996686.334 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-05-13T15:58:06.334Z,1399996686.334 [Default:GPS:A.SetSpeed] Running Loop=1
2014-05-13T15:58:06.334Z,1399996686.334 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-05-13T15:58:06.334Z,1399996686.334 [Default:GPS:B.GoToSurface] Running Loop=1
2014-05-13T15:58:06.334Z,1399996686.334 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-13T15:58:06.335Z,1399996686.335 [Default:GPS:B.GoToSurface] Stopped
2014-05-13T15:58:06.335Z,1399996686.335 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-13T15:58:06.335Z,1399996686.335 [Default:GPS:Read_GPS] Running Loop=1
2014-05-13T15:58:07.375Z,1399996687.375 [NAL9602](INFO): Powering up
2014-05-13T15:58:17.979Z,1399996697.979 [NAL9602](ERROR): NAL9602 initialize error - Can't enter command mode:
+CIEV:0,5
2014-05-13T15:58:17.980Z,1399996697.980 [NAL9602] Communications Fault, FailCount= 1
2014-05-13T15:58:17.980Z,1399996697.980 [NAL9602](ERROR): Communications Fault
2014-05-13T15:58:18.045Z,1399996698.045 [CBIT](ERROR): Communications Fault in component: NAL9602
2014-05-13T15:58:18.438Z,1399996698.438 [NAL9602](INFO): Powering down
2014-05-13T15:58:19.447Z,1399996699.447 [CBIT](INFO): Clearing failed state for component NAL9602
2014-05-13T15:58:19.447Z,1399996699.447 [NAL9602] No Fault, FailCount= 1
2014-05-13T15:58:23.745Z,1399996703.745 [NAL9602](INFO): Powering up NAL9602
2014-05-13T15:58:34.309Z,1399996714.309 [NAL9602](INFO): NAL9602 initialized
2014-05-13T15:58:55.176Z,1399996735.176 [NAL9602](INFO): SBD MO Status=1, MOMSN=28374, MT Status=0, MTMSN=0
2014-05-13T15:58:55.225Z,1399996735.225 [NAL9602](INFO): Sent 45 bytes from file Logs/20140513T152439/Courier0012.lzma
2014-05-13T15:58:55.225Z,1399996735.225 [NAL9602](INFO): Packets left to send: 0
2014-05-13T15:58:55.227Z,1399996735.227 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T152439/Courier0012.lzma.parts/0000.sbd
2014-05-13T15:58:55.227Z,1399996735.227 [NAL9602](INFO): Completed sending Logs/20140513T152439/Courier0012.lzma
2014-05-13T15:59:10.761Z,1399996750.761 [NAL9602](INFO): SBD MO Status=2, MOMSN=28375, MT Status=2, MTMSN=0
2014-05-13T15:59:10.761Z,1399996750.761 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-05-13T15:59:12.176Z,1399996752.176 [NAL9602](IMPORTANT): GPS fix at: 1399996750.00
2014-05-13T15:59:12.230Z,1399996752.230 [Default:GPS:Read_GPS] Stopped
2014-05-13T15:59:12.230Z,1399996752.230 [Default:GPS:D] Running Loop=1
2014-05-13T15:59:12.669Z,1399996752.669 [Default:GPS:D] Stopped
2014-05-13T15:59:12.669Z,1399996752.669 [Default:GPS](INFO): Completed Default:GPS
2014-05-13T15:59:12.669Z,1399996752.669 [Default:GPS] Stopped
2014-05-13T15:59:12.670Z,1399996752.670 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-05-13T15:59:12.670Z,1399996752.670 [Default:GPS:A.SetSpeed] Stopped
2014-05-13T15:59:12.670Z,1399996752.670 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-05-13T16:01:09.861Z,1399996869.861 [NAL9602](INFO): SBD MO Status=1, MOMSN=28375, MT Status=0, MTMSN=0
2014-05-13T16:01:09.914Z,1399996869.914 [NAL9602](INFO): Sent 178 bytes from file Logs/20140513T152439/Express0013.lzma
2014-05-13T16:01:09.914Z,1399996869.914 [NAL9602](INFO): Packets left to send: 0
2014-05-13T16:01:09.916Z,1399996869.916 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T152439/Express0013.lzma.parts/0000.sbd
2014-05-13T16:01:09.916Z,1399996869.916 [NAL9602](INFO): Completed sending Logs/20140513T152439/Express0013.lzma
2014-05-13T16:01:26.115Z,1399996886.115 [NAL9602](INFO): SBD MO Status=0, MOMSN=28376, MT Status=0, MTMSN=0
2014-05-13T16:01:26.242Z,1399996886.242 [Default:Iridium:Read_Iridium] Stopped
2014-05-13T16:01:26.243Z,1399996886.243 [Default:Iridium](INFO): Completed Default:Iridium
2014-05-13T16:01:26.247Z,1399996886.247 [Default:Iridium] Stopped
2014-05-13T16:01:26.247Z,1399996886.247 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-05-13T16:01:26.247Z,1399996886.247 [Default:Iridium:A.SetSpeed] Stopped
2014-05-13T16:01:26.247Z,1399996886.247 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-05-13T16:01:26.753Z,1399996886.753 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-05-13T16:01:26.753Z,1399996886.753 [Default:CallIridium:B] Stopped
2014-05-13T16:01:26.753Z,1399996886.753 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-05-13T16:01:26.753Z,1399996886.753 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-05-13T16:01:26.753Z,1399996886.753 [Default:CallIridium] Stopped
2014-05-13T16:01:26.753Z,1399996886.753 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-05-13T16:01:36.843Z,1399996896.843 [NAL9602](INFO): Powering down
2014-05-13T16:06:26.901Z,1399997186.901 [Default:CallIridium] Running Loop=1
2014-05-13T16:06:26.901Z,1399997186.901 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-05-13T16:06:26.901Z,1399997186.901 [Default:CallIridium:A] Running Loop=1
2014-05-13T16:06:26.922Z,1399997186.922 [Default:CallIridium:A] Stopped
2014-05-13T16:06:26.922Z,1399997186.922 [Default:CallIridium:B] Running Loop=1
2014-05-13T16:06:26.922Z,1399997186.922 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-05-13T16:06:31.883Z,1399997191.883 [Default:Iridium] Running Loop=1
2014-05-13T16:06:31.884Z,1399997191.884 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-05-13T16:06:31.884Z,1399997191.884 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-05-13T16:06:31.884Z,1399997191.884 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-05-13T16:06:31.884Z,1399997191.884 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-05-13T16:06:31.884Z,1399997191.884 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-13T16:06:31.885Z,1399997191.885 [Default:Iridium:B.GoToSurface] Stopped
2014-05-13T16:06:31.885Z,1399997191.885 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-13T16:06:31.885Z,1399997191.885 [Default:Iridium:Read_Iridium] Running Loop=1
2014-05-13T16:06:31.885Z,1399997191.885 [Default:GPS] Running Loop=1
2014-05-13T16:06:31.886Z,1399997191.886 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-05-13T16:06:31.886Z,1399997191.886 [Default:GPS:A.SetSpeed] Running Loop=1
2014-05-13T16:06:31.886Z,1399997191.886 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-05-13T16:06:31.886Z,1399997191.886 [Default:GPS:B.GoToSurface] Running Loop=1
2014-05-13T16:06:31.886Z,1399997191.886 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-13T16:06:31.887Z,1399997191.887 [Default:GPS:B.GoToSurface] Stopped
2014-05-13T16:06:31.887Z,1399997191.887 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-13T16:06:31.887Z,1399997191.887 [Default:GPS:Read_GPS] Running Loop=1
2014-05-13T16:06:32.957Z,1399997192.957 [NAL9602](INFO): Powering up
2014-05-13T16:06:43.521Z,1399997203.521 [NAL9602](INFO): NAL9602 initialized
2014-05-13T16:07:01.254Z,1399997221.254 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=28377, MT Status=1, MTMSN=1843
2014-05-13T16:07:01.316Z,1399997221.316 [NAL9602](INFO): Sent 76 bytes from file Logs/20140513T152439/Courier0016.lzma
2014-05-13T16:07:01.316Z,1399997221.316 [NAL9602](INFO): Packets left to send: 0
2014-05-13T16:07:01.317Z,1399997221.317 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T152439/Courier0016.lzma.parts/0000.sbd
2014-05-13T16:07:01.318Z,1399997221.318 [NAL9602](INFO): Completed sending Logs/20140513T152439/Courier0016.lzma
2014-05-13T16:07:01.912Z,1399997221.912 [NAL9602](INFO): Received command:restart app
2014-05-13T16:07:01.960Z,1399997221.960 [CommandLine](IMPORTANT): got command restart application
2014-05-13T16:07:02.966Z,1399997222.966 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-13T16:07:02.966Z,1399997222.966 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-05-13T16:07:03.065Z,1399997223.065 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2014-05-13T16:07:03.065Z,1399997223.065 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-05-13T16:07:03.066Z,1399997223.066 [CommandLine](INFO): Join timeout helper Thread ID is 1092
2014-05-13T16:07:03.067Z,1399997223.067 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2014-05-13T16:07:03.067Z,1399997223.067 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-05-13T16:07:03.067Z,1399997223.067 [NavChartDb](INFO): Join timeout helper Thread ID is 1093
2014-05-13T16:07:03.263Z,1399997223.263 [NAL9602](IMPORTANT): GPS fix at: 1399997221.00
2014-05-13T16:07:03.306Z,1399997223.306 [Default:GPS:Read_GPS] Stopped
2014-05-13T16:07:03.306Z,1399997223.306 [Default:GPS:D] Running Loop=1
2014-05-13T16:07:03.370Z,1399997223.370 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-13T16:07:03.370Z,1399997223.370 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-05-13T16:07:03.390Z,1399997223.390 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2014-05-13T16:07:03.390Z,1399997223.390 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-05-13T16:07:03.390Z,1399997223.390 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 1094
2014-05-13T16:07:03.590Z,1399997223.590 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-13T16:07:03.591Z,1399997223.591 [WetLabsBB2FL](INFO): Powering down
2014-05-13T16:07:03.591Z,1399997223.591 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-05-13T16:07:03.610Z,1399997223.610 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2014-05-13T16:07:03.610Z,1399997223.610 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-05-13T16:07:03.611Z,1399997223.611 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 1095
2014-05-13T16:07:03.755Z,1399997223.755 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-13T16:07:03.755Z,1399997223.755 [CTD_NeilBrown](INFO): Powering down
2014-05-13T16:07:03.756Z,1399997223.756 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-05-13T16:07:03.756Z,1399997223.756 [ComponentRegistry](INFO): Shutting down AsyncPiEstimator ThreadHandler
2014-05-13T16:07:03.756Z,1399997223.756 [AsyncPiEstimator ThreadHandler](INFO): Thread cancelled.
2014-05-13T16:07:03.757Z,1399997223.757 [AsyncPiEstimator](INFO): Join timeout helper Thread ID is 1096
2014-05-13T16:07:03.794Z,1399997223.794 [Default:GPS:D] Stopped
2014-05-13T16:07:03.794Z,1399997223.794 [Default:GPS](INFO): Completed Default:GPS
2014-05-13T16:07:03.798Z,1399997223.798 [Default:GPS] Stopped
2014-05-13T16:07:03.799Z,1399997223.799 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-05-13T16:07:03.799Z,1399997223.799 [Default:GPS:A.SetSpeed] Stopped
2014-05-13T16:07:03.799Z,1399997223.799 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-05-13T16:07:03.935Z,1399997223.935 [AsyncPiEstimator ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-13T16:07:03.935Z,1399997223.935 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2014-05-13T16:07:03.935Z,1399997223.935 [AsyncPiEstimator ThreadHandler](INFO): Thread cancelled.
2014-05-13T16:07:03.941Z,1399997223.941 [ComponentRegistry](INFO): Shutting down Radio_Freewave ThreadHandler
2014-05-13T16:07:03.941Z,1399997223.941 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-05-13T16:07:03.942Z,1399997223.942 [Radio_Freewave](INFO): Join timeout helper Thread ID is 1097
2014-05-13T16:07:04.319Z,1399997224.319 [Radio_Freewave ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-13T16:07:04.430Z,1399997224.430 [Radio_Freewave](INFO): Powering down
2014-05-13T16:07:04.832Z,1399997224.832 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-05-13T16:07:04.841Z,1399997224.841 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2014-05-13T16:07:04.841Z,1399997224.841 [logger ThreadHandler](INFO): Thread cancelled.
2014-05-13T16:07:04.842Z,1399997224.842 [logger](INFO): Join timeout helper Thread ID is 1100
2014-05-13T16:07:04.880Z,1399997224.880 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-13T16:07:04.880Z,1399997224.880 [logger ThreadHandler](INFO): Thread cancelled.
2014-05-13T16:07:04.902Z,1399997224.902 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2014-05-13T16:07:04.902Z,1399997224.902 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-05-13T16:07:04.903Z,1399997224.903 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2014-05-13T16:07:04.903Z,1399997224.903 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-05-13T16:07:04.904Z,1399997224.904 [controlThread](INFO): Join timeout helper Thread ID is 1101
2014-05-13T16:07:05.088Z,1399997225.088 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-13T16:07:05.089Z,1399997225.089 [controlThread](DEBUG): Uninitializing ControlThread
2014-05-13T16:07:05.089Z,1399997225.089 [AHRS_sp3003D](INFO): Powering down
2014-05-13T16:07:05.090Z,1399997225.090 [DVL_micro](INFO): uninitialize:Powering down
2014-05-13T16:07:05.091Z,1399997225.091 [NAL9602](INFO): Powering down
2014-05-13T16:07:05.094Z,1399997225.094 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-05-13T16:07:05.096Z,1399997225.096 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2014-05-13T16:07:05.096Z,1399997225.096 [Default] Stopped
2014-05-13T16:07:05.096Z,1399997225.096 [Default](INFO): Aggregate::uninitialize Default
2014-05-13T16:07:05.097Z,1399997225.097 [Default:Iridium] Stopped
2014-05-13T16:07:05.097Z,1399997225.097 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-05-13T16:07:05.097Z,1399997225.097 [Default:Iridium:A.SetSpeed] Stopped
2014-05-13T16:07:05.097Z,1399997225.097 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-05-13T16:07:05.097Z,1399997225.097 [Default:Iridium:Read_Iridium] Stopped
2014-05-13T16:07:05.097Z,1399997225.097 [Default:CallIridium] Stopped
2014-05-13T16:07:05.097Z,1399997225.097 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-05-13T16:07:05.097Z,1399997225.097 [Default:CallIridium:B] Stopped
2014-05-13T16:07:05.097Z,1399997225.097 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-05-13T16:07:05.097Z,1399997225.097 [Default:WaitAtTheSurface] Stopped
2014-05-13T16:07:05.098Z,1399997225.098 [Default:WaitAtTheSurface](INFO): Aggregate::uninitialize Default:WaitAtTheSurface
2014-05-13T16:07:05.098Z,1399997225.098 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed] Stopped
2014-05-13T16:07:05.098Z,1399997225.098 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Uninitialize.
2014-05-13T16:07:05.098Z,1399997225.098 [Default:WaitAtTheSurface:B.GoToSurface] Stopped
2014-05-13T16:07:05.098Z,1399997225.098 [Default:WaitAtTheSurface:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-13T16:07:05.103Z,1399997225.103 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2014-05-13T16:07:05.103Z,1399997225.103 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2014-05-13T16:07:05.104Z,1399997225.104 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2014-05-13T16:07:05.104Z,1399997225.104 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2014-05-13T16:07:05.104Z,1399997225.104 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2014-05-13T16:07:05.105Z,1399997225.105 [BuoyancyServo](INFO): Powering down
2014-05-13T16:07:05.117Z,1399997225.117 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2014-05-13T16:07:05.117Z,1399997225.117 [ElevatorServo](INFO): Powering down
2014-05-13T16:07:05.118Z,1399997225.118 [MassServo](DEBUG): Uninitialize Mass Servo.
2014-05-13T16:07:05.118Z,1399997225.118 [MassServo](INFO): Powering down
2014-05-13T16:07:05.118Z,1399997225.118 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2014-05-13T16:07:05.119Z,1399997225.119 [RudderServo](INFO): Powering down
2014-05-13T16:07:05.120Z,1399997225.120 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2014-05-13T16:07:05.120Z,1399997225.120 [ThrusterServo](INFO): Powering down
2014-05-13T16:07:05.121Z,1399997225.121 [SBIT](DEBUG): Uninitialize SBIT Component.
2014-05-13T16:07:05.121Z,1399997225.121 [IBIT](DEBUG): Uninitialize IBIT Component.
2014-05-13T16:07:05.121Z,1399997225.121 [CBIT](DEBUG): Uninitialize CBIT Component.
2014-05-13T16:07:05.166Z,1399997225.166 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-05-13T16:07:05.168Z,1399997225.168 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-05-13T16:07:05.221Z,1399997225.221 [AsyncPiEstimator ThreadHandler](INFO): Thread cancelled.
2014-05-13T16:07:05.246Z,1399997225.246 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-05-13T16:07:05.250Z,1399997225.250 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-05-13T16:07:05.280Z,1399997225.280 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-05-13T16:07:05.334Z,1399997225.334 [logger ThreadHandler](INFO): Thread cancelled.