2014-06-17T16:01:42.680Z,1403020902.680 [Supervisor](DEBUG): Initializing supervisor.
2014-06-17T16:01:42.683Z,1403020902.683 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2014-06-17T16:01:42.683Z,1403020902.683 [SyncHandler](INFO): Protected caller Thread ID is 5484
2014-06-17T16:01:42.684Z,1403020902.684 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2014-06-17T16:01:42.685Z,1403020902.685 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2014-06-17T16:01:42.685Z,1403020902.685 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 5485
2014-06-17T16:01:42.688Z,1403020902.688 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2014-06-17T16:01:42.699Z,1403020902.699 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2014-06-17T16:01:42.700Z,1403020902.700 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2014-06-17T16:01:42.701Z,1403020902.701 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 5486
2014-06-17T16:01:42.701Z,1403020902.701 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2014-06-17T16:01:42.703Z,1403020902.703 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2014-06-17T16:01:42.703Z,1403020902.703 [logger ThreadHandler](INFO): Protected caller Thread ID is 5487
2014-06-17T16:01:42.705Z,1403020902.705 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2014-06-17T16:01:42.706Z,1403020902.706 [Supervisor](INFO): Looking for Config files in directory: Config/
2014-06-17T16:01:42.707Z,1403020902.707 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2014-06-17T16:01:43.196Z,1403020903.196 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2014-06-17T16:01:43.197Z,1403020903.197 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2014-06-17T16:01:43.352Z,1403020903.352 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2014-06-17T16:01:43.353Z,1403020903.353 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2014-06-17T16:01:43.461Z,1403020903.461 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2014-06-17T16:01:43.462Z,1403020903.462 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2014-06-17T16:01:43.585Z,1403020903.585 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2014-06-17T16:01:43.585Z,1403020903.585 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2014-06-17T16:01:43.672Z,1403020903.672 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2014-06-17T16:01:43.807Z,1403020903.807 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2014-06-17T16:01:43.807Z,1403020903.807 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2014-06-17T16:01:43.894Z,1403020903.894 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2014-06-17T16:01:43.894Z,1403020903.894 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2014-06-17T16:01:44.073Z,1403020904.073 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2014-06-17T16:01:44.074Z,1403020904.074 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2014-06-17T16:01:44.357Z,1403020904.357 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2014-06-17T16:01:44.358Z,1403020904.358 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2014-06-17T16:01:44.662Z,1403020904.662 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2014-06-17T16:01:44.662Z,1403020904.662 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2014-06-17T16:01:45.165Z,1403020905.165 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2014-06-17T16:01:45.166Z,1403020905.166 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2014-06-17T16:01:45.357Z,1403020905.357 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2014-06-17T16:01:45.357Z,1403020905.357 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2014-06-17T16:01:45.461Z,1403020905.461 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2014-06-17T16:01:45.461Z,1403020905.461 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2014-06-17T16:01:45.848Z,1403020905.848 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2014-06-17T16:01:45.849Z,1403020905.849 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2014-06-17T16:01:45.966Z,1403020905.966 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2014-06-17T16:01:45.968Z,1403020905.968 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2014-06-17T16:01:45.969Z,1403020905.969 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2014-06-17T16:01:46.078Z,1403020906.078 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2014-06-17T16:01:46.205Z,1403020906.205 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Estimation.cfg
2014-06-17T16:01:46.354Z,1403020906.354 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2014-06-17T16:01:46.452Z,1403020906.452 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2014-06-17T16:01:46.579Z,1403020906.579 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2014-06-17T16:01:46.723Z,1403020906.723 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2014-06-17T16:01:46.824Z,1403020906.824 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2014-06-17T16:01:46.910Z,1403020906.910 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2014-06-17T16:01:47.004Z,1403020907.004 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2014-06-17T16:01:47.102Z,1403020907.102 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2014-06-17T16:01:47.212Z,1403020907.212 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2014-06-17T16:01:47.300Z,1403020907.300 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2014-06-17T16:01:47.308Z,1403020907.308 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2014-06-17T16:01:47.370Z,1403020907.370 [VerticalControl](DEBUG): Construct VerticalControl.
2014-06-17T16:01:47.485Z,1403020907.485 [VerticalControl] Loaded
2014-06-17T16:01:47.486Z,1403020907.486 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2014-06-17T16:01:47.487Z,1403020907.487 [HorizontalControl](DEBUG): Construct HorizontalControl.
2014-06-17T16:01:47.555Z,1403020907.555 [HorizontalControl] Loaded
2014-06-17T16:01:47.556Z,1403020907.556 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2014-06-17T16:01:47.556Z,1403020907.556 [SpeedControl](DEBUG): Construct SpeedControl.
2014-06-17T16:01:47.562Z,1403020907.562 [SpeedControl] Loaded
2014-06-17T16:01:47.562Z,1403020907.562 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2014-06-17T16:01:47.563Z,1403020907.563 [LoopControl](DEBUG): Construct LoopControl.
2014-06-17T16:01:47.563Z,1403020907.563 [LoopControl] Loaded
2014-06-17T16:01:47.564Z,1403020907.564 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2014-06-17T16:01:47.564Z,1403020907.564 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2014-06-17T16:01:47.565Z,1403020907.565 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2014-06-17T16:01:47.677Z,1403020907.677 [SBIT](DEBUG): Construct Startup Built In Test.
2014-06-17T16:01:47.688Z,1403020907.688 [SBIT] Loaded
2014-06-17T16:01:47.688Z,1403020907.688 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2014-06-17T16:01:47.689Z,1403020907.689 [IBIT](DEBUG): Construct Initiated Built In Test.
2014-06-17T16:01:47.717Z,1403020907.717 [IBIT] Loaded
2014-06-17T16:01:47.717Z,1403020907.717 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2014-06-17T16:01:47.719Z,1403020907.719 [CBIT](DEBUG): Construct CBIT Built In Test.
2014-06-17T16:01:47.835Z,1403020907.835 [CBIT] Loaded
2014-06-17T16:01:47.836Z,1403020907.836 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2014-06-17T16:01:47.836Z,1403020907.836 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2014-06-17T16:01:47.837Z,1403020907.837 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2014-06-17T16:01:47.863Z,1403020907.863 [DepthRateCalculator] Loaded
2014-06-17T16:01:47.863Z,1403020907.863 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2014-06-17T16:01:47.868Z,1403020907.868 [PitchRateCalculator] Loaded
2014-06-17T16:01:47.869Z,1403020907.869 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2014-06-17T16:01:47.880Z,1403020907.880 [SpeedCalculator] Loaded
2014-06-17T16:01:47.880Z,1403020907.880 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2014-06-17T16:01:47.895Z,1403020907.895 [TempGradientCalculator] Loaded
2014-06-17T16:01:47.896Z,1403020907.896 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2014-06-17T16:01:47.901Z,1403020907.901 [YawRateCalculator] Loaded
2014-06-17T16:01:47.901Z,1403020907.901 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2014-06-17T16:01:47.901Z,1403020907.901 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2014-06-17T16:01:47.902Z,1403020907.902 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2014-06-17T16:01:52.722Z,1403020912.722 [HFRadarModelCalc] Loaded
2014-06-17T16:01:52.722Z,1403020912.722 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2014-06-17T16:01:56.478Z,1403020916.478 [HFRadarCompactModelForecaster] Loaded
2014-06-17T16:01:56.478Z,1403020916.478 [ComponentRegistry](DEBUG): SyncComponent "HFRadarCompactModelForecaster" handled in the control thread.
2014-06-17T16:01:57.527Z,1403020917.527 [HFRCMSpaceInterpolator] Loaded
2014-06-17T16:01:57.528Z,1403020917.528 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSpaceInterpolator" handled in the control thread.
2014-06-17T16:01:57.530Z,1403020917.530 [HFRCMTimeInterpolator] Loaded
2014-06-17T16:01:57.530Z,1403020917.530 [ComponentRegistry](DEBUG): SyncComponent "HFRCMTimeInterpolator" handled in the control thread.
2014-06-17T16:01:58.535Z,1403020918.535 [HFRCMReconstructedInterpolator] Loaded
2014-06-17T16:01:58.536Z,1403020918.536 [ComponentRegistry](DEBUG): SyncComponent "HFRCMReconstructedInterpolator" handled in the control thread.
2014-06-17T16:01:58.547Z,1403020918.547 [HFRCMSurfaceCurrentAtVehicleLocation] Loaded
2014-06-17T16:01:58.548Z,1403020918.548 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSurfaceCurrentAtVehicleLocation" handled in the control thread.
2014-06-17T16:01:58.574Z,1403020918.574 [HFRCMVirtualSurfaceDrifter] Loaded
2014-06-17T16:01:58.574Z,1403020918.574 [ComponentRegistry](DEBUG): SyncComponent "HFRCMVirtualSurfaceDrifter" handled in the control thread.
2014-06-17T16:01:58.575Z,1403020918.575 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2014-06-17T16:01:58.575Z,1403020918.575 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2014-06-17T16:01:58.834Z,1403020918.834 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2014-06-17T16:01:58.834Z,1403020918.834 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2014-06-17T16:01:58.925Z,1403020918.925 [DeadReckonUsingMultipleVelocitySources] Loaded
2014-06-17T16:01:58.926Z,1403020918.926 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2014-06-17T16:01:58.970Z,1403020918.970 [DeadReckonWithRespectToWater] Loaded
2014-06-17T16:01:58.970Z,1403020918.970 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToWater" handled in the control thread.
2014-06-17T16:01:59.015Z,1403020919.015 [DeadReckonWithRespectToSeafloor] Loaded
2014-06-17T16:01:59.016Z,1403020919.016 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToSeafloor" handled in the control thread.
2014-06-17T16:01:59.074Z,1403020919.074 [DeadReckonUsingDVLWaterTrack] Loaded
2014-06-17T16:01:59.074Z,1403020919.074 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingDVLWaterTrack" handled in the control thread.
2014-06-17T16:01:59.120Z,1403020919.120 [DeadReckonUsingCompactModelForecast] Loaded
2014-06-17T16:01:59.121Z,1403020919.121 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingCompactModelForecast" handled in the control thread.
2014-06-17T16:01:59.137Z,1403020919.137 [NavChart] Loaded
2014-06-17T16:01:59.138Z,1403020919.138 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2014-06-17T16:01:59.142Z,1403020919.142 [UniversalFixResidualReporter] Loaded
2014-06-17T16:01:59.142Z,1403020919.142 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2014-06-17T16:01:59.142Z,1403020919.142 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2014-06-17T16:01:59.143Z,1403020919.143 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2014-06-17T16:01:59.155Z,1403020919.155 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2014-06-17T16:01:59.156Z,1403020919.156 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2014-06-17T16:01:59.349Z,1403020919.349 [CTD_NeilBrown] Loaded
2014-06-17T16:01:59.349Z,1403020919.349 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2014-06-17T16:01:59.351Z,1403020919.351 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 407B94E0
2014-06-17T16:01:59.351Z,1403020919.351 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 5569
2014-06-17T16:01:59.366Z,1403020919.366 [PAR_Licor] Loaded
2014-06-17T16:01:59.366Z,1403020919.366 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2014-06-17T16:01:59.401Z,1403020919.401 [WetLabsBB2FL] Loaded
2014-06-17T16:01:59.401Z,1403020919.401 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2014-06-17T16:01:59.402Z,1403020919.402 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407E94E0
2014-06-17T16:01:59.403Z,1403020919.403 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 5570
2014-06-17T16:01:59.403Z,1403020919.403 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2014-06-17T16:01:59.404Z,1403020919.404 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2014-06-17T16:01:59.765Z,1403020919.765 [AHRS_sp3003D] Loaded
2014-06-17T16:01:59.766Z,1403020919.766 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2014-06-17T16:02:00.018Z,1403020920.018 [Batt_Ocean_Server] Loaded
2014-06-17T16:02:00.019Z,1403020920.019 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2014-06-17T16:02:00.090Z,1403020920.090 [DataOverHttps] Loaded
2014-06-17T16:02:00.090Z,1403020920.090 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2014-06-17T16:02:00.104Z,1403020920.104 [Depth_Keller] Loaded
2014-06-17T16:02:00.104Z,1403020920.104 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2014-06-17T16:02:00.109Z,1403020920.109 [DropWeight] Loaded
2014-06-17T16:02:00.109Z,1403020920.109 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2014-06-17T16:02:00.238Z,1403020920.238 [DVL_micro] Loaded
2014-06-17T16:02:00.238Z,1403020920.238 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2014-06-17T16:02:00.330Z,1403020920.330 [NAL9602] Loaded
2014-06-17T16:02:00.330Z,1403020920.330 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2014-06-17T16:02:00.371Z,1403020920.371 [Onboard] Loaded
2014-06-17T16:02:00.371Z,1403020920.371 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2014-06-17T16:02:00.378Z,1403020920.378 [Radio_Freewave] Loaded
2014-06-17T16:02:00.378Z,1403020920.378 [ComponentRegistry](DEBUG): Component "Radio_Freewave" handled in its own thread.
2014-06-17T16:02:00.379Z,1403020920.379 [Radio_Freewave ThreadHandler](DEBUG): Created PCaller Thread at 40A1B4E0
2014-06-17T16:02:00.380Z,1403020920.380 [Radio_Freewave ThreadHandler](INFO): Protected caller Thread ID is 5571
2014-06-17T16:02:00.386Z,1403020920.386 [SCPI] Loaded
2014-06-17T16:02:00.387Z,1403020920.387 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread.
2014-06-17T16:02:00.387Z,1403020920.387 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2014-06-17T16:02:00.388Z,1403020920.388 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2014-06-17T16:02:00.504Z,1403020920.504 [BuoyancyServo] Loaded
2014-06-17T16:02:00.504Z,1403020920.504 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2014-06-17T16:02:00.516Z,1403020920.516 [ElevatorServo] Loaded
2014-06-17T16:02:00.516Z,1403020920.516 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2014-06-17T16:02:00.527Z,1403020920.527 [MassServo] Loaded
2014-06-17T16:02:00.528Z,1403020920.528 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2014-06-17T16:02:00.539Z,1403020920.539 [RudderServo] Loaded
2014-06-17T16:02:00.540Z,1403020920.540 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2014-06-17T16:02:00.551Z,1403020920.551 [ThrusterServo] Loaded
2014-06-17T16:02:00.551Z,1403020920.551 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2014-06-17T16:02:00.552Z,1403020920.552 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2014-06-17T16:02:00.552Z,1403020920.552 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2014-06-17T16:02:00.730Z,1403020920.730 [InternalSim] Loaded
2014-06-17T16:02:00.730Z,1403020920.730 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2014-06-17T16:02:00.731Z,1403020920.731 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2014-06-17T16:02:00.731Z,1403020920.731 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2014-06-17T16:02:00.767Z,1403020920.767 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2014-06-17T16:02:00.769Z,1403020920.769 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2014-06-17T16:02:00.770Z,1403020920.770 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2014-06-17T16:02:00.776Z,1403020920.776 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2014-06-17T16:02:00.777Z,1403020920.777 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ACC4E0
2014-06-17T16:02:00.778Z,1403020920.778 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 5572
2014-06-17T16:02:00.782Z,1403020920.782 [Supervisor](INFO): Main Thread ID is 766
2014-06-17T16:02:00.783Z,1403020920.783 [Supervisor](DEBUG): Running supervisor.
2014-06-17T16:02:00.783Z,1403020920.783 [CommandLine ThreadHandler](INFO): Handler Thread ID is 5573
2014-06-17T16:02:00.786Z,1403020920.786 [controlThread ThreadHandler](INFO): Handler Thread ID is 5574
2014-06-17T16:02:00.787Z,1403020920.787 [controlThread](DEBUG): Initializing ControlThread
2014-06-17T16:02:00.788Z,1403020920.788 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2014-06-17T16:02:00.789Z,1403020920.789 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2014-06-17T16:02:00.790Z,1403020920.790 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2014-06-17T16:02:00.791Z,1403020920.791 [LoopControl](DEBUG): Initialize LoopControlComponent.
2014-06-17T16:02:00.791Z,1403020920.791 [SBIT](INFO): Initialize SBIT Component.
2014-06-17T16:02:00.791Z,1403020920.791 [SBIT](IMPORTANT): Tethys CM Info: SVN revision: 11420
2014-06-17T16:02:00.792Z,1403020920.792 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2014-06-17T16:02:00.792Z,1403020920.792 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2014-06-17T16:02:00.793Z,1403020920.793 [IBIT](INFO): Initialize IBIT Component.
2014-06-17T16:02:00.793Z,1403020920.793 [CBIT](DEBUG): Initialize CBIT Component.
2014-06-17T16:02:00.794Z,1403020920.794 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2014-06-17T16:02:00.795Z,1403020920.795 [logger ThreadHandler](INFO): Handler Thread ID is 5575
2014-06-17T16:02:00.819Z,1403020920.819 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-06-17T16:02:00.819Z,1403020920.819 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2014-06-17T16:02:00.820Z,1403020920.820 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2014-06-17T16:02:00.820Z,1403020920.820 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2014-06-17T16:02:00.820Z,1403020920.820 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2014-06-17T16:02:00.824Z,1403020920.824 [HFRadarCompactModelForecaster](DEBUG): Found new ECs!
2014-06-17T16:02:00.843Z,1403020920.843 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 5576
2014-06-17T16:02:00.844Z,1403020920.844 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2014-06-17T16:02:00.851Z,1403020920.851 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 5578
2014-06-17T16:02:00.852Z,1403020920.852 [WetLabsBB2FL](INFO): Powering down
2014-06-17T16:02:00.857Z,1403020920.857 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2014-06-17T16:02:00.887Z,1403020920.887 [Radio_Freewave ThreadHandler](INFO): Handler Thread ID is 5579
2014-06-17T16:02:00.907Z,1403020920.907 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 5580
2014-06-17T16:02:00.914Z,1403020920.914 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2014-06-17T16:02:00.915Z,1403020920.915 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2014-06-17T16:02:00.916Z,1403020920.916 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2014-06-17T16:02:00.916Z,1403020920.916 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2014-06-17T16:02:00.916Z,1403020920.916 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2014-06-17T16:02:00.916Z,1403020920.916 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2014-06-17T16:02:00.917Z,1403020920.917 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2014-06-17T16:02:00.917Z,1403020920.917 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2014-06-17T16:02:00.917Z,1403020920.917 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2014-06-17T16:02:09.356Z,1403020929.356 [HFRadarCompactModelForecaster](IMPORTANT): forecast time 201406171300: published 50 modes in rows, 61 hours in columns
2014-06-17T16:02:09.360Z,1403020929.360 [HFRadarCompactModelForecaster](IMPORTANT): expansionCoefficients_[0][48] = -1.069643 for 2014-06-17T13:00:00.000Z
2014-06-17T16:02:09.366Z,1403020929.366 [HFRCMSpaceInterpolator](DEBUG): Initializing HFRCMSpaceInterpolator component with verbosity level 0.
2014-06-17T16:02:09.384Z,1403020929.384 [HFRCMTimeInterpolator](DEBUG): Initializing HFRCMTimeInterpolator component.
2014-06-17T16:02:09.385Z,1403020929.385 [HFRCMReconstructedInterpolator](INFO): Initializing HFRCMReconstructedInterpolator component with velocityAccuracy_ = 0.300000 m/s.
2014-06-17T16:02:09.386Z,1403020929.386 [HFRCMSurfaceCurrentAtVehicleLocation](DEBUG): Initializing HFRCMSurfaceCurrentAtVehicleLocation component.
2014-06-17T16:02:09.386Z,1403020929.386 [HFRCMVirtualSurfaceDrifter](DEBUG): Initializing HFRCMVirtualSurfaceDrifter component.
2014-06-17T16:02:09.387Z,1403020929.387 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-06-17T16:02:09.387Z,1403020929.387 [DeadReckonWithRespectToWater](DEBUG): Initializing DeadReckonWithRespectToWater component.
2014-06-17T16:02:09.388Z,1403020929.388 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component.
2014-06-17T16:02:09.389Z,1403020929.389 [DeadReckonUsingDVLWaterTrack](DEBUG): Initializing DeadReckonUsingDVLWaterTrack component.
2014-06-17T16:02:09.389Z,1403020929.389 [DeadReckonUsingCompactModelForecast](DEBUG): Initializing DeadReckonUsingCompactModelForecast component.
2014-06-17T16:02:09.390Z,1403020929.390 [NavChart](DEBUG): Initialize NavChart Navigation.
2014-06-17T16:02:09.390Z,1403020929.390 [UniversalFixResidualReporter](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-06-17T16:02:11.360Z,1403020931.360 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2014-06-17T16:02:11.391Z,1403020931.391 [InternalSim](DEBUG):  InternalSim initializing...
2014-06-17T16:02:11.504Z,1403020931.504 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2014-06-17T16:02:11.534Z,1403020931.534 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-06-17T16:02:11.569Z,1403020931.569 [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-06-17T16:02:11.570Z,1403020931.570 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2014-06-17T16:02:11.641Z,1403020931.641 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2014-06-17T16:02:11.644Z,1403020931.644 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2014-06-17T16:02:11.647Z,1403020931.647 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-06-17T16:02:11.690Z,1403020931.690 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2014-06-17T16:02:11.694Z,1403020931.694 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-06-17T16:02:11.721Z,1403020931.721 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2014-06-17T16:02:11.793Z,1403020931.793 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Construct.
2014-06-17T16:02:11.826Z,1403020931.826 [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>
            <Progression/>
        </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>
            <Progression/>
        </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>

    </Aggregate>

</Mission>


2014-06-17T16:02:11.834Z,1403020931.834 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,PAR_Licor,AHRS_sp3003D,Batt_Ocean_Server,DataOverHttps,Depth_Keller,DropWeight,DVL_micro,NAL9602,Onboard,SCPI,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,HFRadarModelCalc,HFRadarCompactModelForecaster,HFRCMSpaceInterpolator,HFRCMTimeInterpolator,HFRCMReconstructedInterpolator,HFRCMSurfaceCurrentAtVehicleLocation,HFRCMVirtualSurfaceDrifter,DeadReckonUsingMultipleVelocitySources,DeadReckonWithRespectToWater,DeadReckonWithRespectToSeafloor,DeadReckonUsingDVLWaterTrack,DeadReckonUsingCompactModelForecast,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2014-06-17T16:02:12.014Z,1403020932.014 [Radio_Freewave](INFO): Powering up
2014-06-17T16:02:12.041Z,1403020932.041 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-06-17T16:02:12.112Z,1403020932.112 [Depth_Keller](ERROR): Pressure reading out of range: 1831.023193 decibar
2014-06-17T16:02:12.169Z,1403020932.169 [DVL_micro](INFO): Initializing
2014-06-17T16:02:12.199Z,1403020932.199 [NAL9602](INFO): Powering up NAL9602
2014-06-17T16:02:12.818Z,1403020932.818 [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-06-17T16:02:18.415Z,1403020938.415 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-06-17T16:02:18.422Z,1403020938.422 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-06-17T16:02:18.444Z,1403020938.444 [ElevatorServo](DEBUG): Initializing EZServoServo.
2014-06-17T16:02:18.446Z,1403020938.446 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2014-06-17T16:02:18.456Z,1403020938.456 [MassServo](DEBUG): Initializing EZServoServo.
2014-06-17T16:02:18.462Z,1403020938.462 [MassServo](DEBUG): Initializing MassServo.
2014-06-17T16:02:18.468Z,1403020938.468 [RudderServo](DEBUG): Initializing EZServoServo.
2014-06-17T16:02:18.474Z,1403020938.474 [RudderServo](DEBUG): Initializing RudderServo.
2014-06-17T16:02:18.480Z,1403020938.480 [ThrusterServo](DEBUG): Initializing EZServoServo.
2014-06-17T16:02:18.486Z,1403020938.486 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2014-06-17T16:02:19.155Z,1403020939.155 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2014-06-17T16:02:19.155Z,1403020939.155 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2014-06-17T16:02:19.155Z,1403020939.155 [AHRS_sp3003D] Hardware Fault, FailCount= 1
2014-06-17T16:02:19.155Z,1403020939.155 [AHRS_sp3003D](ERROR): Hardware Fault
2014-06-17T16:02:19.589Z,1403020939.589 [SBIT](IMPORTANT): Beginning Startup BIT
2014-06-17T16:02:19.592Z,1403020939.592 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2014-06-17T16:02:19.592Z,1403020939.592 [CBIT](IMPORTANT): Beginning GF scan
2014-06-17T16:02:19.624Z,1403020939.624 [AHRS_sp3003D](INFO): Powering down
2014-06-17T16:02:21.322Z,1403020941.322 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2014-06-17T16:02:21.322Z,1403020941.322 [AHRS_sp3003D] No Fault, FailCount= 1
2014-06-17T16:02:21.636Z,1403020941.636 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-06-17T16:02:21.740Z,1403020941.740 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003606
2014-06-17T16:02:22.973Z,1403020942.973 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2014-06-17T16:02:22.973Z,1403020942.973 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2014-06-17T16:02:22.973Z,1403020942.973 [AHRS_sp3003D] Hardware Fault, FailCount= 2
2014-06-17T16:02:22.973Z,1403020942.973 [AHRS_sp3003D](ERROR): Hardware Fault
2014-06-17T16:02:23.266Z,1403020943.266 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2014-06-17T16:02:23.291Z,1403020943.291 [AHRS_sp3003D](INFO): Powering down
2014-06-17T16:02:23.338Z,1403020943.338 [NAL9602](INFO): NAL9602 initialized
2014-06-17T16:02:24.676Z,1403020944.676 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2014-06-17T16:02:24.676Z,1403020944.676 [AHRS_sp3003D] No Fault, FailCount= 2
2014-06-17T16:02:24.881Z,1403020944.881 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-06-17T16:02:26.018Z,1403020946.018 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2014-06-17T16:02:26.018Z,1403020946.018 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2014-06-17T16:02:26.018Z,1403020946.018 [AHRS_sp3003D] Hardware Fault, FailCount= 3
2014-06-17T16:02:26.018Z,1403020946.018 [AHRS_sp3003D](ERROR): Hardware Fault
2014-06-17T16:02:26.269Z,1403020946.269 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2014-06-17T16:02:26.311Z,1403020946.311 [AHRS_sp3003D](INFO): Powering down
2014-06-17T16:02:27.673Z,1403020947.673 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2014-06-17T16:02:27.673Z,1403020947.673 [AHRS_sp3003D] No Fault, FailCount= 3
2014-06-17T16:02:27.889Z,1403020947.889 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-06-17T16:02:28.827Z,1403020948.827 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2014-06-17T16:02:28.828Z,1403020948.828 [AHRS_sp3003D](ERROR): readHeadingMagBin got 0xA409A0
2014-06-17T16:02:28.829Z,1403020948.829 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2014-06-17T16:02:28.830Z,1403020948.830 [AHRS_sp3003D] Hardware Fault, FailCount= 4
2014-06-17T16:02:28.830Z,1403020948.830 [AHRS_sp3003D](ERROR): Hardware Fault
2014-06-17T16:02:29.030Z,1403020949.030 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2014-06-17T16:02:29.107Z,1403020949.107 [AHRS_sp3003D](INFO): Powering down
2014-06-17T16:02:30.367Z,1403020950.367 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2014-06-17T16:02:30.367Z,1403020950.367 [AHRS_sp3003D] No Fault, FailCount= 4
2014-06-17T16:02:30.690Z,1403020950.690 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-06-17T16:02:31.843Z,1403020951.843 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2014-06-17T16:02:31.843Z,1403020951.843 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2014-06-17T16:02:31.843Z,1403020951.843 [AHRS_sp3003D] Hardware Fault, FailCount= 5
2014-06-17T16:02:31.843Z,1403020951.843 [AHRS_sp3003D](ERROR): Hardware Fault
2014-06-17T16:02:32.104Z,1403020952.104 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2014-06-17T16:02:32.104Z,1403020952.104 [CBIT](CRITICAL): Hardware Fault in component: AHRS_sp3003D
2014-06-17T16:02:32.155Z,1403020952.155 [AHRS_sp3003D](INFO): Powering down
2014-06-17T16:02:32.261Z,1403020952.261 [CommandLine](FAULT): Scheduling is paused
2014-06-17T16:02:45.726Z,1403020965.726 [CBIT](IMPORTANT): No ground fault detected
2014-06-17T16:03:13.599Z,1403020993.599 [SBIT](IMPORTANT): SBIT PASSED
2014-06-17T16:03:13.949Z,1403020993.949 [MissionManager](IMPORTANT): Started mission Startup
2014-06-17T16:03:13.949Z,1403020993.949 [Startup] Running Loop=1
2014-06-17T16:03:13.949Z,1403020993.949 [Startup](INFO): Aggregate::initialize Startup
2014-06-17T16:03:13.949Z,1403020993.949 [Startup:A.GoToSurface] Running Loop=1
2014-06-17T16:03:13.949Z,1403020993.949 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-06-17T16:03:13.950Z,1403020993.950 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-06-17T16:03:13.950Z,1403020993.950 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2014-06-17T16:03:13.951Z,1403020993.951 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2014-06-17T16:03:13.957Z,1403020993.957 [Startup:StartupSatComms] Running Loop=1
2014-06-17T16:03:13.957Z,1403020993.957 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2014-06-17T16:03:13.957Z,1403020993.957 [Startup:StartupSatComms:A] Running Loop=1
2014-06-17T16:03:14.360Z,1403020994.360 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-06-17T16:04:14.140Z,1403021054.140 [Startup:StartupSatComms:A](INFO): Timed out from 2014-06-17T16:03:13.0Z
2014-06-17T16:04:14.140Z,1403021054.140 [Startup:StartupSatComms:A] Stopped
2014-06-17T16:04:14.140Z,1403021054.140 [Startup:StartupSatComms:B] Running Loop=1
2014-06-17T16:04:14.512Z,1403021054.512 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-06-17T16:04:16.226Z,1403021056.226 [DataOverHttps](INFO): Sending 87 bytes from file Logs/20140617T003916/Courier0684.lzma
2014-06-17T16:04:16.999Z,1403021056.999 [DataOverHttps](INFO): Moved sent file to Logs/20140617T003916/Courier0684.lzma.bak
2014-06-17T16:04:16.999Z,1403021056.999 [DataOverHttps](INFO): SBD MOMSN=1010062
2014-06-17T16:04:51.825Z,1403021091.825 [DataOverHttps](INFO): Sending 251 bytes from file Logs/20140617T160142/Courier0000.lzma
2014-06-17T16:04:52.647Z,1403021092.647 [DataOverHttps](INFO): Moved sent file to Logs/20140617T160142/Courier0000.lzma.bak
2014-06-17T16:04:52.647Z,1403021092.647 [DataOverHttps](INFO): SBD MOMSN=1010065
2014-06-17T16:04:56.885Z,1403021096.885 [DataOverHttps](INFO): Sending 399 bytes from file Logs/20140617T003916/Express0685.lzma
2014-06-17T16:04:57.666Z,1403021097.666 [DataOverHttps](INFO): Moved sent file to Logs/20140617T003916/Express0685.lzma.bak
2014-06-17T16:04:57.666Z,1403021097.666 [DataOverHttps](INFO): SBD MOMSN=1010069
2014-06-17T16:05:14.196Z,1403021114.196 [Startup:StartupSatComms:B](INFO): Timed out from 2014-06-17T16:04:14.1Z
2014-06-17T16:05:14.196Z,1403021114.196 [Startup:StartupSatComms:B] Stopped
2014-06-17T16:05:14.196Z,1403021114.196 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2014-06-17T16:05:14.196Z,1403021114.196 [Startup:StartupSatComms] Stopped
2014-06-17T16:05:14.196Z,1403021114.196 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2014-06-17T16:05:14.197Z,1403021114.197 [Startup](INFO): Completed Startup
2014-06-17T16:05:14.197Z,1403021114.197 [Startup] Stopped
2014-06-17T16:05:14.197Z,1403021114.197 [Startup](INFO): Aggregate::uninitialize Startup
2014-06-17T16:05:14.198Z,1403021114.198 [Startup:A.GoToSurface] Stopped
2014-06-17T16:05:14.198Z,1403021114.198 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-06-17T16:05:14.659Z,1403021114.659 [MissionManager](IMPORTANT): Started mission Default
2014-06-17T16:05:14.659Z,1403021114.659 [Default] Running Loop=1
2014-06-17T16:05:14.659Z,1403021114.659 [Default](INFO): Aggregate::initialize Default
2014-06-17T16:05:14.660Z,1403021114.660 [Default:Iridium] Running Loop=1
2014-06-17T16:05:14.660Z,1403021114.660 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-06-17T16:05:14.660Z,1403021114.660 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-06-17T16:05:14.660Z,1403021114.660 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-06-17T16:05:14.660Z,1403021114.660 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-06-17T16:05:14.660Z,1403021114.660 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-06-17T16:05:14.660Z,1403021114.660 [Default:Iridium:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-06-17T16:05:14.661Z,1403021114.661 [Default:Iridium:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2014-06-17T16:05:14.661Z,1403021114.661 [Default:Iridium:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2014-06-17T16:05:14.662Z,1403021114.662 [Default:CallIridium] Running Loop=1
2014-06-17T16:05:14.662Z,1403021114.662 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-06-17T16:05:14.662Z,1403021114.662 [Default:CallIridium:A] Running Loop=1
2014-06-17T16:05:14.676Z,1403021114.676 [Default:CallIridium:A] Stopped
2014-06-17T16:05:14.676Z,1403021114.676 [Default:CallIridium:B] Running Loop=1
2014-06-17T16:05:14.677Z,1403021114.677 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-06-17T16:05:14.690Z,1403021114.690 [Default:Iridium:Read_Iridium] Running Loop=1
2014-06-17T16:05:14.690Z,1403021114.690 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-06-17T16:05:14.717Z,1403021114.717 [Default:GPS] Running Loop=1
2014-06-17T16:05:14.717Z,1403021114.717 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-06-17T16:05:14.717Z,1403021114.717 [Default:GPS:A.SetSpeed] Running Loop=1
2014-06-17T16:05:14.717Z,1403021114.717 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-06-17T16:05:14.717Z,1403021114.717 [Default:GPS:B.GoToSurface] Running Loop=1
2014-06-17T16:05:14.717Z,1403021114.717 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-06-17T16:05:14.717Z,1403021114.717 [Default:GPS:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-06-17T16:05:14.718Z,1403021114.718 [Default:GPS:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2014-06-17T16:05:14.718Z,1403021114.718 [Default:GPS:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2014-06-17T16:05:14.740Z,1403021114.740 [Default:GPS:Read_GPS] Running Loop=1
2014-06-17T16:05:14.740Z,1403021114.740 [Default:GPS:A.SetSpeed] Running Loop=1
2014-06-17T16:05:14.995Z,1403021114.995 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-06-17T16:05:14.999Z,1403021114.999 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-06-17T16:05:23.467Z,1403021123.467 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-06-17T16:05:23.467Z,1403021123.467 [DVL_micro] Data Fault, FailCount= 1
2014-06-17T16:05:23.467Z,1403021123.467 [DVL_micro](ERROR): Data Fault
2014-06-17T16:05:23.576Z,1403021123.576 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-06-17T16:05:23.872Z,1403021123.872 [DVL_micro](INFO): uninitialize:Powering down
2014-06-17T16:05:24.264Z,1403021124.264 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-06-17T16:05:24.264Z,1403021124.264 [DVL_micro] Hardware Fault, FailCount= 1
2014-06-17T16:05:24.264Z,1403021124.264 [DVL_micro](ERROR): Hardware Fault
2014-06-17T16:05:24.738Z,1403021124.738 [DVL_micro](INFO): Initializing
2014-06-17T16:05:24.797Z,1403021124.797 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-06-17T16:05:24.797Z,1403021124.797 [DVL_micro] No Fault, FailCount= 1
2014-06-17T16:05:30.783Z,1403021130.783 [DataOverHttps](INFO): Sending 973 bytes from file Logs/20140617T160142/Express0001.lzma
2014-06-17T16:05:32.778Z,1403021132.778 [DataOverHttps](INFO): Moved sent file to Logs/20140617T160142/Express0001.lzma.bak
2014-06-17T16:05:32.778Z,1403021132.778 [DataOverHttps](INFO): SBD MOMSN=1010080
2014-06-17T16:05:37.109Z,1403021137.109 [DataOverHttps](INFO): Sending 47 bytes from file Logs/20140617T160142/Courier0004.lzma
2014-06-17T16:05:37.913Z,1403021137.913 [DataOverHttps](INFO): Moved sent file to Logs/20140617T160142/Courier0004.lzma.bak
2014-06-17T16:05:37.913Z,1403021137.913 [DataOverHttps](INFO): SBD MOMSN=1010095
2014-06-17T16:05:42.155Z,1403021142.155 [DataOverHttps](INFO): Sending 114 bytes from file Logs/20140617T160142/Express0005.lzma
2014-06-17T16:05:43.731Z,1403021143.731 [DataOverHttps](INFO): Moved sent file to Logs/20140617T160142/Express0005.lzma.bak
2014-06-17T16:05:43.731Z,1403021143.731 [DataOverHttps](INFO): SBD MOMSN=1010097
2014-06-17T16:05:47.090Z,1403021147.090 [HFRadarModelCalc](IMPORTANT): Forecast time 20140617T130000: published 50 modes in rows, 61 hours in columns, 3050 elements.
2014-06-17T16:05:47.093Z,1403021147.093 [HFRadarModelCalc](IMPORTANT): expansionCoefficients_[0][48] = -1.069643 for 2014-06-17T13:00:00.000Z
2014-06-17T16:05:47.809Z,1403021147.809 [HFRadarCompactModelForecaster](DEBUG): Did not find new historical expansion coefficients.
2014-06-17T16:05:47.819Z,1403021147.819 [Default:Iridium:Read_Iridium] Stopped
2014-06-17T16:05:47.820Z,1403021147.820 [Default:Iridium](INFO): Completed Default:Iridium
2014-06-17T16:05:47.820Z,1403021147.820 [Default:Iridium] Stopped
2014-06-17T16:05:47.821Z,1403021147.821 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-06-17T16:05:47.821Z,1403021147.821 [Default:Iridium:A.SetSpeed] Stopped
2014-06-17T16:05:47.821Z,1403021147.821 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-06-17T16:05:47.821Z,1403021147.821 [Default:Iridium:B.GoToSurface] Stopped
2014-06-17T16:05:47.821Z,1403021147.821 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-06-17T16:05:47.821Z,1403021147.821 [Default:WaitAtTheSurface] Running Loop=1
2014-06-17T16:05:47.821Z,1403021147.821 [Default:WaitAtTheSurface](INFO): Aggregate::initialize Default:WaitAtTheSurface
2014-06-17T16:05:47.821Z,1403021147.821 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed] Running Loop=1
2014-06-17T16:05:47.821Z,1403021147.821 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Initialize.
2014-06-17T16:05:48.110Z,1403021148.110 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed] Running Loop=1
2014-06-17T16:05:48.120Z,1403021148.120 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-06-17T16:05:48.120Z,1403021148.120 [Default:CallIridium:B] Stopped
2014-06-17T16:05:48.120Z,1403021148.120 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-06-17T16:05:48.120Z,1403021148.120 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-06-17T16:05:48.120Z,1403021148.120 [Default:CallIridium] Stopped
2014-06-17T16:05:48.121Z,1403021148.121 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-06-17T16:07:32.202Z,1403021252.202 [CBIT](INFO): Clearing failed count for component AHRS_sp3003D
2014-06-17T16:07:32.202Z,1403021252.202 [AHRS_sp3003D] No Fault, FailCount= 5
2014-06-17T16:07:32.559Z,1403021252.559 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-06-17T16:08:28.682Z,1403021308.682 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-06-17T16:08:28.682Z,1403021308.682 [DVL_micro] Data Fault, FailCount= 1
2014-06-17T16:08:28.682Z,1403021308.682 [DVL_micro](ERROR): Data Fault
2014-06-17T16:08:28.750Z,1403021308.750 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-06-17T16:08:29.103Z,1403021309.103 [DVL_micro](INFO): uninitialize:Powering down
2014-06-17T16:08:29.568Z,1403021309.568 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-06-17T16:08:29.568Z,1403021309.568 [DVL_micro] Hardware Fault, FailCount= 1
2014-06-17T16:08:29.568Z,1403021309.568 [DVL_micro](ERROR): Hardware Fault
2014-06-17T16:08:29.990Z,1403021309.990 [DVL_micro](INFO): Initializing
2014-06-17T16:08:30.043Z,1403021310.043 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-06-17T16:08:30.043Z,1403021310.043 [DVL_micro] No Fault, FailCount= 1
2014-06-17T16:10:44.464Z,1403021444.464 [Default:CallIridium] Running Loop=1
2014-06-17T16:10:44.464Z,1403021444.464 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-06-17T16:10:44.464Z,1403021444.464 [Default:CallIridium:A] Running Loop=1
2014-06-17T16:10:44.465Z,1403021444.465 [Default:CallIridium:A] Stopped
2014-06-17T16:10:44.465Z,1403021444.465 [Default:CallIridium:B] Running Loop=1
2014-06-17T16:10:44.465Z,1403021444.465 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-06-17T16:10:44.911Z,1403021444.911 [Default:Iridium] Running Loop=1
2014-06-17T16:10:44.911Z,1403021444.911 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-06-17T16:10:44.911Z,1403021444.911 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-06-17T16:10:44.911Z,1403021444.911 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-06-17T16:10:44.911Z,1403021444.911 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-06-17T16:10:44.912Z,1403021444.912 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-06-17T16:10:44.912Z,1403021444.912 [Default:Iridium:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-06-17T16:10:44.912Z,1403021444.912 [Default:Iridium:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2014-06-17T16:10:44.913Z,1403021444.913 [Default:Iridium:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2014-06-17T16:10:44.913Z,1403021444.913 [Default:Iridium:Read_Iridium] Running Loop=1
2014-06-17T16:10:47.345Z,1403021447.345 [DataOverHttps](INFO): Sending 45 bytes from file Logs/20140617T160142/Courier0008.lzma
2014-06-17T16:10:48.218Z,1403021448.218 [DataOverHttps](INFO): Moved sent file to Logs/20140617T160142/Courier0008.lzma.bak
2014-06-17T16:10:48.218Z,1403021448.218 [DataOverHttps](INFO): SBD MOMSN=1010100
2014-06-17T16:10:53.599Z,1403021453.599 [DataOverHttps](INFO): Sending 475 bytes from file Logs/20140617T160142/Express0009.lzma
2014-06-17T16:10:54.508Z,1403021454.508 [DataOverHttps](INFO): Moved sent file to Logs/20140617T160142/Express0009.lzma.bak
2014-06-17T16:10:54.508Z,1403021454.508 [DataOverHttps](INFO): SBD MOMSN=1010102
2014-06-17T16:10:57.907Z,1403021457.907 [HFRadarModelCalc](IMPORTANT): Forecast time 20140617T130000: published 50 modes in rows, 61 hours in columns, 3050 elements.
2014-06-17T16:10:57.910Z,1403021457.910 [HFRadarModelCalc](IMPORTANT): expansionCoefficients_[0][48] = -1.069643 for 2014-06-17T13:00:00.000Z
2014-06-17T16:10:58.623Z,1403021458.623 [HFRadarCompactModelForecaster](DEBUG): Did not find new historical expansion coefficients.
2014-06-17T16:10:58.634Z,1403021458.634 [Default:Iridium:Read_Iridium] Stopped
2014-06-17T16:10:58.635Z,1403021458.635 [Default:Iridium](INFO): Completed Default:Iridium
2014-06-17T16:10:58.635Z,1403021458.635 [Default:Iridium] Stopped
2014-06-17T16:10:58.635Z,1403021458.635 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-06-17T16:10:58.636Z,1403021458.636 [Default:Iridium:A.SetSpeed] Stopped
2014-06-17T16:10:58.636Z,1403021458.636 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-06-17T16:10:58.636Z,1403021458.636 [Default:Iridium:B.GoToSurface] Stopped
2014-06-17T16:10:58.636Z,1403021458.636 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-06-17T16:10:59.211Z,1403021459.211 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-06-17T16:10:59.211Z,1403021459.211 [Default:CallIridium:B] Stopped
2014-06-17T16:10:59.212Z,1403021459.212 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-06-17T16:10:59.212Z,1403021459.212 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-06-17T16:10:59.212Z,1403021459.212 [Default:CallIridium] Stopped
2014-06-17T16:10:59.212Z,1403021459.212 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-06-17T16:11:34.274Z,1403021494.274 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-06-17T16:11:34.274Z,1403021494.274 [DVL_micro] Data Fault, FailCount= 1
2014-06-17T16:11:34.274Z,1403021494.274 [DVL_micro](ERROR): Data Fault
2014-06-17T16:11:34.353Z,1403021494.353 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-06-17T16:11:34.710Z,1403021494.710 [DVL_micro](INFO): uninitialize:Powering down
2014-06-17T16:11:35.127Z,1403021495.127 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-06-17T16:11:35.127Z,1403021495.127 [DVL_micro] Hardware Fault, FailCount= 1
2014-06-17T16:11:35.127Z,1403021495.127 [DVL_micro](ERROR): Hardware Fault
2014-06-17T16:11:35.566Z,1403021495.566 [DVL_micro](INFO): Initializing
2014-06-17T16:11:35.616Z,1403021495.616 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-06-17T16:11:35.616Z,1403021495.616 [DVL_micro] No Fault, FailCount= 1
2014-06-17T16:12:24.521Z,1403021544.521 [NAL9602](FAULT): GPS failed to acquire within timeout.
2014-06-17T16:12:24.521Z,1403021544.521 [NAL9602] Data Fault, FailCount= 1
2014-06-17T16:12:24.521Z,1403021544.521 [NAL9602](ERROR): Data Fault
2014-06-17T16:12:24.597Z,1403021544.597 [CBIT](ERROR): Data Fault in component: NAL9602
2014-06-17T16:12:24.945Z,1403021544.945 [NAL9602](INFO): Powering down
2014-06-17T16:12:25.870Z,1403021545.870 [CBIT](INFO): Clearing failed state for component NAL9602
2014-06-17T16:12:25.870Z,1403021545.870 [NAL9602] No Fault, FailCount= 1
2014-06-17T16:12:30.061Z,1403021550.061 [NAL9602](INFO): Powering up NAL9602
2014-06-17T16:12:40.786Z,1403021560.786 [NAL9602](INFO): NAL9602 initialized
2014-06-17T16:14:39.666Z,1403021679.666 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-06-17T16:14:39.666Z,1403021679.666 [DVL_micro] Data Fault, FailCount= 1
2014-06-17T16:14:39.666Z,1403021679.666 [DVL_micro](ERROR): Data Fault
2014-06-17T16:14:39.747Z,1403021679.747 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-06-17T16:14:40.098Z,1403021680.098 [DVL_micro](INFO): uninitialize:Powering down
2014-06-17T16:14:40.528Z,1403021680.528 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-06-17T16:14:40.528Z,1403021680.528 [DVL_micro] Hardware Fault, FailCount= 1
2014-06-17T16:14:40.528Z,1403021680.528 [DVL_micro](ERROR): Hardware Fault
2014-06-17T16:14:41.051Z,1403021681.051 [DVL_micro](INFO): Initializing
2014-06-17T16:14:41.109Z,1403021681.109 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-06-17T16:14:41.109Z,1403021681.109 [DVL_micro] No Fault, FailCount= 1
2014-06-17T16:15:55.065Z,1403021755.065 [Default:CallIridium] Running Loop=1
2014-06-17T16:15:55.065Z,1403021755.065 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-06-17T16:15:55.066Z,1403021755.066 [Default:CallIridium:A] Running Loop=1
2014-06-17T16:15:55.066Z,1403021755.066 [Default:CallIridium:A] Stopped
2014-06-17T16:15:55.066Z,1403021755.066 [Default:CallIridium:B] Running Loop=1
2014-06-17T16:15:55.066Z,1403021755.066 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-06-17T16:15:55.538Z,1403021755.538 [Default:Iridium] Running Loop=1
2014-06-17T16:15:55.538Z,1403021755.538 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-06-17T16:15:55.538Z,1403021755.538 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-06-17T16:15:55.538Z,1403021755.538 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-06-17T16:15:55.538Z,1403021755.538 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-06-17T16:15:55.538Z,1403021755.538 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-06-17T16:15:55.538Z,1403021755.538 [Default:Iridium:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-06-17T16:15:55.539Z,1403021755.539 [Default:Iridium:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2014-06-17T16:15:55.539Z,1403021755.539 [Default:Iridium:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2014-06-17T16:15:55.540Z,1403021755.540 [Default:Iridium:Read_Iridium] Running Loop=1
2014-06-17T16:15:58.410Z,1403021758.410 [DataOverHttps](INFO): Sending 47 bytes from file Logs/20140617T160142/Courier0012.lzma
2014-06-17T16:15:59.326Z,1403021759.326 [DataOverHttps](INFO): Moved sent file to Logs/20140617T160142/Courier0012.lzma.bak
2014-06-17T16:15:59.327Z,1403021759.327 [DataOverHttps](INFO): SBD MOMSN=1010110
2014-06-17T16:16:07.808Z,1403021767.808 [DataOverHttps](INFO): Sending 374 bytes from file Logs/20140617T160142/Express0013.lzma
2014-06-17T16:16:08.730Z,1403021768.730 [DataOverHttps](INFO): Moved sent file to Logs/20140617T160142/Express0013.lzma.bak
2014-06-17T16:16:08.730Z,1403021768.730 [DataOverHttps](INFO): SBD MOMSN=1010112
2014-06-17T16:16:12.115Z,1403021772.115 [HFRadarModelCalc](IMPORTANT): Forecast time 20140617T130000: published 50 modes in rows, 61 hours in columns, 3050 elements.
2014-06-17T16:16:12.117Z,1403021772.117 [HFRadarModelCalc](IMPORTANT): expansionCoefficients_[0][48] = -1.069643 for 2014-06-17T13:00:00.000Z
2014-06-17T16:16:12.854Z,1403021772.854 [HFRadarCompactModelForecaster](DEBUG): Did not find new historical expansion coefficients.
2014-06-17T16:16:12.865Z,1403021772.865 [Default:Iridium:Read_Iridium] Stopped
2014-06-17T16:16:12.866Z,1403021772.866 [Default:Iridium](INFO): Completed Default:Iridium
2014-06-17T16:16:12.866Z,1403021772.866 [Default:Iridium] Stopped
2014-06-17T16:16:12.866Z,1403021772.866 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-06-17T16:16:12.866Z,1403021772.866 [Default:Iridium:A.SetSpeed] Stopped
2014-06-17T16:16:12.866Z,1403021772.866 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-06-17T16:16:12.866Z,1403021772.866 [Default:Iridium:B.GoToSurface] Stopped
2014-06-17T16:16:12.866Z,1403021772.866 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-06-17T16:16:13.499Z,1403021773.499 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-06-17T16:16:13.499Z,1403021773.499 [Default:CallIridium:B] Stopped
2014-06-17T16:16:13.499Z,1403021773.499 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-06-17T16:16:13.499Z,1403021773.499 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-06-17T16:16:13.499Z,1403021773.499 [Default:CallIridium] Stopped
2014-06-17T16:16:13.500Z,1403021773.500 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-06-17T16:17:45.066Z,1403021865.066 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-06-17T16:17:45.066Z,1403021865.066 [DVL_micro] Data Fault, FailCount= 1
2014-06-17T16:17:45.066Z,1403021865.066 [DVL_micro](ERROR): Data Fault
2014-06-17T16:17:45.101Z,1403021865.101 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-06-17T16:17:45.481Z,1403021865.481 [DVL_micro](INFO): uninitialize:Powering down
2014-06-17T16:17:45.889Z,1403021865.889 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-06-17T16:17:45.890Z,1403021865.890 [DVL_micro] Hardware Fault, FailCount= 1
2014-06-17T16:17:45.890Z,1403021865.890 [DVL_micro](ERROR): Hardware Fault
2014-06-17T16:17:46.321Z,1403021866.321 [DVL_micro](INFO): Initializing
2014-06-17T16:17:46.352Z,1403021866.352 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-06-17T16:17:46.352Z,1403021866.352 [DVL_micro] No Fault, FailCount= 1
2014-06-17T16:20:50.288Z,1403022050.288 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-06-17T16:20:50.288Z,1403022050.288 [DVL_micro] Data Fault, FailCount= 1
2014-06-17T16:20:50.288Z,1403022050.288 [DVL_micro](ERROR): Data Fault
2014-06-17T16:20:50.358Z,1403022050.358 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-06-17T16:20:50.696Z,1403022050.696 [DVL_micro](INFO): uninitialize:Powering down
2014-06-17T16:20:51.125Z,1403022051.125 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-06-17T16:20:51.125Z,1403022051.125 [DVL_micro] Hardware Fault, FailCount= 1
2014-06-17T16:20:51.125Z,1403022051.125 [DVL_micro](ERROR): Hardware Fault
2014-06-17T16:20:51.580Z,1403022051.580 [DVL_micro](INFO): Initializing
2014-06-17T16:20:51.669Z,1403022051.669 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-06-17T16:20:51.669Z,1403022051.669 [DVL_micro] No Fault, FailCount= 1
2014-06-17T16:21:09.550Z,1403022069.550 [Default:CallIridium] Running Loop=1
2014-06-17T16:21:09.550Z,1403022069.550 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-06-17T16:21:09.550Z,1403022069.550 [Default:CallIridium:A] Running Loop=1
2014-06-17T16:21:09.550Z,1403022069.550 [Default:CallIridium:A] Stopped
2014-06-17T16:21:09.550Z,1403022069.550 [Default:CallIridium:B] Running Loop=1
2014-06-17T16:21:09.551Z,1403022069.551 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-06-17T16:21:10.043Z,1403022070.043 [Default:Iridium] Running Loop=1
2014-06-17T16:21:10.044Z,1403022070.044 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-06-17T16:21:10.044Z,1403022070.044 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-06-17T16:21:10.044Z,1403022070.044 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-06-17T16:21:10.044Z,1403022070.044 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-06-17T16:21:10.048Z,1403022070.048 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-06-17T16:21:10.049Z,1403022070.049 [Default:Iridium:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-06-17T16:21:10.049Z,1403022070.049 [Default:Iridium:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2014-06-17T16:21:10.049Z,1403022070.049 [Default:Iridium:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2014-06-17T16:21:10.050Z,1403022070.050 [Default:Iridium:Read_Iridium] Running Loop=1
2014-06-17T16:21:12.364Z,1403022072.364 [DataOverHttps](INFO): Sending 45 bytes from file Logs/20140617T160142/Courier0016.lzma
2014-06-17T16:21:13.250Z,1403022073.250 [DataOverHttps](INFO): Moved sent file to Logs/20140617T160142/Courier0016.lzma.bak
2014-06-17T16:21:13.250Z,1403022073.250 [DataOverHttps](INFO): SBD MOMSN=1010121
2014-06-17T16:21:18.670Z,1403022078.670 [DataOverHttps](INFO): Sending 332 bytes from file Logs/20140617T160142/Express0017.lzma
2014-06-17T16:21:19.523Z,1403022079.523 [DataOverHttps](INFO): Moved sent file to Logs/20140617T160142/Express0017.lzma.bak
2014-06-17T16:21:19.523Z,1403022079.523 [DataOverHttps](INFO): SBD MOMSN=1010123
2014-06-17T16:21:23.033Z,1403022083.033 [HFRadarModelCalc](IMPORTANT): Forecast time 20140617T130000: published 50 modes in rows, 61 hours in columns, 3050 elements.
2014-06-17T16:21:23.036Z,1403022083.036 [HFRadarModelCalc](IMPORTANT): expansionCoefficients_[0][48] = -1.069643 for 2014-06-17T13:00:00.000Z
2014-06-17T16:21:23.769Z,1403022083.769 [HFRadarCompactModelForecaster](DEBUG): Did not find new historical expansion coefficients.
2014-06-17T16:21:23.780Z,1403022083.780 [Default:Iridium:Read_Iridium] Stopped
2014-06-17T16:21:23.781Z,1403022083.781 [Default:Iridium](INFO): Completed Default:Iridium
2014-06-17T16:21:23.781Z,1403022083.781 [Default:Iridium] Stopped
2014-06-17T16:21:23.781Z,1403022083.781 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-06-17T16:21:23.782Z,1403022083.782 [Default:Iridium:A.SetSpeed] Stopped
2014-06-17T16:21:23.782Z,1403022083.782 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-06-17T16:21:23.782Z,1403022083.782 [Default:Iridium:B.GoToSurface] Stopped
2014-06-17T16:21:23.782Z,1403022083.782 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-06-17T16:21:24.334Z,1403022084.334 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-06-17T16:21:24.334Z,1403022084.334 [Default:CallIridium:B] Stopped
2014-06-17T16:21:24.334Z,1403022084.334 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-06-17T16:21:24.334Z,1403022084.334 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-06-17T16:21:24.334Z,1403022084.334 [Default:CallIridium] Stopped
2014-06-17T16:21:24.339Z,1403022084.339 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-06-17T16:22:43.729Z,1403022163.729 [NAL9602](FAULT): GPS failed to acquire within timeout.
2014-06-17T16:22:43.729Z,1403022163.729 [NAL9602] Data Fault, FailCount= 2
2014-06-17T16:22:43.729Z,1403022163.729 [NAL9602](ERROR): Data Fault
2014-06-17T16:22:43.788Z,1403022163.788 [CBIT](ERROR): Data Fault in component: NAL9602
2014-06-17T16:22:43.788Z,1403022163.788 [CBIT](CRITICAL): Data Fault in component: NAL9602
2014-06-17T16:22:44.170Z,1403022164.170 [NAL9602](INFO): Powering down
2014-06-17T16:23:55.819Z,1403022235.819 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-06-17T16:23:55.820Z,1403022235.820 [DVL_micro] Data Fault, FailCount= 1
2014-06-17T16:23:55.820Z,1403022235.820 [DVL_micro](ERROR): Data Fault
2014-06-17T16:23:55.869Z,1403022235.869 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-06-17T16:23:56.252Z,1403022236.252 [DVL_micro](INFO): uninitialize:Powering down
2014-06-17T16:23:56.697Z,1403022236.697 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-06-17T16:23:56.697Z,1403022236.697 [DVL_micro] Hardware Fault, FailCount= 1
2014-06-17T16:23:56.697Z,1403022236.697 [DVL_micro](ERROR): Hardware Fault
2014-06-17T16:23:57.116Z,1403022237.116 [DVL_micro](INFO): Initializing
2014-06-17T16:23:57.169Z,1403022237.169 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-06-17T16:23:57.169Z,1403022237.169 [DVL_micro] No Fault, FailCount= 1
2014-06-17T16:24:44.005Z,1403022284.005 [CBIT](INFO): Clearing failed count for component NAL9602
2014-06-17T16:24:44.005Z,1403022284.005 [NAL9602] No Fault, FailCount= 2
2014-06-17T16:24:44.440Z,1403022284.440 [NAL9602](INFO): Powering up NAL9602
2014-06-17T16:24:55.198Z,1403022295.198 [NAL9602](INFO): NAL9602 initialized
2014-06-17T16:26:20.358Z,1403022380.358 [Default:CallIridium] Running Loop=1
2014-06-17T16:26:20.358Z,1403022380.358 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-06-17T16:26:20.359Z,1403022380.359 [Default:CallIridium:A] Running Loop=1
2014-06-17T16:26:20.359Z,1403022380.359 [Default:CallIridium:A] Stopped
2014-06-17T16:26:20.359Z,1403022380.359 [Default:CallIridium:B] Running Loop=1
2014-06-17T16:26:20.359Z,1403022380.359 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-06-17T16:26:20.799Z,1403022380.799 [Default:Iridium] Running Loop=1
2014-06-17T16:26:20.799Z,1403022380.799 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-06-17T16:26:20.799Z,1403022380.799 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-06-17T16:26:20.799Z,1403022380.799 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-06-17T16:26:20.799Z,1403022380.799 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-06-17T16:26:20.799Z,1403022380.799 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-06-17T16:26:20.800Z,1403022380.800 [Default:Iridium:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-06-17T16:26:20.800Z,1403022380.800 [Default:Iridium:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2014-06-17T16:26:20.800Z,1403022380.800 [Default:Iridium:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2014-06-17T16:26:20.801Z,1403022380.801 [Default:Iridium:Read_Iridium] Running Loop=1
2014-06-17T16:26:23.194Z,1403022383.194 [DataOverHttps](INFO): Sending 89 bytes from file Logs/20140617T160142/Courier0020.lzma
2014-06-17T16:26:24.087Z,1403022384.087 [DataOverHttps](INFO): Moved sent file to Logs/20140617T160142/Courier0020.lzma.bak
2014-06-17T16:26:24.087Z,1403022384.087 [DataOverHttps](INFO): SBD MOMSN=1010131
2014-06-17T16:26:32.585Z,1403022392.585 [DataOverHttps](INFO): Sending 338 bytes from file Logs/20140617T160142/Express0021.lzma
2014-06-17T16:26:33.466Z,1403022393.466 [DataOverHttps](INFO): Moved sent file to Logs/20140617T160142/Express0021.lzma.bak
2014-06-17T16:26:33.466Z,1403022393.466 [DataOverHttps](INFO): SBD MOMSN=1010134
2014-06-17T16:26:36.911Z,1403022396.911 [HFRadarModelCalc](IMPORTANT): Forecast time 20140617T140000: published 50 modes in rows, 61 hours in columns, 3050 elements.
2014-06-17T16:26:36.914Z,1403022396.914 [HFRadarModelCalc](IMPORTANT): expansionCoefficients_[0][48] = -3.814250 for 2014-06-17T14:00:00.000Z
2014-06-17T16:26:37.637Z,1403022397.637 [HFRadarCompactModelForecaster](DEBUG): Did not find new historical expansion coefficients.
2014-06-17T16:26:37.647Z,1403022397.647 [Default:Iridium:Read_Iridium] Stopped
2014-06-17T16:26:37.649Z,1403022397.649 [Default:Iridium](INFO): Completed Default:Iridium
2014-06-17T16:26:37.650Z,1403022397.650 [Default:Iridium] Stopped
2014-06-17T16:26:37.650Z,1403022397.650 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-06-17T16:26:37.650Z,1403022397.650 [Default:Iridium:A.SetSpeed] Stopped
2014-06-17T16:26:37.650Z,1403022397.650 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-06-17T16:26:37.650Z,1403022397.650 [Default:Iridium:B.GoToSurface] Stopped
2014-06-17T16:26:37.650Z,1403022397.650 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-06-17T16:26:38.294Z,1403022398.294 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-06-17T16:26:38.294Z,1403022398.294 [Default:CallIridium:B] Stopped
2014-06-17T16:26:38.294Z,1403022398.294 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-06-17T16:26:38.294Z,1403022398.294 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-06-17T16:26:38.294Z,1403022398.294 [Default:CallIridium] Stopped
2014-06-17T16:26:38.294Z,1403022398.294 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-06-17T16:27:01.030Z,1403022421.030 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-06-17T16:27:01.031Z,1403022421.031 [DVL_micro] Data Fault, FailCount= 1
2014-06-17T16:27:01.031Z,1403022421.031 [DVL_micro](ERROR): Data Fault
2014-06-17T16:27:01.106Z,1403022421.106 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-06-17T16:27:01.463Z,1403022421.463 [DVL_micro](INFO): uninitialize:Powering down
2014-06-17T16:27:01.952Z,1403022421.952 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-06-17T16:27:01.952Z,1403022421.952 [DVL_micro] Hardware Fault, FailCount= 1
2014-06-17T16:27:01.952Z,1403022421.952 [DVL_micro](ERROR): Hardware Fault
2014-06-17T16:27:02.377Z,1403022422.377 [DVL_micro](INFO): Initializing
2014-06-17T16:27:02.409Z,1403022422.409 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-06-17T16:27:02.409Z,1403022422.409 [DVL_micro] No Fault, FailCount= 1
2014-06-17T16:30:06.506Z,1403022606.506 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-06-17T16:30:06.506Z,1403022606.506 [DVL_micro] Data Fault, FailCount= 1
2014-06-17T16:30:06.506Z,1403022606.506 [DVL_micro](ERROR): Data Fault
2014-06-17T16:30:06.651Z,1403022606.651 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-06-17T16:30:07.027Z,1403022607.027 [DVL_micro](INFO): uninitialize:Powering down
2014-06-17T16:30:07.539Z,1403022607.539 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-06-17T16:30:07.540Z,1403022607.540 [DVL_micro] Hardware Fault, FailCount= 1
2014-06-17T16:30:07.540Z,1403022607.540 [DVL_micro](ERROR): Hardware Fault
2014-06-17T16:30:08.031Z,1403022608.031 [DVL_micro](INFO): Initializing
2014-06-17T16:30:08.123Z,1403022608.123 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-06-17T16:30:08.123Z,1403022608.123 [DVL_micro] No Fault, FailCount= 1
2014-06-17T16:31:34.412Z,1403022694.412 [Default:CallIridium] Running Loop=1
2014-06-17T16:31:34.413Z,1403022694.413 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-06-17T16:31:34.413Z,1403022694.413 [Default:CallIridium:A] Running Loop=1
2014-06-17T16:31:34.413Z,1403022694.413 [Default:CallIridium:A] Stopped
2014-06-17T16:31:34.413Z,1403022694.413 [Default:CallIridium:B] Running Loop=1
2014-06-17T16:31:34.413Z,1403022694.413 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-06-17T16:31:34.816Z,1403022694.816 [Default:Iridium] Running Loop=1
2014-06-17T16:31:34.817Z,1403022694.817 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-06-17T16:31:34.817Z,1403022694.817 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-06-17T16:31:34.817Z,1403022694.817 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-06-17T16:31:34.817Z,1403022694.817 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-06-17T16:31:34.817Z,1403022694.817 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-06-17T16:31:34.818Z,1403022694.818 [Default:Iridium:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-06-17T16:31:34.818Z,1403022694.818 [Default:Iridium:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2014-06-17T16:31:34.818Z,1403022694.818 [Default:Iridium:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2014-06-17T16:31:34.819Z,1403022694.819 [Default:Iridium:Read_Iridium] Running Loop=1
2014-06-17T16:31:36.722Z,1403022696.722 [DataOverHttps](INFO): Sending 45 bytes from file Logs/20140617T160142/Courier0024.lzma
2014-06-17T16:31:37.640Z,1403022697.640 [DataOverHttps](INFO): Moved sent file to Logs/20140617T160142/Courier0024.lzma.bak
2014-06-17T16:31:37.641Z,1403022697.641 [DataOverHttps](INFO): SBD MOMSN=1010141
2014-06-17T16:31:46.225Z,1403022706.225 [DataOverHttps](INFO): Sending 328 bytes from file Logs/20140617T160142/Express0025.lzma
2014-06-17T16:31:47.060Z,1403022707.060 [DataOverHttps](INFO): Moved sent file to Logs/20140617T160142/Express0025.lzma.bak
2014-06-17T16:31:47.060Z,1403022707.060 [DataOverHttps](INFO): SBD MOMSN=1010143
2014-06-17T16:31:50.482Z,1403022710.482 [HFRadarModelCalc](IMPORTANT): Forecast time 20140617T140000: published 50 modes in rows, 61 hours in columns, 3050 elements.
2014-06-17T16:31:50.484Z,1403022710.484 [HFRadarModelCalc](IMPORTANT): expansionCoefficients_[0][48] = -3.814250 for 2014-06-17T14:00:00.000Z
2014-06-17T16:31:51.210Z,1403022711.210 [HFRadarCompactModelForecaster](DEBUG): Did not find new historical expansion coefficients.
2014-06-17T16:31:51.222Z,1403022711.222 [Default:Iridium:Read_Iridium] Stopped
2014-06-17T16:31:51.223Z,1403022711.223 [Default:Iridium](INFO): Completed Default:Iridium
2014-06-17T16:31:51.223Z,1403022711.223 [Default:Iridium] Stopped
2014-06-17T16:31:51.223Z,1403022711.223 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-06-17T16:31:51.224Z,1403022711.224 [Default:Iridium:A.SetSpeed] Stopped
2014-06-17T16:31:51.224Z,1403022711.224 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-06-17T16:31:51.224Z,1403022711.224 [Default:Iridium:B.GoToSurface] Stopped
2014-06-17T16:31:51.224Z,1403022711.224 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-06-17T16:31:51.874Z,1403022711.874 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-06-17T16:31:51.874Z,1403022711.874 [Default:CallIridium:B] Stopped
2014-06-17T16:31:51.874Z,1403022711.874 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-06-17T16:31:51.874Z,1403022711.874 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-06-17T16:31:51.874Z,1403022711.874 [Default:CallIridium] Stopped
2014-06-17T16:31:51.874Z,1403022711.874 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-06-17T16:33:12.719Z,1403022792.719 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-06-17T16:33:12.719Z,1403022792.719 [DVL_micro] Data Fault, FailCount= 1
2014-06-17T16:33:12.719Z,1403022792.719 [DVL_micro](ERROR): Data Fault
2014-06-17T16:33:12.773Z,1403022792.773 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-06-17T16:33:13.173Z,1403022793.173 [DVL_micro](INFO): uninitialize:Powering down
2014-06-17T16:33:13.584Z,1403022793.584 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-06-17T16:33:13.584Z,1403022793.584 [DVL_micro] Hardware Fault, FailCount= 1
2014-06-17T16:33:13.584Z,1403022793.584 [DVL_micro](ERROR): Hardware Fault
2014-06-17T16:33:13.999Z,1403022793.999 [DVL_micro](INFO): Initializing
2014-06-17T16:33:14.079Z,1403022794.079 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-06-17T16:33:14.079Z,1403022794.079 [DVL_micro] No Fault, FailCount= 1
2014-06-17T16:33:22.746Z,1403022802.746 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#10 STATUS: 65535
2014-06-17T16:34:56.156Z,1403022896.156 [NAL9602](FAULT): GPS failed to acquire within timeout.
2014-06-17T16:34:56.156Z,1403022896.156 [NAL9602] Data Fault, FailCount= 1
2014-06-17T16:34:56.156Z,1403022896.156 [NAL9602](ERROR): Data Fault
2014-06-17T16:34:56.187Z,1403022896.187 [CBIT](ERROR): Data Fault in component: NAL9602
2014-06-17T16:34:56.689Z,1403022896.689 [NAL9602](INFO): Powering down
2014-06-17T16:34:57.543Z,1403022897.543 [CBIT](INFO): Clearing failed state for component NAL9602
2014-06-17T16:34:57.543Z,1403022897.543 [NAL9602] No Fault, FailCount= 1
2014-06-17T16:35:01.871Z,1403022901.871 [NAL9602](INFO): Powering up NAL9602
2014-06-17T16:35:12.890Z,1403022912.890 [NAL9602](INFO): NAL9602 initialized
2014-06-17T16:36:18.002Z,1403022978.002 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-06-17T16:36:18.002Z,1403022978.002 [DVL_micro] Data Fault, FailCount= 1
2014-06-17T16:36:18.002Z,1403022978.002 [DVL_micro](ERROR): Data Fault
2014-06-17T16:36:18.063Z,1403022978.063 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-06-17T16:36:18.468Z,1403022978.468 [DVL_micro](INFO): uninitialize:Powering down
2014-06-17T16:36:18.887Z,1403022978.887 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-06-17T16:36:18.888Z,1403022978.888 [DVL_micro] Hardware Fault, FailCount= 1
2014-06-17T16:36:18.888Z,1403022978.888 [DVL_micro](ERROR): Hardware Fault
2014-06-17T16:36:19.319Z,1403022979.319 [DVL_micro](INFO): Initializing
2014-06-17T16:36:19.385Z,1403022979.385 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-06-17T16:36:19.385Z,1403022979.385 [DVL_micro] No Fault, FailCount= 1
2014-06-17T16:36:47.680Z,1403023007.680 [Default:CallIridium] Running Loop=1
2014-06-17T16:36:47.681Z,1403023007.681 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-06-17T16:36:47.681Z,1403023007.681 [Default:CallIridium:A] Running Loop=1
2014-06-17T16:36:47.681Z,1403023007.681 [Default:CallIridium:A] Stopped
2014-06-17T16:36:47.681Z,1403023007.681 [Default:CallIridium:B] Running Loop=1
2014-06-17T16:36:47.681Z,1403023007.681 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-06-17T16:36:48.091Z,1403023008.091 [Default:Iridium] Running Loop=1
2014-06-17T16:36:48.092Z,1403023008.092 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-06-17T16:36:48.092Z,1403023008.092 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-06-17T16:36:48.092Z,1403023008.092 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-06-17T16:36:48.092Z,1403023008.092 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-06-17T16:36:48.092Z,1403023008.092 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-06-17T16:36:48.092Z,1403023008.092 [Default:Iridium:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-06-17T16:36:48.093Z,1403023008.093 [Default:Iridium:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2014-06-17T16:36:48.093Z,1403023008.093 [Default:Iridium:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2014-06-17T16:36:48.094Z,1403023008.094 [Default:Iridium:Read_Iridium] Running Loop=1
2014-06-17T16:36:50.563Z,1403023010.563 [DataOverHttps](INFO): Sending 45 bytes from file Logs/20140617T160142/Courier0028.lzma
2014-06-17T16:36:51.448Z,1403023011.448 [DataOverHttps](INFO): Moved sent file to Logs/20140617T160142/Courier0028.lzma.bak
2014-06-17T16:36:51.448Z,1403023011.448 [DataOverHttps](INFO): SBD MOMSN=1010151
2014-06-17T16:36:56.865Z,1403023016.865 [DataOverHttps](INFO): Sending 349 bytes from file Logs/20140617T160142/Express0029.lzma
2014-06-17T16:36:57.702Z,1403023017.702 [DataOverHttps](INFO): Moved sent file to Logs/20140617T160142/Express0029.lzma.bak
2014-06-17T16:36:57.702Z,1403023017.702 [DataOverHttps](INFO): SBD MOMSN=1010153
2014-06-17T16:37:01.113Z,1403023021.113 [HFRadarModelCalc](IMPORTANT): Forecast time 20140617T140000: published 50 modes in rows, 61 hours in columns, 3050 elements.
2014-06-17T16:37:01.116Z,1403023021.116 [HFRadarModelCalc](IMPORTANT): expansionCoefficients_[0][48] = -3.814250 for 2014-06-17T14:00:00.000Z
2014-06-17T16:37:01.839Z,1403023021.839 [HFRadarCompactModelForecaster](DEBUG): Did not find new historical expansion coefficients.
2014-06-17T16:37:01.850Z,1403023021.850 [Default:Iridium:Read_Iridium] Stopped
2014-06-17T16:37:01.851Z,1403023021.851 [Default:Iridium](INFO): Completed Default:Iridium
2014-06-17T16:37:01.851Z,1403023021.851 [Default:Iridium] Stopped
2014-06-17T16:37:01.851Z,1403023021.851 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-06-17T16:37:01.851Z,1403023021.851 [Default:Iridium:A.SetSpeed] Stopped
2014-06-17T16:37:01.851Z,1403023021.851 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-06-17T16:37:01.851Z,1403023021.851 [Default:Iridium:B.GoToSurface] Stopped
2014-06-17T16:37:01.852Z,1403023021.852 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-06-17T16:37:02.444Z,1403023022.444 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-06-17T16:37:02.444Z,1403023022.444 [Default:CallIridium:B] Stopped
2014-06-17T16:37:02.444Z,1403023022.444 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-06-17T16:37:02.444Z,1403023022.444 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-06-17T16:37:02.444Z,1403023022.444 [Default:CallIridium] Stopped
2014-06-17T16:37:02.445Z,1403023022.445 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-06-17T16:39:23.474Z,1403023163.474 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-06-17T16:39:23.474Z,1403023163.474 [DVL_micro] Data Fault, FailCount= 1
2014-06-17T16:39:23.474Z,1403023163.474 [DVL_micro](ERROR): Data Fault
2014-06-17T16:39:23.582Z,1403023163.582 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-06-17T16:39:23.950Z,1403023163.950 [DVL_micro](INFO): uninitialize:Powering down
2014-06-17T16:39:24.359Z,1403023164.359 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-06-17T16:39:24.359Z,1403023164.359 [DVL_micro] Hardware Fault, FailCount= 1
2014-06-17T16:39:24.359Z,1403023164.359 [DVL_micro](ERROR): Hardware Fault
2014-06-17T16:39:24.798Z,1403023164.798 [DVL_micro](INFO): Initializing
2014-06-17T16:39:24.858Z,1403023164.858 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-06-17T16:39:24.858Z,1403023164.858 [DVL_micro] No Fault, FailCount= 1
2014-06-17T16:41:58.498Z,1403023318.498 [Default:CallIridium] Running Loop=1
2014-06-17T16:41:58.499Z,1403023318.499 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-06-17T16:41:58.499Z,1403023318.499 [Default:CallIridium:A] Running Loop=1
2014-06-17T16:41:58.499Z,1403023318.499 [Default:CallIridium:A] Stopped
2014-06-17T16:41:58.499Z,1403023318.499 [Default:CallIridium:B] Running Loop=1
2014-06-17T16:41:58.499Z,1403023318.499 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-06-17T16:41:58.966Z,1403023318.966 [Default:Iridium] Running Loop=1
2014-06-17T16:41:58.966Z,1403023318.966 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-06-17T16:41:58.966Z,1403023318.966 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-06-17T16:41:58.966Z,1403023318.966 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-06-17T16:41:58.966Z,1403023318.966 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-06-17T16:41:58.966Z,1403023318.966 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-06-17T16:41:58.967Z,1403023318.967 [Default:Iridium:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-06-17T16:41:58.967Z,1403023318.967 [Default:Iridium:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2014-06-17T16:41:58.967Z,1403023318.967 [Default:Iridium:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2014-06-17T16:41:58.968Z,1403023318.968 [Default:Iridium:Read_Iridium] Running Loop=1
2014-06-17T16:42:01.364Z,1403023321.364 [DataOverHttps](INFO): Sending 47 bytes from file Logs/20140617T160142/Courier0032.lzma
2014-06-17T16:42:02.699Z,1403023322.699 [DataOverHttps](INFO): Moved sent file to Logs/20140617T160142/Courier0032.lzma.bak
2014-06-17T16:42:02.699Z,1403023322.699 [DataOverHttps](INFO): SBD MOMSN=1010162
2014-06-17T16:42:08.106Z,1403023328.106 [DataOverHttps](INFO): Sending 318 bytes from file Logs/20140617T160142/Express0033.lzma
2014-06-17T16:42:09.012Z,1403023329.012 [DataOverHttps](INFO): Moved sent file to Logs/20140617T160142/Express0033.lzma.bak
2014-06-17T16:42:09.012Z,1403023329.012 [DataOverHttps](INFO): SBD MOMSN=1010164
2014-06-17T16:42:12.396Z,1403023332.396 [HFRadarModelCalc](IMPORTANT): Forecast time 20140617T140000: published 50 modes in rows, 61 hours in columns, 3050 elements.
2014-06-17T16:42:12.399Z,1403023332.399 [HFRadarModelCalc](IMPORTANT): expansionCoefficients_[0][48] = -3.814250 for 2014-06-17T14:00:00.000Z
2014-06-17T16:42:13.110Z,1403023333.110 [HFRadarCompactModelForecaster](DEBUG): Did not find new historical expansion coefficients.
2014-06-17T16:42:13.121Z,1403023333.121 [Default:Iridium:Read_Iridium] Stopped
2014-06-17T16:42:13.123Z,1403023333.123 [Default:Iridium](INFO): Completed Default:Iridium
2014-06-17T16:42:13.123Z,1403023333.123 [Default:Iridium] Stopped
2014-06-17T16:42:13.123Z,1403023333.123 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-06-17T16:42:13.123Z,1403023333.123 [Default:Iridium:A.SetSpeed] Stopped
2014-06-17T16:42:13.123Z,1403023333.123 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-06-17T16:42:13.123Z,1403023333.123 [Default:Iridium:B.GoToSurface] Stopped
2014-06-17T16:42:13.123Z,1403023333.123 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-06-17T16:42:13.730Z,1403023333.730 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-06-17T16:42:13.730Z,1403023333.730 [Default:CallIridium:B] Stopped
2014-06-17T16:42:13.730Z,1403023333.730 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-06-17T16:42:13.730Z,1403023333.730 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-06-17T16:42:13.730Z,1403023333.730 [Default:CallIridium] Stopped
2014-06-17T16:42:13.730Z,1403023333.730 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-06-17T16:42:29.013Z,1403023349.013 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-06-17T16:42:29.013Z,1403023349.013 [DVL_micro] Data Fault, FailCount= 1
2014-06-17T16:42:29.013Z,1403023349.013 [DVL_micro](ERROR): Data Fault
2014-06-17T16:42:29.070Z,1403023349.070 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-06-17T16:42:29.435Z,1403023349.435 [DVL_micro](INFO): uninitialize:Powering down
2014-06-17T16:42:29.902Z,1403023349.902 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-06-17T16:42:29.903Z,1403023349.903 [DVL_micro] Hardware Fault, FailCount= 1
2014-06-17T16:42:29.903Z,1403023349.903 [DVL_micro](ERROR): Hardware Fault
2014-06-17T16:42:30.358Z,1403023350.358 [DVL_micro](INFO): Initializing
2014-06-17T16:42:30.418Z,1403023350.418 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-06-17T16:42:30.418Z,1403023350.418 [DVL_micro] No Fault, FailCount= 1
2014-06-17T16:45:15.452Z,1403023515.452 [NAL9602](FAULT): GPS failed to acquire within timeout.
2014-06-17T16:45:15.452Z,1403023515.452 [NAL9602] Data Fault, FailCount= 2
2014-06-17T16:45:15.452Z,1403023515.452 [NAL9602](ERROR): Data Fault
2014-06-17T16:45:15.507Z,1403023515.507 [CBIT](ERROR): Data Fault in component: NAL9602
2014-06-17T16:45:15.508Z,1403023515.508 [CBIT](CRITICAL): Data Fault in component: NAL9602
2014-06-17T16:45:15.876Z,1403023515.876 [NAL9602](INFO): Powering down
2014-06-17T16:45:34.571Z,1403023534.571 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-06-17T16:45:34.571Z,1403023534.571 [DVL_micro] Data Fault, FailCount= 1
2014-06-17T16:45:34.571Z,1403023534.571 [DVL_micro](ERROR): Data Fault
2014-06-17T16:45:34.604Z,1403023534.604 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-06-17T16:45:35.047Z,1403023535.047 [DVL_micro](INFO): uninitialize:Powering down
2014-06-17T16:45:35.458Z,1403023535.458 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-06-17T16:45:35.458Z,1403023535.458 [DVL_micro] Hardware Fault, FailCount= 1
2014-06-17T16:45:35.458Z,1403023535.458 [DVL_micro](ERROR): Hardware Fault
2014-06-17T16:45:35.882Z,1403023535.882 [DVL_micro](INFO): Initializing
2014-06-17T16:45:35.914Z,1403023535.914 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-06-17T16:45:35.914Z,1403023535.914 [DVL_micro] No Fault, FailCount= 1
2014-06-17T16:47:09.515Z,1403023629.515 [Default:CallIridium] Running Loop=1
2014-06-17T16:47:09.515Z,1403023629.515 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-06-17T16:47:09.515Z,1403023629.515 [Default:CallIridium:A] Running Loop=1
2014-06-17T16:47:09.515Z,1403023629.515 [Default:CallIridium:A] Stopped
2014-06-17T16:47:09.515Z,1403023629.515 [Default:CallIridium:B] Running Loop=1
2014-06-17T16:47:09.516Z,1403023629.516 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-06-17T16:47:09.925Z,1403023629.925 [Default:Iridium] Running Loop=1
2014-06-17T16:47:09.925Z,1403023629.925 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-06-17T16:47:09.925Z,1403023629.925 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-06-17T16:47:09.925Z,1403023629.925 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-06-17T16:47:09.926Z,1403023629.926 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-06-17T16:47:09.926Z,1403023629.926 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-06-17T16:47:09.926Z,1403023629.926 [Default:Iridium:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-06-17T16:47:09.926Z,1403023629.926 [Default:Iridium:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2014-06-17T16:47:09.927Z,1403023629.927 [Default:Iridium:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2014-06-17T16:47:09.927Z,1403023629.927 [Default:Iridium:Read_Iridium] Running Loop=1
2014-06-17T16:47:12.379Z,1403023632.379 [DataOverHttps](INFO): Sending 90 bytes from file Logs/20140617T160142/Courier0036.lzma
2014-06-17T16:47:13.220Z,1403023633.220 [DataOverHttps](INFO): Moved sent file to Logs/20140617T160142/Courier0036.lzma.bak
2014-06-17T16:47:13.220Z,1403023633.220 [DataOverHttps](INFO): SBD MOMSN=1010170
2014-06-17T16:47:15.542Z,1403023635.542 [CBIT](INFO): Clearing failed count for component NAL9602
2014-06-17T16:47:15.543Z,1403023635.543 [NAL9602] No Fault, FailCount= 2
2014-06-17T16:47:15.895Z,1403023635.895 [NAL9602](INFO): Powering up NAL9602
2014-06-17T16:47:21.626Z,1403023641.626 [DataOverHttps](INFO): Sending 344 bytes from file Logs/20140617T160142/Express0037.lzma
2014-06-17T16:47:22.512Z,1403023642.512 [DataOverHttps](INFO): Moved sent file to Logs/20140617T160142/Express0037.lzma.bak
2014-06-17T16:47:22.513Z,1403023642.513 [DataOverHttps](INFO): SBD MOMSN=1010173
2014-06-17T16:47:25.878Z,1403023645.878 [HFRadarModelCalc](IMPORTANT): Forecast time 20140617T140000: published 50 modes in rows, 61 hours in columns, 3050 elements.
2014-06-17T16:47:25.880Z,1403023645.880 [HFRadarModelCalc](IMPORTANT): expansionCoefficients_[0][48] = -3.814250 for 2014-06-17T14:00:00.000Z
2014-06-17T16:47:26.595Z,1403023646.595 [HFRadarCompactModelForecaster](DEBUG): Did not find new historical expansion coefficients.
2014-06-17T16:47:26.614Z,1403023646.614 [Default:Iridium:Read_Iridium] Stopped
2014-06-17T16:47:26.615Z,1403023646.615 [Default:Iridium](INFO): Completed Default:Iridium
2014-06-17T16:47:26.615Z,1403023646.615 [Default:Iridium] Stopped
2014-06-17T16:47:26.615Z,1403023646.615 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-06-17T16:47:26.615Z,1403023646.615 [Default:Iridium:A.SetSpeed] Stopped
2014-06-17T16:47:26.615Z,1403023646.615 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-06-17T16:47:26.615Z,1403023646.615 [Default:Iridium:B.GoToSurface] Stopped
2014-06-17T16:47:26.616Z,1403023646.616 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-06-17T16:47:27.167Z,1403023647.167 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-06-17T16:47:27.167Z,1403023647.167 [Default:CallIridium:B] Stopped
2014-06-17T16:47:27.167Z,1403023647.167 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-06-17T16:47:27.168Z,1403023647.168 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-06-17T16:47:27.168Z,1403023647.168 [Default:CallIridium] Stopped
2014-06-17T16:47:27.168Z,1403023647.168 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-06-17T16:47:28.135Z,1403023648.135 [NAL9602](INFO): NAL9602 initialized
2014-06-17T16:48:40.197Z,1403023720.197 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-06-17T16:48:40.197Z,1403023720.197 [DVL_micro] Data Fault, FailCount= 1
2014-06-17T16:48:40.197Z,1403023720.197 [DVL_micro](ERROR): Data Fault
2014-06-17T16:48:40.259Z,1403023720.259 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-06-17T16:48:40.610Z,1403023720.610 [DVL_micro](INFO): uninitialize:Powering down
2014-06-17T16:48:41.050Z,1403023721.050 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-06-17T16:48:41.050Z,1403023721.050 [DVL_micro] Hardware Fault, FailCount= 1
2014-06-17T16:48:41.050Z,1403023721.050 [DVL_micro](ERROR): Hardware Fault
2014-06-17T16:48:41.486Z,1403023721.486 [DVL_micro](INFO): Initializing
2014-06-17T16:48:41.555Z,1403023721.555 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-06-17T16:48:41.555Z,1403023721.555 [DVL_micro] No Fault, FailCount= 1
2014-06-17T16:51:45.516Z,1403023905.516 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-06-17T16:51:45.516Z,1403023905.516 [DVL_micro] Data Fault, FailCount= 1
2014-06-17T16:51:45.516Z,1403023905.516 [DVL_micro](ERROR): Data Fault
2014-06-17T16:51:45.586Z,1403023905.586 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-06-17T16:51:45.929Z,1403023905.929 [DVL_micro](INFO): uninitialize:Powering down
2014-06-17T16:51:46.397Z,1403023906.397 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-06-17T16:51:46.397Z,1403023906.397 [DVL_micro] Hardware Fault, FailCount= 1
2014-06-17T16:51:46.397Z,1403023906.397 [DVL_micro](ERROR): Hardware Fault
2014-06-17T16:51:46.828Z,1403023906.828 [DVL_micro](INFO): Initializing
2014-06-17T16:51:46.875Z,1403023906.875 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-06-17T16:51:46.876Z,1403023906.876 [DVL_micro] No Fault, FailCount= 1
2014-06-17T16:52:23.532Z,1403023943.532 [Default:CallIridium] Running Loop=1
2014-06-17T16:52:23.532Z,1403023943.532 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-06-17T16:52:23.532Z,1403023943.532 [Default:CallIridium:A] Running Loop=1
2014-06-17T16:52:23.537Z,1403023943.537 [Default:CallIridium:A] Stopped
2014-06-17T16:52:23.537Z,1403023943.537 [Default:CallIridium:B] Running Loop=1
2014-06-17T16:52:23.537Z,1403023943.537 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-06-17T16:52:23.956Z,1403023943.956 [Default:Iridium] Running Loop=1
2014-06-17T16:52:23.957Z,1403023943.957 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-06-17T16:52:23.957Z,1403023943.957 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-06-17T16:52:23.957Z,1403023943.957 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-06-17T16:52:23.957Z,1403023943.957 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-06-17T16:52:23.957Z,1403023943.957 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-06-17T16:52:23.957Z,1403023943.957 [Default:Iridium:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-06-17T16:52:23.958Z,1403023943.958 [Default:Iridium:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2014-06-17T16:52:23.958Z,1403023943.958 [Default:Iridium:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2014-06-17T16:52:23.959Z,1403023943.959 [Default:Iridium:Read_Iridium] Running Loop=1
2014-06-17T16:52:25.863Z,1403023945.863 [DataOverHttps](INFO): Sending 45 bytes from file Logs/20140617T160142/Courier0040.lzma
2014-06-17T16:52:26.742Z,1403023946.742 [DataOverHttps](INFO): Moved sent file to Logs/20140617T160142/Courier0040.lzma.bak
2014-06-17T16:52:26.742Z,1403023946.742 [DataOverHttps](INFO): SBD MOMSN=1010182
2014-06-17T16:52:38.461Z,1403023958.461 [DataOverHttps](INFO): Sending 317 bytes from file Logs/20140617T160142/Express0041.lzma
2014-06-17T16:52:39.358Z,1403023959.358 [DataOverHttps](INFO): Moved sent file to Logs/20140617T160142/Express0041.lzma.bak
2014-06-17T16:52:39.358Z,1403023959.358 [DataOverHttps](INFO): SBD MOMSN=1010184
2014-06-17T16:52:42.798Z,1403023962.798 [HFRadarModelCalc](IMPORTANT): Forecast time 20140617T140000: published 50 modes in rows, 61 hours in columns, 3050 elements.
2014-06-17T16:52:42.806Z,1403023962.806 [HFRadarModelCalc](IMPORTANT): expansionCoefficients_[0][48] = -3.814250 for 2014-06-17T14:00:00.000Z
2014-06-17T16:52:43.529Z,1403023963.529 [HFRadarCompactModelForecaster](DEBUG): Did not find new historical expansion coefficients.
2014-06-17T16:52:43.540Z,1403023963.540 [Default:Iridium:Read_Iridium] Stopped
2014-06-17T16:52:43.541Z,1403023963.541 [Default:Iridium](INFO): Completed Default:Iridium
2014-06-17T16:52:43.541Z,1403023963.541 [Default:Iridium] Stopped
2014-06-17T16:52:43.541Z,1403023963.541 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-06-17T16:52:43.541Z,1403023963.541 [Default:Iridium:A.SetSpeed] Stopped
2014-06-17T16:52:43.541Z,1403023963.541 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-06-17T16:52:43.541Z,1403023963.541 [Default:Iridium:B.GoToSurface] Stopped
2014-06-17T16:52:43.541Z,1403023963.541 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-06-17T16:52:44.143Z,1403023964.143 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-06-17T16:52:44.143Z,1403023964.143 [Default:CallIridium:B] Stopped
2014-06-17T16:52:44.143Z,1403023964.143 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-06-17T16:52:44.143Z,1403023964.143 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-06-17T16:52:44.143Z,1403023964.143 [D